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

fix: update log level handling #141

Merged
merged 19 commits into from
Sep 19, 2024
Merged

fix: update log level handling #141

merged 19 commits into from
Sep 19, 2024

Conversation

catsby
Copy link
Contributor

@catsby catsby commented Sep 18, 2024

Short Description

This PR updates Maru's logging to match the standard library's log/slog package, and appropriately filters log messages according to levels. Tests included and feedback very welcome.

Long Description

The current implementation of log level handling is misleading because our custom handler doesn't filter by level. The code comment mentions logging functions already being aware if they are allowed to be called, but in practice I have not found that to be true. This is further complicated by Maru's log levels not matching what log/slog uses both in values and in ordering.

Example: slog uses these levels/ordering

const (
	LevelDebug Level = -4
	LevelInfo  Level = 0
	LevelWarn  Level = 4
	LevelError Level = 8
)

(See here for source and long explaination to the numbers used: https://pkg.go.dev/log/slog#Level)

Where as Maru uses these levels/ordering:

const (
	// WarnLevel level. Non-critical entries that deserve eyes.
	WarnLevel LogLevel = iota
	// InfoLevel level. General operational entries about what's going on inside the
	// application.
	InfoLevel
	// DebugLevel level. Usually only enabled when debugging. Very verbose logging.
	DebugLevel
	// TraceLevel level. Designates finer-grained informational events than the Debug.
	TraceLevel
)

(source: src/message/logging.go#L16-L29)

In theory, implementing the Handler interface would have us ignore messages with a lower level than the one set. Maru sets it's default log level to InfoLevel (from Maru's constants, not slog's) which results in a value of 1. However because our InfoLevel is 1 and slog's LevelInfo is 0, then in theory Maru's logger should actually ignore it because it's a lower level. A call to message.SLog.Info() (ex. in utils.go) invokes slog's Info() method, which calls an internal method log() with slog's LevelInfo level which is a value of 0. The log() method calls the handlers Enabled() method to see if it should log the message, which for maru always returns true, and then passes it on to the handlers Handle() method (Maru's Handle() method here) and we print the message, even though we shouldn't because it's a lower value than our default.

The net effect is setting the log level with --log-level has no effect, except for when setting to trace, in which case we output pterm debugging information with lines for errors/traces and debug calls. Otherwise Maru will always output all of the logs from Debug(), Info(), Warn() or Error() regardless of the level set.

This PR updates Maru's log level constants both in values and ordering to match the standard library log/slog package, and implements the Enabled() method in the handler to filter correctly based on level. The net effect of this PR should be benign in that we aren't changing any usage details, but going forward we'll correctly output logs according to the set level.

NOTE: This PR is based off of my other PR (#140) for changing the Makefile with regards to test-unit and test-e2e tests.

Test output:

 ➜ go test ./src/message/... -v -count=1
=== RUN   Test_LogLevel_Diff
=== RUN   Test_LogLevel_Diff/DebugLevel
=== RUN   Test_LogLevel_Diff/InfoLevel
=== RUN   Test_LogLevel_Diff/InfoWarnLevel
=== RUN   Test_LogLevel_Diff/WarnInfoLevel
=== RUN   Test_LogLevel_Diff/InfoTraceLevel
=== RUN   Test_LogLevel_Diff/TraceInfoLevel
=== RUN   Test_LogLevel_Diff/TraceLevel
--- PASS: Test_LogLevel_Diff (0.00s)
    --- PASS: Test_LogLevel_Diff/DebugLevel (0.00s)
    --- PASS: Test_LogLevel_Diff/InfoLevel (0.00s)
    --- PASS: Test_LogLevel_Diff/InfoWarnLevel (0.00s)
    --- PASS: Test_LogLevel_Diff/WarnInfoLevel (0.00s)
    --- PASS: Test_LogLevel_Diff/InfoTraceLevel (0.00s)
    --- PASS: Test_LogLevel_Diff/TraceInfoLevel (0.00s)
    --- PASS: Test_LogLevel_Diff/TraceLevel (0.00s)
PASS
ok      github.com/defenseunicorns/maru-runner/src/message      0.235s

Related

Type of change

  • Bug fix (non-breaking change which fixes an issue)
  • New feature (non-breaking change which adds functionality)
  • Other (security config, docs update, etc)

Checklist before merging

@catsby catsby requested a review from a team as a code owner September 18, 2024 16:16
@catsby catsby changed the title fix: Update log level handling fix: update log level handling Sep 18, 2024
src/message/logging.go Outdated Show resolved Hide resolved
src/message/logging.go Outdated Show resolved Hide resolved
src/message/message.go Outdated Show resolved Hide resolved
src/message/slog.go Show resolved Hide resolved
@catsby
Copy link
Contributor Author

catsby commented Sep 19, 2024

@Racer159 thanks again for the review. I applied your feedback and added an ErrorLevel level. I also updated the tests to check for the extra lines of output when using TraceLevel. In hindsight the way I went about checking feels clunky, so if you have ideas on improving it I'm all for it.

catsby and others added 4 commits September 19, 2024 15:20
Signed-off-by: catsby <[email protected]>
* add-e2e-env-var:
  remove code comment
  restore old e2e make step and use 'go list' to filter unit tests
ericwyles
ericwyles previously approved these changes Sep 19, 2024
* main:
  chore: use go-list to filter out e2e tests in test-unit step (#140)
src/message/message.go Show resolved Hide resolved
Signed-off-by: catsby <[email protected]>
* main:
  feat: add templated conditionals to tasks (#139)
@Racer159 Racer159 merged commit 414b787 into main Sep 19, 2024
8 checks passed
@Racer159 Racer159 deleted the update-maru-log-levels branch September 19, 2024 21:21
@catsby catsby mentioned this pull request Sep 24, 2024
21 tasks
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 this pull request may close these issues.

3 participants