Requests blocked in Phase 1 (Request Headers) do not appear in the audit log #170

robinkb · 2019-09-30T08:15:47Z

Description

Requests that are blocked in Phase 1 (Request Headers) do not appear in the audit log. The rules are evaluated correctly, and block calls as expected. However, because they do not appear in the audit log, I am blind to a significant portion of possible disruptive actions in the ModSecurity CRS.

The issue is not present in the ModSecurity image based on Apache HTTPD. That is why I am reporting the issue here.

Steps to reproduce

Start the ModSecurity CRS container based on NGINX.

$ docker run --rm -ti -p 8080:80 --name modsecurity-nginx \
      docker.io/owasp/modsecurity-crs:v3.2-modsec3-nginx

In another terminal, tail the audit log.

$ docker exec -ti modsecurity-nginx tail -f /var/log/modsec_audit.log

In yet another terminal, first confirm that the audit log works by triggering a warning. Then, confirm that the audit log does not work when the request is blocked by a rule in phase:1.

# Empty Accept header triggers a warning; returns status code 200.
$ curl http://localhost:8080/ -v -H "Accept;"

# Content-Length with invalid content is blocked; returns status code 400.
$ curl http://localhost:8080/ -v -H "Content-Length: not a digit"

You can repeat the steps above with the Apache-based image, and see that the Apache-based image does not have this problem.

Environment

I tried to track down what software versions were used in the Docker image, which turned out to be quite difficult.

The exact Docker image that I tested is docker.io/owasp/modsecurity-crs:v3.2-modsec3-nginx. Its Dockerfile is located here, in the SpiderLabs/owasp-modsecurity-crs repository.

There, I can see that the image is based on docker.io/owasp/modsecurity:3.0-nginx. The Dockerfile of that image appears to be located here, in the CRS-support/modsecurity-docker repository.

This is where it gets hairy, because both ModSecurity and ModSecurity-nginx are checked out directly from the tip of the master branch. Additionally, the base image used for this Dockerfile is docker.io/library/nginx:1, which is a floating tag that gets updated whenever a new mainline NGINX version is pushed.

Using docker inspect, I was able to determine that the image was built on the 29th of May, 2019.

$ docker inspect docker.io/owasp/modsecurity-crs:v3.2-modsec3-nginx -f "{{ .Created }}"
2019-05-29T23:15:40.7504558Z

From there, I could check the commit logs of both projects to guess what version of the software is actually in the images.

ModSecurity-nginx has not had any development since January of this year, so I can quite confidently say that the actual version in the container image is d7101e13685e, the current tip of the master branch. That is itself a bit funny, because ModSecurity-nginx has not been officially released since the 20th of December, 2017, nearly two years ago.

ModSecurity itself is more actively developed, but based on the container image's timestamp, the actual version seems to be 6d266fae8549, which was the tip of the v3/master branch at the time.

Besides the versions being difficult to track down, this also means that the official ModSecurity image contains software versions that have not seen actual releases.

Finally, the NGINX version was fairy easily tracked down by looking at the embedded version info.

$ docker run --rm docker.io/owasp/modsecurity:3.0-nginx nginx -V
nginx version: nginx/1.15.12
...

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

victorhora · 2020-01-27T00:17:18Z

@robinkb, see if victorhora@ac3e8a9 solves your issue.

theMiddleBlue · 2020-02-12T12:04:39Z

same problem here.

zimmerle · 2020-02-12T12:09:08Z

@victorhora's patch did not solve the issue for you @theMiddleBlue ?

theMiddleBlue · 2020-02-12T12:26:15Z

just compiled now and @victorhora's patch works correctly. Thank you so much @zimmerle and @victorhora. Can this patch be merged to the master branch?

zimmerle · 2020-02-12T12:28:19Z

just compiled now and @victorhora's patch works correctly. Thank you so much @zimmerle and @victorhora. Can this patch be merged to the master branch?

In the queue. I will try to do it today. Thank you for having it tested.

theMiddleBlue · 2020-02-12T12:36:39Z

thanks! just an additional bit: before patching, I wasn't able to get any auditlog for each 403 response code from the upstream server (I mean even if the request didn't match any disruptive action). idk if it could help.

logopk · 2020-02-17T11:59:37Z

Maybe I'm misunderstanding the issue. I have cloned the fix-auditlog-170-branch.

I'm not seeing phase 1 logs when running the CRS 3.2 with Nginx 1.17.8, mod security 3.0.4

Only the test rule:

SecRule ARGS:testparam "@contains test" "id:1234,deny,status:403"
will produce a phase 1 log.

Neither will log to modsec_audit.log

Maybe not related, but I have tried to get the debug log without success. it stays at 0 bytes.

Can you help me, please?

theMiddleBlue · 2020-02-18T09:01:00Z

@victorhora @zimmerle after using the patched version of the nginx connector, I've a problem with a rule that I can't understand well.

SecRuleEngine On
SecDefaultAction "phase:1,log,auditlog,deny,status:403"
SecDefaultAction "phase:2,log,auditlog,deny,status:403"

SecRule REQUEST_URI "(author\=[0-9]+)" "phase:1,id:222,\
   t:lowercase,t:urlDecode,t:trim,\
   block,\
   log,\
   rev:'1',\
   severity:'6',\
   maturity:'9',\
   accuracy:'9',\
   tag:'wordpress',\
   tag:'enumeration',\
   logdata:'Detected on %{TX:1}',\
   msg:'WordPress: User enumeration'"

Sending the following request, nginx closes the connection before sending any response headers...

# curl -v 'http://wordpress/?author=1'
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to wordpress (127.0.0.1) port 80 (#0)
> GET /?author=1 HTTP/1.1
> Host: wordpress
> User-Agent: curl/7.64.1
> Accept: */*
> 
* Empty reply from server
* Connection #0 to host wordpress left intact
curl: (52) Empty reply from server
* Closing connection 0

any idea? it's a little bit odd, isn't it?

debug log:

[158201598339.412284] [] [4] Initializing transaction
[158201598339.412284] [] [4] Transaction context created.
[158201598339.412284] [] [4] Starting phase CONNECTION. (SecRules 0)
[158201598339.412284] [] [9] This phase consists of 30 rule(s).
[158201598339.412284] [] [4] Starting phase URI. (SecRules 0 + 1/2)
[158201598339.412284] [/?author=1] [4] Adding request argument (GET): name "author", value "1"
[158201598339.412284] [/?author=1] [4] Starting phase REQUEST_HEADERS.  (SecRules 1)
[158201598339.412284] [/?author=1] [9] This phase consists of 161 rule(s).
[158201598339.412284] [/?author=1] [4] (Rule: 900000) Executing unconditional rule...
[158201598339.412284] [/?author=1] [4] Running [independent] (non-disruptive) action: setvar
[158201598339.412284] [/?author=1] [8] Saving variable: TX:paranoia_level with value: 1
[158201598339.412284] [/?author=1] [9] Running action: log
[158201598339.412284] [/?author=1] [9] Saving transaction to logs
[158201598339.412284] [/?author=1] [9] Running action: auditlog
[158201598339.412284] [/?author=1] [9] Saving transaction to logs
[158201598339.412284] [/?author=1] [9] Running action: status
[158201598339.412284] [/?author=1] [9] Running action: nolog
[158201598339.412284] [/?author=1] [4] Running (disruptive)     action: pass.
[158201598339.412284] [/?author=1] [8] Running action pass
[158201598339.412284] [/?author=1] [4] (Rule: 900990) Executing unconditional rule...
[158201598339.412284] [/?author=1] [4] Running [independent] (non-disruptive) action: setvar
[158201598339.412284] [/?author=1] [8] Saving variable: TX:crs_setup_version with value: 310
[158201598339.412284] [/?author=1] [9] Running action: log
[158201598339.412284] [/?author=1] [9] Saving transaction to logs
[158201598339.412284] [/?author=1] [9] Running action: auditlog
[158201598339.412284] [/?author=1] [9] Saving transaction to logs
[158201598339.412284] [/?author=1] [9] Running action: status
[158201598339.412284] [/?author=1] [9] Running action: nolog
[158201598339.412284] [/?author=1] [4] Running (disruptive)     action: pass.
[158201598339.412284] [/?author=1] [8] Running action pass
[158201598339.412284] [/?author=1] [4] (Rule: 900000) Executing unconditional rule...
[158201598339.412284] [/?author=1] [4] Running [independent] (non-disruptive) action: setvar
[158201598339.412284] [/?author=1] [8] Saving variable: TX:paranoia_level with value: 1
[158201598339.412284] [/?author=1] [9] Running action: log
[158201598339.412284] [/?author=1] [9] Saving transaction to logs
[158201598339.412284] [/?author=1] [9] Running action: auditlog
[158201598339.412284] [/?author=1] [9] Saving transaction to logs
[158201598339.412284] [/?author=1] [9] Running action: status
[158201598339.412284] [/?author=1] [9] Running action: nolog
[158201598339.412284] [/?author=1] [4] Running (disruptive)     action: pass.
[158201598339.412284] [/?author=1] [8] Running action pass
[158201598339.412284] [/?author=1] [4] (Rule: 222) Executing operator "Rx" with param "(author\=[0-9]+)" against REQUEST_URI.
[158201598339.412284] [/?author=1] [9]  T (0) t:lowercase: "/?author=1"
[158201598339.412284] [/?author=1] [9]  T (0) t:urlDecode: "/?author=1"
[158201598339.412284] [/?author=1] [9]  T (0) t:trim: "/?author=1"
[158201598339.412284] [/?author=1] [9] Target value: "/?author=1" (Variable: REQUEST_URI)
[158201598339.412284] [/?author=1] [9] Matched vars updated.
[158201598339.412284] [/?author=1] [9] This rule severity is: 6 current transaction is: 255
[158201598339.412284] [/?author=1] [9] Saving msg: WordPress: User enumeration
[158201598339.412284] [/?author=1] [4] Rule returned 1.
[158201598339.412284] [/?author=1] [9] Running action: log
[158201598339.412284] [/?author=1] [9] Saving transaction to logs
[158201598339.412284] [/?author=1] [9] Running action: auditlog
[158201598339.412284] [/?author=1] [9] Saving transaction to logs
[158201598339.412284] [/?author=1] [9] Running action: status
[158201598339.412284] [/?author=1] [4] Running (non-disruptive) action: tag
[158201598339.412284] [/?author=1] [9] Rule tag: wordpress
[158201598339.412284] [/?author=1] [4] Running (non-disruptive) action: tag
[158201598339.412284] [/?author=1] [9] Rule tag: enumeration
[158201598339.412284] [/?author=1] [4] Running (disruptive)     action: block.
[158201598339.412284] [/?author=1] [8] Marking request as disruptive.
[158201598339.412284] [/?author=1] [8] Running action deny
[158201598339.412284] [/?author=1] [9] Running action: log
[158201598339.412284] [/?author=1] [9] Saving transaction to logs
[158201598339.412284] [/?author=1] [8] Skipping this phase as this request was already intercepted.
[158201598339.412284] [/?author=1] [4] Starting phase RESPONSE_HEADERS. (SecRules 3)
[158201598339.412284] [/?author=1] [9] This phase consists of 36 rule(s).
[158201598339.412284] [/?author=1] [4] (Rule: 959011) Executing operator "Lt" with param "1" against TX:EXECUTING_PARANOIA_LEVEL.
[158201598339.412284] [/?author=1] [4] Rule returned 0.
[158201598339.412284] [/?author=1] [9] Matched vars cleaned.
[158201598339.412284] [/?author=1] [4] (Rule: 959013) Executing operator "Lt" with param "2" against TX:EXECUTING_PARANOIA_LEVEL.
[158201598339.412284] [/?author=1] [4] Rule returned 0.
[158201598339.412284] [/?author=1] [9] Matched vars cleaned.
[158201598339.412284] [/?author=1] [4] (Rule: 959015) Executing operator "Lt" with param "3" against TX:EXECUTING_PARANOIA_LEVEL.
[158201598339.412284] [/?author=1] [4] Rule returned 0.
[158201598339.412284] [/?author=1] [9] Matched vars cleaned.
[158201598339.412284] [/?author=1] [4] (Rule: 959017) Executing operator "Lt" with param "4" against TX:EXECUTING_PARANOIA_LEVEL.
[158201598339.412284] [/?author=1] [4] Rule returned 0.
[158201598339.412284] [/?author=1] [9] Matched vars cleaned.
[158201598339.412284] [/?author=1] [4] (Rule: 2202) Executing operator "Rx" with param "^Blacklist$" against RESPONSE_HEADERS:X-Forbidden-Reason.
[158201598339.412284] [/?author=1] [4] Rule returned 0.
[158201598339.412284] [/?author=1] [9] Matched vars cleaned.
[158201598339.412284] [/?author=1] [4] (Rule: 2203) Executing operator "Rx" with param "^TBL$" against RESPONSE_HEADERS:X-Forbidden-Reason.
[158201598339.412284] [/?author=1] [4] Rule returned 0.
[158201598339.412284] [/?author=1] [9] Matched vars cleaned.
[158201598339.412284] [/?author=1] [9] Appending response body: 1397 bytes. Limit set to: 524288.000000
[158201598339.412284] [/?author=1] [4] Starting phase RESPONSE_BODY. (SecRules 4)
[158201598339.412284] [/?author=1] [9] This phase consists of 39 rule(s).
[158201598339.412284] [/?author=1] [4] (Rule: 959060) Executing operator "Ge" with param "1" against TX:PARANOIA_LEVEL.
[158201598339.412284] [/?author=1] [9] Target value: "1" (Variable: TX:PARANOIA_LEVEL)
[158201598339.412284] [/?author=1] [9] Matched vars updated.
[158201598339.412284] [/?author=1] [4] Running [independent] (non-disruptive) action: setvar
[158201598339.412284] [/?author=1] [8] Saving variable: TX:outbound_anomaly_score with value: 0
[158201598339.412284] [/?author=1] [4] Rule returned 1.
[158201598339.412284] [/?author=1] [9] Running action: nolog
[158201598339.412284] [/?author=1] [4] Running (disruptive)     action: pass.
[158201598339.412284] [/?author=1] [8] Running action pass
[158201598339.412284] [/?author=1] [4] (Rule: 959061) Executing operator "Ge" with param "2" against TX:PARANOIA_LEVEL.
[158201598339.412284] [/?author=1] [9] Target value: "1" (Variable: TX:PARANOIA_LEVEL)
[158201598339.412284] [/?author=1] [4] Rule returned 0.
[158201598339.412284] [/?author=1] [9] Matched vars cleaned.
[158201598339.412284] [/?author=1] [4] (Rule: 959062) Executing operator "Ge" with param "3" against TX:PARANOIA_LEVEL.
[158201598339.412284] [/?author=1] [9] Target value: "1" (Variable: TX:PARANOIA_LEVEL)
[158201598339.412284] [/?author=1] [4] Rule returned 0.
[158201598339.412284] [/?author=1] [9] Matched vars cleaned.
[158201598339.412284] [/?author=1] [4] (Rule: 959063) Executing operator "Ge" with param "4" against TX:PARANOIA_LEVEL.
[158201598339.412284] [/?author=1] [9] Target value: "1" (Variable: TX:PARANOIA_LEVEL)
[158201598339.412284] [/?author=1] [4] Rule returned 0.
[158201598339.412284] [/?author=1] [9] Matched vars cleaned.
[158201598339.412284] [/?author=1] [4] (Rule: 959100) Executing operator "Ge" with param "" Was: "" against TX:OUTBOUND_ANOMALY_SCORE.
[158201598339.412284] [/?author=1] [9] Target value: "0" (Variable: TX:OUTBOUND_ANOMALY_SCORE)
[158201598339.412284] [/?author=1] [9] Matched vars updated.
[158201598339.412284] [/?author=1] [4] Running [independent] (non-disruptive) action: setvar
[158201598339.412284] [/?author=1] [8] Saving variable: TX:anomaly_score with value: 0
[158201598339.412284] [/?author=1] [9] Saving msg: Outbound Anomaly Score Exceeded (Total Score: 0)
[158201598339.412284] [/?author=1] [4] Rule returned 1.
[158201598339.412284] [/?author=1] [4] Running (non-disruptive) action: tag
[158201598339.412284] [/?author=1] [9] Rule tag: anomaly-evaluation
[158201598339.412284] [/?author=1] [4] Running (disruptive)     action: deny.
[158201598339.412284] [/?author=1] [8] Running action deny
[158201598339.412284] [/?author=1] [8] Skipping this phase as this request was already intercepted.
[158201598339.412284] [/?author=1] [4] Starting phase LOGGING. (SecRules 5)
[158201598339.412284] [/?author=1] [9] This phase consists of 38 rule(s).
[158201598339.412284] [/?author=1] [4] (Rule: 980100) Executing operator "Ge" with param "1" against TX:regex(LEAKAGE\\\/ERRORS).
[158201598339.412284] [/?author=1] [9] Target value: "0" (Variable: TX:regex(LEAKAGE\\\/ERRORS))
[158201598339.412284] [/?author=1] [4] Rule returned 0.
[158201598339.412284] [/?author=1] [9] Matched vars cleaned.
[158201598339.412284] [/?author=1] [4] (Rule: 980110) Executing operator "Ge" with param "1" against TX:regex(AVAILABILITY\\\/APP_NOT_AVAIL).
[158201598339.412284] [/?author=1] [9] Target value: "0" (Variable: TX:regex(AVAILABILITY\\\/APP_NOT_AVAIL))
[158201598339.412284] [/?author=1] [4] Rule returned 0.
[158201598339.412284] [/?author=1] [9] Matched vars cleaned.
[158201598339.412284] [/?author=1] [4] (Rule: 980115) Executing unconditional rule...
[158201598339.412284] [/?author=1] [4] Running [independent] (non-disruptive) action: setvar
[158201598339.412284] [/?author=1] [8] Saving variable: TX:executing_anomaly_score with value: 
[158201598339.412284] [/?author=1] [4] Running [independent] (non-disruptive) action: setvar
[158201598339.412284] [/?author=1] [8] Saving variable: TX:executing_anomaly_score with value: 0
[158201598339.412284] [/?author=1] [4] Running [independent] (non-disruptive) action: setvar
[158201598339.412284] [/?author=1] [8] Saving variable: TX:executing_anomaly_score with value: 0
[158201598339.412284] [/?author=1] [4] Running [independent] (non-disruptive) action: setvar
[158201598339.412284] [/?author=1] [8] Saving variable: TX:executing_anomaly_score with value: 0
[158201598339.412284] [/?author=1] [9] Running action: nolog
[158201598339.412284] [/?author=1] [9] Running action: noauditlog
[158201598339.412284] [/?author=1] [4] Running (disruptive)     action: pass.
[158201598339.412284] [/?author=1] [8] Running action pass
[158201598339.412284] [/?author=1] [4] (Rule: 980120) Executing operator "Lt" with param "" Was: "" against TX:INBOUND_ANOMALY_SCORE.
[158201598339.412284] [/?author=1] [4] Rule returned 0.
[158201598339.412284] [/?author=1] [9] Matched vars cleaned.
[158201598339.412284] [/?author=1] [4] (Rule: 980130) Executing operator "Ge" with param "" Was: "" against TX:INBOUND_ANOMALY_SCORE.
[158201598339.412284] [/?author=1] [4] Rule returned 0.
[158201598339.412284] [/?author=1] [9] Matched vars cleaned.
[158201598339.412284] [/?author=1] [4] (Rule: 980140) Executing operator "Ge" with param "" Was: "" against TX:OUTBOUND_ANOMALY_SCORE.
[158201598339.412284] [/?author=1] [9] Target value: "0" (Variable: TX:OUTBOUND_ANOMALY_SCORE)
[158201598339.412284] [/?author=1] [9] Matched vars updated.
[158201598339.412284] [/?author=1] [9] Saving msg: Outbound Anomaly Score Exceeded (score 0): individual paranoia level scores: , , , 
[158201598339.412284] [/?author=1] [4] Rule returned 1.
[158201598339.412284] [/?author=1] [4] Running (non-disruptive) action: tag
[158201598339.412284] [/?author=1] [9] Rule tag: event-correlation
[158201598339.412284] [/?author=1] [9] Running action: log
[158201598339.412284] [/?author=1] [9] Saving transaction to logs
[158201598339.412284] [/?author=1] [9] Running action: noauditlog
[158201598339.412284] [/?author=1] [4] Running (disruptive)     action: pass.
[158201598339.412284] [/?author=1] [8] Running action pass
[158201598339.412284] [/?author=1] [4] (Rule: 980145) Executing unconditional rule...
[158201598339.412284] [/?author=1] [4] Running [independent] (non-disruptive) action: setvar
[158201598339.412284] [/?author=1] [8] Saving variable: TX:executing_anomaly_score with value: 
[158201598339.412284] [/?author=1] [4] Running [independent] (non-disruptive) action: setvar
[158201598339.412284] [/?author=1] [8] Saving variable: TX:executing_anomaly_score with value: 0
[158201598339.412284] [/?author=1] [4] Running [independent] (non-disruptive) action: setvar
[158201598339.412284] [/?author=1] [8] Saving variable: TX:executing_anomaly_score with value: 0
[158201598339.412284] [/?author=1] [4] Running [independent] (non-disruptive) action: setvar
[158201598339.412284] [/?author=1] [8] Saving variable: TX:executing_anomaly_score with value: 0
[158201598339.412284] [/?author=1] [9] Running action: nolog
[158201598339.412284] [/?author=1] [9] Running action: noauditlog
[158201598339.412284] [/?author=1] [4] Running (disruptive)     action: pass.
[158201598339.412284] [/?author=1] [8] Running action pass
[158201598339.412284] [/?author=1] [4] (Rule: 980150) Executing operator "Lt" with param "" Was: "" against TX:OUTBOUND_ANOMALY_SCORE.
[158201598339.412284] [/?author=1] [9] Target value: "0" (Variable: TX:OUTBOUND_ANOMALY_SCORE)
[158201598339.412284] [/?author=1] [4] Rule returned 0.
[158201598339.412284] [/?author=1] [9] Matched vars cleaned.
[158201598339.412284] [/?author=1] [8] Checking if this request is suitable to be saved as an audit log.
[158201598339.412284] [/?author=1] [8] Checking if this request is relevant to be part of the audit logs.
[158201598339.412284] [/?author=1] [5] Saving this request as part of the audit logs.
[158201598339.412284] [/?author=1] [8] Request was relevant to be saved. Parts: 6014

from the nginx error logs:

2020/02/18 10:00:20 [error] 22#0: *4 [client 172.18.0.1] ModSecurity: Access denied with code 403 (phase 1). Matched "Operator `Rx' with parameter `(author\=[0-9]+)' against variable `REQUEST_URI' (Value: `/?author=1' ) [file "/usr/local/openresty/nginx/conf/modsecurity_config/http-test"] [line "76"] [id "222"] [rev "1"] [msg "WordPress: User enumeration"] [data "Detected on "] [severity "6"] [ver "%{tx.wprs_version}"] [maturity "9"] [accuracy "9"] [tag "wordpress"] [tag "enumeration"] [hostname "172.18.0.4"] [uri "/"] [unique_id "158201642092.385000"] [ref "o2,8o2,8v4,10t:lowercase,t:urlDecode,t:trim"], client: 172.18.0.1, server: wordpress, request: "GET /?author=1 HTTP/1.1", host: "wordpress"
2020/02/18 10:00:20 [error] 22#0: *4 [client 172.18.0.1] ModSecurity: Access denied with code 403 (phase 4). Matched "Operator `Ge' with parameter `' against variable `TX:OUTBOUND_ANOMALY_SCORE' (Value: `0' ) [file "/opt/owasp-modsecurity-crs/rules/RESPONSE-959-BLOCKING-EVALUATION.conf"] [line "68"] [id "959100"] [rev ""] [msg "Outbound Anomaly Score Exceeded (Total Score: 0)"] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [tag "anomaly-evaluation"] [hostname "172.18.0.4"] [uri "/"] [unique_id "158201642092.385000"] [ref ""], client: 172.18.0.1, server: wordpress, request: "GET /?author=1 HTTP/1.1", host: "wordpress"
2020/02/18 10:00:20 [alert] 22#0: *4 header already sent, client: 172.18.0.1, server: wordpress, request: "GET /?author=1 HTTP/1.1", host: "wordpress"

theMiddleBlue · 2020-02-18T09:02:59Z

P.S.

removing the rule:

# curl -v 'http://wordpress/?author=1'
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to wordpress (127.0.0.1) port 80 (#0)
> GET /?author=1 HTTP/1.1
> Host: wordpress
> User-Agent: curl/7.64.1
> Accept: */*
> 
< HTTP/1.1 301 Moved Permanently
< Date: Tue, 18 Feb 2020 09:02:35 GMT
< Content-Type: text/html; charset=UTF-8
< Content-Length: 0
< Connection: keep-alive
< X-Powered-By: PHP/7.3.10
< X-Redirect-By: WordPress
< Location: http://wordpress/author/admin/
< 
* Connection #0 to host wordpress left intact
* Closing connection 0

zimmerle · 2020-02-18T13:17:11Z

Hi @theMiddleBlue

Do you happens to have the debug logs from Nginx?

theMiddleBlue · 2020-02-18T13:25:53Z

that's a tail from the nginx start to the request (error_log level debug):

2020/02/18 14:24:12 [notice] 8#0: ModSecurity-nginx v1.0.1 (rules loaded inline/local/remote: 0/707/0)
2020/02/18 14:24:12 [notice] 8#0: using the "epoll" event method
2020/02/18 14:24:12 [notice] 8#0: start worker processes
2020/02/18 14:24:12 [notice] 8#0: start worker process 23
2020/02/18 14:24:12 [notice] 8#0: start worker process 24
2020/02/18 14:24:12 [notice] 8#0: start worker process 25
2020/02/18 14:24:12 [notice] 8#0: start worker process 26
2020/02/18 14:24:12 [notice] 8#0: start worker process 27
2020/02/18 14:24:12 [notice] 8#0: start worker process 28
2020/02/18 14:24:12 [notice] 8#0: start cache manager process 29
2020/02/18 14:24:12 [notice] 8#0: start cache loader process 30
2020/02/18 14:24:12 [notice] 10#0: gracefully shutting down
2020/02/18 14:24:12 [notice] 9#0: gracefully shutting down
2020/02/18 14:24:12 [notice] 10#0: exiting
2020/02/18 14:24:12 [notice] 9#0: exiting
2020/02/18 14:24:12 [notice] 11#0: gracefully shutting down
2020/02/18 14:24:12 [notice] 13#0: gracefully shutting down
2020/02/18 14:24:12 [notice] 13#0: exiting
2020/02/18 14:24:12 [notice] 12#0: gracefully shutting down
2020/02/18 14:24:12 [notice] 11#0: exiting
2020/02/18 14:24:12 [notice] 12#0: exiting
2020/02/18 14:24:12 [notice] 15#0: exiting
2020/02/18 14:24:12 [notice] 8#0: signal 17 (SIGCHLD) received from 15
2020/02/18 14:24:12 [notice] 8#0: cache manager process 15 exited with code 0
2020/02/18 14:24:12 [notice] 8#0: signal 29 (SIGIO) received
2020/02/18 14:24:12 [notice] 16#0: exiting
2020/02/18 14:24:12 [notice] 14#0: gracefully shutting down
2020/02/18 14:24:12 [notice] 14#0: exiting
2020/02/18 14:24:12 [notice] 10#0: exit
2020/02/18 14:24:12 [notice] 8#0: signal 17 (SIGCHLD) received from 16
2020/02/18 14:24:12 [notice] 8#0: cache loader process 16 exited with code 0
2020/02/18 14:24:12 [notice] 8#0: signal 29 (SIGIO) received
2020/02/18 14:24:12 [notice] 8#0: signal 17 (SIGCHLD) received from 10
2020/02/18 14:24:12 [notice] 8#0: worker process 10 exited with code 0
2020/02/18 14:24:12 [notice] 8#0: signal 29 (SIGIO) received
2020/02/18 14:24:12 [notice] 12#0: exit
2020/02/18 14:24:12 [notice] 13#0: exit
2020/02/18 14:24:12 [notice] 8#0: signal 17 (SIGCHLD) received from 13
2020/02/18 14:24:12 [notice] 8#0: worker process 13 exited with code 0
2020/02/18 14:24:12 [notice] 8#0: worker process 12 exited with code 0
2020/02/18 14:24:12 [notice] 8#0: signal 29 (SIGIO) received
2020/02/18 14:24:12 [notice] 8#0: signal 17 (SIGCHLD) received from 12
2020/02/18 14:24:12 [notice] 14#0: exit
2020/02/18 14:24:12 [notice] 11#0: exit
2020/02/18 14:24:12 [notice] 9#0: exit
2020/02/18 14:24:12 [notice] 8#0: signal 17 (SIGCHLD) received from 14
2020/02/18 14:24:12 [notice] 8#0: worker process 14 exited with code 0
2020/02/18 14:24:12 [notice] 8#0: signal 29 (SIGIO) received
2020/02/18 14:24:12 [notice] 8#0: signal 17 (SIGCHLD) received from 11
2020/02/18 14:24:12 [notice] 8#0: worker process 11 exited with code 0
2020/02/18 14:24:12 [notice] 8#0: signal 29 (SIGIO) received
2020/02/18 14:24:12 [notice] 8#0: signal 17 (SIGCHLD) received from 9
2020/02/18 14:24:12 [notice] 8#0: worker process 9 exited with code 0
2020/02/18 14:24:12 [notice] 8#0: signal 29 (SIGIO) received
2020/02/18 14:24:21 [error] 23#0: *3 [client 172.18.0.1] ModSecurity: Access denied with code 403 (phase 1). Matched "Operator `Rx' with parameter `(author\=[0-9]+)' against variable `REQUEST_URI' (Value: `/?author=1' ) [file "/usr/local/openresty/nginx/conf/modsecurity_config/http-test"] [line "76"] [id "222"] [rev "1"] [msg "WordPress: User enumeration"] [data "Detected on "] [severity "6"] [ver "%{tx.wprs_version}"] [maturity "9"] [accuracy "9"] [tag "wordpress"] [tag "enumeration"] [hostname "172.18.0.4"] [uri "/"] [unique_id "158203226146.109639"] [ref "o2,8o2,8v4,10t:lowercase,t:urlDecode,t:trim"], client: 172.18.0.1, server: wordpress, request: "GET /?author=1 HTTP/1.1", host: "wordpress"
2020/02/18 14:24:21 [error] 23#0: *3 [client 172.18.0.1] ModSecurity: Access denied with code 403 (phase 4). Matched "Operator `Ge' with parameter `' against variable `TX:OUTBOUND_ANOMALY_SCORE' (Value: `0' ) [file "/opt/owasp-modsecurity-crs/rules/RESPONSE-959-BLOCKING-EVALUATION.conf"] [line "68"] [id "959100"] [rev ""] [msg "Outbound Anomaly Score Exceeded (Total Score: 0)"] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [tag "anomaly-evaluation"] [hostname "172.18.0.4"] [uri "/"] [unique_id "158203226146.109639"] [ref ""], client: 172.18.0.1, server: wordpress, request: "GET /?author=1 HTTP/1.1", host: "wordpress"
2020/02/18 14:24:21 [alert] 23#0: *3 header already sent, client: 172.18.0.1, server: wordpress, request: "GET /?author=1 HTTP/1.1", host: "wordpress"

zimmerle · 2020-02-18T13:36:27Z

It seems that ModSecurity is taking a disruptive action on phase:1; While found a disruptive action it communicates it to Nginx, using the Nginx modules chain. Internally at that phase of the request, Nignx has nothing to do except close the request as the headers were not crafted yet.

It is good that we manage to promptly close a bad request without allocating further resources. The flip side is that the rule explicitly requests a 403.

theMiddleBlue · 2020-02-18T13:48:14Z

I'm going to say something that will not help, but it seems something introduced with the recent commit related to the audit_log issue

zimmerle · 2020-02-18T14:00:03Z

Yep. Apparently, it was introduced by the last commit.

It seems that the first intention was to really wait till a point were the status: could be delivered, respecting what is written on the rule. That was buggy. On @victorhora's approach - giving the use case - the status: could be ignored.

I am still thinking about what would be the best approach here: (a) delivery the code informed on status action; (b) close the request as soon as possible (as it was about phase:1) -- I would prefer to not create a compilation flag for it.

theMiddleBlue · 2020-02-18T14:14:09Z

in my setup, I always need to inform the user-agent about a block action (with a landing page that explain why it has been blocked)

theMiddleBlue · 2020-02-18T16:58:04Z

@zimmerle ~~It's really strange that this problem occurs only with the rule I wrote above. With all other rules nginx replies with a 403~~. Anyway, I can't figure out at which commit I can roll-back to fix both problems... any help would be appreciated :)

zimmerle · 2020-02-18T18:03:19Z

@theMiddleBlue don't have an answer now. I am going to investigate it a little deeper tomorrow.

@victorhora it will be good with we have a chance to investigate this together.

fzipi · 2020-03-04T13:47:05Z

Hey @zimmerle , any news on this one?

zimmerle · 2020-03-05T11:49:00Z

Hey @zimmerle , any news on this one?

Still on the backlog. We had no time to dig into this yet.

github-actions · 2020-04-05T00:08:09Z

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

fzipi · 2020-04-05T15:14:17Z

Nope, please don't close this one.

victorhora · 2020-04-07T20:40:44Z

The "nostale" tag has been set for this one too. I'll have another tab on this one :)

github-actions · 2020-07-25T00:30:06Z

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

martinhsv · 2020-07-30T14:17:04Z

Given the 'nostale' tag, this item should not have been closed by the bot.

fzipi · 2020-07-30T14:52:21Z

Definitely.

github-actions · 2020-08-31T00:17:20Z

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

fzipi · 2020-08-31T02:10:22Z

Here, some activity Mr. bot.

Berndinox · 2020-10-16T17:50:58Z

Probleme still there any solution?

AntonyBishop · 2021-03-22T15:51:28Z

Hi. Are there any updates on when a fix may be available? Many thanks

defanator · 2021-03-22T16:48:46Z

I believe this change should have improved the case described here #170 (comment):

e028ca4

I'm seeing correct behaviour with current master of the nginx connector:

root@vagrant:/etc/nginx/modsec# cat /etc/nginx/modsec/main.conf 
include /etc/nginx/modsec/modsecurity.conf

SecDefaultAction "phase:1,log,auditlog,deny,status:403"
SecDefaultAction "phase:2,log,auditlog,deny,status:403"

SecRule REQUEST_URI "(author\=[0-9]+)" "phase:1,id:222,\
   t:lowercase,t:urlDecode,t:trim,\
   block,\
   log,\
   rev:'1',\
   severity:'6',\
   maturity:'9',\
   accuracy:'9',\
   tag:'wordpress',\
   tag:'enumeration',\
   logdata:'Detected on %{TX:1}',\
   msg:'WordPress: User enumeration'"

root@vagrant:/etc/nginx/modsec# curl -v 'http://localhost/modsec-full/?author=1'
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to localhost (127.0.0.1) port 80 (#0)
> GET /modsec-full/?author=1 HTTP/1.1
> Host: localhost
> User-Agent: curl/7.58.0
> Accept: */*
> 
< HTTP/1.1 403 Forbidden
< Server: nginx/1.19.8
< Date: Mon, 22 Mar 2021 16:48:09 GMT
< Content-Type: text/html
< Content-Length: 153
< Connection: keep-alive
< 
<html>
<head><title>403 Forbidden</title></head>
<body>
<center><h1>403 Forbidden</h1></center>
<hr><center>nginx/1.19.8</center>
</body>
</html>
* Connection #0 to host localhost left intact

root@vagrant:/etc/nginx/modsec# cat /var/log/nginx/error.log 
2021/03/22 16:48:09 [error] 3719#3719: *7 [client 127.0.0.1] ModSecurity: Access denied with code 403 (phase 1). Matched "Operator `Rx' with parameter `(author\=[0-9]+)' against variable `REQUEST_URI' (Value: `/modsec-full/?author=1' ) [file "/etc/nginx/modsec/main.conf"] [line "6"] [id "222"] [rev "1"] [msg "WordPress: User enumeration"] [data "Detected on "] [severity "6"] [ver ""] [maturity "9"] [accuracy "9"] [tag "wordpress"] [tag "enumeration"] [hostname "127.0.0.1"] [uri "/modsec-full/"] [unique_id "1616431689"] [ref "o14,8o14,8v4,22t:lowercase,t:urlDecode,t:trim"], client: 127.0.0.1, server: , request: "GET /modsec-full/?author=1 HTTP/1.1", host: "localhost"
2021/03/22 16:48:09 [info] 3719#3719: *7 client 127.0.0.1 closed keepalive connection

logopk · 2022-10-05T16:17:34Z

with 1.0.3 still no messages in modsec_audit.log that stem from eg CRS.

I have one testrule
SecRule ARGS:testparam "@contains test" "id:1234,deny,status:403"

that gets logged as only rule

2022/10/05 18:07:12 [info] 3466#3466: *510 ModSecurity: Warning. detected SQLi using libinjection. [file "/usr/share/modsecurity-crs/rules/REQUEST-942-APPLICATION-ATTACK-SQLI.conf"] [line "46"] [id "942100"] [rev ""] [msg "SQL Injection Attack Detected via libinjection"] [data "Matched Data: s&1c found within ARGS:testcrs: ' OR 1=1 --"] [severity "2"] [ver "OWASP_CRS/3.3.4"] [maturity "0"] [accuracy "0"] [hostname "172.16.18.3"] [uri "/xxx"] [unique_id "166498603220.458852"] [ref "v17,11"], client: 192.168.126.1, server: docker3.mydomain.de, request: "GET /xxx?testcrs=%27%20OR%201=1%20-- HTTP/1.1", host: "docker3.mydomain.de:4533"
2022/10/05 18:07:12 [error] 3466#3466: *510 [client 192.168.126.1] ModSecurity: Access denied with code 403 (phase 2). Matched "Operator `Ge' with parameter `5' against variable `TX:ANOMALY_SCORE' (Value: `5' ) [file "/usr/share/modsecurity-crs/rules/REQUEST-949-BLOCKING-EVALUATION.conf"] [line "81"] [id "949110"] [rev ""] [msg "Inbound Anomaly Score Exceeded (Total Score: 5)"] [data ""] [severity "2"] [ver "OWASP_CRS/3.3.4"] [maturity "0"] [accuracy "0"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-generic"] [hostname "172.16.18.3"] [uri "/xxx"] [unique_id "166498603220.458852"] [ref ""], client: 192.168.126.1, server: docker3.mydomain.de, request: "GET /xxx?testcrs=%27%20OR%201=1%20-- HTTP/1.1", host: "docker3.mydomain.de:4533"

is not logged in modsec_audit.log

BTW, the first entry is only logged with error log-level info. Shouldn't that also be an "error".

martinhsv · 2022-10-05T16:47:57Z

@logopk ,

Regarding your second snippet (from nginx's error.log) and the log levels of the two lines: No. The first line is not an 'error' because that rule is not the one disrupting the traffic. Rule 949110 is 'error' because it is the one causing the 'deny'.

I don't understand the rest of what you are asking. Please provide more detail.

logopk · 2022-10-05T16:55:48Z

@martinhsv to clarify what I wanted to ask.

As the TO I don't see any entries in the modsec_audit log.

Because this was supposed to be fixed I wanted to let you know that I don't see any improvement in v1.0.3.

The second snippet above is not logged in modsec_audit log. So I do not find any information why a request is blocked (together with the missing "info" log above, as I had set the nginx error log-level to warn before).

martinhsv · 2022-10-05T17:10:24Z

@logopk ,

"I don't see any entries in the modsec_audit log."

I just ran with this rule only:

SecRule ARGS:testparam "@contains test" "id:1234,deny,status:403"

with request:

curl http://localhost?testparam=test

And it produced this in audit_log:

...
---vPm4CHGL---H--
ModSecurity: Access denied with code 403 (phase 1). Matched "Operator `Contains' with parameter `test' against variable `ARGS:testparam' (Value: `test' ) [file "/etc/nginx/modsec/owasp-modsecurity-crs/rules/mhsvtest.conf"] [line "417"] [id "1234"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "127.0.0.1"] [uri "/"] [unique_id "166498925163.255664"] [ref "o0,4v16,4"]
...

That does indeed suggest that the issue originally reported here is fixed.

I separately activated the two relevant CRS files and then ran:

curl http://localhost?testparam=a%20OR%201%3D1--

... and 942100 and 949110 were both reported in the audit log.

logopk · 2022-10-05T17:37:55Z

But why not the rules in CRS in my system?

martinhsv · 2022-10-05T17:49:29Z

I'm going to plan to close this issue.

It seems, at minimum, that the original issue that opened this ticket was resolved years ago.

Based on the comment by @defanator a year-and-a-half ago, I'm assuming that even the related issue (no response headers) has been resolved. If I am mistaken about that, feel free to open a new issue with a full description of the problem in current versions (of ModSecurity with ModSecurity-nginx).

@logopk: I am going to suggest you use the debug log (at level 9) to see what's happening. If you cannot figure it out, feel free to open a separate issue. But, if you do so, please use the issue template and provide as much information as possible (including the debug log).

logopk · 2022-10-05T19:19:43Z

Just one last question:

CRS sets all anomaly actions to log but no noauditlog

SecRule TX:ANOMALY_SCORE "@ge %{tx.inbound_anomaly_score_threshold}" \
    "id:949110,\
    phase:2,\
    deny,\
    t:none,\
    log,\
    msg:'Inbound Anomaly Score Exceeded (Total Score: %{TX.ANOMALY_SCORE})',\
    tag:'application-multi',\
    tag:'language-multi',\
    tag:'platform-multi',\
    tag:'attack-generic',\
    ver:'OWASP_CRS/3.3.4',\
    severity:'CRITICAL',\
    setvar:'tx.inbound_anomaly_score=%{tx.anomaly_score}'"

crs-setup.conf defines as default:

SecDefaultAction "phase:1,log,auditlog,pass"
SecDefaultAction "phase:2,log,auditlog,pass"

From debug log I see that 949110 is not logging to auditlog.

Could it be that the default is not applied?

modsec 2.9.4 in apache logs 949110 to modsec_audit.log.

How did you get 949110 to log?

---- Edit:
SecRuleUpdateActionById 949110 "log,auditlog"

and I get this in modsec_audit.log

martinhsv · 2022-10-05T19:58:07Z

"modsec 2.9.4 in apache logs"

You stated you are using version 1.0.3 of this Connector (ModSecurity-nginx) -- which is for use with ModSecurity v3 with nginx.

But now you say that you're running ModSecurity v2.9.4 with Apache?!?

logopk · 2022-10-05T20:13:29Z

I also run an apache server that I use to compare the results.

martinhsv · 2022-10-05T20:19:47Z

Closing per my earlier comments.

@logopk : Feel free to open an issue if you cannot discern what is happening, but please provide all relevant information if you do.

victorhora self-assigned this Jan 22, 2020

victorhora added the bug label Jan 24, 2020

victorhora mentioned this issue Jan 27, 2020

Fix audit_log not generated for disruptive actions #175

Closed

victorhora mentioned this issue Jan 28, 2020

ModSecurity-nginx 1.0.1 and auditlog #176

Closed

zimmerle self-assigned this Feb 18, 2020

github-actions bot added the stale label Apr 5, 2020

victorhora added nostale The label to apply when an issue is exempt from being marked stale and removed stale labels Apr 7, 2020

github-actions bot added the no-issue-activity label Jul 25, 2020

github-actions bot closed this as completed Jul 30, 2020

martinhsv reopened this Jul 30, 2020

github-actions bot removed the no-issue-activity label Jul 31, 2020

github-actions bot added the no-issue-activity label Aug 31, 2020

github-actions bot removed the no-issue-activity label Sep 1, 2020

razvan-moj mentioned this issue Jan 21, 2022

Unable to troubleshoot mod_security blocked requests ministryofjustice/cloud-platform#2714

Closed

razvan-moj mentioned this issue Feb 21, 2022

Add AWS managed ingress option ministryofjustice/cloud-platform#3556

Closed

martinhsv mentioned this issue May 17, 2022

The log cannot record 302 actions owasp-modsecurity/ModSecurity#2741

Closed

martinhsv closed this as completed Oct 5, 2022

Requests blocked in Phase 1 (Request Headers) do not appear in the audit log #170

Requests blocked in Phase 1 (Request Headers) do not appear in the audit log #170

Comments

robinkb commented Sep 30, 2019 • edited Loading

Description

Steps to reproduce

Environment

victorhora commented Jan 27, 2020

theMiddleBlue commented Feb 12, 2020

zimmerle commented Feb 12, 2020

theMiddleBlue commented Feb 12, 2020

zimmerle commented Feb 12, 2020

theMiddleBlue commented Feb 12, 2020 • edited Loading

logopk commented Feb 17, 2020

theMiddleBlue commented Feb 18, 2020

theMiddleBlue commented Feb 18, 2020

zimmerle commented Feb 18, 2020

theMiddleBlue commented Feb 18, 2020

zimmerle commented Feb 18, 2020

theMiddleBlue commented Feb 18, 2020

zimmerle commented Feb 18, 2020

theMiddleBlue commented Feb 18, 2020

theMiddleBlue commented Feb 18, 2020 • edited Loading

zimmerle commented Feb 18, 2020

fzipi commented Mar 4, 2020

zimmerle commented Mar 5, 2020

github-actions bot commented Apr 5, 2020

fzipi commented Apr 5, 2020

victorhora commented Apr 7, 2020

github-actions bot commented Jul 25, 2020

martinhsv commented Jul 30, 2020

fzipi commented Jul 30, 2020

github-actions bot commented Aug 31, 2020

fzipi commented Aug 31, 2020

Berndinox commented Oct 16, 2020

AntonyBishop commented Mar 22, 2021 • edited Loading

defanator commented Mar 22, 2021 • edited Loading

logopk commented Oct 5, 2022

martinhsv commented Oct 5, 2022 • edited Loading

logopk commented Oct 5, 2022

martinhsv commented Oct 5, 2022 • edited Loading

logopk commented Oct 5, 2022 • edited Loading

martinhsv commented Oct 5, 2022 • edited Loading

logopk commented Oct 5, 2022 • edited Loading

martinhsv commented Oct 5, 2022

logopk commented Oct 5, 2022

martinhsv commented Oct 5, 2022

robinkb commented Sep 30, 2019 •

edited

Loading

theMiddleBlue commented Feb 12, 2020 •

edited

Loading

theMiddleBlue commented Feb 18, 2020 •

edited

Loading

AntonyBishop commented Mar 22, 2021 •

edited

Loading

defanator commented Mar 22, 2021 •

edited

Loading

martinhsv commented Oct 5, 2022 •

edited

Loading

martinhsv commented Oct 5, 2022 •

edited

Loading

logopk commented Oct 5, 2022 •

edited

Loading

martinhsv commented Oct 5, 2022 •

edited

Loading

logopk commented Oct 5, 2022 •

edited

Loading