Return-Path: X-Original-To: apmail-httpd-dev-archive@www.apache.org Delivered-To: apmail-httpd-dev-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id C0A0C78D2 for ; Wed, 3 Aug 2011 17:06:56 +0000 (UTC) Received: (qmail 76171 invoked by uid 500); 3 Aug 2011 17:06:55 -0000 Delivered-To: apmail-httpd-dev-archive@httpd.apache.org Received: (qmail 76003 invoked by uid 500); 3 Aug 2011 17:06:54 -0000 Mailing-List: contact dev-help@httpd.apache.org; run by ezmlm Precedence: bulk Reply-To: dev@httpd.apache.org list-help: list-unsubscribe: List-Post: List-Id: Delivered-To: mailing list dev@httpd.apache.org Received: (qmail 75995 invoked by uid 99); 3 Aug 2011 17:06:54 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 03 Aug 2011 17:06:54 +0000 X-ASF-Spam-Status: No, hits=-0.0 required=5.0 tests=MIME_QP_LONG_LINE,SPF_HELO_PASS,SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (nike.apache.org: domain of apache-lists@riggs.me designates 66.128.242.154 as permitted sender) Received: from [66.128.242.154] (HELO zion.christianserving.org) (66.128.242.154) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 03 Aug 2011 17:06:47 +0000 Received: from localhost (localhost.christianserving.org [127.0.0.1]) by zion.christianserving.org (Postfix) with ESMTP id DFEBF222524 for ; Wed, 3 Aug 2011 12:06:25 -0500 (CDT) X-Virus-Scanned: amavisd-new at christianserving.org X-Spam-Score: -5.387 X-Spam-Level: Received: from [192.168.66.17] (unknown [67.216.167.150]) by zion.christianserving.org (Postfix) with ESMTPSA for ; Wed, 3 Aug 2011 12:06:25 -0500 (CDT) Content-Type: text/plain; charset=iso-8859-1 Mime-Version: 1.0 (Apple Message framework v1244.3) Subject: Re: mod_proxy_ajp: ignoring flush before headers (again) From: Jim Riggs In-Reply-To: Date: Wed, 3 Aug 2011 12:06:24 -0500 Content-Transfer-Encoding: quoted-printable Message-Id: <69AF27C7-E996-455B-A012-6821A5050311@riggs.me> References: <1B34CC00-2633-4871-ADBE-EA12FBBDB32E@riggs.me> <70E858A5-B4C5-47A4-B463-65E53DFBDFEC@riggs.me> To: dev@httpd.apache.org X-Mailer: Apple Mail (2.1244.3) X-Virus-Checked: Checked by ClamAV on apache.org X-Old-Spam-Flag: NO X-Old-Spam-Status: No, score=-5.387 tagged_above=-9999 required=6 tests=[ALL_TRUSTED=-1.8, AWL=-2.384, BAYES_00=-2.599, MIME_QP_LONG_LINE=1.396] autolearn=no https://issues.apache.org/bugzilla/show_bug.cgi?id=3D51608 Thank you for your help and quick fix, R=FCdiger!! On Aug 3, 2011, at 10:09 AM, Pl=FCm, R=FCdiger, VF-Group wrote: > Thanks for testing. Committed to trunk as r1153531. > A bug report mentioning the trunk revision could be handy as a = backport tracker for 2.2.x. >=20 > Regards >=20 > R=FCdiger >=20 >> -----Original Message----- >> From: Jim Riggs=20 >> Sent: Mittwoch, 3. August 2011 16:48 >> To: dev@httpd.apache.org >> Subject: Re: mod_proxy_ajp: ignoring flush before headers (again) >>=20 >> This does appear to work. Our automated tests are running=20 >> right now. Shall I submit a but with this patch attached? >>=20 >>=20 >> On Aug 3, 2011, at 7:43 AM, Pl=FCm, R=FCdiger, VF-Group wrote: >>=20 >>> Can you please try if the following patch fixes your issue? >>>=20 >>> Index: mod_proxy_ajp.c >>> =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D >>> --- mod_proxy_ajp.c (revision 1150558) >>> +++ mod_proxy_ajp.c (working copy) >>> @@ -506,16 +506,18 @@ >>> if (bb_len !=3D -1) >>> conn->worker->s->read +=3D bb_len; >>> } >>> - if (ap_pass_brigade(r->output_filters, >>> - =20 >> output_brigade) !=3D APR_SUCCESS) { >>> - ap_log_rerror(APLOG_MARK,=20 >> APLOG_DEBUG, 0, r, >>> - "proxy: error=20 >> processing body.%s", >>> - r->connection->aborted ? >>> - " Client aborted=20 >> connection." : ""); >>> - output_failed =3D 1; >>> + if (headers_sent) { >>> + if (ap_pass_brigade(r->output_filters, >>> + =20 >> output_brigade) !=3D APR_SUCCESS) { >>> + ap_log_rerror(APLOG_MARK,=20 >> APLOG_DEBUG, 0, r, >>> + "proxy:=20 >> error processing body.%s", >>> + =20 >> r->connection->aborted ? >>> + " Client=20 >> aborted connection." : ""); >>> + output_failed =3D 1; >>> + } >>> + data_sent =3D 1; >>> + apr_brigade_cleanup(output_brigade); >>> } >>> - data_sent =3D 1; >>> - apr_brigade_cleanup(output_brigade); >>> } >>> } >>> else { >>>=20 >>> Currently the code sends an empty brigade in your case=20 >> which also triggers the sending of headers by httpd. >>>=20 >>> Regards >>>=20 >>> R=FCdiger >>>=20 >>>> -----Original Message----- >>>> From: Jim Riggs=20 >>>> Sent: Dienstag, 2. August 2011 18:03 >>>> To: dev@httpd.apache.org >>>> Subject: mod_proxy_ajp: ignoring flush before headers (again) >>>>=20 >>>> For some (old 2007) context, see: >>>>=20 >>>> http://markmail.org/message/btwcnbl2i7ftwj4n >>>>=20 >>>> https://community.jivesoftware.com/message/201787 >>>>=20 >>>>=20 >>>> I am proxying an app via AJP to Tomcat 6/7. In certain=20 >>>> circumstances, it appears that the app (or possibly Tomcat)=20 >>>> is erroneously sending a flush before the headers have been=20 >>>> sent. In r579999, Jim added an exception to handle this=20 >>>> situation with the intention of ignoring the flush. I'm not=20 >>>> sure it's working quite right, though, as the brigade is=20 >>>> still getting passed through the filter chain. So,=20 >>>> ap_headers_output_filter() is getting called too soon, I=20 >>>> think. (I am no expert in the httpd code, so I'm not sure=20 >>>> this is really the problem.) >>>>=20 >>>> Can any of you who ARE experts in the code tell me what you=20 >>>> think of the issue and how we can fix it? I'm thinking that=20 >>>> if we are ignoring a flush at mod_proxy_ajp.c:448 (in 2.2.x),=20 >>>> we should not be calling ap_pass_brigade() at line 472, but I=20 >>>> don't know if there are any ramifications of that. >>>>=20 >>>> The symptom is that when this issue happens, the user gets=20 >>>> prompted to save a file (Content-Type returned by httpd is=20 >>>> 'text/plain' even though Tomcat is returning=20 >>>> 'text/html;charset=3Dutf-8'). Below is some debug output=20 >>>> showing correct and incorrect behavior: >>>>=20 >>>> Correct: >>>>=20 >>>> [Tue Aug 02 09:34:50 2011] [debug] mod_proxy_ajp.c(266):=20 >>>> proxy: APR_BUCKET_IS_EOS >>>> [Tue Aug 02 09:34:50 2011] [debug] mod_proxy_ajp.c(271):=20 >>>> proxy: data to read (max 8186 at 4) >>>> [Tue Aug 02 09:34:50 2011] [debug] mod_proxy_ajp.c(286):=20 >>>> proxy: got 0 bytes of data >>>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(687):=20 >>>> ajp_read_header: ajp_ilink_received 04 >>>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(697):=20 >>>> ajp_parse_type: got 04 >>>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(516):=20 >>>> ajp_unmarshal_response: status =3D 200 >>>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(537):=20 >>>> ajp_unmarshal_response: Number of headers is =3D 5 >>>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(599):=20 >>>> ajp_unmarshal_response: Header[0] [Pragma] =3D [No-cache] >>>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(599):=20 >>>> ajp_unmarshal_response: Header[1] [Cache-Control] =3D [no-cache] >>>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(599):=20 >>>> ajp_unmarshal_response: Header[2] [Expires] =3D [Wed, 31 Dec=20 >>>> 1969 18:00:00 CST] >>>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(599):=20 >>>> ajp_unmarshal_response: Header[4] [Content-Type] =3D=20 >>>> [text/html;charset=3Dutf-8] >>>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(609):=20 >>>> ajp_unmarshal_response: ap_set_content_type done >>>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(687):=20 >>>> ajp_read_header: ajp_ilink_received 03 >>>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(697):=20 >>>> ajp_parse_type: got 03 >>>> [Tue Aug 02 09:34:50 2011] [debug] mod_headers.c(756):=20 >>>> headers: ap_headers_output_filter() >>>>=20 >>>>=20 >>>> Incorrect (notice how ap_headers_output_filter() is called=20 >>>> before the headers are received): >>>>=20 >>>> [Tue Aug 02 09:32:18 2011] [debug] mod_proxy_ajp.c(266):=20 >>>> proxy: APR_BUCKET_IS_EOS >>>> [Tue Aug 02 09:32:18 2011] [debug] mod_proxy_ajp.c(271):=20 >>>> proxy: data to read (max 8186 at 4) >>>> [Tue Aug 02 09:32:18 2011] [debug] mod_proxy_ajp.c(286):=20 >>>> proxy: got 0 bytes of data >>>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(687):=20 >>>> ajp_read_header: ajp_ilink_received 03 >>>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(697):=20 >>>> ajp_parse_type: got 03 >>>> [Tue Aug 02 09:32:18 2011] [debug] mod_proxy_ajp.c(452):=20 >>>> Ignoring flush message received before headers >>>> [Tue Aug 02 09:32:18 2011] [debug] mod_headers.c(756):=20 >>>> headers: ap_headers_output_filter() >>>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(687):=20 >>>> ajp_read_header: ajp_ilink_received 03 >>>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(697):=20 >>>> ajp_parse_type: got 03 >>>> [Tue Aug 02 09:32:18 2011] [debug] mod_proxy_ajp.c(452):=20 >>>> Ignoring flush message received before headers >>>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(687):=20 >>>> ajp_read_header: ajp_ilink_received 04 >>>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(697):=20 >>>> ajp_parse_type: got 04 >>>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(516):=20 >>>> ajp_unmarshal_response: status =3D 200 >>>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(537):=20 >>>> ajp_unmarshal_response: Number of headers is =3D 5 >>>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(599):=20 >>>> ajp_unmarshal_response: Header[0] [Pragma] =3D [No-cache] >>>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(599):=20 >>>> ajp_unmarshal_response: Header[1] [Cache-Control] =3D [no-cache] >>>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(599):=20 >>>> ajp_unmarshal_response: Header[2] [Expires] =3D [Wed, 31 Dec=20 >>>> 1969 18:00:00 CST] >>>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(599):=20 >>>> ajp_unmarshal_response: Header[3] [Set-Cookie] =3D=20 >>>> [JSESSIONID=3D39968855F543CA08A440E6136EA6FC28.app1;=20 >>>> Path=3D/tomcat-manager; Secure; HttpOnly] >>>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(599):=20 >>>> ajp_unmarshal_response: Header[4] [Content-Type] =3D=20 >>>> [text/html;charset=3Dutf-8] >>>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(609):=20 >>>> ajp_unmarshal_response: ap_set_content_type done >>>>=20 >>>>=20 >>=20 >>=20