Symas OpenLDAP Knowledge Base

Understanding OpenLDAP Logs

The primary tool for troubleshooting OpenLDAP problems is the slapd log file. The location of this file is set in the configuration files (slapd.conf or slapd.ldif). The default is /opt/symas/openldap/slapd.log. The logging settings should follow the recommendations in Setting Up the OpenLDAP Log. Enabling microsecond timing increases the size of the log entries but the information about performance is extremely valuable.

Symas has written a number of utility programs that produce simple summary information about a slapd log file. It can be downloaded from our git repository. For more information see Symas Log Reduction Tools.

Why We Look at Logs

The slapd.log settings Symas (logLevel/olcLogLevel) recommends for production servers are “stats sync”. “stats” entries log request and result informatin for every LDAP operation serviced by the OpenLDAP server. “sync” entries record the Consumer’s activities processing updates from servers providing them replication feeds (Producers/Masters/Hubs). These logs contain a lot of very useful information. Too much information to handle without a good idea of how to read them.

We generally don’t read them. We let them rotate out and get stored for a while. They are only useful when things go wrong. Wrong means performance is bad. Wrong means client applications are getting unexpected error result codes. Wrong means the server shut down.

Then they are the starting point for understanding what is happening or happened.

General Format of a Log Record

The log records have two basic parts. The first is a preamble with the date-time-stamp, the name of the host/server, and the process name (usually slapd) and its process ID (number). This is terminated by a colon and a blank character (“:”). The preamble is important because it contains the time. When bouncing around among log files, the server’s name is occasionally useful.

The second part of the log record is the actual logged data. For normal LDAP requests (output from the STATS logging level) the data is straightforward. Each request generates predictable and (relatively) readable sequences of log lines. LDAP request lines start with two keyword fields, the connection number (conn=1234), a space, and either a file descriptor number (only on ACCEPT requests) or an operation number (op=0).

There are three completely different types of log entries: LDAP request related entries, syncrepl processing related entries, and other interesting entries. That last category includes records about slapd startup and shutdown and unindexed attributes referenced in search filters.

Connections and File Descriptors

OpenLDAP creates a file ID and assigns it to a (potential) connection when it gets an ACCEPT request. ACCEPT is a request for a new connection. It sets the stage for multiple requests using that connection. ACCEPT generally performs the TLS (encryption, security) verification. In non-TLS connections, it merely triggers OpenLDAP to handle the requests.

In a TLS environment if there are certificate errors or other problems with establishing the TLS connection, you will see the conection being closed with “TLS negotiation failure”. Amazon’s AWS uses a pattern where negotiation failures are used to verify that the server is still running. It’s not uncommon for an AWS OpenLDAP server to be dominated by this pattern. # LDAP Request Related Log Entries{id=“ldap-requests”)

Requests

Once a connection is created, LDAP requests will each be given a sequence number within the connection. The first request is op=0, the second, op=1, and so on. An OpenLDAP server often has several (sometimes many) requests at a time. That means that the various log records will be intermixed. You will need to puzzle out the sequence of a particular request by finding all the pieces and following the request’s progress that way.

The first request after ACCEPT is generally a BIND, establishing the identity of the principle requesting the service and authenticating them for use in checking permissions for subsequent requests. The most common pattern is for a connection to use the credentials established with this first BIND for those later requests.

The LDAP Request Logging Pattern

Using the BIND request’s form:

    conn=1234 op=0 BIND dn="cn=bowser,ou=puppies,dc=example,dc=com" <bind method>

Often there are several BIND records as OpenLDAP and the client LDAP application negotiate to establish a connection at a security level demanded by the OpenLDAP configuration’s settings.

The end of BIND processing produces a RESULT record with the same connection and operation numbers.

    conn=1234 op=0 RESULT tag=97 err=0 qtime=0.000017 etime=0.000456 text=

This pattern of one or more lines for the details of the request followed by a RESULT record is consistent for all of the LDAP request records except SRCH (search) which returns a SEARCH RESULT.

SRCH

The SRCH log entres contain a great deal of information that helps solve various kinds of puzzles. They generally span multiple entries. In handling support requests, the Symas team ignores all of the details about the search in the first evaluation of the log. This is also true of the complexities of ATTACH, BIND, and others. We’ll see why shortly.

Some Explanations

tag

Tags are internal flags within OpenLDAP. They are not particularly useful in reading OpenLDAP logs.

err

The err information is an LDAP Return Code as defined in the RFC. You can find an annotated list in this Knowledge Base.

Not all err values are errors. err=0 says the request was handled without error. 5 and 6 are just result flags to tell the requesting application of the results of compare (COMP). 5 is equal, 6 is not equal. 14 says a SASL BIND is in progress. None of these are errors. The rest indicate that something went wrong.

qtime

qtime and etime are presented by recent versions of OpenLDAP configured for microsecond timing. Otherwise they are not present. Where high accuracy timing is in the log the date-time-stamp is also recorded in microseconds.

qtime is the time, in microseconds, the request was in a queue waiting to be dispatched for processing. qtime is normall very small and consistent. When it is higher, it indicates that OpenLDAP is constrained somehow. That’s an important tuning signal and may indicate the need for more system resources.

etime

etime is the time OpenLDAP took to process the request. etimes are highly variable. Each request presents OpenLDAP with varying levels of complexity and demands on database handling. All of that is generally reflected in etime. Long etimes can be correlated back the parameters on the request. etime is a more important metric for studying performance than qtime in most cases.

nentries

nentries reports the number of entries returned. Also useful in performance studies.

text

text is usually blank.

syncrepl Related Log Entries

Other Interesting Entries