tidb 7.1.0连接关闭错误

polars · 2023 年6 月 6 日 10:13

【 TiDB 使用环境】生产环境 /测试/ Poc
测试
【 TiDB 版本】
7.1.0
【复现路径】做过哪些操作出现的问题
【遇到的问题：问题现象及影响】
sql报错，应用端报错连接关闭
[ERROR] [conn.go:1072] [“connection running loop panic”] [conn=1669219179662106373] [lastSQL=“SELECT DISTINCT spdvc.tenant_id, spmar.user_group_id, spdvc.rule_id, spdvc.rule_comb_id, spdvc.comb_number, spdvc.dimension_id, spdvc.dimension_code, spdvc.column_name, spdvc.value_code, spdvc.no_value_flag, spdvc.auth_dimension_code, spdvc.hierarchy_scope, spdvc.permission FROM sys_perm_dim_value_cache spdvc, sys_perm_model_ass_rule spmar WHERE spdvc.rule_id = spmar.rule_id AND spdvc.rule_id = ? AND spdvc.rule_comb_id = ? AND spmar.model_id = ? AND EXISTS (SELECT 1 FROM sys_permission_rule r WHERE r.id = spdvc.rule_id AND r.rule_status = 1002 AND r.tenant_id = 1476472055858286593) AND spdvc.tenant_id = 1476472055858286593 [arguments: (1665921952692371458, 1665922630806470657, 1491426741154992130)]”] [err=“runtime error: invalid memory address or nil pointer dereference”]
tidb日志如下：
2023-06-06T17:33:27.848080481+08:00 [2023/06/06 17:33:27.847 +08:00] [WARN] [server.go:644] [“Server.onConn handshake”] [conn=1669219179662111683] [error=“write tcp 172.18.65.182:4000->100.97.231.131:53009: write: connection reset by peer”] [“remote addr”=100.97.231.131:53009]

2023-06-06T17:33:28.040586807+08:00 [2023/06/06 17:33:28.040 +08:00] [ERROR] [pd.go:111] [“store min resolved ts not enabled, addr: http://dev-pd:2379”]

2023-06-06T17:33:28.040615362+08:00 [2023/06/06 17:33:28.040 +08:00] [ERROR] [pd.go:111] [“store min resolved ts not enabled, addr: http://dev-pd:2379”]

2023-06-06T17:33:28.040752317+08:00 [2023/06/06 17:33:28.040 +08:00] [ERROR] [pd.go:111] [“store min resolved ts not enabled, addr: http://dev-pd:2379”]

2023-06-06T17:33:28.124709497+08:00 [2023/06/06 17:33:28.124 +08:00] [INFO] [conn.go:1125] [“read packet timeout, close this connection”] [conn=1669219179662105561] [idle=15m0.000398889s] [waitTimeout=900] [error=“read tcp 172.18.65.182:4000->172.18.74.236:32812: i/o timeout”]

2023-06-06T17:33:28.233214818+08:00 [2023/06/06 17:33:28.233 +08:00] [INFO] [conn.go:1125] [“read packet timeout, close this connection”] [conn=1669219179662105563] [idle=15m0.000878951s] [waitTimeout=900] [error=“read tcp 172.18.65.182:4000->172.18.74.236:32816: i/o timeout”]

2023-06-06T17:33:28.543182969+08:00 [2023/06/06 17:33:28.543 +08:00] [INFO] [conn.go:1125] [“read packet timeout, close this connection”] [conn=1669219179662105565] [idle=15m0.000410374s] [waitTimeout=900] [error=“read tcp 172.18.65.182:4000->172.18.74.236:32822: i/o timeout”]

2023-06-06T17:33:28.642755832+08:00 [2023/06/06 17:33:28.642 +08:00] [INFO] [conn.go:1125] [“read packet timeout, close this connection”] [conn=1669219179662105569] [idle=15m0.000919631s] [waitTimeout=900] [error=“read tcp 172.18.65.182:4000->172.18.74.236:32824: i/o timeout”]

2023-06-06T17:33:28.843017215+08:00 [2023/06/06 17:33:28.842 +08:00] [INFO] [conn.go:1125] [“read packet timeout, close this connection”] [conn=1669219179662105571] [idle=15m0.000190512s] [waitTimeout=900] [error=“read tcp 172.18.65.182:4000->172.18.74.236:32828: i/o timeout”]

2023-06-06T17:33:29.173371810+08:00 [2023/06/06 17:33:29.173 +08:00] [INFO] [conn.go:1125] [“read packet timeout, close this connection”] [conn=1669219179662105575] [idle=15m0.000270542s] [waitTimeout=900] [error=“read tcp 172.18.65.182:4000->172.18.74.236:32836: i/o timeout”]

2023-06-06T17:33:29.273388896+08:00 [2023/06/06 17:33:29.273 +08:00] [INFO] [conn.go:1125] [“read packet timeout, close this connection”] [conn=1669219179662105577] [idle=15m0.000674472s] [waitTimeout=900] [error=“read tcp 172.18.65.182:4000->172.18.74.236:32838: i/o timeout”]

2023-06-06T17:33:29.367771865+08:00 [2023/06/06 17:33:29.367 +08:00] [INFO] [conn.go:1125] [“read packet timeout, close this connection”] [conn=1669219179662105579] [idle=15m0.000517187s] [waitTimeout=900] [error=“read tcp 172.18.65.182:4000->172.18.74.236:32840: i/o timeout”]

2023-06-06T17:33:29.374504283+08:00 [2023/06/06 17:33:29.374 +08:00] [INFO] [session.go:3846] [“CRUCIAL OPERATION”] [conn=1669219179662107119] [schemaVersion=93151] [“secure text”=“grant select,insert,update,delete,alter,drop on ms_test.auth_ypd_bp_01_fact003 to polaris@‘%’;”] [user=polaris@%]

2023-06-06T17:33:29.468915764+08:00 [2023/06/06 17:33:29.468 +08:00] [ERROR] [conn.go:1072] [“connection running loop panic”] [conn=1669219179662106373] [lastSQL=“SELECT DISTINCT spdvc.tenant_id, spmar.user_group_id, spdvc.rule_id, spdvc.rule_comb_id, spdvc.comb_number, spdvc.dimension_id, spdvc.dimension_code, spdvc.column_name, spdvc.value_code, spdvc.no_value_flag, spdvc.auth_dimension_code, spdvc.hierarchy_scope, spdvc.permission FROM sys_perm_dim_value_cache spdvc, sys_perm_model_ass_rule spmar WHERE spdvc.rule_id = spmar.rule_id AND spdvc.rule_id = ? AND spdvc.rule_comb_id = ? AND spmar.model_id = ? AND EXISTS (SELECT 1 FROM sys_permission_rule r WHERE r.id = spdvc.rule_id AND r.rule_status = 1002 AND r.tenant_id = 1476472055858286593) AND spdvc.tenant_id = 1476472055858286593 [arguments: (1665921952692371458, 1665922630806470657, 1491426741154992130)]”] [err=“runtime error: invalid memory address or nil pointer dereference”] [stack=“github.com/pingcap/tidb/server.(*clientConn).Run.func1\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/conn.go:1075\nruntime.gopanic\n\t/usr/local/go/src/runtime/panic.go:884\nruntime.panicmem\n\t/usr/local/go/src/runtime/panic.go:260\nruntime.sigpanic\n\t/usr/local/go/src/runtime/signal_unix.go:837\ngithub.com/pingcap/tidb/planner/core.getJoinHints\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/planner/core/hints.go:128\ngithub.com/pingcap/tidb/planner/core.genHintsFromSingle\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/planner/core/hints.go:242\ngithub.com/pingcap/tidb/planner/core.GenHintsFromFlatPlan\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/planner/core/hints.go:47\ngithub.com/pingcap/tidb/executor.getEncodedPlan\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/adapter.go:1700\ngithub.com/pingcap/tidb/executor.(*ExecStmt).SummaryStmt.func1\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/adapter.go:1757\ngithub.com/pingcap/tidb/util/stmtsummary.newStmtSummaryByDigestElement\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/util/stmtsummary/statement_summary.go:635\ngithub.com/pingcap/tidb/util/stmtsummary.(*stmtSummaryByDigest).add.func1\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/util/stmtsummary/statement_summary.go:590\ngithub.com/pingcap/tidb/util/stmtsummary.(*stmtSummaryByDigest).add\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/util/stmtsummary/statement_summary.go:601\ngithub.com/pingcap/tidb/util/stmtsummary.(*stmtSummaryByDigestMap).AddStatement\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/util/stmtsummary/statement_summary.go:344\ngithub.com/pingcap/tidb/util/stmtsummary/v2.Add\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/util/stmtsummary/v2/stmtsummary.go:537\ngithub.com/pingcap/tidb/executor.(*ExecStmt).SummaryStmt\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/adapter.go:1855\ngithub.com/pingcap/tidb/executor.(*ExecStmt).FinishExecuteStmt\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/adapter.go:1342\ngithub.com/pingcap/tidb/executor.(*ExecStmt).CloseRecordSet\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/adapter.go:1415\ngithub.com/pingcap/tidb/executor.(*recordSet).Close\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/adapter.go:180\ngithub.com/pingcap/tidb/session.(*execStmtResult).Close\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/session/session.go:2425\ngithub.com/pingcap/tidb/server.(*tidbResultSet).Close\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/driver_tidb.go:446\ngithub.com/pingcap/tidb/parser/terror.Call\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/parser/terror/terror.go:315\ngithub.com/pingcap/tidb/server.(*clientConn).executePreparedStmtAndWriteResult\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/conn_stmt.go:357\ngithub.com/pingcap/tidb/server.(*clientConn).executePlanCacheStmt\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/conn_stmt.go:226\ngithub.com/pingcap/tidb/server.(*clientConn).handleStmtExecute\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/conn_stmt.go:218\ngithub.com/pingcap/tidb/server.(*clientConn).dispatch\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/conn.go:1399\ngithub.com/pingcap/tidb/server.(*clientConn).Run\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/conn.go:1153\ngithub.com/pingcap/tidb/server.(*Server).onConn\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/server.go:677”]

2023-06-06T17:33:29.685414503+08:00 [2023/06/06 17:33:29.685 +08:00] [INFO] [conn.go:1125] [“read packet timeout, close this connection”] [conn=1669219179662105585] [idle=15m0.000257125s] [waitTimeout=900] [error=“read tcp 172.18.65.182:4000->172.18.74.236:32846: i/o timeout”]

2023-06-06T17:33:29.715193621+08:00 [2023/06/06 17:33:29.715 +08:00] [WARN] [server.go:644] [“Server.onConn handshake”] [conn=1669219179662111689] [error=“write tcp 172.18.65.182:4000->100.116.37.129:25794: write: connection reset by peer”] [“remote addr”=100.116.37.129:25794]

2023-06-06T17:33:29.858878817+08:00 [2023/06/06 17:33:29.858 +08:00] [WARN] [server.go:644] [“Server.onConn handshake”] [conn=1669219179662111695] [error=“write tcp 172.18.65.182:4000->100.97.231.131:61144: write: connection reset by peer”] [“remote addr”=100.97.231.131:61144]

2023-06-06T17:33:29.999050454+08:00 [2023/06/06 17:33:29.998 +08:00] [INFO] [conn.go:1125] [“read packet timeout, close this connection”] [conn=1669219179662105587] [idle=15m0.000207793s] [waitTimeout=900] [error=“read tcp 172.18.65.182:4000->172.18.74.236:32852: i/o timeout”]

2023-06-06T17:33:30.040781611+08:00 [2023/06/06 17:33:30.040 +08:00] [ERROR] [pd.go:111] [“store min resolved ts not enabled, addr: http://dev-pd:2379”]

2023-06-06T17:33:30.040899891+08:00 [2023/06/06 17:33:30.040 +08:00] [ERROR] [pd.go:111] [“store min resolved ts not enabled, addr: http://dev-pd:2379”]

2023-06-06T17:33:30.040946285+08:00 [2023/06/06 17:33:30.040 +08:00] [ERROR] [pd.go:111] [“store min resolved ts not enabled, addr: http://dev-pd:2379”]

2023-06-06T17:33:30.225010730+08:00 [2023/06/06 17:33:30.224 +08:00] [INFO] [conn.go:1125] [“read packet timeout, close this connection”] [conn=1669219179662105593] [idle=15m0.000304069s] [waitTimeout=900] [error=“read tcp 172.18.65.182:4000->172.18.74.236:32856: i/o timeout”]

2023-06-06T17:33:30.424524120+08:00 [2023/06/06 17:33:30.424 +08:00] [INFO] [conn.go:1125] [“read packet timeout, close this connection”] [conn=1669219179662105595] [idle=15m0.000263133s] [waitTimeout=900] [error=“read tcp 172.18.65.182:4000->172.18.74.236:32860: i/o timeout”]

2023-06-06T17:33:30.519173757+08:00 [2023/06/06 17:33:30.519 +08:00] [INFO] [conn.go:1125] [“read packet timeout, close this connection”] [conn=1669219179662105597] [idle=15m0.000459384s] [waitTimeout=900] [error=“read tcp 172.18.65.182:4000->172.18.74.236:32862: i/o timeout”]

2023-06-06T17:33:30.842644833+08:00 [2023/06/06 17:33:30.842 +08:00] [INFO] [conn.go:1125] [“read packet timeout, close this connection”] [conn=1669219179662105599] [idle=15m0.000809921s] [waitTimeout=900] [error=“read tcp 172.18.65.182:4000->172.18.74.236:32868: i/o timeout”]

2023-06-06T17:33:31.031033512+08:00 [2023/06/06 17:33:31.030 +08:00] [INFO] [conn.go:1125] [“read packet timeout, close this connection”] [conn=1669219179662105603] [idle=15m0.0009533s] [waitTimeout=900] [error=“read tcp 172.18.65.182:4000->172.18.74.236:32874: i/o timeout”]

2023-06-06T17:33:31.239809832+08:00 [2023/06/06 17:33:31.239 +08:00] [INFO] [conn.go:1125] [“read packet timeout, close this connection”] [conn=1669219179662105605] [idle=15m0.000193289s] [waitTimeout=900] [error=“read tcp 172.18.65.182:4000->172.18.74.236:32878: i/o timeout”]

2023-06-06T17:33:31.373299170+08:00 [2023/06/06 17:33:31.373 +08:00] [INFO] [conn.go:1125] [“read packet timeout, close this connection”] [conn=1669219179662105607] [idle=15m0.000970922s] [waitTimeout=900] [error=“read tcp 172.18.65.182:4000->172.18.74.236:32880: i/o timeout”]

2023-06-06T17:33:31.584818204+08:00 [2023/06/06 17:33:31.584 +08:00] [INFO] [conn.go:1125] [“read packet timeout, close this connection”] [conn=1669219179662105611] [idle=15m0.001074868s] [waitTimeout=900] [error=“read tcp 172.18.65.182:4000->172.18.74.236:32884: i/o timeout”]

2023-06-06T17:33:31.783990559+08:00 [2023/06/06 17:33:31.783 +08:00] [WARN] [server.go:644] [“Server.onConn handshake”] [conn=1669219179662111709] [error=“write tcp 172.18.65.182:4000->100.116.37.129:5070: write: connection reset by peer”] [“remote addr”=100.116.37.129:5070]

2023-06-06T17:33:31.888822501+08:00 [2023/06/06 17:33:31.888 +08:00] [WARN] [server.go:644] [“Server.onConn handshake”] [conn=1669219179662111711] [error=“write tcp 172.18.65.182:4000->100.97.231.131:11614: write: connection reset by peer”] [“remote addr”=100.97.231.131:11614]

2023-06-06T17:33:31.933008908+08:00 [2023/06/06 17:33:31.932 +08:00] [INFO] [conn.go:1125] [“read packet timeout, close this connection”] [conn=1669219179662105613] [idle=15m0.000907613s] [waitTimeout=900] [error=“read tcp 172.18.65.182:4000->172.18.74.236:32892: i/o timeout”]

2023-06-06T17:33:32.040998812+08:00 [2023/06/06 17:33:32.040 +08:00] [ERROR] [pd.go:111] [“store min resolved ts not enabled, addr: http://dev-pd:2379”]

2023-06-06T17:33:32.041025616+08:00 [2023/06/06 17:33:32.040 +08:00] [ERROR] [pd.go:111] [“store min resolved ts not enabled, addr: http://dev-pd:2379”]

2023-06-06T17:33:32.041184234+08:00 [2023/06/06 17:33:32.041 +08:00] [ERROR] [pd.go:111] [“store min resolved ts not enabled, addr: http://dev-pd:2379”]

2023-06-06T17:33:32.054108173+08:00 [2023/06/06 17:33:32.054 +08:00] [INFO] [conn.go:1125] [“read packet timeout, close this connection”] [conn=1669219179662105615] [idle=15m0.000486132s] [waitTimeout=900] [error=“read tcp 172.18.65.182:4000->172.18.74.236:32894: i/o timeout”]

2023-06-06T17:33:32.269017920+08:00 [2023/06/06 17:33:32.268 +08:00] [INFO] [conn.go:1125] [“read packet timeout, close this connection”] [conn=1669219179662105619] [idle=15m0.00010273s] [waitTimeout=900] [error=“read tcp 172.18.65.182:4000->172.18.74.236:32898: i/o timeout”]

2023-06-06T17:33:32.497159287+08:00 [2023/06/06 17:33:32.497 +08:00] [INFO] [conn.go:1125] [“read packet timeout, close this connection”] [conn=1669219179662105621] [idle=15m0.00086431s] [waitTimeout=900] [error=“read tcp 172.18.65.182:4000->172.18.74.236:32902: i/o timeout”]

2023-06-06T17:33:32.711479121+08:00 [2023/06/06 17:33:32.711 +08:00] [INFO] [conn.go:1125] [“read packet timeout, close this connection”] [conn=1669219179662105623] [idle=15m0.00071775s] [waitTimeout=900] [error=“read tcp 172.18.65.182:4000->172.18.74.236:32906: i/o timeout”]

2023-06-06T17:33:33.689416880+08:00 [2023/06/06 17:33:33.689 +08:00] [WARN] [server.go:644] [“Server.onConn handshake”] [conn=1669219179662111719] [error=“write tcp 172.18.65.182:4000->100.116.37.129:53262: write: connection reset by peer”] [“remote addr”=100.116.37.129:53262]

2023-06-06T17:33:33.801934345+08:00 [2023/06/06 17:33:33.801 +08:00] [WARN] [server.go:644] [“Server.onConn handshake”] [conn=1669219179662111721] [error=“write tcp 172.18.65.182:4000->100.97.231.131:13548: write: connection reset by peer”] [“remote addr”=100.97.231.131:13548]

2023-06-06T17:33:34.040868071+08:00 [2023/06/06 17:33:34.040 +08:00] [ERROR] [pd.go:111] [“store min resolved ts not enabled, addr: http://dev-pd:2379”]

2023-06-06T17:33:34.040883959+08:00 [2023/06/06 17:33:34.040 +08:00] [ERROR] [pd.go:111] [“store min resolved ts not enabled, addr: http://dev-pd:2379”]

2023-06-06T17:33:34.041071333+08:00 [2023/06/06 17:33:34.041 +08:00] [ERROR] [pd.go:111] [“store min resolved ts not enabled, addr: http://dev-pd:2379”]
【资源配置】进入到 TiDB Dashboard -集群信息 (Cluster Info) -主机(Hosts) 截图此页面

【附件：截图/日志/监控】

09-11：已确认bug
https://github.com/pingcap/tidb/issues/46791
目前最新的7.3依然存在，等待发版

xfworld · 2023 年6 月 7 日 02:11

172.18.74.236 是个什么节点？

polars · 2023 年6 月 7 日 03:21

是一台中继服务器，做端口转发的

xfworld · 2023 年6 月 7 日 03:26

日志都是 i/o timeout ，你得好好检查下了

polars · 2023 年6 月 7 日 03:37

这个是给开发人员用的中继服务端口，这些超时，应该是本地开发客户端超时了，业务集群是直连的，不走这个端口，业务报错跟这个没关系

xfworld · 2023 年6 月 7 日 03:43

2023-06-06T17:33:34.040868071+08:00 [2023/06/06 17:33:34.040 +08:00] [ERROR] [pd.go:111] [“store min resolved ts not enabled, addr: http://dev-pd:2379 ”]

不知道什么场景… 比较晕

Anna · 2023 年6 月 7 日 05:22

你参考这个：https://github.com/gruntwork-io/terragrunt/issues/2109

redgame · 2023 年6 月 7 日 23:00

i/o 可以测试下

polars · 2023 年6 月 8 日 02:09

这个环境之前6.5是没问题的，运行了大半年了，所以应该不存在io的问题

yilong · 2023 年6 月 12 日 02:54

如果直接链接 tidb server 执行此 SQL 是否会报错？麻烦测试下。如果依然报错，麻烦同时反馈下表结构。

polars · 2023 年6 月 12 日 06:18

sql客户端直连是可以执行成功的，只有在应用端会偶发出现报错

linnana · 2023 年6 月 14 日 03:13

原因定位到的话分享下啊

Billmay表妹 · 2023 年6 月 14 日 03:31

可以进群咨询官方老师~

Billmay表妹 · 2023 年6 月 14 日 03:37

根据您提供的信息，无法确定具体的问题原因。但是，根据错误信息中的 “connection running loop panic” 和 “连接关闭”，可以初步判断是 TiDB 连接出现了异常，导致应用程序无法正常访问 TiDB 数据库。

可能的原因包括：

网络问题：TiDB 与应用程序之间的网络连接出现了异常，导致连接被关闭。
资源问题：TiDB 集群的资源不足，导致连接被关闭。
TiDB 配置问题：TiDB 配置不当，导致连接被关闭。

为了确定问题的具体原因，建议您查看 TiDB 和应用程序的日志，以及 TiDB 相关的监控信息，例如 TiDB Dashboard。您可以根据日志和监控信息来分析问题，并采取相应的措施来解决问题。

另外，建议您升级 TiDB 到最新版本，以获得更好的性能和稳定性。同时，也可以考虑使用 TiDB 官方提供的工具来进行性能调优和故障排除，例如 TiDB Binlog 和 TiDB Lightning。

system · 2023 年8 月 13 日 03:38

此话题已在最后回复的 60 天后被自动关闭。不再允许新回复。