ModSecurity-nginx icon indicating copy to clipboard operation
ModSecurity-nginx copied to clipboard
verified publisher icon owasp-modsecurity

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

Open robinkb opened this issue 6 years ago • 30 comments

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
...

robinkb avatar Sep 30 '19 08:09 robinkb

@robinkb, see if https://github.com/victorhora/ModSecurity-nginx/commit/ac3e8a9ac65877ab0eeebf416c26f2457ffe8296 solves your issue.

victorhora avatar Jan 27 '20 00:01 victorhora

same problem here.

theMiddleBlue avatar Feb 12 '20 12:02 theMiddleBlue

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

zimmerle avatar Feb 12 '20 12:02 zimmerle

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?

theMiddleBlue avatar Feb 12 '20 12:02 theMiddleBlue

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.

zimmerle avatar Feb 12 '20 12:02 zimmerle

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.

theMiddleBlue avatar Feb 12 '20 12:02 theMiddleBlue

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?

logopk avatar Feb 17 '20 11:02 logopk

@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 avatar Feb 18 '20 09:02 theMiddleBlue

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

theMiddleBlue avatar Feb 18 '20 09:02 theMiddleBlue

Hi @theMiddleBlue

Do you happens to have the debug logs from Nginx?

zimmerle avatar Feb 18 '20 13:02 zimmerle

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"

theMiddleBlue avatar Feb 18 '20 13:02 theMiddleBlue

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.

zimmerle avatar Feb 18 '20 13:02 zimmerle

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

theMiddleBlue avatar Feb 18 '20 13:02 theMiddleBlue

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.

zimmerle avatar Feb 18 '20 14:02 zimmerle

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 avatar Feb 18 '20 14:02 theMiddleBlue

@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 :)

theMiddleBlue avatar Feb 18 '20 16:02 theMiddleBlue

@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.

zimmerle avatar Feb 18 '20 18:02 zimmerle

Hey @zimmerle , any news on this one?

fzipi avatar Mar 04 '20 13:03 fzipi

Hey @zimmerle , any news on this one?

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

zimmerle avatar Mar 05 '20 11:03 zimmerle

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

github-actions[bot] avatar Apr 05 '20 00:04 github-actions[bot]

Nope, please don't close this one.

fzipi avatar Apr 05 '20 15:04 fzipi

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

victorhora avatar Apr 07 '20 20:04 victorhora

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

github-actions[bot] avatar Jul 25 '20 00:07 github-actions[bot]

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

martinhsv avatar Jul 30 '20 14:07 martinhsv

Definitely.

fzipi avatar Jul 30 '20 14:07 fzipi

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

github-actions[bot] avatar Aug 31 '20 00:08 github-actions[bot]

Here, some activity Mr. bot.

fzipi avatar Aug 31 '20 02:08 fzipi

Probleme still there any solution?

Berndinox avatar Oct 16 '20 17:10 Berndinox

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

AntonyBishop avatar Mar 22 '21 15:03 AntonyBishop

I believe this change should have improved the case described here https://github.com/SpiderLabs/ModSecurity-nginx/issues/170#issuecomment-587351025:

https://github.com/SpiderLabs/ModSecurity-nginx/commit/e028ca43c83fd114344c34df6a8dd09eb5f34cc2

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

defanator avatar Mar 22 '21 16:03 defanator