Include arbitrary data into log

[fardin01]

I'm using coraza-caddy. Great project. ❤️

The incoming requests into Caddy server have a x-request-id header. I want to include the value of this header into the logs somehow. The use case is for us to search for a specific request ID in our log management tool, and be able to see and trace all logs for that request in our reverse proxy log, Coraza log, Caddy log, upstream backend log etc.

I could individually change the msg or logdata action of each rule to include %{REQUEST_HEADERS.X-Request-ID}, but that's not maintainable and scalable. So I'm wondering if this use case was already thought of, or if there is a workaround to make it work, such as adding a tag to all the rules via crs-setup.conf, or appending the msg or logdata actions on the fly, or something of that nature.

[fardin01]

@fzipi @jcchavezs Would you be open to making this configurable? As in, by default, the transaction ID would be a 16 char random string, but making it configurable to something like x-request-id request header or any other identifier that end users wish to use?

[jptosso]

Actually you don't need tags, coraza inherits the request id from caddy, so if you change it to your custom id, coraza will use it too
Just change this to x-request-id

https://caddyserver.com/docs/modules/http.handlers.request_id

Technically this can be implemented as an integration standard, as unlike modsecurity, we support a function to create a transaction with the specified ID. But we would have to implement this across all connectors

[fardin01]

Thank you @jptosso. I'm a little confused as to how http.handlers.request_id module would work. Let me expand.

Here is our reverse proxy (Emissary-Ingress) log:

{"start_time":"2024-07-31T07:33:44.417Z","protocol":"HTTP/2","response_flags":"UAEX","authority":"example.com","path":"/?currentScreen=%3Cscript%3Ealert(%E2%80%9CTEST52%E2%80%9D);%3C%2Fscript%3E","x-request-id":"14cc1230-9e60-4e78-8ed7-840207a1bb26","response_code":"403","method":"GET"}

Here is the Caddy server log:

{"level":"info","ts":1722411224.4229,"logger":"http.log.access","msg":"handled request","request":{"remote_ip":"10.63.4.168","remote_port":"58522","client_ip":"10.63.4.168","proto":"HTTP/1.1","method":"GET","host":"example.com","uri":"/?currentScreen=%3Cscript%3Ealert(%E2%80%9CTEST52%E2%80%9D);%3C%2Fscript%3E","headers":{"X-Forwarded-For":["xxxxx"],"X-Request-Id":["14cc1230-9e60-4e78-8ed7-840207a1bb26"],"X-Forwarded-Proto":["https"],"X-Envoy-Internal":["true"],"X-Envoy-Expected-Rq-Timeout-Ms":["5000"],"Content-Length":["0"],"User-Agent":["Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:128.0) Gecko/20100101 Firefox/128.0"],"Cookie":["REDACTED"]}},"bytes_read":0,"user_id":"","duration":0.00322161,"size":188,"status":403,"resp_headers":{"Server":["Caddy"],"X-Blocked":["true"],"Content-Type":["text/plain; charset=utf-8"]}}

And here is the Coraza log from the rule that blocked the request:

{"level":"error","ts":1722411224.4220889,"logger":"http.handlers.waf","msg":"[client \"10.63.4.168\"] Coraza: Access denied (phase 2). Javascript method detected [file \"/etc/caddy/rules/REQUEST-941-APPLICATION-ATTACK-XSS.conf\"] [line \"8411\"] [id \"941390\"] [rev \"\"] [msg \"Javascript method detected\"] [data \"Matched Data: alert( found within ARGS:currentScreen: <script>alert(“TEST52”);</script>\"] [severity \"critical\"] [ver \"OWASP_CRS/4.6.0-dev\"] [maturity \"0\"] [accuracy \"0\"] [tag \"application-multi\"] [tag \"language-multi\"] [tag \"attack-xss\"] [tag \"xss-perf-disable\"] [tag \"paranoia-level/1\"] [tag \"OWASP_CRS\"] [tag \"capec/1000/152/242\"] [hostname \"\"] [uri \"/?currentScreen=%3Cscript%3Ealert(%E2%80%9CTEST52%E2%80%9D);%3C%2Fscript%3E\"] [unique_id \"xvXkQcxmIEeFIjej\"]\n"}

Emissary-Ingress log and Caddy server log both have the x-request-id request header with 14cc1230-9e60-4e78-8ed7-840207a1bb26 value. How do I include this same value in the Coraza log, so that if a rule is matched, its log message would contain the same x-request-id header value?

[jptosso]

I would be ok with replacing the unique ID from Coraza with {http.request.uuid}. @fzipi @jcchavezs ? That should make it work by default

[jcchavezs]

This is something I brought over the table long ago but I didn't want to go beyond with an actual user request. this is the issue #711 and i would be more than happy to bring this to completion but I have a question: Are we talking about debug logs (aka logs) from coraza or audit logs where matched information is requested? in your example: ``` {"level":"error","ts":1722411224.4220889,"logger":"http.handlers.waf","msg":"[client \"10.63.4.168\"] Coraza: Access denied (phase 2). Javascript method detected [file \"/etc/caddy/rules/REQUEST-941-APPLICATION-ATTACK-XSS.conf\"] [line \"8411\"] [id \"941390\"] [rev \"\"] [msg \"Javascript method detected\"] [data \"Matched Data: alert( found within ARGS:currentScreen: <script>alert(“TEST52”);</script>\"] [severity \"critical\"] [ver \"OWASP_CRS/4.6.0-dev\"] [maturity \"0\"] [accuracy \"0\"] [tag \"application-multi\"] [tag \"language-multi\"] [tag \"attack-xss\"] [tag \"xss-perf-disable\"] [tag \"paranoia-level/1\"] [tag \"OWASP_CRS\"] [tag \"capec/1000/152/242\"] [hostname \"\"] [uri \"/?currentScreen=%3Cscript%3Ealert(%E2%80%9CTEST52%E2%80%9D);%3C%2Fscript%3E\"] [unique_id \"xvXkQcxmIEeFIjej\"]\n"} ``` In coraza http middleware we inject the context from the request into the transaction, see https://github.com/corazawaf/coraza/blob/010509a151e309609a2f7ccd174afe4bc9663a18/http/middleware.go#L125-L132. In caddy we could do the same but also add another setting to add a logContextExtractor or something like that so on every context we extract the http-request-id and inject into the logger.

I would be ok with replacing the unique ID from Coraza with {http.request.uuid}. @fzipi <https://github.com/fzipi> @jcchavezs <https://github.com/jcchavezs> ? That should make it work by default

I don't think this would work as every internal call have the same request-id and hence all transactions created from different services will have the same id.

[fardin01]

Thank you @jcchavezs. We are primarily interested in audit logs where matched information is requested. If we get a Coraza: Access denied ... log, we want to be able to correlate this specific log with our reverse proxy and upstream server logs, using the x-request-id header. The logContextExtractor idea sounds great to me.

[jcchavezs]

Since we aim that log, we don't need to do any change in coraza. Check #1121

[fardin01]

Thank you @jcchavezs. Would you be open to having this change merged in corazawaf/coraza-caddy repo?

[matheustmattioli]

Hi, I'm currently having the same issue in the coraza-proxy-wasm.
Is there a way to include the x-request-id header in coraza logs as an additional tag or field like "unique_id" in each rule? I tried to implement it locally but I couldn't modify the rules metadata with actions in .conf files. Or even through the "Matched Rules" transaction variable in plugin.go file.
For example at the function "OnHttpRequestHeaders" I got the header with ctx.requestID, err = proxywasm.GetHttpRequestHeader("x-request-id") and appended it to logFields: logFields = append(logFields, debuglog.Str("x-request-id", ctx.requestID)).

But it only logged this information in non-rule messages, like:

wasm-logs_1 | [2024-10-25 17:33:37.111701][23][info][wasm] [source/extensions/common/wasm/context.cc:1148] wasm log coraza-filter my_vm_id: Finished tx_id="qMHzlTjlKflKbnatBFn" context_id=2 x-request-id="6160d595-971e-4c23-81b1-e33d2468e17c"

And nothing happened in rule messages, like:

[2024-10-25 17:33:37.111423][23][critical][wasm] [source/extensions/common/wasm/context.cc:1157] wasm log coraza-filter my_vm_id: [client "172.19.0.1"] Coraza: Warning. Anomaly Scores: (Inbound Scores: blocking=20, detection=20, per_pl=20-0-0-0, threshold=5) - (Outbound Scores: blocking=0, detection=0, per_pl=0-0-0-0, threshold=4) - (SQLI=0, XSS=20, RFI=0, LFI=0, RCE [file "@owasp_crs/RESPONSE-980-CORRELATION.conf"] [line "13394"] [id "980170"] [rev ""] [msg "Anomaly Scores: (Inbound Scores: blocking=20, detection=20, per_pl=20-0-0-0, threshold=5) - (Outbound Scores: blocking=0, detection=0, per_pl=0-0-0-0, threshold=4) - (SQLI=0, XSS=20, RFI=0, LFI=0, RCE"] [data ""] [severity "emergency"] [ver "OWASP_CRS/4.3.0"] [maturity "0"] [accuracy "0"] [tag "reporting"] [tag "OWASP_CRS"] [hostname "172.19.0.4"] [uri "/anything?arg=<script>alert(0)</script>"] [unique_id "qMHzlTjlKflKbnatBFn"]

In the same function, I tried to access the rules captured by the transaction (as in the snippet below), but it did not work because I could only get the values, and not set new values (I noticed there are no "set" methods).

matchedRules := tx.MatchedRules()

// log x-request-id in each matched rule
for _, rule := range matchedRules {
   ruleTags := rule.Rule().Tags()
   ruleTags = append(ruleTags, "x-request-id: "+ctx.requestID)
   // rule.Rule().SetTags()?
}

Is there another way to implement this idea in the coraza-proxy-wasm version?