13 May 2010

Glassfish Logging with slf4j

Update 18 Dec 2010: There is an extended version of this article.

It can be annoying to have each third-party library or framework in your application logging to a different logfile. slf4j with its various adapters enables you to collect logging events from various APIs (org.slf4j.api, java.util.logging, org.apache.commons.logging) and redirect them to a logging backend of your choice.

I've always preferred log4j or, more recently, logback over java.util.logging, so after working with Glassfish v3 for a while, I tried to tweak it to use logback over slf4j and the jul-to-slf4j bridge.

To redirect java.util.logging used by Glassfish v3, you put the following libs on your classpath:
  • jul-to-slf4j.jar
  • slf4j-api.jar
  • logback-classic.jar
  • logback-core.jar
(You can replace the logback libs by any other supported backend like log4j, see the slf4j docs for more details.)
The problem with Glassfish is:
  • You need to take care of its class loader hierarchy and make sure that the logging jars get picked up early enough.
  • Glassfish does some all-too-clever logger manipulation in its LogManagerService which will get in your way if you don't like the Glassfish defaults: It redirects all System.out messages to a logger.
I did not manage to fully supersede Glassfish logging by slf4j and logback, but at least I can copy all Glassfish log events to my logback application log like this:
  • Put the logging libs in [install-root]/lib/endorsed.
  • Build a JAR containing your logback.xml configuration and put it in the same place.
  • Edit an entry in [instance-root]/config/logging.properties, setting
    handlers = org.slf4j.bridge.SLF4JBridgeHandler
Now if you omit a ConsoleAppender from your logging configuration, the Glassfish server.log will no longer contain any log output from your application. It will still contain the log messages from Glassfish itself, but they will also be included in your own logback logfile.

8 comments:

lightguardjp said...

I'm trying this, seems to have worked decently, though not sure if it's my app or these configuration changes that have made glassfish take much longer to start up.

Harald Wellmann said...

There is a warning in the jul-to-slf4j bridge documentation about a performance penalty: if I get it correctly, log events may be generated even if the associated logger is not active.

So this may be the reason for the slowdown you observed.

At any rate, at least during development, I prefer to have uniform logging with slf4j. If the performance is too bad, I can still switch back to JUL for production.

Of course, it would be really cool if Glassfish would directly support slf4j. I'm going to file an enhancement request for that.

lightguardjp said...

Let me know what the issue number is and I'll vote for it.

SzoboszlaiI said...

Hello!

Doing the steps described in this tutorial when creating a Logger i get the following error:

SEVERE: SLF4J: Class path contains multiple SLF4J bindings.
SEVERE: SLF4J: Found binding in [jar:file:/Develop/glassfishv3/glassfish/lib/endorsed/logback-classic-0.9.24.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SEVERE: SLF4J: Found binding in [jar:file:/Develop/glassfishv3/glassfish/modules/bean-validator.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SEVERE: SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.


How did you solve this problem?
Thanks in advance if you take the time to answer!

Best - Istvan

Harald Wellmann said...

Hi Istvan,

I'm afraid you can't avoid that, you always get this message when there's more than one SLF4J binding on the classpath.

It's rather unfortunate that Glassfish includes its own binding and does not leave the choice to you.

Regards,
Harald

SzoboszlaiI said...

Hello, I have made another mistake, too. I misspelled the handler setting in the logging.properties file. When that is correct, the log starts to behave differently (everything will be logged twice), but I can't figure out, what settings are used. In my logback.xml I have only one fileappender, but the file never gets created.

So actually I am starting to give up trying and just use glassfish's standard slf4j and let it log to server.log.

Perhaps later I will come back to the issue to find out how it can process my logback.xml.

Thanks for the kind answer.

Best - Istvan

Hermann Schmidt said...

Thanks a lot! A decent log for Glassfish at last. What a relief.

I'd like to add that it is possible to point Glassfish to a Logback config file with -Dlogback.configurationFile. The property value is the path relative to the domain's config directory. Works nicely for me.

I think configuration files should not be buried in JARs or EARs in production environments.

Harald Wellmann said...

@Hermann: You're right, using a config file located in the file system is the preferred way of configuring logback.

I noticed this option a while ago in the logback manual, and I'm quite positive it was not available (or at least documented) in earlier releases.

I'll update the follow-up post accordingly.

Best,
Harald