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:
- Configure a RollingFileAppender
- Configure rsyslog to use the imfile module to monitor the file with paragraph read mode
- Profit
