Systemic Qualities.Logging - OpenESB: the Open Source ESB for SOA & Integration

Index Changes

This is version 5. It is not the current version, and thus it cannot be edited.
[Back to current version] [Restore this version]

Logging is used by different people for different things:

administrators will use the log to monitor system state, monitor for errors, and trouble shoot errors
application developers will use the log additionally to trouble shoot their own application code
support, sustaining and development will use the log additionally to trouble shoot the product code

These groups of people want:

Log files that contain enough understandable information,
but not too much useless information,
To be able to tie log messages to particular parts of the system; this is especially important in production environments where there are many different application components deployed on the same server; ideally logging should be tied to applications and to systems
Ways to increase logging in particular areas, and decrease logging in other areas
An easy way to view log files

Requirements on components and runtime

Use JDK logging only; use of log categories and log levels properly. See below.
The right amount of logging information:
1. During normal operation of the system without failures no log should be generated at default level
2. Components need to log this information at consistent log levels and consistent format:
  1. Message flow through system
  2. Configuration Changes
  3. Component lifecycle changes
  4. Connection status
  5. Connection failures
Log messages CONFIG and above should be Internationalizable, which implies:
1. The use of properties bundles for all log messages INFO and higher
2. Debug messages (FINE and less) should not be localized; if such messages are in resource bundles they should be marked as such so that they are not localized. The reason for this is to save money.
Log message catalogs (a list of all messages in the product), which implies that log messages are uniquely identifiable
1. applies to all messages INFO and higher
2. the identifier appears both in the log and in the properties bundle
3. the identifier matches ^[a-zA-Z\-](3,8)\d(3,5). Example: RAR0123, JTA-3452, JMSJCA-E098
4. the identifier consists of two parts: the first part identifies the system (it identifies a namespace), the second part is a unique identifier in that namespace. No guarantee can be made that the namespace identifier is globally unique, but with a proper choice of the name it is unlikely to clash with another namespace within the same product.
5. a log message should begins with the identifier followed by a colon, e.g. RAR0123: The adapter could...
6. messages may be nested and should not loose their message identifiers, e.g. RAR0123: The adapter could not be deployed: RASTCMS-E002 [stcmx://] is not a valid URL
The right information in log messages, which implies
1. Correct English with enough context information and configuration information to make the message understandable to a user. Example: not RAR0123: file not found but RAR0123: The adapter could not be deployed: error reading file [domains/domain1/applications/ear1/rar1/META-INF/ra.xml]: file not found
2. Where a component creates a thread, a proper name for the thread
3. The use of NDC for application names and request names
4. Correct use of stack traces: stacktraces should be propagated to the log using the Throwable parameter in the various log methods in the Logger class; the should NOT be printed to System.out or System.err
5. Stacktraces should preserve the original root cause
6. Correct use of only-once-per-file messages
7. System.out and System.err should NOT be used to log any information
An easy way to manage logs, which implies
1. Publishing a comprehensive list of loggers for each component

Logging quality

Quality of logging can be improved with respect to:

frequency of logging and log level
quality of log messages
consistent use of the nested diagnostic context

This will have to be done mainly through developer education. See below.

The quality of the message texts can be checked for being meaningful and being correct English by QA or Documentation by looking at the properties bundles.

Log level

Logging is turned on by default, at the INFO level to be precise. It should not be necessary for administrators to turn off logging for any log category. Under normal steady-state conditions, the log should not grow at all.

The available log levels should be used as follows:

Level	Frequency	When	Example
SEVERE	Rarely	The system is in critical need of attention. To resolve this error, the administrator MUST undertake action.	Component could not start because of a missing configuration file; application could not be deployed because an object is not bound to JNDI; a message could not be sent because of a missing certificate.
WARNING	Ideally not more than once every few seconds	An error occurred; the error may recover itself.	Failed to connect to an external system, retry attempts will be made; message could not be sent because it contained invalid data
INFO	At most a few times in the application's or container's lifecycle	The system as a whole has changed state.	An inbound connector will now receive messages from an external system
CONFIG	see INFO	A system wide of application wide configuration change has happened	The transaction time out was changed to 50 seconds.
FINE	Per log message: about once for each transaction	debugging and diagnostics	Loading certificate a.cer from store c:\yyy.store
FINER	Multiple times per transaction	debugging and diagnostics	Sending block 982 out of 1000
FINEST	Unlimited	debugging	Received 5 bytes, state = 0

Custom log levels should not be added due to a bug in JDK logging.

Minimum trace messages

JBI components should log the following events at FINE:

accepting a message, printing the ID
denormalizing a message, printing each part
normalizing a message, printing each part
sending a message, printing the ID

Logging categories

The convention of JDK-logging is to use the fully qualified classname of the class that does the logging as the category name. This convention should be adhered to.

Nested diagnostics context

This feature allows a thread to be associated with an application, so that all logging that is done in other parts of the system on behalf of this application logs this context name. This helps tying log messages to applications. There is a similar facility in SJSAS called Callflow. To promote portability between different runtimes, the Logger api will be used and a special meaning will be adhered to particular Logger objects:

Logger.getLogger("com.sun.EnterContext").fine("context") will mark a beginning of an NDC
Logger.getLogger("com.sun.ExitContext").fine("context") will mark the end of an NDC
For backwards compatiblity, com.stc.EnterContext is an alias for com.sun.EnterContext; com.stc.ExitContext is an alias for com.sun.ExitContext;
(Out of scope for Sierra: Logger.getLogger("com.sun.EnterContext").log(Level.Fine, "{0}/{1}", new Object {context, reqid}) will mark a beginning of an NDC and a request id; similar for ExitContext)

See NDC blog entry for more information and immediate use of this feature in SJSAS.

JBI component loggers

JBI introduces a way to get loggers from a component context: ComponentContext.getLogger(name) returns an ordinary logger with name component name + name. These loggers are then associated with the component, i.e. they are listed as loggers for that component. This currently does not work for loggers allocated in libraries in use by the component: these libraries do not call ComponentContext.getLogger(name) but call Logger.getLogger(name).

Components should list the loggers they use in their jbi.xml, including the ones for which ComponentContext.getLogger(name) is called and the library loggers for which Logger.getLogger(name) is called.

The JBI runtime provides MBeans for each for of the loggers associated with a component; these loggers are visible in NetBeans and the admin console and can be manipulated through there. The JBI runtime does not persist logging changes. In fact, the JBI runtime should delegate manipulation of loggers to the SJSAS runtime so that they are persisted in domain.xml together with settings of other loggers.

Log levels and configuration

It should be easy to figure out for an administrator what log categories there are, and to change the log levels on these categories. Same thing for developers.

Only-once-per-file messages

Sometimes components want to log a message only once in the log. This message should be retained when the log file rotates, i.e. the message should be repeated once in the new log file. Functionality can be added to SJSAS that notifies loggers somehow that a log file rotation has happened, or prevents log messages from being written repeatedly to the same log file.

Loggers that have names that end in -once will exhibit this behavior.

Separate log files

Several customers have expressed the wish to have a separate log file per application, or have separate log files for auditing etc. Ignoring the merits or lack thereof of these requirements, this requirement can be addressed by either filtering the exiting rotating log file, or by creating separate log files at the moment the logging happens. For Sierra the approach of filtering in the log viewer will be used.

The user should be able to specify filters that take into account the NDC, level, and log categories.

Duplicate stack traces removal

Redundant printing of stack traces should be avoided. This greatly reduces clutter in the log. This functionality should be added to SJSAS.

Internationalization and message cataloging

The typical way of internationalizing code is error prone and cumbersome. Using a small build tool, the process of internationalization can be reduced to:

Adding an internationalization class to a module
Replacing log messages with a method invocation on this class plus a message identifier
Running the tool as part of the build process automatically generates a properties bundle

Example:

   sLog.info(I18N.x("E001: The component with name [[{0}] could not be "
     + "unloaded after {1} tries, the last error was: {2}", name, Integer.toString(i), e), e);

which results in this log message: XYZBC-E001: The component with name [test] could not be unloaded after 5 tries, the last error was: XYZBC-E002: File [a/b/c/d/] could not be deleted

The properties bundle XYZBC-msgs.properties generated as part of the build contains:

# com.sun.jbi.xyzbc.core.LifecycleManagement:
E001: The component with name [[{0}] could not be unloaded after {1} tries, the last error was: {2}

A way to enforce internationalized messages is to introduce a special String class that represents a localized message. Log wrappers around the java.util.logging.Logger class only accept these localized messages. Likewise, custom exception classes or helper methods to throw exceptions are helpful if they only accept localized string objects.

The I18N build tool and log wrappers / exception helpers that only accept localized messages was used successfully in JMSJCA.

See I18N blog entry for more information on how to use this tool and where to get it.

Action items:

Educate developers so that all new code will be internationalizable and have message catalogs
Publish the JMSJCA approach to internationalizable message logs and catalogs
Decide if all existing code needs to be internationalizable and have message catalogs

Error messages

Errors are propagated in Java using exceptions. Exceptions should be logged only at the place where the exception is not rethrown. This exception should contain enough context information so that a meaningful error message can be logged. For this, it may be necessary to catch exceptions at lower levels, create a new exception, add context information AND the original exception, and throw the new exception. The original exception message should be concatenated to the new exception message and the new original exception message should be set as the cause of the new exception message.

Wrong:

    } catch (Exception e) {
         throw new ApplicationException(I18N.x("E123: method failed"));
    }

Right:

    } catch (Exception e) {
         throw new ApplicationException(
           I18N.x("E123: Webservice {0}({1}) could not be invoked: {2}", methodname, argarray, e)
           , e);
    }

Reducing overhead for debug logging

Calls to fine, finer and finest should be guarded as follows:

if (sLog.isLoggable(Level.FINEST) {
    sLog.fine("Received message with id = " + messageid);
}

The idea of doing it this way that the object creation due to the string concatenation is avoided by first checking if the message would be logged in the first place.

Log viewer

EM provides a web based log viewer, and so does SJSAS. Long term, there should be only one of them.

The web console log viewer should be extended with more filtering capabilities so that the log stream can be filtered based on application name, request id (Post Sierra), thread name (Post Sierra), etc. It should be possible to hide stack traces and to unhide stack traces.

(Post Sierra) Several people in the field have expressed interest in a log viewer that could quickly filter out messages, correlate messages on the same thread, etc. It may be possible to have this task done by the community (Frank wrote a viewer years ago that meets most of these requirements).

Risks

In case the changes to SJSAS cannot happen in time, the NDC and separate log files can be done through a lifecycle listener that doesn't require changes to the app server. However, once-per-file-messages also can be done through a lifecycle listener, but does require a small change to the appserver.

The other changes such as an improved log level management page is not a show stopper, neither is the log viewer. So it simply means that these changes will be pushed to a subsequent release.

Action items

Ranking system:

Critical correspond to P1
Lower ratings correspond to P2

Requirements on SJSAS

Importance	What
Critical	Support for NDC
Important	Improvements in the logging management page
Nice to have	Support for separate log files
Nice to have	Support for only-once-per-file messages
Important	Work with SJSAS team to fix existing bugs in logging configuration page
Nice to have	Duplicate stacktrace removal
Nice to have	Stand alone log viewer; see EM requirements for web based log viewer

Requirements on JBI runtime

Importance	What
Critical	adherence to component requirements
Critical	Loggers in `jbi.xml`
Important	Change in JBI runtime: runtime/manage/src/com/sun/jbi/management/support/DefaultLoggerMBeanImpl.java should call SJSAS MBean method to set log level instead of `Logger.setLevel()`.
Critical	Parts of the JBI runtime currently don't have a unique msgid; needs fixing
Critical	Parts of the JBI runtime currently print stacktraces to the console (end up in the log file); needs fixing

Requirements on Classic CAPS components

Importance	What
Nice to have	Although the Classic CAPS components don't use resource bundles nor do they use unique ids, Classic CAPS components will not be modified to comply with all of the logging guidelines. Some of the worst offending log messages may be changed if enough resources can be found to change them.

Requirements on JBI components

Importance	What
Critical	The JBI components currently don't have a unique msgid; needs fixing.
Critical	Use NDCs for those components for which it makes sense
Critical	Minimum trace messages
Critical	JBI Components should list all loggers in `jbi.xml`

Requirements on Glassfish console or EM

Importance	What
Critical	Assuming that the EM console will be integrated into Glassfish and into the Glassfish console, need to determine if the log viewer in EM is going to replace the log viewer in SJSAS or vice versa.
Critical	Log viewer should filter based on application
Nice to have	Log viewer should filter based by request ID or message ID
Critical	Log viewer should have the ability to hide or unhide stacktraces
Critical	Log viewer (EM) should be fully stable (past (?) instabilities have turned off many users from using EM log viewer)
Nice to have	Log viewer should page faster
Nice to have	Log viewer should be faster in use with respect to setting up filters, etc

Developer education

Importance	What
Critical	Finish guidelines
Critical	Have sessions with developers to ensure everybody is aware of these guidelines.

Resources

Initiative Lead: Frank Kieviet

Version	Date	Author	Size	Changes ...
7	24-Oct-08 19:15 PM, -0700	KevanSimpson	18509	to previous
6	11-Aug-08 14:32 PM, -0700	KevanSimpson	18264	to previous \| to last
5	06-Dec-07 17:09 PM, -0800	Alexander.Fung	17263	to previous \| to last
4	10-Oct-07 16:22 PM, -0700	FrankKieviet	17212	to previous \| to last
3	10-Oct-07 16:04 PM, -0700	Alexander.Fung	17327	to previous \| to last
2	10-Oct-07 15:59 PM, -0700	Alexander.Fung	17343	to previous \| to last
1	10-Oct-07 15:58 PM, -0700	Alexander.Fung	17362	to last

G'day, Anonymous Guest

JSPWiki v2.4.100

« Home Index Changes Prefs

This particular version was published on 06-Dec-07 17:09 PM, -0800 by Alexander.Fung