crosscluster/logical: TestRandomStream failed

[cockroach-teamcity]

crosscluster/logical.TestRandomStream failed on master @ fcf4659dae90ef3d87f8457678b1e6727e3d69b7:

Fatal error:

panic: runtime error: invalid memory address or nil pointer dereference
	(1) attached stack trace
	  -- stack trace:
	  | runtime.gopanic
	  | 	GOROOT/src/runtime/panic.go:783
	  | github.com/cockroachdb/cockroach/pkg/util/ctxgroup.Group.Wait
	  | 	pkg/util/ctxgroup/ctxgroup.go:151
	  | github.com/cockroachdb/cockroach/pkg/crosscluster/logical.(*logicalReplicationWriterProcessor).close
	  | 	pkg/crosscluster/logical/logical_replication_writer_processor.go:461
	  | github.com/cockroachdb/cockroach/pkg/crosscluster/logical.(*logicalReplicationWriterProcessor).ConsumerClosed
	  | 	pkg/crosscluster/logical/logical_replication_writer_processor.go:437
	  | github.com/cockroachdb/cockroach/pkg/sql/execinfra.(*ProcessorBaseNoHelper).Close
	  | 	pkg/sql/execinfra/processorsbase.go:779
	  | github.com/cockroachdb/cockroach/pkg/sql/flowinfra.(*FlowBase).Cleanup
	  | 	pkg/sql/flowinfra/flow.go:678
	  | github.com/cockroachdb/cockroach/pkg/sql/rowflow.(*rowBasedFlow).Cleanup
	  | 	pkg/sql/rowflow/row_based_flow.go:490
	  | github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLPlanner).Run.func3
	  | 	pkg/sql/distsql_running.go:1003
	  | runtime.gopanic
	  | 	GOROOT/src/runtime/panic.go:783
	  | github.com/cockroachdb/cockroach/pkg/util/log/logcrash.ReportOrPanic
	  | 	pkg/util/log/logcrash/crash_reporting.go:434
	  | github.com/cockroachdb/cockroach/pkg/crosscluster/logical.(*logicalReplicationWriterProcessor).Next
	  | 	pkg/crosscluster/logical/logical_replication_writer_processor.go:397
	  | github.com/cockroachdb/cockroach/pkg/sql/execinfra.Run
	  | 	pkg/sql/execinfra/base.go:193
	  | github.com/cockroachdb/cockroach/pkg/sql/execinfra.(*ProcessorBaseNoHelper).Run
	  | 	pkg/sql/execinfra/processorsbase.go:766
	  | github.com/cockroachdb/cockroach/pkg/sql/flowinfra.(*FlowBase).Run
	  | 	pkg/sql/flowinfra/flow.go:574
	  | github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLPlanner).Run
	  | 	pkg/sql/distsql_running.go:1068
	  | github.com/cockroachdb/cockroach/pkg/crosscluster/logical.(*logicalReplicationResumer).ingest.func7
	  | 	pkg/crosscluster/logical/logical_replication_job.go:332
	  | [...repeated from below...]
	Wraps: (2) attached stack trace
	  -- stack trace:
	  | runtime.gopanic
	  | 	GOROOT/src/runtime/panic.go:783
	  | runtime.panicmem
	  | 	GOROOT/src/runtime/panic.go:262
	  | runtime.sigpanic
	  | 	GOROOT/src/runtime/signal_unix.go:925
	  | github.com/cockroachdb/cockroach/pkg/crosscluster/logical.getColumnSchema
	  | 	pkg/crosscluster/logical/replication_statements.go:42
	  | github.com/cockroachdb/cockroach/pkg/crosscluster/logical.newEventDecoder.func1
	  | 	pkg/crosscluster/logical/event_decoder.go:82
	  | github.com/cockroachdb/cockroach/pkg/sql.(*InternalDB).DescsTxn.func1
	  | 	pkg/sql/internal.go:1955
	  | github.com/cockroachdb/cockroach/pkg/sql.(*InternalDB).txn.func4
	  | 	pkg/sql/internal.go:2052
	  | github.com/cockroachdb/cockroach/pkg/kv.(*Txn).exec
	  | 	pkg/kv/txn.go:1139
	  | github.com/cockroachdb/cockroach/pkg/kv.runTxn
	  | 	pkg/kv/db.go:1114
	  | github.com/cockroachdb/cockroach/pkg/kv.(*DB).TxnWithAdmissionControl
	  | 	pkg/kv/db.go:1077
	  | github.com/cockroachdb/cockroach/pkg/kv.(*DB).Txn
	  | 	pkg/kv/db.go:1052
	  | github.com/cockroachdb/cockroach/pkg/sql.(*InternalDB).txn
	  | 	pkg/sql/internal.go:2039
	  | github.com/cockroachdb/cockroach/pkg/sql.(*InternalDB).DescsTxn
	  | 	pkg/sql/internal.go:1953
	  | github.com/cockroachdb/cockroach/pkg/crosscluster/logical.newEventDecoder
	  | 	pkg/crosscluster/logical/event_decoder.go:75
	  | github.com/cockroachdb/cockroach/pkg/crosscluster/logical.newCrudSqlWriter
	  | 	pkg/crosscluster/logical/sql_crud_writer.go:51
	  | github.com/cockroachdb/cockroach/pkg/crosscluster/logical.(*logicalReplicationWriterProcessor).setupBatchHandlers
	  | 	pkg/crosscluster/logical/logical_replication_writer_processor.go:729
	  | github.com/cockroachdb/cockroach/pkg/crosscluster/logical.(*logicalReplicationWriterProcessor).flushBuffer
	  | 	pkg/crosscluster/logical/logical_replication_writer_processor.go:785
	  | github.com/cockroachdb/cockroach/pkg/crosscluster/logical.(*logicalReplicationWriterProcessor).handleStreamBuffer
	  | 	pkg/crosscluster/logical/logical_replication_writer_processor.go:646
	  | github.com/cockroachdb/cockroach/pkg/crosscluster/logical.(*logicalReplicationWriterProcessor).handleEvent
	  | 	pkg/crosscluster/logical/logical_replication_writer_processor.go:529
	  | github.com/cockroachdb/cockroach/pkg/crosscluster/logical.(*logicalReplicationWriterProcessor).consumeEvents
	  | 	pkg/crosscluster/logical/logical_replication_writer_processor.go:502
	  | github.com/cockroachdb/cockroach/pkg/crosscluster/logical.(*logicalReplicationWriterProcessor).Start.func2.1
	  | 	pkg/crosscluster/logical/logical_replication_writer_processor.go:359
	  | github.com/cockroachdb/cockroach/pkg/util/pprofutil.Do
	  | 	pkg/util/pprofutil/labels.go:38
	  | github.com/cockroachdb/cockroach/pkg/crosscluster/logical.(*logicalReplicationWriterProcessor).Start.func2
	  | 	pkg/crosscluster/logical/logical_replication_writer_processor.go:358
	  | github.com/cockroachdb/cockroach/pkg/crosscluster/logical.(*logicalReplicationWriterProcessor).Start.Group.GoCtx.func10
	  | 	pkg/util/ctxgroup/ctxgroup.go:200
	  | golang.org/x/sync/errgroup.(*Group).Go.func1
	  | 	external/org_golang_x_sync/errgroup/errgroup.go:93
	  | runtime.goexit
	  | 	src/runtime/asm_amd64.s:1693
	Wraps: (3) runtime error: invalid memory address or nil pointer dereference
	Error types: (1) *withstack.withStack (2) *withstack.withStack (3) runtime.errorString
	panic: found 1 short-living non-stopped monitors in internal-planner.resume-job-1134799122344574977
	internal-planner.resume-job-1134799122344574977 0 B
	    flow-95f64f6d 0 B
	

Stack:

goroutine 30267 [running]:
github.com/cockroachdb/cockroach/pkg/util/mon.(*BytesMonitor).doStop(0xc00cfa8210, {0x8abdf40, 0xc00a917360}, 0x1)
	pkg/util/mon/bytes_usage.go:781 +0x653
github.com/cockroachdb/cockroach/pkg/util/mon.(*BytesMonitor).Stop(...)
	pkg/util/mon/bytes_usage.go:722
github.com/cockroachdb/cockroach/pkg/sql.newInternalPlanner.func1()
	pkg/sql/planner.go:521 +0x5f
panic({0x720d940?, 0xc0119e7e60?})
	GOROOT/src/runtime/panic.go:783 +0x132
github.com/cockroachdb/cockroach/pkg/util/ctxgroup.Group.Wait({0xc0086b7b40?, {0x8abbd20?, 0xc00be9c0f0?}, 0xc009a53278?})
	pkg/util/ctxgroup/ctxgroup.go:151 +0xbb
github.com/cockroachdb/cockroach/pkg/util/ctxgroup.GoAndWait({0x8abbd58?, 0xc001d95320?}, {0xc002c0f068, 0x4, 0x8abbad0?})
	pkg/util/ctxgroup/ctxgroup.go:224 +0x11d
github.com/cockroachdb/cockroach/pkg/crosscluster/logical.(*logicalReplicationResumer).ingest(0xc00a6178d8, {0x8abbd58, 0xc001d95320}, {0x8b2d350, 0xc00158d130})
	pkg/crosscluster/logical/logical_replication_job.go:368 +0x15aa
github.com/cockroachdb/cockroach/pkg/crosscluster/logical.(*logicalReplicationResumer).ingestWithRetries(0xc00a6178d8, {0x8abbd58, 0xc001d95320}, {0x8b2d350, 0xc00158d130})
	pkg/crosscluster/logical/logical_replication_job.go:932 +0x23a
github.com/cockroachdb/cockroach/pkg/crosscluster/logical.(*logicalReplicationResumer).Resume(0xc00a6178d8, {0x8abbd58, 0xc001d95320}, {0x7634320?, 0xc00158d130})
	pkg/crosscluster/logical/logical_replication_job.go:115 +0x11e
github.com/cockroachdb/cockroach/pkg/jobs.(*Registry).stepThroughStateMachine.func2(0xc003225980?, 0x0?, 0xc00973f8e0, {0x8a907a0?, 0xc00a6178d8?}, {0x8abbd58?, 0xc001d95320?}, {0x7634320?, 0xc00158d130?})
	pkg/jobs/registry.go:1647 +0xb4
github.com/cockroachdb/cockroach/pkg/jobs.(*Registry).stepThroughStateMachine(0xc0083aa008, {0x8abdf40, 0xc00a917400}, {0x7634320, 0xc00158d130}, {0x8a907a0, 0xc00a6178d8}, 0xc003225980, {0xc005aa4412, 0x7}, ...)
	pkg/jobs/registry.go:1648 +0xb7f
github.com/cockroachdb/cockroach/pkg/jobs.(*Registry).runJob(0xc0083aa008, {0x8abdf40, 0xc00a917400}, {0x8a907a0, 0xc00a6178d8}, 0xc003225980, {0xc005aa4412, 0x7}, {0xc009977e48, 0x17})
	pkg/jobs/adopt.go:418 +0x4f9
github.com/cockroachdb/cockroach/pkg/jobs.(*Registry).resumeJob.func1({0x8abdf40?, 0xc00a917220?})
	pkg/jobs/adopt.go:271 +0x13c
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func1({0x8abdf40, 0xc00a917220})
	pkg/util/stop/stopper.go:440 +0x8a
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx in goroutine 30032
	pkg/util/stop/stopper.go:438 +0x125

Log preceding fatal error

=== RUN   TestRandomStream
    test_log_scope.go:171: test logs captured to: outputs.zip/logTestRandomStream347743445
    test_log_scope.go:82: use -show-logs to present logs inline
    test_server_shim.go:182: automatically injected a shared process virtual cluster under test; see comment at top of test_server_shim.go for details.
    logical_replication_job_test.go:1007: waiting for 100 events

Parameters:

• attempt=1
• run=4
• shard=4

Help

See also: How To Investigate a Go Test Failure (internal)

Same failure on other branches

• crosscluster/logical: TestRandomStream failed #159971 crosscluster/logical: TestRandomStream failed [A-disaster-recovery C-test-failure O-robot T-disaster-recovery branch-release-26.1 release-blocker]

/cc @cockroachdb/disaster-recovery

This test on roachdash | Improve this report!

Jira issue: CRDB-58111

[jeffswenson]

@fqazi this seems to be caused by #159162. I'm able to reproduce this on engflow ~1/100 runs and I'm no longer able to reproduce it when I set "sql.catalog.descriptor_lease.use_locked_timestamps.enabled = false".

For some reason I was unable to reproduce this on my mac or on the gceworker. It only reproduces on engflow. I also tried to create a minimal reproduction of what I think is happening, but that test does not reproduce the bug: #160090.

The thing that is causing the TestRandomStream to fail is we are calling GetLeasedImmutableTableByID with the descriptor ID of a table that we never drop, and we are getting nil, nil back from the catalog. I augmented the test with logging and confirmed its the descriptor id we expect and the context is not cancelled.

Reading through the code, I think this is the bug we are seeing:

1. If use_locked_timestamps is enabled, we adjust the read timestamp to be the the time supplied by the most recent range feed checkpoint.
2. It is possible that replicationTS comes before the transaction that created the descriptor we try to read.
3. That causes tc.leased.getByID to return (nil, shouldReadFromStore: true, nil) since the underlying Acquire returns no found.
4. GetLeasedImmutableTableByID would then return (nil, nil), which triggers the nil panic.

I think its questionable whether GetLeasedImmutableTableByID should be used by LDR, but this seems to be used by DistSQL when hydrating a descriptor in the child flows, so if its a problem for LDR its also a problem for DistSQL.

[jeffswenson]

Though it looks like the distsql caller is ignoring the error and only branches based on whether leased != nil, which is kind of weird. So maybe this only impacts the crud writer

cockroach/pkg/sql/execinfra/flow_context.go

Line 133 in 47465f9

leased, _ := flowCtx.Descriptors.GetLeasedImmutableTableByID(ctx, flowCtx.Txn, desc.ID)

.

[fqazi]

@jeffswenson Let me look into this one