*: refine the logs of TiDB

[bb7133]

The annoyance

The logs of TiDB are verbose and annoying, in my mind, it is partially due to the fact that: (1) we don't want to lose any detail, even when it is hardly useful. (2) we didn't pay much attention to them.

Give a possible example, a simple ERROR 1046 (3D000): No database selected error like

tidb> select * from t;
ERROR 1046 (3D000): No database selected

Make 2 long annoying entries in TiDB log:

[2021/05/17 22:04:31.486 +08:00] [WARN] [session.go:1410] ["compile SQL failed"] [conn=5] [error="[planner:1046]No database selected"] [errorVerbose="[planner:1046]No database selected\ngithub.com/pingcap/errors.AddStack\n\t/home/bb7133/Projects/gopath/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20201126102027-b0a155152ca3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/home/bb7133/Projects/gopath/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20201126102027-b0a155152ca3/juju_adaptor.go:15\ngithub.com/pingcap/tidb/planner/core.(*preprocessor).handleTableName\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/planner/core/preprocess.go:1116\ngithub.com/pingcap/tidb/planner/core.(*preprocessor).Leave\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/planner/core/preprocess.go:355\ngithub.com/pingcap/parser/ast.(*TableName).Accept\n\t/home/bb7133/Projects/gopath/pkg/mod/github.com/pingcap/parser@v0.0.0-20210325072920-0d17053a8a69/ast/dml.go:403\ngithub.com/pingcap/parser/ast.(*TableSource).Accept\n\t/home/bb7133/Projects/gopath/pkg/mod/github.com/pingcap/parser@v0.0.0-20210325072920-0d17053a8a69/ast/dml.go:546\ngithub.com/pingcap/parser/ast.(*Join).Accept\n\t/home/bb7133/Projects/gopath/pkg/mod/github.com/pingcap/parser@v0.0.0-20210325072920-0d17053a8a69/ast/dml.go:231\ngithub.com/pingcap/parser/ast.(*TableRefsClause).Accept\n\t/home/bb7133/Projects/gopath/pkg/mod/github.com/pingcap/parser@v0.0.0-20210325072920-0d17053a8a69/ast/dml.go:744\ngithub.com/pingcap/parser/ast.(*SelectStmt).Accept\n\t/home/bb7133/Projects/gopath/pkg/mod/github.com/pingcap/parser@v0.0.0-20210325072920-0d17053a8a69/ast/dml.go:1231\ngithub.com/pingcap/tidb/planner/core.Preprocess\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/planner/core/preprocess.go:89\ngithub.com/pingcap/tidb/executor.(*Compiler).Compile\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/executor/compiler.go:57\ngithub.com/pingcap/tidb/session.(*session).ExecuteStmt\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/session/session.go:1403\ngithub.com/pingcap/tidb/server.(*TiDBContext).ExecuteStmt\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/server/driver_tidb.go:218\ngithub.com/pingcap/tidb/server.(*clientConn).handleStmt\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/server/conn.go:1623\ngithub.com/pingcap/tidb/server.(*clientConn).handleQuery\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/server/conn.go:1496\ngithub.com/pingcap/tidb/server.(*clientConn).dispatch\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/server/conn.go:1030\ngithub.com/pingcap/tidb/server.(*clientConn).Run\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/server/conn.go:795\ngithub.com/pingcap/tidb/server.(*Server).onConn\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/server/server.go:477\nruntime.goexit\n\t/home/bb7133/Softwares/go/src/runtime/asm_amd64.s:1357"] [SQL="select * from t"]
[2021/05/17 22:04:31.486 +08:00] [INFO] [conn.go:812] ["command dispatched failed"] [conn=5] [connInfo="id:5, addr:127.0.0.1:41398 status:10, collation:utf8_general_ci, user:root"] [command=Query] [status="inTxn:0, autocommit:1"] [sql="select * from t"] [txn_mode=OPTIMISTIC] [err="[planner:1046]No database selected\ngithub.com/pingcap/errors.AddStack\n\t/home/bb7133/Projects/gopath/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20201126102027-b0a155152ca3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/home/bb7133/Projects/gopath/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20201126102027-b0a155152ca3/juju_adaptor.go:15\ngithub.com/pingcap/tidb/planner/core.(*preprocessor).handleTableName\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/planner/core/preprocess.go:1116\ngithub.com/pingcap/tidb/planner/core.(*preprocessor).Leave\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/planner/core/preprocess.go:355\ngithub.com/pingcap/parser/ast.(*TableName).Accept\n\t/home/bb7133/Projects/gopath/pkg/mod/github.com/pingcap/parser@v0.0.0-20210325072920-0d17053a8a69/ast/dml.go:403\ngithub.com/pingcap/parser/ast.(*TableSource).Accept\n\t/home/bb7133/Projects/gopath/pkg/mod/github.com/pingcap/parser@v0.0.0-20210325072920-0d17053a8a69/ast/dml.go:546\ngithub.com/pingcap/parser/ast.(*Join).Accept\n\t/home/bb7133/Projects/gopath/pkg/mod/github.com/pingcap/parser@v0.0.0-20210325072920-0d17053a8a69/ast/dml.go:231\ngithub.com/pingcap/parser/ast.(*TableRefsClause).Accept\n\t/home/bb7133/Projects/gopath/pkg/mod/github.com/pingcap/parser@v0.0.0-20210325072920-0d17053a8a69/ast/dml.go:744\ngithub.com/pingcap/parser/ast.(*SelectStmt).Accept\n\t/home/bb7133/Projects/gopath/pkg/mod/github.com/pingcap/parser@v0.0.0-20210325072920-0d17053a8a69/ast/dml.go:1231\ngithub.com/pingcap/tidb/planner/core.Preprocess\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/planner/core/preprocess.go:89\ngithub.com/pingcap/tidb/executor.(*Compiler).Compile\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/executor/compiler.go:57\ngithub.com/pingcap/tidb/session.(*session).ExecuteStmt\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/session/session.go:1403\ngithub.com/pingcap/tidb/server.(*TiDBContext).ExecuteStmt\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/server/driver_tidb.go:218\ngithub.com/pingcap/tidb/server.(*clientConn).handleStmt\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/server/conn.go:1623\ngithub.com/pingcap/tidb/server.(*clientConn).handleQuery\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/server/conn.go:1496\ngithub.com/pingcap/tidb/server.(*clientConn).dispatch\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/server/conn.go:1030\ngithub.com/pingcap/tidb/server.(*clientConn).Run\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/server/conn.go:795\ngithub.com/pingcap/tidb/server.(*Server).onConn\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/server/server.go:477\nruntime.goexit\n\t/home/bb7133/Softwares/go/src/runtime/asm_amd64.s:1357"]

It is annoying for at least 2 reasons: (1) We don't need the stack at all because the cause is clear enough. (2) The stack is too long because the full path of the source code is given, which is obviously unnecessary.

The proposal

IMO we can try to refine the logs of TiDB by:

• Examine the errors, remove/simplify the unnecessary stacks reported according to their semantics:
  • Simple errors caused by the client, or can be easily reproduced can be removed. Example: ERROR 1046: No database selected, ERROR 1064: Error in SQL syntax).
  • Logs that are duplicated can be removed, as you can see from the example given above.
  • To be added.
• Shorten the stack by trimming the path of source code. Although we've the compatibility issue of go build --trim with the plugin(plugin: spurious version-mismatch error for packages that differ only in debug information golang/go#31278 (comment)), it is still possible to trim them without the built-in mechanism of Golang.
• Try to shorten the log entries by a more 'compact' format than the current one:
  • zap is structured and powerful, but the current format like "[name': 'body']"can be simplified.
  • WARNING: change of the format can be complicated and break the ecosystem framework by the users if they rely on the current one.
• Close the existing issues that related to 'log refinements':
  • Refine panic log when it's a OOM Panic #21341
  • reduce the info log for create table #15807
  • To show connId in each line of log, deprecate logutil.BgLogger to logutil.Logger(ctx) #15638 and Print Txn ID and Query ID in log to trace the whole lifetime of a Txn / SQL #17845
• To be added.

[zz-jason]

LGTM. Maybe we need to enumerate the possible error to check whether there are redundant logs. A question is, how to add tests to ensure the logs are not adding back in the future?

[morgo]

@bb7133 can we categorize the ones that are purely "client errors" as not server loggable? i.e. the examples no database selected and syntax error fit clearly in this category to me.

The client error information schema tables are a better fit.