Zap logger prints connection reset by peer but capnslog doesn't

[xxx7xxxx]

Under the newest master code.

When I execute this command:

make
./bin/etcd --logger zap &
export ETCDCTL_API=3
./bin/etcdctl get hello

The zap logger will print:

{"level":"warn","ts":1546426325.950272,"caller":"grpclog/grpclog.go:60","msg":"transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:2379->127.0.0.1:50450: read: connection reset by peer"}

But I change the startup command line to ./bin/etcd # which means capnslog logger , there isn't the same warn log.

[hexfusion]

But I change the startup command line to ./bin/etcd # which means capnslog logger , there isn't the same warn log.

Yeah --logger will be included in 3.4 (unreleased) and we plan to deprecate capnslog in 3.5. I think for this very reason zap is a much better logging solution. I have not dug into this much but feels like it could be a capnslog bug.

[xxx7xxxx]

It is easy to reproduce this weird behavior. Just build repo, then start etcd with different loggers, use v3 etcdctl to get a random key. I think this kind of log should be printed.
Related issues: #8822 #9165

[hexfusion]

It is easy to reproduce this weird behavior. Just build repo, then start etcd with different loggers, use v3 etcdctl to get a random key. I think this kind of log should be printed.

@longdeqidao, I understand we would love your help if you are interested in trying to resolve this.

[WIZARD-CXY]

I came across the same bug here. @hexfusion let me take some time investigate and maybe fix this weird bug

[jingyih]

Thanks @WIZARD-CXY. I just tried, it is reproducible.

[WIZARD-CXY]

@jingyih @hexfusion @xxx7xxxx I took some time to debug this and find that it is logger verbose settings that make this weird behavior.It makes different dicisions when logging

warningf("transport: http2Server.HandleStreams failed to read frame: %v", err) 

in http2_server.go

The warningf logging really print something when below func V returns true.

// V reports whether verbosity level l is at least the requested verbose level.
func V(l int) bool {
        return logger.V(l)
}

The input value l is defined as const logLevel = 2

when using zap

func (zl *zapGRPCLogger) V(l int) bool {
	// infoLog == 0
	if l <= 0 { // debug level, then we ignore info level in gRPC
		return !zl.lg.Core().Enabled(zapcore.DebugLevel)
	}
	return true
}

The capnslog uses verbose level 0

func NewLoggerV2(infoW, warningW, errorW io.Writer) LoggerV2 {
    return NewLoggerV2WithVerbosity(infoW, warningW, errorW, 0)
}

func (g *loggerT) V(l int) bool {
	return l <= g.v   #g.v is set to 0
}

From above capnslog's V function return false while zap V function returns true.So capnslog never prints the warning msg while zap prints it out.

I hope I make the above logic clear.

[WIZARD-CXY]

I checked the code and it's not easy to ignore this error msg unless we modify the zap code.

[jingyih]

By default the log level is INFO. So it is consistent that the zap logger prints the grpc warning? Maybe we should trace down what caused the warning in the first place and see if we can fix that? It looks like the client reset the stream while server still tries to read from it.

[WIZARD-CXY]

From the related issue, I think this msg is spam and can be ignored grpc/grpc-go#1062 (comment)

[WIZARD-CXY]

https://github.com/grpc/grpc-go/pull/1340/files#diff-c00e2e14c3cf91717f079174c1f48bbeR39

[WIZARD-CXY]

Can the zap logger set the verbose level? I go through the code and doc, but didn't find it...

[jingyih]

The flag:
https://github.com/etcd-io/etcd/blob/master/Documentation/op-guide/configuration.md#--log-level

The code:

etcd/embed/config_logging.go

Line 177 in fb7703a

copied.Level = zap.NewAtomicLevelAt(logutil.ConvertToZapLevel(cfg.LogLevel))

[WIZARD-CXY]

ah, but this doesn't affect the verbose level

[jingyih]

hmmm... Looks like it is by design? Maybe because we want to keep the old behavior?

etcd/pkg/logutil/zap_grpc.go

Lines 23 to 26 in fb7703a

	// NewGRPCLoggerV2 converts "*zap.Logger" to "grpclog.LoggerV2".
	// It discards all INFO level logging in gRPC, if debug level
	// is not enabled in "*zap.Logger".
	func NewGRPCLoggerV2(lcfg zap.Config) (grpclog.LoggerV2, error) {

cc @gyuho

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.