Panic happen when input mismatch parameter number

[lizhenhuan]

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. Minimal reproduce step (Required)

用户 TiDB 节点持续重启，tidb log 中存在大量 panic 。 err="runtime error: index out of range [0] with length 0" uptime monitor：

Welcome key word in tidb log

some log：

full log file： tidb.log.tar.gz

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

error log and return error info to user, tidb server not restart

3. What did you see instead (Required)

panic happen , tidb keep restart , server is not aviable

4. What is your TiDB version? (Required)

Server version: 5.7.25-TiDB-v6.3.0 TiDB Server (Apache License 2.0) Community Edition, MySQL 5.7 compatible

Server version: 5.7.25-TiDB-v6.3.0 TiDB Server (Apache License 2.0) Community Edition, MySQL 5.7 compatible

[dveeden]

/severity major /label affects-6.3

[dveeden]

Formatted stack:

github.com/pingcap/tidb/executor.(*outerWorker).run.func1
    /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/index_lookup_join.go:363
runtime.gopanic
    /usr/local/go/src/runtime/panic.go:884
runtime.goPanicIndex
    /usr/local/go/src/runtime/panic.go:113
github.com/pingcap/tidb/expression.(*ParamMarker).GetUserVar
    /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/expression/constant.go:91
github.com/pingcap/tidb/expression.(*Constant).GetType
    /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/expression/constant.go:122
github.com/pingcap/tidb/expression.(*builtinEQIntSig).vecEvalInt
    /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/expression/builtin_compare_vec.go:312
github.com/pingcap/tidb/expression.(*ScalarFunction).VecEvalInt
    /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/expression/scalar_function.go:48
github.com/pingcap/tidb/expression.(*Constant).VecEvalInt
    /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/expression/constant.go:134
github.com/pingcap/tidb/expression.EvalExpr
    /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/expression/expression.go:573
github.com/pingcap/tidb/expression.VecEvalBool
    /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/expression/expression.go:368
github.com/pingcap/tidb/expression.vectorizedFilter
    /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/expression/chunk_executor.go:489
github.com/pingcap/tidb/expression.VectorizedFilterConsiderNull
    /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/expression/chunk_executor.go:401
github.com/pingcap/tidb/expression.VectorizedFilter
    /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/expression/chunk_executor.go:379
github.com/pingcap/tidb/executor.(*SelectionExec).Next
    /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/executor.go:1569
github.com/pingcap/tidb/executor.Next
    /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/executor.go:324
github.com/pingcap/tidb/executor.(*outerWorker).buildTask
    /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/index_lookup_join.go:433
github.com/pingcap/tidb/executor.(*outerWorker).run
    /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/index_lookup_join.go:376

[YangKeao]

Maybe have some connection with https://github.com/pingcap/tidb/issues/38116. The difference is that https://github.com/pingcap/tidb/issues/38116 sets the parameter properly (but removed by TiDB while commit). And for this issue doesn't have enough parameters.

Here is the backtrace. It seems that it affects jdbc only.

runtime.gopanic
        /usr/local/go/src/runtime/panic.go:884
github.com/pingcap/tidb/server.(*clientConn).writeResultset.func1
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/conn.go:2190
runtime.gopanic
        /usr/local/go/src/runtime/panic.go:884
runtime.goPanicIndex
        /usr/local/go/src/runtime/panic.go:113
github.com/pingcap/tidb/expression.(*ParamMarker).GetUserVar
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/expression/constant.go:91
github.com/pingcap/tidb/expression.(*Constant).getLazyDatum
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/expression/constant.go:187
github.com/pingcap/tidb/expression.(*Constant).EvalString
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/expression/constant.go:265
github.com/pingcap/tidb/expression.(*builtinCastStringAsTimeSig).evalTime
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/expression/builtin_cast.go:1297
github.com/pingcap/tidb/expression.(*ScalarFunction).EvalTime
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/expression/scalar_function.go:419
github.com/pingcap/tidb/expression.(*ScalarFunction).Eval
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/expression/scalar_function.go:366
github.com/pingcap/tidb/expression.(*Constant).getLazyDatum
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/expression/constant.go:189
github.com/pingcap/tidb/expression.(*Constant).Eval
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/expression/constant.go:197
github.com/pingcap/tidb/expression.(*Constant).ExplainInfo
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/expression/explain.go:83
github.com/pingcap/tidb/expression.(*ScalarFunction).explainInfo
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/expression/explain.go:52
github.com/pingcap/tidb/expression.(*ScalarFunction).ExplainInfo
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/expression/explain.go:30
github.com/pingcap/tidb/expression.sortedExplainExpressionList
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/expression/explain.go:149
github.com/pingcap/tidb/expression.SortedExplainExpressionList
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/expression/explain.go:139
github.com/pingcap/tidb/planner/core.(*PhysicalSelection).ExplainInfo
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/planner/core/explain.go:301
github.com/pingcap/tidb/planner/core.encodeFlatPlanTree
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/planner/core/encode.go:110
github.com/pingcap/tidb/planner/core.EncodeFlatPlan
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/planner/core/encode.go:62
github.com/pingcap/tidb/executor.getEncodedPlan
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/adapter.go:1488
github.com/pingcap/tidb/executor.(*ExecStmt).SummaryStmt.func1
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/adapter.go:1549
github.com/pingcap/tidb/util/stmtsummary.newStmtSummaryByDigestElement
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/util/stmtsummary/statement_summary.go:603
github.com/pingcap/tidb/util/stmtsummary.(*stmtSummaryByDigest).add.func1
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/util/stmtsummary/statement_summary.go:558
github.com/pingcap/tidb/util/stmtsummary.(*stmtSummaryByDigest).add
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/util/stmtsummary/statement_summary.go:569
github.com/pingcap/tidb/util/stmtsummary.(*stmtSummaryByDigestMap).AddStatement
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/util/stmtsummary/statement_summary.go:340
github.com/pingcap/tidb/executor.(*ExecStmt).SummaryStmt
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/adapter.go:1636
github.com/pingcap/tidb/executor.(*ExecStmt).FinishExecuteStmt
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/adapter.go:1210
github.com/pingcap/tidb/executor.(*ExecStmt).CloseRecordSet
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/adapter.go:1240
github.com/pingcap/tidb/executor.(*recordSet).Close
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/adapter.go:183
github.com/pingcap/tidb/session.(*execStmtResult).Close
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/session/session.go:2263
github.com/pingcap/tidb/server.(*tidbResultSet).Close
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/driver_tidb.go:425
github.com/pingcap/tidb/parser/terror.Call
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/parser/terror/terror.go:306
github.com/pingcap/tidb/server.(*clientConn).writeChunksWithFetchSize
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/conn.go:2356
github.com/pingcap/tidb/server.(*clientConn).writeResultset
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/conn.go:2199
github.com/pingcap/tidb/server.(*clientConn).handleStmtFetch
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/conn_stmt.go:326
github.com/pingcap/tidb/server.(*clientConn).dispatch
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/conn.go:1391
github.com/pingcap/tidb/server.(*clientConn).Run
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/conn.go:1104
github.com/pingcap/tidb/server.(*Server).onConn
        /home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/server.go:563

[dveeden]

@YangKeao might be useful to check with Wireshark what the difference is between Connector/J and Connector/Python (with prepared statement cursor class)

[YangKeao]

After several attempts, I cannot reproduce this problem:

1. mysql-connector-java checks the parameters on the client-side. It cannot submit a query with wrong parameter number.
2. Even the packet is with wrong parameter number, the TiDB reads it according to the parameter number in prepared statement. If the packet is too short (without enough parameter), it will return an error.

I guess this problem is not because the parameter number mismatch, with two evidence:

1. The failing attempt to reproduce this issue above shows that the TiDB can properly handle the packet without enough parameters.
2. All panic happens in the fetch command (or other worker), but we already read parameters (according to the number in the statement) in execute command.

One assumption I could provide is that the TiDB cannot handle two parallel fetch properly. You could verify it with the following java program (or any other connector supports cursor fetch):

public class Example {
    public static void main(String[] args) throws SQLException, InterruptedException {
        Connection conn = DriverManager.getConnection("jdbc:mysql://127.0.0.1:4000/test?useCursorFetch=true&useServerPrepStmts=true&useSSL=false", "root", "");

        conn.setAutoCommit(false); // must set

        conn.prepareStatement("drop table if exists t").execute();
        conn.prepareStatement("create table t (id int auto_increment primary key, id_2 int)").execute();
        conn.prepareStatement("insert into t values (1,1)").execute();
        conn.prepareStatement("insert into t values (2,2)").execute();

        // submit a statement with more arguments:
        PreparedStatement statement1 = conn.prepareStatement("" +
                "select * " +
                "from " +
                "t " +
                "where id = ? and id_2 = ?");
        statement1.setFetchSize(500);
        statement1.setInt(1, 1);
        statement1.setInt(2, 2);
        ResultSet rs_1 = statement1.executeQuery();

        // submit a statement with less arguments:
        PreparedStatement statement2 = conn.prepareStatement("" +
                "select * " +
                "from " +
                "t " +
                "where (id = ?)");
        statement2.setFetchSize(500);
        statement2.setInt(1, 1);
        ResultSet rs_2 = statement2.executeQuery();

        // fetch the result from the first argument
        while (rs_1.next()) {
            int result = rs_1.getInt(1);

            System.out.println(result);
        }

        conn.close();

    }
}

It opens two cursor: one for statement1 with two parameters, and one for statement2 with one parameters. When it tries to read result from statement1, the TiDB will panic, as the parameters in the session has already been modified in the second statement. It produces nearly the same backtrace as shown in the issue, so I guess it's the root cause. @lizhenhuan Could you help to verify it?

This issue actually shared the same root cause with https://github.com/pingcap/tidb/issues/38116, both of them are because the session vars / statement vars of the cursor is shared with others.

[dveeden]

Thanks for the great explanation.

I think this: "When it tries to read result from statement2, the TiDB will panic..." probably should have been this: "When it tries to read result from statement1, the TiDB will panic..."

[YangKeao]

Thanks for the great explanation.

I think this: "When it tries to read result from statement2, the TiDB will panic..." probably should have been this: "When it tries to read result from statement1, the TiDB will panic..."

Nice catch :+1: . Thanks

[YangKeao]

As another issue has been created to track this big problem (https://github.com/pingcap/tidb/issues/40094) and the user has adapted the work around, I'd close this issue.

If you have more discovery over this issue, feel free to reopen or comment under this.