Logging and Tracing from a Websphere Based J2EE Application

Abstract

This article shows how to add logging and tracing services to a J2EE application. The use of the Java logging API is discussed in the context of WebSphere Application Server. The article also shows how to configure the log file name, log level and log file rotation. The article is primarily targeted to the developers.

Background

Prior to version 6, WebSphere Application Server used the JRAS API to perform logging and tracing. A J2EE application could also use JRAS for its own logging purposes. That way, the application's log entries could be stored in the same files as the application server (such as SystemOut.log and trace.log). However, JRAS is an IBM propretary API. Many developers chose to use a more open framework such as Log4J instead. The problems with Log4J were:

1. Configuration had to be done separately from the application server logging configuration.

2. Log4J uses a separate log file from the application server. When debugging a problem, one has to consult both files. Correlating the log entries can be difficult.

As of WebSphere v6, the product has started using the JDK 1.4 logging API to perform logging and tracing. Application developers can now use JDK logging API from their code. The advantages are:

1. The API is standard and will be supported by a JDK 1.4 and up runtime.

2. There is no need to ship any additional JAR file for the logging framework.

3. The API is quite easy to use.

4. Log level, file location and rotation settings can be done by a WebSphere administrator from the web based administrative console.

5. Application's log level can be dynamically changed without restarting the server or the application.

6. The application will write to the same log file as the WebSphere product. During debugging, one needs to look at a single log file. It will be easy to correlate WebSphere's log entries and the application's log entries.

Note: Alternatively, you can also use the Apache Commons Logging API or the JRAS API to perform logging. WebSphere exposes the internal JDK logging framework to these APIs as well. In this article we will look at the Java native logging API as it is the most standard based.

Basics of the Java Logging API

Log Level

An application performs logging using the java.util.logging.Logger class. Each log entry has a level associated with it that reflects its importance. Usually, the system is configured to capture only the very important messages in a log file. During debugging, storage of less important messages is enabled on a temporary basis. The log levels are specified using various constants defined in the java.util.logging.Level class. Additionally, IBM defines a few extra levels in the com.ibm.websphere.logging.WsLevel class. This class extends the Level class.

In decreasing order of importance, the levels are:

1. WsLevel.FATAL

2. Level.SEVERE

3. Level.WARNING

4. WsLevel.AUDIT

5. Level.INFO

6. Level.CONFIG

7. WsLevel.DETAIL

8. Level.FINE

9. Level.FINER

10. Level.FINEST

A few important things to note about the log levels:

1. By default, WebSphere stores log entries of importance level INFO or higher.

2. Log entries are stored in the SystemOut.log file of the application server.

3. You can lower the importance level of the entries that are stored in the log file. However, log entries lower than WsLevel.DETAIL are never stored in the SystemOut.log file. To store these entries, you need to enable the tracing service and specify a separate trace file name (by default trace.log).

The Logger Class

As already mentioned, an application performs logging using the Logger class. An application needs to obtain a logger object first. This can be done using the Logger.getLogger() static method. For example:

Logger logger = Logger.getLogger("com.webage.servlets.SimpleServlet");

This creates a logger named com.webage.servlets.SimpleServlet. Every logger object has a name that is used to configure various properties of the logger. The name of the logger does not have to be a class name. It can be a component or module name. In the example below, we create a single logger object called "PayRollApplication" for the entire application:

Logger logger = Logger.getLogger("PayRollApplication");

A dot separated list of names indicates hierarchy of modules. In the example below, the logger is created for the "Tax" subsystem of the "PayRollApplication" system.

Logger logger = Logger.getLogger("PayRollApplication.Tax");

This logger will inherit all the properties of the logger named PayRollApplication. We will see shortly that, using the WebSphere administrative console, we can set properties at any level of the hierarchy.

Generally speaking, use the name of the class that is using the logger object as the name of the logger. Example:

Logger logger = Logger.getLogger(getClass().getName());

Thread safety of a logger object is of some concern. If you create a logger object at the class level (as a static member variable) or as a regular member variable of a Servlet, the logger will be used simultaneously from multiple threads. A quick examination of the IBM JDK code shows brief synchronization within a core logging method - log(LogRecord record). Judging by the small number of lines that are synchronized, it is the authors opinion that this synchronization should have very minimal performance impact. The alternative is to create a new logger from every method call (and consequently thread). This approach will have its own performance penalty. The relative performance of a per-class logger vs. per method call logger has not been studied as a part of this article.

There are many methods available in the Logger class to perform logging. I will introduce four key methods in two categories. First two methods are easy to call but do not take the class and method names as input. This can make it difficult to locate the source of the log entry in a large application. These methods are:

1. log(Level level, String message)

2. log(Level level, String message, Throwable e). This is used for error logging.

The following two methods allow you to supply the class and method name performing the logging. These methods are recommended in a large application.

1. logp(Level level, String sourceClass, String sourceMethod, String msg)

2. logp(Level level, String sourceClass, String sourceMethod, String msg, Throwable thrown). This is used for error logging.

An example is sufficient to show how to use these methods:

import java.util.logging.Level;
import java.util.logging.Logger;

public class SimpleServlet extends HttpServlet implements Servlet {
    Logger logger = Logger.getLogger(getClass().getName());
    
    protected void doGet(HttpServletRequest req, HttpServletResponse resp) throws ServletException, IOException {
        logger.log(Level.INFO, "An info level log");
        logger.logp(Level.SEVERE, getClass().getName(), "doGet", "A severe level log");
        //...
    }
}

This code will produce the following log entry in the SystemOut.log file:

[3/27/06 18:24:37:429 EST] 0000007c SimpleServlet I   An info level log
[3/27/06 18:24:37:429 EST] 0000007c SimpleServlet E com.webage.servlet.SimpleServlet doGet A severe level log

The second log entry shows the class and method name. This makes the log entry more useful, especially when the application is very large.

A few utility methods are supplied that reduce the amount of typing required.

1. severe(String msg). Logs at Level.SEVERE level.

2. warning(String msg). Logs at Level.WARNING level.

3. info(String msg). Logs at Level.INFO level.

4. Similarly, the fine, finer, finest methods log at Level.FINE, Level.FINER and Level.FINEST level.

Example:

logger.info("An info level log message");

Two specialized methods are provided to indicate a method entry and exit. They create log entries at the Level.FINER level.

1. entering(String sourceClass, String sourceMethod)

2. exiting(String sourceClass, String sourceMethod)

In a very large application, code path may involve very deep call chain. Method entry/exit logging helps get a picture of the call chain by looking at the log file. Example:

protected void doGet(HttpServletRequest req, HttpServletResponse resp) throws ServletException, IOException {
    logger.entering(getClass().getName(), "doGet");
    //...
    logger.exiting(getClass().getName(), "doGet");
}

This will produce the following log entries in the trace.log file.

[3/27/06 18:24:37:409 EST] 0000007c SimpleServlet > com.webage.servlet.SimpleServlet doGet ENTRY
[3/27/06 18:24:37:449 EST] 0000007c SimpleServlet < com.webage.servlet.SimpleServlet doGet RETURN

Level Guidelines

Generally follow these guidelines to decide what level to use for a log entry. Too much logging will decrease performance of the application. Remember, you can always decrease the log level dynamically if needed.

try {
    //..
} catch (Exception e) {
    logger.logp(Level.SEVERE, getClass().getName(), "doGet", "Servlet failed", e);
}

logger.fine("Calculating price of product: " + productId);
if (discount > 0.00) {
    logger.fine("Will apply a discount of: " + discount);
}
//...
logger.fine("Price after discount: " + price);

Configure Logging in WebSphere v6

A simple web based application will be used to illustrate the configuration process. Import all projects from the Project Interchange Format file LogTestAppSrc.zip in Rational Application Developer (RAD6). This will add a dynamic web project called LogTestWeb in the workspace. This project includes a Servlet called SimpleServlet. Study it's class - com.webage.servlet.SimpleServlet. The doGet method performs logging at various levels ranging from SEVERE to FINEST.

    protected void doGet(HttpServletRequest req, HttpServletResponse resp) throws ServletException, IOException {
        logger.entering(getClass().getName(), "doGet");
    
        try {
            logger.severe("A severe level log message");
            logger.logp(Level.SEVERE, getClass().getName(), "doGet", "A severe level log");
            logger.log(Level.INFO, "An info level log");
            logger.info("An info level log message");
            logger.fine("A fine level log message");
            logger.finest("A finest level log message");
            String val = req.getParameter("error");
            if (val != null) {
                throw new Exception("A simulated error condition.");
            }
            resp.setContentType("text/html");
            PrintWriter out = resp.getWriter();
            out.println("<h1>Log Test Servlet</h1>");
        } catch (Exception e) {
            logger.log(Level.SEVERE, "Servlet failed with an error", e);
        }
        logger.exiting(getClass().getName(), "doGet");
    }

Start the WebSphere test server. Deploy the LogTestApp application to the server.

Open a browser and enter the URL: http://localhost:9080/LogTestWeb/SimpleServlet.

Look at the Console view. The Console shows the contents of SystemOut.log and SystemError.log (in red). You should see a few log messages.

These messages are either in SEVERE or INFO level. Now, enter the URL: https://localhost:9080/LogTestWeb/SimpleServlet?error=y. This will simulate an error condition and show a stack trace in the Console.

Now, we will enable tracing and set the log level so that we can view the lower priority messages (FINE, FINER, FINEST). Right click on the server in the Servers view and select Run administrative console. Log into the console. On the left hand side expand Troubleshooting and click on Logs and Trace. Click on the server1 server. Click on Diagnostic Trace.

Make sure that the Enable Log check box is selected. This enables the trace service. If this check box is not turned on, you will need to check it, save configuration and restart the server.

Click on the Change Log Detail Levels link. This page takes a while to load.

The default log specification string is *=info. This means for all loggers, entries with a level of INFO or higher will be stored. We will like to lower this level to FINEST at runtime without restarting the server. Click on the Runtime tab. Again wait for a few seconds for the page to load.

In the list of loggers, expand com.webage.servlet.*. Click on com.webage.servlet.SimpleServlet. From the pop up menu select finest.

System will set the log level setting to: *=info: com.webage.servlet.SimpleServlet=finest. Alternatively, we could have set the log level at a higher hierarchy level (for example com.webage.servlet.*).

Click on Apply.

In the browser enter the URL: http://localhost:9080/LogTestWeb/SimpleServlet. The Console still does not show the FINE level messages or method entry and exit messages. Why? These messages are stored in the trace file. Using Notepad, open <RAD Install>\runtimes\base_v6\profiles\default\logs\server1\trace.log. You should notice these messages at the end.

[3/27/06 19:32:32:679 EST] 00000035 ServletWrappe A   SRVE0242I: [LogTestApp] [/LogTestWeb] [SimpleServlet]: Initialization successful.
[3/27/06 19:32:32:709 EST] 00000035 SimpleServlet > com.webage.servlet.SimpleServlet doGet ENTRY
[3/27/06 19:32:32:709 EST] 00000035 SimpleServlet E   A severe level log message
[3/27/06 19:32:32:739 EST] 00000035 SimpleServlet E com.webage.servlet.SimpleServlet doGet A severe level log
[3/27/06 19:32:32:749 EST] 00000035 SimpleServlet I   An info level log
[3/27/06 19:32:32:779 EST] 00000035 SimpleServlet I   An info level log message
[3/27/06 19:32:32:779 EST] 00000035 SimpleServlet 1   A fine level log message
[3/27/06 19:32:32:779 EST] 00000035 SimpleServlet 3   A finest level log message
[3/27/06 19:32:32:779 EST] 00000035 SimpleServlet < com.webage.servlet.SimpleServlet doGet RETURN

Conclusion

The WebSphere Application Server product uses Java 1.4 logging API to perform internal logging and tracing. You can use the same API from your application. Your application's log entries will be stored in the same file as WebSphere's logs. This greatly aids debugging. WebSphere provides easy to use web based tools to configure the log level at runtime. You can lower the log level when needed to view additional trace messages.

Feedback