The 389-ds access logs write multiple lines per connection. The contents of the logging will vary in particular based on the bind type (simple, over TLS, GSSAPI, etc).
Each line will typically consist of the date, a connection id, the operation and the result. Because there may be simultaneous connections their operations are likely to be interleaved. The connection id (conn) can be used to trace the path of a specific request. Typically this begins with connection information (IP address, TLS parameters, etc) followed by a BIND operation. So the important bit is, when tracing what happens during a specific connection, is to focus on the connection id to be sure you have the whole picture.
Each line represents a step in the operation being performed. Each consists of the operation (BIND, SRCH, RESULT, etc), the operation number so you can keep track of the requests on a given connection which may be long-lived and a disconnection.
The typical operations are: BIND, SRCH, ADD, MOD, DEL, UNBIND. There are certainly others.
Each operation is typically a set of two. The operation being executed and the result of that operation. The result will include things like any errors through (err), the number of entries returned (nentries) and a series of time values indicating how long the operation took. This can be useful for identifying inefficient queries. See logconv.pl(1).
The err values are LDAP return codes. They can be looked up at https://ldap.com/ldap-result-code-reference/
Connection ids will be re-used. They are reset when the server starts and may roll over if the server is up for an extended period under load. So time frame needs to be considered when grouping connections.
An LDAP simple bind over TLS will look like:
[15/Feb/2024:11:41:12.698632329 -0500] conn=325 fd=117 slot=117 SSL connection from 192.168.166.203 to 192.168.166.203
[15/Feb/2024:11:41:12.718960923 -0500] conn=325 TLS1.3 128-bit AES-GCM
[15/Feb/2024:11:41:12.719343297 -0500] conn=325 op=0 BIND dn="uid=admin,cn=users,cn=accounts,dc=example,dc=test" method=128 version=3
[15/Feb/2024:11:41:12.771298989 -0500] conn=325 op=0 RESULT err=0 tag=97 nentries=0 wtime=0.012408745 optime=0.051979560 etime=0.064381665 dn="uid=admin,cn=users,cn=accounts,dc=example,dc=test"
[15/Feb/2024:11:41:12.771724949 -0500] conn=325 op=1 SRCH base="dc=example,dc=test" scope=2 filter="(uid=admin)" attrs=ALL
[15/Feb/2024:11:41:12.772827491 -0500] conn=325 op=1 RESULT err=0 tag=101 nentries=1 wtime=0.000191261 optime=0.001104895 etime=0.001291433
[15/Feb/2024:11:41:12.773500844 -0500] conn=325 op=2 UNBIND
[15/Feb/2024:11:41:12.773542177 -0500] conn=325 op=2 fd=117 Disconnect - Cleanly Closed Connection - U1
So we have connection 325 over a TLS 1.3 connection. A simple bind is done of the IPA admin user. A single search on the base dn for uid=admin is done and a single entry is returned. The search took a small fraction of a second.
A GSSAPI bind will consist of several steps followed by the DN of the user who authenticated, like:
[15/Feb/2024:11:38:05.465936114 -0500] conn=324 op=0 BIND dn="" method=sasl version=3 mech=GSSAPI
[15/Feb/2024:11:38:05.474888818 -0500] conn=324 op=0 RESULT err=14 tag=97 nentries=0 wtime=0.029944980 optime=0.008965664 etime=0.038906293, SASL bind in progress
[15/Feb/2024:11:38:05.475749299 -0500] conn=324 op=1 BIND dn="" method=sasl version=3 mech=GSSAPI
[15/Feb/2024:11:38:05.481930964 -0500] conn=324 op=1 RESULT err=14 tag=97 nentries=0 wtime=0.000169153 optime=0.006191132 etime=0.006355927, SASL bind in progress
[15/Feb/2024:11:38:05.482764551 -0500] conn=324 op=2 BIND dn="" method=sasl version=3 mech=GSSAPI
[15/Feb/2024:11:38:05.485585358 -0500] conn=324 op=2 RESULT err=0 tag=97 nentries=0 wtime=0.000175929 optime=0.002828423 etime=0.002999273 dn="uid=admin,cn=users,cn=accounts,dc=example,dc=test"
GSSAPI takes more steps because of the authentication protocol. This is expected.
The log is buffered by default, writing to disk every 30 seconds. This is to save on I/O costs. To disable the buffering, for troubleshooting for example, apply this ldif:
dn: cn=config
changetype: modify
add: nsslapd-accesslog-logbuffering
nsslapd-accesslog-logbuffering: off
Disabling buffering all the time will negatively affect performance.
Frustrations 