7.2. Error Log Reference

The Directory Server error log records messages for Directory Server transactions and operations. These may be error messages for failed operations, but it also contains general information about the processes of Directory Server and LDAP tasks, such as server startup messages, logins and searches of the directory, and connection information.

7.2.1. Error Log Logging Levels

The error log can record different amounts of detail for operations, as well as different kinds of information depending on the type of error logging enabled.
The logging level is set in the nsslapd-errorlog-level (Error Log Level) configuration attribute. The default log level is 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

Enabling high levels of debug logging can significantly erode server performance. Debug log levels, such as replication (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

The error log format is simpler than the access log entries. It is also more flexible because the kind of information returned depends on the service or operation which is writing the log entry. Generally, error log entries contain the following elements:
  • A timestamp, such as [05/Jan/2017:02:27:22 -0500], although the format varies depending on the platform. The ending four digits, -0500, indicate the time difference in relation to GMT.
  • The plug-in being called, for internal operations.
  • Functions called by the plug-in, for internal operations.
  • Messages returned by the plug-in or operation, which may include LDAP error codes, connection information, or entry information.
Frequently, the messages for an operation appear on multiple lines of the log, but these are not identified with a connection number or operation number.
Example 7.3, “Error Log Excerpt” shows excerpts from an error log at the default logging level, which includes some task information, critical errors, and server startup messages.

Example 7.3. Error Log Excerpt

[05/Jan/2017:02:27:22 -0500] slapi_ldap_bind - Error: could not send bind request for id [cn=repl manager,cn=config] mech [SIMPLE]: error 91 (Can't connect to the LDAP server)
[06/Jan/2017:17:52:04 -0500] schemareload - Schema reload task starts (schema dir: default) ...
[06/Jan/2017:17:52:04 -0500] schemareload - Schema validation passed.
[06/Jan/2017:17:52:04 -0500] schemareload - Schema reload task finished.
[07/Jan/2017:15:54:08 -0500] - libdb: write: 0xb75646e5, 508: No space left on device
[07/Jan/2017:15:54:08 -0500] - libdb: txn_checkpoint: log failed at LSN [22 7649039] No space left on device
[07/Jan/2017:15:54:08 -0500] - Serious Error- - - Failed to checkpoint database, err=28 (No space left on device)
[07/Jan/2017:15:54:08 -0500] - *** DISK FULL ***
[07/Jan/2017:15:54:08 -0500] - Attempting to shut down gracefully.
[07/Jan/2017:15:54:08 -0500] - slapd shutting down - signaling operation threads
[07/Jan/2017:15:54:08 -0500] - slapd shutting down - closing down internal subsystems and plugins
[07/Jan/2017:15:54:11 -0500] - Waiting for 3 database threads to stop
[07/Jan/2017:15:54:11 -0500] - All database threads now stopped
[07/Jan/2017:15:54:12 -0500] - slapd stopped.
        Red Hat-Directory/9.0.4 B2008.310.1012
        server.example.com:389 (/etc/dirsrv/slapd-example)

[07/Jan/2017:22:18:41 -0500] - Red Hat-Directory/9.0.4 B2008.310.1012 starting up
[07/Jan/2017:22:18:44 -0500] memory allocator - cannot calloc 0 elements;
trying to allocate 0 or a negative number of elements is not portable and
gives different results on different platforms.
[07/Jan/2017:22:18:44 -0500] - slapd started.  Listening on All Interfaces port 389 for LDAP requests

7.2.3. Error Log Content for Other Log Levels

The different log levels return not only different levels of detail, but also information about different types of server operations. Some of these are summarized here, but there are many more combinations of logging levels possible.
Replication logging is one of the most important diagnostic levels to implement. This logging level records all operations related to replication and Windows synchronization, including processing modifications on a supplier and writing them to the changelog, sending updates, and changing replication agreements.
Whenever a replication update is prepared or sent, the error log identifies the replication or synchronization agreement being specified, the consumer host and port, and the current replication task. 
[timestamp] NSMMReplicationPlugin - agmt="name" (consumer_host:consumer_port): current_task
For example: 
[09/Jan/2017: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.4, “Replication Error Log Entry” shows the complete process of sending a single entry to a consumer, from adding the entry to the changelog to releasing the consumer after replication is complete.

Example 7.4. Replication Error Log Entry

[09/Jan/2017:13:44:48 -0500] - _csngen_adjust_local_time: gen state before 496799220001:1231526178:0:0
[09/Jan/2017:13:44:48 -0500] - _csngen_adjust_local_time: gen state after 49679b200000:1231526688:0:0
[09/Jan/2017:13:44:48 -0500] NSMMReplicationPlugin - ruv_add_csn_inprogress: successfully inserted csn 49679b20000000010000 into pending list
[09/Jan/2017:13:44:48 -0500] NSMMReplicationPlugin - Purged state information from entry uid=mreynolds,ou=People,dc=example,dc=com up to CSN 495e5d73000000010000
[09/Jan/2017:13:44:48 -0500] NSMMReplicationPlugin - ruv_update_ruv: successfully committed csn 49679b20000000010000
[09/Jan/2017:13:44:48 -0500] NSMMReplicationPlugin - agmt="cn=example2" (alt:13864): State: wait_for_changes -> wait_for_changes
[09/Jan/2017:13:44:48 -0500] NSMMReplicationPlugin - agmt="cn=example2" (alt:13864): State: wait_for_changes -> ready_to_acquire_replica
[09/Jan/2017:13:44:48 -0500] NSMMReplicationPlugin - agmt="cn=example2" (alt:13864): Trying non-secure slapi_ldap_init_ext
[09/Jan/2017:13:44:48 -0500] NSMMReplicationPlugin - agmt="cn=example2" (alt:13864): binddn = cn=directory manager,  passwd = {DES}iRDGwYacBXFTnmlzPU01WQ==
[09/Jan/2017:13:44:48 -0500] NSMMReplicationPlugin - agmt="cn=example2" (alt:13864): No linger to cancel on the connection
[09/Jan/2017:13:44:48 -0500] NSMMReplicationPlugin - agmt="cn=example2" (alt:13864): Replica was successfully acquired.
[09/Jan/2017:13:44:48 -0500] NSMMReplicationPlugin - agmt="cn=example2" (alt:13864): State: ready_to_acquire_replica -> sending_updates
[09/Jan/2017:13:44:48 -0500] - csngen_adjust_time: gen state before 49679b200002:1231526688:0:0
[09/Jan/2017:13:44:48 -0500] - _cl5PositionCursorForReplay (agmt="cn=example2" (alt:13864)): Consumer RUV:
[09/Jan/2017:13:44:48 -0500] NSMMReplicationPlugin - agmt="cn=example2" (alt:13864): {replicageneration} 4949df6e000000010000
[09/Jan/2017:13:44:48 -0500] NSMMReplicationPlugin - agmt="cn=example2" (alt:13864): {replica 1 ldap://server.example.com:389} 494aa17d000000010000 496797f3000000010000 00000000
[09/Jan/2017:13:44:48 -0500] - _cl5PositionCursorForReplay (agmt="cn=example2" (alt:13864)): Supplier RUV:
[09/Jan/2017:13:44:48 -0500] NSMMReplicationPlugin - agmt="cn=example2" (alt:13864): {replicageneration} 4949df6e000000010000
[09/Jan/2017:13:44:48 -0500] NSMMReplicationPlugin - agmt="cn=example2" (alt:13864): {replica 1 ldap://server.example.com:389} 494aa17d000000010000 49679b20000000010000 49679b20
[09/Jan/2017:13:44:48 -0500] agmt="cn=example2" (alt:13864) - session start: anchorcsn=496797f3000000010000
[09/Jan/2017:13:44:48 -0500] NSMMReplicationPlugin - changelog program - agmt="cn=example2" (alt:13864): CSN 496797f3000000010000 found, position set for replay
[09/Jan/2017:13:44:48 -0500] agmt="cn=example2" (alt:13864) - load=1 rec=1 csn=49679b20000000010000
[09/Jan/2017:13:44:48 -0500] NSMMReplicationPlugin - agmt="cn=example2" (alt:13864): replay_update: Sending modify operation (dn="uid=mreynolds,ou=people,dc=example,dc=com" csn=49679b20000000010000)
[09/Jan/2017:13:44:48 -0500] NSMMReplicationPlugin - agmt="cn=example2" (alt:13864): replay_update: Consumer successfully sent operation with csn 49679b20000000010000
[09/Jan/2017:13:44:48 -0500] agmt="cn=example2" (alt:13864) - clcache_load_buffer: rc=-30990
[09/Jan/2017:13:44:48 -0500] NSMMReplicationPlugin - agmt="cn=example2" (alt:13864): No more updates to send (cl5GetNextOperationToReplay)
[09/Jan/2017:13:44:48 -0500] - repl5_inc_waitfor_async_results: 0 5
[09/Jan/2017:13:44:49 -0500] - repl5_inc_result_threadmain starting
[09/Jan/2017:13:44:49 -0500] - repl5_inc_result_threadmain: read result for message_id 5
[09/Jan/2017:13:44:49 -0500] - repl5_inc_result_threadmain: result 3, 0, 0, 5, (null)
[09/Jan/2017:13:44:49 -0500] - repl5_inc_result_threadmain: read result for message_id 5
[09/Jan/2017:13:44:49 -0500] - repl5_inc_waitfor_async_results: 5 5
[09/Jan/2017:13:44:50 -0500] - repl5_inc_result_threadmain: read result for message_id 5
[09/Jan/2017:13:44:51 -0500] - repl5_inc_result_threadmain exiting
[09/Jan/2017:13:44:51 -0500] agmt="cn=example2" (alt:13864) - session end: state=5 load=1 sent=1 skipped=0
[09/Jan/2017:13:44:51 -0500] NSMMReplicationPlugin - agmt="cn=example2" (alt:13864): Successfully released consumer
[09/Jan/2017:13:44:51 -0500] NSMMReplicationPlugin - agmt="cn=example2" (alt:13864): Beginning linger on the connection
[09/Jan/2017:13:44:51 -0500] NSMMReplicationPlugin - agmt="cn=example2" (alt:13864): State: sending_updates -> wait_for_changes
Plug-in logging records every the name of the plugin and all of the functions called by the plugin. This has a simple format: 
[timestamp] Plugin_name - message
[timestamp] - function - message
The information returned can be hundreds of lines long as every step is processed. The precise information recorded depends on the plug-in itself. For example, the ACL Plug-in includes a connection and operation number, as shown in Example 7.5, “Example ACL Plug-in Error Log Entry with Plug-in Logging”.

Example 7.5. Example ACL Plug-in Error Log Entry with Plug-in Logging

[09/Jan/2017:13:15:16 -0500] NSACLPlugin - conn=24826500108779577 op=10 (main): Allow search on entry(cn=replication,cn=config): root user
[09/Jan/2017:13:15:16 -0500] - <= slapi_vattr_filter_test 0
[09/Jan/2017:13:15:16 -0500] NSACLPlugin - Root access (read) allowed on entry(cn=replication,cn=config)
[09/Jan/2017:13:15:16 -0500] NSACLPlugin - Root access (read) allowed on entry(cn=replication,cn=config)
[09/Jan/2017:13:15:16 -0500] NSACLPlugin - Root access (read) allowed on entry(cn=replication,cn=config)
[09/Jan/2017:13:15:16 -0500] - slapi_filter_free type 0x87
[09/Jan/2017:13:15:16 -0500] - => get_filter_internal
[09/Jan/2017:13:15:16 -0500] - EQUALITY
[09/Jan/2017:13:15:16 -0500] - <= get_filter_internal 0
[09/Jan/2017:13:15:16 -0500] get_filter - before optimize:
[09/Jan/2017:13:15:16 -0500] get_filter -  after optimize:
[09/Jan/2017:13:15:16 -0500] index_subsys_assign_filter_decoders - before: (objectClass=nsBackendInstance)
[09/Jan/2017:13:15:16 -0500] index_subsys_assign_filter_decoders -  after: (objectClass=nsBackendInstance)
[09/Jan/2017:13:15:16 -0500] - => slapi_vattr_filter_test_ext
[09/Jan/2017:13:15:16 -0500] - => test_substring_filter
[09/Jan/2017:13:15:16 -0500] -     EQUALITY

Note

Example 7.5, “Example ACL Plug-in Error Log Entry with Plug-in Logging” shows both plug-in logging and search filter processing (log level 32).
Many other kinds of logging have similar output to the plug-in logging level, only for different kinds of internal operations. Heavy trace output (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.
The configuration file processing goes through any .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.6. Config File Processing Log Entry

[09/Jan/2009:16:08:18 -0500] - reading config file /etc/dirsrv/slapd-server/slapd-collations.conf
[09/Jan/2009:16:08:18 -0500] - line 46: collation "" "" "" 1 3  2.16.840.1.113730.3.3.2.0.1     default
[09/Jan/2009:16:08:18 -0500] - line 57: collation en "" "" 1 3  2.16.840.1.113730.3.3.2.11.1    en      en-US
[09/Jan/2009:16:08:18 -0500] - line 58: collation en CA "" 1 3  2.16.840.1.113730.3.3.2.12.1    en-CA
[09/Jan/2009:16:08:18 -0500] - line 59: collation en GB "" 1 3  2.16.840.1.113730.3.3.2.13.1    en-GB
There are two levels of ACI logging, one for debug information and one for summary. Both of these ACI logging levels records some extra information that is not included with other types of plug-ins or error logging, including Connection Number and Operation Number information. Show the name of the plug-in, the bind DN of the user, the operation performed or attempted, and the ACI which was applied. The debug level shows the series of functions called in the course of the bind and any other operations, as well.
Example 7.7, “Access Control Summary Logging” shows the summary access control log entry.

Example 7.7. Access Control Summary Logging

[09/Jan/2017:16:02:01 -0500] NSACLPlugin - #### conn=24826547353419844 op=1 binddn="uid=scarter,ou=people,dc=example,dc=com"
[09/Jan/2017:16:02:01 -0500] NSACLPlugin - conn=24826547353419844 op=1 (main): Allow search on entry(ou=people,dc=example,dc=com).attr(uid) to uid=scarter,ou=people,dc=example,dc=com: allowed by aci(2): aciname= "Enable anonymous access", acidn="dc=example,dc=com"