tomcat-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From David Johle <djo...@industrialinfo.com>
Subject Issues Logging wtith log4j at common and webapp levels
Date Tue, 02 Oct 2012 19:29:50 GMT
I am having some issues getting the right "planetary alignment" of 
file locations & configuration settings to get logging to work how 
I'd ideally like it.  I think I'm having some undesireable 
interactions with static members and classloaders and such.  This 
post is a bit of a novel, sorry about that, but I like to give all 
the details instead of having everyone incorrectly assume what is 
going on or worse yet being one of those annoying "plz hlp me, 
kthxbai" types that expects some kind of miracle.

First off, here is some relevant system configuration information:

RHEL5
Java 1.6
Tomcat 7.0.30

I have configured Tomcat to have 4 Host entries, so 4 webapp/contexts 
total.  It's a clustered setup as well, but for this task that is not 
relevant, only that there are multiple contexts.

And now some back story to make things more clear:

I have a code library in a JAR and a pile (read: 5 digit quantity) of 
JSP files which represent a 10+ year evolution of code touched by 
many different developers.  The JSPs are full of scriptlets with Java 
code (I know that's less than ideal, hence the cleanup efforts) and 
both the JSP & Java code in the JAR are littered with 
System.out.println() & Exception.printStackTrace() calls for various 
logging and/or debugging purposes.  I have been working to modernize 
this to use a proper logging framework, and have standardized on 
log4j as it is what has been used in several other applications I 
have developed -- some of which are now utility libraries shared with 
and used by the web applications.

Previously (Tomcat 5.0.x) we had all internal logging going to the 
catalina.out, and each webapp's logging going to a file local to the 
filesystem heirarchy used by said webapp.  The webapps themselves use 
the same backend codebase and it must always be in sync, so to avoid 
complications we always deployed the JAR to the common lib 
directory.  Despite being in the common area, the System.out output 
was still being captured by the swallowOutput=true setting, and thus 
the "shared" logging statements were still going to the respective 
webapp logfile that made calls to those libraries.

When first upgrading Tomcat to 7.x we ran into some issues with 
getting the logs to the right places because of the new JULI stuff 
xand whatnot, and eventually got it to work by configuring log4j at 
the webapp level, and still using the swallowOutput=true to capture 
the System stuff.  This was working great, and all System.out content 
was sent to the log4j appender local to the webapp.  This was still 
an ugly way of doing logging though, so time to get rid of the bad practices.

So now to make use of the logging framework:

I first decided to tackle the JAR, went the shared code library and 
re-wrote every call (a lot!) to System.out.println() and 
Exception.printStackTrace() to use a proper log4j method indicating a 
logging level and passing exceptions when appropriate.  However, when 
I deployed the new JAR file my results were not exactly as expected/desired.

Some of the early logging was ending up in the catalina.out, along 
with some log4j configuration warnings.  I converted the relevant 
class to use JULI instead as it was an extention of the DeltaManager 
from Tomcat, and thus created prior to the context itself, and used 
only by Tomcat.  The only problem here is that it referenced some 
utility classes that were shared, and thus those still produced the 
log4j startup errors.  So then I converted tomcat to use log4j for 
internal logging as well, which cleared up those errors, and made for 
a clean console.

I set up a quick testing JSP which made System.out calls, log4j 
calls, and a call to a shared Java class which did a log4j call.  I 
put this testing page on two different webapps and could hit each one 
and determine if the logging destinations were correct.

I went on to test more logging and found that calls to log4j within 
the utility libraries (called from JSPs) were either not showing up 
anywhere at all, or all going to the webapp logs of the first loaded 
webapp, regardless of which one actually sourced them.  This, I 
realized, was due to only having the log4j/etc. JAR files at the 
common classloader level.

So I then ended up with a copy of log4j (and the JULI adapter stuff 
needed) in the common lib, as well as in each WEB-INF/lib.  The 
System.out calls (the ones remaining, not yet converted) in the JSP 
files are still being routed to their respective local/per-webapp 
logs, so that's good.  Calls to log4j directly from the JSP files 
also lead to the local log files, and I was able to get the URI as 
part of the logformat, so that's good.  Calls to log4j from the 
shared Java classes, no so much.

FWIW, I am using typical static logger declarations such as this in 
my Java classes:
     private static final Logger log = Logger.getLogger(LogTest.class);

So that brings us to the current issue:

No matter which webapp makes a call to the shared library, the log4j 
calls within are routed into the main tomcat log (same one Tomcat's 
internal logging goes to now).  This is bad for 3 reasons -- 1) I 
can't distinguish which webapp triggered it, 2) the messages are not 
inline with any logging from the calling JSP, 3) the internal logging 
is node specific whereas the webapp logs are shared among the cluster nodes.

After doing much research on this, it seems to once again come down 
to which classloader is being used.  So the next thing I tried was to 
put my shared JAR into each WEB-INF/lib as well.  At first this seems 
to solve everything as all output from my testing JSP (System, log4j, 
shared Java doing log4j) ends up in the local log file for each 
webapp, all in proper sequence and everything.  Well, System.out 
seems to be buffered until the request ends, but that's something I 
can live with until it's gone.

Then I try to actually use the webapp, and the first page I hit blows up.


java.lang.ClassCastException:
    my.custom.StandardSessionFacade cannot be cast to 
my.custom.StandardSessionFacade

What? It can't be casted to its own type? Well once again the 
classloader discrepancy causes a problem.  See, the sessions are 
created by the Manager (common classloader) level and I'm trying to 
reference it at the local (webapp classloader) level.  I believe that 
since the local vs. common classes themselves are different 
class-instances (classloader instances that is, not "instance of a 
class" aka an object) it causes some sort of sandboxing violation, 
thus the CCE.

So maybe the solution there is to split out the small number of 
classes loaded at the common level (namely those that extend the 
tomcat Manager/Session/etc.) and then deploy the rest of my shared 
library at a per-webapp level.  The main problem I have with this is 
that those common level classes also use some of the shared library 
code.  And some of those shared items I specifically do not want a 
per-classloader instance of (sort of like JVM-scoped singletons and 
pure utility classes with all static members/methods), but do still 
want their runtime logging to be per-webapp.

There are other benefits to only having this shared library at the 
common level such as to ensure/enforce correct & consistent versions 
of libraries across webapps, reduce deployment times/complexity, and 
to an extent improve performance and/or reduce memory usage.

So in summary, I'm just trying to get shared libraries to have their 
log4j-based logging written to the webapp-specific log files of the 
calling webapp.  Is this possible?  If so, what's the trick?





---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org


Mime
View raw message