Bug 62568

Summary: ERR_INVALID_HTTP_RESPONSE as of 2.4.34 when listing directories
Product: Apache httpd-2 Reporter: snakedoctr
Component: mod_ratelimitAssignee: Apache HTTPD Bugs Mailing List <bugs>
Status: RESOLVED FIXED    
Severity: normal Keywords: FixedInTrunk
Priority: P2    
Version: 2.4.34   
Target Milestone: ---   
Hardware: PC   
OS: Linux   
Attachments: rate_limit_filter+header_only.patch
rate_limit_filter+header_only-v2.patch
rate_limit_filter+header_only-v3.patch
log1.txt

Description snakedoctr 2018-07-25 18:23:14 UTC 
After upgrading to v2.4.34 from v2.4.33, I'm encountering an "ERR_INVALID_HTTP_RESPONSE" via Chrome 68 as well as "Cancelled load from 'http://127.0.0.1/test/' because it is using HTTP/0.9.”" in Safari v11.1.2.

My (simple) mod_ratelimit config looks like:

SetOutputFilter RATE_LIMIT
SetEnv rate-limit 450

I only encounter this error when there are more than 61 files in the directory listing.  If i disable the SetEnv line, it works fine (since mod_ratelimit isn't actually doing anything).

To recreate the problem:
- Install v2.4.34
- Add the config listed above
- Run the following command from a browseable web directory (/test in my case):
    for NUM in `seq 1 62`; do touch $NUM; done
- Browse to the directory in a browser.  You should receive the error.

If you remove all the files in the directory and refresh the page it will work fine.  If you touch 61 files instead of 62 it will work fine.  But if you create >62 files it will throw the error.

tcpdump shows the file listing going through to the client, but the client chokes for some reason.
Comment 1 snakedoctr 2018-07-25 18:26:41 UTC 
I should have also said this is when using mod_dir (directory indexes).
Comment 2 Eric Covener 2018-07-25 18:30:23 UTC 
This regression is being worked here:
https://www.mail-archive.com/dev@httpd.apache.org/msg71614.html
Comment 3 Luca Toscano 2018-07-26 06:36:43 UTC 
Hi! 

Apologies for the regression, sadly we (most of the blame on me though!) failed to check chunked responses while testing. While trying to fix mod_ratelimit with proxied content we introduced a new bug, that forces the chunked content filter to emit the HTTP headers as body of the response.

I am going to attach to this bug the current patch that we are testing, any feedback would really be appreciated!
Comment 4 Luca Toscano 2018-07-26 06:37:20 UTC 
Created attachment 36049 [details]
rate_limit_filter+header_only.patch
Comment 5 snakedoctr 2018-07-26 11:06:49 UTC 
I applied the patch, and instead of the browser throwing an error like it did before the patch, it now dumps the raw HTML with headers at the top.  e.g.,

2061
HTTP/1.1 200 OK
Date: Thu, 26 Jul 2018 10:58:46 GMT
Server: Apache
Keep-Alive: timeout=5, max=100
Connection: Keep-Alive
Transfer-Encoding: chunked
Content-Type: text/html;charset=ISO-8859-1

<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 3.2 Final//EN">
<html>
 <head>
[...]

That was using the example I provided in my original bug report of touching 62 files in a directory and attempting to get a directory listing via mod_dir.
Comment 6 Luca Toscano 2018-07-27 08:55:03 UTC 
Thanks a lot for testing! In theory the patch should avoid the use case that you mentioned for last, and in my testing environment the repro case that you described works fine (directory listing with 62 files etc..). I did the following:

1) added a Directory and a Options +Indexes and your mod-ratelimit settings
2) created files in there as you suggested (even went to 500 to see if anything changed)
3) tested with Chrome, Safari and curl

Is there anything missing? Just be sure, have you applied the patch to a clean v2.4.34 working copy?

Luca
Comment 7 snakedoctr 2018-07-27 14:36:07 UTC 
That's weird.  I'm certain the patch is applied.  I'm using the FreeBSD ports version of 2.4.34, which does have some patches, but the patch is applying cleanly, so it should be fine.

What's weird is now I can't get it to dump the raw headers to the browser like I was able to yesterday.  It's throwing the browser errors like it was before even with the patch applied.
Comment 8 Luca Toscano 2018-07-27 14:53:31 UTC 
Can you try with curl or even telnet to see what the server returns?
Comment 9 snakedoctr 2018-07-27 15:04:46 UTC 
Curl is definitely showing the headers in the output.  e.g.

2029
HTTP/1.1 200 OK
Date: Fri, 27 Jul 2018 15:02:16 GMT
Server: Apache
Transfer-Encoding: chunked
Content-Type: text/html;charset=ISO-8859-1

<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 3.2 Final//EN">
<html>
 <head>
  <title>
[...]

And then at the end of the HTML it throws in a 0.  e.g.,

[...]
</body></html>

0
Comment 10 Luca Toscano 2018-07-27 15:43:27 UTC 
Ok good, this is exactly the problem that should be solved with the patch, let's concentrate on it. If you try without the patch, what do you get? In theory the same result, but a confirmation would be good.
Comment 11 snakedoctr 2018-07-27 15:48:20 UTC 
Removed the patch, and same result -- headers in output using curl.
Comment 12 Luca Toscano 2018-07-27 15:57:16 UTC 
Ah ok now I realized one thing, namely that in my dir listing tests I don't get a chunked response (don't see the Transfer-Encoding: chunked response header). Need to re-test it again and see if I can repro.
Comment 13 Yann Ylavic 2018-07-28 15:18:24 UTC 
I can't reproduce either with the patch applied.

snakedoctr, could you please provide the error_log with LogLevel trace7?
Comment 14 Yann Ylavic 2018-07-28 15:44:18 UTC 
Created attachment 36055 [details]
rate_limit_filter+header_only-v2.patch

This new patch adds a trace in the chunk-ing filter so that we can see the order of execution.
Thanks for testing with this one instead and provide the error_log with trace7.
Comment 15 snakedoctr 2018-07-30 17:00:27 UTC 
Here's my log with trace7.  The 12:56:xx time frame was /tmp directory with 0 files in it (success).  The 12:57:xx time frame was /tmp directory with 61 files in it (failure).

[Mon Jul 30 12:55:55.588267 2018] [core:trace4] [pid 85350] mpm_common.c(531): mpm child 85351 (gen 0/slot 0) exited
[Mon Jul 30 12:55:55.588319 2018] [core:trace4] [pid 85350] mpm_common.c(531): mpm child 85352 (gen 0/slot 1) exited
[Mon Jul 30 12:55:55.588384 2018] [core:info] [pid 85350] AH00096: removed PID file /var/run/httpd.pid (pid=85350)
[Mon Jul 30 12:55:55.588392 2018] [mpm_prefork:notice] [pid 85350] AH00169: caught SIGTERM, shutting down
[Mon Jul 30 12:55:55.600602 2018] [core:trace4] [pid 85350] mpm_common.c(428): end of generation 0
[Mon Jul 30 12:55:55.690551 2018] [ssl:trace2] [pid 85393] ssl_engine_rand.c(125): Init: Seeding PRNG with 144 bytes of entropy
[Mon Jul 30 12:55:55.690597 2018] [ssl:info] [pid 85393] AH01887: Init: Initializing (virtual) servers for SSL
[Mon Jul 30 12:55:55.690609 2018] [ssl:info] [pid 85393] AH01876: mod_ssl/2.4.34 compiled against Server: Apache/2.4.34, Library: OpenSSL/1.0.2k-freebsd
[Mon Jul 30 12:55:55.710887 2018] [ssl:trace2] [pid 85394] ssl_engine_rand.c(125): Init: Seeding PRNG with 144 bytes of entropy
[Mon Jul 30 12:55:55.710931 2018] [ssl:warn] [pid 85394] AH01873: Init: Session Cache is not configured [hint: SSLSessionCache]
[Mon Jul 30 12:55:55.710939 2018] [ssl:info] [pid 85394] AH01887: Init: Initializing (virtual) servers for SSL
[Mon Jul 30 12:55:55.710949 2018] [ssl:info] [pid 85394] AH01876: mod_ssl/2.4.34 compiled against Server: Apache/2.4.34, Library: OpenSSL/1.0.2k-freebsd
[Mon Jul 30 12:55:55.720077 2018] [core:trace4] [pid 85394] mpm_common.c(531): mpm child 85395 (gen 0/slot 0) started
[Mon Jul 30 12:55:55.720472 2018] [core:trace4] [pid 85394] mpm_common.c(531): mpm child 85396 (gen 0/slot 1) started
[Mon Jul 30 12:55:55.720489 2018] [mpm_prefork:notice] [pid 85394] AH00163: Apache/2.4.34 (FreeBSD) OpenSSL/1.0.2o-freebsd PHP/5.6.36 configured -- resuming normal operations
[Mon Jul 30 12:55:55.720495 2018] [mpm_prefork:info] [pid 85394] AH00164: Server built: unknown
[Mon Jul 30 12:55:55.720514 2018] [core:notice] [pid 85394] AH00094: Command line: '/usr/local/sbin/httpd -D NOHTTPACCEPT'
[Mon Jul 30 12:55:55.720520 2018] [core:debug] [pid 85394] log.c(1568): AH02639: Using SO_REUSEPORT: no (1)
[Mon Jul 30 12:55:55.720526 2018] [mpm_prefork:debug] [pid 85394] prefork.c(918): AH00165: Accept mutex: none (default: flock)
[Mon Jul 30 12:56:21.945657 2018] [core:trace5] [pid 85395] protocol.c(708): [client 192.168.10.10:53596] Request received from client: GET /tmp/ HTTP/1.1
[Mon Jul 30 12:56:21.945749 2018] [http:trace4] [pid 85395] http_request.c(436): [client 192.168.10.10:53596] Headers received from client:
[Mon Jul 30 12:56:21.945758 2018] [http:trace4] [pid 85395] http_request.c(439): [client 192.168.10.10:53596]   Host: 127.0.0.1:8081
[Mon Jul 30 12:56:21.945764 2018] [http:trace4] [pid 85395] http_request.c(439): [client 192.168.10.10:53596]   Connection: keep-alive
[Mon Jul 30 12:56:21.945770 2018] [http:trace4] [pid 85395] http_request.c(439): [client 192.168.10.10:53596]   Cache-Control: max-age=0
[Mon Jul 30 12:56:21.945776 2018] [http:trace4] [pid 85395] http_request.c(439): [client 192.168.10.10:53596]   Upgrade-Insecure-Requests: 1
[Mon Jul 30 12:56:21.945782 2018] [http:trace4] [pid 85395] http_request.c(439): [client 192.168.10.10:53596]   User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/68.0.3440.75 Safari/537.36
[Mon Jul 30 12:56:21.945788 2018] [http:trace4] [pid 85395] http_request.c(439): [client 192.168.10.10:53596]   Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8
[Mon Jul 30 12:56:21.945794 2018] [http:trace4] [pid 85395] http_request.c(439): [client 192.168.10.10:53596]   Accept-Encoding: gzip, deflate, br
[Mon Jul 30 12:56:21.945800 2018] [http:trace4] [pid 85395] http_request.c(439): [client 192.168.10.10:53596]   Accept-Language: en-US,en;q=0.9
[Mon Jul 30 12:56:21.945872 2018] [authz_core:debug] [pid 85395] mod_authz_core.c(817): [client 192.168.10.10:53596] AH01626: authorization result of Require all granted: granted
[Mon Jul 30 12:56:21.945882 2018] [authz_core:debug] [pid 85395] mod_authz_core.c(817): [client 192.168.10.10:53596] AH01626: authorization result of <RequireAny>: granted
[Mon Jul 30 12:56:21.945889 2018] [core:trace3] [pid 85395] request.c(302): [client 192.168.10.10:53596] request authorized without authentication by access_checker_ex hook: /tmp/
[Mon Jul 30 12:56:21.945997 2018] [authz_core:debug] [pid 85395] mod_authz_core.c(817): [client 192.168.10.10:53596] AH01626: authorization result of Require all granted: granted
[Mon Jul 30 12:56:21.946006 2018] [authz_core:debug] [pid 85395] mod_authz_core.c(817): [client 192.168.10.10:53596] AH01626: authorization result of <RequireAny>: granted
[Mon Jul 30 12:56:21.946012 2018] [core:trace3] [pid 85395] request.c(302): [client 192.168.10.10:53596] request authorized without authentication by access_checker_ex hook: /tmp/index.php
[Mon Jul 30 12:56:21.946322 2018] [http:trace3] [pid 85395] http_filters.c(1125): [client 192.168.10.10:53596] Response sent with status 200, headers:
[Mon Jul 30 12:56:21.946333 2018] [http:trace5] [pid 85395] http_filters.c(1134): [client 192.168.10.10:53596]   Date: Mon, 30 Jul 2018 16:56:21 GMT
[Mon Jul 30 12:56:21.946339 2018] [http:trace5] [pid 85395] http_filters.c(1137): [client 192.168.10.10:53596]   Server: Apache
[Mon Jul 30 12:56:21.946347 2018] [http:trace4] [pid 85395] http_filters.c(955): [client 192.168.10.10:53596]   Content-Length: 669
[Mon Jul 30 12:56:21.946353 2018] [http:trace4] [pid 85395] http_filters.c(955): [client 192.168.10.10:53596]   Keep-Alive: timeout=5, max=100
[Mon Jul 30 12:56:21.946359 2018] [http:trace4] [pid 85395] http_filters.c(955): [client 192.168.10.10:53596]   Connection: Keep-Alive
[Mon Jul 30 12:56:21.946365 2018] [http:trace4] [pid 85395] http_filters.c(955): [client 192.168.10.10:53596]   Content-Type: text/html;charset=ISO-8859-1
[Mon Jul 30 12:56:21.946387 2018] [core:trace6] [pid 85395] core_filters.c(523): [client 192.168.10.10:53596] core_output_filter: flushing because of FLUSH bucket
[Mon Jul 30 12:56:22.869157 2018] [core:trace4] [pid 85394] mpm_common.c(531): mpm child 85517 (gen 0/slot 2) started
[Mon Jul 30 12:56:26.950301 2018] [core:trace6] [pid 85395] core_filters.c(523): [client 192.168.10.10:53596] core_output_filter: flushing because of FLUSH bucket
[Mon Jul 30 12:57:13.241300 2018] [core:trace5] [pid 85517] protocol.c(708): [client 192.168.10.10:46599] Request received from client: GET /tmp/ HTTP/1.1
[Mon Jul 30 12:57:13.241395 2018] [http:trace4] [pid 85517] http_request.c(436): [client 192.168.10.10:46599] Headers received from client:
[Mon Jul 30 12:57:13.241404 2018] [http:trace4] [pid 85517] http_request.c(439): [client 192.168.10.10:46599]   Host: 127.0.0.1:8081
[Mon Jul 30 12:57:13.241410 2018] [http:trace4] [pid 85517] http_request.c(439): [client 192.168.10.10:46599]   Connection: keep-alive
[Mon Jul 30 12:57:13.241415 2018] [http:trace4] [pid 85517] http_request.c(439): [client 192.168.10.10:46599]   Cache-Control: max-age=0
[Mon Jul 30 12:57:13.241421 2018] [http:trace4] [pid 85517] http_request.c(439): [client 192.168.10.10:46599]   Upgrade-Insecure-Requests: 1
[Mon Jul 30 12:57:13.241427 2018] [http:trace4] [pid 85517] http_request.c(439): [client 192.168.10.10:46599]   User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/68.0.3440.75 Safari/537.36
[Mon Jul 30 12:57:13.241433 2018] [http:trace4] [pid 85517] http_request.c(439): [client 192.168.10.10:46599]   Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8
[Mon Jul 30 12:57:13.241438 2018] [http:trace4] [pid 85517] http_request.c(439): [client 192.168.10.10:46599]   Accept-Encoding: gzip, deflate, br
[Mon Jul 30 12:57:13.241444 2018] [http:trace4] [pid 85517] http_request.c(439): [client 192.168.10.10:46599]   Accept-Language: en-US,en;q=0.9
[Mon Jul 30 12:57:13.241518 2018] [authz_core:debug] [pid 85517] mod_authz_core.c(817): [client 192.168.10.10:46599] AH01626: authorization result of Require all granted: granted
[Mon Jul 30 12:57:13.241527 2018] [authz_core:debug] [pid 85517] mod_authz_core.c(817): [client 192.168.10.10:46599] AH01626: authorization result of <RequireAny>: granted
[Mon Jul 30 12:57:13.241534 2018] [core:trace3] [pid 85517] request.c(302): [client 192.168.10.10:46599] request authorized without authentication by access_checker_ex hook: /tmp/
[Mon Jul 30 12:57:13.241645 2018] [authz_core:debug] [pid 85517] mod_authz_core.c(817): [client 192.168.10.10:46599] AH01626: authorization result of Require all granted: granted
[Mon Jul 30 12:57:13.241654 2018] [authz_core:debug] [pid 85517] mod_authz_core.c(817): [client 192.168.10.10:46599] AH01626: authorization result of <RequireAny>: granted
[Mon Jul 30 12:57:13.241660 2018] [core:trace3] [pid 85517] request.c(302): [client 192.168.10.10:46599] request authorized without authentication by access_checker_ex hook: /tmp/index.php
[Mon Jul 30 12:57:13.242996 2018] [http:trace3] [pid 85517] http_filters.c(1125): [client 192.168.10.10:46599] Response sent with status 200, headers:
[Mon Jul 30 12:57:13.243007 2018] [http:trace5] [pid 85517] http_filters.c(1134): [client 192.168.10.10:46599]   Date: Mon, 30 Jul 2018 16:57:13 GMT
[Mon Jul 30 12:57:13.243013 2018] [http:trace5] [pid 85517] http_filters.c(1137): [client 192.168.10.10:46599]   Server: Apache
[Mon Jul 30 12:57:13.243021 2018] [http:trace4] [pid 85517] http_filters.c(955): [client 192.168.10.10:46599]   Keep-Alive: timeout=5, max=100
[Mon Jul 30 12:57:13.243027 2018] [http:trace4] [pid 85517] http_filters.c(955): [client 192.168.10.10:46599]   Connection: Keep-Alive
[Mon Jul 30 12:57:13.243033 2018] [http:trace4] [pid 85517] http_filters.c(955): [client 192.168.10.10:46599]   Transfer-Encoding: chunked
[Mon Jul 30 12:57:13.243039 2018] [http:trace4] [pid 85517] http_filters.c(955): [client 192.168.10.10:46599]   Content-Type: text/html;charset=ISO-8859-1
[Mon Jul 30 12:57:13.243172 2018] [:notice] [pid 85517] [client 192.168.10.10:46599] ap_http_chunk_filter()
[Mon Jul 30 12:57:13.243267 2018] [core:trace6] [pid 85517] core_filters.c(523): [client 192.168.10.10:46599] core_output_filter: flushing because of FLUSH bucket
[Mon Jul 30 12:57:13.305550 2018] [core:trace6] [pid 85517] core_filters.c(523): [client 192.168.10.10:46599] core_output_filter: flushing because of FLUSH bucket
[Mon Jul 30 12:57:13.387674 2018] [core:trace5] [pid 85395] protocol.c(708): [client 192.168.10.10:46600] Request received from client: GET /tmp/ HTTP/1.1
[Mon Jul 30 12:57:13.387719 2018] [http:trace4] [pid 85395] http_request.c(436): [client 192.168.10.10:46600] Headers received from client:
[Mon Jul 30 12:57:13.387727 2018] [http:trace4] [pid 85395] http_request.c(439): [client 192.168.10.10:46600]   Host: 127.0.0.1:8081
[Mon Jul 30 12:57:13.387733 2018] [http:trace4] [pid 85395] http_request.c(439): [client 192.168.10.10:46600]   Connection: keep-alive
[Mon Jul 30 12:57:13.387739 2018] [http:trace4] [pid 85395] http_request.c(439): [client 192.168.10.10:46600]   Cache-Control: max-age=0
[Mon Jul 30 12:57:13.387744 2018] [http:trace4] [pid 85395] http_request.c(439): [client 192.168.10.10:46600]   Upgrade-Insecure-Requests: 1
[Mon Jul 30 12:57:13.387750 2018] [http:trace4] [pid 85395] http_request.c(439): [client 192.168.10.10:46600]   User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/68.0.3440.75 Safari/537.36
[Mon Jul 30 12:57:13.387756 2018] [http:trace4] [pid 85395] http_request.c(439): [client 192.168.10.10:46600]   Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8
[Mon Jul 30 12:57:13.387762 2018] [http:trace4] [pid 85395] http_request.c(439): [client 192.168.10.10:46600]   Accept-Encoding: gzip, deflate, br
[Mon Jul 30 12:57:13.387768 2018] [http:trace4] [pid 85395] http_request.c(439): [client 192.168.10.10:46600]   Accept-Language: en-US,en;q=0.9
[Mon Jul 30 12:57:13.387805 2018] [authz_core:debug] [pid 85395] mod_authz_core.c(817): [client 192.168.10.10:46600] AH01626: authorization result of Require all granted: granted
[Mon Jul 30 12:57:13.387814 2018] [authz_core:debug] [pid 85395] mod_authz_core.c(817): [client 192.168.10.10:46600] AH01626: authorization result of <RequireAny>: granted
[Mon Jul 30 12:57:13.387820 2018] [core:trace3] [pid 85395] request.c(302): [client 192.168.10.10:46600] request authorized without authentication by access_checker_ex hook: /tmp/
[Mon Jul 30 12:57:13.387901 2018] [authz_core:debug] [pid 85395] mod_authz_core.c(817): [client 192.168.10.10:46600] AH01626: authorization result of Require all granted: granted
[Mon Jul 30 12:57:13.387909 2018] [authz_core:debug] [pid 85395] mod_authz_core.c(817): [client 192.168.10.10:46600] AH01626: authorization result of <RequireAny>: granted
[Mon Jul 30 12:57:13.387915 2018] [core:trace3] [pid 85395] request.c(302): [client 192.168.10.10:46600] request authorized without authentication by access_checker_ex hook: /tmp/index.php
[Mon Jul 30 12:57:13.389122 2018] [http:trace3] [pid 85395] http_filters.c(1125): [client 192.168.10.10:46600] Response sent with status 200, headers:
[Mon Jul 30 12:57:13.389134 2018] [http:trace5] [pid 85395] http_filters.c(1134): [client 192.168.10.10:46600]   Date: Mon, 30 Jul 2018 16:57:13 GMT
[Mon Jul 30 12:57:13.389140 2018] [http:trace5] [pid 85395] http_filters.c(1137): [client 192.168.10.10:46600]   Server: Apache
[Mon Jul 30 12:57:13.389147 2018] [http:trace4] [pid 85395] http_filters.c(955): [client 192.168.10.10:46600]   Keep-Alive: timeout=5, max=100
[Mon Jul 30 12:57:13.389152 2018] [http:trace4] [pid 85395] http_filters.c(955): [client 192.168.10.10:46600]   Connection: Keep-Alive
[Mon Jul 30 12:57:13.389158 2018] [http:trace4] [pid 85395] http_filters.c(955): [client 192.168.10.10:46600]   Transfer-Encoding: chunked
[Mon Jul 30 12:57:13.389164 2018] [http:trace4] [pid 85395] http_filters.c(955): [client 192.168.10.10:46600]   Content-Type: text/html;charset=ISO-8859-1
[Mon Jul 30 12:57:13.389288 2018] [:notice] [pid 85395] [client 192.168.10.10:46600] ap_http_chunk_filter()
[Mon Jul 30 12:57:13.389336 2018] [core:trace6] [pid 85395] core_filters.c(523): [client 192.168.10.10:46600] core_output_filter: flushing because of FLUSH bucket
[Mon Jul 30 12:57:13.448713 2018] [core:trace6] [pid 85395] core_filters.c(523): [client 192.168.10.10:46600] core_output_filter: flushing because of FLUSH bucket
[Mon Jul 30 12:57:17.878022 2018] [core:trace4] [pid 85394] mpm_common.c(531): mpm child 85395 (gen 0/slot 0) exited
[Mon Jul 30 12:57:17.878060 2018] [core:trace4] [pid 85394] mpm_common.c(531): mpm child 85396 (gen 0/slot 1) exited
[Mon Jul 30 12:57:17.878069 2018] [core:trace4] [pid 85394] mpm_common.c(531): mpm child 85517 (gen 0/slot 2) exited
[Mon Jul 30 12:57:17.878145 2018] [core:info] [pid 85394] AH00096: removed PID file /var/run/httpd.pid (pid=85394)
[Mon Jul 30 12:57:17.878154 2018] [mpm_prefork:notice] [pid 85394] AH00169: caught SIGTERM, shutting down
[Mon Jul 30 12:57:17.890206 2018] [core:trace4] [pid 85394] mpm_common.c(428): end of generation 0
Comment 16 Yann Ylavic 2018-07-30 19:30:53 UTC 
Created attachment 36058 [details]
rate_limit_filter+header_only-v3.patch

Sorry, I missed that mod_ratelimit would log nothing when no burst is configured, which makes the previous output quite useless.

Could you please retry with this new patch, trace7 still and possibly mod_dumpio configured like:
  LoadModule dumpio_module /path/to/mod_dumpio.so
  DumpioOutput on

Thanks.
Comment 17 snakedoctr 2018-07-31 02:36:04 UTC 
Created attachment 36059 [details]
log1.txt

Here is the log with mod_dumpio enabled.  

22:30:xx = without rate limiting enabled.
22:31:xx = with rate limiting enabled.
Comment 18 Yann Ylavic 2018-07-31 07:49:37 UTC 
There is no log message from mod_ratelimit, so somehow "mod_ratelimit.so" used at runtime isn't a patched one. Something went wrong in your patching/install procedure...
Comment 19 snakedoctr 2018-07-31 10:47:09 UTC 
That's weird.  I know mod_ratelimit is working, because when I load the directory with a configuration of "SetEnv rate-limit 4", it loads the raw HTML _extremely slow_ (as expected, at least with regard to the download speed), but when I increase it from 4 to 450, for example, it loads it much quicker (instantly). 
 And when I comment out that line completely, the directory index works fine.
Comment 20 Yann Ylavic 2018-07-31 10:57:28 UTC 
It seems that the original/old version is running, not the patched one.
By looking at the modification date of "mod_ratelimit.so" in your runtime tree, does it match the one of the build tree?
Comment 21 Yann Ylavic 2018-07-31 10:59:23 UTC 
And, by the way, did you ./configure with --enable-ratelimit=shared ?
Comment 22 snakedoctr 2018-07-31 11:26:36 UTC 
*doh*

I was just copying the sbin/httpd binary over, and not doing a full install (so that I could easily switch back to the non-patched version).  Obviously, that missed mod_ratelimit.so.  Once I did a full install w/the patched mod_ratelimit.so, things started working as expected.  

So all that to say the patch works!  Sorry for the mis-direction on my end!
Comment 23 Yann Ylavic 2018-07-31 11:37:41 UTC 
OK, thanks for the clarification and tests.
Comment 24 Yann Ylavic 2018-07-31 11:38:45 UTC 
Committed to trunk in r1837130.
Comment 25 Luca Toscano 2018-07-31 14:00:00 UTC 
(In reply to Yann Ylavic from comment #24)
> Committed to trunk in r1837130.

Thanks a lot for the fix Yann! In @dev Cory proposed another solution (mod_ratelimit only), can we also follow up in there to find an agreement and more people that have tested this?
Comment 26 Luca Toscano 2018-08-30 07:41:43 UTC 
Backported in r1839497, will be part of the next httpd 2.4 release.
Comment 27 Jean Weisbuch 2018-10-24 16:08:06 UTC 
I still have the issue on 2.4.37, doing a HEAD on a simple file containing "ok" does fail each time ("curl -I THEURL" returns "curl: (52) Empty reply from server") while a GET on it (as well as on a 1Gio file) does work (most of the time at least).
--


I compiled it with the logging patch, here is what i got on a working GET on the file containing "ok" :
[webserver] [Wed Oct 24 18:00:45.903534 2018] <500> [ratelimit:notice] [pid 22457] [client 10.94.325.20:51504] rate_limit_filter()
[webserver] [Wed Oct 24 18:00:45.903564 2018] <500> [ratelimit:debug] [pid 22457] mod_ratelimit.c(203): [client 10.94.325.20:51504] AH03485: rl: chunk 2097152; burst 1048576; len 202; rem 0
[webserver] [Wed Oct 24 18:00:45.903570 2018] <500> [ratelimit:notice] [pid 22457] [client 10.94.325.20:51504] rate_limit_filter()
[webserver] [Wed Oct 24 18:00:45.903572 2018] <500> [ratelimit:debug] [pid 22457] mod_ratelimit.c(203): [client 10.94.325.20:51504] AH03485: rl: chunk 2097152; burst 1048374; len 205; rem 0


A failing HEAD of the same file :
[webserver] [Wed Oct 24 18:00:52.427441 2018] <500> [ratelimit:notice] [pid 22788] [client 10.94.325.20:51508] rate_limit_filter()
[webserver] [Wed Oct 24 18:00:52.427468 2018] <500> [ratelimit:debug] [pid 22788] mod_ratelimit.c(203): [client 10.94.325.20:51508] AH03485: rl: chunk 2097152; burst 1048576; len 202; rem 0
Comment 28 Rainer Jung 2018-10-24 18:07:13 UTC 
Why do you think your observation has any realtion to this bug here. The original bug is about directory listings and you problem seems to be HEAD against an existing file system object.

Please post your observations to the users list first. People will try to help you and find out, whether it is a bug for whih you would only then open a new issue here.

When posting to the users list don't forget to add infomration abou your server config, server log entries and for curl also the output when you use the "-v -k" flags in addition.

Regards,

Rainer