sql: TestTraceFieldDecomposition failed

[cockroach-teamcity]

sql.TestTraceFieldDecomposition failed on master @ b07e9c2cc91be05a90b1c0f0665da0da4cde2e7a:

    trace_test.go:380: received trace: "rows affected: 0" // "[n1,client=127.0.0.1:56778,hostssl,user=root,intExec=get-plan-hints]" // "sql/conn_executor_exec.go:1081"
    trace_test.go:380: received trace: "[Open pos:3] executing Sync" // "[n1,client=127.0.0.1:56778,hostssl,user=root,intExec=get-plan-hints]" // "sql/conn_executor.go:2332"
    trace_test.go:380: received trace: "=== SPAN START: commit sql txn ===" // "" // ""
    trace_test.go:380: received trace: "AutoCommit. err: <nil>" // "[n1,client=127.0.0.1:56778,hostssl,user=root,intExec=get-plan-hints]" // "sql/conn_executor_exec.go:4113"
    trace_test.go:380: received trace: "releasing 2 descriptors" // "[n1,client=127.0.0.1:56778,hostssl,user=root,intExec=get-plan-hints]" // "sql/catalog/descs/leased_descriptors.go:391"
    trace_test.go:380: received trace: "release: 1(\"system\",01018003f4e8a703944d238e94efb3c5a6d184) ver=1:0,0, refcount=0" // "[n1,client=127.0.0.1:56778,hostssl,user=root,intExec=get-plan-hints]" // "sql/catalog/lease/descriptor_state.go:271"
    trace_test.go:380: received trace: "release: 76(\"statement_hints\",01018003f4e8a703944d238e94efb3c5a6d184) ver=1:0,0, refcount=0" // "[n1,client=127.0.0.1:56778,hostssl,user=root,intExec=get-plan-hints]" // "sql/catalog/lease/descriptor_state.go:271"
    trace_test.go:380: received trace: "finishing connExecutor" // "[n1,client=127.0.0.1:56778,hostssl,user=root,intExec=get-plan-hints]" // "sql/conn_executor.go:1364"
    trace_test.go:380: received trace: "releasing 0 descriptors" // "[n1,client=127.0.0.1:56778,hostssl,user=root,intExec=get-plan-hints]" // "sql/catalog/descs/leased_descriptors.go:391"
    trace_test.go:380: received trace: "finished reading hints for query SELECT _" // "[n1,client=127.0.0.1:56778,hostssl,user=root]" // "sql/hints/hint_cache.go:493"
    trace_test.go:380: received trace: "planning starts: SELECT" // "[n1,client=127.0.0.1:56778,hostssl,user=root]" // "sql/exec_util.go:3024"
    trace_test.go:380: received trace: "=== SPAN START: optimizer ===" // "" // ""
    trace_test.go:380: received trace: "query cache miss" // "[n1,client=127.0.0.1:56778,hostssl,user=root]" // "sql/plan_opt.go:454"
    trace_test.go:380: received trace: "optbuilder start" // "[n1,client=127.0.0.1:56778,hostssl,user=root]" // "sql/opt/optbuilder/builder.go:244"
    trace_test.go:380: received trace: "optbuilder finish" // "[n1,client=127.0.0.1:56778,hostssl,user=root]" // "sql/opt/optbuilder/builder.go:291"
    trace_test.go:380: received trace: "optimize start" // "[n1,client=127.0.0.1:56778,hostssl,user=root]" // "sql/opt/xform/optimizer.go:251"
    trace_test.go:380: received trace: "optimize finish" // "[n1,client=127.0.0.1:56778,hostssl,user=root]" // "sql/opt/xform/optimizer.go:301"
    trace_test.go:380: received trace: "query cache add" // "[n1,client=127.0.0.1:56778,hostssl,user=root]" // "sql/plan_opt.go:454"
    trace_test.go:380: received trace: "planning ends" // "[n1,client=127.0.0.1:56778,hostssl,user=root]" // "sql/conn_executor_exec.go:1081"
    trace_test.go:380: received trace: "checking distributability" // "[n1,client=127.0.0.1:56778,hostssl,user=root]" // "sql/conn_executor_exec.go:1081"
    trace_test.go:380: received trace: "will distribute plan: false" // "[n1,client=127.0.0.1:56778,hostssl,user=root]" // "sql/conn_executor_exec.go:1081"
    trace_test.go:380: received trace: "world" // "[n1,client=127.0.0.1:56778,hostssl,user=root,hello=[::666]]" // "sql_test/trace_test.go:344"
    trace_test.go:380: received trace: "execution starts: distributed engine" // "[n1,client=127.0.0.1:56778,hostssl,user=root]" // "sql/conn_executor_exec.go:1081"
    trace_test.go:380: received trace: "=== SPAN START: consuming rows ===" // "" // ""
    trace_test.go:380: received trace: "creating DistSQL plan with isLocal=true" // "[n1,client=127.0.0.1:56778,hostssl,user=root]" // "sql/distsql_running.go:2324"
    trace_test.go:380: received trace: "noMutations = true" // "[n1,client=127.0.0.1:56778,hostssl,user=root]" // "sql/distsql_running.go:772"
    trace_test.go:380: received trace: "containsLocking = false" // "[n1,client=127.0.0.1:56778,hostssl,user=root]" // "sql/distsql_running.go:822"
    trace_test.go:380: received trace: "must use root txn due to \"values\" wrapped planNode" // "[n1,client=127.0.0.1:56778,hostssl,user=root]" // "sql/distsql_running.go:845"
    trace_test.go:380: received trace: "running DistSQL plan" // "[n1,client=127.0.0.1:56778,hostssl,user=root]" // "sql/distsql_running.go:941"
    trace_test.go:380: received trace: "=== SPAN START: flow ===" // "" // ""
    trace_test.go:380: received trace: "setting up vectorized flow" // "[n1,client=127.0.0.1:56778,hostssl,user=root]" // "sql/colflow/vectorized_flow.go:228"
    trace_test.go:380: received trace: "planning a row-execution processor in the vectorized flow: LocalPlanNode core needs to be wrapped" // "[n1,client=127.0.0.1:56778,hostssl,user=root]" // "sql/colexec/colbuilder/execplan.go:576"
    trace_test.go:380: received trace: "vectorized flow setup succeeded" // "[n1,client=127.0.0.1:56778,hostssl,user=root]" // "sql/colflow/vectorized_flow.go:269"
    trace_test.go:380: received trace: "starting (0 processors, 0 startables) asynchronously" // "[n1,client=127.0.0.1:56778,hostssl,user=root]" // "sql/flowinfra/flow.go:460"
    trace_test.go:380: received trace: "running the batch flow coordinator in the flow's goroutine" // "[n1,client=127.0.0.1:56778,hostssl,user=root]" // "sql/colflow/vectorized_flow.go:316"
    trace_test.go:380: received trace: "=== SPAN START: batch flow coordinator ===" // "" // ""
    trace_test.go:380: received trace: "=== SPAN START: columnarizer ===" // "" // ""
    trace_test.go:380: received trace: "=== SPAN START: values ===" // "" // ""
    trace_test.go:380: received trace: "ComponentStats{ID: {7412f402-ddb2-44e1-a2ec-d781b010450e PROCESSOR 0 1 }, execution time: 153µs, sql cpu time: 153µs, batches output: 1, rows output: 1}" // "" // ""
    trace_test.go:380: received trace: "ComponentStats{ID: {00000000-0000-0000-0000-000000000000 UNSET 0 ? }}" // "" // ""
    trace_test.go:380: received trace: "ComponentStats{ID: {7412f402-ddb2-44e1-a2ec-d781b010450e FLOW 0 1 }}" // "" // ""
    trace_test.go:380: received trace: "execution ends" // "[n1,client=127.0.0.1:56778,hostssl,user=root]" // "sql/conn_executor_exec.go:1081"
    trace_test.go:380: received trace: "rows affected: 1" // "[n1,client=127.0.0.1:56778,hostssl,user=root]" // "sql/conn_executor_exec.go:1081"
    trace_test.go:380: received trace: "=== SPAN START: commit sql txn ===" // "" // ""
    trace_test.go:380: received trace: "AutoCommit. err: <nil>" // "[n1,client=127.0.0.1:56778,hostssl,user=root]" // "sql/conn_executor_exec.go:4113"
    trace_test.go:380: received trace: "releasing 0 descriptors" // "[n1,client=127.0.0.1:56778,hostssl,user=root]" // "sql/catalog/descs/leased_descriptors.go:391"
    trace_test.go:380: received trace: "[NoTxn pos:3] executing Sync" // "[n1,client=127.0.0.1:56778,hostssl,user=root]" // "sql/conn_executor.go:2332"
    trace_test.go:380: received trace: "[NoTxn pos:4] executing ExecStmt: SET TRACING = off" // "[n1,client=127.0.0.1:56778,hostssl,user=root]" // "sql/conn_executor.go:2332"
    trace_test.go:380: received trace: "executing: SET TRACING = off in state: NoTxn" // "[n1,client=127.0.0.1:56778,hostssl,user=root]" // "sql/conn_executor_exec.go:126"
--- FAIL: TestTraceFieldDecomposition/SHOW_TRACE (0.03s)

Parameters:

• attempt=1
• race=true
• run=2
• shard=15

Help

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

This test on roachdash | Improve this report!

Jira issue: CRDB-56421