Unstable test expression TestGetLock

[tiancaiamao]

Enhancement

This unstable test is easy to reproduce

make ut X='run expression TestGetLock'

[2022/06/06 13:45:18.254 +08:00] [WARN] [session.go:1924] ["compile SQL failed"] [error="[expression:1582]Incorrect parameter count in the call to native function 'get_lock'"] [errorVerbose="[expression:1582]Incorrect parameter count in the call to native function 'get_lock'\ngithub.com/pingcap/errors.AddStack\n\t/home/genius/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/genius/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211224045212-9687c2b0f87c/normalize.go:164\ngithub.com/pingcap/tidb/expression.(*baseFunctionClass).verifyArgsByCount\n\t/home/genius/project/src/github.com/pingcap/tidb/expression/builtin.go:499\ngithub.com/pingcap/tidb/expression.(*baseFunctionClass).verifyArgs\n\t/home/genius/project/src/github.com/pingcap/tidb/expression/builtin.go:494\ngithub.com/pingcap/tidb/expression.(*lockFunctionClass).getFunction\n\t/home/genius/project/src/github.com/pingcap/tidb/expression/builtin_miscellaneous.go:171\ngithub.com/pingcap/tidb/expression.newFunctionImpl\n\t/home/genius/project/src/github.com/pingcap/tidb/expression/scalar_function.go:223\ngithub.com/pingcap/tidb/expression.NewFunction\n\t/home/genius/project/src/github.com/pingcap/tidb/expression/scalar_function.go:254\ngithub.com/pingcap/tidb/planner/core.(*expressionRewriter).newFunction\n\t/home/genius/project/src/github.com/pingcap/tidb/planner/core/expression_rewriter.go:1232\ngithub.com/pingcap/tidb/planner/core.(*expressionRewriter).funcCallToExpression\n\t/home/genius/project/src/github.com/pingcap/tidb/planner/core/expression_rewriter.go:1886\ngithub.com/pingcap/tidb/planner/core.(*expressionRewriter).Leave\n\t/home/genius/project/src/github.com/pingcap/tidb/planner/core/expression_rewriter.go:1099\ngithub.com/pingcap/tidb/parser/ast.(*FuncCallExpr).Accept\n\t/home/genius/project/src/github.com/pingcap/tidb/parser/ast/functions.go:532\ngithub.com/pingcap/tidb/planner/core.(*PlanBuilder).rewriteExprNode\n\t/home/genius/project/src/github.com/pingcap/tidb/planner/core/expression_rewriter.go:199\ngithub.com/pingcap/tidb/planner/core.(*PlanBuilder).rewriteWithPreprocess\n\t/home/genius/project/src/github.com/pingcap/tidb/planner/core/expression_rewriter.go:145\ngithub.com/pingcap/tidb/planner/core.(*PlanBuilder).buildProjection\n\t/home/genius/project/src/github.com/pingcap/tidb/planner/core/logical_plan_builder.go:1290\ngithub.com/pingcap/tidb/planner/core.(*PlanBuilder).buildSelect\n\t/home/genius/project/src/github.com/pingcap/tidb/planner/core/logical_plan_builder.go:3919\ngithub.com/pingcap/tidb/planner/core.(*PlanBuilder).Build\n\t/home/genius/project/src/github.com/pingcap/tidb/planner/core/planbuilder.go:701\ngithub.com/pingcap/tidb/planner.optimize\n\t/home/genius/project/src/github.com/pingcap/tidb/planner/optimize.go:334\ngithub.com/pingcap/tidb/planner.Optimize\n\t/home/genius/project/src/github.com/pingcap/tidb/planner/optimize.go:207\ngithub.com/pingcap/tidb/executor.(*Compiler).Compile\n\t/home/genius/project/src/github.com/pingcap/tidb/executor/compiler.go:79\ngithub.com/pingcap/tidb/session.(*session).ExecuteStmt\n\t/home/genius/project/src/github.com/pingcap/tidb/session/session.go:1917\ngithub.com/pingcap/tidb/testkit.(*TestKit).Exec\n\t/home/genius/project/src/github.com/pingcap/tidb/testkit/testkit.go:214\ngithub.com/pingcap/tidb/testkit.(*TestKit).ExecToErr\n\t/home/genius/project/src/github.com/pingcap/tidb/testkit/testkit.go:251\ngithub.com/pingcap/tidb/expression_test.TestGetLock\n\t/home/genius/project/src/github.com/pingcap/tidb/expression/integration_test.go:259\ntesting.tRunner\n\t/home/genius/project/go/src/testing/testing.go:1439\nruntime.goexit\n\t/home/genius/project/go/src/runtime/asm_amd64.s:1571"] [SQL="SELECT get_lock('testlock')"]
[2022/06/06 13:45:19.272 +08:00] [WARN] [adapter.go:1095] ["# Txn_start_ts: 433715758569095169\n# Query_time: 1.000336019\n# Parse_time: 0\n# Compile_time: 0.000020179\n# Rewrite_time: 0.00000484\n# Optimize_time: 0\n# Wait_TS: 0.000004139\n# Is_internal: true\n# Digest: 503fd5b0bd3ca476326b20cdb82e8088bb82376f9a3b81c2f1887bcf46bb3da6\n# Num_cop_tasks: 0\n# Mem_max: 192\n# Prepared: false\n# Plan_from_cache: false\n# Plan_from_binding: false\n# Has_more_results: false\n# KV_total: 0\n# PD_total: 0\n# Backoff_total: 0\n# Write_sql_response_total: 0\n# Result_rows: 0\n# Succ: false\n# IsExplicitTxn: true\n# Plan: tidb_decode_plan('twHQMAkyN18xCTAJMAlOL0EJMAl0aW1lOjIzLjbCtXMsIGxvb3BzOjEsIHByZXBhcmU6IDUuNjUFGyBpbnNlcnQ6MTgFDixsb2NrX2tleXM6IHsFQzQxcywgcmVnaW9uOjEsIAUaADIBEhRzb2x2ZV8BLxQ6NjkuN8IJZkRja19ycGM6MS4wMDAwODI1MzkBP2RwY19jb3VudDoxfQkxOTIgQnl0ZXMJTi9BCg==')\nINSERT INTO mysql.advisory_locks (lock_name) VALUES ('mygloballock');"]
[2022/06/06 13:45:19.272 +08:00] [WARN] [session.go:1942] ["run statement failed"] [schemaVersion=34] [error="[tikv:1205]Lock wait timeout exceeded; try restarting transaction"] [session="{\n  \"currDBName\": \"\",\n  \"id\": 0,\n  \"status\": 3,\n  \"strictMode\": true,\n  \"txn\": \"433715758569095169\",\n  \"user\": null\n}"]
[2022/06/06 13:45:19.273 +08:00] [WARN] [adapter.go:1095] ["# Txn_start_ts: 0\n# Conn_ID: 1\n# Query_time: 1.001015352\n# Parse_time: 0.00000992\n# Compile_time: 1.000942215\n# Rewrite_time: 1.000880817\n# Optimize_time: 0.000037369\n# Wait_TS: 0\n# Is_internal: false\n# Digest: 62effae92dd50214b4fc01b6f4619259d11a68994cdead2235db509a24c10d5e\n# Num_cop_tasks: 0\n# Prepared: false\n# Plan_from_cache: false\n# Plan_from_binding: false\n# Has_more_results: false\n# KV_total: 0\n# PD_total: 0\n# Backoff_total: 0\n# Write_sql_response_total: 0\n# Result_rows: 1\n# Succ: true\n# IsExplicitTxn: false\n# Plan: tidb_decode_plan('e/BbMAkzXzMJMAkxCTAtPkNvbHVtbiMxCTEJdGltZTo1LjE4wrVzLCBsb29wczoyLCBDb25jdXJyZW5jeTpPRkYJMCBCeXRlcwlOL0EKMQkyNV80CTAJMQlyb3dzOjERRwwzNjBuGUUgCU4vQQlOL0EK')\n# Plan_digest: 4df89435536060a4528770d1c135410a71890415043b7cd580da88c2e5ebcfbf\nSELECT get_lock('mygloballock', 1);"]
[2022/06/06 13:45:19.302 +08:00] [WARN] [session.go:1942] ["run statement failed"] [schemaVersion=34] [error="pessimistic lock retry limit reached"] [errorVerbose="pessimistic lock retry limit reached\ngithub.com/pingcap/tidb/executor.(*ExecStmt).handlePessimisticLockError\n\t/home/genius/project/src/github.com/pingcap/tidb/executor/adapter.go:787\ngithub.com/pingcap/tidb/executor.(*ExecStmt).handlePessimisticDML\n\t/home/genius/project/src/github.com/pingcap/tidb/executor/adapter.go:722\ngithub.com/pingcap/tidb/executor.(*ExecStmt).handleNoDelay\n\t/home/genius/project/src/github.com/pingcap/tidb/executor/adapter.go:514\ngithub.com/pingcap/tidb/executor.(*ExecStmt).Exec\n\t/home/genius/project/src/github.com/pingcap/tidb/executor/adapter.go:465\ngithub.com/pingcap/tidb/session.runStmt\n\t/home/genius/project/src/github.com/pingcap/tidb/session/session.go:2070\ngithub.com/pingcap/tidb/session.(*session).ExecuteStmt\n\t/home/genius/project/src/github.com/pingcap/tidb/session/session.go:1939\ngithub.com/pingcap/tidb/session.(*session).ExecuteInternal\n\t/home/genius/project/src/github.com/pingcap/tidb/session/session.go:1466\ngithub.com/pingcap/tidb/session.(*advisoryLock).GetLock\n\t/home/genius/project/src/github.com/pingcap/tidb/session/advisory_locks.go:78\ngithub.com/pingcap/tidb/session.(*session).GetAdvisoryLock\n\t/home/genius/project/src/github.com/pingcap/tidb/session/session.go:1616\ngithub.com/pingcap/tidb/expression.(*builtinLockSig).evalInt\n\t/home/genius/project/src/github.com/pingcap/tidb/expression/builtin_miscellaneous.go:231\ngithub.com/pingcap/tidb/expression.(*ScalarFunction).EvalInt\n\t/home/genius/project/src/github.com/pingcap/tidb/expression/scalar_function.go:402\ngithub.com/pingcap/tidb/expression.(*ScalarFunction).Eval\n\t/home/genius/project/src/github.com/pingcap/tidb/expression/scalar_function.go:355\ngithub.com/pingcap/tidb/expression.foldConstant\n\t/home/genius/project/src/github.com/pingcap/tidb/expression/constant_fold.go:216\ngithub.com/pingcap/tidb/expression.FoldConstant\n\t/home/genius/project/src/github.com/pingcap/tidb/expression/constant_fold.go:40\ngithub.com/pingcap/tidb/expression.newFunctionImpl\n\t/home/genius/project/src/github.com/pingcap/tidb/expression/scalar_function.go:236\ngithub.com/pingcap/tidb/expression.NewFunction\n\t/home/genius/project/src/github.com/pingcap/tidb/expression/scalar_function.go:254\ngithub.com/pingcap/tidb/planner/core.(*expressionRewriter).newFunction\n\t/home/genius/project/src/github.com/pingcap/tidb/planner/core/expression_rewriter.go:1232\ngithub.com/pingcap/tidb/planner/core.(*expressionRewriter).funcCallToExpression\n\t/home/genius/project/src/github.com/pingcap/tidb/planner/core/expression_rewriter.go:1886\ngithub.com/pingcap/tidb/planner/core.(*expressionRewriter).Leave\n\t/home/genius/project/src/github.com/pingcap/tidb/planner/core/expression_rewriter.go:1099\ngithub.com/pingcap/tidb/parser/ast.(*FuncCallExpr).Accept\n\t/home/genius/project/src/github.com/pingcap/tidb/parser/ast/functions.go:532\ngithub.com/pingcap/tidb/planner/core.(*PlanBuilder).rewriteExprNode\n\t/home/genius/project/src/github.com/pingcap/tidb/planner/core/expression_rewriter.go:199\ngithub.com/pingcap/tidb/planner/core.(*PlanBuilder).rewriteWithPreprocess\n\t/home/genius/project/src/github.com/pingcap/tidb/planner/core/expression_rewriter.go:145\ngithub.com/pingcap/tidb/planner/core.(*PlanBuilder).buildProjection\n\t/home/genius/project/src/github.com/pingcap/tidb/planner/core/logical_plan_builder.go:1290\ngithub.com/pingcap/tidb/planner/core.(*PlanBuilder).buildSelect\n\t/home/genius/project/src/github.com/pingcap/tidb/planner/core/logical_plan_builder.go:3919\ngithub.com/pingcap/tidb/planner/core.(*PlanBuilder).Build\n\t/home/genius/project/src/github.com/pingcap/tidb/planner/core/planbuilder.go:701\ngithub.com/pingcap/tidb/planner.optimize\n\t/home/genius/project/src/github.com/pingcap/tidb/planner/optimize.go:334\ngithub.com/pingcap/tidb/planner.Optimize\n\t/home/genius/project/src/github.com/pingcap/tidb/planner/optimize.go:207\ngithub.com/pingcap/tidb/executor.(*Compiler).Compile\n\t/home/genius/project/src/github.com/pingcap/tidb/executor/compiler.go:79\ngithub.com/pingcap/tidb/session.(*session).ExecuteStmt\n\t/home/genius/project/src/github.com/pingcap/tidb/session/session.go:1917\ngithub.com/pingcap/tidb/testkit.(*TestKit).Exec\n\t/home/genius/project/src/github.com/pingcap/tidb/testkit/testkit.go:214\ngithub.com/pingcap/tidb/testkit.(*TestKit).MustQuery\n\t/home/genius/project/src/github.com/pingcap/tidb/testkit/testkit.go:101\ngithub.com/pingcap/tidb/expression_test.TestGetLock\n\t/home/genius/project/src/github.com/pingcap/tidb/expression/integration_test.go:377"] [session="{\n  \"currDBName\": \"\",\n  \"id\": 0,\n  \"status\": 3,\n  \"strictMode\": true,\n  \"txn\": \"433715758831763456\",\n  \"user\": null\n}"]
[2022/06/06 13:45:19.303 +08:00] [INFO] [ddl_worker.go:155] ["[ddl] DDL worker closed"] [worker="worker 3, tp general"] ["take time"=350ns]
[2022/06/06 13:45:19.303 +08:00] [INFO] [ddl_worker.go:155] ["[ddl] DDL worker closed"] [worker="worker 4, tp add index"] ["take time"=40ns]
[2022/06/06 13:45:19.303 +08:00] [INFO] [delete_range.go:130] ["[ddl] closing delRange"]
[2022/06/06 13:45:19.303 +08:00] [INFO] [session_pool.go:94] ["[ddl] closing sessionPool"]
[2022/06/06 13:45:19.303 +08:00] [INFO] [ddl.go:560] ["[ddl] DDL closed"] [ID=d361396e-7638-4eef-9563-3a48afc898ce] ["take time"=266.219µs]
[2022/06/06 13:45:19.303 +08:00] [INFO] [ddl.go:452] ["[ddl] stop DDL"] [ID=d361396e-7638-4eef-9563-3a48afc898ce]
[2022/06/06 13:45:19.303 +08:00] [INFO] [domain.go:486] ["topNSlowQueryLoop exited."]
[2022/06/06 13:45:19.303 +08:00] [INFO] [domain.go:1252] ["dumpFileGcChecker exited."]
[2022/06/06 13:45:19.303 +08:00] [INFO] [handle_hist.go:143] ["SubLoadWorker exited."]
[2022/06/06 13:45:19.303 +08:00] [INFO] [handle_hist.go:143] ["SubLoadWorker exited."]
[2022/06/06 13:45:19.303 +08:00] [INFO] [handle_hist.go:143] ["SubLoadWorker exited."]
[2022/06/06 13:45:19.303 +08:00] [INFO] [handle_hist.go:143] ["SubLoadWorker exited."]
[2022/06/06 13:45:19.303 +08:00] [INFO] [handle_hist.go:143] ["SubLoadWorker exited."]
[2022/06/06 13:45:19.303 +08:00] [INFO] [domain.go:1046] ["LoadSysVarCacheLoop exited."]
[2022/06/06 13:45:19.303 +08:00] [INFO] [domain.go:996] ["loadPrivilegeInLoop exited."]
[2022/06/06 13:45:19.303 +08:00] [INFO] [domain.go:1167] ["handleEvolvePlanTasksLoop exited."]
[2022/06/06 13:45:19.303 +08:00] [INFO] [domain.go:1124] ["globalBindHandleWorkerLoop exited."]
[2022/06/06 13:45:19.303 +08:00] [INFO] [domain.go:563] ["topologySyncerKeeper exited."]
[2022/06/06 13:45:19.303 +08:00] [INFO] [domain.go:540] ["globalConfigSyncerKeeper exited."]
[2022/06/06 13:45:19.303 +08:00] [INFO] [domain.go:515] ["infoSyncerKeeper exited."]
[2022/06/06 13:45:19.303 +08:00] [INFO] [domain.go:721] ["domain closed"] ["take time"=432.472µs]
[2022/06/06 13:45:19.308 +08:00] [INFO] [db.go:567] ["Closing database"]
[2022/06/06 13:45:19.309 +08:00] [INFO] [db.go:592] ["Memtable flushed"]
[2022/06/06 13:45:19.309 +08:00] [INFO] [db.go:596] ["Compaction finished"]
[2022/06/06 13:45:19.309 +08:00] [INFO] [db.go:615] ["BlobManager finished"]
[2022/06/06 13:45:19.309 +08:00] [INFO] [db.go:619] ["ResourceManager finished"]
[2022/06/06 13:45:19.309 +08:00] [INFO] [db.go:625] ["Waiting for closer"]
--- FAIL: TestGetLock (1.17s)
panic: interface conversion: error is *errors.fundamental, not *errors.Error [recovered]
	panic: interface conversion: error is *errors.fundamental, not *errors.Error

goroutine 179 [running]:
testing.tRunner.func1.2({0x3b06660, 0xc005c4fa40})
	/home/genius/project/go/src/testing/testing.go:1389 +0x24e
testing.tRunner.func1()
	/home/genius/project/go/src/testing/testing.go:1392 +0x39f
panic({0x3b06660, 0xc005c4fa40})
	/home/genius/project/go/src/runtime/panic.go:838 +0x207
github.com/pingcap/tidb/expression.(*builtinLockSig).evalInt(0xc0012a1080, {0x0?, 0xc0012a1080?})
	/home/genius/project/src/github.com/pingcap/tidb/expression/builtin_miscellaneous.go:233 +0x485
github.com/pingcap/tidb/expression.(*ScalarFunction).EvalInt(0xc0051bd680, {0x4aed078, 0xc006d27b00}, {0x0?, 0x80?})
	/home/genius/project/src/github.com/pingcap/tidb/expression/scalar_function.go:402 +0x9c
github.com/pingcap/tidb/expression.(*ScalarFunction).Eval(0xc0051bd680, {0x0?, 0x6?})
	/home/genius/project/src/github.com/pingcap/tidb/expression/scalar_function.go:355 +0x265
github.com/pingcap/tidb/expression.foldConstant({0x4aec290?, 0xc0051bd680?})
	/home/genius/project/src/github.com/pingcap/tidb/expression/constant_fold.go:216 +0xa05
github.com/pingcap/tidb/expression.FoldConstant({0x4aec290, 0xc0051bd680})
	/home/genius/project/src/github.com/pingcap/tidb/expression/constant_fold.go:40 +0x27
github.com/pingcap/tidb/expression.newFunctionImpl({0x4aed078, 0xc006d27b00}, 0x1, {0x3fa0fdd?, 0x10?}, 0xc005263b40, {0xc001269640, 0x2, 0xc005ff4c00?})
	/home/genius/project/src/github.com/pingcap/tidb/expression/scalar_function.go:236 +0x64e
github.com/pingcap/tidb/expression.NewFunction(...)
	/home/genius/project/src/github.com/pingcap/tidb/expression/scalar_function.go:254
github.com/pingcap/tidb/planner/core.(*expressionRewriter).newFunction(0xc000225ee0, {0x3fa0fdd?, 0x3fa0fdd?}, 0x8?, {0xc001269640?, 0xc00129ff40?, 0x20?})
	/home/genius/project/src/github.com/pingcap/tidb/planner/core/expression_rewriter.go:1232 +0xa6
github.com/pingcap/tidb/planner/core.(*expressionRewriter).funcCallToExpression(0xc000225ee0, 0xc005263b00)
	/home/genius/project/src/github.com/pingcap/tidb/planner/core/expression_rewriter.go:1886 +0x6e9
github.com/pingcap/tidb/planner/core.(*expressionRewriter).Leave(0xc000225ee0, {0x4aa1d50?, 0xc005263b00?})
	/home/genius/project/src/github.com/pingcap/tidb/planner/core/expression_rewriter.go:1099 +0x717
github.com/pingcap/tidb/parser/ast.(*FuncCallExpr).Accept(0xc000225e10?, {0x4a83d90, 0xc000225ee0})
	/home/genius/project/src/github.com/pingcap/tidb/parser/ast/functions.go:532 +0xa3
github.com/pingcap/tidb/planner/core.(*PlanBuilder).rewriteExprNode(0xc006cadba0?, 0xc000225ee0, {0x4aacfa0?, 0xc005263b00?}, 0x1)
	/home/genius/project/src/github.com/pingcap/tidb/planner/core/expression_rewriter.go:199 +0x11a
github.com/pingcap/tidb/planner/core.(*PlanBuilder).rewriteWithPreprocess(0xc006cadba0, {0x4a95bd0?, 0xc0000540f0?}, {0x4aacfa0, 0xc005263b00}, {0x4abbfc0?, 0xc000225e10?}, 0x0, 0x0, 0x1, ...)
	/home/genius/project/src/github.com/pingcap/tidb/planner/core/expression_rewriter.go:145 +0x173
github.com/pingcap/tidb/planner/core.(*PlanBuilder).buildProjection(0xc006cadba0, {0x4a95bd0, 0xc0000540f0}, {0x4abbfc0?, 0xc000225e10?}, {0xc000952560, 0x1, 0x3e3d5a0?}, 0xc00144d110?, 0x0, ...)
	/home/genius/project/src/github.com/pingcap/tidb/planner/core/logical_plan_builder.go:1290 +0x617
github.com/pingcap/tidb/planner/core.(*PlanBuilder).buildSelect(0xc006cadba0, {0x4a95bd0, 0xc0000540f0}, 0xc00595b680)
	/home/genius/project/src/github.com/pingcap/tidb/planner/core/logical_plan_builder.go:3919 +0x131b
github.com/pingcap/tidb/planner/core.(*PlanBuilder).Build(0xc006cadba0, {0x4a95bd0, 0xc0000540f0}, {0x4aa2e80?, 0xc00595b680?})
	/home/genius/project/src/github.com/pingcap/tidb/planner/core/planbuilder.go:701 +0x3ef
github.com/pingcap/tidb/planner.optimize({0x4a95bd0, 0xc0000540f0}, {0x4aed078, 0xc006d27b00}, {0x4aa2e80, 0xc00595b680}, {0x4ab5430, 0xc00662c320})
	/home/genius/project/src/github.com/pingcap/tidb/planner/optimize.go:334 +0x74a
github.com/pingcap/tidb/planner.Optimize({0x4a95bd0, 0xc0000540f0}, {0x4aed078, 0xc006d27b00}, {0x4aa2e80, 0xc00595b680}, {0x4ab5430, 0xc00662c320})
	/home/genius/project/src/github.com/pingcap/tidb/planner/optimize.go:207 +0xd58
github.com/pingcap/tidb/executor.(*Compiler).Compile(0xc006feb7a8, {0x4a95bd0, 0xc0000540f0}, {0x4aa7318, 0xc00595b680})
	/home/genius/project/src/github.com/pingcap/tidb/executor/compiler.go:79 +0x4d3
github.com/pingcap/tidb/session.(*session).ExecuteStmt(0xc006d27b00, {0x4a95bd0, 0xc0000540f0}, {0x4aa7318?, 0xc00595b680})
	/home/genius/project/src/github.com/pingcap/tidb/session/session.go:1917 +0x57c
github.com/pingcap/tidb/testkit.(*TestKit).Exec(0xc006f40bc0, {0x3fa0fd6, 0x22}, {0x0?, 0x2?, 0x4?})
	/home/genius/project/src/github.com/pingcap/tidb/testkit/testkit.go:214 +0x516
github.com/pingcap/tidb/testkit.(*TestKit).MustQuery(0xc006f40bc0, {0x3fa0fd6, 0x22}, {0x0, 0x0, 0x0})
	/home/genius/project/src/github.com/pingcap/tidb/testkit/testkit.go:101 +0x119
github.com/pingcap/tidb/expression_test.TestGetLock(0x145ccb9?)
	/home/genius/project/src/github.com/pingcap/tidb/expression/integration_test.go:377 +0x1c7d
testing.tRunner(0xc0017016c0, 0x40a1f78)
	/home/genius/project/go/src/testing/testing.go:1439 +0x102
created by testing.(*T).Run
	/home/genius/project/go/src/testing/testing.go:1486 +0x35f
run all tasks takes 1.238539916s
make: *** [Makefile:121: ut] Error 1

[Mini256]

I am working on making an integration test with Prisma and TiDB, and I encountered the same error when I used pingcap/tidb:v7.0.0 docker image.

interface conversion: error is *errors.fundamental, not *errors.Error

In the GitHub Action of Prisma, the test case will be executed concurrently. Some tests using the SELECT GET_LOCK('prisma_migrate', 10) function will have unstable errors:

https://github.com/prisma/prisma-engines/actions/runs/4782345936/jobs/8501595028

I replicated this process locally, and the following is an error log in the tidb-server container:

[2023/04/24 15:17:22.467 +00:00] [INFO] [ddl.go:1068] ["[ddl] start DDL job"] [job="ID:198, Type:create schema, State:queueing, SchemaState:none, SchemaID:197, TableID:0, RowCount:0, ArgLen:1, start time: 2023-04-24 15:17:22.464 +0000 UTC, Err:<nil>, ErrCount:0, SnapshotVersion:0"] [query="CREATE DATABASE `prisma_migrate_shadow_db_4b159d43-d29f-49cc-8303-452f897156f5`"]
[2023/04/24 15:17:22.477 +00:00] [INFO] [ddl_worker.go:960] ["[ddl] run DDL job"] [worker="worker 3, tp general"] [job="ID:195, Type:create schema, State:queueing, SchemaState:none, SchemaID:193, TableID:0, RowCount:0, ArgLen:0, start time: 2023-04-24 15:17:22.421 +0000 UTC, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2023/04/24 15:17:22.496 +00:00] [INFO] [session.go:3813] ["CRUCIAL OPERATION"] [conn=2199023256059] [schemaVersion=150] [cur_db=prisma_migrate_shadow_db_2def5ff0-3347-485f-a78f-3d59919f332d] [sql="-- CreateTable\nCREATE TABLE `Cat` (\n    `id` INTEGER NOT NULL,\n    `name` VARCHAR(191) NOT NULL,\n\n    PRIMARY KEY (`id`)\n) DEFAULT CHARACTER SET utf8mb4 COLLATE utf8mb4_unicode_ci;"] [user=root@%]
[2023/04/24 15:17:22.504 +00:00] [INFO] [domain.go:224] ["diff load InfoSchema success"] [currentSchemaVersion=150] [neededSchemaVersion=151] ["start time"=271.542µs] [gotSchemaVersion=151] [phyTblIDs="[]"] [actionTypes="[]"]
[2023/04/24 15:17:22.534 +00:00] [INFO] [domain.go:795] ["mdl gets lock, update to owner"] [jobID=195] [version=151]
[2023/04/24 15:17:22.534 +00:00] [INFO] [ddl_worker.go:1177] ["[ddl] wait latest schema version changed(get the metadata lock if tidb_enable_metadata_lock is true)"] [ver=151] ["take time"=30.509209ms] [job="ID:195, Type:create schema, State:done, SchemaState:public, SchemaID:193, TableID:0, RowCount:0, ArgLen:1, start time: 2023-04-24 15:17:22.421 +0000 UTC, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2023/04/24 15:17:22.555 +00:00] [INFO] [ddl_worker.go:234] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:200, Type:create table, State:queueing, SchemaState:none, SchemaID:191, TableID:199, RowCount:0, ArgLen:2, start time: 2023-04-24 15:17:22.531 +0000 UTC, Err:<nil>, ErrCount:0, SnapshotVersion:0; "] [table=true]
[2023/04/24 15:17:22.556 +00:00] [INFO] [ddl.go:1068] ["[ddl] start DDL job"] [job="ID:200, Type:create table, State:queueing, SchemaState:none, SchemaID:191, TableID:199, RowCount:0, ArgLen:2, start time: 2023-04-24 15:17:22.531 +0000 UTC, Err:<nil>, ErrCount:0, SnapshotVersion:0"] [query="-- CreateTable\nCREATE TABLE `Cat` (\n    `id` INTEGER NOT NULL,\n    `name` VARCHAR(191) NOT NULL,\n\n    PRIMARY KEY (`id`)\n) DEFAULT CHARACTER SET utf8mb4 COLLATE utf8mb4_unicode_ci;"]
[2023/04/24 15:17:22.602 +00:00] [INFO] [ddl_worker.go:579] ["[ddl] finish DDL job"] [worker="worker 3, tp general"] [job="ID:195, Type:create schema, State:synced, SchemaState:public, SchemaID:193, TableID:0, RowCount:0, ArgLen:0, start time: 2023-04-24 15:17:22.421 +0000 UTC, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2023/04/24 15:17:22.614 +00:00] [INFO] [ddl.go:1166] ["[ddl] DDL job is finished"] [jobID=195]
[2023/04/24 15:17:22.614 +00:00] [INFO] [callback.go:128] ["performing DDL change, must reload"]
[2023/04/24 15:17:22.643 +00:00] [WARN] [session.go:2202] ["run statement failed"] [schemaVersion=123] [error="pessimistic lock retry limit reached"] [session="{\n  \"currDBName\": \"\",\n  \"id\": 0,\n  \"status\": 3,\n  \"strictMode\": true,\n  \"txn\": \"441017811446530048\",\n  \"user\": null\n}"]
[2023/04/24 15:17:22.645 +00:00] [ERROR] [conn.go:1039] ["connection running loop panic"] [conn=2199023255991] [lastSQL="SELECT GET_LOCK('prisma_migrate', 10)"] [err="interface conversion: error is *errors.fundamental, not *errors.Error"] [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:1042\nruntime.gopanic\n\t/usr/local/go/src/runtime/panic.go:884\ngithub.com/pingcap/tidb/executor.(*Compiler).Compile.func1\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/compiler.go:54\nruntime.gopanic\n\t/usr/local/go/src/runtime/panic.go:884\nruntime.panicdottypeE\n\t/usr/local/go/src/runtime/iface.go:262\nruntime.panicdottypeI\n\t/usr/local/go/src/runtime/iface.go:272\ngithub.com/pingcap/tidb/expression.(*builtinLockSig).evalInt\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/expression/builtin_miscellaneous.go:232\ngithub.com/pingcap/tidb/expression.(*ScalarFunction).EvalInt\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/expression/scalar_function.go:406\ngithub.com/pingcap/tidb/expression.(*ScalarFunction).Eval\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/expression/scalar_function.go:362\ngithub.com/pingcap/tidb/expression.foldConstant\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/expression/constant_fold.go:221\ngithub.com/pingcap/tidb/expression.FoldConstant\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/expression/constant_fold.go:40\ngithub.com/pingcap/tidb/expression.newFunctionImpl\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/expression/scalar_function.go:243\ngithub.com/pingcap/tidb/expression.NewFunction\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/expression/scalar_function.go:261\ngithub.com/pingcap/tidb/planner/core.(*expressionRewriter).newFunction\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/planner/core/expression_rewriter.go:1316\ngithub.com/pingcap/tidb/planner/core.(*expressionRewriter).funcCallToExpression\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/planner/core/expression_rewriter.go:1988\ngithub.com/pingcap/tidb/planner/core.(*expressionRewriter).Leave\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/planner/core/expression_rewriter.go:1161\ngithub.com/pingcap/tidb/parser/ast.(*FuncCallExpr).Accept\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/parser/ast/functions.go:580\ngithub.com/pingcap/tidb/planner/core.(*PlanBuilder).rewriteExprNode\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/planner/core/expression_rewriter.go:200\ngithub.com/pingcap/tidb/planner/core.(*PlanBuilder).rewriteWithPreprocess\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/planner/core/expression_rewriter.go:146\ngithub.com/pingcap/tidb/planner/core.(*PlanBuilder).buildProjection\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/planner/core/logical_plan_builder.go:1444\ngithub.com/pingcap/tidb/planner/core.(*PlanBuilder).buildSelect\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/planner/core/logical_plan_builder.go:4160\ngithub.com/pingcap/tidb/planner/core.(*PlanBuilder).Build\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/planner/core/planbuilder.go:819\ngithub.com/pingcap/tidb/planner.buildLogicalPlan\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/planner/optimize.go:506\ngithub.com/pingcap/tidb/planner.optimize\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/planner/optimize.go:427\ngithub.com/pingcap/tidb/planner.Optimize\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/planner/optimize.go:290\ngithub.com/pingcap/tidb/executor.(*Compiler).Compile\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/compiler.go:98\ngithub.com/pingcap/tidb/session.(*session).ExecuteStmt\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/session/session.go:2140\ngithub.com/pingcap/tidb/server.(*TiDBContext).ExecuteStmt\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/driver_tidb.go:259\ngithub.com/pingcap/tidb/server.(*clientConn).handleStmt\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/conn.go:2001\ngithub.com/pingcap/tidb/server.(*clientConn).handleQuery\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/conn.go:1851\ngithub.com/pingcap/tidb/server.(*clientConn).dispatch\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/conn.go:1337\ngithub.com/pingcap/tidb/server.(*clientConn).Run\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/conn.go:1120\ngithub.com/pingcap/tidb/server.(*Server).onConn\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/server.go:675"]
[2023/04/24 15:17:22.654 +00:00] [INFO] [ddl_worker.go:960] ["[ddl] run DDL job"] [worker="worker 3, tp general"] [job="ID:196, Type:create schema, State:queueing, SchemaState:none, SchemaID:194, TableID:0, RowCount:0, ArgLen:0, start time: 2023-04-24 15:17:22.435 +0000 UTC, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2023/04/24 15:17:22.666 +00:00] [INFO] [domain.go:224] ["diff load InfoSchema success"] [currentSchemaVersion=151] [neededSchemaVersion=152] ["start time"=363.458µs] [gotSchemaVersion=152] [phyTblIDs="[]"] [actionTypes="[]"]
[2023/04/24 15:17:22.679 +00:00] [INFO] [domain.go:795] ["mdl gets lock, update to owner"] [jobID=196] [version=152]
[2023/04/24 15:17:22.681 +00:00] [INFO] [ddl_worker.go:1177] ["[ddl] wait latest schema version changed(get the metadata lock if tidb_enable_metadata_lock is true)"] [ver=152] ["take time"=16.230458ms] [job="ID:196, Type:create schema, State:done, SchemaState:public, SchemaID:194, TableID:0, RowCount:0, ArgLen:1, start time: 2023-04-24 15:17:22.435 +0000 UTC, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2023/04/24 15:17:22.688 +00:00] [INFO] [session.go:3813] ["CRUCIAL OPERATION"] [conn=2199023256063] [schemaVersion=152] [cur_db=with_a_failed_migration] [sql="CREATE DATABASE `prisma_migrate_shadow_db_3cfdac8d-2824-4fdb-bf0b-fb2b7406bf18`"] [user=root@%]
[2023/04/24 15:17:22.700 +00:00] [INFO] [ddl_worker.go:234] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:202, Type:create schema, State:queueing, SchemaState:none, SchemaID:201, TableID:0, RowCount:0, ArgLen:1, start time: 2023-04-24 15:17:22.695 +0000 UTC, Err:<nil>, ErrCount:0, SnapshotVersion:0; "] [table=true]
[2023/04/24 15:17:22.700 +00:00] [INFO] [ddl.go:1068] ["[ddl] start DDL job"] [job="ID:202, Type:create schema, State:queueing, SchemaState:none, SchemaID:201, TableID:0, RowCount:0, ArgLen:1, start time: 2023-04-24 15:17:22.695 +0000 UTC, Err:<nil>, ErrCount:0, SnapshotVersion:0"] [query="CREATE DATABASE `prisma_migrate_shadow_db_3cfdac8d-2824-4fdb-bf0b-fb2b7406bf18`"]
[2023/04/24 15:17:22.707 +00:00] [INFO] [ddl_worker.go:579] ["[ddl] finish DDL job"] [worker="worker 3, tp general"] [job="ID:196, Type:create schema, State:synced, SchemaState:public, SchemaID:194, TableID:0, RowCount:0, ArgLen:0, start time: 2023-04-24 15:17:22.435 +0000 UTC, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2023/04/24 15:17:22.718 +00:00] [INFO] [ddl.go:1166] ["[ddl] DDL job is finished"] [jobID=196]
[2023/04/24 15:17:22.718 +00:00] [INFO] [callback.go:128] ["performing DDL change, must reload"]

Note: the above process can only be reproduced when using tidb-server without configuring tikv-server. When I connect to the tiup playground cluster, this problem does not occur. I'm not sure if the standard cluster will also have this problem.

---

Additionally, I also tried upgrading the container image to pingcap/tidb:nightly, but Prisma's test cases still fail intermittently. However, the error message has changed to:

pessimistic lock retry limit reached

@tiancaiamao, Do you know the reason why its behavior isn't returning 0 when it fails to acquire the lock? How should I avoid this error so that Prisma's tests can also pass in concurrent mode?