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

kvclient: v22.2.6: attempting to append refresh spans after the tracked timestamp has moved forward #99093

Closed
cockroach-teamcity opened this issue Mar 21, 2023 · 1 comment · Fixed by #99325
Assignees
Labels
C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior. O-sentry Originated from an in-the-wild panic report. T-sql-queries SQL Queries Team

Comments

@cockroach-teamcity
Copy link
Member

cockroach-teamcity commented Mar 21, 2023

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

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

Panic message:

txn_interceptor_span_refresher.go:687: log.Fatal: attempting to append refresh spans after the tracked timestamp has moved forward. batchTimestamp: 1679379412.106937991,0 refreshedTimestamp: 1679379412.122678360,2
(1) attached stack trace
-- stack trace:
| github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*txnSpanRefresher).importLeafFinalState
| github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/txn_interceptor_span_refresher.go:687
| github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*TxnCoordSender).UpdateRootWithLeafFinalState
| github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/txn_coord_sender.go:1259
| github.com/cockroachdb/cockroach/pkg/kv.(*Txn).UpdateRootWithLeafFinalState
| github.com/cockroachdb/cockroach/pkg/kv/txn.go:1345
| github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLReceiver).pushMeta
| github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:1129
| github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLReceiver).Push
| github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:1253
| github.com/cockroachdb/cockroach/pkg/sql/execinfra.Run
| github.com/cockroachdb/cockroach/pkg/sql/execinfra/base.go:189
| github.com/cockroachdb/cockroach/pkg/sql/execinfra.(*ProcessorBaseNoHelper).Run
| github.com/cockroachdb/cockroach/pkg/sql/execinfra/processorsbase.go:729
| github.com/cockroachdb/cockroach/pkg/sql/flowinfra.(*FlowBase).Run
| github.com/cockroachdb/cockroach/pkg/sql/flowinfra/flow.go:480
| github.com/cockroachdb/cockroach/pkg/sql/colflow.(*vectorizedFlow).Run
| github.com/cockroachdb/cockroach/pkg/sql/colflow/vectorized_flow.go:307
| github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLPlanner).Run
| github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:731
| github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLPlanner).PlanAndRun
| github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:1698
| github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLPlanner).PlanAndRunAll
| github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:1421
| github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execWithDistSQLEngine
| github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:1587
| github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).dispatchToExecutionEngine
| github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:1201
| github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execStmtInOpenState
| github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:696
| github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execStmt.func1
| github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:131
| github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execWithProfiling
| github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:2428
| github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execStmt
| github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:130
| github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execPortal
| github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:220
| github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execCmd.func2
| github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:2050
| github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execCmd
| github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:2052
| github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).run
| github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:1898
| github.com/cockroachdb/cockroach/pkg/sql.(*Server).ServeConn
| github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:857
| github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*conn).processCommandsAsync.func1
| github.com/cockroachdb/cockroach/pkg/sql/pgwire/conn.go:728
| runtime.goexit
| GOROOT/src/runtime/asm_amd64.s:1594
Wraps: (2) secondary error attachment
| attempting to append refresh spans after the tracked timestamp has moved forward. batchTimestamp: 1679379412.106937991,0 refreshedTimestamp: 1679379412.122678360,2
| (1) assertion failure
| Wraps: (2) attached stack trace
| -- stack trace:
| | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*txnSpanRefresher).assertRefreshSpansAtInvalidTimestamp
| | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/txn_interceptor_span_refresher.go:646
| | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*txnSpanRefresher).importLeafFinalState
| | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/txn_interceptor_span_refresher.go:686
| | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*TxnCoordSender).UpdateRootWithLeafFinalState
| | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/txn_coord_sender.go:1259
| | github.com/cockroachdb/cockroach/pkg/kv.(*Txn).UpdateRootWithLeafFinalState
| | github.com/cockroachdb/cockroach/pkg/kv/txn.go:1345
| | github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLReceiver).pushMeta
| | github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:1129
| | github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLReceiver).Push
| | github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:1253
| | github.com/cockroachdb/cockroach/pkg/sql/execinfra.Run
| | github.com/cockroachdb/cockroach/pkg/sql/execinfra/base.go:189
| | github.com/cockroachdb/cockroach/pkg/sql/execinfra.(*ProcessorBaseNoHelper).Run
| | github.com/cockroachdb/cockroach/pkg/sql/execinfra/processorsbase.go:729
| | github.com/cockroachdb/cockroach/pkg/sql/flowinfra.(*FlowBase).Run
| | github.com/cockroachdb/cockroach/pkg/sql/flowinfra/flow.go:480
| | github.com/cockroachdb/cockroach/pkg/sql/colflow.(*vectorizedFlow).Run
| | github.com/cockroachdb/cockroach/pkg/sql/colflow/vectorized_flow.go:307
| | github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLPlanner).Run
| | github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:731
| | github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLPlanner).PlanAndRun
| | github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:1698
| | github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLPlanner).PlanAndRunAll
| | github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:1421
| | github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execWithDistSQLEngine
| | github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:1587
| | github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).dispatchToExecutionEngine
| | github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:1201
| | github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execStmtInOpenState
| | github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:696
| | github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execStmt.func1
| | github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:131
| | github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execWithProfiling
| | github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:2428
| | github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execStmt
| | github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:130
| | github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execPortal
| | github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:220
| | github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execCmd.func2
| | github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:2050
| | github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execCmd
| | github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:2052
| | github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).run
| | github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:1898
| | github.com/cockroachdb/cockroach/pkg/sql.(*Server).ServeConn
| | github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:857
| | github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*conn).processCommandsAsync.func1
| | github.com/cockroachdb/cockroach/pkg/sql/pgwire/conn.go:728
| | runtim...

Stacktrace (expand for inline code snippets):

if err := sr.assertRefreshSpansAtInvalidTimestamp(tfs.Txn.ReadTimestamp); err != nil {
log.Fatalf(ctx, "%s", err)
}
in pkg/kv/kvclient/kvcoord.(*txnSpanRefresher).importLeafFinalState
for _, reqInt := range tc.interceptorStack {
reqInt.importLeafFinalState(ctx, tfs)
}
in pkg/kv/kvclient/kvcoord.(*TxnCoordSender).UpdateRootWithLeafFinalState

cockroach/pkg/kv/txn.go

Lines 1344 to 1346 in d5a076f

defer txn.mu.Unlock()
txn.mu.sender.UpdateRootWithLeafFinalState(ctx, tfs)
return nil
in pkg/kv.(*Txn).UpdateRootWithLeafFinalState
if r.txn.ID() == meta.LeafTxnFinalState.Txn.ID {
if err := r.txn.UpdateRootWithLeafFinalState(r.ctx, meta.LeafTxnFinalState); err != nil {
r.SetError(err)
in pkg/sql.(*DistSQLReceiver).pushMeta
if meta != nil {
return r.pushMeta(meta)
}
in pkg/sql.(*DistSQLReceiver).Push
if row != nil || meta != nil {
switch dst.Push(row, meta) {
case NeedMoreRows:
in pkg/sql/execinfra.Run
pb.self.Start(ctx)
Run(pb.ctx, pb.self, pb.Output)
}
in pkg/sql/execinfra.(*ProcessorBaseNoHelper).Run
log.VEventf(ctx, 1, "running %T in the flow's goroutine", headProc)
headProc.Run(ctx)
}
in pkg/sql/flowinfra.(*FlowBase).Run
// as the root, so we run this flow with the default implementation.
f.FlowBase.Run(ctx, doneFn)
return
in pkg/sql/colflow.(*vectorizedFlow).Run
// TODO(radu): this should go through the flow scheduler.
flow.Run(ctx, func() {})
in pkg/sql.(*DistSQLPlanner).Run
recv.expectedRowsRead = int64(physPlan.TotalEstimatedScannedRows)
runCleanup := dsp.Run(ctx, planCtx, txn, physPlan, recv, evalCtx, nil /* finishedSetupFn */)
return func() {
in pkg/sql.(*DistSQLPlanner).PlanAndRun
// the planner whether or not to plan remote table readers.
cleanup := dsp.PlanAndRun(
ctx, evalCtx, planCtx, planner.txn, planner.curPlan.main, recv,
in pkg/sql.(*DistSQLPlanner).PlanAndRunAll
}
err := ex.server.cfg.DistSQLPlanner.PlanAndRunAll(ctx, evalCtx, planCtx, planner, recv, evalCtxFactory)
return *recv.stats, err
in pkg/sql.(*connExecutor).execWithDistSQLEngine
ex.sessionTracing.TraceExecStart(ctx, "distributed")
stats, err = ex.execWithDistSQLEngine(
ctx, planner, stmt.AST.StatementReturnType(), res, distribute, progAtomic,
in pkg/sql.(*connExecutor).dispatchToExecutionEngine
if err := ex.dispatchToExecutionEngine(stmtCtx, p, res); err != nil {
stmtThresholdSpan.Finish()
in pkg/sql.(*connExecutor).execStmtInOpenState
err = ex.execWithProfiling(ctx, ast, prepared, func(ctx context.Context) error {
ev, payload, err = ex.execStmtInOpenState(ctx, parserStmt, prepared, pinfo, res, canAutoCommit)
return err
in pkg/sql.(*connExecutor).execStmt.func1
} else {
err = op(ctx)
}
in pkg/sql.(*connExecutor).execWithProfiling
case stateOpen:
err = ex.execWithProfiling(ctx, ast, prepared, func(ctx context.Context) error {
ev, payload, err = ex.execStmtInOpenState(ctx, parserStmt, prepared, pinfo, res, canAutoCommit)
in pkg/sql.(*connExecutor).execStmt
}
ev, payload, err = ex.execStmt(ctx, portal.Stmt.Statement, portal.Stmt, pinfo, stmtRes, canAutoCommit)
// Portal suspension is supported via a "side" state machine
in pkg/sql.(*connExecutor).execPortal
canAutoCommit := ex.implicitTxn() && tcmd.FollowedBySync
ev, payload, err = ex.execPortal(ctx, portal, portalName, stmtRes, pinfo, canAutoCommit)
return err
in pkg/sql.(*connExecutor).execCmd.func2
return err
}()
// Note: we write to ex.statsCollector.phaseTimes, instead of ex.phaseTimes,
in pkg/sql.(*connExecutor).execCmd
var err error
if err = ex.execCmd(); err != nil {
if errors.IsAny(err, io.EOF, errDrainingComplete) {
in pkg/sql.(*connExecutor).run
}(ctx, h)
return h.ex.run(ctx, s.pool, reserved, cancel)
}
in pkg/sql.(*Server).ServeConn
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#L1593-L1595 in runtime.goexit

pkg/kv/kvclient/kvcoord/txn_interceptor_span_refresher.go in pkg/kv/kvclient/kvcoord.(*txnSpanRefresher).importLeafFinalState at line 687
pkg/kv/kvclient/kvcoord/txn_coord_sender.go in pkg/kv/kvclient/kvcoord.(*TxnCoordSender).UpdateRootWithLeafFinalState at line 1259
pkg/kv/txn.go in pkg/kv.(*Txn).UpdateRootWithLeafFinalState at line 1345
pkg/sql/distsql_running.go in pkg/sql.(*DistSQLReceiver).pushMeta at line 1129
pkg/sql/distsql_running.go in pkg/sql.(*DistSQLReceiver).Push at line 1253
pkg/sql/execinfra/base.go in pkg/sql/execinfra.Run at line 189
pkg/sql/execinfra/processorsbase.go in pkg/sql/execinfra.(*ProcessorBaseNoHelper).Run at line 729
pkg/sql/flowinfra/flow.go in pkg/sql/flowinfra.(*FlowBase).Run at line 480
pkg/sql/colflow/vectorized_flow.go in pkg/sql/colflow.(*vectorizedFlow).Run at line 307
pkg/sql/distsql_running.go in pkg/sql.(*DistSQLPlanner).Run at line 731
pkg/sql/distsql_running.go in pkg/sql.(*DistSQLPlanner).PlanAndRun at line 1698
pkg/sql/distsql_running.go in pkg/sql.(*DistSQLPlanner).PlanAndRunAll at line 1421
pkg/sql/conn_executor_exec.go in pkg/sql.(*connExecutor).execWithDistSQLEngine at line 1587
pkg/sql/conn_executor_exec.go in pkg/sql.(*connExecutor).dispatchToExecutionEngine at line 1201
pkg/sql/conn_executor_exec.go in pkg/sql.(*connExecutor).execStmtInOpenState at line 696
pkg/sql/conn_executor_exec.go in pkg/sql.(*connExecutor).execStmt.func1 at line 131
pkg/sql/conn_executor_exec.go in pkg/sql.(*connExecutor).execWithProfiling at line 2428
pkg/sql/conn_executor_exec.go in pkg/sql.(*connExecutor).execStmt at line 130
pkg/sql/conn_executor_exec.go in pkg/sql.(*connExecutor).execPortal at line 220
pkg/sql/conn_executor.go in pkg/sql.(*connExecutor).execCmd.func2 at line 2050
pkg/sql/conn_executor.go in pkg/sql.(*connExecutor).execCmd at line 2052
pkg/sql/conn_executor.go in pkg/sql.(*connExecutor).run at line 1898
pkg/sql/conn_executor.go in pkg/sql.(*Server).ServeConn at line 857
pkg/sql/pgwire/conn.go in pkg/sql/pgwire.(*conn).processCommandsAsync.func1 at line 728
GOROOT/src/runtime/asm_amd64.s in runtime.goexit at line 1594
Tag Value
Cockroach Release v22.2.6
Cockroach SHA: d5a076f
Platform linux amd64
Distribution CCL
Environment v22.2.6
Command server
Go Version ``
# of CPUs
# of Goroutines

Jira issue: CRDB-25797

@cockroach-teamcity cockroach-teamcity added C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior. O-sentry Originated from an in-the-wild panic report. labels Mar 21, 2023
@cucaroach
Copy link
Contributor

cucaroach commented Mar 22, 2023

GIST:

[email protected]:26257/defaultdb> select crdb_internal.decode_plan_gist('AgGK////nxkAABoAAAADBwoUADACBgEFDgUCBgI=');                                           
          crdb_internal.decode_plan_gist
---------------------------------------------------
  • lookup join
  │ table: comments@primary
  │ equality: (_, _, _) = (type,object_id,sub_id)
  │ equality cols are key
  │
  └── • render
      │
      └── • filter
          │
          └── • virtual table
                table: @primary
(11 rows)

Time: 4ms total (execution 3ms / network 0ms)

@yuzefovich yuzefovich changed the title sentry: txn_interceptor_span_refresher.go:687: log.Fatal: attempting to append refresh spans after the tracked timestamp has moved forward. batchTimestamp: 1679379412.106937991,0 refreshedTimestamp: 167937941... kvclient: v22.2.6: attempting to append refresh spans after the tracked timestamp has moved forward Mar 22, 2023
@blathers-crl blathers-crl bot added the T-sql-queries SQL Queries Team label Mar 22, 2023
@yuzefovich yuzefovich self-assigned this Mar 23, 2023
@craig craig bot closed this as completed in eb45930 Mar 23, 2023
@craig craig bot closed this as completed in #99325 Mar 23, 2023
@mgartner mgartner moved this to Done in SQL Queries Jul 24, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior. O-sentry Originated from an in-the-wild panic report. T-sql-queries SQL Queries Team
Projects
Archived in project
Development

Successfully merging a pull request may close this issue.

3 participants