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:
- For normal operations, only INFO and higher messages are logged.
- When debugging a command-line process, it is useful to change the configuration in dspace.cfg to use the log4j-console.properties
NOTE: Don't set the root logger to DEBUG. This is due to https://jira.duraspace.org/browse/DS-239.
Clean Up of Logging System
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:
- 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)
- 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
- Within individual webapps, the classpath will dictate where log messages will go.
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.
log4j is a logging library for java that is used by DSpace. Typically it is configured by writing a configuration file (log4j.properties or log4j.xml).
If the configuration file is in the java classpath, it will be read automatically. In this case, log4j.xml file is preferred over log4j.properties - LogManager.java
The DSpace codebase includes a log4j.properties file and not a log4j.xml. Dryad historically has used the log4j.xml file, so the log4j.properties file was unused. To reduce confusion about which file is used, the customizations in log4j.xml have been converted to log4j.properties, and the log4j.xml file will be removed. This change is made by this commit. The change reduces confusion by making the Dryad configuration changes more explicit -- since they are applied to an existing configuration file instead of adding to a new file with a different format.
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 log4j.properties file in the /opt/dryad/config directory is configured to write all output to files in /opt/dryad/log/. This file is also specified in dspace.cfg as log.init.config.
Outputting only to log files is preferred for normal server operations. When performing command-line tasks ( via the dspace command-line interface), the default logging config would redirect any output to these log files, and the user wouldn't see any output on the console.
When running CLI tasks, log4j should output log messages to the console in addition to the log files.This is accomplished this by adding
-Dlog4j.configuration=$DSPACEDIR/config/log4j-dspace-cli.properties -Ddspace.log.init.disable=trueto 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:
- Explicity set the config file for log4j
- Prevent ConfigurationManager from re-configuring (and overriding the above config) with the file named in log.init.config
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
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)
- log4j.properties (from above link) is placed in $CATALINA_BASE/lib (e.g. /var/tomcat/dryad/lib)
- log4j-1.2.14.jar is placed in $CATALINA_BASE/lib (e.g. /var/tomcat/dryad/lib)
- tomcat-juli.jar and tomcat-juli-adapters.jar are downloaded from http://apache.mirrors.tds.net/tomcat/tomcat-6/v6.0.37/bin/extras/
- tomcat-juli.jar is placed in $CATALINA_BASE/bin (which may need to be created)
- tomcat-juil-adapters.jar is placed in $CATALINA_BASE/lib
- $CATALINA_BASE/conf/logging.properties is deleted
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.