Audit logging not working correctly?

Hello,

There seem to be some issue with the audit logging. But debug logging is working fine.

Audit.log is never created even though that it is specified in coraza.conf

From coraza.conf

# -- Debug log configuration -------------------------------------------------

# Default debug log path
# Debug levels:
# 0:   No logging (least verbose)
# 1:   Error
# 2:   Warn
# 3:   Info
# 4-8: Debug
# 9:   Trace (most verbose)
# Most logging has not been implemented because it will be replaced with
# advanced rule profiling options
SecDebugLog debug.log
SecDebugLogLevel 9

# -- Audit log configuration -------------------------------------------------

# Log the transactions that are marked by a rule, as well as those that
# trigger a server error (determined by a 5xx or 4xx, excluding 404,
# level response status codes).
#
SecAuditEngine On
SecAuditLog audit.log
SecAuditLogParts ABCFHZ
SecAuditLogType concurrent

lsof | grep debug | head -n 1
nginx     1643295                               root   29u      REG                9,0 645230276    3014750 /tmp/debug.log

lsof | grep -i audit does not output anything. So that file is not created or attached.

From coraza/debug.log

2024/03/19 12:00:10 [DEBUG] Skipping rule because of SkipAfter tx_id="CxdXiWpdZSrrUWvLmhd" rule_id=980170 skip_after="END-REPORTING" secmarer=""
2024/03/19 12:00:10 [DEBUG] Evaluating rule tx_id="CxdXiWpdZSrrUWvLmhd" rule_id=0
2024/03/19 12:00:10 [DEBUG] Forcing rule to match tx_id="CxdXiWpdZSrrUWvLmhd" rule_id=0
2024/03/19 12:00:10 [DEBUG] Finish evaluating rule tx_id="CxdXiWpdZSrrUWvLmhd" rule_id=0
2024/03/19 12:00:10 [DEBUG] Finished phase tx_id="CxdXiWpdZSrrUWvLmhd" phase=5
2024/03/19 12:00:10 [DEBUG] Transaction marked for audit logging tx_id="CxdXiWpdZSrrUWvLmhd"

Example of disruptive action from nginx error.log

03/19 12:05:38 [debug] 1767074#0: *90 [lua] coraza.lua:244: intervention(): PID: 1767074   phrase: access  Transaction: c47e8e493795a4a8a556f696ac47d7b2   lua-resty-coraza: disrupted with status 403 action deny
2024/03/19 12:05:38 [warn] 1767074#0: *90 [lua] coraza.lua:92: do_handle(): PID: 1767074        phrase: access  Transaction: c47e8e493795a4a8a556f696ac47d7b2   lua-resty-coraza: request: "GET /wp-admin/ HTTP/2.0" is interrupted by policy. Action is deny, client: <hidden>, server: , request: "GET /wp-admin/ HTT
P/2.0", host: "www.test.eu"
2024/03/19 12:05:38 [debug] 1767074#0: *90 [lua] coraza.lua:124: do_header_filter(): PID: 1767074       phrase: header_filter   Transaction: c47e8e493795a4a8a556f696ac47d7b2   lua-resty-coraza: has been disrupted at request phrase. ignore
2024/03/19 12:05:38 [debug] 1767074#0: *90 [lua] coraza.lua:105: do_interrupt(): PID: 1767074   phrase: header_filter   Transaction: c47e8e493795a4a8a556f696ac47d7b2   lua-resty-coraza: has been disrupted at request phrase. ignore
2024/03/19 12:05:38 [debug] 1767074#0: *90 [lua] coraza.lua:327: append_response_body(): PID: 1767074   phrase: body_filter     Transaction: c47e8e493795a4a8a556f696ac47d7b2   lua-resty-coraza: success to invoke coraza_append_response_body with {"code": 403, "message": "This connection was blocked by Coroza!"}

2024/03/19 12:05:38 [debug] 1767074#0: *90 [lua] coraza.lua:336: process_response_body(): PID: 1767074  phrase: body_filter     Transaction: c47e8e493795a4a8a556f696ac47d7b2   lua-resty-coraza: success to invoke coraza_process_response_body
2024/03/19 12:05:38 [debug] 1767074#0: *90 [lua] coraza.lua:345: process_logging(): PID: 1767074        phrase: log     Transaction: c47e8e493795a4a8a556f696ac47d7b2   lua-resty-coraza: success to invoke coraza_process_logging
2024/03/19 12:05:38 [debug] 1767074#0: *90 [lua] coraza.lua:81: do_free_transaction(): PID: 1767074     phrase: log     Transaction: c47e8e493795a4a8a556f696ac47d7b2   lua-resty-coraza: is freed by coraza_free_transaction
2024/03/19 12:05:38 [debug] 1767074#0: *90 [lua] coraza.lua:257: free_transaction(): PID: 1767074       phrase: log     Transaction: c47e8e493795a4a8a556f696ac47d7b2   lua-resty-coraza: success to invoke coraza_free_transaction
2024/03/19 12:05:40 [debug] 1767074#0: *90 [lua] coraza.lua:159: new_transaction(): PID: 1767074        phrase: access  Transaction: 285cd5c645f0c53ff40791a158ac65e4   lua-resty-coraza: Success to creat new transaction
2024/03/19 12:05:40 [debug] 1767074#0: *90 [lua] coraza.lua:172: process_connection(): PID: 1767074     phrase: access  Transaction: 285cd5c645f0c53ff40791a158ac65e4   lua-resty-coraza: success to invoke coraza_process_connection with sourceAddress:<hidden> clientPort:54949 serverHost:<hidden> serverPort:4
43

I have hidden ip's and domains from log 👍 in case you wonder.

potats0 / lua-resty-coraza

Audit logging not working correctly? #7