Request Logging

[yashrsharma44]

This PR achieves to add in a Request/Response logger in grpc_middlewares v2 branch.

Fixes #310

Current TODO -

• Initial setup for the RequestReporter Configure the request logger in the old logger itself
• Write tests for the new reporter
• Write examples for the new reporter
• Decide what to log after we can access the request/response object cc @bwplotka
  ref: https://github.com/grpc-ecosystem/go-grpc-middleware/pull/311/files#diff-0c98eb4ff4e54e07ef0a999e5d5bd678R137
• Naming of the reporter - Is the current naming correct, or do we want something else 😛

If any suggestions are there, feel free to add in more 😅

Signed-off-by: Yash Sharma yashrsharma44@gmail.com

[bwplotka]

Hm, I still don't get the need for separate logger.

We have already one reporter. One Request is needed? the reporter is also request.

The only missing log line would be on start which we can do based on decider, no? 🤔

[kakkoyun]

So far so good. I've left a couple of suggestions.

[bwplotka]

Hm, not sure about it either, will take a look closer how we could implement it and let's talk on our 1:2 cc @kakkoyun

[bwplotka]

There is easy way how to do what we want btw (:

[yashrsharma44]

After having a 1:2 call with @bwplotka and @kakkoyun, we decided to modify the objectives of this PR -

• Having a precall setup before the actual logging starts
  • Decider to check if logging should be enabled (Implemented at the interceptor level. If not enabled, we return a NoopReporter)
  • Decider to check if logging should be enabled for a given method( To be implemented using the options of the grpc.Options)
  • Log the starting messages (We check using a boolean if the current message is the first and log it in the PostMsgSend/PostMsgRecv level)
• PostMsgSend / PostMsgRecv can log the payload (currently to be worked on in the next PR)
• PostCall to log the errors and corresponding error-logs

This is a bit different from the original implementation because in the earlier PR, we were logging all the messages of the stream, which is quite verbose and irrelevant.

[bwplotka]

Nice, looking awesome, just minor nits!

[yashrsharma44]

Hey Everyone, this PR is ready to be merged.
Would love a final round of review - @kakkoyun @bwplotka @johanbrandhorst

[bwplotka]

Hm, I somehow don't see the latest revision of this, let's discuss

[yashrsharma44]

Tests failing due to - #319

[bwplotka]

It's really LGTM, just small nits on the actual message logged (: and maybe decider.

This PR shows that we might be missing details in the initial design about the "interface" of this change.

The interface is really:

• how user will configure
• what users will see on different configuration.

Can we add some design section for it to make it clear? (: It would avoid some confusion.

IMO:

• Human readable consistent message, and having all variables as fields (e.g type, method as well!)
• finished call and started call is really enough if we would have component:server field or something, right?
• What about single decider:

type LogDecision struct {
     LogStarted, LogFinished bool
}

type Decider func (....) Decision

The alternative is:

type Decider int
const (
    NoLog Decider = iota
    LogStarted
    LogFinished
  
)

WDYT? (:

[yashrsharma44]

Changes made uptil now -

• Human Readable Messages - All the log entries are changed to use space instead of _.
• Using key-value pairs for storing the kind, type and component.
• Changed to start call and finished call.

Changes that need to be made -

• Add a design/example section for using the API(Mentioned in my original TODO)
• Single Decider with multiple options, and an ENUM based interface to configure the options in an easy way.

[yashrsharma44]

I would like to extend the Decider as using a struct instead of ENUM, because -

• We would have 2^2 possibilities, so we need to keep 4 variables for checking the option of logging.
• We can use a struct for storing two variables to check if we want to log at start and end. This way, with minimal fuss, all the conditions are checked.

Interface of new Decider -

type LogDecision struct {
     LogStarted, LogFinished bool
}
func NewLogDecision(LogStarted, LogFinished bool) *LogDecision {
     return &LogDecision {
          LogStarted : LogStarted,
          LogFinished : LogFinished,
     }
}

type Decider func (methodName string, err error) *LogDecision

// Example implementation of the decider
func LogDecider(methodName string, err error) *LogDecision {
          // Have condition check
          return NewLogDecision(logStart, LogFinish)
}

WDYT?

[kakkoyun]

nit

[kakkoyun]

@yashrsharma44 Ok, the interface is apparently different than I had assumed so you can ignore my comments or even better we can update the interface since this is a v2 branch.

[bwplotka]

Some notes after 1:1

[bwplotka]

Looks like we want decider to NOT have error and do adaptive logging base on error, using errCode to Log Level, 💪

Looks like we are going into simpler functions, which means I think I would vote for enums

[yashrsharma44]

Once we fixate on the Decider implementation, I can start with the examples 🤓

[bwplotka]

Nice, Looking good! Small things only.

[bwplotka]

Tiny nit only, we can fix that later (:

LGTM, Thanks! 👍

[bwplotka]

Suggested change

	logger = logger.With("grpc.error", fmt.Sprintf("%v", err))
	logger = logger.With("grpc.error", err.Error())

[yashrsharma44]

Would have been nice not to have skipped the error parameter here. The logging can also be configured using the error as well,(since status code can be derived from the response error).