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 > @@ -904,9 +904,9 @@ > 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 ______________________________________________________________________ --------------------------------------------------------------------- To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
