Too many error log printed

[SunRunAway]

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. What did you do?
   If possible, provide a recipe for reproducing the error.

mysql> x;
ERROR 1064 (42000): You have an error in your SQL syntax; check the manual that corresponds to your TiDB version for the right syntax to use line 1 column 1 near "x" 

2. What did you expect to see?

One line log with enough information.

3. What did you see instead?

3 line log with huge and redundant information.

[2019/09/10 13:22:52.615 +08:00] [WARN] [session.go:1067] ["parse sql error"] [conn=1] [error="line 1 column 1 near \"x\" "] [errorVerbose="line 1 column 1 near \"x\" \ngitpro.ttaallkk.top/pingcap/errors.AddStack\n\t/Users/sunrunaway/Code/gopath/pkg/mod/github.com/pingcap/errors@v0.11.4/errors.go:174\ngitpro.ttaallkk.top/pingcap/errors.Trace\n\t/Users/sunrunaway/Code/gopath/pkg/mod/github.com/pingcap/errors@v0.11.4/juju_adaptor.go:15\ngitpro.ttaallkk.top/pingcap/parser.(*Parser).Parse\n\t/Users/sunrunaway/Code/gopath/pkg/mod/github.com/pingcap/parser@v0.0.0-20190828080649-a621a0f9b06c/yy_parser.go:150\ngitpro.ttaallkk.top/pingcap/tidb/session.(*session).ParseSQL\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/session/session.go:973\ngitpro.ttaallkk.top/pingcap/tidb/session.(*session).execute\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/session/session.go:1064\ngitpro.ttaallkk.top/pingcap/tidb/session.(*session).Execute\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/session/session.go:1045\ngitpro.ttaallkk.top/pingcap/tidb/server.(*TiDBContext).Execute\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/driver_tidb.go:246\ngitpro.ttaallkk.top/pingcap/tidb/server.(*clientConn).handleQuery\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/conn.go:1187\ngitpro.ttaallkk.top/pingcap/tidb/server.(*clientConn).dispatch\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/conn.go:898\ngitpro.ttaallkk.top/pingcap/tidb/server.(*clientConn).Run\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/conn.go:653\ngitpro.ttaallkk.top/pingcap/tidb/server.(*Server).onConn\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/server.go:438\nruntime.goexit\n\t/usr/local/Cellar/go@1.12/1.12.9/libexec/src/runtime/asm_amd64.s:1337"] [sql=x]
[2019/09/10 13:22:52.615 +08:00] [ERROR] [misc.go:114] ["syntax error"] [error="line 1 column 1 near \"x\" "] [errorVerbose="line 1 column 1 near \"x\" \ngitpro.ttaallkk.top/pingcap/errors.AddStack\n\t/Users/sunrunaway/Code/gopath/pkg/mod/github.com/pingcap/errors@v0.11.4/errors.go:174\ngitpro.ttaallkk.top/pingcap/errors.Trace\n\t/Users/sunrunaway/Code/gopath/pkg/mod/github.com/pingcap/errors@v0.11.4/juju_adaptor.go:15\ngitpro.ttaallkk.top/pingcap/parser.(*Parser).Parse\n\t/Users/sunrunaway/Code/gopath/pkg/mod/github.com/pingcap/parser@v0.0.0-20190828080649-a621a0f9b06c/yy_parser.go:150\ngitpro.ttaallkk.top/pingcap/tidb/session.(*session).ParseSQL\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/session/session.go:973\ngitpro.ttaallkk.top/pingcap/tidb/session.(*session).execute\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/session/session.go:1064\ngitpro.ttaallkk.top/pingcap/tidb/session.(*session).Execute\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/session/session.go:1045\ngitpro.ttaallkk.top/pingcap/tidb/server.(*TiDBContext).Execute\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/driver_tidb.go:246\ngitpro.ttaallkk.top/pingcap/tidb/server.(*clientConn).handleQuery\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/conn.go:1187\ngitpro.ttaallkk.top/pingcap/tidb/server.(*clientConn).dispatch\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/conn.go:898\ngitpro.ttaallkk.top/pingcap/tidb/server.(*clientConn).Run\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/conn.go:653\ngitpro.ttaallkk.top/pingcap/tidb/server.(*Server).onConn\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/server.go:438\nruntime.goexit\n\t/usr/local/Cellar/go@1.12/1.12.9/libexec/src/runtime/asm_amd64.s:1337"] [stack="github.com/pingcap/tidb/util.SyntaxError\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/util/misc.go:114\ngitpro.ttaallkk.top/pingcap/tidb/session.(*session).execute\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/session/session.go:1070\ngitpro.ttaallkk.top/pingcap/tidb/session.(*session).Execute\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/session/session.go:1045\ngitpro.ttaallkk.top/pingcap/tidb/server.(*TiDBContext).Execute\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/driver_tidb.go:246\ngitpro.ttaallkk.top/pingcap/tidb/server.(*clientConn).handleQuery\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/conn.go:1187\ngitpro.ttaallkk.top/pingcap/tidb/server.(*clientConn).dispatch\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/conn.go:898\ngitpro.ttaallkk.top/pingcap/tidb/server.(*clientConn).Run\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/conn.go:653\ngitpro.ttaallkk.top/pingcap/tidb/server.(*Server).onConn\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/server.go:438"]
[2019/09/10 13:22:52.617 +08:00] [WARN] [conn.go:669] ["dispatch error"] [conn=1] [connInfo="id:1, addr:127.0.0.1:64590 status:2, collation:utf8_general_ci, user:root"] [sql=x] [err="[parser:1064]You have an error in your SQL syntax; check the manual that corresponds to your TiDB version for the right syntax to use line 1 column 1 near \"x\" \ngitpro.ttaallkk.top/pingcap/errors.AddStack\n\t/Users/sunrunaway/Code/gopath/pkg/mod/github.com/pingcap/errors@v0.11.4/errors.go:174\ngitpro.ttaallkk.top/pingcap/parser/terror.(*Error).GenWithStackByArgs\n\t/Users/sunrunaway/Code/gopath/pkg/mod/github.com/pingcap/parser@v0.0.0-20190828080649-a621a0f9b06c/terror/terror.go:238\ngitpro.ttaallkk.top/pingcap/tidb/util.SyntaxError\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/util/misc.go:124\ngitpro.ttaallkk.top/pingcap/tidb/session.(*session).execute\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/session/session.go:1070\ngitpro.ttaallkk.top/pingcap/tidb/session.(*session).Execute\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/session/session.go:1045\ngitpro.ttaallkk.top/pingcap/tidb/server.(*TiDBContext).Execute\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/driver_tidb.go:246\ngitpro.ttaallkk.top/pingcap/tidb/server.(*clientConn).handleQuery\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/conn.go:1187\ngitpro.ttaallkk.top/pingcap/tidb/server.(*clientConn).dispatch\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/conn.go:898\ngitpro.ttaallkk.top/pingcap/tidb/server.(*clientConn).Run\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/conn.go:653\ngitpro.ttaallkk.top/pingcap/tidb/server.(*Server).onConn\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/server.go:438\nruntime.goexit\n\t/usr/local/Cellar/go@1.12/1.12.9/libexec/src/runtime/asm_amd64.s:1337"]

4. What version of TiDB are you using (tidb-server -V or run select tidb_version(); on TiDB)?

c1d5536

[ghost]

Relates to #18566

This can be a security risk, since these statements are logged verbatim.

[SunRunAway]

Another example

mysql> set tidb_mem_quota_query=1;
Query OK, 0 rows affected (0.00 sec)

mysql> select 1 union select 2;
ERROR 1105 (HY000): Out Of Memory Quota![conn_id=1]

It produces 5 lines log.

[2020/07/31 18:21:09.656 +08:00] [WARN] [expensivequery.go:168] [expensive_query] [cost_time=667.992991114s] [conn_id=1] [user=root] [database=test] [txn_start_ts=0] [mem_max="372 Bytes (372 Bytes)"] [sql=]
[2020/07/31 18:21:09.656 +08:00] [ERROR] [adapter.go:289] ["execute sql panic"] [conn=1] [sql="select 1 union select 2"] [stack="github.com/pingcap/tidb/executor.(*ExecStmt).Exec.func1\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/executor/adapter.go:289\nruntime.gopanic\n\t/usr/local/Cellar/go@1.13/1.13.9/libexec/src/runtime/panic.go:679\ngitpro.ttaallkk.top/pingcap/tidb/util/memory.(*PanicOnExceed).Action\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/util/memory/action.go:96\ngitpro.ttaallkk.top/pingcap/tidb/util/memory.(*Tracker).Consume\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/util/memory/tracker.go:236\ngitpro.ttaallkk.top/pingcap/tidb/executor.(*HashAggExec).initForParallelExec\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/executor/aggregate.go:317\ngitpro.ttaallkk.top/pingcap/tidb/executor.(*HashAggExec).Open\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/executor/aggregate.go:270\ngitpro.ttaallkk.top/pingcap/tidb/executor.(*ExecStmt).Exec\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/executor/adapter.go:320\ngitpro.ttaallkk.top/pingcap/tidb/session.runStmt\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/session/session.go:1203\ngitpro.ttaallkk.top/pingcap/tidb/session.(*session).ExecuteStmt\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/session/session.go:1168\ngitpro.ttaallkk.top/pingcap/tidb/server.(*TiDBContext).ExecuteStmt\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/driver_tidb.go:198\ngitpro.ttaallkk.top/pingcap/tidb/server.(*clientConn).handleStmt\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/conn.go:1428\ngitpro.ttaallkk.top/pingcap/tidb/server.(*clientConn).handleQuery\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/conn.go:1321\ngitpro.ttaallkk.top/pingcap/tidb/server.(*clientConn).dispatch\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/conn.go:920\ngitpro.ttaallkk.top/pingcap/tidb/server.(*clientConn).Run\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/conn.go:727\ngitpro.ttaallkk.top/pingcap/tidb/server.(*Server).onConn\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/server.go:418"]
[2020/07/31 18:21:09.656 +08:00] [INFO] [tidb.go:217] ["rollbackTxn for ddl/autocommit failed"]
[2020/07/31 18:21:09.656 +08:00] [WARN] [session.go:1171] ["run statement failed"] [conn=1] [schemaVersion=33] [error="Out Of Memory Quota![conn_id=1]"] [session="{\n  \"currDBName\": \"test\",\n  \"id\": 1,\n  \"status\": 2,\n  \"strictMode\": true,\n  \"user\": {\n    \"Username\": \"root\",\n    \"Hostname\": \"127.0.0.1\",\n    \"CurrentUser\": false,\n    \"AuthUsername\": \"root\",\n    \"AuthHostname\": \"%\"\n  }\n}"]
[2020/07/31 18:21:09.656 +08:00] [ERROR] [conn.go:744] ["command dispatched failed"] [conn=1] [connInfo="id:1, addr:127.0.0.1:60413 status:10, collation:utf8_general_ci, user:root"] [command=Query] [status="inTxn:0, autocommit:1"] [sql="select 1 union select 2"] [txn_mode=OPTIMISTIC] [err="Out Of Memory Quota![conn_id=1]\ngitpro.ttaallkk.top/pingcap/tidb/executor.(*ExecStmt).Exec.func1\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/executor/adapter.go:288\nruntime.gopanic\n\t/usr/local/Cellar/go@1.13/1.13.9/libexec/src/runtime/panic.go:679\ngitpro.ttaallkk.top/pingcap/tidb/util/memory.(*PanicOnExceed).Action\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/util/memory/action.go:96\ngitpro.ttaallkk.top/pingcap/tidb/util/memory.(*Tracker).Consume\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/util/memory/tracker.go:236\ngitpro.ttaallkk.top/pingcap/tidb/executor.(*HashAggExec).initForParallelExec\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/executor/aggregate.go:317\ngitpro.ttaallkk.top/pingcap/tidb/executor.(*HashAggExec).Open\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/executor/aggregate.go:270\ngitpro.ttaallkk.top/pingcap/tidb/executor.(*ExecStmt).Exec\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/executor/adapter.go:320\ngitpro.ttaallkk.top/pingcap/tidb/session.runStmt\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/session/session.go:1203\ngitpro.ttaallkk.top/pingcap/tidb/session.(*session).ExecuteStmt\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/session/session.go:1168\ngitpro.ttaallkk.top/pingcap/tidb/server.(*TiDBContext).ExecuteStmt\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/driver_tidb.go:198\ngitpro.ttaallkk.top/pingcap/tidb/server.(*clientConn).handleStmt\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/conn.go:1428\ngitpro.ttaallkk.top/pingcap/tidb/server.(*clientConn).handleQuery\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/conn.go:1321\ngitpro.ttaallkk.top/pingcap/tidb/server.(*clientConn).dispatch\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/conn.go:920\ngitpro.ttaallkk.top/pingcap/tidb/server.(*clientConn).Run\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/conn.go:727\ngitpro.ttaallkk.top/pingcap/tidb/server.(*Server).onConn\n\t/Users/sunrunaway/Code/gopath/src/github.com/pingcap/tidb/server/server.go:418\nruntime.goexit\n\t/usr/local/Cellar/go@1.13/1.13.9/libexec/src/runtime/asm_amd64.s:1357"]

[kolbe]

We should probably just change the logging level of application-facing errors so they aren't written to the server error log, or to make it easy for a user to toggle that. There isn't much use in writing duplicate key and syntax errors to the server log, those are not problems a DBA should usually be concerned with. Those errors are returned to the client, which is responsible in any case for handling them.

[ghost]

I like how performance_schema in MySQL 8.0 instruments client errors. It can be useful after an upgrade, change to sql-mode etc. Not all applications track this as they are expected.