(java.util.logging/SLF4J/Log4J) + Glassfish v3 + Per-Application Logging

java.util.logging + Glassfish v3 + Per-Application Logging

After reading a lot of stuff on the web ... java.util.logging in Glassfish (up to at least v3.1)...per application logging (ie: server.log captures all logs, then individual app1.log, app2.log etc logs capture logging just from app1, app2 etc.) is not possible (using just the /config/logging.properties) to configure. See the following (in a roughly chronological order over the last few years):

• http://www.java.net/node/666057
• http://www.java.net/node/684267
• http://old.nabble.com/Configuring-java.util.logging-per-Web-Application-in-Glassfish-td19689665.html
• http://stackoverflow.com/questions/3394416/glassfish-logging-to-multiple-log-files
• http://forums.java.net/node/803338

As those all suggest there is a single loaded java.util.logging in the Java Classloader (as its part of java) and hence there is a single logging.properties for configuration. This means you can only define a single java.util.logging.FileHandler in logging.properties and hence output can only be sent to a single location rather than one per app. Whats more....as a cool thing, since there is only a global logging solution, theres no reason why my app cant get the root logger, set its log.level programatically to FINEST and Bobs your uncle I have every possible log, logging in Production (possibly spilling out usernames and passwords or any other info developers may want to see in DEV but lock down in Production...DB connection details anyone?). So not so good on the security (tho this does require you to have access to deploy to the domain so where not exactly hacking anything here...more just subverting). Funny thing is this is known, and has been for years if you read the links above...but personally I dont see how they can get around this security risk...which is why it probably is still an ongoing issues after 4 or 5 years.

What ways are there around this? A number but none are really pretty. First of all you can add the following code to each and every application in a block in some class that you know will be loaded by the classlaoder initially:

    private static final Logger loggerRoot = Logger.getLogger("org.some.app");
    private static final Logger logger = Logger.getLogger(AppMainClass.class.getName());
    {
        logger.warning("This will only go to server.log");

        Handler h = null;
        try {
            h = new FileHandler("app-1.log");
            h.setFormatter(new SimpleFormatter());
            loggerRoot.addHandler(h);
        }catch(IOException ioe){
            ioe.printStackTrace();
        }
        logger.severe("This will now get logged to both server.log and to app-1.log.");
    }
   
This works but .... theres always a but and in this case theres 2 .... but 1) you have to add this initialiser block within some quickly loaded class because until the classloader loads this class and hence initialises this block you wont have you app-1.log defined. So its kinda YUCK to have to add this programmatically to every class. But 2) Sometimes if you redeploy without stopping and starting the domain completely app-1.lck lock files hang around and before you know it you have a app-1.1.log app-1.2.log, app-1.3.log with a new log file after every deploy and ... get this .... the logging going not just to the latest log file ... but too ALL the log files. Thats gotta be great for performance once we get to a stage of logging the same log statement to 20 different log files. Maybe theres some way around this....I tried setting various parameters like append=true (append to existing file) and count=1 (max count of xxx.#.log files...ie: create only a single log file) but of course neither of these setting helped and my log files continued to grow, require domain bounces and manual cleanups. Its about at this stage, when I saw this, that I chucked in the towel in disgust with this method.

So, secondly you could extend java.util.logging.FileHandler with say MyApp1FileHandler, MyApp2FileHandler, and then define each of these in the logging.properties per app. But you need a new file handler per application whose logs you want to seperate, and further more you also have to package and deploy these MyXXXFileHandlers into glassfish in a MyXXXHandler.jsr, so that they can be picked up by the Glassfish Classloader....which makes this probably more complicated and annoying than just the initialiser block above.  However as an example this shows how to create a CustomHandler should this nightmare tickle your fancy:

http://www.java.net/external?url=http://blogs.oracle.com/naman/entry/configure_my_custom_log_handler

So what next ... cant be that hard to get per-application log files can it ? Surely not? Thats what I thought but turns out ... well at least with java.util.logging and Glassfish (and most likely other servers that dont use custom extensions) ... it is. 

So what else can we do ?

SLF4J + Glassfish v3 + Per-Application Logging

SLF4J Rocks! Everything I read about it rocks! The ideas and concepts (ie: parameterised log statements, greater speed + everything from Log4J that was good...thanks Ceki Gülcü) rock! Its the successor to Log4J which also rocked...so SLF4J is even more 'rock-in'! So lets use that for per-application logging in Glassfish. Right? Not so fast...that'd be frankly too damn easy. What you think you can use the greatest logging framework out there and just get per-application logging working. No...of course you cant. Nothings that easy. But why? Well again its all to do with classloaders (in particular Glassfish's), although in a slightly different way to the java.util.logging issues mentioned earlier.

Turns out that Glassfish uses WELD internally (WELD being the implementation of: JSR-299: Java Contexts and Dependency Injection for the Java EE platform (CDI)). So what you say .... well turns out that the WELD implementation in Glassfish (at least up to v3.1 when I last checked) includes SLF4J internally. This means that when you deploy your app with its SLF4J libs and config ... errr .... well Glassfish ignores them cos the beauty of classloaders is we go up the tree via the parents as far as we can to get our implementation (which in this case means that we end up using the WELD SLF4J version) and hence we ignore our own per-application logging SLF4J properties file. Beautiful ... screwed again!!!

Again ... known issue and in fact has/had the 2nd largest amount of votes for a fix in Glassfish JIRA bug tracker. But that doesnt help people stuck on a non-bleeding edge version of Glassfish for the foreseeable future...even if there was a fix implemented....which at present (July 2011) there is not.

Yay!!! Or....in the immortal words of John McClane/Bruce Willis(Die Hard) .... YippeeKaaayey Motherf*cker.

I mean seriously ... Im not asking for the world here....per-application seperated out log files....surely given this was possible back in the 70's using a couple of shell scripts I should be able to achieve it today ? Considering were so technologically advanced and all after all. (Oh and in case it doesnt come across through text so well....insert a heavy dose of SARCASM right here).

So what next?

Log4J + Glassfish v3 + Per-Application Logging (+ Me Screaming If This Fails Like java.util.logging & SLF4J Above...)

So what fun things did I discover with Log4J. Well for starters the classloader hierarchy and associated configuration of Log4J properties works in reverse to something like JUL. The lowest classloader in the hierarchy overrides the config from any higher classloaders. So if you setup a properties file in /config/log4j.properties using the system property added (-Dlog4j.configuration=file:///${com.sun.aas.instanceRoot}/config/log4j.properties) as described in this guys blog: 


      http://weblogs.java.net/blog/2007/08/28/hell-jdk-logging-ii


and the log4j.properties looks like:


      log4j.logger.xxx.yyy.zzz=DEBUG,stdout,GF_XXX_FILE


.....and then later in your app you do :


      log4j.logger.xxx.yyy.zzz=DEBUG,stdout


...you will only get the stdout appender added to this logger not both of stdout,GF_XXX_FILE that server property file had defined.


Whats more things arent cumulative as I found out so defining the GF_XXX_FILE appended in the glassfish server log4j.properties and then attempting to use it from the application log4j.properties wont work (which is to be expected i guess). I initially wanted to have a server level properties file that I could use to define appenders to at least seperate files and perhaps to standard out as well and then assign those appenders to loggers. This would've been great as you go to the single log4j.properties file and modify that for each app in the domain. However, as always this wasnt so simple for me. Since I already had some apps that defined their own props files within the app deploy these would over-ride the domain level prop file and Id end up with config in two places (server level for some apps and app level for the rest).


So i decided to finally only use application-level log4j.properties and package them up with the deployed modules per application with the config for seperate file logging within each prop file. 

And.....this works for us!!! A little anti-climactic after that entire spiel but hey....


And so now, 3 days later, Ive spent probably an order of magnitude longer on this than I should've .... frustrating .... but on the other hand I know everything about every known logging framework and their quirks. Hmmmm....I wonder how I can use that on a CV ??? :-)

Notes:

• http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/helpers/Loader.html#getResource%28java.lang.String%29
• http://logging.apache.org/log4j/1.2/manual.html