Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Panic happen when input mismatch parameter number #39148

Closed
lizhenhuan opened this issue Nov 15, 2022 · 8 comments
Closed

Panic happen when input mismatch parameter number #39148

lizhenhuan opened this issue Nov 15, 2022 · 8 comments
Assignees
Labels
affects-4.0 This bug affects 4.0.x versions. affects-5.0 This bug affects 5.0.x versions. affects-5.1 This bug affects 5.1.x versions. affects-5.2 This bug affects 5.2.x versions. affects-5.3 This bug affects 5.3.x versions. affects-5.4 This bug affects 5.4.x versions. affects-6.1 affects-6.5 severity/major sig/sql-infra SIG: SQL Infra type/bug The issue is confirmed as a bug.

Comments

@lizhenhuan
Copy link
Contributor

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:
db143cab-3e63-411d-be07-0d361b160d6d

Welcome key word in tidb log
2b39b3b1-ef20-4d27-a0bb-6bbd6712e4b6

some log:
95ebdd72-7b74-49c1-b138-af9e84b92bcd

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

@lizhenhuan lizhenhuan added the type/bug The issue is confirmed as a bug. label Nov 15, 2022
@dveeden
Copy link
Contributor

dveeden commented Nov 16, 2022

/severity major
/label affects-6.3

@ti-chi-bot ti-chi-bot added severity/major affects-6.3 may-affects-4.0 This bug maybe affects 4.0.x versions. may-affects-5.0 This bug maybe affects 5.0.x versions. may-affects-5.1 This bug maybe affects 5.1.x versions. may-affects-5.2 This bug maybe affects 5.2.x versions. may-affects-5.3 This bug maybe affects 5.3.x versions. may-affects-5.4 This bug maybe affects 5.4.x versions. may-affects-6.0 may-affects-6.1 may-affects-6.2 may-affects-6.3 may-affects-6.4 labels Nov 16, 2022
@dveeden
Copy link
Contributor

dveeden commented Nov 16, 2022

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 YangKeao self-assigned this Nov 16, 2022
@YangKeao
Copy link
Member

YangKeao commented Nov 16, 2022

Maybe have some connection with #38116. The difference is that #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
Copy link
Contributor

dveeden commented Nov 16, 2022

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

@seiya-annie seiya-annie added the sig/execution SIG execution label Nov 17, 2022
@zanmato1984 zanmato1984 added sig/sql-infra SIG: SQL Infra and removed sig/execution SIG execution labels Nov 21, 2022
@YangKeao
Copy link
Member

YangKeao commented Dec 21, 2022

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 #38116, both of them are because the session vars / statement vars of the cursor is shared with others.

@YangKeao YangKeao removed may-affects-4.0 This bug maybe affects 4.0.x versions. may-affects-5.1 This bug maybe affects 5.1.x versions. may-affects-5.2 This bug maybe affects 5.2.x versions. may-affects-5.3 This bug maybe affects 5.3.x versions. labels Dec 21, 2022
@YangKeao YangKeao added affects-4.0 This bug affects 4.0.x versions. affects-5.0 This bug affects 5.0.x versions. affects-5.1 This bug affects 5.1.x versions. affects-5.2 This bug affects 5.2.x versions. affects-5.3 This bug affects 5.3.x versions. affects-5.4 This bug affects 5.4.x versions. affects-6.1 and removed may-affects-5.4 This bug maybe affects 5.4.x versions. may-affects-5.0 This bug maybe affects 5.0.x versions. may-affects-6.0 may-affects-6.1 may-affects-6.2 may-affects-6.3 affects-6.3 may-affects-6.4 labels Dec 21, 2022
@dveeden
Copy link
Contributor

dveeden commented Dec 23, 2022

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
Copy link
Member

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 👍 . Thanks

@YangKeao
Copy link
Member

As another issue has been created to track this big problem (#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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
affects-4.0 This bug affects 4.0.x versions. affects-5.0 This bug affects 5.0.x versions. affects-5.1 This bug affects 5.1.x versions. affects-5.2 This bug affects 5.2.x versions. affects-5.3 This bug affects 5.3.x versions. affects-5.4 This bug affects 5.4.x versions. affects-6.1 affects-6.5 severity/major sig/sql-infra SIG: SQL Infra type/bug The issue is confirmed as a bug.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

7 participants