owasp-modsecurity / ModSecurity

ModSecurity is an open source, cross platform web application firewall (WAF) engine for Apache, IIS and Nginx. It has a robust event-based programming language which provides protection from a range of attacks against web applications and allows for HTTP traffic monitoring, logging and real-time analysis.
https://www.modsecurity.org
Apache License 2.0
8.04k stars 1.58k forks source link

`[client <ip address>]` field is missing in `modsec_audit.log` in section H #3174

Open n-rodriguez opened 2 months ago

n-rodriguez commented 2 months ago

Hi there!

I don't know if it's a bug but the [client <ip address>] field is missing in modsec_audit.log in section H.

I know the client ip address is present in section A but it's not very handy to use because it forces you to do some correlations between the different sections especially when the logs reach our Graylog server :

On the other side, Nginx error logs do contain the client ip but :

Example :

Detection mode :

modsec_audit.log :

---B40Spanu---A--
[20/Jun/2024:18:20:33 +0200] 171890043326.958509 10.3.27.225 45984 10.3.27.226 80
...
---B40Spanu---H--
ModSecurity: Warning. Matched "Operator `PmFromFile' with parameter `unix-shell.data' against variable `ARGS:bar' (Value: `/bin/sh' ) [file "/data/nginx/coreruleset/rules/REQUEST-932-APPLICATION-ATTACK-RCE.conf"] [line "556"] [id "932160"] [rev ""] [msg "Remote Command Execution: Unix Shell Code Found"] [data "Matched Data: bin/sh found within ARGS:bar: /bin/sh"] [severity "2"] [ver "OWASP_CRS/4.3.0"] [maturity "0"] [accuracy "0"] [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 "10.3.27.226"] [uri "/"] [unique_id "171890043326.958509"] [ref "o1,6v10,7t:cmdLine,t:normalizePath"]
ModSecurity: Warning. Matched "Operator `Ge' with parameter `5' against variable `TX:BLOCKING_INBOUND_ANOMALY_SCORE' (Value: `5' ) [file "/data/nginx/coreruleset/rules/REQUEST-949-BLOCKING-EVALUATION.conf"] [line "222"] [id "949110"] [rev ""] [msg "Inbound Anomaly Score Exceeded (Total Score: 5)"] [data ""] [severity "0"] [ver "OWASP_CRS/4.3.0"] [maturity "0"] [accuracy "0"] [tag "anomaly-evaluation"] [tag "OWASP_CRS"] [hostname "10.3.27.226"] [uri "/"] [unique_id "171890043326.958509"] [ref ""]

Nginx error.log: empty

Block mode :

modsec_audit.log :

---M6IDyUV5---A--
[20/Jun/2024:18:20:33 +0200] 171890043325.867807 10.3.27.225 52054 10.3.27.225 80
...
---M6IDyUV5---H--
ModSecurity: Warning. Matched "Operator `PmFromFile' with parameter `unix-shell.data' against variable `ARGS:bar' (Value: `/bin/sh' ) [file "/data/nginx/coreruleset/rules/REQUEST-932-APPLICATION-ATTACK-RCE.conf"] [line "556"] [id "932160"] [rev ""] [msg "Remote Command Execution: Unix Shell Code Found"] [data "Matched Data: bin/sh found within ARGS:bar: /bin/sh"] [severity "2"] [ver "OWASP_CRS/4.3.0"] [maturity "0"] [accuracy "0"] [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 "10.3.27.225"] [uri "/"] [unique_id "171890043325.867807"] [ref "o1,6v10,7t:cmdLine,t:normalizePath"]
ModSecurity: Access denied with code 403 (phase 2). Matched "Operator `Ge' with parameter `5' against variable `TX:BLOCKING_INBOUND_ANOMALY_SCORE' (Value: `5' ) [file "/data/nginx/coreruleset/rules/REQUEST-949-BLOCKING-EVALUATION.conf"] [line "222"] [id "949110"] [rev ""] [msg "Inbound Anomaly Score Exceeded (Total Score: 5)"] [data ""] [severity "0"] [ver "OWASP_CRS/4.3.0"] [maturity "0"] [accuracy "0"] [tag "anomaly-evaluation"] [tag "OWASP_CRS"] [hostname "10.3.27.225"] [uri "/"] [unique_id "171890043325.867807"] [ref ""]

Nginx error.log:

2024/06/20 18:20:33 [error] 23698#23698: *1 [client 10.3.27.225] ModSecurity: Access denied with code 403 (phase 2). Matched "Operator `Ge' with parameter `5' against variable `TX:BLOCKING_INBOUND_ANOMALY_SCORE' (Value: `5' ) [file "/data/nginx/coreruleset/rules/REQUEST-949-BLOCKING-EVALUATION.conf"] [line "222"] [id "949110"] [rev ""] [msg "Inbound Anomaly Score Exceeded (Total Score: 5)"] [data ""] [severity "0"] [ver "OWASP_CRS/4.3.0"] [maturity "0"] [accuracy "0"] [tag "anomaly-evaluation"] [tag "OWASP_CRS"] [hostname "10.3.27.225"] [uri "/"] [unique_id "171890043325.867807"] [ref ""], client: 10.3.27.225, server: _, request: "GET /?bar=/bin/sh HTTP/1.1", host: "test-waf01"

It would be nice to have the client ip in modsec_audit.log like :

---M6IDyUV5---H--
[client 10.3.27.225] ModSecurity: Warning. Matched "Operator `PmFromFile' with parameter `unix-shell.data' against variable `ARGS:bar' (Value: `/bin/sh' ) [file "/data/nginx/coreruleset/rules/REQUEST-932-APPLICATION-ATTACK-RCE.conf"] [line "556"] [id "932160"] [rev ""] [msg "Remote Command Execution: Unix Shell Code Found"] [data "Matched Data: bin/sh found within ARGS:bar: /bin/sh"] [severity "2"] [ver "OWASP_CRS/4.3.0"] [maturity "0"] [accuracy "0"] [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 "10.3.27.225"] [uri "/"] [unique_id "171890043325.867807"] [ref "o1,6v10,7t:cmdLine,t:normalizePath"]
[client 10.3.27.225] ModSecurity: Access denied with code 403 (phase 2). Matched "Operator `Ge' with parameter `5' against variable `TX:BLOCKING_INBOUND_ANOMALY_SCORE' (Value: `5' ) [file "/data/nginx/coreruleset/rules/REQUEST-949-BLOCKING-EVALUATION.conf"] [line "222"] [id "949110"] [rev ""] [msg "Inbound Anomaly Score Exceeded (Total Score: 5)"] [data ""] [severity "0"] [ver "OWASP_CRS/4.3.0"] [maturity "0"] [accuracy "0"] [tag "anomaly-evaluation"] [tag "OWASP_CRS"] [hostname "10.3.27.225"] [uri "/"] [unique_id "171890043325.867807"] [ref ""]

To do so I've rebuilt the Debian package with a small patch :

Description: Add client ip to modsec_audit.log
 Add client ip to modsec_audit.log
Author: Nicolas Rodriguez <nico@nicoladmin.fr>
Origin: upstream
---
This patch header follows DEP-3: http://dep.debian.net/deps/dep3/
Index: modsecurity-3.0.9/src/rule_message.cc
===================================================================
--- modsecurity-3.0.9.orig/src/rule_message.cc
+++ modsecurity-3.0.9/src/rule_message.cc
@@ -67,9 +67,9 @@ std::string RuleMessage::log(const RuleM
     std::string msg("");
     msg.reserve(2048);

-    if (props & ClientLogMessageInfo) {
+    //if (props & ClientLogMessageInfo) {
         msg.append("[client " + std::string(*rm->m_clientIpAddress.get()) + "] ");
-    }
+    //}

     if (rm->m_isDisruptive) {
         msg.append("ModSecurity: Access denied with code ");

It seems to work in both mode (Detection mode and Block mode, the logs above were generated with this patch) but I'd like to have your opinion on this.

Thank you!

airween commented 2 months ago

Hi @n-rodriguez,

thanks for reporting!

I don't know if it's a bug but the [client <ip address>] field is missing in modsec_audit.log in section H.

it's definitely not a bug - it's by feature.

I know the client ip address is present in section A but it's not very handy to use because it forces you to do some correlations between the different sections especially when the logs reach our Graylog server :

* `section A` contains the client ip
* `section H` the actual error/reason for deny

On the other side, Nginx error logs do contain the client ip but :

but not that format. [client <ip addr>] format appears in Apache's error log. Nginx uses this syntax:

...  ... [ref ""], client: 127.0.0.1, server: _, request: "POST /post HTTP/1.1",

where the field [ref ""] is the last field from engine, and the rest part comes from the HTTP server itself.

* you only have the last error from ModSecurity
* Nginx error log is filled when `SecRuleEngine` is set to `On` => it doesn't fill Nginx error logs in `DetectionOnly` mode

Example :

[...]

Thanks for examples, those helped me understand the issue.

could you show us how looks like the error_log entry in your config?

The expected setting is this:

    error_log /path/to/your/error.log info;

so you must set up the severity, which should be info.

I'm almost sure you don't have any severity, then the default value is applied (error) which means only lines will be logged which has severity:ERROR action. This is why you see only the "last error from ModSecurity".

2024/06/20 18:20:33 [error] 23698#23698: *1 [client 10.3.27.225] ModSecurity:

In this example the [client 10.3.27.255] is there just because you already applied your patch, right? It's not there by default.

It would be nice to have the client ip in modsec_audit.log like :

---M6IDyUV5---H--
[client 10.3.27.225] ModSecurity: Warning. Matched "Operator `PmFromFile' with parameter `unix-shell.data' against variable `ARGS:bar' (Value: `/bin/sh' ) [file "/data/nginx/coreruleset/rules/REQUEST-932-APPLICATION-ATTACK-RCE.conf"] [line "556"] [id "932160"] [rev ""] [msg "Remote Command Execution: Unix Shell Code Found"] [data "Matched Data: bin/sh found within ARGS:bar: /bin/sh"] [severity "2"] [ver "OWASP_CRS/4.3.0"] [maturity "0"] [accuracy "0"] [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 "10.3.27.225"] [uri "/"] [unique_id "171890043325.867807"] [ref "o1,6v10,7t:cmdLine,t:normalizePath"]
[client 10.3.27.225] ModSecurity: Access denied with code 403 (phase 2). Matched "Operator `Ge' with parameter `5' against variable `TX:BLOCKING_INBOUND_ANOMALY_SCORE' (Value: `5' ) [file "/data/nginx/coreruleset/rules/REQUEST-949-BLOCKING-EVALUATION.conf"] [line "222"] [id "949110"] [rev ""] [msg "Inbound Anomaly Score Exceeded (Total Score: 5)"] [data ""] [severity "0"] [ver "OWASP_CRS/4.3.0"] [maturity "0"] [accuracy "0"] [tag "anomaly-evaluation"] [tag "OWASP_CRS"] [hostname "10.3.27.225"] [uri "/"] [unique_id "171890043325.867807"] [ref ""]

I'm not sure this is a good idea globally - just think about other users who already has their own logparser subsystem, and now an update changes the existing log format.

Btw I don't know exactly is that a tradition or not, but all log entry starts with the string "ModSecurity: ...". It's true in both case of engines: mod_security2 and libmodsecurity3. A parser could know that "this is the entry point" :)

Moreover, audit log is a very special type of log, so I'm sure everyone who uses that to analyze the traffic can extract every necessary info, including client IP. And therefore it would be good to break this format.

To do so I've rebuilt the Debian package with a small patch :

Description: Add client ip to modsec_audit.log
 Add client ip to modsec_audit.log
Author: Nicolas Rodriguez <nico@nicoladmin.fr>
Origin: upstream
---
This patch header follows DEP-3: http://dep.debian.net/deps/dep3/
Index: modsecurity-3.0.9/src/rule_message.cc
===================================================================
--- modsecurity-3.0.9.orig/src/rule_message.cc
+++ modsecurity-3.0.9/src/rule_message.cc
@@ -67,9 +67,9 @@ std::string RuleMessage::log(const RuleM
     std::string msg("");
     msg.reserve(2048);

-    if (props & ClientLogMessageInfo) {
+    //if (props & ClientLogMessageInfo) {
         msg.append("[client " + std::string(*rm->m_clientIpAddress.get()) + "] ");
-    }
+    //}

     if (rm->m_isDisruptive) {
         msg.append("ModSecurity: Access denied with code ");

Beside the others this is not so elegant way to solve this problem. If a line is not necessary, then you should remove it, not just make a comment.

But if you follow the function call stack, you can see that this function is at the end. There are some other implementations of log() method in that class, see this or this. For some reason all other method calls only the first one (without any arguments). If you really want to modify (in your instance locally), you should find the point where the engine build the audit log entry, and change the log() format to log(props, responseCode).

Hope this helped to clarify the context.

n-rodriguez commented 2 months ago

@airween

The expected setting is this:

    error_log /path/to/your/error.log info;

Thanks for the hint. It helps but it's not perfect : log entries appear twice in Nginx error.log (from a single curl call)

2024/06/20 22:15:23 [info] 93593#93593: *2 ModSecurity: Warning. Matched "Operator `PmFromFile' with parameter `unix-shell.data' against variable `ARGS:bar' (Value: `/bin/sh' ) [file "/data/nginx/coreruleset/rules/REQUEST-932-APPLICATION-ATTACK-RCE.conf"] [line "556"] [id "932160"] [rev ""] [msg "Remote Command Execution: Unix Shell Code Found"] [data "Matched Data: bin/sh found within ARGS:bar: /bin/sh"] [severity "2"] [ver "OWASP_CRS/4.3.0"] [maturity "0"] [accuracy "0"] [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 "10.3.27.225"] [uri "/"] [unique_id "171891452325.138961"] [ref "o1,6v10,7t:cmdLine,t:normalizePath"], client: 10.3.24.3, server: _, request: "GET /?bar=/bin/sh HTTP/1.1", host: "test-waf01"
2024/06/20 22:15:23 [info] 93593#93593: *2 ModSecurity: Warning. Matched "Operator `Ge' with parameter `5' against variable `TX:BLOCKING_INBOUND_ANOMALY_SCORE' (Value: `5' ) [file "/data/nginx/coreruleset/rules/REQUEST-949-BLOCKING-EVALUATION.conf"] [line "222"] [id "949110"] [rev ""] [msg "Inbound Anomaly Score Exceeded (Total Score: 5)"] [data ""] [severity "0"] [ver "OWASP_CRS/4.3.0"] [maturity "0"] [accuracy "0"] [tag "anomaly-evaluation"] [tag "OWASP_CRS"] [hostname "10.3.27.225"] [uri "/"] [unique_id "171891452325.138961"] [ref ""], client: 10.3.24.3, server: _, request: "GET /?bar=/bin/sh HTTP/1.1", host: "test-waf01"
2024/06/20 22:15:23 [info] 93593#93593: *2 ModSecurity: Warning. Matched "Operator `PmFromFile' with parameter `unix-shell.data' against variable `ARGS:bar' (Value: `/bin/sh' ) [file "/data/nginx/coreruleset/rules/REQUEST-932-APPLICATION-ATTACK-RCE.conf"] [line "556"] [id "932160"] [rev ""] [msg "Remote Command Execution: Unix Shell Code Found"] [data "Matched Data: bin/sh found within ARGS:bar: /bin/sh"] [severity "2"] [ver "OWASP_CRS/4.3.0"] [maturity "0"] [accuracy "0"] [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 "10.3.27.225"] [uri "/"] [unique_id "171891452354.440282"] [ref "o1,6v10,7t:cmdLine,t:normalizePath"], client: 10.3.24.3, server: _, request: "GET /?bar=/bin/sh HTTP/1.1", host: "test-waf01"
2024/06/20 22:15:23 [info] 93593#93593: *2 ModSecurity: Warning. Matched "Operator `Ge' with parameter `5' against variable `TX:BLOCKING_INBOUND_ANOMALY_SCORE' (Value: `5' ) [file "/data/nginx/coreruleset/rules/REQUEST-949-BLOCKING-EVALUATION.conf"] [line "222"] [id "949110"] [rev ""] [msg "Inbound Anomaly Score Exceeded (Total Score: 5)"] [data ""] [severity "0"] [ver "OWASP_CRS/4.3.0"] [maturity "0"] [accuracy "0"] [tag "anomaly-evaluation"] [tag "OWASP_CRS"] [hostname "10.3.27.225"] [uri "/"] [unique_id "171891452354.440282"] [ref ""], client: 10.3.24.3, server: _, request: "GET /?bar=/bin/sh HTTP/1.1", host: "test-waf01"
2024/06/20 22:15:23 [info] 93593#93593: *2 client 10.3.24.3 closed keepalive connection

The only differences are the unique_id :

[unique_id "171891452325.138961"]
[unique_id "171891452354.440282"]

Btw I think it should be documented somewhere.

In this example the [client 10.3.27.255] is there just because you already applied your patch, right? It's not there by default.

yes

I'm not sure this is a good idea globally - just think about other users who already has their own logparser subsystem, and now an update changes the existing log format.

I agree

Moreover, audit log is a very special type of log, so I'm sure everyone who uses that to analyze the traffic can extract every necessary info, including client IP.

I'd love to see how you do that

Beside the others this is not so elegant way to solve this problem. If a line is not necessary, then you should remove it, not just make a comment.

Of course, it was just for testing ;)

airween commented 2 months ago

@airween

The expected setting is this:

    error_log /path/to/your/error.log info;

Thanks for the hint. It helps but it's not perfect : log entries appear twice in Nginx error.log

so, THIS is a known bug :smile:!

In this example the [client 10.3.27.255] is there just because you already applied your patch, right? It's not there by default.

yes

thanks,

Moreover, audit log is a very special type of log, so I'm sure everyone who uses that to analyze the traffic can extract every necessary info, including client IP.

I'd love to see how you do that

I don't know - I never use audit log to check the traffic. All necessary info is in error.log. I use libmsclogparser to parse log entries. In case of Apache (mod_security2) there are some special info which appear only in error.log, but not in audit.log.

n-rodriguez commented 2 months ago

What I don't understand is : under which conditions [client <ip address>] is added to the log?

Because it seems that this code is never called (=> the if condition is never true) :

if (props & ClientLogMessageInfo) {
    msg.append("[client " + std::string(*rm->m_clientIpAddress.get()) + "] ");
}

or I'm missing something...

airween commented 2 months ago

What I don't understand is : under which conditions [client <ip address>] is added to the log?

I'm not sure there is any call where that condition fits.

Because it seems that this code is never called (=> the if condition is never true) :

yes, you are right.

if (props & ClientLogMessageInfo) {
    msg.append("[client " + std::string(*rm->m_clientIpAddress.get()) + "] ");
}

or I'm missing something...

no, you don't miss anything. This function (if I'm right) never called directly, only the log() method is used. I think this was an option for the future, may be if someone wants to call with different arguments.

n-rodriguez commented 2 months ago

This function (if I'm right) never called

Well... IMHO this function is called because my patch works but this condition if (props & ClientLogMessageInfo) is never met.

n-rodriguez commented 2 months ago

More weird is this : https://www.claranet.com/us/blog/2020-10-30-continuous-security-monitoring-using-modsecurity-elk#h.osjh6ca5x6m8

airween commented 2 months ago

This function (if I'm right) never called

Well... IMHO this function is called because my patch works but this condition if (props & ClientLogMessageInfo) is never met.

Meanwhile I corrected that sentence and appended the "directly" word...

airween commented 2 months ago

More weird is this : https://www.claranet.com/us/blog/2020-10-30-continuous-security-monitoring-using-modsecurity-elk#h.osjh6ca5x6m8

Seems like it was in (or before) 2020 - may be then that function was called directly. Or the author had some similar patch like yours. I'm not sure it worth to waste any time to figure out the reason of that log entry.

Update: please take a look this commit - before this there was a similar method with different name, then the mentioned field was always appended to the log.

n-rodriguez commented 2 months ago

Update: please take a look this commit

Nice catch 👍