Logging Technology

From Dryad wiki
Jump to: navigation, search

Dryad logs events using the Log4j system that is normally used with DSpace. The log4j.properties file in the config directory controls what is logged from DSpace and where.

A few notes specific to the Dryad setup:

  • log4j.properties in the /opt/dryad/config directory is configured to write all output to files in /opt/dryad/log/. This file is specified in dspace.cfg as log.init.config.
  • log4j-dspace-cli.properties is used for when running command-line tasks. It writes messages both to the console and the dspace.log file.
  • DON'T set the root logger to DEBUG. This is due to https://jira.duraspace.org/browse/DS-239.
  • For normal operations, only INFO and higher messages are logged.

Details about log4j

The log4 configuration file found in the classpath will be used for logging until the ConfigurationManager is accessed. ConfigurationManager is used early and often in DSpace operations, as it reads the dspace.cfg file and provides configuration parameters to the rest of the application.

ConfigurationManager reconfigures log4j with the config file named in the log.init.config property (if present). (re)configuration can be prevented by setting the system property dspace.log.init.disable to any value (in JAVA_OPTS for example).

Note: If the log4j config file named in the log.init.config property is the only config file available in the classpath, this reconfiguration step will have no effect. The reconfiguration is a feature of DSpace, allowing administrators to temporarily change the log configuration without altering/renaming the standard log4j.properties file. It may explain some unexpected logging configurations or cases where a few early log messages appear in a different log file than others.

Log4J Command-line / Console Output

The console logging setup is accomplished by adding
-Dlog4j.configuration=$DSPACEDIR/config/log4j-dspace-cli.properties -Ddspace.log.init.disable=true
to the JAVA_OPTS variable in the dspace script. The dspace script checks for existing JAVA_OPTS and won't clobber them, so if you have alternate JAVA_OPTS to set, you may have to explicitly configure logging.

These options do the following:

  1. Explicity set the config file for log4j
  2. Prevent ConfigurationManager from re-configuring (and overriding the above config) with the file named in log.init.config

slf4j bindings issue

This section describes an issue due to having multiple slf4j jar files in the /opt/dryad/lib directory on the servers.

  • Some parts of the DSpace/Dryad codebase use slf4j, which is an abstraction above log4j and other logging frameworks
  • slf4j allows developers to send log messages to a central logging api (org.slf4j.Logger, in slf4j-api-x.y.z.jar)
  • To select an output logging framework, you add a "one" binding jar (such as slf4j-log4j12-x.y.z.jar or slf4j-jdk14-x.y.z.jar) to the classpath
    • If slf4j-log4j12-x.y.z.jar is present, then slf4j will send logging messages to log4j.
  • According to the slf4j documentation, "Do Not place more than one binding on your class path."

As of 2012-12-18 (7419ba582e), the current build of Dryad will only place one binding into /opt/dryad/lib. However, both the production server and the development server have two slf4j bindings in their /opt/dryad/lib directory:

  • slf4j-jdk14-1.5.6.jar (Built-in JDK Logging - java.util.logging)
  • slf4j-log4j12-1.5.6.jar (log4j)

This has several implications:

  1. Running the dspace command-line interface produces little or no console output on a default installation (log messages are sent to log4j and piped into logfiles)
  2. The destination for messages sent to slf4j in a running Dryad instance is undefined. In my testing, the binding that appeared first in the classpath received them.
    • Alphabetically, they may be sent to java.util.logging instead of log4j, which would end up in tomcat logs rather than the dspace log4j-configured logs
  3. Within individual webapps, the classpath will dictate where log messages will go.

Update 2013-02-14

As a first step, we should remove the slf-jdk14-1.5.6.jar from the /opt/dryad/lib directory on the servers, leaving only the slf-log4j jar. This will cause all log messages to go to log4j. There is a lot of DSpace code that uses log4j directly (and not slf4j), and this change would result in everything being routed to log4j.

From there, we can focus on configuring log4j.

Tomcat Logging

catalina.out

The script that runs tomcat (catalina.sh) redirects console (stderr/stdout) output to catalina.out. This file is not part of the logging system - it does not include timestamps, class names, or log levels, so it's important to use loggers rather than outputting directly to stdout/stderr

log4j

The remainder of the log files in the tomcat logs directory configured with log4j. By default, tomcat uses a simplified logging system. Tomcat can easily be reconfigured to use Log4j by applying the following customizations (implemented from tomcat.apache.org/tomcat-6.0-doc/logging.html).

These customizations shall be put in place on any Dryad server instance, so that logfile rotation/retention can be made consistent (Dryad application logs also use log4j)

Note that a CATALINA_BASE directory is unique to the dryad instance (e.g. /var/tomcat/dryad-staging for staging, /var/tomcat/dryad for dev)

  1. log4j.properties (from above link) is placed in $CATALINA_BASE/lib (e.g. /var/tomcat/dryad/lib)
  2. log4j-1.2.14.jar is placed in $CATALINA_BASE/lib (e.g. /var/tomcat/dryad/lib)
  3. tomcat-juli.jar and tomcat-juli-adapters.jar are downloaded from http://apache.mirrors.tds.net/tomcat/tomcat-6/v6.0.37/bin/extras/
    1. tomcat-juli.jar is placed in $CATALINA_BASE/bin (which may need to be created)
    2. tomcat-juil-adapters.jar is placed in $CATALINA_BASE/lib
  4. $CATALINA_BASE/conf/logging.properties is deleted

slf4j

slf4j-jdk-x.y.z.jar keeps reappearing in lib directories and included in maven profiles. This binding should be removed whenever encountered, as we are using the slf4j-log4j-x.y.z.jar binding.

See Also