RSS feed
<< January 1, 2009 | Home | January 3, 2009 >>

Slf4j on Glassfish: When smart ideas collide

Have you ever noticed how two ideas can seem really smart one by one, but not all that great when combined?

I recently tried to install Nexus, the excellent Maven repository manager from Sonatype. (And by the way: Every organization using Maven needs a repository manager and Nexus is the best one out there!)

A secondary goal of the project I was working on was to get some exerience using Glassfish. But sadly, Nexus failed to deploy on Glassfish:



All I got was this error message in the admin console. A closer look in the Glassfish logs didn't reveal any stacktrace or relevant messages. Since my project was a pretty busy one, I soon gave up and found another way to run Nexus.

A couple of days ago however, I decided to find out what caused the StackOverflowError. I restarted Glassfish with debugging enabled and attached IntelliJ IDEA's debugger to it. After setting an exception breakpoint it was easy to see what was really happening under the hood.



I redeployed and got a stacktrace starting with this:

httpWorkerThread-4848-1@1033 daemon, priority=10, in group 'Grizzly', status: 'RUNNING'
at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:491)
at java.lang.StringBuffer.append(StringBuffer.java:302)
at org.apache.log4j.helpers.ISO8601DateFormat.format(ISO8601DateFormat.java:132)
at java.text.DateFormat.format(DateFormat.java:314)
at org.apache.log4j.helpers.PatternParser$DatePatternConverter.convert(PatternParser.java:444)
at org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:64)
at org.apache.log4j.PatternLayout.format(PatternLayout.java:503)
at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:301)
at org.apache.log4j.WriterAppender.append(WriterAppender.java:159)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230)
at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65)
at org.apache.log4j.Category.callAppenders(Category.java:203)
at org.apache.log4j.Category.forcedLog(Category.java:388)
at org.apache.log4j.Category.log(Category.java:853)
at org.slf4j.impl.Log4jLoggerAdapter.log(Log4jLoggerAdapter.java:597)
at org.slf4j.bridge.SLF4JBridgeHandler.callLocationAwareLogger(SLF4JBridgeHandler.java:169)
at org.slf4j.bridge.SLF4JBridgeHandler.publish(SLF4JBridgeHandler.java:242)
at java.util.logging.Logger.log(Logger.java:452)
at java.util.logging.Logger.doLog(Logger.java:474)
at java.util.logging.Logger.logp(Logger.java:590)
at com.sun.common.util.logging.LoggingOutputStream.flush(LoggingOutputStream.java:90)
at java.io.PrintStream.write(PrintStream.java:414)
at sun.nio.cs.StreamEncoder$CharsetSE.writeBytes(StreamEncoder.java:336)
at sun.nio.cs.StreamEncoder$CharsetSE.implWrite(StreamEncoder.java:395)
at sun.nio.cs.StreamEncoder.write(StreamEncoder.java:136)
at sun.nio.cs.StreamEncoder.write(StreamEncoder.java:146)
at java.io.OutputStreamWriter.write(OutputStreamWriter.java:204)
at java.io.Writer.write(Writer.java:126)
at org.apache.log4j.helpers.QuietWriter.write(QuietWriter.java:47)
at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:301)
at org.apache.log4j.WriterAppender.append(WriterAppender.java:159)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230)
at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65)
at org.apache.log4j.Category.callAppenders(Category.java:203)
at org.apache.log4j.Category.forcedLog(Category.java:388)
at org.apache.log4j.Category.log(Category.java:853)
at org.slf4j.impl.Log4jLoggerAdapter.log(Log4jLoggerAdapter.java:597)
at org.slf4j.bridge.SLF4JBridgeHandler.callLocationAwareLogger(SLF4JBridgeHandler.java:169)
at org.slf4j.bridge.SLF4JBridgeHandler.publish(SLF4JBridgeHandler.java:242)
at java.util.logging.Logger.log(Logger.java:452)
at java.util.logging.Logger.doLog(Logger.java:474)
at java.util.logging.Logger.logp(Logger.java:590)
at com.sun.common.util.logging.LoggingOutputStream.flush(LoggingOutputStream.java:90)

and then about 1000 more lines of the same. There was clearly some kind of loop in the logging system that eventually caused the StackOverflowError. How could this happen?

I knew Nexus was using SLF4J, the Simple Logging Facade for Java. SLF4J was set up to log to Log4J. And Log4J was set up with a ConsoleAppender. From the stracktrace I could tell that Log4J wasn't printing its output to the console, but to a LoggingOutputStream. Some googling revealed that LoggingOutputStream is set up by Glassfish to catch any output to System.out and redirect it to the Java Logging API (JUL).

So Log4J was obviously feeding its log lines into what it thought was the console while it was actually fed into the Java Logging API instead. But why did this cause a loop?

The answer is found a few lines up the stacktrace in a class called SLF4JBridgeHandler. This class installs a bridge that will redirect all logs from the Java Logging API back to SLF4J. Which is pretty smart thing to do if you have code logging to JUL, but you want all code to log to be handled throgh SLF4J instead. Combined with Glassfish's LoggingOutputStream however, it caused an infinite loop:

  • The Nexus application code logs to SLF4J
  • SLF4J logs to Log4J
  • Log4J writes its log lines to System.out through the configured ConsoleAppender
  • The log lines are processed by Glassfish's LoggingOutputStream and sent to Java Logging
  • Java Logging sends its logs to SLF4J because of the SLF4JBridgeHandler.
  • SLF4J logs to.. Wait.. Houston, we have a problem!

So the next time you come up an idea you think is really smart, take a minute or two to consider the possibility that right now, somewhere else in the world, someone else might be thinking about an equally smart idea that when combined with yours will make the world explode.

This issue is reported in the Nexus issue tracker as NEXUS-1307.