[U-Boot] Unreadable UBIFS partition after power cuts

Fri Jan 16 16:10:38 CET 2015

Hello Heiko

>>>>
>>>> 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

>> [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.555463] 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
********************************************************************************************************************************
This email message, including any attachments, is for the sole use of the intended recipient(s) and may contain 
confidential and privileged information. Any unauthorized review, use, disclosure or distribution is prohibited. 
If you are not the intended recipient, please contact the sender by reply e-mail and destroy all copies of the original message. 
[Delta Energy Systems]
********************************************************************************************************************************