Tomcat 6.0.35 hangs during startup

[Davie Lin]

Hi everyone,

I am trying to upgrade from Tomcat 5.5.34 to 6.0.35 in AIX environment. I am a java developer not a Unix Admin, however, I will find out as much info as I can.

Here is what my catalina.out is showing

Mar 13, 2012 2:33:30 PM org.apache.catalina.core.AprLifecycleListener init
INFO: The APR based Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: /usr/java6_64/jre/lib/ppc64/default:/usr/java6_64/jre/lib/ppc64:/usr/java6_64/jre/lib/ppc64:/usr/java6_64/jre/lib/ppc64/default:/usr/java6_64/jre/lib/ppc64/j9vm:/usr/java6_64/jre/lib/ppc64:/usr/java6_64/jre/../lib/ppc64:/usr/lib:/usr/lib
Mar 13, 2012 2:33:31 PM org.apache.coyote.http11.Http11Protocol init
INFO: Initializing Coyote HTTP/1.1 on http-8080
Mar 13, 2012 2:33:31 PM org.apache.catalina.startup.Catalina load
INFO: Initialization processed in 1175 ms
Mar 13, 2012 2:33:31 PM org.apache.catalina.core.StandardService start
INFO: Starting service Catalina
Mar 13, 2012 2:33:31 PM org.apache.catalina.core.StandardEngine start
INFO: Starting Servlet Engine: Apache Tomcat/6.0.35
Mar 13, 2012 2:33:31 PM org.apache.catalina.startup.HostConfig deployDescriptor
INFO: Deploying configuration descriptor host-manager.xml
Mar 13, 2012 2:33:31 PM org.apache.catalina.startup.HostConfig deployDescriptor
INFO: Deploying configuration descriptor manager.xml
Mar 13, 2012 2:33:31 PM org.apache.catalina.startup.HostConfig deployWAR
INFO: Deploying web application archive Lids.war
Mar 13, 2012 2:33:32 PM org.apache.catalina.loader.WebappClassLoader validateJarFile
INFO: validateJarFile(/opt/tomcat/webapps/Lids/WEB-INF/lib/servlet-api.jar) - jar not loaded. See Servlet Spec 2.3, section 9.7.2. Offending class: javax/servlet/Servlet.class
Mar 13, 2012 2:33:32 PM org.apache.catalina.core.StandardContext addApplicationListener
INFO: The listener "com.sun.faces.config.ConfigureListener" is already configured for this context. The duplicate definition has been ignored.
log4j:WARN No appenders could be found for logger (com.sun.faces.config.ConfigureListener).
log4j:WARN Please initialize the log4j system properly.

I have try this twice already but everytime catalina.out stop logging when it get to log4j:WARN I was not the person downloaded tomcat, but I certainly can ask the admin that I work with. I have not made any change to server.xml or context.xml. I have made changes to tomcat-user.xml by just adding a role. I don't believe that cause problems.
Has anyone encounter similar situation before?

Thanks for any input or thoughts in advance.

[Tim Holloway]

I see 2 things wrong.

One - and very importantly - the servlet.jar has apparently been included in the deployed WAR. Don't do that. The copy of servlet.jar (the servlet-implementation jar) that you need is part of Tomcat itself.

Two. It's annoyed about the log4j configuration. You should have a log4.xml or log4j.properties file in the WAR's WEB-INF/classes directory. You also need to have at least one appender in it that's set up to be able to handle log requests marked as coming from com.sun.faces.config.ConfigureListener. The fact that you don't means that you probably do have a log4 configuration file, but it doesn't properly set up a default appender.

Just for info, if by any chance you have both a log4j.properties file and a log4j.xml, the xml file takes precedence.

[Davie Lin]

Hi Tim,

Thanks for your insight, very much appreciated. Before I posted this question yesterday afternoon I had some thoughts about Log4j. keep in mind that I was not the original developer for the web app that I deploy to Tomcat 6. This web app does not have Log4j.xml nor Log4j.properties, I think the Log4j message came from commons-logging.jar. I remove commons-logging.jar out of the project's build path and I believe I saw no error. For the time that I inherited this web app I do not recall there was any sort of logging with Log4j. Do you see any problem if I remove commons-loggins.jar?

Thanks for your reply.

[Davie Lin]

I just try removing commons-logging.jar out of my WEB-INF/lib directory and I get

SEVERE: Error configuring application listener of class com.sun.faces.config.ConfigureListener
java.lang.NoClassDefFoundError: org/apache/commons/logging/LogFactory

Looks like commons-logging.jar stays

[Tim Holloway]

One problem that you seen in complex webapps is that there can easily be 3 or more different logging systems at work in them. The webapp might use log4j, the Hibernate jars might employ apache-commons-logging, another component might be using JULI. So we ended up with choice of additional logging subsystems whose purpose is to co-ordinate all those loggers!

Leave the commons-logging jar in, but add some sort of minimal log4j config file. That should be sufficient. Apparently the original project was simply missing it and no one cared, since it's a non-fatal error that's only really a problem if you wanted to actually log something!

[Davie Lin]

Well, I don't know if anyone still reads this thread or not but I notice there is only one of my war not working and started to compare with other web app that works and the web app that doesn't deploy has Richfaces3.1.5 and if I took out those jar files and modify the DD, surprise, surprise, my app is started, of course, the pages that use Richfaces doesn't display anyting and get exception in the log. So what does this mean, I need to upgrade Richfaces?

[Tim Holloway]

Davie Lin wrote:Well, I don't know if anyone still reads this thread or not but I notice there is only one of my war not working and started to compare with other web app that works and the web app that doesn't deploy has Richfaces3.1.5 and if I took out those jar files and modify the DD, surprise, surprise, my app is started, of course, the pages that use Richfaces doesn't display anyting and get exception in the log. So what does this mean, I need to upgrade Richfaces?

Probably not. But if you have both RichFaces and Hibernate in the same app, you have 2 conflicting loggers and you need slf4j to integrate them.

[Davie Lin]

Tim Holloway wrote:Probably not. But if you have both RichFaces and Hibernate in the same app, you have 2 conflicting loggers and you need slf4j to integrate them.

WOW Tim, how do you know I have both RichFaces and Hibernate 3. so slf4j huh..., I will have to look into it tomorrow

Thanks again

[Tim Holloway]

Davie Lin wrote:
WOW Tim, how do you know I have both RichFaces and Hibernate 3.

Because I been there and I dun that and I have the scars to prove it!

[Davie Lin]

Tim Holloway wrote:
Because I been there and I dun that and I have the scars to prove it!

Tim, I was just thinking. Based upon what I have Richfaces 3.1.5 and Hibernate 3 and Tomcat 6.0.35 AIX 6.1 Java 6 64 bit and the problems I am experiencing. Let's say if I need to convince a coworker or manager of mine that this hanging problem is indeed due to a Richface and Hibernate logging contention. My question is, what can I do on my side to convince them it is truely like what you mention on the previous post and thus justifiy in implementing slf4j?

Thanks again.

[Tim Holloway]

I actually don't think that "logging conflicts" are the direct cause of the hangup. However, you're not far off from asking "what can I do on my side to convince them it is truely like what you mention on the previous post and thus justify in implementing hibernate.jar?". You NEED slf4j because without it, your app is broken. At a bare minimum you're probably missing a critical error message that would tell you what the real problem is because your logging infrastructure isn't set up properly. If you're using Maven, getting slf4j and the log4j bridge into your project is fairly easy - just add the dependencies and they'll do the rest themselves.

BTW, I do hope you removed the servlet-api.jar from the Lids webapp.

Tomcat isn't prone to hanging up on its own, so the fault is almost guaranteed to be in the webapp. Logging may or may not reveal the root cause. You need to fix it, but you should also consider taking a diagnostic snapshot of the running system just to see what's going on after Tomcat freezes.

[Davie Lin]

Tim Holloway wrote:BTW, I do hope you removed the servlet-api.jar from the Lids webapp..

Done, servlet-api.jar has been remove out of webapp's lib directory

Tim Holloway wrote:
Tomcat isn't prone to hanging up on its own, so the fault is almost guaranteed to be in the webapp. Logging may or may not reveal the root cause. You need to fix it, but you should also consider taking a diagnostic snapshot of the running system just to see what's going on after Tomcat freezes

Does this mean triggering a java dump? I have generated a java dump by doing kill -3 <pid> but with my limited knowledge, I believe I see no lock contention, here is a snippet

NULL           ------------------------------------------------------------------------
0SECTION       LOCKS subcomponent dump routine
NULL           ===============================
NULL           
1LKPOOLINFO    Monitor pool info:
2LKPOOLTOTAL     Current total number of monitors: 1
NULL           
1LKMONPOOLDUMP Monitor Pool Dump (flat & inflated object-monitors):
2LKMONINUSE      sys_mon_t:0x0000000112A88180 infl_mon_t: 0x0000000112A881C0:
3LKMONOBJECT       sun/misc/GC$LatencyLock@0x07000000002D5138/0x07000000002D5150: <unowned>
3LKNOTIFYQ            Waiting to be notified:
3LKWAITNOTIFY            "GC Daemon" (0x0000000112CE7B00)

I follow the IBM's tutorial a bit and my thoughts were there is no lock contention since there is only one monitor and only the "GC Daemon" is waiting to be notified. There is more stuff after but I don't understand it and the tutorial didn't elaborate

Thanks again for your help

[Tim Holloway]

Actually, it's more common that something goes CPU-crazy or hangs waiting for I/O or network. So looking at the stacktraces for the threads is where I usually start. And yes, the dump is what I meant. Alternatively, if you can jack into the Tomcat JVM with a remote debugger, that's even better.

[Davie Lin]

Tim Holloway wrote:Actually, it's more common that something goes CPU-crazy or hangs waiting for I/O or network. So looking at the stacktraces for the threads is where I usually start. And yes, the dump is what I meant.

Hi Tim,

sorry to bother you again. I have taken 2 dump files at 2 different time but both are with my problem war file and I started learning how to interpret stack trace from Oracle's site. Here is what I found interesting and I would like to know what you think

3XMTHREADINFO      "Signal Dispatcher" J9VMThread:0x0000000111FEBB00, j9thread_t:0x0000000111E57220, java/lang/Thread:0x0700000000040180, state:R, prio=5
3XMTHREADINFO1            (native thread ID:0x31F00AD, native priority:0x5, native policy:UNKNOWN)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at com/ibm/misc/SignalDispatcher.waitForSignal(Native Method)
4XESTACKTRACE                at com/ibm/misc/SignalDispatcher.run(SignalDispatcher.java:66)
3XMTHREADINFO3           Native callstack:
4XENATIVESTACK               nsleep+0xe4 (0x090000000002B7C8 [libc.a+0x2afc8])
4XENATIVESTACK               usleep+0xd4 (0x090000000002B1D8 [libc.a+0x2a9d8])
4XENATIVESTACK               signalWait (0x09000000031FE06C [libjava.so+0x1806c])
4XENATIVESTACK               Java_com_ibm_misc_SignalDispatcher_waitForSignal+0xc (0x09000000031FDB50 [libjava.so+0x17b50])
4XENATIVESTACK               (0x090000000314572C [libj9vm24.so+0x4972c])
4XENATIVESTACK               (0x0900000003107BC0 [libj9vm24.so+0xbbc0])
4XENATIVESTACK               (0x090000000319AF94 [libj9prt24.so+0x1f94])
4XENATIVESTACK               (0x0900000003107AE0 [libj9vm24.so+0xbae0])
4XENATIVESTACK               (0x0900000003186C70 [libj9thr24.so+0x1c70])
4XENATIVESTACK               _pthread_body+0xf0 (0x090000000075FD54 [libpthreads.a+0x3d54])

After comparing the stack trace out of 2 dump files taken different time with same condition. The condition being only have the problem war file in webapps directory.
I believe this is the current RUNNING thread based upon what I learn from Oracle's site because

3XMTHREADINFO      "Signal Dispatcher" J9VMThread:0x0000000111FEBB00, j9thread_t:0x0000000111E57220, java/lang/Thread:0x0700000000040180, state:R, prio=5

State is R, which means Running and while I do have another thread that is also have state R

3XMTHREADINFO      "Attach API wait loop" J9VMThread:0x00000001122C3200, j9thread_t:0x00000001121D6F80, java/lang/Thread:0x070000000006A8E0, state:R, prio=10
3XMTHREADINFO1            (native thread ID:0x2AD0087, native priority:0xA, native policy:UNKNOWN)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at com/ibm/tools/attach/javaSE/IPC.waitSemaphore(Native Method)
4XESTACKTRACE                at com/ibm/tools/attach/javaSE/CommonDirectory.waitSemaphore(CommonDirectory.java:220)
4XESTACKTRACE                at com/ibm/tools/attach/javaSE/AttachHandler$WaitLoop.waitForNotification(AttachHandler.java:329)
4XESTACKTRACE                at com/ibm/tools/attach/javaSE/AttachHandler$WaitLoop.run(AttachHandler.java:396)
3XMTHREADINFO3           Native callstack:
4XENATIVESTACK               (0x0900000003199690 [libj9prt24.so+0x690])
4XENATIVESTACK               (0x09000000031BBF60 [libj9prt24.so+0x22f60])
4XENATIVESTACK               (0x0900000003A81088 [libjclscar_24.so+0x6088])
4XENATIVESTACK               (0x090000000314572C [libj9vm24.so+0x4972c])
4XENATIVESTACK               (0x0900000003107BC0 [libj9vm24.so+0xbbc0])
4XENATIVESTACK               (0x090000000319AF94 [libj9prt24.so+0x1f94])
4XENATIVESTACK               (0x0900000003107AE0 [libj9vm24.so+0xbae0])
4XENATIVESTACK               (0x0900000003186C70 [libj9thr24.so+0x1c70])
4XENATIVESTACK               _pthread_body+0xf0 (0x090000000075FD54 [libpthreads.a+0x3d54])

The priority of "Attach API wait loop" is lower than "Signal Dispatcher" thread. Therefore "Signal Dispatcher" thread is the running thread when I took the dump file both times.

Now looking at the call stack of "Signal Dispatcher" thread, I think it is stuck at

3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at com/ibm/misc/SignalDispatcher.waitForSignal(Native Method)
4XESTACKTRACE                at com/ibm/misc/SignalDispatcher.run(SignalDispatcher.java:66)

My question here is, would you say this is the IBM Java 6 issue?

Thanks again for all your help

[Tim Holloway]

I usually look for the threads who aren't in the process of calling some sort of "wait" method.

And yes, it can't hurt to try running Tomcat under the Sun/Oracle JDK VM instead of IBM's J9. J9 is supposed to work, but we all have our off-days. Just install the Oracle JDK, set JAVA_HOME to point to it and launch Tomcat.

[Davie Lin]

Tim Holloway wrote:And yes, it can't hurt to try running Tomcat under the Sun/Oracle JDK VM instead of IBM's J9. J9 is supposed to work, but we all have our off-days. Just install the Oracle JDK, set JAVA_HOME to point to it and launch Tomcat.

I am all for trying a different JDK, however, we have other Java process that relies on IBM's J9 so our admin hesitate to change to different Java version. My question here is, is there a way for us to not change the default java version while download a new Oracle's JDK/JRE ( I believe Tomcat 6 will ran under a JRE ) and modify catalina.sh to start tomcat under Oracle's JDK/JRE?

Thanks again Tim

[Tim Holloway]

One of the reasons I try to avoid vendor-specific features unless there's an overriding need: you can end up in a corner. It's one thing to use J9 for its performance and the neat operational capabilities, but when you start becoming addicted to com.ibm java classes, that's another matter entirely.

It is perfectly allowable to install and concurrently use more than one JVM on a machine at a time. That, in fact, is the reason why Tomcat uses the JAVA_HOME variable; so that you can set its JAVA_HOME to use one brand/version of Java while other apps may be using other brands/versions. You do NOT need to modify Tomcat's standard scripts to do this, nor should you. Although you can simply set JAVA_HOME in a script that invokes the catalina.sh script, you can also create a TOMCAT_HOME/setenv.sh file and assign JAVA_HOME there.

None of that helps if the webapp itself cannot run without J9, but at least it helps. It also allows you to use a different version of J9 if the current one is "broken" for your purposes. Once upon a time when IBM was in its prime, they'd even go so far as to provide patches (PTFs) for products so that you could use those as interim fixes.

I got the impression that Tomcat6 was intended to be able to run using only a JRE, but I don't think it happened. I've been using the JDK, at any rate. The only real difference as far as configuration goes is what you point JAVA_HOME at.

[Davie Lin]

Hi Tim

We brought this issue to IBM and they want us to try

-Xjit:exclude={org/ajax4jsf/cache/ServletContextInitMap$1.size}

Do I need to modify catalina.sh to add the above? I am not exactly sure where in catalina.sh to add the above.

[Tim Holloway]

Davie Lin wrote:Hi Tim

We brought this issue to IBM and they want us to try

-Xjit:exclude={org/ajax4jsf/cache/ServletContextInitMap$1.size}

Do I need to modify catalina.sh to add the above? I am not exactly sure where in catalina.sh to add the above.

You should be able to create a TOMCAT_HOME/bin/setenv.sh file and put the following statement in it:

CATALINA_OPTS="-Xjit:exclude={org/ajax4jsf/cache/ServletContextInitMap$1.size}"