src/testing/slogtest/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 results() {
 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 }