Bug 50125

Summary: apache failed with any exception
Product: Apache httpd-2 Reporter: nguyen <ndhai77>
Component: mpm_workerAssignee: Apache HTTPD Bugs Mailing List <bugs>
Status: RESOLVED INVALID    
Severity: normal    
Priority: P2    
Version: 2.5-HEAD   
Target Milestone: ---   
Hardware: PC   
OS: Windows XP   

Description nguyen 2010-10-20 12:26:49 UTC
Hi
I DON'T know if it is a BUG or we did something wrong ...
I am using jk mod 1.2.26, Tomcat 5.5, Apache 2
JVM Sun 1.6.0_12-b04, OS Debian

workers.properties:
workers.tomcat_home=/usr/share/tomcat5.5
workers.java_home=/usr/lib/jvm/java-6-sun

ps=/
worker.list=worker1
worker.worker1.port=8009
worker.worker1.host=localhost
worker.worker1.type=ajp13
worker.worker1.lbfactor=1 


It works ALMOST ok but when I hit ANY exception, for ex, java.lang.NullPointerException, http doesn't reponse anymore. We have to restart Tomcat+Apache

Sorry for log in french:

localhost log (tomcat)
14 oct. 2010 23:40:20 org.apache.catalina.core.StandardWrapperValve invoke
GRAVE: "Servlet.service()" pour la servlet jsp a généré une exception
java.lang.NullPointerException  

acces.log (Apache)
xyz.com:80 ip - - [14/Oct/2010:23:40:20 +0200] "GET /xyz/jsp/test.jsp?p=test HTTP/1.1" 500 3046 "-" ""
xyz.com:80 ip - - [14/Oct/2010:23:44:41 +0200] "GET /xyz/jsp/test.jsp?p=test HTTP/1.1" 503 417 "-" ""

error.log (Apache)
[Thu Oct 14 23:40:33 2010] [notice] caught SIGTERM, shutting down
[Thu Oct 14 23:41:34 2010] [notice] Apache/2.2.9 (Debian) mod_jk/1.2.26 configured -- resuming normal operations
[Thu Oct 14 23:45:03 2010] [notice] caught SIGTERM, shutting down
[Thu Oct 14 23:45:04 2010] [notice] Apache/2.2.9 (Debian) mod_jk/1.2.26 configured -- resuming normal operations
[Thu Oct 14 23:45:33 2010] [notice] caught SIGTERM, shutting down

mod_jk.log (apache)
Thu Oct 14 23:37:03 2010]worker1 192.168.163.113 15.249507
[Thu Oct 14 23:40:20 2010]worker1 192.168.163.113 0.058192
[Thu Oct 14 23:41:34 2010][2281:2233493328] [info] init_jk::mod_jk.c (2830): mod_jk/1.2.26 initialized
[Thu Oct 14 23:41:34 2010][2282:2233493328] [info] init_jk::mod_jk.c (2830): mod_jk/1.2.26 initialized
[Thu Oct 14 23:44:41 2010][2286:1086212432] [info] jk_open_socket::jk_connect.c (566): connect to 127.0.0.1:8009 failed (errno=111)
[Thu Oct 14 23:44:41 2010][2286:1086212432] [info] ajp_connect_to_endpoint::jk_ajp_common.c (869): Failed opening socket to (127.0.0.1:8009) (errno=111)
[Thu Oct 14 23:44:41 2010][2286:1086212432] [error] 

catalina (tomcat)
14 oct. 2010 23:40:33 org.apache.coyote.http11.Http11BaseProtocol pause
INFO: Suspension de Coyote HTTP/1.1 sur http-8180
14 oct. 2010 23:43:42 org.apache.catalina.connector.Connector pause
GRAVE: La suspension du gestionnaire de protocole a échouée
java.net.ConnectException: Connection timed out 

Others tests: divise by zero, or use an objet no declare => the same pb


Anyone has the same pb ?
thanks
Comment 1 Rainer Jung 2010-10-20 13:13:21 UTC
Bugzilla is not a support forum. Plese post your questions to the Tomcat users list, or the Apache Web Server users list.

To subscribe, send mail to

   users-subscribe@tomcat.apache.org

or

   users-subscribe@httpd.apache.org

Nevertheless here are some remarks that might be helpful. Please don't answer here but take the discussion to one of the lists.

> It works ALMOST ok but when I hit ANY exception, for ex,
> java.lang.NullPointerException, http doesn't reponse anymore. We have to
> restart Tomcat+Apache

That's pretty strange, but ...

> Sorry for log in french:

... your logs speak a different language (assuming clocks are in sync):

Ordered by timestamp:

Apache receives request, responds with 500:

xyz.com:80 ip - - [14/Oct/2010:23:40:20 +0200] "GET /xyz/jsp/test.jsp?p=test
HTTP/1.1" 500 3046 "-" ""

mod_jk logs the request, it tool 0.05 seconds

[Thu Oct 14 23:40:20 2010]worker1 192.168.163.113 0.058192

and the reason for the status 500 is

14 oct. 2010 23:40:20 org.apache.catalina.core.StandardWrapperValve invoke
GRAVE: "Servlet.service()" pour la servlet jsp a généré une exception
java.lang.NullPointerException  


13 seconds later someone tells Apache to shut down

[Thu Oct 14 23:40:33 2010] [notice] caught SIGTERM, shutting down

... and someone tells Tomcat to shutdown:

14 oct. 2010 23:40:33 org.apache.coyote.http11.Http11BaseProtocol pause
INFO: Suspension de Coyote HTTP/1.1 sur http-8180

but this shutdown hangs ...

Starting up Apache again

[Thu Oct 14 23:41:34 2010] [notice] Apache/2.2.9 (Debian) mod_jk/1.2.26
configured -- resuming normal operations

mod_jk loggs it initialized after the startup
[Thu Oct 14 23:41:34 2010][2281:2233493328] [info] init_jk::mod_jk.c (2830):
mod_jk/1.2.26 initialized
[Thu Oct 14 23:41:34 2010][2282:2233493328] [info] init_jk::mod_jk.c (2830):
mod_jk/1.2.26 initialized

Now Tomcat proceeds shutting down

14 oct. 2010 23:43:42 org.apache.catalina.connector.Connector pause
GRAVE: La suspension du gestionnaire de protocole a échouée
java.net.ConnectException: Connection timed out 

Another request comes in, answered with 503

xyz.com:80 ip - - [14/Oct/2010:23:44:41 +0200] "GET /xyz/jsp/test.jsp?p=test
HTTP/1.1" 503 417 "-" ""

Right, mod_jk says it couldn't connect to Tomcat

[Thu Oct 14 23:44:41 2010][2286:1086212432] [info] jk_open_socket::jk_connect.c
(566): connect to 127.0.0.1:8009 failed (errno=111)
[Thu Oct 14 23:44:41 2010][2286:1086212432] [info]
ajp_connect_to_endpoint::jk_ajp_common.c (869): Failed opening socket to
(127.0.0.1:8009) (errno=111)
[Thu Oct 14 23:44:41 2010][2286:1086212432] [error] 

and that's what we expect, since someone shut it down.

22 seconds later Apache gets shut down again:

[Thu Oct 14 23:45:03 2010] [notice] caught SIGTERM, shutting down
[Thu Oct 14 23:45:04 2010] [notice] Apache/2.2.9 (Debian) mod_jk/1.2.26
configured -- resuming normal operations
[Thu Oct 14 23:45:33 2010] [notice] caught SIGTERM, shutting down

If you don't know who shuts down the components all the time, maybe someone implemented a clever log file monitoring and some automatism outside of Apache and Tomcat does it?

Regards,

Rainer