Audit log no longer written since update to 3.0.14

Question

Audit log no longer written since update to 3.0.14

Opened this issue 5 months ago · 6 comments

Hi!

After updating ModSecurity to version 3.0.14, the audit log files are no longer written.
With a debug log configured, I just see a
Cannot save the audit log: file is not open: ...
as error.

As far as my research goes, this has been introduced with the rewriting of utils/shared_files.cc in ModSecurity 3.0.13. Version 3.0.12 works like a charm with the same setup.

Logs and dumps

Excerpt from debug log:

[175005793234.240265] [] [4] Initializing transaction
[175005793234.240265] [] [4] Transaction context created.
[175005793234.240265] [] [4] Starting phase CONNECTION. (SecRules 0)
[175005793234.240265] [] [9] This phase consists of 27 rule(s).
[175005793234.240265] [] [4] Starting phase URI. (SecRules 0 + 1/2)
[175005793234.240265] [/foobar] [4] Starting phase REQUEST_HEADERS.  (SecRules 1)
...
[175005793234.240265] [/foobar] [9] Running action: noauditlog
[175005793234.240265] [/foobar] [4] Running (disruptive)     action: pass.
[175005793234.240265] [/foobar] [8] Running action pass
[175005793234.240265] [/foobar] [8] Checking if this request is suitable to be saved as an audit log.
[175005793234.240265] [/foobar] [8] Checking if this request is relevant to be part of the audit logs.
[175005793234.240265] [/foobar] [5] Saving this request as part of the audit logs.
[175005793234.240265] [/foobar] [1] Cannot save the audit log: file is not open: nginx-1-audit.log

Error logs says the same time:

2025-06-16T07:12:12.637Z ggd193 waf_6_1[10861]: 2025/06/16 07:12:12 [error] 10861#0: *1 [client 172.16.0.192] ModSecurity: Access denied with code 403 (phase 2). Matched "Operator `Ge' with parameter `5' against variable `TX:BLOCKING_INBOUND_ANOMALY_SCORE' (Value: `5' ) [file "/usr/local/share/crs/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 "127.128.0.6"] [uri "/foobar"] [unique_id "175005793234.240265"] [ref ""], client: 172.16.0.192, server: www.foobar.de, request: "POST /foobar HTTP/1.1", host: "www.foobar.de"

Minimal nginx.conf I'm running to test this:

env TZ=UTC;
load_module "modules/ngx_http_modsecurity_module.so";
user __nginx __nginx;
worker_processes 1;
worker_rlimit_nofile 16000;
events { worker_connections 16000; }
http {
    error_log syslog:sendsyslog,facility=daemon,tag=waf_6,severity=info;

    map $time_iso8601 $time_iso8601_no_postfix {
        ~([^+]+) $1;
    }
    map $msec $millisec {
        ~\.([0-9]+)$ $1;
    }
    map $logtag $logtag {
        default 'waf_6';
    }
    log_format syslogified
        '$time_iso8601_no_postfix.$millisec' 'Z' ' $host '
        '$logtag[$pid]: $remote_addr - $remote_user '
        '"$request" $status $body_bytes_sent "$http_referer" '
        '"$http_user_agent" "$http_x_forwarded_for"';

    # Default 64 can be too low
    server_names_hash_bucket_size 128;

    server {
        set $logtag "waf_0_0";
        error_log syslog:sendsyslog,facility=daemon,tag=waf_0_0,severity=error;
        access_log syslog:sendsyslog,facility=daemon,tag=waf_0_0,severity=info syslogified;
        listen 127.128.0.6:12345 default_server;
        listen [::127.128.0.6]:12345 default_server;
        server_name _;
        
        return 403;
    }
    server {
        set $logtag "waf_6_1";
        error_log syslog:sendsyslog,facility=daemon,tag=waf_6_1,severity=error;
        access_log syslog:sendsyslog,facility=daemon,tag=waf_6_1,severity=info syslogified;
        listen 127.128.0.6:12345;
        listen [::127.128.0.6]:12345;
        server_name www.foobar.de;
        modsecurity on;
        
        # Additional options
        
        location / { # TEST
            proxy_pass http://127.0.0.1:12345;
            
            modsecurity_rules_file /etc/nginx/waf/modsecurity-Default_ModSecurity.conf;
            modsecurity_rules 'SecAuditLog /cage/nginx_waf/logs/6/nginx-1-audit.log';
            
            client_max_body_size 128m;

            # Additional options
            modsecurity_rules 'SecDebugLog /cage/nginx_waf/logs/6/nginx-1-debug.log';
            modsecurity_rules 'SecDebugLogLevel 9';
        }
    }
}

To Reproduce

Steps to reproduce the behavior:

Using the configuration from above and sending a request which would cause an audit log entry, only the error log message is written.
As far as I understand, a writer for the audit log is opened multiple times but then closed immediately again when in AuditLog::init() the old m_writer is removed.

Expected behavior

I would expect that also an audit log entry would be written as seen in the debug log.

Server (please complete the following information):

ModSecurity version (and connector): ModSecurity 3.0.14 with nginx-connector v1.0.3
WebServer: nginx-1.26.3
OS (and distro): OpenBSD 7.7

Rule Set (please complete the following information):

Running any public or commercial rule set? OWAP Core Rule Set
What is the version number? 4.3.0

Additional context
I tried to debug the problem myself and added some output to understand whats going on:

# /usr/local/sbin/nginx -c nginx-WAF.conf -g "pid /var/run/nginx-waf-WAF.pid; daemon off; master_process off;" -p /cage/nginx_waf                                          
AuditLog::merge called   
AL_MERGE_STRING_CONF replace '' with '/tmp/dummy_audit_log_for_syntax_check'
AL_MERGE_STRING_CONF replace '' with '^(?:5|4(?!04))'
AuditLog::init =>  New tmp_writer 0xb8ee402b990 for /tmp/dummy_audit_log_for_syntax_check
AuditLog::init =>  Initializing new writer 0xb8ee402b990
Serial::init => Init serial writer for /tmp/dummy_audit_log_for_syntax_check
SharedFiles::open => No handler for /tmp/dummy_audit_log_for_syntax_check found
SharedFiles::add_new_handler => Opened file /tmp/dummy_audit_log_for_syntax_check with FD 5
SharedFiles::open => Open file: /tmp/dummy_audit_log_for_syntax_check refcount=1
AuditLog::merge called
AL_MERGE_STRING_CONF replace '/tmp/dummy_audit_log_for_syntax_check' with 'nginx-1-audit.log'
AuditLog::init =>  New tmp_writer 0xb8ee402b220 for nginx-1-audit.log
AuditLog::init =>  Initializing new writer 0xb8ee402b220
Serial::init => Init serial writer for nginx-1-audit.log
SharedFiles::open => No handler for nginx-1-audit.log found
SharedFiles::add_new_handler => Opened file nginx-1-audit.log with FD 6
SharedFiles::open => Open file: nginx-1-audit.log refcount=1
AuditLog::init =>  Removing old writer 0xb8ee402b990 for nginx-1-audit.log
Serial::~Serial => destructor called for nginx-1-audit.log
SharedFiles::close =>  SharedFiles::close: file nginx-1-audit.log refcount=0
SharedFiles::close =>  Closing file: nginx-1-audit.log with FD 6
SharedFiles::open => No handler for nginx-1-debug.log found
SharedFiles::add_new_handler => Opened file nginx-1-debug.log with FD 6
SharedFiles::open => Open file: nginx-1-debug.log refcount=1
AuditLog::merge called
AuditLog::init =>  New tmp_writer 0xb8e9521df50 for nginx-1-audit.log
AuditLog::init =>  Initializing new writer 0xb8e9521df50
Serial::init => Init serial writer for nginx-1-audit.log
SharedFiles::open => No handler for nginx-1-audit.log found
SharedFiles::add_new_handler => Opened file nginx-1-audit.log with FD 7
SharedFiles::open => Open file: nginx-1-audit.log refcount=1
AuditLog::init =>  Removing old writer 0xb8ee402b220 for nginx-1-audit.log
Serial::~Serial => destructor called for nginx-1-audit.log
SharedFiles::close =>  SharedFiles::close: file nginx-1-audit.log refcount=0
SharedFiles::close =>  Closing file: nginx-1-audit.log with FD 7
SharedFiles::open => Open file: nginx-1-debug.log refcount=2
SharedFiles::close =>  SharedFiles::close: file nginx-1-debug.log refcount=1
AuditLog::merge called
AuditLog::init =>  New tmp_writer 0xb8ee402b1a0 for nginx-1-audit.log
AuditLog::init =>  Initializing new writer 0xb8ee402b1a0
Serial::init => Init serial writer for nginx-1-audit.log
SharedFiles::open => No handler for nginx-1-audit.log found
SharedFiles::add_new_handler => Opened file nginx-1-audit.log with FD 7
SharedFiles::open => Open file: nginx-1-audit.log refcount=1
AuditLog::init =>  Removing old writer 0xb8e9521df50 for nginx-1-audit.log
Serial::~Serial => destructor called for nginx-1-audit.log
SharedFiles::close =>  SharedFiles::close: file nginx-1-audit.log refcount=0
SharedFiles::close =>  Closing file: nginx-1-audit.log with FD 7
AuditLog::merge called
AuditLog::merge called
AuditLog::merge called
AuditLog::init =>  New tmp_writer 0xb8e8e999570 for nginx-1-audit.log
AuditLog::init =>  Initializing new writer 0xb8e8e999570
Serial::init => Init serial writer for nginx-1-audit.log
SharedFiles::open => No handler for nginx-1-audit.log found
SharedFiles::add_new_handler => Opened file nginx-1-audit.log with FD 7
SharedFiles::open => Open file: nginx-1-audit.log refcount=1
AuditLog::init =>  Removing old writer 0xb8ee402b1a0 for nginx-1-audit.log
Serial::~Serial => destructor called for nginx-1-audit.log
SharedFiles::close =>  SharedFiles::close: file nginx-1-audit.log refcount=0
SharedFiles::close =>  Closing file: nginx-1-audit.log with FD 7
SharedFiles::write =>  Write to file: nginx-1-debug.log

As you can see, FD 7 is openend and immediately closed again, ending in no open writer for the audit log.
Furthermore FD 5 imo leaks, as it is openend for /tmp/dummy_audit_log_for_syntax_check but never closed as the file name on the dummy audit log is replaced with the real name and thus the old writer for FD5 can no longer be found in the unordered map in SharedFiles.

Answer 1 · 2025-06-16T19:21:53.000Z

Hi @mpitzl,

thanks for reporting this - really sorry to hear this issue.

I'm afraid this would be an OpenBSD specific bug. Currently, I don't have any OpenBSD VM around, but let me install one and try to reproduce the described behavior. But first I try to check on Linux with your setup - may be that will come too.

Answer 2 · 2025-06-18T11:03:34.000Z

Hi,

I don't think that this problem is OpenBSD specific. As far as I have checked the code, there's nothing OS dependent.
For me this is a problem due to the SharedFiles rewriting in 3.0.13.

Answer 3 · 2025-06-18T11:33:39.000Z

In the initial comment above:

        location / { # TEST
            proxy_pass http://127.0.0.1:12345;
            
            modsecurity_rules_file /etc/nginx/waf/modsecurity-Default_ModSecurity.conf;

could you share this file? (/etc/nginx/waf/modsecurity-Default_ModSecurity.conf)

Answer 4 · 2025-06-18T13:12:47.000Z

SecRuleEngine On
SecRequestBodyAccess On
SecRule REQUEST_HEADERS:Content-Type "(?:application(?:/soap\+|/)|text/)xml" \
     "id:'200000',phase:1,t:none,t:lowercase,pass,nolog,ctl:requestBodyProcessor=XML"
SecRule REQUEST_HEADERS:Content-Type "application/json" \
     "id:'200001',phase:1,t:none,t:lowercase,pass,nolog,ctl:requestBodyProcessor=JSON"
SecRequestBodyLimit 134217728
SecRequestBodyNoFilesLimit 131072
SecRequestBodyLimitAction Reject
SecRule REQBODY_ERROR "!@eq 0" \
"id:'200002', phase:2,t:none,log,deny,status:400,msg:'Failed to parse request body.',logdata:'%{reqbody_error_msg}',severity:2"
SecRule MULTIPART_STRICT_ERROR "!@eq 0" \
"id:'200003',phase:2,t:none,log,deny,status:400, \
msg:'Multipart request body failed strict validation: \
PE %{REQBODY_PROCESSOR_ERROR}, \
BQ %{MULTIPART_BOUNDARY_QUOTED}, \
BW %{MULTIPART_BOUNDARY_WHITESPACE}, \
DB %{MULTIPART_DATA_BEFORE}, \
DA %{MULTIPART_DATA_AFTER}, \
HF %{MULTIPART_HEADER_FOLDING}, \
LF %{MULTIPART_LF_LINE}, \
SM %{MULTIPART_MISSING_SEMICOLON}, \
IQ %{MULTIPART_INVALID_QUOTING}, \
IP %{MULTIPART_INVALID_PART}, \
IH %{MULTIPART_INVALID_HEADER_FOLDING}, \
FL %{MULTIPART_FILE_LIMIT_EXCEEDED}'"
SecRule MULTIPART_UNMATCHED_BOUNDARY "@eq 1" \
    "id:'200004',phase:2,t:none,log,deny,msg:'Multipart parser detected a possible unmatched boundary.'"
SecPcreMatchLimit 1000
SecPcreMatchLimitRecursion 1000
SecRule TX:/^MSC_/ "!@streq 0" \
        "id:'200005',phase:2,t:none,deny,msg:'ModSecurity internal error flagged: %{MATCHED_VAR_NAME}'"
SecResponseBodyAccess On 
SecResponseBodyMimeType text/plain text/html text/xml
SecResponseBodyLimit 524288
SecResponseBodyLimitAction ProcessPartial
SecTmpDir /tmp/
SecDataDir /tmp/
SecAuditEngine RelevantOnly
SecAuditLogRelevantStatus "^(?:5|4(?!04))"
SecAuditLogParts ABIJDFHZ
SecAuditLogFormat JSON
SecAuditLogType Serial
SecAuditLog /tmp/dummy_audit_log_for_syntax_check
SecArgumentSeparator &
SecCookieFormat 0
SecStatusEngine Off
Include crs-setup-Default_ModSecurity.conf
Include /usr/local/gg/share/crs/include_rules.conf
Include RESPONSE-999-EXCLUSION-RULES-AFTER-CRS-Default_ModSecurity.conf

The included RESPONSE-999-EXCLUSION-RULES-AFTER-CRS-Default_ModSecurity.conf just contains:
SecRuleRemoveById 910100

Answer 5 · 2025-06-18T13:55:54.000Z

Ok, meanwhile I noticed the SecAuditLog /tmp/dummy_audit_log_for_syntax_check in the modsecurity config file.
Removing this line makes the audit log working again.

So, I think on one side this is an unfortunate configuration on our side but nevertheless also a regression compared to the old SharedFile code in 3.0.12 where the logging was functioning even with said SecAuditLog line in place.

Answer 6 · 2025-06-18T14:00:56.000Z

Ok, meanwhile I noticed the SecAuditLog /tmp/dummy_audit_log_for_syntax_check in the modsecurity config file. Removing this line makes the audit log working again.

yes, that was my observation too, but I didn't want to ask again without checking. Anyway, thanks for took this.

So, I think on one side this is an unfortunate configuration on our side but nevertheless also a regression compared to the old SharedFile code in 3.0.12 where the logging was functioning even with said SecAuditLog line in place.

Yes - I think in this case the expected behavior would be that the "default" audit.log is /tmp/dummy_audit_log_for_syntax_check, but server www.foobar.de should have a different one. So we have to inspect this issue.

Thanks.