*: refine the logs of TiDB · pingcap/tidb#24698

(2 comments) (4 reactions) (1 assignee)Go (40,090 stars) (6,186 forks)batch import

help wantedsig/sql-infratype/enhancement

Description

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':
To be added.

Contributor guide

Tech stack: go
Domain: backenddatabase
Issue type: refactor
Difficulty: 3
Estimated time: 1-2 days
Activity status: stale
Clarity: clear
Prerequisites: basic understanding of Gofamiliarity with TiDB architectureknowledge of logging patterns
Newbie friendliness: 40
Research direction: Examine the logs and error handling in files like session.go, conn.go, and planner/core/preprocess.go. The issue proposes removing unnecessary stack traces for client side errors (e.g., 'No database selected') and shortening stack paths. Review existing log refinement issues linked in the description (e.g., #21341) to avoid duplication. Consider using Go's runtime package to trim paths or zap's built in options. The assignee may have ongoing work; check comments for updates.