Brett Delle Grazie | 7 Sep 09:00 2010

Re: unusual mod_jk 1.2.30 log messages

On Thu, 2010-09-02 at 18:26 +0200, Rainer Jung wrote:
> On 02.09.2010 13:39, Brett Delle Grazie wrote:
> > Hi,
> >
> > We're having some strange errors being reported in the 1.2.30 version of
> > mod_jk.  We think they might be related to the performance issues we're
> > experiencing under load.
> >
> > OS: RHEL 5.5 (fully patched)
> > Apache HTTPD: 2.2.3 (from OS vendor)
> > mod_jk: 1.2.30 (downloaded from Tomcat site and compiled locally)
> > Tomcat: 6.0.29 (binary distribution from apache.org)
> > JVM: 1.6.0_21 (Sun, 64-bit).
> 
> Thanks for the info (and for keeping most of it up-to-date) :)
> 
> > A sample is below. I'm mostly concerned about the 'awaited reply cpong
> > recieved 3 instead' and the subsequenct close  and failure to send
> > request.
> >
> > Has anyone seen this before?
> >
> > [Thu Sep 02 07:22:47.508 2010] [31759:47279871456000] [info]
> > init_jk::mod_jk.c (3189): mod_jk/1.2.30 initialized
> > [Thu Sep 02 07:22:47.588 2010] [31763:47279871456000] [info]
> > init_jk::mod_jk.c (3189): mod_jk/1.2.30 initialized
> > [Thu Sep 02 07:22:52.896 2010] [31781:1237244224] [warn]
> > ajp_handle_cping_cpong::jk_ajp_common.c (906): awaited reply cpong,
> > received 3 instead. Closing connection
> > [Thu Sep 02 07:22:52.896 2010] [31781:1237244224] [info]
> > ajp_send_request::jk_ajp_common.c (1518): (jvm2) failed sending request,
> > socket -1 prepost cping/cpong failure (errno=0)
> > [Thu Sep 02 07:22:59.647 2010] [31781:1258223936] [warn]
> > ajp_handle_cping_cpong::jk_ajp_common.c (906): awaited reply cpong,
> > received 3 instead. Closing connection
> > [Thu Sep 02 07:22:59.647 2010] [31781:1258223936] [info]
> > ajp_send_request::jk_ajp_common.c (1518): (jvm2) failed sending request,
> > socket -1 prepost cping/cpong failure (errno=0)
> > [Thu Sep 02 07:23:02.042 2010] [32082:1253792064] [warn]
> > ajp_handle_cping_cpong::jk_ajp_common.c (906): awaited reply cpong,
> > received 3 instead. Closing connection
> > [Thu Sep 02 07:23:02.042 2010] [32082:1253792064] [info]
> > ajp_send_request::jk_ajp_common.c (1518): (jvm2) failed sending request,
> > socket -1 prepost cping/cpong failure (errno=0)
> > [Thu Sep 02 07:23:06.142 2010] [32049:1325504832] [warn]
> > ajp_handle_cping_cpong::jk_ajp_common.c (906): awaited reply cpong,
> > received 3 instead. Closing connection
> > [Thu Sep 02 07:23:06.142 2010] [32049:1325504832] [info]
> > ajp_send_request::jk_ajp_common.c (1518): (jvm1) failed sending request,
> > socket -1 prepost cping/cpong failure (errno=0)
> > [Thu Sep 02 07:23:11.231 2010] [32082:1211832640] [info]
> > ajp_process_callback::jk_ajp_common.c (1882): Writing to client aborted
> > or client network problems
> > [Thu Sep 02 07:23:11.231 2010] [32082:1211832640] [info]
> > ajp_service::jk_ajp_common.c (2540): (jvm1) sending request to tomcat
> > failed (unrecoverable), because of client write error (attempt=1)
> > [Thu Sep 02 07:23:11.232 2010] [32082:1211832640] [info]
> > service::jk_lb_worker.c (1388): service failed, worker jvm1 is in local
> > error state
> > [Thu Sep 02 07:23:11.232 2010] [32082:1211832640] [info]
> > service::jk_lb_worker.c (1407): unrecoverable error 200, request failed.
> > Client failed in the middle of request, we can't recover to another
> > instance.
> > [Thu Sep 02 07:23:11.232 2010] [32082:1211832640] [info]
> > jk_handler::mod_jk.c (2611): Aborting connection for worker=balancer
> > [Thu Sep 02 07:23:11.444 2010] [32049:1315014976] [info]
> > ajp_process_callback::jk_ajp_common.c (1882): Writing to client aborted
> > or client network problems
> > [Thu Sep 02 07:23:11.444 2010] [32049:1315014976] [info]
> > ajp_service::jk_ajp_common.c (2540): (jvm1) sending request to tomcat
> > failed (unrecoverable), because of client write error (attempt=1)
> > [Thu Sep 02 07:23:11.445 2010] [32049:1315014976] [info]
> > service::jk_lb_worker.c (1388): service failed, worker jvm1 is in local
> > error state
> > [Thu Sep 02 07:23:11.445 2010] [32049:1315014976] [info]
> > service::jk_lb_worker.c (1407): unrecoverable error 200, request failed.
> > Client failed in the middle of request, we can't recover to another
> > instance.
> > [Thu Sep 02 07:23:11.445 2010] [32049:1315014976] [info]
> > jk_handler::mod_jk.c (2611): Aborting connection for worker=balancer
> > [Thu Sep 02 07:23:11.645 2010] [32082:1232812352] [info]
> > ajp_process_callback::jk_ajp_common.c (1882): Writing to client aborted
> > or client network problems
> > [Thu Sep 02 07:23:11.645 2010] [32082:1232812352] [info]
> > ajp_service::jk_ajp_common.c (2540): (jvm1) sending request to tomcat
> > failed (unrecoverable), because of client write error (attempt=1)
> > [Thu Sep 02 07:23:11.646 2010] [32082:1232812352] [info]
> > service::jk_lb_worker.c (1388): service failed, worker jvm1 is in local
> > error state
> > [Thu Sep 02 07:23:11.646 2010] [32082:1232812352] [info]
> > service::jk_lb_worker.c (1407): unrecoverable error 200, request failed.
> > Client failed in the middle of request, we can't recover to another
> > instance.
> > [Thu Sep 02 07:23:11.646 2010] [32082:1232812352] [info]
> > jk_handler::mod_jk.c (2611): Aborting connection for worker=balancer
> > [Thu Sep 02 07:23:17.902 2010] [31927:1298282816] [warn]
> > ajp_handle_cping_cpong::jk_ajp_common.c (906): awaited reply cpong,
> > received 3 instead. Closing connection
> > [Thu Sep 02 07:23:17.902 2010] [31927:1298282816] [info]
> > ajp_send_request::jk_ajp_common.c (1518): (jvm1) failed sending request,
> > socket -1 prepost cping/cpong failure (errno=0)
> > [Thu Sep 02 07:23:17.902 2010] [31927:1298282816] [info]
> > ajp_send_request::jk_ajp_common.c (1574): (jvm1) all endpoints are
> > disconnected, detected by connect check (0), cping (1), send (0)
> > [Thu Sep 02 07:23:20.676 2010] [31927:1140934976] [warn]
> > ajp_handle_cping_cpong::jk_ajp_common.c (906): awaited reply cpong,
> > received 3 instead. Closing connection
> > [Thu Sep 02 07:23:20.676 2010] [31927:1140934976] [info]
> > ajp_send_request::jk_ajp_common.c (1518): (jvm2) failed sending request,
> > socket -1 prepost cping/cpong failure (errno=0)
> > [Thu Sep 02 07:23:29.280 2010] [31927:1182894400] [warn]
> > ajp_handle_cping_cpong::jk_ajp_common.c (906): awaited reply cpong,
> > received 3 instead. Closing connection
> > [Thu Sep 02 07:23:29.280 2010] [31927:1182894400] [info]
> > ajp_send_request::jk_ajp_common.c (1518): (jvm2) failed sending request,
> > socket -1 prepost cping/cpong failure (errno=0)
> > [Thu Sep 02 07:23:33.014 2010] [32082:1138403648] [info]
> > ajp_process_callback::jk_ajp_common.c (1882): Writing to client aborted
> > or client network problems
> > [Thu Sep 02 07:23:33.014 2010] [32082:1138403648] [info]
> > ajp_service::jk_ajp_common.c (2540): (jvm1) sending request to tomcat
> > failed (unrecoverable), because of client write error (attempt=1)
> > [Thu Sep 02 07:23:33.014 2010] [32082:1138403648] [info]
> > service::jk_lb_worker.c (1388): service failed, worker jvm1 is in local
> > error state
> > [Thu Sep 02 07:23:33.014 2010] [32082:1138403648] [info]
> > service::jk_lb_worker.c (1407): unrecoverable error 200, request failed.
> > Client failed in the middle of request, we can't recover to another
> > instance.
> > [Thu Sep 02 07:23:33.014 2010] [32082:1138403648] [info]
> > jk_handler::mod_jk.c (2611): Aborting connection for worker=balancer
> >
> > The rest of the log continues in the same pattern albeit with higher
> > frequency as the load increases.
> 
> I guess you hit
> 
> https://issues.apache.org/bugzilla/show_bug.cgi?id=49413
> 
> Even though you don't use JBoss it could still be a flush issue (see 
> comments further down the ticket). In your case, since you have 
> cping/cpong active (which is a good thing), it is not the next request 
> packet that finds a wrong backend packet on the wire but instead the 
> cping. We *thought* we had fixed that shortly before 1.2.30, but there 
> might be a glitch in the patch.
> 
> Could you apply the following patch and proviede the slightly extended 
> log message:
> 
> --- jk_ajp_common.c     2010-02-23 08:26:02.000000000 +0100
> +++ jk_ajp_common.c.debug       2010-09-02 18:24:41.429730000 +0200
>  <at>  <at>  -904,9 +904,9  <at>  <at> 
>                        cmd < JK_AJP13_SEND_BODY_CHUNK ||
>                        cmd > AJP13_CPONG_REPLY) {
>                   jk_log(l, JK_LOG_WARNING,
> -                       "awaited reply cpong, received %d instead. "
> +                       "awaited reply cpong, received %d (%d / %d) 
> instead. "
>                          "Closing connection",
> -                       cmd);
> +                       cmd, i, ae->last_op);
>                   /* We can't trust this connection any more. */
>                   ajp_abort_endpoint(ae, JK_TRUE, l);
>                   JK_TRACE_EXIT(l);
> 
> Regards,
> 
> Rainer
> 

Hi again Rainer,

We've finally managed to gather the logs you requested with mod_jk patch
applied they are as follows:

[Tue Sep 07 07:25:34.506 2010] [1975:47640507769600] [info]
init_jk::mod_jk.c (3189): mod_jk/1.2.30 initialized
[Tue Sep 07 07:25:34.585 2010] [1979:47640507769600] [info]
init_jk::mod_jk.c (3189): mod_jk/1.2.30 initialized
[Tue Sep 07 07:50:40.845 2010] [20843:1151129920] [warn]
ajp_handle_cping_cpong::jk_ajp_common.c (906): awaited reply cpong,
received 3 (0 / 5) instead. Closing connection
[Tue Sep 07 07:50:40.845 2010] [20843:1151129920] [info]
ajp_send_request::jk_ajp_common.c (1518): (jvm2) failed sending request,
socket -1 prepost cping/cpong failure (errno=0)
[Tue Sep 07 07:50:45.989 2010] [20745:1358588224] [warn]
ajp_handle_cping_cpong::jk_ajp_common.c (906): awaited reply cpong,
received 3 (0 / 5) instead. Closing connection
[Tue Sep 07 07:50:45.989 2010] [20745:1358588224] [info]
ajp_send_request::jk_ajp_common.c (1518): (jvm1) failed sending request,
socket -1 prepost cping/cpong failure (errno=0)
[Tue Sep 07 07:50:56.634 2010] [20843:1193089344] [warn]
ajp_handle_cping_cpong::jk_ajp_common.c (906): awaited reply cpong,
received 3 (0 / 5) instead. Closing connection
[Tue Sep 07 07:50:56.634 2010] [20843:1193089344] [info]
ajp_send_request::jk_ajp_common.c (1518): (jvm2) failed sending request,
socket -1 prepost cping/cpong failure (errno=0)
[Tue Sep 07 07:51:04.722 2010] [20952:1147337024] [info]
ajp_process_callback::jk_ajp_common.c (1882): Writing to client aborted
or client network problems
[Tue Sep 07 07:51:04.722 2010] [20952:1147337024] [info]
ajp_service::jk_ajp_common.c (2540): (jvm2) sending request to tomcat
failed (unrecoverable), because of client write error (attempt=1)
[Tue Sep 07 07:51:04.724 2010] [20952:1147337024] [info]
service::jk_lb_worker.c (1388): service failed, worker jvm2 is in local
error state
[Tue Sep 07 07:51:04.724 2010] [20952:1147337024] [info]
service::jk_lb_worker.c (1407): unrecoverable error 200, request failed.
Client failed in the middle of request, we can't recover to another
instance.
[Tue Sep 07 07:51:04.724 2010] [20952:1147337024] [info]
jk_handler::mod_jk.c (2611): Aborting connection for worker=balancer
[Tue Sep 07 07:51:09.226 2010] [20917:1268017472] [info]
ajp_process_callback::jk_ajp_common.c (1882): Writing to client aborted
or client network problems
[Tue Sep 07 07:51:09.226 2010] [20917:1268017472] [info]
ajp_service::jk_ajp_common.c (2540): (jvm1) sending request to tomcat
failed (unrecoverable), because of client write error (attempt=1)
[Tue Sep 07 07:51:09.227 2010] [20917:1268017472] [info]
service::jk_lb_worker.c (1388): service failed, worker jvm1 is in local
error state
[Tue Sep 07 07:51:09.227 2010] [20917:1268017472] [info]
service::jk_lb_worker.c (1407): unrecoverable error 200, request failed.
Client failed in the middle of request, we can't recover to another
instance.
[Tue Sep 07 07:51:09.227 2010] [20917:1268017472] [info]
jk_handler::mod_jk.c (2611): Aborting connection for worker=balancer
[Tue Sep 07 07:51:12.723 2010] [1994:1357330752] [info]
ajp_process_callback::jk_ajp_common.c (1882): Writing to client aborted
or client network problems
[Tue Sep 07 07:51:12.723 2010] [1994:1357330752] [info]
ajp_service::jk_ajp_common.c (2540): (jvm1) sending request to tomcat
failed (unrecoverable), because of client write error (attempt=1)
[Tue Sep 07 07:51:12.723 2010] [1994:1357330752] [info]
service::jk_lb_worker.c (1388): service failed, worker jvm1 is in local
error state
[Tue Sep 07 07:51:12.723 2010] [1994:1357330752] [info]
service::jk_lb_worker.c (1407): unrecoverable error 200, request failed.
Client failed in the middle of request, we can't recover to another
instance.
[Tue Sep 07 07:51:12.723 2010] [1994:1357330752] [info]
jk_handler::mod_jk.c (2611): Aborting connection for worker=balancer
[Tue Sep 07 07:51:14.059 2010] [1994:1137043776] [warn]
ajp_handle_cping_cpong::jk_ajp_common.c (906): awaited reply cpong,
received 3 (0 / 5) instead. Closing connection
[Tue Sep 07 07:51:14.059 2010] [1994:1137043776] [info]
ajp_send_request::jk_ajp_common.c (1518): (jvm1) failed sending request,
socket -1 prepost cping/cpong failure (errno=0)
[Tue Sep 07 07:51:14.286 2010] [1994:1252432192] [warn]
ajp_handle_cping_cpong::jk_ajp_common.c (906): awaited reply cpong,
received 3 (0 / 5) instead. Closing connection
[Tue Sep 07 07:51:14.286 2010] [1994:1252432192] [info]
ajp_send_request::jk_ajp_common.c (1518): (jvm2) failed sending request,
socket -1 prepost cping/cpong failure (errno=0)
[Tue Sep 07 07:51:34.354 2010] [20843:1172109632] [warn]
ajp_handle_cping_cpong::jk_ajp_common.c (906): awaited reply cpong,
received 3 (0 / 5) instead. Closing connection
[Tue Sep 07 07:51:34.354 2010] [20843:1172109632] [info]
ajp_send_request::jk_ajp_common.c (1518): (jvm2) failed sending request,
socket -1 prepost cping/cpong failure (errno=0)
[Tue Sep 07 07:51:45.267 2010] [20953:1148954944] [warn]
ajp_handle_cping_cpong::jk_ajp_common.c (906): awaited reply cpong,
received 3 (0 / 5) instead. Closing connection
[Tue Sep 07 07:51:45.267 2010] [20953:1148954944] [info]
ajp_send_request::jk_ajp_common.c (1518): (jvm2) failed sending request,
socket -1 prepost cping/cpong failure (errno=0)
[Tue Sep 07 07:51:54.832 2010] [20953:1169934656] [warn]
ajp_handle_cping_cpong::jk_ajp_common.c (906): awaited reply cpong,
received 3 (0 / 5) instead. Closing connection
[Tue Sep 07 07:51:54.834 2010] [20953:1169934656] [info]
ajp_send_request::jk_ajp_common.c (1518): (jvm2) failed sending request,
socket -1 prepost cping/cpong failure (errno=0)
[Tue Sep 07 07:51:56.064 2010] [20633:1344907584] [info]
ajp_process_callback::jk_ajp_common.c (1882): Writing to client aborted
or client network problems
[Tue Sep 07 07:51:56.064 2010] [20633:1344907584] [info]
ajp_service::jk_ajp_common.c (2540): (jvm2) sending request to tomcat
failed (unrecoverable), because of client write error (attempt=1)
[Tue Sep 07 07:51:56.064 2010] [20633:1344907584] [info]
service::jk_lb_worker.c (1388): service failed, worker jvm2 is in local
error state
[Tue Sep 07 07:51:56.064 2010] [20633:1344907584] [info]
service::jk_lb_worker.c (1407): unrecoverable error 200, request failed.
Client failed in the middle of request, we can't recover to another
instance.
[Tue Sep 07 07:51:56.064 2010] [20633:1344907584] [info]
jk_handler::mod_jk.c (2611): Aborting connection for worker=balancer
[Tue Sep 07 07:52:01.627 2010] [1997:1269545280] [info]
ajp_process_callback::jk_ajp_common.c (1882): Writing to client aborted
or client network problems
[Tue Sep 07 07:52:01.627 2010] [1997:1269545280] [info]
ajp_service::jk_ajp_common.c (2540): (jvm1) sending request to tomcat
failed (unrecoverable), because of client write error (attempt=1)
[Tue Sep 07 07:52:01.628 2010] [1997:1269545280] [info]
service::jk_lb_worker.c (1388): service failed, worker jvm1 is in local
error state
[Tue Sep 07 07:52:01.628 2010] [1997:1269545280] [info]
service::jk_lb_worker.c (1407): unrecoverable error 200, request failed.
Client failed in the middle of request, we can't recover to another
instance.
[Tue Sep 07 07:52:01.628 2010] [1997:1269545280] [info]
jk_handler::mod_jk.c (2611): Aborting connection for worker=balancer
[Tue Sep 07 07:52:02.769 2010] [21188:1305143616] [warn]
ajp_handle_cping_cpong::jk_ajp_common.c (906): awaited reply cpong,
received 3 (0 / 5) instead. Closing connection
[Tue Sep 07 07:52:02.769 2010] [21188:1305143616] [info]
ajp_send_request::jk_ajp_common.c (1518): (jvm1) failed sending request,
socket -1 prepost cping/cpong failure (errno=0)
[Tue Sep 07 07:52:05.538 2010] [1997:1342974272] [info]
ajp_process_callback::jk_ajp_common.c (1882): Writing to client aborted
or client network problems
[Tue Sep 07 07:52:05.538 2010] [1997:1342974272] [info]
ajp_service::jk_ajp_common.c (2540): (jvm2) sending request to tomcat
failed (unrecoverable), because of client write error (attempt=1)
[Tue Sep 07 07:52:05.538 2010] [1997:1342974272] [info]
service::jk_lb_worker.c (1388): service failed, worker jvm2 is in local
error state
[Tue Sep 07 07:52:05.538 2010] [1997:1342974272] [info]
service::jk_lb_worker.c (1407): unrecoverable error 200, request failed.
Client failed in the middle of request, we can't recover to another
instance.
[Tue Sep 07 07:52:05.538 2010] [1997:1342974272] [info]
jk_handler::mod_jk.c (2611): Aborting connection for worker=balancer
[Tue Sep 07 07:52:12.341 2010] [1997:1154156864] [warn]
ajp_handle_cping_cpong::jk_ajp_common.c (906): awaited reply cpong,
received 3 (0 / 5) instead. Closing connection
[Tue Sep 07 07:52:12.342 2010] [1997:1154156864] [info]
ajp_send_request::jk_ajp_common.c (1518): (jvm2) failed sending request,
socket -1 prepost cping/cpong failure (errno=0)
[Tue Sep 07 07:54:46.760 2010] [22333:1169860928] [info]
ajp_process_callback::jk_ajp_common.c (1882): Writing to client aborted
or client network problems
[Tue Sep 07 07:54:46.760 2010] [22333:1169860928] [info]
ajp_service::jk_ajp_common.c (2540): (jvm1) sending request to tomcat
failed (unrecoverable), because of client write error (attempt=1)
[Tue Sep 07 07:54:46.760 2010] [22333:1169860928] [info]
service::jk_lb_worker.c (1388): service failed, worker jvm1 is in local
error state
[Tue Sep 07 07:54:46.760 2010] [22333:1169860928] [info]
service::jk_lb_worker.c (1407): unrecoverable error 200, request failed.
Client failed in the middle of request, we can't recover to another
instance.
[Tue Sep 07 07:54:46.760 2010] [22333:1169860928] [info]
service::jk_lb_worker.c (1407): unrecoverable error 200, request failed.
Client failed in the middle of request, we can't recover to another
instance.
[Tue Sep 07 07:54:46.760 2010] [22333:1169860928] [info]
jk_handler::mod_jk.c (2611): Aborting connection for worker=balancer
[Tue Sep 07 07:54:47.761 2010] [1997:1164646720] [info]
ajp_process_callback::jk_ajp_common.c (1882): Writing to client aborted
or client network problems
[Tue Sep 07 07:54:47.761 2010] [1997:1164646720] [info]
ajp_service::jk_ajp_common.c (2540): (jvm1) sending request to tomcat
failed (unrecoverable), because of client write error (attempt=1)
[Tue Sep 07 07:54:47.761 2010] [1997:1164646720] [info]
service::jk_lb_worker.c (1388): service failed, worker jvm1 is in local
error state
[Tue Sep 07 07:54:47.761 2010] [1997:1164646720] [info]
service::jk_lb_worker.c (1407): unrecoverable error 200, request failed.
Client failed in the middle of request, we can't recover to another
instance.
[Tue Sep 07 07:54:47.761 2010] [1997:1164646720] [info]
jk_handler::mod_jk.c (2611): Aborting connection for worker=balancer

Hope you can help,

Thanks,

--

-- 
Best Regards,

Brett Delle Grazie

______________________________________________________________________
This email has been scanned by the MessageLabs Email Security System.
For more information please visit http://www.messagelabs.com/email 
______________________________________________________________________

Gmane