7.2. Error Log Reference
7.2.1. Error Log Logging Levels
16384
, which included critical error messages and standard logged messages, like LDAP results codes and startup messages. As with access logging, error logging levels are additive. To enable both replication logging (8192
) and plug-in logging (65536
), set the log level to 73728
(8192
+ 65536
).
Note
8192
) should only be enabled for troubleshooting, not for daily operations.
Table 7.4. Error Log Levels
Setting | Console Name | Description |
---|---|---|
1 | Trace function calls | Logs a message when the server enters and exits a function. |
2 | Packeting handlings | Logs debug information for packets processed by the server. |
4 | Heavy trace output | Logs when the server enters and exits a function, with additional debugging messages. |
8 | Connection management | Logs the current connection status, including the connection methods used for a SASL bind. |
16 | Packets sent/received | Print out the numbers of packets sent and received by the server. |
32 | Search filter processing | Logs all of the functions called by a search operation. |
64 | Config file processing | Prints any .conf configuration files used with the server, line by line, when the server is started. By default, only slapd-collations.conf is available and processed. |
128 | Access control list processing | |
2048 | Log entry parsing. | Logs schema parsing debugging information. |
4096 | Housekeeping | Housekeeping thread debugging. |
8192 | Replication | Logs detailed information about every replication-related operation, including updates and errors, which is important for debugging replication problems. |
16384 | Default | Default level of logging used for critical errors and other messages that are always written to the error log, such as server startup messages. Messages at this level are always included in the error log, regardless of the log level setting. |
32768 | Entry cache | Database entry cache debugging. |
65536 | Plug-ins | Writes an entry to the log file when a server plug-in calls slapi-log-error , so this is used for server plug-in debugging. |
262144 | Access control summary | Summarizes information about access to the server, much less verbose than level 128 . This value is recommended for use when a summary of access control processing is needed. Use 128 for very detailed processing messages. |
7.2.2. Error Log Content
- Log entries written by the server
- Entries that the server writes to the file, use the following format:
time_stamp - severity_level - function_name - message
For example:[24/Mar/2017:11:31:38.781466443 +0100] - ERR - no_diskspace - No enough space left on device (/var/lib/dirsrv/slapd-instance_name/db) (40009728 bytes); at least 145819238 bytes space is needed for db region files
- Log entries written by plug-ins
- Entries that plug-ins write to the file, use the following format:
time_stamp - severity_level - plug-in_name - function_name - message
For example:[24/Mar/2017:11:42:17.628363848 +0100] - ERR - NSMMReplicationPlugin - multimaster_extop_StartNSDS50ReplicationRequest - conn=19 op=3 repl="o=example.com": Excessive clock skew from supplier RUV
- Time stamp: The format can differ depending on your local settings. If high-resolution time stamps are enabled in the
nsslapd-logging-hr-timestamps-enabled
attribute in thecn=config
entry (default), the time stamp is exact to the nanosecond. - Severity level: The following severity levels are used:
EMERG
: This level is logged when the server fails to start.ALERT
: The server is in a critical state and possible action must be taken.CRIT
: Severe error.ERR
: General error.WARNING
: A warning message, that is not necessarily an error.NOTICE
: A normal, but significant condition occurred. For example, this is logged for expected behavior.INFO
: Informational messages, such as startup, shutdown, import, export, backup, restore.DEBUG
: Debug-level messages. This level is also used by default when using a verbose logging level, such asTrace function calls
(1),Access control list processing
(128), andReplication
(8192). For a list of error log levels, see Table 7.4, “Error Log Levels”.
You can use the severity levels to filter your log entries. For example, to display only log entries using theERR
severity:# grep ERR /var/log/dirsrv/slapd-instance_name/errors [24/Mar/2017:11:31:38.781466443 +0100] - ERR - no_diskspace - No enough space left on device (/var/lib/dirsrv/slapd-instance_name/db) (40009728 bytes); at least 145819238 bytes space is needed for db region files [24/Mar/2017:11:31:38.815623298 +0100] - ERR - ldbm_back_start - Failed to init database, err=28 No space left on device [24/Mar/2017:11:31:38.828591835 +0100] - ERR - plugin_dependency_startall - Failed to start database plugin ldbm database ...
- Plug-in name: If a plug-in logged the entry, this column displays the name of the plug-in. If the server logged the entry, this column does not appear.
- Function name: Functions that the operation or the plug-in called.
- Message: The output that the operation or plug-in returned. This message contains additional information, such as LDAP error codes and connection information.
7.2.3. Error Log Content for Other Log Levels
[timestamp] NSMMReplicationPlugin - agmt="name" (consumer_host:consumer_port): current_task
[09/Jan/2020:13:44:48 -0500] NSMMReplicationPlugin - agmt="cn=example2" (alt:13864): {replicageneration} 4949df6e000000010000
{replicageneration}
means that the new information is being sent, and 4949df6e000000010000
is the change sequence number of the entry being replicated.
Example 7.3. Replication Error Log Entry
[29/May/2017:14:15:30.539817639 +0200] - DEBUG - _csngen_adjust_local_time - gen state before 592c103d0000:1496059964:0:1 [29/May/2017:14:15:30.562983285 +0200] - DEBUG - _csngen_adjust_local_time - gen state after 592c10e20000:1496060129:0:1 [29/May/2017:14:15:30.578828393 +0200] - DEBUG - NSMMReplicationPlugin - ruv_add_csn_inprogress - Successfully inserted csn 592c10e2000000020000 into pending list [29/May/2017:14:15:30.589917123 +0200] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5GetDBFileByReplicaName - found DB object 0x558ddfe1f720 for database /var/lib/dirsrv/slapd-master_2/changelogdb/d3de3e8d-446611e7-a89886da-6a37442d_592c0e0b000000010000.db [29/May/2017:14:15:30.600044236 +0200] - DEBUG - NSMMReplicationPlugin - changelog program - cl5WriteOperationTxn - Successfully written entry with csn (592c10e2000000020000) [29/May/2017:14:15:30.615923352 +0200] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5GetDBFileByReplicaName - found DB object 0x558ddfe1f720 for database /var/lib/dirsrv/slapd-master_2/changelogdb/d3de3e8d-446611e7-a89886da-6a37442d_592c0e0b000000010000.db [29/May/2017:14:15:30.627443305 +0200] - DEBUG - NSMMReplicationPlugin - csnplCommitALL: committing all csns for csn 592c10e2000000020000 [29/May/2017:14:15:30.632713657 +0200] - DEBUG - NSMMReplicationPlugin - csnplCommitALL: processing data csn 592c10e2000000020000 [29/May/2017:14:15:30.652621188 +0200] - DEBUG - NSMMReplicationPlugin - ruv_update_ruv - Successfully committed csn 592c10e2000000020000 [29/May/2017:14:15:30.669666453 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_run - agmt="cn=meTo_localhost:39001" (localhost:39001): State: wait_for_changes -> wait_for_changes [29/May/2017:14:15:30.685259483 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_run - agmt="cn=meTo_localhost:39001" (localhost:39001): State: wait_for_changes -> ready_to_acquire_replica [29/May/2017:14:15:30.689906327 +0200] - DEBUG - NSMMReplicationPlugin - conn_connect - agmt="cn=meTo_localhost:39001" (localhost:39001) - Trying non-secure slapi_ldap_init_ext [29/May/2017:14:15:30.700259799 +0200] - DEBUG - NSMMReplicationPlugin - conn_connect - agmt="cn=meTo_localhost:39001" (localhost:39001) - binddn = cn=replrepl,cn=config, passwd = {AES-TUhNR0NTcUdTSWIzRFFFRkRUQm1NRVVHQ1NxR1NJYjNEUUVGRERBNEJDUmlZVFUzTnpRMk55MDBaR1ZtTXpobQ0KTWkxaE9XTTRPREpoTlMwME1EaGpabVUxWmdBQ0FRSUNBU0F3Q2dZSUtvWklodmNOQWdjd0hRWUpZSVpJQVdVRA0KQkFFcUJCRGhwMnNLcEZ2ZWE2RzEwWG10OU41Tg==}+36owaI7oTmvWhxRzUqX5w== [29/May/2017:14:15:30.712287531 +0200] - DEBUG - NSMMReplicationPlugin - conn_cancel_linger - agmt="cn=meTo_localhost:39001" (localhost:39001) - No linger to cancel on the connection [29/May/2017:14:15:30.736779494 +0200] - DEBUG - _csngen_adjust_local_time - gen state before 592c10e20001:1496060129:0:1 [29/May/2017:14:15:30.741909244 +0200] - DEBUG - _csngen_adjust_local_time - gen state after 592c10e30000:1496060130:0:1 [29/May/2017:14:15:30.880287041 +0200] - DEBUG - NSMMReplicationPlugin - acquire_replica - agmt="cn=meTo_localhost:39001" (localhost:39001): Replica was successfully acquired. [29/May/2017:14:15:30.897500049 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_run - agmt="cn=meTo_localhost:39001" (localhost:39001): State: ready_to_acquire_replica -> sending_updates [29/May/2017:14:15:30.914417773 +0200] - DEBUG - csngen_adjust_time - gen state before 592c10e30001:1496060130:0:1 [29/May/2017:14:15:30.926341721 +0200] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5GetDBFile - found DB object 0x558ddfe1f720 for database /var/lib/dirsrv/slapd-master_2/changelogdb/d3de3e8d-446611e7-a89886da-6a37442d_592c0e0b000000010000.db [29/May/2017:14:15:30.943094471 +0200] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5PositionCursorForReplay - (agmt="cn=meTo_localhost:39001" (localhost:39001)): Consumer RUV: [29/May/2017:14:15:30.949395331 +0200] - DEBUG - NSMMReplicationPlugin - agmt="cn=meTo_localhost:39001" (localhost:39001): {replicageneration} 592c0e0b000000010000 [29/May/2017:14:15:30.961118175 +0200] - DEBUG - NSMMReplicationPlugin - agmt="cn=meTo_localhost:39001" (localhost:39001): {replica 1 ldap://localhost:39001} 592c0e17000000010000 592c0e1a000100010000 00000000 [29/May/2017:14:15:30.976680025 +0200] - DEBUG - NSMMReplicationPlugin - agmt="cn=meTo_localhost:39001" (localhost:39001): {replica 2 ldap://localhost:39002} 592c103c000000020000 592c103c000000020000 00000000 [29/May/2017:14:15:30.990404183 +0200] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5PositionCursorForReplay - (agmt="cn=meTo_localhost:39001" (localhost:39001)): Supplier RUV: [29/May/2017:14:15:31.001242624 +0200] - DEBUG - NSMMReplicationPlugin - agmt="cn=meTo_localhost:39001" (localhost:39001): {replicageneration} 592c0e0b000000010000 [29/May/2017:14:15:31.017406105 +0200] - DEBUG - NSMMReplicationPlugin - agmt="cn=meTo_localhost:39001" (localhost:39001): {replica 2 ldap://localhost:39002} 592c103c000000020000 592c10e2000000020000 592c10e1 [29/May/2017:14:15:31.028803190 +0200] - DEBUG - NSMMReplicationPlugin - agmt="cn=meTo_localhost:39001" (localhost:39001): {replica 1 ldap://localhost:39001} 592c0e1a000100010000 592c0e1a000100010000 00000000 [29/May/2017:14:15:31.040172464 +0200] - DEBUG - agmt="cn=meTo_localhost:39001" (localhost:39001) - clcache_get_buffer - found thread private buffer cache 0x558ddf870f00 [29/May/2017:14:15:31.057495165 +0200] - DEBUG - agmt="cn=meTo_localhost:39001" (localhost:39001) - clcache_get_buffer - _pool is 0x558ddfe294d0 _pool->pl_busy_lists is 0x558ddfab84c0 _pool->pl_busy_lists->bl_buffers is 0x558ddf870f00 [29/May/2017:14:15:31.063015498 +0200] - DEBUG - agmt="cn=meTo_localhost:39001" (localhost:39001) - clcache_initial_anchorcsn - agmt="cn=meTo_localhost:39001" (localhost:39001) - (cscb 0 - state 0) - csnPrevMax () csnMax (592c10e2000000020000) csnBuf (592c103c000000020000) csnConsumerMax (592c103c000000020000) [29/May/2017:14:15:31.073252305 +0200] - DEBUG - clcache_initial_anchorcsn - anchor is now: 592c103c000000020000 [29/May/2017:14:15:31.089915209 +0200] - DEBUG - NSMMReplicationPlugin - changelog program - agmt="cn=meTo_localhost:39001" (localhost:39001): CSN 592c103c000000020000 found, position set for replay [29/May/2017:14:15:31.095825439 +0200] - DEBUG - agmt="cn=meTo_localhost:39001" (localhost:39001) - clcache_get_next_change - load=1 rec=1 csn=592c10e2000000020000 [29/May/2017:14:15:31.100123762 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_result_threadmain - Starting [29/May/2017:14:15:31.115749709 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_result_threadmain - Read result for message_id 0 [29/May/2017:14:15:31.125866330 +0200] - DEBUG - NSMMReplicationPlugin - replay_update - agmt="cn=meTo_localhost:39001" (localhost:39001): Sending add operation (dn="cn=user,ou=People,dc=example,dc=com" csn=592c10e2000000020000) [29/May/2017:14:15:31.142339398 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_result_threadmain - Read result for message_id 0 [29/May/2017:14:15:31.160456597 +0200] - DEBUG - NSMMReplicationPlugin - replay_update - agmt="cn=meTo_localhost:39001" (localhost:39001): Consumer successfully sent operation with csn 592c10e2000000020000 [29/May/2017:14:15:31.172399536 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_result_threadmain - Read result for message_id 0 [29/May/2017:14:15:31.188857336 +0200] - DEBUG - agmt="cn=meTo_localhost:39001" (localhost:39001) - clcache_adjust_anchorcsn - agmt="cn=meTo_localhost:39001" (localhost:39001) - (cscb 0 - state 1) - csnPrevMax (592c10e2000000020000) csnMax (592c10e2000000020000) csnBuf (592c10e2000000020000) csnConsumerMax (592c10e2000000020000) [29/May/2017:14:15:31.199605024 +0200] - DEBUG - agmt="cn=meTo_localhost:39001" (localhost:39001) - clcache_load_buffer - rc=-30988 [29/May/2017:14:15:31.210800816 +0200] - DEBUG - NSMMReplicationPlugin - send_updates - agmt="cn=meTo_localhost:39001" (localhost:39001): No more updates to send (cl5GetNextOperationToReplay) [29/May/2017:14:15:31.236214134 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_waitfor_async_results - 0 5 [29/May/2017:14:15:31.246755544 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_result_threadmain - Read result for message_id 0 [29/May/2017:14:15:31.277705986 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_result_threadmain - Read result for message_id 0 [29/May/2017:14:15:31.303530336 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_result_threadmain - Read result for message_id 5 [29/May/2017:14:15:31.318259308 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_result_threadmain - Result 1, 0, 0, 5, (null) [29/May/2017:14:15:31.335263462 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_result_threadmain - Read result for message_id 5 [29/May/2017:14:15:31.364551307 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_waitfor_async_results - 5 5 [29/May/2017:14:15:31.376301820 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_result_threadmain exiting [29/May/2017:14:15:31.393707037 +0200] - DEBUG - agmt="cn=meTo_localhost:39001" (localhost:39001) - clcache_return_buffer - session end: state=5 load=1 sent=1 skipped=0 skipped_new_rid=0 skipped_csn_gt_cons_maxcsn=0 skipped_up_to_date=0 skipped_csn_gt_ruv=0 skipped_csn_covered=0 [29/May/2017:14:15:31.398134114 +0200] - DEBUG - NSMMReplicationPlugin - consumer_connection_extension_acquire_exclusive_access - conn=4 op=3 Acquired consumer connection extension [29/May/2017:14:15:31.423099625 +0200] - DEBUG - NSMMReplicationPlugin - multimaster_extop_StartNSDS50ReplicationRequest - conn=4 op=3 repl="dc=example,dc=com": Begin incremental protocol [29/May/2017:14:15:31.438899389 +0200] - DEBUG - csngen_adjust_time - gen state before 592c10e30001:1496060130:0:1 [29/May/2017:14:15:31.443800884 +0200] - DEBUG - csngen_adjust_time - gen state after 592c10e40001:1496060130:1:1 [29/May/2017:14:15:31.454123488 +0200] - DEBUG - NSMMReplicationPlugin - replica_get_exclusive_access - conn=4 op=3 repl="dc=example,dc=com": Acquired replica [29/May/2017:14:15:31.469698781 +0200] - DEBUG - NSMMReplicationPlugin - release_replica - agmt="cn=meTo_localhost:39001" (localhost:39001): Successfully released consumer [29/May/2017:14:15:31.475096195 +0200] - DEBUG - NSMMReplicationPlugin - conn_start_linger -agmt="cn=meTo_localhost:39001" (localhost:39001) - Beginning linger on the connection [29/May/2017:14:15:31.485281588 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_run - agmt="cn=meTo_localhost:39001" (localhost:39001): State: sending_updates -> wait_for_changes [29/May/2017:14:15:31.495865065 +0200] - DEBUG - NSMMReplicationPlugin - multimaster_extop_StartNSDS50ReplicationRequest - conn=4 op=3 repl="dc=example,dc=com": StartNSDS90ReplicationRequest: response=0 rc=0 [29/May/2017:14:15:31.501617765 +0200] - DEBUG - NSMMReplicationPlugin - consumer_connection_extension_relinquish_exclusive_access - conn=4 op=3 Relinquishing consumer connection extension [29/May/2017:14:15:31.716627741 +0200] - DEBUG - NSMMReplicationPlugin - consumer_connection_extension_acquire_exclusive_access - conn=4 op=4 Acquired consumer connection extension [29/May/2017:14:15:31.735431913 +0200] - DEBUG - NSMMReplicationPlugin - replica_relinquish_exclusive_access - conn=4 op=4 repl="dc=example,dc=com": Released replica held by locking_purl=conn=4 id=3 [29/May/2017:14:15:31.745841821 +0200] - DEBUG - NSMMReplicationPlugin - consumer_connection_extension_relinquish_exclusive_access - conn=4 op=4 Relinquishing consumer connection extension
[timestamp] Plugin_name - message [timestamp] - function - message
Example 7.4. Example ACL Plug-in Error Log Entry with Plug-in Logging
[29/May/2017:14:38:19.133878244 +0200] - DEBUG - get_filter_internal - ==> [29/May/2017:14:38:19.153942547 +0200] - DEBUG - get_filter_internal - PRESENT [29/May/2017:14:38:19.177908064 +0200] - DEBUG - get_filter_internal - <= 0 [29/May/2017:14:38:19.193547449 +0200] - DEBUG - slapi_vattr_filter_test_ext_internal - => [29/May/2017:14:38:19.198121765 +0200] - DEBUG - slapi_vattr_filter_test_ext_internal - <= [29/May/2017:14:38:19.214342752 +0200] - DEBUG - slapi_vattr_filter_test_ext_internal - PRESENT [29/May/2017:14:38:19.219886104 +0200] - DEBUG - NSACLPlugin - acl_access_allowed - conn=15 op=1 (main): Allow search on entry(cn=replication,cn=config): root user [29/May/2017:14:38:19.230152526 +0200] - DEBUG - slapi_vattr_filter_test_ext_internal - <= 0 [29/May/2017:14:38:19.240971955 +0200] - DEBUG - NSACLPlugin - acl_read_access_allowed_on_entry - Root access (read) allowed on entry(cn=replication,cn=config) [29/May/2017:14:38:19.246456160 +0200] - DEBUG - cos-plugin - cos_cache_vattr_types - Failed to get class of service reference [29/May/2017:14:38:19.257200851 +0200] - DEBUG - NSACLPlugin - Root access (read) allowed on entry(cn=replication,cn=config) [29/May/2017:14:38:19.273534025 +0200] - DEBUG - NSACLPlugin - Root access (read) allowed on entry(cn=replication,cn=config) [29/May/2017:14:38:19.289474926 +0200] - DEBUG - slapi_filter_free - type 0x87
Note
4
), access control list processing (128
), schema parsing (2048
), and housekeeping (4096
) all record the functions called by the different operations being performed. In this case, the difference is not in the format of what is being recorded, but what operations it is being recorded for.
.conf
file, printing every line, whenever the server starts up. This can be used to debug any problems with files outside of the server's normal configuration. By default, only slapd-collations.conf
file, which contains configurations for international language sets, is available.
Example 7.5. Config File Processing Log Entry
[29/May/2017:15:26:48.897935879 +0200] - DEBUG - collation_read_config - Reading config file /etc/dirsrv/slapd-master_1/slapd-collations.conf [29/May/2017:15:26:48.902606586 +0200] - DEBUG - collation-plugin - collation_read_config - line 16: collation "" "" "" 1 3 2.16.840.1.113730.3.3.2.0.1 default [29/May/2017:15:26:48.918493657 +0200] - DEBUG - collation-plugin - collation_read_config - line 17: collation ar "" "" 1 3 2.16.840.1.113730.3.3.2.1.1 ar [29/May/2017:15:26:48.932550086 +0200] - DEBUG - collation-plugin - collation_read_config - line 18: collation be "" "" 1 3 2.16.840.1.113730.3.3.2.2.1 be be-BY ...
Example 7.6. Access Control Summary Logging
[29/May/2017:15:34:52.742034888 +0200] - DEBUG - NSACLPlugin - acllist_init_scan - Failed to find root for base: cn=features,cn=config [29/May/2017:15:34:52.761702767 +0200] - DEBUG - NSACLPlugin - acllist_init_scan - Failed to find root for base: cn=config [29/May/2017:15:34:52.771907825 +0200] - DEBUG - NSACLPlugin - acl_access_allowed - #### conn=6 op=1 binddn="cn=user,ou=people,dc=example,dc=com" [29/May/2017:15:34:52.776327012 +0200] - DEBUG - NSACLPlugin - ************ RESOURCE INFO STARTS ********* [29/May/2017:15:34:52.786397852 +0200] - DEBUG - NSACLPlugin - Client DN: cn=user,ou=people,dc=example,dc=com [29/May/2017:15:34:52.797004451 +0200] - DEBUG - NSACLPlugin - resource type:256(search target_DN ) [29/May/2017:15:34:52.807135945 +0200] - DEBUG - NSACLPlugin - Slapi_Entry DN: cn=features,cn=config [29/May/2017:15:34:52.822877838 +0200] - DEBUG - NSACLPlugin - ATTR: objectClass [29/May/2017:15:34:52.827250828 +0200] - DEBUG - NSACLPlugin - rights:search [29/May/2017:15:34:52.831603634 +0200] - DEBUG - NSACLPlugin - ************ RESOURCE INFO ENDS ********* [29/May/2017:15:34:52.847183276 +0200] - DEBUG - NSACLPlugin - acl__scan_for_acis - Num of ALLOW Handles:0, DENY handles:0 [29/May/2017:15:34:52.857857195 +0200] - DEBUG - NSACLPlugin - print_access_control_summary - conn=6 op=1 (main): Deny search on entry(cn=features,cn=config).attr(objectClass) to cn=user,ou=people,dc=example,dc=com: no aci matched the resource