Oracle Fusion Middleware Reference for Oracle Directory Server Enterprise Edition

Chapter 23 Directory Proxy Server Logging

Directory Proxy Server logs information in access logs and error logs. Additionally, a plug-in can be configured to log messages to a syslog daemon. Unlike Directory Server, Directory Proxy Server does not provide an audit log.

Log files for Directory Proxy Server can be configured through Directory Service Control Center or on the command line. For information about how to configure log files, see Chapter 27, Directory Proxy Server Logging, in Oracle Fusion Middleware Administration Guide for Oracle Directory Server Enterprise Edition.

For information about access logs and error logs, see the following sections:

Note that the log message format is still evolving in this release of Directory Proxy Server.

Introduction to Directory Proxy Server Logs

The Directory Proxy Server logging service provides access logs and error logs. The logs are flat files that contain information about client operations and about the health of Directory Proxy Server. By default, log files are stored under instance-path/logs with the permission of 600. If an instance of Directory Proxy Server is started without valid log files, log files are created in the default location and a warning is sent to DSCC.

You can configure the following aspects of the logs:

Set the log level for each message category
Globally set the default log-level for all message categories
Globally enable all logs
Set the name, location and permissions of log files
Set the maximum number of log files
Define a rotation policy for each log file
Include or exclude search filters in access log messages for search operations

Log messages can also be sent to the syslog daemon. For information about how to log messages to a syslog daemon, see Logging Alerts to the syslogd Daemon in Oracle Fusion Middleware Administration Guide for Oracle Directory Server Enterprise Edition.

Log File Rotation

Log files can be rotated manually at any time, or can be rotated automatically when the following events occur:

When the log reaches a specified size
At a specified interval
At a specified start-time, start-day, and interval
At a specified start-time, start-day, and interval, if the log file is bigger than a specified size
At a specified interval, if the log file is bigger than a specified size

The start-time, start-day, and interval can have the following combinations:

Time-of-day followed by an interval of days, hours, or minutes
Day-of-week and time-of-day, followed by an interval of weeks
Day-of-month and time-of-day, followed by an interval of months

The time-of-day takes precedence over the interval. For example, a log that is specified to be rotated at 3am and then every 10 hours is rotated at the following times: 03:00, 13:00, 23:00, and again at 03:00 (not 07:00).

If the log is configured for rotation on the 31st of the month but the month has fewer than 31 days, the log is rotated on the first day of the following month.

Log File Deletion

A log file deletion policy defines when backup log files are deleted. The log file currently in use is never deleted by a deletion policy.

The following deletion policies can be enabled:

Deletion based on time. Log files are deleted when they reach a specified age.
Deletion based on size. Log files are deleted when the total size of all the log files reaches a specified limit. The size of the current log file is taken into account, although this file is not deleted.
Deletion based on free disk space. When the free disk space reaches a specified minimum, the oldest backup log file is deleted. If the free disk space is still lower than the minimum, the next oldest backup log file is deleted, and so forth.

By default, log file deletion is based on free disk space, with a default value of 1 Megabyte. When all three deletion policies are activated simultaneously, they are processed in order of time, size, and free disk space. For information about how to configure log file deletion, see Deleting Directory Proxy Server Logs in Oracle Fusion Middleware Administration Guide for Oracle Directory Server Enterprise Edition.

Message Severity

Messages are included in log files or filtered out of log files according to the severity of the message, the category of the message, and the log-level that has been configured for that category. The categories and log-levels for the error logs and access logs are different, and are discussed in the sections that follow.

Messages are ranked according to their severity. Messages can have one of the following severities, where error is highest severity and debug is the lowest severity:

error
warning
info
debug

Messages with a severity that is lower than the log-level configured for its message category are not included in the log file. Messages with a severity that is equal to or higher than the log-level configured for its associated message category are included in the log file.

Error Logs for Directory Proxy Server

Error logs contain information about the health of the Directory Proxy Server. Error messages are categorized according to the cause of the message. The following table lists the categories of messages that can be included in an error log.

Table 23–1 Message Categories for Error Logs


Category Name	Category Description
`CONFIG`	Information about configuration
`DECODE`	Information about operation decoding
`PLUGIN`	Information about plug-in processing
`PROCESSING`	Information about a significant event that occurred during client processing
`BACKEND`	Information about an operation with a data source
`INTERNAL`	Information about an internal error in the core server
`SHUTDOWN`	Information about an event at server shutdown
`STARTUP`	Information about an event at server startup

Error Log Levels

Each message category can be configured with one of the following log-levels:

none No messages are included in the log file.
error Only error messages are included in the log file.
warning Error messages and warning messages are included in the log file.
info Errors, warnings and informational messages are included in the log file.
all All messages are included in the log file. In most cases, this setting produces the same results as the info setting. In certain situations, this setting enables additional debugging messages to be logged.
inherited The log level is inherited from the value of the default-log-level property.

By default, the log level for each message category is inherited. As the default-log-level property is set to info, each category inherits the info log level.

The log-level of a message category works in conjunction with the severity level of a message to determine which messages are included in the log file. For more information, see Message Severity.

Format of an Error Message

An error log message has this format:

timestamp - message category - message severity - message text

Example 23–1 shows an extract from an error log.

Example 23–1 Extract of an Error Log

[11/Feb/2010:14:52:28 +0100] - STARTUP    - INFO  - Logging Service configured
[11/Feb/2010:14:52:28 +0100] - STARTUP    - INFO  - Java Version: 1.6.0_16 
  (Java Home: /local/instances/dsee7/jre)
[11/Feb/2010:14:52:28 +0100] - STARTUP    - INFO  - Java(TM) SE Runtime Environment 
  (build 1.6.0_16-b01)
[11/Feb/2010:14:52:28 +0100] - STARTUP    - INFO  - Java HotSpot(TM) 64-Bit Server VM 
  (build 14.2-b01, mixed mode)
[11/Feb/2010:14:52:28 +0100] - STARTUP    - INFO  - Java Heap Space: Total Memory 
  (-Xms) = 241MB, Max Memory (-Xmx) = 241MB
[11/Feb/2010:14:52:28 +0100] - STARTUP    - INFO  - Operating System: 
  SunOS/sparcv9 5.10
[11/Feb/2010:14:52:29 +0100] - STARTUP    - INFO  - SSL initialization succeeded.
[11/Feb/2010:14:52:29 +0100] - CONFIG     - WARN  - Attribute 
  certMappingDataViewPolicy in entry cn=LDAPS Listener,cn=Client 
  Listeners,cn=config missing. Using ALL_DATA_VIEW
[11/Feb/2010:14:52:29 +0100] - STARTUP    - INFO  - Creating 50 worker threads.
[11/Feb/2010:14:52:30 +0100] - STARTUP    - INFO  - Sun-Directory-Proxy-Server/7.0 
  B2009.1104.2146 started on host lecap in directory /local/instances/dps-1
[11/Feb/2010:14:52:30 +0100] - STARTUP    - INFO  - Listening for client connections 
  on 0.0.0.0:1389
[11/Feb/2010:14:52:30 +0100] - STARTUP    - INFO  - Listening for secure client 
  connections on 0.0.0.0:1636
[11/Feb/2010:14:52:31 +0100] - BACKEND    - WARN  - LDAP server groupy:11998/ is 
  up and running.
[11/Feb/2010:17:43:10 +0100] - SHUTDOWN   - INFO  - Directory Proxy Server received a 
  shutdown request from external signal (caught by shutdown hook)
[11/Feb/2010:17:43:10 +0100] - BACKEND    - WARN  - LDAP server groupy:11998/ is up 
  and running.
[11/Feb/2010:17:43:11 +0100] - SHUTDOWN   - INFO  - Directory Proxy Server stopped.
[11/Feb/2010:17:43:19 +0100] - STARTUP    - INFO  - Logging Service configured
[11/Feb/2010:17:43:19 +0100] - STARTUP    - INFO  - Java Version: 1.6.0_16 
  (Java Home: /local/instances/dsee7/jre)
[11/Feb/2010:17:43:19 +0100] - STARTUP    - INFO  - Java(TM) SE Runtime Environment 
  (build 1.6.0_16-b01)
[11/Feb/2010:17:43:19 +0100] - STARTUP    - INFO  - Java HotSpot(TM) 64-Bit Server VM
  (build 14.2-b01, mixed mode)
[11/Feb/2010:17:43:19 +0100] - STARTUP    - INFO  - Java Heap Space: Total Memory 
  (-Xms) = 241MB, Max Memory (-Xmx) = 241MB
[11/Feb/2010:17:43:19 +0100] - STARTUP    - INFO  - Operating System: 
  SunOS/sparcv9 5.10
[11/Feb/2010:17:43:19 +0100] - STARTUP    - INFO  - Initializing LDAP server 
  cn=dscc_ldap_groupy:11998,cn=data sources,cn=config
[11/Feb/2010:17:43:19 +0100] - STARTUP    - INFO  - SSL initialization succeeded.
[11/Feb/2010:17:43:20 +0100] - CONFIG     - WARN  - Attribute certMappingDataViewPolicy
  in entry cn=LDAPS Listener,cn=Client Listeners,cn=config missing. Using ALL_DATA_VIEW

Access Logs for Directory Proxy Server

Access logs contain information about the requests being processed by Directory Proxy Server. Access logs contain information about two types of connection:

Connections between clients and Directory Proxy Server
Connections between Directory Proxy Server and data sources

Access log messages are categorized according to the cause of the message. The following table lists the categories of messages that can be included in the access log.

Table 23–2 Message Categories for Access Logs


Category Name	Category Description
`CONNECT`	Information about a client connection
`DISCONNECT`	Information about a client disconnection
`OPERATION`	Information about operations requested by a client
`PROFILE`	Information about the profiles of a connection handler
`SERVER_OP`	Information about operations that are forwarded to data sources
`SERVER_OP_DETAIL`	Detailed information about operations that are forwarded to data sources

Access Log Levels

Each message category can be configured with one of the following log-levels:

none No access messages are included in the log file.
info Informational messages are included in the log file.
all All messages are included in the log file. In most cases, this setting produces the same results as the info setting. In certain situations, this setting enables additional debugging messages to be logged.
inherited The log level is inherited from the value of the default-log-level property.

By default, the log level for each message category is inherited but for SERVER_OP_DETAIL, the log level is none. As the default-log-level property is info, all the message categories except SERVER_OP_DETAIL inherits the log level info.

The log-level of a message category works in conjunction with the severity level of a message to determine which messages are included in the log file. For more information, see Message Severity.

Format of an Access Log Message

An access log message has this format:

timestamp - category - severity - connectionNumber operationNumber
  messageID operationType messageText

Example 23–2 shows an extract of an access log. The log shows a client request that starts with a message in the CONNECT category and ends with a message in the DISCONNECT category. The operation requested by the client is shown by the message in the OPERATION category, and results in several messages in the SERVER_OP category. The logged messages have the INFO and DEBUG severity.

Example 23–2 Extract of an Access Log

[07/17/2005:17:29:45 +0200] - CONNECT    - INFO  - conn=1591031 
  client=129.157.192.132:49216 server=0.0.0.0:9389 protocol=LDAP
[07/17/2005:17:29:45 +0200] - OPERATION  - INFO  - conn=1591031 op=0 
  msgid=1 SEARCH base="o=movie" scope=2 filter="(objectClass=*)"
[07/17/2005:17:29:45 +0200] - SERVER_OP  - INFO  - conn=1591031 op=0 
  SEARCH base="o=movie" scope=2 filter="(objectClass=*)" 
  s_msgid=318022 s_authzid="" s_conn=39
[07/17/2005:17:29:45 +0200] - SERVER_OP  - INFO  - conn=1591031 op=0 
  SEARCH base="o=movie" scope=2 filter="(objectClass=*)" s_msgid=316902 
  s_authzid="" s_conn=76
[07/17/2005:17:29:45 +0200] - SERVER_OP  - INFO  - conn=1591031 op=0 
  SEARCH RESPONSE err=0 msg="" nentries=4 s_conn=76
[07/17/2005:17:29:45 +0200] - SERVER_OP  - DEBUG - Global status code = 0
[07/17/2005:17:29:45 +0200] - SERVER_OP  - INFO  - conn=1591031 op=0 
  SEARCH RESPONSE err=0 msg="" nentries=11 s_conn=39
[07/17/2005:17:29:45 +0200] - SERVER_OP  - DEBUG - Global status code = 0
[07/17/2005:17:29:45 +0200] - OPERATION  - INFO  - conn=1591031 op=0 
  SEARCH RESPONSE err=0 msg="" nentries=22
[07/17/2005:17:29:45 +0200] - OPERATION  - INFO  - conn=1591031 op=1 
  UNBIND
[07/17/2005:17:29:45 +0200] - DISCONNECT - INFO  - conn=1591031 
  reason=unbind"

Message Parts in an Access Log

Messages for the connections between a client and the Directory Proxy Server are labeled in the same way as in Directory Server. Table 23–4 describes parts of the messages between the client and the Directory Proxy Server in Example 23–2. For an explanation of all of the possible message parts, see Content of Access, Error, and Audit Logs.

Table 23–3 Message Parts for Connections Between a Client and a Directory Proxy Server


Log Message Part	Description
`conn`	Identifier for the connection between the client and the Directory Proxy Server.
`op`	The number of an operation on a given connection. The first operation on a connection has the value `op=0`. Subsequent requests on the connection have increasing numbers, `op=1`, `op=2`, etc.
`msgid`	The number of a message to be sent to a client application. The LDAP protocol is mainly asynchronous. If a client request requires a response from a server, the response is given in the following steps: The directory server acknowledges the request and assigns a `msgid` The directory server responds to the request by using the `msgid` identifier A response can be sent in multiple packets, where each packet is identified by the same `msgid`.
`nentries`	The number of entries returned by a search request.
`err`	The result code returned from the LDAP operation. The error number `0` means that the operation was successful. For a list of LDAP result codes, see Result Codes in Log Files.
`msg`	A human readable error diagnostic.

Messages for the connections between Directory Proxy Server and a data source are prefixed with s_. Table 23–4 describes parts of the messages between the Directory Proxy Server and the data source in Example 23–2.

Table 23–4 Message Parts for Connections Between a Directory Proxy Server and a Data Source


Log Message Part	Description
`s_msgid`	Identifier for the message between the Directory Proxy Server and a data source.
`s_authzid`	Authorization identity for an operation to be processed under when the Directory Proxy Server forwards the request to a data source by using proxy authorization.
`s_conn`	Identifier for the connection between the Directory Proxy Server and the data source.

Access Log Buffer

Access log messages are stored in a buffer. The buffer is flushed to the access log at the following times:

When the buffer is full
When the access log is rotated
When Directory Proxy Server is stopped

By default, the size of the access log buffer is 1M. However, the size of the buffer can be configured to control the frequency with which it is flushed.

The buffer is also flushed periodically, that is, every 2.5 seconds, if none of the other conditions is met.

You can configure the size of the access log buffer by setting the log-buffer-size property. For information about how to configure access log properties, see Configuring Directory Proxy Server Logs in Oracle Fusion Middleware Administration Guide for Oracle Directory Server Enterprise Edition.

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.