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