1
2
3
4
5
6
7
8
9
10
11
12
13
14
15 package traceutil
16
17 import (
18 "bytes"
19 "context"
20 "fmt"
21 "io/ioutil"
22 "os"
23 "path/filepath"
24 "testing"
25 "time"
26
27 "go.uber.org/zap"
28 )
29
30 func TestGet(t *testing.T) {
31 traceForTest := &Trace{operation: "Test"}
32 tests := []struct {
33 name string
34 inputCtx context.Context
35 outputTrace *Trace
36 }{
37 {
38 name: "When the context does not have trace",
39 inputCtx: context.TODO(),
40 outputTrace: TODO(),
41 },
42 {
43 name: "When the context has trace",
44 inputCtx: context.WithValue(context.Background(), TraceKey, traceForTest),
45 outputTrace: traceForTest,
46 },
47 }
48
49 for _, tt := range tests {
50 t.Run(tt.name, func(t *testing.T) {
51 trace := Get(tt.inputCtx)
52 if trace == nil {
53 t.Errorf("Expected %v; Got nil", tt.outputTrace)
54 }
55 if trace.operation != tt.outputTrace.operation {
56 t.Errorf("Expected %v; Got %v", tt.outputTrace, trace)
57 }
58 })
59 }
60 }
61
62 func TestCreate(t *testing.T) {
63 var (
64 op = "Test"
65 steps = []string{"Step1, Step2"}
66 fields = []Field{
67 {"traceKey1", "traceValue1"},
68 {"traceKey2", "traceValue2"},
69 }
70 stepFields = []Field{
71 {"stepKey1", "stepValue2"},
72 {"stepKey2", "stepValue2"},
73 }
74 )
75
76 trace := New(op, nil, fields[0], fields[1])
77 if trace.operation != op {
78 t.Errorf("Expected %v; Got %v", op, trace.operation)
79 }
80 for i, f := range trace.fields {
81 if f.Key != fields[i].Key {
82 t.Errorf("Expected %v; Got %v", fields[i].Key, f.Key)
83 }
84 if f.Value != fields[i].Value {
85 t.Errorf("Expected %v; Got %v", fields[i].Value, f.Value)
86 }
87 }
88
89 for i, v := range steps {
90 trace.Step(v, stepFields[i])
91 }
92
93 for i, v := range trace.steps {
94 if steps[i] != v.msg {
95 t.Errorf("Expected %v; Got %v", steps[i], v.msg)
96 }
97 if stepFields[i].Key != v.fields[0].Key {
98 t.Errorf("Expected %v; Got %v", stepFields[i].Key, v.fields[0].Key)
99 }
100 if stepFields[i].Value != v.fields[0].Value {
101 t.Errorf("Expected %v; Got %v", stepFields[i].Value, v.fields[0].Value)
102 }
103 }
104 }
105
106 func TestLog(t *testing.T) {
107 tests := []struct {
108 name string
109 trace *Trace
110 fields []Field
111 expectedMsg []string
112 }{
113 {
114 name: "When dump all logs",
115 trace: &Trace{
116 operation: "Test",
117 startTime: time.Now().Add(-100 * time.Millisecond),
118 steps: []step{
119 {time: time.Now().Add(-80 * time.Millisecond), msg: "msg1"},
120 {time: time.Now().Add(-50 * time.Millisecond), msg: "msg2"},
121 },
122 },
123 expectedMsg: []string{
124 "msg1", "msg2",
125 },
126 },
127 {
128 name: "When trace has fields",
129 trace: &Trace{
130 operation: "Test",
131 startTime: time.Now().Add(-100 * time.Millisecond),
132 steps: []step{
133 {
134 time: time.Now().Add(-80 * time.Millisecond),
135 msg: "msg1",
136 fields: []Field{{"stepKey1", "stepValue1"}},
137 },
138 {
139 time: time.Now().Add(-50 * time.Millisecond),
140 msg: "msg2",
141 fields: []Field{{"stepKey2", "stepValue2"}},
142 },
143 },
144 },
145 fields: []Field{
146 {"traceKey1", "traceValue1"},
147 {"count", 1},
148 },
149 expectedMsg: []string{
150 "Test",
151 "msg1", "msg2",
152 "traceKey1:traceValue1", "count:1",
153 "stepKey1:stepValue1", "stepKey2:stepValue2",
154 "\"step_count\":2",
155 },
156 },
157 {
158 name: "When trace has subtrace",
159 trace: &Trace{
160 operation: "Test",
161 startTime: time.Now().Add(-100 * time.Millisecond),
162 steps: []step{
163 {
164 time: time.Now().Add(-80 * time.Millisecond),
165 msg: "msg1",
166 fields: []Field{{"stepKey1", "stepValue1"}},
167 },
168 {
169 fields: []Field{{"beginSubTrace", "true"}},
170 isSubTraceStart: true,
171 },
172 {
173 time: time.Now().Add(-50 * time.Millisecond),
174 msg: "submsg",
175 fields: []Field{{"subStepKey", "subStepValue"}},
176 },
177 {
178 fields: []Field{{"endSubTrace", "true"}},
179 isSubTraceEnd: true,
180 },
181 {
182 time: time.Now().Add(-30 * time.Millisecond),
183 msg: "msg2",
184 fields: []Field{{"stepKey2", "stepValue2"}},
185 },
186 },
187 },
188 fields: []Field{
189 {"traceKey1", "traceValue1"},
190 {"count", 1},
191 },
192 expectedMsg: []string{
193 "Test",
194 "msg1", "msg2", "submsg",
195 "traceKey1:traceValue1", "count:1",
196 "stepKey1:stepValue1", "stepKey2:stepValue2", "subStepKey:subStepValue",
197 "beginSubTrace:true", "endSubTrace:true",
198 "\"step_count\":3",
199 },
200 },
201 }
202
203 for _, tt := range tests {
204 t.Run(tt.name, func(t *testing.T) {
205 logPath := filepath.Join(os.TempDir(), fmt.Sprintf("test-log-%d", time.Now().UnixNano()))
206 defer os.RemoveAll(logPath)
207
208 lcfg := zap.NewProductionConfig()
209 lcfg.OutputPaths = []string{logPath}
210 lcfg.ErrorOutputPaths = []string{logPath}
211 lg, _ := lcfg.Build()
212
213 for _, f := range tt.fields {
214 tt.trace.AddField(f)
215 }
216 tt.trace.lg = lg
217 tt.trace.Log()
218 data, err := ioutil.ReadFile(logPath)
219 if err != nil {
220 t.Fatal(err)
221 }
222
223 for _, msg := range tt.expectedMsg {
224 if !bytes.Contains(data, []byte(msg)) {
225 t.Errorf("Expected to find %v in log", msg)
226 }
227 }
228 })
229 }
230 }
231
232 func TestLogIfLong(t *testing.T) {
233 tests := []struct {
234 name string
235 threshold time.Duration
236 trace *Trace
237 expectedMsg []string
238 }{
239 {
240 name: "When the duration is smaller than threshold",
241 threshold: time.Duration(200 * time.Millisecond),
242 trace: &Trace{
243 operation: "Test",
244 startTime: time.Now().Add(-100 * time.Millisecond),
245 steps: []step{
246 {time: time.Now().Add(-50 * time.Millisecond), msg: "msg1"},
247 {time: time.Now(), msg: "msg2"},
248 },
249 },
250 expectedMsg: []string{},
251 },
252 {
253 name: "When the duration is longer than threshold",
254 threshold: time.Duration(50 * time.Millisecond),
255 trace: &Trace{
256 operation: "Test",
257 startTime: time.Now().Add(-100 * time.Millisecond),
258 steps: []step{
259 {time: time.Now().Add(-50 * time.Millisecond), msg: "msg1"},
260 {time: time.Now(), msg: "msg2"},
261 },
262 },
263 expectedMsg: []string{
264 "msg1", "msg2",
265 },
266 },
267 {
268 name: "When not all steps are longer than step threshold",
269 threshold: time.Duration(50 * time.Millisecond),
270 trace: &Trace{
271 operation: "Test",
272 startTime: time.Now().Add(-100 * time.Millisecond),
273 steps: []step{
274 {time: time.Now(), msg: "msg1"},
275 {time: time.Now(), msg: "msg2"},
276 },
277 },
278 expectedMsg: []string{
279 "msg1",
280 },
281 },
282 }
283
284 for _, tt := range tests {
285 t.Run(tt.name, func(t *testing.T) {
286 logPath := filepath.Join(os.TempDir(), fmt.Sprintf("test-log-%d", time.Now().UnixNano()))
287 defer os.RemoveAll(logPath)
288
289 lcfg := zap.NewProductionConfig()
290 lcfg.OutputPaths = []string{logPath}
291 lcfg.ErrorOutputPaths = []string{logPath}
292 lg, _ := lcfg.Build()
293
294 tt.trace.lg = lg
295 tt.trace.LogIfLong(tt.threshold)
296 data, err := ioutil.ReadFile(logPath)
297 if err != nil {
298 t.Fatal(err)
299 }
300 for _, msg := range tt.expectedMsg {
301 if !bytes.Contains(data, []byte(msg)) {
302 t.Errorf("Expected to find %v in log", msg)
303 }
304 }
305 })
306 }
307 }
308
View as plain text