kvclient: v20.2.2: transaction unexpectedly committed

[cockroach-teamcity]

This issue was autofiled by Sentry. It represents a crash or reported error on a live cluster with telemetry enabled.

Sentry link: https://sentry.io/organizations/cockroach-labs/issues/2071814981/?referrer=webhooks_plugin

Panic message:

txn_coord_sender.go:823: log.Fatal: transaction unexpectedly committed: ×. ba: ×. txn: meta={id=9b6dfc5b pri=0.00922168 epo=0 ts=1607066927.789567810,0 min=1607066927.789567810,0 seq=4} lock=true stat=COMMITTED rts=0,0 wto=false max=0,0 int=3.
--
*errutil.leafError: log.Fatal: transaction unexpectedly committed: ×. ba: ×. txn: meta={id=9b6dfc5b pri=0.00922168 epo=0 ts=1607066927.789567810,0 min=1607066927.789567810,0 seq=4} lock=true stat=COMMITTED rts=0,0 wto=false max=0,0 int=3. (1)
txn_coord_sender.go:823: *withstack.withStack (top exception)
(check the extra data payloads)

Stacktrace (expand for inline code snippets):

cockroach/pkg/kv/kvclient/kvcoord/txn_coord_sender.go

Lines 822 to 824 in 92d9495

	// committed.
	log.Fatalf(ctx, "transaction unexpectedly committed: %s. ba: %s. txn: %s.", pErr, ba, errTxn)
	}

in pkg/kv/kvclient/kvcoord.sanityCheckCommittedErr

cockroach/pkg/kv/kvclient/kvcoord/txn_coord_sender.go

Lines 795 to 797 in 92d9495

	if errTxn.Status == roachpb.COMMITTED {
	sanityCheckCommittedErr(ctx, pErr, ba)
	}

in pkg/kv/kvclient/kvcoord.(*TxnCoordSender).updateStateLocked

cockroach/pkg/kv/kvclient/kvcoord/txn_coord_sender.go

Lines 501 to 503 in 92d9495

	pErr = tc.updateStateLocked(ctx, ba, br, pErr)

in pkg/kv/kvclient/kvcoord.(*TxnCoordSender).Send

cockroach/pkg/kv/db.go

Lines 743 to 745 in 92d9495

	tracing.AnnotateTrace()
	br, pErr := sender.Send(ctx, ba)
	if pErr != nil {

in pkg/kv.(*DB).sendUsingSender

cockroach/pkg/kv/txn.go

Lines 918 to 920 in 92d9495

	txn.mu.Unlock()
	br, pErr := txn.db.sendUsingSender(ctx, ba, sender)
	if pErr == nil {

in pkg/kv.(*Txn).Send

cockroach/pkg/kv/db.go

Lines 653 to 655 in 92d9495

	ba.Header = b.Header
	b.response, b.pErr = send(ctx, ba)
	b.fillResults(ctx)

in pkg/kv.sendAndFill

cockroach/pkg/kv/txn.go

Lines 589 to 591 in 92d9495

	}
	return sendAndFill(ctx, txn.Send, b)
	}

in pkg/kv.(*Txn).Run

cockroach/pkg/kv/txn.go

Lines 651 to 653 in 92d9495

	b.initResult(1 /* calls */, 0, b.raw, nil)
	return txn.Run(ctx, b)
	}

in pkg/kv.(*Txn).CommitInBatch

cockroach/pkg/sql/tablewriter.go

Lines 148 to 150 in 92d9495

	// coordinator.
	err = tb.txn.CommitInBatch(ctx, tb.b)
	} else {

in pkg/sql.(*tableWriterBase).finalize

cockroach/pkg/sql/upsert.go

Lines 123 to 125 in 92d9495

	if lastBatch {
	if err := n.run.tw.finalize(params.ctx); err != nil {
	return false, err

in pkg/sql.(*upsertNode).BatchedNext

cockroach/pkg/sql/plan_batch.go

Lines 158 to 160 in 92d9495

	for {
	if next, err := r.source.BatchedNext(params); !next {
	return err

in pkg/sql.(*rowCountNode).startExec

cockroach/pkg/sql/plan.go

Lines 513 to 515 in 92d9495

	}
	return n.startExec(params)
	},

in pkg/sql.startExec.func2

cockroach/pkg/sql/walk.go

Lines 118 to 120 in 92d9495

	}
	v.err = v.observer.leaveNode(name, plan)
	}()

in pkg/sql.(*planVisitor).visitInternal.func1

cockroach/pkg/sql/walk.go

Lines 297 to 299 in 92d9495

	}
	}

in pkg/sql.(*planVisitor).visitInternal

cockroach/pkg/sql/walk.go

Lines 85 to 87 in 92d9495

	}
	v.visitInternal(plan, name)
	return plan

in pkg/sql.(*planVisitor).visit

cockroach/pkg/sql/walk.go

Lines 49 to 51 in 92d9495

	v := makePlanVisitor(ctx, observer)
	v.visit(plan)
	return v.err

in pkg/sql.walkPlan

cockroach/pkg/sql/plan.go

Lines 516 to 518 in 92d9495

	}
	return walkPlan(params.ctx, plan, o)
	}

in pkg/sql.startExec

cockroach/pkg/sql/plan_node_to_row_source.go

Lines 124 to 126 in 92d9495

	// This starts all of the nodes below this node.
	if err := startExec(p.params, p.node); err != nil {
	p.MoveToDraining(err)

in pkg/sql.(*planNodeToRowSource).Start

cockroach/pkg/sql/execinfra/processorsbase.go

Lines 773 to 775 in 92d9495

	}
	ctx = pb.self.Start(ctx)
	Run(ctx, pb.self, pb.Out.output)

in pkg/sql/execinfra.(*ProcessorBase).Run

cockroach/pkg/sql/flowinfra/flow.go

Lines 391 to 393 in 92d9495

	}
	headProc.Run(ctx)
	return nil

in pkg/sql/flowinfra.(*FlowBase).Run

cockroach/pkg/sql/distsql_running.go

Lines 421 to 423 in 92d9495

	// TODO(radu): this should go through the flow scheduler.
	if err := flow.Run(ctx, func() {}); err != nil {
	log.Fatalf(ctx, "unexpected error from syncFlow.Start(): %v\n"+

in pkg/sql.(*DistSQLPlanner).Run

cockroach/pkg/sql/distsql_running.go

Lines 1001 to 1003 in 92d9495

	recv.expectedRowsRead = int64(physPlan.TotalEstimatedScannedRows)
	return dsp.Run(planCtx, txn, physPlan, recv, evalCtx, nil /* finishedSetupFn */)
	}

in pkg/sql.(*DistSQLPlanner).PlanAndRun

cockroach/pkg/sql/conn_executor_exec.go

Lines 1000 to 1002 in 92d9495

	// the planner whether or not to plan remote table readers.
	cleanup := ex.server.cfg.DistSQLPlanner.PlanAndRun(
	ctx, evalCtx, planCtx, planner.txn, planner.curPlan.main, recv,

in pkg/sql.(*connExecutor).execWithDistSQLEngine

cockroach/pkg/sql/conn_executor_exec.go

Lines 871 to 873 in 92d9495

	ex.sessionTracing.TraceExecStart(ctx, "distributed")
	stats, err := ex.execWithDistSQLEngine(
	ctx, planner, stmt.AST.StatementType(), res, distributePlan.WillDistribute(), progAtomic,

in pkg/sql.(*connExecutor).dispatchToExecutionEngine

cockroach/pkg/sql/conn_executor_exec.go

Lines 638 to 640 in 92d9495

	p.autoCommit = os.ImplicitTxn.Get() && !ex.server.cfg.TestingKnobs.DisableAutoCommit
	if err := ex.dispatchToExecutionEngine(ctx, p, res); err != nil {
	return nil, nil, err

in pkg/sql.(*connExecutor).execStmtInOpenState

cockroach/pkg/sql/conn_executor_exec.go

Lines 113 to 115 in 92d9495

	} else {
	ev, payload, err = ex.execStmtInOpenState(ctx, stmt, res, pinfo)
	}

in pkg/sql.(*connExecutor).execStmt

cockroach/pkg/sql/conn_executor_exec.go

Lines 202 to 204 in 92d9495

	if !portal.exhausted {
	ev, payload, err = ex.execStmt(stmtCtx, curStmt, stmtRes, pinfo)
	// Portal suspension is supported via a "side" state machine

in pkg/sql.(*connExecutor).execPortal

cockroach/pkg/sql/conn_executor.go

Lines 1532 to 1534 in 92d9495

	res = stmtRes
	ev, payload, err = ex.execPortal(ctx, portal, portalName, stmtRes, pinfo)
	return err

in pkg/sql.(*connExecutor).execCmd.func2

cockroach/pkg/sql/conn_executor.go

Lines 1534 to 1536 in 92d9495

	return err
	}()
	// Note: we write to ex.statsCollector.phaseTimes, instead of ex.phaseTimes,

in pkg/sql.(*connExecutor).execCmd

cockroach/pkg/sql/conn_executor.go

Lines 1390 to 1392 in 92d9495

	var err error
	if err = ex.execCmd(ex.Ctx()); err != nil {
	if errors.IsAny(err, io.EOF, errDrainingComplete) {

in pkg/sql.(*connExecutor).run

cockroach/pkg/sql/conn_executor.go

Lines 507 to 509 in 92d9495

	}()
	return h.ex.run(ctx, s.pool, reserved, cancel)
	}

in pkg/sql.(*Server).ServeConn

cockroach/pkg/sql/pgwire/conn.go

Lines 625 to 627 in 92d9495

	reservedOwned = false // We're about to pass ownership away.
	retErr = sqlServer.ServeConn(ctx, connHandler, reserved, cancelConn)
	}()

in pkg/sql/pgwire.(*conn).processCommandsAsync.func1

pkg/kv/kvclient/kvcoord/txn_coord_sender.go in pkg/kv/kvclient/kvcoord.sanityCheckCommittedErr at line 823
pkg/kv/kvclient/kvcoord/txn_coord_sender.go in pkg/kv/kvclient/kvcoord.(*TxnCoordSender).updateStateLocked at line 796
pkg/kv/kvclient/kvcoord/txn_coord_sender.go in pkg/kv/kvclient/kvcoord.(*TxnCoordSender).Send at line 502
pkg/kv/db.go in pkg/kv.(*DB).sendUsingSender at line 744
pkg/kv/txn.go in pkg/kv.(*Txn).Send at line 919
pkg/kv/db.go in pkg/kv.sendAndFill at line 654
pkg/kv/txn.go in pkg/kv.(*Txn).Run at line 590
pkg/kv/txn.go in pkg/kv.(*Txn).CommitInBatch at line 652
pkg/sql/tablewriter.go in pkg/sql.(*tableWriterBase).finalize at line 149
pkg/sql/upsert.go in pkg/sql.(*upsertNode).BatchedNext at line 124
pkg/sql/plan_batch.go in pkg/sql.(*rowCountNode).startExec at line 159
pkg/sql/plan.go in pkg/sql.startExec.func2 at line 514
pkg/sql/walk.go in pkg/sql.(*planVisitor).visitInternal.func1 at line 119
pkg/sql/walk.go in pkg/sql.(*planVisitor).visitInternal at line 298
pkg/sql/walk.go in pkg/sql.(*planVisitor).visit at line 86
pkg/sql/walk.go in pkg/sql.walkPlan at line 50
pkg/sql/plan.go in pkg/sql.startExec at line 517
pkg/sql/plan_node_to_row_source.go in pkg/sql.(*planNodeToRowSource).Start at line 125
pkg/sql/execinfra/processorsbase.go in pkg/sql/execinfra.(*ProcessorBase).Run at line 774
pkg/sql/flowinfra/flow.go in pkg/sql/flowinfra.(*FlowBase).Run at line 392
pkg/sql/distsql_running.go in pkg/sql.(*DistSQLPlanner).Run at line 422
pkg/sql/distsql_running.go in pkg/sql.(*DistSQLPlanner).PlanAndRun at line 1002
pkg/sql/conn_executor_exec.go in pkg/sql.(*connExecutor).execWithDistSQLEngine at line 1001
pkg/sql/conn_executor_exec.go in pkg/sql.(*connExecutor).dispatchToExecutionEngine at line 872
pkg/sql/conn_executor_exec.go in pkg/sql.(*connExecutor).execStmtInOpenState at line 639
pkg/sql/conn_executor_exec.go in pkg/sql.(*connExecutor).execStmt at line 114
pkg/sql/conn_executor_exec.go in pkg/sql.(*connExecutor).execPortal at line 203
pkg/sql/conn_executor.go in pkg/sql.(*connExecutor).execCmd.func2 at line 1533
pkg/sql/conn_executor.go in pkg/sql.(*connExecutor).execCmd at line 1535
pkg/sql/conn_executor.go in pkg/sql.(*connExecutor).run at line 1391
pkg/sql/conn_executor.go in pkg/sql.(*Server).ServeConn at line 508
pkg/sql/pgwire/conn.go in pkg/sql/pgwire.(*conn).processCommandsAsync.func1 at line 626

Tag	Value
Cockroach Release	v20.2.2
Cockroach SHA:	92d9495
Platform	linux amd64
Distribution	CCL
Environment	v20.2.2
Command	server
Go Version	``
# of CPUs
# of Goroutines

[yuzefovich]

cc @nvanbenschoten

[nvanbenschoten]

There is some history behind this assertion. It was added in #47997, removed in #48227, and then re-added in #48297. It doesn't look like we got the assertion quite right, as people have hit it a few times on v20.2.x.

The unfortunate part about this is that both the error and the batch request are too redacted to meaningfully understand. @andreimatei do you have thoughts about what we can do here? Should we are least improve the redaction so we'll have a better idea of what's going wrong next time we see this?

[yuzefovich]

Just a ping on this issue that we have seen a few more reports of this issue in the wild.

[andreimatei]

Oh man, I don't know what's going on. The assertion says that an error is informing the client that the txn it was operating on is committed. That's not supposed to happen (if the txn committed, who's still operating on it?), except for some edge cases that are explicitly handled.
On all the reports are for 20.2. In 21.1, the batch in the assertion is not completely redacted any more, and I'd be very curious to see that batch. I say we just wait for a 21.1 report.

[andreimatei]

We know a little bit about what's in the batch because of the stack traces - they all come from inserts and updates doing CommitInBatch. This is surprising - the request trying to commit gets an error and also commits?
What I really want to see is the error - and that too is supposed to be less redacted in 21.1.

[knz]

Closing in favor of #67765