Bug 63192

Summary: mod_ratelimit breaks HEAD requests
Product: Apache httpd-2 Reporter: Jean Weisbuch <jean>
Component: mod_ratelimitAssignee: Apache HTTPD Bugs Mailing List <bugs>
Status: RESOLVED FIXED    
Severity: major CC: marcin
Priority: P2 Keywords: FixedInTrunk
Version: 2.4.38   
Target Milestone: ---   
Hardware: PC   
OS: Linux   
Attachments: Don't eat EOS in ap_http_header_filter() for single brigade HEAD responses (trunk)
Don't eat EOS in ap_http_header_filter() for single brigade HEAD responses (2.4.x)

Description Jean Weisbuch 2019-02-20 17:39:40 UTC 
Since upgrading to 2.4.34, mod_ratelimit breaks HEAD requests, the problem still exists in 2.4.38.

Doing a HEAD on a simple text file containing "ok" does fail each time while a GET on the same URL does work (most of the time at least).
Also to note that rate limiting on GET requests does work as expected and that setting a rate-initial-burst superior to the request size doesnt fix the issue.

$ curl -I -vvv http://server.local/check
*   Trying 10.xx.xxx.92...
* TCP_NODELAY set
* Connected to server.local (10.xx.xxx.92) port 80 (#0)
> HEAD /check HTTP/1.1
> Host: server.local
> User-Agent: curl/7.61.0
> Accept: */*
> 
* Empty reply from server
* Connection #0 to host server.local left intact
curl: (52) Empty reply from server

The trace log :
[Wed Feb 20 17:53:38.867696 2019] [core:trace5] [pid 101123] protocol.c(710): [client 10.xx.xxx.20:60016] Request received from client: HEAD /check HTTP/1.1
[Wed Feb 20 17:53:38.867803 2019] [http:trace4] [pid 101123] http_request.c(437): [client 10.xx.xxx.20:60016] Headers received from client:
[Wed Feb 20 17:53:38.867814 2019] [http:trace4] [pid 101123] http_request.c(441): [client 10.xx.xxx.20:60016]   Host: server.local
[Wed Feb 20 17:53:38.867820 2019] [http:trace4] [pid 101123] http_request.c(441): [client 10.xx.xxx.20:60016]   User-Agent: curl/7.61.0
[Wed Feb 20 17:53:38.867826 2019] [http:trace4] [pid 101123] http_request.c(441): [client 10.xx.xxx.20:60016]   Accept: */*
[Wed Feb 20 17:53:38.867976 2019] [authz_core:debug] [pid 101123] mod_authz_core.c(846): [client 10.xx.xxx.20:60016] AH01628: authorization result: granted (no directives)
[Wed Feb 20 17:53:38.867986 2019] [core:trace3] [pid 101123] request.c(304): [client 10.xx.xxx.20:60016] request authorized without authentication by access_checker_ex hook: /check
[Wed Feb 20 17:53:38.868056 2019] [http:trace3] [pid 101123] http_filters.c(1128): [client 10.xx.xxx.20:60016] Response sent with status 200, headers:
[Wed Feb 20 17:53:38.868065 2019] [http:trace5] [pid 101123] http_filters.c(1135): [client 10.xx.xxx.20:60016]   Date: Wed, 20 Feb 2019 16:53:38 GMT
[Wed Feb 20 17:53:38.868071 2019] [http:trace5] [pid 101123] http_filters.c(1138): [client 10.xx.xxx.20:60016]   Server: Apache/2.4.38 (Unix)
[Wed Feb 20 17:53:38.868079 2019] [http:trace4] [pid 101123] http_filters.c(957): [client 10.xx.xxx.20:60016]   Last-Modified: Sat, 23 Dec 2006 07:40:14 GMT
[Wed Feb 20 17:53:38.868085 2019] [http:trace4] [pid 101123] http_filters.c(957): [client 10.xx.xxx.20:60016]   ETag: \"3-42540accb9380\"
[Wed Feb 20 17:53:38.868091 2019] [http:trace4] [pid 101123] http_filters.c(957): [client 10.xx.xxx.20:60016]   Accept-Ranges: bytes
[Wed Feb 20 17:53:38.868096 2019] [http:trace4] [pid 101123] http_filters.c(957): [client 10.xx.xxx.20:60016]   Content-Length: 3
[Wed Feb 20 17:53:38.868113 2019] [ratelimit:debug] [pid 101123] mod_ratelimit.c(196): [client 10.xx.xxx.20:60016] AH03485: rl: burst 1048576; len 198
[Wed Feb 20 17:53:38.868131 2019] [core:trace8] [pid 101123] core_filters.c(580): [client 10.xx.xxx.20:60016] brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 1, morphing buckets: 0
[Wed Feb 20 17:53:38.868157 2019] [core:trace6] [pid 101123] core_filters.c(525): [client 10.xx.xxx.20:60016] will flush because of FLUSH bucket
[Wed Feb 20 17:53:38.868164 2019] [core:trace8] [pid 101123] core_filters.c(535): [client 10.xx.xxx.20:60016] seen in brigade so far: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0
[Wed Feb 20 17:53:38.868171 2019] [core:trace8] [pid 101123] core_filters.c(554): [client 10.xx.xxx.20:60016] flushing now
[Wed Feb 20 17:53:38.868177 2019] [core:trace8] [pid 101123] core_filters.c(569): [client 10.xx.xxx.20:60016] total bytes written: 0
[Wed Feb 20 17:53:38.868183 2019] [core:trace8] [pid 101123] core_filters.c(580): [client 10.xx.xxx.20:60016] brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0
[Wed Feb 20 17:53:39.034116 2019] [core:trace4] [pid 101117] mpm_common.c(536): mpm child 101282 (gen 0/slot 5) started
[Wed Feb 20 17:53:43.873359 2019] [core:trace6] [pid 101123] core_filters.c(525): [client 10.xx.xxx.20:60016] will flush because of FLUSH bucket
[Wed Feb 20 17:53:43.873420 2019] [core:trace8] [pid 101123] core_filters.c(535): [client 10.xx.xxx.20:60016] seen in brigade so far: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0
[Wed Feb 20 17:53:43.873428 2019] [core:trace8] [pid 101123] core_filters.c(554): [client 10.xx.xxx.20:60016] flushing now
[Wed Feb 20 17:53:43.873434 2019] [core:trace8] [pid 101123] core_filters.c(569): [client 10.xx.xxx.20:60016] total bytes written: 0
[Wed Feb 20 17:53:43.873440 2019] [core:trace8] [pid 101123] core_filters.c(580): [client 10.xx.xxx.20:60016] brigade contains: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0

$ httpd -V
Server version: Apache/2.4.38 (Unix)
Server built:   Feb 20 2019 16:57:03
Server's Module Magic Number: 20120211:83
Server loaded:  APR 1.5.2, APR-UTIL 1.5.4
Compiled using: APR 1.5.2, APR-UTIL 1.5.4
Architecture:   64-bit
Server MPM:     prefork
  threaded:     no
    forked:     yes (variable process count)
Server compiled with....
 -D APR_HAS_SENDFILE
 -D APR_HAS_MMAP
 -D APR_HAVE_IPV6 (IPv4-mapped addresses enabled)
 -D APR_USE_SYSVSEM_SERIALIZE
 -D APR_USE_PTHREAD_SERIALIZE
 -D SINGLE_LISTEN_UNSERIALIZED_ACCEPT
 -D APR_HAS_OTHER_CHILD
 -D AP_HAVE_RELIABLE_PIPED_LOGS
 -D DYNAMIC_MODULE_LIMIT=256
 -D HTTPD_ROOT="/home/apache"
 -D SUEXEC_BIN="/home/apache/bin/suexec"
 -D DEFAULT_PIDLOG="logs/httpd.pid"
 -D DEFAULT_SCOREBOARD="logs/apache_runtime_status"
 -D DEFAULT_ERRORLOG="logs/error_log"
 -D AP_TYPES_CONFIG_FILE="conf/mime.types"
 -D SERVER_CONFIG_FILE="conf/httpd.conf"

httpd.conf :
ServerRoot "/home/apache"
LoadModule authz_core_module modules/mod_authz_core.so
LoadModule ratelimit_module modules/mod_ratelimit.so
LoadModule env_module modules/mod_env.so
LoadModule unixd_module modules/mod_unixd.so
User www-data
Group www-data
DocumentRoot "/home/test/www"
ErrorLog "/tmp/error.log"
LogLevel trace8
SetOutputFilter RATE_LIMIT
SetEnv rate-limit 10240
SetEnv rate-initial-burst 1024
Comment 1 Christophe JAILLET 2019-02-20 18:25:35 UTC 
> Since upgrading to 2.4.34

In order to help diagnose the potential regression, which version were you using before the upgrade?
Comment 2 Jean Weisbuch 2019-02-20 21:00:55 UTC 
(In reply to Christophe JAILLET from comment #1)
> > Since upgrading to 2.4.34
> 
> In order to help diagnose the potential regression, which version were you
> using before the upgrade?

It first appeared with 2.4.34 if i recall correctly, still happens on both 2.4.37 and 2.4.38.
Comment 3 Christophe JAILLET 2019-02-20 21:29:50 UTC 
The only modification that occurred in mod_ratelimit in 2.4.34 is r1835168.

I've reverted this commit and the behavior looks correct again (i.e. curl does not exits with "(52) Empty reply from server")
Comment 4 Yann Ylavic 2019-02-20 22:30:00 UTC 
Created attachment 36448 [details]
Don't eat EOS in ap_http_header_filter() for single brigade HEAD responses (trunk)

Does this patch work?
Comment 5 Yann Ylavic 2019-02-20 22:40:01 UTC 
Created attachment 36449 [details]
Don't eat EOS in ap_http_header_filter() for single brigade HEAD responses (2.4.x)

This version applies to 2.4.x branch.
Comment 6 Jean Weisbuch 2019-02-20 22:53:04 UTC 
(In reply to Yann Ylavic from comment #4)
> Created attachment 36448 [details]
> Don't eat EOS in ap_http_header_filter() for single brigade HEAD responses
> (trunk)
> 
> Does this patch work?

The 2.4.x version seems to fix the issue on 2.4.38, thanks.
Comment 7 Yann Ylavic 2019-02-20 23:11:07 UTC 
Thanks for testing, committed to trunk (r1854004).
Comment 8 Yann Ylavic 2019-03-13 10:31:39 UTC 
Backported to 2.4.x, will be in upcoming 2.4.39.
Comment 9 Ruediger Pluem 2021-10-15 17:28:07 UTC 
*** Bug 65636 has been marked as a duplicate of this bug. ***