Hi,


I observe in mod_jk's log errors:
[error] ajp_get_reply::jk_ajp_common.c (1566): (ajp13w) Tomcat is down
or refused connection. No response has been sent to the client (yet)

In the rush hours (20-30 requests/second) up to several entries per hour.
Sometimes it's followed by:
[error] ajp_service::jk_ajp_common.c (1928): (ajp13w) Connecting to
tomcat failed. Tomcat is probably not started or is listening on the
wrong port
or
[error] ajp_connection_tcp_get_message::jk_ajp_common.c (948): (ajp13w)
can't receive the response message from tomcat, network problems or
tomcat is down (127.0.0.1:8009), err=-104

but usually it is covered by another retries. It's corresponding to
exception in tomcat:
ERROR [org.apache.jk.common.HandlerRequest] Error decoding request
java.net.SocketTimeoutException: Read timed out

*Note* Post is quite long because of info from logs. To get know what it
is about it is enough to read descriptions next to numbers.


I increased logs granularity (mod_jk and tomcat + tcpdump) and in a few
checked issues it looks like:

*1*. mod_jk talks with tomcat and some request is serviced.

(...)
[11:10:30] [debug] ajp_process_callback::jk_ajp_common.c (1491): AJP13
protocol: Reuse is OK
[debug] ajp_done::jk_ajp_common.c (2258): recycling connection pool
slot=0 for worker ajp13w
[debug] jk_handler::mod_jk.c (2126): Service finished with status=200
for worker=wlb

*2*. A few seconds later thread is used again by an another request.

[11:10:32] [debug] wc_get_worker_for_name::jk_worker.c (114): found a
worker wlb
[debug] wc_get_name_for_type::jk_worker.c (290): Found worker type 'lb'
[debug] init_ws_service::mod_jk.c (584): Service protocol=HTTP/1.1
method=POST (...)
[debug] service::jk_lb_worker.c (840): service sticky_session=1
id='8A49C0D934C8A115342BA5CBFC79C434'
[debug] service::jk_lb_worker.c (860): service worker=ajp13w route=ajp13w
[debug] ajp_get_endpoint::jk_ajp_common.c (2315): acquired connection
pool slot=0
[debug] ajp_marshal_into_msgb::jk_ajp_common.c (548): ajp marshaling done
[debug] ajp_service::jk_ajp_common.c (1771): processing ajp13w with 2
retries
[debug] ajp_connection_tcp_send_message::jk_ajp_common.c (893): sending
to ajp13 pos=4 len=307 max=8192
(...) [header is sent and it is received by tomcat]

*3*.
a) mod_jk tries to send body:

[11:10:32] [debug] ajp_send_request::jk_ajp_common.c (1273): request
body to send 646 - request body to resend 0

b) tomcat is waiting for it:
DEBUG [org.apache.jk.common.ChannelSocket] Call next 0
org.apache.jk.common.HandlerRequest@(protected)
DEBUG [org.apache.jk.common.HandlerRequest] Handling 2
DEBUG [org.apache.jk.common.ChannelSocket] receive()

*4*. 5 seconds later (connector timeout is 5000ms) tomcat throws exception:
[11:10:37] ERROR [org.apache.jk.common.HandlerRequest] Error decoding
request
java.net.SocketTimeoutException: Read timed out
and resets connection (regarding to tcpdump log)

*5*. A few more seconds later (e.g. 8 from point 3) mod_jk starts
sending a body:
[11:10:40] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c
(893): sending to ajp13 pos=4 len=652 max=8192
[debug] ajp_connection_tcp_send_message::jk_ajp_common.c (893): 0000
12 34 02 88 02 86 3C 3F (...) [body's dump]

*6*. Unfortunately connection was already reseted by tomcat and mod_jk
got info about that:
[11:10:40] [info] ajp_connection_tcp_get_message::jk_ajp_common.c
(942): (ajp13w) Tomcat has forced a connection close for socket 28
[error] ajp_get_reply::jk_ajp_common.c (1566): (ajp13w) Tomcat is down
or refused connection. No response has been sent to the client (yet)
[info] ajp_service::jk_ajp_common.c (1877): (ajp13w) receiving from
tomcat failed, recoverable operation attempt=0

*7*. mod_jk tries to do send request again to tomcat:
[11:10:40] [info] ajp_service::jk_ajp_common.c (1916): (ajp13w) sending
request to tomcat failed, recoverable operation attempt=1
[debug] jk_open_socket::jk_connect.c (335): socket TCP_NODELAY set to On
[debug] jk_open_socket::jk_connect.c (433): trying to connect socket 28
to 127.0.0.1:8009
[debug] jk_open_socket::jk_connect.c (459): socket 28 connected to
127.0.0.1:8009
[debug] ajp_connect_to_endpoint::jk_ajp_common.c (847): Connected socket
28 to (127.0.0.1:8009)
[debug] ajp_connection_tcp_send_message::jk_ajp_common.c (893): sending
to ajp13 pos=4 len=307 max=8192

Usually (but not always) it is able to do that without errors.

I sniffed into mod_jk source code, but I haven't found a place where it
can stuck.


*Question*
What can be delay (about 8 seconds) in mod_jk between sending HTTP
header and HTTP content caused by?


I use Apache 2.0.52 (with MPM prefork), mod_jk 1.2.20, JBoss 3.2.5 with
Tomcat 5.0 (probably 5.0.27) and Red Hat Enterprise Linux ES 4.

mod_jk configuration is quite simple, without load balancing (and wasn't
changed for years).

<workers.properties>
workers.tomcat_home=/jboss/deploy/jbossweb-tomcat50.sar
workers.java_home=/jboss/java
ps=/

worker.list=wlb,jkstatus

worker.ajp13w.type=ajp13
worker.ajp13w.host=localhost
worker.ajp13w.port=8009

worker.wlb.type=lb
worker.wlb.balance_workers=ajp13w
</workers.properties>

The only change in mod_jk config was:
JkShmSize 1024k

<servel.xml>
    <Connector port="8009" address="127.0.0.1"
    minProcessors="5" maxProcessors="100"
    enableLookups="false" acceptCount="100" debug="0"
    connectionTimeout="5000" useURIValidationHack="false"
    protocol="AJP/1.3"/>
</servel.xml>


Thanks for your advice
Marcin


---------------------------------------------------------------------
To start a new topic, e-mail: users@(protected)
To unsubscribe, e-mail: users-unsubscribe@(protected)
For additional commands, e-mail: users-help@(protected)