UBIFS: Recovery failed after power-cut

Mon Jun 27 22:55:33 PDT 2022

Hi all,

We have had a mounting failed case due to power cut and I have been 
investigating the cause.

The problem seems to come down to function ubifs_tnc_locate where 
corresponding znode is found but the logical erase block lnum is not. 
With current logic it returns an error code and thus fail the mount 
operation.

My question is what could possibly cause this situation and in this case 
is it correct to return an error code or better an ENOENT?

Trace:

ubifs_tnc_locate

ubifs_lookup_level0 -> returns found

zt->lnum = 1445

ubifs_tnc_read_node() returns node not found (unmapped)

-> error

Other info: kernel version: 4.19.170

Mtdinfo:

Count of MTD devices:           11

Present MTD devices:            mtd0, mtd1, mtd2, mtd3, mtd4, mtd5, 
mtd6, mtd7, mtd8, mtd9, mtd10

Sysfs interface supported:      yes

mtd8

Name:                           run-time files and logs

Type:                           nand

Eraseblock size:                262144 bytes, 256.0 KiB

Amount of eraseblocks:          2094 (548929536 bytes, 523.5 MiB)

Minimum input/output unit size: 4096 bytes

Sub-page size:                  4096 bytes

OOB size:                       224 bytes

Character device major/minor:   90:16

Bad blocks are allowed:         true
Device is writable:             true

Logs:

[  403.324692] UBIFS DBG tnc (pid 3123): search key (28892, inode)
[  403.330701] UBIFS DBG tnc (pid 3123): found 1, lvl 0, n 5
[  403.336160] UBIFS DBG tnc (pid 3123): LEB 1523:250736, key (28892, inode)
[  403.343004] UBIFS DBG io (pid 3123): LEB 1523:250736, inode node, 
length 160
[  403.350134] UBI DBG gen (pid 3123): read 160 bytes from LEB 0:1523:250736
[  403.356986] UBI DBG eba (pid 3123): read 160 bytes from offset 250736 
of LEB 0:1523, PEB 2044
[  403.365580] UBIFS DBG tnc (pid 3123): search key (28918, inode)
[  403.365588] UBIFS DBG io (pid 3123): LEB 1823:171312, indexing node, 
length 188
[  403.378897] UBI DBG gen (pid 3123): read 188 bytes from LEB 0:1823:171312
[  403.385752] UBI DBG eba (pid 3123): read 188 bytes from offset 171312 
of LEB 0:1823, PEB 826
[  403.394727] UBIFS DBG tnc (pid 3123): LEB 1823:171312, level 1, 8 branch
[  403.401501] UBIFS DBG io (pid 3123): LEB 1823:171160, indexing node, 
length 148
[  403.408900] UBI DBG gen (pid 3123): read 148 bytes from LEB 0:1823:171160
[  403.415761] UBI DBG eba (pid 3123): read 148 bytes from offset 171160 
of LEB 0:1823, PEB 826
[  403.424270] UBIFS DBG tnc (pid 3123): LEB 1823:171160, level 0, 6 branch
[  403.431031] UBIFS DBG tnc (pid 3123): found 1, lvl 0, n 1
[  403.436490] UBIFS DBG tnc (pid 3123): LEB 442:246840, key (28918, inode)
[  403.443248] UBIFS DBG io (pid 3123): LEB 442:246840, inode node, 
length 160
[  403.450266] UBI DBG gen (pid 3123): read 160 bytes from LEB 0:442:246840
[  403.457025] UBI DBG eba (pid 3123): read 160 bytes from offset 246840 
of LEB 0:442, PEB 2049
[  403.465973] UBIFS DBG tnc (pid 3123): search key (28973, inode)
[  403.471950] UBIFS DBG io (pid 3123): LEB 1448:24296, indexing node, 
length 188
[  403.479254] UBI DBG gen (pid 3123): read 188 bytes from LEB 0:1448:24296
[  403.486012] UBI DBG eba (pid 3123): read 188 bytes from offset 24296 
of LEB 0:1448, PEB 633
[  403.494876] UBIFS DBG tnc (pid 3123): LEB 1448:24296, level 1, 8 branch
[  403.501608] UBIFS DBG io (pid 3123): LEB 1448:23720, indexing node, 
length 188
[  403.508892] UBI DBG gen (pid 3123): read 188 bytes from LEB 0:1448:23720
[  403.515659] UBI DBG eba (pid 3123): read 188 bytes from offset 23720 
of LEB 0:1448, PEB 633
[  403.524082] UBIFS DBG tnc (pid 3123): LEB 1448:23720, level 0, 8 branch
[  403.530780] UBIFS DBG tnc (pid 3123): found 1, lvl 0, n 2
[  403.536231] UBIFS DBG tnc (pid 3123): LEB 1729:242968, key (28973, inode)
[  403.543077] UBIFS DBG io (pid 3123): LEB 1729:242968, inode node, 
length 160
[  403.550214] UBI DBG gen (pid 3123): read 160 bytes from LEB 0:1729:242968
[  403.557075] UBI DBG eba (pid 3123): read 160 bytes from offset 242968 
of LEB 0:1729, PEB 369
[  403.566027] UBIFS DBG tnc (pid 3123): search key (29007, inode)
[  403.572004] UBIFS DBG io (pid 3123): LEB 1823:203760, indexing node, 
length 188
[  403.579380] UBI DBG gen (pid 3123): read 188 bytes from LEB 0:1823:203760
[  403.586227] UBI DBG eba (pid 3123): read 188 bytes from offset 203760 
of LEB 0:1823, PEB 826
[  403.595203] UBIFS DBG tnc (pid 3123): LEB 1823:203760, level 1, 8 branch
[  403.601963] UBIFS DBG io (pid 3123): LEB 1823:203568, indexing node, 
length 188
[  403.609364] UBI DBG gen (pid 3123): read 188 bytes from LEB 0:1823:203568
[  403.616226] UBI DBG eba (pid 3123): read 188 bytes from offset 203568 
of LEB 0:1823, PEB 826
[  403.624735] UBIFS DBG tnc (pid 3123): LEB 1823:203568, level 0, 8 branch
[  403.631496] UBIFS DBG tnc (pid 3123): found 1, lvl 0, n 1
[  403.636954] UBIFS DBG tnc (pid 3123): LEB 1231:251896, key (29007, inode)
[  403.643800] UBIFS DBG io (pid 3123): LEB 1231:251896, inode node, 
length 160
[  403.650907] UBI DBG gen (pid 3123): read 160 bytes from LEB 0:1231:251896
[  403.657751] UBI DBG eba (pid 3123): read 160 bytes from offset 251896 
of LEB 0:1231, PEB 952
[  403.666715] UBIFS DBG tnc (pid 3123): search key (29034, inode)
[  403.672691] UBIFS DBG io (pid 3123): LEB 326:27048, indexing node, 
length 108
[  403.679888] UBI DBG gen (pid 3123): read 108 bytes from LEB 0:326:27048
[  403.686559] UBI DBG eba (pid 3123): read 108 bytes from offset 27048 
of LEB 0:326, PEB 430
[  403.695359] UBIFS DBG tnc (pid 3123): LEB 326:27048, level 2, 4 branch
[  403.701950] UBIFS DBG io (pid 3123): LEB 326:26936, indexing node, 
length 108
[  403.709148] UBI DBG gen (pid 3123): read 108 bytes from LEB 0:326:26936
[  403.715821] UBI DBG eba (pid 3123): read 108 bytes from offset 26936 
of LEB 0:326, PEB 430
[  403.724161] UBIFS DBG tnc (pid 3123): LEB 326:26936, level 1, 4 branch
[  403.730749] UBIFS DBG io (pid 3123): LEB 326:26288, indexing node, 
length 68
[  403.737863] UBI DBG gen (pid 3123): read 68 bytes from LEB 0:326:26288
[  403.744449] UBI DBG eba (pid 3123): read 68 bytes from offset 26288 
of LEB 0:326, PEB 430
[  403.752694] UBIFS DBG tnc (pid 3123): LEB 326:26288, level 0, 2 branch
[  403.759278] UBIFS DBG tnc (pid 3123): found 1, lvl 0, n 1
[  403.764729] UBIFS DBG tnc (pid 3123): LEB 1445:217432, key (29034, inode)
[  403.771589] UBIFS DBG io (pid 3123): LEB 1445:217432, inode node, 
length 160
[  403.778696] UBI DBG gen (pid 3123): read 160 bytes from LEB 0:1445:217432
[  403.785546] UBI DBG eba (pid 3123): read 160 bytes from offset 217432 
of LEB 0:1445 (unmapped)
[  403.794222] UBIFS DBG tnc (pid 3123): search key (29034, inode)
[  403.800252] UBIFS DBG tnc (pid 3123): found 1, lvl 0, n 1
[  403.805710] UBIFS DBG io (pid 3123): LEB 1445:217432, inode node, 
length 160
[  403.812818] UBI DBG gen (pid 3123): read 160 bytes from LEB 0:1445:217432
[  403.819720] UBI DBG eba (pid 3123): read 160 bytes from offset 217432 
of LEB 0:1445 (unmapped)
[  403.828406] UBIFS error (ubi0:0 pid 3123): ubifs_read_node: bad node 
type (255 but expected 0)
[  403.837083] UBI DBG gen (pid 3123): test LEB 0:1445
[  403.842010] UBIFS error (ubi0:0 pid 3123): ubifs_read_node: bad node 
at LEB 1445:217432, LEB mapping status 0
[  403.852005] Not a node, first 24 bytes:
[  403.852013] 00000000: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff 
ff ff ff ff ff ff ff ff ........................
[  403.869003] UBIFS DBG tnc (pid 3123): key (29034, inode)
[  403.875243] UBI DBG gen (pid 3123): close device 0, volume 0, mode 2
[  403.883357] UBI DBG gen (pid 3123): close device 0, volume 0, mode 1
mount: /mnt/test: wrong fs type, bad option, bad superblock on 
/dev/ubi0_0, missing codepage or helper program, or other error.

-- 
Best regards,
Lam Le
Consultant - BescoInc Oy - Tekniikantie 12, FI-02150 Espoo, Finland.
Direct: +358442725640. Email: lam at bescosoftware.com.
Skype: lam-le. Web: https://bescosoftware.com.