Making Dump Logs Useful

When something goes awry in a production system, or even in a sufficiently complex non-production system, logs are the only debugging tool I have found to be consistently useful. Debuggers are simply too fine-grained and too slow to configure to be of practical utility, and nothing else exists that will reveal to me the thread of execution.

In a system of enterprise level complexity, one can't simply pile through all of the logs that the system is capable of generating. The cost of generating all of those logs will significantly impact the performance of the system, the amount of data generated may exceed available storage, and once the detail level of the logs is high enough, the only tool capable of extracting any meaningful information is grep. I don't like using grep on logs, because I find it can "hide" useful contextual information from nearby log events.

The logging provided by J2EE containers is already quite configurable: the detail level can be set by class, and classes are organized hierarchically according to package. In some cases, however, this is not enough. Debugging Exchange sync failures frequently requires trace-level logging from SQLAdapter and HTTPAdapter. Both of these classes are generic enough to be used by several different functional components of the application. Turning up the log levels on these two classes generates so many logs that finding useful information in them is extremely difficult. Adding to the complexity is the fact that Exchange Sync is multi-threaded, and operations relating to different mailboxes tend to be interleaved.

We recently found a technique that may simplify debugging in this scenario: log filtering. This technique is specific to Log4J, so currently only works in JBoss and Teee. It turns out that one can specify filter beans on each configured appender. For example, the following appender configuration will output only log messages containing the word "insert" (StringMatchFilter is a builtin filter, provided with Log4J.)

   <appender class="org.jboss.logging.appender.DailyRollingFileAppender" name="NexJFile">
      <errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler"/>
      <param name="File" value="${jboss.server.home.dir}/log/nexj.log"/>
      <param name="Append" value="true"/>
      <param name="DatePattern" value="'.'yyyy-MM-dd"/>
      <layout class="org.apache.log4j.PatternLayout">
         <param name="ConversionPattern" value="%d %-5p [%c] (%t:%x) %m%n"/>
      </layout>
      <filter class="org.apache.log4j.varia.StringMatchFilter">
         <param name="StringToMatch" value="insert"/>
         <param name="AcceptOnMatch" value="true" />
      </filter>
      <filter class="org.apache.log4j.varia.DenyAllFilter">
   </appender>

This is a simple and silly example: the string "insert" can appear anywhere in the message, and we have no real control over the context from which the event originated. Nonetheless this example is interesting for a few reasons. Firstly, note that the filter does not limit the log messages constructed by the system: the usual log level settings by category determine which log messages are built, the filter is applied to all of these messages, and only those messages accepted by the filter are recorded in the target stream (/log/nexj.log).

Secondly, note that filters can be chained (much like Linux IPChains). For each message, a filter has 3 options: ACCEPT (append immediately), DENY (reject immediately) or NEUTRAL (pass the message on to the next filter). In the simple example, the first filter ACCEPTs any message containing "insert" and is NEUTRAL to all other messages. The second filter DENYs everything... but those messages accepted by the first filter never reach the second one. The filters are configurable beans, so any class supporting the required interface can be used as a filter. Naturally, we want to take advantage of this.

The specific goal that I had in mind to assist in debugging Exchange Sync was to be able to generate trace-level logs of SQL and HTTP activity, but restrict the output to events occurring in the context of synchronization to a particular mailbox. I wanted this so that I could get a detailed trace of control flow in ProdData without generating so much data that the logs roll over several times a minute, and so that I wouldn't have to worry about sorting through a lot of interleaved execution.

There are two elements to the plan: 1) dump an identifier for each folder in the context of each log message; 2) write a filter that does matching on the context of each log message.

What is this "context" that I speak of? Log4J supports a "Nested Diagnostic Context", which is really just a fancy word for a string associated with the currently running thread. What is nice about the context is that it is the same across all components in the system that are generating log events on a given thread. So far, we have been putting the current user-principal in this context. But now, where relevant, we also put the class name and OID of the currently active synchronization link in the context. This makes it relatively straight-forward to locate all log events relating to a particular user mailbox/folder.

The second element of the plan is to build a custom filter that accepts log messages based on the contents of their nested diagnostic context. The class is quite simple and has been added to nexj-jboss.jar in 2C maintenance and HEAD. The following is a sample configuration:

   <appender class="org.jboss.logging.appender.DailyRollingFileAppender" name="NexJFile">
      <errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler"/>
      <param name="File" value="${jboss.server.home.dir}/log/nexj.log"/>
      <param name="Append" value="true"/>
      <param name="DatePattern" value="'.'yyyy-MM-dd"/>
      <layout class="org.apache.log4j.PatternLayout">
         <param name="ConversionPattern" value="%d %-5p [%c] (%t:%x) %m%n"/>
      </layout>
      <filter class="nexj.core.util.log.log4j.NDCFilter">
         <param name="Category" value="nexj.core.rpc.http"/>
         <param name="Level" value="DEBUG" />
         <param name="Pattern" value="ExchangeFolder:.*:A0E3D" />
         <param name="Required" value="true" />
      </filter>
      <filter class="nexj.core.util.log.log4j.NDCFilter">
         <param name="Category" value="nexj.core.persistence.sql.SQLAdapter"/>
         <param name="Level" value="INFO" />
         <param name="Pattern" value="ExchangeFolder:OID:1:V32:A0E3D" />
         <param name="Required" value="true" />
      </filter>
   </appender>

The above example uses two filters. Each filter specifies a Category: the filter is neutral to all messages from classes outside the category. Each filter specifies a Level: all messages from Category that are no more detailed than this level are ACCEPTed, regardless of their context. Each filter specified a Pattern, which is a regular expression compared against the nested diagnostic context of any message from Category which is more detailed than Level. If the pattern is found in the context, the message is ACCEPTED. If the pattern is not found, the message is either DENYed (if Required is true) or is marked NEUTRAL and passed to the next filter.

So the sample configuration records all messages in the nexj.core.rpc.http package that are DEBUG level or higher, or that contain "ExchangeFolder:.*:A0E3D" in their context; and records all messages from nexj.core.persistence.sql.SQLAdapter that are INFO level or higher, or that contain "ExchangeFolder:OID:1:V32:A0E3D" in their context. Messages from other categories are unaffected by these filters.

Suppose that you have configured log levels to dump the following logs:

DEBUG [nexj.core.rpc.http.HTTPAdapter] (WorkManager(3)-25:mike2 <ExchangeFolder:OID:1:V32:A0E3D>) 
Sending a message on channel "ExchangeSender"
DUMP  [nexj.core.rpc.http.HTTPAdapter] (WorkManager(3)-25:mike2 <ExchangeFolder:OID:1:V32:A0E3D>) TO<>(

   method="PROPPATCH",

   url="MBX/michael3/Calendar/NexJ-106.EML"

)
DEBUG [HTTPAdapter] (WorkManager(3)-25:mike2 <ExchangeFolder:OID:1:V32:A0E3D>) Received a response on channel "ExchangeSender"
DUMP  [HTTPAdapter] (WorkManager(3)-25:mike2 <ExchangeFolder:OID:1:V32:A0E3D>) TO<>(
   status=207,
   message="Multi-Status"
)
DEBUG [SQLAdapter] (WorkManager(3)-25:mike2 <ExchangeFolder:OID:1:V32:A0E3D>) insert into NJSyncObject
(id, externalId, externalVersion, externalURL, internalId, internalVersion, beforeImage, linkId, classId, groupId, partitionId) 
values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
INFO [SQLAdapter] (WorkManager(3)-25:mike2 <ExchangeFolder:OID:1:V32:A0E3D>) SQL execution time: 15 ms
DEBUG [nexj.core.rpc.http.HTTPAdapter] (WorkManager(3)-25:mike2 <ExchangeFolder:OID:1:V32:46D83>) 
Sending a message on channel "ExchangeSender"
DUMP  [nexj.core.rpc.http.HTTPAdapter] (WorkManager(3)-25:mike2 <ExchangeFolder:OID:1:V32:46D83>) TO<>(
   method="PROPPATCH",
   url="MBX/michael3/Calendar/NexJ-106.EML"
)
DEBUG [HTTPAdapter] (WorkManager(3)-25:mike2 <ExchangeFolder:OID:1:V32:46D83>) Received a response on channel "ExchangeSender"
DUMP  [HTTPAdapter] (WorkManager(3)-25:mike2 <ExchangeFolder:OID:1:V32:46D83>) TO<>(
   status=207,
   message="Multi-Status"
)
DEBUG [SQLAdapter] (WorkManager(3)-25:mike2 <ExchangeFolder:OID:1:V32:46D83>) insert into NJSyncObject
(id, externalId, externalVersion, externalURL, internalId, internalVersion, beforeImage, linkId, classId, groupId, partitionId) 
values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
INFO [SQLAdapter] (WorkManager(3)-25:mike2 <ExchangeFolder:OID:1:V32:46D83>) SQL execution time: 15 ms

With the filter configuration provided above, you would only get the following lines in your log file:

DEBUG [nexj.core.rpc.http.HTTPAdapter] (WorkManager(3)-25:mike2 <ExchangeFolder:OID:1:V32:A0E3D>) 
Sending a message on channel "ExchangeSender"
DUMP  [nexj.core.rpc.http.HTTPAdapter] (WorkManager(3)-25:mike2 <ExchangeFolder:OID:1:V32:A0E3D>) TO<>(
   method="PROPPATCH",
   url="MBX/michael3/Calendar/NexJ-106.EML"
)
DEBUG [HTTPAdapter] (WorkManager(3)-25:mike2 <ExchangeFolder:OID:1:V32:A0E3D>) Received a response on channel "ExchangeSender"
DUMP  [HTTPAdapter] (WorkManager(3)-25:mike2 <ExchangeFolder:OID:1:V32:A0E3D>) TO<>(
   status=207,
   message="Multi-Status"
)
DEBUG [SQLAdapter] (WorkManager(3)-25:mike2 <ExchangeFolder:OID:1:V32:A0E3D>) insert into NJSyncObject
(id, externalId, externalVersion, externalURL, internalId, internalVersion, beforeImage, linkId, classId, groupId, partitionId) 
values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
INFO [SQLAdapter] (WorkManager(3)-25:mike2 <ExchangeFolder:OID:1:V32:A0E3D>) SQL execution time: 15 ms
DEBUG [nexj.core.rpc.http.HTTPAdapter] (WorkManager(3)-25:mike2 <ExchangeFolder:OID:1:V32:46D83>) 
Sending a message on channel "ExchangeSender"
DEBUG [HTTPAdapter] (WorkManager(3)-25:mike2 <ExchangeFolder:OID:1:V32:46D83>) Received a response on channel "ExchangeSender"
INFO [SQLAdapter] (WorkManager(3)-25:mike2 <ExchangeFolder:OID:1:V32:46D83>) SQL execution time: 15 ms

In this case, the data reduction is not huge, but keep in mind that only two mailboxes were involved!