v22.1.4: txn_coord_sender.go:1085: cannot set fixed timestamp

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

Panic message:

txn_coord_sender.go:1085: cannot set fixed timestamp, txn "sql txn" meta={id=8e97c1c8 key=× pri=0.07488499 epo=0 ts=1658846321.857333804,0 min=1658846321.857333804,0 seq=0} lock=false stat=PENDING rts=1658846321.857333804,0 wto=false gul=1658846322.357333804,0 already performed reads
(1) tags: [n1,client=172.18.0.12:47852,user=root]
Wraps: (2) assertion failure
Wraps: (3) attached stack trace
-- stack trace:
| github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*TxnCoordSender).SetFixedTimestamp
| github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/txn_coord_sender.go:1085
| github.com/cockroachdb/cockroach/pkg/kv.(*Txn).SetFixedTimestamp
| github.com/cockroachdb/cockroach/pkg/kv/txn.go:1478
| github.com/cockroachdb/cockroach/pkg/sql.(*txnState).setHistoricalTimestamp
| github.com/cockroachdb/cockroach/pkg/sql/txn_state.go:293
| github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).handleAOST
| github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:758
| github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execBind.func2
| github.com/cockroachdb/cockroach/pkg/sql/conn_executor_prepare.go:386
| github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execBind
| github.com/cockroachdb/cockroach/pkg/sql/conn_executor_prepare.go:421
| github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execCmd
| github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:1983
| github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).run
| github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:1800
| github.com/cockroachdb/cockroach/pkg/sql.(*Server).ServeConn
| github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:748
| github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*conn).processCommandsAsync.func1
| github.com/cockroachdb/cockroach/pkg/sql/pgwire/conn.go:727
| runtime.goexit
| GOROOT/src/runtime/asm_amd64.s:1581
Wraps: (4) cannot set fixed timestamp, txn "sql txn" meta={id=8e97c1c8 key=× pri=0.07488499 epo=0 ts=1658846321.857333804,0 min=1658846321.857333804,0 seq=0} lock=false stat=PENDING rts=1658846321.857333804,0 wto=false gul=1658846322.357333804,0 already performed reads
Error types: (1) *contexttags.withContext (2) *assert.withAssertionFailure (3) *withstack.withStack (4) *errutil.leafError
-- report composition:
*errutil.leafError: cannot set fixed timestamp, txn "sql txn" meta={id=8e97c1c8 key=× pri=0.07488499 epo=0 ts=1658846321.857333804,0 min=1658846321.857333804,0 seq=0} lock=false stat=PENDING rts=1658846321.857333804,0 wto=false gul=1658846322.357333804,0 already performed reads
txn_coord_sender.go:1085: *withstack.withStack (top exception)
*assert.withAssertionFailure
*contexttags.withContext: n1

Stacktrace (expand for inline code snippets):

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

Lines 1084 to 1086 in 3c6c893

	if tc.hasPerformedReadsLocked() {
	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 1477 to 1479 in 3c6c893

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

in pkg/kv.(*Txn).SetFixedTimestamp

cockroach/pkg/sql/txn_state.go

Lines 292 to 294 in 3c6c893

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

in pkg/sql.(*txnState).setHistoricalTimestamp

cockroach/pkg/sql/conn_executor_exec.go

Lines 757 to 759 in 3c6c893

	p.extendedEvalCtx.SetTxnTimestamp(asOf.Timestamp.GoTime())
	if err := ex.state.setHistoricalTimestamp(ctx, asOf.Timestamp); err != nil {
	return err

in pkg/sql.(*connExecutor).handleAOST

cockroach/pkg/sql/conn_executor_prepare.go

Lines 385 to 387 in 3c6c893

	ex.resetPlanner(ctx, p, txn, ex.server.cfg.Clock.PhysicalTime() /* stmtTS */)
	if err := ex.handleAOST(ctx, ps.AST); err != nil {
	return err

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

cockroach/pkg/sql/conn_executor_prepare.go

Lines 420 to 422 in 3c6c893

	// Use the existing transaction.
	if err := resolve(ctx, ex.state.mu.txn); err != nil {
	return retErr(err)

in pkg/sql.(*connExecutor).execBind

cockroach/pkg/sql/conn_executor.go

Lines 1982 to 1984 in 3c6c893

	res = ex.clientComm.CreateBindResult(pos)
	ev, payload = ex.execBind(ctx, tcmd)
	case DeletePreparedStmt:

in pkg/sql.(*connExecutor).execCmd

cockroach/pkg/sql/conn_executor.go

Lines 1799 to 1801 in 3c6c893

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

in pkg/sql.(*connExecutor).run

cockroach/pkg/sql/conn_executor.go

Lines 747 to 749 in 3c6c893

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

in pkg/sql.(*Server).ServeConn

cockroach/pkg/sql/pgwire/conn.go

Lines 726 to 728 in 3c6c893

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

in pkg/sql/pgwire.(*conn).processCommandsAsync.func1
GOROOT/src/runtime/asm_amd64.s#L1580-L1582 in runtime.goexit

pkg/kv/kvclient/kvcoord/txn_coord_sender.go in pkg/kv/kvclient/kvcoord.(*TxnCoordSender).SetFixedTimestamp at line 1085
pkg/kv/txn.go in pkg/kv.(*Txn).SetFixedTimestamp at line 1478
pkg/sql/txn_state.go in pkg/sql.(*txnState).setHistoricalTimestamp at line 293
pkg/sql/conn_executor_exec.go in pkg/sql.(*connExecutor).handleAOST at line 758
pkg/sql/conn_executor_prepare.go in pkg/sql.(*connExecutor).execBind.func2 at line 386
pkg/sql/conn_executor_prepare.go in pkg/sql.(*connExecutor).execBind at line 421
pkg/sql/conn_executor.go in pkg/sql.(*connExecutor).execCmd at line 1983
pkg/sql/conn_executor.go in pkg/sql.(*connExecutor).run at line 1800
pkg/sql/conn_executor.go in pkg/sql.(*Server).ServeConn at line 748
pkg/sql/pgwire/conn.go in pkg/sql/pgwire.(*conn).processCommandsAsync.func1 at line 727
GOROOT/src/runtime/asm_amd64.s in runtime.goexit at line 1581

Tag	Value
Cockroach Release	v22.1.4
Cockroach SHA:	3c6c893
Platform	linux amd64
Distribution	CCL
Environment	v22.1.4
Command	start-single-node
Go Version	``
# of CPUs
# of Goroutines

Jira issue: CRDB-18028

Epic CRDB-17785

[rafiss]

here is a repro:

root@localhost:26257/defaultdb> insert into t values(1); select * from t as of system time '-1s';                                                                                                             
INSERT 0 1
ERROR: internal error: cannot set fixed timestamp, txn "sql txn" meta={id=1175b0a7 key=/Table/104/1/836565656090935297/0 pri=0.01112670 epo=0 ts=1675369977.662315000,0 min=1675369977.662315000,0 seq=1} lock=true stat=PENDING rts=1675369977.662315000,0 wto=false gul=1675369978.162315000,0 already performed writes
SQLSTATE: XX000
DETAIL: stack trace:
github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/txn_coord_sender.go:1062: SetFixedTimestamp()
github.com/cockroachdb/cockroach/pkg/kv/txn.go:1412: SetFixedTimestamp()
github.com/cockroachdb/cockroach/pkg/sql/txn_state.go:312: setHistoricalTimestamp()
github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:818: handleAOST()
github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:658: execStmtInOpenState()
github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:130: func1()
github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:2530: execWithProfiling()
github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:129: execStmt()
github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:1943: func1()
github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:1948: execCmd()
github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:1866: run()
github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:835: ServeConn()
github.com/cockroachdb/cockroach/pkg/sql/pgwire/conn.go:731: func1()
GOROOT/src/runtime/asm_arm64.s:1172: 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.

We have the correct error handling for explicit transactions:

root@localhost:26257/defaultdb> begin; insert into t values(1); select * from t as of system time '-1s'; commit;                                                                                              
BEGIN
INSERT 0 1
ERROR: inconsistent AS OF SYSTEM TIME timestamp; expected: 1675369928.354921000,0, got: 1675369927.356016000,0
SQLSTATE: 42601
HINT: try SET TRANSACTION AS OF SYSTEM TIME
root@localhost:26257/? ERROR> rollback;                                                                                                                                                                       
ROLLBACK

This should be able to be fixed by modifying handleAOST in conn_executor_exec.go.

[ajwerner]

cockroach/pkg/sql/conn_executor_exec.go

Line 813 in 5f0c56e

if ex.implicitTxn() {

I think this logic is using implicitTxn to mean single-statement