Source file src/log/slog/json_handler_test.go

     1  // Copyright 2022 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 slog
     6  
     7  import (
     8  	"bytes"
     9  	"context"
    10  	"encoding/json"
    11  	"errors"
    12  	"fmt"
    13  	"io"
    14  	"log/slog/internal/buffer"
    15  	"math"
    16  	"os"
    17  	"path/filepath"
    18  	"strings"
    19  	"testing"
    20  	"time"
    21  )
    22  
    23  func TestJSONHandler(t *testing.T) {
    24  	for _, test := range []struct {
    25  		name string
    26  		opts HandlerOptions
    27  		want string
    28  	}{
    29  		{
    30  			"none",
    31  			HandlerOptions{},
    32  			`{"time":"2000-01-02T03:04:05Z","level":"INFO","msg":"m","a":1,"m":{"b":2}}`,
    33  		},
    34  		{
    35  			"replace",
    36  			HandlerOptions{ReplaceAttr: upperCaseKey},
    37  			`{"TIME":"2000-01-02T03:04:05Z","LEVEL":"INFO","MSG":"m","A":1,"M":{"b":2}}`,
    38  		},
    39  	} {
    40  		t.Run(test.name, func(t *testing.T) {
    41  			var buf bytes.Buffer
    42  			h := NewJSONHandler(&buf, &test.opts)
    43  			r := NewRecord(testTime, LevelInfo, "m", 0)
    44  			r.AddAttrs(Int("a", 1), Any("m", map[string]int{"b": 2}))
    45  			if err := h.Handle(context.Background(), r); err != nil {
    46  				t.Fatal(err)
    47  			}
    48  			got := strings.TrimSuffix(buf.String(), "\n")
    49  			if got != test.want {
    50  				t.Errorf("\ngot  %s\nwant %s", got, test.want)
    51  			}
    52  		})
    53  	}
    54  }
    55  
    56  // for testing json.Marshaler
    57  type jsonMarshaler struct {
    58  	s string
    59  }
    60  
    61  func (j jsonMarshaler) String() string { return j.s } // should be ignored
    62  
    63  func (j jsonMarshaler) MarshalJSON() ([]byte, error) {
    64  	if j.s == "" {
    65  		return nil, errors.New("json: empty string")
    66  	}
    67  	return []byte(fmt.Sprintf(`[%q]`, j.s)), nil
    68  }
    69  
    70  type jsonMarshalerError struct {
    71  	jsonMarshaler
    72  }
    73  
    74  func (jsonMarshalerError) Error() string { return "oops" }
    75  
    76  func TestAppendJSONValue(t *testing.T) {
    77  	// jsonAppendAttrValue should always agree with json.Marshal.
    78  	for _, value := range []any{
    79  		"hello\r\n\t\a",
    80  		`"[{escape}]"`,
    81  		"<escapeHTML&>",
    82  		// \u2028\u2029 is an edge case in JavaScript vs JSON.
    83  		// \xF6 is an incomplete encoding.
    84  		"\u03B8\u2028\u2029\uFFFF\xF6",
    85  		`-123`,
    86  		int64(-9_200_123_456_789_123_456),
    87  		uint64(9_200_123_456_789_123_456),
    88  		-12.75,
    89  		1.23e-9,
    90  		false,
    91  		time.Minute,
    92  		testTime,
    93  		jsonMarshaler{"xyz"},
    94  		jsonMarshalerError{jsonMarshaler{"pqr"}},
    95  		LevelWarn,
    96  	} {
    97  		got := jsonValueString(AnyValue(value))
    98  		want, err := marshalJSON(value)
    99  		if err != nil {
   100  			t.Fatal(err)
   101  		}
   102  		if got != want {
   103  			t.Errorf("%v: got %s, want %s", value, got, want)
   104  		}
   105  	}
   106  }
   107  
   108  func marshalJSON(x any) (string, error) {
   109  	var buf bytes.Buffer
   110  	enc := json.NewEncoder(&buf)
   111  	enc.SetEscapeHTML(false)
   112  	if err := enc.Encode(x); err != nil {
   113  		return "", err
   114  	}
   115  	return strings.TrimSpace(buf.String()), nil
   116  }
   117  
   118  func TestJSONAppendAttrValueSpecial(t *testing.T) {
   119  	// Attr values that render differently from json.Marshal.
   120  	for _, test := range []struct {
   121  		value any
   122  		want  string
   123  	}{
   124  		{math.NaN(), `"!ERROR:json: unsupported value: NaN"`},
   125  		{math.Inf(+1), `"!ERROR:json: unsupported value: +Inf"`},
   126  		{math.Inf(-1), `"!ERROR:json: unsupported value: -Inf"`},
   127  		{io.EOF, `"EOF"`},
   128  	} {
   129  		got := jsonValueString(AnyValue(test.value))
   130  		if got != test.want {
   131  			t.Errorf("%v: got %s, want %s", test.value, got, test.want)
   132  		}
   133  	}
   134  }
   135  
   136  func jsonValueString(v Value) string {
   137  	var buf []byte
   138  	s := &handleState{h: &commonHandler{json: true}, buf: (*buffer.Buffer)(&buf)}
   139  	if err := appendJSONValue(s, v); err != nil {
   140  		s.appendError(err)
   141  	}
   142  	return string(buf)
   143  }
   144  
   145  func TestJSONAllocs(t *testing.T) {
   146  	ctx := t.Context()
   147  	l := New(NewJSONHandler(io.Discard, &HandlerOptions{}))
   148  	testErr := errors.New("an error occurred")
   149  	testEvent := struct {
   150  		ID      int
   151  		Scope   string
   152  		Enabled bool
   153  	}{
   154  		123456, "abcdefgh", true,
   155  	}
   156  
   157  	t.Run("message", func(t *testing.T) {
   158  		wantAllocs(t, 0, func() {
   159  			l.LogAttrs(ctx, LevelInfo,
   160  				"hello world",
   161  			)
   162  		})
   163  	})
   164  	t.Run("attrs", func(t *testing.T) {
   165  		wantAllocs(t, 1, func() {
   166  			l.LogAttrs(ctx, LevelInfo,
   167  				"hello world",
   168  				String("component", "subtest"),
   169  				Int("id", 67890),
   170  				Bool("flag", true),
   171  				Any("error", testErr),
   172  				Any("event", testEvent),
   173  			)
   174  		})
   175  	})
   176  }
   177  
   178  func BenchmarkJSONHandler(b *testing.B) {
   179  	for _, bench := range []struct {
   180  		name string
   181  		opts HandlerOptions
   182  	}{
   183  		{"defaults", HandlerOptions{}},
   184  		{"time format", HandlerOptions{
   185  			ReplaceAttr: func(_ []string, a Attr) Attr {
   186  				v := a.Value
   187  				if v.Kind() == KindTime {
   188  					return String(a.Key, v.Time().Format(rfc3339Millis))
   189  				}
   190  				if a.Key == "level" {
   191  					return Attr{"severity", a.Value}
   192  				}
   193  				return a
   194  			},
   195  		}},
   196  		{"time unix", HandlerOptions{
   197  			ReplaceAttr: func(_ []string, a Attr) Attr {
   198  				v := a.Value
   199  				if v.Kind() == KindTime {
   200  					return Int64(a.Key, v.Time().UnixNano())
   201  				}
   202  				if a.Key == "level" {
   203  					return Attr{"severity", a.Value}
   204  				}
   205  				return a
   206  			},
   207  		}},
   208  	} {
   209  		b.Run(bench.name, func(b *testing.B) {
   210  			ctx := context.Background()
   211  			l := New(NewJSONHandler(io.Discard, &bench.opts)).With(
   212  				String("program", "my-test-program"),
   213  				String("package", "log/slog"),
   214  				String("traceID", "2039232309232309"),
   215  				String("URL", "https://pkg.go.dev/golang.org/x/log/slog"))
   216  			b.ReportAllocs()
   217  			b.ResetTimer()
   218  			for i := 0; i < b.N; i++ {
   219  				l.LogAttrs(ctx, LevelInfo, "this is a typical log message",
   220  					String("module", "github.com/google/go-cmp"),
   221  					String("version", "v1.23.4"),
   222  					Int("count", 23),
   223  					Int("number", 123456),
   224  				)
   225  			}
   226  		})
   227  	}
   228  }
   229  
   230  func BenchmarkPreformatting(b *testing.B) {
   231  	type req struct {
   232  		Method  string
   233  		URL     string
   234  		TraceID string
   235  		Addr    string
   236  	}
   237  
   238  	structAttrs := []any{
   239  		String("program", "my-test-program"),
   240  		String("package", "log/slog"),
   241  		Any("request", &req{
   242  			Method:  "GET",
   243  			URL:     "https://pkg.go.dev/golang.org/x/log/slog",
   244  			TraceID: "2039232309232309",
   245  			Addr:    "127.0.0.1:8080",
   246  		}),
   247  	}
   248  
   249  	outFile, err := os.Create(filepath.Join(b.TempDir(), "bench.log"))
   250  	if err != nil {
   251  		b.Fatal(err)
   252  	}
   253  	defer func() {
   254  		if err := outFile.Close(); err != nil {
   255  			b.Fatal(err)
   256  		}
   257  	}()
   258  
   259  	for _, bench := range []struct {
   260  		name  string
   261  		wc    io.Writer
   262  		attrs []any
   263  	}{
   264  		{"separate", io.Discard, []any{
   265  			String("program", "my-test-program"),
   266  			String("package", "log/slog"),
   267  			String("method", "GET"),
   268  			String("URL", "https://pkg.go.dev/golang.org/x/log/slog"),
   269  			String("traceID", "2039232309232309"),
   270  			String("addr", "127.0.0.1:8080"),
   271  		}},
   272  		{"struct", io.Discard, structAttrs},
   273  		{"struct file", outFile, structAttrs},
   274  	} {
   275  		ctx := context.Background()
   276  		b.Run(bench.name, func(b *testing.B) {
   277  			l := New(NewJSONHandler(bench.wc, nil)).With(bench.attrs...)
   278  			b.ReportAllocs()
   279  			b.ResetTimer()
   280  			for i := 0; i < b.N; i++ {
   281  				l.LogAttrs(ctx, LevelInfo, "this is a typical log message",
   282  					String("module", "github.com/google/go-cmp"),
   283  					String("version", "v1.23.4"),
   284  					Int("count", 23),
   285  					Int("number", 123456),
   286  				)
   287  			}
   288  		})
   289  	}
   290  }
   291  
   292  func BenchmarkJSONEncoding(b *testing.B) {
   293  	value := 3.14
   294  	buf := buffer.New()
   295  	defer buf.Free()
   296  	b.Run("json.Marshal", func(b *testing.B) {
   297  		b.ReportAllocs()
   298  		for i := 0; i < b.N; i++ {
   299  			by, err := json.Marshal(value)
   300  			if err != nil {
   301  				b.Fatal(err)
   302  			}
   303  			buf.Write(by)
   304  			*buf = (*buf)[:0]
   305  		}
   306  	})
   307  	b.Run("Encoder.Encode", func(b *testing.B) {
   308  		b.ReportAllocs()
   309  		for i := 0; i < b.N; i++ {
   310  			if err := json.NewEncoder(buf).Encode(value); err != nil {
   311  				b.Fatal(err)
   312  			}
   313  			*buf = (*buf)[:0]
   314  		}
   315  	})
   316  	_ = buf
   317  }
   318  

View as plain text