Re: How the bad blocks occured in despite MTD manages the bad blocks

[Richard Weinberger <richard.weinberger@xxxxxxxxx>]

On Fri, Oct 4, 2019 at 8:36 AM JH <jupiter.hce@xxxxxxxxx> wrote:
> I did checked the full boot message, could not figure out what could
> be causes. Sorry, I attached following lengthy full boot message here
> in case if anyone doesn't mind to read it.
>
> U-Boot 2018.03-g4505467374-dirty (Jun 24 2019 - 07:07:18 +0000)
>
> CPU:   Freescale i.MX6ULZ rev1.1 900 MHz (running at 396 MHz)
> CPU:   Commercial temperature grade (0C to 95C) at 49C
> Reset cause: POR
> Model: Freescale i.MX6 ULZ 14x14 EVK Board
> Board: MX6ULZ 14x14 EVK
> DRAM:  512 MiB
> NAND:  256 MiB
> MMC:   FSL_SDHC: 0
> Loading Environment from NAND... *** Warning - bad CRC, using default
> environment
>
> Failed (-5)
> No panel detected: default to TFT43AB
> Display: TFT43AB (480x272)
> Video: LCDIF@0x21c8000 is fused, disable it
> In:    serial
> Out:   serial
> Err:   serial
> Net:   No ethernet found.
> Normal Boot
> Hit any key to stop autoboot:  0
> Booting image 1
>
> NAND read: device 0 offset 0x800000, size 0x2000000
>  33554432 bytes read: OK
>
> NAND read: device 0 offset 0x600000, size 0x200000
>  2097152 bytes read: OK
> Kernel image @ 0x80800000 [ 0x000000 - 0x89e1d8 ]
> ## Flattened Device Tree blob at 83000000
>    Booting using the fdt blob at 0x83000000
>    Using Device Tree in place at 83000000, end 83008a3b
> ft_system_setup for mx6
>
> Starting kernel ...
>
> [    0.000000] Booting Linux on physical CPU 0x0
> [    0.000000] Linux version 5.1.0-rc4 (oe-user@oe-host) (gcc version
> 8.2.0 (GCC)) #1 SMP Fri Jul 19 10:17:53 UTC 2019
> [    0.000000] CPU: ARMv7 Processor [410fc075] revision 5 (ARMv7), cr=10c5387d
> [    0.000000] CPU: div instructions available: patching division code
> [    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing
> instruction cache
> [    0.000000] OF: fdt: Machine model: Traverse PMU
> [    0.000000] earlycon: ec_imx6q0 at MMIO 0x02020000 (options '')
> [    0.000000] printk: bootconsole [ec_imx6q0] enabled
> [    0.000000] Memory policy: Data cache writealloc
> [    0.000000] cma: Reserved 64 MiB at 0x8c000000
> [    0.000000] random: get_random_bytes called from
> start_kernel+0x88/0x498 with crng_init=0
> [    0.000000] percpu: Embedded 18 pages/cpu @(ptrval) s42152 r8192
> d23384 u73728
> [    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 65024
> [    0.000000] Kernel command line: console=ttymxc0,115200 earlycon
> init=/init mtdparts=gpmi-nand:4m(boot),2m(ubootenv),2m(dtb),32m(kernel1),32m(kernel2),-(u1
> [    0.000000] Dentry cache hash table entries: 32768 (order: 5, 131072 bytes)
> [    0.000000] Inode-cache hash table entries: 16384 (order: 4, 65536 bytes)
> [    0.000000] Memory: 167912K/262144K available (11264K kernel code,
> 957K rwdata, 4016K rodata, 1024K init, 7759K bss, 28696K reserved,
> 65536K cma-reserved,)
> [    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
> [    0.000000] Running RCU self tests
> [    0.000000] rcu: Hierarchical RCU implementation.
> [    0.000000] rcu:     RCU event tracing is enabled.
> [    0.000000] rcu:     RCU lockdep checking is enabled.
> [    0.000000] rcu:     RCU restricting CPUs from NR_CPUS=4 to nr_cpu_ids=1.
> [    0.000000] rcu: RCU calculated value of scheduler-enlistment delay
> is 10 jiffies.
> [    0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=1
> [    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
> [    0.000000] Switching to timer-based delay loop, resolution 41ns
> [    0.000020] sched_clock: 32 bits at 24MHz, resolution 41ns, wraps
> every 89478484971ns
> [    0.007841] clocksource: mxc_timer1: mask: 0xffffffff max_cycles:
> 0xffffffff, max_idle_ns: 79635851949 ns
> [    0.020743] Console: colour dummy device 80x30
> [    0.022433] Lock dependency validator: Copyright (c) 2006 Red Hat,
> Inc., Ingo Molnar
> [    0.030976] ... MAX_LOCKDEP_SUBCLASSES:  8
> [    0.034255] ... MAX_LOCK_DEPTH:          48
> [    0.038432] ... MAX_LOCKDEP_KEYS:        8191
> [    0.042878] ... CLASSHASH_SIZE:          4096
> [    0.047130] ... MAX_LOCKDEP_ENTRIES:     32768
> [    0.051568] ... MAX_LOCKDEP_CHAINS:      65536
> [    0.056080] ... CHAINHASH_SIZE:          32768
> [    0.060443]  memory used by lock dependency info: 5243 kB
> [    0.065836]  per task-struct memory footprint: 1536 bytes
> [    0.071454] Calibrating delay loop (skipped), value calculated
> using timer frequency.. 48.00 BogoMIPS (lpj=240000)
> [    0.081683] pid_max: default: 32768 minimum: 301
> [    0.087076] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
> [    0.092944] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
> [    0.105333] *** VALIDATE proc ***
> [    0.107415] *** VALIDATE cgroup1 ***
> [    0.109429] *** VALIDATE cgroup2 ***
> [    0.113008] CPU: Testing write buffer coherency: ok
> [    0.120820] /cpus/cpu@0 missing clock-frequency property
> [    0.123533] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
> [    0.134792] Setting up static identity map for 0x80100000 - 0x80100078
> [    0.139896] rcu: Hierarchical SRCU implementation.
> [    0.147572] smp: Bringing up secondary CPUs ...
> [    0.149311] smp: Brought up 1 node, 1 CPU
> [    0.153304] SMP: Total of 1 processors activated (48.00 BogoMIPS).
> [    0.159652] CPU: All CPU(s) started in SVC mode.
> [    0.171440] devtmpfs: initialized
> [    0.209634] VFP support v0.3: implementor 41 architecture 2 part 30
> variant 7 rev 5
> [    0.216702] clocksource: jiffies: mask: 0xffffffff max_cycles:
> 0xffffffff, max_idle_ns: 19112604462750000 ns
> [    0.224550] futex hash table entries: 256 (order: 2, 16384 bytes)
> [    0.236652] pinctrl core: initialized pinctrl subsystem
> [    0.251598] NET: Registered protocol family 16
> [    0.312381] DMA: preallocated 256 KiB pool for atomic coherent allocations
> [    0.324702] cpuidle: using governor menu
> [    0.360531] vdd3p0: supplied by regulator-dummy
> [    0.366441] cpu: supplied by regulator-dummy
> [    0.371887] vddsoc: supplied by regulator-dummy
> [    0.417888] No ATAGs?
> [    0.418592] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4
> watchpoint registers.
> [    0.426407] hw-breakpoint: maximum watchpoint size is 8 bytes.
> [    0.441233] imx6ul-pinctrl 20e0000.iomuxc: initialized IMX pinctrl driver
> [    0.447210] imx6ul-pinctrl 2290000.iomuxc-snvs: no groups defined
> in /soc/aips-bus@2200000/iomuxc-snvs@2290000
> [    0.455241] imx6ul-pinctrl 2290000.iomuxc-snvs: initialized IMX
> pinctrl driver
> [    0.605091] mxs-dma 1804000.dma-apbh: initialized
> [    0.617322] vgaarb: loaded
> [    0.620125] SCSI subsystem initialized
> [    0.624426] usbcore: registered new interface driver usbfs
> [    0.628041] usbcore: registered new interface driver hub
> [    0.632923] usbcore: registered new device driver usb
> [    0.640600] media: Linux media interface: v0.10
> [    0.642570] videodev: Linux video capture interface: v2.00
> [    0.649142] pps_core: LinuxPPS API ver. 1 registered
> [    0.652766] pps_core: Software ver. 5.3.6 - Copyright 2005-2007
> Rodolfo Giometti <giometti@xxxxxxxx>
> [    0.662184] PTP clock support registered
> [    0.668159] Advanced Linux Sound Architecture Driver Initialized.
> [    0.678663] Bluetooth: Core ver 2.22
> [    0.679715] NET: Registered protocol family 31
> [    0.684068] Bluetooth: HCI device and connection manager initialized
> [    0.690490] Bluetooth: HCI socket layer initialized
> [    0.695286] Bluetooth: L2CAP socket layer initialized
> [    0.700475] Bluetooth: SCO socket layer initialized
> [    0.711109] clocksource: Switched to clocksource mxc_timer1
> [    2.186322] VFS: Disk quotas dquot_6.6.0
> [    2.187802] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
> [    2.263331] NET: Registered protocol family 2
> [    2.270257] tcp_listen_portaddr_hash hash table entries: 128
> (order: 0, 5120 bytes)
> [    2.275687] TCP established hash table entries: 2048 (order: 1, 8192 bytes)
> [    2.282595] TCP bind hash table entries: 2048 (order: 4, 73728 bytes)
> [    2.289082] TCP: Hash tables configured (established 2048 bind 2048)
> [    2.296310] UDP hash table entries: 256 (order: 2, 20480 bytes)
> [    2.301214] UDP-Lite hash table entries: 256 (order: 2, 20480 bytes)
> [    2.308146] NET: Registered protocol family 1
> [    2.317247] RPC: Registered named UNIX socket transport module.
> [    2.320541] RPC: Registered udp transport module.
> [    2.325450] RPC: Registered tcp transport module.
> [    2.329916] RPC: Registered tcp NFSv4.1 backchannel transport module.
> [    2.345957] hw perfevents: enabled with armv7_cortex_a7 PMU driver,
> 5 counters available
> [    2.362619] Initialise system trusted keyrings
> [    2.366106] workingset: timestamp_bits=30 max_order=16 bucket_order=0
> [    2.419270] NFS: Registering the id_resolver key type
> [    2.422320] Key type id_resolver registered
> [    2.425730] Key type id_legacy registered
> [    2.430121] jffs2: version 2.2. (NAND) © 2001-2006 Red Hat, Inc.
> [    2.439454] fuse init (API version 7.29)
> [    2.535396] Key type asymmetric registered
> [    2.537020] Asymmetric key parser 'x509' registered
> [    2.543723] io scheduler mq-deadline registered
> [    2.546097] io scheduler kyber registered
> [    2.573333] imx-sdma 20ec000.sdma: Direct firmware load for
> imx/sdma/sdma-imx6q.bin failed with error -2
> [    2.580243] imx-sdma 20ec000.sdma: Falling back to syfs fallback
> for: imx/sdma/sdma-imx6q.bin
> [    2.619406] printk: console [ttymxc0] enabled
> [    2.624297] printk: bootconsole [ec_imx6q0] disabled
> [    2.631542] random: fast init done
> [    2.643677] 21e8000.serial: ttymxc1 at MMIO 0x21e8000 (irq = 50,
> base_baud = 5000000) is a IMX
> [    2.657514] 21f0000.serial: ttymxc3 at MMIO 0x21f0000 (irq = 51,
> base_baud = 5000000) is a IMX
> [    2.764057] brd: module loaded
> [    2.833811] loop: module loaded
> [    2.879822] nand: device found, Manufacturer ID: 0xef, Chip ID: 0xda
> [    2.886527] nand: Winbond W29N02GV
> [    2.890038] nand: 256 MiB, SLC, erase size: 128 KiB, page size:
> 2048, OOB size: 64
> [    2.903981] Bad block table found at page 131008, version 0x01
> [    2.910824] Bad block table found at page 130944, version 0x01
> [    2.918440] 6 cmdlinepart partitions found on MTD device gpmi-nand
> [    2.924934] Creating 6 MTD partitions on "gpmi-nand":
> [    2.930120] 0x000000000000-0x000000400000 : "boot"
> [    2.956533] 0x000000400000-0x000000600000 : "ubootenv"
> [    2.974802] 0x000000600000-0x000000800000 : "dtb"
> [    2.992638] 0x000000800000-0x000002800000 : "kernel1"
> [    3.050303] 0x000002800000-0x000004800000 : "kernel2"
> [    3.108184] 0x000004800000-0x000010000000 : "ubi"
> [    3.366580] gpmi-nand 1806000.gpmi-nand: driver registered.
> [    3.380236] libphy: Fixed MDIO Bus: probed
> [    3.388114] CAN device driver interface
> [    3.397695] usbcore: registered new interface driver r8152
> [    3.403745] usbcore: registered new interface driver lan78xx
> [    3.409823] usbcore: registered new interface driver asix
> [    3.415759] usbcore: registered new interface driver ax88179_178a
> [    3.422359] usbcore: registered new interface driver cdc_ether
> [    3.428613] usbcore: registered new interface driver smsc95xx
> [    3.434851] usbcore: registered new interface driver net1080
> [    3.440999] usbcore: registered new interface driver cdc_subset
> [    3.447258] usbcore: registered new interface driver zaurus
> [    3.453357] usbcore: registered new interface driver MOSCHIP
> usb-ethernet driver
> [    3.461380] usbcore: registered new interface driver cdc_ncm
> [    3.467368] usbcore: registered new interface driver qmi_wwan
> [    3.473369] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
> [    3.479995] ehci-pci: EHCI PCI platform driver
> [    3.484901] ehci-mxc: Freescale On-Chip EHCI Host driver
> [    3.492047] usbcore: registered new interface driver cdc_wdm
> [    3.498155] usbcore: registered new interface driver usb-storage
> [    3.510549] imx_usb 2184000.usb: No over current polarity defined
> [    3.707122] imx_usb 2184200.usb: 2184200.usb supply vbus not found,
> using dummy regulator
> [    3.722611] ci_hdrc ci_hdrc.1: EHCI Host Controller
> [    3.728546] ci_hdrc ci_hdrc.1: new USB bus registered, assigned bus number 1
> [    3.761274] ci_hdrc ci_hdrc.1: USB 2.0 started, EHCI 1.00
> [    3.770155] usb usb1: New USB device found, idVendor=1d6b,
> idProduct=0002, bcdDevice= 5.01
> [    3.779159] usb usb1: New USB device strings: Mfr=3, Product=2,
> SerialNumber=1
> [    3.786644] usb usb1: Product: EHCI Host Controller
> [    3.791769] usb usb1: Manufacturer: Linux 5.1.0-rc4 ehci_hcd
> [    3.797537] usb usb1: SerialNumber: ci_hdrc.1
> [    3.811992] hub 1-0:1.0: USB hub found
> [    3.816554] hub 1-0:1.0: 1 port detected
> [    3.838398] input: 20cc000.snvs:snvs-powerkey as
> /devices/soc0/soc/2000000.aips-bus/20cc000.snvs/20cc000.snvs:snvs-powerkey/input/input0
> [    3.867744] snvs_rtc 20cc000.snvs:snvs-rtc-lp: registered as rtc0
> [    3.875054] i2c /dev entries driver
> [    3.895722] imx2-wdt 20bc000.wdog: timeout 60 sec (nowayout=0)
> [    3.903370] Bluetooth: HCI UART driver ver 2.3
> [    3.907940] Bluetooth: HCI UART protocol H4 registered
> [    3.913554] Bluetooth: HCI UART protocol LL registered
> [    3.921954] sdhci: Secure Digital Host Controller Interface driver
> [    3.928249] sdhci: Copyright(c) Pierre Ossman
> [    3.933587] sdhci-pltfm: SDHCI platform and OF driver helper
> [    3.992450] mmc0: SDHCI controller on 2190000.usdhc [2190000.usdhc]
> using ADMA
> [    4.028277] usbcore: registered new interface driver usbhid
> [    4.034359] usbhid: USB HID core driver
> [    4.096782] NET: Registered protocol family 10
> [    4.122741] Segment Routing with IPv6
> [    4.127141] sit: IPv6, IPv4 and MPLS over IPv4 tunneling driver
> [    4.145670] NET: Registered protocol family 17
> [    4.150322] can: controller area network core (rev 20170425 abi 9)
> [    4.181595] NET: Registered protocol family 29
> [    4.186185] can: raw protocol (rev 20170425)
> [    4.191093] can: broadcast manager protocol (rev 20170425 t)
> [    4.204443] mmc0: Tuning failed, falling back to fixed sampling clock
> [    4.211646] can: netlink gateway (rev 20170425) max_hops=1
> [    4.218423] Key type dns_resolver registered
> [    4.251192] cpu cpu0: failed to disable 696MHz OPP
> [    4.269933] mmc0: new ultra high speed SDR104 SDIO card at address 0001
> [    4.281074] Registering SWP/SWPB emulation handler
> [    4.295017] Loading compiled-in X.509 certificates
> [    4.401264] imx_thermal tempmon: Commercial CPU temperature grade -
> max:95C critical:90C passive:85C
> [    4.414659] ubi0: default fastmap pool size: 70
> [    4.419399] ubi0: default fastmap WL pool size: 35
> [    4.424414] ubi0: attaching mtd5
> [    5.741419] ubi0: scanning is finished
> [    5.765232] ubi0: attached mtd5 (name "ubi", size 184 MiB)
> [    5.770786] ubi0: PEB size: 131072 bytes (128 KiB), LEB size: 126976 bytes
> [    5.777904] ubi0: min./max. I/O unit sizes: 2048/2048, sub-page size 2048
> [    5.784831] ubi0: VID header offset: 2048 (aligned 2048), data offset: 4096
> [    5.791912] ubi0: good PEBs: 1468, bad PEBs: 4, corrupted PEBs: 0
> [    5.798050] ubi0: user volume: 1, internal volumes: 1, max. volumes
> count: 128
> [    5.805390] ubi0: max/mean erase counter: 18/6, WL threshold: 4096,
> image sequence number: 1971059169
> [    5.814721] ubi0: available PEBs: 104, total reserved PEBs: 1364,
> PEBs reserved for bad PEB handling: 36
> [    5.825275] ubi0: background thread "ubi_bgt0d" started, PID 109
> [    5.833109] snvs_rtc 20cc000.snvs:snvs-rtc-lp: setting system clock
> to 1970-01-01T00:00:01 UTC (1)
> [    5.842699] cfg80211: Loading compiled-in X.509 certificates for
> regulatory database
> [    5.858035] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
> [    5.867119] platform regulatory.0: Direct firmware load for
> regulatory.db failed with error -2
> [    5.876069] platform regulatory.0: Falling back to syfs fallback
> for: regulatory.db
> [    5.884070] ALSA device list:
> [    5.887081]   No soundcards found.
> [    5.898591] UBIFS (ubi0:0): Mounting in unauthenticated mode
> [    5.906283] UBIFS (ubi0:0): background thread "ubifs_bgt0_0" started, PID 115
> [    5.933292] random: crng init done
> [    6.021577] UBIFS (ubi0:0): UBIFS: mounted UBI device 0, volume 0,
> name "rootfs_data"
> [    6.029462] UBIFS (ubi0:0): LEB size: 126976 bytes (124 KiB),
> min./max. I/O unit sizes: 2048 bytes/2048 bytes
> [    6.039536] UBIFS (ubi0:0): FS size: 166338560 bytes (158 MiB, 1310
> LEBs), journal size 8380416 bytes (7 MiB, 66 LEBs)
> [    6.050394] UBIFS (ubi0:0): reserved for root: 4952683 bytes (4836 KiB)
> [    6.057136] UBIFS (ubi0:0): media format: w4/r0 (latest is w5/r0),
> UUID E9F1667C-8AC1-4030-BB1A-9C5341482A61, small LPT model
> [    6.074491] VFS: Mounted root (ubifs filesystem) on device 0:13.

So, UBIFS is happy and mounts cleanly.

> [    6.085038] devtmpfs: mounted
> [    6.090385] Freeing unused kernel memory: 1024K
> [    6.096157] Run /init as init process
> [    6.622933] systemd[1]: System time before build time, advancing clock.
> [    6.773833] systemd[1]: systemd 239 running in system mode. (-PAM
> -AUDIT -SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP -LIBCRYPTSETUP
> -GCRYPT -GNUTLS +AC)
> [    6.799488] systemd[1]: Detected architecture arm.
>
> Welcome to OpenEmbedded nodistro.0!
>
> [    6.880787] systemd[1]: Set hostname to <solar>.
> [    7.619506] systemd[1]: File
> /lib/systemd/system/systemd-journald.service:36 configures an IP
> firewall (IPAddressDeny=any), but the local system does not .
> [    7.638096] systemd[1]: Proceeding WITHOUT firewalling in effect!
> (This warning is only shown for the first loaded unit using IP
> firewalling.)
> [    8.206122] systemd[1]: sasolar.service: Found ordering cycle on
> multi-user.target/start
> [    8.214677] systemd[1]: sasolar.service: Found dependency on
> sacronjob.service/start
> [    8.222958] systemd[1]: sasolar.service: Found dependency on
> sasolar.service/stop
> [    8.230508] systemd[1]: sasolar.service: Job
> sacronjob.service/start deleted to break ordering cycle starting with
> sasolar.service/stop
> [ SKIP ] Ordering cycle found, skipping SA third run cron job
> [    8.318161] systemd[1]: Reached target Swap.
> [  OK  ] Reached target Swap.
> [  OK  ] Started Dispatch Password Requests to Console Directory Watch.
> [  OK  ] Listening on udev Kernel Socket.
> [  OK  ] Created slice system-serial\x2dgetty.slice.
> [  OK  ] Reached target Remote File Systems.
> [  OK  ] Listening on Journal Socket.
>          Mounting Kernel Debug File System...
>          Starting Apply Kernel Variables...
>          Mounting FUSE Control File System...
> [    8.732692] systemd[126]: sys-kernel-debug.mount: Failed to execute
> command: No such file or directory
> [    8.742715] systemd[128]: sys-fs-fuse-connections.mount: Failed to
> execute command: No such file or directory

Some files are missing but it does not look like a UBIFS corruption.
In case of corruption (such as dead directory entry) UBIFS would cry out loud.

I don't see a problem which points to the storage stack.

______________________________________________________
Linux MTD discussion mailing list
http://lists.infradead.org/mailman/listinfo/linux-mtd/