search

owasp-modsecurity / ModSecurity-nginx

ModSecurity v3 Nginx Connector
Apache License 2.0
1.55k stars 281 forks source link

SecAuditLog does not work with modsecurity_rules_remote #212

Closed mdjunior closed 4 years ago

mdjunior commented 4 years ago

Hi,

I did a modsecurity installation using nginx 1.19.0 and the master version of libmodsecurity on CentOS 7.

I noticed that when I load the rules from a remote endpoint via HTTPS, the SecAuditLog directive does not work. Both for files (Serial) and for sending HTTPS.

When I download the file and put it on a server path, SecAuditLog works (both for sending the remote audit and writing to a file).

The test rules file I used is as follows (I only change SecAuditLog and SecAuditLogType to make tests):

SecRuleEngine On
SecRequestBodyAccess On
SecRequestBodyLimit 13107200
SecRequestBodyLimitAction ProcessPartial
SecResponseBodyAccess Off
SecResponseBodyMimeType text/plain text/html text/xml
SecAuditEngine RelevantOnly
SecAuditLogParts ABIJDEFHZ
SecAuditLogFormat JSON
SecAuditLogRelevantStatus "^(5|4)"
SecComponentSignature "GSS/0.0.1"
SecDefaultAction "phase:1,deny,log,auditlog"
SecDefaultAction "phase:2,deny,log,auditlog"
SecAction "phase:1,t:none,setvar:tx.critical_anomaly_score=5,setvar:tx.error_anomaly_score=4,setvar:tx.warning_anomaly_score=3,setvar:tx.notice_anomaly_score=2,nolog,pass"
SecAction "phase:1,t:none,setvar:tx.anomaly_score=0,setvar:tx.sql_injection_score=0,setvar:tx.xss_score=0,setvar:tx.inbound_anomaly_score=0,setvar:tx.outbound_anomaly_score=0,nolog,pass"
SecAction "phase:1,t:none,setvar:tx.inbound_anomaly_score_level=5,setvar:tx.outbound_anomaly_score_level=4,nolog,pass"
SecAction "phase:1,t:none,setvar:tx.max_num_args=255,nolog,pass"
SecAuditLog /var/log/audit.log
SecAuditLogType Serial
SecRule "MULTIPART_STRICT_ERROR" "!@eq 0" "id:'86',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 0" "id:'87',phase:2,t:none,log,deny,msg:'Multipart parser detected a possible unmatched boundary.'"
SecRule "REQBODY_ERROR" "!@eq 0" "id:'88',phase:2,t:none,log,deny,status:400,msg:'Failed to parse request body.',logdata:'%{reqbody_error_msg}',severity:2"
SecRule "REQUEST_HEADERS:Content-Type" "text/xml" "id:'89',phase:1,t:none,t:lowercase,pass,nolog,ctl:requestBodyProcessor=XML"
SecRule "REQUEST_HEADERS:Content-Type" "application/json" "id:'90',phase:1,t:none,t:lowercase,pass,nolog,ctl:requestBodyProcessor=JSON"
SecRule "TX:/^MSC_/" "!@streq 0" "id:'91',phase:2,t:none,deny,msg:'ModSecurity internal error flagged: %{MATCHED_VAR_NAME}'"
SecRule "ARGS:testparam" "@contains test" "id:'92',phase:1,t:none,log,block,msg:'Bloqueio via regra de teste'"
zimmerle commented 4 years ago

Hi @mdjunior,

Is there any relevant message on the logs (audit, error or debug)?

mdjunior commented 4 years ago

@zimmerle, I didn't find any messages in the nginx debug, nor in the error log. I reproduce it below.

2020/07/03 10:18:12 [notice] 6133#6133: ModSecurity-nginx v1.0.1 (rules loaded inline/local/remote: 0/0/10)
2020/07/03 10:18:12 [debug] 6133#6133: bind() 0.0.0.0:80 #8 
2020/07/03 10:18:12 [notice] 6133#6133: using the "epoll" event method
2020/07/03 10:18:12 [debug] 6133#6133: counter: 00007FDC23C65080, 1
2020/07/03 10:18:12 [notice] 6133#6133: nginx/1.19.0
2020/07/03 10:18:12 [notice] 6133#6133: built by gcc 4.8.5 20150623 (Red Hat 4.8.5-39.0.1) (GCC) 
2020/07/03 10:18:12 [notice] 6133#6133: OS: Linux 4.14.35-1818.3.3.el7uek.x86_64
2020/07/03 10:18:12 [notice] 6133#6133: getrlimit(RLIMIT_NOFILE): 32756:65536
2020/07/03 10:18:12 [debug] 6135#6135: write: 9, 00007FFC7F16A7A0, 5, 0
2020/07/03 10:18:12 [debug] 6135#6135: setproctitle: "nginx: master process /opt/ss/nginx-1.19.0/sbin/nginx -c conf/nginx.conf.default"
2020/07/03 10:18:12 [notice] 6135#6135: start worker processes
2020/07/03 10:18:12 [debug] 6135#6135: channel 9:10
2020/07/03 10:18:12 [notice] 6135#6135: start worker process 6136
2020/07/03 10:18:12 [debug] 6135#6135: sigsuspend
2020/07/03 10:18:12 [debug] 6136#6136: add cleanup: 000055A837449230
2020/07/03 10:18:12 [debug] 6136#6136: malloc: 000055A837514D20:8
2020/07/03 10:18:12 [debug] 6136#6136: notify eventfd: 12
2020/07/03 10:18:12 [debug] 6136#6136: eventfd: 13
2020/07/03 10:18:12 [debug] 6136#6136: testing the EPOLLRDHUP flag: success
2020/07/03 10:18:12 [debug] 6136#6136: malloc: 000055A83750E3C0:6144
2020/07/03 10:18:12 [debug] 6136#6136: malloc: 00007FDC23AF5010:237568
2020/07/03 10:18:12 [debug] 6136#6136: malloc: 000055A837449680:98304
2020/07/03 10:18:12 [debug] 6136#6136: malloc: 000055A83752BE60:98304
2020/07/03 10:18:12 [debug] 6136#6136: epoll add event: fd:8 op:1 ev:00002001
2020/07/03 10:18:12 [debug] 6136#6136: http vts init worker
2020/07/03 10:18:12 [debug] 6136#6136: vts::init_worker(): is bypassed
2020/07/03 10:18:12 [debug] 6136#6136: epoll add event: fd:10 op:1 ev:00002001
2020/07/03 10:18:12 [debug] 6136#6136: setproctitle: "nginx: worker process"
2020/07/03 10:18:12 [debug] 6136#6136: worker cycle
2020/07/03 10:18:12 [debug] 6136#6136: epoll timer: -1
2020/07/03 10:18:17 [debug] 6136#6136: epoll: fd:8 ev:0001 d:00007FDC23AF5010
2020/07/03 10:18:17 [debug] 6136#6136: accept on 0.0.0.0:80, ready: 0
2020/07/03 10:18:17 [debug] 6136#6136: posix_memalign: 000055A8374FE810:512 @16
2020/07/03 10:18:17 [debug] 6136#6136: *1 accept: 10.224.143.98:26775 fd:9
2020/07/03 10:18:17 [debug] 6136#6136: *1 event timer add: 9: 60000:1998845807
2020/07/03 10:18:17 [debug] 6136#6136: *1 reusable connection: 1
2020/07/03 10:18:17 [debug] 6136#6136: *1 epoll add event: fd:9 op:1 ev:80002001
2020/07/03 10:18:17 [debug] 6136#6136: timer delta: 5346
2020/07/03 10:18:17 [debug] 6136#6136: worker cycle
2020/07/03 10:18:17 [debug] 6136#6136: epoll timer: 60000
2020/07/03 10:18:17 [debug] 6136#6136: epoll: fd:9 ev:0001 d:00007FDC23AF51E0
2020/07/03 10:18:17 [debug] 6136#6136: *1 http wait request handler
2020/07/03 10:18:17 [debug] 6136#6136: *1 malloc: 000055A8373FB340:1024
2020/07/03 10:18:17 [debug] 6136#6136: *1 recv: eof:0, avail:-1
2020/07/03 10:18:17 [debug] 6136#6136: *1 recv: fd:9 93 of 1024
2020/07/03 10:18:17 [debug] 6136#6136: *1 reusable connection: 0
2020/07/03 10:18:17 [debug] 6136#6136: *1 posix_memalign: 000055A8375227E0:4096 @16
2020/07/03 10:18:17 [debug] 6136#6136: *1 http process request line
2020/07/03 10:18:17 [debug] 6136#6136: *1 http request line: "GET /?testparam=test HTTP/1.1"
2020/07/03 10:18:17 [debug] 6136#6136: *1 http uri: "/"
2020/07/03 10:18:17 [debug] 6136#6136: *1 http args: "testparam=test"
2020/07/03 10:18:17 [debug] 6136#6136: *1 http exten: ""
2020/07/03 10:18:17 [debug] 6136#6136: *1 posix_memalign: 000055A837511E40:4096 @16
2020/07/03 10:18:17 [debug] 6136#6136: *1 http process request header line
2020/07/03 10:18:17 [debug] 6136#6136: *1 http header: "User-Agent: curl/7.29.0"
2020/07/03 10:18:17 [debug] 6136#6136: *1 http header: "Host: 10.224.143.107"
2020/07/03 10:18:17 [debug] 6136#6136: *1 http header: "Accept: */*"
2020/07/03 10:18:17 [debug] 6136#6136: *1 http header done
2020/07/03 10:18:17 [debug] 6136#6136: *1 event timer del: 9: 1998845807
2020/07/03 10:18:17 [debug] 6136#6136: *1 generic phase: 0
2020/07/03 10:18:17 [debug] 6136#6136: *1 generic phase: 1
2020/07/03 10:18:17 [debug] 6136#6136: *1 rewrite phase: 2
2020/07/03 10:18:17 [debug] 6136#6136: *1 test location: "/"
2020/07/03 10:18:17 [debug] 6136#6136: *1 using configuration "/"
2020/07/03 10:18:17 [debug] 6136#6136: *1 http cl:-1 max:1048576
2020/07/03 10:18:17 [debug] 6136#6136: *1 rewrite phase: 4
2020/07/03 10:18:17 [debug] 6136#6136: *1 add cleanup: 000055A837523570
2020/07/03 10:18:17 [error] 6136#6136: *1 [client 10.224.143.98] ModSecurity: Access denied with code 403 (phase 1). Matched "Operator `Contains' with parameter `test' against variable `ARGS:testparam' (Value: `test' ) [file "https://remote-endpoint/api/v1/sites/4a08c5d8-9de9-4ddb-8400-b05e940d8866/rules/raw"] [line "31"] [id "32"] [rev ""] [msg "Bloqueio via regra de teste"] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "10.224.143.107"] [uri "/"] [unique_id "159378229755.836391"] [ref "o0,4v16,4"], client: 10.224.143.98, server: localhost, request: "GET /?testparam=test HTTP/1.1", host: "10.224.143.107"
2020/07/03 10:18:17 [error] 6136#6136: *1 [client 10.224.143.98] ModSecurity: Access denied with code 403 (phase 1). Matched "Operator `Contains' with parameter `test' against variable `ARGS:testparam' (Value: `test' ) [file "https://remote-endpoint/api/v1/sites/4a08c5d8-9de9-4ddb-8400-b05e940d8866/rules/raw"] [line "31"] [id "32"] [rev ""] [msg "Bloqueio via regra de teste"] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "10.224.143.107"] [uri "/"] [unique_id "159378229755.836391"] [ref "o0,4v16,4"], client: 10.224.143.98, server: localhost, request: "GET /?testparam=test HTTP/1.1", host: "10.224.143.107"
2020/07/03 10:18:17 [debug] 6136#6136: *1 http finalize request: 403, "/?testparam=test" a:1, c:1
2020/07/03 10:18:17 [debug] 6136#6136: *1 http special response: 403, "/?testparam=test"
2020/07/03 10:18:17 [debug] 6136#6136: *1 http set discard body
2020/07/03 10:18:17 [debug] 6136#6136: *1 xslt filter header
2020/07/03 10:18:17 [debug] 6136#6136: *1 HTTP/1.1 403 Forbidden
Server: nginx/1.19.0
Date: Fri, 03 Jul 2020 13:18:17 GMT
Content-Type: text/html
Content-Length: 153
Connection: keep-alive

2020/07/03 10:18:17 [debug] 6136#6136: *1 write new buf t:1 f:0 000055A837523630, pos 000055A837523630, size: 155 file: 0, size: 0
2020/07/03 10:18:17 [debug] 6136#6136: *1 http write filter: l:0 f:0 s:155
2020/07/03 10:18:17 [debug] 6136#6136: *1 http output filter "/?testparam=test"
2020/07/03 10:18:17 [debug] 6136#6136: *1 http copy filter: "/?testparam=test"
2020/07/03 10:18:17 [debug] 6136#6136: *1 xslt filter body
2020/07/03 10:18:17 [debug] 6136#6136: *1 http postpone filter "/?testparam=test" 000055A837523790
2020/07/03 10:18:17 [debug] 6136#6136: *1 write old buf t:1 f:0 000055A837523630, pos 000055A837523630, size: 155 file: 0, size: 0
2020/07/03 10:18:17 [debug] 6136#6136: *1 write new buf t:0 f:0 0000000000000000, pos 000055A8365D37C0, size: 100 file: 0, size: 0
2020/07/03 10:18:17 [debug] 6136#6136: *1 write new buf t:0 f:0 0000000000000000, pos 000055A8365D3EA0, size: 53 file: 0, size: 0
2020/07/03 10:18:17 [debug] 6136#6136: *1 http write filter: l:1 f:0 s:308
2020/07/03 10:18:17 [debug] 6136#6136: *1 http write filter limit 0
2020/07/03 10:18:17 [debug] 6136#6136: *1 writev: 308 of 308
2020/07/03 10:18:17 [debug] 6136#6136: *1 http write filter 0000000000000000
2020/07/03 10:18:17 [debug] 6136#6136: *1 http copy filter: 0 "/?testparam=test"
2020/07/03 10:18:17 [debug] 6136#6136: *1 http finalize request: 0, "/?testparam=test" a:1, c:1
2020/07/03 10:18:17 [debug] 6136#6136: *1 set http keepalive handler
2020/07/03 10:18:17 [debug] 6136#6136: *1 http close request
2020/07/03 10:18:17 [debug] 6136#6136: *1 http log handler
2020/07/03 10:18:17 [debug] 6136#6136: *1 http vts handler
2020/07/03 10:18:17 [debug] 6136#6136: *1 malloc: 000055A83741D7D0:4096
2020/07/03 10:18:17 [debug] 6136#6136: *1 malloc: 000055A83741E7E0:4096
2020/07/03 10:18:17 [debug] 6136#6136: *1 free: 000055A83741D7D0
2020/07/03 10:18:17 [debug] 6136#6136: *1 free: 000055A83741E7E0
2020/07/03 10:18:17 [debug] 6136#6136: *1 run cleanup: 000055A837523570
2020/07/03 10:18:17 [debug] 6136#6136: *1 free: 0000000000000000
2020/07/03 10:18:17 [debug] 6136#6136: *1 free: 0000000000000000
2020/07/03 10:18:17 [debug] 6136#6136: *1 free: 000055A8375227E0, unused: 14
2020/07/03 10:18:17 [debug] 6136#6136: *1 free: 000055A837511E40, unused: 2344
2020/07/03 10:18:17 [debug] 6136#6136: *1 free: 000055A8373FB340
2020/07/03 10:18:17 [debug] 6136#6136: *1 hc free: 0000000000000000
2020/07/03 10:18:17 [debug] 6136#6136: *1 hc busy: 0000000000000000 0
2020/07/03 10:18:17 [debug] 6136#6136: *1 tcp_nodelay
2020/07/03 10:18:17 [debug] 6136#6136: *1 reusable connection: 1
2020/07/03 10:18:17 [debug] 6136#6136: *1 event timer add: 9: 65000:1998850807
2020/07/03 10:18:17 [debug] 6136#6136: timer delta: 0
2020/07/03 10:18:17 [debug] 6136#6136: worker cycle
2020/07/03 10:18:17 [debug] 6136#6136: epoll timer: 65000
2020/07/03 10:18:17 [debug] 6136#6136: epoll: fd:9 ev:2001 d:00007FDC23AF51E0
2020/07/03 10:18:17 [debug] 6136#6136: *1 http keepalive handler
2020/07/03 10:18:17 [debug] 6136#6136: *1 malloc: 000055A8373FB340:1024
2020/07/03 10:18:17 [debug] 6136#6136: *1 recv: eof:1, avail:-1
2020/07/03 10:18:17 [debug] 6136#6136: *1 recv: fd:9 0 of 1024
2020/07/03 10:18:17 [info] 6136#6136: *1 client 10.224.143.98 closed keepalive connection
2020/07/03 10:18:17 [debug] 6136#6136: *1 close http connection: 9
2020/07/03 10:18:17 [debug] 6136#6136: *1 event timer del: 9: 1998850807
2020/07/03 10:18:17 [debug] 6136#6136: *1 reusable connection: 0
2020/07/03 10:18:17 [debug] 6136#6136: *1 free: 000055A8373FB340
2020/07/03 10:18:17 [debug] 6136#6136: *1 free: 000055A8374FE810, unused: 120
2020/07/03 10:18:17 [debug] 6136#6136: timer delta: 12
2020/07/03 10:18:17 [debug] 6136#6136: worker cycle
2020/07/03 10:18:17 [debug] 6136#6136: epoll timer: -1

The remotely loaded rules are:

SecRuleEngine On
SecRequestBodyAccess On
SecRequestBodyLimit 13107200
SecRequestBodyLimitAction ProcessPartial
SecResponseBodyAccess Off
SecResponseBodyMimeType text/plain text/html text/xml
SecAuditEngine RelevantOnly
SecAuditLogParts ABIJDEFHZ
SecAuditLogFormat JSON
SecAuditLogRelevantStatus "^(5|4)"
SecComponentSignature "GSS/0.0.1"
SecDefaultAction "phase:1,deny,log,auditlog"
SecDefaultAction "phase:2,deny,log,auditlog"
SecAction "phase:1,t:none,setvar:tx.critical_anomaly_score=5,setvar:tx.error_anomaly_score=4,setvar:tx.warning_anomaly_score=3,setvar:tx.notice_anomaly_score=2,nolog,pass"
SecAction "phase:1,t:none,setvar:tx.anomaly_score=0,setvar:tx.sql_injection_score=0,setvar:tx.xss_score=0,setvar:tx.inbound_anomaly_score=0,setvar:tx.outbound_anomaly_score=0,nolog,pass"
SecAction "phase:1,t:none,setvar:tx.inbound_anomaly_score_level=5,setvar:tx.outbound_anomaly_score_level=4,nolog,pass"
SecAction "phase:1,t:none,setvar:tx.max_num_args=255,nolog,pass"
SecAuditLog https://remote-endpoint/api/v1/sites/eb25596a-ac1f-4a13-a756-b4671aed7f5d/events
SecAuditLogType HTTPS
SecRule "MULTIPART_STRICT_ERROR" "!@eq 0" "id:'86',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 0" "id:'87',phase:2,t:none,log,deny,msg:'Multipart parser detected a possible unmatched boundary.'"
SecRule "REQBODY_ERROR" "!@eq 0" "id:'88',phase:2,t:none,log,deny,status:400,msg:'Failed to parse request body.',logdata:'%{reqbody_error_msg}',severity:2"
SecRule "REQUEST_HEADERS:Content-Type" "text/xml" "id:'89',phase:1,t:none,t:lowercase,pass,nolog,ctl:requestBodyProcessor=XML"
SecRule "REQUEST_HEADERS:Content-Type" "application/json" "id:'90',phase:1,t:none,t:lowercase,pass,nolog,ctl:requestBodyProcessor=JSON"
SecRule "ARGS:testparam" "@contains test" "id:'92',phase:1,t:none,log,block,msg:'Bloqueio via regra de teste'"
SecRule "TX:/^MSC_/" "!@streq 0" "id:'95',phase:2,t:none,deny,msg:'ModSecurity internal error flagged: %{MATCHED_VAR_NAME}'"
mdjunior commented 4 years ago

The following events are from when I configure NGINX to read the rules locally (in a file) and send the Audit events via HTTPS.

2020/07/03 10:27:04 [notice] 6361#6361: ModSecurity-nginx v1.0.1 (rules loaded inline/local/remote: 0/11/0)
2020/07/03 10:27:04 [debug] 6361#6361: bind() 0.0.0.0:80 #6 
2020/07/03 10:27:04 [notice] 6361#6361: using the "epoll" event method
2020/07/03 10:27:04 [debug] 6361#6361: counter: 00007F892DC8D080, 1
2020/07/03 10:27:04 [notice] 6361#6361: nginx/1.19.0
2020/07/03 10:27:04 [notice] 6361#6361: built by gcc 4.8.5 20150623 (Red Hat 4.8.5-39.0.1) (GCC) 
2020/07/03 10:27:04 [notice] 6361#6361: OS: Linux 4.14.35-1818.3.3.el7uek.x86_64
2020/07/03 10:27:04 [notice] 6361#6361: getrlimit(RLIMIT_NOFILE): 32756:65536
2020/07/03 10:27:04 [debug] 6362#6362: write: 7, 00007FFD85C2F850, 5, 0
2020/07/03 10:27:04 [debug] 6362#6362: setproctitle: "nginx: master process /opt/ss/nginx-1.19.0/sbin/nginx -c conf/nginx.conf.local"
2020/07/03 10:27:04 [notice] 6362#6362: start worker processes
2020/07/03 10:27:04 [debug] 6362#6362: channel 7:8
2020/07/03 10:27:04 [notice] 6362#6362: start worker process 6363
2020/07/03 10:27:04 [debug] 6362#6362: sigsuspend
2020/07/03 10:27:04 [debug] 6363#6363: add cleanup: 000055BEF970B4E8
2020/07/03 10:27:04 [debug] 6363#6363: malloc: 000055BEF9706AF0:8
2020/07/03 10:27:04 [debug] 6363#6363: notify eventfd: 10
2020/07/03 10:27:04 [debug] 6363#6363: eventfd: 11
2020/07/03 10:27:04 [debug] 6363#6363: testing the EPOLLRDHUP flag: success
2020/07/03 10:27:04 [debug] 6363#6363: malloc: 000055BEF96CB280:6144
2020/07/03 10:27:04 [debug] 6363#6363: malloc: 00007F892DB93010:237568
2020/07/03 10:27:04 [debug] 6363#6363: malloc: 000055BEF970BA70:98304
2020/07/03 10:27:04 [debug] 6363#6363: malloc: 000055BEF9723A80:98304
2020/07/03 10:27:04 [debug] 6363#6363: epoll add event: fd:6 op:1 ev:00002001
2020/07/03 10:27:04 [debug] 6363#6363: http vts init worker
2020/07/03 10:27:04 [debug] 6363#6363: vts::init_worker(): is bypassed
2020/07/03 10:27:04 [debug] 6363#6363: epoll add event: fd:8 op:1 ev:00002001
2020/07/03 10:27:04 [debug] 6363#6363: setproctitle: "nginx: worker process"
2020/07/03 10:27:04 [debug] 6363#6363: worker cycle
2020/07/03 10:27:04 [debug] 6363#6363: epoll timer: -1
2020/07/03 10:27:08 [debug] 6363#6363: epoll: fd:6 ev:0001 d:00007F892DB93010
2020/07/03 10:27:08 [debug] 6363#6363: accept on 0.0.0.0:80, ready: 0
2020/07/03 10:27:08 [debug] 6363#6363: posix_memalign: 000055BEF96F3A80:512 @16
2020/07/03 10:27:08 [debug] 6363#6363: *1 accept: 10.224.143.98:26779 fd:7
2020/07/03 10:27:08 [debug] 6363#6363: *1 event timer add: 7: 60000:1999376601
2020/07/03 10:27:08 [debug] 6363#6363: *1 reusable connection: 1
2020/07/03 10:27:08 [debug] 6363#6363: *1 epoll add event: fd:7 op:1 ev:80002001
2020/07/03 10:27:08 [debug] 6363#6363: timer delta: 4235
2020/07/03 10:27:08 [debug] 6363#6363: worker cycle
2020/07/03 10:27:08 [debug] 6363#6363: epoll timer: 60000
2020/07/03 10:27:08 [debug] 6363#6363: epoll: fd:7 ev:0001 d:00007F892DB931E0
2020/07/03 10:27:08 [debug] 6363#6363: *1 http wait request handler
2020/07/03 10:27:08 [debug] 6363#6363: *1 malloc: 000055BEF96A9340:1024
2020/07/03 10:27:08 [debug] 6363#6363: *1 recv: eof:0, avail:-1
2020/07/03 10:27:08 [debug] 6363#6363: *1 recv: fd:7 93 of 1024
2020/07/03 10:27:08 [debug] 6363#6363: *1 reusable connection: 0
2020/07/03 10:27:08 [debug] 6363#6363: *1 posix_memalign: 000055BEF96F5730:4096 @16
2020/07/03 10:27:08 [debug] 6363#6363: *1 http process request line
2020/07/03 10:27:08 [debug] 6363#6363: *1 http request line: "GET /?testparam=test HTTP/1.1"
2020/07/03 10:27:08 [debug] 6363#6363: *1 http uri: "/"
2020/07/03 10:27:08 [debug] 6363#6363: *1 http args: "testparam=test"
2020/07/03 10:27:08 [debug] 6363#6363: *1 http exten: ""
2020/07/03 10:27:08 [debug] 6363#6363: *1 posix_memalign: 000055BEF96CCA90:4096 @16
2020/07/03 10:27:08 [debug] 6363#6363: *1 http process request header line
2020/07/03 10:27:08 [debug] 6363#6363: *1 http header: "User-Agent: curl/7.29.0"
2020/07/03 10:27:08 [debug] 6363#6363: *1 http header: "Host: 10.224.143.107"
2020/07/03 10:27:08 [debug] 6363#6363: *1 http header: "Accept: */*"
2020/07/03 10:27:08 [debug] 6363#6363: *1 http header done
2020/07/03 10:27:08 [debug] 6363#6363: *1 event timer del: 7: 1999376601
2020/07/03 10:27:08 [debug] 6363#6363: *1 generic phase: 0
2020/07/03 10:27:08 [debug] 6363#6363: *1 generic phase: 1
2020/07/03 10:27:08 [debug] 6363#6363: *1 rewrite phase: 2
2020/07/03 10:27:08 [debug] 6363#6363: *1 test location: "/"
2020/07/03 10:27:08 [debug] 6363#6363: *1 using configuration "/"
2020/07/03 10:27:08 [debug] 6363#6363: *1 http cl:-1 max:1048576
2020/07/03 10:27:08 [debug] 6363#6363: *1 rewrite phase: 4
2020/07/03 10:27:08 [debug] 6363#6363: *1 add cleanup: 000055BEF96F64C0
2020/07/03 10:27:08 [error] 6363#6363: *1 [client 10.224.143.98] ModSecurity: Access denied with code 403 (phase 1). Matched "Operator `Contains' with parameter `test' against variable `ARGS:testparam' (Value: `test' ) [file "conf/rules-api.conf"] [line "25"] [id "92"] [rev ""] [msg "Bloqueio via regra de teste"] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "10.224.143.107"] [uri "/"] [unique_id "159378282830.750040"] [ref "o0,4v16,4"], client: 10.224.143.98, server: localhost, request: "GET /?testparam=test HTTP/1.1", host: "10.224.143.107"
2020/07/03 10:27:08 [error] 6363#6363: *1 [client 10.224.143.98] ModSecurity: Access denied with code 403 (phase 1). Matched "Operator `Contains' with parameter `test' against variable `ARGS:testparam' (Value: `test' ) [file "conf/rules-api.conf"] [line "25"] [id "92"] [rev ""] [msg "Bloqueio via regra de teste"] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "10.224.143.107"] [uri "/"] [unique_id "159378282830.750040"] [ref "o0,4v16,4"], client: 10.224.143.98, server: localhost, request: "GET /?testparam=test HTTP/1.1", host: "10.224.143.107"
2020/07/03 10:27:08 [debug] 6363#6363: *1 http finalize request: 403, "/?testparam=test" a:1, c:1
2020/07/03 10:27:08 [debug] 6363#6363: *1 http special response: 403, "/?testparam=test"
2020/07/03 10:27:08 [debug] 6363#6363: *1 http set discard body
2020/07/03 10:27:08 [debug] 6363#6363: *1 xslt filter header
2020/07/03 10:27:08 [debug] 6363#6363: *1 HTTP/1.1 403 Forbidden
Server: nginx/1.19.0
Date: Fri, 03 Jul 2020 13:27:08 GMT
Content-Type: text/html
Content-Length: 153
Connection: keep-alive

2020/07/03 10:27:08 [debug] 6363#6363: *1 write new buf t:1 f:0 000055BEF96F6580, pos 000055BEF96F6580, size: 155 file: 0, size: 0
2020/07/03 10:27:08 [debug] 6363#6363: *1 http write filter: l:0 f:0 s:155
2020/07/03 10:27:08 [debug] 6363#6363: *1 http output filter "/?testparam=test"
2020/07/03 10:27:08 [debug] 6363#6363: *1 http copy filter: "/?testparam=test"
2020/07/03 10:27:08 [debug] 6363#6363: *1 xslt filter body
2020/07/03 10:27:08 [debug] 6363#6363: *1 http postpone filter "/?testparam=test" 000055BEF96F66E0
2020/07/03 10:27:08 [debug] 6363#6363: *1 write old buf t:1 f:0 000055BEF96F6580, pos 000055BEF96F6580, size: 155 file: 0, size: 0
2020/07/03 10:27:08 [debug] 6363#6363: *1 write new buf t:0 f:0 0000000000000000, pos 000055BEF8D907C0, size: 100 file: 0, size: 0
2020/07/03 10:27:08 [debug] 6363#6363: *1 write new buf t:0 f:0 0000000000000000, pos 000055BEF8D90EA0, size: 53 file: 0, size: 0
2020/07/03 10:27:08 [debug] 6363#6363: *1 http write filter: l:1 f:0 s:308
2020/07/03 10:27:08 [debug] 6363#6363: *1 http write filter limit 0
2020/07/03 10:27:08 [debug] 6363#6363: *1 writev: 308 of 308
2020/07/03 10:27:08 [debug] 6363#6363: *1 http write filter 0000000000000000
2020/07/03 10:27:08 [debug] 6363#6363: *1 http copy filter: 0 "/?testparam=test"
2020/07/03 10:27:08 [debug] 6363#6363: *1 http finalize request: 0, "/?testparam=test" a:1, c:1
2020/07/03 10:27:08 [debug] 6363#6363: *1 set http keepalive handler
2020/07/03 10:27:08 [debug] 6363#6363: *1 http close request
2020/07/03 10:27:08 [debug] 6363#6363: *1 http log handler
2020/07/03 10:27:08 [debug] 6363#6363: *1 http vts handler
2020/07/03 10:27:08 [debug] 6363#6363: *1 malloc: 000055BEF973DD00:4096
2020/07/03 10:27:08 [debug] 6363#6363: *1 malloc: 000055BEF973ED10:4096
2020/07/03 10:27:08 [debug] 6363#6363: *1 free: 000055BEF973DD00
2020/07/03 10:27:08 [debug] 6363#6363: *1 free: 000055BEF973ED10
2020/07/03 10:27:08 [debug] 6363#6363: *1 run cleanup: 000055BEF96F64C0
2020/07/03 10:27:08 [debug] 6363#6363: *1 free: 0000000000000000
2020/07/03 10:27:08 [debug] 6363#6363: *1 free: 0000000000000000
2020/07/03 10:27:08 [debug] 6363#6363: *1 free: 000055BEF96F5730, unused: 14
2020/07/03 10:27:08 [debug] 6363#6363: *1 free: 000055BEF96CCA90, unused: 2344
2020/07/03 10:27:08 [debug] 6363#6363: *1 free: 000055BEF96A9340
2020/07/03 10:27:08 [debug] 6363#6363: *1 hc free: 0000000000000000
2020/07/03 10:27:08 [debug] 6363#6363: *1 hc busy: 0000000000000000 0
2020/07/03 10:27:08 [debug] 6363#6363: *1 tcp_nodelay
2020/07/03 10:27:08 [debug] 6363#6363: *1 reusable connection: 1
2020/07/03 10:27:08 [debug] 6363#6363: *1 event timer add: 7: 65000:1999381601
2020/07/03 10:27:08 [debug] 6363#6363: timer delta: 0
2020/07/03 10:27:08 [debug] 6363#6363: worker cycle
2020/07/03 10:27:08 [debug] 6363#6363: epoll timer: 65000
2020/07/03 10:27:08 [debug] 6363#6363: epoll: fd:7 ev:2001 d:00007F892DB931E0
2020/07/03 10:27:08 [debug] 6363#6363: *1 http keepalive handler
2020/07/03 10:27:08 [debug] 6363#6363: *1 malloc: 000055BEF96A9340:1024
2020/07/03 10:27:08 [debug] 6363#6363: *1 recv: eof:1, avail:-1
2020/07/03 10:27:08 [debug] 6363#6363: *1 recv: fd:7 0 of 1024
2020/07/03 10:27:08 [info] 6363#6363: *1 client 10.224.143.98 closed keepalive connection
2020/07/03 10:27:08 [debug] 6363#6363: *1 close http connection: 7
2020/07/03 10:27:08 [debug] 6363#6363: *1 event timer del: 7: 1999381601
2020/07/03 10:27:08 [debug] 6363#6363: *1 reusable connection: 0
2020/07/03 10:27:08 [debug] 6363#6363: *1 free: 000055BEF96A9340
2020/07/03 10:27:08 [debug] 6363#6363: *1 free: 000055BEF96F3A80, unused: 120
2020/07/03 10:27:08 [debug] 6363#6363: timer delta: 178
2020/07/03 10:27:08 [debug] 6363#6363: worker cycle
2020/07/03 10:27:08 [debug] 6363#6363: epoll timer: -1

The rules are the same as those used previously. In this case, the endpoint receives the audit events via HTTPS.

zimmerle commented 4 years ago

Try this:

SecDebugLogLevel 9
SecDebugLog /tmp/debug.txt

I expect to have some useful information why it is not working on the debug logs. Should be safe to specify SecDebugLogs and SecRemoteRules in the same config entry -

SecDebugLogLevel 9
SecDebugLog /tmp/debug.txt
SecRemoteRules ...
mdjunior commented 4 years ago

When I configure SecDebugLogLevel and SecDebugLog on rules remote endpoint, it seems that the policies have no effect. No files are generated.

When doing the same with a local configuration file, the file is generated and the events are written to it. I believe that there is some relationship between the remote loading of rules with the ability to write events (in a file or via HTTPS).

Other information: when I set up remote rules to write to a SecAuditLog file, that file is not written either. It is very similar with the feature of not writing the debug events.

Nginx configuration file:

worker_processes  1;
error_log  /dev/stderr;
error_log  /dev/stderr debug;
events {
    worker_connections  1024;
}
http {
    include       mime.types;
    default_type  application/octet-stream;
    sendfile        on;
    keepalive_timeout  65;
    server {
        listen       80;
        server_name  localhost;

        location / {
        modsecurity on;
            #modsecurity_rules_file "conf/rules-api.conf";
            modsecurity_rules_remote https-key "https://remote-endpoint/api/v1/sites/4a08c5d8-9de9-4ddb-8400-b05e940d8866/rules/raw";
        proxy_pass http://10.224.143.98;
        }
    }
}
mdjunior commented 4 years ago

The debug file generated when the rules are loaded locally (via file) is the following.

[159378519884.315334] [] [4] Initializing transaction
[159378519884.315334] [] [4] Transaction context created.
[159378519884.315334] [] [4] Starting phase CONNECTION. (SecRules 0)
[159378519884.315334] [] [9] This phase consists of 0 rule(s).
[159378519884.315334] [] [4] Starting phase URI. (SecRules 0 + 1/2)
[159378519884.315334] [/?testparam=test] [4] Adding request argument (GET): name "testparam", value "test"
[159378519884.315334] [/?testparam=test] [4] Starting phase REQUEST_HEADERS.  (SecRules 1)
[159378519884.315334] [/?testparam=test] [9] This phase consists of 7 rule(s).
[159378519884.315334] [/?testparam=test] [4] (Rule: 0) Executing unconditional rule...
[159378519884.315334] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159378519884.315334] [/?testparam=test] [8] Saving variable: TX:critical_anomaly_score with value: 5
[159378519884.315334] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159378519884.315334] [/?testparam=test] [8] Saving variable: TX:error_anomaly_score with value: 4
[159378519884.315334] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159378519884.315334] [/?testparam=test] [8] Saving variable: TX:warning_anomaly_score with value: 3
[159378519884.315334] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159378519884.315334] [/?testparam=test] [8] Saving variable: TX:notice_anomaly_score with value: 2
[159378519884.315334] [/?testparam=test] [9] Running action: log
[159378519884.315334] [/?testparam=test] [9] Saving transaction to logs
[159378519884.315334] [/?testparam=test] [9] Running action: auditlog
[159378519884.315334] [/?testparam=test] [9] Saving transaction to logs
[159378519884.315334] [/?testparam=test] [9] Running action: nolog
[159378519884.315334] [/?testparam=test] [4] Running (disruptive)     action: pass.
[159378519884.315334] [/?testparam=test] [8] Running action pass
[159378519884.315334] [/?testparam=test] [4] (Rule: 0) Executing unconditional rule...
[159378519884.315334] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159378519884.315334] [/?testparam=test] [8] Saving variable: TX:anomaly_score with value: 0
[159378519884.315334] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159378519884.315334] [/?testparam=test] [8] Saving variable: TX:sql_injection_score with value: 0
[159378519884.315334] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159378519884.315334] [/?testparam=test] [8] Saving variable: TX:xss_score with value: 0
[159378519884.315334] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159378519884.315334] [/?testparam=test] [8] Saving variable: TX:inbound_anomaly_score with value: 0
[159378519884.315334] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159378519884.315334] [/?testparam=test] [8] Saving variable: TX:outbound_anomaly_score with value: 0
[159378519884.315334] [/?testparam=test] [9] Running action: log
[159378519884.315334] [/?testparam=test] [9] Saving transaction to logs
[159378519884.315334] [/?testparam=test] [9] Running action: auditlog
[159378519884.315334] [/?testparam=test] [9] Saving transaction to logs
[159378519884.315334] [/?testparam=test] [9] Running action: nolog
[159378519884.315334] [/?testparam=test] [4] Running (disruptive)     action: pass.
[159378519884.315334] [/?testparam=test] [8] Running action pass
[159378519884.315334] [/?testparam=test] [4] (Rule: 0) Executing unconditional rule...
[159378519884.315334] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159378519884.315334] [/?testparam=test] [8] Saving variable: TX:inbound_anomaly_score_level with value: 5
[159378519884.315334] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159378519884.315334] [/?testparam=test] [8] Saving variable: TX:outbound_anomaly_score_level with value: 4
[159378519884.315334] [/?testparam=test] [9] Running action: log
[159378519884.315334] [/?testparam=test] [9] Saving transaction to logs
[159378519884.315334] [/?testparam=test] [9] Running action: auditlog
[159378519884.315334] [/?testparam=test] [9] Saving transaction to logs
[159378519884.315334] [/?testparam=test] [9] Running action: nolog
[159378519884.315334] [/?testparam=test] [4] Running (disruptive)     action: pass.
[159378519884.315334] [/?testparam=test] [8] Running action pass
[159378519884.315334] [/?testparam=test] [4] (Rule: 0) Executing unconditional rule...
[159378519884.315334] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159378519884.315334] [/?testparam=test] [8] Saving variable: TX:max_num_args with value: 255
[159378519884.315334] [/?testparam=test] [9] Running action: log
[159378519884.315334] [/?testparam=test] [9] Saving transaction to logs
[159378519884.315334] [/?testparam=test] [9] Running action: auditlog
[159378519884.315334] [/?testparam=test] [9] Saving transaction to logs
[159378519884.315334] [/?testparam=test] [9] Running action: nolog
[159378519884.315334] [/?testparam=test] [4] Running (disruptive)     action: pass.
[159378519884.315334] [/?testparam=test] [8] Running action pass
[159378519884.315334] [/?testparam=test] [4] (Rule: 89) Executing operator "Rx" with param "text/xml" against REQUEST_HEADERS:Content-Type.
[159378519884.315334] [/?testparam=test] [4] Rule returned 0.
[159378519884.315334] [/?testparam=test] [9] Matched vars cleaned.
[159378519884.315334] [/?testparam=test] [4] (Rule: 90) Executing operator "Rx" with param "application/json" against REQUEST_HEADERS:Content-Type.
[159378519884.315334] [/?testparam=test] [4] Rule returned 0.
[159378519884.315334] [/?testparam=test] [9] Matched vars cleaned.
[159378519884.315334] [/?testparam=test] [4] (Rule: 92) Executing operator "Contains" with param "test" against ARGS:testparam.
[159378519884.315334] [/?testparam=test] [9] Target value: "test" (Variable: ARGS:testparam)
[159378519884.315334] [/?testparam=test] [9] Matched vars updated.
[159378519884.315334] [/?testparam=test] [9] Saving msg: Bloqueio via regra de teste
[159378519884.315334] [/?testparam=test] [4] Rule returned 1.
[159378519884.315334] [/?testparam=test] [9] Running action: log
[159378519884.315334] [/?testparam=test] [9] Saving transaction to logs
[159378519884.315334] [/?testparam=test] [9] Running action: auditlog
[159378519884.315334] [/?testparam=test] [9] Saving transaction to logs
[159378519884.315334] [/?testparam=test] [9] Running action: log
[159378519884.315334] [/?testparam=test] [9] Saving transaction to logs
[159378519884.315334] [/?testparam=test] [4] Running (disruptive)     action: block.
[159378519884.315334] [/?testparam=test] [8] Marking request as disruptive.
[159378519884.315334] [/?testparam=test] [8] Running action deny
[159378519884.315334] [/?testparam=test] [8] Skipping this phase as this request was already intercepted.
[159378519884.315334] [/?testparam=test] [4] Starting phase RESPONSE_HEADERS. (SecRules 3)
[159378519884.315334] [/?testparam=test] [9] This phase consists of 0 rule(s).
[159378519884.315334] [/?testparam=test] [9] Appending response body: 100 bytes. Limit set to: 0.000000
[159378519884.315334] [/?testparam=test] [9] Appending response body: 153 bytes. Limit set to: 0.000000
[159378519884.315334] [/?testparam=test] [4] Starting phase RESPONSE_BODY. (SecRules 4)
[159378519884.315334] [/?testparam=test] [4] Response body is disabled, returning... 1
[159378519884.315334] [/?testparam=test] [4] Starting phase LOGGING. (SecRules 5)
[159378519884.315334] [/?testparam=test] [9] This phase consists of 0 rule(s).
[159378519884.315334] [/?testparam=test] [8] Checking if this request is suitable to be saved as an audit log.
[159378519884.315334] [/?testparam=test] [8] Checking if this request is relevant to be part of the audit logs.
[159378519884.315334] [/?testparam=test] [5] Saving this request as part of the audit logs.
[159378519884.315334] [/?testparam=test] [7] Sending logs to: https://remote-endpoint/api/v1/sites/eb25596a-ac1f-4a13-a756-b4671aed7f5d/events
[159378519884.315334] [/?testparam=test] [8] Request was relevant to be saved. Parts: 6006
martinhsv commented 4 years ago

I gave this a quick try last night and did not encounter the same problem. I.e. the SecAuditLog setting from the remote file was respected. (I was not, however, duplicating your setup particularly closely; I had a different version of nginx (1.16.1), and I used http rather https for the remote file, etc.)

mdjunior commented 4 years ago

I'm going to set up a lab with this version of nginx (1.16.1).

@martinhsv I didn't understand how you managed to send the data over HTTP. The documentation shows that only HTTPS is supported. Can you share the configuration file?

martinhsv commented 4 years ago

The (v2.9) documentation sure does say that. I'm not sure whether loosening the restriction in v3 was intentional or an oversight.

The config line I used in my quick test looked like this:

modsecurity_rules_remote fakekey http://xxx.xxx.xxx.xxx/files/rules.txt;

This is just a hunch, but if a couple of those file-specific logging config items are the only things that seem to not be respected when coming from the remote file, I wonder if maybe you're hitting some unexpected file permissions issue. If you think that's worth an experiment, you could try opening up the permissions for the normal location, or try writing the logs elsewhere where you're ok with allowing broad write access. Just a thought.

zimmerle commented 4 years ago

I also have noticed that you have this remote endpoint for the logging file - 

Sending logs to: https://remote-endpoint/api/v1/sites/eb25596a-ac1f-4a13-a756-b4671aed7f5d/events

Is that in parallel with the file?

mdjunior commented 4 years ago

Yes, when I set up the rules in a file on disk, the audit logs are sent to the remote endpoint.

mdjunior commented 4 years ago

I configured nginx 1.16.1 using the same version of libmodsecurity and got the same behavior. When rules are loaded remotely, log files are not written to disk and audit logs are not sent to the https endpoint.

2020/07/03 12:06:20 [notice] 8573#8573: ModSecurity-nginx v1.0.1 (rules loaded inline/local/remote: 0/0/10)
2020/07/03 12:06:20 [debug] 8573#8573: bind() 0.0.0.0:80 #8 
2020/07/03 12:06:20 [notice] 8573#8573: using the "epoll" event method
2020/07/03 12:06:20 [debug] 8573#8573: counter: 00007FAA809B3080, 1
2020/07/03 12:06:20 [notice] 8573#8573: nginx/1.16.1
2020/07/03 12:06:20 [notice] 8573#8573: built by gcc 4.8.5 20150623 (Red Hat 4.8.5-39.0.1) (GCC) 
2020/07/03 12:06:20 [notice] 8573#8573: OS: Linux 4.14.35-1818.3.3.el7uek.x86_64
2020/07/03 12:06:20 [notice] 8573#8573: getrlimit(RLIMIT_NOFILE): 32756:65536
[root@ss-nginx-c1cm1-03 nginx-1.16.1]# 2020/07/03 12:06:20 [debug] 8575#8575: write: 9, 00007FFC811FA820, 5, 0
2020/07/03 12:06:20 [debug] 8575#8575: setproctitle: "nginx: master process /opt/ss/nginx-1.16.1/sbin/nginx -c conf/nginx.conf.default"
2020/07/03 12:06:20 [notice] 8575#8575: start worker processes
2020/07/03 12:06:20 [debug] 8575#8575: channel 9:10
2020/07/03 12:06:20 [notice] 8575#8575: start worker process 8576
2020/07/03 12:06:20 [debug] 8575#8575: sigsuspend
2020/07/03 12:06:20 [debug] 8576#8576: add cleanup: 000056275F1D1F10
2020/07/03 12:06:20 [debug] 8576#8576: malloc: 000056275F29DCB0:8
2020/07/03 12:06:20 [debug] 8576#8576: notify eventfd: 12
2020/07/03 12:06:20 [debug] 8576#8576: eventfd: 13
2020/07/03 12:06:20 [debug] 8576#8576: testing the EPOLLRDHUP flag: success
2020/07/03 12:06:20 [debug] 8576#8576: malloc: 000056275F297350:6144
2020/07/03 12:06:20 [debug] 8576#8576: malloc: 00007FAA8082C010:253952
2020/07/03 12:06:20 [debug] 8576#8576: malloc: 000056275F1D2600:98304
2020/07/03 12:06:20 [debug] 8576#8576: malloc: 000056275F2B4DF0:98304
2020/07/03 12:06:20 [debug] 8576#8576: epoll add event: fd:8 op:1 ev:00002001
2020/07/03 12:06:20 [debug] 8576#8576: http vts init worker
2020/07/03 12:06:20 [debug] 8576#8576: vts::init_worker(): is bypassed
2020/07/03 12:06:20 [debug] 8576#8576: epoll add event: fd:10 op:1 ev:00002001
2020/07/03 12:06:20 [debug] 8576#8576: setproctitle: "nginx: worker process"
2020/07/03 12:06:20 [debug] 8576#8576: worker cycle
2020/07/03 12:06:20 [debug] 8576#8576: epoll timer: -1
2020/07/03 12:06:26 [debug] 8576#8576: epoll: fd:8 ev:0001 d:00007FAA8082C010
2020/07/03 12:06:26 [debug] 8576#8576: accept on 0.0.0.0:80, ready: 0
2020/07/03 12:06:26 [debug] 8576#8576: posix_memalign: 000056275F2A7860:512 @16
2020/07/03 12:06:26 [debug] 8576#8576: *1 accept: 10.224.143.98:26903 fd:9
2020/07/03 12:06:26 [debug] 8576#8576: *1 event timer add: 9: 60000:2005334813
2020/07/03 12:06:26 [debug] 8576#8576: *1 reusable connection: 1
2020/07/03 12:06:26 [debug] 8576#8576: *1 epoll add event: fd:9 op:1 ev:80002001
2020/07/03 12:06:26 [debug] 8576#8576: timer delta: 6334
2020/07/03 12:06:26 [debug] 8576#8576: worker cycle
2020/07/03 12:06:26 [debug] 8576#8576: epoll timer: 60000
2020/07/03 12:06:26 [debug] 8576#8576: epoll: fd:9 ev:0001 d:00007FAA8082C200
2020/07/03 12:06:26 [debug] 8576#8576: *1 http wait request handler
2020/07/03 12:06:26 [debug] 8576#8576: *1 malloc: 000056275F184340:1024
2020/07/03 12:06:26 [debug] 8576#8576: *1 recv: eof:0, avail:1
2020/07/03 12:06:26 [debug] 8576#8576: *1 recv: fd:9 93 of 1024
2020/07/03 12:06:26 [debug] 8576#8576: *1 reusable connection: 0
2020/07/03 12:06:26 [debug] 8576#8576: *1 posix_memalign: 000056275F2AB770:4096 @16
2020/07/03 12:06:26 [debug] 8576#8576: *1 http process request line
2020/07/03 12:06:26 [debug] 8576#8576: *1 http request line: "GET /?testparam=test HTTP/1.1"
2020/07/03 12:06:26 [debug] 8576#8576: *1 http uri: "/"
2020/07/03 12:06:26 [debug] 8576#8576: *1 http args: "testparam=test"
2020/07/03 12:06:26 [debug] 8576#8576: *1 http exten: ""
2020/07/03 12:06:26 [debug] 8576#8576: *1 posix_memalign: 000056275F29ADD0:4096 @16
2020/07/03 12:06:26 [debug] 8576#8576: *1 http process request header line
2020/07/03 12:06:26 [debug] 8576#8576: *1 http header: "User-Agent: curl/7.29.0"
2020/07/03 12:06:26 [debug] 8576#8576: *1 http header: "Host: 10.224.143.107"
2020/07/03 12:06:26 [debug] 8576#8576: *1 http header: "Accept: */*"
2020/07/03 12:06:26 [debug] 8576#8576: *1 http header done
2020/07/03 12:06:26 [debug] 8576#8576: *1 event timer del: 9: 2005334813
2020/07/03 12:06:26 [debug] 8576#8576: *1 generic phase: 0
2020/07/03 12:06:26 [debug] 8576#8576: *1 generic phase: 1
2020/07/03 12:06:26 [debug] 8576#8576: *1 rewrite phase: 2
2020/07/03 12:06:26 [debug] 8576#8576: *1 test location: "/"
2020/07/03 12:06:26 [debug] 8576#8576: *1 using configuration "/"
2020/07/03 12:06:26 [debug] 8576#8576: *1 http cl:-1 max:1048576
2020/07/03 12:06:26 [debug] 8576#8576: *1 rewrite phase: 4
2020/07/03 12:06:26 [debug] 8576#8576: *1 add cleanup: 000056275F2AC500
2020/07/03 12:06:26 [error] 8576#8576: *1 [client 10.224.143.98] ModSecurity: Access denied with code 403 (phase 1). Matched "Operator `Contains' with parameter `test' against variable `ARGS:testparam' (Value: `test' ) [file "https://remote-endpoint/api/v1/sites/4a08c5d8-9de9-4ddb-8400-b05e940d8866/rules/raw"] [line "31"] [id "32"] [rev ""] [msg "Bloqueio via regra de teste"] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "10.224.143.107"] [uri "/"] [unique_id "15937887863.348623"] [ref "o0,4v16,4"], client: 10.224.143.98, server: localhost, request: "GET /?testparam=test HTTP/1.1", host: "10.224.143.107"
2020/07/03 12:06:26 [error] 8576#8576: *1 [client 10.224.143.98] ModSecurity: Access denied with code 403 (phase 1). Matched "Operator `Contains' with parameter `test' against variable `ARGS:testparam' (Value: `test' ) [file "https://remote-endpoint/api/v1/sites/4a08c5d8-9de9-4ddb-8400-b05e940d8866/rules/raw"] [line "31"] [id "32"] [rev ""] [msg "Bloqueio via regra de teste"] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "10.224.143.107"] [uri "/"] [unique_id "15937887863.348623"] [ref "o0,4v16,4"], client: 10.224.143.98, server: localhost, request: "GET /?testparam=test HTTP/1.1", host: "10.224.143.107"
2020/07/03 12:06:26 [debug] 8576#8576: *1 http finalize request: 403, "/?testparam=test" a:1, c:1
2020/07/03 12:06:26 [debug] 8576#8576: *1 http special response: 403, "/?testparam=test"
2020/07/03 12:06:26 [debug] 8576#8576: *1 http set discard body
2020/07/03 12:06:26 [debug] 8576#8576: *1 xslt filter header
2020/07/03 12:06:26 [debug] 8576#8576: *1 HTTP/1.1 403 Forbidden
Server: nginx/1.16.1
Date: Fri, 03 Jul 2020 15:06:26 GMT
Content-Type: text/html
Content-Length: 153
Connection: keep-alive

2020/07/03 12:06:26 [debug] 8576#8576: *1 write new buf t:1 f:0 000056275F2AC5C0, pos 000056275F2AC5C0, size: 155 file: 0, size: 0
2020/07/03 12:06:26 [debug] 8576#8576: *1 http write filter: l:0 f:0 s:155
2020/07/03 12:06:26 [debug] 8576#8576: *1 http output filter "/?testparam=test"
2020/07/03 12:06:26 [debug] 8576#8576: *1 http copy filter: "/?testparam=test"
2020/07/03 12:06:26 [debug] 8576#8576: *1 xslt filter body
2020/07/03 12:06:26 [debug] 8576#8576: *1 http postpone filter "/?testparam=test" 000056275F2AC720
2020/07/03 12:06:26 [debug] 8576#8576: *1 write old buf t:1 f:0 000056275F2AC5C0, pos 000056275F2AC5C0, size: 155 file: 0, size: 0
2020/07/03 12:06:26 [debug] 8576#8576: *1 write new buf t:0 f:0 0000000000000000, pos 000056275DC99780, size: 100 file: 0, size: 0
2020/07/03 12:06:26 [debug] 8576#8576: *1 write new buf t:0 f:0 0000000000000000, pos 000056275DC99E60, size: 53 file: 0, size: 0
2020/07/03 12:06:26 [debug] 8576#8576: *1 http write filter: l:1 f:0 s:308
2020/07/03 12:06:26 [debug] 8576#8576: *1 http write filter limit 0
2020/07/03 12:06:26 [debug] 8576#8576: *1 writev: 308 of 308
2020/07/03 12:06:26 [debug] 8576#8576: *1 http write filter 0000000000000000
2020/07/03 12:06:26 [debug] 8576#8576: *1 http copy filter: 0 "/?testparam=test"
2020/07/03 12:06:26 [debug] 8576#8576: *1 http finalize request: 0, "/?testparam=test" a:1, c:1
2020/07/03 12:06:26 [debug] 8576#8576: *1 set http keepalive handler
2020/07/03 12:06:26 [debug] 8576#8576: *1 http close request
2020/07/03 12:06:26 [debug] 8576#8576: *1 http log handler
2020/07/03 12:06:26 [debug] 8576#8576: *1 http vts handler
2020/07/03 12:06:26 [debug] 8576#8576: *1 malloc: 000056275F1A66C0:4096
2020/07/03 12:06:26 [debug] 8576#8576: *1 malloc: 000056275F1A76D0:4096
2020/07/03 12:06:26 [debug] 8576#8576: *1 free: 000056275F1A66C0
2020/07/03 12:06:26 [debug] 8576#8576: *1 free: 000056275F1A76D0
2020/07/03 12:06:26 [debug] 8576#8576: *1 run cleanup: 000056275F2AC500
2020/07/03 12:06:26 [debug] 8576#8576: *1 free: 0000000000000000
2020/07/03 12:06:26 [debug] 8576#8576: *1 free: 0000000000000000
2020/07/03 12:06:26 [debug] 8576#8576: *1 free: 000056275F2AB770, unused: 14
2020/07/03 12:06:26 [debug] 8576#8576: *1 free: 000056275F29ADD0, unused: 2344
2020/07/03 12:06:26 [debug] 8576#8576: *1 free: 000056275F184340
2020/07/03 12:06:26 [debug] 8576#8576: *1 hc free: 0000000000000000
2020/07/03 12:06:26 [debug] 8576#8576: *1 hc busy: 0000000000000000 0
2020/07/03 12:06:26 [debug] 8576#8576: *1 tcp_nodelay
2020/07/03 12:06:26 [debug] 8576#8576: *1 reusable connection: 1
2020/07/03 12:06:26 [debug] 8576#8576: *1 event timer add: 9: 65000:2005339814
2020/07/03 12:06:26 [debug] 8576#8576: timer delta: 1
2020/07/03 12:06:26 [debug] 8576#8576: worker cycle
2020/07/03 12:06:26 [debug] 8576#8576: epoll timer: 65000
2020/07/03 12:06:26 [debug] 8576#8576: epoll: fd:9 ev:2001 d:00007FAA8082C200
2020/07/03 12:06:26 [debug] 8576#8576: *1 http keepalive handler
2020/07/03 12:06:26 [debug] 8576#8576: *1 malloc: 000056275F184340:1024
2020/07/03 12:06:26 [debug] 8576#8576: *1 recv: eof:1, avail:1
2020/07/03 12:06:26 [debug] 8576#8576: *1 recv: fd:9 0 of 1024
2020/07/03 12:06:26 [info] 8576#8576: *1 client 10.224.143.98 closed keepalive connection
2020/07/03 12:06:26 [debug] 8576#8576: *1 close http connection: 9
2020/07/03 12:06:26 [debug] 8576#8576: *1 event timer del: 9: 2005339814
2020/07/03 12:06:26 [debug] 8576#8576: *1 reusable connection: 0
2020/07/03 12:06:26 [debug] 8576#8576: *1 free: 000056275F184340
2020/07/03 12:06:26 [debug] 8576#8576: *1 free: 000056275F2A7860, unused: 120
2020/07/03 12:06:26 [debug] 8576#8576: timer delta: 11
2020/07/03 12:06:26 [debug] 8576#8576: worker cycle
2020/07/03 12:06:26 [debug] 8576#8576: epoll timer: -1

More details on how nginx was generated:

nginx version: nginx/1.16.1
built by gcc 4.8.5 20150623 (Red Hat 4.8.5-39.0.1) (GCC) 
built with OpenSSL 1.1.1c  28 May 2019
TLS SNI support enabled
configure arguments: --prefix=/opt/ss/nginx-1.16.1 --with-debug --without-mail_smtp_module --without-mail_pop3_module --without-mail_imap_module --with-http_ssl_module --with-http_v2_module --with-threads --with-file-aio --with-http_realip_module --with-http_addition_module --with-http_xslt_module --with-http_sub_module --with-http_gunzip_module --with-http_gzip_static_module --with-http_auth_request_module --with-http_random_index_module --with-http_secure_link_module --with-http_degradation_module --with-http_slice_module --with-http_stub_status_module --with-stream --with-stream_ssl_module --with-stream_ssl_preread_module --with-stream_realip_module --with-pcre-jit --error-log-path=stderr --http-log-path=stderr --pid-path=/tmp/nginx.pid --without-http_fastcgi_module --without-http_scgi_module --with-cc=gcc --with-cc-opt=' -Ofast -g -pipe -Wall -mtune=corei7-avx -march=corei7-avx -m64 -maes -mpclmul -msse3 -mssse3 -msse4.1 -msse4.2 -mpopcnt -mfpmath=sse -falign-loops -fomit-frame-pointer -funsafe-math-optimizations -mno-avx -mno-f16c -mno-rdrnd -mno-fsgsbase -fstack-protector-all --param=ssp-buffer-size=4 -Wp,-D_FORTIFY_SOURCE=2 -Wformat -Werror=format-security -fPIE -fPIC -fexceptions -Wa,--noexecstack -Wp,-grecord-gcc-switches' --with-ld-opt=' -Wl,-rpath,/opt/ss/nginx-1.16.1/lib -Wl,-z,relro -Wl,-z,now -Wl,--as-needed -fPIC -fPIE -pie -Wl,-Bsymbolic-functions' --add-module=ngx_devel_kit-0.3.0 --add-module=echo-nginx-module-0.61 --add-module=set-misc-nginx-module-0.32 --add-module=headers-more-nginx-module-0.33 --add-module=ngx_cache_purge-2.3 --add-module=nginx-trusted-proxy-resolver-module-0.3 --with-openssl=openssl-1.1.1c --with-openssl-opt=' -Ofast -g -pipe -Wall -mtune=corei7-avx -march=corei7-avx -m64 -maes -mpclmul -msse3 -mssse3 -msse4.1 -msse4.2 -mpopcnt -mfpmath=sse -falign-loops -fomit-frame-pointer -funsafe-math-optimizations -mno-avx -mno-f16c -mno-rdrnd -mno-fsgsbase -fstack-protector-all --param=ssp-buffer-size=4 -Wp,-D_FORTIFY_SOURCE=2 -Wformat -Werror=format-security -fPIE -fPIC -fexceptions -Wa,--noexecstack -Wp,-grecord-gcc-switches -lz -lpthread -DOPENSSL_PIC -DZLIB -DDSO_DLFCN -DHAVE_DLFCN_H -DKRB5_MIT -DL_ENDIAN -DTERMIO -DPURIFY -DWHIRLPOOL_ASM -DAES_ASM -DRC4_ASM -DOPENSSL_THREADS -D_REENTRANT' --add-module=nginx-module-vts-46d85558e344dfe2b078ce757fd36c69a1ec2dd3 --add-module=nginx-uuid4-module-f8f7ff44e6a8c6cf75232ae4b63d011f2f3b34c1 --add-module=modsecurity-nginx-v1.0.1
zimmerle commented 4 years ago

@mdjunior

What about using this option:

SecDebugLogLevel 9
SecDebugLog /tmp/debug.txt
SecRemoteRules ...

It is a mix, the SecDebugLogs will be enabled locally and yet the auditlog will be enabled from the remote rules.

mdjunior commented 4 years ago

I did a combination of tests with the following settings:

Inline rules to get remote rules

nginx.conf

worker_processes  1;

error_log  /dev/stderr;
error_log  /dev/stderr debug;

events {
    worker_connections  1024;
}
http {
    include       mime.types;
    default_type  application/octet-stream;
    sendfile        on;
    keepalive_timeout  65;
    server {
        listen       80;
        server_name  localhost;

        location / {
        modsecurity on;
            modsecurity_rules '
SecRuleEngine On
SecRemoteRules https-key "https://remote-endpoint/api/v1/sites/4a08c5d8-9de9-4ddb-8400-b05e940d8866/rules/raw"
SecDebugLogLevel 9
SecDebugLog /tmp/debug.txt
';
        proxy_pass http://10.224.143.98;
        }
    }
}

In this example, the remote rules have not been loaded. There is not even an HTTP call at the remote endpoint. The debug file is created, but as the rules have not been loaded, it has the following information:

[159379231593.810915] [] [4] Initializing transaction
[159379231593.810915] [] [4] Transaction context created.
[159379231593.810915] [] [4] Starting phase CONNECTION. (SecRules 0)
[159379231593.810915] [] [9] This phase consists of 0 rule(s).
[159379231593.810915] [] [4] Starting phase URI. (SecRules 0 + 1/2)
[159379231593.810915] [/?testparam=test] [4] Adding request argument (GET): name "testparam", value "test"
[159379231593.810915] [/?testparam=test] [4] Starting phase REQUEST_HEADERS.  (SecRules 1)
[159379231593.810915] [/?testparam=test] [9] This phase consists of 0 rule(s).
[159379231593.810915] [/?testparam=test] [4] Starting phase REQUEST_BODY. (SecRules 2)
[159379231593.810915] [/?testparam=test] [9] This phase consists of 0 rule(s).
[159379231593.810915] [/?testparam=test] [4] Starting phase RESPONSE_HEADERS. (SecRules 3)
[159379231593.810915] [/?testparam=test] [9] This phase consists of 0 rule(s).
[159379231593.810915] [/?testparam=test] [9] Appending response body: 104 bytes. Limit set to: 0.000000
[159379231593.810915] [/?testparam=test] [9] Appending response body: 157 bytes. Limit set to: 0.000000
[159379231593.810915] [/?testparam=test] [4] Starting phase RESPONSE_BODY. (SecRules 4)
[159379231593.810915] [/?testparam=test] [4] Response body is disabled, returning... 2
[159379231593.810915] [/?testparam=test] [4] Starting phase LOGGING. (SecRules 5)
[159379231593.810915] [/?testparam=test] [9] This phase consists of 0 rule(s).
[159379231593.810915] [/?testparam=test] [8] Checking if this request is suitable to be saved as an audit log.
[159379231593.810915] [/?testparam=test] [8] Checking if this request is relevant to be part of the audit logs.
[159379231593.810915] [/?testparam=test] [5] Audit log engine was not set.
[159379231593.810915] [/?testparam=test] [8] Request was relevant to be saved. Parts: 4430

Inline rules (debug) with remote rules

nginx.conf

worker_processes  1;
error_log  /dev/stderr;
error_log  /dev/stderr debug;
events {
    worker_connections  1024;
}
http {
    include       mime.types;
    default_type  application/octet-stream;
    sendfile        on;
    keepalive_timeout  65;
    server {
        listen       80;
        server_name  localhost;

        location / {
        modsecurity on;
            modsecurity_rules '
SecRuleEngine On
SecDebugLogLevel 9
SecDebugLog /tmp/debug.txt
';
            modsecurity_rules_remote https-key "https://remote-endpoint/api/v1/sites/4a08c5d8-9de9-4ddb-8400-b05e940d8866/rules/raw";
        proxy_pass http://10.224.143.98;
        }
    }
}

The debug file is created, and the rules are loaded, but the audit events are not sent (I monitored the endpoint where the event should have arrived. The event was not sent using POST to /.).

[159379270314.971984] [] [4] Initializing transaction
[159379270314.971984] [] [4] Transaction context created.
[159379270314.971984] [] [4] Starting phase CONNECTION. (SecRules 0)
[159379270314.971984] [] [9] This phase consists of 0 rule(s).
[159379270314.971984] [] [4] Starting phase URI. (SecRules 0 + 1/2)
[159379270314.971984] [/?testparam=test] [4] Adding request argument (GET): name "testparam", value "test"
[159379270314.971984] [/?testparam=test] [4] Starting phase REQUEST_HEADERS.  (SecRules 1)
[159379270314.971984] [/?testparam=test] [9] This phase consists of 7 rule(s).
[159379270314.971984] [/?testparam=test] [4] (Rule: 0) Executing unconditional rule...
[159379270314.971984] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379270314.971984] [/?testparam=test] [8] Saving variable: TX:critical_anomaly_score with value: 5
[159379270314.971984] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379270314.971984] [/?testparam=test] [8] Saving variable: TX:error_anomaly_score with value: 4
[159379270314.971984] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379270314.971984] [/?testparam=test] [8] Saving variable: TX:warning_anomaly_score with value: 3
[159379270314.971984] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379270314.971984] [/?testparam=test] [8] Saving variable: TX:notice_anomaly_score with value: 2
[159379270314.971984] [/?testparam=test] [9] Running action: log
[159379270314.971984] [/?testparam=test] [9] Saving transaction to logs
[159379270314.971984] [/?testparam=test] [9] Running action: auditlog
[159379270314.971984] [/?testparam=test] [9] Saving transaction to logs
[159379270314.971984] [/?testparam=test] [9] Running action: nolog
[159379270314.971984] [/?testparam=test] [4] Running (disruptive)     action: pass.
[159379270314.971984] [/?testparam=test] [8] Running action pass
[159379270314.971984] [/?testparam=test] [4] (Rule: 0) Executing unconditional rule...
[159379270314.971984] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379270314.971984] [/?testparam=test] [8] Saving variable: TX:anomaly_score with value: 0
[159379270314.971984] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379270314.971984] [/?testparam=test] [8] Saving variable: TX:sql_injection_score with value: 0
[159379270314.971984] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379270314.971984] [/?testparam=test] [8] Saving variable: TX:xss_score with value: 0
[159379270314.971984] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379270314.971984] [/?testparam=test] [8] Saving variable: TX:inbound_anomaly_score with value: 0
[159379270314.971984] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379270314.971984] [/?testparam=test] [8] Saving variable: TX:outbound_anomaly_score with value: 0
[159379270314.971984] [/?testparam=test] [9] Running action: log
[159379270314.971984] [/?testparam=test] [9] Saving transaction to logs
[159379270314.971984] [/?testparam=test] [9] Running action: auditlog
[159379270314.971984] [/?testparam=test] [9] Saving transaction to logs
[159379270314.971984] [/?testparam=test] [9] Running action: nolog
[159379270314.971984] [/?testparam=test] [4] Running (disruptive)     action: pass.
[159379270314.971984] [/?testparam=test] [8] Running action pass
[159379270314.971984] [/?testparam=test] [4] (Rule: 0) Executing unconditional rule...
[159379270314.971984] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379270314.971984] [/?testparam=test] [8] Saving variable: TX:inbound_anomaly_score_level with value: 5
[159379270314.971984] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379270314.971984] [/?testparam=test] [8] Saving variable: TX:outbound_anomaly_score_level with value: 4
[159379270314.971984] [/?testparam=test] [9] Running action: log
[159379270314.971984] [/?testparam=test] [9] Saving transaction to logs
[159379270314.971984] [/?testparam=test] [9] Running action: auditlog
[159379270314.971984] [/?testparam=test] [9] Saving transaction to logs
[159379270314.971984] [/?testparam=test] [9] Running action: nolog
[159379270314.971984] [/?testparam=test] [4] Running (disruptive)     action: pass.
[159379270314.971984] [/?testparam=test] [8] Running action pass
[159379270314.971984] [/?testparam=test] [4] (Rule: 0) Executing unconditional rule...
[159379270314.971984] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379270314.971984] [/?testparam=test] [8] Saving variable: TX:max_num_args with value: 255
[159379270314.971984] [/?testparam=test] [9] Running action: log
[159379270314.971984] [/?testparam=test] [9] Saving transaction to logs
[159379270314.971984] [/?testparam=test] [9] Running action: auditlog
[159379270314.971984] [/?testparam=test] [9] Saving transaction to logs
[159379270314.971984] [/?testparam=test] [9] Running action: nolog
[159379270314.971984] [/?testparam=test] [4] Running (disruptive)     action: pass.
[159379270314.971984] [/?testparam=test] [8] Running action pass
[159379270314.971984] [/?testparam=test] [4] (Rule: 29) Executing operator "Rx" with param "text/xml" against REQUEST_HEADERS:Content-Type.
[159379270314.971984] [/?testparam=test] [4] Rule returned 0.
[159379270314.971984] [/?testparam=test] [9] Matched vars cleaned.
[159379270314.971984] [/?testparam=test] [4] (Rule: 30) Executing operator "Rx" with param "application/json" against REQUEST_HEADERS:Content-Type.
[159379270314.971984] [/?testparam=test] [4] Rule returned 0.
[159379270314.971984] [/?testparam=test] [9] Matched vars cleaned.
[159379270314.971984] [/?testparam=test] [4] (Rule: 32) Executing operator "Contains" with param "test" against ARGS:testparam.
[159379270314.971984] [/?testparam=test] [9] Target value: "test" (Variable: ARGS:testparam)
[159379270314.971984] [/?testparam=test] [9] Matched vars updated.
[159379270314.971984] [/?testparam=test] [9] Saving msg: Bloqueio via regra de teste
[159379270314.971984] [/?testparam=test] [4] Rule returned 1.
[159379270314.971984] [/?testparam=test] [9] Running action: log
[159379270314.971984] [/?testparam=test] [9] Saving transaction to logs
[159379270314.971984] [/?testparam=test] [9] Running action: auditlog
[159379270314.971984] [/?testparam=test] [9] Saving transaction to logs
[159379270314.971984] [/?testparam=test] [9] Running action: log
[159379270314.971984] [/?testparam=test] [9] Saving transaction to logs
[159379270314.971984] [/?testparam=test] [4] Running (disruptive)     action: block.
[159379270314.971984] [/?testparam=test] [8] Marking request as disruptive.
[159379270314.971984] [/?testparam=test] [8] Running action deny
[159379270314.971984] [/?testparam=test] [8] Skipping this phase as this request was already intercepted.
[159379270314.971984] [/?testparam=test] [4] Starting phase RESPONSE_HEADERS. (SecRules 3)
[159379270314.971984] [/?testparam=test] [9] This phase consists of 0 rule(s).
[159379270314.971984] [/?testparam=test] [9] Appending response body: 100 bytes. Limit set to: 524288.000000
[159379270314.971984] [/?testparam=test] [9] Appending response body: 153 bytes. Limit set to: 524288.000000
[159379270314.971984] [/?testparam=test] [4] Starting phase RESPONSE_BODY. (SecRules 4)
[159379270314.971984] [/?testparam=test] [4] Response body is disabled, returning... 1
[159379270314.971984] [/?testparam=test] [4] Starting phase LOGGING. (SecRules 5)
[159379270314.971984] [/?testparam=test] [9] This phase consists of 0 rule(s).
[159379270314.971984] [/?testparam=test] [8] Checking if this request is suitable to be saved as an audit log.
[159379270314.971984] [/?testparam=test] [8] Checking if this request is relevant to be part of the audit logs.
[159379270314.971984] [/?testparam=test] [5] Saving this request as part of the audit logs.
[159379270314.971984] [/?testparam=test] [7] Sending logs to: https://remote-endpoint/
[159379270314.971984] [/?testparam=test] [8] Request was relevant to be saved. Parts: 6006

Inline rules (debug + audit to https) with remote rules

nginx.conf

worker_processes  1;
error_log  /dev/stderr;
error_log  /dev/stderr debug;
events {
    worker_connections  1024;
}
http {
    include       mime.types;
    default_type  application/octet-stream;
    sendfile        on;
    keepalive_timeout  65;
    server {
        listen       80;
        server_name  localhost;

        location / {
        modsecurity on;
            modsecurity_rules '
SecRuleEngine On
SecDebugLogLevel 9
SecDebugLog /tmp/debug.txt
SecAuditLog https://remote-endpoint/api/v1/sites/eb25596a-ac1f-4a13-a756-b4671aed7f5d/events
SecAuditLogType HTTPS
';
            modsecurity_rules_remote https-key "https://remote-endpoint/api/v1/sites/4a08c5d8-9de9-4ddb-8400-b05e940d8866/rules/raw";
        proxy_pass http://10.224.143.98;
        }
    }
}

In this example, the debug file is written, but the audit events are not sent to the HTTPS endpoint (I monitored the endpoint where the event should have arrived. The event was not sent using POST to /.).

[159379325691.179956] [] [4] Initializing transaction
[159379325691.179956] [] [4] Transaction context created.
[159379325691.179956] [] [4] Starting phase CONNECTION. (SecRules 0)
[159379325691.179956] [] [9] This phase consists of 0 rule(s).
[159379325691.179956] [] [4] Starting phase URI. (SecRules 0 + 1/2)
[159379325691.179956] [/?testparam=test] [4] Adding request argument (GET): name "testparam", value "test"
[159379325691.179956] [/?testparam=test] [4] Starting phase REQUEST_HEADERS.  (SecRules 1)
[159379325691.179956] [/?testparam=test] [9] This phase consists of 7 rule(s).
[159379325691.179956] [/?testparam=test] [4] (Rule: 0) Executing unconditional rule...
[159379325691.179956] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379325691.179956] [/?testparam=test] [8] Saving variable: TX:critical_anomaly_score with value: 5
[159379325691.179956] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379325691.179956] [/?testparam=test] [8] Saving variable: TX:error_anomaly_score with value: 4
[159379325691.179956] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379325691.179956] [/?testparam=test] [8] Saving variable: TX:warning_anomaly_score with value: 3
[159379325691.179956] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379325691.179956] [/?testparam=test] [8] Saving variable: TX:notice_anomaly_score with value: 2
[159379325691.179956] [/?testparam=test] [9] Running action: log
[159379325691.179956] [/?testparam=test] [9] Saving transaction to logs
[159379325691.179956] [/?testparam=test] [9] Running action: auditlog
[159379325691.179956] [/?testparam=test] [9] Saving transaction to logs
[159379325691.179956] [/?testparam=test] [9] Running action: nolog
[159379325691.179956] [/?testparam=test] [4] Running (disruptive)     action: pass.
[159379325691.179956] [/?testparam=test] [8] Running action pass
[159379325691.179956] [/?testparam=test] [4] (Rule: 0) Executing unconditional rule...
[159379325691.179956] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379325691.179956] [/?testparam=test] [8] Saving variable: TX:anomaly_score with value: 0
[159379325691.179956] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379325691.179956] [/?testparam=test] [8] Saving variable: TX:sql_injection_score with value: 0
[159379325691.179956] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379325691.179956] [/?testparam=test] [8] Saving variable: TX:xss_score with value: 0
[159379325691.179956] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379325691.179956] [/?testparam=test] [8] Saving variable: TX:inbound_anomaly_score with value: 0
[159379325691.179956] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379325691.179956] [/?testparam=test] [8] Saving variable: TX:outbound_anomaly_score with value: 0
[159379325691.179956] [/?testparam=test] [9] Running action: log
[159379325691.179956] [/?testparam=test] [9] Saving transaction to logs
[159379325691.179956] [/?testparam=test] [9] Running action: auditlog
[159379325691.179956] [/?testparam=test] [9] Saving transaction to logs
[159379325691.179956] [/?testparam=test] [9] Running action: nolog
[159379325691.179956] [/?testparam=test] [4] Running (disruptive)     action: pass.
[159379325691.179956] [/?testparam=test] [8] Running action pass
[159379325691.179956] [/?testparam=test] [4] (Rule: 0) Executing unconditional rule...
[159379325691.179956] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379325691.179956] [/?testparam=test] [8] Saving variable: TX:inbound_anomaly_score_level with value: 5
[159379325691.179956] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379325691.179956] [/?testparam=test] [8] Saving variable: TX:outbound_anomaly_score_level with value: 4
[159379325691.179956] [/?testparam=test] [9] Running action: log
[159379325691.179956] [/?testparam=test] [9] Saving transaction to logs
[159379325691.179956] [/?testparam=test] [9] Running action: auditlog
[159379325691.179956] [/?testparam=test] [9] Saving transaction to logs
[159379325691.179956] [/?testparam=test] [9] Running action: nolog
[159379325691.179956] [/?testparam=test] [4] Running (disruptive)     action: pass.
[159379325691.179956] [/?testparam=test] [8] Running action pass
[159379325691.179956] [/?testparam=test] [4] (Rule: 0) Executing unconditional rule...
[159379325691.179956] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379325691.179956] [/?testparam=test] [8] Saving variable: TX:max_num_args with value: 255
[159379325691.179956] [/?testparam=test] [9] Running action: log
[159379325691.179956] [/?testparam=test] [9] Saving transaction to logs
[159379325691.179956] [/?testparam=test] [9] Running action: auditlog
[159379325691.179956] [/?testparam=test] [9] Saving transaction to logs
[159379325691.179956] [/?testparam=test] [9] Running action: nolog
[159379325691.179956] [/?testparam=test] [4] Running (disruptive)     action: pass.
[159379325691.179956] [/?testparam=test] [8] Running action pass
[159379325691.179956] [/?testparam=test] [4] (Rule: 29) Executing operator "Rx" with param "text/xml" against REQUEST_HEADERS:Content-Type.
[159379325691.179956] [/?testparam=test] [4] Rule returned 0.
[159379325691.179956] [/?testparam=test] [9] Matched vars cleaned.
[159379325691.179956] [/?testparam=test] [4] (Rule: 30) Executing operator "Rx" with param "application/json" against REQUEST_HEADERS:Content-Type.
[159379325691.179956] [/?testparam=test] [4] Rule returned 0.
[159379325691.179956] [/?testparam=test] [9] Matched vars cleaned.
[159379325691.179956] [/?testparam=test] [4] (Rule: 32) Executing operator "Contains" with param "test" against ARGS:testparam.
[159379325691.179956] [/?testparam=test] [9] Target value: "test" (Variable: ARGS:testparam)
[159379325691.179956] [/?testparam=test] [9] Matched vars updated.
[159379325691.179956] [/?testparam=test] [9] Saving msg: Bloqueio via regra de teste
[159379325691.179956] [/?testparam=test] [4] Rule returned 1.
[159379325691.179956] [/?testparam=test] [9] Running action: log
[159379325691.179956] [/?testparam=test] [9] Saving transaction to logs
[159379325691.179956] [/?testparam=test] [9] Running action: auditlog
[159379325691.179956] [/?testparam=test] [9] Saving transaction to logs
[159379325691.179956] [/?testparam=test] [9] Running action: log
[159379325691.179956] [/?testparam=test] [9] Saving transaction to logs
[159379325691.179956] [/?testparam=test] [4] Running (disruptive)     action: block.
[159379325691.179956] [/?testparam=test] [8] Marking request as disruptive.
[159379325691.179956] [/?testparam=test] [8] Running action deny
[159379325691.179956] [/?testparam=test] [8] Skipping this phase as this request was already intercepted.
[159379325691.179956] [/?testparam=test] [4] Starting phase RESPONSE_HEADERS. (SecRules 3)
[159379325691.179956] [/?testparam=test] [9] This phase consists of 0 rule(s).
[159379325691.179956] [/?testparam=test] [9] Appending response body: 100 bytes. Limit set to: 524288.000000
[159379325691.179956] [/?testparam=test] [9] Appending response body: 153 bytes. Limit set to: 524288.000000
[159379325691.179956] [/?testparam=test] [4] Starting phase RESPONSE_BODY. (SecRules 4)
[159379325691.179956] [/?testparam=test] [4] Response body is disabled, returning... 1
[159379325691.179956] [/?testparam=test] [4] Starting phase LOGGING. (SecRules 5)
[159379325691.179956] [/?testparam=test] [9] This phase consists of 0 rule(s).
[159379325691.179956] [/?testparam=test] [8] Checking if this request is suitable to be saved as an audit log.
[159379325691.179956] [/?testparam=test] [8] Checking if this request is relevant to be part of the audit logs.
[159379325691.179956] [/?testparam=test] [5] Saving this request as part of the audit logs.
[159379325691.179956] [/?testparam=test] [7] Sending logs to: https://remote-endpoint/
[159379325691.179956] [/?testparam=test] [8] Request was relevant to be saved. Parts: 6006

Local rules (debug + audit to https)

nginx.conf

worker_processes  1;
error_log  /dev/stderr;
error_log  /dev/stderr debug;
events {
    worker_connections  1024;
}
http {
    include       mime.types;
    default_type  application/octet-stream;
    sendfile        on;
    keepalive_timeout  65;
    server {
        listen       80;
        server_name  localhost;

        location / {
        modsecurity on;
            modsecurity_rules_file "conf/rules-api.conf";
        proxy_pass http://10.224.143.98;
        }
    }
}

In this example, the debug file is written, and the audit events are sent to the endpoint configured via HTTPS. The key issue is that the rules have been loaded locally.

[159379363142.531786] [] [4] Initializing transaction
[159379363142.531786] [] [4] Transaction context created.
[159379363142.531786] [] [4] Starting phase CONNECTION. (SecRules 0)
[159379363142.531786] [] [9] This phase consists of 0 rule(s).
[159379363142.531786] [] [4] Starting phase URI. (SecRules 0 + 1/2)
[159379363142.531786] [/?testparam=test] [4] Adding request argument (GET): name "testparam", value "test"
[159379363142.531786] [/?testparam=test] [4] Starting phase REQUEST_HEADERS.  (SecRules 1)
[159379363142.531786] [/?testparam=test] [9] This phase consists of 7 rule(s).
[159379363142.531786] [/?testparam=test] [4] (Rule: 0) Executing unconditional rule...
[159379363142.531786] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379363142.531786] [/?testparam=test] [8] Saving variable: TX:critical_anomaly_score with value: 5
[159379363142.531786] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379363142.531786] [/?testparam=test] [8] Saving variable: TX:error_anomaly_score with value: 4
[159379363142.531786] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379363142.531786] [/?testparam=test] [8] Saving variable: TX:warning_anomaly_score with value: 3
[159379363142.531786] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379363142.531786] [/?testparam=test] [8] Saving variable: TX:notice_anomaly_score with value: 2
[159379363142.531786] [/?testparam=test] [9] Running action: log
[159379363142.531786] [/?testparam=test] [9] Saving transaction to logs
[159379363142.531786] [/?testparam=test] [9] Running action: auditlog
[159379363142.531786] [/?testparam=test] [9] Saving transaction to logs
[159379363142.531786] [/?testparam=test] [9] Running action: nolog
[159379363142.531786] [/?testparam=test] [4] Running (disruptive)     action: pass.
[159379363142.531786] [/?testparam=test] [8] Running action pass
[159379363142.531786] [/?testparam=test] [4] (Rule: 0) Executing unconditional rule...
[159379363142.531786] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379363142.531786] [/?testparam=test] [8] Saving variable: TX:anomaly_score with value: 0
[159379363142.531786] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379363142.531786] [/?testparam=test] [8] Saving variable: TX:sql_injection_score with value: 0
[159379363142.531786] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379363142.531786] [/?testparam=test] [8] Saving variable: TX:xss_score with value: 0
[159379363142.531786] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379363142.531786] [/?testparam=test] [8] Saving variable: TX:inbound_anomaly_score with value: 0
[159379363142.531786] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379363142.531786] [/?testparam=test] [8] Saving variable: TX:outbound_anomaly_score with value: 0
[159379363142.531786] [/?testparam=test] [9] Running action: log
[159379363142.531786] [/?testparam=test] [9] Saving transaction to logs
[159379363142.531786] [/?testparam=test] [9] Running action: auditlog
[159379363142.531786] [/?testparam=test] [9] Saving transaction to logs
[159379363142.531786] [/?testparam=test] [9] Running action: nolog
[159379363142.531786] [/?testparam=test] [4] Running (disruptive)     action: pass.
[159379363142.531786] [/?testparam=test] [8] Running action pass
[159379363142.531786] [/?testparam=test] [4] (Rule: 0) Executing unconditional rule...
[159379363142.531786] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379363142.531786] [/?testparam=test] [8] Saving variable: TX:inbound_anomaly_score_level with value: 5
[159379363142.531786] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379363142.531786] [/?testparam=test] [8] Saving variable: TX:outbound_anomaly_score_level with value: 4
[159379363142.531786] [/?testparam=test] [9] Running action: log
[159379363142.531786] [/?testparam=test] [9] Saving transaction to logs
[159379363142.531786] [/?testparam=test] [9] Running action: auditlog
[159379363142.531786] [/?testparam=test] [9] Saving transaction to logs
[159379363142.531786] [/?testparam=test] [9] Running action: nolog
[159379363142.531786] [/?testparam=test] [4] Running (disruptive)     action: pass.
[159379363142.531786] [/?testparam=test] [8] Running action pass
[159379363142.531786] [/?testparam=test] [4] (Rule: 0) Executing unconditional rule...
[159379363142.531786] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159379363142.531786] [/?testparam=test] [8] Saving variable: TX:max_num_args with value: 255
[159379363142.531786] [/?testparam=test] [9] Running action: log
[159379363142.531786] [/?testparam=test] [9] Saving transaction to logs
[159379363142.531786] [/?testparam=test] [9] Running action: auditlog
[159379363142.531786] [/?testparam=test] [9] Saving transaction to logs
[159379363142.531786] [/?testparam=test] [9] Running action: nolog
[159379363142.531786] [/?testparam=test] [4] Running (disruptive)     action: pass.
[159379363142.531786] [/?testparam=test] [8] Running action pass
[159379363142.531786] [/?testparam=test] [4] (Rule: 89) Executing operator "Rx" with param "text/xml" against REQUEST_HEADERS:Content-Type.
[159379363142.531786] [/?testparam=test] [4] Rule returned 0.
[159379363142.531786] [/?testparam=test] [9] Matched vars cleaned.
[159379363142.531786] [/?testparam=test] [4] (Rule: 90) Executing operator "Rx" with param "application/json" against REQUEST_HEADERS:Content-Type.
[159379363142.531786] [/?testparam=test] [4] Rule returned 0.
[159379363142.531786] [/?testparam=test] [9] Matched vars cleaned.
[159379363142.531786] [/?testparam=test] [4] (Rule: 92) Executing operator "Contains" with param "test" against ARGS:testparam.
[159379363142.531786] [/?testparam=test] [9] Target value: "test" (Variable: ARGS:testparam)
[159379363142.531786] [/?testparam=test] [9] Matched vars updated.
[159379363142.531786] [/?testparam=test] [9] Saving msg: Bloqueio via regra de teste
[159379363142.531786] [/?testparam=test] [4] Rule returned 1.
[159379363142.531786] [/?testparam=test] [9] Running action: log
[159379363142.531786] [/?testparam=test] [9] Saving transaction to logs
[159379363142.531786] [/?testparam=test] [9] Running action: auditlog
[159379363142.531786] [/?testparam=test] [9] Saving transaction to logs
[159379363142.531786] [/?testparam=test] [9] Running action: log
[159379363142.531786] [/?testparam=test] [9] Saving transaction to logs
[159379363142.531786] [/?testparam=test] [4] Running (disruptive)     action: block.
[159379363142.531786] [/?testparam=test] [8] Marking request as disruptive.
[159379363142.531786] [/?testparam=test] [8] Running action deny
[159379363142.531786] [/?testparam=test] [8] Skipping this phase as this request was already intercepted.
[159379363142.531786] [/?testparam=test] [4] Starting phase RESPONSE_HEADERS. (SecRules 3)
[159379363142.531786] [/?testparam=test] [9] This phase consists of 0 rule(s).
[159379363142.531786] [/?testparam=test] [9] Appending response body: 100 bytes. Limit set to: 0.000000
[159379363142.531786] [/?testparam=test] [9] Appending response body: 153 bytes. Limit set to: 0.000000
[159379363142.531786] [/?testparam=test] [4] Starting phase RESPONSE_BODY. (SecRules 4)
[159379363142.531786] [/?testparam=test] [4] Response body is disabled, returning... 1
[159379363142.531786] [/?testparam=test] [4] Starting phase LOGGING. (SecRules 5)
[159379363142.531786] [/?testparam=test] [9] This phase consists of 0 rule(s).
[159379363142.531786] [/?testparam=test] [8] Checking if this request is suitable to be saved as an audit log.
[159379363142.531786] [/?testparam=test] [8] Checking if this request is relevant to be part of the audit logs.
[159379363142.531786] [/?testparam=test] [5] Saving this request as part of the audit logs.
[159379363142.531786] [/?testparam=test] [7] Sending logs to: https://remote-endpoint/api/v1/sites/eb25596a-ac1f-4a13-a756-b4671aed7f5d/events
[159379363142.531786] [/?testparam=test] [8] Request was relevant to be saved. Parts: 6006
mdjunior commented 4 years ago

As I did the tests, I removed the directives that were inline from the remote endpoint to avoid overwriting (or similar behavior),

mdjunior commented 4 years ago

Testing using HTTP (instead of HTTPS) I noticed that in the following scenario, I was able to receive the events.

worker_processes  1;
error_log  /dev/stderr;
error_log  /dev/stderr debug;
events {
    worker_connections  1024;
}
http {
    include       mime.types;
    default_type  application/octet-stream;
    sendfile        on;
    keepalive_timeout  65;
    server {
        listen       80;
        server_name  localhost;

        location / {
        modsecurity on;
            modsecurity_rules_remote http-key "http://remote-endpoint/api/v1/sites/4a08c5d8-9de9-4ddb-8400-b05e940d8866/rules/raw";
            modsecurity_rules '
SecRuleEngine On
SecDebugLogLevel 9
SecDebugLog /tmp/debug.txt
SecAuditLogType HTTPS
SecAuditLog http://remote-endpoint/api/v1/sites/eb25596a-ac1f-4a13-a756-b4671aed7f5d/events
';
        proxy_pass http://10.224.143.98;
        }
    }
}

That is, by placing the directives for sending events in the local file, events are sent via HTTP. If configured for HTTPS, the event is not dispatched. If the HTTP endpoint returns in the remotely loaded rules, the event is also not sent.

[159380311696.824659] [] [4] Initializing transaction
[159380311696.824659] [] [4] Transaction context created.
[159380311696.824659] [] [4] Starting phase CONNECTION. (SecRules 0)
[159380311696.824659] [] [9] This phase consists of 0 rule(s).
[159380311696.824659] [] [4] Starting phase URI. (SecRules 0 + 1/2)
[159380311696.824659] [/?testparam=test] [4] Adding request argument (GET): name "testparam", value "test"
[159380311696.824659] [/?testparam=test] [4] Starting phase REQUEST_HEADERS.  (SecRules 1)
[159380311696.824659] [/?testparam=test] [9] This phase consists of 7 rule(s).
[159380311696.824659] [/?testparam=test] [4] (Rule: 0) Executing unconditional rule...
[159380311696.824659] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159380311696.824659] [/?testparam=test] [8] Saving variable: TX:critical_anomaly_score with value: 5
[159380311696.824659] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159380311696.824659] [/?testparam=test] [8] Saving variable: TX:error_anomaly_score with value: 4
[159380311696.824659] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159380311696.824659] [/?testparam=test] [8] Saving variable: TX:warning_anomaly_score with value: 3
[159380311696.824659] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159380311696.824659] [/?testparam=test] [8] Saving variable: TX:notice_anomaly_score with value: 2
[159380311696.824659] [/?testparam=test] [9] Running action: log
[159380311696.824659] [/?testparam=test] [9] Saving transaction to logs
[159380311696.824659] [/?testparam=test] [9] Running action: auditlog
[159380311696.824659] [/?testparam=test] [9] Saving transaction to logs
[159380311696.824659] [/?testparam=test] [9] Running action: nolog
[159380311696.824659] [/?testparam=test] [4] Running (disruptive)     action: pass.
[159380311696.824659] [/?testparam=test] [8] Running action pass
[159380311696.824659] [/?testparam=test] [4] (Rule: 0) Executing unconditional rule...
[159380311696.824659] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159380311696.824659] [/?testparam=test] [8] Saving variable: TX:anomaly_score with value: 0
[159380311696.824659] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159380311696.824659] [/?testparam=test] [8] Saving variable: TX:sql_injection_score with value: 0
[159380311696.824659] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159380311696.824659] [/?testparam=test] [8] Saving variable: TX:xss_score with value: 0
[159380311696.824659] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159380311696.824659] [/?testparam=test] [8] Saving variable: TX:inbound_anomaly_score with value: 0
[159380311696.824659] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159380311696.824659] [/?testparam=test] [8] Saving variable: TX:outbound_anomaly_score with value: 0
[159380311696.824659] [/?testparam=test] [9] Running action: log
[159380311696.824659] [/?testparam=test] [9] Saving transaction to logs
[159380311696.824659] [/?testparam=test] [9] Running action: auditlog
[159380311696.824659] [/?testparam=test] [9] Saving transaction to logs
[159380311696.824659] [/?testparam=test] [9] Running action: nolog
[159380311696.824659] [/?testparam=test] [4] Running (disruptive)     action: pass.
[159380311696.824659] [/?testparam=test] [8] Running action pass
[159380311696.824659] [/?testparam=test] [4] (Rule: 0) Executing unconditional rule...
[159380311696.824659] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159380311696.824659] [/?testparam=test] [8] Saving variable: TX:inbound_anomaly_score_level with value: 5
[159380311696.824659] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159380311696.824659] [/?testparam=test] [8] Saving variable: TX:outbound_anomaly_score_level with value: 4
[159380311696.824659] [/?testparam=test] [9] Running action: log
[159380311696.824659] [/?testparam=test] [9] Saving transaction to logs
[159380311696.824659] [/?testparam=test] [9] Running action: auditlog
[159380311696.824659] [/?testparam=test] [9] Saving transaction to logs
[159380311696.824659] [/?testparam=test] [9] Running action: nolog
[159380311696.824659] [/?testparam=test] [4] Running (disruptive)     action: pass.
[159380311696.824659] [/?testparam=test] [8] Running action pass
[159380311696.824659] [/?testparam=test] [4] (Rule: 0) Executing unconditional rule...
[159380311696.824659] [/?testparam=test] [4] Running [independent] (non-disruptive) action: setvar
[159380311696.824659] [/?testparam=test] [8] Saving variable: TX:max_num_args with value: 255
[159380311696.824659] [/?testparam=test] [9] Running action: log
[159380311696.824659] [/?testparam=test] [9] Saving transaction to logs
[159380311696.824659] [/?testparam=test] [9] Running action: auditlog
[159380311696.824659] [/?testparam=test] [9] Saving transaction to logs
[159380311696.824659] [/?testparam=test] [9] Running action: nolog
[159380311696.824659] [/?testparam=test] [4] Running (disruptive)     action: pass.
[159380311696.824659] [/?testparam=test] [8] Running action pass
[159380311696.824659] [/?testparam=test] [4] (Rule: 29) Executing operator "Rx" with param "text/xml" against REQUEST_HEADERS:Content-Type.
[159380311696.824659] [/?testparam=test] [4] Rule returned 0.
[159380311696.824659] [/?testparam=test] [9] Matched vars cleaned.
[159380311696.824659] [/?testparam=test] [4] (Rule: 30) Executing operator "Rx" with param "application/json" against REQUEST_HEADERS:Content-Type.
[159380311696.824659] [/?testparam=test] [4] Rule returned 0.
[159380311696.824659] [/?testparam=test] [9] Matched vars cleaned.
[159380311696.824659] [/?testparam=test] [4] (Rule: 32) Executing operator "Contains" with param "test" against ARGS:testparam.
[159380311696.824659] [/?testparam=test] [9] Target value: "test" (Variable: ARGS:testparam)
[159380311696.824659] [/?testparam=test] [9] Matched vars updated.
[159380311696.824659] [/?testparam=test] [9] Saving msg: Bloqueio via regra de teste
[159380311696.824659] [/?testparam=test] [4] Rule returned 1.
[159380311696.824659] [/?testparam=test] [9] Running action: log
[159380311696.824659] [/?testparam=test] [9] Saving transaction to logs
[159380311696.824659] [/?testparam=test] [9] Running action: auditlog
[159380311696.824659] [/?testparam=test] [9] Saving transaction to logs
[159380311696.824659] [/?testparam=test] [9] Running action: log
[159380311696.824659] [/?testparam=test] [9] Saving transaction to logs
[159380311696.824659] [/?testparam=test] [4] Running (disruptive)     action: block.
[159380311696.824659] [/?testparam=test] [8] Marking request as disruptive.
[159380311696.824659] [/?testparam=test] [8] Running action deny
[159380311696.824659] [/?testparam=test] [8] Skipping this phase as this request was already intercepted.
[159380311696.824659] [/?testparam=test] [4] Starting phase RESPONSE_HEADERS. (SecRules 3)
[159380311696.824659] [/?testparam=test] [9] This phase consists of 0 rule(s).
[159380311696.824659] [/?testparam=test] [9] Appending response body: 100 bytes. Limit set to: 524288.000000
[159380311696.824659] [/?testparam=test] [9] Appending response body: 153 bytes. Limit set to: 524288.000000
[159380311696.824659] [/?testparam=test] [4] Starting phase RESPONSE_BODY. (SecRules 4)
[159380311696.824659] [/?testparam=test] [4] Response body is disabled, returning... 1
[159380311696.824659] [/?testparam=test] [4] Starting phase LOGGING. (SecRules 5)
[159380311696.824659] [/?testparam=test] [9] This phase consists of 0 rule(s).
[159380311696.824659] [/?testparam=test] [8] Checking if this request is suitable to be saved as an audit log.
[159380311696.824659] [/?testparam=test] [8] Checking if this request is relevant to be part of the audit logs.
[159380311696.824659] [/?testparam=test] [5] Saving this request as part of the audit logs.
[159380311696.824659] [/?testparam=test] [7] Sending logs to: http://remote-endpoint/api/v1/sites/eb25596a-ac1f-4a13-a756-b4671aed7f5d/events
[159380311696.824659] [/?testparam=test] [8] Request was relevant to be saved. Parts: 6006
github-actions[bot] commented 4 years ago

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 5 days