semop failed for cookie 0xd4d09ef: incorrect semaphore state during luksOpen

[Dave Gilbert]

Binary package hint: cryptsetup

Hi,
  I'm doing

sudo cryptsetup luksOpen /dev/mapper/mydevice myuncrypted

and it's working but giving the following warnings:

semid 393218: semop failed for cookie 0xd4d1f7f: incorrect semaphore state
Failed to set a proper state for notification semaphore identified by cookie value 223158143 (0xd4d1f7f) to initialize waiting for incoming notifications.

the values change each time, but it seems to be unlocking the partition and it seems to work OK.

Dave

ProblemType: Bug
DistroRelease: Ubuntu 11.04
Package: cryptsetup 2:1.1.3-4ubuntu1
ProcVersionSignature: Ubuntu 2.6.38-3.30-generic 2.6.38-rc4
Uname: Linux 2.6.38-3-generic x86_64
Architecture: amd64
CheckboxSubmission: f2d10bd9f943a85b486a282e7840a570
CheckboxSystem: 0531969bcfd4f03af7405c98dc94a948
Date: Tue Feb 15 15:26:47 2011
InstallationMedia: Ubuntu 9.10 "Karmic Koala" - Release amd64 (20091027)
ProcEnviron:
 LANGUAGE=en_GB:en
 PATH=(custom, user)
 LANG=en_GB.UTF-8
 LC_MESSAGES=en_GB.utf8
 SHELL=/bin/bash
SourcePackage: cryptsetup
crypttab: # <target name> <source device> <key file> <options>

[Martin Pool (mbp)]

I can reproduce this too.

[dc (darkcharl)]

Same behavior on luksClose:

9996 17:01:33 ioctl(3, DM_TABLE_STATUS, 0x24d6b30) = 0
9996 17:01:33 open("/dev/urandom", O_RDONLY) = 4
9996 17:01:33 read(4, "\254\231", 2) = 2
9996 17:01:33 semget(0xd4d99ac, 1, IPC_CREAT|IPC_EXCL|0600) = 557059
9996 17:01:33 semctl(557059, 0, SETVAL, 0x1) = 0
9996 17:01:33 close(4) = 0
9996 17:01:33 semop(557059, {{0, 1, 0}}, 1) = 0
9996 17:01:33 ioctl(3, DM_DEV_REMOVE, 0x24d6a50) = 0
9996 17:01:34 semget(0xd4d99ac, 1, 0) = 557059
9996 17:01:34 semop(557059, {{0, -1, IPC_NOWAIT}}, 1) = 0
9996 17:01:34 semget(0xd4d99ac, 1, 0) = 557059
9996 17:01:34 semop(557059, {{0, -1, IPC_NOWAIT}}, 1) = -1 EAGAIN (Resource temporarily unavailable)
9996 17:01:34 write(2, "semid 557059: semop failed for cookie 0xd4d99ac: incorrect semaphore state", 74) = 74
9996 17:01:34 write(2, "\n", 1) = 1
9996 17:01:34 write(2, "Failed to set a proper state for notification semaphore identified by cookie value 223189420 (0xd4d99ac) to initialize waiting for incoming notifications.", 154) = 154
9996 17:01:34 write(2, "\n", 1) = 1
9996 17:01:34 semctl(557059, 0, IPC_RMID, 0) = 0

[dc (darkcharl)]

LuksClose debug attached.

[dc (darkcharl)]

Looks like the semaphore gets decremented twice.

[dc (darkcharl)]

The dm (LVM2) calls

[asi (gmazyland)]

I am not sure if anyone from Ubuntu will even respond here, but I checked upstream code and provided logs (btw thanks for them, very usefull here).

What happens here is:
- system is fully udev managed, both userspace and kernel are recent enough
- according to logs, something during "udev event" acknowledge fails and libdevmapper takes old compatible path
(trying to create/remove link in /dev/ itself) and also decrementing cookie semaphore.
- unfortunately, the event _was_ triggerred and dmsetup udevcomplete called and because both udev and libdevmapper decrements the semaphore, the second call fails with the message above.

I think the reason is in kernel (kernel do not annonce for some that uvent was sent) but I was not able to reproduce this. If you have some way how to reproduce it reliably, please let me know...

(The bug is not critical, the operation itself finishes correctly.)

[dc (darkcharl)]

I agree, it's non-critical. Thanks for taking the time to further investigate!

[dc (darkcharl)]

Doesn't seem to be an issue anymore with the newest (2.6.38-9-generic) kernel.

[dc (darkcharl)]

Can someone else confirm?

[Jürgen Kreileder (jk)]

I'm seeing these semaphore errors with a backup-script that uses lvm2 snapshots after upgrading to natty.

I think this bug should be reopened and moved to the proper package (lvm2?) and it should probably be merged with bug #753541

May 9 21:21:43 sphere udevd-work[5144]: inotify_add_watch(6, /dev/dm-25, 10) failed: No such file or directory
May 9 21:21:47 sphere udevd-work[5144]: inotify_add_watch(6, /dev/dm-22, 10) failed: No such file or directory
May 9 21:21:51 sphere udevd-work[5144]: inotify_add_watch(6, /dev/dm-19, 10) failed: No such file or directory
May 9 21:21:54 sphere udevd-work[5144]: inotify_add_watch(6, /dev/dm-28, 10) failed: No such file or directory
May 9 21:21:58 sphere udevd-work[5144]: inotify_add_watch(6, /dev/dm-31, 10) failed: No such file or directory
May 9 21:22:02 sphere udevd-work[5144]: inotify_add_watch(6, /dev/dm-16, 10) failed: No such file or directory
May 9 21:22:05 sphere udevd-work[5144]: inotify_add_watch(6, /dev/dm-13, 10) failed: No such file or directory

  semid 1179650: semop failed for cookie 0xd4d8346: incorrect semaphore state
  Could not signal waiting process using notification semaphore identified by cookie value 223183686 (0xd4d8346)
  semid 1179650: semop failed for cookie 0xd4d8346: incorrect semaphore state
  Failed to set a proper state for notification semaphore identified by cookie value 223183686 (0xd4d8346) to initialize waiting for incoming notifications.
  semid 1245186: semop failed for cookie 0xd4d7e40: incorrect semaphore state
  Failed to set a proper state for notification semaphore identified by cookie value 223182400 (0xd4d7e40) to initialize waiting for incoming notifications.
  semid 1277954: semop failed for cookie 0xd4d59e4: incorrect semaphore state
  Could not signal waiting process using notification semaphore identified by cookie value 223173092 (0xd4d59e4)
  semid 1277954: semop failed for cookie 0xd4d59e4: incorrect semaphore state
  Failed to set a proper state for notification semaphore identified by cookie value 223173092 (0xd4d59e4) to initialize waiting for incoming notifications.
  semid 1343490: semop failed for cookie 0xd4d451a: incorrect semaphore state
  Failed to set a proper state for notification semaphore identified by cookie value 223167770 (0xd4d451a) to initialize waiting for incoming notifications.
  semid 1376258: semop failed for cookie 0xd4dc3e3: incorrect semaphore state
  Could not signal waiting process using notification semaphore identified by cookie value 223200227 (0xd4dc3e3)
  semid 1376258: semop failed for cookie 0xd4dc3e3: incorrect semaphore state
  Failed to set a proper state for notification semaphore identified by cookie value 223200227 (0xd4dc3e3) to initialize waiting for incoming notifications.
  semid 1441794: semop failed for cookie 0xd4dd615: incorrect semaphore state
  Failed to set a proper state for notification semaphore identified by cookie value 223204885 (0xd4dd615) to initialize waiting for incoming notifications.

[Arie Skliarouk (skliarie)]

I get the same "semop failed for cookie 0xd4daad3: incorrect semaphore state" errors when removing an LVM volume:
root@mf:~# lvremove /dev/mf/lvmtest3
Do you really want to remove active logical volume lvmtest3? [y/n]: y
  semid 393216: semop failed for cookie 0xd4daad3: incorrect semaphore state
  Failed to set a proper state for notification semaphore identified by cookie value 223193811 (0xd4daad3) to initialize waiting for incoming notifications.
  Logical volume "lvmtest3" successfully removed
root@mf:~# lvremove /dev/mf/lvmtest3

The bug was filed on "lvm2" over here:
https://bugs.launchpad.net/ubuntu/+source/lvm2/+bug/797226

Could be the bug is related...

[Marek Šabo (zeratul)]

I got this when executing:

zeratul@antioch:~$ sudo cryptsetup luksOpen /dev/md0 raid
Enter passphrase for /dev/md0:
semid 5111810: semop failed for cookie 0xd4dca3f: incorrect semaphore state
Failed to set a proper state for notification semaphore identified by cookie value 223201855 (0xd4dca3f) to initialize waiting for incoming notifications.

System is Kubuntu 11.04, 2.6.38-10-generic-pae, i686. Didn't occur in previous releases.

[hyper_ch (bugs-launchpad-net-roleplayer)]

I get this error now also. Using "Linux netbook 2.6.38-10-generic #46-Ubuntu SMP Tue Jun 28 15:07:17 UTC 2011 x86_64 x86_64 x86_64 GNU/Linux"

semid 688129: semop failed for cookie 0xd4d6c1f: incorrect semaphore state
Failed to set a proper state for notification semaphore identified by cookie value 223177759 (0xd4d6c1f) to initialize waiting for incoming notifications.

It all seems to work fine, except for that error message.

[Linus van Geuns (nirkus)]

I am geting semaphore errors, too.

Setup:
- internal disk SATA
- external disk eSATA
- GPT -> LVM -> LUKS (cryptsetup)

When creating logical volumes, I get:
> "The link /dev/ext0/exttest2 should had been created by udev but it was not found. Falling back to direct link creation."
When removing logical volumes, I get semaphore errors.
When doing luksOpen/luksClose on existing LVMs, I get semaphore errors.

I will attach package & setup information and output of lvcreate -vvvv and lvremove -vvvv.

[Dave Gilbert (ubuntu-treblig)]

Still happening here.

[Jean-Louis Dupond (dupondje)]

This should be fixed in the new version on Precise.

Could somebody test this if their still able to reproduce this?

[Martin Pool (mbp)]

I haven't seen this on Precise.

[kit (kitrule)]

Possibly related to https://code.google.com/p/chromium/issues/detail?id=92762 ?
And from there, a link to https://lkml.org/lkml/2011/8/18/112
Apparently something might have been fixed in the kernel from v3.1 and I see Precise is using v3.2 which could explain it.

[dc (darkcharl)]

+1 (not experiencing in precise with the newer kernel)

[Steve Langasek (vorlon)]

Thanks all, marking as fixed.