The gRPC log is output to the wrong file

[tangenta]

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. Minimal reproduce step (Required)

1. Start TiDB with the following config:

[log.file]
max-size = 1

2. Enable TopSQL or set GRPC_DEBUG environment variable to let gRPC keep printing

[ERROR] [grpclogger.go:116] ["[transport]transport: Got too many pings from the client, closing the connection."] [system=grpc] [grpc_log=true]"
[ERROR] [grpclogger.go:116] ["[transport]transport: loopyWriter.run returning. Err: transport: Connection closing"] [system=grpc] [grpc_log=true]

3. Add workload to cluster to populate the log file.
4. When the log file is rotated, gRPC error message should be output to the origin log file.

2. What did you expect to see? (Required)

New error messages from gRPC should be output to "tidb.log".

3. What did you see instead (Required)

New error messages from gRPC are output to the rotated log file.

From tidb-2022-11-07T16-14-51.727.log:

[2022/11/07 16:15:35.553 +08:00] [ERROR] [grpclogger.go:116] ["[transport]transport: Got too many pings from the client, closing the connection."] [system=grpc] [grpc_log=true]
[2022/11/07 16:15:35.554 +08:00] [ERROR] [grpclogger.go:116] ["[transport]transport: loopyWriter.run returning. Err: transport: Connection closing"] [system=grpc] [grpc_log=true]
[2022/11/07 16:16:45.557 +08:00] [ERROR] [grpclogger.go:116] ["[transport]transport: Got too many pings from the client, closing the connection."] [system=grpc] [grpc_log=true]
[2022/11/07 16:16:45.558 +08:00] [ERROR] [grpclogger.go:116] ["[transport]transport: loopyWriter.run returning. Err: transport: Connection closing"] [system=grpc] [grpc_log=true]

4. What is your TiDB version? (Required)

30a76ce

[tangenta]

There are two logger instances, one for TiDB and the other for gRPC:

tidb/util/logutil/log.go

Line 102 in a33d971

gl, props, err := log.InitLogger(&cfg.Config, zap.AddStacktrace(zapcore.FatalLevel))

tidb/util/logutil/log.go

Line 130 in a33d971

l, prop, err = log.InitLogger(&config, zap.AddStacktrace(zapcore.FatalLevel))

Each of the logger maintains its own size, checks the size in Write() function and rotates the file if necessary.

The root cause: when a logger's file descriptor changes, there is no way to inform the other.

There are possible ways to fix this issue:

• Unify the loggers of TiDB and gRPC. This means we cannot set a different level for gRPC logger. GRPC_DEBUG will not take effect anymore.
• Discard gPRC log. We may not be able to diagnose the gRPC problem by log.
• Print the gPRC log to stderr. The logger is more fragmented.

@breezewish @SabaPing @crazycs520 WDYT?

[xhebox]

/assign xhebox

I am interested in refactoring the mess of log and cli flags, #38857 is also a related issue. I'll post a simple workaround for this first.