slogassert

README

slogassert

import "github.com/thejerf/slogassert"

About Slogassert

slogassert implements a testing handler for slog.

All important observable results of code should be tested. While commonly ignored by people writing tests, log messages are often important things to test for, for several reasons:

• Because they are not tested for, it is suprisingly easy for them to break without anyone realizing.
• Log messages can have security impact. Any log messages that may be used to reconstruct a security incident should be tested to ensure they contain the data they are supposed to contain.
• Even when you don't otherwise deeply care about log messages, log messages can often still double as a way of asserting that certain code was actually reached, and the value of variables at the time it was reached is as expected.

While I wouldn't pull in slogassert just for that third point, if the first two are in play for your code base, slog's strong focus on structured attributes means that log messages can also double as testing probe points within your code that may be otherwise unreachable. I don't use this a lot but when you need it it's very useful. (You may find it helpful to create a testing log level even above Debug for this.)

This implements a handler for slog that more-or-less records the incoming messages, then provides a mechanism for testing for the presence and number of log messages at a variety of different detail levels. As log messages are tested for and matched by assertions, they are removed from the record. If an assertion is made and no log messages match, a testing error will be thrown.

Once all the assertions are complete, an assertion should be made that all log messages are accounted for. If there are unaccounted log messages, the test will fail at the end.

Because this is a test logger, some things normally too expensive to be done in normal logging are done, like taking a full stack trace at the location of all log messages that are recorded. This assists in diagnosing where any unasserted log messages are coming from.

See usage in the godoc.

This also includes a null logger, which I am surprised is not in the library itself as I write this since a nil slog.Logger is invalid.

Release Status

slogassert is beta. I consider the package as it nows stands to be a 1.0 release candidate, but it is not yet officially 1.0.

The code is covered as much as possible, however it is not possible to directly test covering the code that calls fatal errors, so that code can not be covered or directly tested.

Version Numbering

This repository will use semantic versioning.

I will be signing this repository with the "jerf" keybase account. If you are viewing this repository through GitHub, you should see the commits as showing as "verified" in the commit view.

(Bear in mind that due to the nature of how git commit signing works, there may be runs of unverified commits; what matters is that the top one is signed.)

Version History

• v0.3.2:
  • A LogValuer being used for an attribute match would fail to match because slogassert wouldn't resolve the value, but try to match the value against the slog.Value. If the LogValuer did something like change types or something, it would never match. Now values that implement LogValuer can be used directly in attribute matches. See the ValueAsString in assertions_test.go if you don't know what I mean.
• v0.3.1:
  • Annotate the internal .Assert* functions as t.Helper()s to improve error messages when an assert fails.
• v0.3.0 more BREAKING CHANGES:
  • Significant API rewrite. This:

    • Exposes Assert directly, for functional-matching based assertions, which enables a lot of more complicated scenarios.

    • Now that the general power is available to end users, the package doesn't need to offer every marginal match method, so I'm removing the built-in message + level assertion. It's easy now to implement yourself if it's useful, and I haven't used it yet in my own code so I question its general utility, sandwiched between the very useful "please assert this message" (useful because it is agnostic about levels) and "please assert this exact match" methods.

    • If you wrap another slog Handler with this, we need to properly pass WithGroup and WithAttrs down to that wrapped handler too.

      I like slog overall but I will say writing a correct Handler wrapper is distinctly nontrivial.

• v0.2.0 BREAKING CHANGE:

  • If test code panics, and a *testing.T.Cleanup function itself has some sort of .Fatal call, the result is that the panic is eaten. Due to Golang issue #49929, there is no way to detect this in the cleanup function because the cleanup function is run in the wrong place to detect the panic and the t.Failed() method will return false.

    Practice has revealed that this is way too confusing, so I'm removing the automatic cleanup function. Therefore, any slogassert.New calls need to have a defer handler.AssertEmpty() manually added to retain the original behavior. The AssertEmpty function has code added to see whether it is in the middle of a panic, and if so, it will not fatally error. (This is in practice good anyhow because panics frequently result in the log messages being logged but the assertions not running, so it frequently produced spurious and confusing messages anyhow.)

    This still mangles the panic a bit, unfortunately, but the necessary data is still there.

  • I was doing a lot of work on my work laptop and had my work email rather than my personal email, but my signing key is my personal email. This commit signs the top of the repository correctly.

    As I mention in the version numbering section, that's what matters; a signed commit at the top of a repository is essentially signing the whole thing, not just that commit. So it is not necessary to rewrite the whole repo to fix all the previous commits.

• v0.1.3:
  • Add a return value to the *Some* methods that return how many messages they consumed as being asserted.
• v0.1.2:

  • Allow use of ints to compare against Int64, Float64, and Uint64.

    This resolves an issue where you write an AssertPrecise and use a bare int in the source code, which the Go compiler decides is an int, and then that didn't match any of the numeric types. This adds the relevant clauses to the matchers.

• v0.1.1:
  • No code changes, just screwed up tagging.
• v0.1.0:

  • Fixed a major error: Somehow I completely overlooked adding the params on a sublogger added with .With to the resulting log messages. I guess I thought slog would do that for me. And this is why v0.0.9 was only a "release candidate".

    That said, I am advancing this up the semver chain to a release candidate.

• v0.0.9:
  • Fix a locking issue in Unasserted, which should make this all completely thread-safe.
  • I consider this a v1.0.0. release candidate.
• v0.0.8:
  • Make Unasserted return a fully independent copy of the LogMessage so the user can't accidentally corrupt it.
• v0.0.7:
  • Add Unasserted call. I've resisted this because it's kind of a trap, but sometimes you just need it.
• v0.0.6:

  • BREAKING RELEASE: The ability to wrap a handler is added. This is useful for things like recording all the logs in a test into a wrapped handler, then if the test fails, printing out the logs as part of the test failure message. This changes the signature on New and NewWithoutCleanup.

    To recover previous behavior, add a nil on the end of all such calls.

• v0.0.5:
  • Add a NullHandler and NullLogger. This is not 100% on point for the package, but pretty useful for when you need a logger but don't need the logs, which comes up in testing a lot.
• v0.0.4:
  • Handlers are responsible for resolving LogValuer values.
    • This is why you don't promise no bugs.
• v0.0.3:
  • Bugs! Bugs everywhere! Fewer now, but still no promises.
• v0.0.2
  • README fixup.
• v0.0.1
  • Initial release.

Documentation

Overview

Package slogassert provides a slog Handler that allows testing that expected logging messages were made in your test code.

Normal Usage

Normal usage looks like this:

func TestSomething(t *testing.T) {
     // This automatically registers a Cleanup function to assert
     // that all log messages are accounted for.
     handler := slogassert.New(t, slog.LevelWarn)
     logger := slog.New(handler)

     // inject the logger into your test code and run it

     // Now start asserting things:
     handler.AssertSomeOf("some log message")

     // often useful to finish up with an assertion that
     // all log messages have been accounted for:
     handler.AssertEmpty()
}

A variety of assertions at varying levels of detail are available on the Handler.

Index

• Constants
• func NullHandler() slog.Handler
• func NullLogger() *slog.Logger
• type Handler
  • func New(t *testing.T, leveler slog.Leveler, wrapped slog.Handler) *Handler
  • func (h *Handler) Assert(f func(LogMessage) bool) int
  • func (h *Handler) AssertEmpty()
  • func (h *Handler) AssertMessage(msg string)
  • func (h *Handler) AssertPrecise(lmm LogMessageMatch)
  • func (h *Handler) AssertSomeMessage(msg string) int
  • func (h *Handler) AssertSomePrecise(lmm LogMessageMatch) int
  • func (h *Handler) Enabled(_ context.Context, level slog.Level) bool
  • func (h *Handler) Fail(msg string, args ...any)
  • func (h *Handler) Handle(ctx context.Context, record slog.Record) error
  • func (h *Handler) Reset()
  • func (h *Handler) Unasserted() []LogMessage
  • func (h *Handler) WithAttrs(attrs []slog.Attr) slog.Handler
  • func (h *Handler) WithGroup(name string) slog.Handler
• type LogMessage
  • func (lm *LogMessage) Print(w io.Writer)
• type LogMessageMatch

Constants

const (
	// LevelDontCare can be used in a LogMessageMatch to indicate
	// that the level does not need to match.
	LevelDontCare = slog.Level(-255000000)
)

Functions

func NullHandler

func NullHandler() slog.Handler

NullHandler returns a slog.Handler that does nothing.

func NullLogger

func NullLogger() *slog.Logger

NullLogger returns a *slog.Logger pointed at a NullHandler.

Types

type Handler

type Handler struct {
	// contains filtered or unexported fields
}

Handler implements the slog.Handler interface, with additional methods for testing.

All methods on this Handler are thread-safe.

func New

func New(t *testing.T, leveler slog.Leveler, wrapped slog.Handler) *Handler

New creates a new testing logger, logging with the given level.

If wrapped is not nil, Handle calls will be passed down to that handler as well.

It is recommended to generally call defer handler.AssertEmpty() on the result of this call.

func (*Handler) Assert

func (h *Handler) Assert(f func(LogMessage) bool) int

Assert takes in a function that takes a recorded log message and indicates whether or not it is "correct" according to your tests, and should be removed from the slice of unasserted log messages. Essentially all other assertions provided are just ways of populating this.

The passed-in function will be presented only with the remaining unasserted log messages at the time of the call.

func (*Handler) AssertEmpty

func (h *Handler) AssertEmpty()

AssertEmpty asserts that all log messages have now been accounted for and there is nothing left.

A call to this method will be automatically deferred through the testing system if you use New(), but you can also use New

func (*Handler) AssertMessage

func (h *Handler) AssertMessage(msg string)

AssertMessage asserts a logging message recorded with the giving logging message.

func (*Handler) AssertPrecise

func (h *Handler) AssertPrecise(lmm LogMessageMatch)

AssertPrecise takes a LogMessageMatch and asserts the first log message that matches it.

func (*Handler) AssertSomeMessage

func (h *Handler) AssertSomeMessage(msg string) int

AssertSomeMessage asserts that some logging events were recorded with the given message. The return value is the number of matched messages if there were any. If there was zero, the test fails.

func (*Handler) AssertSomePrecise

func (h *Handler) AssertSomePrecise(lmm LogMessageMatch) int

AssertSomePrecise asserts all the messages in the log that match the LogMessageMatch criteria. The return value is th enumber of matched messages if there were any. (If there aren't any this fails the test.)

func (*Handler) Enabled

func (h *Handler) Enabled(_ context.Context, level slog.Level) bool

Enabled implements slog.Handler, reporting back to slog whether or not the handler is enabled for this level of log message.

func (*Handler) Fail

func (h *Handler) Fail(msg string, args ...any)

Fail will print out the remaining unasserted messages and pass the given msg and args to t.Fatalf. This can be used in your custom assertions to fail them out.

func (*Handler) Handle

func (h *Handler) Handle(ctx context.Context, record slog.Record) error

Handle implements slog.Handler, recording a log message into the root handler.

func (*Handler) Reset

func (h *Handler) Reset()

Reset will simply empty out the log entirely. This can be used in anger to simply make tests pass, or when you legitimately have some logging messages you don't want to bind your tests to (for instance this package's own call to testing/slogtest).

func (*Handler) Unasserted

func (h *Handler) Unasserted() []LogMessage

Unasserted returns all the log messages that are currently unasserted within the slog assert. The returned result is a deep copy. This method does NOT assert them; after a call to this method, if there are any messages an AssertEmpty will still fail.

It is probably superficially tempting to just use this and examine the result with code. However, bear in mind that using the assertion functions in conjuction with the default AssertEmpty on test cleanup already handles making sure everything is asserted. There's a lot of bugs easy to write with direct code examination.

However, sometimes you just need to check the messages with code.

func (*Handler) WithAttrs

func (h *Handler) WithAttrs(attrs []slog.Attr) slog.Handler

WithAttrs implements slog.Handler, creating a sub-handler with the given hard-coded attributes.

func (*Handler) WithGroup

func (h *Handler) WithGroup(name string) slog.Handler

WithGroup implements slog.Handler, creating a new handler that will group everything into the given group.

type LogMessage

type LogMessage struct {
	Message    string
	Level      slog.Level
	Stacktrace string
	// key is the slash-encoded group path to this value
	Attrs map[string]slog.Value
	// this package deliberately ignores this, but passing
	// testing/slogtest requires us to store this
	Time time.Time
}

LogMessage is a struct for storing the log messages picked up by slogassert's handler.

func (*LogMessage) Print

func (lm *LogMessage) Print(w io.Writer)

Print is a default method that can dump a LogMessage out to a writer; this is used by slogassert to print unasserted log messages.

type LogMessageMatch

type LogMessageMatch struct {
	Message       string
	Level         slog.Level
	Attrs         map[string]any
	AllAttrsMatch bool
}

LogMessageMatch defines a precise message to match.

The Message works as you'd expect; an equality check. It is always checked, so an empty message means to verify that the message logged was empty.

If Level is LevelDontCare, the level won't be matched. Otherwise, it will also be an equality check.

Attrs is a map of string to any. The strings will be the groups for the given attribute, joined together by dots. For instance, an ungrouped key called "url" will be "url". If it is in a "request" group, it will be keyed by "request.url". If that is also in a "webserver" group, the key will be "webserver.request.url". Any dots in the keys themselves will be backslash encoded, so a top-level key called "a.b" will be "a\.b" in this map.

The value is a matcher on the attribute, which may be one of three things.

It can be a function "func (slog.Value) bool", which will be passed the value. If it returns true, it is considered to match; false is considered to be not a match.

It can be a function "func (T) bool", where "T" matches the concrete value behind the Kind of the slog.Value. In that case, the same rules apply. For KindAny, this must be precisely "func(any) bool"; this is done via type switching, not a lot of `reflect` calls, so only and exactly "func (any) bool" will work.

It can be a concrete value, in which case it must be equal to the value contained in the attribute. Type-appropriate equality is used, e.g., time.Time's are compared via time.Equal.

Any other value will result in an error being returned when used to match.

AllAttrsMatch indicate whether the Attrs map must contain matches for all attributes in the match. If true, and there are unmatched attribtues in the log message, the match will fail. If false, extra attributes in the log message won't fail the match.