Here are the few logs that I see with vdsm.log

<snip_error1>
2017-09-06 12:50:48,625+0530 INFO  (MainThread) [root] Unregistering all secrets (secret:91)
2017-09-06 12:50:48,627+0530 WARN  (MainThread) [root] connection to libvirt broken. ecode: 1 edom: 7 (libvirtconnection:148)
2017-09-06 12:50:48,628+0530 CRIT  (MainThread) [root] taking calling process down. (libvirtconnection:150)
2017-09-06 12:50:48,628+0530 INFO  (MainThread) [vds] Received signal 15, shutting down (vdsm:68)
2017-09-06 12:50:48,628+0530 ERROR (MainThread) [vds] Exception raised (vdsm:154)
Traceback (most recent call last):
  File "/usr/share/vdsm/vdsm", line 152, in run
    serve_clients(log)
  File "/usr/share/vdsm/vdsm", line 117, in serve_clients
    cif.prepareForShutdown()
  File "/usr/share/vdsm/clientIF.py", line 295, in prepareForShutdown
    secret.clear()
  File "/usr/lib/python2.7/site-packages/vdsm/virt/secret.py", line 93, in clear
    for virsecret in con.listAllSecrets():
  File "/usr/lib/python2.7/site-packages/vdsm/libvirtconnection.py", line 142, in wrapper
    __connections.get(id(target)).pingLibvirt()
  File "/usr/lib64/python2.7/site-packages/libvirt.py", line 3745, in getLibVersion
    if ret == -1: raise libvirtError ('virConnectGetLibVersion() failed', conn=self)
libvirtError: internal error: client socket is closed

</snip_error1>

<snip_error2>
2017-09-06 12:50:41,042+0530 INFO  (jsonrpc/2) [jsonrpc.JsonRpcServer] RPC call Host.getCapabilities failed (error -32603) in 0.10 seconds (__init__:539)
2017-09-06 12:50:41,699+0530 ERROR (jsonrpc/7) [jsonrpc.JsonRpcServer] Internal server error (__init__:577)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/yajsonrpc/__init__.py", line 572, in _handle_request
    res = method(**params)
  File "/usr/lib/python2.7/site-packages/vdsm/rpc/Bridge.py", line 198, in _dynamicMethod
    result = fn(*methodArgs)
  File "/usr/lib/python2.7/site-packages/vdsm/gluster/apiwrapper.py", line 79, in list
    return self._gluster.hostsList()
  File "/usr/lib/python2.7/site-packages/vdsm/gluster/api.py", line 89, in wrapper
    rv = func(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/vdsm/gluster/api.py", line 441, in hostsList
    return {'hosts': self.svdsmProxy.glusterPeerStatus()}
  File "/usr/lib/python2.7/site-packages/vdsm/supervdsm.py", line 53, in __call__
    return callMethod()
  File "/usr/lib/python2.7/site-packages/vdsm/supervdsm.py", line 51, in <lambda>
    **kwargs)
  File "<string>", line 2, in glusterPeerStatus
  File "/usr/lib64/python2.7/multiprocessing/managers.py", line 758, in _callmethod
    conn.send((self._id, methodname, args, kwds))
IOError: [Errno 32] Broken pipe

</snip_error2>


<snip_info1>
2017-09-06 12:50:44,174+0530 WARN  (vdsm.Scheduler) [virt.periodic.Operation] could not run <VmDispatcher operation=<class 'vdsm.virt.periodic.DriveWatermarkMonitor'> at 0x387c7d0>, executor queue full (periodic:235)
2017-09-06 12:50:44,302+0530 WARN  (jsonrpc/4) [virt.vm] (vmId='b3a5727b-b0ef-4d72-a1e2-ae7bb2cb56b1') monitor became unresponsive (command timeout, age=380386.17) (vm:5102)
2017-09-06 12:50:44,304+0530 WARN  (jsonrpc/4) [virt.vm] (vmId='a219a204-b58e-4551-a622-6d17fde875c1') monitor became unresponsive (command timeout, age=380386.17) (vm:5102)
2017-09-06 12:50:44,305+0530 WARN  (jsonrpc/4) [virt.vm] (vmId='f317ffc0-8c71-4386-a34a-eef6d8a17ed8') monitor became unresponsive (command timeout, age=380386.17) (vm:5102)
2017-09-06 12:50:44,306+0530 WARN  (jsonrpc/4) [virt.vm] (vmId='9c063af2-527d-4e1e-80c0-34941fe23c83') monitor became unresponsive (command timeout, age=380386.17) (vm:5102)
2017-09-06 12:50:44,307+0530 WARN  (jsonrpc/4) [virt.vm] (vmId='ee443227-c385-41ae-9ba6-8b1106432794') monitor became unresponsive (command timeout, age=380386.17) (vm:5102)
2017-09-06 12:50:44,309+0530 WARN  (jsonrpc/4) [virt.vm] (vmId='514a8013-9898-4fdd-bbe3-32979ae20034') monitor became unresponsive (command timeout, age=380386.17) (vm:5102)
2017-09-06 12:50:44,310+0530 WARN  (jsonrpc/4) [virt.vm] (vmId='c2cee203-9a44-4404-be29-7dc4f9ef8c85') monitor became unresponsive (command timeout, age=380386.18) (vm:5102)
2017-09-06 12:50:44,311+0530 WARN  (jsonrpc/4) [virt.vm] (vmId='1491f34c-8f0c-41f7-8aa1-7fd432688e0a') monitor became unresponsive (command timeout, age=380386.18) (vm:5102)
2017-09-06 12:50:44,315+0530 INFO  (jsonrpc/4) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539)
2017-09-06 12:50:44,319+0530 INFO  (jsonrpc/5) [vdsm.api] START getStoragePoolInfo(spUUID=u'59a95205-01e4-01a8-0352-0000000000ea', options=None) from=::ffff:10.70.34.125,49562, flow_id=1f83d03a, task_id=c1b8b888-1e19-4735-9237-6a4821472087 (api:46)

</snip_info1>

Created attachment 1322633 [details]
vdsm.log from host1

Created attachment 1322634 [details]
vdsm.log from host2

Created attachment 1322635 [details]
vdsm.log from host3

Here is the quick walk through of the setup.

1. Its a converged setup, cluster has both virt & gluster capability enabled

2. Cluster has the feature that enables VMs to access the disk images via libgfapi ( gluster native ) access mechanism

3. There are 3 hosts in the cluster, each having 94GB RAM, and 12 VCPUs.

Here is the memory usage across the hosts:
Host1
------
              total        used        free      shared  buff/cache   available
Mem:             94          60          29           0           4          32

Host2
------
              total        used        free      shared  buff/cache   available
Mem:             94          43          47           0           2          49
Swap:             3           0           3

Host3
------
              total        used        free      shared  buff/cache   available
Mem:             94          46          45           0           2          47
Swap:             3           0           3

4. Each host has got 10 VMs running on it, and each one is created as 'Medium' instance, with 4GB RAM and 2 VCPUs

5. Visible observations
        a. All the VMs have become non-responding
        b. All the storage domain have become inactive
        c. The first host has become non-responsive

I think previous VDSM logs (the attached already have errors - we'd like to see when it started) and probably supervdsm log and /var/log/message might be useful.

... best to get the full sosreport. Thanks

(In reply to Michal Skrivanek from comment #7)
> ... best to get the full sosreport. Thanks

Thanks Michal.

Apologies, for getting late with the required logs with this problem. I have scrapped the setup earlier. Now that I have set it up again, and now I hit the same problem very consistently.

As the sosreports grew beyond 20MB, I couldn't attach them to this bug. I will copy the sosports to the separate lab server and will update the location.

I did hit the same issue in my setup too where vm's are going to non responding state. system is not loaded completely. During weekend enabled libgfapi and left it that way.

Once there are non responding vms in the setup, i cannot start any new vm created from template. It gets stuck in waiting for launch state.

ok, it's good it's reproducible. Can you please narrow down when/how it happens on that setup(or elsewhere) just so we can look at the relevant log?

Hi Michal,

       This particular issue happened on my setup when it was left idle for 2 days. No I/O or no operations was running on the setup. 

from engine:
===================
I see that vm went to non responsive state @Sep 23, 2017 3:41:12 PM VM applinuxvm2 is not responding.


from vdsm.log following is what i see during the same time:
============================================================
2017-09-23 15:41:11,740+0530 INFO  (periodic/7) [vdsm.api] FINISH repoStats return={u'9dec0b9d-7269-4079-9409-a54e390f38eb': {'code': 0, 'actual': True, 'version': 4, 'acqui
red': True, 'delay': '0.00102189', 'lastCheck': '1.7', 'valid': True}, u'6915cf87-53d1-4c0b-b4d8-7784eaf83956': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, '
delay': '0.000628822', 'lastCheck': '0.9', 'valid': True}, u'e2ab5033-43d0-4da6-926d-406d735d0ff9': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.0
00820777', 'lastCheck': '9.3', 'valid': True}} from=internal, task_id=37211fc6-3e23-4311-81e8-bea8526d4ac6 (api:52)
2017-09-23 15:41:11,816+0530 WARN  (jsonrpc/0) [virt.vm] (vmId='53db50cd-05b4-4e56-b5b1-88d2da4b5307') monitor became unresponsive (command timeout, age=64.6299999999) (vm:5
109)
2017-09-23 15:41:11,817+0530 WARN  (jsonrpc/0) [virt.vm] (vmId='eba9c0a4-ed90-4008-8f3d-072d0149bd5f') monitor became unresponsive (command timeout, age=64.6299999999) (vm:5
109)
2017-09-23 15:41:11,817+0530 INFO  (jsonrpc/0) [throttled] Current getAllVmStats: {u'53db50cd-05b4-4e56-b5b1-88d2da4b5307': 'Up', u'eba9c0a4-ed90-4008-8f3d-072d0149bd5f': 'U
p'} (throttledlog:105)
2017-09-23 15:41:11,818+0530 INFO  (jsonrpc/0) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539)
2017-09-23 15:41:12,251+0530 INFO  (Reactor thread) [ProtocolDetector.AcceptorImpl] Accepted connection from ::1:40826 (protocoldetector:72)
2017-09-23 15:41:12,257+0530 INFO  (Reactor thread) [ProtocolDetector.Detector] Detected protocol stomp from ::1:40826 (protocoldetector:127)
2017-09-23 15:41:12,257+0530 INFO  (Reactor thread) [Broker.StompAdapter] Processing CONNECT request (stompreactor:103)
2017-09-23 15:41:12,260+0530 INFO  (JsonRpc (StompReactor)) [Broker.StompAdapter] Subscribe command received (stompreactor:132)
2017-09-23 15:41:12,412+0530 INFO  (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC call Host.getHardwareInfo succeeded in 0.00 seconds (__init__:539)
2017-09-23 15:41:12,415+0530 INFO  (jsonrpc/3) [vdsm.api] START repoStats(options=None) from=::1,40826, task_id=505140bb-e388-4de9-98c7-61f06066b6f7 (api:46)
2017-09-23 15:41:12,415+0530 INFO  (jsonrpc/3) [vdsm.api] FINISH repoStats return={u'9dec0b9d-7269-4079-9409-a54e390f38eb': {'code': 0, 'actual': True, 'version': 4, 'acquir
ed': True, 'delay': '0.00102189', 'lastCheck': '2.4', 'valid': True}, u'6915cf87-53d1-4c0b-b4d8-7784eaf83956': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'd
elay': '0.000628822', 'lastCheck': '1.6', 'valid': True}, u'e2ab5033-43d0-4da6-926d-406d735d0ff9': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.01
85501', 'lastCheck': '0.4', 'valid': True}} from=::1,40826, task_id=505140bb-e388-4de9-98c7-61f06066b6f7 (api:52)
2017-09-23 15:41:12,471+0530 INFO  (jsonrpc/3) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.06 seconds (__init__:539)
2017-09-23 15:41:12,986+0530 INFO  (Reactor thread) [ProtocolDetector.AcceptorImpl] Accepted connection from ::1:40828 (protocoldetector:72)
2017-09-23 15:41:12,991+0530 INFO  (Reactor thread) [ProtocolDetector.Detector] Detected protocol stomp from ::1:40828 (protocoldetector:127)
2017-09-23 15:41:12,991+0530 INFO  (Reactor thread) [Broker.StompAdapter] Processing CONNECT request (stompreactor:103)
2017-09-23 15:41:12,992+0530 INFO  (JsonRpc (StompReactor)) [Broker.StompAdapter] Subscribe command received (stompreactor:132)
2017-09-23 15:41:13,005+0530 INFO  (jsonrpc/2) [vdsm.api] START repoStats(options=None) from=::ffff:10.70.44.73,56640, flow_id=2462ce52, task_id=b1f4bf90-e197-42bc-90de-3392
4b0f6f82 (api:46)



No errors / Tracebacks seen in vdsm, engine and qemu logs.

(In reply to Michal Skrivanek from comment #12)
> ok, it's good it's reproducible. Can you please narrow down when/how it
> happens on that setup(or elsewhere) just so we can look at the relevant log?

Hi Michal,

I couldn't narrow down to the issue.
It happens once the VMs are created and left idle for few hours.

We should really work together to find the real issue.

adding more information is good, and you did that, so thanks for that.
If it happens without any apparent trigger and there is no error in vdsm then please gather more low-level information - ideally enable debug for libvirt and gather that (plan for lots of space for the log if it only happens after days of running). Also, anything in qemu log for that VM?

It does not really converge, moving to 4.1.8

I made an additional research here and discovered that libvirt actually stuck inside of libgluster:

Thread 7 (Thread 0x7f8506ffd700 (LWP 29403)):
#0  0x00007f852b915ef0 in __pause_nocancel () from /lib64/libpthread.so.0
#1  0x00007f852b90cba5 in __pthread_mutex_lock_full () from /lib64/libpthread.so.0
#2  0x00007f851222974c in gf_mem_set_acct_info (xl=xl@entry=0x7f85124cd700 <global_xlator>, alloc_ptr=alloc_ptr@entry=0x7f8506ffc700, size=size@entry=704, type=type@entry=33, typestr=typestr@entry=0x7f85122a01e6 "gf_common_mt_iobuf") at mem-pool.c:67
#3  0x00007f8512229a57 in __gf_calloc (nmemb=nmemb@entry=88, size=size@entry=8, type=type@entry=33, typestr=typestr@entry=0x7f85122a01e6 "gf_common_mt_iobuf") at mem-pool.c:123
#4  0x00007f851222b987 in __iobuf_arena_init_iobufs (iobuf_arena=iobuf_arena@entry=0x7f84f40eb340) at iobuf.c:84
#5  0x00007f851222be0a in __iobuf_arena_alloc (iobuf_pool=iobuf_pool@entry=0x7f84f40eaa50, page_size=page_size@entry=262144, num_iobufs=num_iobufs@entry=8) at iobuf.c:208
#6  0x00007f851222c0ce in __iobuf_pool_add_arena (iobuf_pool=0x7f84f40eaa50, page_size=262144, num_pages=8) at iobuf.c:272
#7  0x00007f851222c1a9 in iobuf_pool_add_arena (iobuf_pool=iobuf_pool@entry=0x7f84f40eaa50, page_size=page_size@entry=262144, num_pages=num_pages@entry=8) at iobuf.c:297
#8  0x00007f851222c4e9 in iobuf_pool_new () at iobuf.c:425
#9  0x00007f85124d6063 in glusterfs_ctx_defaults_init (ctx=ctx@entry=0x7f84f408b8f0) at glfs.c:90
#10 0x00007f85124d6f9c in pub_glfs_new (volname=0x7f850827aa10 "data") at glfs.c:732
#11 0x00007f85126f853c in virStorageFileBackendGlusterInit (src=0x7f850827a5e0) at storage/storage_backend_gluster.c:642
#12 0x00007f8518e00c62 in virStorageFileInitAs (src=src@entry=0x7f850827a5e0, uid=uid@entry=107, gid=gid@entry=107) at storage/storage_driver.c:2982
#13 0x00007f8518e01225 in virStorageFileGetMetadataRecurse (src=src@entry=0x7f850827a5e0, parent=parent@entry=0x7f850827a5e0, uid=uid@entry=107, gid=gid@entry=107, allow_probe=allow_probe@entry=false, report_broken=report_broken@entry=false,
    cycle=cycle@entry=0x7f84f4001880) at storage/storage_driver.c:3242
#14 0x00007f8518e016cf in virStorageFileGetMetadata (src=0x7f850827a5e0, uid=107, gid=107, allow_probe=false, report_broken=report_broken@entry=false) at storage/storage_driver.c:3365
#15 0x00007f8511004235 in qemuDomainDetermineDiskChain (driver=driver@entry=0x7f85080f86c0, vm=0x7f8508266aa0, disk=0x7f850827a860, force_probe=force_probe@entry=true, report_broken=report_broken@entry=false) at qemu/qemu_domain.c:5473
#16 0x00007f851102fc74 in qemuProcessReconnect (opaque=<optimized out>) at qemu/qemu_process.c:6764
#17 0x00007f852e4f8d92 in virThreadHelper (data=<optimized out>) at util/virthread.c:206
#18 0x00007f852b90ee25 in start_thread () from /lib64/libpthread.so.0
#19 0x00007f852b63c34d in clone () from /lib64/libc.so.6


The reason, why it access libgluster here is: "we are attempting to re-detect the backing chain on reconnect to the qemu process thus we are opening the gluster backend to the volume to read the metadata and that is stuck. looks like the gluster library deadlocked, since it waits in an attempt to lock the mutex and all other libvirt threads wait on the VM lock."

Gluster storage domain had heal issue at the same time:
# gluster volume heal data info
Brick 10.70.36.79:/gluster_bricks/data/data
/.shard/f1fe48ae-fdfd-49c6-9c46-b751cc620e20.1599 
/.shard 
[...skipped...]

So, there are probably two errors here: libvirt should not hold the VM lock on long-running ops like this one and gluster should not lock up here.

(In reply to Michal Skrivanek from comment #12)
> ok, it's good it's reproducible. Can you please narrow down when/how it
> happens on that setup(or elsewhere) just so we can look at the relevant log?

Looks like Denis ( Thanks Denis !! ) has found the real issue.

Poornima, do you have any inputs on why there was a deadlock in gfapi. Any logs you would need?

I see that one thread is waiting on lock, can you paste the bt of all threads? so we know who is the other thread holding the lock.

From the bz: 400541 "The __pause_nocancel routine will deadlock a thread if it believes the owner of the mutex concerned has died while holding that mutex."
But it is unlikely that a thread executing gf_mem_set_acct_info has died.

Will need a little more information from the gdb to see who is the owner of the lock and other things. Will update the instructions for the same.

If its reproducible, can anyone of you share the setup for debugging?

Release 3.12 has been EOLd and this bug was still found to be in the NEW state, hence moving the version to mainline, to triage the same and take appropriate actions.

We are not pushing libgfapi for oVirt at the moment.