Add go-kit logging middleware #223

adrien-f · 2019-08-09T12:26:36Z

Greetings 👋

I come from the Thanos project where we mostly use the go-kit logging library and we wanted some sweet gRPC logging for our users.

I'm not a Go expert, so I mostly copy/pasted the tests from the Zap implementation and wrote the go-kit logging system.

The tests suite is green and it works pretty swell with Thanos:

level=debug ts=2019-08-09T12:24:01.299269Z caller=storeset.go:223 component=storeset msg="updating healthy stores" externalLabelOccurrencesInStores="map[string]int{\"\":1}"
level=info ts=2019-08-09T12:24:01.299296Z caller=storeset.go:266 component=storeset msg="adding new store to query storeset" address=127.0.0.1:10904
level=info ts=2019-08-09T12:24:06.300377Z caller=payload_interceptors.go:134 system=grpc span.kind=client grpc.service=thanos.Store grpc.method=Info grpc.request.content={}
level=info ts=2019-08-09T12:24:06.302309Z caller=payload_interceptors.go:134 system=grpc span.kind=client grpc.service=thanos.Store grpc.method=Info grpc.response.content="{\"maxTime\":\"9223372036854775807\",\"storeType\":\"SIDECAR\"}"
level=debug ts=2019-08-09T12:24:06.302375Z caller=client_interceptors.go:49 system=grpc span.kind=client grpc.service=thanos.Store grpc.method=Info msg="finished client unary call" error=null grpc.code=OK grpc.time_ms=2.145```

Let me know if you have any feedback 😄

googlebot · 2019-08-09T12:26:39Z

Thanks for your pull request. It looks like this may be your first contribution to a Google open source project (if not, look below for help). Before we can look at your pull request, you'll need to sign a Contributor License Agreement (CLA).

📝 Please visit https://cla.developers.google.com/ to sign.

Once you've signed (or fixed any issues), please reply here with @googlebot I signed it!) and we'll verify it.

What to do if you already signed the CLA

Individual signers

It's possible we don't have your GitHub username or you're using a different email address on your commit. Check your existing CLA data and verify that your email is set on your git commits.

Corporate signers

Your company has a Point of Contact who decides which employees are authorized to participate. Ask your POC to be added to the group of authorized contributors. If you don't know who your Point of Contact is, direct the Google project maintainer to go/cla#troubleshoot (Public version).
The email used to register you as an authorized contributor must be the email used for the Git commit. Check your existing CLA data and verify that your email is set on your git commits.
The email used to register you as an authorized contributor must also be attached to your GitHub account.

ℹ️ Googlers: Go here for more info.

adrien-f · 2019-08-09T12:28:42Z

@googlebot I signed it!

googlebot · 2019-08-09T12:28:45Z

CLAs look good, thanks!

ℹ️ Googlers: Go here for more info.

codecov-io · 2019-08-09T12:29:59Z

Codecov Report

Merging #223 into master will increase coverage by 0.89%.
The diff coverage is 80.46%.

@@            Coverage Diff             @@
##           master     #223      +/-   ##
==========================================
+ Coverage   72.12%   73.01%   +0.89%     
==========================================
  Files          37       42       +5     
  Lines        1349     1564     +215     
==========================================
+ Hits          973     1142     +169     
- Misses        329      369      +40     
- Partials       47       53       +6

Impacted Files	Coverage Δ
logging/kit/ctxkit/context.go	`0% <0%> (ø)`
logging/kit/server_interceptors.go	`100% <100%> (ø)`
logging/kit/client_interceptors.go	`100% <100%> (ø)`
logging/kit/payload_interceptors.go	`81.81% <81.81%> (ø)`
logging/kit/options.go	`82.69% <82.69%> (ø)`
retry/retry.go	`75.13% <0%> (-2.21%)`	⬇️
... and 1 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 6f8030a...d2efd62. Read the comment docs.

domgreen

Overall just nits... it follow the same pattern as the other interceptors and tests seem to cover the majority of cases. Can you also add a doc.go to describe the new module?

Great to see that it has been tested already against thanos 👍

logging/kit/client_interceptors.go

logging/kit/payload_interceptors.go

tags/kit/context.go

logging/kit/client_interceptors.go

logging/kit/options.go

logging/kit/payload_interceptors.go

domgreen · 2019-08-27T14:55:21Z

@adrien-f mind adding the addition of the new logger to the CHANGELOG as well 👍

domgreen · 2019-09-12T09:36:19Z

@adrien-f could you rebase and push changes ... looking to get this in before we cut a release again

adrien-f · 2019-09-13T07:40:43Z

Sorry I missed your message, will get on it today 😄

adrien-f · 2019-09-13T14:08:10Z

There you go 😄 !

domgreen

Looks good overall just a few minor tweaks to tidy it up abit, mainly:

using the newer "context" package
adding docs/examples
cleaning up comments if they reference zap
running goimports over the code

Thanks again and sorry for the slow turn around on my side.

logging/kit/client_interceptors.go

logging/kit/ctxkit/context.go

logging/kit/options.go

logging/kit/server_interceptors.go

logging/kit/shared_test.go

logging/kit/client_interceptors.go

domgreen · 2019-10-09T13:23:33Z

@adrien-f you been able to have a look at this?

bwplotka · 2019-10-25T11:50:30Z

It would be nice to have this, let's get back to this (: @adrien-f ?

adrien-f · 2019-10-28T12:42:22Z

Hi there !

I did go over your latest reviews 2 weeks ago but failed to notice that the CI was red 🙏 ! How does it look ?

johanbrandhorst · 2019-10-28T14:39:22Z

logging/kit/client_interceptors.go

+	code := o.codeFunc(err)
+	logger = o.levelFunc(code, logger)
+	args := []interface{}{"msg", msg, "error", err, "grpc.code", code.String()}
+	args = append(args, o.durationFunc(time.Now().Sub(startTime))...)


Could use time.Since here instead.

johanbrandhorst · 2019-10-28T14:40:18Z

logging/kit/client_interceptors_test.go

+	if strings.HasPrefix(runtime.Version(), "go1.7") {
+		t.Skipf("Skipping due to json.RawMessage incompatibility with go1.7")
+		return
+	}


Surely we don't need this check. We should only be supporting Go 1.12 and 1.13 at this point.

johanbrandhorst · 2019-10-28T14:46:08Z

logging/kit/options.go

+}
+
+func durationToMilliseconds(duration time.Duration) float32 {
+	return float32(duration.Nanoseconds()/1000) / 1000


Why not duration.Milliseconds? https://golang.org/pkg/time/#Duration.Milliseconds

The project is still built with Go 1.12, should we upgrade ?

bwplotka

Awesome! Thanks for all tests and go-kit support.

It generally looks amazing, but I would focus on reusing more. Otherwise we are inconsistent. Can we create maybe logging/common or logging package so we can put common stuff for all implementations? I think we can reuse much more. Especially given we have 3 implementation now it's time to aggregate common stuff together (:

bwplotka · 2019-10-28T13:46:23Z

logging/kit/ctxkit/context.go

+
+type ctxMarker struct{}
+
+type ctxLogger struct {


Do we need to replicate this for every logger? Can we reuse?

bwplotka · 2019-10-28T13:50:17Z

logging/kit/ctxkit/context.go

+	fields := TagsToFields(ctx)
+	// Add fields added until now.
+	fields = append(fields, l.fields...)
+	return log.With(l.logger, fields...)


just log.With(l.logger, append(fields, l.fields...)...)

bwplotka · 2019-10-28T13:55:08Z

logging/kit/options.go

+var DefaultDurationToField = DurationToTimeMillisField
+
+// DurationToTimeMillisField converts the duration to milliseconds and uses the key `grpc.time_ms`.
+func DurationToTimeMillisField(duration time.Duration) []interface{} {


Can we use []string? I don't think go kit logger supports non string field.

The With call that those fields are used afterwards require []interface{}:
func With(logger Logger, keyvals ...interface{}) Logger
https://godoc.org/github.com/go-kit/kit/log#With

bwplotka · 2019-10-28T14:02:11Z

logging/kit/options.go

+}
+
+// DefaultCodeToLevel is the default implementation of gRPC return codes and interceptor log level for server side.
+func DefaultCodeToLevel(code codes.Code, logger log.Logger) log.Logger {


I would vote for reusing more... We need to reimplement Option stuff and code to level 3 times and it's quite a problem as we have inconsistencies. e.g https://github.com/grpc-ecosystem/go-grpc-middleware/blob/master/logging/logrus/options.go#L87 for codes to level. Can we optimize for it?

bwplotka · 2019-10-28T14:58:58Z

logging/kit/client_interceptors.go

+	logger.Log(args...)
+}
+
+func newClientLoggerFields(ctx context.Context, fullMethodString string) []interface{} {


Can we create maybe logging/common or logging package so we can put common stuff for all implementation. I think we can reuse much more. Especially given we have 3 implementation now it's time to aggregate common stuff together (:

I think we can actually do this in second PR, we can iterate over it (:

bwplotka · 2019-11-02T02:21:51Z

logging/kit/client_interceptors.go

+)
+
+// UnaryClientInterceptor returns a new unary client interceptor that optionally logs the execution of external gRPC calls.
+func UnaryClientInterceptor(logger log.Logger, opts ...Option) grpc.UnaryClientInterceptor {


I just tried to use it and I cannot see the option that would allow me to inject custom fields here like request-id to the logged message ): I think it would be nice to add! It is exactly the same for logrus and zap but would nice to add I guess (: at some point in another PR!

As commented here: https://github.com/grpc-ecosystem/go-grpc-middleware/pull/223/files#r341806517

bwplotka · 2019-11-02T10:37:53Z

logging/kit/client_interceptors.go

+func newClientLoggerFields(ctx context.Context, fullMethodString string) []interface{} {
+	service := path.Dir(fullMethodString)[1:]
+	method := path.Base(fullMethodString)
+	return []interface{}{


We are missing something like callLog = callLog.WithFields(ctx_logrus.Extract(ctx).Data) (this is what logrus do)

Either he or on caller side, but we need to have to use context logger (:

I would agree but I don't see it on the other loggers as well. I do see it in server_interceptors though

adrien-f · 2019-11-07T10:14:10Z

Hey it's me again!

I do agree that some pieces of the logging component is getting repetitive and should probably be merged and aggregated. Should this be a separated MR or you'd like me to work on it in this one 😄 ?

andrascz · 2019-12-18T19:45:22Z

@adrien-f do you still intend to push forward with this PR?

andrascz · 2019-12-18T19:46:08Z

logging/kit/ctxkit/context.go

-	// Add fields added until now.
-	fields = append(fields, l.fields...)
-	return log.With(l.logger, fields...)
+	return log.With(l.logger, append(fields, l.fields...))


This seems to break the tests. append(fields, l.fields...)... should be the correct change.

johanbrandhorst · 2019-12-19T10:49:40Z

Hey it's me again!

I do agree that some pieces of the logging component is getting repetitive and should probably be merged and aggregated. Should this be a separated MR or you'd like me to work on it in this one smile ?

I think we're happy to have this in two separate PRs so that we can get this merged.

bwplotka · 2019-12-19T12:21:27Z

Would be super nice to push it through, and definitely let's add this without major refactoring of others first (:

adrien-f · 2020-01-28T08:45:47Z

Terribly sorry for the long wait 🙏

I've just pushed the latest changes, rebased master and tested with Thanos:

level=info ts=2020-01-28T08:37:21.781054Z caller=server_interceptors.go:91 trace.sampled=false peer.address=127.0.0.1:50891 trace.traceid=3638a03d202e5bf6 trace.spanid=5244947b7812183 grpc.start_time=2020-01-28T09:37:21+01:00 grpc.request.deadline=2020-01-28T09:37:26+01:00 system=grpc span.kind=server grpc.service=thanos.Store grpc.method=Info trace.spanid=5244947b7812183 trace.sampled=false peer.address=127.0.0.1:50891 trace.traceid=3638a03d202e5bf6 msg="finished unary call with code OK" error=null grpc.code=OK grpc.duration=86.212µs

Trace IDs are injected and all tests are green.

I've also started working on a common package/interface, maybe something like

type MiddlewareLogger interface {
	Inject(ctx context.Context, method string, operation OperationKind, startTime time.Time) context.Context
	InjectPayload(ctx context.Context, method string, operation OperationKind) context.Context
	AddFields(ctx context.Context, fields Fields)
	Log(ctx context.Context, message string, level Level)
	LogRequest(ctx context.Context, message string, code codes.Code, level Level, duration DurationEntry, err error)
	LogPayload(ctx context.Context, message string, payload interface{}, payloadName string)
}

but that might be out of scope of this MR.

johanbrandhorst · 2020-01-28T16:05:32Z

Awesome, thanks @adrien-f, let's save the refactor for the next PR!

adrien-f force-pushed the feature/go-kit branch from a3837e8 to 737f2b4 Compare August 9, 2019 12:28

Ahmet-Kaplan mentioned this pull request Aug 19, 2019

Add zerolog logging middleware #224

Closed

Ahmet-Kaplan mentioned this pull request Aug 26, 2019

Add zerolog logging middleware #225

Closed

domgreen reviewed Aug 27, 2019

View reviewed changes

adrien-f force-pushed the feature/go-kit branch from 737f2b4 to a35a11d Compare September 13, 2019 14:06

domgreen reviewed Sep 17, 2019

View reviewed changes

adrien-f force-pushed the feature/go-kit branch from a35a11d to 51ffeb9 Compare October 13, 2019 15:41

bwplotka mentioned this pull request Oct 25, 2019

Improve "failed to receive any data from warning thanos-io/thanos#1686

Closed

adrien-f force-pushed the feature/go-kit branch 2 times, most recently from 29a715a to 6e27dcf Compare October 28, 2019 10:09

johanbrandhorst requested a review from domgreen October 28, 2019 14:38

johanbrandhorst reviewed Oct 28, 2019

View reviewed changes

bwplotka reviewed Oct 28, 2019

View reviewed changes

This was referenced Nov 1, 2019

Add query logging/tracing thanos-io/thanos#1706

Open

Long Term Storage Improvements [Tracking Issue] thanos-io/thanos#1705

Closed

bwplotka reviewed Nov 2, 2019

View reviewed changes

andrascz reviewed Dec 18, 2019

View reviewed changes

adrien-f force-pushed the feature/go-kit branch from c1e56ba to 09011da Compare January 28, 2020 08:39

Add go-kit logging middleware

d2efd62

adrien-f force-pushed the feature/go-kit branch from 09011da to d2efd62 Compare January 28, 2020 08:45

johanbrandhorst approved these changes Jan 28, 2020

View reviewed changes

johanbrandhorst merged commit 3c51f7f into grpc-ecosystem:master Jan 28, 2020

adrien-f deleted the feature/go-kit branch February 12, 2020 13:15

Add go-kit logging middleware #223

Add go-kit logging middleware #223

Conversation

adrien-f commented Aug 9, 2019 • edited

googlebot commented Aug 9, 2019

What to do if you already signed the CLA

Individual signers

Corporate signers

adrien-f commented Aug 9, 2019

googlebot commented Aug 9, 2019

codecov-io commented Aug 9, 2019 • edited

Codecov Report

domgreen left a comment

Choose a reason for hiding this comment

domgreen commented Aug 27, 2019

domgreen commented Sep 12, 2019

adrien-f commented Sep 13, 2019

adrien-f commented Sep 13, 2019

domgreen left a comment

Choose a reason for hiding this comment

domgreen commented Oct 9, 2019

bwplotka commented Oct 25, 2019

adrien-f commented Oct 28, 2019

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bwplotka left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

adrien-f commented Nov 7, 2019

andrascz commented Dec 18, 2019

Choose a reason for hiding this comment

johanbrandhorst commented Dec 19, 2019

bwplotka commented Dec 19, 2019

adrien-f commented Jan 28, 2020

johanbrandhorst commented Jan 28, 2020

adrien-f commented Aug 9, 2019 •

edited

codecov-io commented Aug 9, 2019 •

edited