The per-application logging in JBoss 6 is broken beyond any possibility of repair. Even more, activating per-application logging makes the situation much worse.
Why the hell?! Need to scratch some itch? Look at the bug database, there is so much to do. "No, it is not for us, let's invent something new." And release this piece of ... software, half baked, and forget about any documentation.
So many words unspoken! Or rather unwritten; spoken they were, and a lot.
Back to the topic: why does it not work? To understand it you need first to understand how it really works.
The per-application logging configuration is bound to a classloader that loads jboss-logging.xml file with <define-context> element. When some component (your application code, some jar that come with JBoss, does not matter) invokes getLogger() the execution ends up in JBoss LogManager class. If the requested logger does not exist it has to be created. If the per-application logging is activated some helper class (ClassLoaderLogContextSelector) traverses the invocation stack starting from the most recent entry. For each entry (class) in the invocation stack the check is done whether the entry's classloader has a bound logging configuration. If such a configuration exists it is used and the traversal is stopped. If no classloader-bound logging configuration is found after the traversal the default one (coming from (deploy/jboss-logging.xml) is used.
For example, if your application with a custom jboss-logging.xml calls getLogger() then your class is very close to the top of the invocation stack:
Some JBoss logging codeThe traversal algorithm starts with Some JBoss logging codeand goes down until it finds <your class>.getLogger(). The application has a per-application logging which is bound to the application's classloader, the very same classloader that has loaded <your class>. Bingo, the logger the application code gets back from JBoss will use the application's custom configuration.
Some more JBoss logging code
<your class>.getLogger()
Some other code from the application
Some JBoss EJB/servlet/you name it invocation code, a lot of it actually
Thread.run()
It works even when getLogger() is used by code in some jar packaged with JBoss when your application uses that code. The invocation stack is longer, the traversal takes more time, but this is the only difference:
Some JBoss logging codeSo what is wrong with this?
Some more JBoss logging code
<library class>.getLogger()
Some other library code, can be a lot
Some code from the application calling the library
Some other code from the application
Some JBoss EJB/servlet/you name it invocation code, a lot of it actually
Thread.run()
A lot actually:
- What a performance hog this is! Worst of all the code that does not use the per-application logging suffers the most because all the entries in the invocation stack must be checked before JBoss decides to use the default logging configuration. And stack traces under JBoss are known to be looooong. Like hundreds of entries long. To be fair JBoss warns about this problem in deployers/jboss-logging.deployer/META-INF/logmanager-jboss-beans.xml:
<!--
Of course being JBoss code it does not actually works this way. Bug JBAS-9407 strikes back: the proposed workaround activates this stack traversal algorithm even if no component is using the per-application logging. My patch attached to this bug fixes this and makes sure the stack scanning is activated only if a component with the per-application logging configuration is deployed. But being activated the traversal code is always executed when a logger is created, regardless what component/module asks for a logger.
~ These two beans define the per-classloader log context selector which allows per-deployment logging. Since
~ enabling this feature may have a performance impact in certain cases, it's started up lazily (on demand)
~ when a separate log context is defined in a user deployment.
--> - One might say this is not a big problem. After all the traversal is performed only if a new logger is created and not every time it is used to output something. And because loggers are cached it does not matter how many times getLogger() is invoked, creation and hence the traversal happens only once.
But exactly this fact (traversal at creation) is one of the reasons why the per-application logging is broken. Let's look at the example above, the one with the application using some library. Here is the stack trace again:Some JBoss logging code
Your application calls the library, for example, JPA. JPA provider classes, Hibernate under JBoss, call getLogger(). JBoss finds the application classes in the invocation stack, so the application logging configuration is used also for Hibernate classes. Logging output from Hibernate goes to your logging file. Sun is shining, life is good. You go ahead and deploy a second application that uses JPA and per-application logging. The log file for the second application is created. Logging from the application classes goes there. But not the logging from Hibernate: it goes to the log file of the first application. Surprise!
Some more JBoss logging code
<library class>.getLogger()
Some other library code, can be a lot
Some code from the application calling the library
Some other code from the application
Some JBoss EJB/servlet/you name it invocation code, a lot of it actually
Thread.run()
The reason is clear: when the Hibernate logger was created the classes from the first application were on the stack, so the logger became "bound" to the configuration loaded from the first application.
In reality it gets much more interesting: some Hibernate logging output goes to the default JBoss log (Hibernate code is executed during the application deployment/startup), other might go to this application's log, yet another might go to some other application's log. It all depends on the invocation stack at the moment of creation of the logger. Кто первый встал, того и тапки, which roughly translates to "The first man gets the oyster, the second man gets the shell".
And what happens if the first application is undeployed? Where Hibernate log goes then? I did not bother to check this: nothing good anyway. - As it were enough. You see, when I am talking about application-specific logging I really want the logging from the shared classes still go to the application log when the shared classes execute on behalf of the application. Even if there is yet no class from the application on the stack. For example, JBoss code that runs before invoking a servlet or an EJB business method from the application. Or a web service: there is a lot going on before the application code is invoked: XML parsing, unmarshaling, you name it. Where the logging, including error stack traces, goes? Most likely to the default logging: there is after all no classes from the application on the stack yet. Or to some other log file: the first man gets the oyster, remember?
- It can get even stranger. What I have seen in my tests is that the app-specific logging is activated pretty late in the deployed process. If any of the application code calls getLogger() before the logging configuration is hooked up the logging from the application classes goes to the wrong place: to the default logging. Most often there is a static Logger field in a class. This results in getLogger() being invoked during the loading of the class. For example, JPA provider loads classes looking for annotations. Or CXF code looks for JAX-WS annotations. All this loading is happening before the logging configuration is bound to the application classloader.
This problem can be somewhat compensated by not using a static Logger field, but it is applicable only to the code you control and not to 3rd party code. There can also be situations where static initializer does something worth logging.
Nicely implemented feature, isn't it?
You might be tempted to package more 3rd party jars in your application and play some classloading tricks to make sure that the classes are loaded from the application-packaged jars and not from JBoss-provided jars. Don't!
- This won't buy you anything except maybe the server upgrade. The memory consumption will skyrocket, especially if there are multiple applications doing this.
- This might help you with problems 2 and 3 above. Problems 1 and 4 remain.
- You need to understand Java classloading pretty good. Then you have to forget it and learn the mess that JBoss made of it. And even then most likely it will not work. JBoss will not even deploy your application no matter how hard you try.
For example just packaging Hibernate jars in a simplest EJB application that has otherwise no Hibernate or any other persistency dependencies is enough. If the application has JBoss classloading config that instruct JBoss to look for classes first in jars packaged with the application and only then in the parent (JBoss) clasloader the application will not deploy. While I have quite good understanding of JBoss classloading I would not even try to make this application deployable because I also understand the reason why it fails.
Feel lucky? Give it a try. At best you can make this scheme work with some 3rd party jars but not with the most important and interesting, like Hibernate or CXF.
The question remains: is it actually possible to have the application-specific logging in JBoss 6?
Of course! Scrum solved that problem long time ago: a team decides what they want to have done and as they progress they can redefine what "done" means. Pretty neat and useful. You can do the same here: you can define what "application-specific" means in your case and then implement it.
Jokes aside there is not much you can actually do. The simplest and most sane solution is to forget about all that JBoss woodoo with the application-specific logging. Rollback the workaround for bug JBAS-9407. Use the default logging configuration in deploy/jboss-logging.xml. You can direct the output from your classes to a separate file. All the logging from the shared classes still goes to server.log by default. Directing the output from the shared classes to your application's log file is a bad thing to do: imagine if every application tries to do this. Including thread names in the logging output helps matching the records from the default JBoss log (server.log) back to your application if necessary.
JBoss, you never stops to amuse me!
