1
16
17 package trace
18
19 import (
20 "bytes"
21 "context"
22 "flag"
23 "os"
24 "strings"
25 "testing"
26 "time"
27
28 "k8s.io/klog/v2"
29 )
30
31 func init() {
32 klog.InitFlags(flag.CommandLine)
33 flag.CommandLine.Lookup("logtostderr").Value.Set("false")
34 flag.CommandLine.Lookup("v").Value.Set("2")
35 }
36
37 func TestStep(t *testing.T) {
38 tests := []struct {
39 name string
40 inputString string
41 expectedTrace *Trace
42 }{
43 {
44 name: "When string is empty",
45 inputString: "",
46 expectedTrace: &Trace{
47 traceItems: []traceItem{
48 traceStep{stepTime: time.Now(), msg: ""},
49 },
50 },
51 },
52 {
53 name: "When string is not empty",
54 inputString: "test2",
55 expectedTrace: &Trace{
56 traceItems: []traceItem{
57 traceStep{stepTime: time.Now(), msg: "test2"},
58 },
59 },
60 },
61 }
62
63 for _, tt := range tests {
64 t.Run(tt.name, func(t *testing.T) {
65 sampleTrace := &Trace{}
66 sampleTrace.Step(tt.inputString)
67 if sampleTrace.traceItems[0].(traceStep).msg != tt.expectedTrace.traceItems[0].(traceStep).msg {
68 t.Errorf("Expected %v \n Got %v \n", tt.expectedTrace, sampleTrace)
69 }
70 })
71 }
72 }
73
74 func TestNestedTrace(t *testing.T) {
75 tests := []struct {
76 name string
77 inputString string
78 expectedTrace *Trace
79 }{
80 {
81 name: "Empty string",
82 inputString: "",
83 expectedTrace: &Trace{
84 traceItems: []traceItem{
85 &Trace{startTime: time.Now(), name: ""},
86 },
87 },
88 },
89 {
90 name: "Non-empty string",
91 inputString: "Inner trace",
92 expectedTrace: &Trace{
93 traceItems: []traceItem{
94 &Trace{
95 startTime: time.Now(),
96 name: "Inner trace",
97 traceItems: []traceItem{
98 &Trace{name: "Inner trace"},
99 },
100 },
101 },
102 },
103 },
104 }
105
106 for _, tt := range tests {
107 t.Run(tt.name, func(t *testing.T) {
108 sampleTrace := &Trace{}
109 innerSampleTrace := sampleTrace.Nest(tt.inputString)
110 innerSampleTrace.Nest(tt.inputString)
111 if sampleTrace.traceItems[0].(*Trace).name != tt.expectedTrace.traceItems[0].(*Trace).name {
112 t.Errorf("Expected %v \n Got %v \n", tt.expectedTrace, sampleTrace)
113 }
114 })
115 }
116 }
117
118 func TestTotalTime(t *testing.T) {
119 test := struct {
120 name string
121 inputTrace *Trace
122 }{
123 name: "Test with current system time",
124 inputTrace: &Trace{
125 startTime: time.Now(),
126 },
127 }
128
129 t.Run(test.name, func(t *testing.T) {
130 got := test.inputTrace.TotalTime()
131 if got == 0 {
132 t.Errorf("Expected total time 0, got %d \n", got)
133 }
134 })
135 }
136
137 func TestLog(t *testing.T) {
138 tests := []struct {
139 name string
140 msg string
141 fields []Field
142 expectedMessages []string
143 sampleTrace *Trace
144 verbosity klog.Level
145 }{
146 {
147 name: "Check the log dump with 3 msg",
148 expectedMessages: []string{
149 "msg1", "msg2", "msg3",
150 },
151 sampleTrace: &Trace{
152 name: "Sample Trace",
153 traceItems: []traceItem{
154 &traceStep{stepTime: time.Now(), msg: "msg1"},
155 &traceStep{stepTime: time.Now(), msg: "msg2"},
156 &traceStep{stepTime: time.Now(), msg: "msg3"},
157 },
158 },
159 },
160 {
161 name: "Check formatting",
162 expectedMessages: []string{
163 "URL:/api,count:3", `"msg1" str:text,int:2,bool:false`, `"msg2" x:1`,
164 },
165 sampleTrace: &Trace{
166 name: "Sample Trace",
167 fields: []Field{{"URL", "/api"}, {"count", 3}},
168 traceItems: []traceItem{
169 &traceStep{stepTime: time.Now(), msg: "msg1", fields: []Field{{"str", "text"}, {"int", 2}, {"bool",
170 false}}},
171 &traceStep{stepTime: time.Now(), msg: "msg2", fields: []Field{{"x", "1"}}},
172 },
173 },
174 },
175 {
176 name: "Check fixture formatted",
177 expectedMessages: []string{
178 "URL:/api,count:3", `"msg1" str:text,int:2,bool:false`, `"msg2" x:1`,
179 },
180 sampleTrace: fieldsTraceFixture(),
181 },
182 {
183 name: "Check that logs are not dumped if verbosity < 2",
184 verbosity: 1,
185 expectedMessages: []string{},
186 sampleTrace: fieldsTraceFixture(),
187 },
188 }
189
190 for _, test := range tests {
191 t.Run(test.name, func(t *testing.T) {
192 var buf bytes.Buffer
193 klog.SetOutput(&buf)
194
195 if test.verbosity > 0 {
196 orig := klogV
197 klogV = func(l klog.Level) bool {
198 return l <= test.verbosity
199 }
200 defer func() {
201 klogV = orig
202 }()
203 }
204
205 test.sampleTrace.Log()
206
207 if len(test.expectedMessages) == 0 && buf.Len() != 0 {
208 t.Errorf("\nNo message expected in trace log: \n%v\n", buf.String())
209 }
210
211 for _, msg := range test.expectedMessages {
212 if !strings.Contains(buf.String(), msg) {
213 t.Errorf("\nMsg %q not found in log: \n%v\n", msg, buf.String())
214 }
215 }
216 })
217 }
218 }
219
220 func TestNestedTraceLog(t *testing.T) {
221 currentTime := time.Now()
222 tests := []struct {
223 name string
224 msg string
225 fields []Field
226 expectedMessages []string
227 sampleTrace *Trace
228 }{
229 {
230 name: "Check the log dump with 3 nestedTraces",
231 expectedMessages: []string{
232 "Sample Trace", "msg1", "msg2", "msg3",
233 },
234 sampleTrace: &Trace{
235 name: "Sample Trace",
236 traceItems: []traceItem{
237 &Trace{startTime: currentTime, endTime: ¤tTime, name: "msg1"},
238 &Trace{startTime: currentTime, endTime: ¤tTime, name: "msg2"},
239 &Trace{startTime: currentTime, endTime: ¤tTime, name: "msg3"},
240 },
241 },
242 },
243 {
244 name: "Check the log dump with 3 nestedTraces and steps",
245 expectedMessages: []string{
246 "Sample Trace", "msg1", "msg2", "msg3", "step1", "step2", "step3",
247 },
248 sampleTrace: &Trace{
249 name: "Sample Trace",
250 traceItems: []traceItem{
251 &Trace{startTime: currentTime, endTime: ¤tTime, name: "msg1"},
252 &Trace{startTime: currentTime, endTime: ¤tTime, name: "msg2"},
253 &Trace{startTime: currentTime, endTime: ¤tTime, name: "msg3"},
254 &traceStep{stepTime: currentTime, msg: "step1"},
255 &traceStep{stepTime: currentTime, msg: "step2"},
256 &traceStep{stepTime: currentTime, msg: "step3"},
257 },
258 },
259 },
260 {
261 name: "Check the log dump with nestedTrace with fields",
262 expectedMessages: []string{
263 "Sample Trace", `"msg1" str:text,int:2,bool:false`,
264 },
265 sampleTrace: &Trace{
266 name: "Sample Trace",
267 traceItems: []traceItem{
268 &Trace{
269 startTime: currentTime,
270 endTime: ¤tTime,
271 name: "msg1", fields: []Field{
272 {"str", "text"},
273 {"int", 2},
274 {"bool", false}}},
275 },
276 },
277 },
278 {
279 name: "Check the log dump with doubly nestedTrace",
280 expectedMessages: []string{
281 "Sample Trace", "msg1", "nested1",
282 },
283 sampleTrace: &Trace{
284 name: "Sample Trace",
285 traceItems: []traceItem{
286 &Trace{
287 startTime: currentTime,
288 endTime: ¤tTime,
289 name: "msg1",
290 traceItems: []traceItem{&Trace{name: "nested1", startTime: currentTime, endTime: ¤tTime}},
291 },
292 },
293 },
294 },
295 }
296 for _, test := range tests {
297 t.Run(test.name, func(t *testing.T) {
298 var buf bytes.Buffer
299 klog.SetOutput(&buf)
300 test.sampleTrace.Log()
301 for _, msg := range test.expectedMessages {
302 if !strings.Contains(buf.String(), msg) {
303 t.Errorf("\nMsg %q not found in log: \n%v\n", msg, buf.String())
304 }
305 }
306 })
307 }
308 }
309
310 func fieldsTraceFixture() *Trace {
311 trace := New("Sample Trace", Field{"URL", "/api"}, Field{"count", 3})
312 trace.Step("msg1", Field{"str", "text"}, Field{"int", 2}, Field{"bool", false})
313 trace.Step("msg2", Field{"x", "1"})
314 return trace
315 }
316
317 func TestLogIfLong(t *testing.T) {
318 currentTime := time.Now()
319 type mutate struct {
320 delay time.Duration
321 msg string
322 }
323
324 tests := []*struct {
325 name string
326 expectedMessages []string
327 sampleTrace *Trace
328 threshold time.Duration
329 mutateInfo []mutate
330
331 }{
332 {
333 name: "When threshold is 500 and msg 2 has highest share",
334 expectedMessages: []string{
335 "msg2",
336 },
337 mutateInfo: []mutate{
338 {10, "msg1"},
339 {1000, "msg2"},
340 {0, "msg3"},
341 },
342 threshold: 500,
343 },
344 {
345 name: "When threshold is 10 and msg 3 has highest share",
346 expectedMessages: []string{
347 "msg3",
348 },
349 mutateInfo: []mutate{
350 {0, "msg1"},
351 {0, "msg2"},
352 {50, "msg3"},
353 },
354 threshold: 10,
355 },
356 {
357 name: "When threshold is 0 and all msg have same share",
358 expectedMessages: []string{
359 "msg1", "msg2", "msg3",
360 },
361 mutateInfo: []mutate{
362 {0, "msg1"},
363 {0, "msg2"},
364 {0, "msg3"},
365 },
366 threshold: 0,
367 },
368 {
369 name: "When threshold is 20 and all msg 1 has highest share",
370 expectedMessages: []string{},
371 mutateInfo: []mutate{
372 {10, "msg1"},
373 {0, "msg2"},
374 {0, "msg3"},
375 },
376 threshold: 20,
377 },
378 }
379
380 for _, tt := range tests {
381 t.Run(tt.name, func(t *testing.T) {
382 var buf bytes.Buffer
383 klog.SetOutput(&buf)
384
385 tt.sampleTrace = New("Test trace")
386 for _, mod := range tt.mutateInfo {
387 tt.sampleTrace.traceItems = append(tt.sampleTrace.traceItems,
388 &traceStep{stepTime: currentTime.Add(mod.delay), msg: mod.msg})
389 }
390
391 tt.sampleTrace.LogIfLong(tt.threshold)
392
393 for _, msg := range tt.expectedMessages {
394 if msg != "" && !strings.Contains(buf.String(), msg) {
395 t.Errorf("Msg %q expected in trace log: \n%v\n", msg, buf.String())
396 }
397 }
398 })
399 }
400 }
401
402 func TestLogNestedTrace(t *testing.T) {
403 twoHundred := 200 * time.Millisecond
404 five := 5 * time.Millisecond
405 currentTime := time.Now()
406
407 tests := []struct {
408 name string
409 expectedMsgs []string
410 unexpectedMsg []string
411 trace *Trace
412 verbosity klog.Level
413 }{
414 {
415 name: "Log nested trace when it surpasses threshold",
416 expectedMsgs: []string{"inner1"},
417 unexpectedMsg: []string{"msg"},
418 trace: &Trace{
419 name: "msg",
420 startTime: currentTime.Add(10),
421 traceItems: []traceItem{
422 &Trace{
423 name: "inner1",
424 threshold: &five,
425 startTime: currentTime.Add(-10 * time.Millisecond),
426 endTime: ¤tTime,
427 },
428 },
429 },
430 },
431 {
432 name: "Log inner nested trace when it surpasses threshold",
433 expectedMsgs: []string{"inner2"},
434 unexpectedMsg: []string{"msg", "inner1"},
435 trace: &Trace{
436 name: "msg",
437 startTime: currentTime.Add(10),
438 traceItems: []traceItem{
439 &Trace{
440 name: "inner1",
441 threshold: &five,
442 startTime: currentTime.Add(-1 * time.Millisecond),
443 endTime: ¤tTime,
444 traceItems: []traceItem{
445 &Trace{
446 name: "inner2",
447 threshold: &five,
448 startTime: currentTime.Add(-10 * time.Millisecond),
449 endTime: ¤tTime,
450 },
451 },
452 },
453 },
454 },
455 },
456 {
457 name: "Log inner nested trace when it surpasses threshold and surrounding trace not ended",
458 expectedMsgs: []string{"inner2"},
459 unexpectedMsg: []string{"msg", "inner1"},
460 trace: &Trace{
461 name: "msg",
462 startTime: currentTime.Add(10),
463 traceItems: []traceItem{
464 &Trace{
465 name: "inner1",
466 threshold: &five,
467 traceItems: []traceItem{
468 &Trace{
469 name: "inner2",
470 threshold: &five,
471 startTime: currentTime.Add(-10 * time.Millisecond),
472 endTime: ¤tTime,
473 },
474 },
475 },
476 },
477 },
478 },
479 {
480 name: "Do not log nested trace that does not surpass threshold",
481 expectedMsgs: []string{"msg", "inner2"},
482 unexpectedMsg: []string{"inner1"},
483 trace: &Trace{
484 name: "msg",
485 startTime: currentTime.Add(-300 * time.Millisecond),
486 traceItems: []traceItem{
487 &Trace{
488 name: "inner1",
489 threshold: &five,
490 startTime: currentTime.Add(-1 * time.Millisecond),
491 endTime: ¤tTime,
492 traceItems: []traceItem{
493 &Trace{
494 name: "inner2",
495 threshold: &five,
496 startTime: currentTime.Add(-10 * time.Millisecond),
497 endTime: ¤tTime,
498 },
499 },
500 },
501 },
502 },
503 },
504 {
505 name: "Log all nested traces that surpass threshold",
506 expectedMsgs: []string{"inner1", "inner2"},
507 unexpectedMsg: []string{"msg"},
508 trace: &Trace{
509 name: "msg",
510 startTime: currentTime.Add(10),
511 traceItems: []traceItem{
512 &Trace{
513 name: "inner1",
514 threshold: &five,
515 startTime: currentTime.Add(-10 * time.Millisecond),
516 endTime: ¤tTime,
517 traceItems: []traceItem{
518 &Trace{
519 name: "inner2",
520 threshold: &five,
521 startTime: currentTime.Add(-10 * time.Millisecond),
522 endTime: ¤tTime,
523 },
524 },
525 },
526 },
527 },
528 },
529 {
530 name: "Log all nested traces that surpass threshold and their children if klog verbosity is >= 4",
531 expectedMsgs: []string{"inner1", "inner2"},
532 unexpectedMsg: []string{"msg"},
533 verbosity: 4,
534 trace: &Trace{
535 name: "msg",
536 startTime: currentTime.Add(10),
537 traceItems: []traceItem{
538 &Trace{
539 name: "inner1",
540 threshold: &five,
541 startTime: currentTime.Add(-10 * time.Millisecond),
542 endTime: ¤tTime,
543 traceItems: []traceItem{
544 &Trace{
545 name: "inner2",
546 threshold: &twoHundred,
547 startTime: currentTime.Add(-10 * time.Millisecond),
548 endTime: ¤tTime,
549 },
550 },
551 },
552 },
553 },
554 },
555 }
556
557 for _, tt := range tests {
558 t.Run(tt.name, func(t *testing.T) {
559 var buf bytes.Buffer
560 klog.SetOutput(&buf)
561
562 if tt.verbosity > 0 {
563 orig := klogV
564 klogV = func(l klog.Level) bool {
565 return l <= tt.verbosity
566 }
567 defer func() {
568 klogV = orig
569 }()
570 }
571
572 tt.trace.LogIfLong(twoHundred)
573
574 for _, msg := range tt.expectedMsgs {
575 if msg != "" && !strings.Contains(buf.String(), msg) {
576 t.Errorf("Msg %q expected in trace log: \n%v\n", msg, buf.String())
577 }
578 }
579
580 for _, msg := range tt.unexpectedMsg {
581 if msg != "" && strings.Contains(buf.String(), msg) {
582 t.Errorf("Msg %q not expected in trace log: \n%v\n", msg, buf.String())
583 }
584 }
585 })
586
587 }
588 }
589
590 func TestStepThreshold(t *testing.T) {
591
592 thousandMs := 1000 * time.Millisecond
593 sixHundred := 600 * time.Millisecond
594 hundredMs := 100 * time.Millisecond
595 twoThousandMs := 1200 * time.Millisecond
596
597 tests := []struct {
598 name string
599 inputTrace *Trace
600 expectedThreshold time.Duration
601 }{
602 {
603 name: "Trace with nested traces",
604 inputTrace: &Trace{
605 threshold: &thousandMs,
606 traceItems: []traceItem{
607 traceStep{msg: "trace 1"},
608 traceStep{msg: "trace 2"},
609 &Trace{threshold: &sixHundred},
610 &Trace{name: "msg 1"},
611 },
612 },
613 expectedThreshold: 100 * time.Millisecond,
614 },
615 {
616 name: "Trace with nested traces",
617 inputTrace: &Trace{
618 threshold: &thousandMs,
619 traceItems: []traceItem{
620 traceStep{msg: "trace 1"},
621 traceStep{msg: "trace 2"},
622 &Trace{threshold: &sixHundred},
623 &Trace{name: "msg 1", threshold: &hundredMs},
624 },
625 },
626 expectedThreshold: 100 * time.Millisecond,
627 },
628 {
629 name: "Trace with nested traces with a large threshold",
630 inputTrace: &Trace{
631 threshold: &thousandMs,
632 traceItems: []traceItem{
633 &Trace{threshold: &twoThousandMs},
634 },
635 },
636 expectedThreshold: 125 * time.Millisecond,
637 },
638 }
639
640 for _, tt := range tests {
641 actualThreshold := *tt.inputTrace.calculateStepThreshold()
642 if actualThreshold != tt.expectedThreshold {
643 t.Errorf("Expecting %v threshold but got %v", tt.expectedThreshold, actualThreshold)
644 }
645 }
646 }
647
648 func TestParentEndedBeforeChild(t *testing.T) {
649 var buf bytes.Buffer
650 klog.SetOutput(&buf)
651 parent := New("foo")
652 for i := 0; i < 1000; i++ {
653 go func(parent *Trace) {
654 child := parent.Nest("bar")
655 child.Step("hello")
656 child.LogIfLong(0 * time.Second)
657 }(parent)
658 }
659 parent.Step("world")
660 parent.LogIfLong(0 * time.Second)
661 }
662
663 func TestContext(t *testing.T) {
664 ctx := context.Background()
665
666 trace1 := FromContext(ctx).Nest("op1")
667 ctx = ContextWithTrace(ctx, trace1)
668 defer trace1.Log()
669 func(ctx context.Context) {
670 trace2 := FromContext(ctx).Nest("op2")
671 defer trace2.Log()
672 }(ctx)
673 if len(trace1.traceItems) != 1 {
674 t.Fatalf("expected len(trace1.traceItems) == 1, but got %d", len(trace1.traceItems))
675 }
676 nested, ok := trace1.traceItems[0].(*Trace)
677 if !ok {
678 t.Fatal("expected trace1.traceItems[0] to be a nested trace")
679 }
680 if nested.name != "op2" {
681 t.Errorf("expected trace named op2 to be nested in op1, but got %s", nested.name)
682 }
683 }
684
685 func ExampleTrace_Step() {
686 t := New("frobber")
687
688 time.Sleep(5 * time.Millisecond)
689 t.Step("reticulated splines")
690
691 time.Sleep(10 * time.Millisecond)
692 t.Step("sequenced particles")
693
694 klog.SetOutput(os.Stdout)
695 t.Log()
696 }
697
View as plain text