Added request logging for gRPC and HTTP in the server side

[yashrsharma44]

Fixes #2844

Signed-off-by: Yash Sharma [email protected]

• I added CHANGELOG entry for this change.

Changes

• Updated the grpc middleware version to use v2. We are using the last commit which contains the logging middleware. Once grpc_middleware releases the v2 we can add that as well.
• Reuse the flag for enabling/disabling the start and finish of the requests from http-request logging.(Let me know if a separate flag is needed for gRPC).
• This PR also works on the changes made by Initial setup for Request Logging in HTTP in the server side #2849 and adds in YAML configuration for the same.

Verification

Current Output -

ts=2020-10-25T06:06:52.994721959Z caller=level.go:63 name=sidecar-1 level=info service=gRPC/server component=sidecar protocol=grpc grpc.component=server grpc.service=thanos.Store grpc.method=Info grpc.method_type=unary grpc.start_time=2020-10-25T11:36:52+05:30 grpc.request.deadline=2020-10-25T11:36:57+05:30 grpc.code=OK peer.address=127.0.0.1:41926 grpc.request.request-id=01ENF5VS22Q4M9E326FPCTSJ0F grpc.time_ms=0.038 startedcall=(MISSING)
ts=2020-10-25T06:06:52.99524562Z caller=level.go:63 name=sidecar-1 level=info service=gRPC/server component=sidecar protocol=grpc grpc.component=server grpc.service=thanos.Store grpc.method=Info grpc.method_type=unary grpc.start_time=2020-10-25T11:36:52+05:30 grpc.request.deadline=2020-10-25T11:36:57+05:30 grpc.code=OK peer.address=127.0.0.1:41926 grpc.request.request-id=01ENF5VS22Q4M9E326FPCTSJ0F grpc.time_ms=0.566 finishedcall=(MISSING)
ts=2020-10-25T06:06:52.994721917Z caller=level.go:63 name=sidecar-2 level=info service=gRPC/server component=sidecar protocol=grpc grpc.component=server grpc.service=thanos.Store grpc.method=Info grpc.method_type=unary grpc.start_time=2020-10-25T11:36:52+05:30 grpc.request.deadline=2020-10-25T11:36:57+05:30 grpc.code=OK peer.address=127.0.0.1:33364 grpc.request.request-id=01ENF5VS22Z5WGC34BSQ3MFTE9 grpc.time_ms=0.037 startedcall=(MISSING)
ts=2020-10-25T06:06:52.995514182Z caller=level.go:63 name=sidecar-2 level=info service=gRPC/server component=sidecar protocol=grpc grpc.component=server grpc.service=thanos.Store grpc.method=Info grpc.method_type=unary grpc.start_time=2020-10-25T11:36:52+05:30 grpc.request.deadline=2020-10-25T11:36:57+05:30 grpc.code=OK peer.address=127.0.0.1:33364 grpc.request.request-id=01ENF5VS22Z5WGC34BSQ3MFTE9 grpc.time_ms=0.837 finishedcall=(MISSING)
ts=2020-10-25T06:06:52.995990248Z caller=level.go:63 name=sidecar-0 level=info service=gRPC/server component=sidecar protocol=grpc grpc.component=server grpc.service=thanos.Store grpc.method=Info grpc.method_type=unary grpc.start_time=2020-10-25T11:36:52+05:30 grpc.request.deadline=2020-10-25T11:36:57+05:30 grpc.code=OK peer.address=127.0.0.1:49516 grpc.request.request-id=01ENF5VS23BVAZF5ETRQDJ20Q2 grpc.time_ms=0.04 startedcall=(MISSING)
ts=2020-10-25T06:06:52.996181723Z caller=level.go:63 name=sidecar-0 level=info service=gRPC/server component=sidecar protocol=grpc grpc.component=server grpc.service=thanos.Store grpc.method=Info grpc.method_type=unary grpc.start_time=2020-10-25T11:36:52+05:30 grpc.request.deadline=2020-10-25T11:36:57+05:30 grpc.code=OK peer.address=127.0.0.1:49516 grpc.request.request-id=01ENF5VS23BVAZF5ETRQDJ20Q2 grpc.time_ms=0.231 finishedcall=(MISSING)

Current TODO

• Setup a flag for using the grpc request logging

cc @kakkoyun 🤓

[yashrsharma44]

There seems to be a (MISSING) field, I have pushed the changes in the grpc_middleware, that should be fixed in the subsequent release.

[yashrsharma44]

The test failures are unrelated to this PR.

[kakkoyun]

@yashrsharma44 Needs a rebase.

[bwplotka]

Looks amazing generally just some nits.

Overall:

• Let's be consistent and create helpers for all components on one go.
• don't introduce non relevant changes (CHANGELOG reformat)
• Good work (:

[yashrsharma44]

I have used a logMap to map the options from the string flag into the options for the logging middleware. Since from the flag, I only get a string response, so is there any clean way you suggest for configuring the options?

[yashrsharma44]

Test Failures are unrelated

[bwplotka]

Looking good 👍
Some thoughts during offline disscussions.

[yashrsharma44]

Feature Request: Would be nice if we add in the error message as well - https://cloud-native.slack.com/archives/CK5RSSC10/p1606754524365300

[yashrsharma44]

Currently, we have deployed a basic request logging for HTTP(#2849) and it seems to be working well. However, with the new addition of YAML config for request logging, it raises a question, how should we warn the user for the deprecating flag for request logging for HTTP.

• Should we add this message at the start of the help of log.request.decision - Deprecation Warning - This flag would be soon deprecated, and replaced with YAML config...
• Or maybe add in a warning log when the flag is used, that we would deprecate this in the next release.
  Need ideas for warning users.

Another issue is that, would we allow configuration from both the flags and YAML? Or one?

WDYT? cc @yeya24 @bwplotka @kakkoyun

[yashrsharma44]

Added the YAML configuration for request logging - Sample Config File - https://gist.github.com/yashrsharma44/02f5765c5710dd09ce5d14e854f22825
TODO:

• Add a deprecation warning for using the old flag for request logging
• Complete the todos in the code
• Added some more fields in the HTTP logging.
• Add regex for the Method, Service and Path field
• Discuss which components need to have the request logging enabled.

[yashrsharma44]

Feature Request: Would be nice if we add in the error message as well - https://cloud-native.slack.com/archives/CK5RSSC10/p1606754524365300

Currently, only gRPC provides logging of error, HTTP returns a status code for the same. If we want to log the error for HTTP, we need it from the response body, which is kind of blocking process and not worth it. I have added more fields for HTTP logs, which would help in finding the component which sends in the error.

[bwplotka]

Looks super nice, thanks.

Generally lgtm, just minor nits.

[yashrsharma44]

Documentation of this new feature would be tracked in this issue #3623 😎 💪

[bwplotka]

Nice! Some suggestions still.

High level suggestion:

• Please test things manually. I don't think flag filling works in current version at all
• Make sure we don't use panics or break consistency. Why suddenly we return error different request logging flag?
• Request logging is important but not the core of Thanos functionality. So why warning about deprecation of this flag on every Thanos run, even though only small portion is using this feature?

[bwplotka]

As above

[yashrsharma44]

Can you elaborate on this -

Please test things manually. I don't think flag filling works in current version at all

[yashrsharma44]

Make sure we don't use panics or break consistency. Why suddenly we return error different request logging flag?

Didn't we agree on panic quickly if configs not correct?

[bwplotka]

Nice.

Looks super close, but some things to improve still 🤗

[yashrsharma44]

PTAL whenever free 😎 @kakkoyun @bwplotka

[yashrsharma44]

I had deleted the fork of Thanos for some reason, hence I am not able to push changes to this PR.
Created another PR to track the changes - #3862

[bwplotka]

Function should have verb in name. Parse Configure would be better as you suggested offline.