19.07.2: mount_root: failed - cp -a /tmp/root/* /rom/overlay: Not a tty

On a 8devices Lima board (CONFIG_TARGET_ar71xx_generic_DEVICE_lima=y), running OpenWrt 19.07.2, it looks like the mount_root step is failing:

// from dmesg...
[    9.877660] mount_root: jffs2 not ready yet, using temporary tmpfs overlay
[   75.264850] jffs2_scan_eraseblock(): End of filesystem marker found at 0x0
[   75.272030] jffs2_build_filesystem(): unlocking the mtd device... 
[   75.322586] done.
[   75.330967] jffs2_build_filesystem(): erasing all blocks after the end marker... 
[   75.492541] jffs2: Newly-erased block contained word 0x19852003 at offset 0x01650000
[   75.640768] jffs2: Newly-erased block contained word 0x19852003 at offset 0x01640000

// now from logread (lost the first messages after boot)
...
Thu Feb 27 21:06:21 2020 kern.warn kernel: [   82.148601] jffs2: Newly-erased block contained word 0x19852003 at offset 0x00030000
Thu Feb 27 21:06:21 2020 kern.warn kernel: [   82.160717] jffs2: Newly-erased block contained word 0x19852003 at offset 0x00020000
Thu Feb 27 21:06:21 2020 kern.warn kernel: [   82.172873] jffs2: Newly-erased block contained word 0x19852003 at offset 0x00010000
Thu Feb 27 21:06:21 2020 kern.warn kernel: [   82.184976] jffs2: Newly-erased block contained word 0xdeadc0de at offset 0x00000000
Thu Feb 27 21:06:21 2020 kern.warn kernel: [   82.198967] done.
Thu Feb 27 21:06:21 2020 kern.notice kernel: [   82.201001] jffs2: notice: (2607) 
: complete building xattr subsystem, 0 of xdatum (0 unchecked, 0 orphan) and 0 of xref (0 dead, 0 orphan) found.
Thu Feb 27 21:06:21 2020 daemon.notice procd: /etc/rc.d/S95done: cp: can't create directory '/rom/overlay/upper': No space left on device
Thu Feb 27 21:06:21 2020 daemon.notice procd: /etc/rc.d/S95done: cp: can't create directory '/rom/overlay/work': No space left on device
Thu Feb 27 21:06:21 2020 daemon.err mount_root: failed - cp -a /tmp/root/* /rom/overlay: Not a tty

The cp error lines are very similar to the ones reported in Jffs2: Erase at 0x00020000 failed immediately: -EROFS. Is the sector locked? but the issue is completely different, as the -EROFS issue happened only in git master, never in 19.07.2.

Once this happens, the system gets in a very weird state, with Luci not lunching correctly, dumping errors like this in the system log:

Mon Apr 27 10:03:04 2020 daemon.err uhttpd[1535]: /usr/lib/lua/luci/dispatcher.lua:315: /etc/config/luci seems to be corrupt, unable to find section 'main'
Mon Apr 27 10:03:04 2020 daemon.err uhttpd[1535]: stack traceback:
Mon Apr 27 10:03:04 2020 daemon.err uhttpd[1535]: 	[C]: in function 'assert'
Mon Apr 27 10:03:04 2020 daemon.err uhttpd[1535]: 	/usr/lib/lua/luci/dispatcher.lua:315: in function 'dispatch'
Mon Apr 27 10:03:04 2020 daemon.err uhttpd[1535]: 	/usr/lib/lua/luci/dispatcher.lua:208: in function </usr/lib/lua/luci/dispatcher.lua:207>

But the luci config seems to exist and it's fine:

# cat /etc/config/luci 

config core 'main'
	option lang 'auto'
	option mediaurlbase '/luci-static/bootstrap'
	option resourcebase '/luci-static/resources'

config extern 'flash_keep'
	option uci '/etc/config/'
	option dropbear '/etc/dropbear/'
	option openvpn '/etc/openvpn/'
	option passwd '/etc/passwd'
	option opkg '/etc/opkg.conf'
	option firewall '/etc/firewall.user'
	option uploads '/lib/uci/upload/'

config internal 'languages'

config internal 'sauth'
	option sessionpath '/tmp/luci-sessions'
	option sessiontime '3600'

config internal 'ccache'
	option enable '1'

config internal 'themes'
	option Bootstrap '/luci-static/bootstrap'

config internal 'apply'
	option rollback '90'
	option holdoff '4'
	option timeout '5'
	option display '1.5'

Any idea what could be happening here?

Some more info:

root@openwrt:~# uname -a
Linux 4.14.171 #0 Thu Feb 27 21:05:12 2020 mips GNU/Linux
root@openwrt:~# df -h
Filesystem                Size      Used Available Use% Mounted on
/dev/root                 7.5M      7.5M         0 100% /rom
tmpfs                    29.1M    476.0K     28.6M   2% /tmp
tmpfs                    29.1M    228.0K     28.8M   1% /tmp/root
overlayfs:/tmp/root      29.1M    228.0K     28.8M   1% /
tmpfs                   512.0K         0    512.0K   0% /dev
/dev/mtdblock6           22.4M     22.4M         0 100% /rom/overlay

Digging this a bit further, it looks like the JFFS2 partition formatting during boot after the sysupgrade works ok, but once the partition is mounted, it reports 100% usage right away.

I can manually force this sequence running the following:

root@openwrt:~# umount /rom/overlay

root@openwrt:~# flash_eraseall -j /dev/mtd6
Erasing 64 Kibyte @ 1660000 - 100% complete.Cleanmarker written at 1650000.

root@openwrt:~# mount -t jffs2 /dev/mtdblock6 /rom/overlay

root@openwrt:~# df -h
Filesystem                Size      Used Available Use% Mounted on
/dev/root                 7.5M      7.5M         0 100% /rom
tmpfs                    29.1M    240.0K     28.8M   1% /tmp
tmpfs                    29.1M    204.0K     28.9M   1% /tmp/root
overlayfs:/tmp/root      29.1M    204.0K     28.9M   1% /
tmpfs                   512.0K         0    512.0K   0% /dev
/dev/mtdblock6           22.4M     22.4M         0 100% /rom/overlay

I don't yet understand why after formatting and remounting it reports 100% usage.

This issue looks like it was a problem with the 19.07.2 setup I was working with. In this setup, I had backported commit https://github.com/openwrt/openwrt/commit/d7f21940bcaf70ba404d354c7fa6519c1717d00a to my build branch.

That commit was treating all w25q256 spi-nor flash cards in the same way, and that is wrong because there really are 2 different versions: w25q256jv and w25q256fv. The correct way to handle these is implemented in the following fix instead: https://github.com/openwrt/openwrt/commit/4745969ad7c0cb65f55c8de1f05eba786ca27f71

Now, the issue I was seeing was happening when 4byte opcodes were unconditionally enabled on a system that had a w25q256fv (which doesn't support all 4byte opcodes). In this setup, the spi-nor allows read operations, but all write operations are ignored... so, any attempt to e.g. format the mtdblock6 partition would not do anything, as originally reported.

E.g. the following line is indicating that after erasing, the word is not 0xffffffff, it still has some other value, effectively reporting that the erase is not being done.

[   75.492541] jffs2: Newly-erased block contained word 0x19852003 at offset 0x01650000

TLDR; when 4B opcodes are enabled in the w25q256fv, no write will be done in the spi-nor.

1 Like

This topic was automatically closed 10 days after the last reply. New replies are no longer allowed.