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