*: refine the logs of TiDB

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(https://github.com/golang/go/issues/31278#issuecomment-541106229), 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':
  • https://github.com/pingcap/tidb/issues/21341
  • https://github.com/pingcap/tidb/issues/15807
  • https://github.com/pingcap/tidb/issues/15638 and https://github.com/pingcap/tidb/issues/17845
• To be added.