Logging And Tracing From A Websphere Based J2Ee Application Tutorial

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>runtimesbase_v6profilesdefaultlogsserver1trace.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.

Related Training

WebSphere Application Server 8.5 Administration on Linux

WebSphere Application Server 8.5 Administration on Windows

EJB and JPA Programming with Java EE 6 – WebSphere 8.0 / RAD 8.0

Web Application Programming with Java EE 6 – WebSphere 8.0 / RAD 8.0