Storage hotplugging under the hood


#1

This is an excerpt from system log on ORxPi2 hotplugging a 4GB USB flash drive. I decided to break the logs down and explain what it’s doing step by step for your reference.

USB device is connected:

Jan  4 14:06:15 orxpi2 user.info kernel: [   67.612543] usb 1-1.5: new high-speed USB device number 6 using dwc_otg
Jan  4 14:06:15 orxpi2 user.info kernel: [   67.739677] usb 1-1.5: New USB device found, idVendor=8564, idProduct=1000
Jan  4 14:06:15 orxpi2 user.info kernel: [   67.748274] usb 1-1.5: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Jan  4 14:06:15 orxpi2 user.info kernel: [   67.758645] usb 1-1.5: Product: Mass Storage Device
Jan  4 14:06:15 orxpi2 user.info kernel: [   67.765239] usb 1-1.5: Manufacturer: JetFlash
Jan  4 14:06:15 orxpi2 user.info kernel: [   67.771166] usb 1-1.5: SerialNumber: LA4ZUK7O
Jan  4 14:06:15 orxpi2 user.info kernel: [   67.778617] usb-storage 1-1.5:1.0: USB Mass Storage device detected
Jan  4 14:06:15 orxpi2 user.info kernel: [   67.788302] scsi host0: usb-storage 1-1.5:1.0
Jan  4 14:06:16 orxpi2 user.notice kernel: [   68.794610] scsi 0:0:0:0: Direct-Access     JetFlash Transcend 4GB    8.07 PQ: 0 ANSI: 4
Jan  4 14:06:16 orxpi2 user.notice kernel: [   68.809659] sd 0:0:0:0: [sda] 7626752 512-byte logical blocks: (3.90 GB/3.63 GiB)
Jan  4 14:06:16 orxpi2 user.notice kernel: [   68.823758] sd 0:0:0:0: [sda] Write Protect is off
Jan  4 14:06:16 orxpi2 user.debug kernel: [   68.831272] sd 0:0:0:0: [sda] Mode Sense: 23 00 00 00
Jan  4 14:06:16 orxpi2 user.notice kernel: [   68.832287] sd 0:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
Jan  4 14:06:16 orxpi2 user.info kernel: [   68.851082]  sda: sda1
Jan  4 14:06:16 orxpi2 user.notice kernel: [   68.859441] sd 0:0:0:0: [sda] Attached SCSI removable disk

Hotplug detects the device. This device is formatted FAT32 (on Linux), and is therefore checked for integrity.

Jan  4 14:06:17 orxpi2 user.debug hotplug.sda1: Checking filesystem using /sbin/fsck.fat

Device is temporarily mounted so that its contents can be checked:

Jan  4 14:06:18 orxpi2 user.debug hotplug.sda1: Mounting /dev/sda1 -> /mnt/sda1
Jan  4 14:06:18 orxpi2 user.info hotplug.sda1: /dev/sda1 mounted at /mnt/sda1

Hotplug starts examining the contents:

Jan  4 14:06:18 orxpi2 user.debug hotplug.sda1: Processing external storage

External storage is currently marked with a platform file. This file tells the system whether this storage was previously used on another (possibly incompatible) platform. We see here that no platform file is present on the storage:

Jan  4 14:06:21 orxpi2 user.debug hotplug.sda1: External storage platform is: (none)

Hotplug starts to prepare the storage:

Jan  4 14:06:21 orxpi2 user.debug hotplug.sda1: Preparing for external storage use

Services are stopped. Until the services are restarted, GUI is not available and you will see a 500 page.

Jan  4 14:06:21 orxpi2 user.debug hotplug.sda1: Stopping services
Jan  4 14:06:21 orxpi2 user.debug hotplug.sda1: Stoppnig S91librarian
Jan  4 14:06:21 orxpi2 user.debug hotplug.sda1: Stoppnig S91fsal
Jan  4 14:06:21 orxpi2 user.debug hotplug.sda1: Stoppnig S90ondd

When ONDD is stopped, tuner device is released:

Jan  4 14:06:21 orxpi2 user.info kernel: [   73.506069] dw2102: su3000_power_ctrl: 0, initialized 1
Jan  4 14:06:21 orxpi2 user.info kernel: [   73.506069] 

Hotplug continues:

Jan  4 14:06:24 orxpi2 user.debug hotplug.sda1: Services stopped

This is a storage device that has not been initialzied in the past:

Jan  4 14:06:24 orxpi2 user.debug hotplug.sda1: Initializing external storage
Jan  4 14:06:24 orxpi2 user.debug hotplug.sda1: Writing platform file to external storage
Jan  4 14:06:24 orxpi2 user.debug hotplug.sda1: Migrating old directory structure
Jan  4 14:06:24 orxpi2 user.debug hotplug.sda1: Migration finished successfully.

Content is copied from internal storage to external:[1]

Jan  4 14:06:24 orxpi2 user.debug hotplug.sda1: Copying content from internal storage to external
Jan  4 14:06:24 orxpi2 user.debug hotplug.sda1: Copying /mnt/data/downloads/* -> /mnt/sda1

Monitoring script decides to attempt to collect data and fails beccause ONDD
is still stopped:

Jan  4 14:06:31 orxpi2 user.info outernet.monitor: Collecting data
Jan  4 14:06:31 orxpi2 user.info outernet.monitor: Could not connect to socket. Pausing for next attempt
Jan  4 14:06:36 orxpi2 user.info outernet.monitor: Could not connect to socket. Pausing for next attempt
Jan  4 14:06:41 orxpi2 user.info outernet.monitor: Could not connect to socket. Pausing for next attempt
Jan  4 14:06:46 orxpi2 user.info outernet.monitor: Could not connect to socket. Pausing for next attempt
Jan  4 14:06:51 orxpi2 user.info outernet.monitor: Could not connect to socket. Pausing for next attempt
Jan  4 14:06:56 orxpi2 user.info outernet.monitor: Could not connect to socket. Pausing for next attempt
Jan  4 14:07:01 orxpi2 user.info outernet.monitor: Could not connect to socket. Pausing for next attempt
Jan  4 14:07:06 orxpi2 user.info outernet.monitor: Could not connect to socket. Pausing for next attempt
Jan  4 14:07:11 orxpi2 user.info outernet.monitor: Could not connect to socket. Pausing for next attempt
Jan  4 14:07:16 orxpi2 user.info outernet.monitor: Could not connect to socket. Pausing for next attempt

Udev complains about the script taking long, but this is fine.

Jan  4 14:07:17 orxpi2 daemon.warn kernel: [  129.050672] udevd[168]: worker [426] /devices/platform/bcm2708_usb/usb1/1-1/1-1.5/1-1.5:1.0/host0/target0:0:0/0:0:0:0/block/sda/sda1 is taking a long time

Monitoring script is still making attempts to connect to ONDD:

Jan  4 14:07:21 orxpi2 user.info outernet.monitor: Could not connect to socket. Pausing for next attempt
Jan  4 14:07:26 orxpi2 user.info outernet.monitor: Could not connect to socket. Pausing for next attempt
Jan  4 14:07:31 orxpi2 user.info outernet.monitor: Could not connect to socket. Pausing for next attempt
Jan  4 14:07:36 orxpi2 user.info outernet.monitor: Could not connect to socket. Pausing for next attempt

Hotplug is remounting the external storage to correct mount point (/mnt/data/downloads):

Jan  4 14:07:39 orxpi2 user.info hotplug.sda1: Using /dev/sda1 as external storage

Monitoring script is still making attempts to connect to ONDD:

Jan  4 14:07:41 orxpi2 user.info outernet.monitor: Could not connect to socket. Pausing for next attempt
Jan  4 14:07:46 orxpi2 user.info outernet.monitor: Could not connect to socket. Pausing for next attempt
Jan  4 14:07:51 orxpi2 user.info outernet.monitor: Could not connect to socket. Pausing for next attempt
Jan  4 14:07:56 orxpi2 user.info outernet.monitor: Could not connect to socket. Pausing for next attempt
Jan  4 14:08:01 orxpi2 user.info outernet.monitor: Could not connect to socket. Pausing for next attempt
Jan  4 14:08:06 orxpi2 user.info outernet.monitor: Could not connect to socket. Pausing for next attempt
Jan  4 14:08:11 orxpi2 user.info outernet.monitor: Could not connect to socket. Pausing for next attempt
Jan  4 14:08:16 orxpi2 user.info outernet.monitor: Could not connect to socket. Pausing for next attempt
Jan  4 14:08:21 orxpi2 user.info outernet.monitor: Could not connect to socket. Pausing for next attempt

Hotplug is done and is now starting the services.

Jan  4 14:08:22 orxpi2 user.debug hotplug.sda1: Restarting services

ONDD is started.

Jan  4 14:08:22 orxpi2 user.info ondd[461]: [main] v2.2.0

Kernel is initializing the tuner:

Jan  4 14:08:22 orxpi2 user.info kernel: [  194.855055] dw2102: su3000_power_ctrl: 1, initialized 1
Jan  4 14:08:22 orxpi2 user.info kernel: [  194.855055] 

All services are now started:

Jan  4 14:08:22 orxpi2 user.debug hotplug.sda1: Services started

Kernel loads the firmware for the tuner:

Jan  4 14:08:23 orxpi2 user.info kernel: [  194.937414] ds3000_firmware_ondemand: Waiting for firmware upload (dvb-fe-ds3103.fw)...
Jan  4 14:08:23 orxpi2 user.info kernel: [  194.950168] ds3000_firmware_ondemand: Waiting for firmware upload(2)...

ONDD is applying the tuner settings:

Jan  4 14:08:24 orxpi2 user.info ondd[461]: [main] tuning to 1721 Mhz 27500 KSym

Monitoring is successfully getting the data from ONDD:

Jan  4 14:08:26 orxpi2 user.info outernet.monitor: Connected to socket
Jan  4 14:08:26 orxpi2 user.info outernet.monitor: Connected to socket
Jan  4 14:08:26 orxpi2 user.info outernet.monitor: Finished collecting data in 115.151937008 seconds

As you can see, the whole operation took a little over 2 minutes to complete. This is highly dependent on the amount of data you have in the internal storage as copying is the slowest part.

Footnotes:

[1] Note that there is a bug which causes the copying to skip tweets


#2

Is this telling me that the CHIP may not like a flash drive that has been formatted on a Windows PC or other platform? The reason I ask is because, if so, that may be what started the failure on my external 32GB drive.

It was all working, but, at one point, to test the RTL/LNA on other Inmarsat channels, I plugged the USB hub that also contains RTL and the flash drive, into my Windows laptop to run SDR#. After that, the flash drive would no longer work properly on the CHIP. Even when reformatted with a Macbook it still wouldn’t work.

Now, one point to ponder is that the flash drive was originally formatted on a Win7 PC, and worked fine until I plugged it into the laptop once. Same flash drive works fin on other machines/OS, just doesn’t seem to play with rxos. The incoming files get written, but never get processed into Librarian.