ModSecurity 3 and NginX-Connector only logging with SecRuleEngine On

[aadlung]

Dear ModSecurity-Team,

I've setup ModSecurity 3 including the nginx connector. If I turn it on for testing with SecRuleEngine On - I get the audit log, and debug log, and blocking requests if rules match.

If I just use SecRuleEngine DetectionOnly I do not get any audit or error log.

Is this "as designed", or anything that needs to be turned on in addition? Even test rules do not trigger any logs, even with SecAuditEngine On.

Regards,
Andy

[aadlung]

Update: In the DEBUG logs, I see the rules, this is for example my debug log with log level 9. Even the test rule is being matched, and the message shows that something should be written to the logs, but my /var/log/modsec_audit.log and /var/log/nginx/error.log stays empty.

[4] Initializing transaction
[4] Transaction context created.
[4] Starting phase CONNECTION. (SecRules 0)
[9] This phase consists of 0 rule(s).
[4] Starting phase URI. (SecRules 0 + 1/2)
[4] Adding request argument (GET): name "testparam", value "test"
[4] Starting phase REQUEST_HEADERS.  (SecRules 1)
[9] This phase consists of 4 rule(s).
[4] (Rule: 1234) Executing operator "Contains" with param "test" against ARGS:testparam.
[9] Target value: "test" (Variable: ARGS:testparam)
[9] Matched vars updated.
[9] Rule contains a `pass' action
[4] Running [independent] (non-disruptive) action: log
[9] Saving transaction to logs
[4] Rule returned 1.
[4] Not running disruptive action: pass. SecRuleEngine is not On
[4] Running (non-disruptive) action: auditlog
[4] (Rule: 200000) Executing operator "Rx" with param "(?:application(?:/soap\+|/)|text/)xml" against REQUEST_HEADERS:Content-Type.
[4] Rule returned 0.

[zimmerle]

Hi @aadlung,

The audit logs should be saved while SecAuditEngine is On or RelevantOnly, however, SecAuditLogRelevantStatus is taking into consideration in both cases.

The logs are saved by the end of the transaction, during logging phase. Check in your debug logs for something similar to this:

(...)
[4] Starting phase LOGGING. (SecRules 5)
[9] This phase consists of 0 rule(s).
[8] Checking if this request is suitable to be saved as an audit log.
[8] Checking if this request is relevant to be part of the audit logs.
[5] Saving this request as part of the audit logs.
[8] Request was relevant to be saved. Parts: 4430
[9] JSON: Cleaning up JSON results
(...)

That should give you a hint why your logs are not being saved.

[aadlung]

I will check again - with Detection Only - no Logging Phase is executed in the debug logs, I do not find one. If I take the same configuration, just change the SecAuditEngine to On, everything works as expected.
Maybe as the "On" creates a HTTP 403 this is then matched in the RelevantStatus, although the documentation states this is just used if SecAuditEngine is set to RelevantOnly.

But I think I will have to play around maybe the RelevantStatus is used all the time as @zimmerle mentioned compared to the documentation.

[9] JSON parser initialization
[9] yajl JSON parsing callback initialization
[4] Initializing transaction
[4] Transaction context created.
[4] Starting phase CONNECTION. (SecRules 0)
[9] This phase consists of 0 rule(s).
[4] Starting phase URI. (SecRules 0 + 1/2)
[4] Adding request argument (GET): name "testparam", value "test"
[4] Starting phase REQUEST_HEADERS.  (SecRules 1)
[9] This phase consists of 4 rule(s).
[4] (Rule: 1234) Executing operator "Contains" with param "test" against ARGS:testparam.
[9] Target value: "test" (Variable: ARGS:testparam)
[9] Matched vars updated.
[4] Running [independent] (non-disruptive) action: log
[9] Saving transaction to logs
[4] Running [independent] (non-disruptive) action: msg
[9] Saving msg: Our test rule has triggered
[4] Rule returned 1.
[4] Running (disruptive)     action: deny
[8] Running action deny
[4] Running (non-disruptive) action: auditlog
[4] Running (non-disruptive) action: status
[8] Skipping this phase as this request was already intercepted.
[4] Starting phase RESPONSE_HEADERS. (SecRules 3)
[9] This phase consists of 0 rule(s).
[9] Appending response body: 0 bytes. Limit set to: 524288.000000
[9] Appending response body: 0 bytes. Limit set to: 524288.000000
[4] Starting phase RESPONSE_BODY. (SecRules 4)
[9] This phase consists of 0 rule(s).
[4] Starting phase LOGGING. (SecRules 5)
[9] This phase consists of 0 rule(s).
[8] Checking if this request is suitable to be saved as an audit log.
[8] Checking if this request is relevant to be part of the audit logs.
[5] Saving this request as part of the audit logs.
[8] Request was relevant to be saved. Parts: 6006
[9] JSON: Cleaning up JSON results

Same config with "DetectionOnly":

[9] JSON parser initialization
[9] yajl JSON parsing callback initialization
[4] Initializing transaction
[4] Transaction context created.
[4] Starting phase CONNECTION. (SecRules 0)
[9] This phase consists of 0 rule(s).
[4] Starting phase URI. (SecRules 0 + 1/2)
[4] Adding request argument (GET): name "testparam", value "test"
[4] Starting phase REQUEST_HEADERS.  (SecRules 1)
[9] This phase consists of 4 rule(s).
[4] (Rule: 1234) Executing operator "Contains" with param "test" against ARGS:testparam.
[9] Target value: "test" (Variable: ARGS:testparam)
[9] Matched vars updated.
[4] Running [independent] (non-disruptive) action: log
[9] Saving transaction to logs
[4] Running [independent] (non-disruptive) action: msg
[9] Saving msg: Our test rule has triggered
[4] Rule returned 1.
[4] Not running disruptive action: deny. SecRuleEngine is not On
[4] Running (non-disruptive) action: auditlog
[4] Running (non-disruptive) action: status
[4] (Rule: 200000) Executing operator "Rx" with param "(?:application(?:/soap\+|/)|text/)xml" against REQUEST_HEADERS:Content-Type.
[4] Rule returned 0.
[9] Matched vars cleaned.
[4] (Rule: 200001) Executing operator "Rx" with param "application/json" against REQUEST_HEADERS:Content-Type.
[4] Rule returned 0.
[9] Matched vars cleaned.
[4] (Rule: 900990) Executing unconditional rule...
[9] Rule contains a `pass' action
[4] Running [independent] (non-disruptive) action: setvar
[8] Saving variable: TX:crs_setup_version with value: 302
[4] Running (non-disruptive) action: nolog
[4] Not running disruptive action: pass. SecRuleEngine is not On
[4] Starting phase REQUEST_BODY. (SecRules 2)
[9] This phase consists of 4 rule(s).
[4] (Rule: 200002) Executing operator "Eq" with param "0" against REQBODY_ERROR.
[6] Resolving: reqbody_error_msg to: NULL
[9] Target value: "0" (Variable: REQBODY_ERROR)
[4] Rule returned 0.
[9] Matched vars cleaned.
[4] (Rule: 200003) Executing operator "Eq" with param "0" against MULTIPART_STRICT_ERROR.
[6] Resolving: REQBODY_PROCESSOR_ERROR to: 0
[6] Resolving: MULTIPART_BOUNDARY_QUOTED to: NULL
[6] Resolving: MULTIPART_BOUNDARY_WHITESPACE to: NULL
[6] Resolving: MULTIPART_DATA_BEFORE to: NULL
[6] Resolving: MULTIPART_DATA_AFTER to: NULL
[6] Resolving: MULTIPART_HEADER_FOLDING to: NULL
[6] Resolving: MULTIPART_LF_LINE to: NULL
[6] Resolving: MULTIPART_MISSING_SEMICOLON to: NULL
[6] Resolving: MULTIPART_INVALID_QUOTING to: NULL
[6] Resolving: MULTIPART_INVALID_PART to: NULL
[6] Resolving: MULTIPART_INVALID_HEADER_FOLDING to: NULL
[6] Resolving: MULTIPART_FILE_LIMIT_EXCEEDED to: NULL
[4] Rule returned 0.
[9] Matched vars cleaned.
[4] (Rule: 200004) Executing operator "Eq" with param "0" against MULTIPART_UNMATCHED_BOUNDARY.
[4] Rule returned 0.
[9] Matched vars cleaned.
[4] (Rule: 200005) Executing operator "StrEq" with param "0" against TX.
[6] Resolving: MATCHED_VAR_NAME to: NULL
[4] Rule returned 0.
[9] Matched vars cleaned.
[9] JSON: Cleaning up JSON results

[zimmerle]

Hi @aadlung,

That is odd. The logging phase (as well the other phases), should be called regardless of the engine status. I will double check it.

[zimmerle]

@aadlung can you share your nginx debug logs? it may help to identify what is going on with the request life cycle.

[aadlung]

@zimmerle you mean logs of nginx, so switching nginx to debug logging mode, or the logs of mod security in another logging mode?

[zimmerle]

Hi @aadlung,

It is about the nginx debug logs. It will be even better if you can also enable the ModSecurity-nginx connector debug logs. That could be done by changing it here: https://github.com./SpiderLabs/ModSecurity-nginx/blob/master/src/ddebug.h#L15-L18

Notice that the connector debug log will be saved all together with the nginx debug logs.

[intelbg]

@zimmerle I confirm the same problem - libmodsecurity is compiled with son support and the log is empty (in if it's detection only and turned on). Here is attached debug log on level 9. Please review it and instruct me what I can do. Thank you in advance.
json-debug-log-9.txt

[missilefish]

I am also getting nowhere with the audit.log, I have a FP in my implementation when "SecRuleEngine On" but I can't find it in any log when setting "SecRuleEngine DetectionOnly" so I can run live.

nginx version: nginx/1.12.1
built by gcc 5.4.0 20160609 (Ubuntu 5.4.0-6ubuntu1~16.04.4)
built with OpenSSL 1.0.2g 1 Mar 2016
TLS SNI support enabled
configure arguments: --user=nginx --group=nginx --with-pcre-jit --with-debug --with-http_ssl_module --with-http_realip_module --add-module=/opt/ModSecurity-nginx

Also my modsecurity.conf is using OWASP rules and I have been alternating things like this below to try and trigger a clean log of the rule.

#SecDefaultAction "phase:1,log,auditlog,deny,status:403"
#SecDefaultAction "phase:2,log,auditlog,deny,status:403"

SecDefaultAction "phase:1,log,auditlog,pass"
SecDefaultAction "phase:2,log,auditlog,pass"

I can't get concurrent logging or serial to do anything for an actual rule violation event

[edward-02020]

I discovered Modsecurity V3 can't logging when I custom the nginx 403 page. Maybe when we use custom error page,the nginx status code looks like 200?
Whether error_page 403 /error403.html; or error_page 403 = /error403.html; in nginx.conf

[zimmerle]

Hi all,

• I can confirm that in a minimalist setup the audit log works for both: DetectionOnly and On. So, auditlog is working as expected while SecRuleEngine is set with the values DetectionOnly and/or On. However, if the logging is marking to save only specific http codes, those may not be reached in detection only due to the fact that ModSecurity will not force return codes.

• I can't reproduce the custom error page setup, as nginx does not respect the custom page whenever ModSecurity asks to give a certain error. I am going to need further details on the nginx configuration to understand and reproduce the problem. Please try to create a minimal scenario where the problem is reproducible and shared the configurations so that i can have a look at it here.

[missilefish]

That is exactly what was causing no log to be written. However, I also can't run in 'SecRuleEngine DetectionOnly' mode, not getting any logging there no matter what.

[intelbg]

@zimmerle thank you about your reply. I provide you my configuration of nginx with custom page:

server blocks
locations
etc
.........
error_page 500 502 503 504 /50x.html;
location = /50x.html {
root /usr/local/nginx/html;
internal;
}
error_page 404 /40x.html;
location = /40x.html {
root /usr/local/nginx/html;
internal;
}
# And this is the really important part. If I comment it and restart nginx logging works, but with it it does not work (here is the custom 403 page):
error_page 403 /403.html;
location = /403.html {
root /usr/local/nginx/html;
internal;
}

Here is the custom 403 page:
cat /usr/local/nginx/html/403.html

<html>
<head>
  <title>Error happened</title>
</head>
<body>
<h1>403        Forbidden</h1>
</body>

<script>
  var cookie = getCookie("uid");
  document.querySelector("h1").innerText = document.querySelector("h1").innerText + " by " + cookie;
  function getCookie(cname) {
    var name = cname + "=";
    var decodedCookie = decodeURIComponent(document.cookie);
    var ca = decodedCookie.split(';');
    for(var i = 0; i <ca.length; i++) {
      var c = ca[i];
      while (c.charAt(0) == ' ') {
        c = c.substring(1);
      }
      if (c.indexOf(name) == 0) {
        return c.substring(name.length, c.length);
      }
    }
    return "";
  }
</script>
</html>

Do you need additional information? I think this is enough.

[missilefish]

@zimmerle I stripped down the config to a minimalist one, lots of legacy if statements in it for old school wordpress security. When I reloaded with DetectionOnly on all is good. I'm not sure exactly what the culprit was/is but here is what was in the old included conf, which had a lot of useless stuff in it.

wp.conf.zip

[edward-02020]

@intelbg That's right ! When I used nginx custom 403 page with error_page 403 /error403.html; ,My modsecurity can not write any log, But when I commented out this line , It is regular work .

[intelbg]

is there any progress on this case or eta?

[intelbg]

@zimmerle is it planned this problem to be fixed? If not can you please tell / orient me in which source file the problem may be to hire a programmer that can write a patch, because I had a deadline for this project and it's overdued?

[aadlung]

@zimmerle can you share your minimal configuration which works with mod_security and nginx, which can easily be tested by testparams or curl?
Even when adding 2xx to the SecAuditLogRelevantStatusit does not audit-log in DetectionOnly for me.
My minimal configuration is:

location / {

    modsecurity on;

    modsecurity_rules '
    SecRuleEngine DetectionOnly
    SecDebugLog /tmp/modsec_debug_vhost.log
    SecDebugLogLevel 9
    SecRule ARGS:testparam1 "@contains test" "id:1,phase:2,t:trim,block"
    SecRule ARGS:testparam2 "@contains test" "id:1234,log,auditlog,deny,status:403"

    SecAuditEngine On
    SecAuditLog /var/log/modsec_audit.log
    SecAuditLogRelevantStatus "^(?:5|4|2(?!04))"
    SecAuditLogParts ABIJDEFHZ
    SecAuditLogType Serial
'

[aadlung]

Regarding your information with the MODSECURITY_DDEBUG I just see the following if I set the nginx error_log mode to debug. I cannot compile nginx with debug mode.

2017/11/03 14:17:30 [info] 13034#13034: *443 [client 188.x.x.x] ModSecurity: Warning. Matched "Operator Contains' with parameter test' against variable ARGS:testparam1' (Value: test' ) [file "<>"] [line "4"] [id "1"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [ref "o0,4v17,4t:trim"] [hostname "188.x.x.x"] [uri "/"] [unique_id "150971505098.971670"], client: 188.x.x.x, server: www.example.com, request: "GET /?testparam1=test HTTP/1.0", host: "www.example.com"

[aadlung]

@zimmerle I think I can explain the issue now fairly simple:

I had the modsecurity configuration in the location / part of the nginx configuration. As I saw debug log, I thought it's enough there.

But for sure, to catch PHP scripts and so on, I need to have it configured/included in the corresponding PHP-Location-Blocks as well, and all other blocks where I want to activate it.

Not sure why I saw debug logging which shows the request in location / even if it was then executed in the PHP-Location-Block, but adding the modsecurity configuration to the PHP-Location-Block now shows the Audit Log.

The only weird thing is that I see now ALL PHP requests in Audit Log, even if there is no debug log, the audit log stores the request, without any rule matched.

Just to confirm, that's as expected? I should not have only 1 configuration for ModSecurity but it should be configured combined with the nginx `location´ blocks?

[zimmerle]

please have a look on those two configuration files: [1] and [2]. As you can see those two configurations differ by the place where the error_page was added. Notice that in [1] ModSecurity rules will be valid for the error_page, which is not case of the example [2].

What seems to be happening is that your request was redirected to a nested location that was configured without any ModSecurity rule. Therefore, no logging was generated. If you place the error_page inside the same location block that you have ModSecurity, the audit_log will work as expected.

[intelbg]

@zimmerle I tried to move the error_page inside location / { block, but it does not work to me again. Is there any other dependent thing?

[zimmerle]

@intelbg please share your new configuration. In our tests we are not able to reproduce it.

[intelbg]

In my new tests with the following configuration the logging works, but it's because the custom error page is ignored (can't figure out why) and the nginx default error page is used instead:

location / {
mod security on;
modsecurity_rules_file /usr/local/nginx/conf/owasp-modsecurity-crs/modsec_includes.conf;
error_page 403 /403.html;
location = /403.html {
root /usr/local/nginx/html;
internal;
}

    proxy_pass	http://1.1.1.1:8080;

    proxy_next_upstream error timeout invalid_header http_500 http_502 http_503 http_504;
    proxy_redirect  off;
    proxy_buffering on;
    proxy_set_header        Host            $host;
    proxy_set_header        X-Real-IP	$remote_addr;
    proxy_set_header        X-Forwarded-For $proxy_add_x_forwarded_for;
    proxy_set_header        X-Forwarded-Protocol  $scheme;

}

[zimmerle]

Hi @intelbg,

I am not sure why the custom error page is not being displayed. The scenario changes if you enable/disable ModSecurity?

[edward-02020]

Hi ~ @zimmerle @intelbg ,
The problems I found during my use were when I set crs-setup.conf

 SecDefaultAction "phase:1,log,auditlog,deny,status:403"
 SecDefaultAction "phase:2,log,auditlog,deny,status:403"

The custom error page can't be displayed.
But when set

 SecDefaultAction "phase:1,log,auditlog,redirect:'https://%{request_headers.host}/error403.html',tag:'Host: %{request_headers.host}'"
 SecDefaultAction "phase:2,log,auditlog,redirect:'https://%{request_headers.host}/error403.html',tag:'Host: %{request_headers.host}'"

It works well . I think it may be a bug . So I've been using second options .

[intelbg]

@zimmerle I tested now again and copy new vhost file with mod security enabled. Everything is ok and the custom error_page is displayed. After that I moved error_page in /location, restarted nginx and custom error_page was no more displayed. I then moved back error_page outside location / and custom display appeared again. The problem I think is not in the mod security about this, but this confirms that moving the error_page is not a solution.

[intelbg]

I found the right configuration. Please test you too to confirm it :)

   recursive_error_pages on;   ## this is in the server { block!

location / {
error_page 403 /403.html;

        modsecurity on;

modsecurity_rules_file /usr/local/nginx/conf/owasp-modsecurity-crs/modsec_includes.conf;
}
location = /403.html {
internal;
}

With this the custom error_page works and modsec_audit logs works too. I am waiting for your confirmation.

[intelbg]

The mistake is mine :( The custom error page works, but not and the logging :(

[victorhora]

The original issue titled "ModSecurity 3 and NginX-Connector only logging with SecRuleEngine On" has proved to be a non-issue (#1568 (comment)).

The discussion has moved to be related with custom 403 error page not working as expected specifically with the Nginx connector. This is a known issue and already being handled at owasp-modsecurity/ModSecurity-nginx#76.

As such I'm assuming the initial issue has been resolved and the connector specific should be handled at owasp-modsecurity/ModSecurity-nginx#76. Please follow up on that issue. Thanks!