Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Nginx sends response without headers #238

Closed
airween opened this issue Jan 21, 2021 · 16 comments · Fixed by #240
Closed

Nginx sends response without headers #238

airween opened this issue Jan 21, 2021 · 16 comments · Fixed by #240
Assignees

Comments

@airween
Copy link
Member

airween commented Jan 21, 2021

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 defanator self-assigned this Jan 21, 2021
@defanator
Copy link
Collaborator

@airween appreciate if you'll be able to check this one: defanator@51cbaf3

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

@airween
Copy link
Member Author

airween commented Jan 25, 2021

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
Copy link
Collaborator

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
Copy link
Member Author

airween commented Jan 25, 2021

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
Copy link
Member Author

airween commented Jan 25, 2021

(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
Copy link
Collaborator

@airween could you please check #240 incl. new test case for the issue? Does it look correct?

@airween
Copy link
Member Author

airween commented Feb 3, 2021

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
Copy link
Collaborator

@airween I've just updated PR with 4f26b48 - this is kinda experimental change but it addresses the issue with extra processing. Could you please check once again? TIA!

@airween
Copy link
Member Author

airween commented Feb 3, 2021

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 <[email protected]>
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
Copy link
Collaborator

@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
Copy link
Member Author

airween commented Feb 3, 2021

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
Copy link
Member Author

airween commented Feb 3, 2021

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
Copy link
Collaborator

@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
Copy link
Member Author

airween commented Feb 4, 2021

Thanks, I can check that later.

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

@defanator
Copy link
Collaborator

@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
Copy link
Member Author

airween commented Feb 4, 2021

Ah, okay - thanks! :)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants