1
18
19 package binarylog
20
21 import (
22 "bytes"
23 "context"
24 "fmt"
25 "net"
26 "testing"
27 "time"
28
29 binlogpb "google.golang.org/grpc/binarylog/grpc_binarylog_v1"
30 "google.golang.org/grpc/codes"
31 "google.golang.org/grpc/status"
32 "google.golang.org/protobuf/proto"
33 "google.golang.org/protobuf/types/known/durationpb"
34 )
35
36 func (s) TestLog(t *testing.T) {
37 idGen.reset()
38 ml := NewTruncatingMethodLogger(10, 10)
39
40 buf := bytes.NewBuffer(nil)
41 ml.sink = newWriterSink(buf)
42
43 addr := "1.2.3.4"
44 port := 790
45 tcpAddr, _ := net.ResolveTCPAddr("tcp", fmt.Sprintf("%v:%d", addr, port))
46 addr6 := "2001:1db8:85a3::8a2e:1370:7334"
47 port6 := 796
48 tcpAddr6, _ := net.ResolveTCPAddr("tcp", fmt.Sprintf("[%v]:%d", addr6, port6))
49
50 testProtoMsg := &binlogpb.Message{
51 Length: 1,
52 Data: []byte{'a'},
53 }
54 testProtoBytes, _ := proto.Marshal(testProtoMsg)
55
56 testCases := []struct {
57 config LogEntryConfig
58 want *binlogpb.GrpcLogEntry
59 }{
60 {
61 config: &ClientHeader{
62 OnClientSide: false,
63 Header: map[string][]string{
64 "a": {"b", "bb"},
65 },
66 MethodName: "testservice/testmethod",
67 Authority: "test.service.io",
68 Timeout: 2*time.Second + 3*time.Nanosecond,
69 PeerAddr: tcpAddr,
70 },
71 want: &binlogpb.GrpcLogEntry{
72 Timestamp: nil,
73 CallId: 1,
74 SequenceIdWithinCall: 0,
75 Type: binlogpb.GrpcLogEntry_EVENT_TYPE_CLIENT_HEADER,
76 Logger: binlogpb.GrpcLogEntry_LOGGER_SERVER,
77 Payload: &binlogpb.GrpcLogEntry_ClientHeader{
78 ClientHeader: &binlogpb.ClientHeader{
79 Metadata: &binlogpb.Metadata{
80 Entry: []*binlogpb.MetadataEntry{
81 {Key: "a", Value: []byte{'b'}},
82 {Key: "a", Value: []byte{'b', 'b'}},
83 },
84 },
85 MethodName: "testservice/testmethod",
86 Authority: "test.service.io",
87 Timeout: &durationpb.Duration{
88 Seconds: 2,
89 Nanos: 3,
90 },
91 },
92 },
93 PayloadTruncated: false,
94 Peer: &binlogpb.Address{
95 Type: binlogpb.Address_TYPE_IPV4,
96 Address: addr,
97 IpPort: uint32(port),
98 },
99 },
100 },
101 {
102 config: &ClientHeader{
103 OnClientSide: false,
104 MethodName: "testservice/testmethod",
105 Authority: "test.service.io",
106 },
107 want: &binlogpb.GrpcLogEntry{
108 Timestamp: nil,
109 CallId: 1,
110 SequenceIdWithinCall: 0,
111 Type: binlogpb.GrpcLogEntry_EVENT_TYPE_CLIENT_HEADER,
112 Logger: binlogpb.GrpcLogEntry_LOGGER_SERVER,
113 Payload: &binlogpb.GrpcLogEntry_ClientHeader{
114 ClientHeader: &binlogpb.ClientHeader{
115 Metadata: &binlogpb.Metadata{},
116 MethodName: "testservice/testmethod",
117 Authority: "test.service.io",
118 },
119 },
120 PayloadTruncated: false,
121 },
122 },
123 {
124 config: &ServerHeader{
125 OnClientSide: true,
126 Header: map[string][]string{
127 "a": {"b", "bb"},
128 },
129 PeerAddr: tcpAddr6,
130 },
131 want: &binlogpb.GrpcLogEntry{
132 Timestamp: nil,
133 CallId: 1,
134 SequenceIdWithinCall: 0,
135 Type: binlogpb.GrpcLogEntry_EVENT_TYPE_SERVER_HEADER,
136 Logger: binlogpb.GrpcLogEntry_LOGGER_CLIENT,
137 Payload: &binlogpb.GrpcLogEntry_ServerHeader{
138 ServerHeader: &binlogpb.ServerHeader{
139 Metadata: &binlogpb.Metadata{
140 Entry: []*binlogpb.MetadataEntry{
141 {Key: "a", Value: []byte{'b'}},
142 {Key: "a", Value: []byte{'b', 'b'}},
143 },
144 },
145 },
146 },
147 PayloadTruncated: false,
148 Peer: &binlogpb.Address{
149 Type: binlogpb.Address_TYPE_IPV6,
150 Address: addr6,
151 IpPort: uint32(port6),
152 },
153 },
154 },
155 {
156 config: &ClientMessage{
157 OnClientSide: true,
158 Message: testProtoMsg,
159 },
160 want: &binlogpb.GrpcLogEntry{
161 Timestamp: nil,
162 CallId: 1,
163 SequenceIdWithinCall: 0,
164 Type: binlogpb.GrpcLogEntry_EVENT_TYPE_CLIENT_MESSAGE,
165 Logger: binlogpb.GrpcLogEntry_LOGGER_CLIENT,
166 Payload: &binlogpb.GrpcLogEntry_Message{
167 Message: &binlogpb.Message{
168 Length: uint32(len(testProtoBytes)),
169 Data: testProtoBytes,
170 },
171 },
172 PayloadTruncated: false,
173 Peer: nil,
174 },
175 },
176 {
177 config: &ServerMessage{
178 OnClientSide: false,
179 Message: testProtoMsg,
180 },
181 want: &binlogpb.GrpcLogEntry{
182 Timestamp: nil,
183 CallId: 1,
184 SequenceIdWithinCall: 0,
185 Type: binlogpb.GrpcLogEntry_EVENT_TYPE_SERVER_MESSAGE,
186 Logger: binlogpb.GrpcLogEntry_LOGGER_SERVER,
187 Payload: &binlogpb.GrpcLogEntry_Message{
188 Message: &binlogpb.Message{
189 Length: uint32(len(testProtoBytes)),
190 Data: testProtoBytes,
191 },
192 },
193 PayloadTruncated: false,
194 Peer: nil,
195 },
196 },
197 {
198 config: &ClientHalfClose{
199 OnClientSide: false,
200 },
201 want: &binlogpb.GrpcLogEntry{
202 Timestamp: nil,
203 CallId: 1,
204 SequenceIdWithinCall: 0,
205 Type: binlogpb.GrpcLogEntry_EVENT_TYPE_CLIENT_HALF_CLOSE,
206 Logger: binlogpb.GrpcLogEntry_LOGGER_SERVER,
207 Payload: nil,
208 PayloadTruncated: false,
209 Peer: nil,
210 },
211 },
212 {
213 config: &ServerTrailer{
214 OnClientSide: true,
215 Err: status.Errorf(codes.Unavailable, "test"),
216 PeerAddr: tcpAddr,
217 },
218 want: &binlogpb.GrpcLogEntry{
219 Timestamp: nil,
220 CallId: 1,
221 SequenceIdWithinCall: 0,
222 Type: binlogpb.GrpcLogEntry_EVENT_TYPE_SERVER_TRAILER,
223 Logger: binlogpb.GrpcLogEntry_LOGGER_CLIENT,
224 Payload: &binlogpb.GrpcLogEntry_Trailer{
225 Trailer: &binlogpb.Trailer{
226 Metadata: &binlogpb.Metadata{},
227 StatusCode: uint32(codes.Unavailable),
228 StatusMessage: "test",
229 StatusDetails: nil,
230 },
231 },
232 PayloadTruncated: false,
233 Peer: &binlogpb.Address{
234 Type: binlogpb.Address_TYPE_IPV4,
235 Address: addr,
236 IpPort: uint32(port),
237 },
238 },
239 },
240 {
241 config: &ServerTrailer{
242 OnClientSide: true,
243 },
244 want: &binlogpb.GrpcLogEntry{
245 Timestamp: nil,
246 CallId: 1,
247 SequenceIdWithinCall: 0,
248 Type: binlogpb.GrpcLogEntry_EVENT_TYPE_SERVER_TRAILER,
249 Logger: binlogpb.GrpcLogEntry_LOGGER_CLIENT,
250 Payload: &binlogpb.GrpcLogEntry_Trailer{
251 Trailer: &binlogpb.Trailer{
252 Metadata: &binlogpb.Metadata{},
253 StatusCode: uint32(codes.OK),
254 StatusMessage: "",
255 StatusDetails: nil,
256 },
257 },
258 PayloadTruncated: false,
259 Peer: nil,
260 },
261 },
262 {
263 config: &Cancel{
264 OnClientSide: true,
265 },
266 want: &binlogpb.GrpcLogEntry{
267 Timestamp: nil,
268 CallId: 1,
269 SequenceIdWithinCall: 0,
270 Type: binlogpb.GrpcLogEntry_EVENT_TYPE_CANCEL,
271 Logger: binlogpb.GrpcLogEntry_LOGGER_CLIENT,
272 Payload: nil,
273 PayloadTruncated: false,
274 Peer: nil,
275 },
276 },
277
278
279 {
280 config: &ClientHeader{
281 OnClientSide: false,
282 Header: map[string][]string{
283 "grpc-reserved": {"to be omitted"},
284 ":authority": {"to be omitted"},
285 "a": {"b", "bb"},
286 },
287 },
288 want: &binlogpb.GrpcLogEntry{
289 Timestamp: nil,
290 CallId: 1,
291 SequenceIdWithinCall: 0,
292 Type: binlogpb.GrpcLogEntry_EVENT_TYPE_CLIENT_HEADER,
293 Logger: binlogpb.GrpcLogEntry_LOGGER_SERVER,
294 Payload: &binlogpb.GrpcLogEntry_ClientHeader{
295 ClientHeader: &binlogpb.ClientHeader{
296 Metadata: &binlogpb.Metadata{
297 Entry: []*binlogpb.MetadataEntry{
298 {Key: "a", Value: []byte{'b'}},
299 {Key: "a", Value: []byte{'b', 'b'}},
300 },
301 },
302 },
303 },
304 PayloadTruncated: false,
305 },
306 },
307 {
308 config: &ServerHeader{
309 OnClientSide: true,
310 Header: map[string][]string{
311 "grpc-reserved": {"to be omitted"},
312 ":authority": {"to be omitted"},
313 "a": {"b", "bb"},
314 },
315 },
316 want: &binlogpb.GrpcLogEntry{
317 Timestamp: nil,
318 CallId: 1,
319 SequenceIdWithinCall: 0,
320 Type: binlogpb.GrpcLogEntry_EVENT_TYPE_SERVER_HEADER,
321 Logger: binlogpb.GrpcLogEntry_LOGGER_CLIENT,
322 Payload: &binlogpb.GrpcLogEntry_ServerHeader{
323 ServerHeader: &binlogpb.ServerHeader{
324 Metadata: &binlogpb.Metadata{
325 Entry: []*binlogpb.MetadataEntry{
326 {Key: "a", Value: []byte{'b'}},
327 {Key: "a", Value: []byte{'b', 'b'}},
328 },
329 },
330 },
331 },
332 PayloadTruncated: false,
333 },
334 },
335 }
336 for i, tc := range testCases {
337 buf.Reset()
338 tc.want.SequenceIdWithinCall = uint64(i + 1)
339 ml.Log(context.Background(), tc.config)
340 inSink := new(binlogpb.GrpcLogEntry)
341 if err := proto.Unmarshal(buf.Bytes()[4:], inSink); err != nil {
342 t.Errorf("failed to unmarshal bytes in sink to proto: %v", err)
343 continue
344 }
345 inSink.Timestamp = nil
346 if !proto.Equal(inSink, tc.want) {
347 t.Errorf("Log(%+v), in sink: %+v, want %+v", tc.config, inSink, tc.want)
348 }
349 }
350 }
351
352 func (s) TestTruncateMetadataNotTruncated(t *testing.T) {
353 testCases := []struct {
354 ml *TruncatingMethodLogger
355 mpPb *binlogpb.Metadata
356 }{
357 {
358 ml: NewTruncatingMethodLogger(maxUInt, maxUInt),
359 mpPb: &binlogpb.Metadata{
360 Entry: []*binlogpb.MetadataEntry{
361 {Key: "", Value: []byte{1}},
362 },
363 },
364 },
365 {
366 ml: NewTruncatingMethodLogger(2, maxUInt),
367 mpPb: &binlogpb.Metadata{
368 Entry: []*binlogpb.MetadataEntry{
369 {Key: "", Value: []byte{1}},
370 },
371 },
372 },
373 {
374 ml: NewTruncatingMethodLogger(1, maxUInt),
375 mpPb: &binlogpb.Metadata{
376 Entry: []*binlogpb.MetadataEntry{
377 {Key: "", Value: nil},
378 },
379 },
380 },
381 {
382 ml: NewTruncatingMethodLogger(2, maxUInt),
383 mpPb: &binlogpb.Metadata{
384 Entry: []*binlogpb.MetadataEntry{
385 {Key: "", Value: []byte{1, 1}},
386 },
387 },
388 },
389 {
390 ml: NewTruncatingMethodLogger(2, maxUInt),
391 mpPb: &binlogpb.Metadata{
392 Entry: []*binlogpb.MetadataEntry{
393 {Key: "", Value: []byte{1}},
394 {Key: "", Value: []byte{1}},
395 },
396 },
397 },
398
399
400 {
401 ml: NewTruncatingMethodLogger(1, maxUInt),
402 mpPb: &binlogpb.Metadata{
403 Entry: []*binlogpb.MetadataEntry{
404 {Key: "", Value: []byte{1}},
405 {Key: "grpc-trace-bin", Value: []byte("some.trace.key")},
406 },
407 },
408 },
409 }
410
411 for i, tc := range testCases {
412 truncated := tc.ml.truncateMetadata(tc.mpPb)
413 if truncated {
414 t.Errorf("test case %v, returned truncated, want not truncated", i)
415 }
416 }
417 }
418
419 func (s) TestTruncateMetadataTruncated(t *testing.T) {
420 testCases := []struct {
421 ml *TruncatingMethodLogger
422 mpPb *binlogpb.Metadata
423
424 entryLen int
425 }{
426 {
427 ml: NewTruncatingMethodLogger(2, maxUInt),
428 mpPb: &binlogpb.Metadata{
429 Entry: []*binlogpb.MetadataEntry{
430 {Key: "", Value: []byte{1, 1, 1}},
431 },
432 },
433 entryLen: 0,
434 },
435 {
436 ml: NewTruncatingMethodLogger(2, maxUInt),
437 mpPb: &binlogpb.Metadata{
438 Entry: []*binlogpb.MetadataEntry{
439 {Key: "", Value: []byte{1}},
440 {Key: "", Value: []byte{1}},
441 {Key: "", Value: []byte{1}},
442 },
443 },
444 entryLen: 2,
445 },
446 {
447 ml: NewTruncatingMethodLogger(2, maxUInt),
448 mpPb: &binlogpb.Metadata{
449 Entry: []*binlogpb.MetadataEntry{
450 {Key: "", Value: []byte{1, 1}},
451 {Key: "", Value: []byte{1}},
452 },
453 },
454 entryLen: 1,
455 },
456 {
457 ml: NewTruncatingMethodLogger(2, maxUInt),
458 mpPb: &binlogpb.Metadata{
459 Entry: []*binlogpb.MetadataEntry{
460 {Key: "", Value: []byte{1}},
461 {Key: "", Value: []byte{1, 1}},
462 },
463 },
464 entryLen: 1,
465 },
466 }
467
468 for i, tc := range testCases {
469 truncated := tc.ml.truncateMetadata(tc.mpPb)
470 if !truncated {
471 t.Errorf("test case %v, returned not truncated, want truncated", i)
472 continue
473 }
474 if len(tc.mpPb.Entry) != tc.entryLen {
475 t.Errorf("test case %v, entry length: %v, want: %v", i, len(tc.mpPb.Entry), tc.entryLen)
476 }
477 }
478 }
479
480 func (s) TestTruncateMessageNotTruncated(t *testing.T) {
481 testCases := []struct {
482 ml *TruncatingMethodLogger
483 msgPb *binlogpb.Message
484 }{
485 {
486 ml: NewTruncatingMethodLogger(maxUInt, maxUInt),
487 msgPb: &binlogpb.Message{
488 Data: []byte{1},
489 },
490 },
491 {
492 ml: NewTruncatingMethodLogger(maxUInt, 3),
493 msgPb: &binlogpb.Message{
494 Data: []byte{1, 1},
495 },
496 },
497 {
498 ml: NewTruncatingMethodLogger(maxUInt, 2),
499 msgPb: &binlogpb.Message{
500 Data: []byte{1, 1},
501 },
502 },
503 }
504
505 for i, tc := range testCases {
506 truncated := tc.ml.truncateMessage(tc.msgPb)
507 if truncated {
508 t.Errorf("test case %v, returned truncated, want not truncated", i)
509 }
510 }
511 }
512
513 func (s) TestTruncateMessageTruncated(t *testing.T) {
514 testCases := []struct {
515 ml *TruncatingMethodLogger
516 msgPb *binlogpb.Message
517
518 oldLength uint32
519 }{
520 {
521 ml: NewTruncatingMethodLogger(maxUInt, 2),
522 msgPb: &binlogpb.Message{
523 Length: 3,
524 Data: []byte{1, 1, 1},
525 },
526 oldLength: 3,
527 },
528 }
529
530 for i, tc := range testCases {
531 truncated := tc.ml.truncateMessage(tc.msgPb)
532 if !truncated {
533 t.Errorf("test case %v, returned not truncated, want truncated", i)
534 continue
535 }
536 if len(tc.msgPb.Data) != int(tc.ml.messageMaxLen) {
537 t.Errorf("test case %v, message length: %v, want: %v", i, len(tc.msgPb.Data), tc.ml.messageMaxLen)
538 }
539 if tc.msgPb.Length != tc.oldLength {
540 t.Errorf("test case %v, message.Length field: %v, want: %v", i, tc.msgPb.Length, tc.oldLength)
541 }
542 }
543 }
544
View as plain text