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 2018/04/02 13:19:40 UTC
[Bug 62249] New: Server only responding after timeout when there are
extra data after the request
https://bz.apache.org/bugzilla/show_bug.cgi?id=62249
Bug ID: 62249
Summary: Server only responding after timeout when there are
extra data after the request
Product: Apache httpd-2
Version: 2.4.33
Hardware: Sun
OS: SunOS
Status: NEW
Severity: regression
Priority: P2
Component: Core
Assignee: bugs@httpd.apache.org
Reporter: k.j.chernov@gmail.com
Target Milestone: ---
Hi.
Looks like regression after 2.4.29.
I'm sending a request:
POST /path/to/app HTTP/1.1\r\n
Host: host:port\r\n
Content-Type: text/xml; charset=utf-8\r\n
Content-Length: 417\r\n
\r\n
<417_bytes_of_data>\s\r\n
In 2.4.29 I was always receiving a response:
HTTP/1.1 200 OK
Date: Mon, 02 Apr 2018 13:12:21 GMT
Server: Apache
Strict-Transport-Security: max-age=63072000; includeSubdomains; preload
Content-Type: text/xml;charset=utf-8
Content-Length: 1891
<1891_bytes_of_data>
In 2.4.33 sometimes I'm not receiving a response at all (until the connection
is being closed by apache after Timeout seconds), sometimes I'm receiving:
HTTP/1.1 200 OK
Date: Mon, 02 Apr 2018 13:08:23 GMT
Server: Apache
Strict-Transport-Security: max-age=63072000; includeSubdomains; preload
Content-Type: text/xml;charset=utf-8
Transfer-Encoding: chunked
and sometimes I'm receiving only part of response (and the rest of the response
is sent after Timeout seconds):
HTTP/1.1 200 OK
Date: Mon, 02 Apr 2018 13:14:08 GMT
Server: Apache
Strict-Transport-Security: max-age=63072000; includeSubdomains; preload
Content-Type: text/xml;charset=utf-8
Transfer-Encoding: chunked
544
<544_bytes_of_data>
However, in all cases the request made it to the application, but the client
did not receive a response.
Can you please tell me whether this Apache's behaviour is correct? If yes, is
there any RFC that can prove correctness of this behaviour (tried looking by
myself, but stuck at reading about HTTP pipelining -- according to it, this
request should be handled correctly).
--
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 62249] Server only responding after timeout when there are
extra data after the request
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=62249
--- Comment #13 from Konstantin J. Chernov <k....@gmail.com> ---
(In reply to Yann Ylavic from comment #12)
> With MPM worker, pipelined responses are not flushed (up to five)
Well, that explains everything, thank you :)
Is that behavior considered correct?
--
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 62249] Server only responding after timeout when there are
extra data after the request
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=62249
Eric Covener <co...@gmail.com> changed:
What |Removed |Added
----------------------------------------------------------------------------
Status|NEW |NEEDINFO
--- Comment #1 from Eric Covener <co...@gmail.com> ---
What module generates the response here? Proxy? CGI?
Can you get a backtrace of the server in the middle of the timeout period using
pstack? You need to pick the right child process (or just hit all of them).
--
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 62249] Server only responding after timeout when there are
extra data after the request
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=62249
--- Comment #12 from Yann Ylavic <yl...@gmail.com> ---
The file req_test.txt contains two trailing bytes (one SP and one CR) which
httpd considers as the next incomplete/pipelined request.
With MPM worker, pipelined responses are not flushed (up to five), and since
there are no further data the flush finally happens at KeepAliveTimeout (the
second invalid/incomplete request is not logged).
If you add one more LF to req_test.txt you'll notice that two responses are
sent immediately, the second of which is a "400 bad request".
With MPM event, there is a non-blocking flush attempt before entering keepalive
state (regardless of pipelining), so the first response is received immediatly,
but the second one reaches Timeout (likewise not logged).
--
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 62249] Server only responding after timeout when there are
extra data after the request
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=62249
--- Comment #2 from Konstantin J. Chernov <k....@gmail.com> ---
Created attachment 35834
--> https://bz.apache.org/bugzilla/attachment.cgi?id=35834&action=edit
pstack #1
Attached pstack.21515.
According to access.log the request was handled by pid 21515:tid 17
pstack made after ~10 seconds after the request were sent. Tried two times to
be sure the thread's stacktrace is the same.
Response is generated by mod_proxy_http (Tomcat as a backend).
--
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 62249] Server only responding after timeout when there are
extra data after the request
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=62249
--- Comment #11 from Konstantin J. Chernov <k....@gmail.com> ---
Created attachment 35840
--> https://bz.apache.org/bugzilla/attachment.cgi?id=35840&action=edit
Information needed to reproduce the bug
Attached file test_result.zip.
httpd.test.conf + test.conf -- configuration files
req_test.txt -- request causing bug
spool.event.txt -- attempt to send request with event MPM
spool.worker.txt -- attempt to send request with worker MPM
_access and _error logs
apache started as
/path/to/apache/bin/httpd -D_test -d /path/to/apache -f
/path/to/httpd.test.conf -k start
I had to cut error logs to the part when request arrives to apache.
Most important: this time there is no proxy, backend or some files on file
system. It's just a 404 error response that didn't get it to client with worker
mpm.
I sent a request (req_test.txt) when worker MPM was active. After 30s (timeout)
I received a respone (see spool.worker.txt + test_error.log.20180405.worker).
Then I sent the same request when event MPM was active. I received response
(see spool.event.txt + test_error.log.20180405.event) and pressed Ctrl+C.
--
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 62249] Server only responding after timeout when there are
extra data after the request
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=62249
--- Comment #9 from Yann Ylavic <yl...@gmail.com> ---
Hi Konstantin,
can't it be related to bug 61786 (i.e. does it still happen with the APR patch
from there)?
If the MPM event wakeup code is buggy (per this other bug report), flushing
data to the client might be impacted too...
--
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 62249] Server only responding after timeout when there are
extra data after the request
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=62249
--- Comment #5 from Konstantin J. Chernov <k....@gmail.com> ---
After digging a bit deeper, I found out that 2.4.33 was built with worker mpm
(my fault, I guess :)), and 2.4.29 was on event mpm.
Recompiled 2.4.33 with event mpm and the behavior changed -- the client always
receiving a response (however, it comes sometimes chunked, and sometimes with
content-length -- 50\50 -- that's really odd).
I guess the issue shouldn't be marked as regression anymore, it's more like
just a bug. What I don't understand is why the behavior changes so much when
switching between different MPMs.
--
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 62249] Server only responding after timeout when there are
extra data after the request
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=62249
--- Comment #4 from Konstantin J. Chernov <k....@gmail.com> ---
I aborted the request (on the client) after retreiving a pstack. I can wait for
30s (Timeout value) if that matters.
Here's the access.log entry:
[02/Apr/2018:16:31:19 +0300] [127.0.0.1]=>[127.0.0.1:port] [pid 21515:tid 27]
[C:AGaYFZrpYKA] [WsIwp9buuLz3q3TeUyRXQgAAAdg] "POST /path/to/app HTTP/1.1" 200
1891 9555277/9s 1982 6639 TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384
Here's tomcat access.log entry:
[02/Apr/2018:16:31:19 +0300] WsIwp9buuLz3q3TeUyRXQgAAAdg
[127.0.0.1]=>[host:port] - HTTP/1.1:POST /path/to/app 200 [10 ms]
Tomcat logs the time when request ended, apache logs the time when request
started. 9s wasted somewhere unknown, without client receiving the response.
--
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 62249] Server only responding after timeout when there are
extra data after the request
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=62249
--- Comment #8 from Konstantin J. Chernov <k....@gmail.com> ---
(In reply to Rainer Jung from comment #6)
> I don't see the 9 seconds in this example. Start at 16:31:19 (Apache), end
> at 16:31:19 (Tomcat). So the same second?
[02/Apr/2018:16:31:19 +0300] [127.0.0.1]=>[127.0.0.1:port] [pid 21515:tid 27]
[C:AGaYFZrpYKA] [WsIwp9buuLz3q3TeUyRXQgAAAdg] "POST /path/to/app HTTP/1.1" 200
1891 9555277/9s 1982 6639 TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384
9555277/9s -- is %D/%Ts -- here's 9 seconds.
But yes, the request were sent to backend at 16:31:19, and response were sent
by backend the same second. The problem is -- the client didn't get a response.
It actually looks like a buffering problem of some sort, however with mpm_event
everything is fine.
> "LogLevel trace8" logs for a reproduction
> more config details and a smaller reproduction scenario?
Will try to reproduce outside of production environment and share the details.
> Which APR/APU are you using?
Latest stable. apr 1.6.3, apr-util 1.6.1
> Which compilation setup, which configure flags?
Solaris 11, latest SRU, Oracle T4-1
export CC="gcc -m64"
export CXX="g++ -m64"
export CFLAGS="-m64"
export CXXFLAGS="-m64"
./configure --prefix=$BIN_HOME --with-included-apr --with-expat=builtin
--with-ssl=$BIN_HOME --with-ldap --enable-ldap --enable-authnz-ldap
gmake
gmake install
worker version was built with
export ac_cv_func_port_create=no
openssl precompiled and installed into $BIN_HOME
--
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 62249] Server only responding after timeout when there are
extra data after the request
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=62249
--- Comment #3 from Eric Covener <co...@gmail.com> ---
Comment on attachment 35834
--> https://bz.apache.org/bugzilla/attachment.cgi?id=35834
pstack #1
weird, they're all reading line-based data and no proxy in any stack. Are you
sure it was still hung/running at the time? I assume your access log
corroboration was only done _after_ the pstack -- since once logged, nothing is
running.
--
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 62249] Server only responding after timeout when there are
extra data after the request
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=62249
--- Comment #7 from Rainer Jung <ra...@kippdata.de> ---
Is it possible to provide
- "LogLevel trace8" logs for a reproduction
- more config details and a smaller reproduction scenario? For instance you are
using Tomcat as a proxy backend, but does it also happen with another Apache
VirtualHost as the backend?
I could try to reproduce on Solaris, but it would help to get a better
description of your setup.
Which APR/APU are you using?
Which compilation setup, which configure flags?
Thanks and regards,
Rainer
--
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 62249] Server only responding after timeout when there are
extra data after the request
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=62249
Yann Ylavic <yl...@gmail.com> changed:
What |Removed |Added
----------------------------------------------------------------------------
Status|NEW |RESOLVED
Resolution|--- |INVALID
--- Comment #14 from Yann Ylavic <yl...@gmail.com> ---
Yes, it's expected, pipelined requests are supposed to be full ones, the goal
of pipelining is to optimize bandwidth in the first place.
So httpd tries to respect that by pipelining responses, with this "risk" for
clients that they don't really play the game..
But note that trailing CRLFs (and only CRLFs) are not considered pipelining,
they are tolerated and consumed/eaten up to a reasonable limit. Here your
sample contained a space too.
--
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 62249] Server only responding after timeout when there are
extra data after the request
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=62249
--- Comment #10 from Konstantin J. Chernov <k....@gmail.com> ---
> can't it be related to bug 61786 (i.e. does it still happen with the APR patch from there)?
I don't see how can it be related.
The issue described here only appears on worker mpm (when apache built without
port support).
--
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 62249] Server only responding after timeout when there are
extra data after the request
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=62249
Konstantin J. Chernov <k....@gmail.com> changed:
What |Removed |Added
----------------------------------------------------------------------------
Status|NEEDINFO |NEW
--
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 62249] Server only responding after timeout when there are
extra data after the request
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=62249
--- Comment #6 from Rainer Jung <ra...@kippdata.de> ---
(In reply to Konstantin J. Chernov from comment #4)
> I aborted the request (on the client) after retreiving a pstack. I can wait
> for 30s (Timeout value) if that matters.
>
> Here's the access.log entry:
> [02/Apr/2018:16:31:19 +0300] [127.0.0.1]=>[127.0.0.1:port] [pid 21515:tid
> 27] [C:AGaYFZrpYKA] [WsIwp9buuLz3q3TeUyRXQgAAAdg] "POST /path/to/app
> HTTP/1.1" 200 1891 9555277/9s 1982 6639 TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384
>
> Here's tomcat access.log entry:
> [02/Apr/2018:16:31:19 +0300] WsIwp9buuLz3q3TeUyRXQgAAAdg
> [127.0.0.1]=>[host:port] - HTTP/1.1:POST /path/to/app 200 [10 ms]
>
> Tomcat logs the time when request ended, apache logs the time when request
> started. 9s wasted somewhere unknown, without client receiving the response.
I don't see the 9 seconds in this example. Start at 16:31:19 (Apache), end at
16:31:19 (Tomcat). So the same second?
--
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