Emergency RO after overlapping backpointer detected [17671896]

[RAOF]

On master commit 17671896

Some time after mount my filesystem goes ERO with a message like:

[ 4505.890352] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): overlapping backpointer found when inserting btree=extents l=0 offset=0:0 len=24 pos=1074071934:120:U32_MAX
                 into u64s 15 type alloc_v4 4:62743:0 len 0 ver 0: 
                   gen 9 oldest_gen 0 data_type user
                   journal_seq       12072236
                   need_discard      0
                   need_inc_gen      0
                   dirty_sectors     24
                   cached_sectors    0
                   stripe            0
                   stripe_redundancy 0
                   io_time[READ]     19609110448
                   io_time[WRITE]    24848665840
                   backpointers:     1  
                     btree=backpointers l=1 offset=0:0 len=512 pos=3:4756466532352:0
                 for u64s 9 type extent 1074071934:120:U32_MAX len 88 ver 162939624: crc: c_size 24 size 88 offset 0 nonce 0 csum chacha20_poly1305_80 compress lz4 ptr: 5:268778:896 gen 18 ptr: 4:62743:0 gen 9
[ 4505.890365] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): inconsistency detected - emergency read only
[ 4505.890494] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): transaction updates for bch2_write_index_default journal seq 12072250
                 update: btree=extents cached=0 bch2_trans_update_extent+0x62b/0xed0 [bcachefs]
                   old u64s 5 type deleted 1074071934:120:U32_MAX len 0 ver 0
                   new u64s 9 type extent 1074071934:120:U32_MAX len 88 ver 162939624: crc: c_size 24 size 88 offset 0 nonce 0 csum chacha20_poly1305_80 compress lz4 ptr: 5:268778:896 gen 18 ptr: 4:62743:0 gen 9
                 update: btree=inodes cached=0 bch2_inode_write+0x57/0x70 [bcachefs]
                   old u64s 18 type inode_v2 0:1074071934:U32_MAX len 0 ver 0: mode 100644 flags 17300000 journal_seq 12072250 bi_atime 25383211994162083 bi_ctime 25383211994162083 bi_mtime 25383211994162083 bi_otime 25383211994162083 bi_size 16384 bi_sectors 32 bi_uid 1000 bi_gid 1000 bi_nlink 0 bi_generation 28 bi_dev 0 bi_data_checksum 0 bi_compression 0 bi_project 0 bi_background_compression 0 bi_data_replicas 0 bi_promote_target 0 bi_foreground_target 0 bi_backgrou

This happens a variable time after mount - I've seen as short as a couple of minutes, or as long as 8+ hours. It doesn't [i]appear[/i] to be related to user-generated IO - I've had this happen in the initramfs environment.

mount -o fsck,fix_errors,verbose will succeed, and mount the filesystem RW. A mount after unclean shutdown will warn about an overlapping backpointer, and then continue. A mount after clean shutdown will not.

A log of a mount after unclean shutdown, followed by an unmount an remount is:

[   30.487268] bcachefs: bch2_fs_open() 
[   30.487848] bcachefs: bch2_read_super() 
[   30.489352] bcachefs: bch2_read_super() ret 0
[   30.489900] bcachefs: bch2_read_super() 
[   30.492651] bcachefs: bch2_read_super() ret 0
[   30.493174] bcachefs: bch2_read_super() 
[   30.526347] bcachefs: bch2_read_super() ret 0
[   30.526839] bcachefs: bch2_read_super() 
[   30.529915] bcachefs: bch2_read_super() ret 0
[   30.530380] bcachefs: bch2_read_super() 
[   30.533211] bcachefs: bch2_read_super() ret 0
[   30.533650] bcachefs: bch2_read_super() 
[   30.536427] bcachefs: bch2_read_super() ret 0
[   30.536837] bcachefs: bch2_fs_alloc() 
[   30.549806] bcachefs: bch2_fs_journal_init() 
[   30.550430] bcachefs: bch2_fs_journal_init() ret 0
[   30.550821] bcachefs: bch2_fs_btree_cache_init() 
[   30.551576] bcachefs: bch2_fs_btree_cache_init() ret 0
[   30.552213] bcachefs: bch2_fs_encryption_init() 
[   30.563684] bcachefs: bch2_fs_encryption_init() ret 0
[   30.564002] bcachefs: __bch2_fs_compress_init() 
[   30.564318] bcachefs: __bch2_fs_compress_init() ret 0
[   30.564620] bcachefs: bch2_fs_fsio_init() 
[   30.564925] bcachefs: bch2_fs_fsio_init() ret 0
[   30.565191] bcachefs: bch2_dev_alloc() 
[   30.565727] bcachefs: bch2_dev_alloc() ret 0
[   30.565964] bcachefs: bch2_dev_alloc() 
[   30.566444] bcachefs: bch2_dev_alloc() ret 0
[   30.566651] bcachefs: bch2_dev_alloc() 
[   30.567193] bcachefs: bch2_dev_alloc() ret 0
[   30.567385] bcachefs: bch2_dev_alloc() 
[   30.567920] bcachefs: bch2_dev_alloc() ret 0
[   30.568104] bcachefs: bch2_dev_alloc() 
[   30.568344] bcachefs: bch2_dev_alloc() ret 0
[   30.568526] bcachefs: bch2_dev_alloc() 
[   30.568728] bcachefs: bch2_dev_alloc() ret 0
[   30.569083] bcachefs: bch2_fs_alloc() ret 0
[   30.569387] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): recovering from unclean shutdown
[   30.569590] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): starting journal read
[   31.354759] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): journal read done on device nvme0n1, ret 0
[   31.701854] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): journal read done on device nvme1n1, ret 0
[   85.706034] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): journal read done on device sda2, ret 0
[   86.439535] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): journal read done on device sdb2, ret 0
[   95.994015] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): journal read done on device sdc, ret 0
[   96.306188] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): journal read done on device sdd, ret 0
[   96.363507] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): journal read done, 83740 keys in 1043 entries, seq 12415059
[   96.363664] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): dropped unflushed entries 12415058-12415058
[   96.495084] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): starting alloc read
[  102.474263] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): alloc read done
[  102.474416] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): starting stripes_read
[  102.474567] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): stripes_read done
[  102.474718] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): checking allocations
[  177.370432] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): done checking allocations
[  177.370593] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): checking need_discard and freespace btrees
[  196.163991] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): done checking need_discard and freespace btrees
[  196.164166] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): starting journal replay, 31747 keys
[  196.170876] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): going read-write
[  196.828820] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): overlapping backpointer found when inserting btree=alloc l=1 offset=0:0 len=512 pos=4:247157:0
                 into u64s 15 type alloc_v4 4:62743:0 len 0 ver 0: 
                   gen 10 oldest_gen 0 data_type btree
                   journal_seq       12415048
                   need_discard      0
                   need_inc_gen      0
                   dirty_sectors     512
                   cached_sectors    0
                   stripe            0
                   stripe_redundancy 0
                   io_time[READ]     20330949240
                   io_time[WRITE]    25469031368
                   backpointers:     1  
                     btree=backpointers l=1 offset=0:0 len=512 pos=3:4756466532352:0
                 for u64s 12 type btree_ptr_v2 4:247157:0 len 0 ver 0: seq b8657981854bea70 written 0 min_key 4:246322:1 ptr: 5:4831:512 gen 13 ptr: 4:62743:0 gen 10
[  197.277889] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): journal replay done
[  197.278670] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): checking lrus
[  200.425408] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): done checking lrus
[  200.425661] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): checking backpointers to alloc keys
[  204.282280] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): done checking backpointers to alloc keys
[  204.282542] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): checking backpointers to extents
[  287.356353] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): done checking backpointers to extents
[  287.356625] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): checking extents to backpointers
[  397.468256] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): done checking extents to backpointers
[  397.468534] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): checking alloc to lru refs
[  406.759534] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): done checking alloc to lru refs
[  406.759809] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): reading snapshots table
[  406.760083] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): reading snapshots done
[  406.760348] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): starting fsck
[  409.651853] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): checking extents
[  423.836301] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): checking dirents
[  429.459380] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): checking xattrs
[  429.461961] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): checking root directory
[  438.728001] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): checking inode nlinks
[  444.090385] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): fsck done
[  444.877542] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): ret (No error)
[  444.879058] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): mounted version=backpointers opts=metadata_replicas=2,data_replicas=2,compression=lz4,metadata_target=ssd,foreground_target=ssd,background_target=rotational,promote_target=ssd,noinodes_use_key_cache,verbose,journal_reclaim_delay=1000,fsck,fix_errors
[  444.881638] bcachefs: bch2_fs_open() ret 0
[  490.928276] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): shutting down
[  490.961345] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): flushing journal and stopping allocators
[  491.932677] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): flushing journal and stopping allocators complete
[  491.940349] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): marking filesystem clean
[  491.987196] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): shutdown complete
[  500.091316] bcachefs: bch2_fs_open() 
[  500.092269] bcachefs: bch2_read_super() 
[  500.096700] bcachefs: bch2_read_super() ret 0
[  500.097593] bcachefs: bch2_read_super() 
[  500.114948] bcachefs: bch2_read_super() ret 0
[  500.115828] bcachefs: bch2_read_super() 
[  500.155051] bcachefs: bch2_read_super() ret 0
[  500.155909] bcachefs: bch2_read_super() 
[  500.181603] bcachefs: bch2_read_super() ret 0
[  500.182436] bcachefs: bch2_read_super() 
[  500.863850] bcachefs: bch2_read_super() ret 0
[  500.864116] bcachefs: bch2_read_super() 
[  501.437799] bcachefs: bch2_read_super() ret 0
[  501.438060] bcachefs: bch2_fs_alloc() 
[  501.449746] bcachefs: bch2_fs_journal_init() 
[  501.450207] bcachefs: bch2_fs_journal_init() ret 0
[  501.450496] bcachefs: bch2_fs_btree_cache_init() 
[  501.451122] bcachefs: bch2_fs_btree_cache_init() ret 0
[  501.451583] bcachefs: bch2_fs_encryption_init() 
[  501.451858] bcachefs: bch2_fs_encryption_init() ret 0
[  501.452123] bcachefs: __bch2_fs_compress_init() 
[  501.452411] bcachefs: __bch2_fs_compress_init() ret 0
[  501.452684] bcachefs: bch2_fs_fsio_init() 
[  501.452998] bcachefs: bch2_fs_fsio_init() ret 0
[  501.453262] bcachefs: bch2_dev_alloc() 
[  501.453963] bcachefs: bch2_dev_alloc() ret 0
[  501.454190] bcachefs: bch2_dev_alloc() 
[  501.454897] bcachefs: bch2_dev_alloc() ret 0
[  501.455114] bcachefs: bch2_dev_alloc() 
[  501.455862] bcachefs: bch2_dev_alloc() ret 0
[  501.456063] bcachefs: bch2_dev_alloc() 
[  501.456705] bcachefs: bch2_dev_alloc() ret 0
[  501.456898] bcachefs: bch2_dev_alloc() 
[  501.457144] bcachefs: bch2_dev_alloc() ret 0
[  501.457330] bcachefs: bch2_dev_alloc() 
[  501.457542] bcachefs: bch2_dev_alloc() ret 0
[  501.457907] bcachefs: bch2_fs_alloc() ret 0
[  501.458234] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): recovering from clean shutdown, journal seq 12415222
[  501.458453] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): starting journal read
[  502.130933] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): journal read done on device nvme0n1, ret 0
[  502.545503] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): journal read done on device nvme1n1, ret 0
[  556.975922] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): ja->sectors_free == ca->mi.bucket_size
[  556.976528] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): cur_idx 364/8192
[  556.977133] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): bucket_seq[363] = 12415189
[  556.977726] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): bucket_seq[364] = 12415220
[  556.978303] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): bucket_seq[365] = 12168750
[  556.978874] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): journal read done on device sda2, ret 0
[  557.788293] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): ja->sectors_free == ca->mi.bucket_size
[  557.788842] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): cur_idx 360/8192
[  557.789397] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): bucket_seq[359] = 12415185
[  557.789944] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): bucket_seq[360] = 12415190
[  557.790486] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): bucket_seq[361] = 12168724
[  557.791029] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): journal read done on device sdb2, ret 0
[  566.085166] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): ja->sectors_free == ca->mi.bucket_size
[  566.085753] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): cur_idx 354/8192
[  566.086329] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): bucket_seq[353] = 12415186
[  566.086914] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): bucket_seq[354] = 12415218
[  566.087495] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): bucket_seq[355] = 12168703
[  566.088077] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): journal read done on device sdc, ret 0
[  566.382201] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): ja->sectors_free == ca->mi.bucket_size
[  566.382823] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): cur_idx 353/8192
[  566.383429] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): bucket_seq[352] = 12415187
[  566.384046] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): bucket_seq[353] = 12415219
[  566.384661] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): bucket_seq[354] = 12168722
[  566.385279] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): journal read done on device sdd, ret 0
[  566.386158] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): journal read done, 0 keys in 1 entries, seq 12415223
[  566.449842] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): starting alloc read
[  572.221925] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): alloc read done
[  572.222118] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): starting stripes_read
[  572.222311] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): stripes_read done
[  572.222501] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): checking allocations
[  645.326772] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): done checking allocations
[  645.327188] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): checking need_discard and freespace btrees
[  661.231225] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): done checking need_discard and freespace btrees
[  661.231471] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): starting journal replay, 0 keys
[  661.231718] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): journal replay done
[  661.231961] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): checking lrus
[  664.171634] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): done checking lrus
[  664.171886] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): checking backpointers to alloc keys
[  667.907672] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): done checking backpointers to alloc keys
[  667.907932] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): checking backpointers to extents
[  745.656952] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): done checking backpointers to extents
[  745.657224] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): checking extents to backpointers
[  853.482542] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): done checking extents to backpointers
[  853.482808] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): checking alloc to lru refs
[  862.700351] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): done checking alloc to lru refs
[  862.700615] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): reading snapshots table
[  862.700881] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): reading snapshots done
[  862.701139] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): starting fsck
[  865.562794] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): checking extents
[  879.521304] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): checking dirents
[  885.037410] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): checking xattrs
[  885.039953] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): checking root directory
[  893.849676] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): checking inode nlinks
[  899.209327] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): fsck done
[  899.944101] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): ret (No error)
[  899.944912] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): going read-write
[  900.005634] bcachefs (a4b165a2-556b-4650-88b8-d90f8ee4b473): mounted version=backpointers opts=metadata_replicas=2,data_replicas=2,compression=lz4,metadata_target=ssd,foreground_target=ssd,background_target=rotational,promote_target=ssd,noinodes_use_key_cache,verbose,journal_reclaim_delay=1000,fsck,fix_errors