udisks-daemon assertion error: HACK: Wanting to register object at path `%s' but there is already an object there.

[George Shuklin]

crash after startup

ProblemType: Crash
DistroRelease: Ubuntu 12.04
Package: udisks 1.0.4-2
Uname: Linux 3.2.0-rc3-next-20111202 i686
ApportVersion: 1.90-0ubuntu1
Architecture: i386
Date: Sun Dec 4 02:50:11 2011
ExecutablePath: /usr/lib/udisks/udisks-daemon
Lsusb:
 Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
 Bus 002 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
 Bus 001 Device 002: ID 8087:0024 Intel Corp. Integrated Rate Matching Hub
 Bus 002 Device 002: ID 8087:0024 Intel Corp. Integrated Rate Matching Hub
 Bus 001 Device 003: ID 0421:0518 Nokia Mobile Phones
MachineType: LENOVO 4290RB3
ProcCmdline: /usr/lib/udisks/udisks-daemon
ProcEnviron:

ProcKernelCmdLine: BOOT_IMAGE=/boot/vmlinuz-3.2.0-rc3-next-20111202 root=UUID=ff771e68-857e-4d94-8f9a-90822e3deab4 ro quiet splash i915_enable_rc6 i195.i915_enable_rc6=1 pcie.aspm=force vt.handoff=7
Signal: 5
SourcePackage: udisks
StacktraceTop:
 ?? ()
 ?? ()
 g_udev_marshal_VOID__STRING_OBJECT () from /usr/lib/i386-linux-gnu/libgudev-1.0.so.0
 g_closure_invoke () from /usr/lib/i386-linux-gnu/libgobject-2.0.so.0
 ?? () from /usr/lib/i386-linux-gnu/libgobject-2.0.so.0
Title: udisks-daemon crashed with signal 5 in g_udev_marshal_VOID__STRING_OBJECT()
UpgradeStatus: No upgrade log present (probably fresh install)
UserGroups:

dmi.bios.date: 07/01/2011
dmi.bios.vendor: LENOVO
dmi.bios.version: 8DET49WW (1.19 )
dmi.board.asset.tag: Not Available
dmi.board.name: 4290RB3
dmi.board.vendor: LENOVO
dmi.board.version: Not Available
dmi.chassis.asset.tag: No Asset Information
dmi.chassis.type: 10
dmi.chassis.vendor: LENOVO
dmi.chassis.version: Not Available
dmi.modalias: dmi:bvnLENOVO:bvr8DET49WW(1.19):bd07/01/2011:svnLENOVO:pn4290RB3:pvrThinkPadX220:rvnLENOVO:rn4290RB3:rvrNotAvailable:cvnLENOVO:ct10:cvrNotAvailable:
dmi.product.name: 4290RB3
dmi.product.version: ThinkPad X220
dmi.sys.vendor: LENOVO

[Apport retracing service (apport)]

StacktraceTop:
 register_disks_device (device=0x9504ff0) at device.c:1968
 device_new (daemon=0x94e4c10, d=0x94fa590) at device.c:5159
 block_device_add (emit_event=1, d=0x94fa590, daemon=0x94e4c10) at daemon.c:1340
 device_add (daemon=0x94e4c10, d=0x94fa590, emit_event=1) at daemon.c:1389
 g_udev_marshal_VOID__STRING_OBJECT () from /tmp/tmptNU4ZC/usr/lib/i386-linux-gnu/libgudev-1.0.so.0

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[Martin Pitt (pitti)]

Thanks for your reports! I'm afraid I have too little information yet to see what's wrong with this. Is anybody able to reproduce this using a series of steps, possibly with inserting/removing/suspending etc. several times in a row? If you can, please open a terminal and run this:

  sudo /usr/lib/udisks/udisks-daemon --replace 2>&1 | tee /tmp/udisks.log

Then play around with your system until you get a crash, i. e. it prints something like "HACK: Wanting to register object at path..." and returns to the bash prompt. Then please attach /tmp/udisks.log here.

Thanks!

[Sebastien Bacher (seb128)]

got the same error while connecting,disconnecting an ipod nano

[Martin Pitt (pitti)]

Sebastien kindly did some more debugging, keeping notes here. This seems to be related to media polling (we verified both in-kernel and udisks based polling trigger this, and cause the same uevents).

Correlating udev events and the corresponding udev debug output, we get:

UDEV [26112.066235] remove /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4:1.0/host29/target29:0:0/29:
0:0:0/block/sdb/sdb1 (block)
--
**** REMOVING /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4:1.0/host29/target29:0:0/29:0:0:0/block/
sdb/sdb1
**** EMITTING REMOVED for /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4:1.0/host29/target29:0:0/29:
0:0:0/block/sdb/sdb1

UDEV [26112.067123] remove /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4:1.0/host29/target29:0:0/29:0:0:0/block/sdb (block)
--
**** REMOVING /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4:1.0/host29/target29:0:0/29:0:0:0/block/
sdb
**** EMITTING REMOVED for /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4:1.0/host29/target29:0:0/29:
0:0:0/block/sdb
**** scsi_host IGNORING REMOVE /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4:1.0/host29/scsi_host/h
ost29

Now we get a rather weird change uevent with a hilariously broken device path and device name, at a time when sdb is already gone!

UDEV [26112.087644] change /sdb (block)
ACTION=change
DEVNAME=/dev/sdb
DEVPATH=/sdb
DEVTYPE=disk
DISK_MEDIA_CHANGE=1
SUBSYSTEM=block
--
**** TREATING CHANGE AS ADD /sys/sdb
**** ADDING /sys/sdb
**** UPDATING /sys/sdb
**** ADDED /sys/sdb
**** EMITTING ADDED for /sys/sdb

Now we get a similar change event again, but this time WITHOUT DISK_MEDIA_CHANGE

UDEV [26112.102230] change /sdb (block)
ACTION=change
DEVNAME=/dev/sdb
DEVPATH=/sdb
DEVTYPE=disk
SUBSYSTEM=block
--
**** CHANGING /sys/sdb
**** UPDATING /sys/sdb
**** EMITTING CHANGED for /sys/sdb
**** CHANGED /sys/sdb

Now we get the device back:

UDEV [26123.419938] add /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4:1.0/host32/target32:0:0/32:0:0:0/block/sdb (block)
--
**** ADDING /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4:1.0/host32/target32:0:0/32:0:0:0/block/sdb
**** UPDATING /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4:1.0/host32/target32:0:0/32:0:0:0/block/sdb

(udisks-daemon:24900): udisks-daemon-ERROR **: **** HACK: Wanting to register object at path `/org/freedesktop/UDisks/devices/sdb' but there is already an object there. This is an internal error in the daemon. Aborting.

So I think the problem is that the media polling for the /sdb device creates a device in udisks.

[Martin Pitt (pitti)]

For posterity I attach the udisks and udev logs.

[Martin Pitt (pitti)]

With a little extra debugging, Sebastien's latest log confirms this:

**** TREATING CHANGE AS ADD /sys/sdb
**** ADDING /sys/sdb
**** UPDATING /sys/sdb
**** registering /org/freedesktop/UDisks/devices/sdb

[Martin Pitt (pitti)]

This patch should fix it, but as I'm still unable to reproduce I cannot verify this. It could be that the kernel actually has a /sys/sdb when this weird change event happens. Sebastien, can you please apply this and check if it fixes the problem? You should see something like

   Ignoring device with nonexisting native path: /sys/sdb

now, and udisks should just go on.

Also, can you please check if this affects udisks2 in the ubuntu-desktop PPA?

[Martin Pitt (pitti)]

In https://bugs.launchpad.net/bugs/899757 we get quite a few duplicates on a crash that looks like this:

#1 0xb74640b3 in g_log (log_domain=0x8072adb "udisks-daemon", log_level=G_LOG_LEVEL_ERROR, format=0x8078cac "**** HACK: Wanting to register object at path `%s' but there is already an object there. This is an internal error in the daemon. Aborting.\n") at /build/buildd/glib2.0-2.30.1/./glib/gmessages.c:591
        args = 0xbfe867ac "`hP\t"
#2 0x08068736 in register_disks_device (device=0x9504ff0) at device.c:1968
        error = 0x0
#3 device_new (daemon=0x94e4c10, d=0x94fa590) at device.c:5159
        device = 0x9504ff0
        native_path = <optimized out>
#4 0x080523d0 in block_device_add (emit_event=1, d=0x94fa590, daemon=0x94e4c10) at daemon.c:1340
        device = <optimized out>
        native_path = 0x94e2ef8 "/sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.2/1-1.2:1.0/host7/target7:0:0/7:0:0:0/block/sdb"

(Full trace at https://launchpadlibrarian.net/86784583/Stacktrace.txt, but this is the essential part).

This happens when adding a new device, particular with devices which bounce a bit (i. e. you get several adds, removes, and changes before it stabilizes).

Unfortunately I cannot reproduce this myself with the devices I have, but a colleague of mine (Sebastien Bacher) can reproduce it very easily with his iPod.

After a few rounds of debugging I now understand what happens:

This seems to be related to media polling (we verified both in-kernel and udisks based polling trigger this, and cause the same uevents).

Correlating udev events and the corresponding udev debug output, we get:

UDEV [26112.066235] remove /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4:1.0/host29/target29:0:0/29:
0:0:0/block/sdb/sdb1 (block)
--
**** REMOVING /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4:1.0/host29/target29:0:0/29:0:0:0/block/
sdb/sdb1
**** EMITTING REMOVED for /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4:1.0/host29/target29:0:0/29:
0:0:0/block/sdb/sdb1

UDEV [26112.067123] remove /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4:1.0/host29/target29:0:0/29:0:0:0/block/sdb (block)
--
**** REMOVING /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4:1.0/host29/target29:0:0/29:0:0:0/block/
sdb
**** EMITTING REMOVED for /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4:1.0/host29/target29:0:0/29:
0:0:0/block/sdb
**** scsi_host IGNORING REMOVE /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4:1.0/host29/scsi_host/h
ost29

Now we get a rather weird change uevent with a hilariously broken device path and device name, at a time when sdb is already gone!

UDEV [26112.087644] change /sdb (block)
ACTION=change
DEVNAME=/dev/sdb
DEVPATH=/sdb
DEVTYPE=disk
DISK_MEDIA_CHANGE=1
SUBSYSTEM=block
--
**** TREATING CHANGE AS ADD /sys/sdb
**** ADDING /sys/sdb
**** UPDATING /sys/sdb
**** ADDED /sys/sdb
**** EMITTING ADDED for /sys/sdb

Now we get a similar change event again, but this time WITHOUT DISK_MEDIA_CHANGE

UDEV [26112.102230] change /sdb (block)
ACTION=change
DEVNAME=/dev/sdb
DEVPATH=/sdb
DEVTYPE=disk
SUBSYSTEM=block
--
**** CHANGING /sys/sdb
**** UPDATING /sys/sdb
**** EMITTING CHANGED for...

[Martin Pitt (pitti)]

I'll have Sebastien test a potential patch, I'll submit it here if that is successful. I also asked him to test with udisks2, so that it doesn't get the same problem all over again.

I am not sure whether this is to be considered a kernel bug (sending media change uevents after a device is removed, especially with bogus device paths), but they might be useful for other purposes or hard to avoid.

Within udisks, I see two options to fix this:

 * Drop the "treating change as add" logic. In all my experiments and log files I created for this bug I never saw a situation where a device got added without an "add" event, even with the worst bouncing. I. e. we could just simply ignore change events on nonexisting devices. My gut feeling is that this is the "more" correct approach, and certainly the one we should pursue in udisks2 (if it is affected in the first place).

 * Add a plausibility check to add/change events, to ensure that the native path actually exists before we create an object for it. That's what I'm currently testing. It's much less intrusive and much safer than the first option, so it's appropriate for the udisks1 branch.

[Martin Pitt (pitti)]

Previous patch had a segfault due to a copy&paste error, this patch has been tested by Sebastien. udisks2 is unaffected.

[Martin Pitt (pitti)]

Created attachment 59366
Ignore add/change events for a nonexisting native path

This patch has been verified to work. We also asserted that udisks2 is not affected by this problem (it does not have all these hacks that piled up in udisks to work around past kernel bugs.)

[Launchpad Janitor (janitor)]

This bug was fixed in the package udisks - 1.0.4-5ubuntu1

---------------
udisks (1.0.4-5ubuntu1) precise; urgency=low

  * Merge with Debian unstable. Remaining Ubuntu changes:
    - debian/control: Change the "cryptsetup" suggests to a "cryptsetup-bin"
      recommends, so that LUKS functionality works by default. This change
      needs to be kept in Ubuntu until the cryptsetup package split goes into
      Debian as well. (LP: #343363)

udisks (1.0.4-5) unstable; urgency=low

  * debian/control: Drop ntfsprogs recommendation, it's now a transitional
    package. ntfs-3g provides the programs now.
  * Add debian/patches/00git_media_card_device_tags.patch: Mark MemStick and
    MMC devices as such, so that they get automounted. Backported from
    udisks2. (LP: #942777)
  * Add 12-bogus-uevent-paths.patch: Ignore add/change events for a
    nonexisting native path. (LP: #899757)
  * debian/copyright: Update to copyright 1.0 format.
  * debian/control: Bump Standards-Version to 3.9.3.

udisks (1.0.4-4) unstable; urgency=low

  * Install systemd service file for udisks-daemon.
 -- Martin Pitt <email address hidden> Mon, 02 Apr 2012 12:21:43 +0200

[Ehcor8 (guyroche08)]

I had this bug by looking after updates with the "update gestion" in ubuntu i386 32b on portable pc hp 2220 sf. 4gb ram, ATI radeon 4500 (video)
All items selected in "update gestion".

A+

Guy Roche

mail <email address hidden>
mail <email address hidden>

domicile 0324 376446
mobile [phone]

> Message du 04/04/12 16:26
> de : "MartinPitt"<email address hidden>
> à : <email address hidden>
> cc :
> objet : [Bug 899757]
>
> Created attachment 59366
> Ignore add/change events for a nonexisting native path
>
> This patch has been verified to work. We also asserted that udisks2 is
> not affected by this problem (it does not have all these hacks that
> piled up in udisks to work around past kernel bugs.)
>
> --
> You received this bug notification because you are subscribed to a
> duplicate bug report (963561).
> https://bugs.launchpad.net/bugs/899757
>
> Title:
> udisks-daemon assertion error: HACK: Wanting to register object at
> path `%s' but there is already an object there.
>
> Status in abstraction for enumerating and managing block devices:
> In Progress
> Status in “udisks” package in Ubuntu:
> Fix Released
>
> Bug description:
> crash after startup
>
> ProblemType: Crash
> DistroRelease: Ubuntu 12.04
> Package: udisks 1.0.4-2
> Uname: Linux 3.2.0-rc3-next-20111202 i686
> ApportVersion: 1.90-0ubuntu1
> Architecture: i386
> Date: Sun Dec 4 02:50:11 2011
> ExecutablePath: /usr/lib/udisks/udisks-daemon
> Lsusb:
> Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
> Bus 002 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
> Bus 001 Device 002: ID 8087:0024 Intel Corp. Integrated Rate Matching Hub
> Bus 002 Device 002: ID 8087:0024 Intel Corp. Integrated Rate Matching Hub
> Bus 001 Device 003: ID 0421:0518 Nokia Mobile Phones
> MachineType: LENOVO 4290RB3
> ProcCmdline: /usr/lib/udisks/udisks-daemon
> ProcEnviron:
>
> ProcKernelCmdLine: BOOT_IMAGE=/boot/vmlinuz-3.2.0-rc3-next-20111202 root=UUID=ff771e68-857e-4d94-8f9a-90822e3deab4 ro quiet splash i915_enable_rc6 i195.i915_enable_rc6=1 pcie.aspm=force vt.handoff=7
> Signal: 5
> SourcePackage: udisks
> StacktraceTop:
> ?? ()
> ?? ()
> g_udev_marshal_VOID__STRING_OBJECT () from /usr/lib/i386-linux-gnu/libgudev-1.0.so.0
> g_closure_invoke () from /usr/lib/i386-linux-gnu/libgobject-2.0.so.0
> ?? () from /usr/lib/i386-linux-gnu/libgobject-2.0.so.0
> Title: udisks-daemon crashed with signal 5 in g_udev_marshal_VOID__STRING_OBJECT()
> UpgradeStatus: No upgrade log present (probably fresh install)
> UserGroups:
>
> dmi.bios.date: 07/01/2011
> dmi.bios.vendor: LENOVO
> dmi.bios.version: 8DET49WW (1.19 )
> dmi.board.asset.tag: Not Available
> dmi.board.name: 4290RB3
> dmi.board.vendor: LENOVO
> dmi.board.version: Not Available
> dmi.chassis.asset.tag: No Asset Information
> dmi.chassis.type: 10
> dmi.chassis.vendor: LENOVO
> dmi.chassis.version: Not Available
> dmi.modalias: dmi:bvnLENOVO:bvr8DET49WW(1.19):bd07/01/2011:svnLENOVO:pn4290RB3:pvrThinkPadX220:rvnLENOVO:rn4290RB3:rvrNotAvailable:cvnLENOVO:ct10:cvrNotAvailable:
> dmi.produ...

[Martin Pitt (pitti)]

I pushed this now. It's confirmed to work, and that downstream bug got a gazillion duplicates, so it does hurt people a lot.