2.6.30: hald crashes on resume from STR apparently on LED device
Andrey Borzenkov
arvidjaar at mail.ru
Sun Jun 21 07:17:23 PDT 2009
On Sunday 14 of June 2009 22:19:02 Andrey Borzenkov wrote:
> I did not experience this crash under 2.6.29. I got it under 2.6.30
> (both rc and final) with varying frequency. At least for me it is
> 2.6.30 regression.
>
> hald aborts on D-Bus assertion with stack trace below.Program
> received signal SIGABRT, Aborted.
> 0x00007f183ff9e915 in raise (sig=<value optimized out>) at
> ../nptl/sysdeps/unix/sysv/linux/raise.c:64
> 64 return INLINE_SYSCALL (tgkill, 3, pid, selftid, sig);
> (gdb) bt
> #0 0x00007f183ff9e915 in raise (sig=<value optimized out>) at
> ../nptl/sysdeps/unix/sysv/linux/raise.c:64
> #1 0x00007f183ff9ff8a in abort () at abort.c:88
> #2 0x00007f1840793f35 in _dbus_abort () at dbus-sysdeps.c:88
> #3 0x00007f184078fd6d in _dbus_warn_check_failed (
> format=0x7f184079c5a0 "arguments to %s() were incorrect,
> assertion \"%s\" failed in file %s line %d.\nThis is normally a bug
> in some application using the D-Bus library.\n") at
> dbus-internals.c:283 #4 0x00007f18407873f9 in
> dbus_pending_call_set_notify (pending=0x0, function=0x41b320
> <reply_from_singleton_device_changed>,
> user_data=0xc74c30, free_user_data=0x416000 <del_sdci>) at dbus-
> pending-call.c:598
> #5 0x0000000000415f6e in singleton_signal_device_changed
> (connection=0xbdc140, device=0x7f18411af2c0, added=1)
> at hald_dbus.c:3481
> #6 0x0000000000419fe2 in hald_singleton_device_added
> (command_line=0xc601e0 "hald-addon-leds", device=0x7f18411af2c0)
> at hald_dbus.c:3570
OK this is HAL bug which could be triggered by some changes in 2.6.30
series. I leave kernel on Cc list so far to ask whether there was
actually behaviour change in 2.6.30 or it is just different timing that
now hits badly.
So what happens is simple. During suspend led device is removed; during
resume it is recreated. Apparently removing led device cause hald-addon-
leds to exit (thus disconnecting D-Bus connection); and sometimes next
"add" event comes too early, before hald had chance to notice missing
addon.
So attached is POC patch that simply adds extra check to
hald_singleton_device_added() to ensure we do not abort on disconnected
D-Bus connection. It does not seem to have evil effects; it is possible
that we do miss some event but I do not quite understand processing
logic here. Apparently event should be replayed ...
Here is list of hald processes after resume. Notice that hald-addon-leds
is restarted every time:
pts/1}% pgrep -l hald
13996 hald
13997 hald-runner
14098 hald-addon-rfki
14130 hald-addon-gene
14156 hald-addon-inpu
14190 hald-addon-stor
14194 hald-addon-cpuf
14195 hald-addon-acpi
14796 hald-addon-leds
{pts/1}% pgrep -l hald
13996 hald
13997 hald-runner
14098 hald-addon-rfki
14130 hald-addon-gene
14156 hald-addon-inpu
14190 hald-addon-stor
14194 hald-addon-cpuf
14195 hald-addon-acpi
16145 hald-addon-leds
{pts/1}% pgrep -l hald
13996 hald
13997 hald-runner
14098 hald-addon-rfki
14130 hald-addon-gene
14156 hald-addon-inpu
14190 hald-addon-stor
14194 hald-addon-cpuf
14195 hald-addon-acpi
17543 hald-addon-leds
{pts/1}% pgrep -l hald
13996 hald
13997 hald-runner
14098 hald-addon-rfki
14130 hald-addon-gene
14156 hald-addon-inpu
14190 hald-addon-stor
14194 hald-addon-cpuf
14195 hald-addon-acpi
{pts/1}% pgrep -l hald
13996 hald
13997 hald-runner
14098 hald-addon-rfki
14130 hald-addon-gene
14156 hald-addon-inpu
14190 hald-addon-stor
14194 hald-addon-cpuf
14195 hald-addon-acpi
21842 hald-addon-leds
{pts/1}% pgrep -l hald
13996 hald
13997 hald-runner
14098 hald-addon-rfki
14130 hald-addon-gene
14156 hald-addon-inpu
14190 hald-addon-stor
14194 hald-addon-cpuf
14195 hald-addon-acpi
23946 hald-addon-leds
and events that are generated by kernel during suspend/remove cycle:
{pts/0}% sudo udevadm monitor --env --kernel
monitor will print the received events for:
KERNEL - the kernel uevent
KERNEL[1245593084.803490] remove
/devices/pci0000:00/0000:00:1c.1/0000:0c:00.0/leds/iwl-phy0::assoc
(leds)
UDEV_LOG=3
ACTION=remove
DEVPATH=/devices/pci0000:00/0000:00:1c.1/0000:0c:00.0/leds/iwl-
phy0::assoc
SUBSYSTEM=leds
SEQNUM=1458
KERNEL[1245593084.803530] remove
/devices/pci0000:00/0000:00:1c.1/0000:0c:00.0/leds/iwl-phy0::RX (leds)
UDEV_LOG=3
ACTION=remove
DEVPATH=/devices/pci0000:00/0000:00:1c.1/0000:0c:00.0/leds/iwl-phy0::RX
SUBSYSTEM=leds
SEQNUM=1459
KERNEL[1245593084.803550] remove
/devices/pci0000:00/0000:00:1c.1/0000:0c:00.0/leds/iwl-phy0::TX (leds)
UDEV_LOG=3
ACTION=remove
DEVPATH=/devices/pci0000:00/0000:00:1c.1/0000:0c:00.0/leds/iwl-phy0::TX
SUBSYSTEM=leds
SEQNUM=1460
KERNEL[1245593084.803570] remove
/devices/pci0000:00/0000:00:1c.1/0000:0c:00.0/leds/iwl-phy0::radio
(leds)
UDEV_LOG=3
ACTION=remove
DEVPATH=/devices/pci0000:00/0000:00:1c.1/0000:0c:00.0/leds/iwl-
phy0::radio
SUBSYSTEM=leds
SEQNUM=1461
KERNEL[1245593084.803590] remove /devices/system/cpu/cpu1/cpufreq
(cpu)
UDEV_LOG=3
ACTION=remove
DEVPATH=/devices/system/cpu/cpu1/cpufreq
SUBSYSTEM=cpu
SEQNUM=1462
KERNEL[1245593084.803610] remove /devices/system/cpu/cpu1/cache/index0
(cpu)
UDEV_LOG=3
ACTION=remove
DEVPATH=/devices/system/cpu/cpu1/cache/index0
SUBSYSTEM=cpu
SEQNUM=1463
KERNEL[1245593084.803629] remove /devices/system/cpu/cpu1/cache/index1
(cpu)
UDEV_LOG=3
ACTION=remove
DEVPATH=/devices/system/cpu/cpu1/cache/index1
SUBSYSTEM=cpu
SEQNUM=1464
KERNEL[1245593084.803648] remove /devices/system/cpu/cpu1/cache/index2
(cpu)
UDEV_LOG=3
ACTION=remove
DEVPATH=/devices/system/cpu/cpu1/cache/index2
SUBSYSTEM=cpu
SEQNUM=1465
KERNEL[1245593084.803667] remove /devices/system/cpu/cpu1/cache (cpu)
UDEV_LOG=3
ACTION=remove
DEVPATH=/devices/system/cpu/cpu1/cache
SUBSYSTEM=cpu
SEQNUM=1466
KERNEL[1245593084.803687] remove
/devices/system/machinecheck/machinecheck1 (machinecheck)
UDEV_LOG=3
ACTION=remove
DEVPATH=/devices/system/machinecheck/machinecheck1
SUBSYSTEM=machinecheck
SEQNUM=1467
KERNEL[1245593084.803707] add /devices/system/cpu/cpu1/cache/index0
(cpu)
UDEV_LOG=3
ACTION=add
DEVPATH=/devices/system/cpu/cpu1/cache/index0
SUBSYSTEM=cpu
SEQNUM=1468
KERNEL[1245593084.803726] add /devices/system/cpu/cpu1/cache/index1
(cpu)
UDEV_LOG=3
ACTION=add
DEVPATH=/devices/system/cpu/cpu1/cache/index1
SUBSYSTEM=cpu
SEQNUM=1469
KERNEL[1245593084.803745] add /devices/system/cpu/cpu1/cache/index2
(cpu)
UDEV_LOG=3
ACTION=add
DEVPATH=/devices/system/cpu/cpu1/cache/index2
SUBSYSTEM=cpu
SEQNUM=1470
KERNEL[1245593084.803764] add /devices/system/cpu/cpu1/cache (cpu)
UDEV_LOG=3
ACTION=add
DEVPATH=/devices/system/cpu/cpu1/cache
SUBSYSTEM=cpu
SEQNUM=1471
KERNEL[1245593084.803784] add
/devices/system/machinecheck/machinecheck1 (machinecheck)
UDEV_LOG=3
ACTION=add
DEVPATH=/devices/system/machinecheck/machinecheck1
SUBSYSTEM=machinecheck
SEQNUM=1472
KERNEL[1245593084.803804] add /devices/system/cpu/cpu1/cpufreq
(cpu)
UDEV_LOG=3
ACTION=add
DEVPATH=/devices/system/cpu/cpu1/cpufreq
SUBSYSTEM=cpu
SEQNUM=1473
KERNEL[1245593084.803825] change
/devices/LNXSYSTM:00/device:00/ACPI0003:00/power_supply/AC
(power_supply)
UDEV_LOG=3
ACTION=change
DEVPATH=/devices/LNXSYSTM:00/device:00/ACPI0003:00/power_supply/AC
SUBSYSTEM=power_supply
POWER_SUPPLY_NAME=AC
POWER_SUPPLY_TYPE=Mains
POWER_SUPPLY_ONLINE=1
SEQNUM=1474
KERNEL[1245593084.803860] change
/devices/LNXSYSTM:00/device:00/PNP0C0A:00/power_supply/BAT0
(power_supply)
UDEV_LOG=3
ACTION=change
DEVPATH=/devices/LNXSYSTM:00/device:00/PNP0C0A:00/power_supply/BAT0
SUBSYSTEM=power_supply
POWER_SUPPLY_NAME=BAT0
POWER_SUPPLY_TYPE=Battery
POWER_SUPPLY_STATUS=Unknown
POWER_SUPPLY_PRESENT=1
POWER_SUPPLY_TECHNOLOGY=Li-ion
POWER_SUPPLY_VOLTAGE_MIN_DESIGN=11100000
POWER_SUPPLY_VOLTAGE_NOW=12016000
POWER_SUPPLY_CURRENT_NOW=2595000
POWER_SUPPLY_CHARGE_FULL_DESIGN=5200000
POWER_SUPPLY_CHARGE_FULL=4925000
POWER_SUPPLY_CHARGE_NOW=2819000
POWER_SUPPLY_MODEL_NAME=DELL WR0478
POWER_SUPPLY_MANUFACTURER=Samsung SDI
POWER_SUPPLY_SERIAL_NUMBER=21873
SEQNUM=1475
KERNEL[1245593084.817242] change
/devices/LNXSYSTM:00/device:00/PNP0C0A:00/power_supply/BAT0
(power_supply)
UDEV_LOG=3
ACTION=change
DEVPATH=/devices/LNXSYSTM:00/device:00/PNP0C0A:00/power_supply/BAT0
SUBSYSTEM=power_supply
POWER_SUPPLY_NAME=BAT0
POWER_SUPPLY_TYPE=Battery
POWER_SUPPLY_STATUS=Unknown
POWER_SUPPLY_PRESENT=1
POWER_SUPPLY_TECHNOLOGY=Li-ion
POWER_SUPPLY_VOLTAGE_MIN_DESIGN=11100000
POWER_SUPPLY_VOLTAGE_NOW=12016000
POWER_SUPPLY_CURRENT_NOW=2595000
POWER_SUPPLY_CHARGE_FULL_DESIGN=5200000
POWER_SUPPLY_CHARGE_FULL=4925000
POWER_SUPPLY_CHARGE_NOW=2819000
POWER_SUPPLY_MODEL_NAME=DELL WR0478
POWER_SUPPLY_MANUFACTURER=Samsung SDI
POWER_SUPPLY_SERIAL_NUMBER=21873
SEQNUM=1476
KERNEL[1245593084.817297] change
/devices/LNXSYSTM:00/device:00/PNP0C0A:00/power_supply/BAT0
(power_supply)
UDEV_LOG=3
ACTION=change
DEVPATH=/devices/LNXSYSTM:00/device:00/PNP0C0A:00/power_supply/BAT0
SUBSYSTEM=power_supply
POWER_SUPPLY_NAME=BAT0
POWER_SUPPLY_TYPE=Battery
POWER_SUPPLY_STATUS=Charging
POWER_SUPPLY_PRESENT=1
POWER_SUPPLY_TECHNOLOGY=Li-ion
POWER_SUPPLY_VOLTAGE_MIN_DESIGN=11100000
POWER_SUPPLY_VOLTAGE_NOW=11717000
POWER_SUPPLY_CURRENT_NOW=2275000
POWER_SUPPLY_CHARGE_FULL_DESIGN=5200000
POWER_SUPPLY_CHARGE_FULL=4925000
POWER_SUPPLY_CHARGE_NOW=2819000
POWER_SUPPLY_MODEL_NAME=DELL WR0478
POWER_SUPPLY_MANUFACTURER=Samsung SDI
POWER_SUPPLY_SERIAL_NUMBER=21873
SEQNUM=1477
KERNEL[1245593084.817342] add
/devices/pci0000:00/0000:00:1c.1/0000:0c:00.0/leds/iwl-phy0::radio
(leds)
UDEV_LOG=3
ACTION=add
DEVPATH=/devices/pci0000:00/0000:00:1c.1/0000:0c:00.0/leds/iwl-
phy0::radio
SUBSYSTEM=leds
SEQNUM=1478
KERNEL[1245593084.817382] add
/devices/pci0000:00/0000:00:1c.1/0000:0c:00.0/leds/iwl-phy0::assoc
(leds)
UDEV_LOG=3
ACTION=add
DEVPATH=/devices/pci0000:00/0000:00:1c.1/0000:0c:00.0/leds/iwl-
phy0::assoc
SUBSYSTEM=leds
SEQNUM=1479
KERNEL[1245593084.817402] add
/devices/pci0000:00/0000:00:1c.1/0000:0c:00.0/leds/iwl-phy0::RX (leds)
UDEV_LOG=3
ACTION=add
DEVPATH=/devices/pci0000:00/0000:00:1c.1/0000:0c:00.0/leds/iwl-phy0::RX
SUBSYSTEM=leds
SEQNUM=1480
KERNEL[1245593084.817421] add
/devices/pci0000:00/0000:00:1c.1/0000:0c:00.0/leds/iwl-phy0::TX (leds)
UDEV_LOG=3
ACTION=add
DEVPATH=/devices/pci0000:00/0000:00:1c.1/0000:0c:00.0/leds/iwl-phy0::TX
SUBSYSTEM=leds
SEQNUM=1481
KERNEL[1245593084.817442] remove
/devices/pci0000:00/0000:00:1a.0/usb2/2-2/2-2.1/2-2.1:1.0/bluetooth/hci0
(bluetooth)
UDEV_LOG=3
ACTION=remove
DEVPATH=/devices/pci0000:00/0000:00:1a.0/usb2/2-2/2-2.1/2-2.1:1.0/bluetooth/hci0
SUBSYSTEM=bluetooth
DEVTYPE=host
SEQNUM=1482
KERNEL[1245593084.817464] add
/devices/pci0000:00/0000:00:1a.0/usb2/2-2/2-2.1/2-2.1:1.0/bluetooth/hci0
(bluetooth)
UDEV_LOG=3
ACTION=add
DEVPATH=/devices/pci0000:00/0000:00:1a.0/usb2/2-2/2-2.1/2-2.1:1.0/bluetooth/hci0
SUBSYSTEM=bluetooth
DEVTYPE=host
SEQNUM=1483
-------------- next part --------------
A non-text attachment was scrubbed...
Name: hal-0.5.12-singleton_connection.patch
Type: text/x-patch
Size: 530 bytes
Desc: not available
Url : http://lists.freedesktop.org/archives/hal/attachments/20090621/ad06eae9/attachment.bin
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 197 bytes
Desc: This is a digitally signed message part.
Url : http://lists.freedesktop.org/archives/hal/attachments/20090621/ad06eae9/attachment.pgp
More information about the hal
mailing list