ER-X-SFP ubiattach fails to mount mtd5 because of PEB errors

For Developers
1

Hopefully someone here can help...

ER-X-SFP booted initramfs image can't flash 4.x nor 5.4 snapshot image due to PEB errors in NAND partition, dmesg output:

UBI: auto-attach mtd5
[    6.713554] ubi0: attaching mtd5
[    7.168325] ubi0 error: ubi_attach: bad image sequence number 2018561425 in PEB 352, expected 940586124
[    7.187046] Erase counter header dump:
[    7.194507]  magic          0x55424923
[    7.201966]  version        1
[    7.207870]  ec             13
[    7.213947]  vid_hdr_offset 2048
[    7.220370]  data_offset    4096
[    7.226787]  image_seq      2018561425
[    7.234248]  hdr_crc        0x2ec7c84c
[    7.241705] erase counter header hexdump:
[    7.249845] ubi0 error: ubi_attach_mtd_dev: failed to attach mtd5, error -22
[    7.263919] UBI error: cannot attach mtd5

Problem is, it does perform ubiformat, notices PEB errors, and writes firmware image to mtd5, but upon reboot it ends in an kernel panic that it can't mount root partition.

Seems like a problem in NAND driver or ubiformat/ubiattach that can't perform error correction handling properly. Ubiquiti recovery image works fine, it ignores the PEB errors and is able to attach mtd partition...

Here's output from sysupgrade using latest snapshot:

Wed Apr 14 15:55:28 UTC 2021 upgrade: Commencing upgrade. Closing all shell sessions.
Watchdog handover: fd=3
- watchdog -
killall: telnetd: no process killed
Wed Apr 14 15:55:29 UTC 2021 upgrade: Sending TERM to remaining processes ... logd hostapd wpa_supplicant odhcpd ntpd netifd dnsmasq ubusd urngd
Wed Apr 14 15:55:32 UTC 2021 upgrade: Sending KILL to remaining processes ...
[  602.761607] sh (3018): drop_caches: 3
Wed Apr 14 15:55:33 UTC 2021 upgrade: Switching to ramdisk...
Wed Apr 14 15:55:35 UTC 2021 upgrade: Performing system upgrade...
[  604.792667] ubi0: attaching mtd5
[  605.248805] ubi0 error: ubi_attach: bad image sequence number 2018561425 in PEB 352, expected 940586124
[  605.267523] Erase counter header dump:
[  605.274983]  magic          0x55424923
[  605.282442]  version        1
[  605.288346]  ec             13
[  605.294420]  vid_hdr_offset 2048
[  605.300847]  data_offset    4096
[  605.307266]  image_seq      2018561425
[  605.314783]  hdr_crc        0x2ec7c84c
[  605.322247] erase counter header hexdump:
[  605.330403] ubi0 error: ubi_attach_mtd_dev: failed to attach mtd5, error -22
ubiattach: error!: cannot attach mtd5
           error 22 (Invalid argument)
1+0 records in
1+0 records out
Unlocking kernel1 ...

Writing from <stdin> to kernel1 ...
[  607.173582] ubi0: attaching mtd5
[  607.629015] ubi0 error: ubi_attach: bad image sequence number 2018561425 in PEB 352, expected 940586124
[  607.647731] Erase counter header dump:
[  607.655187]  magic          0x55424923
[  607.662645]  version        1
[  607.668548]  ec             13
[  607.674621]  vid_hdr_offset 2048
[  607.681049]  data_offset    4096
[  607.687491]  image_seq      2018561425
[  607.694949]  hdr_crc        0x2ec7c84c
[  607.702408] erase counter header hexdump:
[  607.710551] ubi0 error: ubi_attach_mtd_dev: failed to attach mtd5, error -22
ubiattach: error!: cannot attach mtd5
           error 22 (Invalid argument)
ubiformat: mtd5 (nand), size 259784704 bytes (247.7 MiB), 1982 eraseblocks of 131072 bytes (128.0 KiB), min. I/O size 2048 bytes
libscan: scanning eraseblock 1981 -- 100 % complete
ubiformat: 1981 eraseblocks have valid erase counter, mean value is 12
ubiformat: 1 bad eraseblocks found, numbers: 1748
ubiforma[  644.990090] ubi0: attaching mtd5 % complete
ubiformat: formatting eraseblock 1981 -- 100 % complete
[  645.449307] mt7621-nand 1e003000.nand: Uncorrectable ECC error at page 26241.0
[  645.464183] ubi0 warning: ubi_io_read: error -77 (ECC error) while reading 64 bytes from PEB 352:2048, read only 0 bytes, retry
[  645.487247] mt7621-nand 1e003000.nand: Uncorrectable ECC error at page 26241.0
[  645.502110] ubi0 warning: ubi_io_read: error -77 (ECC error) while reading 64 bytes from PEB 352:2048, read only 0 bytes, retry
[  645.525171] mt7621-nand 1e003000.nand: Uncorrectable ECC error at page 26241.0
[  645.540070] ubi0 warning: ubi_io_read: error -77 (ECC error) while reading 64 bytes from PEB 352:2048, read only 0 bytes, retry
[  645.563128] mt7621-nand 1e003000.nand: Uncorrectable ECC error at page 26241.0
[  645.577969] ubi0 error: ubi_io_read: error -77 (ECC error) while reading 64 bytes from PEB 352:2048, read 0 bytes
[  645.598408] CPU: 1 PID: 3635 Comm: ubiattach Not tainted 5.4.110 #0
[  645.610864] Stack : 8ff7e800 8007d738 80700000 806fa5e8 80760000 806fa5b0 806f9524 8ec85c74
[  645.627484]         80ab0000 8fe99fc8 80746d63 8068b274 00000001 00000001 8ec85c18 34c52616
[  645.644100]         00000000 00000000 80af0000 00000000 00000030 00000135 20646574 2e342e35
[  645.660716]         00000000 00000020 00000000 00092188 80000000 80760000 00000000 00000160
[  645.677333]         02c00800 00000000 00000800 00000000 00000002 8035c910 00000004 80ab0004
[  645.693951]         ...
[  645.698806] Call Trace:
[  645.703684] [<8000b64c>] show_stack+0x30/0x100
[  645.712523] [<805ca2e4>] dump_stack+0xa4/0xdc
[  645.721186] [<803ba4b0>] ubi_io_read+0x274/0x3a0
[  645.730366] [<803bab2c>] ubi_io_read_vid_hdr+0x6c/0x2b4
[  645.740760] [<803c062c>] ubi_attach+0x488/0x1594
[  645.749939] [<803b3e08>] ubi_attach_mtd_dev+0x5e4/0xb88
[  645.760328] [<803b52c8>] ctrl_cdev_ioctl+0x16c/0x1c4
[  645.770201] [<80191350>] do_vfs_ioctl+0xb8/0x7c0
[  645.779379] [<80191aa8>] ksys_ioctl+0x50/0xb4
[  645.788047] [<80014558>] syscall_common+0x34/0x58
[  645.797658] UBI assert failed in ubi_io_read at 190 (pid 3635)
[  645.809277] CPU: 1 PID: 3635 Comm: ubiattach Not tainted 5.4.110 #0
[  645.821731] Stack : 8ff7e800 8007d738 80700000 806fa5e8 80760000 806fa5b0 806f9524 8ec85c74
[  645.838348]         80ab0000 8fe99fc8 80746d63 8068b274 00000001 00000001 8ec85c18 34c52616
[  645.854967]         00000000 00000000 80af0000 00000000 00000030 00000148 20646574 2e342e35
[  645.871582]         00000000 00000020 00000000 000c593d 80000000 80760000 00000000 00000160
[  645.888198]         02c00800 00000000 00000800 00000000 00000002 8035c910 00000004 80ab0004
[  645.904814]         ...
[  645.909668] Call Trace:
[  645.914528] [<8000b64c>] show_stack+0x30/0x100
[  645.923361] [<805ca2e4>] dump_stack+0xa4/0xdc
[  645.932024] [<803ba4e8>] ubi_io_read+0x2ac/0x3a0
[  645.941204] [<803bab2c>] ubi_io_read_vid_hdr+0x6c/0x2b4
[  645.951603] [<803c062c>] ubi_attach+0x488/0x1594
[  645.960786] [<803b3e08>] ubi_attach_mtd_dev+0x5e4/0xb88
[  645.971178] [<803b52c8>] ctrl_cdev_ioctl+0x16c/0x1c4
[  645.981049] [<80191350>] do_vfs_ioctl+0xb8/0x7c0
[  645.990226] [<80191aa8>] ksys_ioctl+0x50/0xb4
[  645.998888] [<80014558>] syscall_common+0x34/0x58
[  646.008609] ubi0 error: ubi_attach_mtd_dev: failed to attach mtd5, error -5
ubiattach: error!: cannot attach mtd5
           error 5 (I/O error)
libubi: error!: "/dev/" is not a character device
ubimkvol: error!: error while probing "/dev/"
          error 22 (Invalid argument)
cannot create rootfs volume
libubi: error!: "/dev/" is not a character device
ubiupdatevol: error!: e[  646.088023] reboot: Restarting system
rror while probing "/dev/"
              error 22 (Invalid argument)
tar: write error: Broken pipe
sysupgrade successful
umount: can't unmount /dev: Resource busy
umount: can't unmount /tmp: Resource busy
2

Here's output using Ubiquiti Recovery image and flash with recent firmware version:

ubi0: attaching mtd7
mtk_nand: UnCorrectable at PageAddr=99393
ubi0 warning: ubi_io_read: error -77 (ECC error) while reading 64 bytes from PEB 1495:2048, read only 64 bytes, retry
mtk_nand: UnCorrectable at PageAddr=99393
ubi0 warning: ubi_io_read: error -77 (ECC error) while reading 64 bytes from PEB 1495:2048, read only 64 bytes, retry
mtk_nand: UnCorrectable at PageAddr=99393
ubi0 warning: ubi_io_read: error -77 (ECC error) while reading 64 bytes from PEB 1495:2048, read only 64 bytes, retry
mtk_nand: UnCorrectable at PageAddr=99393
ubi0 error: ubi_io_read: error -77 (ECC error) while reading 64 bytes from PEB 1495:2048, read 64 bytes
CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.14.54-UBNT #1
Stack : 00000000 00000000 00000000 00000000 81757c0a 00000039 00000000 0000000b
        8fc403d4 815c2ca7 81543ebc 00000000 00000001 00000001 8fc35bd0 815c8328
        00000000 00000000 81750000 00000007 00000000 00000000 0000009f 00000000
        00000000 00000000 0000009e 70617773 00000000 00000000 815f0000 8fc23000
        00000000 81570000 81573e54 81551900 00000008 812bbfd4 00000000 81750000
        ...
Call Trace:
[<8100f4c8>] show_stack+0x74/0x104
[<8149e92c>] dump_stack+0x9c/0xd0
[<813203f4>] ubi_io_read+0x270/0x314
[<81320928>] ubi_io_read_vid_hdr+0x94/0x204
[<81325cf4>] ubi_attach+0x500/0x135c
[<8131a6c4>] ubi_attach_mtd_dev+0x5bc/0xab4
[<81608c5c>] ubi_init+0x238/0x3c4
[<810056a8>] do_one_initcall+0x154/0x15c
[<815f2df8>] kernel_init_freeable+0x238/0x240
[<814b5948>] kernel_init+0x10/0x10c
[<8100a1d8>] ret_from_kernel_thread+0x14/0x1c
mtk_nand: UnCorrectable at PageAddr=100353
ubi0 warning: ubi_io_read: error -77 (ECC error) while reading 64 bytes from PEB 1510:2048, read only 64 bytes, retry
mtk_nand: UnCorrectable at PageAddr=100353
ubi0 warning: ubi_io_read: error -77 (ECC error) while reading 64 bytes from PEB 1510:2048, read only 64 bytes, retry
mtk_nand: UnCorrectable at PageAddr=100353
ubi0 warning: ubi_io_read: error -77 (ECC error) while reading 64 bytes from PEB 1510:2048, read only 64 bytes, retry
mtk_nand: UnCorrectable at PageAddr=100353
ubi0 error: ubi_io_read: error -77 (ECC error) while reading 64 bytes from PEB 1510:2048, read 64 bytes
CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.14.54-UBNT #1
Stack : 00000000 00000000 00000000 00000000 81757c0a 00000039 00000000 0000000b
        8fc403d4 815c2ca7 81543ebc 00000000 00000001 00000001 8fc35bd0 815c8328
        00000000 00000000 81750000 00000007 00000000 00000000 000000ba 00000000
        00000000 00000000 000000b9 70617773 00000000 00000000 815f0000 8fc23000
        00000000 81570000 81573e54 81551900 00000008 812bbfd4 00000000 81750000
        ...
Call Trace:
[<8100f4c8>] show_stack+0x74/0x104
[<8149e92c>] dump_stack+0x9c/0xd0
[<813203f4>] ubi_io_read+0x270/0x314
[<81320928>] ubi_io_read_vid_hdr+0x94/0x204
[<81325cf4>] ubi_attach+0x500/0x135c
[<8131a6c4>] ubi_attach_mtd_dev+0x5bc/0xab4
[<81608c5c>] ubi_init+0x238/0x3c4
[<810056a8>] do_one_initcall+0x154/0x15c
[<815f2df8>] kernel_init_freeable+0x238/0x240
[<814b5948>] kernel_init+0x10/0x10c
[<8100a1d8>] ret_from_kernel_thread+0x14/0x1c
ESW: Link Status Changed - Port0 Link UP
gsw_interrupt_mt7621: dev(link-up) = NULL
ubi0: scanning is finished
ubi0: attached mtd7 (name "RootFS", size 247 MiB)
ubi0: PEB size: 131072 bytes (128 KiB), LEB size: 126976 bytes
ubi0: min./max. I/O unit sizes: 2048/2048, sub-page size 2048
ubi0: VID header offset: 2048 (aligned 2048), data offset: 4096
ubi0: good PEBs: 1979, bad PEBs: 3, corrupted PEBs: 0
ubi0: user volume: 1, internal volumes: 1, max. volumes count: 128
ubi0: max/mean erase counter: 21/16, WL threshold: 4096, image sequence number: 1869315788
ubi0: available PEBs: 0, total reserved PEBs: 1979, PEBs reserved for bad PEB handling: 37
ubi0: background thread "ubi_bgt0d" started, PID 69
do_mount_squash_image: started
do_mount_squash_image: mkdir /root.dev
do_mount_squash_image: sys_mount ubi0_0 /root.dev ubifs
UBIFS (ubi0:0): background thread "ubifs_bgt0_0" started, PID 70
UBIFS (ubi0:0): UBIFS: mounted UBI device 0, volume 0, name "troot"
UBIFS (ubi0:0): LEB size: 126976 bytes (124 KiB), min./max. I/O unit sizes: 2048 bytes/2048 bytes
UBIFS (ubi0:0): FS size: 244428800 bytes (233 MiB, 1925 LEBs), journal size 12189696 bytes (11 MiB, 96 LEBs)
UBIFS (ubi0:0): reserved for root: 4952683 bytes (4836 KiB)
UBIFS (ubi0:0): media format: w4/r0 (latest is w5/r0), UUID 99C03E24-5D5A-4C5B-8B93-F8C26EA581EF, small LPT model
UBIFS (ubi0:0): full atime support is enabled.
do_mount_squash_image: Mounting squashfs image /dev/loop_root to /root.loop
do_mount_squash_image: mounting overlay fs to /root with params upperdir=/root.dev/w,lowerdir=/root.loop,workdir=/root.dev/work

Howcome Ubiquiti recovery image and firmware is able to ignore the PEB errors?