Anyone who has ever had to look at logs from a Confluence instance knows that they are pretty verbose. Yet at times we still wish there was a little bit more information in them, particularly regarding the nature of the web request in which the log message was generated. CONF-7878 was raised by a user exasperated by trying to understand where certain, seemingly ephemeral messages were coming from. This exasperation is certainly understandable. Often the best resource for reproducing logged errors is the user that was affected by the error as they can describe the sequence of actions that were performed that resulted in the error. To facilitate this we needed some small enhancements to our logging infrastructure.

Since Confluence 2.4.2 we now have a web filter and an XWork interceptor which add some particularly pertinent information to Log4j's Mapped Diagnostic Context (MDC). The MDC is basically a thread local key value map allowing developers to store information about the code that is executing that can be used to enhance the context of logged messages.

Whenever a log message is emitted at a level higher than WARN or has an associated Throwable, Confluence's log appender will output a line with the contents of the MDC. In addition to the information added by the web filter and XWork interceptor, Confluence developers have the option of adding new items to the MDC if they feel that any messages generated by their code would benefit from extra context when logged.

Here's an example of the new log message format:

2007-04-23 03:06:14,484 ERROR [TP-Processor11] [atlassian.renderer.v2.V2Renderer]
   render Unable to render content due to system error: null
 -- url: /pages/doexportpage.action | userName: ben | action: doexportpage 
    | page: 69518087748064507
java.lang.NullPointerException
        at com.atlassian.confluence.importexport.DefaultExportContext.isPageInExport
    (DefaultExportContext.java:115)
        at com.atlassian.confluence.importexport.impl.ExportLinkRenderer.isExportedPage
    (ExportLinkRenderer.java:119)

As you can see from the second line of the log message we now know the URL and name of the action which was executing when this error was logged along with the user who was affected and the database ID of the page that was involved. This should allow our customers and support staff to analyze log messages such as these much more effectively and hopefully reduce the time it takes to track down and solve these problems.