hotplug events queued out-of-order

Andrew Allen andrew_d_allen at yahoo.com
Fri Apr 8 13:40:16 PDT 2005 

Hi:

It looks like two simultaneous usb hotplug events are being queued in
non-SEQNUM order, and that causes an unnecessary wait for a timeout (as the
seqnum after last_hotplug_seqnum is already in the queue, and thus won't be
sent again...), which delays the running of fstab-sync. I can't quite unravel
the queueing of osspec.c enough to know what needs to be fixed here. 

running hal-0.4.7, udev 039, hotplug-2004_04_01 on the newest fedora core 3
kernel 2.6.10-1.770_FC3

Andrew

---

here's the interesting part of the hald (hal-0.4.7) output:

13:04:26.425 [I] linux/osspec.c:1667: SEQNUM=901, TIMESTAMP=1112990666
13:04:26.426 [I] linux/osspec.c:1739: Queing up seqnum=901,
sysfspath=/devices/pci0000:00/0000:00:10.2/usb4/4-1/4-1:1.0, subsys=usb
13:04:26.426 [I] linux/osspec.c:1667: SEQNUM=900, TIMESTAMP=1112990666
13:04:26.426 [I] linux/osspec.c:1739: Queing up seqnum=900,
sysfspath=/devices/pci0000:00/0000:00:10.2/usb4/4-1, subsys=usb
13:04:26.426 [I] linux/osspec.c:1349: action=add seqnum=900 subsystem=usb
sysfs_path=/sys/devices/pci0000:00/0000:00:10.2/usb4/4-1
13:04:27.883 [I] device_info.c:1160: scan_fdi_files: Processing file
'6in1-card-reader.fdi'
13:04:27.883 [I] device_info.c:1160: scan_fdi_files: Processing file
'7in1-card-reader.fdi'
13:04:27.883 [I] device_info.c:1160: scan_fdi_files: Processing file
'ide-drives.fdi'
13:04:27.883 [I] device_info.c:1160: scan_fdi_files: Processing file
'jetflash-mp3-player.fdi'
13:04:27.883 [I] device_info.c:1160: scan_fdi_files: Processing file
'lexar-media-cf-reader.fdi'
13:04:27.884 [I] device_info.c:1160: scan_fdi_files: Processing file
'lucent-pcmcia-wireless.fdi'
13:04:27.884 [I] device_info.c:1160: scan_fdi_files: Processing file
'sony_dsc.fdi'
13:04:27.884 [I] device_info.c:1160: scan_fdi_files: Processing file
'usb-zip-drives.fdi'
13:04:27.884 [I] device_info.c:1160: scan_fdi_files: Processing file
'storage-policy.fdi'
13:04:27.885 [I] callout.c:318: Invoking /etc/hal/device.d/printer_remove.hal
13:04:27.890 [I] callout.c:330: Child pid 32489 for printer_remove.hal
13:04:27.891 [I] linux/osspec.c:1544:
******************************************
13:04:27.891 [I] linux/osspec.c:1545: **** hotplug_counter is now 1
13:04:27.891 [I] linux/osspec.c:1546:
******************************************
13:04:27.891 [I] linux/osspec.c:1667: SEQNUM=902, TIMESTAMP=1112990666
13:04:27.891 [I] linux/osspec.c:1739: Queing up seqnum=902,
sysfspath=/class/scsi_host/host13, subsys=scsi_host
libhal.c 911 : Error sending msg: Message did not receive a reply
13:05:04.046 [I] linux/osspec.c:1514: Looking at 901
13:05:04.046 [I] linux/osspec.c:1514: Looking at 902
13:05:04.046 [E] linux/osspec.c:1521: Timed out waiting for hotplug event 901.
Rebasing to 901

and the interesting part of /var/log/messages:

Apr  8 12:40:23 localhost kernel: usb 4-1: new full speed USB device using
uhci_hcd and address 16
Apr  8 12:40:23 localhost kernel: usb 4-1: not running at top speed; connect to
a high speed hub
Apr  8 12:40:23 localhost kernel: scsi11 : SCSI emulation for USB Mass Storage
devices
Apr  8 12:40:24 localhost default.hotplug[30366]: arguments (usb) env
(SUBSYSTEM=usb OLDPWD=/ DEVPATH=/devices/pci0000:00/0000:00:10.2/usb4/4-1
PATH=/bin:/sbin:/usr/sbin:/usr/bin ACTION=add PWD=/etc/hotplug HOME=/ SHLVL=2
PHYSDEVDRIVER=usb DEBUG=yes PHYSDEVBUS=usb SEQNUM=872 _=/bin/env)
Apr  8 12:40:24 localhost default.hotplug[30366]: invoke /etc/hotplug/usb.agent
()
Apr  8 12:40:24 localhost default.hotplug[30379]: arguments (usb) env
(SUBSYSTEM=usb OLDPWD=/
DEVPATH=/devices/pci0000:00/0000:00:10.2/usb4/4-1/4-1:1.0
PATH=/bin:/sbin:/usr/sbin:/usr/bin ACTION=add PWD=/etc/hotplug HOME=/ SHLVL=2
DEVICE=/proc/bus/usb/004/016 INTERFACE=8/6/80 PRODUCT=d7d/1600/100 TYPE=0/0/0
DEBUG=yes PHYSDEVBUS=usb SEQNUM=873 _=/bin/env)
Apr  8 12:40:24 localhost default.hotplug[30379]: invoke /etc/hotplug/usb.agent
()
Apr  8 12:40:24 localhost default.hotplug[30401]: arguments (scsi_host) env
(PHYSDEVPATH=/devices/pci0000:00/0000:00:10.2/usb4/4-1/4-1:1.0/host11
SUBSYSTEM=scsi_host OLDPWD=/ DEVPATH=/class/scsi_host/host11
PATH=/bin:/sbin:/usr/sbin:/usr/bin ACTION=add PWD=/etc/hotplug HOME=/ SHLVL=2
DEBUG=yes SEQNUM=874 _=/bin/env)
Apr  8 12:40:24 localhost default.hotplug[30401]: no runnable
/etc/hotplug/scsi_host.agent is installed
Apr  8 12:40:24 localhost default.hotplug[30401]: log to
/var/log/hotplug/events (scsi_host )
Apr  8 12:40:25 localhost usb.agent[30379]: Setup usb-storage for USB product
d7d/1600/100
Apr  8 12:40:25 localhost usb.agent[30379]: Setup 0x00 0x00 for USB product
d7d/1600/100
Apr  8 12:40:28 localhost kernel:   Vendor:           Model: USB DISK 20X     
Rev: PMAP
Apr  8 12:40:28 localhost kernel:   Type:   Direct-Access                     
ANSI SCSI revision: 00
Apr  8 12:40:29 localhost kernel: SCSI device sdg: 251904 512-byte hdwr sectors
(129 MB)
Apr  8 12:40:29 localhost kernel: sdg: Write Protect is off
Apr  8 12:40:29 localhost kernel: sdg: assuming drive cache: write through
Apr  8 12:40:29 localhost kernel: SCSI device sdg: 251904 512-byte hdwr sectors
(129 MB)
Apr  8 12:40:29 localhost kernel: sdg: Write Protect is off
Apr  8 12:40:29 localhost kernel: sdg: assuming drive cache: write through
Apr  8 12:40:29 localhost kernel:  sdg: sdg1
Apr  8 12:40:29 localhost kernel: Attached scsi removable disk sdg at scsi11,
channel 0, id 0, lun 0
Apr  8 12:40:29 localhost default.hotplug[30461]: arguments (scsi) env
(SUBSYSTEM=scsi OLDPWD=/
DEVPATH=/devices/pci0000:00/0000:00:10.2/usb4/4-1/4-1:1.0/host11/target11:0:0/11:0:0:0
PATH=/bin:/sbin:/usr/sbin:/usr/bin ACTION=add PWD=/etc/hotplug HOME=/ SHLVL=2
DEBUG=yes PHYSDEVBUS=scsi SEQNUM=875 _=/bin/env)
Apr  8 12:40:29 localhost default.hotplug[30461]: invoke
/etc/hotplug/scsi.agent ()
Apr  8 12:40:29 localhost scsi.agent[30461]: disk at
/devices/pci0000:00/0000:00:10.2/usb4/4-1/4-1:1.0/host11/target11:0:0/11:0:0:0
Apr  8 12:40:29 localhost default.hotplug[30458]: arguments (block) env
(PHYSDEVPATH=/devices/pci0000:00/0000:00:10.2/usb4/4-1/4-1:1.0/host11/target11:0:0/11:0:0:0
SUBSYSTEM=block OLDPWD=/ DEVPATH=/block/sdg PATH=/bin:/sbin:/usr/sbin:/usr/bin
ACTION=add PWD=/etc/hotplug HOME=/ SHLVL=2 PHYSDEVDRIVER=sd DEBUG=yes
PHYSDEVBUS=scsi SEQNUM=876 _=/bin/env)
Apr  8 12:40:29 localhost default.hotplug[30458]: no runnable
/etc/hotplug/block.agent is installed
Apr  8 12:40:29 localhost default.hotplug[30458]: log to
/var/log/hotplug/events (block )
Apr  8 12:40:29 localhost default.hotplug[30493]: arguments (scsi_device) env
(PHYSDEVPATH=/devices/pci0000:00/0000:00:10.2/usb4/4-1/4-1:1.0/host11/target11:0:0/11:0:0:0
SUBSYSTEM=scsi_device OLDPWD=/ DEVPATH=/class/scsi_device/11:0:0:0
PATH=/bin:/sbin:/usr/sbin:/usr/bin
ACTION=add PWD=/etc/hotplug HOME=/ SHLVL=2 PHYSDEVDRIVER=sd DEBUG=yes
PHYSDEVBUS=scsi SEQNUM=878 _=/bin/env)
Apr  8 12:40:29 localhost default.hotplug[30503]: arguments (block) env
(PHYSDEVPATH=/devices/pci0000:00/0000:00:10.2/usb4/4-1/4-1:1.0/host11/target11:0:0/11:0:0:0
SUBSYSTEM=block OLDPWD=/ DEVPATH=/block/sdg/sdg1
PATH=/bin:/sbin:/usr/sbin:/usr/bin ACTION=add PWD=/etc/hotplug HOME=/ SHLVL=2
PHYSDEVDRIVER=sd DEBUG=yes PHYSDEVBUS=scsi SEQNUM=877 _=/bin/env)
Apr  8 12:40:29 localhost default.hotplug[30503]: no runnable
/etc/hotplug/block.agent is installed
Apr  8 12:40:29 localhost default.hotplug[30503]: log to
/var/log/hotplug/events (block )
Apr  8 12:40:29 localhost default.hotplug[30493]: no runnable
/etc/hotplug/scsi_device.agent is installed
Apr  8 12:40:29 localhost default.hotplug[30493]: log to
/var/log/hotplug/events (scsi_device )
Apr  8 12:41:01 localhost hald[29981]: Timed out waiting for hotplug event 873.
Rebasing to 873
Apr  8 12:41:02 localhost fstab-sync[30558]: added mount point
/media/UDISK_20X1 for /dev/sdg1
Apr  8 12:41:02 localhost kernel: FAT: utf8 is not a recommended IO charset for
FAT filesystems, filesystem will be case sensitive!
Apr  8 12:41:02 localhost kernel: SELinux: initialized (dev sdg1, type vfat),
uses genfs_contexts
Apr  8 12:45:01 localhost crond(pam_unix)[30576]: session opened for user root
by (uid=0)
Apr  8 12:45:02 localhost crond(pam_unix)[30576]: session closed for user root



		
__________________________________ 
Yahoo! Messenger 
Show us what our next emoticon should look like. Join the fun. 
http://www.advision.webevents.yahoo.com/emoticontest
_______________________________________________
hal mailing list
hal at lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/hal

More information about the Hal mailing list