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

n-rodriguez · 2024-06-20T17:02:38Z

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 :

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 :

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 :

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 <[email protected]>
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!

The text was updated successfully, but these errors were encountered:

airween · 2024-06-20T19:43:40Z

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 <[email protected]>
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 · 2024-06-20T20:27:47Z

@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 · 2024-06-20T20:38:42Z

@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 😄!

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 · 2024-06-20T20:44:55Z

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 · 2024-06-20T20:52:22Z

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 · 2024-06-20T20:55:52Z

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 · 2024-06-20T20:59:44Z

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

airween · 2024-06-20T21:34:08Z

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 · 2024-06-20T21:43:04Z

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 · 2024-06-20T23:12:58Z

Update: please take a look this commit

Nice catch 👍

airween · 2024-10-14T15:54:33Z

Hi @n-rodriguez, do you have any idea how should we solve this (if we need to do that at all)?

Cc: @eduar-hte.

n-rodriguez · 2024-10-14T16:33:17Z

Hi @airween! we finally solved this by setting error_log /path/to/your/error.log info; in Nginx.

Log entries still appear twice in Nginx error.log but we've got the infos we want :)

I think we can close this issue. Thank you!

n-rodriguez added the 3.x Related to ModSecurity version 3.x label Jun 20, 2024

n-rodriguez changed the title ~~[client <ip address>] field is missing in modsec_audit.log in section H~~ [client <ip address>] field is missing in modsec_audit.log in section H Jun 20, 2024

n-rodriguez closed this as completed Oct 14, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

n-rodriguez commented Jun 20, 2024 •

edited

Loading

airween commented Jun 20, 2024

n-rodriguez commented Jun 20, 2024 •

edited

Loading

airween commented Jun 20, 2024

n-rodriguez commented Jun 20, 2024 •

edited

Loading

airween commented Jun 20, 2024 •

edited

Loading

n-rodriguez commented Jun 20, 2024

n-rodriguez commented Jun 20, 2024

airween commented Jun 20, 2024

airween commented Jun 20, 2024 •

edited

Loading

n-rodriguez commented Jun 20, 2024

airween commented Oct 14, 2024

n-rodriguez commented Oct 14, 2024

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

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

Comments

n-rodriguez commented Jun 20, 2024 • edited Loading

airween commented Jun 20, 2024

n-rodriguez commented Jun 20, 2024 • edited Loading

airween commented Jun 20, 2024

n-rodriguez commented Jun 20, 2024 • edited Loading

airween commented Jun 20, 2024 • edited Loading

n-rodriguez commented Jun 20, 2024

n-rodriguez commented Jun 20, 2024

airween commented Jun 20, 2024

airween commented Jun 20, 2024 • edited Loading

n-rodriguez commented Jun 20, 2024

airween commented Oct 14, 2024

n-rodriguez commented Oct 14, 2024

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

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

n-rodriguez commented Jun 20, 2024 •

edited

Loading

n-rodriguez commented Jun 20, 2024 •

edited

Loading

n-rodriguez commented Jun 20, 2024 •

edited

Loading

airween commented Jun 20, 2024 •

edited

Loading

airween commented Jun 20, 2024 •

edited

Loading