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.