Contents


Using logging and tracing in the WebSphere Commerce custom code

Comments

As members of the WebSphere Commerce Support and Services organization, we encounter implementations that do not provide appropriate logging and tracing to help troubleshoot various problems. Either the logging is missing, uses inadequate technologies, such as System.out, or relies on deprecated and reserved components, such as WC_EXTERN or WC_ORDER. This article will show how you can implement logging for your custom code in a matter of minutes. We will describe the logging facilities offered by WebSphere Application Server V6.0, provide examples, and offer best practices to make your logging effective.

WebSphere logging facilities and Java logging

WebSphere Commerce V5.6.1.1 and V6.0 support WebSphere Application Server V6.0 (hereafter called Application Server). This version of Application Server fully integrates the Java™ logging API (java.util.logging), which was added in J2SE 1.4 to provide advanced control of informational output from applications. In Application Server V6.0, you can implement logging for your applications using the Java logging standard and take advantage of the WebSphere logging features, such as file management, runtime configuration, and administration through the Administrative Console or the wsadmin tool.

The JRas framework, which was the logging standard in WebSphere Application Server V5, has been deprecated. If you have implemented logging using JRas, your application will continue to work. However, if you face a new implementation, use Java logging instead.

Adding logging to your code

Setting up logging and tracing in your own code is simple. The following example shows a generic WebSphere Commerce command that uses the logging APIs.

package com.mycompany.commerce;

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

public class ExtGetContractUnitPriceCmdImpl extends
      GetContractUnitPriceCmdImpl {

  private static final String CLASS_NAME =
   ExtGetContractUnitPriceCmdImpl.class.getName();
  private static Logger logger = Logger.getLogger(CLASS_NAME);

  public void performExecute() throws ECException {
     final String methodName = "performExecute";

      if (logger.isLoggable(Level.FINER))
         logger.entering( CLASS_NAME, methodName,
               "userId= " + getCommandContext().getUserId());

      try {
         super.performExecute();
         boolean a = someOtherFuntion();
         if (logger.isLoggable(Level.FINE))
            logger.logp( Level.FINE, CLASS_NAME, methodName,
               "someOtherFunction returned " + a );
      } catch ( Exception e ) {
         logger.logp(Level.SEVERE, CLASS_NAME, methodName,
                     e.getClass().getName() + "Your Logging Message", e );
      }

      logger.exiting( CLASS_NAME, methodName );
   }
}

Dissecting the example

This sections breaks down the sample code above and explains each section separately.

  1. To begin, include the necessary imports:
    import java.util.logging.Level;
    import java.util.logging.Logger;
  2. Next, you need to define the logger. Select any name for the logger. In this case, as a general practice, define the logger to match the fully qualified class name. This defines an implicit hierarchy that allows you to enable logging at the different package or class levels (more on this later). Also, in the example below, we follow the WebSphere Commerce standard of creating a final string for the class name that will be used by the logging API.
    private static final String CLASS_NAME = 
       ExtGetContractUnitPriceCmdImpl.class.getName();
    private static Logger logger = Logger.getLogger(CLASS_NAME);

    Grouping loggers by functionality is also a valid practice. In this case, you create loggers that match the functionality provided by the class, such as inventory, orders, or payments.
  3. It is a common practice to define a string to contain the method name because it is used inside the method. The next line, logger.entering(), is a convenient method that is used to log the entry to the method using the FINER level. We recommend using isLoggable() because you lower the footprint of tracing by not concatenating the strings or creating objects if the message is not logged.
    final String methodName = "performExecute";
    if (logger.isLoggable(Level.FINER))logger.entering( CLASS_NAME, methodName, 
    "userId= " + getCommandContext().getUserId());
  4. Produce a log entry if the logging is set to FINE or higher. The logger object provides different signatures. In this case, print the class and method name from where the message was originated.
    if (logger.isLoggable(Level.FINE))
    logger.logp( Level.FINE, CLASS_NAME, methodName, 
    "someOtherFunction returned " + a );
  5. Finally, log the method exit. This is recommended if you logged the entry event. Alternatively, you can also include a message, such as the result of the method or the value to be returned.
    logger.exiting( CLASS_NAME, methodName );

Using adequate logging levels

When logging a message, pay special consideration to the logging level that the message will be using. You can log messages using any of the following levels:

  • SEVERE
  • WARNING
  • INFO
  • CONFIG
  • FINE
  • FINER
  • FINEST

Recommendations

This section highlights a few best practices to help you use the logging features in your custom code and also discusses pitfalls that you can avoid.

  • Avoid the "all or nothing approach", where you either get full tracing in your application or no messages at all.
  • The INFO level is not meant for debugging purposes and it is usually enabled by default. Use this level carefully because too much logging affects the performance of your application. For example, do not use INFO levels for commands, such as OrderItemAdd, that are executed from the store front because they can flood the trace logs with messages.
  • Three different levels are provided for tracing: FINE, FINER, FINEST. One way of deciding which level to use is considering their impact while the trace is enabled. For example, you can organize your messages so that FINE is enabled in production without a significant performance impact. However, only enable FINEST while a particular situation is occurring because the negative impact in performance will be significant. If you use the entering or existing convenience methods, the messages are logged using FINER.
  • The impact of adding logging to your application is minor if its level is not being logged. For this, remember to use the Logger.isLoggable(Level) approach when you need to create objects to log the entry. The most common scenario is when you concatenate strings that are then passed as parameters to the loggers.
  • Always log errors and exceptions using SEVERE or WARNING. This ensures that the errors are logged when running with the INFO level. If the exception needs to be propagated, use the WebSphere Commerce Command error handling framework, which creates internationalized messages and specifies an error view.
  • Ensure the trace messages are unique within a method to help distinguish the code flow.
  • Use a tracing level for Entry and Exit logging (FINER is used by convenience methods, such as logger.entering()). Also use a trace level when a decision is made in the code; for example, to indicate which code path was chosen in an "if" statement.
  • All Entry tracing need corresponding Exit messages. Ensure that all the exit points are covered.
  • Log all the input parameters along with the Entry trace and the return parameters with the Exit trace.

Tracing in WebSphere Application Server

Now that your code implements logging, let’s see how tracing is enabled and administered in Application Server.

Using the WebSphere Administrative console

Using the WebSphere Administrative console, you can view and edit the trace specification. The console shows you two tabs, Configuration and Runtime. Configuration trace takes effect during startup and requires a restart. Runtime trace sets a new trace on a running server. The server returns to the trace specification defined under the Configuration tab the next time it is restarted. Figure 1 shows the Runtime tab of the Administrative console.

Figure 1. Runtime tab of the Administrative console
Figure 1. Runtime tab of the Administrative console
Figure 1. Runtime tab of the Administrative console

For more information about how to enable tracing, see the following WebSphere Application Server Information Center links:

Using the wsadmin tool to specify a new trace

Alternatively, WebSphere also allows you to control the trace through scripting using the wsadmin tool. This is the best option when you do not have access to the Administrative console or you want to automate tracing during certain events.

  1. Follow the instructions in the WebSphere Application Server Information Center to start the wsadmin tool.
  2. Ensure that the wsadmin utility is connected to the WebSphere Commerce server. When the wsadmin utility starts, it prints out the server to which it is connected.
    [root@idefix bin]# ./wsadmin.sh
    WASX7209I: Connected to process "server1" on node 
    WC_demo_node using SOAP connector;
    The type of process is: UnManagedProcess
    WASX7029I: For help, enter: "$Help help"wsadmin>
  3. Create a reference to the TraceService object:
    set traceServ [$AdminControl completeObjectName type=TraceService,*]
  4. Print and save the current trace specification:
    set spec [$AdminControl getAttribute $traceServ traceSpecification]
    puts "Current runtime trace specification: $spec"
  5. Specify new trace specification by issuing the following command. The new trace takes effect immediately.
    $AdminControl setAttribute $traceServ traceSpecification
    com.ibm.websphere.commerce.WC_ORDER=all:com.mycompany.
    orders=all
  6. When the trace specification has been changed, the following line is printed in SystemOut.log and the trace is written to the trace file:
    [1/10/08 10:49:22:500 EST] 0000002e ManagerAdmin ITRAS0018I: The 
    trace state has changed. The new trace state is *=info:com.ibm.
    websphere.commerce.WC_ORDER=all:com.mycompany.orders=all.
  7. Reproduce the problem.
  8. To restore the original trace specification, issue the following command:
    $AdminControl setAttribute $traceServ traceSpecification $spec 
    puts "Current runtime trace specification: $spec"
  9. Exit the wsadmin utility by invoking the quit command.

Using the JACL script to enable tracing

In the download section, you will find the tracespec.jacl script in the code_sample.zip file. This script helps you automate the steps described above.

Where does the trace go?

Your trace goes to two different files, SystemOut.log and trace.log, which is the same as when using the WebSphere Application Server or WebSphere Commerce tracing. You can find the trace logs in the following locations:

Log Developer Runtime

SystemOut.log

WCToolkitEE60\wasprofile\logs\server1

AppServer\profiles\profileName\logs\server1\

trace.log

WCToolkitEE60\wasprofile\logs\server1

AppServer\profiles\profileName\logs\server1\

Depending on the level used when logging the message, these files are written to the following logs:

Level SystemOut.log SystemErr.log trace.log

SEVERE

YES

NO

YES

WARNING

YES

NO

YES

INFO

YES

NO

YES

CONFIG

YES

NO

YES

FINE

 

NO

YES

FINER

 

NO

YES

FINEST

 

NO

YES

Creating the trace specification

If you use the Administrative console, the console writes the trace specification for you as you select the different components. Alternatively, you can also enter the trace in the text area. To specify a trace, you need to enter the name of the logger followed by an equal sign and the logging level desired. You can specify multiple components by separating them with colons (:). Figure 2 shows the logger’s tree that is displayed in the console.

Figure 2. Creating the trace specification in the WebSphere Administrative console
Figure 2. Creating the trace specification in the WebSphere Administrative console
Figure 2. Creating the trace specification in the WebSphere Administrative console

If the name of the logger corresponds to Java packages and classes, you can use the asterisk (*) as a wildcard to indicate that you want to trace all the components that begin with a certain name. For example, by setting the following trace, you enable full tracing for all the WebSphere Commerce customizations made by your company:

com.mycompany.commerce.*=all

When you enable logging at a certain level, you are also enabling all the levels above it. The following list was extracted from java.util.logging.Level:

Type Level Value

Disabled

OFF

MAX_VALUE

Error

SEVERE

1000

 

WARNING

900

Information

INFO

800

 

CONFIG

700

Tracing

FINE

500

 

FINER

400

 

FINEST

300

 

ALL

MIN_VALUE

For example, if logging is set to INFO, messages that use SEVERE and WARNING are also logged.

Tracing WebSphere Commerce components

WebSphere Commerce provides a number of trace components for which you can enable tracing. In contrast with the example provided above, WebSphere Commerce does not have loggers that match the fully qualified class name. Instead, WebSphere Commerce loggers are grouped by functionality. For instance, the commands that are used to manage orders use com.ibm.websphere.commerce.WC_ORDER, contracts com.ibm.websphere.commerce.WC_CONTRACT, and so on. For example, to enable tracing for the runtime engine and the scheduler, use the following string.

com.ibm.websphere.commerce.WC_ORDER=all:com.ibm.websphere.
commerce.WC_SCHEDULER=all

Avoid these practices:

  • Never use the WebSphere Commerce components to log messages from the custom code.
  • Do not use WC_EXTERN, which is deprecated. Instead, always define your own loggers.

Conclusion

Implementing logging and tracing by using the Java Logging framework is a straightforward process. This article showed that following a few best practices and using the tracing tool can significantly improve the serviceability of the code.


Downloadable resources


Related topics


Comments

Sign in or register to add and subscribe to comments.

static.content.url=http://www.ibm.com/developerworks/js/artrating/
SITE_ID=1
Zone=Middleware, Commerce
ArticleID=287837
ArticleTitle=Using logging and tracing in the WebSphere Commerce custom code
publish-date=02062008