1 package kit_test
2
3 import (
4 "io"
5 "runtime"
6 "strings"
7 "testing"
8 "time"
9
10 "github.com/go-kit/log"
11 "github.com/go-kit/log/level"
12 grpc_middleware "github.com/grpc-ecosystem/go-grpc-middleware"
13 grpc_kit "github.com/grpc-ecosystem/go-grpc-middleware/logging/kit"
14 grpc_ctxtags "github.com/grpc-ecosystem/go-grpc-middleware/tags"
15 pb_testproto "github.com/grpc-ecosystem/go-grpc-middleware/testing/testproto"
16 "github.com/stretchr/testify/assert"
17 "github.com/stretchr/testify/require"
18 "github.com/stretchr/testify/suite"
19 "google.golang.org/grpc"
20 "google.golang.org/grpc/codes"
21 )
22
23 func customCodeToLevel(c codes.Code, logger log.Logger) log.Logger {
24 if c == codes.Unauthenticated {
25
26 return level.Error(logger)
27 }
28 return grpc_kit.DefaultCodeToLevel(c, logger)
29 }
30
31 func TestKitLoggingSuite(t *testing.T) {
32 if strings.HasPrefix(runtime.Version(), "go1.7") {
33 t.Skipf("Skipping due to json.RawMessage incompatibility with go1.7")
34 return
35 }
36
37 for _, tcase := range []struct {
38 timestampFormat string
39 }{
40 {
41 timestampFormat: time.RFC3339,
42 },
43 {
44 timestampFormat: "2006-01-02",
45 },
46 } {
47 opts := []grpc_kit.Option{
48 grpc_kit.WithLevels(customCodeToLevel),
49 grpc_kit.WithTimestampFormat(tcase.timestampFormat),
50 }
51
52 b := newKitBaseSuite(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_kit.StreamServerInterceptor(b.logger, opts...)),
58 grpc_middleware.WithUnaryServerChain(
59 grpc_ctxtags.UnaryServerInterceptor(grpc_ctxtags.WithFieldExtractor(grpc_ctxtags.CodeGenRequestFieldExtractor)),
60 grpc_kit.UnaryServerInterceptor(b.logger, opts...)),
61 }
62 suite.Run(t, &kitServerSuite{b})
63 }
64 }
65
66 type kitServerSuite struct {
67 *kitBaseSuite
68 }
69
70 func (s *kitServerSuite) 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 *kitServerSuite) TestPingError_WithCustomLevels() {
104 for _, tcase := range []struct {
105 code codes.Code
106 level level.Value
107 msg string
108 }{
109 {
110 code: codes.Internal,
111 level: level.ErrorValue(),
112 msg: "Internal must remap to ErrorLevel in DefaultCodeToLevel",
113 },
114 {
115 code: codes.NotFound,
116 level: level.InfoValue(),
117 msg: "NotFound must remap to InfoLevel in DefaultCodeToLevel",
118 },
119 {
120 code: codes.FailedPrecondition,
121 level: level.WarnValue(),
122 msg: "FailedPrecondition must remap to WarnLevel in DefaultCodeToLevel",
123 },
124 {
125 code: codes.Unauthenticated,
126 level: level.ErrorValue(),
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 *kitServerSuite) 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 TestKitLoggingOverrideSuite(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_kit.Option{
191 grpc_kit.WithDurationField(grpc_kit.DurationToDurationField),
192 }
193 b := newKitBaseSuite(t)
194 b.InterceptorTestSuite.ServerOpts = []grpc.ServerOption{
195 grpc_middleware.WithStreamServerChain(
196 grpc_ctxtags.StreamServerInterceptor(),
197 grpc_kit.StreamServerInterceptor(b.logger, opts...)),
198 grpc_middleware.WithUnaryServerChain(
199 grpc_ctxtags.UnaryServerInterceptor(),
200 grpc_kit.UnaryServerInterceptor(b.logger, opts...)),
201 }
202 suite.Run(t, &kitServerOverrideSuite{b})
203 }
204
205 type kitServerOverrideSuite struct {
206 *kitBaseSuite
207 }
208
209 func (s *kitServerOverrideSuite) 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 *kitServerOverrideSuite) 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 TestKitServerOverrideSuppressedSuite(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_kit.Option{
263 grpc_kit.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 := newKitBaseSuite(t)
271 b.InterceptorTestSuite.ServerOpts = []grpc.ServerOption{
272 grpc_middleware.WithStreamServerChain(
273 grpc_ctxtags.StreamServerInterceptor(),
274 grpc_kit.StreamServerInterceptor(b.logger, opts...)),
275 grpc_middleware.WithUnaryServerChain(
276 grpc_ctxtags.UnaryServerInterceptor(),
277 grpc_kit.UnaryServerInterceptor(b.logger, opts...)),
278 }
279 suite.Run(t, &kitServerOverridenDeciderSuite{b})
280 }
281
282 type kitServerOverridenDeciderSuite struct {
283 *kitBaseSuite
284 }
285
286 func (s *kitServerOverridenDeciderSuite) 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 *kitServerOverridenDeciderSuite) TestPingError_HasOverriddenDecider() {
298 code := codes.NotFound
299 msg := "NotFound must remap to InfoLevel in DefaultCodeToLevel"
300
301 s.buffer.Reset()
302 _, err := s.Client.PingError(
303 s.SimpleCtx(),
304 &pb_testproto.PingRequest{Value: "something", ErrorCodeReturned: uint32(code)})
305 require.Error(s.T(), err, "each call here must return an error")
306 msgs := s.getOutputJSONs()
307 require.Len(s.T(), msgs, 1, "only the interceptor log message is printed in PingErr")
308 m := msgs[0]
309 assert.Equal(s.T(), m["grpc.service"], "mwitkow.testproto.TestService", "all lines must contain service name")
310 assert.Equal(s.T(), m["grpc.method"], "PingError", "all lines must contain method name")
311 assert.Equal(s.T(), m["grpc.code"], code.String(), "all lines must contain the correct gRPC code")
312 assert.Equal(s.T(), m["level"], "info", msg)
313 }
314
315 func (s *kitServerOverridenDeciderSuite) TestPingList_HasOverriddenDecider() {
316 stream, err := s.Client.PingList(s.SimpleCtx(), goodPing)
317 require.NoError(s.T(), err, "should not fail on establishing the stream")
318 for {
319 _, err := stream.Recv()
320 if err == io.EOF {
321 break
322 }
323 require.NoError(s.T(), err, "reading stream should not fail")
324 }
325 msgs := s.getOutputJSONs()
326 require.Len(s.T(), msgs, 1, "single log statements should be logged")
327
328 assert.Equal(s.T(), msgs[0]["grpc.service"], "mwitkow.testproto.TestService", "all lines must contain service name")
329 assert.Equal(s.T(), msgs[0]["grpc.method"], "PingList", "all lines must contain method name")
330 assert.Equal(s.T(), msgs[0]["msg"], "some pinglist", "handler's message must contain user message")
331
332 assert.NotContains(s.T(), msgs[0], "grpc.time_ms", "handler's message must not contain default duration")
333 assert.NotContains(s.T(), msgs[0], "grpc.duration", "handler's message must not contain overridden duration")
334 }
335
View as plain text