4

I'm using logback for logging of a Java web service app, using embedded Jetty. The logging works as expected based on the logback.xml file... all except for some logs originating in Java, but showing up in the jsvc output to stderr.

I would like specifically to see all my Java-generated logs with millisecond timestamps to match my other logs, and ones showing up in the jsvc stderr output are only down to the second.

The jsvc stdout logs are mostly generated from Jersey and I see my own code referenced as objects are registered with Guice, which gives me hope that it can be controlled through logback. I don't understand what causes those logs to show up in jsvc's stderr output rather than in the logback catchall. Has anyone solved a similar problem in their code or configuration when using jsvc?

phatfingers
  • 9,770
  • 3
  • 30
  • 44

3 Answers3

2

The solution required changes in a few places, and was largely an slf4j configuration issue. My app has numerous dependencies, and they introduce a variety of logging implementations. Slf4j was designed to corral them all together, and the process is often just an easy drop-in of a jar, but java.util.logging takes a bit more effort.

The slf4j Bridging Legacy APIs page describes (mostly) how to wire up the JUL dependency introduced by Jersey. I had already included the jul-to-slf4j.jar, but it wasn't wired up correctly. I needed to execute SLF4JBridgeHandler.install() in the initialization of my app. In addition, the page cautions about negative performance implications unless I also include the following in my logback.xml file:

<contextListener class="ch.qos.logback.classic.jul.LevelChangePropagator">
    <resetJUL>true</resetJUL>
</contextListener>

That got me most of the way there, but introduced duplication of log events-- one went to slf4j and the other continued to stderr. Google directed me to an article in Claus Neilsen's Blog, "Bridging java.util.logging to SLF4J". This contained a helpful snippet of code:

// Jersey uses java.util.logging - bridge to slf4
java.util.logging.Logger rootLogger = LogManager.getLogManager().getLogger("");
Handler[] handlers = rootLogger.getHandlers();
for (int i = 0; i < handlers.length; i++) {
    rootLogger.removeHandler(handlers[i]);
}
SLF4JBridgeHandler.install();

With that in place, the Jersey logs that were showing up in my jsvc stderr output are now showing up with the rest of my logs, nicely formatted, as directed by logback.xml.

phatfingers
  • 9,770
  • 3
  • 30
  • 44
1

As I understand it, jsvc is a daemon written in C that manages Java applications. It's not really running in Java itself and it's limited in its logging to stdout and stderr. You could redirect the jsvc output to named pipes and have some process read them and give you the millisecond timestamps. Up to you how much effort you want to put into a solution.

Old Pro
  • 24,624
  • 7
  • 58
  • 106
  • You understand correctly what jsvc is. The error messages in question are generated by Jersey from my own app and sent to stderr. I think jsvc is catching stderr and directing the output to a file. I'm looking for a solution that will intercept the stderr log output before it reaches jsvc. – phatfingers Apr 17 '12 at 15:18
  • I've updated the question to more clearly reflect that my concern is with log data that is produced from within Java, but is showing up in the jsvc stderr output. – phatfingers Apr 17 '12 at 17:33
  • 1
    @phatfingers, Where are you putting logback.xml? If you have it in your webapp's WEB-INF/classes folder then obviously Jersey won't use it for its own logging. You need to set up your default logging by putting logging.xml [in the global classpath](http://logback.qos.ch/faq.html#configFileLocation). – Old Pro Apr 17 '12 at 23:57
  • @Old_Pro, I'm using embedded Jetty rather than a servlet container. All my developed classes are in one jar file, my external libs are in a subfolder, and the jar file's MANIFEST.MF references them in a Class-Path variable. My main class is pulp.HttpServerMain, and the logback.xml is in that same "pulp" package in the jar file right next to the HttpServerMain.class file. – phatfingers Apr 18 '12 at 01:25
  • @Old_Pro, I modified the string passed in the -cp parameter to jsvc using a fully-qualified path to an external world-readable logback.xml file, but still no joy. I think you're onto something, though-- the webapp context is respecting the logback.xml file, but what is effectively the container's logging is seeing only the stdout. I'll tinker with it some more and share whatever I find. – phatfingers Apr 18 '12 at 02:24
  • @phatfingers, I'm not familiar with Guice and how it wires things together. I'd start with moving the logback.xml to the top level of the jar. If that doesn't work, put it in the same folder as the external libs and add the **folder** to the Class-Path in the Manifest file. – Old Pro Apr 18 '12 at 02:29
  • The messages show up in red in my Eclipse console when run locally. I'm hoping that's enough to rule out packaging issues. Here's a sample of what I'm seeing: `Apr 17, 2012 11:05:12 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory getComponentProvider INFO: Binding pulp.resource.ContentResource to GuiceManagedComponentProvider with the scope "Singleton"` – phatfingers Apr 18 '12 at 06:38
  • @phatfingers Eclipse console shows stderr in red, doesn't rule out packaging issues. Try running jsvc using a fully-qualified path to **the folder containing** the external world-readable logback.xml file rather than the file itself. – Old Pro Apr 18 '12 at 08:58
  • Sorry, @Pro, should have acknowledged that earlier. The app is seeing logback.xml just fine. It's not the issue. – phatfingers Apr 18 '12 at 14:27
  • @phatfingers, well, you didn't say you were using slf4j. Glad you got it figured out. – Old Pro Apr 18 '12 at 19:56
0

According to client or container Filter javadoc, Jersey uses JDK Logging API to generates its log lines to System.out by default.

So you have to refer to the Java Logging guide to set up the LogManager so that its filters by class or level, or even diverts (or copy) log lines from System.out to your own file.

Your own code using slf4j, you have to configure logback to replace the ConsoleAppender by a FileAppender.

Yves Martin
  • 10,217
  • 2
  • 38
  • 77
  • I'm binding log output to logback using slf4j. The data in question is showing up in stderr. – phatfingers Apr 18 '12 at 06:32
  • 1
    As you say you want to manage all logs lines out of your Java process, you have Jersey output to divert and also you own code with slf4j/logback... So there is two tasks to do. – Yves Martin Apr 18 '12 at 06:49
  • Please provide your logback XML configuration, probably the issue is there. – Yves Martin Apr 18 '12 at 06:52