Sun Java System Directory Server Enterprise Edition 6.2 Reference

Tracking Client Requests Through Directory Proxy Server and Directory Server Access Logs

Access logs show client accesses to the server and corresponding server responses. Directory Proxy Server access logs further show information about the connections set up against data sources, in this case Directory Server instances.

Tracking client requests can be broken down into the following steps:

Tracking the operations performed within a single client connection
Identifying the client that performed a certain operation

Tracking Operations by Connection

Directory Proxy Server typically sets up connections with backend servers before it handles client connections. This means that the proxy can pool operations, binding and rebinding only when necessary and avoiding connection setup overhead. Directory Proxy Server identifies these backend connections in its access log with tags of the form s_conn=data-source:number, where data-source is a data source name from the configuration and number is a server connection number assigned by the proxy. Such s_conn server connections can then be matched to connection numbers in Directory Server access logs using the port number from which the proxy connected to the directory as a client when establishing the connection. Therefore, s_conn in proxy access log messages be translated into conn in directory access log messages.

Tracking Operations in Directory Proxy Server

In the Directory Proxy Server access log, each client operation is contained within a CONNECT and a DISCONNECT message. Between these two messages, several OPERATION messages can appear. Each OPERATION message can contain several SERVER_OP messages.

The OPERATION messages refer to operations performed by the client. The SERVER_OP messages refer to operations performed by Directory Proxy Server.

The following extract of a Directory Proxy Server access log file shows the start (CONNECT) and end (DISCONNECT) of a connection, conn=0. The log shows all the OPERATION requests performed by a client this connection and the related SERVER_OP requests sent to the backend server by Directory Proxy Server on behalf of the client.

[timestamp] - CONNECT    - INFO  - conn=0 client=129.157.192.132:59112 server=0.0.0.0:9389 protocol=LDAP
[timestamp] - OPERATION  - INFO  - conn=0 op=0 BIND dn="uid=u1,ou=users,o=movie" method="SIMPLE"
[timestamp] - SERVER_OP  - INFO  - conn=0 op=0 BIND dn="uid=u1,ou=users,o=movie" method="SIMPLE" s_msgid=2 
                                                    s_conn=server-1:1
[timestamp] - SERVER_OP  - INFO  - conn=0 op=0 BIND RESPONSE err=0 msg="" s_conn=server-1:1
[timestamp] - OPERATION  - INFO  - conn=0 op=0 BIND RESPONSE err=0 msg="" etime=0
[timestamp] - OPERATION  - INFO  - conn=0 op=1 msgid=2 SEARCH base="o=movie" scope=2 filter="(objectclass=*)"
[timestamp] - SERVER_OP  - INFO  - conn=0 op=1 SEARCH base="o=movie" scope=2 filter="(objectclass=*)" s_msgid=3 
                                                      s_conn=server-1:1
[timestamp] - SERVER_OP  - INFO  - conn=0 op=1 SEARCH RESPONSE err=0 msg="" nentries=12 s_conn=server-1:1
[timestamp] - OPERATION  - INFO  - conn=0 op=1 SEARCH RESPONSE err=0 msg="" nentries=12 etime=0
[timestamp] - OPERATION  - INFO  - conn=0 op=2 UNBIND
[timestamp] - SERVER_OP  - INFO  - conn=0 op=-1 BIND dn="" method="SIMPLE" s_msgid=4 s_conn=server-1:1
[timestamp] - SERVER_OP  - INFO  - conn=0 op=-1 BIND RESPONSE err=0 msg="" s_conn=server-1:1
[timestamp] - DISCONNECT - INFO  - conn=0 reason="unbind"

Following this log, it is possible to track all operations that were performed by or on behalf of a particular client.

Tracking Operations Between Directory Proxy Server and Directory Server

When Directory Proxy Server starts up, it establishes connections with all the remote servers identified in its configuration. These connections are logged in the Directory Proxy Server access log, and are identified by the field s_conn=server-name:number. The server-name is defined in the Directory Proxy Server configuration and refers to a specific backend server. The number indicates how many connections there have been to this backend server, through the same port.

For example, in the following extract from the Directory Proxy Servers_conn=server-1:1 is the first connection to remote server server-1 through port 59100.

SERVER_OP - INFO - Created connection for BIND s_conn=server-1:1 client=129.157.192.132:59100

When this connection is established, the corresponding line in the Directory Server access log shows that the connection from Directory Proxy Server through port 59100 is identified with the connection ID conn=244.

conn=244 op=-1 msgId=-1 - fd=19 slot=19 LDAP connection from 129.157.192.132:59100 to 129.157.192.132

For the remainder of the life of this connection, server-1:1 in the Directory Proxy Server can be mapped to conn=24 in the Directory Server access log.

This kind of mapping between connections also requires that Directory Proxy Server and the backend Directory Server are synchronized.

Note that a connection from Directory Proxy Server to a backend Directory Server can remain alive for several days. If you rotate logs, either manually or automatically, it might therefore be necessary to access archived log files to trace the operations performed during a connection.

Client Identification

A client is identified in the access logs by its IP address and, optionally, by its bind DN. When a client establishes a connection to Directory Proxy Server, the following kind of message is logged in the Directory Proxy Server access log:

[timestamp] - CONNECT  - INFO  - conn=0 client=IP1:port1 server=IP2:port2 protocol=LDAP

Directory Proxy Server identifies this client connection as conn=0.

When Directory Proxy Server establishes a connection with a remote Directory Server, the following kind of message is logged in the Directory Proxy Server access log:

[timestamp] - SERVER_OP  - INFO  - Created connection for READ s_conn=server-1:1 client=IP2:port3 
 server=IP4:port4 protocol=LDAP main

Directory Proxy Server identifies this connection to the remote server as s_conn=server-1:1.

At the same time, the following kind of message is logged in the Directory Server access log:

[timestamp] conn=13 op=-1 msgId=-1 - fd=23 slot=23 LDAP connection from IP2:port3 to IP4

So, Directory Server identifies the connection as conn=13.

Tracking the connection in this way enables you to identify the full connection path from the client to Directory Server.

Directory Proxy Server does not wait for a client connection before it establishes a connection to a remote server. The Directory Proxy Server configuration specifies that certain connections are dedicated to bind operations, others to read operations, and others to write operations. When Directory Proxy Server starts up, it establishes all connections to the remote servers, according to this configuration.

When a connection has been established completely (from the client to Directory Server) the client can be identified by its DN.

Directory Server recognizes the client DN as one of the following:

True client bind DN. The bind DN is the client's own bind DN if Directory Proxy Server is configured in Use Bind mode.
Modified client bind DN. The bind DN is modified if Directory Proxy Server is configured in User Proxy Auth Control mode. The DN is modified as a result of DN renaming or user mapping.

A single connection can be used by multiple clients (though not simultaneously). To identify a client connection correctly in the access logs, Directory Proxy Server and Directory Server must be synchronized, that is, the server clock must be as close as possible. This will ensure that the timestamps in the access logs correspond. If the servers are not synchronized, you should synchronize them by using a time server, or evaluate the difference between the server clocks and search the access logs taking this difference into account.