ccl/schemachangerccl: TestBackupMixedVersionElements_base_add_column failed

[cockroach-teamcity]

ccl/schemachangerccl.TestBackupMixedVersionElements_base_add_column failed with artifacts on release-23.1 @ 2ef359d69043c38727e8554f858d856e0f682e71:

I230728 17:18:45.829629 289693 13@kv/kvserver/replica_raft.go:381  [T1,n1,s1,r14/1:/Table/1{3-4}] 84  proposing SIMPLE(l2) [(n2,s2):2LEARNER]: after=[(n1,s1):1 (n2,s2):2LEARNER] next=3
I230728 17:18:45.831331 292638 13@kv/kvserver/store_snapshot.go:1579  [T1,n1,s1,r14/1:/Table/1{3-4}] 85  streamed INITIAL snapshot 420cee0b at applied index 22 to (n2,s2):2LEARNER with 4.7 KiB in 0.00s @ 32 MiB/s: kvs=45 rangeKVs=0, rate-limit: 32 MiB/s, queued: 0.00s
I230728 17:18:45.832089 292641 13@kv/kvserver/replica_raftstorage.go:480  [T1,n2,s2,r14/2:{-}] 86  applying INITIAL snapshot 420cee0b from (n1,s1):1 at applied index 22
I230728 17:18:45.832441 292641 3@pebble/event.go:697  [n2,s2,pebble] 87  [JOB 15] ingesting: sstable created 000014
I230728 17:18:45.832476 292641 3@pebble/event.go:697  [n2,s2,pebble] 88  [JOB 15] ingesting: sstable created 000019
I230728 17:18:45.832488 292641 3@pebble/event.go:697  [n2,s2,pebble] 89  [JOB 15] ingesting: sstable created 000015
I230728 17:18:45.832501 292641 3@pebble/event.go:697  [n2,s2,pebble] 90  [JOB 15] ingesting: sstable created 000016
I230728 17:18:45.832510 292641 3@pebble/event.go:697  [n2,s2,pebble] 91  [JOB 15] ingesting: sstable created 000017
I230728 17:18:45.832520 292641 3@pebble/event.go:697  [n2,s2,pebble] 92  [JOB 15] ingesting: sstable created 000018
I230728 17:18:45.832563 292641 3@pebble/event.go:717  [n2,s2,pebble] 93  [JOB 16] WAL created 000020 (recycled 000002)
I230728 17:18:45.832696 292832 3@pebble/event.go:677  [n2,s2,pebble] 94  [JOB 17] flushing 1 memtable to L0
I230728 17:18:45.832741 292832 3@pebble/event.go:697  [n2,s2,pebble] 95  [JOB 17] flushing: sstable created 000021
I230728 17:18:45.832886 292832 3@pebble/event.go:681  [n2,s2,pebble] 96  [JOB 17] flushed 1 memtable to L0 [000021] (1.7 K), in 0.0s (0.0s total), output rate 12 M/s
I230728 17:18:45.832969 292851 3@pebble/event.go:665  [n2,s2,pebble] 97  [JOB 18] compacting(default) L0 [000021] (1.7 K) + L6 [000013 000012] (2.8 K)
I230728 17:18:45.833126 292851 3@pebble/event.go:697  [n2,s2,pebble] 98  [JOB 18] compacting: sstable created 000022
I230728 17:18:45.833306 292641 3@pebble/event.go:705  [n2,s2,pebble] 99  [JOB 15] ingested L6:000014 (1.4 K), L0:000019 (1.1 K), L0:000015 (1.4 K), L6:000016 (1.2 K), L6:000017 (1.4 K), L6:000018 (2.1 K)
I230728 17:18:45.833473 292851 3@pebble/event.go:669  [n2,s2,pebble] 100  [JOB 18] compacted(default) L0 [000021] (1.7 K) + L6 [000013 000012] (2.8 K) -> L6 [000022] (2.3 K), in 0.0s (0.0s total), output rate 5.1 M/s
I230728 17:18:45.833578 292854 3@pebble/event.go:665  [n2,s2,pebble] 101  [JOB 19] compacting(default) L0 [000019 000015] (2.6 K) + L6 [000022] (2.3 K)
I230728 17:18:45.833700 292854 3@pebble/event.go:697  [n2,s2,pebble] 102  [JOB 19] compacting: sstable created 000023
I230728 17:18:45.833803 292641 kv/kvserver/replica_raftstorage.go:491  [T1,n2,s2,r14/2:/Table/1{3-4}] 103  applied INITIAL snapshot 420cee0b from (n1,s1):1 at applied index 22 (total=2ms data=4.2 KiB ingestion=6@1ms)
I230728 17:18:45.833936 292854 3@pebble/event.go:669  [n2,s2,pebble] 104  [JOB 19] compacted(default) L0 [000019 000015] (2.6 K) + L6 [000022] (2.3 K) -> L6 [000023] (2.4 K), in 0.0s (0.0s total), output rate 8.1 M/s
I230728 17:18:45.834091 292868 3@pebble/event.go:701  [n2,s2,pebble] 105  [JOB 20] sstable deleted 000012
I230728 17:18:45.834190 292837 3@pebble/event.go:665  [n2,s2,pebble] 106  [JOB 22] compacting(elision-only) L6 [000014] (1.4 K) + L6 [] (0 B)
I230728 17:18:45.834303 292837 3@pebble/event.go:697  [n2,s2,pebble] 107  [JOB 22] compacting: sstable created 000024
I230728 17:18:45.834459 292837 3@pebble/event.go:669  [n2,s2,pebble] 108  [JOB 22] compacted(elision-only) L6 [000014] (1.4 K) + L6 [] (0 B) -> L6 [000024] (1.2 K), in 0.0s (0.0s total), output rate 5.8 M/s
I230728 17:18:45.834539 292841 3@pebble/event.go:665  [n2,s2,pebble] 109  [JOB 23] compacting(elision-only) L6 [000016] (1.2 K) + L6 [] (0 B)
I230728 17:18:45.834612 292868 3@pebble/event.go:701  [n2,s2,pebble] 110  [JOB 20] sstable deleted 000013
I230728 17:18:45.834639 292841 3@pebble/event.go:669  [n2,s2,pebble] 111  [JOB 23] compacted(elision-only) L6 [000016] (1.2 K) + L6 [] (0 B) -> L6 [] (0 B), in 0.0s (0.0s total), output rate 0 B/s
I230728 17:18:45.834615 292840 3@pebble/event.go:701  [n2,s2,pebble] 112  [JOB 22] sstable deleted 000014
I230728 17:18:45.834691 292843 3@pebble/event.go:665  [n2,s2,pebble] 113  [JOB 24] compacting(elision-only) L6 [000017] (1.4 K) + L6 [] (0 B)
I230728 17:18:45.834761 292868 3@pebble/event.go:701  [n2,s2,pebble] 114  [JOB 20] sstable deleted 000015
I230728 17:18:45.834789 292868 3@pebble/event.go:701  [n2,s2,pebble] 116  [JOB 20] sstable deleted 000019
I230728 17:18:45.834805 292868 3@pebble/event.go:701  [n2,s2,pebble] 117  [JOB 20] sstable deleted 000021
I230728 17:18:45.834799 292842 3@pebble/event.go:701  [n2,s2,pebble] 118  [JOB 23] sstable deleted 000016
I230728 17:18:45.834817 292868 3@pebble/event.go:701  [n2,s2,pebble] 119  [JOB 20] sstable deleted 000022
I230728 17:18:45.834766 292843 3@pebble/event.go:697  [n2,s2,pebble] 115  [JOB 24] compacting: sstable created 000025
I230728 17:18:45.834897 289693 13@kv/kvserver/replica_command.go:2352  [T1,n1,replicate,s1,r14/1:/Table/1{3-4}] 120  change replicas (add [(n2,s2):2] remove []): existing descriptor r14:/Table/1{3-4} [(n1,s1):1, (n2,s2):2LEARNER, next=3, gen=1]
I230728 17:18:45.834940 292843 3@pebble/event.go:669  [n2,s2,pebble] 121  [JOB 24] compacted(elision-only) L6 [000017] (1.4 K) + L6 [] (0 B) -> L6 [000025] (1.2 K), in 0.0s (0.0s total), output rate 5.6 M/s
I230728 17:18:45.835022 292871 3@pebble/event.go:665  [n2,s2,pebble] 122  [JOB 25] compacting(elision-only) L6 [000018] (2.1 K) + L6 [] (0 B)
I230728 17:18:45.835111 292871 3@pebble/event.go:697  [n2,s2,pebble] 123  [JOB 25] compacting: sstable created 000026
I230728 17:18:45.835273 292871 3@pebble/event.go:669  [n2,s2,pebble] 124  [JOB 25] compacted(elision-only) L6 [000018] (2.1 K) + L6 [] (0 B) -> L6 [000026] (1.9 K), in 0.0s (0.0s total), output rate 9.1 M/s
I230728 17:18:45.835352 292874 3@pebble/event.go:701  [n2,s2,pebble] 125  [JOB 25] sstable deleted 000018
I230728 17:18:45.835394 292870 3@pebble/event.go:701  [n2,s2,pebble] 126  [JOB 24] sstable deleted 000017
I230728 17:18:45.838338 289693 13@kv/kvserver/replica_raft.go:381  [T1,n1,s1,r14/1:/Table/1{3-4}] 127  proposing SIMPLE(v2) [(n2,s2):2]: after=[(n1,s1):1 (n2,s2):2] next=3
I230728 17:18:45.839169 289693 13@kv/kvserver/replicate_queue.go:1260  [T1,n1,replicate,s1,r28/1:/Table/2{7-8}] 128  adding voter n3,s3: [1*:12]
I230728 17:18:45.839825 289693 13@kv/kvserver/replica_command.go:2352  [T1,n1,replicate,s1,r28/1:/Table/2{7-8}] 129  change replicas (add [(n3,s3):2LEARNER] remove []): existing descriptor r28:/Table/2{7-8} [(n1,s1):1, next=2, gen=0]
--- FAIL: TestBackupMixedVersionElements_base_add_column (106.45s)
=== RUN   TestBackupMixedVersionElements_base_add_column/backup/restore_stage_6_of_10
    testcluster.go:429: pq: n3 required, but unavailable
    --- FAIL: TestBackupMixedVersionElements_base_add_column/backup/restore_stage_6_of_10 (0.80s)

Help

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

/cc @cockroachdb/sql-foundations

This test on roachdash | Improve this report!

Jira issue: CRDB-30201

[rafiss]

We don't have logs because #107951 was not backported yet. (see also #103042). closing as unactionable, but next time it flakes, we will be able to see more.