Closed cockroach-teamcity closed 1 year ago
Weird, the test output here is for a successful test: it ends with predicates checked: all had the same result in SELECT and CHANGEFEED
which is logged in the last line of the test. Wondering if the use of a panic/recover in closeFeedIgnoreError is confusing the test framework, or something about the output looks like an error, or the test was run multiple times and the wrong output was logged? This passes locally using ./dev test
, so it's something specific to how the test ran in bazci.
dev stress perhaps to run this many times? Do we have a test seed printed somewhere to try to repro same run?
I can't deterministically repro this, but running under stress+race is turning up some errors in rpc JSON encoding that are maybe somehow the root cause here?
1:
WARNING: DATA RACE
Write at 0x00c004c162f0 by goroutine 9774:
github.com/cockroachdb/cockroach/pkg/sql/colfetcher.(*ColBatchDirectScan).Release()
github.com/cockroachdb/cockroach/pkg/sql/colfetcher/colbatch_direct_scan.go:147 +0x53
github.com/cockroachdb/cockroach/pkg/sql/colexec/colexecargs.(*NewColOperatorResult).Release()
github.com/cockroachdb/cockroach/pkg/sql/colexec/colexecargs/op_creation.go:139 +0x617
github.com/cockroachdb/cockroach/pkg/sql/colflow.(*vectorizedFlowCreator).Release()
github.com/cockroachdb/cockroach/pkg/sql/colflow/vectorized_flow.go:703 +0x8d0
github.com/cockroachdb/cockroach/pkg/sql/colflow.(*vectorizedFlow).Release()
github.com/cockroachdb/cockroach/pkg/sql/colflow/vectorized_flow.go:352 +0x47
github.com/cockroachdb/cockroach/pkg/sql/colflow.(*vectorizedFlow).Cleanup()
github.com/cockroachdb/cockroach/pkg/sql/colflow/vectorized_flow.go:401 +0x52b
github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLPlanner).Run.func2()
github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:833 +0x61
runtime.deferreturn()
GOROOT/src/runtime/panic.go:476 +0x32
github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLPlanner).PlanAndRun()
github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:1793 +0x2ec
github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLPlanner).PlanAndRunAll()
github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:1544 +0x34b
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execWithDistSQLEngine()
github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:1641 +0xa84
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).dispatchToExecutionEngine()
github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:1262 +0x1624
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execStmtInOpenState()
github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:744 +0x3a91
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execStmt.func1()
github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:130 +0x18e
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execWithProfiling()
github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:2530 +0x50f
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execStmt()
github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:129 +0x6cd
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execPortal()
github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:219 +0x217
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execCmd.func2()
github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:2022 +0xad7
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execCmd()
github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:2024 +0xbd6
github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).run()
github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:1866 +0x424
github.com/cockroachdb/cockroach/pkg/sql.(*InternalExecutor).runWithEx.func1()
github.com/cockroachdb/cockroach/pkg/sql/internal.go:171 +0x117
Previous read at 0x00c004c162f0 by goroutine 388:
reflect.Value.Index()
GOROOT/src/reflect/value.go:1416 +0x1ef
encoding/json.arrayEncoder.encode()
GOROOT/src/encoding/json/encode.go:915 +0xe7
encoding/json.arrayEncoder.encode-fm()
<autogenerated>:1 +0x90
encoding/json.sliceEncoder.encode()
GOROOT/src/encoding/json/encode.go:888 +0x4e2
encoding/json.sliceEncoder.encode-fm()
<autogenerated>:1 +0x90
encoding/json.structEncoder.encode()
GOROOT/src/encoding/json/encode.go:760 +0x2ba
encoding/json.structEncoder.encode-fm()
<autogenerated>:1 +0xdb
encoding/json.ptrEncoder.encode()
GOROOT/src/encoding/json/encode.go:944 +0x3c2
encoding/json.ptrEncoder.encode-fm()
<autogenerated>:1 +0x90
encoding/json.structEncoder.encode()
GOROOT/src/encoding/json/encode.go:760 +0x2ba
encoding/json.structEncoder.encode-fm()
<autogenerated>:1 +0xdb
encoding/json.structEncoder.encode()
GOROOT/src/encoding/json/encode.go:760 +0x2ba
encoding/json.structEncoder.encode-fm()
<autogenerated>:1 +0xdb
encoding/json.ptrEncoder.encode()
GOROOT/src/encoding/json/encode.go:944 +0x3c2
encoding/json.ptrEncoder.encode-fm()
<autogenerated>:1 +0x90
encoding/json.(*encodeState).reflectValue()
GOROOT/src/encoding/json/encode.go:359 +0x88
encoding/json.(*encodeState).marshal()
GOROOT/src/encoding/json/encode.go:331 +0x20b
encoding/json.(*Encoder).Encode()
GOROOT/src/encoding/json/stream.go:206 +0xcf
github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.GRPCTransportFactory.func1()
github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/transport_race.go:120 +0x2c4
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2()
github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:470 +0x1f6
2:
* ERROR: a panic has occurred!
* panic: reflect: slice index out of range
* (1) attached stack trace
* -- stack trace:
* | runtime.gopanic
* | GOROOT/src/runtime/panic.go:890
* | encoding/json.(*encodeState).marshal.func1
* | GOROOT/src/encoding/json/encode.go:327
* | runtime.gopanic
* | GOROOT/src/runtime/panic.go:890
* | reflect.Value.Index
* | GOROOT/src/reflect/value.go:1412
* | encoding/json.arrayEncoder.encode
* | GOROOT/src/encoding/json/encode.go:915
* | encoding/json.sliceEncoder.encode
* | GOROOT/src/encoding/json/encode.go:888
* | encoding/json.structEncoder.encode
* | GOROOT/src/encoding/json/encode.go:760
* | encoding/json.ptrEncoder.encode
* | GOROOT/src/encoding/json/encode.go:944
* | encoding/json.structEncoder.encode
* | GOROOT/src/encoding/json/encode.go:760
* | encoding/json.structEncoder.encode
* | GOROOT/src/encoding/json/encode.go:760
* | encoding/json.ptrEncoder.encode
* | GOROOT/src/encoding/json/encode.go:944
* | encoding/json.(*encodeState).reflectValue
* | GOROOT/src/encoding/json/encode.go:359
* | encoding/json.(*encodeState).marshal
* | GOROOT/src/encoding/json/encode.go:331
* | encoding/json.(*Encoder).Encode
* | GOROOT/src/encoding/json/stream.go:206
* | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.GRPCTransportFactory.func1
* | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/transport_race.go:120
* | github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2
* | github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:470
* | runtime.goexit
* | src/runtime/asm_amd64.s:1594
* Wraps: (2) panic: reflect: slice index out of range
* Error types: (1) *withstack.withStack (2) *errutil.leafError
*
panic: reflect: slice index out of range [recovered]
panic: reflect: slice index out of range [recovered]
panic: reflect: slice index out of range
These stack traces look like they're specific to race builds so possibly unrelated. But surprising to see a panic deep into a standard library.
ccl/changefeedccl.TestChangefeedRandomExpressions failed with artifacts on master @ 639decf058c78f0afe0dba613d60670628c92e81:
changefeed_test.go:923: SELECT array_to_string(IFNULL(array_agg(distinct rowid),'{}'),'|') FROM seed WHERE (((true OR false) OR ((e'\x11':::STRING::STRING || (B'10001010101000111101110010000110011011000101011011111100010110011110101111010101011111'::VARBIT | B'00101101100011010001100011010110110101011011010'::VARBIT)::VARBIT::VARBIT)::STRING NOT ILIKE (st_asgeojson(e'&8\x07':::STRING::STRING, NULL::INT8, (-5254389604683114372):::INT8::INT8)::STRING::STRING || ((-1035320416713543333):::INT8::INT8 // ((-6448369151594613222):::INT8::INT8 * NULL::INT8)::INT8::INT8)::INT8::INT8)::STRING)) AND false)
changefeed_test.go:932: Skipping predicate (((true OR false) OR ((e'\x11':::STRING::STRING || (B'10001010101000111101110010000110011011000101011011111100010110011110101111010101011111'::VARBIT | B'00101101100011010001100011010110110101011011010'::VARBIT)::VARBIT::VARBIT)::STRING NOT ILIKE (st_asgeojson(e'&8\x07':::STRING::STRING, NULL::INT8, (-5254389604683114372):::INT8::INT8)::STRING::STRING || ((-1035320416713543333):::INT8::INT8 // ((-6448369151594613222):::INT8::INT8 * NULL::INT8)::INT8::INT8)::INT8::INT8)::STRING)) AND false) because it returned no rows
changefeed_test.go:923: SELECT array_to_string(IFNULL(array_agg(distinct rowid),'{}'),'|') FROM seed WHERE EXISTS (SELECT B'011010101100110100001101110111011101000000' AS "coL4356" FROM d.public.seed@[0] AS tab1515)
changefeed_test.go:936: Expecting statement CREATE CHANGEFEED WITH schema_change_policy='stop' AS SELECT rowid FROM seed WHERE EXISTS (SELECT B'011010101100110100001101110111011101000000' AS "coL4356" FROM d.public.seed@[0] AS tab1515) to emit 100 events
testfeed_test.go:278: creating external connection
testfeed_test.go:281: ran create external connection
changefeed_test.go:939: Test tolerating create changefeed error: failed to start feed for job 0: pq: sub-query expressions not supported by CDC
helpers_test.go:703: runtime error: invalid memory address or nil pointer dereference
changefeed_test.go:923: SELECT array_to_string(IFNULL(array_agg(distinct rowid),'{}'),'|') FROM seed WHERE 'ffffffff-ffff-ffff-ffff-ffffffffffff':::UUID::UUID NOT IN (SELECT seed._uuid::UUID AS col4381 FROM d.public.seed@[0] AS tab😎1522 WHERE crdb_internal.pretty_key(seed._bytes::BYTES, seed._int2::INT8)::STRING ILIKE seed._string ORDER BY seed._interval DESC NULLS LAST, seed._timestamptz NULLS LAST, seed._bytes ASC NULLS LAST)
changefeed_test.go:927: Skipping query SELECT array_to_string(IFNULL(array_agg(distinct rowid),'{}'),'|') FROM seed WHERE 'ffffffff-ffff-ffff-ffff-ffffffffffff':::UUID::UUID NOT IN (SELECT seed._uuid::UUID AS col4381 FROM d.public.seed@[0] AS tab😎1522 WHERE crdb_internal.pretty_key(seed._bytes::BYTES, seed._int2::INT8)::STRING ILIKE seed._string ORDER BY seed._interval DESC NULLS LAST, seed._timestamptz NULLS LAST, seed._bytes ASC NULLS LAST) because error pq: LIKE regexp compilation failed: LIKE pattern must not end with escape character
changefeed_test.go:923: SELECT array_to_string(IFNULL(array_agg(distinct rowid),'{}'),'|') FROM seed WHERE seed._string NOT LIKE seed._string
changefeed_test.go:927: Skipping query SELECT array_to_string(IFNULL(array_agg(distinct rowid),'{}'),'|') FROM seed WHERE seed._string NOT LIKE seed._string because error pq: LIKE regexp compilation failed: LIKE pattern must not end with escape character
changefeed_test.go:923: SELECT array_to_string(IFNULL(array_agg(distinct rowid),'{}'),'|') FROM seed WHERE EXISTS (SELECT B'000000011010110000011000000011101' AS col4477 FROM d.public.seed@[0] AS "ta b1548" WHERE true)
changefeed_test.go:936: Expecting statement CREATE CHANGEFEED WITH schema_change_policy='stop' AS SELECT rowid FROM seed WHERE EXISTS (SELECT B'000000011010110000011000000011101' AS col4477 FROM d.public.seed@[0] AS "ta b1548" WHERE true) to emit 100 events
testfeed_test.go:278: creating external connection
testfeed_test.go:281: ran create external connection
changefeed_test.go:939: Test tolerating create changefeed error: failed to start feed for job 0: pq: sub-query expressions not supported by CDC
helpers_test.go:703: runtime error: invalid memory address or nil pointer dereference
changefeed_test.go:923: SELECT array_to_string(IFNULL(array_agg(distinct rowid),'{}'),'|') FROM seed WHERE NULL::greeting NOT IN (SELECT 'hi':::greeting::greeting AS 🙃col4480 FROM d.public.seed@[0] AS tab1550 WHERE false ORDER BY seed.tableoid NULLS LAST, seed._timestamp DESC NULLS LAST)
changefeed_test.go:936: Expecting statement CREATE CHANGEFEED WITH schema_change_policy='stop' AS SELECT rowid FROM seed WHERE NULL::greeting NOT IN (SELECT 'hi':::greeting::greeting AS 🙃col4480 FROM d.public.seed@[0] AS tab1550 WHERE false ORDER BY seed.tableoid NULLS LAST, seed._timestamp DESC NULLS LAST) to emit 100 events
testfeed_test.go:278: creating external connection
testfeed_test.go:281: ran create external connection
changefeed_test.go:939: Test tolerating create changefeed error: failed to start feed for job 0: pq: sub-query expressions not supported by CDC
helpers_test.go:703: runtime error: invalid memory address or nil pointer dereference
changefeed_test.go:923: SELECT array_to_string(IFNULL(array_agg(distinct rowid),'{}'),'|') FROM seed WHERE ((NULL AND ((-5652715609055749711):::INT8::INT8 NOT IN ((-1468674142098467087):::INT8, st_numinteriorring(st_multipointfromtext(e'\'':::STRING::STRING, 173716407849516012:::INT8::INT8)::GEOMETRY::GEOMETRY)::INT8, 1178245315123507576:::INT8))) AND true)
changefeed_test.go:932: Skipping predicate ((NULL AND ((-5652715609055749711):::INT8::INT8 NOT IN ((-1468674142098467087):::INT8, st_numinteriorring(st_multipointfromtext(e'\'':::STRING::STRING, 173716407849516012:::INT8::INT8)::GEOMETRY::GEOMETRY)::INT8, 1178245315123507576:::INT8))) AND true) because it returned no rows
changefeed_test.go:923: SELECT array_to_string(IFNULL(array_agg(distinct rowid),'{}'),'|') FROM seed WHERE (seed._bool AND NULL)
changefeed_test.go:932: Skipping predicate (seed._bool AND NULL) because it returned no rows
changefeed_test.go:923: SELECT array_to_string(IFNULL(array_agg(distinct rowid),'{}'),'|') FROM seed WHERE (seed._timestamptz < (seed._timestamptz::TIMESTAMPTZ - '00:00:00':::INTERVAL::INTERVAL)::TIMESTAMPTZ)
changefeed_test.go:932: Skipping predicate (seed._timestamptz < (seed._timestamptz::TIMESTAMPTZ - '00:00:00':::INTERVAL::INTERVAL)::TIMESTAMPTZ) because it returned no rows
changefeed_test.go:923: SELECT array_to_string(IFNULL(array_agg(distinct rowid),'{}'),'|') FROM seed WHERE (seed._string::STRING % seed._string::STRING)::BOOL
changefeed_test.go:936: Expecting statement CREATE CHANGEFEED WITH schema_change_policy='stop' AS SELECT rowid FROM seed WHERE (seed._string::STRING % seed._string::STRING)::BOOL to emit 48 events
testfeed_test.go:278: creating external connection
testfeed_test.go:281: ran create external connection
changefeed_test.go:923: SELECT array_to_string(IFNULL(array_agg(distinct rowid),'{}'),'|') FROM seed WHERE EXISTS (SELECT seed.tableoid AS col4600)
changefeed_test.go:936: Expecting statement CREATE CHANGEFEED WITH schema_change_policy='stop' AS SELECT rowid FROM seed WHERE EXISTS (SELECT seed.tableoid AS col4600) to emit 100 events
testfeed_test.go:278: creating external connection
testfeed_test.go:281: ran create external connection
changefeed_test.go:939: Test tolerating create changefeed error: failed to start feed for job 0: pq: sub-query expressions not supported by CDC
helpers_test.go:703: runtime error: invalid memory address or nil pointer dereference
changefeed_test.go:923: SELECT array_to_string(IFNULL(array_agg(distinct rowid),'{}'),'|') FROM seed WHERE EXISTS (SELECT CASE WHEN seed._bool THEN seed._date ELSE seed._date END AS col4613 FROM d.public.seed AS tab1595 JOIN d.public.seed AS tab1596 ON (tab1595._jsonb) = (tab1596._jsonb))
changefeed_test.go:936: Expecting statement CREATE CHANGEFEED WITH schema_change_policy='stop' AS SELECT rowid FROM seed WHERE EXISTS (SELECT CASE WHEN seed._bool THEN seed._date ELSE seed._date END AS col4613 FROM d.public.seed AS tab1595 JOIN d.public.seed AS tab1596 ON (tab1595._jsonb) = (tab1596._jsonb)) to emit 100 events
testfeed_test.go:278: creating external connection
testfeed_test.go:281: ran create external connection
changefeed_test.go:939: Test tolerating create changefeed error: failed to start feed for job 0: pq: sub-query expressions not supported by CDC
helpers_test.go:703: runtime error: invalid memory address or nil pointer dereference
changefeed_test.go:923: SELECT array_to_string(IFNULL(array_agg(distinct rowid),'{}'),'|') FROM seed WHERE (inet('':::STRING::STRING)::INET::INET >> set_masklen('1315:f15e:350a:92bf:a958:dcce:bc2e:3778/90':::INET::INET, 15441268322837485:::INT8::INT8)::INET::INET)::BOOL
changefeed_test.go:927: Skipping query SELECT array_to_string(IFNULL(array_agg(distinct rowid),'{}'),'|') FROM seed WHERE (inet('':::STRING::STRING)::INET::INET >> set_masklen('1315:f15e:350a:92bf:a958:dcce:bc2e:3778/90':::INET::INET, 15441268322837485:::INT8::INT8)::INET::INET)::BOOL because error pq: inet(): could not parse "" as inet. invalid IP
changefeed_test.go:955: 30 predicates checked: all had the same result in SELECT and CHANGEFEED
--- FAIL: TestChangefeedRandomExpressions/kafka (13.48s)
See also: [How To Investigate a Go Test Failure \(internal\)](https://cockroachlabs.atlassian.net/l/c/HgfXfJgM)
ccl/changefeedccl.TestChangefeedRandomExpressions failed with artifacts on master @ 1d901eeca5c187f9d80fb52f985c1224de57762d:
Help
See also: [How To Investigate a Go Test Failure \(internal\)](https://cockroachlabs.atlassian.net/l/c/HgfXfJgM)
/cc @cockroachdb/cdc
This test on roachdash | Improve this report!
Jira issue: CRDB-23906
Epic CRDB-11732