Logging for Legacy Weave Versions

Logging in Weave is done using the third party library named Log4j. It is beyond the scope of this document to explain the how the logging infrastructure works with Log4J however the reader is encouraged to visit the Log4J website to find out more information about inner workings of the library.

The following links will help the reader understand more about Log4J.

Main Site:

http://logging.apache.org/log4j/1.2/

Documentation:

http://logging.apache.org/log4j/docs/documentation.html

Wiki:

http://wiki.apache.org/logging-log4j/

Books:

http://www.qos.ch/shop/products/log4jManual
http://www.amazon.com/Apache-Log4j-Second-Samudra-Gupta/dp/1590594991

Architecture

From the architectural point of view, software application modules and logging components reside in two separate layers. The application makes a call to the logging components in the logging layer and delegates the logging responsibility to those components. The logging components receive the logging request and publish the logging information at preferred destinations.

The figure below represents the collaboration of a software module and its logging components.

The architecture of the log4j API is layered. Each layer consists of different objects performing different tasks. The top layer captures the logging information, the middle layer is involved in analyzing and authorizing the logging information, and the bottom layer is responsible for formatting and publishing the logging information to a destination. In essence, log4j consists of three types of primary objects:

• Logger: The Logger object (known as the Category object in releases prior to log4j 1.2) is responsible for capturing logging information. Logger objects are stored in a namespace hierarchy. I’ll discuss this topic further in the “Logger Object” section of this chapter.

• Appender: The Appender object is responsible for publishing logging information to various preferred destinations. Each Appender object will have at least one target destination attached to it. For example, a ConsoleAppender object is capable of printing logging information to a console.

• Layout: The Layout object is used to format logging information in different styles. Appender objects utilize Layout objects before publishing logging information. Layout objects play an important role in publishing logging information in a way that is human-readable and reusable.

The preceding core objects are central to the architecture of log4j. Apart from them, there are several auxiliary objects that can plug and play to any layer of the API. These objects help manage the different Logger objects active within an application and fine-tune the logging process.

The principal auxiliary components in the log4j framework that play a vital role in the logging framework are: 

• Level: The Level object, previously referred to as the Priority object, defines the granularity and priority of any logging information. Each piece of logging information is accompanied by its appropriate Level object, which tells the Logger object about the priority of the information. There are seven levels of logging defined within the API: OFF, DEBUG, INFO, ERROR, WARN, FATAL, and ALL. Each level has a unique integer value. The Level values can be arranged in an ascending manner:

ALL<DEBUG<INFO<WARN<ERROR<FATAL<OFF

where ALL means most of the logging information will be published and OFF means none of the logging information will be published. For more on this topic, see the “Level Object"

• Filter: The Filter object is used to analyze logging information and make further decisions on whether that information should be logged or not. In the log4j context, Appender objects can have several Filter objects associated with them. If logging information is passed to a particular Appender object, all the Filter objects associated with that Appender need to approve the logging information before it can be published to the preferred destination attached to the Appender. Filter objects are very helpful in filtering out unwanted logging information based on any application-specific criteria.

• ObjectRenderer: The ObjectRenderer object is specialized in providing a String representation of different objects passed to the logging framework. More precisely, when the application passes a custom Object to the logging framework, the logging framework will use the corresponding ObjectRenderer to obtain a String representation of the passed Object. This is used by Layout objects to prepare the final logging information.

• LogManager: The LogManager object manages the logging framework. It is responsible for reading the initial configuration parameters from a system-wide configuration file or a configuration class. The LogManager stores in a namespace hierarchy each Logger instance created with a namespace within an application. When we try to obtain the reference named logger, the LogManager class returns the already created instance of it, or creates a new instance of the named logger, stores it in a repository for future reference, and returns the new instance to the caller application.

Configuring logging

The preceding configuration defines the level of the root logger as DEBUG and specifies the appender to use as testAppender. Next, we define the appender testAppender as referencing the org.apache.log4j.ConsoleAppender object and specify the layout of the appender as org.apache.log4j.PatternLayout. A PatternLayout also requires that a conversion pattern or a format be supplied. We supply the conversion pattern %m%n in this case, which means the logging message will be printed followed by a newline character.

A more complex configuration can attach multiple appenders to a particular logger. Each appender, in turn, can have a different layout, and that layout can have a conversion pattern associated with it. Below is an example of a more complex configuration file.

This configuration file defines the root logger as having level DEBUG and attaches two appenders named CONSOLE and FILE to it. We define one of our own custom loggers with the name com.foo
and the level DEBUG and attach an appender named FILE to the custom logger. The appender FILE is defined as org.apache.log4j.FileAppender. The FILE appender writes to a file named log.out
located in the user.home system path. It is important to note that log4j supports UNIX-style variable substitution such as ${variableName}. The variable name defined is considered as the key and searched first in the system properties. If the log4j framework does not find the name, it then looks for the value for the variable in the properties file being parsed. The CONSOLE appender is then assigned to the org.apache.log4j.ConsoleAppender and the conversion pattern defined is %m%n, which means the printed logging message will be followed by a newline character.

Given the above simple examples the default logging setup for Weave should now look fairly self explanatory.

Reading Log files

When Weave has been installed without any modifications to the logging.properties file, the Weave logs the following information to both the console and the weave.log file within the $WEAVE_HOME/logs directory.  The weave.log file contains the current log messages that Weave has produced in the following format

TIME LOGGING_LEVEL THREAD MESSAGE_ORIGIN MESSAGE

Examples

The following examples help explain each element in the each item.

Example 1

Give the above example the following items can be determined.

Example 2

The main items that change and you should be aware of are the Thread, Message Origin and the Message.  These three items define when and where the message was logged from.  The Thread component can cause some confusion to many first time readers if they have not familiar with mutithreaded applications.  A key example is that you may see the same message three times in succession.  This happens due the the WebService that Weave runs under, is handling requests from multiple different locations at the same time.  Each thread is being executed concurrently and working in isolation within the Weave application.  An example of what you would see in the log file is

The above example illustrates that there were four threads being executed. btpool0-0,btpool0-4,btpool0-7 and btpool0-9.  You can see that btpool0-4 has added a logging message between a message logged by btpool0-0 and btpool0-7.  When looking for a particular sequence messages that have been logged by a particular user, make sure that the thread name is the same throughout the request.

Common issues

Some of the underlying libraries used within Weave also produce logging information.  Each library determines what it sees as being relevant to log at various debugging levels (i.e. ERROR, INFO, etc).  These messages can sometime confuse the reader about where and when an error has occurred.  Also an error message may be in sever parts, this is called a nested exception.  Typically the exact error location and message will be the first in 

e.g. The error below was caused by the Database closing the connection.  The first exception is the most detailed as it explains that the error's original location was in the class oracle.jdbc.driver.SQLStateMapping which is core to the oracle communications libraries back to the database. The next error nested exception is the code that called the oracle class  com.cohga.server.stats.export.internal.ExportEvents. This classes re threw the exception which was logged in the logging file.

When reading a log file you will typically work your way from the bottom to the top.  If you do and you encounter an error, please go to the first location in the log file that it occurs.  It will generally be the most detailed.