xdsclient/transport: reduce chattiness of logs #5992
Conversation
|
@arvindbr8 : FYI |
|
|
||
| // V reports whether verbosity level l is at least the requested verbose level. | ||
| func (pl *PrefixLogger) V(l int) bool { | ||
| return Logger.V(l) |
There was a problem hiding this comment.
Shouldn't this be pl.logger.V(l)?
And above, in Debugf.
There was a problem hiding this comment.
PrefixLogger is a concrete type, while the field logger is of type grpclog.DepthLoggerV2.
grpclog.DepthLoggerV2 does not have a Debug or V method.
type DepthLoggerV2 interface {
// InfoDepth logs to INFO log at the specified depth. Arguments are handled in the manner of fmt.Println.
InfoDepth(depth int, args ...interface{})
// WarningDepth logs to WARNING log at the specified depth. Arguments are handled in the manner of fmt.Println.
WarningDepth(depth int, args ...interface{})
// ErrorDepth logs to ERROR log at the specified depth. Arguments are handled in the manner of fmt.Println.
ErrorDepth(depth int, args ...interface{})
// FatalDepth logs to FATAL log at the specified depth. Arguments are handled in the manner of fmt.Println.
FatalDepth(depth int, args ...interface{})
}The global Logger, which we have to end up using is of type grpclog.LoggerV2, and it has methods for debug logging and checking the verbosity levels. We need to coalesce these interfaces a little. I feel that would be a bigger effort and would block this PR, which is really required asap, to reduce log spam.
I've added a TODO here and filed a bug for the same.
| @@ -120,19 +120,19 @@ func (t *Transport) lrsRunner(ctx context.Context) { | |||
| defer cancel() | |||
| stream, err := v3lrsgrpc.NewLoadReportingServiceClient(t.cc).StreamLoadStats(streamCtx) | |||
| if err != nil { | |||
| t.logger.Warningf("Failed to create LRS stream: %v", err) | |||
| t.logger.Warningf("Creating LRS stream to server %q: %v", t.serverURI, err) | |||
There was a problem hiding this comment.
I don't really like this style of not saying something bad happened, but printing an error string after the attempted operation instead. Is this the new style? E.g. WARNING: Going swimming: water is cold doesn't actually tell me if this means things broke completely, so it's not going swimming, or if it might still swim but perform in a degraded fashion.
There was a problem hiding this comment.
I conflated the concept of not having filler words in error strings (which tend to get repeated when errors are propagated up the stack) with log messages. I have changed everything in here to say that something actually failed. Thanks.
| return | ||
| } | ||
| } | ||
| } | ||
|
|
||
| func (t *Transport) sendFirstLoadStatsRequest(stream lrsStream, node *v3corepb.Node) error { | ||
| req := &v3lrspb.LoadStatsRequest{Node: node} | ||
| t.logger.Debugf("Sending initial LoadStatsRequest: %s", pretty.ToJSON(req)) | ||
| if t.logger.V(perRPCVerbosityLevel) { |
There was a problem hiding this comment.
Debugf is V(2) && Info(). If increasing the verbosity level of these logs, we should also switch to Infof instead.
Also, consider a wrapper instead to avoid repeating this pattern a lot. Maybe t.logger can override Debugf to be level 9? Or add a Trace level or something. Or maybe we should just change grpclog.Debugf to use 9 everywhere?
There was a problem hiding this comment.
I changed all calls to Debugf inside this verbosity check to Infof. I didn't want to change the default verbosity level of Debugf to 9 since I still want to retain the ability to get some debug logs, but not all (especially the ones corresponding to every request/response). Thanks.
- mention that something failed in the log strings - add a TODO for refactoring existing logger interfaces - use `Infof` instead of `Debugf` when using explicit verbosity checks
| @@ -45,6 +45,9 @@ import ( | |||
| statuspb "google.golang.org/genproto/googleapis/rpc/status" | |||
| ) | |||
|
|
|||
| // Extremely verbose per-RPC level logs should check for this verbosity level. | |||
There was a problem hiding this comment.
Nit: I don't like this comment. Extremely feels pointless, and what does "check for this verbosity level" mean? Perhaps talk about gating the detail of the logs/logs being terse.
There was a problem hiding this comment.
Done. Made the comment more verbose :)
This is one among a set of PRs to reduce chattiness of xdsclient logs. Addresses #5839.
This PR addresses logs in the
xdsclient/transportpackage:Vmethod to thePrefixLoggertype to make it possible to log at specified verbosity.Info.perRPCVerbosityLevel, a terse message atDebugis loggedDebugWith this change, if the user sets severity to
INFOand does not set verbosity levels, transport logs will only contain entries for events like transport creation, stream creation, stream closing etc.RELEASE NOTES: none