Mailing-List: contact dev-help@httpd.apache.org; run by ezmlm
Precedence: bulk
Reply-To: dev@httpd.apache.org
Received-SPF: pass (athena.apache.org: local policy)
Content-class: urn:content-classes:message
MIME-Version: 1.0
Content-Type: text/plain;
	charset="iso-8859-1"
Content-Transfer-Encoding: quoted-printable
Subject: RE: mod_proxy_ajp: ignoring flush before headers (again)
Date: Wed, 3 Aug 2011 17:09:41 +0200
Message-ID: 
 <E563FB5AB3F02844AC749BA39E494AB405185B7B@VF-MBX11.internal.vodafone.com>
In-Reply-To: <70E858A5-B4C5-47A4-B463-65E53DFBDFEC@riggs.me>
Thread-Topic: mod_proxy_ajp: ignoring flush before headers (again)
Thread-Index: AcxR7HVplslXfVwIT4SZdzgapvTY6AAAhf8A
References: <1B34CC00-2633-4871-ADBE-EA12FBBDB32E@riggs.me>
 <E563FB5AB3F02844AC749BA39E494AB405185AA5@VF-MBX11.internal.vodafone.com>
 <70E858A5-B4C5-47A4-B463-65E53DFBDFEC@riggs.me>
From: =?iso-8859-1?Q?=22Pl=FCm=2C_R=FCdiger=2C_VF-Group=22?=
 <ruediger.pluem@vodafone.com>
To: <dev@httpd.apache.org>

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.

Regards

R=FCdiger

> -----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