On Tue, 2010-09-07 at 08:00 +0100, Brett Delle Grazie wrote: > 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, >
self update - A lot of our requests will be for images which will be larger than the standard 8k packet limit. These aren't static images so they can't be cached. Any help appreciated 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
