1 package grpc_zap_test
2
3 import (
4 "io"
5 "runtime"
6 "strings"
7 "testing"
8 "time"
9
10 grpc_middleware "github.com/grpc-ecosystem/go-grpc-middleware"
11 grpc_zap "github.com/grpc-ecosystem/go-grpc-middleware/logging/zap"
12 grpc_ctxtags "github.com/grpc-ecosystem/go-grpc-middleware/tags"
13 pb_testproto "github.com/grpc-ecosystem/go-grpc-middleware/testing/testproto"
14 "github.com/stretchr/testify/assert"
15 "github.com/stretchr/testify/require"
16 "github.com/stretchr/testify/suite"
17 "go.uber.org/zap"
18 "go.uber.org/zap/zapcore"
19 "google.golang.org/grpc"
20 "google.golang.org/grpc/codes"
21 )
22
23 func customCodeToLevel(c codes.Code) zapcore.Level {
24 if c == codes.Unauthenticated {
25
26 return zap.DPanicLevel
27 }
28 level := grpc_zap.DefaultCodeToLevel(c)
29 return level
30 }
31
32 func TestZapLoggingSuite(t *testing.T) {
33 if strings.HasPrefix(runtime.Version(), "go1.7") {
34 t.Skipf("Skipping due to json.RawMessage incompatibility with go1.7")
35 return
36 }
37
38 for _, tcase := range []struct {
39 timestampFormat string
40 }{
41 {
42 timestampFormat: time.RFC3339,
43 },
44 {
45 timestampFormat: "2006-01-02",
46 },
47 } {
48 opts := []grpc_zap.Option{
49 grpc_zap.WithLevels(customCodeToLevel),
50 grpc_zap.WithTimestampFormat(tcase.timestampFormat),
51 }
52 b := newBaseZapSuite(t)
53 b.timestampFormat = tcase.timestampFormat
54 b.InterceptorTestSuite.ServerOpts = []grpc.ServerOption{
55 grpc_middleware.WithStreamServerChain(
56 grpc_ctxtags.StreamServerInterceptor(grpc_ctxtags.WithFieldExtractor(grpc_ctxtags.CodeGenRequestFieldExtractor)),
57 grpc_zap.StreamServerInterceptor(b.log, opts...)),
58 grpc_middleware.WithUnaryServerChain(
59 grpc_ctxtags.UnaryServerInterceptor(grpc_ctxtags.WithFieldExtractor(grpc_ctxtags.CodeGenRequestFieldExtractor)),
60 grpc_zap.UnaryServerInterceptor(b.log, opts...)),
61 }
62 suite.Run(t, &zapServerSuite{b})
63 }
64 }
65
66 type zapServerSuite struct {
67 *zapBaseSuite
68 }
69
70 func (s *zapServerSuite) TestPing_WithCustomTags() {
71 deadline := time.Now().Add(3 * time.Second)
72 _, err := s.Client.Ping(s.DeadlineCtx(deadline), goodPing)
73 require.NoError(s.T(), err, "there must be not be an error on a successful call")
74
75 msgs := s.getOutputJSONs()
76 require.Len(s.T(), msgs, 2, "two log statements should be logged")
77 for _, m := range msgs {
78 assert.Equal(s.T(), m["grpc.service"], "mwitkow.testproto.TestService", "all lines must contain service name")
79 assert.Equal(s.T(), m["grpc.method"], "Ping", "all lines must contain method name")
80 assert.Equal(s.T(), m["span.kind"], "server", "all lines must contain the kind of call (server)")
81 assert.Equal(s.T(), m["custom_tags.string"], "something", "all lines must contain `custom_tags.string`")
82 assert.Equal(s.T(), m["grpc.request.value"], "something", "all lines must contain fields extracted")
83 assert.Equal(s.T(), m["custom_field"], "custom_value", "all lines must contain `custom_field`")
84
85 assert.Contains(s.T(), m, "custom_tags.int", "all lines must contain `custom_tags.int`")
86 require.Contains(s.T(), m, "grpc.start_time", "all lines must contain the start time")
87 _, err := time.Parse(s.timestampFormat, m["grpc.start_time"].(string))
88 assert.NoError(s.T(), err, "should be able to parse start time")
89
90 require.Contains(s.T(), m, "grpc.request.deadline", "all lines must contain the deadline of the call")
91 _, err = time.Parse(s.timestampFormat, m["grpc.request.deadline"].(string))
92 require.NoError(s.T(), err, "should be able to parse deadline")
93 assert.Equal(s.T(), m["grpc.request.deadline"], deadline.Format(s.timestampFormat), "should have the same deadline that was set by the caller")
94 }
95
96 assert.Equal(s.T(), msgs[0]["msg"], "some ping", "handler's message must contain user message")
97
98 assert.Equal(s.T(), msgs[1]["msg"], "finished unary call with code OK", "handler's message must contain user message")
99 assert.Equal(s.T(), msgs[1]["level"], "info", "must be logged at info level")
100 assert.Contains(s.T(), msgs[1], "grpc.time_ms", "interceptor log statement should contain execution time")
101 }
102
103 func (s *zapServerSuite) TestPingError_WithCustomLevels() {
104 for _, tcase := range []struct {
105 code codes.Code
106 level zapcore.Level
107 msg string
108 }{
109 {
110 code: codes.Internal,
111 level: zap.ErrorLevel,
112 msg: "Internal must remap to ErrorLevel in DefaultCodeToLevel",
113 },
114 {
115 code: codes.NotFound,
116 level: zap.InfoLevel,
117 msg: "NotFound must remap to InfoLevel in DefaultCodeToLevel",
118 },
119 {
120 code: codes.FailedPrecondition,
121 level: zap.WarnLevel,
122 msg: "FailedPrecondition must remap to WarnLevel in DefaultCodeToLevel",
123 },
124 {
125 code: codes.Unauthenticated,
126 level: zap.DPanicLevel,
127 msg: "Unauthenticated is overwritten to DPanicLevel with customCodeToLevel override, which probably didn't work",
128 },
129 } {
130 s.buffer.Reset()
131 _, err := s.Client.PingError(
132 s.SimpleCtx(),
133 &pb_testproto.PingRequest{Value: "something", ErrorCodeReturned: uint32(tcase.code)})
134 require.Error(s.T(), err, "each call here must return an error")
135
136 msgs := s.getOutputJSONs()
137 require.Len(s.T(), msgs, 1, "only the interceptor log message is printed in PingErr")
138
139 m := msgs[0]
140 assert.Equal(s.T(), m["grpc.service"], "mwitkow.testproto.TestService", "all lines must contain service name")
141 assert.Equal(s.T(), m["grpc.method"], "PingError", "all lines must contain method name")
142 assert.Equal(s.T(), m["grpc.code"], tcase.code.String(), "all lines have the correct gRPC code")
143 assert.Equal(s.T(), m["level"], tcase.level.String(), tcase.msg)
144 assert.Equal(s.T(), m["msg"], "finished unary call with code "+tcase.code.String(), "needs the correct end message")
145
146 require.Contains(s.T(), m, "grpc.start_time", "all lines must contain the start time")
147 _, err = time.Parse(s.timestampFormat, m["grpc.start_time"].(string))
148 assert.NoError(s.T(), err, "should be able to parse start time")
149 }
150 }
151
152 func (s *zapServerSuite) TestPingList_WithCustomTags() {
153 stream, err := s.Client.PingList(s.SimpleCtx(), goodPing)
154 require.NoError(s.T(), err, "should not fail on establishing the stream")
155 for {
156 _, err := stream.Recv()
157 if err == io.EOF {
158 break
159 }
160 require.NoError(s.T(), err, "reading stream should not fail")
161 }
162 msgs := s.getOutputJSONs()
163 require.Len(s.T(), msgs, 2, "two log statements should be logged")
164
165 for _, m := range msgs {
166 assert.Equal(s.T(), m["grpc.service"], "mwitkow.testproto.TestService", "all lines must contain service name")
167 assert.Equal(s.T(), m["grpc.method"], "PingList", "all lines must contain method name")
168 assert.Equal(s.T(), m["span.kind"], "server", "all lines must contain the kind of call (server)")
169 assert.Equal(s.T(), m["custom_tags.string"], "something", "all lines must contain `custom_tags.string` set by AddFields")
170 assert.Equal(s.T(), m["grpc.request.value"], "something", "all lines must contain fields extracted from goodPing because of test.manual_extractfields.pb")
171
172 assert.Contains(s.T(), m, "custom_tags.int", "all lines must contain `custom_tags.int` set by AddFields")
173 require.Contains(s.T(), m, "grpc.start_time", "all lines must contain the start time")
174 _, err := time.Parse(s.timestampFormat, m["grpc.start_time"].(string))
175 assert.NoError(s.T(), err, "should be able to parse start time")
176 }
177
178 assert.Equal(s.T(), msgs[0]["msg"], "some pinglist", "handler's message must contain user message")
179
180 assert.Equal(s.T(), msgs[1]["msg"], "finished streaming call with code OK", "handler's message must contain user message")
181 assert.Equal(s.T(), msgs[1]["level"], "info", "OK codes must be logged on info level.")
182 assert.Contains(s.T(), msgs[1], "grpc.time_ms", "interceptor log statement should contain execution time")
183 }
184
185 func TestZapLoggingOverrideSuite(t *testing.T) {
186 if strings.HasPrefix(runtime.Version(), "go1.7") {
187 t.Skip("Skipping due to json.RawMessage incompatibility with go1.7")
188 return
189 }
190 opts := []grpc_zap.Option{
191 grpc_zap.WithDurationField(grpc_zap.DurationToDurationField),
192 }
193 b := newBaseZapSuite(t)
194 b.InterceptorTestSuite.ServerOpts = []grpc.ServerOption{
195 grpc_middleware.WithStreamServerChain(
196 grpc_ctxtags.StreamServerInterceptor(),
197 grpc_zap.StreamServerInterceptor(b.log, opts...)),
198 grpc_middleware.WithUnaryServerChain(
199 grpc_ctxtags.UnaryServerInterceptor(),
200 grpc_zap.UnaryServerInterceptor(b.log, opts...)),
201 }
202 suite.Run(t, &zapServerOverrideSuite{b})
203 }
204
205 type zapServerOverrideSuite struct {
206 *zapBaseSuite
207 }
208
209 func (s *zapServerOverrideSuite) TestPing_HasOverriddenDuration() {
210 _, err := s.Client.Ping(s.SimpleCtx(), goodPing)
211 require.NoError(s.T(), err, "there must be not be an error on a successful call")
212 msgs := s.getOutputJSONs()
213 require.Len(s.T(), msgs, 2, "two log statements should be logged")
214
215 for _, m := range msgs {
216 assert.Equal(s.T(), m["grpc.service"], "mwitkow.testproto.TestService", "all lines must contain service name")
217 assert.Equal(s.T(), m["grpc.method"], "Ping", "all lines must contain method name")
218 }
219 assert.Equal(s.T(), msgs[0]["msg"], "some ping", "handler's message must contain user message")
220 assert.NotContains(s.T(), msgs[0], "grpc.time_ms", "handler's message must not contain default duration")
221 assert.NotContains(s.T(), msgs[0], "grpc.duration", "handler's message must not contain overridden duration")
222
223 assert.Equal(s.T(), msgs[1]["msg"], "finished unary call with code OK", "handler's message must contain user message")
224 assert.Equal(s.T(), msgs[1]["level"], "info", "OK error codes must be logged on info level.")
225 assert.NotContains(s.T(), msgs[1], "grpc.time_ms", "handler's message must not contain default duration")
226 assert.Contains(s.T(), msgs[1], "grpc.duration", "handler's message must contain overridden duration")
227 }
228
229 func (s *zapServerOverrideSuite) TestPingList_HasOverriddenDuration() {
230 stream, err := s.Client.PingList(s.SimpleCtx(), goodPing)
231 require.NoError(s.T(), err, "should not fail on establishing the stream")
232 for {
233 _, err := stream.Recv()
234 if err == io.EOF {
235 break
236 }
237 require.NoError(s.T(), err, "reading stream should not fail")
238 }
239 msgs := s.getOutputJSONs()
240 require.Len(s.T(), msgs, 2, "two log statements should be logged")
241 for _, m := range msgs {
242 s.T()
243 assert.Equal(s.T(), m["grpc.service"], "mwitkow.testproto.TestService", "all lines must contain service name")
244 assert.Equal(s.T(), m["grpc.method"], "PingList", "all lines must contain method name")
245 }
246
247 assert.Equal(s.T(), msgs[0]["msg"], "some pinglist", "handler's message must contain user message")
248 assert.NotContains(s.T(), msgs[0], "grpc.time_ms", "handler's message must not contain default duration")
249 assert.NotContains(s.T(), msgs[0], "grpc.duration", "handler's message must not contain overridden duration")
250
251 assert.Equal(s.T(), msgs[1]["msg"], "finished streaming call with code OK", "handler's message must contain user message")
252 assert.Equal(s.T(), msgs[1]["level"], "info", "OK error codes must be logged on info level.")
253 assert.NotContains(s.T(), msgs[1], "grpc.time_ms", "handler's message must not contain default duration")
254 assert.Contains(s.T(), msgs[1], "grpc.duration", "handler's message must contain overridden duration")
255 }
256
257 func TestZapServerOverrideSuppressedSuite(t *testing.T) {
258 if strings.HasPrefix(runtime.Version(), "go1.7") {
259 t.Skip("Skipping due to json.RawMessage incompatibility with go1.7")
260 return
261 }
262 opts := []grpc_zap.Option{
263 grpc_zap.WithDecider(func(method string, err error) bool {
264 if err != nil && method == "/mwitkow.testproto.TestService/PingError" {
265 return true
266 }
267 return false
268 }),
269 }
270 b := newBaseZapSuite(t)
271 b.InterceptorTestSuite.ServerOpts = []grpc.ServerOption{
272 grpc_middleware.WithStreamServerChain(
273 grpc_ctxtags.StreamServerInterceptor(),
274 grpc_zap.StreamServerInterceptor(b.log, opts...)),
275 grpc_middleware.WithUnaryServerChain(
276 grpc_ctxtags.UnaryServerInterceptor(),
277 grpc_zap.UnaryServerInterceptor(b.log, opts...)),
278 }
279 suite.Run(t, &zapServerOverriddenDeciderSuite{b})
280 }
281
282 type zapServerOverriddenDeciderSuite struct {
283 *zapBaseSuite
284 }
285
286 func (s *zapServerOverriddenDeciderSuite) TestPing_HasOverriddenDecider() {
287 _, err := s.Client.Ping(s.SimpleCtx(), goodPing)
288 require.NoError(s.T(), err, "there must be not be an error on a successful call")
289 msgs := s.getOutputJSONs()
290 require.Len(s.T(), msgs, 1, "single log statements should be logged")
291
292 assert.Equal(s.T(), msgs[0]["grpc.service"], "mwitkow.testproto.TestService", "all lines must contain service name")
293 assert.Equal(s.T(), msgs[0]["grpc.method"], "Ping", "all lines must contain method name")
294 assert.Equal(s.T(), msgs[0]["msg"], "some ping", "handler's message must contain user message")
295 }
296
297 func (s *zapServerOverriddenDeciderSuite) TestPingError_HasOverriddenDecider() {
298 code := codes.NotFound
299 level := zapcore.InfoLevel
300 msg := "NotFound must remap to InfoLevel in DefaultCodeToLevel"
301
302 s.buffer.Reset()
303 _, err := s.Client.PingError(
304 s.SimpleCtx(),
305 &pb_testproto.PingRequest{Value: "something", ErrorCodeReturned: uint32(code)})
306 require.Error(s.T(), err, "each call here must return an error")
307 msgs := s.getOutputJSONs()
308 require.Len(s.T(), msgs, 1, "only the interceptor log message is printed in PingErr")
309 m := msgs[0]
310 assert.Equal(s.T(), m["grpc.service"], "mwitkow.testproto.TestService", "all lines must contain service name")
311 assert.Equal(s.T(), m["grpc.method"], "PingError", "all lines must contain method name")
312 assert.Equal(s.T(), m["grpc.code"], code.String(), "all lines must contain the correct gRPC code")
313 assert.Equal(s.T(), m["level"], level.String(), msg)
314 }
315
316 func (s *zapServerOverriddenDeciderSuite) TestPingList_HasOverriddenDecider() {
317 stream, err := s.Client.PingList(s.SimpleCtx(), goodPing)
318 require.NoError(s.T(), err, "should not fail on establishing the stream")
319 for {
320 _, err := stream.Recv()
321 if err == io.EOF {
322 break
323 }
324 require.NoError(s.T(), err, "reading stream should not fail")
325 }
326 msgs := s.getOutputJSONs()
327 require.Len(s.T(), msgs, 1, "single log statements should be logged")
328
329 assert.Equal(s.T(), msgs[0]["grpc.service"], "mwitkow.testproto.TestService", "all lines must contain service name")
330 assert.Equal(s.T(), msgs[0]["grpc.method"], "PingList", "all lines must contain method name")
331 assert.Equal(s.T(), msgs[0]["msg"], "some pinglist", "handler's message must contain user message")
332
333 assert.NotContains(s.T(), msgs[0], "grpc.time_ms", "handler's message must not contain default duration")
334 assert.NotContains(s.T(), msgs[0], "grpc.duration", "handler's message must not contain overridden duration")
335 }
336
337 func TestZapLoggingServerMessageProducerSuite(t *testing.T) {
338 if strings.HasPrefix(runtime.Version(), "go1.7") {
339 t.Skip("Skipping due to json.RawMessage incompatibility with go1.7")
340 return
341 }
342 opts := []grpc_zap.Option{
343 grpc_zap.WithMessageProducer(StubMessageProducer),
344 }
345 b := newBaseZapSuite(t)
346 b.InterceptorTestSuite.ServerOpts = []grpc.ServerOption{
347 grpc_middleware.WithStreamServerChain(
348 grpc_ctxtags.StreamServerInterceptor(),
349 grpc_zap.StreamServerInterceptor(b.log, opts...)),
350 grpc_middleware.WithUnaryServerChain(
351 grpc_ctxtags.UnaryServerInterceptor(),
352 grpc_zap.UnaryServerInterceptor(b.log, opts...)),
353 }
354 suite.Run(t, &zapServerMessageProducerSuite{b})
355 }
356
357 type zapServerMessageProducerSuite struct {
358 *zapBaseSuite
359 }
360
361 func (s *zapServerMessageProducerSuite) TestPing_HasOverriddenMessageProducer() {
362 _, err := s.Client.Ping(s.SimpleCtx(), goodPing)
363 require.NoError(s.T(), err, "there must be not be an error on a successful call")
364 msgs := s.getOutputJSONs()
365 require.Len(s.T(), msgs, 2, "two log statements should be logged")
366
367 for _, m := range msgs {
368 assert.Equal(s.T(), m["grpc.service"], "mwitkow.testproto.TestService", "all lines must contain service name")
369 assert.Equal(s.T(), m["grpc.method"], "Ping", "all lines must contain method name")
370 }
371 assert.Equal(s.T(), msgs[0]["msg"], "some ping", "handler's message must contain user message")
372
373 assert.Equal(s.T(), msgs[1]["msg"], "custom message", "handler's message must contain user message")
374 assert.Equal(s.T(), msgs[1]["level"], "info", "OK error codes must be logged on info level.")
375 }
376
View as plain text