Bug 1081940

So far the problem is only with the pvscan.

Since piped pvscan is used with bash completion, it could potentially cause temporary lockups in cluster if an error in bash completion code is present.

This request was not resolved in time for the current release.
Red Hat invites you to ask your support representative to
propose this request, if still desired, for consideration in
the next release of Red Hat Enterprise Linux.

Yes, please grab some diagnostics and work out what it is waiting for:  ps listing (incl wchan), lsof, run with -vvvv, strace etc.

The pvscan drops from the hang after about 30-40 seconds.

[0] rhel7-b/~ # time pvscan | true

real    0m0.224s
user    0m0.007s
sys     0m0.014s


[0] rhel7-c/~ # time pvscan | true

real    0m33.215s
user    0m0.012s
sys     0m0.008s

[0] rhel7-d/~ # time pvscan | true

real    0m33.044s
user    0m0.009s
sys     0m0.014s


Strace shows it waits on read from clvmd.sock after sending request to lock #global lock, this is _send_request fn in cluster_locking.c, the "reread" label in the code:


write(2, "Setting global/wait_for_locks to"..., 34Setting global/wait_for_locks to 1) = 34
write(2, "\n", 1)                       = 1
write(2, "#locking/locking.c:271       ", 29#locking/locking.c:271       ) = 29
write(2, "Cluster locking selected.", 25Cluster locking selected.) = 25
write(2, "\n", 1)                       = 1
socket(PF_LOCAL, SOCK_STREAM, 0)        = 3
connect(3, {sa_family=AF_LOCAL, sun_path="/run/lvm/clvmd.sock"}, 110) = 0
rt_sigprocmask(SIG_SETMASK, ~[RTMIN RT_1], [], 8) = 0
write(2, "#locking/cluster_locking.c:502  "..., 37#locking/cluster_locking.c:502       ) = 37
write(2, "Locking VG P_#global PW (VG) (0x"..., 34Locking VG P_#global PW (VG) (0x4)) = 34
write(2, "\n", 1)                       = 1
write(3, "3\0\0\0\0\0\0\0\0\0\0\0\v\0\0\0\0\4\4P_#global\0", 29) = 29
read(3,

Created attachment 1054860 [details]
Backtraces from clvmd and pvscan when the hang appears

The pvscan is waiting on clvmd and clvmd is waiting on:

(gdb) bt
#0  0x00007f470c4226d5 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00007f470c634a68 in sync_write_v6 () from /lib64/libdlm.so.3
#2  0x00007f470c6355c0 in ls_lock_v6 () from /lib64/libdlm.so.3
#3  0x00007f470c6356a5 in ls_lock () from /lib64/libdlm.so.3
#4  0x00007f470c6358fd in dlm_ls_lock_wait () from /lib64/libdlm.so.3
#5  0x00007f470d713f6a in _lock_resource (resource=0x7f470f023763 "P_#global", mode=4, flags=0, lockid=0x7f470d550cb4) at clvmd-corosync.c:448
#6  0x00007f470d70e57d in lock_vg () at clvmd-command.c:224
#7  do_pre_command () at clvmd-command.c:259
#8  0x00007f470d70fe40 in pre_and_post_thread (arg=0x7f470f023600) at clvmd.c:1694
#9  0x00007f470c41edc5 in start_thread () from /lib64/libpthread.so.0
#10 0x00007f470bf481bd in clone () from /lib64/libc.so.6

It's possible the pipe used in reproducer is just a thing that changes timing to make this bug appear. I'll try to dig deeper, possibly finding simpler reproducer. I don't quite believe the pipe could have direct effect here for this bug.

(In reply to Peter Rajnoha from comment #13)
> Created attachment 1054860 [details]
> Backtraces from clvmd and pvscan when the hang appears

This was with 3 nodes where 1 always passed (both pvscan and clvmd finished with clear state), the other two got blocked with the backtrace above. I'll try to reproduce with 2 nodes only...

Also easily reproducible with 2 nodes.

This looks like the P_#global lock was not released properly on node which finished the pvscan (rhel7-c in the log below - the lock still registered as "Granted") and another node is just waiting for this lock to be released (rhel7-b - "Waiting"):

rhel7-b/~ # dlm_tool lockdebug -v clvmd

Resource len  9  "P_#global"
Master:2         
Waiting
00000001 -- (PW) Master:   2 00000002          
time 0002079452097660 flags 00000000 00000001 bast 0 0


rhel7-c/~ # dlm_tool lockdebug -v clvmd

Resource len  9  "P_#global"
Master           
Granted
00000001 PW                                    
time 0002077280469236 flags 00000000 00000001 bast 0 0
Waiting
00000002 -- (PW) Remote:   1 00000001          
time 0002077302832343 flags 00000000 00010001 bast 0 0


I'm looking for the exact code path taken to check why the lock was not released properly...

There's unhandled signal from broken pipe which kills the LVM command *before* it has a chance to unlock the VG, keeping the locks around and blocking other commands:

write(1, "  PV /dev/vda2   VG rhel   lvm2 "..., 55) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=1849, si_uid=0} ---
+++ killed by SIGPIPE +++

The "true" command (and maybe others too) just doesn't care what's in the pipe, breaking the pipe. I suppose we should add a signal handler here to cover this case...

The cleanup on clvmd side in case client disconnects immediately doesn't seem to cleanup the lock that was initiated by the client... Inspecting more...

The code that schedules the necessary clean up after a client disappears does not work properly and locks do not get released at the right time.

Let's try this one:
  https://lists.fedorahosted.org/pipermail/lvm2-commits/2015-July/004323.html

Gitweb:        http://git.fedorahosted.org/git/?p=lvm2.git;a=commitdiff;h=be662439331abf6ccb16dd996bfe15eb613b4e53
Commit:        be662439331abf6ccb16dd996bfe15eb613b4e53
Parent:        57534733b7750f17f5ffa115306dcb650d8015b9
Author:        Alasdair G Kergon <agk at redhat.com>
AuthorDate:    Thu Jul 23 23:10:16 2015 +0100
Committer:     Alasdair G Kergon <agk at redhat.com>
CommitterDate: Thu Jul 23 23:10:16 2015 +0100

clvmd: Fix freeze if client dies holding locks.

Simply running concurrent copies of 'pvscan | true' is enough to make
clvmd freeze: pvscan exits on the EPIPE without first releasing the
global lock.

clvmd notices the client disappear but because the cleanup code that
releases the locks is triggered from within some processing after the
next select() returns, and that processing can 'break' after doing just
one action, it sometimes never releases the locks to other clients.

Move the cleanup code before the select.
Check all fds after select().
Improve some debug messages and warn in the unlikely event that
select() capacity could soon be exceeded.
---
 WHATS_NEW                     |    1 +
 daemons/clvmd/clvmd-command.c |    4 +-
 daemons/clvmd/clvmd.c         |   67 +++++++++++++++++++++++++++--------------
 3 files changed, 47 insertions(+), 25 deletions(-)

tested with multiple simultaneous pvscans with (and without) pipes on a 3-node cluster. 
All returned without issues. 

Marking VERIFIED with:


lvm2-2.02.127-1.el7    BUILT: Mon Aug 10 10:22:35 CEST 2015
lvm2-libs-2.02.127-1.el7    BUILT: Mon Aug 10 10:22:35 CEST 2015
lvm2-cluster-2.02.127-1.el7    BUILT: Mon Aug 10 10:22:35 CEST 2015
device-mapper-1.02.104-1.el7    BUILT: Mon Aug 10 10:22:35 CEST 2015
device-mapper-libs-1.02.104-1.el7    BUILT: Mon Aug 10 10:22:35 CEST 2015
device-mapper-event-1.02.104-1.el7    BUILT: Mon Aug 10 10:22:35 CEST 2015
device-mapper-event-libs-1.02.104-1.el7    BUILT: Mon Aug 10 10:22:35 CEST 2015
device-mapper-persistent-data-0.5.4-1.el7    BUILT: Fri Jul 17 15:56:22 CEST 2015
cmirror-2.02.127-1.el7    BUILT: Mon Aug 10 10:22:35 CEST 2015

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://rhn.redhat.com/errata/RHBA-2015-2147.html