You are viewing a plain text version of this content. The canonical link for it is here.
Posted to bugs@httpd.apache.org by bu...@apache.org on 2016/02/22 17:02:09 UTC
[Bug 59045] New: AH01382: Request body read timeout triggered in
reverse proxy setup
https://bz.apache.org/bugzilla/show_bug.cgi?id=59045
Bug ID: 59045
Summary: AH01382: Request body read timeout triggered in
reverse proxy setup
Product: Apache httpd-2
Version: 2.4.17
Hardware: PC
OS: Linux
Status: NEW
Severity: major
Priority: P2
Component: mod_reqtimeout
Assignee: bugs@httpd.apache.org
Reporter: peter@pramberger.at
Created attachment 33581
--> https://bz.apache.org/bugzilla/attachment.cgi?id=33581&action=edit
Debug output
Hi,
I'm currently facing a strange issue with Apache 2.4.17 running in a reverse
proxy setup. The web server terminates SSL, and requests are forwarded via AJP
to a Tomcat server.
It seems that mod_reqtimeout triggers a AH01382 for requests running longer
(>20s default request timeout), even though the web server already responded
with status code 200. This is triggered with both Worker and Event MPMs.
Attached is the debug output from a sample session. The request starts in line
1054, line 1153 shows the timeout error, while in line 1130 the 200 response is
already sent back to the client.
Please note the time difference of 50s between forwarding the request to the
client (line 1120), and getting back the response from the server (line 1121).
The AH01382 is NOT triggered if I increase the request body timeout to e.g.
900s.
Seems like mod_reqtimeout is triggered too late in the chain, so that the
request processing time on the backend server is wrongly taken into account.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 59045] AH01382: Request body read timeout triggered in reverse
proxy setup
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=59045
Yann Ylavic <yl...@gmail.com> changed:
What |Removed |Added
----------------------------------------------------------------------------
CC| |ylavic.dev@gmail.com
--- Comment #6 from Yann Ylavic <yl...@gmail.com> ---
Created attachment 33609
--> https://bz.apache.org/bugzilla/attachment.cgi?id=33609&action=edit
Disable mod_reqtimeout in between requests
I think I figure out what's going on, and this has to do with mod_ssl (which
doesn't show up in the log but the numerous "FLUSH bucket" make me assume it is
enabled...).
Indeed mod_ssl "transforms" the speculative reads into normal reads, which
bypasses the check in mod_reqtimeout.
The attached patch detects outgoing EOR buckets and disables mod_reqtimeout
until the next request is read (that anyway only concerns
speculative/administrative and non-blocking reads, which should not be taken
into account).
Could you please give it a try?
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 59045] AH01382: Request body read timeout triggered in reverse
proxy setup
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=59045
--- Comment #5 from Peter Pramberger <pe...@pramberger.at> ---
Just in case it matters: mod_reqtimeout is definitely loaded before any of the
proxy modules.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 59045] Request body read timeout (AH01382) triggered with SSL
in reverse proxy setup
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=59045
--- Comment #15 from Yann Ylavic <yl...@gmail.com> ---
Committed version in r1734239, proposed for backport to 2.4.x.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 59045] AH01382: Request body read timeout triggered in reverse
proxy setup
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=59045
--- Comment #1 from Peter Pramberger <pe...@pramberger.at> ---
Even though this is not the latest version I assume the same behaviour in
2.4.18. At least there were no changes to mod_reqtimeout.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 59045] Request body read timeout (AH01382) triggered with SSL
in reverse proxy setup
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=59045
--- Comment #11 from Ruediger Pluem <rp...@apache.org> ---
(In reply to Yann Ylavic from comment #8)
> Created attachment 33611 [details]
> Disable mod_reqtimeout in between requests
>
> Actually the previous patch failed to add the new filter, this one should be
> better.
>
> Thanks for testing.
Hm. Is another output filter really the best solution? It has to be passed for
every run of the output chain.
How about setting a note to c->notes in check_pipeline that informs
mod_reqtimeout to step out of our way temporarily? This removes the need for
mod_reqtimeout to second guess from other conditions that it has to step out.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 59045] Request body read timeout (AH01382) triggered with SSL
in reverse proxy setup
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=59045
--- Comment #9 from Peter Pramberger <pe...@pramberger.at> ---
Unfortunately I can't do a real-life test with the application yet, this might
take a couple of days, sorry.
But when trying to manually test it, I noticed some strange behaviour (not
related to your patch!):
1) Triggering a request header read timeout:
$ openssl s_client -connect 10.15.24.4:443 -quiet
<no input>
<Connection closed after 20s, no output>
[Mon Feb 29 13:21:26.240128 2016] [reqtimeout:info] [pid 1384:tid
140271576659712] [client 10.15.24.23:51325] AH01382: Request header read
timeout
10.15.24.23 securities-backoffice-http-test.DOMAIN - [29/Feb/2016:13:21:26
+0100] "-" 408 - "-" "-"
While a 408 is logged, there is no actual response from the web server.
Shouldn't it return a "HTTP/1.1 408" status line?
2) Triggering a request body read timeout:
$ openssl s_client -connect 10.15.24.23:443 -quiet
POST /SecuritiesTool/rpc HTTP/1.1
Host: securities-backoffice-http-test.DOMAIN
Content-Type: application/octet-stream
Content-Length: 100
<no body sent>
HTTP/1.1 400 Bad Request
Date: Mon, 29 Feb 2016 12:21:33 GMT
Server: Apache
Content-Length: 318
Connection: close
Content-Type: text/html; charset=iso-8859-1
[Mon Feb 29 13:21:54.466678 2016] [reqtimeout:info] [pid 1646:tid
140271608129280] [client 10.15.24.23:51327] AH01382: Request body read timeout
10.15.24.23 securities-backoffice-http-test.DOMAIN - [29/Feb/2016:13:21:33
+0100] "POST /SecuritiesTool/rpc HTTP/1.1" 400 318 "-" "-"
What happened to the 408?
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 59045] AH01382: Request body read timeout triggered in reverse
proxy setup
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=59045
Yann Ylavic <yl...@gmail.com> changed:
What |Removed |Added
----------------------------------------------------------------------------
Attachment #33609|0 |1
is obsolete| |
--- Comment #8 from Yann Ylavic <yl...@gmail.com> ---
Created attachment 33611
--> https://bz.apache.org/bugzilla/attachment.cgi?id=33611&action=edit
Disable mod_reqtimeout in between requests
Actually the previous patch failed to add the new filter, this one should be
better.
Thanks for testing.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 59045] Request body read timeout (AH01382) triggered with SSL
in reverse proxy setup
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=59045
--- Comment #13 from Ruediger Pluem <rp...@apache.org> ---
(In reply to Yann Ylavic from comment #12)
> (In reply to Ruediger Pluem from comment #11)
> >
> > Hm. Is another output filter really the best solution? It has to be passed
> > for every run of the output chain.
> > How about setting a note to c->notes in check_pipeline that informs
> > mod_reqtimeout to step out of our way temporarily? This removes the need for
> > mod_reqtimeout to second guess from other conditions that it has to step out.
>
> It's not really an heavy filter, not sure it performs slower than an
> apr_table lookup...
> This filter shouldn't be noticeable from a performance POV, and I think it
> is sane in any case, do we (will) control all the speculative/non-blocking
> (administrative) reads between requests?
I admit that it might be a matter of taste. You can argue that you don't know
where all these actions between requests happen and hence that in these cases
the callers that pull from the input chain miss to set the note. Furthermore
you can argue that the callers shouldn't need to know about mod_reqtimeout and
the need to disable it and that they might forget to enable it again or disable
it again if we do so automatically in mod_reqtimeout. On the other hand we had
a fix for this issue already in 2.4.16 and did not capture all cases. Probably
we missed other edge cases and need to add further more less complex code to
detect them in mod_reqtimeout whereas in the notes case we would just need to
set the note on callers side.
>
> The "notes" could possibly be added for individual modules (if needed) to
> handle a temporary state (those that currently disable mod_reqtimeout
> completely, for no good reason IMHO), but that's another story I think.
>
> But I'm not totally opposed to your solution either, maybe other opinions?
No extraordinary strong feelings. Would love to hear the opinion of others.
Maybe we should forward this to dev@ for discussion and make a decision based
on this discussion which way to go.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 59045] AH01382: Request body read timeout triggered in reverse
proxy setup
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=59045
--- Comment #3 from Yann Ylavic <yl...@gmail.com> ---
This should be fixed since 2.4.16 (by r1689922).
The [speculative-nonblocking] read (log line 1151) shouldn't trigger any
timeout because it is explicitly bypassed at the very beginning of
mod_reqtimeout's filter.
Could it be possible that the mod_reqtimeout(.so) used/linked is not up to
date?
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 59045] AH01382: Request body read timeout triggered in reverse
proxy setup
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=59045
--- Comment #2 from Peter Pramberger <pe...@pramberger.at> ---
Forgot to mention: same behaviour when using HTTP instead of AJP to the backend
server.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 59045] Request body read timeout (AH01382) triggered with SSL
in reverse proxy setup
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=59045
--- Comment #12 from Yann Ylavic <yl...@gmail.com> ---
(In reply to Ruediger Pluem from comment #11)
>
> Hm. Is another output filter really the best solution? It has to be passed
> for every run of the output chain.
> How about setting a note to c->notes in check_pipeline that informs
> mod_reqtimeout to step out of our way temporarily? This removes the need for
> mod_reqtimeout to second guess from other conditions that it has to step out.
It's not really an heavy filter, not sure it performs slower than an apr_table
lookup...
This filter shouldn't be noticeable from a performance POV, and I think it is
sane in any case, do we (will) control all the speculative/non-blocking
(administrative) reads between requests?
The "notes" could possibly be added for individual modules (if needed) to
handle a temporary state (those that currently disable mod_reqtimeout
completely, for no good reason IMHO), but that's another story I think.
But I'm not totally opposed to your solution either, maybe other opinions?
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 59045] Request body read timeout (AH01382) triggered with SSL
in reverse proxy setup
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=59045
--- Comment #10 from Peter Pramberger <pe...@pramberger.at> ---
Sorry for the delay - the first tests look good, I'm awaiting the final
confirmation for tomorrow.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 59045] Request body read timeout (AH01382) triggered with SSL
in reverse proxy setup
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=59045
Yann Ylavic <yl...@gmail.com> changed:
What |Removed |Added
----------------------------------------------------------------------------
Status|NEW |RESOLVED
Resolution|--- |FIXED
--- Comment #16 from Yann Ylavic <yl...@gmail.com> ---
Backported to 2.4.19 in r1734416.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 59045] Request body read timeout (AH01382) triggered with SSL
in reverse proxy setup
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=59045
Peter Pramberger <pe...@pramberger.at> changed:
What |Removed |Added
----------------------------------------------------------------------------
Summary|AH01382: Request body read |Request body read timeout
|timeout triggered in |(AH01382) triggered with
|reverse proxy setup |SSL in reverse proxy setup
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 59045] Request body read timeout (AH01382) triggered with SSL
in reverse proxy setup
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=59045
--- Comment #14 from Peter Pramberger <pe...@pramberger.at> ---
Well, whatever the correct solution would be, the provided patch seems to fix
the issue for me. I can live with it till it is finally fixed in an upcoming
release.
Thanks for your help.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 59045] AH01382: Request body read timeout triggered in reverse
proxy setup
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=59045
--- Comment #4 from Peter Pramberger <pe...@pramberger.at> ---
Unfortunately not - I'm using mock for a clean RPM build environment. And there
is another sign:
$ grep "ap_hook_pre_read_request" httpd-2.4.12/modules/filters/mod_reqtimeout.c
$ grep "ap_hook_pre_read_request" httpd-2.4.17/modules/filters/mod_reqtimeout.c
ap_hook_pre_read_request(reqtimeout_before_header, NULL, NULL,
$ strings mod_reqtimeout.so | grep "ap_hook_pre_read_request"
ap_hook_pre_read_request
That issue actually appeared with 2.4.16 first, but due to a number of factors
(one of them being that mod_reqtimeout logs these AH01382 only on info level,
the second one is having a Java thick client which triggers another bug due to
this premature connection close) it took till now to lock it down to
mod_reqtimeout.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 59045] AH01382: Request body read timeout triggered in reverse
proxy setup
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=59045
--- Comment #7 from Peter Pramberger <pe...@pramberger.at> ---
Yes, I left debugging disabled for mod_ssl to keep the debug output manageable.
Thanks, I'll try it.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org