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

sql: span use-after-Finish in "batch flow coordinator" #75425

Closed
andreimatei opened this issue Jan 23, 2022 · 7 comments · Fixed by #75479 or #76084
Closed

sql: span use-after-Finish in "batch flow coordinator" #75425

andreimatei opened this issue Jan 23, 2022 · 7 comments · Fixed by #75479 or #76084
Assignees
Labels
C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior. T-cdc

Comments

@andreimatei
Copy link
Contributor

#75424 adds some more span use-after-Finish detection. With that patch, the streamproducer package immediately finds a violation. The span that's being used after having been Finish() ed is the batch flow coordinator one.

@yuzefovich will you please help me with this? :)

COCKROACH_DEBUG_SPAN_USE_AFTER_FINISH=true make test PKG=./pkg/ccl/streamingccl/streamproducer

The span was finished at:

panic: use of Span after Finish. Span: batch flow coordinator. Finish previously called at: goroutine 13453 [running]:
runtime/debug.Stack()
        /home/andrei/goroot/src/runtime/debug/stack.go:24 +0x65
github.com/cockroachdb/cockroach/pkg/util/tracing.(*Span).finishInternal(0xc0043f3500)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/util/tracing/span.go:256 +0x73
github.com/cockroachdb/cockroach/pkg/util/tracing.(*Span).Finish(0x517be20)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/util/tracing/span.go:247 +0x19
github.com/cockroachdb/cockroach/pkg/sql/colflow.(*BatchFlowCoordinator).Run(0xc002e36dc0, {0x5208c88, 0xc001289f40})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/colflow/flow_coordinator.go:287 +0x477
github.com/cockroachdb/cockroach/pkg/sql/colflow.(*vectorizedFlow).Run(0xc00367cbe0, {0x5208c88, 0xc001289f40}, 0x1)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/colflow/vectorized_flow.go:259 +0x1d9
github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLPlanner).Run(0xc0059deb00, 0xc00271ae10, 0xc0005f0000, 0xc003ddcc80, 0xc002caf500, 0xc000c4cf08, 0x0)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:563 +0xb56
github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLPlanner).PlanAndRun(0x5208d30, {0x5208d30, 0xc004749a70}, 0x1, 0xc00271ae10, 0xc003ab26a8, {{0x520a818, 0xc0043154a0}, 0x0}, 0xc002caf500)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:1401 +0x191
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execWithDistSQLEngine(0xc000c4c600, {0x5208d30, 0xc004749a70}, 0xc000c4cc48, 0xc004749a70, {0x7fb1f693bdf8, 0xc003ab26a8}, 0x0, 0xc004315498)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:1408 +0x5f4
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).dispatchToExecutionEngine(0xc000c4c600, {0x5208d30, 0xc004749a70}, 0xc000c4cc48, {0x7fb1f693bdf8, 0xc003ab26a8})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:1085 +0x9c7
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execStmtInOpenState(0xc000c4c600, {0x5208d30, 0xc004749a70}, {{0x52370f8, 0xc0018c5090}, {0xc0042360bc, 0x34}, 0x2, 0x0}, 0xc003bc1700, ...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:722 +0x2526
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execStmt(0xc000c4c600, {0x5208d30, 0xc004749a10}, {{0x52370f8, 0xc0018c5090}, {0xc0042360bc, 0x34}, 0x2, 0x0}, 0xc003bc1700, ...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:135 +0x572
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execPortal(0xc000c4c600, {0x5208d30, 0xc004749a10}, {0xc003bc1700, {0xc002a979c0, 0x2, 0x2}, {0xc0044809ac, 0x1, 0x1}, ...}, ...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:222 +0x158
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execCmd.func2({{0xc00423614c, 0x0}, 0x0, {0x2657b1f3, 0xed97f7562, 0x0}}, 0xc000c4c600, 0xc0043a1a38, 0xc0043a1a28, 0xc0043a1948, ...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:1820 +0x511
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execCmd(0xc000c4c600, {0x5208c88, 0xc001289d40})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:1822 +0x43a
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).run(0xc000c4c600, {0x5208c88, 0xc001136ec0}, 0xc0012a14a0, {0xc00375de10, 0x4201fd, 0xc00420b220}, 0xc005881ee0)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:1676 +0x285
github.com/cockroachdb/cockroach/pkg/sql.(*Server).ServeConn(0xc003ab2000, {0x5208c88, 0xc001136ec0}, {0xc004892300}, {0x3, 0xc001287ca0, 0xc00420b220}, 0xc000854048)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:681 +0x9a
github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*conn).processCommandsAsync.func1()
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/pgwire/conn.go:669 +0x2f5

and later used at:

github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).closeWrapper(0xc000c4c600, {0x5208c88, 0xc001136ec0}, {0x39dcd60, 0xc0051c83d0})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:975 +0x1a5
github.com/cockroachdb/cockroach/pkg/sql.(*Server).ServeConn.func1()
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:679 +0x53
panic({0x39dcd60, 0xc0051c83d0})
        /home/andrei/goroot/src/runtime/panic.go:1038 +0x215
github.com/cockroachdb/cockroach/pkg/util/tracing.(*Span).detectUseAfterFinish(0x5208d30)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/util/tracing/span.go:183 +0x134
github.com/cockroachdb/cockroach/pkg/util/tracing.(*Span).Tracer(...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/util/tracing/span.go:226
github.com/cockroachdb/cockroach/pkg/util/log.getSpanOrEventLog({0x5208d30, 0xc004749f20})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/util/log/trace.go:92 +0x54
github.com/cockroachdb/cockroach/pkg/util/log.logfDepth({0x5208d30, 0xc004749f20}, 0x1, 0x3, 0x0, {0x412c79f, 0x2c}, {0xc00439f948, 0x2, 0x2})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/util/log/channels.go:55 +0x2a8
github.com/cockroachdb/cockroach/pkg/util/log.Errorf(...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/util/log/log_channels_generated.go:640
github.com/cockroachdb/cockroach/pkg/ccl/streamingccl/streamproducer.(*eventStream).Close(0xc001b0c600, {0x5208d30, 0xc004749f20})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/ccl/streamingccl/streamproducer/event_stream.go:207 +0x136
github.com/cockroachdb/cockroach/pkg/sql/rowexec.(*projectSetProcessor).close(0xc004d50a00)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/rowexec/project_set.go:291 +0x9a
github.com/cockroachdb/cockroach/pkg/sql/rowexec.(*projectSetProcessor).ConsumerClosed(0xc0043f3858)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/rowexec/project_set.go:299 +0x19
github.com/cockroachdb/cockroach/pkg/sql/execinfra.(*ProcessorBaseNoHelper).InternalClose(0xc000701c00)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/execinfra/processorsbase.go:911 +0x149
github.com/cockroachdb/cockroach/pkg/sql/colexec.(*Columnarizer).Close(0xc00439fa58)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/colexec/columnarizer.go:296 +0x30
github.com/cockroachdb/cockroach/pkg/sql/colexec.(*invariantsChecker).Close(0xc001289f40)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/colexec/invariants_checker.go:135 +0x35
github.com/cockroachdb/cockroach/pkg/sql/colflow.(*vectorizedFlowCreator).setupFlow.func1.1.1()
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/colflow/vectorized_flow.go:1139 +0x58
github.com/cockroachdb/cockroach/pkg/sql/colflow.(*callbackCloser).Close(0xc000ce7900)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/colflow/vectorized_flow.go:1047 +0x1a
github.com/cockroachdb/cockroach/pkg/sql/colflow.(*BatchFlowCoordinator).close(0xc002e36dc0)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/colflow/flow_coordinator.go:335 +0x8f
github.com/cockroachdb/cockroach/pkg/sql/colflow.(*BatchFlowCoordinator).Run.func1()
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/colflow/flow_coordinator.go:260 +0x2b
github.com/cockroachdb/cockroach/pkg/sql/colflow.(*BatchFlowCoordinator).Run(0xc002e36dc0, {0x5208c88, 0xc001289f40})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/colflow/flow_coordinator.go:287 +0x498
github.com/cockroachdb/cockroach/pkg/sql/colflow.(*vectorizedFlow).Run(0xc00367cbe0, {0x5208c88, 0xc001289f40}, 0x1)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/colflow/vectorized_flow.go:259 +0x1d9
github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLPlanner).Run(0xc0059deb00, 0xc00271ae10, 0xc0005f0000, 0xc003ddcc80, 0xc002caf500, 0xc000c4cf08, 0x0)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:563 +0xb56
github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLPlanner).PlanAndRun(0x5208d30, {0x5208d30, 0xc004749a70}, 0x1, 0xc00271ae10, 0xc003ab26a8, {{0x520a818, 0xc0043154a0}, 0x0}, 0xc002caf500)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:1401 +0x191
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execWithDistSQLEngine(0xc000c4c600, {0x5208d30, 0xc004749a70}, 0xc000c4cc48, 0xc004749a70, {0x7fb1f693bdf8, 0xc003ab26a8}, 0x0, 0xc004315498)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:1408 +0x5f4
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).dispatchToExecutionEngine(0xc000c4c600, {0x5208d30, 0xc004749a70}, 0xc000c4cc48, {0x7fb1f693bdf8, 0xc003ab26a8})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:1085 +0x9c7
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execStmtInOpenState(0xc000c4c600, {0x5208d30, 0xc004749a70}, {{0x52370f8, 0xc0018c5090}, {0xc0042360bc, 0x34}, 0x2, 0x0}, 0xc003bc1700, ...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:722 +0x2526
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execStmt(0xc000c4c600, {0x5208d30, 0xc004749a10}, {{0x52370f8, 0xc0018c5090}, {0xc0042360bc, 0x34}, 0x2, 0x0}, 0xc003bc1700, ...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:135 +0x572
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execPortal(0xc000c4c600, {0x5208d30, 0xc004749a10}, {0xc003bc1700, {0xc002a979c0, 0x2, 0x2}, {0xc0044809ac, 0x1, 0x1}, ...}, ...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:222 +0x158
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execCmd.func2({{0xc00423614c, 0x0}, 0x0, {0x2657b1f3, 0xed97f7562, 0x0}}, 0xc000c4c600, 0xc0043a1a38, 0xc0043a1a28, 0xc0043a1948, ...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:1820 +0x511
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execCmd(0xc000c4c600, {0x5208c88, 0xc001289d40})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:1822 +0x43a
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).run(0xc000c4c600, {0x5208c88, 0xc001136ec0}, 0xc0012a14a0, {0xc00375de10, 0x4201fd, 0xc00420b220}, 0xc005881ee0)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:1676 +0x285
github.com/cockroachdb/cockroach/pkg/sql.(*Server).ServeConn(0xc003ab2000, {0x5208c88, 0xc001136ec0}, {0xc004892300}, {0x3, 0xc001287ca0, 0xc00420b220}, 0xc000854048)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:681 +0x9a
github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*conn).processCommandsAsync.func1()
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/pgwire/conn.go:669 +0x2f5
created by github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*conn).processCommandsAsync
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/pgwire/conn.go:597 +0x273

interestingly, if I run a race test, I get a different scenario, but for the same span:

COCKROACH_DEBUG_SPAN_USE_AFTER_FINISH=true make testrace PKG=./pkg/ccl/streamingccl/streamproducer
panic: use of Span after Finish. Span: batch flow coordinator. Finish previously called at: goroutine 6725 [running]:
runtime/debug.Stack()
        /home/andrei/goroot/src/runtime/debug/stack.go:24 +0x72
github.com/cockroachdb/cockroach/pkg/util/tracing.(*Span).finishInternal(0xc002789b00)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/util/tracing/span.go:256 +0xff
github.com/cockroachdb/cockroach/pkg/util/tracing.(*Span).Finish(0xc0048f4d50)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/util/tracing/span.go:247 +0x2f
github.com/cockroachdb/cockroach/pkg/sql/colflow.(*BatchFlowCoordinator).Run(0xc00284d340, {0x8ef49c8, 0xc00449c0c0})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/colflow/flow_coordinator.go:287 +0x4f6
github.com/cockroachdb/cockroach/pkg/sql/colflow.(*vectorizedFlow).Run(0xc001b6c180, {0x8ef49c8, 0xc00449c0c0}, 0x1)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/colflow/vectorized_flow.go:259 +0x329
github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLPlanner).Run(0xc004447100, 0xc00303f1d0, 0xc00284d970, 0xc003385300, 0xc0045ace00, 0xc002330210, 0x0)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:563 +0xf95
github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLPlanner).PlanAndRun(0x8ef4a70, {0x8ef4a70, 0xc002f4a750}, 0x1, 0xc00303f1d0, 0xc000e1d100, {{0x8ef6210, 0xc003384f80}, 0x0}, 0xc0045ace00)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:1401 +0x24a
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execWithDistSQLEngine(0xc00232f900, {0x8ef4a70, 0xc002f4a750}, 0xc00232ff50, 0xc002f4a750, {0x7f38053493f8, 0xc000e1d128}, 0x0, 0xc002fd7978)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:1408 +0xcec
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).dispatchToExecutionEngine(0xc00232f900, {0x8ef4a70, 0xc002f4a750}, 0xc00232ff50, {0x7f38053493f8, 0xc000e1d128})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:1085 +0x12c5
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execStmtInOpenState(0xc00232f900, {0x8ef4a70, 0xc002f4a750}, {{0x8f22e38, 0xc0005efa20}, {0xc003a290bc, 0x27}, 0x0, 0x0}, 0xc0004e9000, ...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:722 +0x342b
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execStmt(0xc00232f900, {0x8ef4a70, 0xc002f4a6f0}, {{0x8f22e38, 0xc0005efa20}, {0xc003a290bc, 0x27}, 0x0, 0x0}, 0xc0004e9000, ...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:135 +0x93d
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execPortal(0xc00232f900, {0x8ef4a70, 0xc002f4a6f0}, {0xc0004e9000, {0xc334738, 0x0, 0x0}, {0xc0031b270a, 0x3, 0x3}, ...}, ...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:222 +0x1dd
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execCmd.func2({{0xc003a2910c, 0x0}, 0x0, {0x16c2802b, 0xed97f75fa, 0x0}}, 0xc00232f900, 0xc0048f7810, 0xc0048f7800, 0xc0047135d8, ...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:1820 +0xa1d
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execCmd(0xc00232f900, {0x8ef49c8, 0xc00177ff80})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:1822 +0x6f9
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).run(0xc00232f900, {0x8ef49c8, 0xc000eddb80}, 0xc003173d68, {0x5f94a14, 0x0, 0xc0007701e0}, 0xc0028d72e0)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:1676 +0x5ff
github.com/cockroachdb/cockroach/pkg/sql.(*Server).ServeConn(0xc00442dc00, {0x8ef49c8, 0xc000eddb80}, {0xc00442dc00}, {0x3, 0xc005a8cbb1, 0xc0007701e0}, 0xc00070a1b0)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:681 +0x14c
github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*conn).processCommandsAsync.func1()
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/pgwire/conn.go:669 +0x406
created by github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*conn).processCommandsAsync
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/pgwire/conn.go:597 +0x405


goroutine 6695 [running]:
github.com/cockroachdb/cockroach/pkg/util/tracing.(*Span).detectUseAfterFinish(0xc002789b00)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/util/tracing/span.go:183 +0x245
github.com/cockroachdb/cockroach/pkg/util/tracing.(*Span).Tracer(...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/util/tracing/span.go:226
github.com/cockroachdb/cockroach/pkg/util/log.getSpanOrEventLog({0x8ef4a70, 0xc002f4ab70})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/util/log/trace.go:92 +0x65
github.com/cockroachdb/cockroach/pkg/util/log.vEventf({0x8ef4a70, 0xc002f4ab70}, 0x0, 0x1, 0x303f0e18, {0x606798b, 0x36}, {0xc0046ac638, 0x1, 0x1})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/util/log/trace.go:206 +0x125
github.com/cockroachdb/cockroach/pkg/util/log.VEventf(...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/util/log/trace.go:232
github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLReceiver).SetError(0xc0045a0700, {0x8e63e00, 0xc00019c280})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:912 +0x18d
github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLReceiver).pushMeta(0xc0045a0700, 0xc000472540)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:959 +0xa88
github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLReceiver).Push(0xc0045a0700, {0x0, 0x0, 0x0}, 0xc000472540)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:1047 +0x4d6
github.com/cockroachdb/cockroach/pkg/sql/rowflow.(*copyingRowReceiver).Push(0xc0045a0e00, {0x0, 0x0, 0x0}, 0x0)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/rowflow/row_based_flow.go:454 +0x2d6
github.com/cockroachdb/cockroach/pkg/sql/execinfra.Run({0x8ef4a70, 0xc005c36870}, {0x8f1b078, 0xc000294a80}, {0x8e860d8, 0xc0045a0e00})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/execinfra/base.go:189 +0x86
github.com/cockroachdb/cockroach/pkg/sql/execinfra.(*ProcessorBaseNoHelper).Run(0xc000294a80, {0x8ef49c8, 0xc005e1df40})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/execinfra/processorsbase.go:733 +0xeb
github.com/cockroachdb/cockroach/pkg/sql/flowinfra.(*FlowBase).Run(0xc002497380, {0x8ef49c8, 0xc005e1df40}, 0x0)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/flowinfra/flow.go:453 +0x42a
github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLPlanner).Run(0xc004447100, 0xc002d90a50, 0x0, 0xc004f47998, 0xc0045a0700, 0xc003a08c00, 0x0)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:563 +0xf95
github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl/changefeeddist.StartDistChangefeed({0x8ef4a70, 0xc002f4ab70}, {0x8f7c338, 0xc00232ff50}, 0x0, {0x0, {0x0, 0x0}, 0xc005c36600, {0x16ccf2677d60748d, ...}}, ...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl/changefeeddist/distflow.go:144 +0xa28
github.com/cockroachdb/cockroach/pkg/ccl/streamingccl/streamproducer.streamKVs({0x8ef4a70, 0xc002f4ab70}, {0x8fdcd60, 0xc00232ff50}, {0x5a3678, 0x5a3f2c, 0x0}, {0xc005c365d0, 0x1, 0x1}, ...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/ccl/streamingccl/streamproducer/replication_stream_planning.go:105 +0x3fb
github.com/cockroachdb/cockroach/pkg/ccl/streamingccl/streamproducer.doCreateReplicationStream({0x8ef4a70, 0xc002f4ab70}, {0x8fdcd60, 0xc00232ff50}, 0xc003d265d0, 0x0)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/ccl/streamingccl/streamproducer/replication_stream_planning.go:164 +0x7f5
github.com/cockroachdb/cockroach/pkg/ccl/streamingccl/streamproducer.createReplicationStreamHook.func1({0x8ef4a70, 0xc002f4ab70}, {0x499537, 0x496761, 0xc00356c7d0}, 0xe2451e)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/ccl/streamingccl/streamproducer/replication_stream_planning.go:202 +0x6f
github.com/cockroachdb/cockroach/pkg/sql.(*hookFnNode).startExec.func1()
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/planhook.go:148 +0xec
created by github.com/cockroachdb/cockroach/pkg/sql.(*hookFnNode).startExec
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/planhook.go:147 +0x1d3
FAIL    github.com/cockroachdb/cockroach/pkg/ccl/streamingccl/streamproducer    5.650s
@andreimatei andreimatei added the C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior. label Jan 23, 2022
@blathers-crl blathers-crl bot added the T-sql-queries SQL Queries Team label Jan 23, 2022
@andreimatei
Copy link
Contributor Author

I think this problem is detected as #75334 when span reuse is enabled.

@andreimatei
Copy link
Contributor Author

Thanks for the help! But unfortunately it would appear that there's still some problem, even after #75479 :(. But hopefully whatever is still wrong is similar to what you've fixed before.
With the same #75424 patched in as before (rebased on your previous fix), both the streamproducer and the streamclient packages fail immediately under stress (in 1 run).
#75424 doesn't really do anything new, btw, it just make some use-after-Finishes panic even when the respective query is not traced, whereas without it they would only panic if the respective query is traced verbosely.

The failures look like this (first stack is where the span is Finished(), the second one is the access after Finish()):

COCKROACH_DEBUG_SPAN_USE_AFTER_FINISH=true make stress TESTFLAGS="-v" 
PKG=./pkg/ccl/streamingccl/streamproducer
...
=== RUN   TestReplicationStreamTenant/stream-tenant-with-cursor
panic: use of Span after Finish. Span: batch flow coordinator. Finish previously called at: goroutine 3602 [running]:
runtime/debug.Stack()
        /home/andrei/goroot/src/runtime/debug/stack.go:24 +0x65
github.com/cockroachdb/cockroach/pkg/util/tracing.(*Span).finishInternal(0xc004354000)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/util/tracing/span.go:256 +0x73
github.com/cockroachdb/cockroach/pkg/util/tracing.(*Span).Finish(...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/util/tracing/span.go:247
github.com/cockroachdb/cockroach/pkg/sql/colflow.(*BatchFlowCoordinator).Run.func1()
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/colflow/flow_coordinator.go:276 +0x77
github.com/cockroachdb/cockroach/pkg/sql/colflow.(*BatchFlowCoordinator).Run(0xc000b17ef0, {0x52282c8, 0xc004818700})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/colflow/flow_coordinator.go:291 +0x3ee
github.com/cockroachdb/cockroach/pkg/sql/colflow.(*vectorizedFlow).Run(0xc002b41540, {0x52282c8, 0xc004818700}, 0x1)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/colflow/vectorized_flow.go:259 +0x1d9
github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLPlanner).Run(0xc002b8bc00, 0xc0015a9950, 0xc002741550, 0xc0038fff80, 0xc002852000, 0xc001c3a200, 0x0)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:563 +0xb56
github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLPlanner).PlanAndRun(0x5228370, {0x5228370, 0xc003f812c0}, 0x1, 0xc0015a9950, 0xc002d95128, {{0x5229b10, 0xc0038ff380}, 0x0}, 0xc002852000)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:1401 +0x191
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execWithDistSQLEngine(0xc001c39900, {0x5228370, 0xc003f812c0}, 0xc001c39f40, 0xc003f812c0, {0x7f27b0cc78f8, 0xc002d95128}, 0x0, 0xc0022f7d38)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:1396 +0x5f4
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).dispatchToExecutionEngine(0xc001c39900, {0x5228370, 0xc003f812c0}, 0xc001c39f40, {0x7f27b0cc78f8, 0xc002d95128})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:1073 +0x9c7
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execStmtInOpenState(0xc001c39900, {0x5228370, 0xc003f812c0}, {{0x5256558, 0xc002740dc0}, {0xc000cad0bc, 0x27}, 0x0, 0x0}, 0xc002ae5600, ...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:710 +0x2446
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execStmt(0xc001c39900, {0x5228370, 0xc003f81260}, {{0x5256558, 0xc002740dc0}, {0xc000cad0bc, 0x27}, 0x0, 0x0}, 0xc002ae5600, ...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:136 +0x57e
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execPortal(0xc001c39900, {0x5228370, 0xc003f81260}, {0xc002ae5600, {0x7a42a50, 0x0, 0x0}, {0xc002065658, 0x3, 0x3}, ...}, ...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:224 +0x16e
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execCmd.func2({{0xc000cad10c, 0x0}, 0x0, {0x2b0fd826, 0xed983cd1e, 0x0}, 0x1}, 0xc001c39900, 0xc000d0ba30, 0xc000d0ba20, ...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:1831 +0x531
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execCmd(0xc001c39900, {0x52282c8, 0xc004818540})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:1833 +0x452
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).run(0xc001c39900, {0x52282c8, 0xc0046ba540}, 0xc0031c1da0, {0xc003a07e10, 0x4201fd, 0xc002efa6e0}, 0xc004135950)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:1676 +0x285
github.com/cockroachdb/cockroach/pkg/sql.(*Server).ServeConn(0xc002d94a80, {0x52282c8, 0xc0046ba540}, {0xc001702a00}, {0x3, 0xc002065140, 0xc002efa6e0}, 0xc0005b1cc8)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:681 +0x9a
github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*conn).processCommandsAsync.func1()
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/pgwire/conn.go:680 +0x2f5
created by github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*conn).processCommandsAsync
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/pgwire/conn.go:608 +0x273


goroutine 3609 [running]:
github.com/cockroachdb/cockroach/pkg/util/tracing.(*Span).detectUseAfterFinish(0x5228370)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/util/tracing/span.go:183 +0x134
github.com/cockroachdb/cockroach/pkg/util/tracing.(*Span).Tracer(...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/util/tracing/span.go:226
github.com/cockroachdb/cockroach/pkg/util/log.getSpanOrEventLog({0x5228370, 0xc003f815c0})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/util/log/trace.go:92 +0x54
github.com/cockroachdb/cockroach/pkg/util/log.vEventf({0x5228370, 0xc003f815c0}, 0x0, 0x1, 0xf10d30, {0x417cddf, 0x36}, {0xc000f10d48, 0x1, 0x1})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/util/log/trace.go:206 +0xff
github.com/cockroachdb/cockroach/pkg/util/log.VEventf(...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/util/log/trace.go:232
github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLReceiver).SetError(0xc002853500, {0x51980e0, 0xc000198280})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:912 +0x16d
github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLReceiver).pushMeta(0xc002853500, 0xc000466460)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:959 +0x2c5
github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLReceiver).Push(0xc002853500, {0x0, 0x52da9e8, 0xc0053a8b58}, 0xc003a12800)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:1047 +0x29c
github.com/cockroachdb/cockroach/pkg/sql/rowflow.(*copyingRowReceiver).Push(0xc0053a8a80, {0x0, 0x3, 0x0}, 0x100)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/rowflow/row_based_flow.go:454 +0x18b
github.com/cockroachdb/cockroach/pkg/sql/execinfra.Run({0x5228370, 0xc003f81920}, {0x524e7d8, 0xc0053a8a80}, {0x51b9bb8, 0xc001733180})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/execinfra/base.go:189 +0x86
github.com/cockroachdb/cockroach/pkg/sql/execinfra.(*ProcessorBaseNoHelper).Run(0xc0053a8a80, {0x52282c8, 0xc004818940})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/execinfra/processorsbase.go:733 +0x5b
github.com/cockroachdb/cockroach/pkg/sql/flowinfra.(*FlowBase).Run(0xc003bce4e0, {0x52282c8, 0xc004818940}, 0x0)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/flowinfra/flow.go:453 +0x258
github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLPlanner).Run(0xc002b8bc00, 0xc0015a9a40, 0x0, 0xc003a07bf8, 0xc002853500, 0xc004e14000, 0x0)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:563 +0xb56
github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl/changefeeddist.StartDistChangefeed({0x5228370, 0xc003f815c0}, {0x52aec98, 0xc001c39f40}, 0x0, {0x0, {0x0, 0x0}, 0xc003f816b0, {0x16cdf51cb6107eef, ...}}, ...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl/changefeeddist/distflow.go:144 +0x78e
github.com/cockroachdb/cockroach/pkg/ccl/streamingccl/streamproducer.streamKVs({0x5228370, 0xc003f815c0}, {0x530e860, 0xc001c39f40}, {0x462b13, 0x453636, 0x0}, {0xc003f81680, 0x1, 0x1}, ...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/ccl/streamingccl/streamproducer/replication_stream_planning.go:105 +0x365
github.com/cockroachdb/cockroach/pkg/ccl/streamingccl/streamproducer.doCreateReplicationStream({0x5228370, 0xc003f815c0}, {0x530e860, 0xc001c39f40}, 0xc00346e960, 0xc001b8a3c8)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/ccl/streamingccl/streamproducer/replication_stream_planning.go:164 +0x4b3
github.com/cockroachdb/cockroach/pkg/ccl/streamingccl/streamproducer.createReplicationStreamHook.func1({0x5228370, 0xc003f815c0}, {0x0, 0x0, 0xc001728fd0}, 0x3653392)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/ccl/streamingccl/streamproducer/replication_stream_planning.go:202 +0x2f
github.com/cockroachdb/cockroach/pkg/sql.(*hookFnNode).startExec.func1()
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/planhook.go:148 +0x5b
created by github.com/cockroachdb/cockroach/pkg/sql.(*hookFnNode).startExec
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/planhook.go:147 +0x145

and streamclient:

COCKROACH_DEBUG_SPAN_USE_AFTER_FINISH=true make stress TESTFLAGS="-v"  PKG=./pkg/ccl/streamingccl/streamclient  
...
=== RUN   TestSinklessReplicationClient/stream-address-disconnects
panic: use of Span after Finish. Span: batch flow coordinator. Finish previously called at: goroutine 1713 [running]:
runtime/debug.Stack()
        /home/andrei/goroot/src/runtime/debug/stack.go:24 +0x65
github.com/cockroachdb/cockroach/pkg/util/tracing.(*Span).finishInternal(0xc0053d2900)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/util/tracing/span.go:256 +0x73
github.com/cockroachdb/cockroach/pkg/util/tracing.(*Span).Finish(...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/util/tracing/span.go:247
github.com/cockroachdb/cockroach/pkg/sql/colflow.(*BatchFlowCoordinator).Run.func1()
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/colflow/flow_coordinator.go:276 +0x77
github.com/cockroachdb/cockroach/pkg/sql/colflow.(*BatchFlowCoordinator).Run(0xc00359bd90, {0x51b7b28, 0xc0026f1580})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/colflow/flow_coordinator.go:291 +0x3ee
github.com/cockroachdb/cockroach/pkg/sql/colflow.(*vectorizedFlow).Run(0xc0033541e0, {0x51b7b28, 0xc0026f1580}, 0x1)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/colflow/vectorized_flow.go:259 +0x1d9
github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLPlanner).Run(0xc001273600, 0xc000fe8ff0, 0xc0055ac9a0, 0xc000c21100, 0xc0044a0380, 0xc001e04200, 0x0)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:563 +0xb56
github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLPlanner).PlanAndRun(0x51b7bd0, {0x51b7bd0, 0xc003b62d80}, 0x1, 0xc000fe8ff0, 0xc00336dba8, {{0x51b9338, 0xc000c20580}, 0x0}, 0xc0044a0380)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:1401 +0x191
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execWithDistSQLEngine(0xc001e03900, {0x51b7bd0, 0xc003b62d80}, 0xc001e03f40, 0xc003b62d80, {0x7f5055476c38, 0xc00336dba8}, 0x0, 0xc001a7d258)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:1396 +0x5f4
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).dispatchToExecutionEngine(0xc001e03900, {0x51b7bd0, 0xc003b62d80}, 0xc001e03f40, {0x7f5055476c38, 0xc00336dba8})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:1073 +0x9c7
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execStmtInOpenState(0xc001e03900, {0x51b7bd0, 0xc003b62d80}, {{0x51e5c18, 0xc0055ac8f0}, {0xc005390032, 0x54}, 0x0, 0x0}, 0x0, ...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:710 +0x2446
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execStmt(0xc001e03900, {0x51b7bd0, 0xc003b62c90}, {{0x51e5c18, 0xc0055ac8f0}, {0xc005390032, 0x54}, 0x0, 0x0}, 0x0, ...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:136 +0x57e
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execCmd.func1({{{0x51e5c18, 0xc0055ac8f0}, {0xc005390032, 0x54}, 0x0, 0x0}, {0x8bcee25, 0xed983cf04, 0x0}, {0x8bcf1c9, ...}, ...}, ...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:1753 +0x2b0
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execCmd(0xc001e03900, {0x51b7b28, 0xc0026f1440})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:1757 +0xc10
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).run(0xc001e03900, {0x51b7b28, 0xc0026f0680}, 0xc000e9e900, {0xc005c45e10, 0x4201fd, 0xc0011e7ea0}, 0xc00074f4f0)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:1676 +0x285
github.com/cockroachdb/cockroach/pkg/sql.(*Server).ServeConn(0xc00336d500, {0x51b7b28, 0xc0026f0680}, {0xc0003df100}, {0x3, 0xc0046c73d0, 0xc0011e7ea0}, 0xc0005cc918)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:681 +0x9a
github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*conn).processCommandsAsync.func1()
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/pgwire/conn.go:680 +0x2f5
created by github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*conn).processCommandsAsync
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/pgwire/conn.go:608 +0x273


goroutine 1778 [running]:
github.com/cockroachdb/cockroach/pkg/util/tracing.(*Span).detectUseAfterFinish(0x51b7bd0)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/util/tracing/span.go:183 +0x134
github.com/cockroachdb/cockroach/pkg/util/tracing.(*Span).Tracer(...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/util/tracing/span.go:226
github.com/cockroachdb/cockroach/pkg/util/log.getSpanOrEventLog({0x51b7bd0, 0xc003b638c0})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/util/log/trace.go:92 +0x54
github.com/cockroachdb/cockroach/pkg/util/log.vEventf({0x51b7bd0, 0xc003b638c0}, 0x0, 0x1, 0x2656d30, {0x41167c0, 0x36}, {0xc002656d48, 0x1, 0x1})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/util/log/trace.go:206 +0xff
github.com/cockroachdb/cockroach/pkg/util/log.VEventf(...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/util/log/trace.go:232
github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLReceiver).SetError(0xc002787500, {0x5128dc0, 0xc0000f4290})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:912 +0x16d
github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLReceiver).pushMeta(0xc002787500, 0xc003e30930)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:959 +0x2c5
github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLReceiver).Push(0xc002787500, {0x0, 0x52696a8, 0xc0021e95d8}, 0xc003f4bc00)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:1047 +0x29c
github.com/cockroachdb/cockroach/pkg/sql/rowflow.(*copyingRowReceiver).Push(0xc0021e9500, {0x0, 0x3, 0x0}, 0x100)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/rowflow/row_based_flow.go:454 +0x18b
github.com/cockroachdb/cockroach/pkg/sql/execinfra.Run({0x51b7bd0, 0xc002c5c2d0}, {0x51dde98, 0xc0021e9500}, {0x514a3f0, 0xc00326a700})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/execinfra/base.go:189 +0x86
github.com/cockroachdb/cockroach/pkg/sql/execinfra.(*ProcessorBaseNoHelper).Run(0xc0021e9500, {0x51b7b28, 0xc0026f1780})
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/execinfra/processorsbase.go:733 +0x5b
github.com/cockroachdb/cockroach/pkg/sql/flowinfra.(*FlowBase).Run(0xc002820000, {0x51b7b28, 0xc0026f1780}, 0x0)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/flowinfra/flow.go:453 +0x258
github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLPlanner).Run(0xc001273600, 0xc000fe91d0, 0x0, 0xc004f8bbf8, 0xc002787500, 0xc0053d2c00, 0x0)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:563 +0xb56
github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl/changefeeddist.StartDistChangefeed({0x51b7bd0, 0xc003b638c0}, {0x523dd98, 0xc001e03f40}, 0x0, {0x0, {0x0, 0x0}, 0xc003b63d70, {0x16cdf58db8cad9c5, ...}}, ...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl/changefeeddist/distflow.go:144 +0x78e
github.com/cockroachdb/cockroach/pkg/ccl/streamingccl/streamproducer.streamKVs({0x51b7bd0, 0xc003b638c0}, {0x529d460, 0xc001e03f40}, {0x0, 0x1ea4000, 0xc0}, {0xc003b63d10, 0x1, 0x1}, ...)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/ccl/streamingccl/streamproducer/replication_stream_planning.go:105 +0x365
github.com/cockroachdb/cockroach/pkg/ccl/streamingccl/streamproducer.doCreateReplicationStream({0x51b7bd0, 0xc003b638c0}, {0x529d460, 0xc001e03f40}, 0xc000340060, 0xc00074f4f0)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/ccl/streamingccl/streamproducer/replication_stream_planning.go:164 +0x4b3
github.com/cockroachdb/cockroach/pkg/ccl/streamingccl/streamproducer.createReplicationStreamHook.func1({0x51b7bd0, 0xc003b638c0}, {0x0, 0x33205e0, 0xc0046c7444}, 0xc00000fd70)
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/ccl/streamingccl/streamproducer/replication_stream_planning.go:202 +0x2f
github.com/cockroachdb/cockroach/pkg/sql.(*hookFnNode).startExec.func1()
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/planhook.go:148 +0x5b
created by github.com/cockroachdb/cockroach/pkg/sql.(*hookFnNode).startExec
        /home/andrei/src/github.com/cockroachdb/cockroach/pkg/sql/planhook.go:147 +0x145

@andreimatei andreimatei reopened this Jan 26, 2022
@yuzefovich
Copy link
Member

Alright, I'll take another look. Previously, I didn't try running #75424 with the original fix since I thought I saw the problem clearly.

What's confusing to me on the first glance is that we have a mix of the vectorized and row-based flows in the stack traces.

@yuzefovich
Copy link
Member

I see what the problem is.

First, we have a vectorized flow that is created in order to evaluate the query CREATE REPLICATION STREAM FOR TENANT. During evaluation of the query we create a replication stream that runs in a separate row-based flow. Notably, that flow outlives the vectorized flow that created it, and we set the context on the DistSQLReceiver for the row-based flow with the tracing span created by the vectorized flow. It's not surprising then that after the vectorized flow exits and finishes the tracing span it created, because the row-based flow keeps on running, it might find the span in the context and might try to use it (I think it is only applicable to error propagation into the DistSQLReceiver because the row-based flow itself derived a separate tracing span for its lifetime).

Now the question is what do we do about this. We could derive a new context with a separate span in it with something like:

diff --git a/pkg/ccl/changefeedccl/changefeeddist/distflow.go b/pkg/ccl/changefeedccl/changefeeddist/distflow.go
index 4efe9675b3..ea609c60cc 100644
--- a/pkg/ccl/changefeedccl/changefeeddist/distflow.go
+++ b/pkg/ccl/changefeedccl/changefeeddist/distflow.go
@@ -15,11 +15,13 @@ import (
        "github.com/cockroachdb/cockroach/pkg/kv"
        "github.com/cockroachdb/cockroach/pkg/roachpb"
        "github.com/cockroachdb/cockroach/pkg/sql"
+       "github.com/cockroachdb/cockroach/pkg/sql/execinfra"
        "github.com/cockroachdb/cockroach/pkg/sql/execinfrapb"
        "github.com/cockroachdb/cockroach/pkg/sql/physicalplan"
        "github.com/cockroachdb/cockroach/pkg/sql/sem/tree"
        "github.com/cockroachdb/cockroach/pkg/sql/types"
        "github.com/cockroachdb/cockroach/pkg/util/hlc"
+       "github.com/cockroachdb/cockroach/pkg/util/tracing"
 )
 
 // ChangefeedResultTypes is the types returned by changefeed stream.
@@ -43,6 +45,9 @@ func StartDistChangefeed(
 ) error {
        // Changefeed flows handle transactional consistency themselves.
        var noTxn *kv.Txn
+       var span *tracing.Span
+       ctx, span = execinfra.ProcessorSpan(ctx, "dist-changefeed")
+       defer span.Finish()
 
        dsp := execCtx.DistSQLPlanner()
        evalCtx := execCtx.ExtendedEvalContext()

We'll then need to do a similar trick in other places where one flow creates another flow that outlives its creator. I'm not sure whether there is a more principled way to do this, but I'll push this issue back to you Andrei to talk with CDC team on what to do.

@yuzefovich yuzefovich assigned andreimatei and unassigned yuzefovich Jan 27, 2022
@blathers-crl blathers-crl bot added the T-cdc label Jan 27, 2022
@blathers-crl
Copy link

blathers-crl bot commented Jan 27, 2022

cc @cockroachdb/cdc

@yuzefovich
Copy link
Member

Note that #75479 did fix an actual problem in the infrastructure owned by the SQL Queries, now it seems that we need to fix things in the users of that infrastructure.

@andreimatei
Copy link
Contributor Author

Fixing in #76084

craig bot pushed a commit that referenced this issue Feb 7, 2022
76084: sql: run planHooks in a new tracing span r=andreimatei a=andreimatei

For some reason, plan hooks run in a new goroutine; that goroutine
communicates results through a channel, that's adapted to look like a
planNode by the hookFnNode. Before this patch, that goroutine was
capturing the caller's ctx, and hence the caller's tracing span. This
was leading to span-use-after-Finish because the goroutine in question
was sometimes outliving the caller. Although not written anywhere, I
think the expectation is that generally the goroutine will not outlive
the the hookFnNode by much, since hookFnNode.Next() is supposed to be
consumed fully. Still, at the very least, there were races related to
ctx cancellation, as the hookFnNode listens for cancellation in parallel
with the goroutine running (which is probably a bad idea).

This patch fixes ths span use-after-finish by giving the goroutine a new
span. I took the opportunity to give all the plan hooks names, and use
that as the span name. Since these hooks are all weirdos, it seems like
a good idea to particularly reflect them in the trace, regardless of the
bug that's being fixed.

Fixes #75425

Release note: None

76178: roachtest: add new pgjdbc passing tests r=rafiss a=rafiss

fixes #76061

Release note: None

Co-authored-by: Andrei Matei <andrei@cockroachlabs.com>
Co-authored-by: Rafi Shamim <rafi@cockroachlabs.com>
@craig craig bot closed this as completed in f83f8ab Feb 7, 2022
@exalate-issue-sync exalate-issue-sync bot removed the T-sql-queries SQL Queries Team label Jun 16, 2022
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. T-cdc
Projects
None yet
3 participants