VF50 Kernel Panic starting with UBIFS error (ubi0:2 pid 1)

Fielded VF50 unit came back for repair after failing to boot upon power up. Hardware/software versions:

  • Toradex Colibri VF50 128MB V1.2B
  • Viola Plus V1.2B
  • Colibri-VF_Console-Image_2.7-20180104.tar.bz2
  • U-Boot 2016.11-2.7.4+g1b121c6

System presents kernel panic and comparing a good system with this failing system indicates the first signs of failure with the following line:

[    3.875937] UBIFS error (ubi0:2 pid 1): read_pnode: error -22 reading pnode at 8:6184

Earlier in the boot process, there is another line that shows something that may be interesting, only because these max/mean numbers are much higher than typically witnessed for known good systems:

ubi0: max/mean erase counter: 406/56, WL threshold: 4096, image sequence number: 0

We have reviewed all the BSP updated from the 2.7 release all the way through to the 5 release and do not see any obvious fixes related to this issue. We have seen other similar issues reported with UBI in releases 2.5 and earlier, but they appear to have been fixed in 2.6 and later.

Thanks for any insight you may lend.

Compete boot log is here:

U-Boot 2016.11-2.7.4+g1b121c6 (Oct 05 2017 - 03:30:34 +0000)

CPU: Freescale Vybrid VF500 at 396 MHz
Reset cause: POWER ON RESET
DRAM:  128 MiB
NAND:  128 MiB
MMC:   FSL_SDHC: 0
*** Warning - bad CRC, using default environment

In:    serial
Out:   serial
Err:   serial
Model: Toradex Colibri VF50 128MB V1.2B, Serial# 08467324
Net:   FEC
Hit any key to stop autoboot:  0
Booting from NAND...
ubi0: default fastmap pool size: 50
ubi0: default fastmap WL pool size: 25
ubi0: attaching mtd1
ubi0: attached by fastmap
ubi0: fastmap pool size: 50
ubi0: fastmap WL pool size: 25
ubi0: attached mtd1 (name "mtd=3", size 126 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: 1002, bad PEBs: 6, corrupted PEBs: 0
ubi0: user volume: 3, internal volumes: 1, max. volumes count: 128
ubi0: max/mean erase counter: 406/56, WL threshold: 4096, image sequence number: 0
ubi0: available PEBs: 0, total reserved PEBs: 1002, PEBs reserved for bad PEB handling: 14
Read 0 bytes from volume kernel to 81000000
No size specified -> Using max size (4757176)
Read 0 bytes from volume dtb to 82000000
No size specified -> Using max size (25108)
Kernel image @ 0x81000000 [ 0x000000 - 0x4896b8 ]
## Flattened Device Tree blob at 82000000
   Booting using the fdt blob at 0x82000000
   Using Device Tree in place at 82000000, end 82009213

Starting kernel ...

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 4.4.88-2.7.4+ge0f2806 (yocto@1d53c4004829) (gcc version 6.2.1 20161016 (Linaro GCC 6.2-2016.11) ) #1 T7
[    0.000000] CPU: ARMv7 Processor [410fc051] revision 1 (ARMv7), cr=10c5387d
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[    0.000000] Machine model: Toradex Colibri VF50 on Colibri Evaluation Board
[    0.000000] cma: Reserved 16 MiB at 0x86c00000
[    0.000000] Memory policy: Data cache writeback
[    0.000000] CPU: All CPU(s) started in SVC mode.
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 32004
[    0.000000] Kernel command line: ubi.mtd=ubi root=ubi0:rootfs rw rootfstype=ubifs ubi.fm_autoconvert=1 console=tty1 console=ttyL)
[    0.000000] PID hash table entries: 512 (order: -1, 2048 bytes)
[    0.000000] Dentry cache hash table entries: 16384 (order: 4, 65536 bytes)
[    0.000000] Inode-cache hash table entries: 8192 (order: 3, 32768 bytes)
[    0.000000] Memory: 102436K/129024K available (6095K kernel code, 218K rwdata, 2148K rodata, 228K init, 183K bss, 10204K reserve)
[    0.000000] Virtual kernel memory layout:
[    0.000000]     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
[    0.000000]     fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
[    0.000000]     vmalloc : 0x88000000 - 0xff800000   (1912 MB)
[    0.000000]     lowmem  : 0x80000000 - 0x87e00000   ( 126 MB)
[    0.000000]     modules : 0x7f000000 - 0x80000000   (  16 MB)
[    0.000000]       .text : 0x80008000 - 0x80814fdc   (8244 kB)
[    0.000000]       .init : 0x80815000 - 0x8084e000   ( 228 kB)
[    0.000000]       .data : 0x8084e000 - 0x808849e0   ( 219 kB)
[    0.000000]        .bss : 0x808849e0 - 0x808b25e8   ( 184 kB)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] NR_IRQS:16 nr_irqs:16 16
[    0.000053] sched_clock: 64 bits at 132MHz, resolution 7ns, wraps every 2199023255551ns
[    0.000121] clocksource: arm_global_timer: mask: 0xffffffffffffffff max_cycles: 0x1e7178659b, max_idle_ns: 440795204301 ns
[    0.001231] Console: colour dummy device 80x30
[    0.002327] console [tty1] enabled
[    0.002411] Calibrating delay loop... 262.96 BogoMIPS (lpj=1314816)
[    0.070290] pid_max: default: 32768 minimum: 301
[    0.070630] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.070732] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.072695] CPU: Testing write buffer coherency: ok
[    0.073688] Setting up static identity map for 0x80008200 - 0x80008258
[    0.077650] devtmpfs: initialized
[    0.096125] VFP support v0.3: implementor 41 architecture 2 part 30 variant 5 rev 1
[    0.097247] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.097457] futex hash table entries: 256 (order: -1, 3072 bytes)
[    0.100749] pinctrl core: initialized pinctrl subsystem
[    0.104119] NET: Registered protocol family 16
[    0.108105] DMA: preallocated 256 KiB pool for atomic coherent allocations
[    0.110914] cpuidle: using governor menu
[    0.145833] irq: no irq domain found for /soc/aips-bus@40000000/gpio@40049000 !
[    0.149731] PM: CKE/RESET pulls available, enable Suspend-to-RAM
[    0.150920] hw-breakpoint: found 2 (+1 reserved) breakpoint and 1 watchpoint registers.
[    0.151053] hw-breakpoint: maximum watchpoint size is 4 bytes.
[    0.153808] vf610-pinctrl 40048000.iomuxc: initialized IMX pinctrl driver
[    0.201631] SCSI subsystem initialized
[    0.202712] usbcore: registered new interface driver usbfs
[    0.203023] usbcore: registered new interface driver hub
[    0.203417] usbcore: registered new device driver usb
[    0.206226] i2c i2c-0: IMX I2C adapter registered
[    0.206478] i2c i2c-0: using dma0chan0 (tx) and dma0chan1 (rx) for DMA transfers
[    0.207018] Linux video capture interface: v2.00
[    0.207465] pps_core: LinuxPPS API ver. 1 registered
[    0.207551] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti 
[    0.207768] PTP clock support registered
[    0.209145] Advanced Linux Sound Architecture Driver Initialized.
[    0.212716] clocksource: Switched to clocksource arm_global_timer
[    0.253655] NET: Registered protocol family 2
[    0.256008] TCP established hash table entries: 1024 (order: 0, 4096 bytes)
[    0.256172] TCP bind hash table entries: 1024 (order: 0, 4096 bytes)
[    0.256274] TCP: Hash tables configured (established 1024 bind 1024)
[    0.256653] UDP hash table entries: 256 (order: 0, 4096 bytes)
[    0.256776] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes)
[    0.257355] NET: Registered protocol family 1
[    0.258479] RPC: Registered named UNIX socket transport module.
[    0.258600] RPC: Registered udp transport module.
[    0.258663] RPC: Registered tcp transport module.
[    0.258724] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.261182] hw perfevents: enabled with armv7_cortex_a5 PMU driver, 3 counters available
[    0.288021] NFS: Registering the id_resolver key type
[    0.288261] Key type id_resolver registered
[    0.288345] Key type id_legacy registered
[    0.288528] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    0.290394] ntfs: driver 2.1.32 [Flags: R/W].
[    0.291948] fuse init (API version 7.23)
[    0.311672] io scheduler noop registered
[    0.311806] io scheduler deadline registered
[    0.312404] io scheduler cfq registered (default)
[    0.328604] 40027000.serial: ttyLP0 at MMIO 0x40027000 (irq = 19, base_baud = 4125000) is a FSL_LPUART
[    0.843182] console [ttyLP0] enabled
[    0.849816] [drm] Initialized drm 1.1.0 20060810
[    0.865363] [drm] Supports vblank timestamp caching Rev 2 (21.10.2013).
[    0.872082] [drm] No driver support for vblank timestamp query.
[    0.922295] Console: switching to colour frame buffer device 80x30
[    0.954908] fsl-dcu 40058000.dcu: fb0:  frame buffer device
[    0.970316] [drm] Initialized fsl-dcu-drm 1.0.0 20150213 on minor 0
[    1.009454] loop: module loaded
[    1.026605] nand: device found, Manufacturer ID: 0xc2, Chip ID: 0xf1
[    1.043276] nand: Macronix MX30LF1G18AC
[    1.057447] nand: 128 MiB, SLC, erase size: 128 KiB, page size: 2048, OOB size: 64
[    1.086317] Bad block table found at page 65472, version 0x01
[    1.103018] Bad block table found at page 65408, version 0x01
[    1.119257] nand_read_bbt: bad block at 0x0000013c0000
[    1.134707] nand_read_bbt: bad block at 0x000006ae0000
[    1.150124] 4 cmdlinepart partitions found on MTD device vf610_nfc
[    1.166533] Creating 4 MTD partitions on "vf610_nfc":
[    1.181664] 0x000000000000-0x000000020000 : "vf-bcb"
[    1.198140] 0x000000020000-0x000000180000 : "u-boot"
[    1.214590] 0x000000180000-0x000000200000 : "u-boot-env"
[    1.231369] 0x000000200000-0x000008000000 : "ubi"
[    1.256696] +V3.3: supplied by 3.3V
[    1.271926] pps pps0: new PPS source ptp0
[    1.296551] libphy: fec_enet_mii_bus: probed
[    1.312014] fec 400d1000.ethernet eth0: registered PHC device 0
[    1.328695] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    1.345998] usbcore: registered new interface driver usb-storage
[    1.362378] usbcore: registered new interface driver usbserial
[    1.377864] usbcore: registered new interface driver usbserial_generic
[    1.393744] usbserial: USB Serial support registered for generic
[    1.409077] usbcore: registered new interface driver ftdi_sio
[    1.424186] usbserial: USB Serial support registered for FTDI USB Serial Device
[    1.449388] usbcore: registered new interface driver pl2303
[    1.464335] usbserial: USB Serial support registered for pl2303
[    1.483518] 40034000.usb supply vbus not found, using dummy regulator
[    1.501809] mousedev: PS/2 mouse device common for all mice
[    1.521738] rtc-ds1307 0-0068: rtc core: registered m41t0 as rtc0
[    1.539573] snvs_rtc 400a7000.snvs:snvs-rtc-lp: rtc core: registered 400a7000.snvs:snvs- as rtc1
[    1.568259] i2c /dev entries driver
[    1.586848] imx2-wdt 4003e000.wdog: timeout 60 sec (nowayout=0)
[    1.603445] sdhci: Secure Digital Host Controller Interface driver
[    1.619977] sdhci: Copyright(c) Pierre Ossman
[    1.634770] sdhci-pltfm: SDHCI platform and OF driver helper
[    1.652641] /soc/aips-bus@40080000/esdhc@400b2000: voltage-ranges unspecified
[    1.671087] sdhci-esdhc-imx 400b2000.esdhc: Got CD GPIO
[    1.688128] sdhci-esdhc-imx 400b2000.esdhc: No vmmc regulator found
[    1.705632] sdhci-esdhc-imx 400b2000.esdhc: No vqmmc regulator found
[    1.763317] mmc0: SDHCI controller on 400b2000.esdhc [400b2000.esdhc] using ADMA
[    1.795181] hidraw: raw HID events driver (C) Jiri Kosina
[    1.812597] usbcore: registered new interface driver usbhid
[    1.829856] usbhid: USB HID core driver
[    1.865551] Netfilter messages via NETLINK v0.30.
[    1.881851] nfnl_acct: registering with nfnetlink.
[    1.898079] nf_conntrack version 0.5.0 (1856 buckets, 7424 max)
[    1.916666] nf_tables: (c) 2007-2009 Patrick McHardy 
[    1.935819] ip_tables: (C) 2000-2006 Netfilter Core Team
[    1.954527] NET: Registered protocol family 10
[    1.973732] ip6_tables: (C) 2000-2006 Netfilter Core Team
[    1.990302] NET: Registered protocol family 17
[    2.005798] bridge: automatic filtering via arp/ip/ip6tables has been deprecated. Update your scripts to load br_netfilter if yo.
[    2.040158] Bridge firewalling registered
[    2.055303] 8021q: 802.1Q VLAN Support v1.8
[    2.070502] Key type dns_resolver registered
[    2.085902] Registering SWP/SWPB emulation handler
[    2.104354] registered taskstats version 1
[    2.125860] 40034000.usb supply vbus not found, using dummy regulator
[    2.149108] ci_hdrc ci_hdrc.0: EHCI Host Controller
[    2.164564] ci_hdrc ci_hdrc.0: new USB bus registered, assigned bus number 1
[    2.202892] ci_hdrc ci_hdrc.0: USB 2.0 started, EHCI 1.00
[    2.221973] hub 1-0:1.0: USB hub found
[    2.236475] hub 1-0:1.0: 1 port detected
[    2.253124] VCC_USB[1-4]: supplied by 5V
[    2.271820] ci_hdrc ci_hdrc.1: EHCI Host Controller
[    2.286955] ci_hdrc ci_hdrc.1: new USB bus registered, assigned bus number 2
[    2.322927] ci_hdrc ci_hdrc.1: USB 2.0 started, EHCI 1.00
[    2.341111] hub 2-0:1.0: USB hub found
[    2.356103] hub 2-0:1.0: 1 port detected
[    2.373544] input: colibri-vf50-ts as /devices/platform/vf50-touchscreen/input/input0
[    2.405610] ubi0: default fastmap pool size: 50
[    2.420344] ubi0: default fastmap WL pool size: 25
[    2.435013] ubi0: attaching mtd3
[    2.549587] ubi0: attached by fastmap
[    2.562663] ubi0: fastmap pool size: 50
[    2.575453] ubi0: fastmap WL pool size: 25
[    2.600518] ubi0: attached mtd3 (name "ubi", size 126 MiB)
[    2.615020] ubi0: PEB size: 131072 bytes (128 KiB), LEB size: 126976 bytes
[    2.631058] ubi0: min./max. I/O unit sizes: 2048/2048, sub-page size 2048
[    2.647183] ubi0: VID header offset: 2048 (aligned 2048), data offset: 4096
[    2.663664] ubi0: good PEBs: 1002, bad PEBs: 6, corrupted PEBs: 0
[    2.679170] ubi0: user volume: 3, internal volumes: 1, max. volumes count: 128
[    2.704755] ubi0: max/mean erase counter: 406/56, WL threshold: 4096, image sequence number: 0
[    2.732573] ubi0: available PEBs: 0, total reserved PEBs: 1002, PEBs reserved for bad PEB handling: 14
[    2.762670] ubi0: background thread "ubi_bgt0d" started, PID 67
[    2.783782] rtc-ds1307 0-0068: setting system clock to 2021-03-21 13:51:37 UTC (1616334697)
[    2.833089] usb 2-1: new high-speed USB device number 2 using ci_hdrc
[    2.851118] ALSA device list:
[    2.865493]   No soundcards found.
[    2.883348] UBIFS (ubi0:2): background thread "ubifs_bgt0_2" started, PID 69
[    2.938907] UBIFS (ubi0:2): recovery needed
[    3.875937] UBIFS error (ubi0:2 pid 1): read_pnode: error -22 reading pnode at 8:6184
[    3.906825] (pid 1) dumping pnode:
[    3.922033]  address 86135b00 parent 86135a80 cnext 0
[    3.939155]  flags 0 iip 3 level 0 num 0
[    3.955219]  0: free 0 dirty 131016 flags 1 lnum 0
[    3.972198]  1: free 0 dirty 126568 flags 1 lnum 0
[    3.988804]  2: free 0 dirty 125896 flags 1 lnum 0
[    4.005057]  3: free 0 dirty 126576 flags 1 lnum 0
[    4.020945] CPU: 0 PID: 1 Comm: swapper Not tainted 4.4.88-2.7.4+ge0f2806 #1
[    4.039334] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
[    4.057095] Backtrace:
[    4.070550] [<800134ac>] (dump_backtrace) from [<800136a4>] (show_stack+0x18/0x1c)
[    4.099903]  r7:00000003 r6:86135b00 r5:ffffffea r4:86b6b000
[    4.117044] [<8001368c>] (show_stack) from [<802a9b18>] (dump_stack+0x24/0x28)
[    4.145807] [<802a9af4>] (dump_stack) from [<80233724>] (ubifs_get_pnode.part.4+0x24c/0x2dc)
[    4.176065] [<802334d8>] (ubifs_get_pnode.part.4) from [<8023519c>] (ubifs_lpt_lookup_dirty+0x260/0x2b0)
[    4.207752]  r10:00000008 r9:861350a4 r8:00000006 r7:00000000 r6:000001fc r5:86b6b000
[    4.239072]  r4:00000002
[    4.253062] [<80234f3c>] (ubifs_lpt_lookup_dirty) from [<80238a68>] (ubifs_update_one_lp+0x3c/0x170)
[    4.285105]  r10:00000008 r9:00000000 r8:80000001 r7:00000207 r6:86b6b85c r5:86b6b000
[    4.316922]  r4:0000060a r3:00000000
[    4.332665] [<80238a2c>] (ubifs_update_one_lp) from [<802265ec>] (ubifs_tnc_remove_range+0xfc/0x284)
[    4.366642]  r8:86b6b000 r7:8613b648 r6:00000060 r5:00000002 r4:8613b600
[    4.387240] [<802264f0>] (ubifs_tnc_remove_range) from [<80226a8c>] (ubifs_tnc_remove_ino+0x12c/0x13c)
[    4.423727]  r10:00011f93 r9:ffffffff r8:86135680 r7:00011f94 r6:00000000 r5:86b6b000
[    4.459287]  r4:fffffffe
[    4.475346] [<80226960>] (ubifs_tnc_remove_ino) from [<80229548>] (ubifs_replay_journal+0xe44/0x1528)
[    4.511536]  r10:86843cf8 r9:860c9240 r8:86b6b960 r7:20000000 r6:86b6b000 r5:00000000
[    4.546920]  r4:860c9260
[    4.562847] [<80228704>] (ubifs_replay_journal) from [<8021e2a8>] (ubifs_mount+0x115c/0x17e4)
[    4.597704]  r10:86b6b1b0 r9:00000000 r8:0001e5a0 r7:86b6b000 r6:8600e4c0 r5:86bb7c00
[    4.632193]  r4:00000000
[    4.647695] [<8021d14c>] (ubifs_mount) from [<800ce374>] (mount_fs+0x1c/0xac)
[    4.668321]  r10:8085f768 r9:80857034 r8:00000000 r7:8085f768 r6:8085f768 r5:8600e440
[    4.702767]  r4:8021d14c
[    4.718050] [<800ce358>] (mount_fs) from [<800e64dc>] (vfs_kern_mount+0x50/0xfc)
[    4.750903]  r6:00008000 r5:8600e440 r4:86ba9000
[    4.768780] [<800e648c>] (vfs_kern_mount) from [<800e9194>] (do_mount+0x1a8/0xbb4)
[    4.801695]  r9:80857034 r8:8600e400 r7:8600e440 r6:00008000 r5:00000020 r4:00000000
[    4.835403] [<800e8fec>] (do_mount) from [<800e9f1c>] (SyS_mount+0x94/0xc0)
[    4.855520]  r10:8075c638 r9:80840868 r8:00008000 r7:8075c638 r6:00000000 r5:8600e400
[    4.889539]  r4:8600e440
[    4.904901] [<800e9e88>] (SyS_mount) from [<808162b4>] (mount_block_root+0x138/0x264)
[    4.938068]  r8:87db20e0 r7:00008000 r6:80840858 r5:86007000 r4:86007000
[    4.958217] [<8081617c>] (mount_block_root) from [<808165b4>] (prepare_namespace+0xa4/0x1a0)
[    4.992664]  r10:80840838 r9:00000008 r8:80815600 r7:80840834 r6:80884a00 r5:80840868
[    5.027001]  r4:80840858
[    5.042256] [<80816510>] (prepare_namespace) from [<80815ef0>] (kernel_init_freeable+0x1d0/0x1e0)
[    5.077170]  r5:80884a00 r4:8081238c
[    5.093792] [<80815d20>] (kernel_init_freeable) from [<805f6d3c>] (kernel_init+0x10/0xf0)
[    5.127847]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:805f6d2c
[    5.162484]  r4:00000000
[    5.178264] [<805f6d2c>] (kernel_init) from [<8000f838>] (ret_from_fork+0x14/0x3c)
[    5.211814]  r5:805f6d2c r4:00000000
[    5.228481] UBIFS error (ubi0:2 pid 1): read_pnode: calc num: 127
[    5.247470] UBIFS error (ubi0:2 pid 1): ubifs_update_one_lp: cannot update properties of LEB 519, error -22
[    5.282005] znode 8613b600, LEB 545:43168 len 188 parent 8613b500 iip 0 level 0 child_cnt 8 flags 1
[    5.316154] zbranches:
[    5.330872]  0: LNC   (null) LEB 519:0 len 1972 key (73619, data, 49)
[    5.349905]  1: LNC   (null) LEB 519:1976 len 1546 key (73619, data, 50)
[    5.368992]  2: LNC   (null) LEB 519:3528 len 1937 key (73619, data, 51)
[    5.387690]  3: LNC   (null) LEB 557:22360 len 1420 key (73619, data, 52)
[    5.406231]  4: LNC   (null) LEB 569:102664 len 1551 key (73619, data, 53)
[    5.424642]  5: LNC   (null) LEB 569:104216 len 1352 key (73619, data, 54)
[    5.442609]  6: LNC   (null) LEB 557:26664 len 1381 key (73619, data, 55)
[    5.460631]  7: LNC   (null) LEB 557:28728 len 1847 key (73619, data, 56)
[    5.485358] UBIFS (ubi0:2): background thread "ubifs_bgt0_2" stops
[    5.541182] UBIFS (ubi0:2): recovery needed
[    6.330256] UBIFS error (ubi0:2 pid 1): read_pnode: error -22 reading pnode at 8:6184
[    6.358889] (pid 1) dumping pnode:
[    6.372366]  address 860ca580 parent 860ca600 cnext 0
[    6.387367]  flags 0 iip 3 level 0 num 0
[    6.401261]  0: free 0 dirty 131016 flags 1 lnum 0
[    6.415897]  1: free 0 dirty 126568 flags 1 lnum 0
[    6.430047]  2: free 0 dirty 125896 flags 1 lnum 0
[    6.443990]  3: free 0 dirty 126576 flags 1 lnum 0
[    6.457602] CPU: 0 PID: 1 Comm: swapper Not tainted 4.4.88-2.7.4+ge0f2806 #1
[    6.473869] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
[    6.489455] Backtrace:
[    6.500690] [<800134ac>] (dump_backtrace) from [<800136a4>] (show_stack+0x18/0x1c)
[    6.526000]  r7:00000003 r6:860ca580 r5:ffffffea r4:86b6b000
[    6.541272] [<8001368c>] (show_stack) from [<802a9b18>] (dump_stack+0x24/0x28)
[    6.567510] [<802a9af4>] (dump_stack) from [<80233724>] (ubifs_get_pnode.part.4+0x24c/0x2dc)
[    6.596169] [<802334d8>] (ubifs_get_pnode.part.4) from [<8023519c>] (ubifs_lpt_lookup_dirty+0x260/0x2b0)
[    6.627322]  r10:00000008 r9:86bb4ba4 r8:00000006 r7:00000000 r6:000001fc r5:86b6b000
[    6.658315]  r4:00000002
[    6.672203] [<80234f3c>] (ubifs_lpt_lookup_dirty) from [<80238a68>] (ubifs_update_one_lp+0x3c/0x170)
[    6.704122]  r10:00000008 r9:00000000 r8:80000001 r7:00000207 r6:86b6b85c r5:86b6b000
[    6.735807]  r4:0000060a r3:00000000
[    6.751457] [<80238a2c>] (ubifs_update_one_lp) from [<802265ec>] (ubifs_tnc_remove_range+0xfc/0x284)
[    6.785326]  r8:86b6b000 r7:860f5648 r6:00000060 r5:00000002 r4:860f5600
[    6.805826] [<802264f0>] (ubifs_tnc_remove_range) from [<80226a8c>] (ubifs_tnc_remove_ino+0x12c/0x13c)
[    6.842213]  r10:00011f93 r9:ffffffff r8:860caa00 r7:00011f94 r6:00000000 r5:86b6b000
[    6.877760]  r4:fffffffe
[    6.893743] [<80226960>] (ubifs_tnc_remove_ino) from [<80229548>] (ubifs_replay_journal+0xe44/0x1528)
[    6.929836]  r10:86843cf8 r9:8609e1c0 r8:86b6b960 r7:20000000 r6:86b6b000 r5:00000000
[    6.965095]  r4:8609e1e0
[    6.980851] [<80228704>] (ubifs_replay_journal) from [<8021e2a8>] (ubifs_mount+0x115c/0x17e4)
[    7.015626]  r10:86b6b1b0 r9:00000000 r8:0001e5a0 r7:86b6b000 r6:86122f80 r5:86070c00
[    7.050001]  r4:00000002
[    7.065302] [<8021d14c>] (ubifs_mount) from [<800ce374>] (mount_fs+0x1c/0xac)
[    7.085858]  r10:8085f768 r9:80857034 r8:00000000 r7:8085f768 r6:8085f768 r5:86122040
[    7.120087]  r4:8021d14c
[    7.135389] [<800ce358>] (mount_fs) from [<800e64dc>] (vfs_kern_mount+0x50/0xfc)
[    7.168124]  r6:00008001 r5:86122040 r4:8613b000
[    7.185886] [<800e648c>] (vfs_kern_mount) from [<800e9194>] (do_mount+0x1a8/0xbb4)
[    7.218698]  r9:80857034 r8:86122000 r7:86122040 r6:00008001 r5:00000060 r4:00000000
[    7.252322] [<800e8fec>] (do_mount) from [<800e9f1c>] (SyS_mount+0x94/0xc0)
[    7.272343]  r10:8075c638 r9:80840868 r8:00008001 r7:8075c638 r6:00000000 r5:86122000
[    7.306215]  r4:86122040
[    7.321497] [<800e9e88>] (SyS_mount) from [<808162b4>] (mount_block_root+0x138/0x264)
[    7.354550]  r8:87db20e0 r7:00008001 r6:80840858 r5:86007000 r4:86007000
[    7.374487] [<8081617c>] (mount_block_root) from [<808165b4>] (prepare_namespace+0xa4/0x1a0)
[    7.408827]  r10:80840838 r9:00000008 r8:80815600 r7:80840834 r6:80884a00 r5:80840868
[    7.442971]  r4:80840858
[    7.458137] [<80816510>] (prepare_namespace) from [<80815ef0>] (kernel_init_freeable+0x1d0/0x1e0)
[    7.492955]  r5:80884a00 r4:8081238c
[    7.509494] [<80815d20>] (kernel_init_freeable) from [<805f6d3c>] (kernel_init+0x10/0xf0)
[    7.543499]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:805f6d2c
[    7.577915]  r4:00000000
[    7.593507] [<805f6d2c>] (kernel_init) from [<8000f838>] (ret_from_fork+0x14/0x3c)
[    7.627024]  r5:805f6d2c r4:00000000
[    7.643482] UBIFS error (ubi0:2 pid 1): read_pnode: calc num: 127
[    7.662422] UBIFS error (ubi0:2 pid 1): ubifs_update_one_lp: cannot update properties of LEB 519, error -22
[    7.696924] znode 860f5600, LEB 545:43168 len 188 parent 860f5500 iip 0 level 0 child_cnt 8 flags 1
[    7.731018] zbranches:
[    7.745693]  0: LNC   (null) LEB 519:0 len 1972 key (73619, data, 49)
[    7.764660]  1: LNC   (null) LEB 519:1976 len 1546 key (73619, data, 50)
[    7.783695]  2: LNC   (null) LEB 519:3528 len 1937 key (73619, data, 51)
[    7.802315]  3: LNC   (null) LEB 557:22360 len 1420 key (73619, data, 52)
[    7.820792]  4: LNC   (null) LEB 569:102664 len 1551 key (73619, data, 53)
[    7.839150]  5: LNC   (null) LEB 569:104216 len 1352 key (73619, data, 54)
[    7.857054]  6: LNC   (null) LEB 557:26664 len 1381 key (73619, data, 55)
[    7.875015]  7: LNC   (null) LEB 557:28728 len 1847 key (73619, data, 56)
[    7.900034] List of all partitions:
[    7.914072] No filesystem could mount root, tried:  ubifs
[    7.930250] Kernel panic - not syncing: VFS: Unable to mount root fs on unknown-block(0,0)
[    7.959122] ---[ end Kernel panic - not syncing: VFS: Unable to mount root fs on unknown-block(0,0)

Greetings @John011!

We’ve seen such issues on NAND-based modules in the past. As you already investigated, this is related to some UBIFS issue. While it seemed to have been solved in an earlier kernel version, we still saw issues like these on other modules.

The first thing I would suggest you to do is to try our BSP 2.8.7, which is the latest BSP version supported on the Vybrid-based modules. We’ve ran some tests with this BSP version and the UBIFS issues seem to have been solved. You could set up a testing gig to randomly force-reboot the module by cutting the power supply to try to reproduce the issue faster.

Thank you gustavo.tx. We are in the process of setting up the power cut test environment, starting with the existing image. We will then test the 2.8.7 image. Can you share any test results or characterization of such regarding your BSP 2.8.7 testing? For instance, did pre-2.8.7 create boot issues after x power cuts, on average, and BSP 2.8.7 tested up to y power cuts without ever creating an issue? Related, was there a particular bug fix in 2.8.7 that addressed the issue? As you can imagine, BSP updates require a lot of additional testing as part of the release process.

Hi @John011!

All testing we have conducted were essentially empirical and at the same time comparing with the older BSP. From this, we have not seen the issue happen anymore.

I’ll contact the BSP team to try to get more information about this - I know that this bug was supposed to be fixed since we’ve worked with some UBIFS maintainers, but if I recall correctly, we introduced some changes in the kernel configuration to assure this would work correctly.

Another reason I recommend you to upgrade your BSP - if viable - is that BSP 2.7 is not supported anymore, while BSP 2.8.7 will be supported for quite some time still.

FYI, we performed 1000s of power cut tests on the aforementioned configuration. To use an old break-up line, “it’s not you, it’s me”. We were performing network status writes to the file system that, sometimes, got caught in the middle of a power-cut. About half the time this created the kernel panic above, the other half the time creating a read-only-file system that booted (still problematic).

Summary of results:

All tests were run, in a loop, with a 10 second power off time followed by a random, even distribution of 10 - 1000 second power on time.

Base System (Colibri-VF_Console-Image_2.7-20180104.tar.bz2 + U-Boot 2016.11-2.7.4+g1b121c6):

1040 Power Cuts, 0 issues.

Base System + Application Performing Regular Network Status Writes to File System:

211 Mean-Power-Cuts-Before-Failure, 123 Min, 336 Max

Base System + Application Without Regular Network Status Writes to File System:

1253 Power Cuts, 0 issues.

If you agree, I’m happy to mark this as “Answered” as I explore 100% reliable ways to both write data (logs, telemetry, etc.) and endure power cuts in the middle of writes. If the 2.8.7 BSP is known to specifically address power-cut-while-writing-to-FS, let me know and we will slot time to update and test in the lab.

@John011,

Thanks for your feedback!

I agree. I think the best way to deal with this is to try to solve this by treating the power cut event by e.g. using an external battery for maintaining the supply while Linux elegantly shuts down (by using the gpio-poweroff feature, for example).

I’ll report this to the BSP team so I can check if was specifically dealt with. On my side, I wasn’t able to reproduce the issue neither on BSP 2.8.7 nor on BSP 3.0.4, but this also might depend on the way or how much you’re writing to the flash.