How to make Anomaly scores to be shown in Nginx error log?

[Florian Ockhuysen]

Hi all,

I have a self-hosted web application that I want to secure with CRS and Nginx. I'm working through Christian's tutorial on Netnea. However, I'm stuck in Tutorial 7: including the CRS, at the point where the Incoming and Outgoing Score are added to the error log. For some reason I can't get these figures to show up in the log. It seems that none of the phase 5 rules log anything. Am I missing a setting that I need to tweak? Setting the error_log level to debug has no effect.

I'm using: nginx 1.21.1; modsecurity v3.0.5; modsecurity-nginx v1.0.2; crs v3.3.2

Since rule 980145 is occupied in CRS v3.3.2, I've removed 980130 and added rule 980131 like this:

SecAction \

   "id:980131,\

    phase:5,\

    pass,\

    t:none,\

    log,\

    noauditlog,\

    msg:'Incoming and Outgoing Score: %{TX.ANOMALY_SCORE} %{TX.OUTBOUND_ANOMALY_SCORE}'"

Example request:

curl http://localhost/index.html?exec=/bin/bash

Only this  shows up in /nginx/logs/error.log:

2021/08/25 12:20:08 [info] 167#167: *1 ModSecurity: Warning. Matched "Operator `PmFromFile' with parameter `unix-shell.data' against variable `ARGS:exec' (Value: `/bin/bash' ) [file "/nginx/conf/crs/rules/REQUEST-932-APPLICATION-ATTACK-RCE.conf"] [line "480"] [id "932160"] [rev ""] [msg "Remote Command Execution: Unix Shell Code Found"] [data "Matched Data: bin/bash found within ARGS:exec: /bin/bash"] [severity "2"] [ver "OWASP_CRS/3.3.2"] [maturity "0"] [accuracy "0"] [tag "Local Lab Service"] [tag "application-multi"] [tag "language-shell"] [tag "platform-unix"] [tag "attack-rce"] [tag "paranoia-level/1"] [tag "OWASP_CRS"] [tag "capec/1000/152/248/88"] [tag "PCI/6.5.2"] [hostname "127.0.0.1"] [uri "/index.html"] [unique_id "1629886808"] [ref "o1,8v21,9t:urlDecodeUni,t:cmdLine,t:normalizePath,t:lowercase"], client: 127.0.0.1, server: localhost, request: "GET /index.html?exec=/bin/bash HTTP/1.1", host: "localhost"

Any help is much appreciated!

Cheers,

Florian

[azu...@pobox.sk]

Hi Florian,

try looking into crs-setup.conf, section Alert Logging Control. Does
this helped you?





Citát Florian Ockhuysen <ockh...@gmail.com>:

> --
> You received this message because you are subscribed to the Google
> Groups "ModSecurity Core Rule Set project" group.
> To unsubscribe from this group and stop receiving emails from it,
> send an email to
> modsecurity-core-rule-...@owasp.org.
> To view this discussion on the web visit
> https://groups.google.com/a/owasp.org/d/msgid/modsecurity-core-rule-set-project/af2173e9-828e-41cb-b3f3-15f8db1344can%40owasp.org.

[Florian Ockhuysen]

Hi Azurit,

Thanks for your suggestion. As I understand it, I'm using Anomaly Scoring Mode and logging to both log and auditlog. I've commented out the SecDefaultAction rules in crs-setup.conf. When doing a ripgrep search in the /nginx folder for SecDefaultAction, shows these to be active:

./conf/modsecurity.conf

28:SecDefaultAction "phase:1,log,auditlog,pass,tag:'Local Lab Service'"

29:SecDefaultAction "phase:2,log,auditlog,pass,tag:'Local Lab Service'"

I've tried adding a SecDefaultAction for phase 5 but that didn't work.

Cheers,

Florian

[azu...@pobox.sk]

Are you sure that that request was blocked? Final anomaly score is
logged only for blocked requests.

CRS is logging in phase 2 for inbound anomaly score and in pahse 4 for
outbound anomaly score.

> https://groups.google.com/a/owasp.org/d/msgid/modsecurity-core-rule-set-project/bfb36795-b047-4483-bcf5-3c68e45ddd13n%40owasp.org.

[Florian Ockhuysen]

You're right, nothing is blocked, because I raised the inbound and
outbound anomaly thresholds to 10000. What I'm trying to achieve though
(following the tutorial), is to make sure the anomaly scores for every
request, blocked and non-blocked, are logged to Nginx error.log, hence
the extra SecAction 980131.

Now I've disabled 980131 and re-activated 980130. When I set the anomaly
thresholds back to 5, the request is blocked but still none of the
messages from RESPONSE-980-CORRELATION.conf are logged.

I followed the request in modsec_debug.log with debug log level set to
9. It looks like TX:executing_anomaly_score is correctly set to 5 but
not logged. Instead, it's trying to log TX:INBOUND_ANOMALY_SCORE, which
seems empty (""). Maybe that's why it doesn't show up in the nginx
error.log. Are we logging the wrong variable here? Here's the output,
starting with the logging phase:

[1629895323] [/index.html?exec=/bin/bash] [4] Starting phase LOGGING.
(SecRules 5)
[1629895323] [/index.html?exec=/bin/bash] [9] This phase consists of 46
rule(s).
[1629895323] [/index.html?exec=/bin/bash] [4] (Rule: 912110) Executing
operator "Eq" with param "0" against TX:dos_burst_time_slice.
[1629895323] [/index.html?exec=/bin/bash] [9] Target value: "0"
(Variable: TX:dos_burst_time_slice)
[1629895323] [/index.html?exec=/bin/bash] [9] Matched vars updated.
[1629895323] [/index.html?exec=/bin/bash] [4] Rule returned 1.
[1629895323] [/index.html?exec=/bin/bash] [4] Executing chained rule.
[1629895323] [/index.html?exec=/bin/bash] [4] (Rule: 0) Executing
operator "Eq" with param "0" against TX:dos_counter_threshold.
[1629895323] [/index.html?exec=/bin/bash] [9] Target value: "0"
(Variable: TX:dos_counter_threshold)
[1629895323] [/index.html?exec=/bin/bash] [9] Matched vars updated.
[1629895323] [/index.html?exec=/bin/bash] [4] Rule returned 1.
[1629895323] [/index.html?exec=/bin/bash] [4] Executing chained rule.
[1629895323] [/index.html?exec=/bin/bash] [4] (Rule: 0) Executing
operator "Eq" with param "0" against TX:dos_block_timeout.
[1629895323] [/index.html?exec=/bin/bash] [9] Target value: "0"
(Variable: TX:dos_block_timeout)
[1629895323] [/index.html?exec=/bin/bash] [9] Matched vars updated.
[1629895323] [/index.html?exec=/bin/bash] [4] Rule returned 1.
[1629895323] [/index.html?exec=/bin/bash] [9] Running action: nolog
[1629895323] [/index.html?exec=/bin/bash] [9] Running action: skipAfter
[1629895323] [/index.html?exec=/bin/bash] [5] Setting skipAfter for:
END-DOS-PROTECTION-CHECKS
[1629895323] [/index.html?exec=/bin/bash] [4] Running (disruptive)    
action: pass.
[1629895323] [/index.html?exec=/bin/bash] [8] Running action pass
[1629895323] [/index.html?exec=/bin/bash] [9] Skipped rule id '912140'
due to a SecMarker: END-DOS-PROTECTION-CHECKS
[1629895323] [/index.html?exec=/bin/bash] [9] Skipped rule id '912150'
due to a SecMarker: END-DOS-PROTECTION-CHECKS
[1629895323] [/index.html?exec=/bin/bash] [9] Skipped rule id '912160'
due to a SecMarker: END-DOS-PROTECTION-CHECKS
[1629895323] [/index.html?exec=/bin/bash] [9] Skipped rule id '912161'
due to a SecMarker: END-DOS-PROTECTION-CHECKS
[1629895323] [/index.html?exec=/bin/bash] [9] Skipped rule id '912170'
due to a SecMarker: END-DOS-PROTECTION-CHECKS
[1629895323] [/index.html?exec=/bin/bash] [9] Skipped rule id '912019'
due to a SecMarker: END-DOS-PROTECTION-CHECKS
[1629895323] [/index.html?exec=/bin/bash] [9] Skipped rule id '912171'
due to a SecMarker: END-DOS-PROTECTION-CHECKS
[1629895323] [/index.html?exec=/bin/bash] [4] (Rule: 980100) Executing
operator "Ge" with param "1" against TX:regex(LEAKAGE\\\/ERRORS).
[1629895323] [/index.html?exec=/bin/bash] [9] Target value: "0"
(Variable: TX:regex(LEAKAGE\\\/ERRORS))
[1629895323] [/index.html?exec=/bin/bash] [4] Rule returned 0.
[1629895323] [/index.html?exec=/bin/bash] [9] Matched vars cleaned.
[1629895323] [/index.html?exec=/bin/bash] [4] (Rule: 980110) Executing
operator "Ge" with param "1" against
TX:regex(AVAILABILITY\\\/APP_NOT_AVAIL).
[1629895323] [/index.html?exec=/bin/bash] [9] Target value: "0"
(Variable: TX:regex(AVAILABILITY\\\/APP_NOT_AVAIL))
[1629895323] [/index.html?exec=/bin/bash] [4] Rule returned 0.
[1629895323] [/index.html?exec=/bin/bash] [9] Matched vars cleaned.
[1629895323] [/index.html?exec=/bin/bash] [4] (Rule: 980115) Executing
unconditional rule...
[1629895323] [/index.html?exec=/bin/bash] [4] Running [independent]
(non-disruptive) action: setvar
[1629895323] [/index.html?exec=/bin/bash] [8] Saving variable:
TX:executing_anomaly_score with value: 5
[1629895323] [/index.html?exec=/bin/bash] [4] Running [independent]
(non-disruptive) action: setvar
[1629895323] [/index.html?exec=/bin/bash] [8] Saving variable:
TX:executing_anomaly_score with value: 5
[1629895323] [/index.html?exec=/bin/bash] [4] Running [independent]
(non-disruptive) action: setvar
[1629895323] [/index.html?exec=/bin/bash] [8] Saving variable:
TX:executing_anomaly_score with value: 5
[1629895323] [/index.html?exec=/bin/bash] [4] Running [independent]
(non-disruptive) action: setvar
[1629895323] [/index.html?exec=/bin/bash] [8] Saving variable:
TX:executing_anomaly_score with value: 5
[1629895323] [/index.html?exec=/bin/bash] [9] Running action: log
[1629895323] [/index.html?exec=/bin/bash] [9] Saving transaction to logs
[1629895323] [/index.html?exec=/bin/bash] [9] Running action: auditlog
[1629895323] [/index.html?exec=/bin/bash] [9] Saving transaction to logs
[1629895323] [/index.html?exec=/bin/bash] [4] Running (disruptive)    
action: pass.
[1629895323] [/index.html?exec=/bin/bash] [8] Running action pass
[1629895323] [/index.html?exec=/bin/bash] [4] (Rule: 980120) Executing
operator "Lt" with param "5" Was: "" against TX:INBOUND_ANOMALY_SCORE.
[1629895323] [/index.html?exec=/bin/bash] [9] Target value: "5"
(Variable: TX:INBOUND_ANOMALY_SCORE)
[1629895323] [/index.html?exec=/bin/bash] [4] Rule returned 0.
[1629895323] [/index.html?exec=/bin/bash] [9] Matched vars cleaned.
[1629895323] [/index.html?exec=/bin/bash] [4] (Rule: 980130) Executing
operator "Ge" with param "5" Was: "" against TX:INBOUND_ANOMALY_SCORE.
[1629895323] [/index.html?exec=/bin/bash] [9] Target value: "5"
(Variable: TX:INBOUND_ANOMALY_SCORE)
[1629895323] [/index.html?exec=/bin/bash] [9] Matched vars updated.
[1629895323] [/index.html?exec=/bin/bash] [4] Rule returned 1.
[1629895323] [/index.html?exec=/bin/bash] [4] Running (non-disruptive)
action: tag
[1629895323] [/index.html?exec=/bin/bash] [9] Rule tag: event-correlation
[1629895323] [/index.html?exec=/bin/bash] [9] Saving msg: Inbound
Anomaly Score Exceeded (Total Inbound Score: 5 -
SQLI=0,XSS=0,RFI=0,LFI=0,RCE=5,PHPI=0,HTTP=0,SESS=0): individual
paranoia level scores: 5, 0, 0, 0
[1629895323] [/index.html?exec=/bin/bash] [9] Running action: log
[1629895323] [/index.html?exec=/bin/bash] [9] Saving transaction to logs
[1629895323] [/index.html?exec=/bin/bash] [9] Running action: auditlog
[1629895323] [/index.html?exec=/bin/bash] [9] Saving transaction to logs
[1629895323] [/index.html?exec=/bin/bash] [4] Running (disruptive)    
action: pass.
[1629895323] [/index.html?exec=/bin/bash] [8] Running action pass
[1629895323] [/index.html?exec=/bin/bash] [4] (Rule: 980140) Executing
operator "Ge" with param "4" Was: "" against TX:OUTBOUND_ANOMALY_SCORE.
[1629895323] [/index.html?exec=/bin/bash] [9] Target value: "0"
(Variable: TX:OUTBOUND_ANOMALY_SCORE)
[1629895323] [/index.html?exec=/bin/bash] [4] Rule returned 0.
[1629895323] [/index.html?exec=/bin/bash] [9] Matched vars cleaned.
[1629895323] [/index.html?exec=/bin/bash] [4] (Rule: 980145) Executing
unconditional rule...
[1629895323] [/index.html?exec=/bin/bash] [4] Running [independent]
(non-disruptive) action: setvar
[1629895323] [/index.html?exec=/bin/bash] [8] Saving variable:
TX:executing_anomaly_score with value: 0
[1629895323] [/index.html?exec=/bin/bash] [4] Running [independent]
(non-disruptive) action: setvar
[1629895323] [/index.html?exec=/bin/bash] [8] Saving variable:
TX:executing_anomaly_score with value: 0
[1629895323] [/index.html?exec=/bin/bash] [4] Running [independent]
(non-disruptive) action: setvar
[1629895323] [/index.html?exec=/bin/bash] [8] Saving variable:
TX:executing_anomaly_score with value: 0
[1629895323] [/index.html?exec=/bin/bash] [4] Running [independent]
(non-disruptive) action: setvar
[1629895323] [/index.html?exec=/bin/bash] [8] Saving variable:
TX:executing_anomaly_score with value: 0
[1629895323] [/index.html?exec=/bin/bash] [9] Running action: log
[1629895323] [/index.html?exec=/bin/bash] [9] Saving transaction to logs
[1629895323] [/index.html?exec=/bin/bash] [9] Running action: auditlog
[1629895323] [/index.html?exec=/bin/bash] [9] Saving transaction to logs
[1629895323] [/index.html?exec=/bin/bash] [4] Running (disruptive)    
action: pass.
[1629895323] [/index.html?exec=/bin/bash] [8] Running action pass
[1629895323] [/index.html?exec=/bin/bash] [4] (Rule: 980150) Executing
operator "Lt" with param "4" Was: "" against TX:OUTBOUND_ANOMALY_SCORE.
[1629895323] [/index.html?exec=/bin/bash] [9] Target value: "0"
(Variable: TX:OUTBOUND_ANOMALY_SCORE)
[1629895323] [/index.html?exec=/bin/bash] [9] Matched vars updated.
[1629895323] [/index.html?exec=/bin/bash] [4] Rule returned 1.
[1629895323] [/index.html?exec=/bin/bash] [4] Executing chained rule.
[1629895323] [/index.html?exec=/bin/bash] [4] (Rule: 0) Executing
operator "Gt" with param "1" against TX:MONITOR_ANOMALY_SCORE.
[1629895323] [/index.html?exec=/bin/bash] [4] Rule returned 0.
[1629895323] [/index.html?exec=/bin/bash] [9] Matched vars cleaned.
[1629895323] [/index.html?exec=/bin/bash] [8] Checking if this request
is suitable to be saved as an audit log.
[1629895323] [/index.html?exec=/bin/bash] [4] There was an audit log
modifier for this transaction.
[1629895323] [/index.html?exec=/bin/bash] [7] AuditLog parts before
modification(s): 8190.
[1629895323] [/index.html?exec=/bin/bash] [8] Checking if this request
is relevant to be part of the audit logs.
[1629895323] [/index.html?exec=/bin/bash] [5] Saving this request as
part of the audit logs.
[1629895323] [/index.html?exec=/bin/bash] [8] Request was relevant to be
saved. Parts: 8190


I also started thinking that it could have to do something with Windows.
I'm doing this on Windows 10 WSL Ubuntu, maybe the error device is
handled in some weird way that nginx doesn't support. I'll try tonight
to install nginx on Arch Linux and if that changes anything.

Again, thanks for taking the time to look into this. I'm learning a lot
already!

Cheers,

Florian

[azu...@pobox.sk]

Can you recheck that all CRS .conf files are loaded into web server?

I see that logging is working:

[1629895323] [/index.html?exec=/bin/bash] [9] Saving msg: Inbound
Anomaly Score Exceeded (Total Inbound Score: 5 -
SQLI=0,XSS=0,RFI=0,LFI=0,RCE=5,PHPI=0,HTTP=0,SESS=0): individual
paranoia level scores: 5, 0, 0, 0
[1629895323] [/index.html?exec=/bin/bash] [9] Running action: log

[1629895323] [/index.html?exec=/bin/bash] [9] Running action: auditlog




Citát Florian Ockhuysen <ockh...@gmail.com>:

> https://groups.google.com/a/owasp.org/d/msgid/modsecurity-core-rule-set-project/2d17bdc8-9aee-8d2d-3c1b-c89d8a6e7b60%40gmail.com.

[Florian Ockhuysen]

Yes all the .conf files are loaded. The log action is run but the
message still doesn't show up in the nginx error log for some reason.

[Florian Ockhuysen]

An update, in Linux I got the same results. I found the answer, however. The phase 5 logging messages are only logged if the 'auditlog' action is specified. 'log,'auditlog' and 'nolog,auditlog' make the messages show up in both the audit and error logs. With 'log,noauditlog' the debug log shows that the log action is run but no message shows up in the error or audit logs.

Thanks for the help,

Florian

[Christian Folini]

Thank you for reporting back. That's clearly a bug with ModSec3 or the
connector. Please file a bug report.

Best,

Christian

> > https://groups.google.com/a/owasp.org/d/msgid/modsecurity-core-rule-set-project/2d17bdc8-9aee-8d2d-3c1b-c89d8a6e7b60%40gmail.com

> > .
> > >
> > >
> > >
> >
>
> --
> You received this message because you are subscribed to the Google Groups "ModSecurity Core Rule Set project" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to modsecurity-core-rule-...@owasp.org.

> To view this discussion on the web visit https://groups.google.com/a/owasp.org/d/msgid/modsecurity-core-rule-set-project/CAPHMYOdir8VDG%3D2%3D2jwW6mHrBEr_34F0JZoLPBp_HehWEOjfsQ%40mail.gmail.com.

[Florian Ockhuysen]

Done, the bug report can be found here: https://github.com/SpiderLabs/ModSecurity/issues/2609

[Christian Folini]

Thank you very much.

Christian