Bug 5283

Summary:	Invalid handling of hotplug events coming in wrong order
Product:	hal	Reporter:	Alexander Darovsky <adarovsky>
Component:	hald	Assignee:	David Zeuthen (not reading bugmail) <zeuthen>
Status:	RESOLVED NOTABUG	QA Contact:
Severity:	major
Priority:	high
Version:	unspecified
Hardware:	Other
OS:	Linux (All)
Whiteboard:
i915 platform:		i915 features:
Attachments:	a possible fix

Description Alexander Darovsky 2005-12-08 18:40:37 UTC

Hi.  
  
I have an USB flash disk (working via usb-storage). It works perfectly,  
but unfortunately is not detected by HAL.  
  
I tried to debug HAL and got the following problem:  
  
hotplug system gives information to HAL in the following order:  
  
Dec  8 11:27:01 [hal.hotplug] sending event: 1500: add,  
scsi_device, /class/scsi_device/27:0:0:0 ((nil))  
Dec  8 11:27:01 [hal.hotplug] sending event: 1499: add,  
scsi_generic, /class/scsi_generic/sg0 (/dev/sg0)  
Dec  8 11:27:02 [hal.hotplug] sending event: 1498: add, block, /block/sda/sda1  
(/dev/sda1)  
Dec  8 11:27:02 [hal.hotplug] sending event: 1497: add, block, /block/sda  
(/dev/sda)  
  
HAL does not look on SEQNUM and tries to process /dev/sda1. Of cource, it  
cannot find parent and drops processing of /dev/sda1:  
  
..... 
11:27:01.336 [I] osspec.c:237: bytes_read=213 buf='add@/block/sda' 
11:27:01.368 [I] osspec.c:237: bytes_read=223 buf='add@/block/sda/sda1' 
11:27:01.369 [I] osspec.c:237: bytes_read=247 
buf='add@/class/scsi_generic/sg0' 
11:27:01.370 [I] osspec.c:237: bytes_read=237 
buf='add@/class/scsi_device/27:0:0:0' 
11:27:01.428 [I] osspec.c:154: SEQNUM=1496, TIMESTAMP=1134023221, ACTION=add, 
SUBSYS=scsi, 
SYSFSPATH=/devices/pci0000:00/0000:00:1d.2/usb4/4-1/4-1:1.0/host27/target27:0:0/27:0:0:0, 
DEVNAME=, IFINDEX=-1 
11:27:01.428 [I] physdev.c:1457: phys_add: subsys=scsi 
sysfs_path=/sys/devices/pci0000:00/0000:00:1d.2/usb4/4-1/4-1:1.0/host27/target27:0:0/27:0:0:0, 
parent=0x080cd540 
11:27:01.431 [I] physdev.c:1382: Add callouts completed 
udi=/org/freedesktop/Hal/devices/usb_device_c76_5_noserial_scsi_host_scsi_device_lun0 
11:27:01.432 [I] hald.c:89: Added device to GDL; 
udi=/org/freedesktop/Hal/devices/usb_device_c76_5_noserial_scsi_host_scsi_device_lun0 
11:27:01.462 [I] osspec.c:154: SEQNUM=1500, TIMESTAMP=1134023221, ACTION=add, 
SUBSYS=scsi_device, SYSFSPATH=/class/scsi_device/27:0:0:0, DEVNAME=, 
IFINDEX=-1 
11:27:01.463 [I] classdev.c:1182: class_add: subsys=scsi_device 
sysfs_path=/sys/class/scsi_device/27:0:0:0 dev= physdev=0x080cd268 
11:27:01.474 [I] osspec.c:154: SEQNUM=1499, TIMESTAMP=1134023221, ACTION=add, 
SUBSYS=scsi_generic, SYSFSPATH=/class/scsi_generic/sg0, DEVNAME=/dev/sg0, 
IFINDEX=-1 
11:27:01.474 [I] classdev.c:1182: class_add: subsys=scsi_generic 
sysfs_path=/sys/class/scsi_generic/sg0 dev=/dev/sg0 physdev=0x080cd268 
11:27:02.509 [I] osspec.c:154: SEQNUM=1498, TIMESTAMP=1134023222, ACTION=add, 
SUBSYS=block, SYSFSPATH=/block/sda/sda1, DEVNAME=/dev/sda1, IFINDEX=-1 
11:27:02.510 [I] blockdev.c:566: block_add: sysfs_path=/sys/block/sda/sda1 
dev=/dev/sda1 is_part=1, parent=0x00000000 
11:27:02.510 [I] blockdev.c:477: get_luks_uuid: device_file=/dev/sda1 
11:27:02.510 [I] blockdev.c:602: Ignoring hotplug event - no parent 
11:27:02.523 [I] osspec.c:154: SEQNUM=1497, TIMESTAMP=1134023222, ACTION=add, 
SUBSYS=block, SYSFSPATH=/block/sda, DEVNAME=/dev/sda, IFINDEX=-1 
11:27:02.524 [I] blockdev.c:566: block_add: sysfs_path=/sys/block/sda 
dev=/dev/sda is_part=0, parent=0x080cd268 
11:27:02.524 [I] blockdev.c:781: parent_bus is scsi 
..... 
 
It is not the only case of wrong order of hotplug events, but, as far as I can 
see, these issues take place in the same time, without time gaps between 
messages in wrong order. 
 
Maybe it makes sense to create message buffer and sort it by SEQNUM? Say, set 
a timer (say, 0.5 seconds) when message comes, and process it only when time 
expires. In the meanwhile, there may be several messages arrive, and it will 
be possible to sort them. If message is replaced up in the processing queue, 
it's associated time is computed as min( time(current_message), 
min_time_of_messages_being_surpassed ) 
 
This will give a constant delay of 0.5 seconds, but all devices will be 
detected...

Comment 1 Jörg Walter 2005-12-10 09:11:39 UTC

Created attachment 4063 [details] [review]
a possible fix

This is a possible fix. It isn't the most elegant of solutions, but it is
effective and rather non-intrusive: hal.hotplug attaches a POSIX shared memory
segment containing the last processed seqnum, forks into the background and
waits until the last processed seqnum is seqnum-1, or until .5 seconds elapse
(which never happens on my system, it's just a safeguard because I don't know
hotplug too well).
There is the remote chance of a race condition because storing a new value in
the shared memory segment is probably not atomic (I don't know if it is), but
if this kind of perfection is worth the added complexity of mutex-protected
access is up to you ;)

Comment 2 Danny Kukawka 2005-12-11 02:55:14 UTC

The hal hotplug helper is obsolete with the next release. udev use now a direct 
socket to HAL. Could you try to reproduce this with the newest udev version. 
For more see the CVS comment:

2005-11-15  Kay Sievers  <kay.sievers@vrfy.org>

        * hald/linux2/osspec.c: (hald_udev_data), (hald_helper_data),
        (osspec_init): Listen to socket: /org/freedesktop/hal/udev_event
        Udev will pass all data over this socket to HAL, if the following
        rule is given:
          RUN+="socket:/org/freedesktop/hal/udev_event"

        The HAL hotplug helper /usr/sbin/hal.hotplug is no longer needed
        and should be replaced by the direct udev connection which will
        no longer fork a process for every event.

        This is the preparation to reuse the persistent data udev collects
        from the hardware, instead of querying it a second time with HAL.
        If we reach this, drive_id/* and the hotplug helper will be removed
        from HAL.

Comment 3 Kay Sievers 2005-12-11 06:44:01 UTC

HAL depends on udev to receice kernel events, no other solution is supported or
expected to work reliably.

HAL intentionally does not care about SEQNUM. Udev does that, or recent
kernel/udev setups receive kernel events from a socket instead of using
/sbin/hotplug and SEQNUM.

Comment 4 Alexander Darovsky 2005-12-12 14:32:48 UTC

(In reply to comment #2)  
> The hal hotplug helper is obsolete with the next release. udev use now a  
direct   
> socket to HAL. Could you try to reproduce this with the newest udev version.   
> For more see the CVS comment:  
>   
> 2005-11-15  Kay Sievers  <kay.sievers@vrfy.org>  
>   
>         * hald/linux2/osspec.c: (hald_udev_data), (hald_helper_data),  
>         (osspec_init): Listen to socket: /org/freedesktop/hal/udev_event  
>         Udev will pass all data over this socket to HAL, if the following  
>         rule is given:  
>           RUN+="socket:/org/freedesktop/hal/udev_event"  
>   
>         The HAL hotplug helper /usr/sbin/hal.hotplug is no longer needed  
>         and should be replaced by the direct udev connection which will  
>         no longer fork a process for every event.  
>   
>         This is the preparation to reuse the persistent data udev collects  
>         from the hardware, instead of querying it a second time with HAL.  
>         If we reach this, drive_id/* and the hotplug helper will be removed  
>         from HAL.  
>   
  
Thank you. The problem was really in udev. I couldn't imagine that it can make  
mess from hotplug events, but udev-073 did. Upgrade to 077 or downgrade to 072  
solves this problem

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.