1 package logsink_test
2
3 import (
4 "bytes"
5 "errors"
6 "math"
7 "reflect"
8 "runtime"
9 "slices"
10 "testing"
11 "time"
12
13 "github.com/golang/glog/internal/logsink"
14 "github.com/golang/glog/internal/stackdump"
15 "github.com/google/go-cmp/cmp"
16 )
17
18
19 type savingTextSink struct{ data []byte }
20
21 func (savingTextSink) Enabled(*logsink.Meta) bool { return true }
22 func (s *savingTextSink) Emit(meta *logsink.Meta, data []byte) (n int, err error) {
23 s.data = slices.Clone(data)
24 return len(data), nil
25 }
26
27 func TestThreadPadding(t *testing.T) {
28 originalSinks := logsink.StructuredSinks
29 defer func() { logsink.StructuredSinks = originalSinks }()
30 var sink savingTextSink
31 logsink.TextSinks = []logsink.Text{&sink}
32
33 _, file, line, _ := runtime.Caller(0)
34 meta := &logsink.Meta{
35 Time: time.Now(),
36 File: file,
37 Line: line,
38 Severity: logsink.Info,
39 }
40
41 const msg = "DOOMBAH!"
42
43 for _, tc := range [...]struct {
44 n uint64
45 want []byte
46 }{
47
48
49 {want: []byte(" "), n: 0},
50 {want: []byte(" 1 "), n: 1},
51 {want: []byte(" 912389 "), n: 912389},
52 {want: []byte(" 2147483648 "), n: math.MaxInt32 + 1},
53 {want: []byte(" 9223372036854775806 "), n: math.MaxInt64 - 1},
54 {want: []byte(" 9223372036854775808 "), n: math.MaxInt64 + 1},
55 {want: []byte(" 9223372036854775817 "), n: math.MaxInt64 + 10},
56 {want: []byte(" 18446744073709551614 "), n: math.MaxUint64 - 1},
57 } {
58 meta.Thread = int64(tc.n)
59 logsink.Printf(meta, "%v", msg)
60 t.Logf(`logsink.Printf(%+v, "%%v", %q)`, meta, msg)
61
62
63 if !bytes.Contains(sink.data, tc.want) {
64 t.Errorf("needle = '%s' not found in %s", tc.want, sink.data)
65 }
66 }
67 }
68
69 func TestFatalMessage(t *testing.T) {
70 const msg = "DOOOOOOM!"
71
72 _, file, line, _ := runtime.Caller(0)
73 meta := &logsink.Meta{
74 Time: time.Now(),
75 File: file,
76 Line: line,
77 Severity: logsink.Fatal,
78 }
79
80 logsink.Printf(meta, "%v", msg)
81 t.Logf(`logsink.Printf(%+v, "%%v", %q)`, meta, msg)
82
83 gotMeta, gotMsg, ok := logsink.FatalMessage()
84 if !ok || !reflect.DeepEqual(gotMeta, meta) || !bytes.Contains(gotMsg, []byte(msg)) {
85 t.Errorf("logsink.FatalMessage() = %+v, %q, %v", gotMeta, gotMsg, ok)
86 }
87 }
88
89 func TestStructuredSink(t *testing.T) {
90
91
92 originalSinks := logsink.StructuredSinks
93 defer func() {
94 logsink.StructuredSinks = originalSinks
95 }()
96
97 testStacktrace := stackdump.Caller(0)
98
99 for _, test := range []struct {
100 name string
101 format string
102 args []any
103 meta logsink.Meta
104 wantErr bool
105 sinks []testStructuredSinkAndWants
106 }{
107 {
108 name: "sink is called with expected format and args",
109 format: "test %d",
110 args: []any{1},
111 sinks: []testStructuredSinkAndWants{
112 {
113 sink: &fakeStructuredSink{},
114 },
115 },
116 },
117 {
118 name: "sink is called with expected meta",
119 meta: logsink.Meta{
120 Severity: logsink.Info,
121 File: "base/go/logsink_test.go",
122 Line: 1,
123 Time: time.Unix(1545321163, 0),
124 Thread: 1,
125 },
126 sinks: []testStructuredSinkAndWants{
127 {
128 sink: &fakeStructuredSink{},
129 },
130 },
131 },
132 {
133 name: "sink is called with expected meta (2)",
134 meta: logsink.Meta{
135 Severity: logsink.Error,
136 File: "foo.go",
137 Line: 1337,
138 Time: time.Unix(0, 0),
139 Thread: 123,
140 },
141 sinks: []testStructuredSinkAndWants{
142 {
143 sink: &fakeStructuredSink{},
144 },
145 },
146 },
147 {
148 name: "sink returns error",
149 format: "test",
150 meta: logsink.Meta{
151 Severity: logsink.Info,
152 File: "base/go/logsink_test.go",
153 Line: 1,
154 Time: time.Unix(1545321163, 0),
155 Thread: 1,
156 },
157 wantErr: true,
158 sinks: []testStructuredSinkAndWants{
159 {
160 sink: &fakeStructuredSink{
161 err: errors.New("err"),
162 },
163 },
164 },
165 },
166 {
167 name: "sink is StackWanter and WantStack() returns true",
168 sinks: []testStructuredSinkAndWants{
169 {
170 sink: &fakeStructuredSinkThatWantsStack{
171 wantStack: true,
172 },
173 wantStack: true,
174 },
175 },
176 },
177 {
178 name: "sink is StackWanter and WantStack() returns false",
179 sinks: []testStructuredSinkAndWants{
180 {
181 sink: &fakeStructuredSinkThatWantsStack{
182 wantStack: false,
183 },
184 wantStack: false,
185 },
186 },
187 },
188 {
189 name: "use stacktrace from args if available",
190 format: "test\n%s",
191 args: []any{testStacktrace},
192 sinks: []testStructuredSinkAndWants{
193 {
194 sink: &fakeStructuredSinkThatWantsStack{
195 wantStack: true,
196 },
197 wantStack: true,
198 wantStackEqual: &testStacktrace,
199 },
200 },
201 },
202 {
203 name: "respect StackWanter contract",
204 format: "test\n%s",
205 args: []any{testStacktrace},
206 sinks: []testStructuredSinkAndWants{
207 {
208 sink: &fakeStructuredSinkThatWantsStack{
209 wantStack: true,
210 },
211 wantStack: true,
212 wantStackEqual: &testStacktrace,
213 },
214 {
215 sink: &fakeStructuredSink{},
216 },
217 },
218 },
219 {
220 name: "respect StackWanter contract for multiple sinks",
221 format: "test\n%s",
222 args: []any{testStacktrace},
223 sinks: []testStructuredSinkAndWants{
224 {
225 sink: &fakeStructuredSinkThatWantsStack{wantStack: true},
226 wantStack: true,
227 wantStackEqual: &testStacktrace,
228 },
229 {
230 sink: &fakeStructuredSinkThatWantsStack{wantStack: false},
231 wantStack: false,
232 },
233 {
234 sink: &fakeStructuredSinkThatWantsStack{wantStack: true},
235 wantStack: true,
236 wantStackEqual: &testStacktrace,
237 },
238 {
239 sink: &fakeStructuredSink{},
240 wantStack: false,
241 },
242 {
243 sink: &fakeStructuredSinkThatWantsStack{wantStack: true},
244 wantStack: true,
245 wantStackEqual: &testStacktrace,
246 },
247 },
248 },
249 } {
250 t.Run(test.name, func(t *testing.T) {
251 testStructuredSinks := make([]logsink.Structured, len(test.sinks))
252 for i, sink := range test.sinks {
253 testStructuredSinks[i] = sink.sink
254 }
255
256 logsink.StructuredSinks = testStructuredSinks
257
258
259
260 meta := test.meta
261 _, err := logsink.Printf(&meta, test.format, test.args...)
262 if gotErr := err != nil; gotErr != test.wantErr {
263 t.Fatalf("logsink.Printf() = (_, %v), want err? %t", err, test.wantErr)
264 }
265
266
267 for _, testStructuredSinkAndWants := range test.sinks {
268
269 if got, want := testStructuredSinkAndWants.sink.Calls(), 1; got != want {
270 t.Fatalf("sink.calls = %d, want %d", got, want)
271 }
272
273
274 gotMeta := testStructuredSinkAndWants.sink.GotMeta()
275
276 cmpIgnoreSomeFields := cmp.FilterPath(func(p cmp.Path) bool { return p.String() == "Stack" || p.String() == "Depth" }, cmp.Ignore())
277 if diff := cmp.Diff(&test.meta, gotMeta, cmpIgnoreSomeFields); diff != "" {
278 t.Errorf("sink.meta diff -want +got:\n%s", diff)
279 }
280
281
282
283
284 if testStructuredSinkAndWants.wantStack && gotMeta.Stack == nil {
285 t.Errorf("sink.meta.Stack = %v, but WantStack = %t", gotMeta.Stack, testStructuredSinkAndWants.wantStack)
286 } else if testStructuredSinkAndWants.wantStackEqual != nil {
287
288 if diff := cmp.Diff(testStructuredSinkAndWants.wantStackEqual, gotMeta.Stack); diff != "" {
289 t.Errorf("sink.meta.Stack diff -want +got:\n%s", diff)
290 }
291 }
292
293
294
295 if got, want := gotMeta.Depth, 1; got != want {
296 t.Errorf("sink.meta.Depth = %d, want %d", got, want)
297 }
298
299 if got, want := testStructuredSinkAndWants.sink.GotFormat(), test.format; got != want {
300 t.Errorf("sink.format = %q, want %q", got, want)
301 }
302
303 if diff := cmp.Diff(test.args, testStructuredSinkAndWants.sink.GotArgs()); diff != "" {
304 t.Errorf("sink.args diff -want +got:\n%s", diff)
305 }
306 }
307 })
308 }
309 }
310
311 func BenchmarkStructuredSink(b *testing.B) {
312
313
314 originalSinks := logsink.StructuredSinks
315 defer func() {
316 logsink.StructuredSinks = originalSinks
317 }()
318
319 noop := noopStructuredSink{}
320 noopWS := noopStructuredSinkWantStack{}
321 stringWS := stringStructuredSinkWantStack{}
322
323 _, file, line, _ := runtime.Caller(0)
324 stack := stackdump.Caller(0)
325 genMeta := func(dump *stackdump.Stack) *logsink.Meta {
326 return &logsink.Meta{
327 Time: time.Now(),
328 File: file,
329 Line: line,
330 Severity: logsink.Warning,
331 Thread: 1240,
332 Stack: dump,
333 }
334 }
335
336 for _, test := range []struct {
337 name string
338 sinks []logsink.Structured
339 meta *logsink.Meta
340 }{
341 {name: "meta_nostack_01_sinks_00_want_stack_pconly", meta: genMeta(nil), sinks: []logsink.Structured{noop}},
342 {name: "meta___stack_01_sinks_01_want_stack_pconly", meta: genMeta(&stack), sinks: []logsink.Structured{noopWS}},
343 {name: "meta_nostack_01_sinks_01_want_stack_pconly", meta: genMeta(nil), sinks: []logsink.Structured{noopWS}},
344 {name: "meta_nostack_01_sinks_01_want_stack_string", meta: genMeta(nil), sinks: []logsink.Structured{stringWS}},
345 {name: "meta_nostack_02_sinks_01_want_stack_pconly", meta: genMeta(nil), sinks: []logsink.Structured{noopWS, noop}},
346 {name: "meta_nostack_02_sinks_02_want_stack_string", meta: genMeta(nil), sinks: []logsink.Structured{stringWS, stringWS}},
347 {name: "meta_nostack_10_sinks_00_want_stack_pconly", meta: genMeta(nil), sinks: []logsink.Structured{noop, noop, noop, noop, noop, noop, noop, noop, noop, noop}},
348 {name: "meta_nostack_10_sinks_05_want_stack_pconly", meta: genMeta(nil), sinks: []logsink.Structured{noop, noopWS, noop, noop, noopWS, noop, noopWS, noopWS, noopWS, noop}},
349 {name: "meta_nostack_10_sinks_05_want_stack_string", meta: genMeta(nil), sinks: []logsink.Structured{noop, stringWS, noop, noop, stringWS, noop, stringWS, stringWS, stringWS, noop}},
350 {name: "meta___stack_10_sinks_05_want_stack_pconly", meta: genMeta(&stack), sinks: []logsink.Structured{noop, noopWS, noop, noop, noopWS, noop, noopWS, noopWS, noopWS, noop}},
351 {name: "meta___stack_10_sinks_05_want_stack_string", meta: genMeta(&stack), sinks: []logsink.Structured{noop, stringWS, noop, noop, stringWS, noop, stringWS, stringWS, stringWS, noop}},
352 } {
353 b.Run(test.name, func(b *testing.B) {
354 logsink.StructuredSinks = test.sinks
355 savedStack := test.meta.Stack
356
357 args := []any{1}
358
359 b.ResetTimer()
360 for i := 0; i < b.N; i++ {
361 _, err := logsink.Printf(test.meta, "test %d", args...)
362 if err != nil {
363 b.Fatalf("logsink.Printf(): didn't expect any error while benchmarking, got %v", err)
364 }
365
366
367
368 test.meta.Depth = 0
369
370
371
372
373
374
375 test.meta.Stack = savedStack
376 }
377 })
378 }
379 }
380
381
382
383
384 type testStructuredSinkAndWants struct {
385
386 sink testStructuredSink
387
388
389 wantStack bool
390
391
392 wantStackEqual *stackdump.Stack
393 }
394
395 type testStructuredSink interface {
396 logsink.Structured
397
398 GotMeta() *logsink.Meta
399 GotFormat() string
400 GotArgs() []any
401 Calls() int
402 }
403
404 type fakeStructuredSink struct {
405
406 err error
407
408 gotMeta *logsink.Meta
409
410 gotFormat string
411
412 gotArgs []any
413
414 calls int
415 }
416
417 func (s *fakeStructuredSink) GotMeta() *logsink.Meta {
418 return s.gotMeta
419 }
420
421 func (s *fakeStructuredSink) GotFormat() string {
422 return s.gotFormat
423 }
424
425 func (s *fakeStructuredSink) GotArgs() []any {
426 return s.gotArgs
427 }
428
429 func (s *fakeStructuredSink) Calls() int {
430 return s.calls
431 }
432
433 func (s *fakeStructuredSink) Printf(meta *logsink.Meta, format string, a ...any) (n int, err error) {
434 s.gotMeta = meta
435 s.gotFormat = format
436 s.gotArgs = a
437 s.calls++
438 return 0, s.err
439 }
440
441 type fakeStructuredSinkThatWantsStack struct {
442 fakeStructuredSink
443
444 wantStack bool
445 }
446
447 func (s *fakeStructuredSinkThatWantsStack) WantStack(meta *logsink.Meta) bool {
448 return s.wantStack
449 }
450
451 type noopStructuredSink struct{}
452
453 func (s noopStructuredSink) Printf(meta *logsink.Meta, format string, a ...any) (n int, err error) {
454 return 0, nil
455 }
456
457 type noopStructuredSinkWantStack struct{}
458
459 func (s noopStructuredSinkWantStack) WantStack(_ *logsink.Meta) bool { return true }
460 func (s noopStructuredSinkWantStack) Printf(meta *logsink.Meta, format string, a ...any) (n int, err error) {
461 return 0, nil
462 }
463
464 type stringStructuredSinkWantStack struct{}
465
466 func (s stringStructuredSinkWantStack) WantStack(_ *logsink.Meta) bool { return true }
467 func (s stringStructuredSinkWantStack) Printf(meta *logsink.Meta, format string, a ...any) (n int, err error) {
468 return len(meta.Stack.String()), nil
469 }
470
471
472
473
474
475 func TestStructuredTextWrapper(t *testing.T) {
476
477 originalTextSinks := logsink.TextSinks
478 defer func() {
479 logsink.TextSinks = originalTextSinks
480 }()
481
482
483
484 reference := fakeTextSink{enabled: true}
485 logsink.TextSinks = []logsink.Text{&reference}
486
487 meta := logsink.Meta{
488 Severity: logsink.Info,
489 File: "base/go/logsink_test.go",
490 Line: 1,
491 Time: time.Unix(1545321163, 0),
492 Thread: 1,
493 }
494 format := "test %d"
495 args := []any{1}
496
497 for _, test := range []struct {
498 name string
499 sinks []fakeTextSink
500 wantByteCount int
501 wantErr bool
502 }{
503 {
504 name: "no sinks",
505 sinks: []fakeTextSink{},
506 },
507 {
508 name: "single sink",
509 sinks: []fakeTextSink{
510 fakeTextSink{enabled: true, byteCount: 300},
511 },
512 wantByteCount: 300,
513 },
514 {
515 name: "multiple sinks",
516 sinks: []fakeTextSink{
517 fakeTextSink{enabled: true, byteCount: 100},
518 fakeTextSink{enabled: true, byteCount: 300},
519 fakeTextSink{enabled: true, byteCount: 200},
520 },
521 wantByteCount: 300,
522 },
523 {
524 name: "some sinks disabled",
525 sinks: []fakeTextSink{
526 fakeTextSink{enabled: true, byteCount: 100},
527 fakeTextSink{enabled: true, byteCount: 200},
528 fakeTextSink{},
529 fakeTextSink{},
530 },
531 wantByteCount: 200,
532 },
533 {
534 name: "all sinks disabled",
535 sinks: []fakeTextSink{
536 fakeTextSink{},
537 fakeTextSink{},
538 fakeTextSink{},
539 },
540 },
541 {
542 name: "error",
543 sinks: []fakeTextSink{
544 fakeTextSink{enabled: true, byteCount: 100},
545 fakeTextSink{enabled: true, err: errors.New("err")},
546 fakeTextSink{enabled: true, byteCount: 200},
547 },
548 wantErr: true,
549 },
550 } {
551 t.Run(test.name, func(t *testing.T) {
552 wrapper := logsink.StructuredTextWrapper{}
553 for i := range test.sinks {
554 wrapper.TextSinks = append(wrapper.TextSinks, &test.sinks[i])
555 }
556
557
558
559 m := meta
560 if _, err := logsink.Printf(&m, format, args); err != nil {
561 t.Fatalf("failed to write to reference sink: %v", err)
562 }
563
564
565
566 m = meta
567 n, err := wrapper.Printf(&m, format, args)
568
569 if gotErr := err != nil; gotErr != test.wantErr {
570 t.Fatalf("StructuredTextWrapper.Printf() returned err=%v, want err? %t", err, test.wantErr)
571 }
572
573
574 if err != nil {
575 return
576 }
577
578 if n != test.wantByteCount {
579 t.Fatalf("StructuredTextWrapper.Printf() returned n=%v, want %v", n, test.wantByteCount)
580 }
581
582 for i, sink := range test.sinks {
583 if sink.enabled {
584 if got, want := sink.calls, 1; got != want {
585 t.Fatalf("sinks[%v].calls = %d, want %d", i, got, want)
586 }
587
588 if diff := cmp.Diff(&meta, sink.gotMeta); diff != "" {
589 t.Errorf("sinks[%v].meta diff -want +got:\n%s", i, diff)
590 }
591
592 if got, want := sink.gotBytes, reference.gotBytes; bytes.Compare(got, want) != 0 {
593 t.Errorf("sinks[%v].bytes = %s, want %s", i, got, want)
594 }
595 } else {
596 if got, want := sink.calls, 0; got != want {
597 t.Fatalf("sinks[%v].calls = %d, want %d", i, got, want)
598 }
599 }
600 }
601 })
602 }
603 }
604
605 type fakeTextSink struct {
606
607 enabled bool
608
609 byteCount int
610
611 err error
612
613 gotMeta *logsink.Meta
614
615 gotBytes []byte
616
617 calls int
618 }
619
620 func (s *fakeTextSink) Enabled(meta *logsink.Meta) bool {
621 return s.enabled
622 }
623
624 func (s *fakeTextSink) Emit(meta *logsink.Meta, bytes []byte) (n int, err error) {
625 s.gotMeta = meta
626 s.gotBytes = bytes
627 s.calls++
628 return s.byteCount, s.err
629 }
630
View as plain text