slogtest.go

     1  // Copyright 2023 The Go Authors. All rights reserved.
     2  // Use of this source code is governed by a BSD-style
     3  // license that can be found in the LICENSE file.
     4  
     5  // Package slogtest implements support for testing implementations of log/slog.Handler.
     6  package slogtest
     7  
     8  import (
     9  	"context"
    10  	"errors"
    11  	"fmt"
    12  	"log/slog"
    13  	"reflect"
    14  	"runtime"
    15  	"testing"
    16  	"time"
    17  )
    18  
    19  type testCase struct {
    20  	// Subtest name.
    21  	name string
    22  	// If non-empty, explanation explains the violated constraint.
    23  	explanation string
    24  	// f executes a single log event using its argument logger.
    25  	// So that mkdescs.sh can generate the right description,
    26  	// the body of f must appear on a single line whose first
    27  	// non-whitespace characters are "l.".
    28  	f func(*slog.Logger)
    29  	// If mod is not nil, it is called to modify the Record
    30  	// generated by the Logger before it is passed to the Handler.
    31  	mod func(*slog.Record)
    32  	// checks is a list of checks to run on the result.
    33  	checks []check
    34  }
    35  
    36  var cases = []testCase{
    37  	{
    38  		name:        "built-ins",
    39  		explanation: withSource("this test expects slog.TimeKey, slog.LevelKey and slog.MessageKey"),
    40  		f: func(l *slog.Logger) {
    41  			l.Info("message")
    42  		},
    43  		checks: []check{
    44  			hasKey(slog.TimeKey),
    45  			hasKey(slog.LevelKey),
    46  			hasAttr(slog.MessageKey, "message"),
    47  		},
    48  	},
    49  	{
    50  		name:        "attrs",
    51  		explanation: withSource("a Handler should output attributes passed to the logging function"),
    52  		f: func(l *slog.Logger) {
    53  			l.Info("message", "k", "v")
    54  		},
    55  		checks: []check{
    56  			hasAttr("k", "v"),
    57  		},
    58  	},
    59  	{
    60  		name:        "empty-attr",
    61  		explanation: withSource("a Handler should ignore an empty Attr"),
    62  		f: func(l *slog.Logger) {
    63  			l.Info("msg", "a", "b", "", nil, "c", "d")
    64  		},
    65  		checks: []check{
    66  			hasAttr("a", "b"),
    67  			missingKey(""),
    68  			hasAttr("c", "d"),
    69  		},
    70  	},
    71  	{
    72  		name:        "zero-time",
    73  		explanation: withSource("a Handler should ignore a zero Record.Time"),
    74  		f: func(l *slog.Logger) {
    75  			l.Info("msg", "k", "v")
    76  		},
    77  		mod: func(r *slog.Record) { r.Time = time.Time{} },
    78  		checks: []check{
    79  			missingKey(slog.TimeKey),
    80  		},
    81  	},
    82  	{
    83  		name:        "WithAttrs",
    84  		explanation: withSource("a Handler should include the attributes from the WithAttrs method"),
    85  		f: func(l *slog.Logger) {
    86  			l.With("a", "b").Info("msg", "k", "v")
    87  		},
    88  		checks: []check{
    89  			hasAttr("a", "b"),
    90  			hasAttr("k", "v"),
    91  		},
    92  	},
    93  	{
    94  		name:        "groups",
    95  		explanation: withSource("a Handler should handle Group attributes"),
    96  		f: func(l *slog.Logger) {
    97  			l.Info("msg", "a", "b", slog.Group("G", slog.String("c", "d")), "e", "f")
    98  		},
    99  		checks: []check{
   100  			hasAttr("a", "b"),
   101  			inGroup("G", hasAttr("c", "d")),
   102  			hasAttr("e", "f"),
   103  		},
   104  	},
   105  	{
   106  		name:        "empty-group",
   107  		explanation: withSource("a Handler should ignore an empty group"),
   108  		f: func(l *slog.Logger) {
   109  			l.Info("msg", "a", "b", slog.Group("G"), "e", "f")
   110  		},
   111  		checks: []check{
   112  			hasAttr("a", "b"),
   113  			missingKey("G"),
   114  			hasAttr("e", "f"),
   115  		},
   116  	},
   117  	{
   118  		name:        "inline-group",
   119  		explanation: withSource("a Handler should inline the Attrs of a group with an empty key"),
   120  		f: func(l *slog.Logger) {
   121  			l.Info("msg", "a", "b", slog.Group("", slog.String("c", "d")), "e", "f")
   122  
   123  		},
   124  		checks: []check{
   125  			hasAttr("a", "b"),
   126  			hasAttr("c", "d"),
   127  			hasAttr("e", "f"),
   128  		},
   129  	},
   130  	{
   131  		name:        "WithGroup",
   132  		explanation: withSource("a Handler should handle the WithGroup method"),
   133  		f: func(l *slog.Logger) {
   134  			l.WithGroup("G").Info("msg", "a", "b")
   135  		},
   136  		checks: []check{
   137  			hasKey(slog.TimeKey),
   138  			hasKey(slog.LevelKey),
   139  			hasAttr(slog.MessageKey, "msg"),
   140  			missingKey("a"),
   141  			inGroup("G", hasAttr("a", "b")),
   142  		},
   143  	},
   144  	{
   145  		name:        "multi-With",
   146  		explanation: withSource("a Handler should handle multiple WithGroup and WithAttr calls"),
   147  		f: func(l *slog.Logger) {
   148  			l.With("a", "b").WithGroup("G").With("c", "d").WithGroup("H").Info("msg", "e", "f")
   149  		},
   150  		checks: []check{
   151  			hasKey(slog.TimeKey),
   152  			hasKey(slog.LevelKey),
   153  			hasAttr(slog.MessageKey, "msg"),
   154  			hasAttr("a", "b"),
   155  			inGroup("G", hasAttr("c", "d")),
   156  			inGroup("G", inGroup("H", hasAttr("e", "f"))),
   157  		},
   158  	},
   159  	{
   160  		name:        "empty-group-record",
   161  		explanation: withSource("a Handler should not output groups if there are no attributes"),
   162  		f: func(l *slog.Logger) {
   163  			l.With("a", "b").WithGroup("G").With("c", "d").WithGroup("H").Info("msg")
   164  		},
   165  		checks: []check{
   166  			hasKey(slog.TimeKey),
   167  			hasKey(slog.LevelKey),
   168  			hasAttr(slog.MessageKey, "msg"),
   169  			hasAttr("a", "b"),
   170  			inGroup("G", hasAttr("c", "d")),
   171  			inGroup("G", missingKey("H")),
   172  		},
   173  	},
   174  	{
   175  		name:        "nested-empty-group-record",
   176  		explanation: withSource("a Handler should not output nested groups if there are no attributes"),
   177  		f: func(l *slog.Logger) {
   178  			l.With("a", "b").WithGroup("G").With("c", "d").WithGroup("H").WithGroup("I").Info("msg")
   179  		},
   180  		checks: []check{
   181  			hasKey(slog.TimeKey),
   182  			hasKey(slog.LevelKey),
   183  			hasAttr(slog.MessageKey, "msg"),
   184  			hasAttr("a", "b"),
   185  			inGroup("G", hasAttr("c", "d")),
   186  			inGroup("G", missingKey("H")),
   187  			inGroup("G", missingKey("I")),
   188  		},
   189  	},
   190  	{
   191  		name:        "resolve",
   192  		explanation: withSource("a Handler should call Resolve on attribute values"),
   193  		f: func(l *slog.Logger) {
   194  			l.Info("msg", "k", &replace{"replaced"})
   195  		},
   196  		checks: []check{hasAttr("k", "replaced")},
   197  	},
   198  	{
   199  		name:        "resolve-groups",
   200  		explanation: withSource("a Handler should call Resolve on attribute values in groups"),
   201  		f: func(l *slog.Logger) {
   202  			l.Info("msg",
   203  				slog.Group("G",
   204  					slog.String("a", "v1"),
   205  					slog.Any("b", &replace{"v2"})))
   206  		},
   207  		checks: []check{
   208  			inGroup("G", hasAttr("a", "v1")),
   209  			inGroup("G", hasAttr("b", "v2")),
   210  		},
   211  	},
   212  	{
   213  		name:        "resolve-WithAttrs",
   214  		explanation: withSource("a Handler should call Resolve on attribute values from WithAttrs"),
   215  		f: func(l *slog.Logger) {
   216  			l = l.With("k", &replace{"replaced"})
   217  			l.Info("msg")
   218  		},
   219  		checks: []check{hasAttr("k", "replaced")},
   220  	},
   221  	{
   222  		name:        "resolve-WithAttrs-groups",
   223  		explanation: withSource("a Handler should call Resolve on attribute values in groups from WithAttrs"),
   224  		f: func(l *slog.Logger) {
   225  			l = l.With(slog.Group("G",
   226  				slog.String("a", "v1"),
   227  				slog.Any("b", &replace{"v2"})))
   228  			l.Info("msg")
   229  		},
   230  		checks: []check{
   231  			inGroup("G", hasAttr("a", "v1")),
   232  			inGroup("G", hasAttr("b", "v2")),
   233  		},
   234  	},
   235  	{
   236  		name:        "empty-PC",
   237  		explanation: withSource("a Handler should not output SourceKey if the PC is zero"),
   238  		f: func(l *slog.Logger) {
   239  			l.Info("message")
   240  		},
   241  		mod: func(r *slog.Record) { r.PC = 0 },
   242  		checks: []check{
   243  			missingKey(slog.SourceKey),
   244  		},
   245  	},
   246  }
   247  
   248  // TestHandler tests a [slog.Handler].
   249  // If TestHandler finds any misbehaviors, it returns an error for each,
   250  // combined into a single error with [errors.Join].
   251  //
   252  // TestHandler installs the given Handler in a [slog.Logger] and
   253  // makes several calls to the Logger's output methods.
   254  // The Handler should be enabled for levels Info and above.
   255  //
   256  // The results function is invoked after all such calls.
   257  // It should return a slice of map[string]any, one for each call to a Logger output method.
   258  // The keys and values of the map should correspond to the keys and values of the Handler's
   259  // output. Each group in the output should be represented as its own nested map[string]any.
   260  // The standard keys [slog.TimeKey], [slog.LevelKey] and [slog.MessageKey] should be used.
   261  //
   262  // If the Handler outputs JSON, then calling [encoding/json.Unmarshal] with a `map[string]any`
   263  // will create the right data structure.
   264  //
   265  // If a Handler intentionally drops an attribute that is checked by a test,
   266  // then the results function should check for its absence and add it to the map it returns.
   267  func TestHandler(h slog.Handler, results func() []map[string]any) error {
   268  	// Run the handler on the test cases.
   269  	for _, c := range cases {
   270  		ht := h
   271  		if c.mod != nil {
   272  			ht = &wrapper{h, c.mod}
   273  		}
   274  		l := slog.New(ht)
   275  		c.f(l)
   276  	}
   277  
   278  	// Collect and check the results.
   279  	var errs []error
   280  	res := results()
   281  	if g, w := len(res), len(cases); g != w {
   282  		return fmt.Errorf("got %d results, want %d", g, w)
   283  	}
   284  	for i, got := range res {
   285  		c := cases[i]
   286  		for _, check := range c.checks {
   287  			if problem := check(got); problem != "" {
   288  				errs = append(errs, fmt.Errorf("%s: %s", problem, c.explanation))
   289  			}
   290  		}
   291  	}
   292  	return errors.Join(errs...)
   293  }
   294  
   295  // Run exercises a [slog.Handler] on the same test cases as [TestHandler], but
   296  // runs each case in a subtest. For each test case, it first calls newHandler to
   297  // get an instance of the handler under test, then runs the test case, then
   298  // calls result to get the result. If the test case fails, it calls t.Error.
   299  func Run(t *testing.T, newHandler func(*testing.T) slog.Handler, result func(*testing.T) map[string]any) {
   300  	for _, c := range cases {
   301  		t.Run(c.name, func(t *testing.T) {
   302  			h := newHandler(t)
   303  			if c.mod != nil {
   304  				h = &wrapper{h, c.mod}
   305  			}
   306  			l := slog.New(h)
   307  			c.f(l)
   308  			got := result(t)
   309  			for _, check := range c.checks {
   310  				if p := check(got); p != "" {
   311  					t.Errorf("%s: %s", p, c.explanation)
   312  				}
   313  			}
   314  		})
   315  	}
   316  }
   317  
   318  type check func(map[string]any) string
   319  
   320  func hasKey(key string) check {
   321  	return func(m map[string]any) string {
   322  		if _, ok := m[key]; !ok {
   323  			return fmt.Sprintf("missing key %q", key)
   324  		}
   325  		return ""
   326  	}
   327  }
   328  
   329  func missingKey(key string) check {
   330  	return func(m map[string]any) string {
   331  		if _, ok := m[key]; ok {
   332  			return fmt.Sprintf("unexpected key %q", key)
   333  		}
   334  		return ""
   335  	}
   336  }
   337  
   338  func hasAttr(key string, wantVal any) check {
   339  	return func(m map[string]any) string {
   340  		if s := hasKey(key)(m); s != "" {
   341  			return s
   342  		}
   343  		gotVal := m[key]
   344  		if !reflect.DeepEqual(gotVal, wantVal) {
   345  			return fmt.Sprintf("%q: got %#v, want %#v", key, gotVal, wantVal)
   346  		}
   347  		return ""
   348  	}
   349  }
   350  
   351  func inGroup(name string, c check) check {
   352  	return func(m map[string]any) string {
   353  		v, ok := m[name]
   354  		if !ok {
   355  			return fmt.Sprintf("missing group %q", name)
   356  		}
   357  		g, ok := v.(map[string]any)
   358  		if !ok {
   359  			return fmt.Sprintf("value for group %q is not map[string]any", name)
   360  		}
   361  		return c(g)
   362  	}
   363  }
   364  
   365  type wrapper struct {
   366  	slog.Handler
   367  	mod func(*slog.Record)
   368  }
   369  
   370  func (h *wrapper) Handle(ctx context.Context, r slog.Record) error {
   371  	h.mod(&r)
   372  	return h.Handler.Handle(ctx, r)
   373  }
   374  
   375  func withSource(s string) string {
   376  	_, file, line, ok := runtime.Caller(1)
   377  	if !ok {
   378  		panic("runtime.Caller failed")
   379  	}
   380  	return fmt.Sprintf("%s (%s:%d)", s, file, line)
   381  }
   382  
   383  type replace struct {
   384  	v any
   385  }
   386  
   387  func (r *replace) LogValue() slog.Value { return slog.AnyValue(r.v) }
   388  
   389  func (r *replace) String() string {
   390  	return fmt.Sprintf("<replace(%v)>", r.v)
   391  }
   392
View as plain text