Headers are already sent. Cannot perform the redirection at this point

[kpushkaryov]

I can't make the SecResponseBodyLimit directive together with SecResponseBodyLimitAction Reject block oversized responses from nginx. ModSecurity-nginx reports "Headers are already sent. Cannot perform the redirection at this point" to error.log. The client receives the response in full with code 200.

The results are similar when I use a rule instead, e.g. SecRule RESPONSE_CONTENT_LENGTH "@ge 10000" "phase:4,id:1,deny,log,msg:'Oversized response',status:403". There is "Headers are already sent" in error.log, but the client receives an empty response without status code. Three different status codes are reported in logs for this request: 500 is in access.log, 200 in error.log, 403 in ModSecurity audit log.

ModSecurity version: 3.0.5.
ModSecurity-nginx version: 1.0.2.
nginx version: 1.20.1.

nginx -V info:

nginx version: nginx/1.20.1
built with OpenSSL 1.1.1c FIPS  28 May 2019 (running with OpenSSL 1.1.1g FIPS  21 Apr 2020)
TLS SNI support enabled
configure arguments: --prefix=/usr/share --sbin-path=/usr/sbin/nginx --conf-path=/etc/nginx/nginx.conf --modules-path=/usr/share/nginx/modules --error-log-path=/var/log/nginx/error.log --http-log-path=/var/log/nginx/access.log --lock-path=/var/lock/nginx.lock --pid-path=/run/nginx.pid --http-client-body-temp-path=/var/lib/nginx/body --http-fastcgi-temp-path=/var/lib/nginx/fastcgi --http-proxy-temp-path=/var/lib/nginx/proxy --http-scgi-temp-path=/var/lib/nginx/scgi --http-uwsgi-temp-path=/var/lib/nginx/uwsgi --user=nginx --group=nginx --with-file-aio --with-compat --with-http_ssl_module --with-http_realip_module --with-http_sub_module --with-http_dav_module --with-http_gzip_static_module --with-http_stub_status_module --with-http_v2_module --add-dynamic-module=mod_brotli --add-dynamic-module=mod_passenger/src/nginx_module --add-dynamic-module=mod_pagespeed --add-dynamic-module=mod_security --with-debug --with-cc-opt='-O0 -g -DMODSECURITY_DDEBUG'

The config of nginx is as follows:

load_module nginx/modules/ngx_http_modsecurity_module.so;

events {
    worker_connections  1024;
}

error_log /nginx/log/error.log debug;

http {
	access_log /nginx/log/access.log;
	server {
		listen 127.0.0.1:8080;
		root /nginx/www;
	}
	modsecurity on;
	modsecurity_rules '
		SecRuleEngine On
		SecRequestBodyAccess On
		SecRequestBodyLimit 10240
		SecResponseBodyAccess On
		SecResponseBodyLimit 10240
		SecResponseBodyLimitAction Reject
		SecAuditEngine On
		SecAuditLog "/nginx/log/modsec_audit.log"
		SecAuditLogType serial
		SecDebugLog "/nginx/log/modsec_debug.log"
		SecDebugLogLevel 9
	';
}

In /nginx/www I have two text files, of which jack.txt is bigger than the response size limit of 10240 bytes:

-rw-r--r--. 1 root root 10750 Nov 10 09:44 jack.txt
-rw-r--r--. 1 root root     5 Nov 10 08:52 test.txt

When I access them, both files are returned successfully:

[root@host nginx]# curl -v http://127.0.0.1:8080/test.txt
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to 127.0.0.1 (127.0.0.1) port 8080 (#0)
> GET /test.txt HTTP/1.1
> Host: 127.0.0.1:8080
> User-Agent: curl/7.61.1
> Accept: */*
> 
< HTTP/1.1 200 OK
< Server: nginx/1.20.1
< Date: Wed, 10 Nov 2021 05:50:28 GMT
< Content-Type: text/plain
< Content-Length: 5
< Last-Modified: Wed, 10 Nov 2021 01:52:49 GMT
< Connection: keep-alive
< ETag: "618b25f1-5"
< Accept-Ranges: bytes
< 
Test
* Connection #0 to host 127.0.0.1 left intact
[root@host nginx]# curl -v http://127.0.0.1:8080/jack.txt
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to 127.0.0.1 (127.0.0.1) port 8080 (#0)
> GET /jack.txt HTTP/1.1
> Host: 127.0.0.1:8080
> User-Agent: curl/7.61.1
> Accept: */*
> 
< HTTP/1.1 200 OK
< Server: nginx/1.20.1
< Date: Wed, 10 Nov 2021 05:51:06 GMT
< Content-Type: text/plain
< Content-Length: 10750
< Last-Modified: Wed, 10 Nov 2021 02:44:01 GMT
< Connection: keep-alive
< ETag: "618b31f1-29fe"
< Accept-Ranges: bytes
< 
All work and no play makes Jack a dull boy
All work and no play makes Jack a dull boy
<...>
* Connection #0 to host 127.0.0.1 left intact

The most relevant part of error.log is:

modsec *** ngx_http_modsecurity_header_filter: header filter, recovering ctx: 0x15bfb58 at mod_security/src/ngx_http_modsecurity_header_filter.c line 425.
modsec *** ngx_http_modsecurity_header_filter:  Sending header to ModSecurity - header: `Server'. at mod_security/src/ngx_http_modsecurity_header_filter.c line 474.
modsec *** ngx_http_modsecurity_header_filter:  Sending header to ModSecurity - header: `Date'. at mod_security/src/ngx_http_modsecurity_header_filter.c line 474.
modsec *** ngx_http_modsecurity_header_filter:  Sending header to ModSecurity - header: `Content-Length'. at mod_security/src/ngx_http_modsecurity_header_filter.c line 474.
modsec *** ngx_http_modsecurity_header_filter:  Sending header to ModSecurity - header: `Content-Type'. at mod_security/src/ngx_http_modsecurity_header_filter.c line 474.
modsec *** ngx_http_modsecurity_header_filter:  Sending header to ModSecurity - header: `Last-Modified'. at mod_security/src/ngx_http_modsecurity_header_filter.c line 474.
modsec *** ngx_http_modsecurity_header_filter:  Sending header to ModSecurity - header: `Connection'. at mod_security/src/ngx_http_modsecurity_header_filter.c line 474.
modsec *** ngx_http_modsecurity_header_filter:  Sending header to ModSecurity - header: `Transfer-Encoding'. at mod_security/src/ngx_http_modsecurity_header_filter.c line 474.
modsec *** ngx_http_modsecurity_header_filter:  Sending header to ModSecurity - header: `Vary'. at mod_security/src/ngx_http_modsecurity_header_filter.c line 474.
modsec *** ngx_http_modsecurity_process_intervention: processing intervention at mod_security/src/ngx_http_modsecurity_module.c line 143.
modsec *** ngx_http_modsecurity_process_intervention: nothing to do at mod_security/src/ngx_http_modsecurity_module.c line 152.
2021/11/10 12:51:06 [debug] 97144#0: *2 HTTP/1.1 200 OK
Server: nginx/1.20.1
Date: Wed, 10 Nov 2021 05:51:06 GMT
Content-Type: text/plain
Content-Length: 10750
Last-Modified: Wed, 10 Nov 2021 02:44:01 GMT
Connection: keep-alive
ETag: "618b31f1-29fe"
Accept-Ranges: bytes

2021/11/10 12:51:06 [debug] 97144#0: *2 write new buf t:1 f:0 000000000163DDD0, pos 000000000163DDD0, size: 242 file: 0, size: 0
2021/11/10 12:51:06 [debug] 97144#0: *2 http write filter: l:0 f:0 s:242
2021/11/10 12:51:06 [debug] 97144#0: *2 http output filter "/jack.txt?"
2021/11/10 12:51:06 [debug] 97144#0: *2 http copy filter: "/jack.txt?"
2021/11/10 12:51:06 [debug] 97144#0: *2 malloc: 0000000001644D20:10750
2021/11/10 12:51:06 [debug] 97144#0: *2 read: 18, 0000000001644D20, 10750, 0
2021/11/10 12:51:06 [debug] 97144#0: *2 http postpone filter "/jack.txt?" 000000000163DFD0
modsec *** ngx_http_modsecurity_body_filter: body filter, recovering ctx: 0x15bfb58 at mod_security/src/ngx_http_modsecurity_body_filter.c line 53.
modsec *** ngx_http_modsecurity_process_intervention: processing intervention at mod_security/src/ngx_http_modsecurity_module.c line 143.
2021/11/10 12:51:06 [error] 97144#0: *2 Response body limit is marked to reject the request while sending response to client, client: 127.0.0.1, server: , request: "GET /jack.txt HTTP/1.1", host: "127.0.0.1:8080"
modsec *** ngx_http_modsecurity_process_intervention: Headers are already sent. Cannot perform the redirection at this point. at mod_security/src/ngx_http_modsecurity_module.c line 226.
modsec *** ngx_http_modsecurity_process_intervention: processing intervention at mod_security/src/ngx_http_modsecurity_module.c line 143.
modsec *** ngx_http_modsecurity_process_intervention: nothing to do at mod_security/src/ngx_http_modsecurity_module.c line 152.

In modsec_audit.log we see that ModSecurity assigned code 403 to the oversized response:

[10/Nov/2021:12:51:06 +0700] 1636523466 127.0.0.1 46242 127.0.0.1 8080
---OeksdokT---B--
GET /jack.txt HTTP/1.1
Host: 127.0.0.1:8080
User-Agent: curl/7.61.1
Accept: */*

---OeksdokT---F--
HTTP/1.1 403
Server: nginx/1.20.1
Date: Wed, 10 Nov 2021 05:51:06 GMT
Content-Length: 10750
Content-Type: text/plain
Last-Modified: Wed, 10 Nov 2021 02:44:01 GMT
Connection: keep-alive
ETag: "618b31f1-29fe"

---OeksdokT---H--

---OeksdokT---Z--

Also, inspection of modsec_debug.log confirms that the request is to be rejected:

[1636523466] [/jack.txt] [4] Starting phase RESPONSE_HEADERS. (SecRules 3)
[1636523466] [/jack.txt] [9] This phase consists of 0 rule(s).
[1636523466] [/jack.txt] [9] Appending response body: 10750 bytes. Limit set to: 10240.000000
[1636523466] [/jack.txt] [5] Response body is bigger than the maximum expected.
[1636523466] [/jack.txt] [5] Response body limit is marked to reject the request
[1636523466] [/jack.txt] [4] Starting phase RESPONSE_BODY. (SecRules 4)

Nevertheless, the client receives the response in full with code 200.

As far as I understand, when ModSecurity tries to block the response it's too late, as its headers have already been sent.

I've tried to debug the issue myself. As error.log shows, response headers are sent between ngx_http_modsecurity_header_filter() and ngx_http_modsecurity_body_filter(). Looking from GDB, the headers are sent by ngx_http_header_filter() at the end of the filter chain:

Breakpoint 1, ngx_http_modsecurity_header_filter (r=0x4) at mod_security/src/ngx_http_modsecurity_header_filter.c:410
410	{
(gdb) n
412	    ngx_list_part_t *part = &r->headers_out.headers.part;
(gdb) p r->header_sent
$2 = 0
(gdb) watch r->header_sent
Hardware watchpoint 2: r->header_sent
(gdb) cont
Continuing.

Hardware watchpoint 2: r->header_sent

Old value = 0
New value = 1
ngx_http_header_filter (r=0x1913360) at src/http/ngx_http_header_filter_module.c:178
178	    if (r != r->main) {
(gdb) bt
#0  ngx_http_header_filter (r=0x1913360) at src/http/ngx_http_header_filter_module.c:178
#1  0x00000000004bc330 in ngx_http_chunked_header_filter (r=0x1913360) at src/http/modules/ngx_http_chunked_filter_module.c:100
#2  0x00000000004bcfc7 in ngx_http_v2_header_filter (r=0x1913360) at src/http/v2/ngx_http_v2_filter_module.c:167
#3  0x00000000004c2b80 in ngx_http_range_header_filter (r=0x1913360) at src/http/modules/ngx_http_range_filter_module.c:264
#4  0x00000000004c4681 in ngx_http_gzip_header_filter (r=0x1913360) at src/http/modules/ngx_http_gzip_filter_module.c:239
#5  0x00007f1b226ea011 in ngx_http_modsecurity_header_filter (r=0x1913360) at mod_security/src/ngx_http_modsecurity_header_filter.c:557
#6  0x00000000004c6ec7 in ngx_http_ssi_header_filter (r=0x1913360) at src/http/modules/ngx_http_ssi_filter_module.c:341
#7  0x00000000004cda86 in ngx_http_charset_header_filter (r=0x1913360) at src/http/modules/ngx_http_charset_filter_module.c:236
#8  0x00000000004d1087 in ngx_http_sub_header_filter (r=0x1913360) at src/http/modules/ngx_http_sub_filter_module.c:186
#9  0x00000000004d33ce in ngx_http_userid_filter (r=0x1913360) at src/http/modules/ngx_http_userid_filter_module.c:239
#10 0x00000000004d4d31 in ngx_http_headers_filter (r=0x1913360) at src/http/modules/ngx_http_headers_filter_module.c:183
#11 0x00000000004d6c41 in ngx_http_not_modified_header_filter (r=0x1913360) at src/http/modules/ngx_http_not_modified_filter_module.c:108
#12 0x000000000047aefa in ngx_http_send_header (r=0x1913360) at src/http/ngx_http_core_module.c:1848
#13 0x00000000004e5221 in ngx_http_static_handler (r=0x1913360) at src/http/modules/ngx_http_static_module.c:247
#14 0x0000000000479af9 in ngx_http_core_content_phase (r=0x1913360, ph=0x18d73c8) at src/http/ngx_http_core_module.c:1266
#15 0x0000000000478962 in ngx_http_core_run_phases (r=0x1913360) at src/http/ngx_http_core_module.c:875
#16 0x00000000004788cb in ngx_http_handler (r=0x1913360) at src/http/ngx_http_core_module.c:858
#17 0x0000000000489378 in ngx_http_process_request (r=0x1913360) at src/http/ngx_http_request.c:2106
#18 0x0000000000487b79 in ngx_http_process_request_headers (rev=0x18db2b0) at src/http/ngx_http_request.c:1508
#19 0x0000000000486eb5 in ngx_http_process_request_line (rev=0x18db2b0) at src/http/ngx_http_request.c:1175
#20 0x0000000000485488 in ngx_http_wait_request_handler (rev=0x18db2b0) at src/http/ngx_http_request.c:503
#21 0x0000000000461141 in ngx_epoll_process_events (cycle=0x188ae20, timer=60000, flags=1) at src/event/modules/ngx_epoll_module.c:901
#22 0x000000000044d016 in ngx_process_events_and_timers (cycle=0x188ae20) at src/event/ngx_event.c:247
#23 0x000000000045dfc7 in ngx_worker_process_cycle (cycle=0x188ae20, data=0x0) at src/os/unix/ngx_process_cycle.c:719
#24 0x000000000045a559 in ngx_spawn_process (cycle=0x188ae20, proc=0x45ded6 <ngx_worker_process_cycle>, data=0x0, name=0x534b2a "worker process", respawn=-3) at src/os/unix/ngx_process.c:199
#25 0x000000000045cd6a in ngx_start_worker_processes (cycle=0x188ae20, n=1, type=-3) at src/os/unix/ngx_process_cycle.c:344
#26 0x000000000045c3fa in ngx_master_process_cycle (cycle=0x188ae20) at src/os/unix/ngx_process_cycle.c:130
#27 0x00000000004130f8 in main (argc=3, argv=0x7ffd8c626e28) at src/core/nginx.c:383

This happens before response body processing and I can't see what should have stopped nginx from sending the headers before the body was checked by ModSecurity.

An archive file with all logs, config and data files mentioned above is attached.
nginx.zip

[martinhsv]

Hi @kpushkaryov ,

This sounds like fundamentally the same issue as #41.

Feel free to correct me if you think I am mistaken.

[kpushkaryov]

@martinhsv, the issues may be related, but I'm not sure. The error messages are similar, but still different. Also, SecResponseBodyLimit isn't mentioned there and I don't know whether the two cases are processed in the same way inside nginx.