[dm-crypt] Cryptsetup (>= 1.7.0) luksOpen/luksClose gets stuck after open/close

[dm-crypt] Cryptsetup (>= 1.7.0) luksOpen/luksClose gets stuck after open/close

[Guido Trentalancia]

Hello.

Cryptsetup version 1.7.0 and 1.7.1 gets stuck on luksOpen and luksClose
immediately after the device has been opened or closed.

The process has to be killed.

Here are the last bits of the strace output for luksOpen (after
entering the passphrase):

read(7, "\213\364\23\350X'\326\355s\231\34\262\360h\4\266\245\"\266:\207\330)\344s\332\3211\354\2\355\17"..., 512) = 512
sendmsg(7, {msg_name(0)=NULL, msg_iov(1)=[{"p\1O\225\233\244\235\315G\243o\7\265QO\316\3I\305\300\f\201Awh\321&m\200}\353."..., 512}], msg_controllen=64, [{cmsg_len=20, cmsg_level=SOL_ALG, cmsg_type=3, ...}, {cmsg_len=40, cmsg_level=SOL_ALG, cmsg_type=2, ...}], msg_flags=0}, 0) = 512
read(7, "\f7\223&\245\357Z!\367\206g\346\267Y\251\377\200\345\246\357GG\333,6\202`Z\247:4\310"..., 512) = 512
sendmsg(7, {msg_name(0)=NULL, msg_iov(1)=[{"\207@-\276\372\347\26\0\24\335Y6\244\2Q\344\315^\301\"\325e\352\271'Y+\210\320\237\313\10"..., 512}], msg_controllen=64, [{cmsg_len=20, cmsg_level=SOL_ALG, cmsg_type=3, ...}, {cmsg_len=40, cmsg_level=SOL_ALG, cmsg_type=2, ...}], msg_flags=0}, 0) = 512
read(7, "\264\267\211\254R\23|\202\335Zt\203\333\22\362\350\1\315\261\306\241e\340\362\376\210\30\205\35\0275\235"..., 512) = 512
sendmsg(7, {msg_name(0)=NULL, msg_iov(1)=[{"\7\304\2346\243s\225\235*\314u\370\310VL\337S\216\17\r\265\366\252W\346J\201\357\253)\356\227"..., 512}], msg_controllen=64, [{cmsg_len=20, cmsg_level=SOL_ALG, cmsg_type=3, ...}, {cmsg_len=40, cmsg_level=SOL_ALG, cmsg_type=2, ...}], msg_flags=0}, 0) = 512
read(7, "\232a\262\334\320\372a\253\372\227Ky&&\10\2363V\225\263\370\316\264\277\\\266G\217\226\253\261\31"..., 512) = 512
sendmsg(7, {msg_name(0)=NULL, msg_iov(1)=[{"P\"\304\212S\322\10LD\217\17S\0*\205\7c\343\312\322\254Vl\31\304\214\247:\270\233\272Y"..., 512}], msg_controllen=64, [{cmsg_len=20, cmsg_level=SOL_ALG, cmsg_type=3, ...}, {cmsg_len=40, cmsg_level=SOL_ALG, cmsg_type=2, ...}], msg_flags=0}, 0) = 512
read(7, "k\242\250Xw\376N\352\202\37q|\315 :\230\23 \2/h\221x\305\313\334\n\6\241\350\342\24"..., 512) = 512
sendmsg(7, {msg_name(0)=NULL, msg_iov(1)=[{"j%\214\327*\203\225\216\233\3776\225\373\373+(XNC\371\277\32\363\322~j`\333J.\267\25"..., 512}], msg_controllen=64, [{cmsg_len=20, cmsg_level=SOL_ALG, cmsg_type=3, ...}, {cmsg_len=40, cmsg_level=SOL_ALG, cmsg_type=2, ...}], msg_flags=0}, 0) = 512
read(7, "\3621\202\0359\t\323\220\241\206\231:\314\207B\274\221\7\305\253\223\201H<\316\300\232\216r\367+\224"..., 512) = 512
sendmsg(7, {msg_name(0)=NULL, msg_iov(1)=[{"o\342w\330\354\244\377\23f\177b\34\244\323gt\352\332\324\241\246\21\211&@n\256\307\275\7\2536"..., 512}], msg_controllen=64, [{cmsg_len=20, cmsg_level=SOL_ALG, cmsg_type=3, ...}, {cmsg_len=40, cmsg_level=SOL_ALG, cmsg_type=2, ...}], msg_flags=0}, 0) = 512
read(7, "\241\307\344I\342\334gJ\340\375\322u\33\341\0038u\10\323\257\313u\23$\243\27\217\36\247^\322\260"..., 512) = 512
sendmsg(7, {msg_name(0)=NULL, msg_iov(1)=[{"\312[#\211\344w\206\36l\312\326\31\210\362\17\267\1[\305\373\21\354\340p\214C\245\315js\t\22"..., 512}], msg_controllen=64, [{cmsg_len=20, cmsg_level=SOL_ALG, cmsg_type=3, ...}, {cmsg_len=40, cmsg_level=SOL_ALG, cmsg_type=2, ...}], msg_flags=0}, 0) = 512
read(7, "/<G(\364\203\341\257\2121\0\215~\302\337\6\314\356\227\215\341\177\366t\355\350e\350\234b]\332"..., 512) = 512
sendmsg(7, {msg_name(0)=NULL, msg_iov(1)=[{"e\253\30,$\363p\303[RqU\347k\236\241\245U]\333\330\332\306\221\324\213\313\331F\23\0\345"..., 512}], msg_controllen=64, [{cmsg_len=20, cmsg_level=SOL_ALG, cmsg_type=3, ...}, {cmsg_len=40, cmsg_level=SOL_ALG, cmsg_type=2, ...}], msg_flags=0}, 0) = 512
read(7, "K\226{i\316\217\363)\340\207\317]3\356}\322>A\6\2c\267\337I\347\244.o\305\234\352\373"..., 512) = 512
sendmsg(7, {msg_name(0)=NULL, msg_iov(1)=[{"\356\17\214w\220V6l\351\212\2\314\273\255&\333u\276\254\n\370\262eDT\340]\232XN\203i"..., 512}], msg_controllen=64, [{cmsg_len=20, cmsg_level=SOL_ALG, cmsg_type=3, ...}, {cmsg_len=40, cmsg_level=SOL_ALG, cmsg_type=2, ...}], msg_flags=0}, 0) = 512
read(7, "\267\211f\322\232\3327Us\10\311{\303\2273\332)\211\300#\276H\2207\2607N\375\375VFj"..., 512) = 512
sendmsg(7, {msg_name(0)=NULL, msg_iov(1)=[{"\350N\367_7\323\246\377\34=O\300\307\363\2274\206\351&\3212\377\3674\263Bg_5\247T\306"..., 512}], msg_controllen=64, [{cmsg_len=20, cmsg_level=SOL_ALG, cmsg_type=3, ...}, {cmsg_len=40, cmsg_level=SOL_ALG, cmsg_type=2, ...}], msg_flags=0}, 0) = 512
read(7, "\16O\25{\236\352`\262\224\307H\330\7k9)?\30l\202\234\232v\244B\261\364\262.\245\243\210"..., 512) = 512
close(6)                                = 0
close(7)                                = 0
munmap(0x7f7679fcd000, 258048)          = 0
stat("/dev/mapper/vg_vortex-LogVol03", {st_mode=S_IFBLK|0660, st_rdev=makedev(253, 5), ...}) = 0
open("/dev/mapper/vg_vortex-LogVol03", O_RDWR|O_EXCL) = 6
ioctl(6, BLKROGET, 0)                   = 0
ioctl(6, BLKGETSIZE64, 104857600000)    = 0
close(6)                                = 0
open("/dev/mapper/vg_vortex-LogVol03", O_RDONLY) = 6
ioctl(6, BLKRAGET, 256)                 = 0
close(6)                                = 0
open("/dev/urandom", O_RDONLY)          = 6
read(6, "NL", 2)                        = 2
semget(0xd4d4c4e, 1, IPC_CREAT|IPC_EXCL|0600) = 229380
semctl(229380, 0, SETVAL, 0x1)          = 0
semctl(229380, 0, GETVAL, 0x7f7679730d4a) = 1
close(6)                                = 0
semop(229380, {{0, 1, 0}}, 1)           = 0
semctl(229380, 0, GETVAL, 0x7f7679730ce7) = 2
ioctl(5, DM_DEV_CREATE, 0x20dd820)      = 0
ioctl(5, DM_TABLE_LOAD, 0x20dd560)      = 0
ioctl(5, DM_DEV_SUSPEND, 0x20dd430)     = 0
semget(0xd4d4c4e, 1, 0)                 = 229380
semctl(229380, 0, GETVAL, 0x7f7679730d17) = 2
semop(229380, {{0, -1, IPC_NOWAIT}}, 1) = 0
semop(229380, {{0, 0, 0}}, 1)           = -1 EINTR (Interrupted system call)
--- SIGINT {si_signo=SIGINT, si_code=SI_KERNEL} ---
rt_sigreturn({mask=[]})                 = -1 EINTR (Interrupted system call)
semop(229380, {{0, 0, 0}}, 1

The device is opened correctly and it can be mounted.

Here are the last bits of the strace output for luksClose:

stat("/dev/mapper/control", {st_mode=S_IFCHR|0600, st_rdev=makedev(10, 236), ...}) = 0
open("/dev/mapper/control", O_RDWR)     = 3
ioctl(3, DM_TABLE_STATUS, 0x9b8690)     = 0
readlink("/sys/dev/block/253:5", "../../devices/virtual/block/dm-5", 4095) = 32
ioctl(3, DM_TABLE_STATUS, 0x9bc6a0)     = 0
stat("/dev/mapper/vg_vortex-LogVol03", {st_mode=S_IFBLK|0660, st_rdev=makedev(253, 5), ...}) = 0
open("/dev/mapper/vg_vortex-LogVol03", O_RDONLY|O_DIRECT) = 4
fstat(4, {st_mode=S_IFBLK|0660, st_rdev=makedev(253, 5), ...}) = 0
ioctl(4, BLKSSZGET, 512)                = 0
fstatfs(4, {f_type="TMPFS_MAGIC", f_bsize=4096, f_blocks=484700, f_bfree=484700, f_bavail=484700, f_files=484700, f_ffree=483639, f_fsid={0, 0}, f_namelen=255, f_frsize=4096, f_flags=34}) = 0
read(4, "LUKS\272\276\0\1aes\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512
fstat(4, {st_mode=S_IFBLK|0660, st_rdev=makedev(253, 5), ...}) = 0
close(4)                                = 0
open("/dev/mapper/vg_vortex-LogVol03", O_RDONLY|O_DIRECT) = 4
fstat(4, {st_mode=S_IFBLK|0660, st_rdev=makedev(253, 5), ...}) = 0
ioctl(4, BLKSSZGET, 512)                = 0
fstatfs(4, {f_type="TMPFS_MAGIC", f_bsize=4096, f_blocks=484700, f_bfree=484700, f_bavail=484700, f_files=484700, f_ffree=483639, f_fsid={0, 0}, f_namelen=255, f_frsize=4096, f_flags=34}) = 0
read(4, "LUKS\272\276\0\1aes\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512
fstat(4, {st_mode=S_IFBLK|0660, st_rdev=makedev(253, 5), ...}) = 0
close(4)                                = 0
ioctl(3, DM_TABLE_STATUS, 0x9b8ca0)     = 0
readlink("/sys/dev/block/253:5", "../../devices/virtual/block/dm-5", 4095) = 32
ioctl(3, DM_TABLE_STATUS, 0x9c0720)     = 0
stat("/dev/mapper/vg_vortex-LogVol03", {st_mode=S_IFBLK|0660, st_rdev=makedev(253, 5), ...}) = 0
open("/dev/mapper/vg_vortex-LogVol03", O_RDONLY|O_DIRECT) = 4
fstat(4, {st_mode=S_IFBLK|0660, st_rdev=makedev(253, 5), ...}) = 0
ioctl(4, BLKSSZGET, 512)                = 0
fstatfs(4, {f_type="TMPFS_MAGIC", f_bsize=4096, f_blocks=484700, f_bfree=484700, f_bavail=484700, f_files=484700, f_ffree=483639, f_fsid={0, 0}, f_namelen=255, f_frsize=4096, f_flags=34}) = 0
read(4, "LUKS\272\276\0\1aes\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512
fstat(4, {st_mode=S_IFBLK|0660, st_rdev=makedev(253, 5), ...}) = 0
close(4)                                = 0
open("/dev/urandom", O_RDONLY)          = 4
open("/dev/random", O_RDONLY|O_NONBLOCK) = 5
access("/etc/gcrypt/fips_enabled", F_OK) = -1 ENOENT (No such file or directory)
open("/proc/sys/crypto/fips_enabled", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/etc/gcrypt/hwf.deny", O_RDONLY)  = -1 ENOENT (No such file or directory)
mmap(NULL, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa5f7972000
getuid()                                = 0
mlock(0x7fa5f7972000, 16384)            = 0
uname({sysname="Linux", nodename="vortex", ...}) = 0
open("/dev/mapper/vg_vortex-LogVol03", O_RDONLY|O_SYNC|O_DIRECT) = 6
open("/dev/mapper/vg_vortex-LogVol03", O_RDONLY) = 7
fstat(7, {st_mode=S_IFBLK|0660, st_rdev=makedev(253, 5), ...}) = 0
ioctl(7, BLKSSZGET, 512)                = 0
close(7)                                = 0
fstatfs(6, {f_type="TMPFS_MAGIC", f_bsize=4096, f_blocks=484700, f_bfree=484700, f_bavail=484700, f_files=484700, f_ffree=483639, f_fsid={0, 0}, f_namelen=255, f_frsize=4096, f_flags=34}) = 0
read(6, "LUKS\272\276\0\1aes\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1024) = 1024
open("/dev/mapper/vg_vortex-LogVol03", O_RDONLY) = 7
fstat(7, {st_mode=S_IFBLK|0660, st_rdev=makedev(253, 5), ...}) = 0
ioctl(7, BLKGETSIZE64, 104857600000)    = 0
close(7)                                = 0
close(6)                                = 0
ioctl(3, DM_TABLE_STATUS, 0x9b8bc0)     = 0
open("/dev/urandom", O_RDONLY)          = 6
read(6, "\352\345", 2)                  = 2
semget(0xd4de5ea, 1, IPC_CREAT|IPC_EXCL|0600) = 196611
semctl(196611, 0, SETVAL, 0x1)          = 0
semctl(196611, 0, GETVAL, 0x7fa5f7072d4a) = 1
close(6)                                = 0
semop(196611, {{0, 1, 0}}, 1)           = 0
semctl(196611, 0, GETVAL, 0x7fa5f7072ce7) = 2
ioctl(3, DM_DEV_REMOVE, 0x9b8bc0)       = 0
semget(0xd4de5ea, 1, 0)                 = 196611
semctl(196611, 0, GETVAL, 0x7fa5f7072d17) = 2
semop(196611, {{0, -1, IPC_NOWAIT}}, 1) = 0
semop(196611, {{0, 0, 0}}, 1)           = -1 EINTR (Interrupted system call)
--- SIGINT {si_signo=SIGINT, si_code=SI_KERNEL} ---
rt_sigreturn({mask=[]})                 = -1 EINTR (Interrupted system call)
semop(196611, {{0, 0, 0}}, 1

The device is closed correctly, however the cryptsetup process has to
be killed again to get the shell prompt back.

Previous versions (such as 1.6.8 and earlier ones) are not affected by
this bug.

Any idea ?

Regards,

Guido

Re: [dm-crypt] Cryptsetup (>= 1.7.0) luksOpen/luksClose gets stuck after open/close

[Milan Broz]

On 04/07/2016 04:26 PM, Guido Trentalancia wrote:
> Hello.
> 
> Cryptsetup version 1.7.0 and 1.7.1 gets stuck on luksOpen and luksClose
> immediately after the device has been opened or closed.

If it is stuck on semop operation, then it is problem of underlying
device-mapper library (that uses system semaphores for synchronization).

Usually it is caused by a misconfiguration of udev rules (there must be udev
rule calling dmsetup udevcomplete otherwise it ends like in your case).

Please check that you have these udev rules installed - they are
usually part of lvm2/dsmetup subpackage (depends on distro, for example in Debian
it is /lib/udev/rules.d/55-dm.rules).

...
> 
> The device is closed correctly, however the cryptsetup process has to
> be killed again to get the shell prompt back.

Does calling "dmsetup udevcomplete_all" help? If so, see above.

> Previous versions (such as 1.6.8 and earlier ones) are not affected by
> this bug.

I guess 1.6.8 is either compiled without udev support or you reinstalled something.
(cryptsetup 1.7.0 does not contain any related changes to this problem).

Please better post cryptsetup command with --debug, strace only on request
(it does not contain important information, moreove ot can contain your password).
Also always mention your distro and version.

Thanks,
Milan

Re: [dm-crypt] Cryptsetup (>= 1.7.0) luksOpen/luksClose gets stuck after open/close

[Guido Trentalancia]

Hello Milan,

thanks for getting back on this.

On gio, 2016-04-07 at 18:23 +0200, Milan Broz wrote:
> On 04/07/2016 04:26 PM, Guido Trentalancia wrote:
> > 
> > Hello.
> > 
> > Cryptsetup version 1.7.0 and 1.7.1 gets stuck on luksOpen and
> > luksClose
> > immediately after the device has been opened or closed.
> If it is stuck on semop operation, then it is problem of underlying
> device-mapper library (that uses system semaphores for
> synchronization).
> 
> Usually it is caused by a misconfiguration of udev rules (there must
> be udev
> rule calling dmsetup udevcomplete otherwise it ends like in your
> case).
> 
> Please check that you have these udev rules installed - they are
> usually part of lvm2/dsmetup subpackage (depends on distro, for
> example in Debian
> it is /lib/udev/rules.d/55-dm.rules).

The udev rules that you mention (containing a call to dmsetup
udevcomplete) are usually installed as:

/usr/lib/udev/rules.d/95-dm-notify.rules

by LVM. However, LVM 2.2.02.148 doesn't seem to install such rule, so
that might be the problem. I am going to check and will let you know
soon...

Regards,

Guido

Re: [dm-crypt] Cryptsetup (>= 1.7.0) luksOpen/luksClose gets stuck after open/close

[Guido Trentalancia]

Hello again !

On gio, 2016-04-07 at 18:23 +0200, Milan Broz wrote:
> On 04/07/2016 04:26 PM, Guido Trentalancia wrote:
> > 
> > Hello.
> > 
> > Cryptsetup version 1.7.0 and 1.7.1 gets stuck on luksOpen and
> > luksClose
> > immediately after the device has been opened or closed.
> If it is stuck on semop operation, then it is problem of underlying
> device-mapper library (that uses system semaphores for
> synchronization).
> 
> Usually it is caused by a misconfiguration of udev rules (there must
> be udev
> rule calling dmsetup udevcomplete otherwise it ends like in your
> case).
> 
> Please check that you have these udev rules installed - they are
> usually part of lvm2/dsmetup subpackage (depends on distro, for
> example in Debian
> it is /lib/udev/rules.d/55-dm.rules).

I have checked again and it does not depend on a missing udev rule or
on LVM. It is a bug in cryptsetup version >= 1.7.0.

Any idea on how to fix it ?

Regards,

Guido

Re: [dm-crypt] Cryptsetup (>= 1.7.0) luksOpen/luksClose gets stuck after open/close

[Milan Broz]

On 04/07/2016 07:49 PM, Guido Trentalancia wrote:
> 
> Any idea on how to fix it ?

Please post requested relevant debug information first.
You can start comparing debug output with working old package.

Milan

Re: [dm-crypt] Cryptsetup (>= 1.7.0) luksOpen/luksClose gets stuck after open/close

[Guido Trentalancia]

Hello.

My first message contains the debug information (last part of the
strace output).

I am now going to add the last part of the diff between the strace
output of the working (1.6.8) versus broken (1.7.1) cryptsetup
(luksOpen):

< open("/dev/mapper/vg_vortex-LogVol02", O_RDONLY) = 6
---
> open("/dev/mapper/vg_vortex-LogVol03", O_RDONLY) = 6
1239,1245c1284,1288
< ioctl(5, DM_DEV_CREATE, 0x9cc530)       = 0
< ioctl(5, DM_TABLE_LOAD, 0x9cc4d0)       = 0
< ioctl(5, DM_DEV_SUSPEND, 0x9cc3b0)      = 0
< stat("/dev/mapper/luks-c2fa768d-335c-4217-93ce-8c37e61c9d98", 0x7fff8deea600) = -1 ENOENT (No such file or directory)
< gettid()                                = 667
< open("/proc/self/task/667/attr/current", O_RDONLY) = 6
< read(6, "root:sysadm_r:lvm_t:s0-s0:c0.c10"..., 4095) = 35
---
> open("/dev/urandom", O_RDONLY)          = 6
> read(6, "NL", 2)                        = 2
> semget(0xd4d4c4e, 1, IPC_CREAT|IPC_EXCL|0600) = 229380
> semctl(229380, 0, SETVAL, 0x1)          = 0
> semctl(229380, 0, GETVAL, 0x7f7679730d4a) = 1
1247,1411c1290,1301
< open("/etc/selinux/config", O_RDONLY)   = 6
< fstat(6, {st_mode=S_IFREG|0644, st_size=715, ...}) = 0
< mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6421775000
< read(6, "# This file controls the state o"..., 4096) = 715
< read(6, "", 4096)                       = 0
< close(6)                                = 0
< munmap(0x7f6421775000, 4096)            = 0
< futex(0x7f64201e7640, FUTEX_WAKE_PRIVATE, 2147483647) = 0
< open("/etc/selinux/policy-new/contexts/files/file_contexts.subs_dist", O_RDONLY) = 6
< fstat(6, {st_mode=S_IFREG|0644, st_size=465, ...}) = 0
< mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6421775000
< read(6, "# This file can is used to confi"..., 4096) = 465
< read(6, "", 4096)                       = 0
< close(6)                                = 0
< munmap(0x7f6421775000, 4096)            = 0
< open("/etc/selinux/policy-new/contexts/files/file_contexts.subs", O_RDONLY) = -1 ENOENT (No such file or directory)
< open("/etc/selinux/policy-new/contexts/files/file_contexts", O_RDONLY) = 6
< fstat(6, {st_mode=S_IFREG|0644, st_size=172054, ...}) = 0
< open("/etc/selinux/policy-new/contexts/files/file_contexts.homedirs", O_RDONLY) = 7
< open("/etc/selinux/policy-new/contexts/files/file_contexts.local", O_RDONLY) = -1 ENOENT (No such file or directory)
< fstat(6, {st_mode=S_IFREG|0644, st_size=172054, ...}) = 0
< mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6421775000
< read(6, "/.*\tsystem_u:object_r:default_t:"..., 4096) = 4096
< read(6, "_shlib_t:s0\n/usr/(local/)?Adobe/"..., 4096) = 4096
< read(6, "tem_u:object_r:fixed_disk_device"..., 4096) = 4096
< read(6, "plugins/check_log\t--\tsystem_u:ob"..., 4096) = 4096
< read(6, "b(64)?/nagios/plugins/check_sens"..., 4096) = 4096
< read(6, "ject_r:bin_t:s0\n/var/log/(x)?ine"..., 4096) = 4096
< read(6, "_u:object_r:named_zone_t:s0\n/var"..., 4096) = 4096
< read(6, "(/.*)?\tsystem_u:object_r:httpd_c"..., 4096) = 4096
< read(6, "/raw/raw[0-9]+\t-c\tsystem_u:objec"..., 4096) = 4096
< read(6, "m_u:object_r:psad_var_run_t:s0\n/"..., 4096) = 4096
< read(6, "_u:object_r:crond_var_run_t:s0\n/"..., 4096) = 4096
< read(6, "c_t:s0\n/usr/X11R6/lib(64)?/X11/x"..., 4096) = 4096
< read(6, "p/\\.font-unix(/.*)?\tsystem_u:obj"..., 4096) = 4096
< read(6, "samba(/.*)?\tsystem_u:object_r:sa"..., 4096) = 4096
< read(6, "?bin(/.*)?\tsystem_u:object_r:lpr"..., 4096) = 4096
< read(6, "/]*)*\t--\tsystem_u:object_r:textr"..., 4096) = 4096
< read(6, "m_u:object_r:printer_device_t:s0"..., 4096) = 4096
< read(6, "tem_u:object_r:bin_t:s0\n/emul/ia"..., 4096) = 4096
< read(6, "l_shlib_t:s0\n/usr/lib/nx/libXcom"..., 4096) = 4096
< read(6, "\tsystem_u:object_r:cert_t:s0\n/va"..., 4096) = 4096
< read(6, "s/glesx\\.so(\\.[^/]*)*\t--\tsystem_"..., 4096) = 4096
< read(6, "/.*\t<<none>>\n/var/lib/likewise-o"..., 4096) = 4096
< read(6, "_r:ifconfig_exec_t:s0\n/sbin/tc\t-"..., 4096) = 4096
< read(6, "-\tsystem_u:object_r:mysqld_etc_t"..., 4096) = 4096
< read(6, "hot\t-c\tsystem_u:object_r:apm_bio"..., 4096) = 4096
< read(6, "ell_exec_t:s0\n/etc/mail/make\t--\t"..., 4096) = 4096
< read(6, "ject_r:sssd_exec_t:s0\n/usr/bin/k"..., 4096) = 4096
< read(6, "system_u:object_r:etc_aliases_t:"..., 4096) = 4096
< read(6, "t_r:rsync_etc_t:s0\n/sbin/restore"..., 4096) = 4096
< read(6, "u:object_r:checkpc_exec_t:s0\n/us"..., 4096) = 4096
< read(6, "eiser4\t--\tsystem_u:object_r:fsad"..., 4096) = 4096
< read(6, "/run/fcron\\.fifo\t-s\tsystem_u:obj"..., 4096) = 4096
< read(6, "root\t--\tsystem_u:object_r:sysadm"..., 4096) = 4096
< read(6, "tc/sysconfig/hwconf\t--\tsystem_u:"..., 4096) = 4096
< read(6, "ystem_u:object_r:afs_fsserver_ex"..., 4096) = 4096
< read(6, "0\n/usr/bin/partition_uuid\t--\tsys"..., 4096) = 4096
< read(6, "d\\.sock\t-s\tsystem_u:object_r:lvm"..., 4096) = 4096
< read(6, "ystem_u:object_r:textrel_shlib_t"..., 4096) = 4096
< read(6, ":object_r:httpd_cvs_script_exec_"..., 4096) = 4096
< read(6, "t_r:smbd_var_run_t:s0\n/usr/libex"..., 4096) = 4096
< read(6, "object_r:rpm_exec_t:s0\n/usr/shar"..., 4096) = 4096
< read(6, "itchdesk-gui\\.py\t--\tsystem_u:obj"..., 4096) = 4096
< read(6, "m_u:object_r:bin_t:s0\n", 4096) = 22
< read(6, "", 4096)                       = 0
< fstat(7, {st_mode=S_IFREG|0644, st_size=6873, ...}) = 0
< mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6421774000
< read(7, "#\n#\n# User-specific file context"..., 4096) = 4096
< read(7, "ntent_t:s0\n/root/.mozilla/plugin"..., 4096) = 2777
< read(7, "", 4096)                       = 0
< mmap(NULL, 376832, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f64216f3000
< lseek(6, 0, SEEK_SET)                   = 0
< lseek(7, 0, SEEK_SET)                   = 0
< read(6, "/.*\tsystem_u:object_r:default_t:"..., 4096) = 4096
< read(6, "_shlib_t:s0\n/usr/(local/)?Adobe/"..., 4096) = 4096
< read(6, "tem_u:object_r:fixed_disk_device"..., 4096) = 4096
< read(6, "plugins/check_log\t--\tsystem_u:ob"..., 4096) = 4096
< read(6, "b(64)?/nagios/plugins/check_sens"..., 4096) = 4096
< read(6, "ject_r:bin_t:s0\n/var/log/(x)?ine"..., 4096) = 4096
< brk(0xa0a000)                           = 0xa0a000
< read(6, "_u:object_r:named_zone_t:s0\n/var"..., 4096) = 4096
< read(6, "(/.*)?\tsystem_u:object_r:httpd_c"..., 4096) = 4096
< read(6, "/raw/raw[0-9]+\t-c\tsystem_u:objec"..., 4096) = 4096
< read(6, "m_u:object_r:psad_var_run_t:s0\n/"..., 4096) = 4096
< read(6, "_u:object_r:crond_var_run_t:s0\n/"..., 4096) = 4096
< read(6, "c_t:s0\n/usr/X11R6/lib(64)?/X11/x"..., 4096) = 4096
< read(6, "p/\\.font-unix(/.*)?\tsystem_u:obj"..., 4096) = 4096
< brk(0xa2b000)                           = 0xa2b000
< read(6, "samba(/.*)?\tsystem_u:object_r:sa"..., 4096) = 4096
< read(6, "?bin(/.*)?\tsystem_u:object_r:lpr"..., 4096) = 4096
< read(6, "/]*)*\t--\tsystem_u:object_r:textr"..., 4096) = 4096
< read(6, "m_u:object_r:printer_device_t:s0"..., 4096) = 4096
< read(6, "tem_u:object_r:bin_t:s0\n/emul/ia"..., 4096) = 4096
< read(6, "l_shlib_t:s0\n/usr/lib/nx/libXcom"..., 4096) = 4096
< read(6, "\tsystem_u:object_r:cert_t:s0\n/va"..., 4096) = 4096
< read(6, "s/glesx\\.so(\\.[^/]*)*\t--\tsystem_"..., 4096) = 4096
< brk(0xa4c000)                           = 0xa4c000
< read(6, "/.*\t<<none>>\n/var/lib/likewise-o"..., 4096) = 4096
< read(6, "_r:ifconfig_exec_t:s0\n/sbin/tc\t-"..., 4096) = 4096
< read(6, "-\tsystem_u:object_r:mysqld_etc_t"..., 4096) = 4096
< read(6, "hot\t-c\tsystem_u:object_r:apm_bio"..., 4096) = 4096
< read(6, "ell_exec_t:s0\n/etc/mail/make\t--\t"..., 4096) = 4096
< brk(0xa6d000)                           = 0xa6d000
< read(6, "ject_r:sssd_exec_t:s0\n/usr/bin/k"..., 4096) = 4096
< read(6, "system_u:object_r:etc_aliases_t:"..., 4096) = 4096
< read(6, "t_r:rsync_etc_t:s0\n/sbin/restore"..., 4096) = 4096
< read(6, "u:object_r:checkpc_exec_t:s0\n/us"..., 4096) = 4096
< read(6, "eiser4\t--\tsystem_u:object_r:fsad"..., 4096) = 4096
< read(6, "/run/fcron\\.fifo\t-s\tsystem_u:obj"..., 4096) = 4096
< brk(0xa8e000)                           = 0xa8e000
< read(6, "root\t--\tsystem_u:object_r:sysadm"..., 4096) = 4096
< read(6, "tc/sysconfig/hwconf\t--\tsystem_u:"..., 4096) = 4096
< read(6, "ystem_u:object_r:afs_fsserver_ex"..., 4096) = 4096
< read(6, "0\n/usr/bin/partition_uuid\t--\tsys"..., 4096) = 4096
< read(6, "d\\.sock\t-s\tsystem_u:object_r:lvm"..., 4096) = 4096
< read(6, "ystem_u:object_r:textrel_shlib_t"..., 4096) = 4096
< brk(0xaaf000)                           = 0xaaf000
< read(6, ":object_r:httpd_cvs_script_exec_"..., 4096) = 4096
< read(6, "t_r:smbd_var_run_t:s0\n/usr/libex"..., 4096) = 4096
< read(6, "object_r:rpm_exec_t:s0\n/usr/shar"..., 4096) = 4096
< read(6, "itchdesk-gui\\.py\t--\tsystem_u:obj"..., 4096) = 4096
< read(6, "m_u:object_r:bin_t:s0\n", 4096) = 22
< read(6, "", 4096)                       = 0
< read(7, "#\n#\n# User-specific file context"..., 4096) = 4096
< read(7, "ntent_t:s0\n/root/.mozilla/plugin"..., 4096) = 2777
< read(7, "", 4096)                       = 0
< mmap(NULL, 376832, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6421697000
< munmap(0x7f64216f3000, 376832)          = 0
< close(6)                                = 0
< munmap(0x7f6421775000, 4096)            = 0
< close(7)                                = 0
< munmap(0x7f6421774000, 4096)            = 0
< brk(0xad0000)                           = 0xad0000
< open("/sys/fs/selinux/mls", O_RDONLY)   = 6
< read(6, "1", 19)                        = 1
< close(6)                                = 0
< futex(0x7f64201e88d0, FUTEX_WAKE_PRIVATE, 2147483647) = 0
< socket(PF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC, 0) = 6
< connect(6, {sa_family=AF_LOCAL, sun_path="/var/run/setrans/.setrans-unix"}, 110) = -1 ENOENT (No such file or directory)
< close(6)                                = 0
< socket(PF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC, 0) = 6
< connect(6, {sa_family=AF_LOCAL, sun_path="/var/run/setrans/.setrans-unix"}, 110) = -1 ENOENT (No such file or directory)
< close(6)                                = 0
< gettid()                                = 667
< open("/proc/self/task/667/attr/fscreate", O_RDWR) = 6
< write(6, "system_u:object_r:fixed_disk_dev"..., 41) = 41
< close(6)                                = 0
< umask(0)                                = 022
< mknod("/dev/mapper/luks-c2fa768d-335c-4217-93ce-8c37e61c9d98", S_IFBLK|0600, makedev(253, 8)) = 0
< umask(022)                              = 0
< gettid()                                = 667
< open("/proc/self/task/667/attr/fscreate", O_RDWR) = 6
< write(6, NULL, 0)                       = 0
< close(6)                                = 0
< chown("/dev/mapper/luks-c2fa768d-335c-4217-93ce-8c37e61c9d98", 0, 0) = 0
< open("/sys/dev/block/253:8/bdi/read_ahead_kb", O_RDONLY) = 6
< read(6, "128\n", 23)                    = 4
< close(6)                                = 0
< close(5)                                = 0
< munlockall()                            = 0
< setpriority(PRIO_PROCESS, 0, 0)         = 0
< munmap(0x7f6421697000, 376832)          = 0
< exit_group(0)                           = ?
< +++ exited with 0 +++
---
> semop(229380, {{0, 1, 0}}, 1)           = 0
> semctl(229380, 0, GETVAL, 0x7f7679730ce7) = 2
> ioctl(5, DM_DEV_CREATE, 0x20dd820)      = 0
> ioctl(5, DM_TABLE_LOAD, 0x20dd560)      = 0
> ioctl(5, DM_DEV_SUSPEND, 0x20dd430)     = 0
> semget(0xd4d4c4e, 1, 0)                 = 229380
> semctl(229380, 0, GETVAL, 0x7f7679730d17) = 2
> semop(229380, {{0, -1, IPC_NOWAIT}}, 1) = 0
> semop(229380, {{0, 0, 0}}, 1)           = -1 EINTR (Interrupted system call)
> --- SIGINT {si_signo=SIGINT, si_code=SI_KERNEL} ---
> rt_sigreturn({mask=[]})                 = -1 EINTR (Interrupted system call)
> semop(229380, {{0, 0, 0}}, 1

The two versions show a different behaviour (the working version reads
SELinux configuration, the broken version opens /dev/urandom and gets
stuck), so the code must have changed.

If you need other information, please let me know. Obviously I cannot
post gdb output as the program does not crash, it simply gets stuck.
But it's a genuine bug...

Regards,

Guido

On Thu, 07/04/2016 alle 20.06 +0200, Milan Broz wrote:
> On 04/07/2016 07:49 PM, Guido Trentalancia wrote:
> > 
> > 
> > Any idea on how to fix it ?
> Please post requested relevant debug information first.
> You can start comparing debug output with working old package.
> 
> Milan

Re: [dm-crypt] Cryptsetup (>= 1.7.0) luksOpen/luksClose gets stuck after open/close

[Milan Broz]

On 04/07/2016 08:47 PM, Guido Trentalancia wrote:
> Hello.
> 
> My first message contains the debug information (last part of the
> strace output).

No, it does not. Please post debug information and NOT strace as
I described in the first reply...

Just add --debug to cryptsetup command and you have it (without strace).
It contains a lot of info that is needed to debug almost all kind of cryptsetup problem.

You also missed request to post distro version here.
Do you compile cryptsetup yourself?

Anyway, I am almost sure you are missing the udev dmsetup udevcomplete
call in udev, this is very common error.

> If you need other information, please let me know. Obviously I cannot
> post gdb output as the program does not crash, it simply gets stuck.

Strace or gdb info is not needed if not requested, --debug log is usually
enough to see what is going on.

And did you try that "dmsetup udevcomplete_all" I already suggested?
(once it is "stuck", run from another terminal - is should finish that command)

> The two versions show a different behaviour (the working version reads
> SELinux configuration, the broken version opens /dev/urandom and gets
> stuck), so the code must have changed.

I do not know about any change there.
Running code depends on compilation parameters, some basic info how code
behaves is in the debug log I am still waiting for...


Milan

Re: [dm-crypt] Cryptsetup (>= 1.7.0) luksOpen/luksClose gets stuck after open/close

[Guido Trentalancia]

Hello Milan,

I have checked again and I can now confirm that the problem happens
only when using LVM version 2.2.02.148.

After upgrading to LVM version 2.2.02.149 the problem disappears.

However, it might not depend on the udev rule, as such rule had not
been uninstalled when using LVM version 2.2.02.148. Also, I still
cannot explain the reason why cryptsetup < 1.7.0 works fine even when
LVM2.2.02.148 and the mentioned udev rule are installed.

Regards,

Guido

On Thu, 2016-04-07 at 21:24 +0200, Milan Broz wrote:
> On 04/07/2016 08:47 PM, Guido Trentalancia wrote:
> > 
> > Hello.
> > 
> > My first message contains the debug information (last part of the
> > strace output).
> No, it does not. Please post debug information and NOT strace as
> I described in the first reply...
> 
> Just add --debug to cryptsetup command and you have it (without
> strace).
> It contains a lot of info that is needed to debug almost all kind of
> cryptsetup problem.
> 
> You also missed request to post distro version here.
> Do you compile cryptsetup yourself?
> 
> Anyway, I am almost sure you are missing the udev dmsetup
> udevcomplete
> call in udev, this is very common error.
> 
> > 
> > If you need other information, please let me know. Obviously I
> > cannot
> > post gdb output as the program does not crash, it simply gets
> > stuck.
> Strace or gdb info is not needed if not requested, --debug log is
> usually
> enough to see what is going on.
> 
> And did you try that "dmsetup udevcomplete_all" I already suggested?
> (once it is "stuck", run from another terminal - is should finish
> that command)
> 
> > 
> > The two versions show a different behaviour (the working version
> > reads
> > SELinux configuration, the broken version opens /dev/urandom and
> > gets
> > stuck), so the code must have changed.
> I do not know about any change there.
> Running code depends on compilation parameters, some basic info how
> code
> behaves is in the debug log I am still waiting for...
> 
> 
> Milan