Sending Java Stack Traces to Loggly

Recently at my new Autopilot contract, I was tasked with configuring some of our applications to send log entries to Loggly. We're using log4j, rsyslog, and syslog4j.

The Loggly service produces nice data which are easily accessible through a pleasant interface. The configuration was simple, logging works from anything that can log with syslog, and Loggly support was generally responsive (it definitely helps to have a corporate relationship).

Once we had the environment configured, we configured log4j following Loggly's Log4j Setup instructions. We were getting log messages into loggly in no time. The only problem was that we weren't getting stack traces.

This was a little bit confusing because the setup document reads:

You can send your Java logs using Log4j. The method shown supports multi-line events such as a Java stacktraces over Syslog.

I dug through the my usual channels looking for someone else who had the same experience. All I was able to find really was this one Stack Overflow question.

Not really being a Java guy, I assumed I was just missing something. In fact, the folks at Loggly told me I was missing something too. :) I first started looking into the rsyslog documentation regarding multi-line log entries (like stack traces). I noticed that the file input module supports a ReadMode attribute, but the udp input module does not.

I added a rolling file appender to my log4j.properties file, I configured the imfile in our rsyslog config file, and we were off to the races. Good looking easy to read stack traces. It's worth noting I'm using the paragraph ReadMode because not all lines in a Java stack trace are indented. Thus, I needed a full blank line between log entries. This is more or less our log4j.properties configuration for the rolling file appender:

  log4j.appender.ROLLING=org.apache.log4j.rolling.RollingFileAppender
  log4j.appender.ROLLING.File=/tmp/log4j.log
  log4j.appender.ROLLING.rollingPolicy=org.apache.log4j.rolling.TimeBasedRollingPolicy
  log4j.appender.ROLLING.rollingPolicy.FileNamePattern=/tmp/log4j.log.%d{yyyy-MM}.gz
  log4j.appender.ROLLING.layout=org.apache.log4j.PatternLayout
  log4j.appender.ROLLING.layout.ConversionPattern=%n%d{yyMMdd.HHmmss,SSS} %t %C{1}.%M %p: %m%n

This was well and good but I wanted to make sure I wasn't missing a simpler alternative. The docs said it would work via rsyslog udp and I wanted to know why I was having such trouble. I looked at the network traffic coming from my dev instances. I noticed that my messages didn't include any stack trace information at all. It wasn't just a multiline issue really. It was that stack traces were never being logged by syslog4j. I looked into the ConsoleAppender and found that it gets its append behavior from WriterAppender.subAppend. That method is how the console gets stack traces after the message has been written using the layout.

if(layout.ignoresThrowable()) {
    String[] s = event.getThrowableStrRep();
    if (s != null) {
        int len = s.length;
        for(int i = 0; i < len; i++) {
            this.qw.write(s[i]);
            this.qw.write(Layout.LINE_SEP);
        }
    }
}

I started looking at the Syslog4jAppenderSkeleton.append method. I noticed that this appender never logs stack traces at all.

protected void append(LoggingEvent event) {
 if (!this.initialized) {
  _initialize();
 }
  
 if (this.initialized) {
  int level = event.getLevel().getSyslogEquivalent();
   
  if (this.layout != null) {
   String message = this.layout.format(event);
   
   this.syslog.log(level,message);
   
  } else {
   String message = event.getRenderedMessage();
   
   this.syslog.log(level,message);
  }
 }
}

It was no wonder I wasn't getting stack traces into loggly. I looked back at the ConsoleAppender and wondered what the layout.ignoresThrowable was. I looked at the docs and found that the PatternLayout.ignoresThrowable method always returns true because it can't handle throwables. In fact, the same page reads:

A flexible layout configurable with pattern string. This code is known to have synchronization and other issues which are not present in org.apache.log4j.EnhancedPatternLayout. EnhancedPatternLayout should be used in preference to PatternLayout. EnhancedPatternLayout is distributed in the log4j extras companion.

Easily convinced, I switched to the EnhancedPatternLayout. I configured the ConsoleAppender to use the enhanced pattern layout and I added the %throwable configuration item to it. Viola! Stack traces . . . by my own doing. I copied the configuration to the Syslog4jAppender section, started the long deployment process, and watched in disappointment as I still had no stack traces.

I started messing with the layout on my Syslog4j appender and noticed nothing I did changed the resulting log message. That seemed a little odd, so I dug into that a little. I dug back into the Syslog4jAppenderSkeleton.append again. I set a breakpoint on this.layout.format(event); and attached the debugger. My breakpoint was never hit. The layout was always null!

I set out in search of where that field was getting set. We're using the log4j.properties file so our configuration is parsed by the PropertyConfigurator parseAppender method. This is a pretty big method but here's what I noticed:

if(appender.requiresLayout()) {
    Layout layout = (Layout) OptionConverter.instantiateByKey(props, layoutPrefix, Layout.class, null);
    if(layout != null) {
        appender.setLayout(layout);
        LogLog.debug("Parsing layout options for \"" + appenderName +"\".");
        //configureOptionHandler(layout, layoutPrefix + ".", props);
        PropertySetter.setProperties(layout, props, layoutPrefix + ".");
        LogLog.debug("End of parsing for \"" + appenderName +"\".");
    }
}

So again I looked at the implementation of Syslog4JAppenderSkeleton and found that requiresLayout always returns false!

public boolean requiresLayout() {
    return false;
}

This struck me as odd and it made me wonder how anyone ever was able to use the layout property with syslog4j. It turns out that DOMConfigurator.parseAppender ignores requiresLayout and sets the layout any time there's a layout tag in the log4j.xml configuration file.

// Set appender layout
else if (currentElement.getTagName().equals(LAYOUT_TAG)) {
    appender.setLayout(parseLayout(currentElement));
}

Having a fundamental opposition to switching to XML, I needed another way to get the Syslog4jAppender to respect my layout desires. To my chagrin, the best approach I could come up with was to subclass the Syslog4jAppender and override the requiresLayout method:

public class Syslog4jLayoutAppender extends Syslog4jAppender {
   @Override
   public boolean requiresLayout() {
      return true;
   }
}

I switched my configuration to use this appender, redeployed, and my stack traces started to appear in loggly. Unfortunately, they were all on one line with character codes in place of linefeeds. Preferring easy to read stack traces, I flipped the rolling file appender back on and considered this the best alternative. In short, here's how I get stack traces into loggly:

1. Configure a RollingFileAppender
2. Configure rsyslog to use the imfile module to monitor the file with paragraph read mode
3. Profit