Project

General

Profile

Logging Infrastructure

Whether you are investigating an issue in FWD runtime code or in business logic, a well-placed logging statement can be a low impact mechanism to look inside the state of your application or the runtime environment. Logging statements should be added with careful consideration for performance impacts and readability of the resulting log information.

The FWD server environment supports “proper” logging, by which we mean that a logging infrastructure based on the J2SE logging environment is available to the developer. The FWD client runtime code base, on the other hand, does not offer this facility, though it is expected to be added with future development.

“Poor Man's” Logging

In the absence of a true logging infrastructure, or when a temporary solution is more appropriate or simply more convenient, basic print or println statements serve as a handy backup method of dumping runtime information. Currently, this is the only form of logging currently available for the FWD client runtime code base.

The current version of FWD supports the character mode user interface (CHUI) as an interactive client. This implementation uses the terminal's stdout stream to render its user interface, so calls to System.out.println for example, are not recommended in the client code base, as they will cause screen corruption which likely will get in the way of any debugging efforts. Rather, use System.err as the target stream, and redirect the terminal's stderr stream to a file when launching the FWD CHUI client, as in:

java {JVM options} com.goldencode.p2j.main.ClientDriver {program options} 2>client.log

The use of System.out.println and System.err.println for temporary debug logging statements is naturally supported on the FWD server as well, and sometimes this is the best option to gather ad-hoc information. This is a particularly good option for performance-sensitive areas, where the overhead of logging decisions is undesirable, and you do not want to leave a permanent logging statement behind in the code. Of course, it is very important to remove any such statements after a debugging effort is complete.

“Proper” Logging

This section assumes the reader already is familiar with the configuration of the logging facilities available for the FWD server. If not, please review the prerequisite material mentioned in the introduction to this chapter. Here we discuss how to add new logging statements to FWD runtime code or to application code.

The foundation of logging in the FWD (server) environment is the logging infrastructure added to the Java platform in J2SE 1.4, the public API for which is in the java.util.logging package. This package contains the Logger class, instances of which are worker objects used to log messages for specific system or application components. Logger instances can be named or anonymous.

Named loggers are named using a dot-separated, hierarchical namespace, which typically corresponds with a specific package or class name. Named loggers in FWD runtime code follow this convention.

Anonymous loggers have no associated namespace, and as such, cannot be retrieved by name. Thus, an anonymous logger, once obtained, can only be accessed by the object reference first returned by the logging environment. Thus, access to it can be protected, so that unrelated code cannot retrieve it and change its state. This is an important security consideration, as it prevents an untrusted piece of code from obtaining the logger by name and affecting the integrity of security sensitive logging, such as audit messages, for example.

Log messages are each assigned a level of severity. These are checked against configuration values associated in the FWD directory with the names of individual Logger instances, and against global settings for various types of log handlers. This check determines whether a given log message is recorded/displayed or not. A description of log handlers and details on how to configure this service are provided in the Debugging Converted Code chapter of the FWD Conversion Handbook.

The central logging class in the FWD runtime source is com.goldencode.p2j.util.LogHelper. This is a helper class which the majority of FWD runtime code uses to access Logger instances. Typically, a named Logger instance is retrieved and stored in a static member variable of the class which will use it, as in:

package com.myorg.myapp.abc;

import com.goldencode.p2j.util.LogHelper;

public class MyClass
{
   private static Logger log1 = LogHelper.getLogger(MyClass.class);

   private static Logger log2 = LogHelper.getLogger("some-random.hierarchical.name");

   private static Logger log3 = LogHelper.getSecureLogger(true);

   ...
}

The first assignment above uses the LogHelper.getLogger(Class) method to obtain a named Logger whose name is that of the package containing MyClass (in this case com.myorg.myapp.abc). It stores that object in the class member log1.

The second assignment uses an overloaded version of the same LogHelper method, in this case, LogHelper.getLogger(String). It retrieves a named Logger whose name is some-random.hierarchical.name and stores that object in the class member log2. The name passed to this method could be any text value. The desired naming hierarchy is defined by separating nested namespaces with a dot (.). Thus, in the example above, an administrator could configure different severity levels for the logging namespaces some-random, some-random.hierarchical, and some-random.hierarchical.name, if desired. This logger would use the setting for the most granular of those namespaces.

The third assignment uses the LogHelper.getSecureLogger(boolean) method to obtain an anonymous Logger instance. The true argument indicates that the returned Logger is operating in the context of the FWD server. It is necessary to pass this argument, even though there is no logging support for the FWD client at the time of this writing. The returned logger is considered secure because it is anonymous, no other class can access the same Logger instance and manipulate it. This type of logger is used for auditing purposes in the FWD runtime environment.

Since the log1, log2, and log3 variables are static, they are initialized once and once only, when MyClass is first loaded by the Java class loader. The Logger objects are then available for use throughout MyClass to check their configured, logging severity levels, and to write messages to the log as needed.

The first assignment in the example above is typical of the most common idiom used throughout the FWD runtime code. Granularity of logging is most often along package lines, though there are exceptions.

Using a Logger instance is fairly straightforward. There are several, overloaded versions of the logp method which typically are used in the FWD runtime code.

Here is an example of getting and using a Logger instance, excerpted from the com.goldencode.p2j.net.Conversation class, with minor modifications:

import java.util.logging.*;
import com.goldencode.p2j.util.*;

...

public class Conversation
{
   /** Logger */
   private static final Logger LOG =
      LogHelper.getLogger(Conversation.class.getName());

   ...

   public void run()
   {
      ...

      try
      {
         ...
      }

      catch (ApplicationRequestedStop exc)
      {
         // normal termination of the queue
         if (LOG.isLoggable(Level.FINE))
         {
            String msg = LogHelper.generate(exc.getMessage());
            LOG.logp(Level.FINE, "Conversation", "run", msg);
         }
      }
      ...
   }
   ...
}

Near the top of the example, we use the variant of the overloaded LogHelper.getLogger method which accepts a String parameter. By passing the fully qualified name of the Conversation class, we get a Logger instance specific to the namespace defined by the name of the enclosing class: com.goldencode.p2j.net.Conversation.

This is a more granular namespace than we would have gotten if we had used the variant of this method which accepts a Class parameter. Had we done that instead, passing in Conversation.class as the argument, we would get have gotten a logger for the com.goldencode.p2j.net namespace, which potentially is shared across many classes in the corresponding package. Because the various classes in this package perform a great deal of logging, this is too coarse of a namespace for practical use. By requesting a Logger instance for only the com.goldencode.p2j.net.Conversation namespace, we can control the level of this logger independently of all the other classes in the com.goldencode.p2j.net package and produce a more readable log file with content tailored to our area of interest.

At the bottom of the example, we catch an ApplicationRequestedStop exception, which is thrown upon normal termination of a client's session with the FWD server. This code would log a message about that event if the logging level for the com.goldencode.p2j.net.Conversation logger were set to FINE (or more granular), similar to the following:

[12/04/2009 13:26:33 EST] (Conversation.run:FINE) {0000000F:00000010:user1} Application requested stop

Inside a conditional block which checks if our desired level of logging is enabled, the message is composed. We take the message text from the caught exception and use the method LogHelper.generate to prepend information about the current session, thread ID, and user ID.

String msg = LogHelper.generate(exc.getMessage());

This is an important helper method. The context it provides to a log message can be invaluable when debugging a problem, particularly in a system with many active users/sessions/threads. It is this method which composes the {0000000F:00000010:user1} portion of the sample message above. The first component, 0000000F, is the unique session ID which the FWD Security Manager has assigned to the user session from which the message is logged. The second component, 00000010, is the unique thread ID, also assigned by the Security Manager. Both the session ID and thread ID are formatted as eight-digit hexadecimal strings. The third component, user1, is the user name associated with the session. The same user name may be associated with multiple sessions and threads at the same time; this indicates the user has multiple client sessions active with the FWD server.

Finally, the log message is sent to the log, at the target logging level set in the Logger.logp method (in this case, Level.FINE).

LOG.logp(Level.FINE, "Conversation", "run", msg);

This variant of the Logger.logp method accepts a logging level, the names of the enclosing class and method, respectively, and the message text. All of this information is formatted into the final message written to the log. If the logger is configured to a less detailed logging level than that specified in the Logger.logp call, the message will not be written.

Here is an example of using a slightly different variant of the Logger.logp method, excerpted from com.goldencode.p2j.main.StandardServer, with minor modifications. Import statements, the class definition, definition of the LOG member, and method declarations have been omitted from this example, as they are not significantly different than in the Conversation class example above.

catch (Throwable thr)
{
   LOG.logp(Level.SEVERE,
            "StandardServer",
            "hookTerminate",
            LogHelper.generate("terminate() failed!"),
            thr);
}

Note that this variant of Logger.logp accepts as its last parameter an instance of Throwable. This last argument differentiates this variant of the method from the one used in the previous example. In this case, when the Throwable object thr is caught, we will log a message similar to the following:

[12/05/2009 02:54:00 EST] (StandardServer.hookTerminate:SEVERE) {0000001E:0000020A:user2} terminate() failed!

Immediately after this entry, the stack trace from the Throwable object thr will be logged.

Performance Considerations

The recommended idiom when logging a message is to enclose the entire logging operation, including the composition of the message, within a conditional block, which only executes if the logger is configured to log messages at our desired level of logging detail (or at a higher/finer level). This is why the logging code above is enclosed in the test:

if (LOG.isLoggable(Level.FINE))

It might appear that this check is redundant, since Logger.logp already filters messages by logging level. However, the isLoggable check is important when considering performance. Composing the text of a log message typically requires string concatenation, generally an expensive operation. Retrieval of information needed for the log message may involve other, relatively costly operations as well. Taken together, the overhead of this work can be considerable, compared to the actual work of the enclosing code. We do not want to incur this overhead unless absolutely necessary, since logging should be as transparent as possible from a performance standpoint. The simple act of introducing logging should not introduce a performance bottleneck.

The isLoggable check is thus very valuable to avoid this work when it is unnecessary. The Logger.isLoggable call itself is relatively inexpensive, as it only requires one or two integer comparisons between the target level and instance data within the Logger object. That being said, no method call is completely without cost, so be careful not to introduce logging into extremely performance-sensitive sections of code, such as very tight loops. Even the fastest method can slow down performance when it is invoked millions of times.

Admittedly, the isLoggable check is not strictly necessary in the FWD runtime examples above, since neither is part of a performance-critical section of code. The ApplicationRequestedStop exception is not thrown often, nor at a point in the life cycle of a user session where performance is particularly important. Likewise, StandardServer.hookTerminate only runs as a session is ending, when the performance of handling an error is not of great concern. Nevertheless, the isLoggable check is a best practice that is used throughout FWD runtime code.

Apache Commons Logging

Do NOT use this approach for adding logging. The use of different logging approaches in different parts of the FWD runtime is historical and the intention is to phase out the use of the Apache Commons logging library in future versions of the FWD Project.

In certain classes (notably in the com.goldencode.p2j.persist package and its sub-packages) a different logging mechanism is employed, though it is configured in the same way, and is backed by the same logging infrastructure.

This logging mechanism uses the Apache Commons logging classes, an open source library available at http://commons.apache.org/logging/. This library is designed to sit atop various Java logging infrastructures, such as Log4J or - as is the case with the FWD runtime environment - the J2SE logging libraries. Additional implementations are supported. The intention is to provide a uniform logging interface for a developer's use, regardless of the underlying logging implementation.

The process of retrieving a logging object and using that object to write log messages with the Apache Commons library is conceptually the same as the examples shown above, but the API is a bit different.

The class which does the work of logging in this case is org.apache.commons.logging.Log. Each instance of this class represents an underlying, named logger.

An instance of the Log class is accessed using one of the following static methods in the org.apache.commons.logging.LogFactory class:

public static Log getLog(String) throws LogConfigurationException
public static Log getLog(Class) throws LogConfigurationException

The former method uses the String argument as the name of the logger represented by the returned Log object. As with LogHelper.getLogger(String), this is a dot-separated, hierarchical name which can be any arbitrary text.

The latter method uses the fully qualified name of the Class argument as the name of the logger represented by the returned Log object. Note that this behavior is different than that of LogHelper.getLogger(Class), which trims off the class name and uses only the package qualifier to determine the name of the underlying logger.

The following example illustrates the use of this library to retrieve a Log object and to use it to write a log message. This is a slightly modified excerpt from the com.goldencode.p2j.persist.Persistence class:

import org.apache.commons.logging.*;
...

public class Persistence
{
   ...

   /** Logger */
   private static final Log LOG = LogFactory.getLog(Persistence.class);
   ...

   public void save(Persistable dmo, Serializable id)
   throws PersistenceException
   {
      ...

      if (LOG.isDebugEnabled())
      {
         StringBuilder buf = new StringBuilder("Persisted DMO (");
         buf.append(dmo);
         buf.append(") with ID ");
         buf.append(id);
         String msg = message(buf.toString());

         LOG.debug(msg);
      }
      ...
   }
   ...
}

In this case, we use the LogFactory.getLog(Class) method to retrieve a Log with the namespace com.goldencode.p2j.persist.Persistence. The returned Log instance is stored in the static member variable LOG.

The Apache Commons logging library defines its own constants for the various logging levels, which map to the J2SE logging levels as follows:

Apache Commons Logging Level J2SE Logging Level
FATAL SEVERE
ERROR SEVERE
WARN WARNING
INFO INFO
DEBUG FINE
TRACE FINEST

Note there is no Apache Commons analog for the J2SE logging level of FINER. The TRACE level includes both the FINER and FINEST levels.

In the Persistence.save method, we wish to log a message at DEBUG level. As before, we enclose the work of logging, including the composition of the message, within a conditional block. The condition checks that the requested level of logging for the com.goldencode.p2j.persist.Persistence logger is set to FINE or higher, which is the J2SE logging level associated with the Apache Commons DEBUG level:

if (LOG.isDebugEnabled())

The Log class has similar methods to query whether each level of logging is enabled:

public boolean isFatalEnabled()
public boolean isErrorEnabled()
public boolean isWarnEnabled()
public boolean isInfoEnabled()
public boolean isDebugEnabled()
public boolean isTraceEnabled()

We then compose the error message:

StringBuilder buf = new StringBuilder("Persisted DMO (");
buf.append(dmo);
buf.append(") with ID ");
buf.append(id);
String msg = message(buf.toString());

In this case, we don't use the LogHelper.generate method to provide context information. Instead, a private method Persistence.message is used, which internally does similar work to LogHelper.generate, but also adds some persistence-related details to the message prefix.

To actually write the log message, we use another method of Log:

LOG.debug(msg);

Internally, this method applies the FINE logging level filter and logs the message. The Log class provides similar methods for each logging level:

public void fatal(Object message)
public void fatal(Object message, Throwable exception)
public void error(Object message)
public void error(Object message, Throwable exception)
public void warn(Object message)
public void warn(Object message, Throwable exception)
public void info(Object message)
public void info(Object message, Throwable exception)
public void debug(Object message)
public void debug(Object message, Throwable exception)
public void trace(Object message)
public void trace(Object message, Throwable exception)

Each logging level is supported by two overloaded methods: one which logs only a message and another which logs a message and a stack trace of an exception.

Because this logging mechanism is targeted for removal in future versions of the FWD Project, we recommend not using it for new code. Nevertheless, it is described here so that readers of the FWD runtime code will understand its use.

Changing Logging Levels

Server Logging Configuration

Currently, the administration client has no support for dynamic changes to the logging levels of individual loggers, nor to the default logging settings for the FWD server as a whole. In order to change logger settings today, the server must be stopped, the logging configuration changed in the FWD server directory, and the server must then be restarted. Please refer to the Debugging Converted Code chapter of the FWD Conversion Handbook for a description of how to configure logging.

This limitation may be removed in a future version of the FWD Project.

Client Logging Configuration

Logging in the client can be specified in the bootstrap configuration file (TBD: example and link to admin doc).

For spawned clients, you can set the bootstrap config value logging:debug:enable to true in clientConfig/cfgOverrides in directory.xml. (TBD: link to admin doc)


© 2004-2020 Golden Code Development Corporation. ALL RIGHTS RESERVED.