feat: Audit logs in proxy-wasm logs #263

M4tteoP · 2024-03-25T23:31:03Z

Address #255.
As an initial solution to address the lack of audit logs, this PR proposes, as suggested in #255 (comment), to write audit logs the normal envoy logs.

This PR relies on:

The Coraza branch https://github.com/corazawaf/coraza/tree/json_tinygo in which the Audit Log format options have been built also for tiny go as it seems that also JSON is now supported.
A dedicated audit log writer that prints the formatted auditlogs as proxy-wasm info messages.

Any feedback or better alternative approaches is welcomed.

Examples:

	"SecAuditEngine On",
	"SecAuditLogType wasmSerial",
	"SecAuditLogFormat JSON",
	"Include @owasp_crs/*.conf",

▶ curl -I 'localhost:8080/get?<script>alert</script>'

envoy-logs-1  | [2024-03-25 22:25:21.566289][40][info][wasm] [source/extensions/common/wasm/context.cc:1148] wasm log coraza-filter my_vm_id: {"transaction":{"timestamp":"2024/03/25 22:25:21","unix_timestamp":1711405521529601000,"id":"XvJJqLMKctidFfNPzFn","client_ip":"192.168.65.1","client_port":19332,"host_ip":"172.19.0.2","host_port":8080,"server_id":"localhost","request":{"method":"HEAD","protocol":"HTTP/1.1","uri":"/get?\u003cscript\u003ealert\u003c/script\u003e","http_version":"","headers":{":authority":["localhost:8080"],":method":["HEAD"],":path":["/get?\u003cscript\u003ealert\u003c/script\u003e"],":scheme":["http"],"accept":["*/*"],"host":["localhost:8080"],"user-agent":["curl/8.4.0"],"x-forwarded-proto":["http"],"x-request-id":["45002c61-c2f3-4cea-bf4e-f565e3e01638"]},"body":"","files":null},"response":{"protocol":"","status":0,"headers":{},"body":""},"producer":{"connector":"","version":"","server":"","rule_engine":"On","stopwatch":"1711405521529601000 36411000; combined=34752000, p1=34231000, p2=0, p3=0, p4=0, p5=521000","rulesets":["OWASP_CRS/4.0.0-rc2"]}}}

	"SecAuditEngine On",
	"SecAuditLogType wasmSerial",
	"SecAuditLogFormat Native",
	"Include @owasp_crs/*.conf",

▶ curl -I 'localhost:8080/get?<script>alert</script>'

envoy-logs-1  | [2024-03-25 22:36:04.613069][37][debug][wasm] [source/extensions/common/wasm/context.cc:1145] wasm log coraza-filter my_vm_id: Transaction marked for audit logging tx_id="nWttyyYWjlmazTVNjHX"
envoy-logs-1  | [2024-03-25 22:36:04.613225][37][info][wasm] [source/extensions/common/wasm/context.cc:1148] wasm log coraza-filter my_vm_id: --UTQkQHkZIS-B--
envoy-logs-1  | [2024/03/25 22:36:04] nWttyyYWjlmazTVNjHX 192.168.65.1 21341 172.19.0.6 8080
log coraza-filter my_vm_id: Finished phase tx_id="nWttyyYWjlmazTVNjHX" phase=5
envoy-logs-1  | HEAD /get?<script>alert</script> HTTP/1.1
envoy-logs-1  | :method: HEAD
envoy-logs-1  | :scheme: http
envoy-logs-1  | user-agent: curl/8.4.0
envoy-logs-1  | x-request-id: b45b2564-7066-4924-9e58-651b2f5c90e2
envoy-logs-1  | host: localhost:8080
envoy-logs-1  | :authority: localhost:8080
envoy-logs-1  | :path: /get?<script>alert</script>
envoy-logs-1  | accept: */*
envoy-logs-1  | x-forwarded-proto: http
envoy-logs-1  | --UTQkQHkZIS-I--
envoy-logs-1  | [2024/03/25 22:36:04] nWttyyYWjlmazTVNjHX 192.168.65.1 21341 172.19.0.6 8080
envoy-logs-1  | --UTQkQHkZIS-J--
envoy-logs-1  | [2024/03/25 22:36:04] nWttyyYWjlmazTVNjHX 192.168.65.1 21341 172.19.0.6 8080
envoy-logs-1  | --UTQkQHkZIS-D--
envoy-logs-1  | [2024/03/25 22:36:04] nWttyyYWjlmazTVNjHX 192.168.65.1 21341 172.19.0.6 8080
envoy-logs-1  | --UTQkQHkZIS-E--
envoy-logs-1  | [2024/03/25 22:36:04] nWttyyYWjlmazTVNjHX 192.168.65.1 21341 172.19.0.6 8080
envoy-logs-1  | --UTQkQHkZIS-F--
envoy-logs-1  | [2024/03/25 22:36:04] nWttyyYWjlmazTVNjHX 192.168.65.1 21341 172.19.0.6 8080
envoy-logs-1  | --UTQkQHkZIS-H--
envoy-logs-1  | [2024/03/25 22:36:04] nWttyyYWjlmazTVNjHX 192.168.65.1 21341 172.19.0.6 8080
envoy-logs-1  | Stopwatch:
envoy-logs-1  | Response-Body-Transformed:
envoy-logs-1  | Producer:
envoy-logs-1  | Server:
envoy-logs-1  |
envoy-logs-1  | [2024-03-25 22:36:04.613251][37][debug][wasm] [source/extensions/common/wasm/context.cc:1145] wasm log coraza-filter my_vm_id: Transaction finished tx_id="nWttyyYWjlmazTVNjHX" is_interrupted=true status=0 rule_id=949111```

M4tteoP · 2024-03-26T13:47:24Z

internal/auditlog/serial_writer.go

+		return nil
+	}
+
+	proxywasm.LogInfo(string(bts))


I'm wondering if it could be handy to provide some fixed text like AuditLog: to simplify a bit the parsing

It would be helpful to display how the log would look like in envoy to decide.

Default Serial:

[2024-03-31 10:47:41.011720][33][critical][wasm] [source/extensions/common/wasm/context.cc:1180] wasm log coraza-filter my_vm_id: [client "192.168.65.1"] Coraza: Warning. NoScript XSS InjectionChecker: HTML Injection [file "@owasp_crs/REQUEST-941-APPLICATION-ATTACK-XSS.conf"] [line "7786"] [id "941160"] [rev ""] [msg "NoScript XSS InjectionChecker: HTML Injection"] [data "Matched Data: <script found within ARGS_GET_NAMES:<script>alert</script>: <script>alert</script>"] [severity "critical"] [ver "OWASP_CRS/4.0.0-rc2"] [maturity "0"] [accuracy "0"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-xss"] [tag "paranoia-level/1"] [tag "OWASP_CRS"] [tag "capec/1000/152/242"] [hostname "172.19.0.6"] [uri "/get?<script>alert</script>"] [unique_id "REOYcbXFlHezRahgOnj"] [2024-03-31 10:47:41.013784][33][critical][wasm] [source/extensions/common/wasm/context.cc:1180] wasm log coraza-filter my_vm_id: [client "192.168.65.1"] Coraza: Access denied (phase 1). Inbound Anomaly Score Exceeded in phase 1 (Total Score: 15) [file "@owasp_crs/REQUEST-949-BLOCKING-EVALUATION.conf"] [line "11355"] [id "949111"] [rev ""] [msg "Inbound Anomaly Score Exceeded in phase 1 (Total Score: 15)"] [data ""] [severity "emergency"] [ver "OWASP_CRS/4.0.0-rc2"] [maturity "0"] [accuracy "0"] [tag "anomaly-evaluation"] [hostname "172.19.0.6"] [uri "/get?<script>alert</script>"] [unique_id "REOYcbXFlHezRahgOnj"] [2024-03-31 10:47:41.014007][33][info][wasm] [source/extensions/common/wasm/context.cc:1171] wasm log coraza-filter my_vm_id: Transaction interrupted tx_id="REOYcbXFlHezRahgOnj" context_id=2 action="deny" phase="http_request_headers" envoy-logs-1 | [2024-03-31 10:47:41.015074][33][critical][wasm] [source/extensions/common/wasm/context.cc:1180] wasm log coraza-filter my_vm_id: [client "192.168.65.1"] Coraza: Warning. Anomaly Scores: (Inbound Scores: blocking=15, detection=15, per_pl=15-0-0-0, threshold=5) - (Outbound Scores: blocking=0, detection=0, per_pl=0-0-0-0, threshold=4) - (SQLI=0, XSS=15, RFI=0, LFI=0, RCE [file "@owasp_crs/RESPONSE-980-CORRELATION.conf"] [line "13216"] [id "980170"] [rev ""] [msg "Anomaly Scores: (Inbound Scores: blocking=15, detection=15, per_pl=15-0-0-0, threshold=5) - (Outbound Scores: blocking=0, detection=0, per_pl=0-0-0-0, threshold=4) - (SQLI=0, XSS=15, RFI=0, LFI=0, RCE"] [data ""] [severity "emergency"] [ver "OWASP_CRS/4.0.0-rc2"] [maturity "0"] [accuracy "0"] [tag "reporting"] [hostname "172.19.0.6"] [uri "/get?<script>alert</script>"] [unique_id "REOYcbXFlHezRahgOnj"] [2024-03-31 10:47:41.016142][33][info][wasm] [source/extensions/common/wasm/context.cc:1171] wasm log coraza-filter my_vm_id: {"transaction":{"timestamp":"2024/03/31 10:47:40","unix_timestamp":1711882060997357000,"id":"REOYcbXFlHezRahgOnj","client_ip":"192.168.65.1","client_port":43721,"host_ip":"172.19.0.6","host_port":8080,"server_id":"localhost","request":{"method":"GET","protocol":"HTTP/1.1","uri":"/get?\u003cscript\u003ealert\u003c/script\u003e","http_version":"","headers":{":authority":["localhost:8080"],":method":["GET"],":path":["/get?\u003cscript\u003ealert\u003c/script\u003e"],":scheme":["http"],"accept":["*/*"],"host":["localhost:8080"],"user-agent":["curl/8.4.0"],"x-forwarded-proto":["http"],"x-request-id":["29a178e3-5e3b-4a15-a248-8dfed12ac9f8"]},"body":"","files":null},"response":{"protocol":"","status":0,"headers":{},"body":""},"producer":{"connector":"","version":"","server":"","rule_engine":"On","stopwatch":"1711882060997357000 18026000; combined=15767000, p1=15447000, p2=0, p3=0, p4=0, p5=320000","rulesets":["OWASP_CRS/4.0.0-rc2"]}}} [2024-03-31 10:47:41.016226][33][info][wasm] [source/extensions/common/wasm/context.cc:1171] wasm log coraza-filter my_vm_id: Finished tx_id="REOYcbXFlHezRahgOnj" context_id=2

Added fixed text AuditLog::

[2024-03-31 10:54:40.983460][33][critical][wasm] [source/extensions/common/wasm/context.cc:1180] wasm log coraza-filter my_vm_id: [client "192.168.65.1"] Coraza: Warning. NoScript XSS InjectionChecker: HTML Injection [file "@owasp_crs/REQUEST-941-APPLICATION-ATTACK-XSS.conf"] [line "7786"] [id "941160"] [rev ""] [msg "NoScript XSS InjectionChecker: HTML Injection"] [data "Matched Data: <script found within ARGS_GET_NAMES:<script>alert</script>: <script>alert</script>"] [severity "critical"] [ver "OWASP_CRS/4.0.0-rc2"] [maturity "0"] [accuracy "0"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-xss"] [tag "paranoia-level/1"] [tag "OWASP_CRS"] [tag "capec/1000/152/242"] [hostname "172.19.0.2"] [uri "/get?<script>alert</script>"] [unique_id "ueEFsylJqTpZRrfXIIv"] [2024-03-31 10:54:40.985984][33][critical][wasm] [source/extensions/common/wasm/context.cc:1180] wasm log coraza-filter my_vm_id: [client "192.168.65.1"] Coraza: Access denied (phase 1). Inbound Anomaly Score Exceeded in phase 1 (Total Score: 15) [file "@owasp_crs/REQUEST-949-BLOCKING-EVALUATION.conf"] [line "11355"] [id "949111"] [rev ""] [msg "Inbound Anomaly Score Exceeded in phase 1 (Total Score: 15)"] [data ""] [severity "emergency"] [ver "OWASP_CRS/4.0.0-rc2"] [maturity "0"] [accuracy "0"] [tag "anomaly-evaluation"] [hostname "172.19.0.2"] [uri "/get?<script>alert</script>"] [unique_id "ueEFsylJqTpZRrfXIIv"] [2024-03-31 10:54:40.987554][33][critical][wasm] [source/extensions/common/wasm/context.cc:1180] wasm log coraza-filter my_vm_id: [client "192.168.65.1"] Coraza: Warning. Anomaly Scores: (Inbound Scores: blocking=15, detection=15, per_pl=15-0-0-0, threshold=5) - (Outbound Scores: blocking=0, detection=0, per_pl=0-0-0-0, threshold=4) - (SQLI=0, XSS=15, RFI=0, LFI=0, RCE [file "@owasp_crs/RESPONSE-980-CORRELATION.conf"] [line "13216"] [id "980170"] [rev ""] [msg "Anomaly Scores: (Inbound Scores: blocking=15, detection=15, per_pl=15-0-0-0, threshold=5) - (Outbound Scores: blocking=0, detection=0, per_pl=0-0-0-0, threshold=4) - (SQLI=0, XSS=15, RFI=0, LFI=0, RCE"] [data ""] [severity "emergency"] [ver "OWASP_CRS/4.0.0-rc2"] [maturity "0"] [accuracy "0"] [tag "reporting"] [hostname "172.19.0.2"] [uri "/get?<script>alert</script>"] [unique_id "ueEFsylJqTpZRrfXIIv"] [2024-03-31 10:54:40.988729][33][info][wasm] [source/extensions/common/wasm/context.cc:1171] wasm log coraza-filter my_vm_id: AuditLog:{"transaction":{"timestamp":"2024/03/31 10:54:40","unix_timestamp":1711882480966736000,"id":"ueEFsylJqTpZRrfXIIv","client_ip":"192.168.65.1","client_port":45409,"host_ip":"172.19.0.2","host_port":8080,"server_id":"localhost","request":{"method":"GET","protocol":"HTTP/1.1","uri":"/get?\u003cscript\u003ealert\u003c/script\u003e","http_version":"","headers":{":authority":["localhost:8080"],":method":["GET"],":path":["/get?\u003cscript\u003ealert\u003c/script\u003e"],":scheme":["http"],"accept":["*/*"],"host":["localhost:8080"],"user-agent":["curl/8.4.0"],"x-forwarded-proto":["http"],"x-request-id":["11ea3884-a427-4257-a937-fabc095891cf"]},"body":"","files":null},"response":{"protocol":"","status":0,"headers":{},"body":""},"producer":{"connector":"","version":"","server":"","rule_engine":"On","stopwatch":"1711882480966736000 21063000; combined=18371000, p1=17957000, p2=0, p3=0, p4=0, p5=414000","rulesets":["OWASP_CRS/4.0.0-rc2"]}}} [2024-03-31 10:54:40.988833][33][info][wasm] [source/extensions/common/wasm/context.cc:1171] wasm log coraza-filter my_vm_id: Finished tx_id="ueEFsylJqTpZRrfXIIv" context_id=2

While it could still be okay to look for a line with {"transaction":{"timestamp" to extract all the audit logs, I think that for a new user that takes a look at the logs, marking explicitly the lines could ease the understanding

internal/auditlog/serial_writer.go

jcchavezs · 2024-03-26T23:04:45Z

Maybe we want to set the formatter to json? cc @anuraaga

M4tteoP · 2024-03-26T23:07:32Z

Maybe we want to set the formatter to json

I agree, while the native formatter is "working", the output emitted in multiple lines logs looks far from being easily usable unless for a very controlled debugging

jcchavezs · 2024-03-26T23:10:56Z

Maybe we can override the json formatter for this repo but does not have to happen in this PR but specifically with envoy, I think it makes sense to have the logs in json.

…

On Wed, 27 Mar 2024, 00:07 Matteo Pace, ***@***.***> wrote: Maybe we want to set the formatter to json I agree, while the native formatter is "working", the output emitted in multiple lines logs looks far from being easily usable unless for a very controlled debugging — Reply to this email directly, view it on GitHub <#263 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAXOYASTLF7Y7N7NUFNDDMDY2HWTTAVCNFSM6AAAAABFH433J2VHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDAMRRGYYTMMJTHE> . You are receiving this because your review was requested.Message ID: ***@***.***>

anuraaga · 2024-03-27T00:23:36Z

internal/auditlog/serial_writer.go

+// See https://github.com/corazawaf/coraza/blob/main/internal/auditlog/init_tinygo.go
+// This function registers a new audit log writer for Wasm named "wasmserial" that prints
+// audit logs to the proxy-wasm log as info messages.
+func RegisterWasmSerialWriter() {


Just wondering, what's the difference in the output if not using the custom writer, i.e. using stdout or err instead of proxywasm.LogInfo? I thought the latter might pack everything onto a single line but it seems it doesn't, so don't know if there's a big difference.

Thanks Rag, it is actually working fine, I added to the Coraza PR the registration of the Serial writer also for the tinygo build: corazawaf/coraza#1027 (comment)
I see value in overriding it only if we wish to add some prefixes, or something to the line to highlight that it is an audit log (already considering that we are mixing all the logs into the normal envoy logs as a start.

Sounds good, I think a prefix makes sense

internal/auditlog/serial_writer.go

anuraaga · 2024-04-01T03:54:53Z

internal/auditlog/serial_writer.go

+// See https://github.com/corazawaf/coraza/blob/main/internal/auditlog/init_tinygo.go
+// This function registers a new audit log writer for Wasm named "wasmserial" that prints
+// audit logs to the proxy-wasm log as info messages.
+func RegisterWasmSerialWriter() {


Sounds good, I think a prefix makes sense

go.sum

internal/auditlog/serial_writer.go

jcchavezs · 2024-04-11T10:29:52Z

Could you please rebase this PR @M4tteoP ?

M4tteoP · 2024-06-14T08:35:57Z

To be resolved before Merging: point to Coraza v3.2 version that comes with corazawaf/coraza#1027

jcchavezs · 2024-06-20T07:56:24Z

Can we merge this @M4tteoP ?

M4tteoP requested review from anuraaga and jcchavezs as code owners March 25, 2024 23:31

M4tteoP marked this pull request as draft March 25, 2024 23:47

M4tteoP mentioned this pull request Mar 25, 2024

feat: registers RegisterFormatters for tinygo corazawaf/coraza#1027

Merged

M4tteoP marked this pull request as ready for review March 26, 2024 13:27

M4tteoP commented Mar 26, 2024

View reviewed changes

jcchavezs reviewed Mar 26, 2024

View reviewed changes

internal/auditlog/serial_writer.go Outdated Show resolved Hide resolved

anuraaga reviewed Mar 27, 2024

View reviewed changes

M4tteoP commented Mar 28, 2024

View reviewed changes

internal/auditlog/serial_writer.go Outdated Show resolved Hide resolved

anuraaga approved these changes Apr 1, 2024

View reviewed changes

M4tteoP commented Apr 1, 2024

View reviewed changes

go.sum Outdated Show resolved Hide resolved

jcchavezs reviewed Apr 2, 2024

View reviewed changes

internal/auditlog/serial_writer.go Outdated Show resolved Hide resolved

M4tteoP force-pushed the wasm_auditlogs_cpw branch from 708dcae to 472adcd Compare April 11, 2024 10:32

jcchavezs approved these changes Jun 14, 2024

View reviewed changes

jcchavezs mentioned this pull request Jun 14, 2024

New metric "Matched Rules" #271

Open

This was referenced Jun 20, 2024

update to CRS v4.3.0 #276

Merged

Updates to Coraza v3.2.1 and several dependencies #282

Merged

M4tteoP added 7 commits July 8, 2024 11:46

implements auditlogs as info logs

0667cef

TINYGO_VERSION and recommended/demo

a385e97

adds serial_writer_go

a620f32

fix test registering serial writer

42923fd

JSON added to recommended, SecAuditLog for default Serial writer

9cb6fd0

enforces prefix, comments in recommended confs

ec56bc5

nit: naming

cf8f47b

M4tteoP force-pushed the wasm_auditlogs_cpw branch from 472adcd to cf8f47b Compare July 8, 2024 09:47

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat: Audit logs in proxy-wasm logs #263

feat: Audit logs in proxy-wasm logs #263

M4tteoP commented Mar 25, 2024 •

edited

Loading

M4tteoP Mar 26, 2024

jcchavezs Mar 30, 2024

M4tteoP Mar 31, 2024

jcchavezs commented Mar 26, 2024

M4tteoP commented Mar 26, 2024

jcchavezs commented Mar 26, 2024 via email

anuraaga Mar 27, 2024

M4tteoP Mar 28, 2024

anuraaga Apr 1, 2024

anuraaga Apr 1, 2024

jcchavezs commented Apr 11, 2024

M4tteoP commented Jun 14, 2024

jcchavezs commented Jun 20, 2024

feat: Audit logs in proxy-wasm logs #263

Are you sure you want to change the base?

feat: Audit logs in proxy-wasm logs #263

Conversation

M4tteoP commented Mar 25, 2024 • edited Loading

M4tteoP Mar 26, 2024

Choose a reason for hiding this comment

jcchavezs Mar 30, 2024

Choose a reason for hiding this comment

M4tteoP Mar 31, 2024

Choose a reason for hiding this comment

jcchavezs commented Mar 26, 2024

M4tteoP commented Mar 26, 2024

jcchavezs commented Mar 26, 2024 via email

anuraaga Mar 27, 2024

Choose a reason for hiding this comment

M4tteoP Mar 28, 2024

Choose a reason for hiding this comment

anuraaga Apr 1, 2024

Choose a reason for hiding this comment

anuraaga Apr 1, 2024

Choose a reason for hiding this comment

jcchavezs commented Apr 11, 2024

M4tteoP commented Jun 14, 2024

jcchavezs commented Jun 20, 2024

M4tteoP commented Mar 25, 2024 •

edited

Loading