From 59ebbee5c207bb6034462a75da61b79668fe9232 Mon Sep 17 00:00:00 2001 From: Tyler Yahn Date: Fri, 29 Mar 2024 12:21:22 -0700 Subject: [PATCH] Add multi-logged integration tests to otelslog (#5329) * Add multi-logged integration tests to otelslog * Add Go Authors copyright --- bridges/otelslog/handler_test.go | 296 ++++++++++++++++++++++++++++++- 1 file changed, 294 insertions(+), 2 deletions(-) diff --git a/bridges/otelslog/handler_test.go b/bridges/otelslog/handler_test.go index 2654c4a7842..5b7c85a9897 100644 --- a/bridges/otelslog/handler_test.go +++ b/bridges/otelslog/handler_test.go @@ -1,13 +1,21 @@ // Copyright The OpenTelemetry Authors // SPDX-License-Identifier: Apache-2.0 +// Copyright 2023 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + package otelslog import ( "context" + "fmt" "log/slog" + "reflect" + "runtime" "testing" "testing/slogtest" + "time" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -18,6 +26,8 @@ import ( "go.opentelemetry.io/otel/sdk/instrumentation" ) +var now = time.Now() + func TestNewLogger(t *testing.T) { assert.IsType(t, &Handler{}, NewLogger().Handler()) } @@ -114,7 +124,291 @@ func value2Result(v log.Value) any { return nil } +// testCase represents a complete setup/run/check of an slog handler to test. +// It is based on the testCase from "testing/slogtest" (1.22.1). +type testCase struct { + // Subtest name. + name string + // If non-empty, explanation explains the violated constraint. + explanation string + // f executes a single log event using its argument logger. + // So that mkdescs.sh can generate the right description, + // the body of f must appear on a single line whose first + // non-whitespace characters are "l.". + f func(*slog.Logger) + // If mod is not nil, it is called to modify the Record + // generated by the Logger before it is passed to the Handler. + mod func(*slog.Record) + // checks is a list of checks to run on the result. Each item is a slice of + // checks that will be evaluated for the corresponding record emitted. + checks [][]check +} + +// copied from slogtest (1.22.1). +type check func(map[string]any) string + +// copied from slogtest (1.22.1). +func hasKey(key string) check { + return func(m map[string]any) string { + if _, ok := m[key]; !ok { + return fmt.Sprintf("missing key %q", key) + } + return "" + } +} + +// copied from slogtest (1.22.1). +func missingKey(key string) check { + return func(m map[string]any) string { + if _, ok := m[key]; ok { + return fmt.Sprintf("unexpected key %q", key) + } + return "" + } +} + +// copied from slogtest (1.22.1). +func hasAttr(key string, wantVal any) check { + return func(m map[string]any) string { + if s := hasKey(key)(m); s != "" { + return s + } + gotVal := m[key] + if !reflect.DeepEqual(gotVal, wantVal) { + return fmt.Sprintf("%q: got %#v, want %#v", key, gotVal, wantVal) + } + return "" + } +} + +// copied from slogtest (1.22.1). +func inGroup(name string, c check) check { + return func(m map[string]any) string { + v, ok := m[name] + if !ok { + return fmt.Sprintf("missing group %q", name) + } + g, ok := v.(map[string]any) + if !ok { + return fmt.Sprintf("value for group %q is not map[string]any", name) + } + return c(g) + } +} + +// copied from slogtest (1.22.1). +func withSource(s string) string { + _, file, line, ok := runtime.Caller(1) + if !ok { + panic("runtime.Caller failed") + } + return fmt.Sprintf("%s (%s:%d)", s, file, line) +} + +// copied from slogtest (1.22.1). +type wrapper struct { + slog.Handler + mod func(*slog.Record) +} + +// copied from slogtest (1.22.1). +func (h *wrapper) Handle(ctx context.Context, r slog.Record) error { + h.mod(&r) + return h.Handler.Handle(ctx, r) +} + func TestSLogHandler(t *testing.T) { + cases := []testCase{ + { + name: "Values", + explanation: withSource("all slog Values need to be supported"), + f: func(l *slog.Logger) { + l.Info( + "msg", + "any", struct{ data int64 }{data: 1}, + "bool", true, + "duration", time.Minute, + "float64", 3.14159, + "int64", -2, + "string", "str", + "time", now, + "uint64", uint64(3), + // KindGroup and KindLogValuer are left for slogtest.TestHandler. + ) + }, + checks: [][]check{{ + hasKey(slog.TimeKey), + hasKey(slog.LevelKey), + hasAttr("any", "{data:1}"), + hasAttr("bool", true), + hasAttr("duration", int64(time.Minute)), + hasAttr("float64", 3.14159), + hasAttr("int64", int64(-2)), + hasAttr("string", "str"), + hasAttr("time", now.UnixNano()), + hasAttr("uint64", int64(3)), + }}, + }, + { + name: "multi-messages", + explanation: withSource("this test expects multiple independent messages"), + f: func(l *slog.Logger) { + l.Info("one") + l.Info("two") + }, + checks: [][]check{{ + hasKey(slog.TimeKey), + hasKey(slog.LevelKey), + hasAttr(slog.MessageKey, "one"), + }, { + hasKey(slog.TimeKey), + hasKey(slog.LevelKey), + hasAttr(slog.MessageKey, "two"), + }}, + }, + { + name: "multi-attrs", + explanation: withSource("attributes from one message do not affect another"), + f: func(l *slog.Logger) { + l.Info("one", "k", "v") + l.Info("two") + }, + checks: [][]check{{ + hasAttr("k", "v"), + }, { + missingKey("k"), + }}, + }, + { + name: "independent-WithAttrs", + explanation: withSource("a Handler should only include attributes from its own WithAttr origin"), + f: func(l *slog.Logger) { + l1 := l.With("a", "b") + l2 := l1.With("c", "d") + l3 := l1.With("e", "f") + + l3.Info("msg", "k", "v") + l2.Info("msg", "k", "v") + l1.Info("msg", "k", "v") + l.Info("msg", "k", "v") + }, + checks: [][]check{{ + hasAttr("a", "b"), + hasAttr("e", "f"), + hasAttr("k", "v"), + }, { + hasAttr("a", "b"), + hasAttr("c", "d"), + hasAttr("k", "v"), + missingKey("e"), + }, { + hasAttr("a", "b"), + hasAttr("k", "v"), + missingKey("c"), + missingKey("e"), + }, { + hasAttr("k", "v"), + missingKey("a"), + missingKey("c"), + missingKey("e"), + }}, + }, + { + name: "independent-WithGroup", + explanation: withSource("a Handler should only include attributes from its own WithGroup origin"), + f: func(l *slog.Logger) { + l1 := l.WithGroup("G").With("a", "b") + l2 := l1.WithGroup("H").With("c", "d") + l3 := l1.WithGroup("I").With("e", "f") + + l3.Info("msg", "k", "v") + l2.Info("msg", "k", "v") + l1.Info("msg", "k", "v") + l.Info("msg", "k", "v") + }, + checks: [][]check{{ + hasKey(slog.TimeKey), + hasKey(slog.LevelKey), + hasAttr(slog.MessageKey, "msg"), + missingKey("a"), + missingKey("c"), + missingKey("H"), + inGroup("G", hasAttr("a", "b")), + inGroup("G", inGroup("I", hasAttr("e", "f"))), + inGroup("G", inGroup("I", hasAttr("k", "v"))), + }, { + hasKey(slog.TimeKey), + hasKey(slog.LevelKey), + hasAttr(slog.MessageKey, "msg"), + missingKey("a"), + missingKey("c"), + inGroup("G", hasAttr("a", "b")), + inGroup("G", inGroup("H", hasAttr("c", "d"))), + inGroup("G", inGroup("H", hasAttr("k", "v"))), + }, { + hasKey(slog.TimeKey), + hasKey(slog.LevelKey), + hasAttr(slog.MessageKey, "msg"), + missingKey("a"), + missingKey("c"), + missingKey("H"), + inGroup("G", hasAttr("a", "b")), + inGroup("G", hasAttr("k", "v")), + }, { + hasKey(slog.TimeKey), + hasKey(slog.LevelKey), + hasAttr("k", "v"), + hasAttr(slog.MessageKey, "msg"), + missingKey("a"), + missingKey("c"), + missingKey("G"), + missingKey("H"), + }}, + }, + { + name: "independent-WithGroup.WithAttrs", + explanation: withSource("a Handler should only include group attributes from its own WithAttr origin"), + f: func(l *slog.Logger) { + l = l.WithGroup("G") + l.With("a", "b").Info("msg", "k", "v") + l.With("c", "d").Info("msg", "k", "v") + }, + checks: [][]check{{ + inGroup("G", hasAttr("a", "b")), + inGroup("G", hasAttr("k", "v")), + inGroup("G", missingKey("c")), + }, { + inGroup("G", hasAttr("c", "d")), + inGroup("G", hasAttr("k", "v")), + inGroup("G", missingKey("a")), + }}, + }, + } + + // Based on slogtest.Run. + for _, c := range cases { + t.Run(c.name, func(t *testing.T) { + r := new(recorder) + var h slog.Handler = NewHandler(WithLoggerProvider(r)) + if c.mod != nil { + h = &wrapper{h, c.mod} + } + l := slog.New(h) + c.f(l) + got := r.Results() + if len(got) != len(c.checks) { + t.Fatalf("missing record checks: %d records, %d checks", len(got), len(c.checks)) + } + for i, checks := range c.checks { + for _, check := range checks { + if p := check(got[i]); p != "" { + t.Errorf("%s: %s", p, c.explanation) + } + } + } + }) + } + t.Run("slogtest.TestHandler", func(t *testing.T) { r := new(recorder) h := NewHandler(WithLoggerProvider(r)) @@ -125,8 +419,6 @@ func TestSLogHandler(t *testing.T) { t.Fatal(err) } }) - - // TODO: Add multi-logged testing. See #5195. } func TestNewHandlerConfiguration(t *testing.T) {