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.

Sign up for GitHub

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

Jump to bottom

logging plus http response_code advice #209

Open
ericinfra opened this issue Jun 25, 2023 · 8 comments
Open

logging plus http response_code advice #209

ericinfra opened this issue Jun 25, 2023 · 8 comments
Assignees
@jcchavezs @M4tteoP

Comments

@ericinfra
Copy link

I use sqlmap to simulate the attack, both coraza and ModSecurity return 403
But ModSecurity logs the http response_code, cozara doesn't

The ModSecurity logging is "ModSecurity: Access denied with code 403"
cozara logging is "Coraza: Access denied (phase 1)" and "Coraza: Access denied (phase 5)"

This leads to the need to manually check the access log to judge and guess the httpresponse_code returned to the client by coraza, which is troublesome

ModSecurity log

2023/05/30 08:56:59 [error] 1471#1471: *2621726 [client 192.168.12.21] ModSecurity: Access denied with code 403 (phase 2). Matched "Operator `Ge' with parameter `5' against variable `TX:ANOMALY_SCORE' (Value: `10' ) [file "/etc/nginx/owasp-modsecurity-crs/rules/REQUEST-949-BLOCKING-EVALUATION.conf"] [line "81"] [id "949110"] [rev ""] [msg "Inbound Anomaly Score Exceeded (Total Score: 10)"] [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 "192.168.0.157"] [uri "/"] [unique_id "16854370199.677820"] [ref ""], client: 192.168.12.21, server: wordpress.k8s.com, request: "POST / HTTP/1.1", host: "wordpress.k8s.com", referrer: "http://wordpress.k8s.com"

coraza log

2023-06-25T07:16:19.171010Z	critical	envoy wasm external/envoy/source/extensions/common/wasm/context.cc:1157	wasm log my-wasm-root-id my-wasm-vm-id: [client "192.168.122.1"] Coraza: Access denied (phase 1). Inbound Anomaly Score Exceeded in phase 1 (Total Score: 8) [file "@owasp_crs/REQUEST-949-BLOCKING-EVALUATION.conf"] [line "10773"] [id "949111"] [rev ""] [msg "Inbound Anomaly Score Exceeded in phase 1 (Total Score: 8)"] [data ""] [severity "emergency"] [ver "OWASP_CRS/4.0.0-rc1"] [maturity "0"] [accuracy "0"] [tag "anomaly-evaluation"] [hostname "10.110.32.70"] [uri "/"] [unique_id "ehTcATrroSYpMrlDwTQ"]
	thread=31
2023-06-25T07:16:19.171308Z	info	envoy wasm external/envoy/source/extensions/common/wasm/context.cc:1148	wasm log my-wasm-root-id my-wasm-vm-id: Transaction interrupted tx_id="ehTcATrroSYpMrlDwTQ" context_id=4 action="deny" phase="http_request_headers"	thread=31
2023-06-25T07:16:19.171678Z	critical	envoy wasm external/envoy/source/extensions/common/wasm/context.cc:1157	wasm log my-wasm-root-id my-wasm-vm-id: [client "192.168.122.1"] Coraza: Access denied (phase 5). Anomaly Scores: (Inbound Scores: blocking=8, detection=8, per_pl=8-0-0-0, threshold=5) - (Outbound Scores: blocking=0, detection=0, per_pl=0-0-0-0, threshold=4) - (SQLI=0, XSS=0, RFI=0, LFI=0, RCE=0,  [file "@owasp_crs/RESPONSE-980-CORRELATION.conf"] [line "12628"] [id "980170"] [rev ""] [msg "Anomaly Scores: (Inbound Scores: blocking=8, detection=8, per_pl=8-0-0-0, threshold=5) - (Outbound Scores: blocking=0, detection=0, per_pl=0-0-0-0, threshold=4) - (SQLI=0, XSS=0, RFI=0, LFI=0, RCE=0, "] [data ""] [severity "emergency"] [ver "OWASP_CRS/4.0.0-rc1"] [maturity "0"] [accuracy "0"] [tag "reporting"] [hostname "10.110.32.70"] [uri "/"] [unique_id "ehTcATrroSYpMrlDwTQ"]
	thread=31
2023-06-25T07:16:19.171781Z	info	envoy wasm external/envoy/source/extensions/common/wasm/context.cc:1148	wasm log my-wasm-root-id my-wasm-vm-id: Finished tx_id="ehTcATrroSYpMrlDwTQ" context_id=4	thread=31
{"start_time": "2023-06-25T07:16:19.164Z","req_method": "GET","x_envoy_original_path": "/","protocol": "HTTP/1.1","response_code": "403","response_flags": "-","bytes_received": "0","bytes_send": "0","duration": "6","resp_x_envoy_upstream_service_time": "-","x_forwarded_for": "-","user_agent": "sqlmap/1.7.5.4#dev (https://sqlmap.org)","x_request_id": "b67d5226-79ca-92ac-963e-dc38267c77e3","authority": "192.168.122.102:30845","upstream_host": "-","upstream_cluster": "inbound|80||","upstream_local_address": "-","downstream_local_address": "10.110.32.70:80","downstream_remote_address": "192.168.122.1:55964","resp_x_foo_fault_flag": "-"}
@jcchavezs
Copy link
Member

Hi @ericinfra, thanks for coming by. We removed that some time ago especially because in a proxy we can't guarantee what was the response code that would end up returned to upstream but not only limited to proxies but to connectors in general, see corazawaf/coraza#795 for more details.

Is this something you need for production or just for the benchmarks?

@ericinfra
Copy link
Author

ericinfra commented Jun 25, 2023 •
edited
Loading

Hi @jcchavezs .Thank you for the reply

This is need for production ,currently in beta

Convenient event tracking and analysis

Or when the following two log messages exist at the same time

"Coraza: Access denied (phase 1)" and "Coraza: Access denied (phase 5)"

I want to clearly confirm which rule is blocking malicious attacks

@jcchavezs
Copy link
Member

Would a response header telling you the rule help? Of course that can't be leaked to client in prod.

@ericinfra
Copy link
Author

ericinfra commented Jun 25, 2023 •
edited
Loading

Can it be associated with istio proxy access log?

I hope that the "Coraza: Access denied" log and the "istio proxy/envoy" access log can be associated with a unique identifier for easy tracking of events

@jcchavezs jcchavezs mentioned this issue Jun 25, 2023
Open
@ericinfra
Copy link
Author

ericinfra commented Jun 26, 2023 •
edited
Loading

Question 1:
Only after triggering the 949 rule, there is Inbound Anomaly Score Exceeded in phase 1 (Total Score: 48)
But when the 980 rule is triggered, the "Total Score" keyword is not seen
Very confused, what is the Anomaly Score that triggers the 980 rule and leads to "Access denied"?

REQUEST-949-BLOCKING-EVALUATION.conf log ,Total Score: 48

2023-06-26T08:48:14.108812Z	critical	envoy wasm external/envoy/source/extensions/common/wasm/context.cc:1157	wasm log my-wasm-root-id my-wasm-vm-id: [client "192.168.122.1"] Coraza: Access denied (phase 1). Inbound Anomaly Score Exceeded in phase 1 (Total Score: 48) [file "@owasp_crs/REQUEST-949-BLOCKING-EVALUATION.conf"] [line "10773"] [id "949111"] [rev ""] [msg "Inbound Anomaly Score Exceeded in phase 1 (Total Score: 48)"] [data ""] [severity "emergency"] [ver "OWASP_CRS/4.0.0-rc1"] [maturity "0"] [accuracy "0"] [tag "anomaly-evaluation"] [hostname "10.110.32.70"] [uri "/?s=..%2F..%2F..%2F..%2F..%2F..%2F..%2F..%2F..%2F..%2F..%2F..%2F..%2F..%2F..%2F..%2F"] [unique_id "segMKgHkWDPmIwxaowb"]

RESPONSE-980-CORRELATION.conf Access denied log, did not see the "Total Score" keyword

2023-06-26T08:48:12.641728Z	critical	envoy wasm external/envoy/source/extensions/common/wasm/context.cc:1157	wasm log my-wasm-root-id my-wasm-vm-id: [client "192.168.122.1"] Coraza: Access denied (phase 5). Anomaly Scores: (Inbound Scores: blocking=3, detection=3, per_pl=3-0-0-0, threshold=5) - (Outbound Scores: blocking=0, detection=0, per_pl=0-0-0-0, threshold=4) - (SQLI=0, XSS=0, RFI=0, LFI=0, RCE=0,  [file "@owasp_crs/RESPONSE-980-CORRELATION.conf"] [line "12628"] [id "980170"] [rev ""] [msg "Anomaly Scores: (Inbound Scores: blocking=3, detection=3, per_pl=3-0-0-0, threshold=5) - (Outbound Scores: blocking=0, detection=0, per_pl=0-0-0-0, threshold=4) - (SQLI=0, XSS=0, RFI=0, LFI=0, RCE=0, "] [data ""] [severity "emergency"] [ver "OWASP_CRS/4.0.0-rc1"] [maturity "0"] [accuracy "0"] [tag "reporting"] [hostname "10.110.32.70"] [uri "/wp-includes/js/2821272244324623417"] [unique_id "LfBFgSWGArVPGmFUdiw"]

Question 2:

Is the "Access denied" directive in RESPONSE-980-CORRELATION.conf really effective? I see that 2023-06-26T09:00:18 still has a normal access log with 301 status

980 wasm 2023-06-26T09:00:18 log

2023-06-26T09:00:18.558035Z	warning	envoy wasm external/envoy/source/extensions/common/wasm/context.cc:1151	wasm log my-wasm-root-id my-wasm-vm-id: [client "10.110.32.46"] Coraza: Access denied (phase 1). Host header is a numeric IP address [file "@owasp_crs/REQUEST-920-PROTOCOL-ENFORCEMENT.conf"] [line "2243"] [id "920350"] [rev ""] [msg "Host header is a numeric IP address"] [data "10.110.32.70:80"] [severity "warning"] [ver "OWASP_CRS/4.0.0-rc1"] [maturity "0"] [accuracy "0"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-protocol"] [tag "paranoia-level/1"] [tag "OWASP_CRS"] [tag "capec/1000/210/272"] [tag "PCI/6.5.10"] [hostname "10.110.32.70"] [uri "/metrics"] [unique_id "OzWlmsqxDbKJjjaYXrP"]
2023-06-26T09:00:18.593148Z	critical	envoy wasm external/envoy/source/extensions/common/wasm/context.cc:1157	wasm log my-wasm-root-id my-wasm-vm-id: [client "10.110.32.46"] Coraza: Access denied (phase 5). Anomaly Scores: (Inbound Scores: blocking=3, detection=3, per_pl=3-0-0-0, threshold=5) - (Outbound Scores: blocking=0, detection=0, per_pl=0-0-0-0, threshold=4) - (SQLI=0, XSS=0, RFI=0, LFI=0, RCE=0,  [file "@owasp_crs/RESPONSE-980-CORRELATION.conf"] [line "12628"] [id "980170"] [rev ""] [msg "Anomaly Scores: (Inbound Scores: blocking=3, detection=3, per_pl=3-0-0-0, threshold=5) - (Outbound Scores: blocking=0, detection=0, per_pl=0-0-0-0, threshold=4) - (SQLI=0, XSS=0, RFI=0, LFI=0, RCE=0, "] [data ""] [severity "emergency"] [ver "OWASP_CRS/4.0.0-rc1"] [maturity "0"] [accuracy "0"] [tag "reporting"] [hostname "10.110.32.70"] [uri "/metrics"] [unique_id "OzWlmsqxDbKJjjaYXrP"]
2023-06-26T09:00:18.594099Z	warning	envoy wasm external/envoy/source/extensions/common/wasm/context.cc:1151	wasm log my-wasm-root-id my-wasm-vm-id: [client "10.110.32.46"] Coraza: Access denied (phase 1). Host header is a numeric IP address [file "@owasp_crs/REQUEST-920-PROTOCOL-ENFORCEMENT.conf"] [line "2243"] [id "920350"] [rev ""] [msg "Host header is a numeric IP address"] [data "10.110.32.70:30845"] [severity "warning"] [ver "OWASP_CRS/4.0.0-rc1"] [maturity "0"] [accuracy "0"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-protocol"] [tag "paranoia-level/1"] [tag "OWASP_CRS"] [tag "capec/1000/210/272"] [tag "PCI/6.5.10"] [hostname "10.110.32.70"] [uri "/metrics"] [unique_id "KjkRGNlRpxeKJftwrWP"]
2023-06-26T09:00:18.595245Z	critical	envoy wasm external/envoy/source/extensions/common/wasm/context.cc:1157	wasm log my-wasm-root-id my-wasm-vm-id: [client "10.110.32.46"] Coraza: Access denied (phase 5). Anomaly Scores: (Inbound Scores: blocking=3, detection=3, per_pl=3-0-0-0, threshold=5) - (Outbound Scores: blocking=0, detection=0, per_pl=0-0-0-0, threshold=4) - (SQLI=0, XSS=0, RFI=0, LFI=0, RCE=0,  [file "@owasp_crs/RESPONSE-980-CORRELATION.conf"] [line "12628"] [id "980170"] [rev ""] [msg "Anomaly Scores: (Inbound Scores: blocking=3, detection=3, per_pl=3-0-0-0, threshold=5) - (Outbound Scores: blocking=0, detection=0, per_pl=0-0-0-0, threshold=4) - (SQLI=0, XSS=0, RFI=0, LFI=0, RCE=0, "] [data ""] [severity "emergency"] [ver "OWASP_CRS/4.0.0-rc1"] [maturity "0"] [accuracy "0"] [tag "reporting"] [hostname "10.110.32.70"] [uri "/metrics"] [unique_id "KjkRGNlRpxeKJftwrWP"]

pod 2023-06-26T09:00:18 access log

127.0.0.6 - - [26/Jun/2023:09:00:18 +0000] "GET /metrics HTTP/1.1" 301 352 "-" "Prometheus/2.38.0"

@jcchavezs
Copy link
Member

jcchavezs commented Jun 26, 2023 via email

@M4tteoP
Copy link
Member

M4tteoP commented Jun 26, 2023

Hi @ericinfra

Question 1:
Only after triggering the 949 rule, there is Inbound Anomaly Score Exceeded in phase 1 (Total Score: 48)
But when the 980 rule is triggered, the "Total Score" keyword is not seen
Very confused, what is the Anomaly Score that triggers the 980 rule and leads to "Access denied"?

The misleading part is the Access denied prefix. Any Disruptive action will prefix the error log with Access denied. The problem is that the disruptive actions group is broad and includes deny, allow, and pass actions. Thanks for the report, I'm working on a PR on Coraza to have better log messages for each action.

Question 2:
Is the "Access denied" directive in RESPONSE-980-CORRELATION.conf really effective? I see that 2023-06-26T09:00:18 still has a normal access log with 301 status

Is effective in terms of telling you that rule 980170 has been triggered. Being a rule with pass as disruptive action, the enforcement of the action is actually not an "access denied", but rather logging that line.
For more context, phase 5 rules are logging rules, meant to provide aggregated data about the transaction, an interruption will never be triggered at that phase.

An example to clarify 949111 and 980170 logs:
In your example:

[2023-06-26 14:51:28.911367][27][critical][wasm] [source/extensions/common/wasm/context.cc:1184] wasm log coraza-filter my_vm_id: [client "172.18.0.1"] Coraza: Access denied (phase 1). Inbound Anomaly Score Exceeded in phase 1 (Total Score: 13) [file "@owasp_crs/REQUEST-949-BLOCKING-EVALUATION.conf"] [line "11022"] [id "949111"] [rev ""] [msg "Inbound Anomaly Score Exceeded in phase 1 (Total Score: 13)"] [data ""] [severity "emergency"] [ver "OWASP_CRS/4.0.0-rc1"] [maturity "0"] [accuracy "0"] [tag "anomaly-evaluation"] [hostname "172.18.0.4"] [uri "/%3Cscript%3E%3C/script%3E"] [unique_id "gWGJBRQEaYSsJMETKub"]

This line tells you that a blocking action has been enforced, denying the request because of a total score equal to 13.

[2023-06-26 14:51:28.912915][27][critical][wasm] [source/extensions/common/wasm/context.cc:1184] wasm log coraza-filter my_vm_id: [client "172.18.0.1"] Coraza: Access denied (phase 5). Anomaly Scores: (Inbound Scores: blocking=13, detection=13, per_pl=13-0-0-0, threshold=5) - (Outbound Scores: blocking=0, detection=0, per_pl=0-0-0-0, threshold=4) - (SQLI=0, XSS=10, RFI=0, LFI=0, RCE [file "@owasp_crs/RESPONSE-980-CORRELATION.conf"] [line "12877"] [id "980170"] [rev ""] [msg "Anomaly Scores: (Inbound Scores: blocking=13, detection=13, per_pl=13-0-0-0, threshold=5) - (Outbound Scores: blocking=0, detection=0, per_pl=0-0-0-0, threshold=4) - (SQLI=0, XSS=10, RFI=0, LFI=0, RCE"] [data ""] [severity "emergency"] [ver "OWASP_CRS/4.0.0-rc1"] [maturity "0"] [accuracy "0"] [tag "reporting"] [hostname "172.18.0.4"] [uri "/%3Cscript%3E%3C/script%3E"] [unique_id "gWGJBRQEaYSsJMETKub"]

980170 provides you with more details about this score, for example splitting the score across the paranoia levels (13-0-0-0), Inbound and Outbound scores, and between categories of attacks (SQLI,XSS,RFI etc...). Therefore, it is expected to not have the Total Score here.

@M4tteoP
Copy link
Member

M4tteoP commented Jun 26, 2023

The ModSecurity logging is "ModSecurity: Access denied with code 403"
cozara logging is "Coraza: Access denied (phase 1)" and "Coraza: Access denied (phase 5)"

About it, as stated by JC, the old implementation was not properly working and has been removed by corazawaf/coraza#795. What we might evaluate is if it is worth adding a log line connector side printing what the waf module tried to enforce. But I agree with corazawaf/coraza#795 (comment), we should at least clearly state that it is what the waf module tried to enforce, not necessarily the real final status code.

@M4tteoP M4tteoP mentioned this issue Jun 26, 2023
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@jcchavezs jcchavezs

@M4tteoP M4tteoP

Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@jcchavezs @M4tteoP @ericinfra