Re: 2.6.30: hald crashes on resume from STR apparently on LED device

From: Andrey Borzenkov
Date: Sun Jun 21 2009 - 10:17:27 EST

Next message: Maxim Levitsky: "Re: [git pull] drm: previous pull req + 1."
Previous message: Herbert Xu: "Crypto Fixes for 2.6.31"
Next in thread: Richard Purdie: "Re: 2.6.30: hald crashes on resume from STR apparently on LEDdevice"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

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

+++ hald/hald_dbus.c.singleton_connection 2009-02-26 08:55:36.000000000 +0100
--- hald/hald_dbus.c 2009-06-21 13:48:15.000000000 +0200
@@ -3476,7 +3476,7 @@ singleton_signal_device_changed (DBusCon
if (dbus_connection_send_with_reply (connection,
message,
&pending_call,
- /*-1*/ 8000)) {
+ /*-1*/ 8000) && pending_call) {
/*HAL_INFO (("connection=%x message=%x", connection, message));*/
dbus_pending_call_set_notify (pending_call,
reply_from_singleton_device_changed,

Attachment: signature.asc
Description: This is a digitally signed message part.

Next message: Maxim Levitsky: "Re: [git pull] drm: previous pull req + 1."
Previous message: Herbert Xu: "Crypto Fixes for 2.6.31"
Next in thread: Richard Purdie: "Re: 2.6.30: hald crashes on resume from STR apparently on LEDdevice"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]