cockroachdb / cockroachdb/cockroach

basalt-26.3.2-rc-20260908: testutils/sqlutils: TestInjectDescriptors failed

Open
#174,983 4 comments 0 reactions 0 assignees View on GitHub
branch-basalt-26.3.2-rc-20260908 C-test-failure O-robot T-sql-queries
Dominant language
Go
Stars
32.5k
Forks
4.1k
PR merge metrics
PR metrics pending

Description

testutils/sqlutils.TestInjectDescriptors [failed](https://mesolite.cluster.engflow.com/invocations/default/4e6b3e4b-4f3a-4ae0-ac38-acabe7fa7d66?testReportRun=3&testReportShard=1&testReportAttempt=1#targets-Ly9wa2cvdGVzdHV0aWxzL3NxbHV0aWxzOnNxbHV0aWxzX3Rlc3Q=) on basalt-26.3.2-rc-20260908 @ [807558e5e81666af257c811e925e4cae570abc28](https://github.com/cockroachdb/cockroach/commits/807558e5e81666af257c811e925e4cae570abc28):

```
I260910 11:38:28.615398 18 3@pebble/obsolete_files.go:122 [T1,Vsystem,n1,s1,r96/1:/Tenant/10/Table/4{5-6}] 22096 [JOB 8] MANIFEST deleted 000621
I260910 11:38:28.615621 18 3@pebble/obsolete_files.go:101 [T1,Vsystem,n1,s1,r96/1:/Tenant/10/Table/4{5-6}] 22097 [JOB 8] sstable deleted 000723
I260910 11:38:28.618724 18 3@pebble/obsolete_files.go:122 [T1,Vsystem,n1,s1,r92/1:/Tenant/10/Table/2{5-6}] 22098 [JOB 12] MANIFEST deleted 000314
I260910 11:38:28.618947 18 3@pebble/obsolete_files.go:101 [T1,Vsystem,n1,s1,r92/1:/Tenant/10/Table/2{5-6}] 22099 [JOB 12] sstable deleted 000313
I260910 11:38:28.619162 18 3@pebble/obsolete_files.go:101 [T1,Vsystem,n1,s1,r92/1:/Tenant/10/Table/2{5-6}] 22100 [JOB 12] sstable deleted 000315
I260910 11:38:28.620022 18 3@pebble/obsolete_files.go:122 [T1,Vsystem,n1,s1,r98/1:/Tenant/10/Table/4{7-8}] 22101 [JOB 8] MANIFEST deleted 000829
I260910 11:38:28.620245 18 3@pebble/obsolete_files.go:101 [T1,Vsystem,n1,s1,r98/1:/Tenant/10/Table/4{7-8}] 22102 [JOB 8] sstable deleted 000927
I260910 11:38:28.621678 18 3@pebble/obsolete_files.go:122 [T1,Vsystem,n1,s1,r104/1:/Tenant/10/Table/6{1-2}] 22103 [JOB 8] MANIFEST deleted 001043
I260910 11:38:28.622621 492 13@kv/kvserver/store_range_flusher.go:778 [T1,Vsystem,n1,s1] 22104 range flusher: queued=1 (33 KiB) flushing=0 completed=0 noop=0 failed=0 disabled=0 since last scan, cumulative-flushed=21 MiB approx-store-local=1.4 MiB
I260910 11:38:28.703200 492 13@kv/kvserver/store_range_flusher.go:778 [T1,Vsystem,n1,s1] 22105 range flusher: queued=1 (33 KiB) flushing=0 completed=0 noop=0 failed=0 disabled=0 since last scan, cumulative-flushed=21 MiB approx-store-local=1.4 MiB
I260910 11:38:28.798837 18 3@pebble/obsolete_files.go:101 [T1,Vsystem,n1,s1,r104/1:/Tenant/10/Table/6{1-2}] 22106 [JOB 8] sstable deleted 001131
I260910 11:38:28.800100 18 3@pebble/obsolete_files.go:122 [T1,Vsystem,n1,s1,r93/1:/Tenant/10/Table/2{6-7}] 22107 [JOB 9] MANIFEST deleted 000317
I260910 11:38:28.800371 18 3@pebble/obsolete_files.go:101 [T1,Vsystem,n1,s1,r93/1:/Tenant/10/Table/2{6-7}] 22108 [JOB 9] sstable deleted 000415
I260910 11:38:28.801607 18 3@pebble/obsolete_files.go:122 [T1,Vsystem,n1,s1,r105/1:/Tenant/10/Table/6{2-3}] 22109 [JOB 11] MANIFEST deleted 001234
I260910 11:38:28.801812 18 3@pebble/obsolete_files.go:101 [T1,Vsystem,n1,s1,r105/1:/Tenant/10/Table/6{2-3}] 22110 [JOB 11] sstable deleted 001235
I260910 11:38:28.945752 492 13@kv/kvserver/store_range_flusher.go:778 [T1,Vsystem,n1,s1] 22111 range flusher: queued=1 (33 KiB) flushing=0 completed=0 noop=0 failed=0 disabled=0 since last scan, cumulative-flushed=21 MiB approx-store-local=1.4 MiB
I260910 11:38:28.946660 21 3@storage/multi_compaction_scheduler.go:689 [T1,Vsystem,n1] 22112 compaction scheduler stats: grants(log=0 state=12 range-shared=12 range-flusher=14) running=3/3(log=0 state=3 range-shared=0 range-flusher=0) awaiting-finish(log=0 state=0 range-shared=0 range-flusher=0) range-shared: engines=75 heap=0
I260910 11:38:28.960637 142032 3@pebble/event.go:1377 [n1,s1,pebble] 22113 [JOB 728] compacted(default) L0 [000540] (5.3KB) Score=64.87 + L6 [000535] (46KB) Score=0.00 -> L6 [000544(48KB)] (48KB), in 0.8s (0.8s total), output rate 62KB/s
I260910 11:38:29.026809 492 13@kv/kvserver/store_range_flusher.go:778 [T1,Vsystem,n1,s1] 22114 range flusher: queued=0 (0 B) flushing=1 completed=0 noop=0 failed=0 disabled=0 since last scan, cumulative-flushed=21 MiB approx-store-local=1.4 MiB
I260910 11:38:29.097770 142087 3@kv/kvserver/replica_manifest_committer.go:800 [T1,Vsystem,n1,s1,r105/1:/Tenant/10/Table/{63-84}] 22115 RangeFlush: SSTs 1, sst size 3004, data size 4592, Points 49, RangeDels 0
I260910 11:38:29.132047 492 13@kv/kvserver/store_range_flusher.go:778 [T1,Vsystem,n1,s1] 22116 range flusher: queued=0 (0 B) flushing=1 completed=0 noop=0 failed=0 disabled=0 since last scan, cumulative-flushed=21 MiB approx-store-local=1.4 MiB
I260910 11:38:29.197359 142072 3@pebble/event.go:1377 [n1,s1,pebble] 22117 [JOB 731] compacted(default) L0 [000542] (92KB) Score=64.52 + L6 [000537] (243KB) Score=0.00 -> L6 [000546(239KB)] (239KB), in 0.8s (0.8s total), output rate 313KB/s
I260910 11:38:29.217244 18 server/server_controller.go:380 [T1,Vsystem,n1] 22118 server controller shutting down
I260910 11:38:29.217484 18 server/server_controller.go:389 [T1,Vsystem,n1] 22119 waiting for tenant servers to report stopped
I260910 11:38:29.389573 492 13@kv/kvserver/store_range_flusher.go:778 [T1,Vsystem,n1,s1] 22120 range flusher: queued=0 (0 B) flushing=1 completed=0 noop=0 failed=0 disabled=0 since last scan, cumulative-flushed=21 MiB approx-store-local=1.4 MiB
I260910 11:38:29.420825 5532 2@util/log/event_log.go:90 [T10,Vtest-tenant,nsql1] 22121 ={"Timestamp":1789040309420814284,"EventType":"runtime_stats","MemRSSBytes":3562123264,"GoroutineCount":611,"MemStackSysBytes":17661952,"GoAllocBytes":1113861832,"GoTotalBytes":1333740088,"HeapFragmentBytes":21344568,"HeapReservedBytes":151732224,"HeapReleasedBytes":12312576,"CGoAllocBytes":462560,"CGoTotalBytes":2916352,"CGoCallRate":0.19999076,"CPUUserPercent":66.696915,"CPUSysPercent":4.8997736,"GCRunCount":71,"NetHostRecvBytes":234227,"NetHostSendBytes":234227}
I260910 11:38:29.421447 5532 2@server/status/runtime_log.go:43 [T10,Vtest-tenant,nsql1] 22122 runtime stats: 3.3 GiB RSS, 611 goroutines (stacks: 17 MiB), 1.0 GiB/1.2 GiB Go alloc/total (heap fragmentation: 20 MiB, heap reserved: 145 MiB, heap released: 12 MiB), 452 KiB/2.8 MiB CGO alloc/total (0.2 CGO/sec), 66.7/4.9 %(u/s)time, 0.0 %gc (71x), 229 KiB/229 KiB (r/w)net
I260910 11:38:29.672583 492 13@kv/kvserver/store_range_flusher.go:778 [T1,Vsystem,n1,s1] 22123 range flusher: queued=0 (0 B) flushing=1 completed=0 noop=0 failed=0 disabled=0 since last scan, cumulative-flushed=21 MiB approx-store-local=1.4 MiB
I260910 11:38:29.954422 492 13@kv/kvserver/store_range_flusher.go:778 [T1,Vsystem,n1,s1] 22124 range flusher: queued=0 (0 B) flushing=1 completed=0 noop=0 failed=0 disabled=0 since last scan, cumulative-flushed=21 MiB approx-store-local=1.4 MiB
I260910 11:38:29.974811 142087 3@pebble/ingest.go:1212 [T1,Vsystem,n1,s1,r105/1:/Tenant/10/Table/{63-84}] 22125 [JOB 49] ingesting: sstable created 001465
I260910 11:38:29.975603 142087 3@pebble/version_set.go:1034 [T1,Vsystem,n1,s1,r105/1:/Tenant/10/Table/{63-84}] 22126 [JOB 49] MANIFEST created 001466
I260910 11:38:29.975868 142087 15@kv/kvserver/replica_manifest_committer.go:229 [T1,Vsystem,n1,s1,r105/1:/Tenant/10/Table/{63-84}] 22127 RangeFlush r105: manifest-num 001466 files 1
I260910 11:38:29.997919 142087 3@pebble/ingest.go:2666 [T1,Vsystem,n1,s1,r105/1:/Tenant/10/Table/{63-84}] 22128 [JOB 49] ingested L0:001465 (2.9KB); manifest update took 0.0s; block reads took 0.0s with 1.9KB block bytes read
I260910 11:38:29.998486 142087 13@kv/kvserver/store_range_flusher.go:857 [T1,Vsystem,n1] 22129 range flush completed for r105 (no-data=false, approx 33 KiB queued)
I260910 11:38:29.998980 142134 3@pebble/obsolete_files.go:122 [T1,Vsystem,n1,s1,r105/1:/Tenant/10/Table/{63-84}] 22130 [JOB 49] MANIFEST deleted 001462
I260910 11:38:29.999585 142135 3@pebble/compaction.go:2543 [T1,Vsystem,n1,s1,r105/1:/Tenant/10/Table/{63-84}] 22131 [JOB 53] compacting(default) L0 [001465] (2.9KB) Score=100.00 + L6 [001463] (22KB) Score=0.00; OverlappingRatio: Single 7.51, Multi 0.00
I260910 11:38:30.000564 142135 3@pebble/compaction.go:3353 [T1,Vsystem,n1,s1,r105/1:/Tenant/10/Table/{63-84}] 22132 [JOB 53] compacting: sstable created 000014
I260910 11:38:30.010548 142135 3@pebble/version_set.go:1034 [T1,Vsystem,n1,s1,r105/1:/Tenant/10/Table/{63-84}] 22133 [JOB 53] MANIFEST created 001468
I260910 11:38:30.050267 142135 3@pebble/compaction.go:2705 [T1,Vsystem,n1,s1,r105/1:/Tenant/10/Table/{63-84}] 22134 [JOB 53] compacted(default) L0 [001465] (2.9KB) Score=100.00 + L6 [001463] (22KB) Score=0.00 -> L6 [001467(24KB)] (24KB), in 0.0s (0.1s total), output rate 2.3MB/s
I260910 11:38:30.052392 142144 3@pebble/obsolete_files.go:101 [T1,Vsystem,n1,s1,r105/1:/Tenant/10/Table/{63-84}] 22135 [JOB 53] sstable deleted 001465
I260910 11:38:30.052786 142142 3@pebble/obsolete_files.go:122 [T1,Vsystem,n1,s1,r105/1:/Tenant/10/Table/{63-84}] 22136 [JOB 53] MANIFEST deleted 001464
I260910 11:38:30.053077 142143 3@pebble/obsolete_files.go:101 [T1,Vsystem,n1,s1,r105/1:/Tenant/10/Table/{63-84}] 22137 [JOB 53] sstable deleted 001463
I260910 11:38:30.080687 492 13@kv/kvserver/store_range_flusher.go:778 [T1,Vsystem,n1,s1] 22138 range flusher: queued=0 (0 B) flushing=0 completed=1 noop=0 failed=0 disabled=0 since last scan, cumulative-flushed=21 MiB approx-store-local=1.3 MiB
I260910 11:38:30.599952 492 13@kv/kvserver/store_range_flusher.go:778 [T1,Vsystem,n1,s1] 22139 range flusher: queued=0 (0 B) flushing=0 completed=0 noop=0 failed=0 disabled=0 since last scan, cumulative-flushed=21 MiB approx-store-local=1.3 MiB
W260910 11:38:30.613117 5666 2@rpc/clock_offset.go:392 [T10,Vtest-tenant,nsql1,rnode=1,raddr=127.0.0.1:42727,class=rangefeed,rpc] 22140 latency jump (prev avg 1036.86ms, current 2490.15ms)
I260910 11:38:30.719095 492 13@kv/kvserver/store_range_flusher.go:778 [T1,Vsystem,n1,s1] 22141 range flusher: queued=0 (0 B) flushing=0 completed=0 noop=0 failed=0 disabled=0 since last scan, cumulative-flushed=21 MiB approx-store-local=1.3 MiB
I260910 11:38:30.812156 492 13@kv/kvserver/store_range_flusher.go:778 [T1,Vsystem,n1,s1] 22142 range flusher: queued=0 (0 B) flushing=0 completed=0 noop=0 failed=0 disabled=0 since last scan, cumulative-flushed=21 MiB approx-store-local=1.3 MiB
I260910 11:38:30.922714 492 13@kv/kvserver/store_range_flusher.go:778 [T1,Vsystem,n1,s1] 22143 range flusher: queued=0 (0 B) flushing=0 completed=0 noop=0 failed=0 disabled=0 since last scan, cumulative-flushed=21 MiB approx-store-local=1.3 MiB
I260910 11:38:31.054219 492 13@kv/kvserver/store_range_flusher.go:778 [T1,Vsystem,n1,s1] 22144 range flusher: queued=0 (0 B) flushing=0 completed=0 noop=0 failed=0 disabled=0 since last scan, cumulative-flushed=21 MiB approx-store-local=1.3 MiB
W260910 11:38:31.138325 591 15@kv/kvserver/spanlatch/manager.go:702 [T1,Vsystem,n1,s1,r26/1:/Table/2{2-3},raft] 22145 TruncateLog [/Table/22] has held latch for 4s. Some possible causes are slow disk reads, slow raft replication, and expensive request processing.
```

Parameters:
- attempt=1
- race=true
- run=3
- shard=1
Help

See also: [How To Investigate a Go Test Failure \(internal\)](https://cockroachlabs.atlassian.net/l/c/HgfXfJgM)

[This test on roachdash](https://roachdash.crdb.dev/?filter=status:open%20t:.*TestInjectDescriptors.*&sort=title+created&display=lastcommented+project) | [Improve this report!](https://github.com/cockroachdb/cockroach/tree/master/pkg/cmd/bazci/githubpost/issues)

Contributor guide

Open the contributing guide

Research direction

Start by reproducing testutils/sqlutils.TestInjectDescriptors with attempt=1, race=true, run=3, and shard=1 at commit 807558e5e81666af257c811e925e4cae570abc28. Inspect the test output and the referenced test report to determine why it fails; done means the test passes reliably under the reported configuration.

Written by the indexing model from the issue text.

Assessment

Tech stack
go
Domain
databases, distributed-systems, testing
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Active
Clarity
Needs clarification
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.