fsck this shit

Tue Jun 2 16:38:49 UTC 2020

Once upon a time, the power ran out, and then...

** SU+J Recovering /dev/<...>
** Reading 33554432 byte journal from inode 4.
** Building recovery table.
** Resolving unreferenced inode list.
** Processing journal entries.
fsck: /dev/<...>: Segmentation fault

GAAAY.

OK, let's check the core dump... oh, wait... tough luck. Fortunately, subsequent runs of fsck ended up likewise, so I was able to get a core dump by re-executing fsck while being inside a TMPFS-backed directory. (On the other hand, unfortunately, fsck was never able to replay the journal.) Furthermore, I saved the .sujournal file, but saving the contents of the whole filesystem was beyond my resources. (It would have been adequate to use a tool that collected (only) the blocks that fsck read before segfaulting (thus constructing a small test case), but no such tool was at hand.)

Before running "fsck -y" (because I had no other options) I looked at "fsck -n" to see whether a particular, large file would get idiotically removed as part of "fixing" the filesystem. This routine is prompted by (1) personal experiences of files getting lost or truncated to 0 length, and (2) past reports of disasterous behaviors involving soft updates, such as untouched (read-only) files getting lost; "lost" means not even relinked to /lost+found or anything. And wouldn't ya know it, fsck did ask whether to remove something that had an unambiguously large size (to be exact, IIRC: "DUP ... REMOVE?", whatever that means). That's it, either (a) remove the file, or (b) stay dirty; take it or leave it. It's not like there was some 3rd option to relink the file to /lost+found. After "fsck -y", the file disappeared without a trace. GAAAAAAAAAY.

The fsck_ffs (or fsck_ufs) file was the one distributed with the 12.1-RELEASE, the one with the SHA3-256 checksum of 447592ae05dc7829823901700bb90940968cae006719964d39b1212bb312d164. Let's see the backtrace:

* thread #1, name = 'fsck_ufs', stop reason = signal SIGSEGV
   * frame #0: 0x0000000000219d93 fsck_ffs`blk_free(bno=10692928, mask=0, frags=134643471) at suj.c:653:34
     frame #1: 0x000000000021a481 fsck_ffs`ino_trunc(ino=5296913, size=134610944) at suj.c:1547:3
     frame #2: 0x0000000000216fee fsck_ffs`suj_check [inlined] cg_adj_blk(sc=0x0000000801574540) at suj.c:1788:5
     frame #3: 0x0000000000216fc3 fsck_ffs`suj_check [inlined] cg_apply at suj.c:1900
     frame #4: 0x0000000000216fa5 fsck_ffs`suj_check(filesys="/dev/<...>") at suj.c:2737
     frame #5: 0x000000000020ef54 fsck_ffs`main [inlined] checkfilesys(filesys="/dev/<...>") at main.c:427:9
     frame #6: 0x000000000020ef07 fsck_ffs`main(argc=1, argv=0x00007fffffffec48) at main.c:205
     frame #7: 0x000000000020810f fsck_ffs`_start(ap=<unavailable>, cleanup=<unavailable>) at crt1.c:76:7

Some analysis:

1. It's obvious that frags=134643471 is absurd.

2. The value of `frags` in frame #0 comes from the value of `frags` in frame #1. Regarding frame #1, which is a state of ino_trunc(): it is very suspicious that `frags` is assigned only in the first loop -- conditionally, even --, but is repeatedly used in the second loop. Is the 134643471 memory garbage? This smells GAAY.

3. In frame #0, we have i == 28262448, which means that relevant loop managed to garble >28 Mb of memory with 1-bits, as can be seen by the following: in frame #1, we have ip->dp2 ==
{
   di_mode = 65535
   di_nlink = -1
   di_uid = 4294967295
   di_gid = 4294967295
   di_blksize = 4294967295
   di_size = 18446744073709551615
   di_blocks = 18446744073709551615
   di_atime = -1
   di_mtime = -1
   di_ctime = -1
   di_birthtime = -1
   di_mtimensec = -1
   di_atimensec = -1
   di_ctimensec = -1
   di_birthnsec = -1
   di_gen = 4294967295
   di_kernflags = 4294967295
   di_flags = 4294967295
   di_extsize = 4294967295
   di_extb = ([0] = -1, [1] = -1)
   di_db = ([0] = -1, [1] = -1, [2] = -1, [3] = -1, [4] = -1, [5] = -1, [6] = -1, [7] = -1, [8] = -1, [9] = -1, [10] = -1, [11] = -1)
   di_ib = ([0] = -1, [1] = -1, [2] = -1)
   di_modrev = 18446744073709551615
   di_freelink = 4294967295
   di_spare = ([0] = 4294967295, [1] = 4294967295, [2] = 4294967295)
}.

4. By the way, *fs ==
{
   fs_firstfield = 0
   fs_unused_1 = 0
   fs_sblkno = 24
   fs_cblkno = 32
   fs_iblkno = 40
   fs_dblkno = 5056
   fs_old_cgoffset = 0
   fs_old_cgmask = 0
   fs_old_time = 0
   fs_old_size = 0
   fs_old_dsize = 0
   fs_ncg = 164
   fs_bsize = 32768
   fs_fsize = 4096
   fs_frag = 8
   fs_minfree = 0
   fs_old_rotdelay = 0
   fs_old_rps = 0
   fs_bmask = -32768
   fs_fmask = -4096
   fs_bshift = 15
   fs_fshift = 12
   fs_maxcontig = 4
   fs_maxbpg = 4096
   fs_fragshift = 3
   fs_fsbtodb = 3
   fs_sbsize = 4096
   fs_spare1 = ([0] = 0, [1] = 0)
   fs_nindir = 4096
   fs_inopb = 128
   fs_old_nspf = 0
   fs_optim = 1
   fs_old_npsect = 0
   fs_old_interleave = 0
   fs_old_trackskew = 0
   fs_id = ([0] = 1568391747, [1] = 841092898)
   fs_old_csaddr = 0
   fs_cssize = 4096
   fs_cgsize = 32768
   fs_spare2 = 0
   fs_old_nsect = 0
   fs_old_spc = 0
   fs_old_ncyl = 0
   fs_old_cpg = 0
   fs_ipg = 80256
   fs_fpg = 160280
   fs_old_cstotal = (cs_ndir = 0, cs_nbfree = 0, cs_nifree = 0, cs_nffree = 0)
   fs_fmod = '\0'
   fs_clean = '\0'
   fs_ronly = '\0'
   fs_old_flags = '\x80'
   fs_fsmnt = {
     [0] = '/'
     [1] = '\0'
     ...
   }
   fs_volname = {
     [0] = '\0'
   }
   fs_swuid = 0
   fs_pad = 0
   fs_cgrotor = 91
   fs_ocsp = ([0] = 0x0000000000000000, [1] = 0x0000000000000000, [2] = 0x0000000000000000, [3] = 0x0000000000000000, [4] = 0x0000000000000000, [5] = 0x0000000000000000, [6] = 0x0000000000000000, [7] = 0x0000000000000000, [8] = 0x0000000000000000, [9] = 0x0000000000000000, [10] = 0x0000000000000000, [11] = 0x0000000000000000)
   fs_contigdirs = 0x0000000800692a90 <no value available>
   fs_csp = 0x000000080069e000
   fs_maxcluster = 0x0000000800692800
   fs_active = 0x0000000000000000
   fs_old_cpc = 0
   fs_maxbsize = 32768
   fs_unrefs = 0
   fs_providersize = 26250240
   fs_metaspace = 6408
   fs_sparecon64 = ([0] = 0, [1] = 0, [2] = 0, [3] = 0, [4] = 0, [5] = 0, [6] = 0, [7] = 0, [8] = 0, [9] = 0, [10] = 0, [11] = 0, [12] = 0)
   fs_sblockactualloc = 65536
   fs_sblockloc = 65536
   fs_cstotal = {
     cs_ndir = 54923
     cs_nbfree = 188121
     cs_nifree = 12699260
     cs_nffree = 59369
     cs_numclusters = 0
     cs_spare = ([0] = 0, [1] = 0, [2] = 0)
   }
   fs_time = 1588190343
   fs_size = 26250240
   fs_dsize = 25424967
   fs_csaddr = 5056
   fs_pendingblocks = 0
   fs_pendinginodes = 0
   fs_snapinum = {
     [0] = 0
     ...
   }
   fs_avgfilesize = 16384
   fs_avgfpdir = 64
   fs_save_cgsize = 0
   fs_mtime = 1588178967
   fs_sujfree = 0
   fs_sparecon32 = {
     [0] = 0
     ...
   }
   fs_metackhash = 2
   fs_flags = 522
   fs_contigsumsize = 4
   fs_maxsymlinklen = 120
   fs_old_inodefmt = 0
   fs_maxfilesize = 2252349704110079
   fs_qbmask = 32767
   fs_qfmask = 4095
   fs_state = 0
   fs_old_postblformat = 0
   fs_old_nrpos = 0
   fs_spare5 = ([0] = 0, [1] = 0)
   fs_magic = 424935705
}.