Logging of unknown system variables is overly verbose

[dveeden]

Enhancement

A query like the one below ends up with mutliple log lines, including a stacktrace.

SELECT @@query_response_time_stats;

[2022/07/07 09:49:40.957 +02:00] [WARN] [session.go:1959] ["compile SQL failed"] [conn=2199023255955] [error="[variable:1193]Unknown system variable 'query_response_time_stats'"] [SQL="SELECT @@query_response_time_stats"]
[2022/07/07 09:49:40.958 +02:00] [INFO] [conn.go:1149] ["command dispatched failed"] [conn=2199023255955] [connInfo="id:2199023255955, addr:[::1]:45964 status:10, collation:utf8mb4_0900_ai_ci, user:root"] [command=Query] [status="inTxn:0, autocommit:1"] [sql="SELECT @@query_response_time_stats"] [txn_mode=OPTIMISTIC] [timestamp=0] [err="[variable:1193]Unknown system variable 'query_response_time_stats'\ngithub.com/pingcap/errors.AddStack\n\t/home/dvaneeden/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211224045212-9687c2b0f87c/errors.go:174\ngithub.com/pingcap/errors.(*Error).GenWithStackByArgs\n\t/home/dvaneeden/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211224045212-9687c2b0f87c/normalize.go:164\ngithub.com/pingcap/tidb/planner/core.(*expressionRewriter).rewriteVariable\n\t/home/dvaneeden/dev/pingcap/tidb/planner/core/expression_rewriter.go:1295\ngithub.com/pingcap/tidb/planner/core.(*expressionRewriter).Leave\n\t/home/dvaneeden/dev/pingcap/tidb/planner/core/expression_rewriter.go:1094\ngithub.com/pingcap/tidb/parser/ast.(*VariableExpr).Accept\n\t/home/dvaneeden/dev/pingcap/tidb/parser/ast/expressions.go:1294\ngithub.com/pingcap/tidb/planner/core.(*PlanBuilder).rewriteExprNode\n\t/home/dvaneeden/dev/pingcap/tidb/planner/core/expression_rewriter.go:199\ngithub.com/pingcap/tidb/planner/core.(*PlanBuilder).rewriteWithPreprocess\n\t/home/dvaneeden/dev/pingcap/tidb/planner/core/expression_rewriter.go:145\ngithub.com/pingcap/tidb/planner/core.(*PlanBuilder).buildProjection\n\t/home/dvaneeden/dev/pingcap/tidb/planner/core/logical_plan_builder.go:1290\ngithub.com/pingcap/tidb/planner/core.(*PlanBuilder).buildSelect\n\t/home/dvaneeden/dev/pingcap/tidb/planner/core/logical_plan_builder.go:3919\ngithub.com/pingcap/tidb/planner/core.(*PlanBuilder).Build\n\t/home/dvaneeden/dev/pingcap/tidb/planner/core/planbuilder.go:701\ngithub.com/pingcap/tidb/planner.optimize\n\t/home/dvaneeden/dev/pingcap/tidb/planner/optimize.go:329\ngithub.com/pingcap/tidb/planner.Optimize\n\t/home/dvaneeden/dev/pingcap/tidb/planner/optimize.go:202\ngithub.com/pingcap/tidb/executor.(*Compiler).Compile\n\t/home/dvaneeden/dev/pingcap/tidb/executor/compiler.go:79\ngithub.com/pingcap/tidb/session.(*session).ExecuteStmt\n\t/home/dvaneeden/dev/pingcap/tidb/session/session.go:1948\ngithub.com/pingcap/tidb/server.(*TiDBContext).ExecuteStmt\n\t/home/dvaneeden/dev/pingcap/tidb/server/driver_tidb.go:229\ngithub.com/pingcap/tidb/server.(*clientConn).handleStmt\n\t/home/dvaneeden/dev/pingcap/tidb/server/conn.go:2022\ngithub.com/pingcap/tidb/server.(*clientConn).handleQuery\n\t/home/dvaneeden/dev/pingcap/tidb/server/conn.go:1876\ngithub.com/pingcap/tidb/server.(*clientConn).dispatch\n\t/home/dvaneeden/dev/pingcap/tidb/server/conn.go:1371\ngithub.com/pingcap/tidb/server.(*clientConn).Run\n\t/home/dvaneeden/dev/pingcap/tidb/server/conn.go:1121\ngithub.com/pingcap/tidb/server.(*Server).onConn\n\t/home/dvaneeden/dev/pingcap/tidb/server/server.go:566\nruntime.goexit\n\t/usr/lib/golang/src/runtime/asm_amd64.s:1571"]

I think this should:

• Not include a backtrace
• Log a single line/message

This can happen when migrating from another MySQL-compatible database system and/or when using applications or connectors that send these. This is not always something the end-user can influence and it is something that can happen for every connection in case of the connector doing this.

[dveeden]

The example in the description has a variable that is coming from https://docs.percona.com/percona-server/5.7/diagnostics/response_time_distribution.html