[U-Boot] Unreadable UBIFS partition after power cuts

Fri Jan 16 16:38:45 CET 2015

I'm definitely not a friend of Outlook,
here the third trial with my personal account.

>>>>
>>>> We have a PPC MPC5125 device with 64MB NOR flash. The U-boot has to load the kernel and initramfs from a UBIFS partition.
>>>> Recently we made an upgrade from U-Boot version V2010.12 to version V2014.10. Now after some regression tests with power cuts, we got an UBIFS state, which is unreadable for U-Boot  version  V2014.10. If I do a tftpboot an mount the UBIFS with linux, there is no problem. It is also very >>strange, that if I downgrade the U-Boot to V2010.12, then it is also no problem with the partition and everything is readable. I tend to say there is probably a regression with the most recent U-Boot version. But I don't know where I can start to find it. I enabled also the DEBUG define, but there >>appears no additional debug message concerning UBIFS. How can I debug this?
>>>
>>> You can enable:
>>
>>> #undef CONFIG_UBI_SILENCE_MSG
>>> #define CONFIG_MTD_DEBUG
>>> #define CONFIG_MTD_DEBUG_VERBOSE 1
>>
>> Now I got output, thank you. I have to investigate more to get a better picture.
>
>Thanks!
>
>>> With which Linux version do you test? U-Boot is synced with linux 3.15 ... so, if you can test it with a kernel >= 3.15 this would be great!
>>
>> Our device is running with 2.6.34, with the patches from git://git.infradead.org/users/dedekind/ubifs-v2.6.34.git. I'm also able to open mount the image with linux 3.13  (Ubuntu 14.04/x86_64) and the mtdram module.
>> As soon the image is once mounted (and recovered) either with 2.6.34 or 3.13, the U-Boot V2014.10 can load it as well.
>>
>> Here the dmesg output mount with linux 3.13 which succeeds:
>> [189672.868677] UBI: attaching mtd0 to ubi0 [189672.869154] UBI:
>> scanning is finished [189672.870359] UBI: attached mtd0 (name "mtdram
>> test device", size 63 MiB) to ubi0 [189672.870363] UBI: PEB size:
>> 131072 bytes (128 KiB), LEB size: 130944 bytes [189672.870366] UBI:
>> min./max. I/O unit sizes: 1/64, sub-page size 1 [189672.870367] UBI:
>> VID header offset: 64 (aligned 64), data offset: 128 [189672.870369]
>> UBI: good PEBs: 504, bad PEBs: 0, corrupted PEBs: 0 [189672.870371]
>> UBI: user volume: 1, internal volumes: 1, max. volumes count: 128
>> [189672.870373] UBI: max/mean erase counter: 280/161, WL threshold:
>> 4096, image sequence number: 2041090957 [189672.870374] UBI:
>> available
>> PEBs: 0, total reserved PEBs: 504, PEBs reserved for bad PEB handling:
>> 0 [189672.870489] UBI: background thread "ubi_bgt0d" started, PID
>> 50742 [189689.698048] UBIFS: background thread "ubifs_bgt0_0"
>> started, PID 50750 [189689.698157] UBIFS: recovery needed
>> [189689.699949]
>> UBIFS: recovery completed
>This two lines arer interesting ... I see this message also in U-Boot code:
>./fs/ubifs/super.c in mount_ubifs() ...
>Why does this output not come in U-Boot?
>Maybe it is worth to look into this place too ...

 I don't know why I didn't got this lines before. Now the recovery
lines are there:
UBIFS DBG scan: look at LEB 2:76800 (54144 bytes left)
UBIFS DBG scan: hit empty space at LEB 2:76800
UBIFS DBG scan: stop scanning LEB 2 at offset 76800
UBIFS: recovery needed
UBI DBG gen (pid 1): read 11 bytes from LEB 0:8:130808
UBI DBG eba (pid 1): read 11 bytes from offset 130808 of LEB 0:8, PEB 349
UBI DBG io (pid 1): read 11 bytes from PEB 349:130936
UBIFS DBG lp: space_bits 14
UBIFS DBG lp: lpt_lnum_bits 2
UBIFS DBG lp: lpt_offs_bits 17
UBIFS DBG lp: lpt_spc_bits 17
UBIFS DBG lp: pcnt_bits 7
UBIFS DBG lp: lnum_bits 9
UBIFS DBG lp: pnode_sz 17
UBIFS DBG lp: nnode_sz 12
UBIFS DBG lp: ltab_sz 11
UBIFS DBG lp: lsave_sz 291
UBIFS DBG lp: lsave_cnt 256
UBIFS DBG lp: lpt_hght 4
UBIFS DBG lp: big_lpt 0
UBIFS DBG lp: LPT root is at 7:24
UBIFS DBG lp: LPT head is at 7:40
UBIFS DBG lp: LPT ltab is at 8:130808
UBIFS DBG rcvry: no orphans
UBIFS: recovery deferred
UBIFS: mounted UBI device 0, volume 0, name "flash", R/O mode
UBIFS: LEB size: 130944 bytes (127 KiB), min./max. I/O unit sizes: 8
bytes/1024 bytes
UBIFS: FS size: 61674624 bytes (58 MiB, 471 LEBs), journal size
8249472 bytes (7 MiB, 63 LEBs)
UBIFS: reserved for root: 0 bytes (0 KiB)
UBIFS: media format: w4/r0 (latest is w4/r0), UUID 07b5e7e0, small LPT model

>> [189689.700308] UBIFS: mounted UBI device 0, volume 0, name "flash"
>> [189689.700313] UBIFS: LEB size: 130944 bytes (127 KiB), min./max.
>> I/O unit sizes: 8 bytes/64 bytes [189689.700316] UBIFS: FS size:
>> 61674624 bytes (58 MiB, 471 LEBs), journal size 8249472 bytes (7 MiB,
>> 63 LEBs) [189689.700318] UBIFS: reserved for root: 0 bytes (0 KiB)
>> [189689.700321] UBIFS: media format: w4/r0 (latest is w4/r0), UUID
>> 370BF56B-8A90-443C-B344-BF6BA00A8634, small LPT model
>>
>>>> Here the output from U-Boot V2014.10:
>>>>
>>>> => ubi part fs
>>>> UBI: attaching mtd1 to ubi0
>>>> UBI: scanning is finished
>>>> UBI: attached mtd1 (name "mtd=0", size 63 MiB) to ubi0
>>>> UBI: PEB size: 131072 bytes (128 KiB), LEB size: 130944 bytes
>>>> UBI: min./max. I/O unit sizes: 1/64, sub-page size 1
>>>> UBI: VID header offset: 64 (aligned 64), data offset: 128
>>>> UBI: good PEBs: 504, bad PEBs: 0, corrupted PEBs: 0
>>>> UBI: user volume: 1, internal volumes: 1, max. volumes count: 128
>>>> UBI: max/mean erase counter: 280/161, WL threshold: 4096, image
>>>> sequence number: 2041090957
>>>> UBI: available PEBs: 0, total reserved PEBs: 504, PEBs reserved for
>>>> bad PEB handling: 0 => ubifsmount ubi:flash => ubifsls
>>>>         53549  Mon Dec 01 11:34:08 2014  setup.xml
>>>>          2051  Wed Nov 19 09:05:49 2014  LOG_Default_000001.csv
>>>>     filldir: Error in ubifs_iget(), ino=44049 ret=ffffffea!
>>
>>> seems a problem in ubifs_iget() fs/ubifs/super.c ... it returns -EINVAL please debug into this function for a starting point.
>>
>> Thank you for the hint. I will start from there.
>>

The interesting part I think will be the PEB 347 with the mapped LEB
159. Below the partial output form the ubifsls command:

UBIFS DBG gen: inode 44049
UBIFS DBG tnc: search key (44049, inode)
UBIFS DBG io: LEB 344:952, indexing node, length 148
UBI DBG gen (pid 1): read 148 bytes from LEB 0:344:952
UBI DBG eba (pid 1): read 148 bytes from offset 952 of LEB 0:344, PEB 472
UBI DBG io (pid 1): read 148 bytes from PEB 472:1080
UBIFS DBG tnc: LEB 344:952, level 1, 6 branch
UBIFS DBG io: LEB 344:824, indexing node, length 128
UBI DBG gen (pid 1): read 128 bytes from LEB 0:344:824
UBI DBG eba (pid 1): read 128 bytes from offset 824 of LEB 0:344, PEB 472
UBI DBG io (pid 1): read 128 bytes from PEB 472:952
UBIFS DBG tnc: LEB 344:824, level 0, 5 branch
UBIFS DBG tnc: found 1, lvl 0, n 0
UBIFS DBG tnc: LEB 159:45304, key (44049, inode)
UBIFS DBG io: LEB 159:45304, inode node, length 160
UBI DBG gen (pid 1): read 160 bytes from LEB 0:159:45304
UBI DBG eba (pid 1): read 160 bytes from offset 45304 of LEB 0:159, PEB 347
UBI DBG io (pid 1): read 160 bytes from PEB 347:45432
UBIFS DBG tnc: search key (44049, inode)
UBIFS DBG tnc: found 1, lvl 0, n 0
UBIFS DBG io: LEB 159:45304, inode node, length 160
UBI DBG gen (pid 1): read 160 bytes from LEB 0:159:45304
UBI DBG eba (pid 1): read 160 bytes from offset 45304 of LEB 0:159, PEB 347
UBI DBG io (pid 1): read 160 bytes from PEB 347:45432
UBIFS error: ubifs_read_node: bad node type (255 but expected 0)
UBI DBG gen (pid 1): test LEB 0:159
UBIFS error: ubifs_read_node: bad node at LEB 159:45304, LEB mapping status 1
Not a node, first 24 bytes:UBIFS DBG tnc: key (44049, inode)
UBIFS error: ubifs_iget: failed to read inode 44049, error -22
filldir: Error in ubifs_iget(), ino=44049 ret=ffffffea!
UBI DBG gen (pid 1): close device 0, volume 0, mode 1
=>

A mount of the same image with 3.13 under Linux, shows some
corruptions with strange output ("dangling branch" and "dangling
match"):
[367478.555403] fallible_read_node: UBIFS DBG tnc (pid 35692): LEB
159:45464, key (1, direntry, 0x69ce16c)
[367478.555405] try_read_node: UBIFS DBG io (pid 35692): LEB
159:45464, direntry node, length 79
[367478.555408] ubi_leb_read: UBI DBG gen (pid 35692): read 79 bytes
from LEB 0:159:45464
[367478.555410] ubi_eba_read_leb: UBI DBG eba (pid 35692): read 79
bytes from offset 45464 of LEB 0:159, PEB 13
[367478.555413] ubi_io_read: UBI DBG io (pid 35692): read 79 bytes
from PEB 13:45592
[367478.555416] fallible_read_node: UBIFS DBG mnt (pid 35692):
dangling branch LEB 159:45464 len 79, key (1, direntry, 0x69ce16c)
[367478.555420] ubifs_read_node: UBIFS DBG io (pid 35692): LEB
324:2144, indexing node, length 168
[367478.555422] ubi_leb_read: UBI DBG gen (pid 35692): read 168 bytes
from LEB 0:324:2144
[367478.555425] ubi_eba_read_leb: UBI DBG eba (pid 35692): read 168
bytes from offset 2144 of LEB 0:324, PEB 62
[367478.555427] ubi_io_read: UBI DBG io (pid 35692): read 168 bytes
from PEB 62:2272
[367478.555430] read_znode: UBIFS DBG tnc (pid 35692): LEB 324:2144,
level 1, 7 branch
[367478.555433] ubifs_read_node: UBIFS DBG io (pid 35692): LEB
324:920, indexing node, length 88
[367478.555435] ubi_leb_read: UBI DBG gen (pid 35692): read 88 bytes
from LEB 0:324:920
[367478.555438] ubi_eba_read_leb: UBI DBG eba (pid 35692): read 88
bytes from offset 920 of LEB 0:324, PEB 62
[367478.555440] ubi_io_read: UBI DBG io (pid 35692): read 88 bytes
from PEB 62:1048
[367478.555442] read_znode: UBIFS DBG tnc (pid 35692): LEB 324:920,
level 0, 3 branch
[367478.555445] ubifs_tnc_add_nm: UBIFS DBG tnc (pid 35692): rc
returned 0, znode ffff8801ac050000, n 5
[367478.555449] tnc_insert: UBIFS DBG tnc (pid 35692): inserted at 6
level 0, key (1, direntry, 0x69ce16c)
[367478.555452] ubifs_tnc_remove_nm: UBIFS DBG tnc (pid 35692): , key
(1, direntry, 0x69ce16c)
[367478.555455] lookup_level0_dirty: UBIFS DBG tnc (pid 35692): search
and dirty key (1, direntry, 0x69ce16c)
[367478.555458] lookup_level0_dirty: UBIFS DBG tnc (pid 35692): found
1, lvl 0, n 5
[367478.555461] fallible_read_node: UBIFS DBG tnc (pid 35692): LEB
159:45464, key (1, direntry, 0x69ce16c)
[367478.555463] try_read_node: UBIFS DBG io (pid 35692): LEB
159:45464, direntry node, length 79
[367478.555465] ubi_leb_read: UBI DBG gen (pid 35692): read 79 bytes
from LEB 0:159:45464
[367478.555468] ubi_eba_read_leb: UBI DBG eba (pid 35692): read 79
bytes from offset 45464 of LEB 0:159, PEB 13
[367478.555470] ubi_io_read: UBI DBG io (pid 35692): read 79 bytes
from PEB 13:45592
[367478.555474] fallible_read_node: UBIFS DBG mnt (pid 35692):
dangling branch LEB 159:45464 len 79, key (1, direntry, 0x69ce16c)
[367478.555476] fallible_read_node: UBIFS DBG tnc (pid 35692): LEB
198:38040, key (1, direntry, 0x69ce16c)
[367478.555479] try_read_node: UBIFS DBG io (pid 35692): LEB
198:38040, direntry node, length 79
[367478.555481] ubi_leb_read: UBI DBG gen (pid 35692): read 79 bytes
from LEB 0:198:38040
[367478.555484] ubi_eba_read_leb: UBI DBG eba (pid 35692): read 79
bytes from offset 38040 of LEB 0:198, PEB 44
[367478.555486] ubi_io_read: UBI DBG io (pid 35692): read 79 bytes
from PEB 44:38168
[367478.555490] fallible_resolve_collision: UBIFS DBG mnt (pid 35692):
dangling match LEB 159:45464 len 79 key (1, direntry, 0x69ce16c)
[367478.555492] ubifs_tnc_remove_nm: UBIFS DBG tnc (pid 35692): rc
returned 1, znode ffff8801ac050000, n 5
[367478.555495] tnc_delete: UBIFS DBG tnc (pid 35692): deleting key
(1, direntry, 0x69ce16c)
[367478.555498] ubifs_lpt_lookup_dirty: UBIFS DBG lp (pid 35692): LEB
159, free 104, dirty 130760, flags 1
[367478.555500] ubifs_change_lp: UBIFS DBG lp (pid 35692): LEB 159,
free -2147483647, dirty 130839, flags 1
[367478.555503] ubifs_lpt_lookup_dirty: UBIFS DBG lp (pid 35692): LEB
159, free 104, dirty 130760, flags 1

What does a "dangling branch" and "dangling match" mean? Are those
situations handled differently under U-Boot?

Anton