You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@httpd.apache.org by Jim Riggs <ap...@riggs.me> on 2011/08/02 18:02:49 UTC
mod_proxy_ajp: ignoring flush before headers (again)
For some (old 2007) context, see:
http://markmail.org/message/btwcnbl2i7ftwj4n
https://community.jivesoftware.com/message/201787
I am proxying an app via AJP to Tomcat 6/7. In certain circumstances, it appears that the app (or possibly Tomcat) is erroneously sending a flush before the headers have been sent. In r579999, Jim added an exception to handle this situation with the intention of ignoring the flush. I'm not sure it's working quite right, though, as the brigade is still getting passed through the filter chain. So, ap_headers_output_filter() is getting called too soon, I think. (I am no expert in the httpd code, so I'm not sure this is really the problem.)
Can any of you who ARE experts in the code tell me what you think of the issue and how we can fix it? I'm thinking that if we are ignoring a flush at mod_proxy_ajp.c:448 (in 2.2.x), we should not be calling ap_pass_brigade() at line 472, but I don't know if there are any ramifications of that.
The symptom is that when this issue happens, the user gets prompted to save a file (Content-Type returned by httpd is 'text/plain' even though Tomcat is returning 'text/html;charset=utf-8'). Below is some debug output showing correct and incorrect behavior:
Correct:
[Tue Aug 02 09:34:50 2011] [debug] mod_proxy_ajp.c(266): proxy: APR_BUCKET_IS_EOS
[Tue Aug 02 09:34:50 2011] [debug] mod_proxy_ajp.c(271): proxy: data to read (max 8186 at 4)
[Tue Aug 02 09:34:50 2011] [debug] mod_proxy_ajp.c(286): proxy: got 0 bytes of data
[Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(687): ajp_read_header: ajp_ilink_received 04
[Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(697): ajp_parse_type: got 04
[Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(516): ajp_unmarshal_response: status = 200
[Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(537): ajp_unmarshal_response: Number of headers is = 5
[Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(599): ajp_unmarshal_response: Header[0] [Pragma] = [No-cache]
[Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(599): ajp_unmarshal_response: Header[1] [Cache-Control] = [no-cache]
[Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(599): ajp_unmarshal_response: Header[2] [Expires] = [Wed, 31 Dec 1969 18:00:00 CST]
[Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(599): ajp_unmarshal_response: Header[4] [Content-Type] = [text/html;charset=utf-8]
[Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(609): ajp_unmarshal_response: ap_set_content_type done
[Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(687): ajp_read_header: ajp_ilink_received 03
[Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(697): ajp_parse_type: got 03
[Tue Aug 02 09:34:50 2011] [debug] mod_headers.c(756): headers: ap_headers_output_filter()
Incorrect (notice how ap_headers_output_filter() is called before the headers are received):
[Tue Aug 02 09:32:18 2011] [debug] mod_proxy_ajp.c(266): proxy: APR_BUCKET_IS_EOS
[Tue Aug 02 09:32:18 2011] [debug] mod_proxy_ajp.c(271): proxy: data to read (max 8186 at 4)
[Tue Aug 02 09:32:18 2011] [debug] mod_proxy_ajp.c(286): proxy: got 0 bytes of data
[Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(687): ajp_read_header: ajp_ilink_received 03
[Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(697): ajp_parse_type: got 03
[Tue Aug 02 09:32:18 2011] [debug] mod_proxy_ajp.c(452): Ignoring flush message received before headers
[Tue Aug 02 09:32:18 2011] [debug] mod_headers.c(756): headers: ap_headers_output_filter()
[Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(687): ajp_read_header: ajp_ilink_received 03
[Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(697): ajp_parse_type: got 03
[Tue Aug 02 09:32:18 2011] [debug] mod_proxy_ajp.c(452): Ignoring flush message received before headers
[Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(687): ajp_read_header: ajp_ilink_received 04
[Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(697): ajp_parse_type: got 04
[Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(516): ajp_unmarshal_response: status = 200
[Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(537): ajp_unmarshal_response: Number of headers is = 5
[Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(599): ajp_unmarshal_response: Header[0] [Pragma] = [No-cache]
[Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(599): ajp_unmarshal_response: Header[1] [Cache-Control] = [no-cache]
[Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(599): ajp_unmarshal_response: Header[2] [Expires] = [Wed, 31 Dec 1969 18:00:00 CST]
[Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(599): ajp_unmarshal_response: Header[3] [Set-Cookie] = [JSESSIONID=39968855F543CA08A440E6136EA6FC28.app1; Path=/tomcat-manager; Secure; HttpOnly]
[Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(599): ajp_unmarshal_response: Header[4] [Content-Type] = [text/html;charset=utf-8]
[Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(609): ajp_unmarshal_response: ap_set_content_type done
Re: mod_proxy_ajp: ignoring flush before headers (again)
Posted by Jim Riggs <ap...@riggs.me>.
https://issues.apache.org/bugzilla/show_bug.cgi?id=51608
Thank you for your help and quick fix, Rüdiger!!
On Aug 3, 2011, at 10:09 AM, Plüm, Rüdiger, 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.
>
> Regards
>
> Rüdiger
>
>> -----Original Message-----
>> From: Jim Riggs
>> Sent: Mittwoch, 3. August 2011 16:48
>> To: dev@httpd.apache.org
>> Subject: Re: mod_proxy_ajp: ignoring flush before headers (again)
>>
>> This does appear to work. Our automated tests are running
>> right now. Shall I submit a but with this patch attached?
>>
>>
>> On Aug 3, 2011, at 7:43 AM, Plüm, Rüdiger, VF-Group wrote:
>>
>>> Can you please try if the following patch fixes your issue?
>>>
>>> Index: mod_proxy_ajp.c
>>> ===================================================================
>>> --- mod_proxy_ajp.c (revision 1150558)
>>> +++ mod_proxy_ajp.c (working copy)
>>> @@ -506,16 +506,18 @@
>>> if (bb_len != -1)
>>> conn->worker->s->read += bb_len;
>>> }
>>> - if (ap_pass_brigade(r->output_filters,
>>> -
>> output_brigade) != APR_SUCCESS) {
>>> - ap_log_rerror(APLOG_MARK,
>> APLOG_DEBUG, 0, r,
>>> - "proxy: error
>> processing body.%s",
>>> - r->connection->aborted ?
>>> - " Client aborted
>> connection." : "");
>>> - output_failed = 1;
>>> + if (headers_sent) {
>>> + if (ap_pass_brigade(r->output_filters,
>>> +
>> output_brigade) != APR_SUCCESS) {
>>> + ap_log_rerror(APLOG_MARK,
>> APLOG_DEBUG, 0, r,
>>> + "proxy:
>> error processing body.%s",
>>> +
>> r->connection->aborted ?
>>> + " Client
>> aborted connection." : "");
>>> + output_failed = 1;
>>> + }
>>> + data_sent = 1;
>>> + apr_brigade_cleanup(output_brigade);
>>> }
>>> - data_sent = 1;
>>> - apr_brigade_cleanup(output_brigade);
>>> }
>>> }
>>> else {
>>>
>>> Currently the code sends an empty brigade in your case
>> which also triggers the sending of headers by httpd.
>>>
>>> Regards
>>>
>>> Rüdiger
>>>
>>>> -----Original Message-----
>>>> From: Jim Riggs
>>>> Sent: Dienstag, 2. August 2011 18:03
>>>> To: dev@httpd.apache.org
>>>> Subject: mod_proxy_ajp: ignoring flush before headers (again)
>>>>
>>>> For some (old 2007) context, see:
>>>>
>>>> http://markmail.org/message/btwcnbl2i7ftwj4n
>>>>
>>>> https://community.jivesoftware.com/message/201787
>>>>
>>>>
>>>> I am proxying an app via AJP to Tomcat 6/7. In certain
>>>> circumstances, it appears that the app (or possibly Tomcat)
>>>> is erroneously sending a flush before the headers have been
>>>> sent. In r579999, Jim added an exception to handle this
>>>> situation with the intention of ignoring the flush. I'm not
>>>> sure it's working quite right, though, as the brigade is
>>>> still getting passed through the filter chain. So,
>>>> ap_headers_output_filter() is getting called too soon, I
>>>> think. (I am no expert in the httpd code, so I'm not sure
>>>> this is really the problem.)
>>>>
>>>> Can any of you who ARE experts in the code tell me what you
>>>> think of the issue and how we can fix it? I'm thinking that
>>>> if we are ignoring a flush at mod_proxy_ajp.c:448 (in 2.2.x),
>>>> we should not be calling ap_pass_brigade() at line 472, but I
>>>> don't know if there are any ramifications of that.
>>>>
>>>> The symptom is that when this issue happens, the user gets
>>>> prompted to save a file (Content-Type returned by httpd is
>>>> 'text/plain' even though Tomcat is returning
>>>> 'text/html;charset=utf-8'). Below is some debug output
>>>> showing correct and incorrect behavior:
>>>>
>>>> Correct:
>>>>
>>>> [Tue Aug 02 09:34:50 2011] [debug] mod_proxy_ajp.c(266):
>>>> proxy: APR_BUCKET_IS_EOS
>>>> [Tue Aug 02 09:34:50 2011] [debug] mod_proxy_ajp.c(271):
>>>> proxy: data to read (max 8186 at 4)
>>>> [Tue Aug 02 09:34:50 2011] [debug] mod_proxy_ajp.c(286):
>>>> proxy: got 0 bytes of data
>>>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(687):
>>>> ajp_read_header: ajp_ilink_received 04
>>>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(697):
>>>> ajp_parse_type: got 04
>>>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(516):
>>>> ajp_unmarshal_response: status = 200
>>>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(537):
>>>> ajp_unmarshal_response: Number of headers is = 5
>>>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(599):
>>>> ajp_unmarshal_response: Header[0] [Pragma] = [No-cache]
>>>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(599):
>>>> ajp_unmarshal_response: Header[1] [Cache-Control] = [no-cache]
>>>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(599):
>>>> ajp_unmarshal_response: Header[2] [Expires] = [Wed, 31 Dec
>>>> 1969 18:00:00 CST]
>>>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(599):
>>>> ajp_unmarshal_response: Header[4] [Content-Type] =
>>>> [text/html;charset=utf-8]
>>>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(609):
>>>> ajp_unmarshal_response: ap_set_content_type done
>>>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(687):
>>>> ajp_read_header: ajp_ilink_received 03
>>>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(697):
>>>> ajp_parse_type: got 03
>>>> [Tue Aug 02 09:34:50 2011] [debug] mod_headers.c(756):
>>>> headers: ap_headers_output_filter()
>>>>
>>>>
>>>> Incorrect (notice how ap_headers_output_filter() is called
>>>> before the headers are received):
>>>>
>>>> [Tue Aug 02 09:32:18 2011] [debug] mod_proxy_ajp.c(266):
>>>> proxy: APR_BUCKET_IS_EOS
>>>> [Tue Aug 02 09:32:18 2011] [debug] mod_proxy_ajp.c(271):
>>>> proxy: data to read (max 8186 at 4)
>>>> [Tue Aug 02 09:32:18 2011] [debug] mod_proxy_ajp.c(286):
>>>> proxy: got 0 bytes of data
>>>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(687):
>>>> ajp_read_header: ajp_ilink_received 03
>>>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(697):
>>>> ajp_parse_type: got 03
>>>> [Tue Aug 02 09:32:18 2011] [debug] mod_proxy_ajp.c(452):
>>>> Ignoring flush message received before headers
>>>> [Tue Aug 02 09:32:18 2011] [debug] mod_headers.c(756):
>>>> headers: ap_headers_output_filter()
>>>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(687):
>>>> ajp_read_header: ajp_ilink_received 03
>>>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(697):
>>>> ajp_parse_type: got 03
>>>> [Tue Aug 02 09:32:18 2011] [debug] mod_proxy_ajp.c(452):
>>>> Ignoring flush message received before headers
>>>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(687):
>>>> ajp_read_header: ajp_ilink_received 04
>>>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(697):
>>>> ajp_parse_type: got 04
>>>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(516):
>>>> ajp_unmarshal_response: status = 200
>>>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(537):
>>>> ajp_unmarshal_response: Number of headers is = 5
>>>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(599):
>>>> ajp_unmarshal_response: Header[0] [Pragma] = [No-cache]
>>>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(599):
>>>> ajp_unmarshal_response: Header[1] [Cache-Control] = [no-cache]
>>>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(599):
>>>> ajp_unmarshal_response: Header[2] [Expires] = [Wed, 31 Dec
>>>> 1969 18:00:00 CST]
>>>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(599):
>>>> ajp_unmarshal_response: Header[3] [Set-Cookie] =
>>>> [JSESSIONID=39968855F543CA08A440E6136EA6FC28.app1;
>>>> Path=/tomcat-manager; Secure; HttpOnly]
>>>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(599):
>>>> ajp_unmarshal_response: Header[4] [Content-Type] =
>>>> [text/html;charset=utf-8]
>>>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(609):
>>>> ajp_unmarshal_response: ap_set_content_type done
>>>>
>>>>
>>
>>
RE: mod_proxy_ajp: ignoring flush before headers (again)
Posted by "Plüm, Rüdiger, VF-Group" <ru...@vodafone.com>.
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üdiger
> -----Original Message-----
> From: Jim Riggs
> Sent: Mittwoch, 3. August 2011 16:48
> To: dev@httpd.apache.org
> Subject: Re: mod_proxy_ajp: ignoring flush before headers (again)
>
> This does appear to work. Our automated tests are running
> right now. Shall I submit a but with this patch attached?
>
>
> On Aug 3, 2011, at 7:43 AM, Plüm, Rüdiger, VF-Group wrote:
>
> > Can you please try if the following patch fixes your issue?
> >
> > Index: mod_proxy_ajp.c
> > ===================================================================
> > --- mod_proxy_ajp.c (revision 1150558)
> > +++ mod_proxy_ajp.c (working copy)
> > @@ -506,16 +506,18 @@
> > if (bb_len != -1)
> > conn->worker->s->read += bb_len;
> > }
> > - if (ap_pass_brigade(r->output_filters,
> > -
> output_brigade) != APR_SUCCESS) {
> > - ap_log_rerror(APLOG_MARK,
> APLOG_DEBUG, 0, r,
> > - "proxy: error
> processing body.%s",
> > - r->connection->aborted ?
> > - " Client aborted
> connection." : "");
> > - output_failed = 1;
> > + if (headers_sent) {
> > + if (ap_pass_brigade(r->output_filters,
> > +
> output_brigade) != APR_SUCCESS) {
> > + ap_log_rerror(APLOG_MARK,
> APLOG_DEBUG, 0, r,
> > + "proxy:
> error processing body.%s",
> > +
> r->connection->aborted ?
> > + " Client
> aborted connection." : "");
> > + output_failed = 1;
> > + }
> > + data_sent = 1;
> > + apr_brigade_cleanup(output_brigade);
> > }
> > - data_sent = 1;
> > - apr_brigade_cleanup(output_brigade);
> > }
> > }
> > else {
> >
> > Currently the code sends an empty brigade in your case
> which also triggers the sending of headers by httpd.
> >
> > Regards
> >
> > Rüdiger
> >
> >> -----Original Message-----
> >> From: Jim Riggs
> >> Sent: Dienstag, 2. August 2011 18:03
> >> To: dev@httpd.apache.org
> >> Subject: mod_proxy_ajp: ignoring flush before headers (again)
> >>
> >> For some (old 2007) context, see:
> >>
> >> http://markmail.org/message/btwcnbl2i7ftwj4n
> >>
> >> https://community.jivesoftware.com/message/201787
> >>
> >>
> >> I am proxying an app via AJP to Tomcat 6/7. In certain
> >> circumstances, it appears that the app (or possibly Tomcat)
> >> is erroneously sending a flush before the headers have been
> >> sent. In r579999, Jim added an exception to handle this
> >> situation with the intention of ignoring the flush. I'm not
> >> sure it's working quite right, though, as the brigade is
> >> still getting passed through the filter chain. So,
> >> ap_headers_output_filter() is getting called too soon, I
> >> think. (I am no expert in the httpd code, so I'm not sure
> >> this is really the problem.)
> >>
> >> Can any of you who ARE experts in the code tell me what you
> >> think of the issue and how we can fix it? I'm thinking that
> >> if we are ignoring a flush at mod_proxy_ajp.c:448 (in 2.2.x),
> >> we should not be calling ap_pass_brigade() at line 472, but I
> >> don't know if there are any ramifications of that.
> >>
> >> The symptom is that when this issue happens, the user gets
> >> prompted to save a file (Content-Type returned by httpd is
> >> 'text/plain' even though Tomcat is returning
> >> 'text/html;charset=utf-8'). Below is some debug output
> >> showing correct and incorrect behavior:
> >>
> >> Correct:
> >>
> >> [Tue Aug 02 09:34:50 2011] [debug] mod_proxy_ajp.c(266):
> >> proxy: APR_BUCKET_IS_EOS
> >> [Tue Aug 02 09:34:50 2011] [debug] mod_proxy_ajp.c(271):
> >> proxy: data to read (max 8186 at 4)
> >> [Tue Aug 02 09:34:50 2011] [debug] mod_proxy_ajp.c(286):
> >> proxy: got 0 bytes of data
> >> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(687):
> >> ajp_read_header: ajp_ilink_received 04
> >> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(697):
> >> ajp_parse_type: got 04
> >> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(516):
> >> ajp_unmarshal_response: status = 200
> >> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(537):
> >> ajp_unmarshal_response: Number of headers is = 5
> >> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(599):
> >> ajp_unmarshal_response: Header[0] [Pragma] = [No-cache]
> >> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(599):
> >> ajp_unmarshal_response: Header[1] [Cache-Control] = [no-cache]
> >> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(599):
> >> ajp_unmarshal_response: Header[2] [Expires] = [Wed, 31 Dec
> >> 1969 18:00:00 CST]
> >> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(599):
> >> ajp_unmarshal_response: Header[4] [Content-Type] =
> >> [text/html;charset=utf-8]
> >> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(609):
> >> ajp_unmarshal_response: ap_set_content_type done
> >> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(687):
> >> ajp_read_header: ajp_ilink_received 03
> >> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(697):
> >> ajp_parse_type: got 03
> >> [Tue Aug 02 09:34:50 2011] [debug] mod_headers.c(756):
> >> headers: ap_headers_output_filter()
> >>
> >>
> >> Incorrect (notice how ap_headers_output_filter() is called
> >> before the headers are received):
> >>
> >> [Tue Aug 02 09:32:18 2011] [debug] mod_proxy_ajp.c(266):
> >> proxy: APR_BUCKET_IS_EOS
> >> [Tue Aug 02 09:32:18 2011] [debug] mod_proxy_ajp.c(271):
> >> proxy: data to read (max 8186 at 4)
> >> [Tue Aug 02 09:32:18 2011] [debug] mod_proxy_ajp.c(286):
> >> proxy: got 0 bytes of data
> >> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(687):
> >> ajp_read_header: ajp_ilink_received 03
> >> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(697):
> >> ajp_parse_type: got 03
> >> [Tue Aug 02 09:32:18 2011] [debug] mod_proxy_ajp.c(452):
> >> Ignoring flush message received before headers
> >> [Tue Aug 02 09:32:18 2011] [debug] mod_headers.c(756):
> >> headers: ap_headers_output_filter()
> >> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(687):
> >> ajp_read_header: ajp_ilink_received 03
> >> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(697):
> >> ajp_parse_type: got 03
> >> [Tue Aug 02 09:32:18 2011] [debug] mod_proxy_ajp.c(452):
> >> Ignoring flush message received before headers
> >> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(687):
> >> ajp_read_header: ajp_ilink_received 04
> >> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(697):
> >> ajp_parse_type: got 04
> >> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(516):
> >> ajp_unmarshal_response: status = 200
> >> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(537):
> >> ajp_unmarshal_response: Number of headers is = 5
> >> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(599):
> >> ajp_unmarshal_response: Header[0] [Pragma] = [No-cache]
> >> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(599):
> >> ajp_unmarshal_response: Header[1] [Cache-Control] = [no-cache]
> >> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(599):
> >> ajp_unmarshal_response: Header[2] [Expires] = [Wed, 31 Dec
> >> 1969 18:00:00 CST]
> >> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(599):
> >> ajp_unmarshal_response: Header[3] [Set-Cookie] =
> >> [JSESSIONID=39968855F543CA08A440E6136EA6FC28.app1;
> >> Path=/tomcat-manager; Secure; HttpOnly]
> >> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(599):
> >> ajp_unmarshal_response: Header[4] [Content-Type] =
> >> [text/html;charset=utf-8]
> >> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(609):
> >> ajp_unmarshal_response: ap_set_content_type done
> >>
> >>
>
>
Re: mod_proxy_ajp: ignoring flush before headers (again)
Posted by Jim Riggs <ap...@riggs.me>.
This does appear to work. Our automated tests are running right now. Shall I submit a but with this patch attached?
On Aug 3, 2011, at 7:43 AM, Plüm, Rüdiger, VF-Group wrote:
> Can you please try if the following patch fixes your issue?
>
> Index: mod_proxy_ajp.c
> ===================================================================
> --- mod_proxy_ajp.c (revision 1150558)
> +++ mod_proxy_ajp.c (working copy)
> @@ -506,16 +506,18 @@
> if (bb_len != -1)
> conn->worker->s->read += bb_len;
> }
> - if (ap_pass_brigade(r->output_filters,
> - output_brigade) != APR_SUCCESS) {
> - ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r,
> - "proxy: error processing body.%s",
> - r->connection->aborted ?
> - " Client aborted connection." : "");
> - output_failed = 1;
> + if (headers_sent) {
> + if (ap_pass_brigade(r->output_filters,
> + output_brigade) != APR_SUCCESS) {
> + ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r,
> + "proxy: error processing body.%s",
> + r->connection->aborted ?
> + " Client aborted connection." : "");
> + output_failed = 1;
> + }
> + data_sent = 1;
> + apr_brigade_cleanup(output_brigade);
> }
> - data_sent = 1;
> - apr_brigade_cleanup(output_brigade);
> }
> }
> else {
>
> Currently the code sends an empty brigade in your case which also triggers the sending of headers by httpd.
>
> Regards
>
> Rüdiger
>
>> -----Original Message-----
>> From: Jim Riggs
>> Sent: Dienstag, 2. August 2011 18:03
>> To: dev@httpd.apache.org
>> Subject: mod_proxy_ajp: ignoring flush before headers (again)
>>
>> For some (old 2007) context, see:
>>
>> http://markmail.org/message/btwcnbl2i7ftwj4n
>>
>> https://community.jivesoftware.com/message/201787
>>
>>
>> I am proxying an app via AJP to Tomcat 6/7. In certain
>> circumstances, it appears that the app (or possibly Tomcat)
>> is erroneously sending a flush before the headers have been
>> sent. In r579999, Jim added an exception to handle this
>> situation with the intention of ignoring the flush. I'm not
>> sure it's working quite right, though, as the brigade is
>> still getting passed through the filter chain. So,
>> ap_headers_output_filter() is getting called too soon, I
>> think. (I am no expert in the httpd code, so I'm not sure
>> this is really the problem.)
>>
>> Can any of you who ARE experts in the code tell me what you
>> think of the issue and how we can fix it? I'm thinking that
>> if we are ignoring a flush at mod_proxy_ajp.c:448 (in 2.2.x),
>> we should not be calling ap_pass_brigade() at line 472, but I
>> don't know if there are any ramifications of that.
>>
>> The symptom is that when this issue happens, the user gets
>> prompted to save a file (Content-Type returned by httpd is
>> 'text/plain' even though Tomcat is returning
>> 'text/html;charset=utf-8'). Below is some debug output
>> showing correct and incorrect behavior:
>>
>> Correct:
>>
>> [Tue Aug 02 09:34:50 2011] [debug] mod_proxy_ajp.c(266):
>> proxy: APR_BUCKET_IS_EOS
>> [Tue Aug 02 09:34:50 2011] [debug] mod_proxy_ajp.c(271):
>> proxy: data to read (max 8186 at 4)
>> [Tue Aug 02 09:34:50 2011] [debug] mod_proxy_ajp.c(286):
>> proxy: got 0 bytes of data
>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(687):
>> ajp_read_header: ajp_ilink_received 04
>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(697):
>> ajp_parse_type: got 04
>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(516):
>> ajp_unmarshal_response: status = 200
>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(537):
>> ajp_unmarshal_response: Number of headers is = 5
>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(599):
>> ajp_unmarshal_response: Header[0] [Pragma] = [No-cache]
>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(599):
>> ajp_unmarshal_response: Header[1] [Cache-Control] = [no-cache]
>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(599):
>> ajp_unmarshal_response: Header[2] [Expires] = [Wed, 31 Dec
>> 1969 18:00:00 CST]
>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(599):
>> ajp_unmarshal_response: Header[4] [Content-Type] =
>> [text/html;charset=utf-8]
>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(609):
>> ajp_unmarshal_response: ap_set_content_type done
>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(687):
>> ajp_read_header: ajp_ilink_received 03
>> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(697):
>> ajp_parse_type: got 03
>> [Tue Aug 02 09:34:50 2011] [debug] mod_headers.c(756):
>> headers: ap_headers_output_filter()
>>
>>
>> Incorrect (notice how ap_headers_output_filter() is called
>> before the headers are received):
>>
>> [Tue Aug 02 09:32:18 2011] [debug] mod_proxy_ajp.c(266):
>> proxy: APR_BUCKET_IS_EOS
>> [Tue Aug 02 09:32:18 2011] [debug] mod_proxy_ajp.c(271):
>> proxy: data to read (max 8186 at 4)
>> [Tue Aug 02 09:32:18 2011] [debug] mod_proxy_ajp.c(286):
>> proxy: got 0 bytes of data
>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(687):
>> ajp_read_header: ajp_ilink_received 03
>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(697):
>> ajp_parse_type: got 03
>> [Tue Aug 02 09:32:18 2011] [debug] mod_proxy_ajp.c(452):
>> Ignoring flush message received before headers
>> [Tue Aug 02 09:32:18 2011] [debug] mod_headers.c(756):
>> headers: ap_headers_output_filter()
>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(687):
>> ajp_read_header: ajp_ilink_received 03
>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(697):
>> ajp_parse_type: got 03
>> [Tue Aug 02 09:32:18 2011] [debug] mod_proxy_ajp.c(452):
>> Ignoring flush message received before headers
>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(687):
>> ajp_read_header: ajp_ilink_received 04
>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(697):
>> ajp_parse_type: got 04
>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(516):
>> ajp_unmarshal_response: status = 200
>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(537):
>> ajp_unmarshal_response: Number of headers is = 5
>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(599):
>> ajp_unmarshal_response: Header[0] [Pragma] = [No-cache]
>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(599):
>> ajp_unmarshal_response: Header[1] [Cache-Control] = [no-cache]
>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(599):
>> ajp_unmarshal_response: Header[2] [Expires] = [Wed, 31 Dec
>> 1969 18:00:00 CST]
>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(599):
>> ajp_unmarshal_response: Header[3] [Set-Cookie] =
>> [JSESSIONID=39968855F543CA08A440E6136EA6FC28.app1;
>> Path=/tomcat-manager; Secure; HttpOnly]
>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(599):
>> ajp_unmarshal_response: Header[4] [Content-Type] =
>> [text/html;charset=utf-8]
>> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(609):
>> ajp_unmarshal_response: ap_set_content_type done
>>
>>
RE: mod_proxy_ajp: ignoring flush before headers (again)
Posted by "Plüm, Rüdiger, VF-Group" <ru...@vodafone.com>.
Can you please try if the following patch fixes your issue?
Index: mod_proxy_ajp.c
===================================================================
--- mod_proxy_ajp.c (revision 1150558)
+++ mod_proxy_ajp.c (working copy)
@@ -506,16 +506,18 @@
if (bb_len != -1)
conn->worker->s->read += bb_len;
}
- if (ap_pass_brigade(r->output_filters,
- output_brigade) != APR_SUCCESS) {
- ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r,
- "proxy: error processing body.%s",
- r->connection->aborted ?
- " Client aborted connection." : "");
- output_failed = 1;
+ if (headers_sent) {
+ if (ap_pass_brigade(r->output_filters,
+ output_brigade) != APR_SUCCESS) {
+ ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r,
+ "proxy: error processing body.%s",
+ r->connection->aborted ?
+ " Client aborted connection." : "");
+ output_failed = 1;
+ }
+ data_sent = 1;
+ apr_brigade_cleanup(output_brigade);
}
- data_sent = 1;
- apr_brigade_cleanup(output_brigade);
}
}
else {
Currently the code sends an empty brigade in your case which also triggers the sending of headers by httpd.
Regards
Rüdiger
> -----Original Message-----
> From: Jim Riggs
> Sent: Dienstag, 2. August 2011 18:03
> To: dev@httpd.apache.org
> Subject: mod_proxy_ajp: ignoring flush before headers (again)
>
> For some (old 2007) context, see:
>
> http://markmail.org/message/btwcnbl2i7ftwj4n
>
> https://community.jivesoftware.com/message/201787
>
>
> I am proxying an app via AJP to Tomcat 6/7. In certain
> circumstances, it appears that the app (or possibly Tomcat)
> is erroneously sending a flush before the headers have been
> sent. In r579999, Jim added an exception to handle this
> situation with the intention of ignoring the flush. I'm not
> sure it's working quite right, though, as the brigade is
> still getting passed through the filter chain. So,
> ap_headers_output_filter() is getting called too soon, I
> think. (I am no expert in the httpd code, so I'm not sure
> this is really the problem.)
>
> Can any of you who ARE experts in the code tell me what you
> think of the issue and how we can fix it? I'm thinking that
> if we are ignoring a flush at mod_proxy_ajp.c:448 (in 2.2.x),
> we should not be calling ap_pass_brigade() at line 472, but I
> don't know if there are any ramifications of that.
>
> The symptom is that when this issue happens, the user gets
> prompted to save a file (Content-Type returned by httpd is
> 'text/plain' even though Tomcat is returning
> 'text/html;charset=utf-8'). Below is some debug output
> showing correct and incorrect behavior:
>
> Correct:
>
> [Tue Aug 02 09:34:50 2011] [debug] mod_proxy_ajp.c(266):
> proxy: APR_BUCKET_IS_EOS
> [Tue Aug 02 09:34:50 2011] [debug] mod_proxy_ajp.c(271):
> proxy: data to read (max 8186 at 4)
> [Tue Aug 02 09:34:50 2011] [debug] mod_proxy_ajp.c(286):
> proxy: got 0 bytes of data
> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(687):
> ajp_read_header: ajp_ilink_received 04
> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(697):
> ajp_parse_type: got 04
> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(516):
> ajp_unmarshal_response: status = 200
> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(537):
> ajp_unmarshal_response: Number of headers is = 5
> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(599):
> ajp_unmarshal_response: Header[0] [Pragma] = [No-cache]
> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(599):
> ajp_unmarshal_response: Header[1] [Cache-Control] = [no-cache]
> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(599):
> ajp_unmarshal_response: Header[2] [Expires] = [Wed, 31 Dec
> 1969 18:00:00 CST]
> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(599):
> ajp_unmarshal_response: Header[4] [Content-Type] =
> [text/html;charset=utf-8]
> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(609):
> ajp_unmarshal_response: ap_set_content_type done
> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(687):
> ajp_read_header: ajp_ilink_received 03
> [Tue Aug 02 09:34:50 2011] [debug] ajp_header.c(697):
> ajp_parse_type: got 03
> [Tue Aug 02 09:34:50 2011] [debug] mod_headers.c(756):
> headers: ap_headers_output_filter()
>
>
> Incorrect (notice how ap_headers_output_filter() is called
> before the headers are received):
>
> [Tue Aug 02 09:32:18 2011] [debug] mod_proxy_ajp.c(266):
> proxy: APR_BUCKET_IS_EOS
> [Tue Aug 02 09:32:18 2011] [debug] mod_proxy_ajp.c(271):
> proxy: data to read (max 8186 at 4)
> [Tue Aug 02 09:32:18 2011] [debug] mod_proxy_ajp.c(286):
> proxy: got 0 bytes of data
> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(687):
> ajp_read_header: ajp_ilink_received 03
> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(697):
> ajp_parse_type: got 03
> [Tue Aug 02 09:32:18 2011] [debug] mod_proxy_ajp.c(452):
> Ignoring flush message received before headers
> [Tue Aug 02 09:32:18 2011] [debug] mod_headers.c(756):
> headers: ap_headers_output_filter()
> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(687):
> ajp_read_header: ajp_ilink_received 03
> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(697):
> ajp_parse_type: got 03
> [Tue Aug 02 09:32:18 2011] [debug] mod_proxy_ajp.c(452):
> Ignoring flush message received before headers
> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(687):
> ajp_read_header: ajp_ilink_received 04
> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(697):
> ajp_parse_type: got 04
> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(516):
> ajp_unmarshal_response: status = 200
> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(537):
> ajp_unmarshal_response: Number of headers is = 5
> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(599):
> ajp_unmarshal_response: Header[0] [Pragma] = [No-cache]
> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(599):
> ajp_unmarshal_response: Header[1] [Cache-Control] = [no-cache]
> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(599):
> ajp_unmarshal_response: Header[2] [Expires] = [Wed, 31 Dec
> 1969 18:00:00 CST]
> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(599):
> ajp_unmarshal_response: Header[3] [Set-Cookie] =
> [JSESSIONID=39968855F543CA08A440E6136EA6FC28.app1;
> Path=/tomcat-manager; Secure; HttpOnly]
> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(599):
> ajp_unmarshal_response: Header[4] [Content-Type] =
> [text/html;charset=utf-8]
> [Tue Aug 02 09:32:18 2011] [debug] ajp_header.c(609):
> ajp_unmarshal_response: ap_set_content_type done
>
>