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