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