Fixed auditlog in case of internal redirect

[AirisX]

The key problem is that in case of internal redirection, for example, to a custom error page, the logger registered on NGX_HTTP_LOG_PHASE will never work.

[AirisX]

I changed the value of the parameter SecAuditEngine on RelevantOnly in modsecurity-config-auditlog.t since before that all request to Nginx where logged in auditlog despite the rules. This caused false positive results. After that I added missing rules.

I also added a test cases for a custom error page displaying with ModSecurity enabled.

[AirisX]

I think that this PR should be improved. Although it gives expected behaviour when displaying a custom error page, but since the handler is running earlier, some information can't be falls into the audit log (e.g. response headers). Also, the response code in the audit log is not always correspond to reality.

[avkarenow]

Hello,

it's any change to have a working solution for this issue?

[awmackowiak]

When this PR will be merged?

[zimmerle]

Hi @awmackowiak,

I am sorry to say that this patch is still queued for review. There is no ETA yet. However, you can apply it under your own branch and make use of it. If you do, please let us know if there was any issue.

[jreisinger]

Hello guys. I think this is a really needed feature. You almost always want to show a custom error page for blocked request and at the same time you also want to know why the request was blocked. What is the reason of not merging this PR? Thanks.

[github-actions]

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 5 days

[jreisinger]

Hello guys. Can you re-open and consider this PR? We've been using https://github.com/AirisX/ModSecurity-nginx/tree/fix/auditlog for several months and haven't noticed any issue.

[victorhora]

The "nostale" tag has been set for this one and it's now reopened. We'll get to it when possible. Thank you.

[jreisinger]

Hello @zimmerle and @defanator, do you think it's possible to merge https://github.com/AirisX/ModSecurity-nginx/tree/fix/auditlog? Thanks.

[github-actions]

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 5 days

[jreisinger]

Hello @zimmerle and @defanator, can you review the MR?

[github-actions]

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 5 days

[martinhsv]

Given the 'nostale' tag, this item should not have been closed by the bot.

[github-actions]

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 5 days

[defanator]

@AirisX just made yet another attempt to check this one, and here's what I'm getting with additional tests incorporated into modsecurity-request-body.t:

diff --git a/tests/modsecurity-request-body.t b/tests/modsecurity-request-body.t
index 2d71c81..4e284a4 100644
--- a/tests/modsecurity-request-body.t
+++ b/tests/modsecurity-request-body.t
@@ -43,6 +43,37 @@ http {
         modsecurity on;
         client_header_buffer_size 1024;
 
+        error_page 500 502 503 504 /50x.html;
+        error_page 403 /403.html;
+
+        location /test-error-page {
+            modsecurity_rules '
+		#SecAuditEngine RelevantOnly
+		#SecAuditLogRelevantStatus "^(?:4((00)|(03)))"
+		SecAuditEngine RelevantOnly
+		SecAuditLogRelevantStatus "^(?:5|4(?!04))"
+		#SecAuditEngine On
+                SecAuditLogParts ABIJDEFHZ
+                SecAuditLog %%TESTDIR%%/auditlog-error-page.txt
+                SecAuditLogType Serial
+                SecAuditLogStorageDir %%TESTDIR%%
+                SecRuleEngine On
+                SecRequestBodyAccess On
+		SecDefaultAction "phase:1,log,deny,status:403"
+		SecDefaultAction "phase:2,log,deny,status:403"
+		SecDefaultAction "phase:3,log,deny,status:403"
+		SecDefaultAction "phase:4,log,deny,status:403"
+                SecRule REQUEST_BODY "@rx BAD BODY" "id:11,phase:request,deny,log,status:403"
+		SecDebugLog %%TESTDIR%%/modsec-debug.log
+                SecDebugLogLevel 9
+            ';
+            proxy_pass http://127.0.0.1:5555;
+            proxy_connect_timeout 1s;
+            proxy_read_timeout 1s;
+        }
+
+        location = /50x.html {}
+
         location /bodyaccess {
             modsecurity_rules '
                 SecRuleEngine On
@@ -121,10 +152,12 @@ http {
 }
 EOF
 
+$t->write_file('/50x.html', 'custom 50x error page');
+$t->write_file('/403.html', 'custom 403 error page');
 $t->run_daemon(\&http_daemon);
 $t->run()->waitforsocket('127.0.0.1:' . port(8081));
 
-$t->plan(40);
+$t->plan(42);
 
 ###############################################################################
 
@@ -170,6 +203,9 @@ foreach my $method (('GET', 'POST', 'PUT', 'DELETE')) {
 like(http_req_body($method, '/bodylimitrejectserver', 'BODY' x 33), qr/403 Forbidden/, "$method request body limit reject, block (inherited SecRequestBodyLimit)");
 }
 
+like(http_req_body('POST', '/test-error-page', 'BODY' x 8), qr/custom 50x error page/, 'error page (good body)');
+like(http_req_body('POST', '/test-error-page', 'BAD BODY' x 8), qr/custom 403 error page/, 'error page (bad body)');
+
 ###############################################################################
 
 sub http_daemon {

Tests are fine:

[..]
ok 41 - error page (good body)
ok 42 - error page (bad body)
ok 43 - no alerts
ok 44 - no sanitizer errors
ok
All tests successful.

Error log and access log entries are also fine:

127.0.0.1 - - [14/Jan/2021:12:54:10 +0000] "POST /test-error-page HTTP/1.1" 502 21 "-" "-"
127.0.0.1 - - [14/Jan/2021:12:54:10 +0000] "POST /test-error-page HTTP/1.1" 403 21 "-" "-"

2021/01/14 12:54:10 [error] 18310#18310: *73 connect() failed (111: Connection refused) while connecting to upstream, client: 127.0.0.1, server: localhost, request: "POST /test-error-page HTTP/1.1", upstream: "http://127.0.0.1:5555/test-error-page", host: "localhost"
2021/01/14 12:54:10 [error] 18310#18310: *75 [client 127.0.0.1] ModSecurity: Access denied with code 403 (phase 2). Matched "Operator `Rx' with parameter `BAD BODY' against variable `REQUEST_BODY' (Value: `BAD BODYBAD BODYBAD BODYBAD BODYBAD BODYBAD BODYBAD BODYBAD BODY' ) [file "<<reference missing or not informed>>"] [line "17"] [id "11"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "127.0.0.1"] [uri "/test-error-page"] [unique_id "1610628850"] [ref "o0,8v84,64"], client: 127.0.0.1, server: localhost, request: "POST /test-error-page HTTP/1.1", host: "localhost"

However, audit log contains the wrong response code:

test@vagrant:/tmp/nginx-test-klexxoygtL$ cat auditlog-error-page.txt 
---irI0lzl5---A--
[14/Jan/2021:12:54:10 +0000] 1610628850 127.0.0.1 28450 127.0.0.1 8350
---irI0lzl5---B--
POST /test-error-page HTTP/1.1
Host: localhost
Connection: close
Content-Length: 64

---irI0lzl5---D--

---irI0lzl5---F--
HTTP/1.1 200

---irI0lzl5---H--
ModSecurity: Access denied with code 200 (phase 2). Matched "Operator `Rx' with parameter `BAD BODY' against variable `REQUEST_BODY' (Value: `BAD BODYBAD BODYBAD BODYBAD BODYBAD BODYBAD BODYBAD BODYBAD BODY' ) [file "<<reference missing or not informed>>"] [line "17"] [id "11"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "127.0.0.1"] [uri "/test-error-page"] [unique_id "1610628850"] [ref "o0,8v84,64"]

---irI0lzl5---I--

---irI0lzl5---J--

---irI0lzl5---Z--

I saw your mention here - #90 (comment) - have you had any chance to look at this?

UPDATE: I took your original tests and did a few modifications incl. additional tests for response codes in audit log:
https://github.com/defanator/ModSecurity-nginx/blob/PR90/tests/modsecurity-config-custom-error-page.t#L160-L166
Still going to check whether there's an easy way to get as more details as possible at the actual logging stage (wherever it happens given the changes introduced by this PR).

[defanator]

@AirisX I made an initial attempt to improve at least a part about getting actual response code to audit logs here - https://github.com/defanator/ModSecurity-nginx/tree/PR90 (the defanator@cd3f904 commit). Appreciate if you would take a look.

@zimmerle is it safe to call msc_update_status_code() at the early stages of a transaction?

[zimmerle]

@zimmerle is it safe to call msc_update_status_code() at the early stages of a transaction?

msc_update_status_code will keep ModSecurity updated for the HTTP response code, it is basically used to feed the variable RESPONSE_STATUS and provide information for the AuditLogs.

This value for status code is also meant to be set whenever processResponseHeaders is called.

Not to confuse this value with the value set by the status action. ModSecurity may ask the webserver to return a given return code. Still, the webserver decides to perform something else. This value set on msc_update_status_code is meant to hold whatever the webserver returns to the user.

Having said that, if you set the status value before having the response headers ready, it may cause a mismatch between what you have expected to deliver and what was delivered. Regardless it is likely that the value is going to be updated by processResponseHeaders.

Keep in mind that the audit log will consider the last value set before its execution. Calling msc_update_status_code after processResponseHeaders but before the log phase will change the audit logs' value. Likewise, the RESPONSE_STATUS variable will have its value updated for each time msc_update_status_code is called.

The only problem that I can think of is if one may rely on the not defined behavior of using RESPONSE_STATUS in a rule whereas the phase is prior to what we understand to be a determined value for RESPONSE_STATUS -- Status code that is returned to the user.

As long as we inform ModSecurity the response status code correctly for the AuditLogs, I think it is safe to set the variable.

msc_update_status_code

https://github.com/SpiderLabs/ModSecurity/blob/6ca028b6f5713ea505bcdd39a43a1aaa4fba936e/src/transaction.cc#L1822-L1842

processResponseHeaders

https://github.com/SpiderLabs/ModSecurity/blob/6ca028b6f5713ea505bcdd39a43a1aaa4fba936e/src/transaction.cc#L1038-L1069

[zimmerle]

Thanks @AirisX and @defanator. Closing this in favor of: #241