Chapter 14. Configuring Subsystem Logs

The Certificate System subsystems create log files that record events related to activities, such as administration, communications using any of the protocols the server supports, and various other processes employed by the subsystems. While a subsystem instance is running, it keeps a log of information and error messages on all the components it manages. Additionally, the Apache and Tomcat web servers generate error and access logs.
Each subsystem instance maintains its own log files for installation, audit, and other logged functions.
Log plug-in modules are listeners which are implemented as Java™ classes and are registered in the configuration framework.
All the log files and rotated log files, except for audit logs, are located in whatever directory was specified in -redirect_logs when the instance was created with pkicreate. Regular audit logs are located in the log directory with other types of logs, while signed audit logs are written to /var/lib/instance_name/logs/signedAudit/. The default location for logs can be changed by modifying the configuration.

14.1. About Certificate System Logs

Certificate System subsystems keep several different kinds of logs, which provide specific information depending on the type of subsystem, types of services, and individual log settings. The kinds of logs that can be kept for an instance depend on the kind of subsystem that it is.

14.1.1. System Log

Subsystem logs are kept for the CA, OCSP, DRM, and TKS subsystems.
This log, system, records information about requests to the server (all HTTP and HTTPS requests) and the responses from the server. Information recorded in this log includes the IP address (both IPv4 and IPv6) of the client machine that accessed the server; operations performed, such as search, add, and edit; and the result of the access, such as the number of entries returned:
id_number processor - [date:time] [number_of_operations] [result] servlet: message

Example 14.1. TKS System Log

10439.http-13443-Processor25 - [19/May/2009:14:16:51 CDT] [11] [3] UGSubsystem: Get User Error User not found
This log is on by default.

14.1.2. Transactions Log

Transaction logs are kept for the CA, OCSP, DRM, and TKS subsystems.
This log, transactions, records any kind of operation performed or submitted to the subsystem.
id_number.processor - [date:time] [number_of_operations] [result] servlet: message
These messages are specific to the certificate service, such as the CA receiving certificate requests, the DRM archiving or retrieving keys, and the TKS registering a new TPS. This log can also be used to detect any unauthorized access or activity.

Example 14.2. DRM Transactions Log

11438.http-10443-Processor25 - [27/May/2009:07:56:18 CDT] [1] [1] archival reqID 4 fromAgent agentID: CA-server.example.com-9444 authenticated by noAuthManager is completed DN requested: UID=recoverykey,E=recoverykey@email.com,CN=recover key serial number: 0x3
This log is on by default.

14.1.3. Debug Logs

Debug logs are maintained for all six subsystems, with varying degrees and types of information.
Debug logs for each subsystem record much more detailed information than system, transaction, and access logs. Debug logs contain very specific information for every operation performed by the subsystem, including plug-ins and servlets which are run, connection information, and server request and response messages.
The general types of services which are recorded to the debug log are briefly discussed in Section 14.2.1.1, “Services That Are Logged”. These services include authorization requests, processing certificate requests, certificate status checks, and archiving and recovering keys, and access to web services.
The debug logs for the CA, OCSP, DRM, and TKS record detailed information about the processes for the subsystem. Each log entry has the following format:
[date:time] [processor]: servlet: message
The message can be a return message from the subsystem or contain values submitted to the subsystem.
For example, the TKS records this message for connecting to an LDAP server:
[10/Jun/2009:05:14:51][main]: Established LDAP connection using basic authentication to host localhost port 389 as cn=Directory Manager
The processor is main, and the message is the message from the server about the LDAP connection, and there is no servlet.
The CA, on the other hand, records information about certificate operations as well as subsystem connections:
[06/Jun/2009:14:59:38][http-9443-Processor24]: ProfileSubmitServlet: key=$request.requestowner$ value=RA-server.example.com-4747
In this case, the processor is the HTTP protocol over the CA's agent port, while it specifies the servlet for handling profiles and contains a message giving a profile parameter (the subsystem owner of a request) and its value (that the RA initiated the request).

Example 14.3. CA Certificate Request Log Messages

[06/Jun/2009:14:59:38][http-9443-Processor24]: ProfileSubmitServlet: key=$request.profileapprovedby$ value=admin
[06/Jun/2009:14:59:38][http-9443-Processor24]: ProfileSubmitServlet: key=$request.cert_request$ value=MIIBozCCAZ8wggEFAgQqTfoHMIHHgAECpQ4wDDEKMAgGA1UEAxMBeKaBnzANBgkqhkiG9w0BAQEFAAOB...
[06/Jun/2009:14:59:38][http-9443-Processor24]: ProfileSubmitServlet: key=$request.profile$ value=true
[06/Jun/2009:14:59:38][http-9443-Processor24]: ProfileSubmitServlet: key=$request.cert_request_type$ value=crmf
[06/Jun/2009:14:59:38][http-9443-Processor24]: ProfileSubmitServlet: key=$request.requestversion$ value=1.0.0
[06/Jun/2009:14:59:38][http-9443-Processor24]: ProfileSubmitServlet: key=$request.req_locale$ value=en
[06/Jun/2009:14:59:38][http-9443-Processor24]: ProfileSubmitServlet: key=$request.requestowner$ value=RA-server.example.com-4747
[06/Jun/2009:14:59:38][http-9443-Processor24]: ProfileSubmitServlet: key=$request.dbstatus$ value=NOT_UPDATED
[06/Jun/2009:14:59:38][http-9443-Processor24]: ProfileSubmitServlet: key=$request.subject$ value=uid=jsmith, e=jsmith@example.com
[06/Jun/2009:14:59:38][http-9443-Processor24]: ProfileSubmitServlet: key=$request.requeststatus$ value=begin
[06/Jun/2009:14:59:38][http-9443-Processor24]: ProfileSubmitServlet: key=$request.auth_token.user$ value=uid=RA-server.example.com-4747,ou=People,dc=server.example.com-pki-ca
[06/Jun/2009:14:59:38][http-9443-Processor24]: ProfileSubmitServlet: key=$request.req_key$ value=MIGfMA0GCSqGSIb3DQEBAQUAA4GNADCBiQKBgQDreuEsBWq9WuZ2MaBwtNYxvkLP^M
HcN0cusY7gxLzB+XwQ/VsWEoObGldg6WwJPOcBdvLiKKfC605wFdynbEgKs0fChV^M
k9HYDhmJ8hX6+PaquiHJSVNhsv5tOshZkCfMBbyxwrKd8yZ5G5I+2gE9PUznxJaM^M
HTmlOqm4HwFxzy0RRQIDAQAB
[06/Jun/2009:14:59:38][http-9443-Processor24]: ProfileSubmitServlet: key=$request.auth_token.authmgrinstname$ value=raCertAuth
[06/Jun/2009:14:59:38][http-9443-Processor24]: ProfileSubmitServlet: key=$request.auth_token.uid$ value=RA-server.example.com-4747
[06/Jun/2009:14:59:38][http-9443-Processor24]: ProfileSubmitServlet: key=$request.auth_token.userid$ value=RA-server.example.com-4747
[06/Jun/2009:14:59:38][http-9443-Processor24]: ProfileSubmitServlet: key=$request.requestor_name$ value=
[06/Jun/2009:14:59:38][http-9443-Processor24]: ProfileSubmitServlet: key=$request.profileid$ value=caRAagentCert
[06/Jun/2009:14:59:38][http-9443-Processor24]: ProfileSubmitServlet: key=$request.auth_token.userdn$ value=uid=RA-server.example.com-4747,ou=People,dc=server.example.com-pki-ca
[06/Jun/2009:14:59:38][http-9443-Processor24]: ProfileSubmitServlet: key=$request.requestid$ value=20
[06/Jun/2009:14:59:38][http-9443-Processor24]: ProfileSubmitServlet: key=$request.auth_token.authtime$ value=1212782378071
[06/Jun/2009:14:59:38][http-9443-Processor24]: ProfileSubmitServlet: key=$request.req_x509info$ value=MIICIKADAgECAgEAMA0GCSqGSIb3DQEBBQUAMEAxHjAcBgNVBAoTFVJlZGJ1ZGNv^M
bXB1dGVyIERvbWFpbjEeMBwGA1UEAxMVQ2VydGlmaWNhdGUgQXV0aG9yaXR5MB4X^M
DTA4MDYwNjE5NTkzOFoXDTA4MTIwMzE5NTkzOFowOzEhMB8GCSqGSIb3DQEJARYS^M
anNtaXRoQGV4YW1wbGUuY29tMRYwFAYKCZImiZPyLGQBARMGanNtaXRoMIGfMA0G^M
CSqGSIb3DQEBAQUAA4GNADCBiQKBgQDreuEsBWq9WuZ2MaBwtNYxvkLPHcN0cusY^M
7gxLzB+XwQ/VsWEoObGldg6WwJPOcBdvLiKKfC605wFdynbEgKs0fChVk9HYDhmJ^M
8hX6+PaquiHJSVNhsv5tOshZkCfMBbyxwrKd8yZ5G5I+2gE9PUznxJaMHTmlOqm4^M
HwFxzy0RRQIDAQABo4HFMIHCMB8GA1UdIwQYMBaAFG8gWeOJIMt+aO8VuQTMzPBU^M
78k8MEoGCCsGAQUFBwEBBD4wPDA6BggrBgEFBQcwAYYuaHR0cDovL3Rlc3Q0LnJl^M
ZGJ1ZGNvbXB1dGVyLmxvY2FsOjkwODAvY2Evb2NzcDAOBgNVHQ8BAf8EBAMCBeAw^M
HQYDVR0lBBYwFAYIKwYBBQUHAwIGCCsGAQUFBwMEMCQGA1UdEQQdMBuBGSRyZXF1^M
ZXN0LnJlcXVlc3Rvcl9lbWFpbCQ=
Likewise, the OCSP shows OCSP request information:
[07/Jul/2009:06:25:40][http-11180-Processor25]: OCSPServlet: OCSP Request:
[07/Jul/2009:06:25:40][http-11180-Processor25]: OCSPServlet:
MEUwQwIBADA+MDwwOjAJBgUrDgMCGgUABBSEWjCarLE6/BiSiENSsV9kHjqB3QQU
TPS and RA debug logs are much simpler, recording a timestamp and message.
date time - message
In fact, the RA and TPS debug logs are mainly limited to startup messages.

Example 14.4. TPS Debug Log Snippet

Sat Jun 20 16:28:05 CDT 2009 - TPS wizard: starting up
Sat Jun 20 16:28:05 CDT 2009 - TPS wizard: start up complete
Sat Jun 20 16:28:07 CDT 2009 - TPS wizard: starting up

14.1.4. Error Log

The RA and TPS subsystems do not keep a system or transaction log as the other subsystems do, but they keep an analogous error log. This error log (error_log) records all kinds of operations for the subsystem, such as opening and closing connections and processing operation requests.
[date time] [type_of_message] message
There are a number of different types of messages that are recorded to the error log, including both minor message (info and debug) and serious ones (warning and error).

Example 14.5. TPS Error Log Snippet

[Sat Jun 20 16:28:09 2009] [info] Configuring server for SSL protocol
[Sat Jun 20 16:28:09 2009] [debug] nss_engine_init.c(594): Enabling SSL3
[Sat Jun 20 16:28:09 2009] [debug] nss_engine_init.c(599): Enabling TLS
[Sat Jun 20 16:28:09 2009] [debug] nss_engine_init.c(770): Configuring permitted SSL ciphers [-des,-desede3,-rc2,-rc2export,-rc4,-rc4export,
+rsa_3des_sha,-rsa_des_56_sha,+rsa_des_sha,-rsa_null_md5,-rsa_null_sha,-rsa_rc2_40_md5,+rsa_rc4_128_md5,-rsa_rc4_128_sha,-rsa_rc4_40_md5,-rsa
_rc4_56_sha,-fortezza,-fortezza_rc4_128_sha,-fortezza_null,-fips_des_sha,+fips_3des_sha,-rsa_aes_128_sha,-rsa_aes_256_sha,+ecdhe_ecdsa_aes_25
6_sha]
[Sat Jun 20 16:28:09 2009] [info] Using nickname Server-Cert cert-pki-tps.

14.1.5. Installation Logs

All six subsystems keep an install log.
Every time a subsystem is created either through the initial installation or creating additional instances with pkicreate, an installation file with the complete debug output from the installation, including any errors and, if the installation is successful, the URL and PIN to the configuration interface for the instance. The file is created in the log directory for the instance with a name in the form instance_ID-install.log.
[date time] [debug] message
Each line in the install log follows a step in the installation process.

Example 14.6. RA Install Log

[2009-05-19 09:30:30] [debug] Processing PKI files and symbolic links for '/var/lib/pki-ra' ...
[2009-05-19 09:30:31] [debug] Processing PKI security databases for '/var/lib/pki-ra' ...
[2009-05-19 09:30:31] [debug] Processing PKI security modules for '/var/lib/pki-ra' ...
[2009-05-19 09:30:31] [debug]     Attempting to add hardware security modules to system if applicable ...
[2009-05-19 09:30:31] [debug]         module name: lunasa  lib: /usr/lunasa/lib/libCryptoki2.so DOES NOT EXIST!
[2009-05-19 09:30:31] [debug]         module name: nfast  lib: /opt/nfast/toolkits/pkcs11/libcknfast.so DOES NOT EXIST!
[2009-05-19 09:30:31] [debug] Restorecon file context for /usr/share/pki
[2009-05-19 09:30:32] [debug] Restorecon file context for /etc/rc.d/init.d/pki-ra
[2009-05-19 09:30:33] [debug] Restorecon file context for /var/lib/pki-ra
[2009-05-19 09:30:33] [debug] Restorecon file context for /var/log/pki-ra
[2009-05-19 09:30:34] [debug] Restorecon /etc/pki-ra
[2009-05-19 09:30:34] [debug] Restorecon file context for /usr/sbin/httpd.worker
[2009-05-19 09:30:34] [debug] Setting selinux context pki_ra_port_t for 12890
[2009-05-19 09:30:39] [debug] Setting 'pki-ra' runlevel to '-'
[2009-05-19 09:30:39] [debug] Setting 'pki-ra' start priority to '86'
[2009-05-19 09:30:39] [debug] Setting 'pki-ra' stop priority to '14'
[2009-05-19 09:30:39] [debug] Registered 'pki-ra' with '/sbin/chkconfig'.
[2009-05-19 09:30:54] [log] Configuration Wizard listening on
http://server.example.com:12888/ra/admin/console/config/login?pin=U3PXGwMJrcDPj4RrmDdK
[2009-05-19 09:30:54] [log] After configuration, the server can be operated by the command:
/sbin/service pki-ra start | stop | restart

14.1.6. Apache and Tomcat Error and Access Logs

The CA, RA, DRM, OCSP, and TKS subsystems use a Tomcat web server instance for their agent and end-entities' interfaces. The TPS and RA subsystems use an Apache web server.
Error and access logs are created by the Apache and Tomcat web servers, which are installed with the Certificate System and provide HTTP services. The error log contains the HTTP error messages the server has encountered. The access log lists access activity through the HTTP interface.

Table 14.1. Logs Created by Apache and Tomcat

Apache (TPS and RA) Tomcat (CA, DRM, OCSP, TKS)
access_log admin.timestamp
error_log catalina.timestamp
catalina.out
host-manager.timestamp
localhost.timestamp
localhost_access_log.timestamp
manager.timestamp
These logs are not available or configurable within the Certificate System; they are only configurable within Apache or Tomcat. See the Apache documentation for information about configuring these logs.

14.1.7. Self-Tests Log

The self-tests log records information obtained during the self-tests run when the server starts or when the self-tests are manually run. The tests can be viewed by opening this log. This log is not configurable through the Console. This log can only be configured by changing settings in the CS.cfg file. The information about logs in this section does not pertain to this log. See Section 12.11, “Running Self-Tests” for more information about self-tests.