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:        "resolve",
   176  		explanation: withSource("a Handler should call Resolve on attribute values"),
   177  		f: func(l *slog.Logger) {
   178  			l.Info("msg", "k", &replace{"replaced"})
   179  		},
   180  		checks: []check{hasAttr("k", "replaced")},
   181  	},
   182  	{
   183  		name:        "resolve-groups",
   184  		explanation: withSource("a Handler should call Resolve on attribute values in groups"),
   185  		f: func(l *slog.Logger) {
   186  			l.Info("msg",
   187  				slog.Group("G",
   188  					slog.String("a", "v1"),
   189  					slog.Any("b", &replace{"v2"})))
   190  		},
   191  		checks: []check{
   192  			inGroup("G", hasAttr("a", "v1")),
   193  			inGroup("G", hasAttr("b", "v2")),
   194  		},
   195  	},
   196  	{
   197  		name:        "resolve-WithAttrs",
   198  		explanation: withSource("a Handler should call Resolve on attribute values from WithAttrs"),
   199  		f: func(l *slog.Logger) {
   200  			l = l.With("k", &replace{"replaced"})
   201  			l.Info("msg")
   202  		},
   203  		checks: []check{hasAttr("k", "replaced")},
   204  	},
   205  	{
   206  		name:        "resolve-WithAttrs-groups",
   207  		explanation: withSource("a Handler should call Resolve on attribute values in groups from WithAttrs"),
   208  		f: func(l *slog.Logger) {
   209  			l = l.With(slog.Group("G",
   210  				slog.String("a", "v1"),
   211  				slog.Any("b", &replace{"v2"})))
   212  			l.Info("msg")
   213  		},
   214  		checks: []check{
   215  			inGroup("G", hasAttr("a", "v1")),
   216  			inGroup("G", hasAttr("b", "v2")),
   217  		},
   218  	},
   219  	{
   220  		name:        "empty-PC",
   221  		explanation: withSource("a Handler should not output SourceKey if the PC is zero"),
   222  		f: func(l *slog.Logger) {
   223  			l.Info("message")
   224  		},
   225  		mod: func(r *slog.Record) { r.PC = 0 },
   226  		checks: []check{
   227  			missingKey(slog.SourceKey),
   228  		},
   229  	},
   230  }
   231  
   232  // TestHandler tests a [slog.Handler].
   233  // If TestHandler finds any misbehaviors, it returns an error for each,
   234  // combined into a single error with [errors.Join].
   235  //
   236  // TestHandler installs the given Handler in a [slog.Logger] and
   237  // makes several calls to the Logger's output methods.
   238  // The Handler should be enabled for levels Info and above.
   239  //
   240  // The results function is invoked after all such calls.
   241  // It should return a slice of map[string]any, one for each call to a Logger output method.
   242  // The keys and values of the map should correspond to the keys and values of the Handler's
   243  // output. Each group in the output should be represented as its own nested map[string]any.
   244  // The standard keys [slog.TimeKey], [slog.LevelKey] and [slog.MessageKey] should be used.
   245  //
   246  // If the Handler outputs JSON, then calling [encoding/json.Unmarshal] with a `map[string]any`
   247  // will create the right data structure.
   248  //
   249  // If a Handler intentionally drops an attribute that is checked by a test,
   250  // then the results function should check for its absence and add it to the map it returns.
   251  func TestHandler(h slog.Handler, results func() []map[string]any) error {
   252  	// Run the handler on the test cases.
   253  	for _, c := range cases {
   254  		ht := h
   255  		if c.mod != nil {
   256  			ht = &wrapper{h, c.mod}
   257  		}
   258  		l := slog.New(ht)
   259  		c.f(l)
   260  	}
   261  
   262  	// Collect and check the results.
   263  	var errs []error
   264  	res := results()
   265  	if g, w := len(res), len(cases); g != w {
   266  		return fmt.Errorf("got %d results, want %d", g, w)
   267  	}
   268  	for i, got := range res {
   269  		c := cases[i]
   270  		for _, check := range c.checks {
   271  			if problem := check(got); problem != "" {
   272  				errs = append(errs, fmt.Errorf("%s: %s", problem, c.explanation))
   273  			}
   274  		}
   275  	}
   276  	return errors.Join(errs...)
   277  }
   278  
   279  // Run exercises a [slog.Handler] on the same test cases as [TestHandler], but
   280  // runs each case in a subtest. For each test case, it first calls newHandler to
   281  // get an instance of the handler under test, then runs the test case, then
   282  // calls result to get the result. If the test case fails, it calls t.Error.
   283  func Run(t *testing.T, newHandler func(*testing.T) slog.Handler, result func(*testing.T) map[string]any) {
   284  	for _, c := range cases {
   285  		t.Run(c.name, func(t *testing.T) {
   286  			h := newHandler(t)
   287  			if c.mod != nil {
   288  				h = &wrapper{h, c.mod}
   289  			}
   290  			l := slog.New(h)
   291  			c.f(l)
   292  			got := result(t)
   293  			for _, check := range c.checks {
   294  				if p := check(got); p != "" {
   295  					t.Errorf("%s: %s", p, c.explanation)
   296  				}
   297  			}
   298  		})
   299  	}
   300  }
   301  
   302  type check func(map[string]any) string
   303  
   304  func hasKey(key string) check {
   305  	return func(m map[string]any) string {
   306  		if _, ok := m[key]; !ok {
   307  			return fmt.Sprintf("missing key %q", key)
   308  		}
   309  		return ""
   310  	}
   311  }
   312  
   313  func missingKey(key string) check {
   314  	return func(m map[string]any) string {
   315  		if _, ok := m[key]; ok {
   316  			return fmt.Sprintf("unexpected key %q", key)
   317  		}
   318  		return ""
   319  	}
   320  }
   321  
   322  func hasAttr(key string, wantVal any) check {
   323  	return func(m map[string]any) string {
   324  		if s := hasKey(key)(m); s != "" {
   325  			return s
   326  		}
   327  		gotVal := m[key]
   328  		if !reflect.DeepEqual(gotVal, wantVal) {
   329  			return fmt.Sprintf("%q: got %#v, want %#v", key, gotVal, wantVal)
   330  		}
   331  		return ""
   332  	}
   333  }
   334  
   335  func inGroup(name string, c check) check {
   336  	return func(m map[string]any) string {
   337  		v, ok := m[name]
   338  		if !ok {
   339  			return fmt.Sprintf("missing group %q", name)
   340  		}
   341  		g, ok := v.(map[string]any)
   342  		if !ok {
   343  			return fmt.Sprintf("value for group %q is not map[string]any", name)
   344  		}
   345  		return c(g)
   346  	}
   347  }
   348  
   349  type wrapper struct {
   350  	slog.Handler
   351  	mod func(*slog.Record)
   352  }
   353  
   354  func (h *wrapper) Handle(ctx context.Context, r slog.Record) error {
   355  	h.mod(&r)
   356  	return h.Handler.Handle(ctx, r)
   357  }
   358  
   359  func withSource(s string) string {
   360  	_, file, line, ok := runtime.Caller(1)
   361  	if !ok {
   362  		panic("runtime.Caller failed")
   363  	}
   364  	return fmt.Sprintf("%s (%s:%d)", s, file, line)
   365  }
   366  
   367  type replace struct {
   368  	v any
   369  }
   370  
   371  func (r *replace) LogValue() slog.Value { return slog.AnyValue(r.v) }
   372  
   373  func (r *replace) String() string {
   374  	return fmt.Sprintf("<replace(%v)>", r.v)
   375  }
   376
View as plain text