Re: [U-Boot] Unreadable UBIFS partition after power cuts

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
participants (1)
-
Anton Habegger