UBIFS corruption after power cut - possibly unstable bits issue?

Mon Oct 26 13:31:10 PDT 2015

On Mon, Oct 26, 2015 at 1:01 PM, Richard Weinberger <richard at nod.at> wrote:
> Tim,
>
> Am 26.10.2015 um 20:37 schrieb Tim Harvey:
>> Greetings,
>>
>> I'm looking into a re-producible ubifs corruption issue on an IMX6
>> based board with a 16Gb MT29F2G08 SLC NAND flash. During boot
>> reliability tests we can recreate perhaps 1 in 10000 cases of a UBIFS
>> corruption that results in a permanent failure to mount the rootfs.
>>
>> In this scenario the U-Boot bootloader first mounts the ubifs to load
>> the kernel/dtb from the /boot directory, then the kernel is mounting
>> the rootfs read-only, then later its mounted read/write via /etc/fstab
>> but is never written to directly by our software. Our software runs
>> various tests for several minutes then power-cuts the board.
>>
>> After corruption, U-Boot fails reading the superblock but if I load a
>> kernel/dtb from the net and boot it I see some more useful info from
>> the kernel:
>>
>> [    0.000000] Linux version 4.2.0-00012-gd722238 (tharvey at tharvey)
>> (gcc version 4.8.3 (OpenWrt/Linaro GCC 4.8-2014.04 r43990) ) #189 SMP
>> Fri Oct 23 16:24:27 PDT 2015
>> ...
>> [    2.375663] nand: device found, Manufacturer ID: 0x2c, Chip ID: 0xd5
>> [    2.382075] nand: Micron MT29F16G08ADACAH4
>> [    2.386190] nand: 2048 MiB, SLC, erase size: 256 KiB, page size:
>> 4096, OOB size: 224
>> [    2.394821] gpmi-nand 112000.gpmi-nand: enable the asynchronous EDO mode 5
>> [    2.401760] Scanning device for bad blocks
>> [    4.000436] 3 ofpart partitions found on MTD device gpmi-nand
>> [    4.006201] Creating 3 MTD partitions on "gpmi-nand":
>> [    4.011298] 0x000000000000-0x000001000000 : "uboot"
>> [    4.021174] 0x000001000000-0x000001100000 : "env"
>> [    4.028287] 0x000001100000-0x000080000000 : "rootfs"
>> [    4.037134] gpmi-nand 112000.gpmi-nand: driver registered.
>> ...
>> [    8.678875] ubi0: scanning is finished
>> [    8.706815] ubi0: attached mtd2 (name "rootfs", size 2031 MiB)
>> [    8.712710] ubi0: PEB size: 262144 bytes (256 KiB), LEB size: 253952 bytes
>> [    8.719598] ubi0: min./max. I/O unit sizes: 4096/4096, sub-page size 4096
>> [    8.726415] ubi0: VID header offset: 4096 (aligned 4096), data offset: 8192
>> [    8.733398] ubi0: good PEBs: 8124, bad PEBs: 0, corrupted PEBs: 0
>> [    8.739501] ubi0: user volume: 1, internal volumes: 1, max. volumes
>> count: 128
>> [    8.746748] ubi0: max/mean erase counter: 5/2, WL threshold: 4096,
>> image sequence number: 36433972
>> [    8.755747] ubi0: available PEBs: 0, total reserved PEBs: 8124,
>> PEBs reserved for bad PEB handling: 160
>> [    8.765357] ubi0: background thread "ubi_bgt0d" started, PID 79
>> ...
>> [    8.888732] UBIFS (ubi0:0): recovery needed
>> [    8.916292] ubi0 warning: ubi_io_read: error -74 (ECC error) while reading 36
>> 864 bytes from PEB 5195:225280, read only 36864 bytes, retry
>> [    8.931116] ubi0 warning: ubi_io_read: error -74 (ECC error) while reading 36
>> 864 bytes from PEB 5195:225280, read only 36864 bytes, retry
>> [    8.945869] ubi0 warning: ubi_io_read: error -74 (ECC error) while reading 36
>> 864 bytes from PEB 5195:225280, read only 36864 bytes, retry
>> [    8.960676] ubi0 error: ubi_io_read: error -74 (ECC error) while reading 3686
>> 4 bytes from PEB 5195:225280, read 36864 bytes
>> [    8.971859] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.2.0-00012-gd722238 #1
>> 89
>> [    8.979177] Hardware name: Freescale i.MX6 Quad/DualLite (Device Tree)
>> [    8.985747] Backtrace:
>> [    8.988248] [<80013468>] (dump_backtrace) from [<80013654>] (show_stack+0x18/
>> 0x1c)
>> [    8.995848]  r6:80abf960 r5:80abf960 r4:00000000 r3:00000000
>> [    9.001649] [<8001363c>] (show_stack) from [<80798948>]
>> (dump_stack+0x8c/0xa4)
>> [    9.008894] [<807988bc>] (dump_stack) from [<8045d410>]
>> (ubi_io_read+0x128/0x304)
>> [    9.016428]  r6:00000000 r5:00009000 r4:ffffffb6 r3:ee070000
>> [    9.022201] [<8045d2e8>] (ubi_io_read) from [<8045a650>]
>> (ubi_eba_read_leb+0x18c/0x430)
>> [    9.030210]  r10:00000000 r9:f069e000 r8:0000144b r7:00000179
>> r6:00000000 r5:edab6000
>> [    9.038189]  r4:edb10000
>> [    9.040783] [<8045a4c4>] (ubi_eba_read_leb) from [<80459a08>]
>> (ubi_leb_read+0x7c/0xd4)
>> [    9.048724]  r10:00000000 r9:00000179 r8:f069e000 r7:edb10000
>> r6:00035000 r5:00009000
>> [    9.056677]  r4:edab6000
>> [    9.059254] [<8045998c>] (ubi_leb_read) from [<80253c2c>]
>> (ubifs_leb_read+0x30/0x9c)
>> [    9.067044]  r10:ee034000 r9:edb55e40 r8:00000179 r7:00035000
>> r6:00009000 r5:ee034000
>> [    9.074996]  r4:edb55e40
>> [    9.077563] [<80253bfc>] (ubifs_leb_read) from [<8025bfe0>]
>> (ubifs_start_scan+0x74/0xf0)
>> [    9.085697]  r8:f0669000 r7:00000179 r6:ee034000 r5:00035000 r4:edb55e40
>> [    9.092575] [<8025bf6c>] (ubifs_start_scan) from [<8026e624>]
>> (ubifs_recover_leb+0x64/0x810)
>> [    9.101051]  r8:00009000 r7:00000179 r6:ee034000 r5:edb55cc0 r4:00000179
>> [    9.107850] [<8026e5c0>] (ubifs_recover_leb) from [<8025d890>]
>> (ubifs_replay_journal+0xed0/0x16a0)
>> [    9.116846]  r10:ee034000 r9:edb55e40 r8:edb55e48 r7:ee034000
>> r6:edb55cc0 r5:edb55cc0
>> [    9.124782]  r4:00000179
>> [    9.127344] [<8025c9c0>] (ubifs_replay_journal) from [<802515ec>]
>> (ubifs_mount+0x1234/0x19fc)
>> [    9.135906]  r10:00000001 r9:ee034008 r8:edb4a300 r7:eda92800
>> r6:ee034b38 r5:ee034000
>> [    9.143842]  r4:00000000
>> [    9.146411] [<802503b8>] (ubifs_mount) from [<80103c6c>] (mount_fs+0x1c/0xb0)
>> [    9.153578]  r10:00008001 r9:00000000 r8:80abc2e0 r7:801234a8
>> r6:80abc2e0 r5:edb4a280
>> [    9.161514]  r4:eda61400
>> [    9.164084] [<80103c50>] (mount_fs) from [<8011fedc>]
>> (vfs_kern_mount+0x5c/0x144)
>> [    9.171602]  r6:00008001 r5:edb4a280 r4:eda61400
>> [    9.176282] [<8011fe80>] (vfs_kern_mount) from [<801234a8>]
>> (do_mount+0x19c/0xd0c)
>> [    9.183886]  r9:80abc2e0 r8:80ab0bdc r7:edb4a240 r6:edb4a280
>> r5:00000060 r4:00000000
>> [    9.191743] [<8012330c>] (do_mount) from [<801243ac>] (SyS_mount+0x7c/0xa8)
>> [    9.198721]  r10:000000d5 r9:80a8d9c8 r8:8094cfa0 r7:00008001
>> r6:00000000 r5:edb4a280
>> [    9.206660]  r4:edb4a240
>> [    9.209227] [<80124330>] (SyS_mount) from [<80a3a248>]
>> (mount_block_root+0x114/0x240)
>> [    9.217091]  r8:ef5af1c0 r7:80a8d9b8 r6:edb8e000 r5:edb8e000 r4:00008001
>> [    9.223907] [<80a3a134>] (mount_block_root) from [<80a3a634>]
>> (prepare_namespace+0x98/0x1d0)
>> [    9.232380]  r10:000000d5 r9:80a8d998 r8:80a9b5c0 r7:80a8d990
>> r6:80a8d9b8 r5:80a8d9b8
>> [    9.240297]  r4:80a8d9c8
>> [    9.242877] [<80a3a59c>] (prepare_namespace) from [<80a39ee4>]
>> (kernel_init_freeable+0x1a4/0x1f0)
>> [    9.251780]  r6:80b09000 r5:80b09000 r4:00000007
>> [    9.256467] [<80a39d40>] (kernel_init_freeable) from [<80792cdc>]
>> (kernel_init+0x10/0xf4)
>> [    9.264667]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:
>> 80792ccc
>> [    9.272614]  r4:00000000
>> [    9.275177] [<80792ccc>] (kernel_init) from [<8000f938>]
>> (ret_from_fork+0x14/0x3c)
>> [    9.282782]  r4:00000000 r3:00000000
>> [    9.286909] UBIFS error (ubi0:0 pid 1): ubifs_recover_leb: corrupt
>> empty space LEB 377:217088, corruption starts at 24762
>> [    9.297900] UBIFS error (ubi0:0 pid 1): ubifs_scanned_corruption:
>> corruption at LEB 377:241850
>> [    9.306536] UBIFS error (ubi0:0 pid 1): ubifs_scanned_corruption:
>> first 8192 bytes from LEB 377:241850
>> [    9.315870] 00000000: ffffffef ffffffff ffffffff ffffffff ffffffff
>> ffffffff ffffffff ffffffff  ................................
>> [    9.327374] 00000020: ffffffff ffffffff ffffffff ffffffff ffffffff
>> ffffffff ffffffff ffffffff  ................................
>> [    9.338883] 00000040: ffffffff ffffffff ffffffff ffffffff ffffffff
>> ffffffff ffffffff ffffffff  ................................
>> [    9.350389] 00000060: ffffffff ffffffff ffffffff ffffffff ffffffff
>> ffffffff ffffffff ffffffff  ................................
>> ...
>> [    9.352755] 00001fc0: ffffffff ffffffff ffffffff ffffffff ffffffff ffffffff f
>> fffffff ffffffff  ................................
>> [    9.352765] 00001fe0: ffffffff ffffffff ffffffff ffffffff ffffffff ffffffff f
>> fffffff ffffffff  ................................
>> [    9.352770] UBIFS error (ubi0:0 pid 1): ubifs_recover_leb: LEB 377 scanning f
>> ailed
>> [   12.271485] VFS: Cannot open root device "ubi0:rootfs" or unknown-block(0,0):
>>  error -117
>>
>> Thus far we have encountered this with a 16Gb MT29F16G08 and 'not'
>> with a 2Gb MT29F2G08. The two parts have different geometries and the
>> 16Gb part has a much larger block erase time (2ms) compared to the 2Gb
>> (700us).
>
> gpmi-nand is not able to correct bit flips on erased pages.
> This is why UBI is facing uncorrectable ECC errors and UBIFS gives up.

Hi Richard,

What would be causing the bit-flips on the erased pages? Could it have
something to do with the larger flash part having a much longer erase
time?

There shouldn't be anything writing to ubifs so I'm not clear what
caused this to occur. Note that even if I remove the /etc/fstab that
causes root to be re-mounted read/write I always see 'UBIFS (ubi0:0):
recovery needed' and I'm not understanding what causes that but it
makes me think that NAND is getting touched each and every boot by the
recovery process.

> In March there was an attempt to fix that in software.
> But no mainline ready solution was presented so far:
> http://lists.infradead.org/pipermail/linux-mtd/2014-March/052521.html
>
> It is not clear whether to implement this directly in gpmi-nand or MTD core.
> Currently UBIFS assumes that empty spaces must contain only 0xff octets.
> A naive approach would be removing that check from UBIFS, bit this can have
> disastrous consequences as UBIFS's recovery algorithm relies on that.

I think I ran across that approach right before the thread you pointed
me to: http://thread.gmane.org/gmane.linux.drivers.mtd/52208

>
>> We have also seen several occurrences of errors on both NAND chips
>> that cause a failure to mount rootfs but are not permanent
>> (power-cycle again and all is well):
>> [17:39:02][    2.666800] ubi0: attaching mtd2
>> [17:39:05][    5.388606] ubi0: scanning is finished
>> [17:39:05][    5.395747] ubi0 error: vtbl_check: bad CRC at record 72:
>> 0xf116c36b, not 0x000000
>> [17:39:05][    5.403330] Volume table record 72 dump:
>> [17:39:05][    5.407279]        reserved_pebs   0
>> [17:39:05][    5.410342]        alignment       0
>> [17:39:05][    5.413402]        data_pad        0
>> [17:39:05][    5.416481]        vol_type        0
>> [17:39:05][    5.419543]        upd_marker      0
>> [17:39:05][    5.422603]        name_len        0
>> [17:39:05][    5.427696]        name            NULL
>> [17:39:05][    5.433237] ubi0 error: vtbl_check: bad CRC at record 72:
>> 0xf116c36b, not 0x000000
>> [17:39:05][    5.440846] Volume table record 72 dump:
>> [17:39:05][    5.446806]        reserved_pebs   0
>> [17:39:05][    5.451881]        alignment       0
>> [17:39:05][    5.456967]        data_pad        0
>> [17:39:05][    5.462042]        vol_type        0
>> [17:39:05][    5.467137]        upd_marker      0
>> [17:39:05][    5.472216]        name_len        0
>> [17:39:05][    5.475304]        name            NULL
>> [17:39:05][    5.478629] ubi0 error: process_lvol: both volume tables
>> are corrupted
>> [17:39:05][    5.492599] ubi0 error: ubi_attach_mtd_dev: failed to
>> attach mtd2, error -22
>> [17:39:05][    5.499728] UBI error: cannot attach mtd2
>>
>> Are any/all of the above the 'unstable bits' issue? Any
>
> Not really. Why do you think so?

No reason - it is just not clear to me how to know if you have run
into the 'unstable bits' issue.

>
>> recommendations on what to look for next?
>
> How does the corruption look like in the second case?
> Maybe we can identify a pattern. :-)

the second case is not permanent corruption - when the system is
power-cycled it comes up fine the next time.

Tim

>
> Thanks,
> //richard