tomcat-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From groupalias v <group....@gmail.com>
Subject Re: Debugging tomcat<->apache(mod_jk) bridge
Date Fri, 04 Dec 2009 20:24:38 GMT
I too saw that mod_jk thinks it is talking to tomcat. But I do not see
any logs in tomcat to indicate that.

Also with the same parameters mod_proxy_ajp is able to fetch my page.
Could be some nasty machine specific thing.

On Fri, Dec 4, 2009 at 12:45 AM, Rainer Jung <rainer.jung@kippdata.de> wrote:
> On 04.12.2009 09:31, groupalias v wrote:
>>
>> Also as I promised here is the mod_jk.log after running it in debug
>> mode ( please note that I am not looking for an answer but would still
>> be looking to figure out what's happening with mod_jk)  --
>
> Skipping init messages ...
>
>> [Tue Dec 01 14:13:01 2009] [7270:3083376384] [debug]
>> jk_child_init::mod_jk.c (3068): Initialized mod_jk/1.2.28
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>> map_uri_to_worker_ext::jk_uri_worker_map.c (1036): Attempting to map
>> URI '/test/index.jsp' from 1 maps
>
> That's the request ...
>
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>> find_match::jk_uri_worker_map.c (850): Attempting to map context URI
>> '/test/*=A' source 'JkMount'
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>> find_match::jk_uri_worker_map.c (863): Found a wildchar match
>> '/test/*=A'
>
> We know we have to send it via "A" ...
>
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>> jk_handler::mod_jk.c (2459): Into handler jakarta-servlet worker=A
>> r->proxyreq=0
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>> wc_get_worker_for_name::jk_worker.c (116): found a worker A
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>
> OK, there is a worker named "A" ...
>
>> wc_maintain::jk_worker.c (339): Maintaining worker A
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>> ajp_maintain::jk_ajp_common.c (3081): reached pool min size 5 from 10
>> cache slots
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>> wc_get_name_for_type::jk_worker.c (293): Found worker type 'ajp13'
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>> init_ws_service::mod_jk.c (977): Service protocol=HTTP/1.1 method=GET
>> ssl=false host=(null) addr=X.X.X.X name=www.example.com port=80
>> auth=(null) user=(null) laddr=192.168.2.2 raddr=X.X.X.X
>> uri=/test/index.jsp
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>> ajp_get_endpoint::jk_ajp_common.c (2977): acquired connection pool
>> slot=0 after 0 retries
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>> ajp_marshal_into_msgb::jk_ajp_common.c (605): ajp marshaling done
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>> ajp_service::jk_ajp_common.c (2283): processing A with 2 retries
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>> ajp_send_request::jk_ajp_common.c (1501): (A) all endpoints are
>> disconnected.
>
> We need to connect to "A" ..
>
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>> jk_open_socket::jk_connect.c (452): socket TCP_NODELAY set to On
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>> jk_open_socket::jk_connect.c (489): socket SO_KEEPALIVE set to On
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>> jk_open_socket::jk_connect.c (541): timeout 300 set for socket=17
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>> jk_open_socket::jk_connect.c (576): trying to connect socket 17 to
>> 127.0.0.1:8009
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>> jk_open_socket::jk_connect.c (602): socket 17 connected to
>> 127.0.0.1:8009
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>> ajp_connect_to_endpoint::jk_ajp_common.c (931): Connected socket 17 to
>> (127.0.0.1:8009)
>
> Connected to "A" as 127.0.0.1 on port 8009 ...
>
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>> ajp_connection_tcp_send_message::jk_ajp_common.c (1070): sending to
>> ajp13 pos=4 len=450 max=8192
>
> I'm missing the request data here? Did you remove it?
>
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>> ajp_send_request::jk_ajp_common.c (1560): (A) request body to send 0 -
>> request body to resend 0
>
> OK, we send the request.
>
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>> ajp_connection_tcp_get_message::jk_ajp_common.c (1259): received from
>> ajp13 pos=0 len=19 max=8192
>
> We got 19 Bytes of response ...
>
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>> ajp_connection_tcp_get_message::jk_ajp_common.c (1259): 0000    04 01
>> 90 00 0B 42 61 64 20 52 65 71 75 65 73 74  - .....Bad.Request
>
> And the response says status = 0x0190 = 400 with status message "Bad
> Request". So whoever or whatever produced this result claims that what it
> received was a bad request. So maybe the request has inconsistent headers
> like using content-length together with chunked encoding or similar.
>
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>> ajp_connection_tcp_get_message::jk_ajp_common.c (1259): 0010    00 00
>> 00 00 00 00 00 00 00 00 00 00 00 00 00 00  - ................
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>> ajp_unmarshal_response::jk_ajp_common.c (660): status = 400
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>> ajp_unmarshal_response::jk_ajp_common.c (667): Number of headers is =
>> 0
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>> ajp_connection_tcp_get_message::jk_ajp_common.c (1259): received from
>> ajp13 pos=0 len=2 max=8192
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>> ajp_connection_tcp_get_message::jk_ajp_common.c (1259): 0000    05 01
>> 00 00 00 00 00 00 00 00 00 00 00 00 00 00  - ................
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>> ajp_process_callback::jk_ajp_common.c (1846): AJP13 protocol: Reuse is
>> OK
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>> ajp_reset_endpoint::jk_ajp_common.c (743): (A) resetting endpoint with
>> sd = 17
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>> ajp_done::jk_ajp_common.c (2905): recycling connection pool slot=0 for
>> worker A
>> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug]
>> jk_handler::mod_jk.c (2599): Service finished with status=400 for
>> worker=A
>
> That's correct from the point of view of mod_jk. That's what the backend
> responded.
>
> Regards,
>
> Rainer
>

---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org


Mime
View raw message