Rework Logger API #682

jcchavezs · 2023-03-02T09:16:43Z

This PR follows this PR manojgop#3 and conflates some of the efforts from @manojgop, @ns-sundar and me around reducing allocations in logging in the context of the @intel's research https://owasp.slack.com/archives/C02BXH135AT/p1677616370248079

zerolog is optimized for logging and does not allocate memory unlike fmr.Sprintf() for debug logs Signed-off-by: Manoj Gopalakrishnan <manoj.gopalakrishnan@intel.com>

actions/skipafter.go

codecov · 2023-03-02T09:31:51Z

Codecov Report

Patch coverage: 84.23% and project coverage change: +0.27 🎉

Comparison is base (801a1d6) 80.57% compared to head (2fb63aa) 80.85%.

Additional details and impacted files

@@            Coverage Diff             @@
##           v3/dev     #682      +/-   ##
==========================================
+ Coverage   80.57%   80.85%   +0.27%     
==========================================
  Files         144      146       +2     
  Lines        7763     7986     +223     
==========================================
+ Hits         6255     6457     +202     
- Misses       1278     1303      +25     
+ Partials      230      226       -4

Flag	Coverage Δ
default	`76.91% <83.96%> (+0.39%)`	⬆️
examples	`27.17% <39.94%> (+0.12%)`	⬆️
ftw	`50.47% <28.53%> (-0.96%)`	⬇️
ftw-multiphase	`50.56% <28.53%> (-0.96%)`	⬇️
tinygo	`75.89% <82.06%> (+0.42%)`	⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

Impacted Files	Coverage Δ
actions/expirevar.go	`67.85% <0.00%> (ø)`
actions/setenv.go	`38.88% <0.00%> (-4.87%)`	⬇️
internal/seclang/directives.go	`70.91% <65.00%> (-0.40%)`	⬇️
actions/setvar.go	`58.51% <66.66%> (+1.19%)`	⬆️
actions/ctl.go	`84.12% <68.75%> (+5.88%)`	⬆️
internal/corazawaf/waf.go	`92.66% <70.83%> (-1.38%)`	⬇️
debuglogger/nop.go	`72.72% <72.72%> (ø)`
internal/seclang/parser.go	`92.36% <80.00%> (-0.18%)`	⬇️
internal/corazawaf/rule.go	`76.01% <81.81%> (-0.65%)`	⬇️
internal/corazawaf/transaction.go	`78.54% <82.97%> (-0.05%)`	⬇️
... and 13 more

Help us with your feedback. Take ten seconds to tell us how you rate us. Have a feature suggestion? Share it here.

☔ View full report at Codecov.
📢 Do you have feedback about the report comment? Let us know in this issue.

debuglogger/level.go

debuglogger/default.go

jcchavezs · 2023-03-02T23:08:10Z

actions/ctl.go

@@ -170,12 +199,18 @@ func (a *ctlFn) Evaluate(_ rules.RuleMetadata, txS rules.TransactionState) {
 	case ctlHashEnforcement:
 		// Not supported yet
 	case ctlDebugLogLevel:


This was a good way to try out or API. Turned out to work.

jcchavezs · 2023-03-02T23:09:48Z

types/transaction.go

@@ -186,6 +188,9 @@ type Transaction interface {
 	// MatchedRules returns the rules that have matched the requests with associated information.
 	MatchedRules() []MatchedRule

+	// DebugLogger returns the debug logger for this transaction.
+	DebugLogger() debuglogger.Logger


Adding this allows us to centralize logs in connectors and also be in sync with the changes made through WAF directives (otherwise if we pass a logger and the output or the level is changed inside waf due to immutability we don't keep track of that in the provided log).

debuglogger/logger.go

ns-sundar · 2023-03-03T00:53:53Z

debuglogger/logger.go

+	Uint(key string, i uint) Event
+	// Stringer adds the field key with val.String() (or null if val is nil)
+	// to the Event.
+	Stringer(key string, val fmt.Stringer) Event


It may be useful to have a way to add an entire dictionary. Not saying we should implement it right now, but it may be good to have that in the interface.

I would defer this until the point we need it. Still it will be a breaking change but adding a dict sounds very specific.

I was thinking of ways to log an entire object or some map/slice field within an object, instead of having to do it for each integer, etc. But, I guess, we can instead serialize the object to JSON with Marshall() and then log that JSON string.

So I agree we can drop or punt this.

ns-sundar · 2023-03-03T00:58:15Z

internal/corazawaf/rule.go

-	tx.WAF.Logger.Debug("[%s] [%d] Evaluating rule %d", tx.id, rid, r.ID_)
-	defer tx.WAF.Logger.Debug("[%s] [%d] Finish evaluating rule %d", tx.id, rid, r.ID_)
+	tx.DebugLogger().Debug().Str("tx_id", tx.id).Int("rule_id", rid).Msg("Evaluating rule")
+	defer tx.DebugLogger().Debug().Str("tx_id", tx.id).Int("rule_id", rid).Msg("Finish evaluating rule")


It would be good to check if golang does common sub-expression elimination to evaluate the common parts just once. The docs don't mention it. I suspect this is a hot path, so it may be worth it.

jcchavezs · 2023-03-03T12:05:18Z

PTAL @anuraaga @ns-sundar @manojgop

internal/corazawaf/rule.go

jcchavezs · 2023-03-03T21:54:45Z

@anuraaga @ns-sundar @manojgop you can see the new logger API in action here: corazawaf/coraza-proxy-wasm#160

internal/corazawaf/rule.go

jcchavezs · 2023-03-04T05:04:47Z

Logger is immutable by design, mainly because that allow us to pass logger among layers with enriched context (for example, the logger we create at WAF then is passed down to the transaction with the tx_id, if we do mutate the context then all logs in the transaction will carry a rule ID which is incorrect. I think in this case we can roll back the change and don't create a new logger, just pass the rule_id every time inside the method.

…

On Sat, 4 Mar 2023, 05:49 manojgop, ***@***.***> wrote: ***@***.**** commented on this pull request. ------------------------------ In internal/corazawaf/rule.go <#682 (comment)>: > @@ -174,10 +175,12 @@ func (r *Rule) doEvaluate(phase types.RulePhase, tx *Transaction, cache map[tran rid = r.ParentID_ } + logger := tx.DebugLogger().With(debuglogger.Int("rule_id", rid)) Creating logger instance here is resulting in additional heap allocations and is impacting performance. Can we just update the context with new "rule_id" instead of creating new logger instance — Reply to this email directly, view it on GitHub <#682 (review)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAXOYAVBNAP67LKBYJ6OTWDW2LCUTANCNFSM6AAAAAAVNDNZGI> . You are receiving this because you authored the thread.Message ID: ***@***.***>

manojgop · 2023-03-04T05:09:57Z

Logger is immutable by design, mainly because that allow us to pass logger among layers with enriched context (for example, the logger we create at WAF then is passed down to the transaction with the tx_id, if we do mutate the context then all logs in the transaction will carry a rule ID which is incorrect. I think in this case we can roll back the change and don't create a new logger, just pass the rule_id every time inside the method.
…
On Sat, 4 Mar 2023, 05:49 manojgop, @.> wrote: @.* commented on this pull request. ------------------------------ In internal/corazawaf/rule.go <#682 (comment)>: > @@ -174,10 +175,12 @@ func (r Rule) doEvaluate(phase types.RulePhase, tx Transaction, cache map[tran rid = r.ParentID_ } + logger := tx.DebugLogger().With(debuglogger.Int("rule_id", rid)) Creating logger instance here is resulting in additional heap allocations and is impacting performance. Can we just update the context with new "rule_id" instead of creating new logger instance — Reply to this email directly, view it on GitHub <#682 (review)>, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAXOYAVBNAP67LKBYJ6OTWDW2LCUTANCNFSM6AAAAAAVNDNZGI . You are receiving this because you authored the thread.Message ID: @.*>

In that case , would be better to rollback this change for rule id.

jcchavezs · 2023-03-04T05:25:13Z

@manojgop please do re-check and let me know if you are happy in terms of allocations so I can finally merge this PR.

manojgop · 2023-03-04T05:30:14Z

@manojgop please do re-check and let me know if you are happy in terms of allocations so I can finally merge this PR.

Performance looks good now after rollback. Just FYI - In my system creating the new logger instance resulted in 30% reduction in performance when I ran testing/coreruleset bench mark. I think it might be good to add some perf tests as part of GitHub Action CI, so that it'll be easy to capture performance regression (in a different PR)

manojgop · 2023-03-04T05:34:46Z

@manojgop please do re-check and let me know if you are happy in terms of allocations so I can finally merge this PR.

Performance looks good now after rollback. Just FYI - In my system creating the new logger instance resulted in 30% reduction in performance when I ran testing/coreruleset bench mark. I think it might be good to add some perf tests as part of GitHub Action CI, so that it'll be easy to capture performance regression (in a different PR)

After roll back

Before Rollback (creating new logger instance for every rule id)

jcchavezs · 2023-03-04T06:05:52Z

I think it might be good to add some perf tests as part of GitHub Action

CI, so that it'll be easy to capture performance regression (in a different PR) @manojgop I think we have that but maybe not working properly https://github.com/corazawaf/coraza/blob/v3/dev/.github/workflows/benchmark.yml#L36 Also I think it mixes results among PRs, anyways would you be up to introduce this checks on CI?

…

On Sat, 4 Mar 2023, 06:37 manojgop, ***@***.***> wrote: ***@***.**** approved this pull request. — Reply to this email directly, view it on GitHub <#682 (review)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAXOYAXINKUELQ2LDJORAKLW2LIH3ANCNFSM6AAAAAAVNDNZGI> . You are receiving this because you authored the thread.Message ID: ***@***.***>

ns-sundar · 2023-03-06T06:44:04Z

I know this is merged, but it may be worthwhile to document some additional data points on how far the allocations get reduced with 'zerolog'.

Environment: IceLake VM with 4 vCPUs, 6 GB RAM
Comparison: Commit 801a1d6 (before zerolog) vs. HEAD ad9db60
Five successive runs of CRS

BenchmarkCRSCompilation-4
- Before: 719468, 719516, 719478, 719524, 719529 allocs/op
- After: 718164, 718040, 718107, 718089, 718103 allocs/op
BenchmarkCRSSimpleGET-4
- Before: 29881, 29882, 29887, 29885, 29883 allocs/op
- After: 4891 4894 4893 4894 4892 allocs/op
BenchmarkCRSSimplePOST-4
- Before: 45208 45206 45208 45205 45206 allocs/op
- After: 7807 7813 7811 7810
BenchmarkCRSLargePOST-4
- Before: 45393 45410 45398 45390 45388
- After: 7986 7979 7974 7971

The data shows a consistent large reduction in allocations, thus validating the premise behind moving to zerolog.

jcchavezs · 2023-03-06T08:39:51Z

Thanks for the great summary @ns-sundar

@ns-sundar

* Use zerolog for logging. zerolog is optimized for logging and does not allocate memory unlike fmr.Sprintf() for debug logs Signed-off-by: Manoj Gopalakrishnan <manoj.gopalakrishnan@intel.com> * chore: introduce API changes to ease support of zerolog. * chore: uses interface of logging. * chore: uniformize logger messages. * feat: polish debug logger API. * chore: small nit in nop event. * chore: uniformize log fields. * docs: explains the timestamp skip. * chore: improves nop loggic and also print allocations. * chore: fixes missing log messages. * chore: generic improvements. * tests: improves coverage. * chore: readds log. * tests: improves coverage. * feat: adds logger per transaction to allow 'ctlDebugLogLevel'. * chore: nit printf. * tests: covers 'ctlDebugLogLevel'. * feat: adds Logger.With context fields as per @ns-sundar suggestion. * chore: removes Event.Errs method to narrow down the API surface. * docs: adds more comments on the IsEnabled method. * chore: uses contextful logs for rule. * feat: adds PrinterFactory abstraction to ease the plug of new logs. * chore: refine printer. * chore: rollsback creating a new log per rule evaluation. --------- Signed-off-by: Manoj Gopalakrishnan <manoj.gopalakrishnan@intel.com> Co-authored-by: Manoj Gopalakrishnan <manoj.gopalakrishnan@intel.com>

jcchavezs requested a review from a team as a code owner March 2, 2023 09:16

manojgop and others added 10 commits March 2, 2023 10:23

Use zerolog for logging.

7c64e4e

zerolog is optimized for logging and does not allocate memory unlike fmr.Sprintf() for debug logs Signed-off-by: Manoj Gopalakrishnan <manoj.gopalakrishnan@intel.com>

chore: introduce API changes to ease support of zerolog.

d1d5881

chore: uses interface of logging.

01a776c

chore: uniformize logger messages.

1bdd3c8

feat: polish debug logger API.

fe00e8a

chore: small nit in nop event.

23b9b20

chore: uniformize log fields.

817f028

docs: explains the timestamp skip.

5f09a60

chore: improves nop loggic and also print allocations.

94a96a6

chore: fixes missing log messages.

0f8ae9a

jcchavezs force-pushed the use_zerolog_frictionless branch from 1a585bd to 0f8ae9a Compare March 2, 2023 09:26

jcchavezs commented Mar 2, 2023

View reviewed changes

actions/skipafter.go Show resolved Hide resolved

chore: generic improvements.

904955b

jcchavezs changed the title ~~Use zerolog frictionless~~ Rework Logger API Mar 2, 2023

manojgop reviewed Mar 2, 2023

View reviewed changes

debuglogger/level.go Outdated Show resolved Hide resolved

jcchavezs added 3 commits March 2, 2023 12:59

tests: improves coverage.

0ccdbe2

chore: readds log.

de4bf72

tests: improves coverage.

3b21685

anuraaga reviewed Mar 2, 2023

View reviewed changes

debuglogger/default.go Outdated Show resolved Hide resolved

debuglogger/default.go Outdated Show resolved Hide resolved

debuglogger/default.go Outdated Show resolved Hide resolved

jcchavezs added 3 commits March 2, 2023 23:47

feat: adds logger per transaction to allow 'ctlDebugLogLevel'.

1be5728

chore: nit printf.

1426314

tests: covers 'ctlDebugLogLevel'.

6be37d3

jcchavezs commented Mar 2, 2023

View reviewed changes

ns-sundar reviewed Mar 3, 2023

View reviewed changes

jcchavezs added 3 commits March 3, 2023 12:31

feat: adds Logger.With context fields as per @ns-sundar suggestion.

04af417

chore: removes Event.Errs method to narrow down the API surface.

9fbb612

Merge branch 'v3/dev' into use_zerolog_frictionless

e4d12c2

docs: adds more comments on the IsEnabled method.

0162be8

manojgop reviewed Mar 3, 2023

View reviewed changes

internal/corazawaf/rule.go Show resolved Hide resolved

jcchavezs added 3 commits March 3, 2023 19:41

chore: uses contextful logs for rule.

4aab51b

feat: adds PrinterFactory abstraction to ease the plug of new logs.

3ad819e

chore: refine printer.

62a9224

jcchavezs mentioned this pull request Mar 3, 2023

chore: uses new coraza logger. corazawaf/coraza-proxy-wasm#160

Merged

anuraaga approved these changes Mar 4, 2023

View reviewed changes

manojgop reviewed Mar 4, 2023

View reviewed changes

internal/corazawaf/rule.go Outdated Show resolved Hide resolved

chore: rollsback creating a new log per rule evaluation.

2fb63aa

manojgop approved these changes Mar 4, 2023

View reviewed changes

jcchavezs merged commit b91d392 into corazawaf:v3/dev Mar 4, 2023

M4tteoP mentioned this pull request Mar 6, 2023

fix: default Event in log levels, adds test #691

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Rework Logger API #682

Rework Logger API #682

jcchavezs commented Mar 2, 2023

codecov bot commented Mar 2, 2023 •

edited

Loading

jcchavezs Mar 2, 2023

jcchavezs Mar 2, 2023

ns-sundar Mar 3, 2023

jcchavezs Mar 3, 2023

ns-sundar Mar 3, 2023

ns-sundar Mar 3, 2023

jcchavezs commented Mar 3, 2023

jcchavezs commented Mar 3, 2023

jcchavezs commented Mar 4, 2023 via email

manojgop commented Mar 4, 2023

jcchavezs commented Mar 4, 2023

manojgop commented Mar 4, 2023

manojgop commented Mar 4, 2023

jcchavezs commented Mar 4, 2023 via email

ns-sundar commented Mar 6, 2023

jcchavezs commented Mar 6, 2023

Rework Logger API #682

Rework Logger API #682

Conversation

jcchavezs commented Mar 2, 2023

codecov bot commented Mar 2, 2023 • edited Loading

Codecov Report

jcchavezs Mar 2, 2023

Choose a reason for hiding this comment

jcchavezs Mar 2, 2023

Choose a reason for hiding this comment

ns-sundar Mar 3, 2023

Choose a reason for hiding this comment

jcchavezs Mar 3, 2023

Choose a reason for hiding this comment

ns-sundar Mar 3, 2023

Choose a reason for hiding this comment

ns-sundar Mar 3, 2023

Choose a reason for hiding this comment

jcchavezs commented Mar 3, 2023

jcchavezs commented Mar 3, 2023

jcchavezs commented Mar 4, 2023 via email

manojgop commented Mar 4, 2023

jcchavezs commented Mar 4, 2023

manojgop commented Mar 4, 2023

manojgop commented Mar 4, 2023

jcchavezs commented Mar 4, 2023 via email

ns-sundar commented Mar 6, 2023

jcchavezs commented Mar 6, 2023

codecov bot commented Mar 2, 2023 •

edited

Loading