Nginx sends response without headers

owasp-modsecurity / ModSecurity-nginx

ModSecurity v3 Nginx Connector

Apache License 2.0

1.49k stars 277 forks source link

Nginx sends response without headers #238

Closed airween closed 3 years ago

airween commented 3 years ago

As we discussed in ModSecurity issue #2465, the nginx connector tries to do all the processing as early as possible.

The unexpected behavior is the server doesn't send the response headers to client. It can reproduced with this minimal rule set:

include /etc/nginx/modsec/modsecurity.conf

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

SecAction "id:900101,phase:1,nolog,pass,t:none,setvar:tx.trigger_phase1=1"
SecAction "id:900103,phase:1,nolog,pass,t:none,setvar:tx.trigger_phase3=1"
SecAction "id:900105,phase:1,nolog,pass,t:none,setvar:tx.trigger_phase5=1"

SecRule TX:TRIGGER_PHASE1 "@eq 1" "id:901111,phase:1,t:none,deny,log"
SecRule REQUEST_BODY "@rx attack" "id:901121,phase:2,t:none,deny,log"
SecRule TX:TRIGGER_PHASE3 "@eq 1" "id:901131,phase:3,t:none,deny,log"
SecRule RESPONSE_BODY "@rx ok" "id:901141,phase:4,t:none,deny,log"
SecRule TX:TRIGGER_PHASE5 "@eq 1" "id:901151,phase:5,t:none,pass,log,msg:'This is the phase 5.'"

The request can be anything, the set contains 3 rules which will triggered always in phase 1, 3 and 5.

The disrputive action of these rules are deny which means the rule wants to terminate the process, but Nginx continues.

defanator commented 3 years ago

@airween appreciate if you'll be able to check this one: https://github.com/defanator/ModSecurity-nginx/commit/51cbaf3c97addd581973a62a6103221831a11c7e

(I'm still trying to figure out the better way(s) of handling this.)

airween commented 3 years ago

Hi @defanator,

so many thanks for quick work - looks like it works as we expect:

$ curl -vvv 'http://localhost/modsec-full/ncl_items.shtml'
* Expire in 0 ms for 6 (transfer 0x55aac808bf50)
...
* Expire in 1 ms for 1 (transfer 0x55aac808bf50)
*   Trying ::1...
* TCP_NODELAY set
* Expire in 149997 ms for 3 (transfer 0x55aac808bf50)
* Expire in 200 ms for 4 (transfer 0x55aac808bf50)
* connect to ::1 port 80 failed: Connection refused
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Expire in 149997 ms for 3 (transfer 0x55aac808bf50)
* Connected to localhost (127.0.0.1) port 80 (#0)
> GET /modsec-full/ncl_items.shtml HTTP/1.1
> Host: localhost
> User-Agent: curl/7.64.0
> Accept: */*
> 
< HTTP/1.1 403 Forbidden
< Server: nginx/1.19.6
< Date: Mon, 25 Jan 2021 16:02:18 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.6</center>
</body>
</html>

In the error.log I got:

2021/01/25 16:02:18 [error] 31577#31577: *2 [client 127.0.0.1] ModSecurity: Access denied with code 403 (phase 1). Matched "Operator `Eq' with parameter `1' against variable `TX:TRIGGER_PHASE1' (Value: `1' ) [file "/etc/nginx/modsec/main.conf"] [line "10"] [id "901112"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "127.0.0.1"] [uri "/modsec-full/ncl_items.shtml"] [unique_id "1611590538"] [ref ""], client: 127.0.0.1, server: , request: "GET /modsec-full/ncl_items.shtml HTTP/1.1", host: "localhost"
2021/01/25 16:02:18 [error] 31577#31577: *2 [client 127.0.0.1] ModSecurity: Access denied with code 403 (phase 3). Matched "Operator `Eq' with parameter `1' against variable `TX:TRIGGER_PHASE3' (Value: `1' ) [file "/etc/nginx/modsec/main.conf"] [line "12"] [id "901131"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "127.0.0.1"] [uri "/modsec-full/ncl_items.shtml"] [unique_id "1611590538"] [ref ""], client: 127.0.0.1, server: , request: "GET /modsec-full/ncl_items.shtml HTTP/1.1", host: "localhost"
2021/01/25 16:02:18 [info] 31577#31577: *2 ModSecurity: Warning. Matched "Operator `Eq' with parameter `1' against variable `TX:TRIGGER_PHASE5' (Value: `1' ) [file "/etc/nginx/modsec/main.conf"] [line "14"] [id "901151"] [rev ""] [msg "This is the phase 5."] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "127.0.0.1"] [uri "/modsec-full/ncl_items.shtml"] [unique_id "1611590538"] [ref ""] while logging request, client: 127.0.0.1, server: , request: "GET /modsec-full/ncl_items.shtml HTTP/1.1", host: "localhost"

I'm using the temporary small rule set above (with 5 rules and 3 SecAction's).

But I'm still wondering why did phase:3 rule was triggered when phase:1 rule intervened the transaction? (Phase:5 obliviously triggered)

Thanks again!

defanator commented 3 years ago

But I'm still wondering why did phase:3 rule was triggered when phase:1 rule intervened the transaction? (Phase:5 obliviously triggered)

That's a great question.

According to the https://github.com/SpiderLabs/ModSecurity/wiki/Reference-Manual-(v2.x)#processing-phases diagram, phase 3 means "response headers", right?

airween commented 3 years ago

Exactly.

But if one of the request header contains an attack, and the engine blocks the request (with deny action), I don't think that it needs to check the next phases (except 5th).

The next question is: if the phase:3 rules activated, then it means the engine got the response from the server/upstream? But the server/upstream sends back the response headers only when it got the request body too (eg. if the request is POST).

So the request header contains an attack what we wants to block, it no matters, the Nginx sends the request body (without inspect), server got it? (I don't know is that true or not, just asking).

Here is the relevant part of Apache's error.log:

[Mon Jan 25 16:36:55.880628 2021] [:error] [pid 645628] [client ::1:50687] [client ::1] ModSecurity: Warning. Matched phrase "nikto" at REQUEST_HEADERS:User-Agent. [file "/usr/share/modsecurity-crs/rules/REQUEST-913-SCANNER-DETECTION.conf"] [line "54"] [id "913100"] [msg "Found User-Agent associated with security scanner"] [data "Matched Data: nikto found within REQUEST_HEADERS:User-Agent: nikto"] [severity "CRITICAL"] [ver "OWASP_CRS/3.3.1"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-reputation-scanner"] [tag "paranoia-level/1"] [tag "OWASP_CRS"] [tag "capec/1000/118/224/541/310"] [tag "PCI/6.5.10"] [hostname "localhost"] [uri "/"] [unique_id "YA7zpwcT9vAISkIAefAufgAAAAA"]

[Mon Jan 25 16:36:55.890242 2021] [:error] [pid 645628] [client ::1:50687] [client ::1] ModSecurity: Access denied with code 403 (phase 1). Operator GE matched 5 at TX:anomaly_score. [file "/usr/share/modsecurity-crs/rules/REQUEST-949-BLOCKING-EVALUATION.conf"] [line "166"] [id "949111"] [msg "Inbound Anomaly Score Exceeded in phase 1 (Total Score: 5)"] [severity "CRITICAL"] [ver "OWASP_CRS/3.3.1"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-generic"] [hostname "localhost"] [uri "/"] [unique_id "YA7zpwcT9vAISkIAefAufgAAAAA"]

[Mon Jan 25 16:36:55.891256 2021] [:error] [pid 645628] [client ::1:50687] [client ::1] ModSecurity: Warning. Operator GE matched 5 at TX:inbound_anomaly_score. [file "/usr/share/modsecurity-crs/rules/RESPONSE-980-CORRELATION.conf"] [line "91"] [id "980130"] [msg "Inbound Anomaly Score Exceeded (Total Inbound Score: 5 - SQLI=0,XSS=0,RFI=0,LFI=0,RCE=0,PHPI=0,HTTP=0,SESS=0): individual paranoia level scores: 5, 0, 0, 0"] [ver "OWASP_CRS/3.3.1"] [tag "event-correlation"] [hostname "localhost"] [uri "/"] [unique_id "YA7zpwcT9vAISkIAefAufgAAAAA"]

Here I'm using CRS with blocking_early feature, so the 1st line just a warning, where engine sets the anomaly score. The second line shows that the engine blocked the transaction - and there isn't more phase, only the logging (phase:5).

airween commented 3 years ago

(I don't know is that true or not, just asking).

Meanwhile I've checked this functionality: if any phase:1 rule intervened transaction, then the request body won't send to server.

defanator commented 3 years ago

@airween could you please check https://github.com/SpiderLabs/ModSecurity-nginx/pull/240 incl. new test case for the issue? Does it look correct?

airween commented 3 years ago

Hi @defanator,

looks like nothing changed in behavior since the previous version:

* Expire in 0 ms for 6 (transfer 0x5569115f7f50)
...
* Expire in 1 ms for 1 (transfer 0x5569115f7f50)
*   Trying ::1...
* TCP_NODELAY set
* Expire in 149997 ms for 3 (transfer 0x5569115f7f50)
* Expire in 200 ms for 4 (transfer 0x5569115f7f50)
* connect to ::1 port 80 failed: Connection refused
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Expire in 149997 ms for 3 (transfer 0x5569115f7f50)
* Connected to localhost (127.0.0.1) port 80 (#0)
> GET /index.php HTTP/1.1
> Host: localhost
> User-Agent: curl/7.64.0
> Accept: */*
> 
< HTTP/1.1 403 Forbidden
< Server: nginx/1.19.6
< Date: Wed, 03 Feb 2021 14:25:59 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.6</center>
</body>
</html>
* Connection #0 to host localhost left intact

error.log:

2021/02/03 14:25:43 [notice] 19742#19742: ModSecurity-nginx v1.0.1 (rules loaded inline/local/remote: 0/42/0)
2021/02/03 14:25:43 [notice] 19742#19742: using the "epoll" event method
2021/02/03 14:25:43 [notice] 19742#19742: nginx/1.19.6
2021/02/03 14:25:43 [notice] 19742#19742: built by gcc 8.3.0 (Debian 8.3.0-6) 
2021/02/03 14:25:43 [notice] 19742#19742: OS: Linux 4.19.0-9-amd64
2021/02/03 14:25:43 [notice] 19742#19742: getrlimit(RLIMIT_NOFILE): 131072:131072
2021/02/03 14:25:43 [notice] 19743#19743: start worker processes
2021/02/03 14:25:43 [notice] 19743#19743: start worker process 19744

2021/02/03 14:25:59 [error] 19744#19744: *1 [client 127.0.0.1] ModSecurity: Access denied with code 403 (phase 1). Matched "Operator `Eq' with parameter `1' against variable `TX:TRIGGER_PHASE1' (Value: `1' ) [file "/etc/nginx/modsec/main.conf"] [line "10"] [id "901112"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "127.0.0.1"] [uri "/index.php"] [unique_id "1612362359"] [ref ""], client: 127.0.0.1, server: , request: "GET /index.php HTTP/1.1", host: "localhost"

2021/02/03 14:25:59 [error] 19744#19744: *1 [client 127.0.0.1] ModSecurity: Access denied with code 403 (phase 3). Matched "Operator `Eq' with parameter `1' against variable `TX:TRIGGER_PHASE3' (Value: `1' ) [file "/etc/nginx/modsec/main.conf"] [line "12"] [id "901131"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "127.0.0.1"] [uri "/index.php"] [unique_id "1612362359"] [ref ""], client: 127.0.0.1, server: , request: "GET /index.php HTTP/1.1", host: "localhost"

2021/02/03 14:25:59 [info] 19744#19744: *1 ModSecurity: Warning. Matched "Operator `Eq' with parameter `1' against variable `TX:TRIGGER_PHASE5' (Value: `1' ) [file "/etc/nginx/modsec/main.conf"] [line "14"] [id "901151"] [rev ""] [msg "This is the phase 5."] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "127.0.0.1"] [uri "/index.php"] [unique_id "1612362359"] [ref ""] while logging request, client: 127.0.0.1, server: , request: "GET /index.php HTTP/1.1", host: "localhost"

The second Access denied with code 403 is still presents, which is weird.

The response is (still) correct now.

defanator commented 3 years ago

@airween I've just updated PR with https://github.com/SpiderLabs/ModSecurity-nginx/pull/240/commits/4f26b48998db5119ca818b0909b6b14e08ebb544 - this is kinda experimental change but it addresses the issue with extra processing. Could you please check once again? TIA!

airween commented 3 years ago

I think I've used that commit:

$ git branch
  issue238
  issue238-approach2
* issue238-fix
  master

$ git log -1
commit 4f26b48998db5119ca818b0909b6b14e08ebb544 (HEAD -> issue238-fix, defan/issue238-fix)
Author: Andrei Belov <defanator@gmail.com>
Date:   Wed Feb 3 18:13:38 2021 +0300

    Avoid extra processing of subsequent interventions if one was already triggered

$ git describe
v1.0.1-20-g4f26b48

Then I recompiled the Nginx with ./configure --with-compat --add-dynamic-module=../ModSecurity-nginx-issue238 ..., make ... make install, check the module time and date (it's freshly compiled), and restart Nginx.

This gives me the result above.

defanator commented 3 years ago

@airween that's weird because that commit effectively removes 2nd error log entry for phase 3 - here's what I'm getting here locally with the test case introduced:

test@vagrant:~$ cat /tmp/nginx-test-17DrQtuh35/error.log 
2021/02/03 18:16:44 [notice] 7947#7947: ModSecurity-nginx v1.0.1 (rules loaded inline/local/remote: 26/0/0)
2021/02/03 18:16:44 [notice] 7947#7947: using the "epoll" event method
2021/02/03 18:16:44 [notice] 7947#7947: nginx/1.19.6
2021/02/03 18:16:44 [notice] 7947#7947: built by gcc 7.5.0 (Ubuntu 7.5.0-3ubuntu1~18.04) 
2021/02/03 18:16:44 [notice] 7947#7947: OS: Linux 4.15.0-128-generic
2021/02/03 18:16:44 [notice] 7947#7947: getrlimit(RLIMIT_NOFILE): 131072:131072
2021/02/03 18:16:44 [notice] 7947#7947: start worker processes
2021/02/03 18:16:44 [notice] 7947#7947: start worker process 7948
2021/02/03 18:16:44 [error] 7948#7948: *1 [client 127.0.0.1] ModSecurity: Access denied with code 403 (phase 1). Matched "Operator `Eq' with parameter `1' against variable `TX:TRIGGER_PHASE1' (Value: `1' ) [file "<<reference missing or not informed>>"] [line "9"] [id "901111"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "127.0.0.1"] [uri "/early-block"] [unique_id "161237620483.421439"] [ref ""], client: 127.0.0.1, server: localhost, request: "GET /early-block HTTP/1.0", host: "localhost"
2021/02/03 18:16:44 [info] 7948#7948: *1 ModSecurity: Warning. Matched "Operator `Eq' with parameter `1' against variable `TX:TRIGGER_PHASE5' (Value: `1' ) [file "<<reference missing or not informed>>"] [line "13"] [id "901151"] [rev ""] [msg "This is the phase 5."] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "127.0.0.1"] [uri "/early-block"] [unique_id "161237620483.421439"] [ref ""] while logging request, client: 127.0.0.1, server: localhost, request: "GET /early-block HTTP/1.0", host: "localhost"
2021/02/03 18:16:44 [notice] 7947#7947: signal 3 (SIGQUIT) received from 7945, shutting down
2021/02/03 18:16:44 [notice] 7948#7948: gracefully shutting down
2021/02/03 18:16:44 [notice] 7948#7948: exiting
2021/02/03 18:16:44 [notice] 7948#7948: exit
2021/02/03 18:16:44 [notice] 7947#7947: signal 17 (SIGCHLD) received from 7948
2021/02/03 18:16:44 [notice] 7947#7947: worker process 7948 exited with code 0
2021/02/03 18:16:44 [notice] 7947#7947: exit

airween commented 3 years ago

ModSecurity-nginx v1.0.1 (rules loaded inline/local/remote: 26/0/0)

can you show me your config?

Just because I have

ModSecurity-nginx v1.0.1 (rules loaded inline/local/remote: 0/42/0)

How can I debug that I'm using the right connector? Eg. increased log level shows the git version...? Output of strings ngx_http_modsecurity_module.so?

airween commented 3 years ago

Ah, sorry - I was confused and compiled the module but used a previously installed code.

I can confirm, after the last commit the connector works as we expect:

2021/02/03 19:49:02 [notice] 29997#29997: ModSecurity-nginx v1.0.1 (rules loaded inline/local/remote: 0/42/0)
2021/02/03 19:49:02 [notice] 29997#29997: using the "epoll" event method
2021/02/03 19:49:02 [notice] 29997#29997: nginx/1.19.6
2021/02/03 19:49:02 [notice] 29997#29997: built by gcc 8.3.0 (Debian 8.3.0-6) 
2021/02/03 19:49:02 [notice] 29997#29997: OS: Linux 4.19.0-9-amd64
2021/02/03 19:49:02 [notice] 29997#29997: getrlimit(RLIMIT_NOFILE): 131072:131072
2021/02/03 19:49:02 [notice] 29999#29999: start worker processes
2021/02/03 19:49:02 [notice] 29999#29999: start worker process 30000

2021/02/03 19:49:11 [error] 30000#30000: *1 [client 127.0.0.1] ModSecurity: Access denied with code 403 (phase 1). Matched "Operator `Eq' with parameter `1' against variable `TX:TRIGGER_PHASE1' (Value: `1' ) [file "/etc/nginx/modsec/main.conf"] [line "10"] [id "901112"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "127.0.0.1"] [uri "/index.php"] [unique_id "1612381751"] [ref ""], client: 127.0.0.1, server: , request: "GET /index.php HTTP/1.1", host: "localhost"

2021/02/03 19:49:11 [info] 30000#30000: *1 ModSecurity: Warning. Matched "Operator `Eq' with parameter `1' against variable `TX:TRIGGER_PHASE5' (Value: `1' ) [file "/etc/nginx/modsec/main.conf"] [line "14"] [id "901151"] [rev ""] [msg "This is the phase 5."] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "127.0.0.1"] [uri "/index.php"] [unique_id "1612381751"] [ref ""] while logging request, client: 127.0.0.1, server: , request: "GET /index.php HTTP/1.1", host: "localhost"

with this curl request:

$ curl -vvv 'http://localhost/index.php'
* Expire in 0 ms for 6 (transfer 0x5655364b8f50)
...
* Expire in 1 ms for 1 (transfer 0x5655364b8f50)
*   Trying ::1...
* TCP_NODELAY set
* Expire in 149997 ms for 3 (transfer 0x5655364b8f50)
* Expire in 200 ms for 4 (transfer 0x5655364b8f50)
* connect to ::1 port 80 failed: Connection refused
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Expire in 149997 ms for 3 (transfer 0x5655364b8f50)
* Connected to localhost (127.0.0.1) port 80 (#0)
> GET /index.php HTTP/1.1
> Host: localhost
> User-Agent: curl/7.64.0
> Accept: */*
> 
< HTTP/1.1 403 Forbidden
< Server: nginx/1.19.6
< Date: Wed, 03 Feb 2021 19:49:11 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.6</center>
</body>
</html>
* Connection #0 to host localhost left intact

Sorry for my mistake.

defanator commented 3 years ago

@airween no problem, thanks for confirming.

I've added a test case for this to the modsecurity.t, so the config can be found here: https://github.com/defanator/ModSecurity-nginx/blob/issue238-fix/tests/modsecurity.t#L40-L126

(You also may set the TEST_NGINX_LEAVE=yes env. variable to keep temporary nginx-test-* directories after prove run, that could be helpful in investigating particular cases.)

airween commented 3 years ago

Thanks, I can check that later.

Is there any timing for merge (and/or make new release)?

defanator commented 3 years ago

@airween this change may have an effect on a couple of other opened issues/PRs (#90, #204) but given the state of those I think I'll merge this one and proceed with further investigation on possible error_page effects a bit later.

For the release - I'd ask @zimmerle on their input here. I'm not the right guy here for making releases. :)

airween commented 3 years ago

Ah, okay - thanks! :)