Logging for Legacy Weave Versions

Applicable for Weave versions prior to, and including, 2.6.6

 

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:

Apache 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

#set the level of the root logger to DEBUG and set its appender #as an appender named testAppender log4j.rootLogger = DEBUG, testAppender #define a named logger log4j.logger.dataAccessLogger = com.apress.logging.logger #set the appender named testAppender to be a console appender log4j.appender.testAppender=org.apache.log4j.ConsoleAppender #set the layout for the appender testAppender log4j.appender.testAppender.layout=org.apache.log4j.PatternLayout log4j.appender.testAppender.layout.conversionPattern=%m%n

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.

# define the root logger with two appenders writing to console and file log4j.rootLogger = DEBUG, CONSOLE, FILE   #define your own logger named com.foo #and assign level and appender to your own logger log4j.logger.com.foo=DEBUG,FILE   #define the appender named FILE log4j.appender.FILE=org.apache.log4j.FileAppender log4j.appender.FILE.File=${user.home}/log.out   #define the appender named CONSOLE log4j.appender.CONSOLE=org.apache.log4j.ConsoleAppender log4j.appender.CONSOLE.conversionPattern=%m%n

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.

# Logging settings, see Log4J documentation for further help # Web address http://jakarta.apache.org/log4j/docs/api/index.html   # Threshold can be set to DEBUG, INFO, WARN, ERROR or FATAL   # Output to stdout and log file, use during instial installation # The following should be used when debugging Weave log4j.rootCategory=DEBUG, stdout, file     # Uncomment the following to reduce the amount of information written to the logfile # Note: we have removed the stdout to not have any messages being written to the standard out #log4j.rootCategory=ERROR, file     # Define a logger that sends it's outout to the console # only usfull when Weave isn't installed as a service log4j.appender.stdout=org.apache.log4j.ConsoleAppender log4j.appender.stdout.Threshold=DEBUG log4j.appender.stdout.layout=org.apache.log4j.PatternLayout log4j.appender.stdout.layout.ConversionPattern=%m <%c> [%t] %n   # Define a logger that sends it's output to a rolling log file log4j.appender.file=org.apache.log4j.DailyRollingFileAppender log4j.appender.file.Threshold=DEBUG log4j.appender.file.File=../logs/weave.log log4j.appender.file.Encoding=UTF-8 log4j.appender.file.layout=org.apache.log4j.PatternLayout log4j.appender.file.layout.ConversionPattern=%d{ABSOLUTE} %-5p [%t] %x %c "%m"%n   # If you want email for problems then add this to the rooCategory # e.g. alter the above to log4j.rootCategory=ERROR, email, file log4j.appender.email=org.apache.log4j.net.SMTPAppender log4j.appender.email.Threshold=ERROR log4j.appender.email.SMTPHost=mail log4j.appender.email.SMTPPort=22 # Uncomment the following lines if you have to authenticate when sending mail #log4j.appender.email.SMTPUsername=mail #log4j.appender.email.SMTPPassword=mail     # Set the following to true to enable debugging information about sending email to the stdout. # Useful if you find you are having issues send mail. log4j.appender.email.SMTPDebug=false   log4j.appender.email.From=weave@localdomain log4j.appender.email.To=admin@localdomain log4j.appender.email.Subject=[Weave] Application error log4j.appender.email.BufferSize=512 log4j.appender.email.layout=org.apache.log4j.PatternLayout log4j.appender.email.layout.ConversionPattern=%d{ABSOLUTE} %-5p [%t] %x %c "%m"%n   # Reduce the messages from some of the apache classes # Uncomment the following if you would like to see more detailed messages from some # of the third party libraries used.  Please note some of these packages produce vasts # amounts of logging information and will most likely reduce the speed of Weave. log4j.logger.org.apache=WARN log4j.logger.org.mortbay=ERROR log4j.logger.org.geotools=ERROR log4j.logger.net.refractions=ERROR log4j.logger.org.springframework=WARN log4j.logger.org.acegisecurity=WARN log4j.logger.net.sf.ehcache=ERROR   # Comment out the following line to get AXL requests and responses logged log4j.logger.com.cohga.server.map.arcims.log.ArcImsLog=ERROR

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.

Item

Value

Description

Item

Value

Description

TIME

00:06:45,405

States the time the message was logged to the file.  Format is HOURS:MINUTES:SECONDS,MILLISECONDS

LOGGING_LEVEL

DEBUG

The Level of the message logged. Possible values are DEBUG, WARN, INFO or ERROR

THREAD

[pool1-thread-1]

The thread that the message was logged in (See below for more information about reading logs).

MESSAGE_ORIGIN

com.cohga.client.weave.Activator

The class that the message was logged against. e.g. The class Activator in the package com.cohga.client.weave

MESSAGE

"Removed script source from ..."

The message that is being set to the log.  Typically this is in human readable form, however sometimes the messages may not be that intuitive to the user.

Example 2

Item

Value

Description

Item

Value

Description

TIME

00:06:45,405

States the time the message was logged to the file.  Format is HOURS:MINUTES:SECONDS,MILLISECONDS

LOGGING_LEVEL

DEBUG

The Level of the message logged. Possible values are DEBUG, WARN, INFO or ERROR

THREAD

[OSGi Console]

The thread that the message was logged in (See below for more information about reading logs).  

MESSAGE_ORIGIN

com.cohga.search.indexer.internal.Activator

The class that the message was logged against. e.g. The class Activator in the package com.cohga.search.indexer.internal

MESSAGE

"Stopping Weave Index ..."

The message that is being set to the log.  Typically this is in human readable form, however sometimes the messages may not be that intuitive to the user.

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.