4.6 Configuring Logging for tc Runtime

As with standard Apache Tomcat, SpringSource tc Runtime uses Commons Logging throughout its internal code which in turn allows you to choose a logging configuration that suits your needs, such as java.util.logging (configured by default) or log4j. Commons Logging provides tc Runtime with the ability to log hierarchically across various log levels without needing to rely on a particular logging implementation.

The sections that follow summarize the basic information in the standard Apache Tomcat logging documentation (see Logging in Tomcat.) These sections also describe the additional logging features of tc Runtime as compared to the default logging in Apache Tomcat, such as asynchronous logging.

Configuring the JULI Implementation of java.util.logging

SpringSource tc Runtime provides its own implementation of java.util.logging called JULI that addresses a major limitation of the JDK implementation: the inability to configure per-Web application logging. The JULI implementation is the default logging framework in tc Runtime.

Note: It is assumed that you are already familiar with the basic java.util.logging facility provided by the JDK. If you are not, see:

With the JULI implementation, you can configure logging at a variety of levels:

  • Globally for the entire JVM used by tc Runtime by updating the standard the logging.properties file of the JDK, typically located in the JAVA_HOME/jre/lib directory.

  • Per-tc Runtime instance by updating the logging.properties file located in the CATALINA_BASE/conf directory of the tc Runtime instance.

  • Per-Web application by adding a logging.properties file in the WEB-INF/classes directory of the Web application deployed to the tc Runtime instance.

At each level you use a logging.properties file to configure logging; the level that the file configures is based on the location of the file. You can also configure logging programmatically, although this document does not discuss this method. The logging.properties files for the tc Runtime instance or Web application, however, support extended constructs that allow more freedom to define handlers and assign them to loggers. The differences are described later in this section.

The default tc Runtime logging.properties file, located in CATALINA_BASE/conf of your server instance, specifies two types of handlers: ConsoleHandler for routing logging to stdout and FileHandler for writing long messages to a file. You can set the log level of each handler to standard java.util.logging levels, such as SEVERE, WARNING, etc; see Logging Levels for java.util.logging for the full list.

The default log level setting in the JDK logging.properties file is set to INFO. You can also target specific packages from which to collect logging and specify the level of logging you want. For example, to set debugging from the entire tc Runtime instance, add the following to the CATALINA_BASE/conf/logging.properties file:

 org.apache.catalina.level=FINEST

If you set the preceding log level, also set the ConsoleHandler level to collect this threshold, or in other words, be at a level higher than the overall tc Runtime level.

When you configure the logging.properties file for the tc Runtime instance or Web application, you use a similar configuration as that of the JDK logging.properties file. You can also specify additional extensions to allow better flexibility in assigning loggers. Use the following guidelines:

  • As in Java 6.0, declare the list of handlers using handlers.

  • As in Java 6.0, loggers define a list of handlers using the loggerName.handlers property.

  • You define the set of handlers for the root logger using the .handlers property; note that there is no logger name.

  • By default, loggers do not delegate to their parent if they have associated handlers. You can change this behavior for a particular logger using the loggerName.useParentHandlers property, which accepts a boolean value (true or false).

  • As in Java 6.0, use the handlerName.level property to specify the level of logging you want for a given handler. See Logging Levels for java.util.logging for all the available log levels.

  • You can add a prefix to handler names by specifying the handlerName.prefix property. In this case, tc Runtime can instantiate multiple handlers from a single class. A prefix is a String that starts with a digit and ends with '.'. For example, 22foobar. is a valid prefix. The default prefix, if you do not specify one for a particular handler, is juli..

  • Similarly, you can also add a suffix to handler names with the handlerName.suffix property. The default suffix, if you do not specify one for a particular handler, is .log.

  • Specify the directory to which a file handler writes its log files using the handlerName.directory property; the default value is logs. You can use the ${catalina.base} variable to point to a CATALINA_BASE directory of your tc Runtime instance.

  • A tc Runtime instance buffers logging using a default buffer size of 8192 bytes. If you want to reduce the disk access frequency and write larger chunks of data to a log each time, increase the buffer size of a handler by using the handlerName.bufferSize property.

  • System property replacement for property values which start with ${systemPropertyName}.

The following example shows a CATALINA_BASE/conf/logging.properties file for a tc Runtime instance. It shows how to use the level, prefix, directory, and bufferSize properties for a variety of FileHandlers:

handlers = 1catalina.org.apache.juli.FileHandler, \
           2localhost.org.apache.juli.FileHandler, \
           3manager.org.apache.juli.FileHandler, \
           4admin.org.apache.juli.FileHandler, \
           java.util.logging.ConsoleHandler

.handlers = 1catalina.org.apache.juli.FileHandler, java.util.logging.ConsoleHandler

############################################################
# Handler specific properties.
# Describes specific configuration info for Handlers.
############################################################

1catalina.org.apache.juli.FileHandler.level = FINE
1catalina.org.apache.juli.FileHandler.directory = ${catalina.base}/logs
1catalina.org.apache.juli.FileHandler.prefix = catalina.

2localhost.org.apache.juli.FileHandler.level = FINE
2localhost.org.apache.juli.FileHandler.directory = ${catalina.base}/logs
2localhost.org.apache.juli.FileHandler.prefix = localhost.

3manager.org.apache.juli.FileHandler.level = FINE
3manager.org.apache.juli.FileHandler.directory = ${catalina.base}/logs
3manager.org.apache.juli.FileHandler.prefix = manager.

4admin.org.apache.juli.FileHandler.level = FINE
4admin.org.apache.juli.FileHandler.directory = ${catalina.base}/logs
4admin.org.apache.juli.FileHandler.prefix = admin.
4admin.org.apache.juli.FileHandler.bufferSize = 16384

java.util.logging.ConsoleHandler.level = FINE
java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter


############################################################
# Facility specific properties.
# Provides extra control for each logger.
############################################################

org.apache.catalina.core.ContainerBase.[Catalina].[localhost].level = INFO
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].handlers = \
   2localhost.org.apache.juli.FileHandler

org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/manager].level = INFO
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/manager].handlers = \
   3manager.org.apache.juli.FileHandler

org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/admin].level = INFO
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/admin].handlers = \
   4admin.org.apache.juli.FileHandler

The following example shows a WEB-INF/classes/logging.properties file for a specific Web application. The properties file configures a ConsoleHandler to route messages to stdout. IT also configures a FileHandler that prints log messages at the FINE level to the CATALINA_BASE/logs/servlet-examples.log file:

handlers = org.apache.juli.FileHandler, java.util.logging.ConsoleHandler

############################################################
# Handler specific properties.
# Describes specific configuration info for Handlers.
############################################################

org.apache.juli.FileHandler.level = FINE
org.apache.juli.FileHandler.directory = ${catalina.base}/logs
org.apache.juli.FileHandler.prefix = servlet-examples.

java.util.logging.ConsoleHandler.level = FINE
java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter

Logging Levels for java.util.logging

The following table lists the standard log levels that you can set in the various logging.properties files, with the highest level listed first down to the lowest level (OFF). Enabling logging at a given level also enables logging at all higher levels. In general, the lower level of logging you enable, the more data that tc Runtime writes to the log files, so be careful when setting the logging level very low.

Table 4.2. Standard Log Levels

LevelDescription
ALLLogs all messages.
SEVERELogs messages indicating a serious failure.

SEVERE messages describe events that prevent normal program execution. They should be completely intelligible to end users and to system administrators.

WARNINGLogs message indicating a potential problem.

WARNING messages describe events that interest end users or system managers, or that indicate potential problems.

INFOLogs informational messages.

Typically, INFO messages are written to the console or its equivalent, which means that the INFO level should only be used for reasonably significant messages that will make sense to end users and system admins.

CONFIGLogs static configuration messages.

CONFIG messages provide a variety of static configuration information, to assist in debugging problems that may be associated with particular configurations; for example, the CPU type, the graphics depth, the GUI look-and-feel, and so on.

FINE

Logs relatively detailed tracing. FINE messages might include things like minor (recoverable) failures. Issues indicating potential performance problems are also worth logging as FINE. In general the FINE level should be used for information that will be broadly interesting to developers who do not have a specialized interest in the specific subsystem.

The exact meaning of the three levels vary among subsystems, but in general, use FINEST for the most voluminous detailed output, FINER for somewhat less detailed output, and FINE for the lowest volume and most important messages.
FINER

See FINE for FINE, FINER, and FINEST descriptions. FINER indicates a fairly detailed tracing message. By default logging calls for entering, returning, or throwing an exception are traced at this level.

FINEST

See FINE for FINE, FINER, and FINEST descriptions. FINEST indicates a highly detailed tracing message.

OFFTurns off logging.

Configuring Asynchronous Logging

By default, the tc Runtime thread that handles incoming Web requests is the same thread that writes to the log file, such as catalina.out. Thus if a resource issue causes the thread writing to the log file to block, the incoming Web request is also blocked until the thread is able to finish writing to the log file. Depending on your environment, this problem can affect the performance of incoming Web requests.

Asynchronous logging addresses this potential performance problem with a separate thread write to the log file. The Web request thread does not have to wait for the write to the log file to complete, and incoming request from users (or Web services) are not affected by internal resource issues.

Another advantage of asynchronous logging is that you can configure a more verbose log level without affecting the performance of the incoming requests, because even though a lot of information is being written to the log file, it is being written by a different thread from the one handling the incoming requests.

[Note]Note

Asynchronous logging is available only if your tc Runtime instance uses version 1.6 of the JDK/JRE. Also, asynchronous logging is available only with the java.util.logging logging configuration, and not with log4j.

To configure asynchronous logging for a tc Runtime instance:

  1. Open the CATALINA_BASE/conf/logging.properties file for editing, where CATALINA_BASE refers to the root directory of your tc Runtime instance, such as /home/tcserver/springsource-tc-server-standard/myserver. Change every instance of FileHandler in the file to AsyncFileHandler.

    The following snippet shows how the first few non-commented lines of the file will look after the substitution:

    handlers = 1catalina.org.apache.juli.AsyncFileHandler, \
               2localhost.org.apache.juli.AsyncFileHandler, \
               3manager.org.apache.juli.AsyncFileHandler, \
               4host-manager.org.apache.juli.AsyncFileHandler, \
               java.util.logging.ConsoleHandler
    
    .handlers = 1catalina.org.apache.juli.AsyncFileHandler
    
    ############################################################
    # Handler specific properties.
    # Describes specific configuration info for Handlers.
    ############################################################
    
    1catalina.org.apache.juli.AsyncFileHandler.level = FINE
    1catalina.org.apache.juli.AsyncFileHandler.directory = ${catalina.base}/logs
    1catalina.org.apache.juli.AsyncFileHandler.prefix = catalina.
    
    2localhost.org.apache.juli.AsyncFileHandler.level = FINE
    2localhost.org.apache.juli.AsyncFileHandler.directory = ${catalina.base}/logs
    2localhost.org.apache.juli.AsyncFileHandler.prefix = localhost.
    ...
  2. Optionally configure how asynchronous logging behaves by setting one or more of the system properties listed in the properties table. Each property has a default value so you only need to set them if their default values are not adequate.

    Set the properties in the CATALINA_BASE/bin/setenv.sh (Unix) or CATALINA_BASE/bin/setenv.bat (Windows) file by updating the APPLICATION_OPTS variable. Use the standard -D option for each system property you set. The following example shows how to set two of the properties on Unix:

    APPLICATION_OPTS=-Dorg.apache.juli.AsyncOverflowDropType=1 -Dorg.apache.juli.AsyncMaxRecordCount=10000
  3. Restart your tc Runtime instance for the changes to take effect.

Asynchronous Logging System Properties

The following table lists the system properties you can set to configure the asynchronous logging feature of tc Runtime.

Table 4.3. Asynchronous Logging System Properties

Property NameDescriptionDefault Value
org.apache.juli.AsyncOverflowDropTypeSpecifies the action taken by tc Runtime when the memory limit of records has been reached. You can set this property to one of the following values:
  • 1 : tc Runtime drops, and does not log, the record that caused the overflow.

  • 2 : tc Runtime drops the record that is next in line to be logged to make room for the latest record on the queue.

  • 3 : tc Runtime suspends the thread while the queue empties out and flushes the entries to the write buffer.

  • 4 : tc Runtime drops the current log entry.

1
org.apache.juli.AsyncMaxRecordCountMax number of log records that the asynchronous logger keeps in memory. When this limit is reached and a new record is being logged by the JULI framework, the system takes an action based on the value of the org.apache.juli.AsyncOverflowDropType property.

This number represents the global number of records, not on a per handler basis.

10000
org.apache.juli.AsyncLoggerPollIntervalPoll interval (in milliseconds) of the asynchronous logger thread. If the log queue is empty, the asynchronous logging thread issues a poll(poll_interval) call in order to not wake up to often.1000

Configuring log4j

The following steps describe how to configure basic log4j, rather than java.util.logging, as the logging implementation for a given tc Runtime instance. The text after the basic procedure describes how to further customize the log4j configuration.

  1. Under the CATALINA_BASE directory, which is the root directory of your tc Runtime instance (for example, /home/tcserver/springsource-tc-server-standard/myserver), create the following directories if they do not already exist:

    • CATALINA_BASE/lib

    • CATALINA_BASE/bin

  2. Create a file called log4j.properties in the CATALINA_BASE/lib directory of your tc Runtime instance.

  3. Add the following properties to the log4j.properties file:

    log4j.rootLogger=INFO, R 
    log4j.appender.R=org.apache.log4j.RollingFileAppender
    log4j.appender.R.File=${catalina.base}/logs/tomcat.log
    log4j.appender.R.MaxFileSize=10MB 
    log4j.appender.R.MaxBackupIndex=10
    log4j.appender.R.layout=org.apache.log4j.PatternLayout 
    log4j.appender.R.layout.ConversionPattern=%p %t %c - %m%n
  4. Download log4j (version 1.2 or later) and place the log4j.jar file in the CATALINA_BASE/lib directory of your tc Runtime instance.

  5. Copy the CATALINA_BASE/bin/extras/tomcat-juli.jar file provided with tc Server to the CATALINA_BASE/bin directory of your tc Runtime instance.

  6. Copy the CATALINA_HOME/bin/extras/tomcat-juli-adpaters.jar file provided with tc Server to the CATALINA_BASE/lib directory of your tc Runtime instance.

  7. Delete the CATALINA_BASE/conf/logging.properties file to prevent java.util.properties from generating zero-length log files.

Specifying Included Packages With log4j Logging

SpringSource recommends that you configure the specific packages that you want to include in the logging. Because tc Runtime defines loggers by Engine and Host names, use these names in the log4j.properties file.

For example, if you want a more detailed Catalina localhost log, add the following lines to the end of the log4j.properties you created:

log4j.logger.org.apache.catalina.core.ContainerBase.[Catalina].[localhost]=DEBUG
log4j.logger.org.apache.catalina.core=DEBUG
log4j.logger.org.apache.catalina.session=DEBUG

Warning: A level of DEBUG produces megabytes of logging and will consequently slow the startup of tc Runtime. Be sure that you use this level sparingly, typically only when you need to debug internal tc Runtime operations.

For the full list of logging levels you can specify when configuring log4j, see Log Levels.

Configuring a Web Application with log4j Logging

You can configure your Web applications to use log4j for their own logging, which is in addition to the tc Runtime logging configuration described in the preceding sections.

The basic steps are as follows:

  1. Create a log4j.properties file that is similar to the one described in Configuring log4j.

  2. Update the log4j.properties file with logging information specific to your application. For example, if you want to specify that the logger in package my.package be at level DEBUG, add the following:

    log4j.logger.my.package=DEBUG
  3. Put the log4j-version.jar file in the WEB-INF/lib directory of your Web application, where version refers to the version of the JAR file, such as log4j-1.2.15.jar.

See the log4j documentation for detailed information.

Updating Logging Parameters Dynamically

You can use JMX to modify logging levels and other logging parameters while tc Runtime is executing. The modifications you make using JMX are not persisted; when the server restarts, any changes you made are lost. You could use this feature to enable debugging messages to help troubleshoot an application problem while the problem is occurring. This is useful for problems that take time to develop after a reboot or are otherwise difficult to reproduce.

The JULI implementation of java.util.logging allows you to create separate loggers for each Web application by adding logging.properties files to your Web applications. This allows you to control logging at a very fine level.

Using JMX, you can list loggers, change the logging level for any single logger by name, and set a new handler (log file) for a logger. You can specify the logger you want to manage using a logger string defined in the logging.properties file, prefixed with "jmx:", for example jmx:com.springsource.tcserver.

Following is code for a JSP you can use to try out using JMX to manage loggers dynamically. It reports whether different logging levels are enabled and also displays the class loader and logger names. Add the JSP to a web application, deploy it, and call it before and after changing the logging level as described in the first example below.

<%@page import="org.apache.juli.logging.*"%>
<% 
  Log log = LogFactory.getLog(this.getClass());
  String dmessage = "log.jsp log message[DEBUG] "+System.currentTimeMillis();
  String imessage = "log.jsp log message[INFO] "+System.currentTimeMillis();
  String wmessage = "log.jsp log message[WARN] "+System.currentTimeMillis();
  String emessage = "log.jsp log message[ERROR] "+System.currentTimeMillis();
  log.debug(dmessage);
  log.info(imessage);
  log.warn(wmessage);
  log.error(emessage);
%>
  Debug Enabled: <%=log.isDebugEnabled()%> <br/>  
  Info  Enabled: <%=log.isInfoEnabled()%> <br/>
  Warn  Enabled: <%=log.isWarnEnabled()%> <br/>
  Error Enabled: <%=log.isErrorEnabled()%> <br/>
  
Class Loader: <%=this.getClass().getClassLoader().getParent().
    getClass().getName()%>#<%=System.identityHashCode(this.getClass().
    getClassLoader().getParent())%> <br/>  
LoggerName: <%=this.getClass().getName()%>#<%=this.getClass().
    getClassLoader().getParent().getClass().
    getName()%>#<%=System.identityHashCode(this.getClass().
    getClassLoader().getParent())%> <br/>  

The following examples use JConsole, the Java Monitoring and Management Console included with the JDK, to manage loggers. There is a jconsole executable in the JDK bin directory that you can execute from a shell or Command Prompt. JConsole connects to a tc Runtime instance at the JMX port, 6969 by default. To verify your JMX port, check the base.jmx.port property in the CATALINA_HOME/conf/catalina.properties file.

Setting a New Logging Level for a Logger

This example shows how to use JMX to change the logging level for a logger without restarting the tc Runtime instance. A logger string from the CATALINA_HOME/conf/logging.properties file identifies the logger.

  1. Start JConsole and connect to the tc Runtime instance.

    In the New Connection window Remote Process field, enter the host name or IP and JMX port for the tc Server, separated by a colon. Enter the user name and password (the defaults are admin/springsource) and click Connect.

  2. Click the MBeans tab.

  3. In the tree at the left, expand java.util.logging > Logging > Operations, and click the setLoggerLevel operation.

  4. In the Operation invocation section, enter the logger name in the p0 field and the new logging level in the p1 field. Then click setLoggerLevel.

    The logger name, p0, can be one of the following:

    • Logger strings defined in CATALINA_HOME/conf/logging.properties prefixed with "jmx:". For example jmx:com.springsource.tcserver, jmx:org.apache.catalina, or jmx:org.apache.tomcat.

    • A fully qualified logger name, as described in the preceding section.

    If you are using the JSP code presented above to test this feature, copy the logger name from the page's output in your browser and paste it into the p0 field. Be careful not to copy any trailing spaces into the field.

    The logging level, p1, is one of the logging levels described in Logging Levels for java.util.logging: SEVERE, WARNING, INFO, CONFIG, FINE, FINER, FINEST, OFF, or ALL.

After you click SetLoggerLevel, the new logging level takes effect. If you are using the sample JSP code, reloading the page logs messages and updates the status of the logging levels.

Example: Create a New Log File and Redirect Debug Output To It

The following example creates a log handler (a log file), associates it with a logger, and sets the logging level for the logger. The result is a newly created log file with messages redirected into it.

  1. Start JConsole and connect to the tc Server instance. (See previous example.)

  2. Click the MBeans tab and then, in the tree at left, navigate to tcServer > Serviceability > LoggingManager > Operations.

  3. Click the createHandler operation. You use this operation to create a log file. Complete the parameters as follows:

    • p0: empty. This parameter is ignored.

    • p1: The name of your handler, for example MyJMXLog.

    • p2: The location of the log file, for example ${catalina.base}/logs.

    • p3: The prefix of the log file name, for example debug-example.

    • p4: The suffix for the log file name, for example .log.

    Parameters p2, p3, and p4 establish the location and name of the new log file. The file name is constructed from the prefix, a day timestamp, and the suffix, for example debug-example.2011-11-11.log. The p2 parameter specifies the directory where the file is created, in this example CATALINA_HOME/logs.

  4. Click createHandler.

    Now you can verify that the new log file has been created in the CATALINA_HOME/logs directory.

  5. Click the setHandler operation. You use this operation to associate the log file you created with a logger. Complete the parameters as follows:

    • p0: empty.

    • p1: The name of your handler, for example MyJMXLog.

    • p2: The name of the logger, for example jmx:org.apache.

  6. Navigate to java.util.logging > Logging > Operations and click the setLoggerLevel operation. Complete the parameters as follows:

    • p0: jmx.org.apache

    • p1: ALL

  7. Click setLoggerLevel.

    Messages are now written to the new log file.

Remember that changes you make with JMX are lost when the server is rebooted. The changes are not written to the tc Server configuration files.