Logging

TrustBuilder logging is being handled SLF4j with Logback as base implementation.

Logging can be done in different ways, in general the standard logging blocks the application if i/o is too high or the disk is full.

Standard Logging

TrustBuilder, without custom logging configuration, will log to the System.out target (default Websphere Application Server configuration is systemOut.log). This default behavior is to log only the levels INFO/WARN and ERROR of an initial TrustBuilder setup. Which causes the following events to be logged:

Starting of the application
Loading of the configuration
Failure to load configuration
User specific logging (as scripted)
Stopping of the application

Overwrite default settings

These settings can be overriden by the creation of a custom logback.xml located either in your TB_HOME or by adding a 'logback.configurationFile' system property. The latter had the advantage/disadvantage that it applies to all applications on the application server. These settings can be found in the WAS ISC

CODE

ISC > Application servers > server1 > Process definition > Java Virtual Machine

Change the Generic JVM arguments to the logback.xml

CODE

Generic JVM arguments

-Dlogback.configurationFile=/opt/securit/trustbuilder/instance_x/logback.xml

Please refer to the Logback documentation for a full reference for Logback logging.

In Logback there are several levels regarding logging (from basic logging to detailed logging):

FATAL Very severe error events that potentially cause the application to abort.
ERROR Error events that might still allow the application to continue running.
WARN Potentially harmful situations.
INFO Informational messages that highlight the progress of the application at a coarse grained level.
DEBUG Fine grained informational events that are useful to debug an application.
TRACE Finer grained informational events than the DEBUG.

Example: Logback.xml Here you can find an exmaple of a simple logback-configuration, this configuration has seperate File-appenders per logtype (Perf, Audit, ScriptLogger):

CODE

<configuration>
 <jmxConfigurator />

 <!-- default output (System.out) --> 
 <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
  <!-- log only INFO entries -->
  <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
   <level>INFO</level>
  </filter>
  <encoder>
   <!-- pattern to be used for log entries -->
   <Pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg [%X{TB_ID}]%n</Pattern>
  </encoder>
 </appender>

 <!-- logfile with rollover -->
 <appender name="TRACEFILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
  <!-- name of the logfile -->
  <file>${user.install.root}/logs/trustbuilder.log</file>
  <!-- events are appended at the end of an existing file (=default setting) -->
  <append>true</append>
  <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
   <!-- daily rollover -->
   <fileNamePattern>%d{yyyy-MM-dd}.trustbuilder.log</fileNamePattern>
   <!-- keep 30 days' worth of history -->
   <maxHistory>30</maxHistory>
  </rollingPolicy>
  <encoder>
   <Pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg [%X{TB_ID}]%n</Pattern>
  </encoder>
 </appender>

 <appender name="SCRIPT_LOG_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
  <file>${user.install.root}/logs/trustbuilder_scripts.log</file>
  <append>true</append>
  <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
   <!-- daily rollover -->
   <fileNamePattern>%d{yyyy-MM-dd}.trustbuilder.log</fileNamePattern>
   <!-- keep 30 days' worth of history -->
   <maxHistory>30</maxHistory>
  </rollingPolicy>
  <encoder>
   <Pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg [%X{TB_ID}]%n</Pattern>
  </encoder>
 </appender>

 <!-- all entries are mapped confirm the config under SCRIPT_LOG_FILE -->
 <logger name="Engine.ScriptLogger" level="TRACE">
  <appender-ref ref="SCRIPT_LOG_FILE" />
 </logger>

  <!-- loggers without appenders -->
 <logger name="httpclient.wire" level="INFO" />
 <logger name="org.apache" level="INFO" />
 <logger name="java.sql" level="INFO" />
 <logger name="Engine" level="DEBUG" />
 <!--<logger name="be.securit.trustbuilder.adapter.totp" level="TRACE" />-->
 <!--<logger name="be.securit.trustbuilder.adapter.ocsp" level="TRACE" />-->
 <!--<logger name="be.securit.trustbuilder.adapter.http" level="TRACE" />-->
 <!--<logger name="be.securit.trustbuilder.adapter.jdbc" level="TRACE" />-->
 <!--<logger name="be.securit.trustbuilder.adapter.ldap" level="TRACE" />-->
 <!--<logger name="be.securit.trustbuilder.adapter.digipass" level="TRACE" />-->

 <!-- main log appenders STDOUT and TRACEFILE for TRACE-level -->
 <root level="TRACE">
  <appender-ref ref="STDOUT"/>
  <appender-ref ref="TRACEFILE"/>
  <appender-ref ref="SCRIPT_LOG_FILE"/>
 </root>
</configuration>

It is also possible to use environment variables in the logback configuration:

add an environment property to the generic JVM arguments of the Java process definition of the Trustbuilder server in the WebSphere administration Console.

For example ${TBHOME} would log in our example to /opt/securit/trustbuilder/tbapps if our TBHOME was configured through the system properties ${user.install.root}/logs would log in the log folder of websphere

However, remember that for the system properties to be taken into account the JVM requires a restart.

In order to reload the logging configuration without requiring an application restart or server restart you can add the scan="true" attribute on the configuration element. By default, the configuration file will be scanned for changes once every minute. You can specify a different scanning period by setting the scanPeriod attribute of the element. Values can be specified in units of milliseconds, seconds, minutes or hours. Here is an example:

CODE

<configuration scan="true" scanPeriod="30 seconds" >
...
</configuration>

In order to debug the logging a 'debug' attribute is allowed on the root (like the scan attribute) which will output the how and where logging will appear on the stderr.

Note: All threads are being blocked by default and trustbuilder effectively halts on blocked i/o. If the disk becomes free again the behaviour of trustbuilder is depending on the underlying container / jdk.

Async Logging

Logback offers the functionality to log asynchronously from version 1.0.4 and up. AsyncAppender buffers events in a BlockingQueue. A worker thread created by AsyncAppender takes events from the head of the queue, and dispatches them to the single appender attached to AsyncAppender. Note that by default, AsyncAppender will drop events of level TRACE, DEBUG and INFO if its queue is 80% full. This strategy has an amazingly favorable effect on performance at the cost of event loss. Event loss can be prevented by setting the discardingThreshold property to 0 (zero).

In this case a circular buffer is used and events are dropped once full (if setup correctly) In which case trustbuilder should work without issues. Using asynchronous logging is generally a good idea. You don't want your application to slow down if the server IO is a little behind flushing all that logging to the filesystem. By making it asynchronous your application can continue running without having to wait for the log lines to be written to their final destination.

Auditing In case of audit logs you must take care that the logs don't get lost !!

Async Configuration

CODE

<configuration>
  <appender name="FILE" class="ch.qos.logback.core.FileAppender">
    <file>myapp.log</file>
    <encoder>
      <pattern>%logger{35} - %msg%n</pattern>
    </encoder>
  </appender>

  <appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
    <!-- <queueSize>..</queueSize> -->
    <!-- <discardingThreshold>..</discardingThreshold> -->
    <!-- <includeCallerData>..</includeCallerData> -->
    <appender-ref ref="FILE" />
  </appender>

  <root level="DEBUG">
    <appender-ref ref="ASYNC" />
  </root>
</configuration>

Properties

queueSize int The maximum capacity of the blocking queue. By default, queueSize is set to 256.
discardingThreshold int By default, when the blocking queue has 20% capacity remaining, it will drop events of level TRACE, DEBUG and INFO, keeping only events of level WARN and ERROR. To keep all events, set discardingThreshold to 0.
includeCallerData boolean Extracting caller data can be rather expensive. To improve performance, by default, caller data associated with an event is not extracted when the event added to the event queue. By default, only cheap data like the thread name and the MDC are copied. You can direct this appender to include caller data by setting theincludeCallerData property to true.

Tec Logging

There is a special appender with its own layout class to enable logging that can be read by Tivoli Enterprise Console (TEC) allowing for event generation from logs. The appender is found in the Logback configuration file.

CODE

<appender name="TECLogger" class="ch.qos.logback.core.ConsoleAppender">
 <encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
   <layout class="be.securit.trustbuilder.util.TecLoggingLayout">
       <msgCatalog>alpha</msgCatalog>
       <source>TRUSTBDR</source>
       <maxLength>120</maxLength>
   </layout>
 </encoder>
</appender>

The main difference here from the other appenders is the layout class that is used. This can be customised for each client. Optionally, you can pass a parameter maxLength. If this parameter is specified, the length of the logged lines are truncated to this length. If the parameter is not specified, the lines are logged without truncating. Note the two parameters MsgCatalog, being the environment and Source, being the application name. The value of these parameters are used to populate the fields Application Name and Msg Catalog outlined in the table below. The information that is logged is described in the following table.

Date Date in the format of ddmmyyyy (28012010)
Time Time in the format of hhmm (1556)
Hostname Hostname of the server where TB is running (SECURIT-mt)
Application Name Name of the application (TRUSTBDR)
Sub source Name of the component creating the entry in the log, HTTP, JDBC or Challenge connector for instance [HTTP]
Event type Functional, Technical (TECHNICAL)
Severity The log level (HARMLESS)
Msg Catalog One of alpha, beta or gamma (Alpha)
Message The actual message that has been passed to the logger (Exception from HTTP connector.)

Here is an example of logging from the TEC log.

28012010 1556 SECURIT-mt TRUSTBDR HTTPAdapter TECHNICAL HARMLESS alpha (80):2010-01-28 15:56:48.578: HTTPAdapter connection made to authorisation server. 28012010 1556 SECURIT-mt TRUSTBDR TRUSTBDR TECHNICAL HARMLESS alpha (80):2010-01-28 15:56:53.406: [Engine]=[End request] 01022010 1027 SECURIT-mt TRUSTBDR TRUSTBDR TECHNICAL HARMLESS alpha (83):2010-02-01 10:27:57.390: [Engine]=[Start request] 01022010 1027 SECURIT-mt TRUSTBDR JDBCAdapter TECHNICAL CRITICAL alpha (83):2010-02-01 10:27:57.828: [JDBCAdapter] No Datasource found for TBDS 01022010 1027 SECURIT-mt TRUSTBDR TRUSTBDR TECHNICAL HARMLESS alpha (83):2010-02-01 10:27:58.375: [Engine]=[End request]

The severity field is mapped to the log level in the following manner.

TEC Severity - Logback Level * CRITICAL - ERROR * WARNING - WARN * HARMLESS - All other levels not listed above.

The sub-source details the component that produces the entry. Here is a list of sub-components from the TrustBuilder Core:

Component Name = Logged in Sub-Component

TB Engine Core = TRUSTBDR
JDBC Connector = JDBCAdapter
LDAP Connector = LdapAdapter
Challenge Connector = ChallengeAdapter
HTTP Connector = HttpServer or HttpAdapter
Gemalto Connector = GemaltoAdapter
SAML Connector = SamlAdapter

Database Logging

CODE

 <appender name="DB" class="ch.qos.logback.classic.db.DBAppender">
    <connectionSource class="ch.qos.logback.core.db.DriverManagerConnectionSource">
     <driverClass>com.mysql.jdbc.Driver</driverClass>
     <url>jdbc:mysql://host_name:3306/datebase_name</url>
     <user>username</user>
     <password>password</password>
    </connectionSource>
 </appender>

or through a datasource

<appender name="DB" class="ch.qos.logback.classic.db.DBAppender">
   <connectionSource class="ch.qos.logback.core.db.JNDIConnectionSource">
      <param name="jndiLocation" value="jdbc/MySQLDS" />
      <param name="username" value="myUser" />
      <param name="password" value="myPassword" />
   </connectionSource>
</appender>