Chapter 7. Log File Reference

PDF

Red Hat Directory Server (Directory Server) provides logs to help monitor directory activity. Monitoring helps quickly detecting and remedying failures and, where done proactively, anticipating and resolving potential problems before they result in failure or poor performance. Part of monitoring the directory effectively is understanding the structure and content of the log files.

This chapter does not provide an exhaustive list of log messages. However, the information presented in this chapter serves as a good starting point for common problems and for better understanding the information in the access, error, and audit logs.

Logs are kept per Directory Server instances and are located in the /var/log/dirsrv/slapd-instance directory.

7.1. Access Log Reference

The Directory Server access log contains detailed information about client connections to the directory. A connection is a sequence of requests from the same client with the following structure:

Connection record, which provides the connection index and the IP address of the client
Bind record
Bind result record
Sequence of operation request and operation result pairs of records, or individual records in the case of connection, closed, and abandon records
Unbind record
Closed record

The following is an example access log entry:

[23/Jun/2020:16:30:27.388006333 -0400] conn=20 op=5 SRCH base="dc=example,dc=com" scope=2 filter="(&(objectClass=top)(objectClass=ldapsubentry)(objectClass=passwordpolicy))" attrs="distinguishedName"

Apart from connection, closed, and abandon records, which appear individually, all records appear in pairs, consisting of a request for service record followed by a RESULT record:

[23/Jun/2020:16:30:27.390881301 -0400] conn=20 op=5 RESULT err=0 tag=101 nentries=0 wtime=0.000035342 optime=0.002877749 etime=0.002911121

The RESULT message contains the following performance-related entries:;

wtime: The amount of time the operation was waiting in the work queue before a worker thread picked up the operation
optime: The amount of time it took for the actual operation to perform the task
etime: The elapsed time, which covers the time the operation was received by the server to when the server sent back the result to the client

Note

The wtime and optime values provide useful information about how the server handles load and processes operations. Due to the timing of when Directory Server gathers these statistics, the sum of the wtime and optime values are slightly greater than the etime value. However, this very small difference is negligible.

The access logs have different levels of logging, set in the nsslapd-accesslog-level attribute. The following sections provide an overview of the default access logging content, log levels, and the content logged at different logging levels:

Note that you cannot change the format of the access log.

7.1.1. Access Logging Levels

Different levels of access logging generate different amounts of detail and record different kinds of operations. The log level is set in the instance’s Section 3.1.1.2, “nsslapd-accesslog-level (Access Log Level)” configuration attribute. The default level of logging is level 256, which logs access to an entry, but there are four different log levels available:

0 = No access logging.
4 = Logging for internal access operations.
256 = Logging for access to an entry.
512 = Logging for access to an entry and referrals.

This levels are additive, so to enable several different kinds of logging, add the values of those levels together. For example, to log internal access operations, entry access, and referrals, set the value of nsslapd-accesslog-level to 516 (512+4).

7.1.2. Default Access Logging Content

This section describes the access log content in detail based on the default access logging level extract shown below.

Example 7.1. Example Access Log

[21/Apr/2020:11:39:51 -0700] conn=11 fd=608 slot=608 connection from 207.1.153.51 to 192.18.122.139
[21/Apr/2020:11:39:51 -0700] conn=11 op=0 BIND dn="cn=Directory Manager" method=128 version=3
[21/Apr/2020:11:39:51 -0700] conn=11 op=0 RESULT err=0 tag=97 nentries=0 etime=0
[21/Apr/2020:11:39:51 -0700] conn=11 op=1 SRCH base="dc=example,dc=com" scope=2 filter="(mobile=+1 123 456-7890)"
[21/Apr/2020:11:39:51 -0700] conn=11 op=1 RESULT err=0 tag=101 nentries=1 etime=3 notes=U
[21/Apr/2020:11:39:51 -0700] conn=11 op=2 UNBIND
[21/Apr/2020:11:39:51 -0700] conn=11 op=2 fd=608 closed - U1
[21/Apr/2020:11:39:52 -0700] conn=12 fd=634 slot=634 connection from 207.1.153.51 to 192.18.122.139
[21/Apr/2020:11:39:52 -0700] conn=12 op=0 BIND dn="cn=Directory Manager" method=128 version=3
[21/Apr/2020:11:39:52 -0700] conn=12 op=0 RESULT err=0 tag=97 nentries=0 etime=0
[21/Apr/2020:11:39:52 -0700] conn=12 op=1 SRCH base="dc=example,dc=com" scope=2 filter="(uid=bjensen)"
[21/Apr/2020:11:39:52 -0700] conn=12 op=2 ABANDON targetop=1 msgid=2 nentries=0 etime=0
[21/Apr/2020:11:39:52 -0700] conn=12 op=3 UNBIND
[21/Apr/2020:11:39:52 -0700] conn=12 op=3 fd=634 closed - U1
[21/Apr/2020:11:39:53 -0700] conn=13 fd=659 slot=659 connection from 207.1.153.51 to 192.18.122.139
[21/Apr/2020:11:39:53 -0700] conn=13 op=0 BIND dn="cn=Directory Manager" method=128 version=3
[21/Apr/2020:11:39:53 -0700] conn=13 op=0 RESULT err=0 tag=97 nentries=0 etime=0
[21/Apr/2020:11:39:53 -0700] conn=13 op=1 EXT oid="2.16.840.1.113730.3.5.3"
[21/Apr/2020:11:39:53 -0700] conn=13 op=1 RESULT err=0 tag=120 nentries=0 etime=0
[21/Apr/2020:11:39:53 -0700] conn=13 op=2 ADD dn="cn=Sat Apr 21 11:39:51 MET DST 2020,dc=example,dc=com"
[21/Apr/2020:11:39:53 -0700] conn=13 op=2 RESULT err=0 tag=105 nentries=0 etime=0 csn=3b4c8cfb000000030000
[21/Apr/2020:11:39:53 -0700] conn=13 op=3 EXT oid="2.16.840.1.113730.3.5.5"
[21/Apr/2020:11:39:53 -0700] conn=13 op=3 RESULT err=0 tag=120 nentries=0 etime=0
[21/Apr/2020:11:39:53 -0700] conn=13 op=4 UNBIND
[21/Apr/2020:11:39:53 -0700] conn=13 op=4 fd=659 closed - U1
[21/Apr/2020:11:39:55 -0700] conn=14 fd=700 slot=700 connection from 207.1.153.51 to 192.18.122.139
[21/Apr/2020:11:39:55 -0700] conn=14 op=0 BIND dn="" method=sasl version=3 mech=DIGEST-MD5
[21/Apr/2020:11:39:55 -0700] conn=14 op=0 RESULT err=14 tag=97 nentries=0 etime=0, SASL bind in progress
[21/Apr/2020:11:39:55 -0700] conn=14 op=1 BIND dn="uid=jdoe,dc=example,dc=com" method=sasl version=3 mech=DIGEST-MD5
[21/Apr/2020:11:39:55 -0700] conn=14 op=1 RESULT err=0 tag=97nentries=0 etime=0 dn="uid=jdoe,dc=example,dc=com"
[21/Apr/2020:11:39:55 -0700] conn=14 op=2 UNBIND
[21/Apr/2020:11:39:53 -0700] conn=14 op=2 fd=700 closed - U1

Connection Number

Every external LDAP request is listed with an incremental connection number, in this case conn=11, starting at conn=0 immediately after server startup.

[21/Apr/2020:11:39:51 -0700] conn=11 fd=608 slot=608 connection from 207.1.153.51 to 192.18.122.139

Internal LDAP requests are not recorded in the access log by default. To activate the logging of internal access operations, specify access logging level 4 on the Section 3.1.1.2, “nsslapd-accesslog-level (Access Log Level)” configuration attribute.

File Descriptor

Every connection from an external LDAP client to Directory Server requires a file descriptor or socket descriptor from the operating system, in this case fd=608. fd=608 indicates that it was file descriptor number 608 out of the total pool of available file descriptors which was used.

[21/Apr/2020:11:39:51 -0700] conn=11 fd=608 slot=608 connection from 207.1.153.51 to 192.18.122.139

Slot Number

The slot number, in this case slot=608, is a legacy part of the access log which has the same meaning as file descriptor. Ignore this part of the access log.

[21/Apr/2020:11:39:51 -0700] conn=11 fd=608 slot=608 connection from 207.1.153.51 to 192.18.122.139

Operation Number

To process a given LDAP request, Directory Server will perform the required series of operations. For a given connection, all operation request and operation result pairs are given incremental operation numbers beginning with op=0 to identify the distinct operations being performed.

[21/Apr/2020:11:39:51 -0700] conn=11 op=0 RESULT err=0 tag=97 nentries=0 etime=0

In Section 7.1.2, “Default Access Logging Content”, we have op=0 for the bind operation request and result pair, then op=1 for the LDAP search request and result pair, and so on. The entry op=-1 in the access log generally means that the LDAP request for this connection was not issued by an external LDAP client but, instead, initiated internally.

Method Type

The method number, in this case method=128, indicates which LDAPv3 bind method was used by the client.

[21/Apr/2020:11:39:51 -0700] conn=11 op=0 BIND dn="cn=Directory Manager" method=128 version=3

There are three possible bind method values:

0 for authentication
128 for simple bind with user password
sasl for SASL bind using external authentication mechanism

Version Number

The version number, in this case version=3, indicates the LDAP version number (either LDAPv2 or LDAPv3) that the LDAP client used to communicate with the LDAP server.

[21/Apr/2020:11:39:51 -0700] conn=11 op=0 BIND dn="cn=Directory Manager" method=128 version=3

Error Number

The error number, in this case err=0, provides the LDAP result code returned from the LDAP operation performed. The LDAP error number 0 means that the operation was successful. For a more comprehensive list of LDAP result codes, see Section 7.4, “LDAP Result Codes”.

[21/Apr/2020:11:39:51 -0700] conn=11 op=0 RESULT err=0 tag=97 nentries=0 etime=0

Tag Number

The tag number, in this case tag=97, indicates the type of result returned, which is almost always a reflection of the type of operation performed. The tags used are the BER tags from the LDAP protocol.

[21/Apr/2020:11:39:51 -0700] conn=11 op=0 RESULT err=0 tag=97 nentries=0 etime=0

Table 7.1. Commonly-Used Tags
Tag	Description
tag=97	Result from a client bind operation.
tag=100	The actual entry being searched for.
tag=101	Result from a search operation.
tag=103	Result from a modify operation.
tag=105	Result from an add operation.
tag=107	Result from a delete operation.
tag=109	Result from a moddn operation.
tag=111	Result from a compare operation.
tag=115	Search reference when the entry on which the search was performed holds a referral to the required entry. Search references are expressed in terms of a referral.
tag=120	Result from an extended operation.
tag=121	Result from an intermediate operation.

Note

tag=100 and tag=115 are not result tags as such, and so it is unlikely that they will be recorded in the access log.

Number of Entries

nentries shows the number of entries, in this case nentries=0, that were found matching the LDAP client’s request.

[21/Apr/2020:11:39:51 -0700] conn=11 op=0 RESULT err=0 tag=97 nentries=0 etime=0

Elapsed Time

etime shows the elapsed time, in this case etime=3, or the amount of time (in seconds) that it took the Directory Server to perform the LDAP operation.

[21/Apr/2020:11:39:51 -0700] conn=11 op=1 RESULT err=0 tag=101 nentries=1 etime=3 notes=U

An etime value of 0 means that the operation actually took 0 nanoseconds to perform.

LDAP Request Type

The LDAP request type indicates the type of LDAP request being issued by the LDAP client. Possible values are:

SRCH for search
MOD for modify
DEL for delete
ADD for add
MODDN for moddn
EXT for extended operation
ABANDON for abandon operation

If the LDAP request resulted in sorting of entries, then the message SORT serialno will be recorded in the log, followed by the number of candidate entries that were sorted. For example:

[04/May/2020:15:51:46 -0700] conn=114 op=68 SORT serialno (1)

The number enclosed in parentheses specifies the number of candidate entries that were sorted, which in this case is 1.

LDAP Response Type

The LDAP response type indicates the LDAP response being issued by the LDAP client. There are three possible values:

RESULT
ENTRY
REFERRAL, an LDAP referral or search reference

Search Indicators

Directory Server provides additional information on searches in the notes field of log entries. For example:

[21/Apr/2016:11:39:51 -0700] conn=11 op=1 RESULT err=0 tag=101 nentries=1 etime=3 notes=U

The following search indicators exist:

Paged Search Indicator: notes=P

LDAP clients with limited resources can control the rate at which an LDAP server returns the results of a search operation. When the search performed used the LDAP control extension for simple paging of search results, Directory Server logs the notes=P paged search indicator. This indicator is informational and no further actions are required.

For more details, see RFC 2696.

Unindexed Search Indicators: notes=A and notes=U

When attributes are not indexed, Directory Server must search them in the database directly. This procedure is more resource-intensive than searching the index file.

The following unindexed search indicators can be logged:

notes=A
All candidate attributes in the filter were unindexed and a full table scan was required. This can exceed the value set in the nsslapd-lookthroughlimit parameter.
notes=U
This state is set in the following situations:
- At least one of the search terms is unindexed.
- The limit set in the nsslapd-idlistscanlimit parameter was reached during the search operation. For details, see Section 4.4.1.9, “nsslapd-idlistscanlimit”.
  Unindexed searches occur in the following scenarios:
The nsslapd-idlistscanlimit parameter’s value was reached within the index file used for the search.
No index file existed.
The index file was not configured in the way required by the search.
To optimize future searches, add frequently searched unindexed attributes to the index. For details, see the corresponding section in the Directory Server Administration Guide.
Note
An unindexed search indicator is often accompanied by a large etime value, as unindexed searches are generally more time consuming.

Beside a single value, the notes field can have the following value combinations: notes=P,A and notes=U,P.

VLV-Related Entries

When a search involves virtual list views (VLVs), appropriate entries are logged in the access log file. Similar to the other entries, VLV-specific entries show the request and response information side by side:

VLV RequestInformation ResponseInformation

RequestInformation has the following form:

beforeCount:afterCount:index:contentCount

If the client uses a position-by-value VLV request, the format for the first part, the request information would be beforeCount: afterCount: value.

ResponseInformation has the following form:

targetPosition:contentCount (resultCode)

The example below highlights the VLV-specific entries:

[07/May/2020:11:43:29 -0700] conn=877 op=8530 SRCH base="(ou=People)" scope=2 filter="(uid=*)"
[07/May/2020:11:43:29 -0700] conn=877 op=8530 SORT uid
[07/May/2020:11:43:29 -0700] conn=877 op=8530 VLV 0:5:0210 10:5397 (0)
[07/May/2020:11:43:29 -0700] conn=877 op=8530 RESULT err=0 tag=101 nentries=1 etime=0

In the above example, the first part, 0:5:0210, is the VLV request information:

The beforeCount is 0.
The afterCount is 5.
The value is 0210.

The second part, 10:5397 (0), is the VLV response information:

The targetPosition is 10.
The contentCount is 5397.
The (resultCode) is (0).

Search Scope

The entry scope=n defines the scope of the search performed, and n can have a value of 0, 1, or 2.

0 for base search
1 for one-level search
2 for subtree search

Extended Operation OID

An extended operation OID, such as EXT oid="2.16.840.1.113730.3.5.3" or EXT oid="2.16.840.1.113730.3.5.5" in Example 7.1, “Example Access Log”, provides the OID of the extended operation being performed. Table 7.2, “LDAPv3 Extended Operations Supported by Directory Server” provides a partial list of LDAPv3 extended operations and their OIDs supported in Directory Server.

Table 7.2. LDAPv3 Extended Operations Supported by Directory Server
Extended Operation Name	Description	OID
Directory Server Start Replication Request	Sent by a replication initiator to indicate that a replication session is requested.	2.16.840.1.113730.3.5.3
Directory Server Replication Response	Sent by a replication responder in response to a Start Replication Request Extended Operation or an End Replication Request Extended Operation.	2.16.840.1.113730.3.5.4
Directory Server End Replication Request	Sent to indicate that a replication session is to be terminated.	2.16.840.1.113730.3.5.5
Directory Server Replication Entry Request	Carries an entry, along with its state information (`csn` and `UniqueIdentifier`) and is used to perform a replica initialization.	2.16.840.1.113730.3.5.6
Directory Server Bulk Import Start	Sent by the client to request a bulk import together with the suffix being imported to and sent by the server to indicate that the bulk import may begin.	2.16.840.1.113730.3.5.7
Directory Server Bulk Import Finished	Sent by the client to signal the end of a bulk import and sent by the server to acknowledge it.	2.16.840.1.113730.3.5.8

Change Sequence Number

The change sequence number, in this case csn=3b4c8cfb000000030000, is the replication change sequence number, indicating that replication is enabled on this particular naming context.

Abandon Message

The abandon message indicates that an operation has been aborted.

[21/Apr/2020:11:39:52 -0700] conn=12 op=2 ABANDON targetop=1 msgid=2 nentries=0 etime=0

nentries=0 indicates the number of entries sent before the operation was aborted, etime=0 value indicates how much time (in seconds) had elapsed, and targetop=1 corresponds to an operation value from a previously initiated operation (that appears earlier in the access log).

There are two possible log ABANDON messages, depending on whether the message ID succeeds in locating which operation was to be aborted. If the message ID succeeds in locating the operation (the targetop) then the log will read as above. However, if the message ID does not succeed in locating the operation or if the operation had already finished prior to the ABANDON request being sent, then the log will read as follows:

[21/Apr/2020:11:39:52 -0700] conn=12 op=2 ABANDON targetop=NOTFOUND msgid=2

targetop=NOTFOUND indicates the operation to be aborted was either an unknown operation or already complete.

Message ID

The message ID, in this case msgid=2, is the LDAP operation identifier, as generated by the LDAP SDK client. The message ID may have a different value than the operation number but identifies the same operation. The message ID is used with an ABANDON operation and tells the user which client operation is being abandoned.

[21/Apr/2020:11:39:52 -0700] conn=12 op=2 ABANDON targetop=NOTFOUND msgid=2

Note

The Directory Server operation number starts counting at 0, and, in the majority of LDAP SDK/client implementations, the message ID number starts counting at 1, which explains why the message ID is frequently equal to the Directory Server operation number plus 1.

SASL Multi-Stage Bind Logging

In Directory Server, logging for multi-stage binds is explicit. Each stage in the bind process is logged. The error codes for these SASL connections are really return codes. In Example 7.1, “Example Access Log”, the SASL bind is currently in progress so it has a return code of err=14, meaning the connection is still open, and there is a corresponding progress statement, SASL bind in progress.

[21/Apr/2020:11:39:55 -0700] conn=14 op=0 BIND dn="" method=sasl version=3 mech=DIGEST-MD5
[21/Apr/2020:11:39:55 -0700] conn=14 op=0 RESULT err=14 tag=97 nentries=0 etime=0, SASL bind in progress

In logging a SASL bind, the sasl method is followed by the LDAP Version Number and the SASL mechanism used, as shown below with the GSS-API mechanism.

[21/Apr/2020:12:57:14 -0700] conn=32 op=0 BIND dn="" method=sasl version=3 mech=GSSAPI

Note

The authenticated DN (the DN used for access control decisions) is now logged in the BIND result line as opposed to the bind request line, as was previously the case:

[21/Apr/2020:11:39:55 -0700] conn=14 op=1 RESULT err=0 tag=97 nentries=0 etime=0 dn="uid=jdoe,dc=example,dc=com"

For SASL binds, the DN value displayed in the bind request line is not used by the server and, as a consequence, is not relevant. However, given that the authenticated DN is the DN which, for SASL binds, must be used for audit purposes, it is essential that this be clearly logged. Having this authenticated DN logged in the bind result line avoids any confusion as to which DN is which.

7.1.3. Access Log Content for Additional Access Logging Levels

This section presents the additional access logging levels available in the Directory Server access log.

In Example 7.2, “Access Log Extract with Internal Access Operations Level (Level 4)”, access logging level 4, which logs internal operations, is enabled.

Example 7.2. Access Log Extract with Internal Access Operations Level (Level 4)

[12/Jul/2020:16:45:46 +0200] conn=Internal op=-1 SRCH base="cn=\22dc=example,dc=com\22,cn=mapping tree,cn=config"scope=0 filter="objectclass=nsMappingTree"attrs="nsslapd-referral" options=persistent
[12/Jul/2020:16:45:46 +0200] conn=Internal op=-1 RESULT err=0 tag=48 nentries=1etime=0
[12/Jul/2020:16:45:46 +0200] conn=Internal op=-1 SRCH base="cn=\22dc=example,dc=com\22,cn=mapping tree,cn=config"scope=0 filter="objectclass=nsMappingTree" attrs="nsslapd-state"
[12/Jul/2020:16:45:46 +0200] conn=Internal op=-1 RESULT err=0 tag=48 nentries=1etime=0

Access log level 4 enables logging for internal operations, which log search base, scope, filter, and requested search attributes, in addition to the details of the search being performed.

In the following example, access logging level 768 is enabled (512 + 256), which logs access to entries and referrals. In this extract, six entries and one referral are returned in response to the search request, which is shown on the first line.

[12/Jul/2020:16:43:02 +0200] conn=306 fd=60 slot=60 connection from 127.0.0.1 to 127.0.0.1
[12/Jul/2020:16:43:02 +0200] conn=306 op=0 SRCH base="dc=example,dc=com" scope=2 filter="(description=*)" attrs=ALL
[12/Jul/2020:16:43:02 +0200] conn=306 op=0 ENTRY dn="ou=Special
[12/Jul/2020:16:43:02 +0200] conn=306 op=0 ENTRY dn="cn=Accounting Managers,ou=groups,dc=example,dc=com"
[12/Jul/2020:16:43:02 +0200] conn=306 op=0 ENTRY dn="cn=HR Managers,ou=groups,dc=example,dc=com"
[12/Jul/2020:16:43:02 +0200] conn=306 op=0 ENTRY dn="cn=QA Managers,ou=groups,dc=example,dc=com"
[12/Jul/2020:16:43:02 +0200] conn=306 op=0 ENTRY dn="cn=PD Managers,ou=groups,dc=example,dc=com"
[12/Jul/2020:16:43:02 +0200] conn=306 op=0 ENTRY dn="ou=Red Hat Servers,dc=example,dc=com"
[12/Jul/2020:16:43:02 +0200] conn=306 op=0 REFERRAL

Connection Description

The connection description, in this case conn=Internal, indicates that the connection is an internal connection. The operation number op=-1 also indicates that the operation was initiated internally.

[12/Jul/2020:16:45:46 +0200] conn=Internal op=-1 ENTRY dn="cn=\22dc=example,dc=com\22,cn=mapping tree,cn=config"

Options Description

The options description (options=persistent) indicates that a persistent search is being performed, as distinguished from a regular search operation. Persistent searches can be used as a form of monitoring and configured to return changes to given configurations as changes occur.

Both log levels 512 and 4 are enabled for this example, so both internal access operations and entry access and referrals being logged.

[12/Jul/2020:16:45:46 +0200] conn=Internal op=-1 SRCH base="cn=\22dc=example,dc=com\22,cn=mapping tree,cn=config"scope=0 filter="objectclass=nsMappingTree"attrs="nsslapd-referral" options=persistent

7.1.4. Common Connection Codes

A connection code is a code that is added to the closed log message to provide additional information related to the connection closure.

Table 7.3. Common Connection Codes
Connection Code	Description
A1	Client aborts the connection.
B1	Corrupt BER tag encountered. If BER tags, which encapsulate data being sent over the wire, are corrupt when they are received, a B1 connection code is logged to the access log. BER tags can be corrupted due to physical layer network problems or bad LDAP client operations, such as an LDAP client aborting before receiving all request results.
B2	BER tag is longer than the `nsslapd-maxbersize` attribute value. For further information about this configuration attribute, see Section 3.1.1.118, “nsslapd-maxbersize (Maximum Message Size)”.
B3	Corrupt BER tag encountered.
B4	Server failed to flush data response back to client.
P2	Closed or corrupt connection has been detected.
T1	Client does not receive a result within the specified `idletimeout` period. For further information about this configuration attribute, see Section 3.1.1.97, “nsslapd-idletimeout (Default Idle Timeout)”.
T2	Server closed connection after `ioblocktimeout` period was exceeded. For further information about this configuration attribute, see Section 3.1.1.100, “nsslapd-ioblocktimeout (IO Block Time Out)”.
U1	Connection closed by server after client sends an unbind request. The server will always close the connection when it sees an unbind request.

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 Section 3.1.1.79, “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	Provides very detailed access control list processing information.
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 format of the error log differs compared from that of the access log:

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

Error log entries contain the following columns:

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 the cn=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 as Trace function calls (1), Access control list processing (128), and Replication (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 the ERR 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

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/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” 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.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-supplier_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-supplier_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-supplier_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

Plug-in logging records every the name of the plug-in and all of the functions called by the plug-in. 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.4, “Example ACL Plug-in Error Log Entry with Plug-in Logging”.

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

Example 7.4, “Example ACL Plug-in Error Log Entry with Plug-in Logging” shows both plug-in logging and search filter processing (log level 65696).

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.5. Config File Processing Log Entry

[29/May/2017:15:26:48.897935879 +0200] - DEBUG - collation_read_config - Reading config file /etc/dirsrv/slapd-supplier_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
...

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.6, “Access Control Summary Logging” shows the summary access control log entry.

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

7.3. Audit Log Reference

The audit log records changes made to the server instance. Unlike the error and access log, the audit log does not record access to the server instance, so searches against the database are not logged.

The audit log is formatted differently than the access and error logs and is like a time-stamped LDIF file. The operations recorded in the audit log are formatted as LDIF statements:

 timestamp: date
 dn: modified_entry
 changetype: action
 action:attribute
 attribute:new_value
 -
 replace: modifiersname
 modifiersname: dn
 -
 replace: modifytimestamp
 modifytimestamp: date
 -

LDIF files and formats are described in more detail in the "LDAP Data Interchange Format" appendix of the Administration Guide.

Several different kinds of audit entries are shown in Example 7.7, “Audit Log Content”.

Example 7.7. Audit Log Content

 ... modifying an entry ...
 time: 20200108181429
 dn: uid=scarter,ou=people,dc=example,dc=com
 changetype: modify
 replace: userPassword
 userPassword: {SSHA}8EcJhJoIgBgY/E5j8JiVoj6W3BLyj9Za/rCPOw==
 -
 replace: modifiersname
 modifiersname: cn=Directory Manager
 -
 replace: modifytimestamp
 modifytimestamp: 20200108231429Z
 -

 ... sending a replication update ...
 time: 20200109131811
 dn: cn=example2,cn=replica,cn="dc=example,dc=com",cn=mapping tree,cn=config
 changetype: modify
 replace: nsds5BeginReplicaRefresh
 nsds5BeginReplicaRefresh: start
 -
 replace: modifiersname
 modifiersname: cn=Directory Manager
 -
 replace: modifytimestamp
 modifytimestamp: 20200109181810Z
 -

Note that you cannot change to format or set a log level for the audit log.

7.4. LDAP Result Codes

Directory Server uses the following LDAP result codes:

Table 7.5. LDAP Result Codes
Decimal Values	Hex Values	Constants
0	0x00	LDAP_SUCCESS
1	0x01	LDAP_OPERATIONS_ERROR
2	0x02	LDAP_PROTOCOL_ERROR
3	0x03	LDAP_TIMELIMIT_EXCEEDED
4	0x04	LDAP_SIZELIMIT_EXCEEDED
5	0x05	LDAP_COMPARE_FALSE
6	0x06	LDAP_COMPARE_TRUE
7	0x07	LDAP_AUTH_METHOD_NOT_SUPPORTED
LDAP_STRONG_AUTH_NOT_SUPPORTED
8	0x08	LDAP_STRONG_AUTH_REQUIRED
9	0x09	LDAP_PARTIAL_RESULTS
10	0x0a	LDAP_REFERRAL ^[a]
11	0x0b	LDAP_ADMINLIMIT_EXCEEDED
12	0x0c	LDAP_UNAVAILABLE_CRITICAL_EXTENSION
13	0x0d	LDAP_CONFIDENTIALITY_REQUIRED
14	0x0e	LDAP_SASL_BIND_IN_PROGRESS
16	0x10	LDAP_NO_SUCH_ATTRIBUTE
17	0x11	LDAP_UNDEFINED_TYPE
18	0x12	LDAP_INAPPROPRIATE_MATCHING
19	0x13	LDAP_CONSTRAINT_VIOLATION
20	0x14	LDAP_TYPE_OR_VALUE_EXISTS
21	0x15	LDAP_INVALID_SYNTAX
32	0x20	LDAP_NO_SUCH_OBJECT
33	0x21	LDAP_ALIAS_PROBLEM
34	0x22	LDAP_INVALID_DN_SYNTAX
35	0x23	LDAP_IS_LEAF ^[b]
36	0x24	LDAP_ALIAS_DEREF_PROBLEM
48	0x30	LDAP_INAPPROPRIATE_AUTH
49	0x31	LDAP_INVALID_CREDENTIALS
50	0x32	LDAP_INSUFFICIENT_ACCESS
51	0x33	LDAP_BUSY
52	0x34	LDAP_UNAVAILABLE
53	0x35	LDAP_UNWILLING_TO_PERFORM
54	0x36	LDAP_LOOP_DETECT
60	0x3c	LDAP_SORT_CONTROL_MISSING
61	0x3d	LDAP_INDEX_RANGE_ERROR
64	0x40	LDAP_NAMING_VIOLATION
65	0x41	LDAP_OBJECT_CLASS_VIOLATION
66	0x42	LDAP_NOT_ALLOWED_ON_NONLEAF
67	0x43	LDAP_NOT_ALLOWED_ON_RDN
68	0x44	LDAP_ALREADY_EXISTS
69	0x45	LDAP_NO_OBJECT_CLASS_MODS
70	0x46	LDAP_RESULTS_TOO_LARGE ^[c]
71	0x47	LDAP_AFFECTS_MULTIPLE_DSAS
76	0x4C	LDAP_VIRTUAL_LIST_VIEW_ERROR
80	0x50	LDAP_OTHER
81	0x51	LDAP_SERVER_DOWN
82	0x52	LDAP_LOCAL_ERROR
83	0x53	LDAP_ENCODING_ERROR
84	0x54	LDAP_DECODING_ERROR
85	0x55	LDAP_TIMEOUT
86	0x56	LDAP_AUTH_UNKNOWN
87	0x57	LDAP_FILTER_ERROR
88	0x58	LDAP_USER_CANCELLED
89	0x59	LDAP_PARAM_ERROR
90	0x5A	LDAP_NO_MEMORY
91	0x5B	LDAP_CONNECT_ERROR
92	0x5C	LDAP_NOT_SUPPORTED
93	0x5D	LDAP_CONTROL_NOT_FOUND
94	0x5E	LDAP_MORE_RESULTS_TO_RETURN
95	0x5F	LDAP_MORE_RESULTS_TO_RETURN
96	0x60	LDAP_CLIENT_LOOP
97	0x61	LDAP_REFERRAL_LIMIT_EXCEEDED
118	0x76	LDAP_CANCELLED

^[a] LDAPv3 ^[b] Not used in LDAPv3 ^[c] Reserved for CLDAP

7.5. Replacing Log Files with a Named Pipe

Many administrators want to do some special configuration or operation with logging data, like configuring an access log to record only certain events. This is not possible using the standard Directory Server log file configuration attributes, but it is possible by sending the log data to a named pipe, and then using another script to process the data. Using a named pipe for the log simplifies these special tasks, like:

Logging certain events, like failed bind attempts or connections from specific users or IP addresses
Logging entries which match a specific regular expression pattern
Keeping the log to a certain length (logging only the last number of lines)
Sending a notification, such as an email, when an event occurs

Replacing a log file with a pipe improves performance, especially on servers with a high rate of operations.

The named pipe is different than using a script to extract data from the logs because of how data are handled in the log buffer.

If a log is buffered, server performance is good, but important data are not written to disk (the log file) as soon as the event occurs. If the server is having a problem with crashing, it may crash before the data is written to disk — and there is no data for the script to extract.

If a log is not buffered^[1], the writes are flushed to disk with each operation, causing a lot of disk I/O and performance degradation.

Replacing the log disk file with a pipe has the benefits of buffering, since the script that reads from the pipe can buffer the incoming log data in memory (which is not possible with a simple script).

The usage and option details for the script is covered in Section 9.4, “ds-logpipe.py”. The basic format is: ds-logpipe.py/path/to/named_pipe--userpipe_user--maxlinesnumber--serverpidfilefile.pid--serverpidPID--servertimeoutseconds--plugin=/path/to/plugin.pypluginfile.arg=value

7.5.1. Using the Named Pipe for Logging

The Directory Server instance can use a named pipe for its logging simply by running the named pipe log script and giving the name of the pipe. (If the server is already running, then the log has to be reopened, but there is no configuration required otherwise.)

# ds-logpipe.py /var/log/dirsrv/slapd-example/access

Running the ds-logpipe.py in this way has the advantage of being simple to implement and not requiring any Directory Server configuration changes. This is useful for fast debugging or monitoring, especially if you are looking for a specific type of event.

If the Directory Server instance will frequently or permanently use the named pipe rather than a real file for logging, then it is possible to reconfigure the instance to create the named pipe and use it for logging (as it does by default for the log files).

Three things need to be configured for the log configuration for the instance:

The log file to use has to be changed to the pipe (nsslapd-*log, where the * can be access, error, or audit^[2], depending on the log type being configured)
Buffering should be disabled because the script already buffers the log entries (nsslapd-*log-logbuffering)
Log rotation should be disabled so that the server does not attempt to rotate the named pipe (nsslapd-*log-maxlogsperdir, nsslapd-*log-logexpirationtime, and nsslapd-*log-logrotationtime)

These configuration changes can be made in the Directory Server Console or using ldapmodify.

For example, this switches the access log to access.pipe:

# ldapmodify -D "cn=Directory Manager" -W -p 389 -h server.example.com -x

dn: cn=config
changetype: modify
replace: nsslapd-accesslog
nsslapd-accesslog: /var/log/dirsrv/slapd-instance/access.pipe
-
replace: nsslapd-accesslog-logbuffering
nsslapd-accesslog-logbuffering: off
-
replace: nsslapd-accesslog-maxlogsperdir
nsslapd-accesslog-maxlogsperdir: 1
-
replace: nsslapd-accesslog-logexpirationtime
nsslapd-accesslog-logexpirationtime: -1
-
replace: nsslapd-accesslog-logrotationtime
nsslapd-accesslog-logrotationtime: -1

Note

Making these changes causes the server to close the current log file and switch to the named pipe immediately. This can be very helpful for debugging a running server and sifting the log output for specific messages.

7.5.2. Starting the Named Pipe with the Server

The named pipe can be started and shut down along with the Directory Server instance by editing the instance’s init script configuration file.

Note

The named pipe script has to be specifically configured in the instance’s dse.ldif file before it can be called at server startup.

Open the instance configuration file for the server system.
```
/etc/sysconfig/dirsrv-instance_name
```
Warning
Do not edit the /etc/sysconfig/dirsrv file.

At the end of the file, there will be a line that reads:

# Put custom instance specific settings below here.

Below that line, insert the ds-logpipe.py command to launch when the server starts. For example:

# only keep the last 1000 lines of the error log
python /usr/bin/ds-logpipe.py /var/log/dirsrv/slapd-example/errors.pipe -m 1000 -u dirsrv -s /var/run/dirsrv/slapd-example.pid > /var/log/dirsrv/slapd-example/errors &

# only log failed binds
python /usr/bin/ds-logpipe.py /var/log/dirsrv/slapd-example/access.pipe -u dirsrv -s /var/run/dirsrv/slapd-example.pid --plugin=/usr/share/dirsrv/data/failedbinds.py failedbinds.logfile=/var/log/dirsrv/slapd-example/access.failedbinds &

Note

The -s option both specifies the .pid file for the server to write its PID to and sets the script to start and stop with the server process.

7.5.3. Using Plug-ins with the Named Pipe Log

A plug-in can be called to read the log data from the named pipe and perform some operation on it. There are some considerations with using plug-ins with the named pipe log script:

The plug-in function is called for every line read from the named pipe.
The plug-in function must be a Python script and must end in .py.
Any plug-in arguments are passed in the command line to the named pipe log script.
A pre-operation function can be specified for when the plug-in is loaded.
A post-operation function can be called for when the script exits.

7.5.3.1. Loading Plug-ins with the Named Pipe Log Script

There are two options with ds-logpipe.py to use for plug-ins:

The --plugin option gives the path to the plug-in file (which must be a Python script and must end in .py).
The plugin.arg option passes plug-in arguments to the named pipe log script. The plug-in file name (without the .py extension) is plugin and any argument allowed in that plug-in can be arg .

For example:

ds-logpipe.py /var/log/dirsrc/slapd-example/errors.pipe --plugin=/usr/share/dirsrv/data/example-funct.py example-funct.regex="warning" > warnings.txt

If there are more than one values passed for the same argument, then they are converted into a list of values in the plug-in dict. For example, this script gives two values for arg1:

--plugin=/path/to/pluginname.py pluginname.arg1=foo pluginname.arg1=bar pluginname.arg2=baz

In the plug-in, this is converted to:

{'arg1': ['foo', 'bar'],
 'arg2': 'baz'}

This is a Python dict object with two keys. The first key is the string arg1, and its value is a Python list object with two elements, the strings foo and bar. The second key is the string arg2, and its value is the string baz. If an argument has only a single value, it is left as a simple string. Multiple values for a single argument name are converted into a list of strings.

7.5.3.2. Writing Plug-ins to Use with the Named Pipe Log Script

The ds-logpipe.py command expects up to three functions in any plug-in: plugin (), pre (), and post ().

Any plug-in used with the ds-logpipe.py command must specify the plugin function.

The plugin () function is performed against every line in the log data, while the pre () and post () functions are run when the script is started and stopped, respectively.

Each function can have any arguments defined for it, and these arguments can then be passed to the script using the plugin.arg option. Additionally, each function can have its own return values and actions defined for it.

Example 7.8. Simple Named Pipe Log Plug-in

def pre(myargs):
    retval = True
    myarg = myargs['argname']
    if isinstance(myarg, list): # handle list of values
    else: # handle single value
    if bad_problem:
        retval = False
    return retval

def plugin(line):
    retval = True
    # do something with line
    if something_is_bogus:
        retval = False
    return retval

def post(): # no arguments
    # do something
    # no return value

^[1] Server performance suffers when log buffering is disabled on the access log, when the log level is changed on the error log, or with audit logging.

^[2] The audit log is not enabled by default, so this log has to be enabled before a named pipe can be used to replace it.

Chapter 7. Log File Reference

7.1. Access Log Reference

7.1.1. Access Logging Levels

7.1.2. Default Access Logging Content

7.1.3. Access Log Content for Additional Access Logging Levels

7.1.4. Common Connection Codes

7.2. Error Log Reference

7.2.1. Error Log Logging Levels

7.2.2. Error Log Content

7.2.3. Error Log Content for Other Log Levels

7.3. Audit Log Reference

7.4. LDAP Result Codes

7.5. Replacing Log Files with a Named Pipe

7.5.1. Using the Named Pipe for Logging

7.5.2. Starting the Named Pipe with the Server

7.5.3. Using Plug-ins with the Named Pipe Log

7.5.3.1. Loading Plug-ins with the Named Pipe Log Script

7.5.3.2. Writing Plug-ins to Use with the Named Pipe Log Script

Learn

Try, buy, & sell

Communities

About Red Hat Documentation

Making open source more inclusive

About Red Hat

Red Hat legal and privacy links

Red Hat legal and privacy links