`SELECT $$` from MySQL Client leads to errors in the logs

[dveeden]

Bug Report

MySQL Client 8.4.0 sends SELECT $$ when connecting and this leads to log entries like this:

{
  "level": "INFO",
  "time": "2024/06/03 10:14:15.875 +02:00",
  "caller": "conn.go:1151",
  "message": "command dispatched failed",
  "conn": 2097154,
  "session_alias": "",
  "connInfo": "id:2097154, addr:127.0.0.1:57330 status:10, collation:utf8mb4_0900_ai_ci, user:root",
  "command": "Query",
  "status": "inTxn:0, autocommit:1",
  "sql": "select $$",
  "txn_mode": "PESSIMISTIC",
  "timestamp": 0,
  "err": "[planner:1054]Unknown column '$$' in 'field list'\ngithub.com/pingcap/errors.AddStack\n\t/home/dvaneeden/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20240318064555-6bd07397691f/errors.go:178\ngithub.com/pingcap/errors.(*Error).GenWithStackByArgs\n\t/home/dvaneeden/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20240318064555-6bd07397691f/normalize.go:175\ngithub.com/pingcap/tidb/pkg/planner/core.(*expressionRewriter).toColumn\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/planner/core/expression_rewriter.go:2438\ngithub.com/pingcap/tidb/pkg/planner/core.(*expressionRewriter).Leave\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/planner/core/expression_rewriter.go:1454\ngithub.com/pingcap/tidb/pkg/parser/ast.(*ColumnName).Accept\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/parser/ast/expressions.go:534\ngithub.com/pingcap/tidb/pkg/parser/ast.(*ColumnNameExpr).Accept\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/parser/ast/expressions.go:607\ngithub.com/pingcap/tidb/pkg/planner/core.rewriteExprNode\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/planner/core/expression_rewriter.go:302\ngithub.com/pingcap/tidb/pkg/planner/core.(*PlanBuilder).rewriteWithPreprocess\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/planner/core/expression_rewriter.go:241\ngithub.com/pingcap/tidb/pkg/planner/core.(*PlanBuilder).buildProjection\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/planner/core/logical_plan_builder.go:1713\ngithub.com/pingcap/tidb/pkg/planner/core.(*PlanBuilder).buildSelect\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/planner/core/logical_plan_builder.go:4238\ngithub.com/pingcap/tidb/pkg/planner/core.(*PlanBuilder).Build\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/planner/core/planbuilder.go:515\ngithub.com/pingcap/tidb/pkg/planner.buildLogicalPlan\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/planner/optimize.go:549\ngithub.com/pingcap/tidb/pkg/planner.optimize\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/planner/optimize.go:466\ngithub.com/pingcap/tidb/pkg/planner.Optimize\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/planner/optimize.go:334\ngithub.com/pingcap/tidb/pkg/executor.(*Compiler).Compile\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/executor/compiler.go:99\ngithub.com/pingcap/tidb/pkg/session.(*session).ExecuteStmt\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/session/session.go:2094\ngithub.com/pingcap/tidb/pkg/server.(*TiDBContext).ExecuteStmt\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/server/driver_tidb.go:294\ngithub.com/pingcap/tidb/pkg/server.(*clientConn).handleStmt\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/server/conn.go:2021\ngithub.com/pingcap/tidb/pkg/server.(*clientConn).handleQuery\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/server/conn.go:1774\ngithub.com/pingcap/tidb/pkg/server.(*clientConn).dispatch\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/server/conn.go:1348\ngithub.com/pingcap/tidb/pkg/server.(*clientConn).Run\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/server/conn.go:1114\ngithub.com/pingcap/tidb/pkg/server.(*Server).onConn\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/server/server.go:739\nruntime.goexit\n\t/usr/lib/golang/src/runtime/asm_amd64.s:1695"
}

1. Minimal reproduce step (Required)

Connect with MySQL Client 8.4.0

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

No errors

3. What did you see instead (Required)

Error about SELECT $$

4. What is your TiDB version? (Required)

Release Version: v8.2.0-alpha-282-gfc3132ce9b
Edition: Community
Git Commit Hash: fc3132ce9bbc10a36ba94111b50b112d9c330e36
Git Branch: master
UTC Build Time: 2024-06-03 07:50:31
GoVersion: go1.22.3
Race Enabled: false
Check Table Before Drop: false
Store: unistore

Impact on users

1. Adds noise to the logging
2. Might increase error metrics, causing noise in metrics.

[dveeden]

• MySQL 8.4.0 responds with error 1064 (ER_PARSE_ERROR)
• TiDB responds with error 1054 (ER_BAD_FIELD_ERROR)

This looks related to javascript support in MySQL Enterprise: https://blogs.oracle.com/mysql/post/introducing-javascript-support-in-mysql

The code for this in the client is here: https://github.com/mysql/mysql-server/blob/824e2b4064053f7daf17d7f3f84b7a3ed92e5fb4/client/mysql.cc#L1286-L1290

The commit for this is https://github.com/mysql/mysql-server/commit/9c7bc2973110861b731311f8b42af152f62d65af

This is mentioned in the MySQL 8.1.0 release notes:

The use of the dollar sign ($) as the initial character of an unquoted identifier was deprecated in MySQL 8.0.32. In this release, the use of an unquoted identifier starting with the dollar sign and containing one or more dollar signs in addition to the first one generates a syntax error. Quoted identifiers, and unquoted identifiers that start with a dollar sign but contain no additional occurrences of this character, are not affected by this change. Use of an unquoted identifier with a leading dollar sign that is otherwise permitted continues to raise a warning.

For more information, see Schema Object Names. (WL#15254)

References: See also: Bug #34684193.

[dveeden]

We could change the level of this specific query to DEBUG.

[dveeden]

For example:

diff --git a/pkg/server/conn.go b/pkg/server/conn.go
index 7f3c3caea0..1343579095 100644
--- a/pkg/server/conn.go
+++ b/pkg/server/conn.go
@@ -114,6 +114,8 @@ import (
    "go.uber.org/zap"
 )

+var expectedError error = errors.New("Expected error")
+
 const (
    connStatusDispatching int32 = iota
    connStatusReading
@@ -1148,15 +1150,21 @@ func (cc *clientConn) Run(ctx context.Context) {
                        timestamp = ctx.GetSessionVars().TxnCtx.StaleReadTs
                    }
                }
-               logutil.Logger(ctx).Info("command dispatched failed",
-                   zap.String("connInfo", cc.String()),
-                   zap.String("command", mysql.Command2Str[data[0]]),
-                   zap.String("status", cc.SessionStatusToString()),
-                   zap.Stringer("sql", getLastStmtInConn{cc}),
-                   zap.String("txn_mode", txnMode),
-                   zap.Uint64("timestamp", timestamp),
-                   zap.String("err", errStrForLog(err, cc.ctx.GetSessionVars().EnableRedactLog)),
-               )
+               if terror.ErrorEqual(err, expectedError) {
+                   logutil.Logger(ctx).Debug("command dispatched failed due to expected error",
+                       zap.Stringer("sql", getLastStmtInConn{cc}),
+                   )
+               } else {
+                   logutil.Logger(ctx).Info("command dispatched failed",
+                       zap.String("connInfo", cc.String()),
+                       zap.String("command", mysql.Command2Str[data[0]]),
+                       zap.String("status", cc.SessionStatusToString()),
+                       zap.Stringer("sql", getLastStmtInConn{cc}),
+                       zap.String("txn_mode", txnMode),
+                       zap.Uint64("timestamp", timestamp),
+                       zap.String("err", errStrForLog(err, cc.ctx.GetSessionVars().EnableRedactLog)),
+                   )
+               }
            }
            err1 := cc.writeError(ctx, err)
            terror.Log(err1)
@@ -1698,6 +1706,9 @@ func (cc *clientConn) audit(eventType plugin.GeneralEvent) {
 // Some special queries like `load data` that does not return result, which is handled in handleFileTransInConn.
 func (cc *clientConn) handleQuery(ctx context.Context, sql string) (err error) {
    defer trace.StartRegion(ctx, "handleQuery").End()
+   if sql == "select $$" {
+       return expectedError
+   }
    sessVars := cc.ctx.GetSessionVars()
    sc := sessVars.StmtCtx
    prevWarns := sc.GetWarnings()

Note that this is only a PoC. This doesn't return the right error to the client.

[dveeden]

Related: #53095

[dveeden]

Note that there are also a few other expected errors:

MySQL Shell 8.4.0 does the following:

• SELECT UDF_NAME FROM performance_schema.user_defined_functions
• SELECT name FROM mysql.func
• SELECT VARIABLE_NAME FROM performance_schema.user_variables_by_thread WHERE THREAD_ID=sys.ps_thread_id(NULL)

MySQL Client 8.4.0 also does

• SELECT * FROM `<table>` LIMIT 0 for all tables in the SHOW TABLES output. This causes errors for sequences.

[2024/06/04 09:48:50.885 +02:00] [WARN] [session.go:2116] ["compile SQL failed"] [conn=2097154] [session_alias=] [error="[schema:1146]Table 'performance_schema.user_defined_functions' doesn't exist"] [SQL="SELECT UDF_NAME FROM performance_schema.user_defined_functions"]
[2024/06/04 09:48:50.885 +02:00] [INFO] [conn.go:1158] ["command dispatched failed"] [conn=2097154] [session_alias=] [connInfo="id:2097154, addr:127.0.0.1:36588 status:10, collation:utf8mb4_0900_ai_ci, user:root"] [command=Query] [status="inTxn:0, autocommit:1"] [sql="SELECT UDF_NAME FROM performance_schema.user_defined_functions"] [txn_mode=PESSIMISTIC] [timestamp=0] [err="[schema:1146]Table 'performance_schema.user_defined_functions' doesn't exist"]
[2024/06/04 09:48:50.885 +02:00] [WARN] [session.go:2116] ["compile SQL failed"] [conn=2097154] [session_alias=] [error="[schema:1146]Table 'mysql.func' doesn't exist"] [SQL="SELECT name FROM mysql.func"]
[2024/06/04 09:48:50.885 +02:00] [INFO] [conn.go:1158] ["command dispatched failed"] [conn=2097154] [session_alias=] [connInfo="id:2097154, addr:127.0.0.1:36588 status:10, collation:utf8mb4_0900_ai_ci, user:root"] [command=Query] [status="inTxn:0, autocommit:1"] [sql="SELECT name FROM mysql.func"] [txn_mode=PESSIMISTIC] [timestamp=0] [err="[schema:1146]Table 'mysql.func' doesn't exist"]
[2024/06/04 09:48:50.886 +02:00] [WARN] [session.go:2116] ["compile SQL failed"] [conn=2097154] [session_alias=] [error="[schema:1146]Table 'performance_schema.user_variables_by_thread' doesn't exist"] [SQL="SELECT VARIABLE_NAME FROM performance_schema.user_variables_by_thread WHERE THREAD_ID=sys.ps_thread_id(NULL)"]
[2024/06/04 09:48:50.886 +02:00] [INFO] [conn.go:1158] ["command dispatched failed"] [conn=2097154] [session_alias=] [connInfo="id:2097154, addr:127.0.0.1:36588 status:10, collation:utf8mb4_0900_ai_ci, user:root"] [command=Query] [status="inTxn:0, autocommit:1"] [sql="SELECT VARIABLE_NAME FROM performance_schema.user_variables_by_thread WHERE THREAD_ID=sys.ps_thread_id(NULL)"] [txn_mode=PESSIMISTIC] [timestamp=0] [err="[schema:1146]Table 'performance_schema.user_variables_by_thread' doesn't exist"]

[2024/06/04 09:52:13.342 +02:00] [WARN] [session.go:2116] ["compile SQL failed"] [conn=2097156] [session_alias=] [error="[planner:1051]Unknown table ''"] [SQL="SELECT * FROM `s1` LIMIT 0"]
[2024/06/04 09:52:13.342 +02:00] [INFO] [conn.go:1158] ["command dispatched failed"] [conn=2097156] [session_alias=] [connInfo="id:2097156, addr:127.0.0.1:57000 status:10, collation:utf8mb4_0900_ai_ci, user:root"] [command=Query] [status="inTxn:0, autocommit:1"] [sql="SELECT * FROM `s1` LIMIT 0"] [txn_mode=PESSIMISTIC] [timestamp=0] [err="[planner:1051]Unknown table ''\ngithub.com/pingcap/errors.AddStack\n\t/home/dvaneeden/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20240318064555-6bd07397691f/errors.go:178\ngithub.com/pingcap/errors.(*Error).GenWithStackByArgs\n\t/home/dvaneeden/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20240318064555-6bd07397691f/normalize.go:175\ngithub.com/pingcap/tidb/pkg/planner/core.(*PlanBuilder).unfoldWildStar\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/planner/core/logical_plan_builder.go:3877\ngithub.com/pingcap/tidb/pkg/planner/core.(*PlanBuilder).buildSelect\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/planner/core/logical_plan_builder.go:4112\ngithub.com/pingcap/tidb/pkg/planner/core.(*PlanBuilder).Build\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/planner/core/planbuilder.go:515\ngithub.com/pingcap/tidb/pkg/planner.buildLogicalPlan\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/planner/optimize.go:549\ngithub.com/pingcap/tidb/pkg/planner.optimize\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/planner/optimize.go:466\ngithub.com/pingcap/tidb/pkg/planner.Optimize\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/planner/optimize.go:334\ngithub.com/pingcap/tidb/pkg/executor.(*Compiler).Compile\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/executor/compiler.go:99\ngithub.com/pingcap/tidb/pkg/session.(*session).ExecuteStmt\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/session/session.go:2094\ngithub.com/pingcap/tidb/pkg/server.(*TiDBContext).ExecuteStmt\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/server/driver_tidb.go:294\ngithub.com/pingcap/tidb/pkg/server.(*clientConn).handleStmt\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/server/conn.go:2032\ngithub.com/pingcap/tidb/pkg/server.(*clientConn).handleQuery\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/server/conn.go:1785\ngithub.com/pingcap/tidb/pkg/server.(*clientConn).dispatch\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/server/conn.go:1356\ngithub.com/pingcap/tidb/pkg/server.(*clientConn).Run\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/server/conn.go:1116\ngithub.com/pingcap/tidb/pkg/server.(*Server).onConn\n\t/home/dvaneeden/dev/pingcap/tidb/pkg/server/server.go:739\nruntime.goexit\n\t/usr/lib/golang/src/runtime/asm_amd64.s:1695"]

[dveeden]

We could create a table with queries (or plans? or digests?) that we should not log or log on a different level.

We could also do something like this: https://dev.mysql.com/doc/refman/8.4/en/error-log-rule-based-filtering.html

However I think there might be a simpler option: We can emit structured logs (log format: json) and this allows external programs to do any kind of logging based on the fields that are present in the messages. However this doesn't fix the noisy metrics. However the metrics aren't wrong, these are actually errors.