Usb-storage fail to load in preinit

higuita · February 8, 2020, 8:01pm

i have a wl-500w, upgraded to to 19.07.1 and then follow the https://openwrt.org/docs/guide-user/additional-software/extroot_configuration. but root do not mount on boot.

I can mount manually, but on boot, preinit is not loading the usb-storage, but it is loaded without problem in the init, after aborting the extroot mount.

# logread | sed -n -e "/- preinit -/,/sda: sda1/p"
Sat Feb  8 04:28:29 2020 user.info kernel: [    4.305687] init: - preinit -
Sat Feb  8 04:28:29 2020 kern.info kernel: [    4.584169] usb 1-2: new high-speed USB device number 2 using ehci-pci
Sat Feb  8 04:28:29 2020 kern.notice kernel: [    4.914804] random: procd: uninitialized urandom read (4 bytes read)
Sat Feb  8 04:28:29 2020 kern.notice kernel: [    6.189867] random: jshn: uninitialized urandom read (4 bytes read)
Sat Feb  8 04:28:29 2020 kern.notice kernel: [    6.374958] random: jshn: uninitialized urandom read (4 bytes read)
Sat Feb  8 04:28:29 2020 kern.notice kernel: [    6.604856] random: jshn: uninitialized urandom read (4 bytes read)
Sat Feb  8 04:28:29 2020 kern.info kernel: [    7.233767] b44 ssb0:0 eth0: Link is up at 100 Mbps, half duplex
Sat Feb  8 04:28:29 2020 kern.info kernel: [    7.240037] b44 ssb0:0 eth0: Flow control is off for TX and off for RX
Sat Feb  8 04:28:29 2020 kern.info kernel: [    7.250029] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
Sat Feb  8 04:28:29 2020 kern.info kernel: [    7.259281] IPv6: ADDRCONF(NETDEV_UP): eth0.1: link is not ready
Sat Feb  8 04:28:29 2020 kern.info kernel: [    7.266353] IPv6: ADDRCONF(NETDEV_CHANGE): eth0.1: link becomes ready
Sat Feb  8 04:28:29 2020 kern.info kernel: [    8.243970] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
Sat Feb  8 04:28:29 2020 kern.info kernel: [    8.323997] b44 ssb0:0 eth0: Link is Up - 100Mbps/Full - flow control off
Sat Feb  8 04:28:29 2020 kern.notice kernel: [   10.955337] jffs2: notice: (408) jffs2_build_xattr_subsystem: complete building xattr subsystem, 17 of xdatum (3 unchecked, 14 orphan) and 72 of xref (15 dead, 0 orphan) found.
Sat Feb  8 04:28:29 2020 user.info kernel: [   10.977469] mount_root: loading kmods from internal overlay
Sat Feb  8 04:28:29 2020 user.err kernel: [   11.007361] kmodloader: failed to open /tmp/overlay/upper/lib/modules/4.14.167/b43.ko
Sat Feb  8 04:28:29 2020 user.err kernel: [   11.016183] kmodloader: failed to open /tmp/overlay/upper/lib/modules/4.14.167/cfg80211.ko
Sat Feb  8 04:28:29 2020 user.err kernel: [   11.025428] kmodloader: failed to open /tmp/overlay/upper/lib/modules/4.14.167/compat.ko
Sat Feb  8 04:28:29 2020 user.err kernel: [   11.115261] kmodloader: failed to open /tmp/overlay/upper/lib/modules/4.14.167/mac80211.ko
Sat Feb  8 04:28:29 2020 user.err kernel: [   11.130186] kmodloader: failed to open /tmp/overlay/upper/lib/modules/4.14.167/ppp_async.ko
Sat Feb  8 04:28:29 2020 user.err kernel: [   11.139510] kmodloader: failed to open /tmp/overlay/upper/lib/modules/4.14.167/ppp_generic.ko
Sat Feb  8 04:28:29 2020 user.err kernel: [   11.149021] kmodloader: failed to open /tmp/overlay/upper/lib/modules/4.14.167/pppoe.ko
Sat Feb  8 04:28:29 2020 user.err kernel: [   11.157987] kmodloader: failed to open /tmp/overlay/upper/lib/modules/4.14.167/pppox.ko
Sat Feb  8 04:28:29 2020 user.err kernel: [   11.259341] mount_root: failed to launch kmodloader from internal overlay
Sat Feb  8 04:28:29 2020 user.info kernel: [   11.415570] block: attempting to load /tmp/jffs_cfg/upper/etc/config/fstab
Sat Feb  8 04:28:29 2020 user.info kernel: [   11.427923] block: extroot: device not present, retrying in 30 seconds
Sat Feb  8 04:28:29 2020 user.err kernel: [   41.505104] block: extroot: cannot find device sda1
Sat Feb  8 04:28:29 2020 user.info kernel: [   41.512578] mount_root: switching to jffs2 overlay
Sat Feb  8 04:28:29 2020 kern.warn kernel: [   41.574946] overlayfs: upper fs does not support tmpfile.
Sat Feb  8 04:28:29 2020 user.warn kernel: [   41.593271] urandom-seed: Seeding with /etc/urandom.seed
Sat Feb  8 04:28:29 2020 kern.info kernel: [   41.739952] b44 ssb0:0 eth0: powering down PHY
Sat Feb  8 04:28:29 2020 user.info kernel: [   41.799269] procd: - early -
Sat Feb  8 04:28:29 2020 user.info kernel: [   41.802623] procd: - watchdog -
Sat Feb  8 04:28:29 2020 kern.info kernel: [   42.644641] b44 ssb0:0 eth0: Link is Down
Sat Feb  8 04:28:29 2020 user.info kernel: [   42.663591] procd: - watchdog -
Sat Feb  8 04:28:29 2020 user.info kernel: [   42.671650] procd: - ubus -
Sat Feb  8 04:28:29 2020 kern.notice kernel: [   42.832152] random: ubusd: uninitialized urandom read (4 bytes read)
Sat Feb  8 04:28:29 2020 kern.notice kernel: [   42.847051] random: ubusd: uninitialized urandom read (4 bytes read)
Sat Feb  8 04:28:29 2020 kern.notice kernel: [   42.864491] random: ubusd: uninitialized urandom read (4 bytes read)
Sat Feb  8 04:28:29 2020 user.info kernel: [   42.894933] procd: - init -
Sat Feb  8 04:28:29 2020 user.info kernel: [   45.334548] kmodloader: loading kernel modules from /etc/modules.d/*
Sat Feb  8 04:28:29 2020 user.info kernel: [   45.609282] urngd: v1.0.2 started.
Sat Feb  8 04:28:29 2020 kern.notice kernel: [   46.344325] random: crng init done
Sat Feb  8 04:28:29 2020 kern.notice kernel: [   46.347811] random: 3 urandom warning(s) missed due to ratelimiting
Sat Feb  8 04:28:29 2020 kern.notice kernel: [   46.671487] SCSI subsystem initialized
Sat Feb  8 04:28:29 2020 kern.info kernel: [   46.857661] ip6_tables: (C) 2000-2006 Netfilter Core Team
Sat Feb  8 04:28:29 2020 kern.info kernel: [   46.918290] ip_tables: (C) 2000-2006 Netfilter Core Team
Sat Feb  8 04:28:29 2020 kern.info kernel: [   46.963671] nf_conntrack version 0.5.0 (1024 buckets, 4096 max)
Sat Feb  8 04:28:29 2020 kern.info kernel: [   47.268827] usb-storage 1-2:1.0: USB Mass Storage device detected
Sat Feb  8 04:28:29 2020 kern.info kernel: [   47.304782] scsi host0: usb-storage 1-2:1.0
Sat Feb  8 04:28:29 2020 kern.info kernel: [   47.310910] usbcore: registered new interface driver usb-storage
Sat Feb  8 04:28:29 2020 kern.info kernel: [   47.419241] xt_time: kernel timezone is -0000
Sat Feb  8 04:28:29 2020 user.info kernel: [   47.454814] kmodloader: done loading kernel modules from /etc/modules.d/*
Sat Feb  8 04:28:29 2020 kern.notice kernel: [   48.326153] scsi 0:0:0:0: Direct-Access     VBTM     Store 'n' Go     1.04 PQ: 0 ANSI: 0 CCS
Sat Feb  8 04:28:29 2020 kern.notice kernel: [   48.345694] sd 0:0:0:0: [sda] 501760 512-byte logical blocks: (257 MB/245 MiB)
Sat Feb  8 04:28:29 2020 kern.notice kernel: [   48.364030] sd 0:0:0:0: [sda] Write Protect is off
Sat Feb  8 04:28:29 2020 kern.debug kernel: [   48.369015] sd 0:0:0:0: [sda] Mode Sense: 23 00 00 00
Sat Feb  8 04:28:29 2020 kern.err kernel: [   48.374320] sd 0:0:0:0: [sda] No Caching mode page found
Sat Feb  8 04:28:29 2020 kern.err kernel: [   48.379821] sd 0:0:0:0: [sda] Assuming drive cache: write through
Sat Feb  8 04:28:29 2020 kern.info kernel: [   48.413633]  sda: sda1

i suspect that kmodloader is only reading the /rom/etc/modules-boot.d/ and ignoring the /etc/modules-boot.d/

# ls -l /etc/modules-boot.d/ /rom/etc/modules-boot.d/
/etc/modules-boot.d/:
lrwxrwxrwx    1 root     root            27 Feb  8 00:52 02-crypto-hash -> ../modules.d/02-crypto-hash
lrwxrwxrwx    1 root     root            29 Feb  8 00:52 04-crypto-crc32c -> ../modules.d/04-crypto-crc32c
lrwxrwxrwx    1 root     root            23 Jan 29 16:05 19-usb-ssb -> ../modules.d/19-usb-ssb
lrwxrwxrwx    1 root     root            25 Feb  8 00:52 20-lib-crc16 -> ../modules.d/20-lib-crc16
lrwxrwxrwx    1 root     root            24 Jan 29 16:05 20-usb-core -> ../modules.d/20-usb-core
lrwxrwxrwx    1 root     root            23 Feb  8 00:52 30-fs-ext4 -> ../modules.d/30-fs-ext4
lrwxrwxrwx    1 root     root            35 Jan 29 16:05 30-gpio-button-hotplug -> ../modules.d/30-gpio-button-hotplug
lrwxrwxrwx    1 root     root            24 Jan 29 16:05 35-usb-ehci -> ../modules.d/35-usb-ehci
lrwxrwxrwx    1 root     root            25 Feb  8 00:53 40-scsi-core -> ../modules.d/40-scsi-core
lrwxrwxrwx    1 root     root            20 Jan 29 16:05 40-usb2 -> ../modules.d/40-usb2
lrwxrwxrwx    1 root     root            24 Jan 29 16:05 42-usb2-pci -> ../modules.d/42-usb2-pci
lrwxrwxrwx    1 root     root            34 Jan 29 16:05 50-ledtrig-default-on -> ../modules.d/50-ledtrig-default-on
lrwxrwxrwx    1 root     root            29 Jan 29 16:05 50-ledtrig-timer -> ../modules.d/50-ledtrig-timer
lrwxrwxrwx    1 root     root            24 Jan 29 16:05 50-usb-uhci -> ../modules.d/50-usb-uhci
lrwxrwxrwx    1 root     root            25 Jan 29 16:05 60-leds-gpio -> ../modules.d/60-leds-gpio
lrwxrwxrwx    1 root     root            24 Feb  8 09:43 usb-storage -> ../modules.d/usb-storage

/rom/etc/modules-boot.d/:
lrwxrwxrwx    1 root     root            23 Jan 29 16:05 19-usb-ssb -> ../modules.d/19-usb-ssb
lrwxrwxrwx    1 root     root            24 Jan 29 16:05 20-usb-core -> ../modules.d/20-usb-core
lrwxrwxrwx    1 root     root            35 Jan 29 16:05 30-gpio-button-hotplug -> ../modules.d/30-gpio-button-hotplug
lrwxrwxrwx    1 root     root            24 Jan 29 16:05 35-usb-ehci -> ../modules.d/35-usb-ehci
lrwxrwxrwx    1 root     root            20 Jan 29 16:05 40-usb2 -> ../modules.d/40-usb2
lrwxrwxrwx    1 root     root            24 Jan 29 16:05 42-usb2-pci -> ../modules.d/42-usb2-pci
lrwxrwxrwx    1 root     root            34 Jan 29 16:05 50-ledtrig-default-on -> ../modules.d/50-ledtrig-default-on
lrwxrwxrwx    1 root     root            29 Jan 29 16:05 50-ledtrig-timer -> ../modules.d/50-ledtrig-timer
lrwxrwxrwx    1 root     root            24 Jan 29 16:05 50-usb-uhci -> ../modules.d/50-usb-uhci
lrwxrwxrwx    1 root     root            25 Jan 29 16:05 60-leds-gpio -> ../modules.d/60-leds-gpio

manual mount works fine:

~# mount /dev/sda1 /mnt/
~# df -h
Filesystem                Size      Used Available Use% Mounted on
/dev/root                 2.6M      2.6M         0 100% /rom
tmpfs                    13.8M     64.0K     13.7M   0% /tmp
/dev/mtdblock5            3.8M    736.0K      3.1M  19% /overlay
overlayfs:/overlay        3.8M    736.0K      3.1M  19% /
tmpfs                   512.0K         0    512.0K   0% /dev
/dev/sda1               233.2M     21.7M    195.3M  10% /mnt

Trying to increase the wait time to mount the extroot do not work, as usb-storage is not loaded, waiting more time will not help.

Trying the

export PREINIT=1
mount_root

may work, but i can't ssh to the device, it returns permission denied (publickey) but the /mnt/upper/etc/dropbear/authorized_keys is equal to the one in /etc/dropbear/

So i'm missing something or something is broken in my system or in openwrt?

Thanks in advance for the help
higuita

Jantek · May 6, 2020, 8:43pm

Hi I got a similar behavior on my TD-W8970B:

root@Router:~# logread | sed -n -e "/- preinit -/,/- init -/p"
Wed May  6 22:32:02 2020 user.info kernel: [    5.338925] init: - preinit -
Wed May  6 22:32:02 2020 kern.info kernel: [    5.799236] usb 2-1: new high-speed USB device number 2 using dwc2
Wed May  6 22:32:02 2020 kern.info kernel: [    6.501380] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
Wed May  6 22:32:02 2020 kern.notice kernel: [    9.806706] jffs2: notice: (496) jffs2_build_xattr_subsystem: complete building xattr subsystem, 17 of xdatum (3 unchecked, 14 orphan) and 52 of xref (14 dead, 0 orphan) found.
Wed May  6 22:32:02 2020 user.info kernel: [    9.855152] mount_root: loading kmods from internal overlay
Wed May  6 22:32:02 2020 user.info kernel: [   10.283455] kmodloader: loading kernel modules from /tmp/overlay/upper/etc/modules-boot.d/*
Wed May  6 22:32:02 2020 kern.notice kernel: [   10.894748] SCSI subsystem initialized
Wed May  6 22:32:02 2020 kern.info kernel: [   10.945337] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
Wed May  6 22:32:02 2020 kern.info kernel: [   10.951583] ohci-platform: OHCI generic platform driver
Wed May  6 22:32:02 2020 kern.info kernel: [   10.986591] usb-storage 2-1:1.0: USB Mass Storage device detected
Wed May  6 22:32:02 2020 kern.info kernel: [   10.992486] scsi host0: usb-storage 2-1:1.0
Wed May  6 22:32:02 2020 kern.info kernel: [   10.996724] usbcore: registered new interface driver usb-storage
Wed May  6 22:32:02 2020 kern.info kernel: [   11.016212] uhci_hcd: USB Universal Host Controller Interface driver
Wed May  6 22:32:02 2020 user.info kernel: [   11.022103] kmodloader: done loading kernel modules from /tmp/overlay/upper/etc/modules-boot.d/*
Wed May  6 22:32:02 2020 user.info kernel: [   11.416231] block: attempting to load /tmp/jffs_cfg/upper/etc/config/fstab
Wed May  6 22:32:02 2020 user.info kernel: [   11.440909] block: extroot: device not present, retrying in 5 seconds
Wed May  6 22:32:02 2020 kern.notice kernel: [   11.998686] scsi 0:0:0:0: Direct-Access     USB Mass Storage Device        PQ: 0 ANSI: 0 CCS
Wed May  6 22:32:02 2020 kern.notice kernel: [   12.011761] sd 0:0:0:0: [sda] Attached SCSI removable disk
Wed May  6 22:32:02 2020 user.err kernel: [   16.766687] block: extroot: cannot find device with UUID cb10bb9b-191e-4e90-8e84-fe7ee5b24604
Wed May  6 22:32:02 2020 user.info kernel: [   16.792085] mount_root: switching to jffs2 overlay
Wed May  6 22:32:02 2020 kern.warn kernel: [   16.836657] overlayfs: upper fs does not support tmpfile.
Wed May  6 22:32:02 2020 user.warn kernel: [   16.861733] urandom-seed: Seeding with /etc/urandom.seed
Wed May  6 22:32:02 2020 user.info kernel: [   17.087684] procd: - early -
Wed May  6 22:32:02 2020 user.info kernel: [   17.089316] procd: - watchdog -
Wed May  6 22:32:02 2020 kern.notice kernel: [   17.699803] sd 0:0:0:0: [sda] 7744512 512-byte logical blocks: (3.97 GB/3.69 GiB)
Wed May  6 22:32:02 2020 kern.info kernel: [   17.713828]  sda: sda1
Wed May  6 22:32:02 2020 user.info kernel: [   18.216564] procd: - watchdog -
Wed May  6 22:32:02 2020 user.info kernel: [   18.219223] procd: - ubus -
Wed May  6 22:32:02 2020 user.info kernel: [   18.438348] procd: - init -
root@Router:~#

I doesn't matter how great I set delay_root. The partition don't get recognized in preinit state.

desmo999r · June 1, 2021, 7:40am

Hello,

I had the same problem with my TP-W8970 which has 4MB of flash and does not provide the usb-storage driver during the pre init phase.
I had to create a custom image with the right packages to have it work.
It very well explained here: https://openwrt.org/docs/guide-user/additional-software/extroot_configuration#custom_image
And the process is painless.

Here is the build command I used:

make image PROFILE=tplink_tdw8970 PACKAGES="block-mount kmod-fs-ext4 kmod-usb-storage kmod-usb-ohci kmod-usb-uhci kmod-usb-dwc2 kmod-usb-ledtrig-usbport kmod-ath9k"