Source file
src/log/slog/json_handler_test.go
1
2
3
4
5 package slog
6
7 import (
8 "bytes"
9 "context"
10 "encoding/json"
11 "errors"
12 "internal/goexperiment"
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 func TestJSONHandlerMarshalerEscaping(t *testing.T) {
57 var buf bytes.Buffer
58 h := NewJSONHandler(&buf, nil)
59 r := NewRecord(testTime, LevelInfo, "m", 0)
60 r.AddAttrs(Any("m", jsonMarshaler{marshalerASCII}))
61 if err := h.Handle(t.Context(), r); err != nil {
62 t.Fatal(err)
63 }
64 got := bytes.TrimSuffix(buf.Bytes(), []byte{'\n'})
65 if !json.Valid(got) {
66 t.Fatalf("output is not valid JSON: %q", got)
67 }
68 for _, escaped := range []string{`\"`, `\\`, `\t`, `\n`, `\u0000`} {
69 if !bytes.Contains(got, []byte(escaped)) {
70 t.Errorf("output %q does not contain JSON escape %q", got, escaped)
71 }
72 }
73 for i := byte(0); i < 0x20; i++ {
74 if bytes.IndexByte(got, i) >= 0 {
75 t.Errorf("output %q contains unescaped control character %#x", got, i)
76 }
77 }
78 var record struct {
79 M []string `json:"m"`
80 }
81 if err := json.Unmarshal(got, &record); err != nil {
82 t.Fatal(err)
83 }
84 if len(record.M) != 1 || record.M[0] != marshalerASCII {
85 t.Errorf("marshaled value = %q, want %q", record.M, []string{marshalerASCII})
86 }
87 }
88
89
90 type jsonMarshaler struct {
91 s string
92 }
93
94 func (j jsonMarshaler) String() string { return j.s }
95
96 func (j jsonMarshaler) MarshalJSON() ([]byte, error) {
97 if j.s == "" {
98 return nil, errors.New("json: empty string")
99 }
100 return json.Marshal([]string{j.s})
101 }
102
103 type jsonMarshalerError struct {
104 jsonMarshaler
105 }
106
107 var _ error = jsonMarshalerError{}
108
109 func (jsonMarshalerError) Error() string { return "oops" }
110
111 func TestAppendJSONValue(t *testing.T) {
112
113 for _, value := range []any{
114 "hello\r\n\t\a",
115 `"[{escape}]"`,
116 "<escapeHTML&>",
117
118
119 "\u03B8\u2028\u2029\uFFFF\xF6",
120 `-123`,
121 int64(-9_200_123_456_789_123_456),
122 uint64(9_200_123_456_789_123_456),
123 -12.75,
124 1.23e-9,
125 false,
126 time.Minute,
127 testTime,
128 jsonMarshaler{"xyz"},
129 jsonMarshalerError{jsonMarshaler{"pqr"}},
130 LevelWarn,
131 } {
132 got := jsonValueString(AnyValue(value))
133 want, err := marshalJSON(value)
134 if err != nil {
135 t.Fatal(err)
136 }
137 if got != want {
138 t.Errorf("%v: got %s, want %s", value, got, want)
139 t.Errorf("%v: got %x, want %x", value, got, want)
140 }
141 }
142 }
143
144 func marshalJSON(x any) (string, error) {
145 var buf bytes.Buffer
146 enc := json.NewEncoder(&buf)
147 enc.SetEscapeHTML(false)
148 if err := enc.Encode(x); err != nil {
149 return "", err
150 }
151 return strings.TrimSpace(buf.String()), nil
152 }
153
154 func TestJSONAppendAttrValueSpecial(t *testing.T) {
155
156 for _, test := range []struct {
157 value any
158 want string
159 }{
160 {math.NaN(), `"!ERROR:json: unsupported value: NaN"`},
161 {math.Inf(+1), `"!ERROR:json: unsupported value: +Inf"`},
162 {math.Inf(-1), `"!ERROR:json: unsupported value: -Inf"`},
163 {io.EOF, `"EOF"`},
164 } {
165 got := jsonValueString(AnyValue(test.value))
166 if got != test.want {
167 t.Errorf("%v: got %s, want %s", test.value, got, test.want)
168 }
169 }
170 }
171
172 func jsonValueString(v Value) string {
173 var buf []byte
174 s := &handleState{h: &commonHandler{json: true}, buf: (*buffer.Buffer)(&buf)}
175 if err := appendJSONValue(s, v); err != nil {
176 s.appendError(err)
177 }
178 return string(buf)
179 }
180
181 func TestJSONAllocs(t *testing.T) {
182 ctx := t.Context()
183 l := New(NewJSONHandler(io.Discard, &HandlerOptions{}))
184 testErr := errors.New("an error occurred")
185 testEvent := struct {
186 ID int
187 Scope string
188 Enabled bool
189 }{
190 123456, "abcdefgh", true,
191 }
192
193 t.Run("message", func(t *testing.T) {
194 wantAllocs(t, 0, func() {
195 l.LogAttrs(ctx, LevelInfo,
196 "hello world",
197 )
198 })
199 })
200 t.Run("attrs", func(t *testing.T) {
201
202
203
204
205 wantAllocs(t, 1+goexperiment.JSONv2Int, func() {
206 l.LogAttrs(ctx, LevelInfo,
207 "hello world",
208 String("component", "subtest"),
209 Int("id", 67890),
210 Bool("flag", true),
211 Any("error", testErr),
212 Any("event", testEvent),
213 )
214 })
215 })
216 }
217
218 func BenchmarkJSONHandler(b *testing.B) {
219 for _, bench := range []struct {
220 name string
221 opts HandlerOptions
222 }{
223 {"defaults", HandlerOptions{}},
224 {"time format", HandlerOptions{
225 ReplaceAttr: func(_ []string, a Attr) Attr {
226 v := a.Value
227 if v.Kind() == KindTime {
228 return String(a.Key, v.Time().Format(rfc3339Millis))
229 }
230 if a.Key == "level" {
231 return Attr{"severity", a.Value}
232 }
233 return a
234 },
235 }},
236 {"time unix", HandlerOptions{
237 ReplaceAttr: func(_ []string, a Attr) Attr {
238 v := a.Value
239 if v.Kind() == KindTime {
240 return Int64(a.Key, v.Time().UnixNano())
241 }
242 if a.Key == "level" {
243 return Attr{"severity", a.Value}
244 }
245 return a
246 },
247 }},
248 } {
249 b.Run(bench.name, func(b *testing.B) {
250 ctx := context.Background()
251 l := New(NewJSONHandler(io.Discard, &bench.opts)).With(
252 String("program", "my-test-program"),
253 String("package", "log/slog"),
254 String("traceID", "2039232309232309"),
255 String("URL", "https://pkg.go.dev/golang.org/x/log/slog"))
256 b.ReportAllocs()
257 for b.Loop() {
258 l.LogAttrs(ctx, LevelInfo, "this is a typical log message",
259 String("module", "github.com/google/go-cmp"),
260 String("version", "v1.23.4"),
261 Int("count", 23),
262 Int("number", 123456),
263 )
264 }
265 })
266 }
267 }
268
269 func BenchmarkPreformatting(b *testing.B) {
270 type req struct {
271 Method string
272 URL string
273 TraceID string
274 Addr string
275 }
276
277 structAttrs := []any{
278 String("program", "my-test-program"),
279 String("package", "log/slog"),
280 Any("request", &req{
281 Method: "GET",
282 URL: "https://pkg.go.dev/golang.org/x/log/slog",
283 TraceID: "2039232309232309",
284 Addr: "127.0.0.1:8080",
285 }),
286 }
287
288 outFile, err := os.Create(filepath.Join(b.TempDir(), "bench.log"))
289 if err != nil {
290 b.Fatal(err)
291 }
292 defer func() {
293 if err := outFile.Close(); err != nil {
294 b.Fatal(err)
295 }
296 }()
297
298 for _, bench := range []struct {
299 name string
300 wc io.Writer
301 attrs []any
302 }{
303 {"separate", io.Discard, []any{
304 String("program", "my-test-program"),
305 String("package", "log/slog"),
306 String("method", "GET"),
307 String("URL", "https://pkg.go.dev/golang.org/x/log/slog"),
308 String("traceID", "2039232309232309"),
309 String("addr", "127.0.0.1:8080"),
310 }},
311 {"struct", io.Discard, structAttrs},
312 {"struct file", outFile, structAttrs},
313 } {
314 ctx := context.Background()
315 b.Run(bench.name, func(b *testing.B) {
316 l := New(NewJSONHandler(bench.wc, nil)).With(bench.attrs...)
317 b.ReportAllocs()
318 for b.Loop() {
319 l.LogAttrs(ctx, LevelInfo, "this is a typical log message",
320 String("module", "github.com/google/go-cmp"),
321 String("version", "v1.23.4"),
322 Int("count", 23),
323 Int("number", 123456),
324 )
325 }
326 })
327 }
328 }
329
330 func BenchmarkJSONEncoding(b *testing.B) {
331 value := 3.14
332 buf := buffer.New()
333 defer buf.Free()
334 b.Run("json.Marshal", func(b *testing.B) {
335 b.ReportAllocs()
336 for i := 0; i < b.N; i++ {
337 by, err := json.Marshal(value)
338 if err != nil {
339 b.Fatal(err)
340 }
341 buf.Write(by)
342 *buf = (*buf)[:0]
343 }
344 })
345 b.Run("Encoder.Encode", func(b *testing.B) {
346 b.ReportAllocs()
347 for i := 0; i < b.N; i++ {
348 if err := json.NewEncoder(buf).Encode(value); err != nil {
349 b.Fatal(err)
350 }
351 *buf = (*buf)[:0]
352 }
353 })
354 _ = buf
355 }
356
View as plain text