Bug 2256551

Summary: ErrorDocument is not sent when mod_security changes error code in phase 3/4
Product: [Fedora] Fedora Reporter: Luboš Uhliarik <luhliari>
Component: mod_securityAssignee: Luboš Uhliarik <luhliari>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: unspecified    
Version: rawhideCC: jorton, luhliari
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Linux   
Whiteboard:
Fixed In Version: mod_security-2.9.7-4.fc39 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2024-01-12 01:11:17 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Luboš Uhliarik 2024-01-03 00:06:19 UTC 
Description of problem:

It seems this is a long standing issue between mod_security and httpd:

https://github.com/SpiderLabs/ModSecurity/issues/533
https://bz.apache.org/bugzilla/show_bug.cgi?id=66290

Using a simplified config like this with mod_security:

ProxyPass /helloworld http://unavailablesite/helloworld
ErrorDocument 403 /forbidden.html
SecRule RESPONSE_PROTOCOL "@contains HTTP" "id:'4',phase:4,auditlog,log,deny,status:403,msg:'yay!'"

One would expect for mod_security to override the 503 with a 403 and provide the custom 403 ErrorDocument. (More realistic scenarios are using the core rule set, which will change a 5xx level response code to a 403 at paranoia level 2)

The response code is changed to 403, but it suggests the ErrorDocument can't be served:

<html><head>
<title>403 Forbidden</title>
</head><body>
<h1>Forbidden</h1>
<p>You don't have permission to access this resource.</p>
<p>Additionally, a 503 Service Unavailable
error was encountered while trying to use an ErrorDocument to handle the request.</p>
</body></html>

If you do proxy through to the backend and that returns another error code like 500, then this reports that 500 (or whatever from the backend) was encountered instead while serving the ErrorDocument. If you test a local page that would return a 200, then mod_security can set the 403 and serve out the ErrorDocument.

From logs and backtracking, I see no indication that the ErrorDocument is attempted and no ap_internal_redirect call. So stepping through logs and backtraces, the proxy connection fails and the processing steps into ap_die. No ErrorDocument is set for this code so it falls through:

===
[Fri Sep 30 17:38:22.633786 2022] [proxy_fcgi:debug] [pid 73359] mod_proxy_fcgi.c(1021): [client 127.0.0.1:32980] AH01076: url: http://127.0.0.1:8080/helloworld/foo proxyname: (null) proxyport: 0
[Fri Sep 30 17:38:22.633794 2022] [proxy_fcgi:debug] [pid 73359] mod_proxy_fcgi.c(1024): [client 127.0.0.1:32980] AH01077: declining URL http://127.0.0.1:8080/helloworld/foo
[Fri Sep 30 17:38:22.633803 2022] [proxy_http:trace1] [pid 73359] mod_proxy_http.c(1978): [client 127.0.0.1:32980] HTTP: serving URL http://127.0.0.1:8080/helloworld/foo
[Fri Sep 30 17:38:22.633812 2022] [proxy:debug] [pid 73359] proxy_util.c(2353): AH00942: HTTP: has acquired connection for (127.0.0.1)
[Fri Sep 30 17:38:22.633822 2022] [proxy:debug] [pid 73359] proxy_util.c(2408): [client 127.0.0.1:32980] AH00944: connecting http://127.0.0.1:8080/helloworld/foo to 127.0.0.1:8080
[Fri Sep 30 17:38:22.633833 2022] [proxy:debug] [pid 73359] proxy_util.c(2634): [client 127.0.0.1:32980] AH00947: connected /helloworld/foo to 127.0.0.1:8080
[Fri Sep 30 17:38:22.633896 2022] [proxy:trace2] [pid 73359] proxy_util.c(3070): HTTP: fam 2 socket created to connect to 127.0.0.1
[Fri Sep 30 17:38:22.634041 2022] [proxy:error] [pid 73359] (111)Connection refused: AH00957: HTTP: attempt to connect to 127.0.0.1:8080 (127.0.0.1) failed
[Fri Sep 30 17:38:22.634062 2022] [proxy_http:error] [pid 73359] [client 127.0.0.1:32980] AH01114: HTTP: failed to make connection to backend: 127.0.0.1
[Fri Sep 30 17:38:22.634071 2022] [proxy:debug] [pid 73359] proxy_util.c(2368): AH00943: HTTP: has released connection for (127.0.0.1)

(gdb) bt
#0 0x0000561b30a2db70 in ap_die_r ()
#1 0x0000561b30a2e627 in ap_process_async_request ()
#2 0x0000561b30a2e9c2 in ap_process_request ()
#3 0x0000561b30a2abe5 in ap_process_http_connection ()
#4 0x0000561b30a210c8 in ap_run_process_connection ()
#5 0x00007f3c11be6e71 in child_main () from target:/etc/httpd/modules/mod_mpm_prefork.so
#6 0x00007f3c11be7174 in make_child () from target:/etc/httpd/modules/mod_mpm_prefork.so
#7 0x00007f3c11be71cf in startup_children () from target:/etc/httpd/modules/mod_mpm_prefork.so
#8 0x00007f3c11be7db3 in prefork_run () from target:/etc/httpd/modules/mod_mpm_prefork.so
#9 0x0000561b309f915e in ap_run_mpm ()
#10 0x0000561b309f1733 in main ()

#0 0x0000561b30a082c0 in ap_response_code_string ()
#1 0x0000561b30a2de26 in ap_die_r ()
#2 0x0000561b30a2e627 in ap_process_async_request ()
#3 0x0000561b30a2e9c2 in ap_process_request ()
#4 0x0000561b30a2abe5 in ap_process_http_connection ()
#5 0x0000561b30a210c8 in ap_run_process_connection ()
#6 0x00007f3c11be6e71 in child_main () from target:/etc/httpd/modules/mod_mpm_prefork.so
#7 0x00007f3c11be7174 in make_child () from target:/etc/httpd/modules/mod_mpm_prefork.so
#8 0x00007f3c11be71cf in startup_children () from target:/etc/httpd/modules/mod_mpm_prefork.so
#9 0x00007f3c11be7db3 in prefork_run () from target:/etc/httpd/modules/mod_mpm_prefork.so
#10 0x0000561b309f915e in ap_run_mpm ()
#11 0x0000561b309f1733 in main ()

Thread 1 "httpd" hit Breakpoint 3, 0x0000561b30a082c0 in ap_response_code_string ()
(gdb) bt
#0 0x0000561b30a082c0 in ap_response_code_string ()
#1 0x0000561b30a2c944 in ap_send_error_response ()
#2 0x0000561b30a2e627 in ap_process_async_request ()
#3 0x0000561b30a2e9c2 in ap_process_request ()
#4 0x0000561b30a2abe5 in ap_process_http_connection ()
#5 0x0000561b30a210c8 in ap_run_process_connection ()
#6 0x00007f3c11be6e71 in child_main () from target:/etc/httpd/modules/mod_mpm_prefork.so
#7 0x00007f3c11be7174 in make_child () from target:/etc/httpd/modules/mod_mpm_prefork.so
#8 0x00007f3c11be71cf in startup_children () from target:/etc/httpd/modules/mod_mpm_prefork.so
#9 0x00007f3c11be7db3 in prefork_run () from target:/etc/httpd/modules/mod_mpm_prefork.so
#10 0x0000561b309f915e in ap_run_mpm ()
#11 0x0000561b309f1733 in main ()
===

After those points, mod_security sets its 403. ap_die_r is called again out of ap_http_header_filter. It never hits ap_response_code_string in this ap_die_r call though to fetch the ErrorDocument for this 403:
===
[Fri Sep 30 17:41:05.331091 2022] [:error] [pid 73359] [client 127.0.0.1:32980] [client 127.0.0.1] ModSecurity: Access denied with code 403 (phase 4). String match "HTTP" at RESPONSE_PROTOCOL. [file "/etc/httpd/conf.d/mod_security.conf"] [line "62"] [id "4"] [msg "yay!"] [hostname "localhost"] [uri "/helloworld/foo"] [unique_id "AAAAAMGZhzPXJ45OHYQdKAAAAAA"]

#0 0x0000561b30a2db70 in ap_die_r ()
#1 0x0000561b30a31b74 in ap_http_header_filter ()
#2 0x0000561b309ff1b6 in ap_content_length_filter ()
#3 0x0000561b30a32e81 in ap_byterange_filter ()
#4 0x00007f3c0b475bae in send_error_bucket (msr=msr@entry=0x561b31e220a0, f=f@entry=0x561b31e15210, status=status@entry=403) at apache2_util.c:43
#5 0x00007f3c0b4758a3 in output_filter (f=0x561b31e15210, bb_in=<optimized out>) at apache2_io.c:999
#6 0x0000561b309fced2 in end_output_stream ()
#7 0x0000561b30a2ca30 in ap_send_error_response ()
#8 0x0000561b30a2e627 in ap_process_async_request ()
#9 0x0000561b30a2e9c2 in ap_process_request ()
#10 0x0000561b30a2abe5 in ap_process_http_connection ()
#11 0x0000561b30a210c8 in ap_run_process_connection ()
#12 0x00007f3c11be6e71 in child_main () from target:/etc/httpd/modules/mod_mpm_prefork.so
#13 0x00007f3c11be7174 in make_child () from target:/etc/httpd/modules/mod_mpm_prefork.so
#14 0x00007f3c11be71cf in startup_children () from target:/etc/httpd/modules/mod_mpm_prefork.so
#15 0x00007f3c11be7db3 in prefork_run () from target:/etc/httpd/modules/mod_mpm_prefork.so
#16 0x0000561b309f915e in ap_run_mpm ()
#17 0x0000561b309f1733 in main ()

Thread 1 "httpd" hit Breakpoint 3, 0x0000561b30a082c0 in ap_response_code_string ()
(gdb) bt
#0 0x0000561b30a082c0 in ap_response_code_string ()
#1 0x0000561b30a2c944 in ap_send_error_response ()
#2 0x0000561b30a31b74 in ap_http_header_filter ()
#3 0x0000561b309ff1b6 in ap_content_length_filter ()
#4 0x0000561b30a32e81 in ap_byterange_filter ()
#5 0x00007f3c0b475bae in send_error_bucket (msr=msr@entry=0x561b31e220a0, f=f@entry=0x561b31e15210, status=status@entry=403) at apache2_util.c:43
#6 0x00007f3c0b4758a3 in output_filter (f=0x561b31e15210, bb_in=<optimized out>) at apache2_io.c:999
#7 0x0000561b309fced2 in end_output_stream ()
#8 0x0000561b30a2ca30 in ap_send_error_response ()
#9 0x0000561b30a2e627 in ap_process_async_request ()
#10 0x0000561b30a2e9c2 in ap_process_request ()
#11 0x0000561b30a2abe5 in ap_process_http_connection ()
#12 0x0000561b30a210c8 in ap_run_process_connection ()
#13 0x00007f3c11be6e71 in child_main () from target:/etc/httpd/modules/mod_mpm_prefork.so
#14 0x00007f3c11be7174 in make_child () from target:/etc/httpd/modules/mod_mpm_prefork.so
#15 0x00007f3c11be71cf in startup_children () from target:/etc/httpd/modules/mod_mpm_prefork.so
#16 0x00007f3c11be7db3 in prefork_run () from target:/etc/httpd/modules/mod_mpm_prefork.so
#17 0x0000561b309f915e in ap_run_mpm ()
#18 0x0000561b309f1733 in main ()
===

So it looks like mod_security through phase 3/4 will result in the 403 being set in the course of ap_http_header_filter calls. That means this calls ap_die here passing in the 403 and also 503 on the request originally:

https://github.com/apache/httpd/blob/2.4.37/modules/http/http_filters.c#L1374

That 503 is then picked up here in ap_die_r as a recursive_error so that it skips the ap_response_code_string call in its else and the ErrorDocument is not served as a result:

https://github.com/apache/httpd/blob/3ec0ffb9e1ac05622b97a7afd6992dd2bd41ce38/modules/http/http_request.c#L127

So the ErrorDocument works for a page that originally had a 200 since there is not a recursive_error seen by ap_die_r in that case.

How reproducible:

Always

Steps to Reproduce:
1. Configure httpd/mod_security with:

ProxyPass /helloworld http://unavailablesite/helloworld
ErrorDocument 403 /forbidden.html
SecRule RESPONSE_PROTOCOL "@contains HTTP" "id:'4',phase:4,auditlog,log,deny,status:403,msg:'yay!'"

2. $ curl -v localhost/helloworld/foo

Actual results:

< HTTP/1.1 403 Forbidden
< Date: Fri, 30 Sep 2022 21:38:22 GMT
< Server: Apache/2.4.37 (Red Hat Enterprise Linux) OpenSSL/1.1.1k
< Connection: close
< Content-Type: text/html; charset=iso-8859-1
<
<!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
<html><head>
<title>403 Forbidden</title>
</head><body>
<h1>Forbidden</h1>
<p>You don't have permission to access this resource.</p>
<p>Additionally, a 503 Service Unavailable
error was encountered while trying to use an ErrorDocument to handle the request.</p>
</body></html>

Expected results:

httpd returns configured ErrorDocument

Additional info:

A string for the ErrorDocument is successfully returned:

ErrorDocument 403 "forbidden"



Reproducible: Always
Comment 1 Fedora Update System 2024-01-03 00:50:00 UTC 
FEDORA-2024-abf8d50571 has been submitted as an update to Fedora 39. https://bodhi.fedoraproject.org/updates/FEDORA-2024-abf8d50571
Comment 2 Fedora Update System 2024-01-04 01:03:08 UTC 
FEDORA-2024-abf8d50571 has been pushed to the Fedora 39 testing repository.
Soon you'll be able to install the update with the following command:
`sudo dnf upgrade --enablerepo=updates-testing --refresh --advisory=FEDORA-2024-abf8d50571`
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2024-abf8d50571

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.
Comment 3 Fedora Update System 2024-01-12 01:11:17 UTC 
FEDORA-2024-abf8d50571 has been pushed to the Fedora 39 stable repository.
If problem still persists, please make note of it in this bug report.