sql: v21.2.5: SET TRANSACTION AS OF SYSTEM TIME should have a nice error if reads were already performed

[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/3059755899/?referrer=webhooks_plugin

Panic message:

txn_coord_sender.go:1047: cannot set fixed timestamp, txn "sql txn" meta={id=8ee478ca pri=0.00459305 epo=0 ts=1646203224.865911984,0 min=1646203224.865911984,0 seq=0} lock=false stat=PENDING rts=1646203224.865911984,0 wto=false gul=1646203224.865911984,0 already performed reads
--
*errutil.leafError: cannot set fixed timestamp, txn "sql txn" meta={id=8ee478ca pri=0.00459305 epo=0 ts=1646203224.865911984,0 min=1646203224.865911984,0 seq=0} lock=false stat=PENDING rts=1646203224.865911984,0 wto=false gul=1646203224.865911984,0 already performed reads (1)
txn_coord_sender.go:1047: *withstack.withStack (top exception)
*assert.withAssertionFailure
*contexttags.withContext: n1 (2)
(check the extra data payloads)

Stacktrace (expand for inline code snippets):

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

Lines 1046 to 1048 in 5afb632

	if !tc.interceptorAlloc.txnSpanRefresher.refreshFootprint.empty() {
	return errors.WithContextTags(errors.AssertionFailedf(
	"cannot set fixed timestamp, txn %s already performed reads", tc.mu.txn), ctx)

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

cockroach/pkg/kv/txn.go

Lines 1390 to 1392 in 5afb632

	defer txn.mu.Unlock()
	return txn.mu.sender.SetFixedTimestamp(ctx, ts)
	}

in pkg/kv.(*Txn).SetFixedTimestamp

cockroach/pkg/sql/txn_state.go

Lines 271 to 273 in 5afb632

	defer ts.mu.Unlock()
	if err := ts.mu.txn.SetFixedTimestamp(ctx, historicalTimestamp); err != nil {
	return err

in pkg/sql.(*txnState).setHistoricalTimestamp

cockroach/pkg/sql/conn_executor.go

Lines 2332 to 2334 in 5afb632

	if !asOfTs.IsEmpty() {
	if err := ex.state.setHistoricalTimestamp(ex.Ctx(), asOfTs); err != nil {
	return err

in pkg/sql.(*connExecutor).setTransactionModes

cockroach/pkg/sql/set_transaction.go

Lines 36 to 38 in 5afb632

	if err := p.extendedEvalCtx.TxnModesSetter.setTransactionModes(n.Modes, asOfTs); err != nil {
	return nil, err

in pkg/sql.(*planner).SetTransaction

cockroach/pkg/sql/opaque.go

Lines 191 to 193 in 5afb632

	case *tree.SetTransaction:
	return p.SetTransaction(ctx, n)
	case *tree.SetSessionAuthorizationDefault:

in pkg/sql.planOpaque

cockroach/pkg/sql/opaque.go

Lines 60 to 62 in 5afb632

	var err error
	plan, err = planOpaque(ctx, p, stmt)
	if err != nil {

in pkg/sql.buildOpaque

cockroach/pkg/sql/opt/optbuilder/opaque.go

Lines 68 to 70 in 5afb632

	}
	obj, err := info.buildFn(b.ctx, b.semaCtx, b.evalCtx, stmt)
	if err != nil {

in pkg/sql/opt/optbuilder.(*Builder).tryBuildOpaque

cockroach/pkg/sql/opt/optbuilder/builder.go

Lines 373 to 375 in 5afb632

	// See if we have an opaque handler registered for this statement type.
	if outScope := b.tryBuildOpaque(stmt, inScope); outScope != nil {
	// The opaque handler may resolve objects; we don't care about caching

in pkg/sql/opt/optbuilder.(*Builder).buildStmt

cockroach/pkg/sql/opt/optbuilder/builder.go

Lines 240 to 242 in 5afb632

	b.ctes = nil
	outScope = b.buildStmt(stmt, desiredTypes, inScope)
	// Build With operators for any CTEs hoisted to the top level.

in pkg/sql/opt/optbuilder.(*Builder).buildStmtAtRoot

cockroach/pkg/sql/opt/optbuilder/builder.go

Lines 214 to 216 in 5afb632

	// and physical properties.
	outScope := b.buildStmtAtRoot(b.stmt, nil /* desiredTypes */)

in pkg/sql/opt/optbuilder.(*Builder).Build

cockroach/pkg/sql/plan_opt.go

Lines 520 to 522 in 5afb632

	bld := optbuilder.New(ctx, &p.semaCtx, p.EvalContext(), &opc.catalog, f, opc.p.stmt.AST)
	if err := bld.Build(); err != nil {
	return nil, err

in pkg/sql.(*optPlanningCtx).buildExecMemo

cockroach/pkg/sql/plan_opt.go

Lines 193 to 195 in 5afb632

	execMemo, err := opc.buildExecMemo(ctx)
	if err != nil {

in pkg/sql.(*planner).makeOptimizerPlan

cockroach/pkg/sql/conn_executor_exec.go

Lines 1259 to 1261 in 5afb632

	func (ex *connExecutor) makeExecPlan(ctx context.Context, planner *planner) error {
	if err := planner.makeOptimizerPlan(ctx); err != nil {
	log.VEventf(ctx, 1, "optimizer plan failed: %v", err)

in pkg/sql.(*connExecutor).makeExecPlan

cockroach/pkg/sql/conn_executor_exec.go

Lines 971 to 973 in 5afb632

	// between here and there needs to happen even if there's an error.
	err := ex.makeExecPlan(ctx, planner)
	// We'll be closing the plan manually below after execution; this

in pkg/sql.(*connExecutor).dispatchToExecutionEngine

cockroach/pkg/sql/conn_executor_exec.go

Lines 708 to 710 in 5afb632

	if err := ex.dispatchToExecutionEngine(ctx, p, res); err != nil {
	stmtThresholdSpan.Finish()

in pkg/sql.(*connExecutor).execStmtInOpenState

cockroach/pkg/sql/conn_executor_exec.go

Lines 128 to 130 in 5afb632

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

in pkg/sql.(*connExecutor).execStmt

cockroach/pkg/sql/conn_executor_exec.go

Lines 215 to 217 in 5afb632

	}
	ev, payload, err = ex.execStmt(ctx, portal.Stmt.Statement, portal.Stmt, pinfo, stmtRes)
	// Portal suspension is supported via a "side" state machine

in pkg/sql.(*connExecutor).execPortal

cockroach/pkg/sql/conn_executor.go

Lines 1772 to 1774 in 5afb632

	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 1774 to 1776 in 5afb632

	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 1628 to 1630 in 5afb632

	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 667 to 669 in 5afb632

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

in pkg/sql.(*Server).ServeConn

cockroach/pkg/sql/pgwire/conn.go

Lines 647 to 649 in 5afb632

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

in pkg/sql/pgwire.(*conn).processCommandsAsync.func1
/usr/local/go/src/runtime/asm_amd64.s#L1370-L1372 in runtime.goexit

pkg/kv/kvclient/kvcoord/txn_coord_sender.go in pkg/kv/kvclient/kvcoord.(*TxnCoordSender).SetFixedTimestamp at line 1047
pkg/kv/txn.go in pkg/kv.(*Txn).SetFixedTimestamp at line 1391
pkg/sql/txn_state.go in pkg/sql.(*txnState).setHistoricalTimestamp at line 272
pkg/sql/conn_executor.go in pkg/sql.(*connExecutor).setTransactionModes at line 2333
pkg/sql/set_transaction.go in pkg/sql.(*planner).SetTransaction at line 37
pkg/sql/opaque.go in pkg/sql.planOpaque at line 192
pkg/sql/opaque.go in pkg/sql.buildOpaque at line 61
pkg/sql/opt/optbuilder/opaque.go in pkg/sql/opt/optbuilder.(*Builder).tryBuildOpaque at line 69
pkg/sql/opt/optbuilder/builder.go in pkg/sql/opt/optbuilder.(*Builder).buildStmt at line 374
pkg/sql/opt/optbuilder/builder.go in pkg/sql/opt/optbuilder.(*Builder).buildStmtAtRoot at line 241
pkg/sql/opt/optbuilder/builder.go in pkg/sql/opt/optbuilder.(*Builder).Build at line 215
pkg/sql/plan_opt.go in pkg/sql.(*optPlanningCtx).buildExecMemo at line 521
pkg/sql/plan_opt.go in pkg/sql.(*planner).makeOptimizerPlan at line 194
pkg/sql/conn_executor_exec.go in pkg/sql.(*connExecutor).makeExecPlan at line 1260
pkg/sql/conn_executor_exec.go in pkg/sql.(*connExecutor).dispatchToExecutionEngine at line 972
pkg/sql/conn_executor_exec.go in pkg/sql.(*connExecutor).execStmtInOpenState at line 709
pkg/sql/conn_executor_exec.go in pkg/sql.(*connExecutor).execStmt at line 129
pkg/sql/conn_executor_exec.go in pkg/sql.(*connExecutor).execPortal at line 216
pkg/sql/conn_executor.go in pkg/sql.(*connExecutor).execCmd.func2 at line 1773
pkg/sql/conn_executor.go in pkg/sql.(*connExecutor).execCmd at line 1775
pkg/sql/conn_executor.go in pkg/sql.(*connExecutor).run at line 1629
pkg/sql/conn_executor.go in pkg/sql.(*Server).ServeConn at line 668
pkg/sql/pgwire/conn.go in pkg/sql/pgwire.(*conn).processCommandsAsync.func1 at line 648
/usr/local/go/src/runtime/asm_amd64.s in runtime.goexit at line 1371

Tag	Value
Cockroach Release	v21.2.5
Cockroach SHA:	5afb632
Platform	linux amd64
Distribution	CCL
Environment	development
Command	start-single-node
Go Version	``
# of CPUs
# of Goroutines

Jira issue: CRDB-13565

[jordanlewis]

Tagging @cockroachdb/sql-experience because I'm thinking that it's unexpected that a txn has been able to perform reads before setting a historical timestamp.

[rafiss]

I think this is a case of an unhandled error case that definitely should be handled. Here's a repro:

root@:26257/defaultdb> begin;
BEGIN

root@:26257/defaultdb  OPEN> select * from a;
  a
-----
  1
(1 row)


root@:26257/defaultdb  OPEN> set transaction as of system time '-1s';
ERROR: internal error: cannot set fixed timestamp, txn "sql txn" meta={id=2e2c6e5b pri=0.00246419 epo=0 ts=1646672419.172919000,0 min=1646672419.172919000,0 seq=0} lock=false stat=PENDING rts=1646672419.172919000,0 wto=false gul=1646672419.672919000,0 already performed reads
SQLSTATE: XX000
DETAIL: stack trace:
/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/txn_coord_sender.go:1047: SetFixedTimestamp()
/go/src/github.com/cockroachdb/cockroach/pkg/kv/txn.go:1391: SetFixedTimestamp()
/go/src/github.com/cockroachdb/cockroach/pkg/sql/txn_state.go:272: setHistoricalTimestamp()
/go/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:2333: setTransactionModes()
/go/src/github.com/cockroachdb/cockroach/pkg/sql/set_transaction.go:37: SetTransaction()
/go/src/github.com/cockroachdb/cockroach/pkg/sql/opaque.go:192: planOpaque()
/go/src/github.com/cockroachdb/cockroach/pkg/sql/opaque.go:61: buildOpaque()
/go/src/github.com/cockroachdb/cockroach/pkg/sql/opt/optbuilder/opaque.go:69: tryBuildOpaque()
/go/src/github.com/cockroachdb/cockroach/pkg/sql/opt/optbuilder/builder.go:374: buildStmt()
/go/src/github.com/cockroachdb/cockroach/pkg/sql/opt/optbuilder/builder.go:241: buildStmtAtRoot()
/go/src/github.com/cockroachdb/cockroach/pkg/sql/opt/optbuilder/builder.go:215: Build()
/go/src/github.com/cockroachdb/cockroach/pkg/sql/plan_opt.go:521: buildExecMemo()
/go/src/github.com/cockroachdb/cockroach/pkg/sql/plan_opt.go:194: makeOptimizerPlan()
/go/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:1260: makeExecPlan()
/go/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:972: dispatchToExecutionEngine()
/go/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:709: execStmtInOpenState()
/go/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:129: execStmt()
/go/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:1705: func1()
/go/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:1707: execCmd()
/go/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:1629: run()
/go/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:668: ServeConn()
/go/src/github.com/cockroachdb/cockroach/pkg/sql/pgwire/conn.go:648: func1()
/usr/local/go/src/runtime/asm_amd64.s:1371: goexit()

HINT: You have encountered an unexpected error.

Please check the public issue tracker to check whether this problem is
already tracked. If you cannot find it there, please report the error
with details by creating a new issue.

If you would rather not post publicly, please contact us directly
using the support form.

We appreciate your feedback.