From users-return-205606-apmail-tomcat-users-archive=tomcat.apache.org@tomcat.apache.org Fri Dec 04 20:25:14 2009 Return-Path: Delivered-To: apmail-tomcat-users-archive@www.apache.org Received: (qmail 33321 invoked from network); 4 Dec 2009 20:25:13 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (140.211.11.3) by minotaur.apache.org with SMTP; 4 Dec 2009 20:25:13 -0000 Received: (qmail 82738 invoked by uid 500); 4 Dec 2009 20:25:08 -0000 Delivered-To: apmail-tomcat-users-archive@tomcat.apache.org Received: (qmail 82677 invoked by uid 500); 4 Dec 2009 20:25:08 -0000 Mailing-List: contact users-help@tomcat.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: "Tomcat Users List" Delivered-To: mailing list users@tomcat.apache.org Received: (qmail 82666 invoked by uid 99); 4 Dec 2009 20:25:08 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 04 Dec 2009 20:25:08 +0000 X-ASF-Spam-Status: No, hits=-0.0 required=10.0 tests=SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (nike.apache.org: domain of group.vas@gmail.com designates 209.85.223.199 as permitted sender) Received: from [209.85.223.199] (HELO mail-iw0-f199.google.com) (209.85.223.199) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 04 Dec 2009 20:25:00 +0000 Received: by iwn37 with SMTP id 37so2155143iwn.30 for ; Fri, 04 Dec 2009 12:24:39 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=gamma; h=domainkey-signature:mime-version:received:in-reply-to:references :date:message-id:subject:from:to:cc:content-type :content-transfer-encoding; bh=s9+zFkQU6DYO7Up6oBImjYOEzK8JcdbhxzSTIWGF2oM=; b=ENfuVchnEHfsNxiiCKojM6XuInR4R48FTw/jpfwTUMwC8nIrtnxMw2Sh/Qx6jLZWOt h+YLVn0AjhLNUJgkJMD7v5qkjUpZakzBegTCiDvbCYiVx9JHSh1mTfBh/8nAnTrB4mfr WqI59sauPVGR0TB79wnpY07HIHHINL/Ag7DKA= DomainKey-Signature: a=rsa-sha1; c=nofws; d=gmail.com; s=gamma; h=mime-version:in-reply-to:references:date:message-id:subject:from:to :cc:content-type:content-transfer-encoding; b=g3+vhDWGm00xaFIsxJrq7Vu5bdCCShct1OJsJhjPefzwRCh22PfpmCWTQ/m+CYO1xp uzeUaBiOm/iTI9A1TQ2Ytsp8KH4YEK3Hfgun7FZKcQ8DOHBrZyzYyC1vDZRZzKsMOyHU pDIh2Vv3D5kaf3iZVvDEMzRfSKLx4OLNg37e0= MIME-Version: 1.0 Received: by 10.231.48.210 with SMTP id s18mr4529712ibf.3.1259958278904; Fri, 04 Dec 2009 12:24:38 -0800 (PST) In-Reply-To: <4B18CC28.7060801@kippdata.de> References: <4B15358C.3050305@ice-sa.com> <4B15CD1B.2020609@christopherschultz.net> <4B1641DB.6080506@ice-sa.com> <4B16E699.7030300@ice-sa.com> <4B18CC28.7060801@kippdata.de> Date: Fri, 4 Dec 2009 12:24:38 -0800 Message-ID: Subject: Re: Debugging tomcat<->apache(mod_jk) bridge From: groupalias v To: Rainer Jung Cc: Tomcat Users List Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: quoted-printable X-Virus-Checked: Checked by ClamAV on apache.org 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 wrot= e: > 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) =A0-- > > 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/*=3DA' 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/*=3DA' > > 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=3DA >> r->proxyreq=3D0 >> [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=3DHTTP/1.1 method=3DGE= T >> ssl=3Dfalse host=3D(null) addr=3DX.X.X.X name=3Dwww.example.com port=3D8= 0 >> auth=3D(null) user=3D(null) laddr=3D192.168.2.2 raddr=3DX.X.X.X >> uri=3D/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=3D0 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=3D17 >> [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=3D4 len=3D450 max=3D8192 > > 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=3D0 len=3D19 max=3D8192 > > 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 =A0 =A004 0= 1 >> 90 00 0B 42 61 64 20 52 65 71 75 65 73 74 =A0- .....Bad.Request > > And the response says status =3D 0x0190 =3D 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 =A0 =A000 0= 0 >> 00 00 00 00 00 00 00 00 00 00 00 00 00 00 =A0- ................ >> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug] >> ajp_unmarshal_response::jk_ajp_common.c (660): status =3D 400 >> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug] >> ajp_unmarshal_response::jk_ajp_common.c (667): Number of headers is =3D >> 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=3D0 len=3D2 max=3D8192 >> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug] >> ajp_connection_tcp_get_message::jk_ajp_common.c (1259): 0000 =A0 =A005 0= 1 >> 00 00 00 00 00 00 00 00 00 00 00 00 00 00 =A0- ................ >> [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 =3D 17 >> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug] >> ajp_done::jk_ajp_common.c (2905): recycling connection pool slot=3D0 for >> worker A >> [Tue Dec 01 14:13:02 2009] [7267:3083376384] [debug] >> jk_handler::mod_jk.c (2599): Service finished with status=3D400 for >> worker=3DA > > 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