File System becomes read only

mnicolas · September 13, 2021, 12:11pm

Hello,

I have an issue with a Toradex VF61running Angstrom Linux: after a few minutes the filesystem (from the flash drive embedded in the Toradex) becomes read only. If I reboot, it comes back to being read/write for some time.

Here is the result of the mount command at startup:
root@AlbenV3_0479:~# mount
ubi0:rootfs on / type ubifs (rw,relatime)
[…]

After a while the command returns the following

root@AlbenV3_0479:~# mount
ubi0:rootfs on / type ubifs (ro,relatime)
[…]

In dmesg, I can see the following error messages:

[ 713.365751] UBIFS error (ubi0:2 pid 6): make_reservation: cannot reserve 160 bytes in jhead 1, error -30
[ 713.403502] UBIFS error (ubi0:2 pid 6): ubifs_write_inode: can’t write inode 15698, error -30
[ 713.440763] systemd-journald[76]: Failed to rotate /var/log/journal/f1b32112fab04150ae6d14b327a4115e/system.journal: Read-only file system
[ 713.487999] systemd-journald[76]: Failed to write entry (9 items, 312 bytes), ignoring: Input/output error

Any idea of what could cause this problem? Is this a hardware issue (damaged flash drive)?
Thanks!

Mario

henrique.tx · September 13, 2021, 5:15pm

Hi @mnicolas !

Can you share more information about what is happening?

Module version?
Which Carrier Board and version?
Which Operating system version?
Is there any application running the files? Or even, is there any “non-default” application running at all?
Can you share the full boot log of the module?

Best regards,

mnicolas · September 14, 2021, 9:35am

Hello,

here is the requested information:

Module VF61 version : V1.2B 256MB IT
Carrier Board: Iris version 1.1B
Linux embedded 4.4.59-2.7.2 (colobri vf linux image 2.7)
Yes, we have proprietary applications running. Most of the modified files are stored in RAM file system and later sent via network or stored in an external SD, which is working. The main file system mainly contains configuration files that are occasionally modified
The log is full of “Failed to write entry” entries

rafael.tx · September 14, 2021, 6:57pm

Hi @mnicolas, it would be really nice if you could attach the full log output of the boot (connected to serial interface, from the u-boot output forward). The log should include both the time when the fs is mounted RW and also when the fs is mounted RO. With this information we can try to analyze if there are more clues pointing to a bad flash chip or if there is another problem.

Best regards,
Rafael

mnicolas · September 15, 2021, 12:31pm

Here is the boot log
I can see multiple errors “mmcblk0: error -84” :

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 4.4.59-2.7.2+g7cfa321 (linuxdev@linuxdev.toradex.int) (gcc version 6.2.1 20161016 (Linaro GCC 6.2-2016.11) ) #2 Mon Apr 10 01:16:26 CEST 2017
[    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 VF61 on Colibri Evaluation Board
[    0.000000] cma: Reserved 16 MiB at 0x8ec00000
[    0.000000] Memory policy: Data cache writeback
[    0.000000] On node 0 totalpages: 65024
[    0.000000] free_area_init_node: node 0, pgdat 80879624, node_mem_map 8ea00000
[    0.000000]   Normal zone: 508 pages used for memmap
[    0.000000]   Normal zone: 0 pages reserved
[    0.000000]   Normal zone: 65024 pages, LIFO batch:15
[    0.000000] CPU: All CPU(s) started in SVC mode.
[    0.000000] pcpu-alloc: s0 r0 d32768 u32768 alloc=1*32768
[    0.000000] pcpu-alloc: [0] 0 
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 64516
[    0.000000] Kernel command line: ubi.mtd=ubi root=ubi0:rootfs rootfstype=ubifs ubi.fm_autoconvert=1 console=tty1 console=ttyLP0,115200n8 consoleblank=0 mtdparts=vf610_nfc:128k(vf-bcb)ro,1408k(u-boot)ro,512k(u-boot-env),-(ubi)
[    0.000000] PID hash table entries: 1024 (order: 0, 4096 bytes)
[    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: 232432K/260096K available (6059K kernel code, 216K rwdata, 2148K rodata, 224K init, 176K bss, 11280K reserved, 16384K cma-reserved)
[    0.000000] Virtual kernel memory layout:
[    0.000000]     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
[    0.000000]     fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
[    0.000000]     vmalloc : 0x90000000 - 0xff800000   (1784 MB)
[    0.000000]     lowmem  : 0x80000000 - 0x8fe00000   ( 254 MB)
[    0.000000]     modules : 0x7f000000 - 0x80000000   (  16 MB)
[    0.000000]       .text : 0x80008000 - 0x8080bff4   (8208 kB)
[    0.000000]       .init : 0x8080c000 - 0x80844000   ( 224 kB)
[    0.000000]       .data : 0x80844000 - 0x8087a0e0   ( 217 kB)
[    0.000000]        .bss : 0x8087a0e0 - 0x808a6130   ( 177 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.000000] L2C-310 erratum 769419 enabled
[    0.000000] L2C-310 dynamic clock gating enabled, standby mode enabled
[    0.000000] L2C-310 cache controller enabled, 8 ways, 512 kB
[    0.000000] L2C-310: CACHE_ID 0x410000c8, AUX_CTRL 0x06060000
[    0.000041] sched_clock: 64 bits at 166MHz, resolution 5ns, wraps every 4398046511102ns
[    0.000087] clocksource: arm_global_timer: mask: 0xffffffffffffffff max_cycles: 0x2674622ffc, max_idle_ns: 440795203810 ns
[    0.000996] Console: colour dummy device 80x30
[    0.002014] console [tty1] enabled
[    0.002069] Calibrating delay loop... 331.77 BogoMIPS (lpj=1658880)
[    0.060128] pid_max: default: 32768 minimum: 301
[    0.060346] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.060404] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.061650] CPU: Testing write buffer coherency: ok
[    0.062224] Setting up static identity map for 0x80008200 - 0x80008258
[    0.064240] devtmpfs: initialized
[    0.077281] VFP support v0.3: implementor 41 architecture 2 part 30 variant 5 rev 1
[    0.077915] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.078025] futex hash table entries: 256 (order: -1, 3072 bytes)
[    0.079844] pinctrl core: initialized pinctrl subsystem
[    0.081962] NET: Registered protocol family 16
[    0.084683] DMA: preallocated 256 KiB pool for atomic coherent allocations
[    0.086100] cpuidle: using governor menu
[    0.109297] PM: CKE/RESET pulls available, enable Suspend-to-RAM
[    0.109963] hw-breakpoint: found 2 (+1 reserved) breakpoint and 1 watchpoint registers.
[    0.110041] hw-breakpoint: maximum watchpoint size is 4 bytes.
[    0.110788] vf610-pinctrl 40048000.iomuxc: initialized IMX pinctrl driver
[    0.139094] SCSI subsystem initialized
[    0.139700] usbcore: registered new interface driver usbfs
[    0.139883] usbcore: registered new interface driver hub
[    0.140082] usbcore: registered new device driver usb
[    0.141599] i2c i2c-0: IMX I2C adapter registered
[    0.141729] i2c i2c-0: using dma0chan0 (tx) and dma0chan1 (rx) for DMA transfers
[    0.142039] Linux video capture interface: v2.00
[    0.142235] pps_core: LinuxPPS API ver. 1 registered
[    0.142283] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[    0.142408] PTP clock support registered
[    0.143208] Advanced Linux Sound Architecture Driver Initialized.
[    0.145310] clocksource: Switched to clocksource arm_global_timer
[    0.163134] NET: Registered protocol family 2
[    0.164568] TCP established hash table entries: 2048 (order: 1, 8192 bytes)
[    0.164680] TCP bind hash table entries: 2048 (order: 1, 8192 bytes)
[    0.164770] TCP: Hash tables configured (established 2048 bind 2048)
[    0.165014] UDP hash table entries: 256 (order: 0, 4096 bytes)
[    0.165091] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes)
[    0.165480] NET: Registered protocol family 1
[    0.166038] RPC: Registered named UNIX socket transport module.
[    0.166097] RPC: Registered udp transport module.
[    0.166139] RPC: Registered tcp transport module.
[    0.166182] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.167889] hw perfevents: enabled with armv7_cortex_a5 PMU driver, 3 counters available
[    0.184752] NFS: Registering the id_resolver key type
[    0.184912] Key type id_resolver registered
[    0.184959] Key type id_legacy registered
[    0.185041] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    0.186094] ntfs: driver 2.1.32 [Flags: R/W].
[    0.186985] fuse init (API version 7.23)
[    0.191092] io scheduler noop registered
[    0.191159] io scheduler deadline registered
[    0.191489] io scheduler cfq registered (default)
[    0.200083] 40027000.serial: ttyLP0 at MMIO 0x40027000 (irq = 19, base_baud = 5210526) is a FSL_LPUART
[    0.728846] console [ttyLP0] enabled
[    0.733312] 40028000.serial: ttyLP1 at MMIO 0x40028000 (irq = 20, base_baud = 5210526) is a FSL_LPUART
[    0.743637] 40029000.serial: ttyLP2 at MMIO 0x40029000 (irq = 21, base_baud = 5210526) is a FSL_LPUART
[    0.754652] [drm] Initialized drm 1.1.0 20060810
[    0.766505] [drm] Supports vblank timestamp caching Rev 2 (21.10.2013).
[    0.773173] [drm] No driver support for vblank timestamp query.
[    0.805284] Console: switching to colour frame buffer device 80x30
[    0.832409] fsl-dcu 40058000.dcu: fb0:  frame buffer device
[    0.846471] [drm] Initialized fsl-dcu-drm 1.0.0 20150213 on minor 0
[    0.873566] loop: module loaded
[    0.888053] nand: device found, Manufacturer ID: 0xc2, Chip ID: 0xdc
[    0.902939] nand: Macronix MX30LF4G28AC
[    0.915080] nand: 512 MiB, SLC, erase size: 128 KiB, page size: 2048, OOB size: 112
[    0.940107] Bad block table found at page 262080, version 0x01
[    0.954960] Bad block table found at page 262016, version 0x01
[    0.969482] nand_read_bbt: bad block at 0x0000013c0000
[    0.983250] nand_read_bbt: bad block at 0x0000087a0000
[    0.997057] 4 cmdlinepart partitions found on MTD device vf610_nfc
[    1.011964] Creating 4 MTD partitions on "vf610_nfc":
[    1.025884] 0x000000000000-0x000000020000 : "vf-bcb"
[    1.040294] 0x000000020000-0x000000180000 : "u-boot"
[    1.054296] 0x000000180000-0x000000200000 : "u-boot-env"
[    1.068531] 0x000000200000-0x000020000000 : "ubi"
[    1.088843] +V3.3: supplied by 3.3V
[    1.100989] pps pps0: new PPS source ptp0
[    1.118267] libphy: fec_enet_mii_bus: probed
[    1.130888] fec 400d1000.ethernet eth0: registered PHC device 0
[    1.144807] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    1.159298] usbcore: registered new interface driver usb-storage
[    1.173006] usbcore: registered new interface driver usbserial
[    1.186174] usbcore: registered new interface driver usbserial_generic
[    1.199761] usbserial: USB Serial support registered for generic
[    1.212795] usbcore: registered new interface driver ftdi_sio
[    1.225503] usbserial: USB Serial support registered for FTDI USB Serial Device
[    1.246567] usbcore: registered new interface driver pl2303
[    1.259246] usbserial: USB Serial support registered for pl2303
[    1.274468] 40034000.usb supply vbus not found, using dummy regulator
[    1.289316] mousedev: PS/2 mouse device common for all mice
[    1.304180] rtc-ds1307 0-0068: rtc core: registered m41t00 as rtc0
[    1.318783] snvs_rtc 400a7000.snvs:snvs-rtc-lp: rtc core: registered 400a7000.snvs:snvs- as rtc1
[    1.342821] i2c /dev entries driver
[    1.356232] imx2-wdt 4003e000.wdog: timeout 60 sec (nowayout=0)
[    1.370113] sdhci: Secure Digital Host Controller Interface driver
[    1.384219] sdhci: Copyright(c) Pierre Ossman
[    1.396645] sdhci-pltfm: SDHCI platform and OF driver helper
[    1.411542] /soc/aips-bus@40080000/esdhc@400b2000: voltage-ranges unspecified
[    1.427313] sdhci-esdhc-imx 400b2000.esdhc: Got CD GPIO
[    1.441380] sdhci-esdhc-imx 400b2000.esdhc: No vmmc regulator found
[    1.456270] sdhci-esdhc-imx 400b2000.esdhc: No vqmmc regulator found
[    1.505529] mmc0: SDHCI controller on 400b2000.esdhc [400b2000.esdhc] using ADMA
[    1.533788] hidraw: raw HID events driver (C) Jiri Kosina
[    1.548283] usbcore: registered new interface driver usbhid
[    1.562825] usbhid: USB HID core driver
[    1.636618] wm97xx-ts 0-0:wm9712-codec: detected a wm9712 codec
[    1.653942] input: wm97xx touchscreen as /devices/platform/sound/0-0:wm9712-codec/input/input0
[    1.683266] fsl-sai-ac97-dt-driver sound: wm9712-hifi <-> 40031000.sai mapping ok
[    1.713336] Netfilter messages via NETLINK v0.30.
[    1.727347] nfnl_acct: registering with nfnetlink.
[    1.741198] nf_conntrack version 0.5.0 (3887 buckets, 15548 max)
[    1.757250] nf_tables: (c) 2007-2009 Patrick McHardy <kaber@trash.net>
[    1.773738] ip_tables: (C) 2000-2006 Netfilter Core Team
[    1.789370] NET: Registered protocol family 10
[    1.804931] ip6_tables: (C) 2000-2006 Netfilter Core Team
[    1.819401] NET: Registered protocol family 17
[    1.832714] bridge: automatic filtering via arp/ip/ip6tables has been deprecated. Update your scripts to load br_netfilter if you need this.
[    1.863412] Bridge firewalling registered
[    1.876529] 8021q: 802.1Q VLAN Support v1.8
[    1.890544] mmc0: new high speed SDHC card at address aaaa
[    1.905103] Key type dns_resolver registered
[    1.919355] Registering SWP/SWPB emulation handler
[    1.933367] mmcblk0: mmc0:aaaa SH32G 29.7 GiB 
[    1.949802] mmcblk0: error -84 transferring data, sector 0, nr 8, cmd response 0x900, card status 0xb00
[    1.977024] registered taskstats version 1
[    1.993936] 40034000.usb supply vbus not found, using dummy regulator
[    2.016535] ci_hdrc ci_hdrc.0: EHCI Host Controller
[    2.031355] ci_hdrc ci_hdrc.0: new USB bus registered, assigned bus number 1
[    2.065377] ci_hdrc ci_hdrc.0: USB 2.0 started, EHCI 1.00
[    2.080998] hub 1-0:1.0: USB hub found
[    2.093099] hub 1-0:1.0: 1 port detected
[    2.106281] mmc0: tried to reset card
[    2.119363] VCC_USB[1-4]: supplied by 5V
[    2.131975] mmcblk0: error -84 transferring data, sector 0, nr 8, cmd response 0x900, card status 0xb00
[    2.157422] mmcblk0: retrying using single block read
[    2.171303] mmcblk0: error -84 transferring data, sector 0, nr 8, cmd response 0x900, card status 0x0
[    2.197051] blk_update_request: I/O error, dev mmcblk0, sector 0
[    2.211572] ci_hdrc ci_hdrc.1: EHCI Host Controller
[    2.225577] ci_hdrc ci_hdrc.1: new USB bus registered, assigned bus number 2
[    2.241540] mmcblk0: error -84 transferring data, sector 1, nr 7, cmd response 0x900, card status 0x0
[    2.267540] blk_update_request: I/O error, dev mmcblk0, sector 1
[    2.282260] ci_hdrc ci_hdrc.1: USB 2.0 started, EHCI 1.00
[    2.297789] hub 2-0:1.0: USB hub found
[    2.310285] hub 2-0:1.0: 1 port detected
[    2.322711] mmcblk0: error -84 transferring data, sector 2, nr 6, cmd response 0x900, card status 0x0
[    2.348843] blk_update_request: I/O error, dev mmcblk0, sector 2
[    2.365693] ubi0: default fastmap pool size: 200
[    2.378919] ubi0: default fastmap WL pool size: 100
[    2.392220] ubi0: attaching mtd3
[    2.404958] mmcblk0: error -84 transferring data, sector 3, nr 5, cmd response 0x900, card status 0x0
[    2.431411] blk_update_request: I/O error, dev mmcblk0, sector 3
[    2.447192] mmcblk0: error -84 transferring data, sector 4, nr 4, cmd response 0x900, card status 0x0
[    2.474730] blk_update_request: I/O error, dev mmcblk0, sector 4
[    2.490838] mmcblk0: error -84 transferring data, sector 5, nr 3, cmd response 0x900, card status 0x0
[    2.518539] blk_update_request: I/O error, dev mmcblk0, sector 5
[    2.534574] mmcblk0: error -84 transferring data, sector 6, nr 2, cmd response 0x900, card status 0x0
[    2.562356] blk_update_request: I/O error, dev mmcblk0, sector 6
[    2.578558] mmcblk0: error -84 transferring data, sector 7, nr 1, cmd response 0x900, card status 0x0
[    2.606651] blk_update_request: I/O error, dev mmcblk0, sector 7
[    2.622229] Buffer I/O error on dev mmcblk0, logical block 0, async page read
[    2.640313] mmcblk0: error -84 transferring data, sector 0, nr 8, cmd response 0x900, card status 0xb00
[    2.669306] mmcblk0: retrying using single block read
[    2.684963] mmcblk0: error -84 transferring data, sector 0, nr 8, cmd response 0x900, card status 0x0
[    2.713824] blk_update_request: I/O error, dev mmcblk0, sector 0
[    2.730893] mmcblk0: error -84 transferring data, sector 1, nr 7, cmd response 0x900, card status 0x0
[    2.760689] blk_update_request: I/O error, dev mmcblk0, sector 1
[    2.777852] mmcblk0: error -84 transferring data, sector 2, nr 6, cmd response 0x900, card status 0x0
[    2.807895] usb 2-1: new full-speed USB device number 2 using ci_hdrc
[    2.825681] mmcblk0: error -84 transferring data, sector 3, nr 5, cmd response 0x900, card status 0x0
[    2.856529] mmcblk0: error -84 transferring data, sector 4, nr 4, cmd response 0x900, card status 0x0
[    2.887479] mmcblk0: error -84 transferring data, sector 5, nr 3, cmd response 0x900, card status 0x0
[    2.918648] mmcblk0: error -84 transferring data, sector 6, nr 2, cmd response 0x900, card status 0x0
[    2.949800] mmcblk0: error -84 transferring data, sector 7, nr 1, cmd response 0x900, card status 0x0
[    2.980422] Buffer I/O error on dev mmcblk0, logical block 0, async page read
[    2.998678]  mmcblk0: unable to read partition table
[    3.171736] ftdi_sio 2-1:1.0: FTDI USB Serial Device converter detected
[    3.190217] usb 2-1: Detected FT232RL
[    3.208919] usb 2-1: FTDI USB Serial Device converter now attached to ttyUSB0
[    3.255861] ubi0: attached by fastmap
[    3.270278] ubi0: fastmap pool size: 200
[    3.284642] ubi0: fastmap WL pool size: 100
[    3.314509] ubi0: attached mtd3 (name "ubi", size 510 MiB)
[    3.330321] ubi0: PEB size: 131072 bytes (128 KiB), LEB size: 126976 bytes
[    3.347400] ubi0: min./max. I/O unit sizes: 2048/2048, sub-page size 2048
[    3.364333] ubi0: VID header offset: 2048 (aligned 2048), data offset: 4096
[    3.381440] ubi0: good PEBs: 4074, bad PEBs: 6, corrupted PEBs: 0
[    3.397532] ubi0: user volume: 3, internal volumes: 1, max. volumes count: 128
[    3.424276] ubi0: max/mean erase counter: 183/25, WL threshold: 4096, image sequence number: 0
[    3.452496] ubi0: available PEBs: 0, total reserved PEBs: 4074, PEBs reserved for bad PEB handling: 74
[    3.481574] ubi0: background thread "ubi_bgt0d" started, PID 61
[    3.498751] input: gpio-keys as /devices/platform/gpio-keys/input/input1
[    3.516989] rtc-ds1307 0-0068: setting system clock to 2021-09-15 12:02:45 UTC (1631707365)
[    3.557773] ALSA device list:
[    3.570268]   #0: Colibri VF61 AC97 Audio
[    3.602471] UBIFS (ubi0:2): recovery needed
[    3.657912] UBIFS (ubi0:2): recovery deferred
[    3.671245] UBIFS (ubi0:2): UBIFS: mounted UBI device 0, volume 2, name "rootfs", R/O mode
[    3.696859] UBIFS (ubi0:2): LEB size: 126976 bytes (124 KiB), min./max. I/O unit sizes: 2048 bytes/2048 bytes
[    3.724700] UBIFS (ubi0:2): FS size: 496984064 bytes (473 MiB, 3914 LEBs), journal size 9023488 bytes (8 MiB, 72 LEBs)
[    3.754439] UBIFS (ubi0:2): reserved for root: 0 bytes (0 KiB)
[    3.769977] UBIFS (ubi0:2): media format: w4/r0 (latest is w4/r0), UUID 11E76A55-ADE3-4CBD-A204-890AACC01A9A, small LPT model
[    3.801456] VFS: Mounted root (ubifs filesystem) readonly on device 0:14.
[    3.819075] devtmpfs: mounted
[    3.832631] Freeing unused kernel memory: 224K (8080c000 - 80844000)
[    4.045141] random: systemd: uninitialized urandom read (16 bytes read, 37 bits of entropy available)
[    4.088895] systemd[1]: systemd 230 running in system mode. (+PAM -AUDIT -SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP -LIBCRYPTSETUP -GCRYPT -GNUTLS +ACL +XZ -LZ4 -SECCOMP +BLKID -ELFUTILS +KMOD -IDN)
[    4.137627] systemd[1]: Detected architecture arm.
[    4.176569] systemd[1]: Set hostname to <AlbenV3_0479>.
[    4.225051] random: systemd: uninitialized urandom read (16 bytes read, 40 bits of entropy available)
[    4.376109] random: systemd-sysv-ge: uninitialized urandom read (16 bytes read, 44 bits of entropy available)
[    4.422595] random: systemd-sysv-ge: uninitialized urandom read (16 bytes read, 46 bits of entropy available)
[    4.482051] random: systemd: uninitialized urandom read (16 bytes read, 48 bits of entropy available)
[    4.513222] random: systemd: uninitialized urandom read (16 bytes read, 48 bits of entropy available)
[    4.583995] random: systemd: uninitialized urandom read (16 bytes read, 51 bits of entropy available)
[    4.615837] random: systemd: uninitialized urandom read (16 bytes read, 52 bits of entropy available)
[    4.648808] random: systemd: uninitialized urandom read (16 bytes read, 52 bits of entropy available)
[    4.720861] random: systemd: uninitialized urandom read (16 bytes read, 54 bits of entropy available)
[    4.979543] systemd[1]: Configuration file /etc/systemd/system/sol_reset_ip.service is marked executable. Please remove executable permission bits. Proceeding anyway.
[    5.086787] systemd[1]: Listening on udev Kernel Socket.
[    5.126030] systemd[1]: Listening on Journal Socket (/dev/log).
[    5.166641] systemd[1]: Created slice System Slice.
[    5.206077] systemd[1]: Created slice system-getty.slice.
[    5.245888] systemd[1]: Listening on /dev/initctl Compatibility Named Pipe.
[    5.304398] systemd[1]: Created slice system-serial\x2dgetty.slice.
[    5.345731] systemd[1]: Reached target Remote File Systems.
[    5.385889] systemd[1]: Created slice User and Session Slice.
[    5.425574] systemd[1]: Reached target Slices.
[    5.456033] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
[    5.505888] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[    5.555571] systemd[1]: Reached target Paths.
[    5.585937] systemd[1]: Listening on Journal Socket.
[    5.622258] systemd[1]: Starting Create list of required static device nodes for the current kernel...
[    5.679171] systemd[1]: Starting Journal Service...
[    5.719355] systemd[1]: Starting File System Check on Root Device...
[    5.752734] systemd[1]: Starting Setup Virtual Console...
[    5.803274] systemd[1]: Starting Load Kernel Modules...
[    5.842742] systemd[1]: Reached target Swap.
[    5.896739] systemd[1]: Mounting Temporary Directory...
[    5.951293] systemd[1]: Listening on udev Control Socket.
[    5.999546] systemd[1]: Listening on Network Service Netlink Socket.
[    6.069457] systemd[1]: Mounting Debug File System...
[    6.139143] systemd[1]: Mounted Debug File System.
[    6.165938] systemd[1]: Mounted Temporary Directory.
[    6.196295] systemd[1]: Started Journal Service.
[    6.508263] UBIFS (ubi0:2): completing deferred recovery
[    6.654101] UBIFS (ubi0:2): background thread "ubifs_bgt0_2" started, PID 97
[    6.685966] UBIFS error (ubi0:2 pid 93): read_pnode: error -22 reading pnode at 9:57746
[    6.709134] (pid 93) dumping pnode:
[    6.720214] 	address 8ddeb100 parent 8ddeaf80 cnext 0
[    6.732763] 	flags 0 iip 2 level 0 num 0
[    6.743905] 	0: free 0 dirty 106344 flags 1 lnum 0
[    6.755790] 	1: free 0 dirty 130920 flags 34 lnum 0
[    6.767607] 	2: free 24 dirty 126248 flags 1 lnum 0
[    6.779403] 	3: free 0 dirty 110768 flags 1 lnum 0
[    6.790991] CPU: 0 PID: 93 Comm: mount Not tainted 4.4.59-2.7.2+g7cfa321 #2
[    6.804848] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
[    6.818256] Backtrace: 
[    6.827694] [<800134ac>] (dump_backtrace) from [<800136a4>] (show_stack+0x18/0x1c)
[    6.849538]  r7:00000002 r6:8ddeb100 r5:ffffffea r4:8e7a2000
[    6.863361] [<8001368c>] (show_stack) from [<802a1a1c>] (dump_stack+0x24/0x28)
[    6.886061] [<802a19f8>] (dump_stack) from [<80232b1c>] (ubifs_get_pnode.part.4+0x24c/0x2dc)
[    6.910878] [<802328d0>] (ubifs_get_pnode.part.4) from [<80234230>] (ubifs_get_pnode+0x2c/0x38)
[    6.936993]  r10:00000000 r9:8dc9a044 r8:8dc70d44 r7:8ddeb080 r6:0000000c r5:8e7a285c
[    6.963839]  r4:8e7a2000
[    6.975633] [<80234204>] (ubifs_get_pnode) from [<8023cd98>] (ubifs_lpt_start_commit+0x9e0/0xe98)
[    7.002958] [<8023c3b8>] (ubifs_lpt_start_commit) from [<8022a80c>] (do_commit+0x154/0x4dc)
[    7.030427]  r10:00000000 r9:8dc9a044 r8:8dc70d44 r7:00000003 r6:8e7a2150 r5:00000000
[    7.058801]  r4:8e7a2000
[    7.071503] [<8022a6b8>] (do_commit) from [<8022adac>] (ubifs_run_commit+0x74/0xb8)
[    7.099960]  r8:00000000 r7:00000000 r6:00000000 r5:8e7a21cc r4:8e7a2000
[    7.118153] [<8022ad38>] (ubifs_run_commit) from [<802399a4>] (ubifs_rcvry_gc_commit+0x7c/0x1fc)
[    7.148240]  r5:8dc70c00 r4:8e7a2000
[    7.162642] [<80239928>] (ubifs_rcvry_gc_commit) from [<8021bb9c>] (ubifs_remount_fs+0x428/0x724)
[    7.192572]  r7:00000000 r6:8e7a27d0 r5:8e7a2814 r4:8e7a2000
[    7.209481] [<8021b774>] (ubifs_remount_fs) from [<800cdc2c>] (do_remount_sb+0x6c/0x1d4)
[    7.238566]  r10:00000000 r9:8dc9a044 r8:00000000 r7:00000000 r6:00000000 r5:00000000
[    7.268003]  r4:8dc9a000
[    7.280826] [<800cdbc0>] (do_remount_sb) from [<800e8f98>] (do_mount+0x5ac/0xbb4)
[    7.308496]  r8:8e796490 r7:8dc9a000 r6:00000020 r5:00000020 r4:00000000
[    7.326524] [<800e89ec>] (do_mount) from [<800e9910>] (SyS_mount+0x94/0xc0)
[    7.344123]  r10:00000000 r9:8dd5a000 r8:c0ed0020 r7:005141e8 r6:00000000 r5:8dd86dc0
[    7.373212]  r4:8dd86d80
[    7.385897] [<800e987c>] (SyS_mount) from [<8000f780>] (ret_fast_syscall+0x0/0x3c)
[    7.413345]  r8:8000f944 r7:00000015 r6:00000000 r5:00000000 r4:00000000
[    7.431223] UBIFS error (ubi0:2 pid 93): read_pnode: calc num: 258
[    7.447850] UBIFS error (ubi0:2 pid 93): do_commit: commit failed, error -22
[    7.465187] UBIFS warning (ubi0:2 pid 93): ubifs_ro_mode: switched to read-only mode, error -22
[    7.493855] CPU: 0 PID: 93 Comm: mount Not tainted 4.4.59-2.7.2+g7cfa321 #2
[    7.511046] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
[    7.527839] Backtrace: 
[    7.540453] [<800134ac>] (dump_backtrace) from [<800136a4>] (show_stack+0x18/0x1c)
[    7.568096]  r7:00000003 r6:8e7a2150 r5:ffffffea r4:8e7e0e40
[    7.584513] [<8001368c>] (show_stack) from [<802a1a1c>] (dump_stack+0x24/0x28)
[    7.611678] [<802a19f8>] (dump_stack) from [<8021f2b0>] (ubifs_ro_mode.part.0+0x7c/0x84)
[    7.640050] [<8021f234>] (ubifs_ro_mode.part.0) from [<8021f3c8>] (ubifs_ro_mode+0x1c/0x20)
[    7.669092]  r4:8e7a2000
[    7.681805] [<8021f3ac>] (ubifs_ro_mode) from [<8022ab88>] (do_commit+0x4d0/0x4dc)
[    7.709604] [<8022a6b8>] (do_commit) from [<8022adac>] (ubifs_run_commit+0x74/0xb8)
[    7.737864]  r8:00000000 r7:00000000 r6:00000000 r5:8e7a21cc r4:8e7a2000
[    7.755999] [<8022ad38>] (ubifs_run_commit) from [<802399a4>] (ubifs_rcvry_gc_commit+0x7c/0x1fc)
[    7.785738]  r5:8dc70c00 r4:8e7a2000
[    7.799950] [<80239928>] (ubifs_rcvry_gc_commit) from [<8021bb9c>] (ubifs_remount_fs+0x428/0x724)
[    7.829953]  r7:00000000 r6:8e7a27d0 r5:8e7a2814 r4:8e7a2000
[    7.846845] [<8021b774>] (ubifs_remount_fs) from [<800cdc2c>] (do_remount_sb+0x6c/0x1d4)
[    7.875958]  r10:00000000 r9:8dc9a044 r8:00000000 r7:00000000 r6:00000000 r5:00000000
[    7.905708]  r4:8dc9a000
[    7.918728] [<800cdbc0>] (do_remount_sb) from [<800e8f98>] (do_mount+0x5ac/0xbb4)
[    7.947023]  r8:8e796490 r7:8dc9a000 r6:00000020 r5:00000020 r4:00000000
[    7.965064] [<800e89ec>] (do_mount) from [<800e9910>] (SyS_mount+0x94/0xc0)
[    7.982675]  r10:00000000 r9:8dd5a000 r8:c0ed0020 r7:005141e8 r6:00000000 r5:8dd86dc0
[    8.011780]  r4:8dd86d80
[    8.024418] [<800e987c>] (SyS_mount) from [<8000f780>] (ret_fast_syscall+0x0/0x3c)
[    8.052515]  r8:8000f944 r7:00000015 r6:00000000 r5:00000000 r4:00000000
[    8.075445] UBIFS (ubi0:2): background thread "ubifs_bgt0_2" stops
[    8.376964] systemd-journald[75]: Received request to flush runtime journal from PID 1
[    9.799622] random: nonblocking pool is initialized
[   10.931714] vf610 rpmsg driver is registered.
[   11.161475] mmcblk0: error -84 transferring data, sector 62333824, nr 8, cmd response 0x900, card status 0xb00
[   11.191966] mmcblk0: retrying using single block read
[   11.435987] wm97xx-ts 0-0:wm9712-codec: No IRQ specified
[   11.567912] mmcblk0: error -84 transferring data, sector 62333824, nr 8, cmd response 0x900, card status 0x0
[   11.597805] blk_update_request: 6 callbacks suppressed
[   11.612888] blk_update_request: I/O error, dev mmcblk0, sector 62333824
[   12.168275] mmcblk0: error -84 transferring data, sector 62333825, nr 7, cmd response 0x900, card status 0x0
[   12.198134] blk_update_request: I/O error, dev mmcblk0, sector 62333825
[   12.661643] mmcblk0: error -84 transferring data, sector 62333826, nr 6, cmd response 0x900, card status 0x0
[   12.691537] blk_update_request: I/O error, dev mmcblk0, sector 62333826
[   12.931304] virtio_rpmsg_bus virtio0: rpmsg host is online
[   12.951996] mmcblk0: error -84 transferring data, sector 62333827, nr 5, cmd response 0x900, card status 0x0
[   12.982268] blk_update_request: I/O error, dev mmcblk0, sector 62333827
[   13.010593] mmcblk0: error -84 transferring data, sector 62333828, nr 4, cmd response 0x900, card status 0x0
[   13.040895] blk_update_request: I/O error, dev mmcblk0, sector 62333828
[   13.060651] mmcblk0: error -84 transferring data, sector 62333829, nr 3, cmd response 0x900, card status 0x0
[   13.090986] blk_update_request: I/O error, dev mmcblk0, sector 62333829
[   13.110139] mmcblk0: error -84 transferring data, sector 62333830, nr 2, cmd response 0x900, card status 0x0
[   13.140880] blk_update_request: I/O error, dev mmcblk0, sector 62333830
[   13.160541] mmcblk0: error -84 transferring data, sector 62333831, nr 1, cmd response 0x900, card status 0x0
[   13.191724] blk_update_request: I/O error, dev mmcblk0, sector 62333831
[   13.212727] mmcblk0: error -84 transferring data, sector 62333824, nr 8, cmd response 0x900, card status 0xb00
[   13.244425] mmcblk0: retrying using single block read
[   13.262489] mmcblk0: error -84 transferring data, sector 62333824, nr 8, cmd response 0x900, card status 0x0
[   13.293805] blk_update_request: I/O error, dev mmcblk0, sector 62333824
[   13.313803] mmcblk0: error -84 transferring data, sector 62333825, nr 7, cmd response 0x900, card status 0x0
[   13.345093] blk_update_request: I/O error, dev mmcblk0, sector 62333825
[   13.364965] mmcblk0: error -84 transferring data, sector 62333826, nr 6, cmd response 0x900, card status 0x0
[   13.397985] mmcblk0: error -84 transferring data, sector 62333827, nr 5, cmd response 0x900, card status 0x0
[   13.431328] mmcblk0: error -84 transferring data, sector 62333828, nr 4, cmd response 0x900, card status 0x0
[   13.464332] mmcblk0: error -84 transferring data, sector 62333829, nr 3, cmd response 0x900, card status 0x0
[   13.497210] mmcblk0: error -84 transferring data, sector 62333830, nr 2, cmd response 0x900, card status 0x0
[   13.530030] mmcblk0: error -84 transferring data, sector 62333831, nr 1, cmd response 0x900, card status 0x0
[   13.561901] Buffer I/O error on dev mmcblk0, logical block 7791728, async page read
[   15.206604] using random self ethernet address
[   15.222196] using random host ethernet address
[   16.073290] usb0: HOST MAC 00:14:2d:ff:ff:fe
[   16.115450] usb0: MAC 00:14:2d:ff:ff:ff
[   16.389967] IPv6: ADDRCONF(NETDEV_UP): usb0: link is not ready
[   16.545402] fec 400d1000.ethernet eth0: Freescale FEC PHY driver [Micrel KSZ8041] (mii_bus:phy_addr=400d1000.etherne:00, irq=-1)
[   16.589923] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[   18.545900] fec 400d1000.ethernet eth0: Link is Up - 100Mbps/Full - f
[  458.850156] mmcblk0: error -84 transferring data, sector 0, nr 32, cmd response 0x900, card status 0xb00
[  458.860545] mmcblk0: retrying using single block read
[  458.885948] mmcblk0: error -84 transferring data, sector 0, nr 32, cmd response 0x900, card status 0x0
[  458.896055] blk_update_request: 6 callbacks suppressed
[  458.901590] blk_update_request: I/O error, dev mmcblk0, sector 0
[  458.910920] mmcblk0: error -84 transferring data, sector 1, nr 31, cmd response 0x900, card status 0x0
[  458.921037] blk_update_request: I/O error, dev mmcblk0, sector 1
[  458.929038] mmcblk0: error -84 transferring data, sector 2, nr 30, cmd response 0x900, card status 0x0
[  458.939127] blk_update_request: I/O error, dev mmcblk0, sector 2
[  458.946797] mmcblk0: error -84 transferring data, sector 3, nr 29, cmd response 0x900, card status 0x0
[  458.974498] blk_update_request: I/O error, dev mmcblk0, sector 3
[  459.013639] mmcblk0: error -84 transferring data, sector 4, nr 28, cmd response 0x900, card status 0x0
[  459.042976] blk_update_request: I/O error, dev mmcblk0, sector 4
[  459.105648] mmcblk0: error -84 transferring data, sector 5, nr 27, cmd response 0x900, card status 0x0
[  459.136060] blk_update_request: I/O error, dev mmcblk0, sector 5
[  459.205988] mmcblk0: error -84 transferring data, sector 6, nr 26, cmd response 0x900, card status 0x0
[  459.238145] blk_update_request: I/O error, dev mmcblk0, sector 6
[  459.269130] mmcblk0: error -84 transferring data, sector 7, nr 25, cmd response 0x900, card status 0x0
[  459.302130] blk_update_request: I/O error, dev mmcblk0, sector 7
[  459.345903] mmcblk0: error -84 transferring data, sector 8, nr 24, cmd response 0x900, card status 0x0
[  459.379615] blk_update_request: I/O error, dev mmcblk0, sector 8
[  459.455874] mmcblk0: error -84 transferring data, sector 9, nr 23, cmd response 0x900, card status 0x0
[  459.489626] blk_update_request: I/O error, dev mmcblk0, sector 9
[  459.527544] mmcblk0: error -84 transferring data, sector 10, nr 22, cmd response 0x900, card status 0x0
[  459.562576] mmcblk0: error -84 transferring data, sector 11, nr 21, cmd response 0x900, card status 0x0
[  459.608694] mmcblk0: error -84 transferring data, sector 12, nr 20, cmd response 0x900, card status 0x0
[  459.655850] mmcblk0: error -84 transferring data, sector 13, nr 19, cmd response 0x900, card status 0x0
[  459.691495] mmcblk0: error -84 transferring data, sector 14, nr 18, cmd response 0x900, card status 0x0

rafael.tx · September 16, 2021, 6:52pm

It seems that there’s a corrupted block in your NAND and this is causing a failure in the commit procedure of UBIFS.

[    6.685966] UBIFS error (ubi0:2 pid 93): read_pnode: error -22 reading pnode at 9:57746

Could you see if you see the same message on multiple reboots of the board? Also check if it’s the same pnode (in this istance the pnode is 9:57746).

Do you have an idea of when this problem started to happen?
Is it possible that the system is turned off without proper shutdown procedure?
Is this a development system or is it a board that came from the field?

We have a system running some tests in the office right now to see if we replicate a similar issue, so any extra information can help us try to replicate your setup as closely as possible.

These errors are associated with your SD card, it seems that there are a lot of IO errors associated with it. Could you check if another card gives you different results?

mnicolas · September 17, 2021, 1:47pm

Hello,

I rebooted the system and the error message still occurs on the same pnode:
[ 5.897862] UBIFS error (ubi0:2 pid 85): read_pnode: error -22 reading pnode at 9:57746

As you pointed out, the other errors (error -84) were related to the SD card that was not present in the test system I used when I ran the previous dmesg command, so they are unrelated with the file system becoming read only.

I cannot say exactly when the problems started to occur, but at most a few days ago, on a system that has been running for months.
The system has been occasionally switched off without a proper shutdown procedure (due to power outage or hardware changes) but it normally stays all 24/7.
This is a development board that replicates an environment that is deployed in the field; our concern is to know if the same issue could happen in the field.

henrique.tx · October 26, 2021, 5:17pm

Hi @mnicolas !

We created an experimental setup to try to reproduce the issue, but so far we could not see it happening.

We will keep it running so, if we manage to capture the issue, maybe we can better investigate it.

Best regards