fix: update log level handling #141

catsby · 2024-09-18T16:16:57Z

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