Bug 54112 - ISAPI redirector not working when IIS recycles
Summary: ISAPI redirector not working when IIS recycles
Status: RESOLVED INVALID
Alias: None
Product: Tomcat Connectors
Classification: Unclassified
Component: isapi (show other bugs)
Version: 1.2.36
Hardware: PC All
: P2 blocker with 5 votes (vote)
Target Milestone: ---
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2012-11-07 13:26 UTC by sivaram
Modified: 2015-09-09 19:30 UTC (History)
1 user (show)



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description sivaram 2012-11-07 13:26:43 UTC
My Server details are below.

Windows 2008 R2 EE 64 bit
IIS 7.5 64 bit mode
isapi_redirect.dll (64 bit)
Tomcat 6.0 running in 64bit mode
Java Version :1.6.0_32
ISAPI redirector : 1.2.36.0

The default IIS recycle parameter is 29 hours, in this process when IIS recycles, the current worker process which handles the request are closed and the new worker process is not created and the server is getting 503 Service unavailable. Below is the error log.


Error log:


[Wed Nov 07 08:52:31.348 2012] [9260:9416] [debug] init_ws_service::jk_isapi_plugin.c (3446): Forwarding request header User-Agent : Mozilla/5.0 (Windows NT 5.1) AppleWebKit/537.4 (KHTML, like Gecko) Chrome/22.0.1229.94 Safari/537.4
[Wed Nov 07 08:52:31.349 2012] [9260:9416] [debug] init_ws_service::jk_isapi_plugin.c (3475): Service protocol=HTTP/1.1 method=GET host=10.246.0.3 addr=10.246.0.3 name=www.siva.com port=443 auth= user= uri=/SIVA/error.jsp
[Wed Nov 07 08:52:31.349 2012] [9260:9416] [debug] init_ws_service::jk_isapi_plugin.c (3487): Service request headers=10 attributes=9 chunked=no content-length=0 available=0
[Wed Nov 07 08:52:31.350 2012] [9260:9416] [debug] wc_get_worker_for_name::jk_worker.c (115): found a worker lb
[Wed Nov 07 08:52:31.350 2012] [9260:9416] [debug] HttpExtensionProc::jk_isapi_plugin.c (2298): got a worker for name lb
[Wed Nov 07 08:52:31.350 2012] [9260:9416] [debug] get_sessionid::jk_lb_worker.c (542): Detected session identifier [8E6FEF2AAA1A9B9390C5601F37AAFE58].
[Wed Nov 07 08:52:31.351 2012] [9260:9416] [debug] service::jk_lb_worker.c (1203): service sticky_session=1 id='8E6FEF2AAA1A9B9390C5601F37AAFE58'
[Wed Nov 07 08:52:31.351 2012] [9260:9416] [debug] service::jk_lb_worker.c (1248): service worker=node1 route=node1
[Wed Nov 07 08:52:31.351 2012] [9260:9416] [debug] ajp_get_endpoint::jk_ajp_common.c (3154): acquired connection pool slot=0 after 0 retries
[Wed Nov 07 08:52:31.352 2012] [9260:9416] [debug] ajp_marshal_into_msgb::jk_ajp_common.c (626): ajp marshaling done
[Wed Nov 07 08:52:31.352 2012] [9260:9416] [debug] ajp_service::jk_ajp_common.c (2449): processing node1 with 2 retries
[Wed Nov 07 08:52:31.353 2012] [9260:9416] [debug] ajp_send_request::jk_ajp_common.c (1623): (node1) all endpoints are disconnected.
[Wed Nov 07 08:52:31.353 2012] [9260:9416] [debug] jk_open_socket::jk_connect.c (485): socket TCP_NODELAY set to On
[Wed Nov 07 08:52:31.353 2012] [9260:9416] [debug] jk_open_socket::jk_connect.c (609): trying to connect socket 736 to 0.0.0.0:0
[Wed Nov 07 08:52:31.354 2012] [9260:9416] [info] jk_open_socket::jk_connect.c (627): connect to 0.0.0.0:0 failed (errno=47)
[Wed Nov 07 08:52:31.354 2012] [9260:9416] [info] ajp_connect_to_endpoint::jk_ajp_common.c (995): Failed opening socket to (0.0.0.0:0) (errno=47)
[Wed Nov 07 08:52:31.354 2012] [9260:9416] [error] ajp_send_request::jk_ajp_common.c (1629): (node1) connecting to backend failed. Tomcat is probably not started or is listening on the wrong port (errno=47)
[Wed Nov 07 08:52:31.355 2012] [9260:9416] [info] ajp_service::jk_ajp_common.c (2622): (node1) sending request to tomcat failed (recoverable), because of error during request sending (attempt=1)
[Wed Nov 07 08:52:31.355 2012] [9260:9416] [debug] ajp_service::jk_ajp_common.c (2471): retry 1, sleeping for 100 ms before retrying
[Wed Nov 07 08:52:31.367 2012] [9260:2860] [debug] handle_notify_event::jk_isapi_plugin.c (1909): Filter started
[Wed Nov 07 08:52:31.368 2012] [9260:2860] [debug] map_uri_to_worker_ext::jk_uri_worker_map.c (1131): Attempting to map URI '/www.siva.com/APP302/favicon.ico' from 14 maps
[Wed Nov 07 08:52:31.370 2012] [9260:2860] [debug] find_match::jk_uri_worker_map.c (945): Attempting to map context URI '/APP302/*=lb' source 'uriworkermap'
[Wed Nov 07 08:52:31.373 2012] [9260:2860] [debug] find_match::jk_uri_worker_map.c (945): Attempting to map context URI '/SIVA/*=lb' source 'uriworkermap'
[Wed Nov 07 08:52:31.376 2012] [9260:2860] [debug] find_match::jk_uri_worker_map.c (945): Attempting to map context URI '/jk-manager=jk-status' source 'uriworkermap'
[Wed Nov 07 08:52:31.377 2012] [9260:2860] [debug] find_match::jk_uri_worker_map.c (945): Attempting to map context URI '/servlets-examples/*=lb' source 'uriworkermap'
[Wed Nov 07 08:52:31.377 2012] [9260:2860] [debug] find_match::jk_uri_worker_map.c (945): Attempting to map context URI '/jsp-examples/*=lb' source 'uriworkermap'
[Wed Nov 07 08:52:31.380 2012] [9260:2860] [debug] find_match::jk_uri_worker_map.c (945): Attempting to map context URI '/APP302/*=lb' source 'uriworkermap'
[Wed Nov 07 08:52:31.380 2012] [9260:2860] [debug] find_match::jk_uri_worker_map.c (958): Found a wildchar match '/APP302/*=lb'



[Wed Nov 07 08:52:31.381 2012] [9260:2860] [debug] handle_notify_event::jk_isapi_plugin.c (1991): check if [/APP302/favicon.ico] points to the web-inf directory
[Wed Nov 07 08:52:31.381 2012] [9260:2860] [debug] handle_notify_event::jk_isapi_plugin.c (2008): [/APP302/favicon.ico] is a servlet url - should redirect to lb
[Wed Nov 07 08:52:31.382 2012] [9260:2860] [debug] handle_notify_event::jk_isapi_plugin.c (2046): fowarding escaped URI [/APP302/favicon.ico]
[Wed Nov 07 08:52:31.382 2012] [9260:2860] [debug] handle_notify_event::jk_isapi_plugin.c (2119): forwarding to : /jakarta/isapi_redirect.dll
[Wed Nov 07 08:52:31.383 2012] [9260:2860] [debug] handle_notify_event::jk_isapi_plugin.c (2121): forward URI   : TOMCATURI0000000180000000:/APP302/favicon.ico
[Wed Nov 07 08:52:31.383 2012] [9260:2860] [debug] handle_notify_event::jk_isapi_plugin.c (2126): forward worker: TOMCATWORKER0000000180000000:lb
[Wed Nov 07 08:52:31.383 2012] [9260:2860] [debug] handle_notify_event::jk_isapi_plugin.c (2128): worker index  : TOMCATWORKERIDX0000000180000000:6
[Wed Nov 07 08:52:31.384 2012] [9260:2860] [debug] init_ws_service::jk_isapi_plugin.c (3158): Reading extension header HTTP_TOMCATWORKER0000000180000000: lb
[Wed Nov 07 08:52:31.385 2012] [9260:2860] [debug] init_ws_service::jk_isapi_plugin.c (3159): Reading extension header HTTP_TOMCATWORKERIDX0000000180000000: 6
[Wed Nov 07 08:52:31.385 2012] [9260:2860] [debug] init_ws_service::jk_isapi_plugin.c (3160): Reading extension header HTTP_TOMCATURI0000000180000000: /APP302/favicon.ico
[Wed Nov 07 08:52:31.385 2012] [9260:2860] [debug] init_ws_service::jk_isapi_plugin.c (3161): Reading extension header HTTP_TOMCATQUERY0000000180000000: (null)
[Wed Nov 07 08:52:31.386 2012] [9260:2860] [debug] init_ws_service::jk_isapi_plugin.c (3221): Applying service extensions
[Wed Nov 07 08:52:31.386 2012] [9260:2860] [debug] init_ws_service::jk_isapi_plugin.c (3446): Forwarding request header Connection : keep-alive
[Wed Nov 07 08:52:31.387 2012] [9260:2860] [debug] init_ws_service::jk_isapi_plugin.c (3446): Forwarding request header Content-Length : 0
[Wed Nov 07 08:52:31.387 2012] [9260:2860] [debug] init_ws_service::jk_isapi_plugin.c (3446): Forwarding request header Accept : */*
[Wed Nov 07 08:52:31.388 2012] [9260:2860] [debug] init_ws_service::jk_isapi_plugin.c (3446): Forwarding request header Accept-Charset : ISO-8859-1,utf-8;q=0.7,*;q=0.3
[Wed Nov 07 08:52:31.388 2012] [9260:2860] [debug] init_ws_service::jk_isapi_plugin.c (3446): Forwarding request header Accept-Encoding : gzip,deflate,sdch
[Wed Nov 07 08:52:31.388 2012] [9260:2860] [debug] init_ws_service::jk_isapi_plugin.c (3446): Forwarding request header Accept-Language : en-US,en;q=0.8
[Wed Nov 07 08:52:31.389 2012] [9260:2860] [debug] init_ws_service::jk_isapi_plugin.c (3446): Forwarding request header Cookie : JSESSIONID=3DB334C95F67416A3AEEF70C68D8BD0A
[Wed Nov 07 08:52:31.389 2012] [9260:2860] [debug] init_ws_service::jk_isapi_plugin.c (3446): Forwarding request header Host : www.siva.com
[Wed Nov 07 08:52:31.390 2012] [9260:2860] [debug] init_ws_service::jk_isapi_plugin.c (3446): Forwarding request header User-Agent : Mozilla/5.0 (Windows NT 5.1) AppleWebKit/537.4 (KHTML, like Gecko) Chrome/22.0.1229.94 Safari/537.4
[Wed Nov 07 08:52:31.390 2012] [9260:2860] [debug] init_ws_service::jk_isapi_plugin.c (3475): Service protocol=HTTP/1.1 method=GET host=10.246.0.3 addr=10.246.0.3 name=www.siva.com port=443 auth= user= uri=/APP302/favicon.ico
[Wed Nov 07 08:52:31.390 2012] [9260:2860] [debug] init_ws_service::jk_isapi_plugin.c (3487): Service request headers=9 attributes=9 chunked=no content-length=0 available=0
[Wed Nov 07 08:52:31.391 2012] [9260:2860] [debug] wc_get_worker_for_name::jk_worker.c (115): found a worker lb
[Wed Nov 07 08:52:31.391 2012] [9260:2860] [debug] HttpExtensionProc::jk_isapi_plugin.c (2298): got a worker for name lb
[Wed Nov 07 08:52:31.391 2012] [9260:2860] [debug] get_sessionid::jk_lb_worker.c (542): Detected session identifier [3DB334C95F67416A3AEEF70C68D8BD0A].
[Wed Nov 07 08:52:31.392 2012] [9260:2860] [debug] service::jk_lb_worker.c (1203): service sticky_session=1 id='3DB334C95F67416A3AEEF70C68D8BD0A'
[Wed Nov 07 08:52:31.392 2012] [9260:2860] [debug] service::jk_lb_worker.c (1248): service worker=node1 route=node1
[Wed Nov 07 08:52:31.392 2012] [9260:2860] [debug] ajp_get_endpoint::jk_ajp_common.c (3154): acquired connection pool slot=1 after 0 retries
[Wed Nov 07 08:52:31.393 2012] [9260:2860] [debug] ajp_marshal_into_msgb::jk_ajp_common.c (626): ajp marshaling done
[Wed Nov 07 08:52:31.393 2012] [9260:2860] [debug] ajp_service::jk_ajp_common.c (2449): processing node1 with 2 retries
[Wed Nov 07 08:52:31.394 2012] [9260:2860] [debug] ajp_send_request::jk_ajp_common.c (1623): (node1) all endpoints are disconnected.
[Wed Nov 07 08:52:31.394 2012] [9260:2860] [debug] jk_open_socket::jk_connect.c (485): socket TCP_NODELAY set to On
[Wed Nov 07 08:52:31.395 2012] [9260:2860] [debug] jk_open_socket::jk_connect.c (609): trying to connect socket 744 to 0.0.0.0:0
[Wed Nov 07 08:52:31.395 2012] [9260:2860] [info] jk_open_socket::jk_connect.c (627): connect to 0.0.0.0:0 failed (errno=47)
[Wed Nov 07 08:52:31.395 2012] [9260:2860] [info] ajp_connect_to_endpoint::jk_ajp_common.c (995): Failed opening socket to (0.0.0.0:0) (errno=47)
[Wed Nov 07 08:52:31.396 2012] [9260:2860] [error] ajp_send_request::jk_ajp_common.c (1629): (node1) connecting to backend failed. Tomcat is probably not started or is listening on the wrong port (errno=47)
[Wed Nov 07 08:52:31.396 2012] [9260:2860] [info] ajp_service::jk_ajp_common.c (2622): (node1) sending request to tomcat failed (recoverable), because of error during request sending (attempt=1)
[Wed Nov 07 08:52:31.396 2012] [9260:2860] [debug] ajp_service::jk_ajp_common.c (2471): retry 1, sleeping for 100 ms before retrying
[Wed Nov 07 08:52:31.456 2012] [9260:9416] [debug] ajp_send_request::jk_ajp_common.c (1623): (node1) all endpoints are disconnected.
[Wed Nov 07 08:52:31.456 2012] [11192:10828] [info] TerminateFilter::jk_isapi_plugin.c (2384): Jakarta/ISAPI/isapi_redirector/1.2.36 stopping
[Wed Nov 07 08:52:31.457 2012] [9260:9416] [debug] jk_open_socket::jk_connect.c (485): socket TCP_NODELAY set to On
[Wed Nov 07 08:52:31.457 2012] [11192:10828] [debug] close_workers::jk_worker.c (217): close_workers will destroy worker lb
[Wed Nov 07 08:52:31.458 2012] [9260:9416] [debug] jk_open_socket::jk_connect.c (609): trying to connect socket 744 to 0.0.0.0:0
[Wed Nov 07 08:52:31.458 2012] [11192:10828] [debug] ajp_destroy::jk_ajp_common.c (3032): up to 250 endpoints to close
[Wed Nov 07 08:52:31.458 2012] [9260:9416] [info] jk_open_socket::jk_connect.c (627): connect to 0.0.0.0:0 failed (errno=47)
[Wed Nov 07 08:52:31.458 2012] [11192:10828] [debug] ajp_close_endpoint::jk_ajp_common.c (804): (node1) closing endpoint with socket 732
[Wed Nov 07 08:52:31.459 2012] [9260:9416] [info] ajp_connect_to_endpoint::jk_ajp_common.c (995): Failed opening socket to (0.0.0.0:0) (errno=47)
[Wed Nov 07 08:52:31.459 2012] [11192:10828] [debug] jk_shutdown_socket::jk_connect.c (732): About to shutdown socket 732 [127.0.0.1:57237 -> 127.0.0.1:8009]
[Wed Nov 07 08:52:31.460 2012] [9260:9416] [error] ajp_send_request::jk_ajp_common.c (1629): (node1) connecting to backend failed. Tomcat is probably not started or is listening on the wrong port (errno=47)
[Wed Nov 07 08:52:31.460 2012] [9260:9416] [info] ajp_service::jk_ajp_common.c (2622): (node1) sending request to tomcat failed (recoverable), because of error during request sending (attempt=2)
[Wed Nov 07 08:52:31.460 2012] [9260:9416] [error] ajp_service::jk_ajp_common.c (2642): (node1) connecting to tomcat failed.
[Wed Nov 07 08:52:31.460 2012] [11192:10828] [debug] jk_shutdown_socket::jk_connect.c (803): shutting down the read side of socket 732 [127.0.0.1:57237 -> 127.0.0.1:8009]
[Wed Nov 07 08:52:31.461 2012] [9260:9416] [debug] ajp_reset_endpoint::jk_ajp_common.c (786): (node1) resetting endpoint with socket -1 (socket shutdown)
[Wed Nov 07 08:52:31.461 2012] [11192:10828] [debug] jk_shutdown_socket::jk_connect.c (814): Shutdown socket 732 [127.0.0.1:57237 -> 127.0.0.1:8009] and read 0 lingering bytes in 0 sec.
[Wed Nov 07 08:52:31.462 2012] [9260:9416] [debug] ajp_done::jk_ajp_common.c (3085): recycling connection pool for worker node1 and socket -1
[Wed Nov 07 08:52:31.462 2012] [11192:10828] [debug] ajp_close_endpoint::jk_ajp_common.c (804): (node1) closing endpoint with socket 756
[Wed Nov 07 08:52:31.462 2012] [9260:9416] [info] service::jk_lb_worker.c (1480): service failed, worker node1 is in local error state
[Wed Nov 07 08:52:31.463 2012] [11192:10828] [debug] jk_shutdown_socket::jk_connect.c (732): About to shutdown socket 756 [127.0.0.1:57239 -> 127.0.0.1:8009]
[Wed Nov 07 08:52:31.463 2012] [9260:9416] [debug] service::jk_lb_worker.c (1491): recoverable error... will try to recover on other worker
[Wed Nov 07 08:52:31.464 2012] [9260:9416] [debug] service::jk_lb_worker.c (1215): retry 1, sleeping for 100 ms before retrying
[Wed Nov 07 08:52:31.463 2012] [11192:10828] [debug] jk_shutdown_socket::jk_connect.c (803): shutting down the read side of socket 756 [127.0.0.1:57239 -> 127.0.0.1:8009]
[Wed Nov 07 08:52:31.464 2012] [11192:10828] [debug] jk_shutdown_socket::jk_connect.c (814): Shutdown socket 756 [127.0.0.1:57239 -> 127.0.0.1:8009] and read 0 lingering bytes in 0 sec.
[Wed Nov 07 08:52:31.465 2012] [11192:10828] [debug] ajp_close_endpoint::jk_ajp_common.c (804): (node1) closing endpoint with socket 792
[Wed Nov 07 08:52:31.465 2012] [11192:10828] [debug] jk_shutdown_socket::jk_connect.c (732): About to shutdown socket 792 [127.0.0.1:57242 -> 127.0.0.1:8009]
[Wed Nov 07 08:52:31.465 2012] [11192:10828] [debug] jk_shutdown_socket::jk_connect.c (803): shutting down the read side of socket 792 [127.0.0.1:57242 -> 127.0.0.1:8009]
[Wed Nov 07 08:52:31.466 2012] [11192:10828] [debug] jk_shutdown_socket::jk_connect.c (814): Shutdown socket 792 [127.0.0.1:57242 -> 127.0.0.1:8009] and read 0 lingering bytes in 0 sec.
[Wed Nov 07 08:52:31.466 2012] [11192:10828] [debug] ajp_close_endpoint::jk_ajp_common.c (804): (node1) closing endpoint with socket 552
[Wed Nov 07 08:52:31.467 2012] [11192:10828] [debug] jk_shutdown_socket::jk_connect.c (732): About to shutdown socket 552 [127.0.0.1:57247 -> 127.0.0.1:8009]
[Wed Nov 07 08:52:31.467 2012] [11192:10828] [debug] jk_shutdown_socket::jk_connect.c (803): shutting down the read side of socket 552 [127.0.0.1:57247 -> 127.0.0.1:8009]
[Wed Nov 07 08:52:31.468 2012] [11192:10828] [debug] jk_shutdown_socket::jk_connect.c (814): Shutdown socket 552 [127.0.0.1:57247 -> 127.0.0.1:8009] and read 0 lingering bytes in 0 sec.
[Wed Nov 07 08:52:31.468 2012] [11192:10828] [debug] ajp_close_endpoint::jk_ajp_common.c (804): (node1) closing endpoint with socket 804
[Wed Nov 07 08:52:31.468 2012] [11192:10828] [debug] jk_shutdown_socket::jk_connect.c (732): About to shutdown socket 804 [127.0.0.1:57275 -> 127.0.0.1:8009]
[Wed Nov 07 08:52:31.469 2012] [11192:10828] [debug] jk_shutdown_socket::jk_connect.c (803): shutting down the read side of socket 804 [127.0.0.1:57275 -> 127.0.0.1:8009]
[Wed Nov 07 08:52:31.469 2012] [11192:10828] [debug] jk_shutdown_socket::jk_connect.c (814): Shutdown socket 804 [127.0.0.1:57275 -> 127.0.0.1:8009] and read 0 lingering bytes in 0 sec.
[Wed Nov 07 08:52:31.469 2012] [11192:10828] [debug] ajp_close_endpoint::jk_ajp_common.c (804): (node1) closing endpoint with socket 824
[Wed Nov 07 08:52:31.470 2012] [11192:10828] [debug] jk_shutdown_socket::jk_connect.c (732): About to shutdown socket 824 [127.0.0.1:57283 -> 127.0.0.1:8009]
[Wed Nov 07 08:52:31.471 2012] [11192:10828] [debug] jk_shutdown_socket::jk_connect.c (803): shutting down the read side of socket 824 [127.0.0.1:57283 -> 127.0.0.1:8009]
[Wed Nov 07 08:52:31.472 2012] [11192:10828] [debug] jk_shutdown_socket::jk_connect.c (814): Shutdown socket 824 [127.0.0.1:57283 -> 127.0.0.1:8009] and read 0 lingering bytes in 0 sec.
[Wed Nov 07 08:52:31.472 2012] [11192:10828] [debug] ajp_close_endpoint::jk_ajp_common.c (804): (node1) closing endpoint with socket -1 (socket shutdown)

[Wed Nov 07 08:52:31.497 2012] [9260:2860] [debug] ajp_send_request::jk_ajp_common.c (1623): (node1) all endpoints are disconnected.

[Wed Nov 07 08:52:31.501 2012] [9260:2860] [error] ajp_service::jk_ajp_common.c (2642): (node1) connecting to tomcat failed.


[Wed Nov 07 08:52:39.177 2012] [9260:9416] [debug] jk_open_socket::jk_connect.c (485): socket TCP_NODELAY set to On
[Wed Nov 07 08:52:39.177 2012] [9260:9416] [debug] jk_open_socket::jk_connect.c (609): trying to connect socket 736 to 0.0.0.0:0
[Wed Nov 07 08:52:39.178 2012] [9260:9416] [info] jk_open_socket::jk_connect.c (627): connect to 0.0.0.0:0 failed (errno=47)
[Wed Nov 07 08:52:39.178 2012] [9260:9416] [info] ajp_connect_to_endpoint::jk_ajp_common.c (995): Failed opening socket to (0.0.0.0:0) (errno=47)
[Wed Nov 07 08:52:39.179 2012] [9260:9416] [error] ajp_send_request::jk_ajp_common.c (1629): (node1) connecting to backend failed. Tomcat is probably not started or is listening on the wrong port (errno=47)
[Wed Nov 07 08:52:39.179 2012] [9260:9416] [info] ajp_service::jk_ajp_common.c (2622): (node1) sending request to tomcat failed (recoverable), because of error during request sending (attempt=2)
[Wed Nov 07 08:52:39.180 2012] [9260:9416] [error] ajp_service::jk_ajp_common.c (2642): (node1) connecting to tomcat failed.
[Wed Nov 07 08:52:39.180 2012] [9260:9416] [debug] ajp_reset_endpoint::jk_ajp_common.c (786): (node1) resetting endpoint with socket -1 (socket shutdown)
[Wed Nov 07 08:52:39.181 2012] [9260:9416] [debug] ajp_done::jk_ajp_common.c (3085): recycling connection pool for worker node1 and socket -1
[Wed Nov 07 08:52:39.181 2012] [9260:9416] [debug] service::jk_lb_worker.c (1466): worker node1 escalating local error to global error
[Wed Nov 07 08:52:39.182 2012] [9260:9416] [info] service::jk_lb_worker.c (1480): service failed, worker node1 is in error state
[Wed Nov 07 08:52:39.182 2012] [9260:9416] [debug] service::jk_lb_worker.c (1491): recoverable error... will try to recover on other worker
[Wed Nov 07 08:52:39.183 2012] [9260:9416] [debug] service::jk_lb_worker.c (1215): retry 1, sleeping for 100 ms before retrying
[Wed Nov 07 08:52:39.283 2012] [9260:9416] [info] service::jk_lb_worker.c (1549): All tomcat instances failed, no more workers left (attempt=0, retry=1)
[Wed Nov 07 08:52:39.284 2012] [9260:9416] [info] service::jk_lb_worker.c (1560): All tomcat instances are busy or in error state
[Wed Nov 07 08:52:39.286 2012] [9260:9416] [error] service::jk_lb_worker.c (1565): All tomcat instances failed, no more workers left
[Wed Nov 07 08:52:39.287 2012] [9260:9416] [error] HttpExtensionProc::jk_isapi_plugin.c (2328): service() failed with http error 503


Please help me on this.
Comment 1 sivaram 2012-11-12 10:31:30 UTC
We are facing this issue when the IIS recycle happens. This is a show stopper for our Website.
Comment 2 Mladen Turk 2012-11-12 14:05:02 UTC
Could you post your workers.properties file.
... and is it 1.2.36 or 1.2.37? If it's 1.2.36 use 1.2.37
Comment 3 sivaram 2012-11-13 06:26:42 UTC
############################################
isapi_redirect.dll file version - 1.2.36
############################################
worker.properties.minimal file
############################################
# The workers that jk should create and work with
#

worker.list=lb,jk-status

#
# Defining a worker named node1 and of type ajp13
# Note that the name and the type do not have to match.
#
worker.node1.type=ajp13
worker.node1.host=localhost
worker.node1.port=8009

#
# Defining a load balancer
# 

worker.lb.type=lb
worker.lb.balance_workers=node1

#
# Define status worker
#

worker.jk-status.type=status
############################################
worker.properties file.
############################################
# Define two status worker:
# - jk-status for read-only use
# - jk-manager for read/write use
worker.list=jk-status
worker.jk-status.type=status
worker.jk-status.read_only=true

worker.list=jk-manager
worker.jk-manager.type=status

# We define a load balancer worker
# with name "balancer"
worker.list=balancer
worker.balancer.type=lb
# error_escalation_time: seconds, default = recover_time/2 (=30)
# Determines, how fast a detected error should switch from
# local error state to global error state
# Since: 1.2.28
worker.balancer.error_escalation_time=0

# - max_reply_timeouts: number, default=0
#   If there are to many reply timeouts, a worker
#   is put into the error state, i.e. it will become
#   unavailable for all sessions residing on the respective
#   Tomcat. The number of tolerated reply timeouts is
#   configured with max_reply_timeouts. The number of
#   timeouts occuring is divided by 2 once a minute and the
#   resulting counter is compared against max_reply_timeouts.
#   If you set max_reply_timeouts to N and the errors are
#   occuring equally distributed over time, you will
#   tolerate N/2 errors per minute. If they occur in a burst
#   you will tolerate N errors.
#   Since: 1.2.24
worker.balancer.max_reply_timeouts=10



# Now we add members to the load balancer
# First member is "node1", most
# attributes are inherited from the
# template "worker.template".
worker.balancer.balance_workers=node1
worker.node1.reference=worker.template
worker.node1.host=localhost
worker.node1.port=8109
# Activation allows to configure
# whether this node should actually be used
# A: active (use node fully)
# D: disabled (only use, if sticky session needs this node)
# S: stopped (do not use)
#   Since: 1.2.19
worker.node1.activation=A

# Second member is "node2", most
# attributes are inherited from the
# template "worker.template".
worker.balancer.balance_workers=node2
worker.node2.reference=worker.template
worker.node2.host=localhost
worker.node2.port=8209
# Activation allows to configure
# whether this node should actually be used
# A: active (use node fully)
# D: disabled (only use, if sticky session needs this node)
# S: stopped (do not use)
#   Since: 1.2.19
worker.node2.activation=A

# Finally we put the parameters
# which should apply to all our ajp13
# workers into the referenced template
# - Type is ajp13
worker.template.type=ajp13

# - socket_connect_timeout: milliseconds, default=0
#   Since: 1.2.27
worker.template.socket_connect_timeout=5000

# - socket_keepalive: boolean, default=false
#   Should we send TCP keepalive packets
#   when connection is idle (socket option)?
worker.template.socket_keepalive=true

# - ping_mode: Character, default=none
#   When should we use cping/cpong connection probing?
#   C = directly after establishing a new connection
#   P = directly before sending each request
#   I = in regular intervals for idle connections
#       using the watchdog thread
#   A = all of the above
#   Since: 1.2.27
worker.template.ping_mode=A

# - ping_timeout: milliseconds, default=10000
#   Wait timeout for cpong after cping
#   Can be overwritten for modes C and P
#   Using connect_timeout and prepost_timeout.
#   Since: 1.2.27
worker.template.ping_timeout=10000

# - connection_pool_minsize: number, default=connection_pool_size
#   Lower pool size when shrinking pool due
#   to idle connections
#   We want all connections to be closed when
#   idle for a long time in order to prevent
#   firewall problems.
#   Since: 1.2.16
worker.template.connection_pool_minsize=0

# - connection_pool_timeout: seconds, default=0
#   Idle time, before a connection is eligible
#   for being closed (pool shrinking).
#   This should be the same value as connectionTimeout
#   in the Tomcat AJP connector, but there it is
#   milliseconds, here seconds.
worker.template.connection_pool_timeout=600

# - reply_timeout: milliseconds, default=0
#   Any pause longer than this timeout during waiting
#   for a part of the reply will abort handling the request
#   in mod_jk. The request will proceed running in
#   Tomcat, but the web server resources will be freed
#   and an error is send to the client.
#   For individual requests, the timeout can be overwritten
#   by the Apache environment variable JK_REPLY_TIMEOUT.
#   JK_REPLY_TIMEOUT since: 1.2.27
worker.template.reply_timeout=300000

# - recovery_options: number, default=0
#   Bit mask to configure, if a request, which was send
#   to a backend successfully, should be retried on another backend
#   in case there's a problem with the response.
#   Value "3" disables retries, whenever a part of the request was
#   successfully send to the backend.
worker.template.recovery_options=3




(In reply to comment #2)
> Could you post your workers.properties file.
> ... and is it 1.2.36 or 1.2.37? If it's 1.2.36 use 1.2.37
Comment 4 Mladen Turk 2012-11-13 06:45:19 UTC
(In reply to comment #3)
> 
> worker.list=lb,jk-status
...
> worker.list=jk-status
...
> worker.list=jk-manager
...
> worker.list=balancer
...

Wow, what a pile of trash.
So how many workers you actually have and for what?
I'll just close this case, and you can seek guidance on users list.
Comment 5 sivaram 2012-11-13 07:14:52 UTC
Hi,
Sorry I posted the incorrect data in my previous comment.
We have configured worker.properties.minimal file and the details are below.
We are using ISAPI redirector file version - 1.2.36

############################################
worker.properties.minimal file
############################################
# The workers that jk should create and work with
#

worker.list=lb,jk-status

#
# Defining a worker named node1 and of type ajp13
# Note that the name and the type do not have to match.
#
worker.node1.type=ajp13
worker.node1.host=localhost
worker.node1.port=8009

#
# Defining a load balancer
# 

worker.lb.type=lb
worker.lb.balance_workers=node1

#
# Define status worker
#

worker.jk-status.type=status
Comment 6 Mladen Turk 2012-11-13 07:50:21 UTC
Like said, please try with latest (1.2.37)
It has fixed bug in shared memory address sequence which should relate to the bug you are seeing.
Comment 7 sivaram 2012-11-13 07:53:21 UTC
Thank You, I will try to use the latest version of Jakarta plugin and let you know the updates.
Comment 8 Rainer Jung 2015-01-07 10:29:29 UTC
Does this problem still exist? No user feedback since 2 years.
Comment 9 Rainer Jung 2015-09-09 19:30:29 UTC
I can't see any problems with app pool recycling and the redirector for current versions (1.2.42-dev on Windows 7 with IIS 7.5. Furthermore no feedback on the questions for several months, so closing as INVALID.