Apache ErrorDocument is not executed when error code has been rewritten in Phase 4

[rcbarnett-zz]

MODSEC-385: (Same behavior which was written in https://www.modsecurity.org/tracker/browse/MODSEC-183.)

Basically the problem is that, although the right status code returns to the client, the appropriate ErrorDocument doesn't appear in a browser. Furthermore, there are no indication in strace that apache even tried to open any ErrorDocument page.

Setup:
Apache config has ErrorDocument 403 /error/403.html

Basic modsecurity configuration, two more line added:
SecRule REQUEST_URI attack "id:'1',phase:1,log,deny,status:403"
SecRule RESPONSE_STATUS "@eq 500" "phase:4,deny,status:403,id:1111"

Response to the first:
http://s18.postimage.org/hmr0y4sax/custom403working.png

Text form:
"http://192.168.110.139/attack

403

This is my custom error message page, every 403 should be end up with this. "

Response to the second:
http://s18.postimage.org/l530uit6x/custom403notworking.png

Text form:
"http://192.168.110.139/test.php

Forbidden

You don't have permission to access /test.php on this server.

Additionally, a 403 Forbidden error was encountered while trying to use an ErrorDocument to handle the request.
Apache/2.2.22 (Ubuntu) Server at 192.168.110.139 Port 80"

Test.php (this triggers an Error 500):

It seems, in Phase 4 (as a matter of fact Phase 3 produces the same) response rewrite can't end on a custom ErrorDocument page for some reason. Even funnier, if I modify the line for the sake of testing as below:
SecRule RESPONSE_STATUS "@eq 500" "phase:4,deny,status:200,id:1111"

Response:
OK

The server encountered an internal error or misconfiguration and was unable to complete your request.

Please contact the server administrator, webmaster@localhost and inform them of the time the error occurred, and anything you might have done that may have caused the error.

More information about this error may be available in the server error log.

Additionally, a 200 OK error was encountered while trying to use an ErrorDocument to handle the request.

Apache/2.2.22 (Ubuntu) Server at 192.168.110.139 Port 80

If you need any more information please let me know.

[rcbarnett-zz]

Original reporter: degetz

I was wondering if there was any insight into a work around for this issue? http://sourceforge.net/p/mod-security/mailman/message/24053417/ seems to explain fairly closely the problem we are having.

We have ProxyErrorOverride Off since we want to log the original error message and with it on the response going to the browser is a 500 not a 403 as per the mod_security rule.

One item that is not explained is that we can use the string format of ErrorDocument, for example, ErrorDocument 403 "Access Denied" works, however ErrorDocument 403 /error403.html does not.

[victorhora]

Couldn't reproduce this with latest commit from 2.9.x branch.

My test environment was the following:

Linux alpine38 4.14.69-0-virt #1-Alpine SMP Mon Sep 10 19:55:02 UTC 2018 x86_64 Linux

Server version: Apache/2.4.34 (Unix)
Server built:   Aug 20 2018 10:36:38
Server's Module Magic Number: 20120211:79
Server loaded:  APR 1.6.3, APR-UTIL 1.6.1
Compiled using: APR 1.6.3, APR-UTIL 1.6.1
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

Tested with Apache conf/rules:

ErrorDocument 500 "The server made a boo boo."
ErrorDocument 403 /forbidden.html
ErrorDocument 404 /missing.html
SecRule REQUEST_URI attack "id:'1',phase:1,auditlog,log,deny,status:403"
SecRule RESPONSE_PROTOCOL "@contains HTTP" "id:'4',phase:4,auditlog,log,deny,status:403,msg:'yay!'"

Custom ErrorDocument file:

alpine38:/var/www/localhost/htdocs# cat forbidden.html
alpine38:/var/www/localhost/htdocs# cat forbidden.html
Testing CUSTOM APACHE ErrorDocument: 403 FORBIDDEN

Curl command

curl -v localhost/
*   Trying ::1...
* TCP_NODELAY set
* Connected to localhost (::1) port 80 (#0)
> GET / HTTP/1.1
> Host: localhost
> User-Agent: curl/7.61.1
> Accept: */*
>
< HTTP/1.1 403 Forbidden
< Date: Sun, 07 Oct 2018 17:28:55 GMT
< Server: Apache/2.4.34 (Unix)
< Last-Modified: Sun, 07 Oct 2018 17:20:20 GMT
< ETag: "33-577a6b81d6cac"
< Accept-Ranges: bytes
< Content-Length: 51
< Content-Type: text/html
<
Testing CUSTOM APACHE ErrorDocument: 403 FORBIDDEN
* Connection #0 to host localhost left intact

Debug logs:

[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/][4] Initialising transaction (txid W7pDXJpy6cQXzuGyd3J6ZAAAAAA).
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/][4] Transaction context created (dcfg 55c9f82f6250).
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/][4] Starting phase REQUEST_HEADERS.
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/][9] This phase consists of 1 rule(s).
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/][4] Recipe: Invoking rule 55c9f83282e0; [file "/etc/apache2/conf.d/modsecurity.conf"] [line "239"] [id "1"].
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/][5] Rule 55c9f83282e0: SecRule "REQUEST_URI" "@rx attack" "phase:1,id:1,auditlog,log,deny,status:403"
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/][4] Transformation completed in 1 usec.
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/][4] Executing operator "rx" with param "attack" against REQUEST_URI.
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/][9] Target value: "/"
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/][4] Operator completed in 12 usec.
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/][4] Rule returned 0.
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/][9] No match, not chained -> mode NEXT_RULE.
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/][4] Second phase starting (dcfg 55c9f82f6250).
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/][4] Input filter: This request does not have a body.
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/][4] Starting phase REQUEST_BODY.
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/][9] This phase consists of 0 rule(s).
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/index.html][4] Hook insert_filter: Adding output filter (r 55c9f835eb20).
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/index.html][9] Output filter: Receiving output (f 55c9f836b5b8, r 55c9f835eb20).
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/index.html][4] Starting phase RESPONSE_HEADERS.
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/index.html][9] This phase consists of 0 rule(s).
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/index.html][9] Content Injection: Not enabled.
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/index.html][9] Output filter: Bucket type MMAP contains 45 bytes.
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/index.html][9] Output filter: Bucket type EOS contains 0 bytes.
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/index.html][4] Output filter: Completed receiving response body (buffered full - 45 bytes).
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/index.html][4] Starting phase RESPONSE_BODY.
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/index.html][9] This phase consists of 1 rule(s).
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/index.html][4] Recipe: Invoking rule 55c9f83258d0; [file "/etc/apache2/conf.d/modsecurity.conf"] [line "242"] [id "4"].
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/index.html][5] Rule 55c9f83258d0: SecRule "RESPONSE_PROTOCOL" "@contains HTTP" "phase:4,id:4,auditlog,log,deny,status:403"
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/index.html][4] Transformation completed in 1 usec.
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/index.html][4] Executing operator "contains" with param "HTTP" against RESPONSE_PROTOCOL.
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/index.html][9] Target value: "HTTP/1.1"
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/index.html][4] Operator completed in 2 usec.
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/index.html][4] Rule returned 1.
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/index.html][9] Match, intercepted -> returning.
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/index.html][1] Access denied with code 403 (phase 4). String match "HTTP" at RESPONSE_PROTOCOL. [file "/etc/apache2/conf.d/modsecurity.conf"] [line "242"] [id "4"]
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f835eb20][/index.html][4] Initialising logging.
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f836ba50][/forbidden.html][4] Starting phase LOGGING.
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f836ba50][/forbidden.html][9] This phase consists of 0 rule(s).
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f836ba50][/forbidden.html][4] Recording persistent data took 0 microseconds.
[07/Oct/2018:13:33:16 --0400] [localhost/sid#55c9f82d9c50][rid#55c9f836ba50][/forbidden.html][4] Audit log: Logging this transaction.

If the issue persists on a given environment, please let us know and we can investigate further.

[aogburn]

I can still reproduce. It seems @victorhora did not reproduce since that response originally had a 200 code. If the response originally has an error, then this issue is seen.

So testing this without the available proxy destination would result in a 503 that mod_security changes to 403:

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

The 503 is seen as a recursive error in ap_die_r of httpd so that it skips the ErrorDocument:

$ curl -v localhost/helloworld/foo
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to localhost (127.0.0.1) port 80 (#0)
> GET /helloworld/foo HTTP/1.1
> Host: localhost
> User-Agent: curl/7.61.1
> Accept: */*
> 
< 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>

I also raised https://bz.apache.org/bugzilla/show_bug.cgi?id=66290 for discussion and investigation from the httpd perspective.

[martinhsv]

Hello @aogburn ,

If you have a problem to report, it would be best to just open a new issue and fully describe it.

It is possible that you are describing some different use case than what this issue originally described. But even if this one was originally closed in error, given that this one has been closed for four years,h andling any currently-observed problem makes more sense via a new issue.

[marcstern]

I found the problem (and the solution).
In send_error_bucket(), we have the following line:
f->r->status_line = ap_get_status_line(status);
If we add that line:
f->r->status = 200;
it tell httpd that we're not (yet) inside an ErrorDocument processing, so it has to try using ErrorDocument diectives containing a URL. If we leave the existing status different from 200, it thinks that the status comes from a local URL defined with ErrorDocument.

[aogburn]

Thanks @marcstern, yes that would explain the problem behavior here. Is there any PR of that change? This issue is the same originally reported here by others. So can we further handle here or do I need to copy/paste to a new report and lose the history here?