Add log fields metadata to gRPC calls #359

carlosms · 2018-11-19T11:33:15Z

WIP because it needs support from go-log, src-d/go-log#9. But I'd like to get feedback.

The changes in this PR depend on fixing #357 to be really useful. But the issues are independent, the other bug can be fixed after this one is merged. In the examples below you can see the analyzer and event-id fields.

Changes in this PR include:

Improvements to already existing interceptors. Now they use a log from context, instead of the default one.
Before

[2018-11-19T11:09:35.061228511Z]  INFO unary client call started app=lookoutd grpc.method=NotifyReviewEvent grpc.service=pb.Analyzer span.kind=client system=grpc

After:

[2018-11-19T11:08:17.043544201Z]  INFO gRPC unary client call started analyzer=Dummy app=lookoutd event-id=47428977cec7253cc30466a12eee386de46f7306 event-type=*pb.ReviewEvent grpc.method=NotifyReviewEvent grpc.service=pb.Analyzer head=refs/pull/1/head provider=github repo=https://github.com/src-d/lookout-test-fixtures.git span.kind=client system=grpc

.
New interceptors to pass log fields in the gRPC metadata, encoded as JSON. Using these interceptors the logs fields go from lookoutd -> analyzer as client/server, but also from analyzer -> lookoutd.
Before:

[2018-11-19T11:23:46.423025958Z]  INFO gRPC streaming server call started app=lookoutd grpc.method=GetChanges grpc.service=pb.Data span.kind=server system=grpc
[2018-11-19T11:23:46.423263865Z]  INFO validating refs: [internal_repository_url:"https://github.com/src-d/lookout-test-fixtures.git" reference_name:"refs/heads/master" hash:"6a92946068897d0a6f6ffa6457f889163dcc51b5"  internal_repository_url:"https://github.com/src-d/lookout-test-fixtures.git" reference_name:"refs/pull/3/head" hash:"6221d2fe0bc2148debfa8d3c8c92b8c15451920d" ], validateRefName: true app=lookoutd
[2018-11-19T11:23:46.423559138Z]  INFO fetching references for repository https://github.com/src-d/lookout-test-fixtures.git: [refs/heads/master:refs/heads/master refs/pull/3/head:refs/pull/3/head] app=lookoutd
[2018-11-19T11:23:46.822346422Z]  INFO gRPC streaming server call finished app=lookoutd duration=399.322434ms grpc.code=OK grpc.method=GetChanges grpc.service=pb.Data grpc.start_time=2018-11-19T11:23:46Z span.kind=server system=grpc

After:

[2018-11-19T11:21:38.402117594Z]  INFO gRPC streaming server call started analyzer=Dummy app=lookoutd event-id=47428977cec7253cc30466a12eee386de46f7306 event-type=map[] grpc.method=GetChanges grpc.service=pb.Data head=refs/pull/1/head provider=github repo=https://github.com/src-d/lookout-test-fixtures.git span.kind=server system=grpc
[2018-11-19T11:21:38.402355891Z]  INFO validating refs: [internal_repository_url:"https://github.com/src-d/lookout-test-fixtures.git" reference_name:"refs/heads/i197-base" hash:"fa8a63d8ed4ceee82f40273090c28e31576dafda"  internal_repository_url:"https://github.com/src-d/lookout-test-fixtures.git" reference_name:"refs/pull/1/head" hash:"5fe468b62112e69bae390051e990271f7b1cc294" ], validateRefName: true analyzer=Dummy app=lookoutd event-id=47428977cec7253cc30466a12eee386de46f7306 event-type=map[] head=refs/pull/1/head provider=github repo=https://github.com/src-d/lookout-test-fixtures.git
[2018-11-19T11:21:38.402707005Z]  INFO fetching references for repository https://github.com/src-d/lookout-test-fixtures.git: [refs/heads/i197-base:refs/heads/i197-base refs/pull/1/head:refs/pull/1/head] analyzer=Dummy app=lookoutd event-id=47428977cec7253cc30466a12eee386de46f7306 event-type=map[] head=refs/pull/1/head provider=github repo=https://github.com/src-d/lookout-test-fixtures.git
[2018-11-19T11:21:39.024092952Z]  INFO gRPC streaming server call finished analyzer=Dummy app=lookoutd duration=621.987351ms event-id=47428977cec7253cc30466a12eee386de46f7306 event-type=map[] grpc.code=OK grpc.method=GetChanges grpc.service=pb.Data grpc.start_time=2018-11-19T11:21:38Z head=refs/pull/1/head provider=github repo=https://github.com/src-d/lookout-test-fixtures.git span.kind=server system=grpc

If an analyzer does not use the interceptors the log fields are not passed around, but it will not cause any problems. Since the metadata is JSON, it should be easy to add this functionality to the python SDK.

util/grpchelper/logfields.go

lookout-staging · 2018-11-19T11:37:00Z

util/grpchelper/logger.go


 		return clientStream, err
 	}
 }

-func newServerRequestLogger(l log.Logger, fullMethod string) log.Logger {
+func newServerRequestLogger(ctx context.Context, fullMethod string) log.Logger {


duplicate of util/grpchelper/logger.go:104-115 (dupl)

If you have feedback about this comment, please, tell us.

lookout-staging · 2018-11-19T11:37:00Z

util/grpchelper/logger.go

 }

-func newClientRequestLogger(l log.Logger, fullMethod string) log.Logger {
+func newClientRequestLogger(ctx context.Context, fullMethod string) log.Logger {


duplicate of util/grpchelper/logger.go:91-102 (dupl)

If you have feedback about this comment, please, tell us.

lookout-staging · 2018-11-19T11:37:01Z

util/grpchelper/logfields.go

@@ -0,0 +1,90 @@
+package grpchelper


file is not goimported (goimports)

If you have feedback about this comment, please, tell us.

smacker

👍 we will need that new method in go-log for #357 too

smacker · 2018-11-20T10:12:09Z

I just noticed that CI is green even without Fields{}. Maybe we should add test?

carlosms · 2018-11-20T10:52:07Z

Yes, I was thinking I would wait for support in go-log. And then add some new greps to dummy_analyzer_test.go and multi_analyzer_test.go looking for log lines with grpc.method=GetChanges including the new log fields.

cmd/server-test/dummy_analyzer_test.go

util/grpchelper/logfields.go

carlosms · 2018-12-28T18:06:22Z

Pushed new commits on top of #375, with tests.

We still need to decide if we want to keep the log fields in the metadata, or as grpc fields. But at least this branch is now up to date and ready to be merged, or be adapted.

mcuadros · 2019-01-24T15:21:45Z

Sorry for delaying this, you can do as you want, my only concert was not passing an instance of a logger in a context.

Signed-off-by: Carlos Martín <[email protected]>

carlosms requested review from smacker, dpordomingo and smola November 19, 2018 11:33

carlosms mentioned this pull request Nov 19, 2018

Add method to access logger Fields src-d/go-log#9

Closed

lookout-staging bot reviewed Nov 19, 2018

View reviewed changes

carlosms force-pushed the grpc-log-tags branch from 0ba8f7f to 942d9b2 Compare November 19, 2018 12:03

carlosms changed the title ~~[WIP] Add log fields metadata to gRPC calls~~ Add log fields metadata to gRPC calls Nov 20, 2018

smacker approved these changes Nov 20, 2018

View reviewed changes

dpordomingo approved these changes Nov 21, 2018

View reviewed changes

carlosms mentioned this pull request Dec 20, 2018

Do not store logger in context, store log fields instead #427

Closed

carlosms force-pushed the grpc-log-tags branch from 942d9b2 to e366972 Compare December 28, 2018 17:52

lookout-staging bot reviewed Dec 28, 2018

View reviewed changes

cmd/server-test/dummy_analyzer_test.go Show resolved Hide resolved

util/grpchelper/logfields.go Show resolved Hide resolved

util/grpchelper/logfields.go Show resolved Hide resolved

carlosms added 3 commits January 25, 2019 10:02

New gRPC interceptors to add log fiels to metadata

4c74157

Signed-off-by: Carlos Martín <[email protected]>

Add analyzer field to ctxlog

1a50036

Signed-off-by: Carlos Martín <[email protected]>

Add tests for gRPC interceptors

6ba788a

Signed-off-by: Carlos Martín <[email protected]>

carlosms force-pushed the grpc-log-tags branch from e366972 to 6ba788a Compare January 25, 2019 10:13

carlosms merged commit 9d24df0 into src-d:master Jan 25, 2019

carlosms mentioned this pull request Feb 21, 2019

Extract gRPC interceptors from lookout src-d/lookout-sdk#71

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add log fields metadata to gRPC calls #359

Add log fields metadata to gRPC calls #359

carlosms commented Nov 19, 2018 •

edited

Loading

lookout-staging bot Nov 19, 2018

lookout-staging bot Nov 19, 2018

lookout-staging bot Nov 19, 2018

smacker left a comment

smacker commented Nov 20, 2018

carlosms commented Nov 20, 2018

carlosms commented Dec 28, 2018

mcuadros commented Jan 24, 2019

Add log fields metadata to gRPC calls #359

Add log fields metadata to gRPC calls #359

Conversation

carlosms commented Nov 19, 2018 • edited Loading

lookout-staging bot Nov 19, 2018

Choose a reason for hiding this comment

lookout-staging bot Nov 19, 2018

Choose a reason for hiding this comment

lookout-staging bot Nov 19, 2018

Choose a reason for hiding this comment

smacker left a comment

Choose a reason for hiding this comment

smacker commented Nov 20, 2018

carlosms commented Nov 20, 2018

carlosms commented Dec 28, 2018

mcuadros commented Jan 24, 2019

carlosms commented Nov 19, 2018 •

edited

Loading