1/*
2Copyright 2019 The Kubernetes Authors.
3
4Licensed under the Apache License, Version 2.0 (the "License");
5you may not use this file except in compliance with the License.
6You may obtain a copy of the License at
7
8    http://www.apache.org/licenses/LICENSE-2.0
9
10Unless required by applicable law or agreed to in writing, software
11distributed under the License is distributed on an "AS IS" BASIS,
12WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13See the License for the specific language governing permissions and
14limitations under the License.
15*/
16
17package trace
18
19import (
20	"bytes"
21	"os"
22	"strings"
23	"testing"
24	"time"
25
26	"k8s.io/klog"
27)
28
29func TestStep(t *testing.T) {
30	tests := []struct {
31		name          string
32		inputString   string
33		expectedTrace *Trace
34	}{
35		{
36			name:        "When string is empty",
37			inputString: "",
38			expectedTrace: &Trace{
39				steps: []traceStep{
40					{stepTime: time.Now(), msg: ""},
41				},
42			},
43		},
44		{
45			name:        "When string is not empty",
46			inputString: "test2",
47			expectedTrace: &Trace{
48				steps: []traceStep{
49					{stepTime: time.Now(), msg: "test2"},
50				},
51			},
52		},
53	}
54
55	for _, tt := range tests {
56		t.Run(tt.name, func(t *testing.T) {
57			sampleTrace := &Trace{}
58			sampleTrace.Step(tt.inputString)
59			if sampleTrace.steps[0].msg != tt.expectedTrace.steps[0].msg {
60				t.Errorf("Expected %v \n Got %v \n", tt.expectedTrace, sampleTrace)
61			}
62		})
63	}
64}
65
66func TestTotalTime(t *testing.T) {
67	test := struct {
68		name       string
69		inputTrace *Trace
70	}{
71		name: "Test with current system time",
72		inputTrace: &Trace{
73			startTime: time.Now(),
74		},
75	}
76
77	t.Run(test.name, func(t *testing.T) {
78		got := test.inputTrace.TotalTime()
79		if got == 0 {
80			t.Errorf("Expected total time 0, got %d \n", got)
81		}
82	})
83}
84
85func TestLog(t *testing.T) {
86	tests := []struct {
87		name             string
88		msg              string
89		fields           []Field
90		expectedMessages []string
91		sampleTrace      *Trace
92	}{
93		{
94			name: "Check the log dump with 3 msg",
95			expectedMessages: []string{
96				"msg1", "msg2", "msg3",
97			},
98			sampleTrace: &Trace{
99				name: "Sample Trace",
100				steps: []traceStep{
101					{stepTime: time.Now(), msg: "msg1"},
102					{stepTime: time.Now(), msg: "msg2"},
103					{stepTime: time.Now(), msg: "msg3"},
104				},
105			},
106		},
107		{
108			name: "Check formatting",
109			expectedMessages: []string{
110				"URL:/api,count:3", "msg1 str:text,int:2,bool:false", "msg2 x:1",
111			},
112			sampleTrace: &Trace{
113				name:   "Sample Trace",
114				fields: []Field{{"URL", "/api"}, {"count", 3}},
115				steps: []traceStep{
116					{stepTime: time.Now(), msg: "msg1", fields: []Field{{"str", "text"}, {"int", 2}, {"bool", false}}},
117					{stepTime: time.Now(), msg: "msg2", fields: []Field{{"x", "1"}}},
118				},
119			},
120		},
121		{
122			name: "Check fixture formatted",
123			expectedMessages: []string{
124				"URL:/api,count:3", "msg1 str:text,int:2,bool:false", "msg2 x:1",
125			},
126			sampleTrace: fieldsTraceFixture(),
127		},
128	}
129
130	for _, test := range tests {
131		t.Run(test.name, func(t *testing.T) {
132			var buf bytes.Buffer
133			klog.SetOutput(&buf)
134			test.sampleTrace.Log()
135			for _, msg := range test.expectedMessages {
136				if !strings.Contains(buf.String(), msg) {
137					t.Errorf("\nMsg %q not found in log: \n%v\n", msg, buf.String())
138				}
139			}
140		})
141	}
142}
143
144func fieldsTraceFixture() *Trace {
145	trace := New("Sample Trace", Field{"URL", "/api"}, Field{"count", 3})
146	trace.Step("msg1", Field{"str", "text"}, Field{"int", 2}, Field{"bool", false})
147	trace.Step("msg2", Field{"x", "1"})
148	return trace
149}
150
151func TestLogIfLong(t *testing.T) {
152	currentTime := time.Now()
153	type mutate struct {
154		delay time.Duration
155		msg   string
156	}
157
158	tests := []*struct {
159		name             string
160		expectedMessages []string
161		sampleTrace      *Trace
162		threshold        time.Duration
163		mutateInfo       []mutate // mutateInfo contains the information to mutate step's time to simulate multiple tests without waiting.
164
165	}{
166		{
167			name: "When threshold is 500 and msg 2 has highest share",
168			expectedMessages: []string{
169				"msg2",
170			},
171			mutateInfo: []mutate{
172				{10, "msg1"},
173				{1000, "msg2"},
174				{0, "msg3"},
175			},
176			threshold: 500,
177		},
178		{
179			name: "When threshold is 10 and msg 3 has highest share",
180			expectedMessages: []string{
181				"msg3",
182			},
183			mutateInfo: []mutate{
184				{0, "msg1"},
185				{0, "msg2"},
186				{50, "msg3"},
187			},
188			threshold: 10,
189		},
190		{
191			name: "When threshold is 0 and all msg have same share",
192			expectedMessages: []string{
193				"msg1", "msg2", "msg3",
194			},
195			mutateInfo: []mutate{
196				{0, "msg1"},
197				{0, "msg2"},
198				{0, "msg3"},
199			},
200			threshold: 0,
201		},
202		{
203			name:             "When threshold is 20 and all msg 1 has highest share",
204			expectedMessages: []string{},
205			mutateInfo: []mutate{
206				{10, "msg1"},
207				{0, "msg2"},
208				{0, "msg3"},
209			},
210			threshold: 20,
211		},
212	}
213
214	for _, tt := range tests {
215		t.Run(tt.name, func(t *testing.T) {
216			var buf bytes.Buffer
217			klog.SetOutput(&buf)
218
219			tt.sampleTrace = New("Test trace")
220
221			for index, mod := range tt.mutateInfo {
222				tt.sampleTrace.Step(mod.msg)
223				tt.sampleTrace.steps[index].stepTime = currentTime.Add(mod.delay)
224			}
225
226			tt.sampleTrace.LogIfLong(tt.threshold)
227
228			for _, msg := range tt.expectedMessages {
229				if msg != "" && !strings.Contains(buf.String(), msg) {
230					t.Errorf("Msg %q expected in trace log: \n%v\n", msg, buf.String())
231				}
232			}
233		})
234	}
235}
236
237func ExampleTrace_Step() {
238	t := New("frobber")
239
240	time.Sleep(5 * time.Millisecond)
241	t.Step("reticulated splines") // took 5ms
242
243	time.Sleep(10 * time.Millisecond)
244	t.Step("sequenced particles") // took 10ms
245
246	klog.SetOutput(os.Stdout) // change output from stderr to stdout
247	t.Log()
248}
249