logging with context

[zellyn]

Would you be willing to accept a patch that threads context into all the grpclog calls? The default implementation would discard it, but it would be useful for logging packages that take trace or other information in the context.

[iamqizhao]

@bradfitz

I got an impression that Brad has a grand plan to improve logging story of grpc. Brad, can you throw out the concrete plan before taking action on it?

[bradfitz]

Yes, context propagation would be great.

I would also like to address #289 at the same time as any API changes, and change the grpclogger.Logger interface to be much smaller. Currently it is:

// Logger mimics golang's standard Logger as an interface.                                                                                                                                                           
type Logger interface {
        Fatal(args ...interface{})
        Fatalf(format string, args ...interface{})
        Fatalln(args ...interface{})
        Print(args ...interface{})
        Printf(format string, args ...interface{})
        Println(args ...interface{})
}

But I'd like to get it down to a more Go-like (small) interface. Something like:

type Logger interface {
     Log(context.Context, error)
     Fatal(context.Context, error)
}

As a transition, we can use contest.TODO and errors.New+fmt.Errorf to fix existing callers. Notably, error can be stringified. That's all that matters.

Then we create a new grpcerrors package with our error types, for other logger implementations to do what they want with, converting them to key/value pairs, assigning priority levels, etc.

Maybe we'll even define some optional interfaces in grpcerrors for error types to implement. (but won't be required... using fmt.Errorf is always an option).

And we can keep all the helper funcs in package grpclog like Printf, Fatalf etc, at least for now.

[bradfitz]

Note that my existing PR #546 doesn't change how logging works. It just makes it expected log output quiet during end2end tests, so unexpected output becomes noticeable. But PR #546 can go in independent of this.

[Thomasdezeeuw]

Do mean Log(context.Context, error) or Log(context.Context, string)?

Also with a API change could Fatal be removed completely? I realise that there are situations where it would be required, but not being to able to cleanup on exit (by using os.Exit(1)) can have some bad side effects.

[bradfitz]

I definitely mean error and not string. Making it a string doesn't fix the structured logging problem. An error is just an interface value, so we can add types over time, and also means we can do things like lazy stringification.

[Thomasdezeeuw]

But how would you log (debug) information? Or are you planning on adding log levels to the context?

[bradfitz]

The context could contain the requested log level, which the log sites could inspect to decide whether to log. It's the value being logged that has a level, inspectable via an optional interface on the error values (but people would use helpers).

[bufdev]

A quick thought: adding log level to contexts could be expensive, especially since a new context struct is created every time a value is added. Consider a debug message that is called in a tight loop - it is a lot cheaper to have the log library do:

func Debug(whatever ...interface{}) {
  if level > Level_DEBUG {
    return
  }
  Print(Level_DEBUG, whatever...)
}

Than:

func Print(ctx context.Context, etc ...interface{}) {
  ...
}

grpclog.Print(context.WithValue(ctx, "logLevel", "DEBUG"), etc...)

[bradfitz]

@peter-edge, I don't think anybody was proposing the latter.

[dsymonds]

I can't say I'm a fan of cramming stuff into a context just to signal a log level. That's very different to what context values are intended for.

[bradfitz]

@dsymonds, we're not going to put log level in a context.

[dsymonds]

You said "The context could contain the requested log level, ...". Did I misunderstand that?

[bradfitz]

The context could contain the requested log level

@dsymonds, perhaps that quoted comment of mine was misinterpreted. It doesn't contain the log site's log level. It can contain the requested level of verbose logging from the caller. (e.g. by default, normal log level, but certain requests or during debugging or sampling could request verbose logs as opt-in on that context).

[dsymonds]

Ah, right. I see. Almost like a request-scoped v/vmodule setting. That might be okay, though I think the majority of grpc-go's logging is currently not request-specific.

[bradfitz]

@dsymonds, yeah, and I think the majority of it will remain so. But it's an option if/when we need it.