1:30 a.m.
I have two hosts, only one of them was running VM's at the time of
this crash so I can't tell if this is a node specific problem.
rpm -qa | egrep -i 'gluster|vdsm|libvirt' |sort
glusterfs-3.6.7-1.el7.x86_64
glusterfs-api-3.6.7-1.el7.x86_64
glusterfs-cli-3.6.7-1.el7.x86_64
glusterfs-fuse-3.6.7-1.el7.x86_64
glusterfs-libs-3.6.7-1.el7.x86_64
glusterfs-rdma-3.6.7-1.el7.x86_64
libvirt-client-1.2.8-16.el7_1.5.x86_64
libvirt-daemon-1.2.8-16.el7_1.5.x86_64
libvirt-daemon-config-nwfilter-1.2.8-16.el7_1.5.x86_64
libvirt-daemon-driver-interface-1.2.8-16.el7_1.5.x86_64
libvirt-daemon-driver-network-1.2.8-16.el7_1.5.x86_64
libvirt-daemon-driver-nodedev-1.2.8-16.el7_1.5.x86_64
libvirt-daemon-driver-nwfilter-1.2.8-16.el7_1.5.x86_64
libvirt-daemon-driver-qemu-1.2.8-16.el7_1.5.x86_64
libvirt-daemon-driver-secret-1.2.8-16.el7_1.5.x86_64
libvirt-daemon-driver-storage-1.2.8-16.el7_1.5.x86_64
libvirt-daemon-kvm-1.2.8-16.el7_1.5.x86_64
libvirt-lock-sanlock-1.2.8-16.el7_1.5.x86_64
libvirt-python-1.2.8-7.el7_1.1.x86_64
vdsm-4.16.30-0.el7.centos.x86_64
vdsm-cli-4.16.30-0.el7.centos.noarch
vdsm-jsonrpc-4.16.30-0.el7.centos.noarch
vdsm-python-4.16.30-0.el7.centos.noarch
vdsm-python-zombiereaper-4.16.30-0.el7.centos.noarch
vdsm-xmlrpc-4.16.30-0.el7.centos.noarch
vdsm-yajsonrpc-4.16.30-0.el7.centos.noarch
VM's were in a paused state, with errors in UI:
2015-Dec-22, 15:06
VM pcic-apps has paused due to unknown storage error.
2015-Dec-22, 15:06
Host compute2 is not responding. It will stay in Connecting state for
a grace period of 82 seconds and after that an attempt to fence the
host will be issued.
2015-Dec-22, 15:03
Invalid status on Data Center EDC2. Setting Data Center status to Non
Responsive (On host compute2, Error: General Exception).
2015-Dec-22, 15:03
VM pcic-storage has paused due to unknown storage error.
2015-Dec-22, 15:03
VM docker1 has paused due to unknown storage error.
VDSM logs look normal until:
Dummy-99::DEBUG::2015-12-22
23:03:58,949::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail)
dd if=/rhev/data-center/f72ec125-69a1-4c1b-a5e1-313fcb70b6ff/mastersd/dom_md/inbox
iflag=direct,fullblock count=1 bs=1024000 (cwd None)
Dummy-99::DEBUG::2015-12-22
23:03:58,963::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail)
SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0
MB) copied, 0.00350501 s, 292 MB/s\n'; <rc> = 0
VM Channels Listener::INFO::2015-12-22
23:03:59,527::guestagent::180::vm.Vm::(_handleAPIVersion)
vmId=`7067679e-43aa-43c0-b263-b0a711ade2e2`::Guest API version changed
from 2 to 1
Thread-245428::DEBUG::2015-12-22
23:03:59,718::libvirtconnection::151::root::(wrapper) Unknown
libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found:
Requested metadata element is not present
libvirtEventLoop::INFO::2015-12-22
23:04:00,447::vm::4982::vm.Vm::(_onIOError)
vmId=`376e98b7-7798-46e8-be03-5dddf6cfb54f`::abnormal vm stop device
virtio-disk0 error eother
libvirtEventLoop::DEBUG::2015-12-22
23:04:00,447::vm::5666::vm.Vm::(_onLibvirtLifecycleEvent)
vmId=`376e98b7-7798-46e8-be03-5dddf6cfb54f`::event Suspended detail 2
opaque None
libvirtEventLoop::INFO::2015-12-22
23:04:00,447::vm::4982::vm.Vm::(_onIOError)
vmId=`376e98b7-7798-46e8-be03-5dddf6cfb54f`::abnormal vm stop device
virtio-disk0 error eother
...
libvirtEventLoop::INFO::2015-12-22
23:04:00,843::vm::4982::vm.Vm::(_onIOError)
vmId=`97fbbf97-944b-4b77-b0bf-6a831f9090d8`::abnormal vm stop device
virtio-disk1 error eother
libvirtEventLoop::DEBUG::2015-12-22
23:04:00,844::vm::5666::vm.Vm::(_onLibvirtLifecycleEvent)
vmId=`97fbbf97-944b-4b77-b0bf-6a831f9090d8`::event Suspended detail 2
opaque None
Dummy-99::DEBUG::2015-12-22
23:04:00,973::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail)
dd if=/rhev/data-center/f72ec125-69a1-4c1b-a5e1-313fcb70b6ff/mastersd/dom_md/inbox
iflag=direct,fullblock count=1 bs=1024000 (cwd None)
Dummy-99::DEBUG::2015-12-22
23:04:00,983::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail)
FAILED: <err> = "dd: failed to open
'/rhev/data-center/f72ec125-69a1-4c1b-a5e1-313fcb70b6ff/mastersd/dom_md/inbox':
Transport endpoint is not connected\n"; <rc> = 1
Dummy-99::ERROR::2015-12-22
23:04:00,983::storage_mailbox::787::Storage.MailBox.SpmMailMonitor::(run)
Error checking for mail
Traceback (most recent call last):
File "/usr/share/vdsm/storage/storage_mailbox.py", line 785, in run
self._checkForMail()
File "/usr/share/vdsm/storage/storage_mailbox.py", line 734, in _checkForMail
"Could not read mailbox: %s" % self._inbox)
IOError: [Errno 5] _handleRequests._checkForMail - Could not read
mailbox: /rhev/data-center/f72ec125-69a1-4c1b-a5e1-313fcb70b6ff/mastersd/dom_md/inbox
Dummy-99::DEBUG::2015-12-22
23:04:02,987::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail)
dd if=/rhev/data-center/f72ec125-69a1-4c1b-a5e1-313fcb70b6ff/mastersd/dom_md/inbox
iflag=direct,fullblock count=1 bs=1024000 (cwd None)
Dummy-99::DEBUG::2015-12-22
23:04:02,994::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail)
FAILED: <err> = "dd: failed to open
'/rhev/data-center/f72ec125-69a1-4c1b-a5e1-313fcb70b6ff/mastersd/dom_md/inbox':
Transport endpoint is not connected\n"; <rc> = 1
Dummy-99::ERROR::2015-12-22
23:04:02,994::storage_mailbox::787::Storage.MailBox.SpmMailMonitor::(run)
Error checking for mail
Traceback (most recent call last):
File "/usr/share/vdsm/storage/storage_mailbox.py", line 785, in run
self._checkForMail()
File "/usr/share/vdsm/storage/storage_mailbox.py", line 734, in _checkForMail
"Could not read mailbox: %s" % self._inbox)
IOError: [Errno 5] _handleRequests._checkForMail - Could not read
mailbox: /rhev/data-center/f72ec125-69a1-4c1b-a5e1-313fcb70b6ff/mastersd/dom_md/inbox
Thread-563692::DEBUG::2015-12-22
23:04:03,539::__init__::481::jsonrpc.JsonRpcServer::(_serveRequest)
Calling 'StoragePool.getSpmStatus' in bridge with {u'storagepoolID':
u'f72ec125-69a1-4c1b-a5e1-313fcb70b6ff'}
Thread-563692::DEBUG::2015-12-22
23:04:03,540::task::595::Storage.TaskManager.Task::(_updateState)
Task=`6121360f-af29-48cf-8a8c-957480472a9d`::moving from state init ->
state preparing
Thread-563692::INFO::2015-12-22
23:04:03,540::logUtils::44::dispatcher::(wrapper) Run and protect:
getSpmStatus(spUUID=u'f72ec125-69a1-4c1b-a5e1-313fcb70b6ff',
options=None)
Thread-563692::ERROR::2015-12-22
23:04:03,541::task::866::Storage.TaskManager.Task::(_setError)
Task=`6121360f-af29-48cf-8a8c-957480472a9d`::Unexpected error
Traceback (most recent call last):
File "/usr/share/vdsm/storage/task.py", line 873, in _run
return fn(*args, **kargs)
File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
res = f(*args, **kwargs)
File "/usr/share/vdsm/storage/hsm.py", line 633, in getSpmStatus
status = self._getSpmStatusInfo(pool)
File "/usr/share/vdsm/storage/hsm.py", line 627, in _getSpmStatusInfo
(pool.spmRole,) + pool.getSpmStatus()))
File "/usr/share/vdsm/storage/sp.py", line 126, in getSpmStatus
return self._backend.getSpmStatus()
File "/usr/share/vdsm/storage/spbackends.py", line 416, in getSpmStatus
lVer, spmId = self.masterDomain.inquireClusterLock()
File "/usr/share/vdsm/storage/sd.py", line 515, in inquireClusterLock
return self._clusterLock.inquire()
File "/usr/share/vdsm/storage/clusterlock.py", line 321, in inquire
resource = sanlock.read_resource(self._leasesPath, SDM_LEASE_OFFSET)
SanlockException: (107, 'Sanlock resource read failure', 'Transport
endpoint is not connected')
...
I noticed the gluster mount point was still shown running 'mount' but
when I tried to ls the mount point I got a "transport endpoint is not
connected" error.
I haven't been able to find anything more interested in the logs, and
the journal is blank before the recent host restart.
In the gluster client logs from the host I see:
...
[2015-12-22 22:52:23.238369] W [fuse-bridge.c:1261:fuse_err_cbk]
0-glusterfs-fuse: 31263720: REMOVEXATTR() /__DIRECT_IO_TEST__ => -1
(No dat
a available)
[2015-12-22 22:57:23.778018] W [fuse-bridge.c:1261:fuse_err_cbk]
0-glusterfs-fuse: 31316031: REMOVEXATTR() /__DIRECT_IO_TEST__ => -1
(No dat
a available)
[2015-12-22 23:02:24.376491] W [fuse-bridge.c:1261:fuse_err_cbk]
0-glusterfs-fuse: 31473552: REMOVEXATTR() /__DIRECT_IO_TEST__ => -1
(No dat
a available)
pending frames:
frame : type(1) op(FSTAT)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(0) op(0)
frame : type(0) op(0)
...
frame : type(1) op(READ)
frame : type(0) op(0)
frame : type(1) op(OPEN)
frame : type(1) op(OPEN)
frame : type(1) op(OPEN)
frame : type(1) op(OPEN)
frame : type(0) op(0)
patchset: git://git.gluster.com/glusterfs.git
signal received: 6
time of crash:
2015-12-22 23:04:00
configuration details:
argp 1
backtrace 1
dlfcn 1
libpthread 1
llistxattr 1
setfsid 1
spinlock 1
epoll.h 1
xattr.h 1
st_atim.tv_nsec 1
package-string: glusterfs 3.6.7
/lib64/libglusterfs.so.0(_gf_msg_backtrace_nomem+0xb2)[0x7f0d091f6392]
/lib64/libglusterfs.so.0(gf_print_trace+0x32d)[0x7f0d0920d88d]
/lib64/libc.so.6(+0x35650)[0x7f0d0820f650]
/lib64/libc.so.6(gsignal+0x37)[0x7f0d0820f5d7]
/lib64/libc.so.6(abort+0x148)[0x7f0d08210cc8]
/lib64/libc.so.6(+0x75e07)[0x7f0d0824fe07]
/lib64/libc.so.6(+0x7d1fd)[0x7f0d082571fd]
/usr/lib64/glusterfs/3.6.7/xlator/protocol/client.so(client_local_wipe+0x39)[0x7f0cfe8acdf9]
/usr/lib64/glusterfs/3.6.7/xlator/protocol/client.so(client3_3_readv_cbk+0x487)[0x7f0cfe8c1197]
/lib64/libgfrpc.so.0(rpc_clnt_handle_reply+0x90)[0x7f0d08fca100]
/lib64/libgfrpc.so.0(rpc_clnt_notify+0x174)[0x7f0d08fca374]
/lib64/libgfrpc.so.0(rpc_transport_notify+0x23)[0x7f0d08fc62c3]
/usr/lib64/glusterfs/3.6.7/rpc-transport/socket.so(+0x8790)[0x7f0d047f3790]
/usr/lib64/glusterfs/3.6.7/rpc-transport/socket.so(+0xaf84)[0x7f0d047f5f84]
/lib64/libglusterfs.so.0(+0x767c2)[0x7f0d0924b7c2]
/usr/sbin/glusterfs(main+0x502)[0x7f0d096a0fe2]
/lib64/libc.so.6(__libc_start_main+0xf5)[0x7f0d081fbaf5]
/usr/sbin/glusterfs(+0x6381)[0x7f0d096a1381]
In /var/log/messages:
...
Dec 22 23:00:49 compute2 journal: metadata not found: Requested
metadata element is not present
Dec 22 23:00:59 compute2 journal: metadata not found: Requested
metadata element is not present
Dec 22 23:01:01 compute2 systemd: Created slice user-0.slice.
Dec 22 23:01:01 compute2 systemd: Starting Session 1316 of user root.
Dec 22 23:01:01 compute2 systemd: Started Session 1316 of user root.
Dec 22 23:01:01 compute2 systemd: Failed to reset devices.list on
/machine.slice: Invalid argument
Dec 22 23:01:03 compute2 journal: metadata not found: Requested
metadata element is not present
...
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: pending
frames:
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: frame :
type(1) op(FSTAT)
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: frame :
type(1) op(READ)
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: frame :
type(1) op(READ)
...
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: frame :
type(1) op(OPEN)
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: frame :
type(0) op(0)
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]:
patchset: git://git.gluster.com/glusterfs.git
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: signal
received: 6
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: time of
crash:
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]:
2015-12-22 23:04:00
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]:
configuration details:
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: argp 1
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]:
backtrace 1
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: dlfcn 1
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]:
libpthread 1
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]:
llistxattr 1
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: setfsid
1
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]:
spinlock 1
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: epoll.h
1
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: xattr.h
1
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]:
st_atim.tv_nsec 1
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]:
package-string: glusterfs 3.6.7
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]:
---------
Dec 22 23:04:03 compute2 sanlock[944]: 2015-12-22 23:04:03+0000 944341
[948]: open error -107
/rhev/data-center/mnt/glusterSD/10.0.231.50:_vm-storage/a5a83df1-47e2-4927-9add-079199ca7ef8/dom_md/leases
Dec 22 23:04:03 compute2 sanlock[944]: 2015-12-22 23:04:03+0000 944342
[944]: ci 8 fd 17 pid -1 recv errno 104
Dec 22 23:04:03 compute2 sanlock[944]: 2015-12-22 23:04:03+0000 944342
[949]: open error -107
/rhev/data-center/mnt/glusterSD/10.0.231.50:_vm-storage/a5a83df1-47e2-4927-9add-079199ca7ef8/dom_md/leases
Dec 22 23:04:03 compute2 sanlock[944]: 2015-12-22 23:04:03+0000 944342
[944]: ci 9 fd 18 pid -1 recv errno 104
Dec 22 23:04:03 compute2 sanlock[944]: 2015-12-22 23:04:03+0000 944342
[948]: open error -1
/rhev/data-center/mnt/glusterSD/10.0.231.50:_vm-storage/a5a83df1-47e2-4927-9add-079199ca7ef8/dom_md/leases
Dec 22 23:04:03 compute2 sanlock[944]: 2015-12-22 23:04:03+0000 944342
[948]: r1 release_token open error -107
Dec 22 23:04:03 compute2 journal: vdsm root ERROR Panic: Unrecoverable
errors during SPM stop process.
Traceback (most recent call last):
File "/usr/share/vdsm/storage/sp.py", line 414, in stopSpm
self.masterDomain.releaseClusterLock()
File "/usr/share/vdsm/storage/sd.py", line 512, in releaseClusterLock
self._clusterLock.release()
File "/usr/share/vdsm/storage/clusterlock.py", line 342, in release
raise se.ReleaseLockFailure(self._sdUUID, e)
ReleaseLockFailure: Cannot release lock:
(u'a5a83df1-47e2-4927-9add-079199ca7ef8', SanlockException(107,
'Sanlock resource not released', 'Transport endpoint is not
connected'))
Dec 22 23:04:03 compute2 journal: End of file while reading data:
Input/output error
Dec 22 23:04:03 compute2 journal: End of file while reading data:
Input/output error
Dec 22 23:04:03 compute2 systemd: vdsmd.service: main process exited,
code=killed, status=9/KILL
Dec 22 23:04:03 compute2 systemd: Failed to reset devices.list on
/machine.slice: Invalid argument
Dec 22 23:04:03 compute2 vdsmd_init_common.sh: vdsm: Running run_final_hooks
Dec 22 23:04:03 compute2 systemd: Unit vdsmd.service entered failed state.
Dec 22 23:04:03 compute2 systemd: vdsmd.service holdoff time over,
scheduling restart.
Dec 22 23:04:03 compute2 systemd: Stopping Virtual Desktop Server Manager...
Dec 22 23:04:03 compute2 systemd: Starting Virtual Desktop Server Manager...
Dec 22 23:04:03 compute2 systemd: Failed to reset devices.list on
/machine.slice: Invalid argument
At this point I tried restarting vdsmd but ended up having to restart
the host. There was network connectivity to gluster before I
restarted, and I was able to manually mount the vm-storage volume on
the host and ls without issue.
After restarting the host I'm up and running again but I'm sure I'll
get hit by this again if I can't sort out what the issue is.
7:14 a.m.
[+ Ravi, Pranith]
On 12/23/2015 06:00 AM, Steve Dainard wrote:
I have two hosts, only one of them was running VM's at the time
of
this crash so I can't tell if this is a node specific problem.
rpm -qa | egrep -i 'gluster|vdsm|libvirt' |sort
glusterfs-3.6.7-1.el7.x86_64
glusterfs-api-3.6.7-1.el7.x86_64
glusterfs-cli-3.6.7-1.el7.x86_64
glusterfs-fuse-3.6.7-1.el7.x86_64
glusterfs-libs-3.6.7-1.el7.x86_64
glusterfs-rdma-3.6.7-1.el7.x86_64
libvirt-client-1.2.8-16.el7_1.5.x86_64
libvirt-daemon-1.2.8-16.el7_1.5.x86_64
libvirt-daemon-config-nwfilter-1.2.8-16.el7_1.5.x86_64
libvirt-daemon-driver-interface-1.2.8-16.el7_1.5.x86_64
libvirt-daemon-driver-network-1.2.8-16.el7_1.5.x86_64
libvirt-daemon-driver-nodedev-1.2.8-16.el7_1.5.x86_64
libvirt-daemon-driver-nwfilter-1.2.8-16.el7_1.5.x86_64
libvirt-daemon-driver-qemu-1.2.8-16.el7_1.5.x86_64
libvirt-daemon-driver-secret-1.2.8-16.el7_1.5.x86_64
libvirt-daemon-driver-storage-1.2.8-16.el7_1.5.x86_64
libvirt-daemon-kvm-1.2.8-16.el7_1.5.x86_64
libvirt-lock-sanlock-1.2.8-16.el7_1.5.x86_64
libvirt-python-1.2.8-7.el7_1.1.x86_64
vdsm-4.16.30-0.el7.centos.x86_64
vdsm-cli-4.16.30-0.el7.centos.noarch
vdsm-jsonrpc-4.16.30-0.el7.centos.noarch
vdsm-python-4.16.30-0.el7.centos.noarch
vdsm-python-zombiereaper-4.16.30-0.el7.centos.noarch
vdsm-xmlrpc-4.16.30-0.el7.centos.noarch
vdsm-yajsonrpc-4.16.30-0.el7.centos.noarch
VM's were in a paused state, with errors in UI:
2015-Dec-22, 15:06
VM pcic-apps has paused due to unknown storage error.
2015-Dec-22, 15:06
Host compute2 is not responding. It will stay in Connecting state for
a grace period of 82 seconds and after that an attempt to fence the
host will be issued.
2015-Dec-22, 15:03
Invalid status on Data Center EDC2. Setting Data Center status to Non
Responsive (On host compute2, Error: General Exception).
2015-Dec-22, 15:03
VM pcic-storage has paused due to unknown storage error.
2015-Dec-22, 15:03
VM docker1 has paused due to unknown storage error.
VDSM logs look normal until:
Dummy-99::DEBUG::2015-12-22
23:03:58,949::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail)
dd if=/rhev/data-center/f72ec125-69a1-4c1b-a5e1-313fcb70b6ff/mastersd/dom_md/inbox
iflag=direct,fullblock count=1 bs=1024000 (cwd None)
Dummy-99::DEBUG::2015-12-22
23:03:58,963::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail)
SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0
MB) copied, 0.00350501 s, 292 MB/s\n'; <rc> = 0
VM Channels Listener::INFO::2015-12-22
23:03:59,527::guestagent::180::vm.Vm::(_handleAPIVersion)
vmId=`7067679e-43aa-43c0-b263-b0a711ade2e2`::Guest API version changed
from 2 to 1
Thread-245428::DEBUG::2015-12-22
23:03:59,718::libvirtconnection::151::root::(wrapper) Unknown
libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found:
Requested metadata element is not present
libvirtEventLoop::INFO::2015-12-22
23:04:00,447::vm::4982::vm.Vm::(_onIOError)
vmId=`376e98b7-7798-46e8-be03-5dddf6cfb54f`::abnormal vm stop device
virtio-disk0 error eother
libvirtEventLoop::DEBUG::2015-12-22
23:04:00,447::vm::5666::vm.Vm::(_onLibvirtLifecycleEvent)
vmId=`376e98b7-7798-46e8-be03-5dddf6cfb54f`::event Suspended detail 2
opaque None
libvirtEventLoop::INFO::2015-12-22
23:04:00,447::vm::4982::vm.Vm::(_onIOError)
vmId=`376e98b7-7798-46e8-be03-5dddf6cfb54f`::abnormal vm stop device
virtio-disk0 error eother
...
libvirtEventLoop::INFO::2015-12-22
23:04:00,843::vm::4982::vm.Vm::(_onIOError)
vmId=`97fbbf97-944b-4b77-b0bf-6a831f9090d8`::abnormal vm stop device
virtio-disk1 error eother
libvirtEventLoop::DEBUG::2015-12-22
23:04:00,844::vm::5666::vm.Vm::(_onLibvirtLifecycleEvent)
vmId=`97fbbf97-944b-4b77-b0bf-6a831f9090d8`::event Suspended detail 2
opaque None
Dummy-99::DEBUG::2015-12-22
23:04:00,973::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail)
dd if=/rhev/data-center/f72ec125-69a1-4c1b-a5e1-313fcb70b6ff/mastersd/dom_md/inbox
iflag=direct,fullblock count=1 bs=1024000 (cwd None)
Dummy-99::DEBUG::2015-12-22
23:04:00,983::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail)
FAILED: <err> = "dd: failed to open
'/rhev/data-center/f72ec125-69a1-4c1b-a5e1-313fcb70b6ff/mastersd/dom_md/inbox':
Transport endpoint is not connected\n"; <rc> = 1
Dummy-99::ERROR::2015-12-22
23:04:00,983::storage_mailbox::787::Storage.MailBox.SpmMailMonitor::(run)
Error checking for mail
Traceback (most recent call last):
File "/usr/share/vdsm/storage/storage_mailbox.py", line 785, in run
self._checkForMail()
File "/usr/share/vdsm/storage/storage_mailbox.py", line 734, in
_checkForMail
"Could not read mailbox: %s" % self._inbox)
IOError: [Errno 5] _handleRequests._checkForMail - Could not read
mailbox: /rhev/data-center/f72ec125-69a1-4c1b-a5e1-313fcb70b6ff/mastersd/dom_md/inbox
Dummy-99::DEBUG::2015-12-22
23:04:02,987::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail)
dd if=/rhev/data-center/f72ec125-69a1-4c1b-a5e1-313fcb70b6ff/mastersd/dom_md/inbox
iflag=direct,fullblock count=1 bs=1024000 (cwd None)
Dummy-99::DEBUG::2015-12-22
23:04:02,994::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail)
FAILED: <err> = "dd: failed to open
'/rhev/data-center/f72ec125-69a1-4c1b-a5e1-313fcb70b6ff/mastersd/dom_md/inbox':
Transport endpoint is not connected\n"; <rc> = 1
Dummy-99::ERROR::2015-12-22
23:04:02,994::storage_mailbox::787::Storage.MailBox.SpmMailMonitor::(run)
Error checking for mail
Traceback (most recent call last):
File "/usr/share/vdsm/storage/storage_mailbox.py", line 785, in run
self._checkForMail()
File "/usr/share/vdsm/storage/storage_mailbox.py", line 734, in
_checkForMail
"Could not read mailbox: %s" % self._inbox)
IOError: [Errno 5] _handleRequests._checkForMail - Could not read
mailbox: /rhev/data-center/f72ec125-69a1-4c1b-a5e1-313fcb70b6ff/mastersd/dom_md/inbox
Thread-563692::DEBUG::2015-12-22
23:04:03,539::__init__::481::jsonrpc.JsonRpcServer::(_serveRequest)
Calling 'StoragePool.getSpmStatus' in bridge with {u'storagepoolID':
u'f72ec125-69a1-4c1b-a5e1-313fcb70b6ff'}
Thread-563692::DEBUG::2015-12-22
23:04:03,540::task::595::Storage.TaskManager.Task::(_updateState)
Task=`6121360f-af29-48cf-8a8c-957480472a9d`::moving from state init ->
state preparing
Thread-563692::INFO::2015-12-22
23:04:03,540::logUtils::44::dispatcher::(wrapper) Run and protect:
getSpmStatus(spUUID=u'f72ec125-69a1-4c1b-a5e1-313fcb70b6ff',
options=None)
Thread-563692::ERROR::2015-12-22
23:04:03,541::task::866::Storage.TaskManager.Task::(_setError)
Task=`6121360f-af29-48cf-8a8c-957480472a9d`::Unexpected error
Traceback (most recent call last):
File "/usr/share/vdsm/storage/task.py", line 873, in _run
return fn(*args, **kargs)
File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
res = f(*args, **kwargs)
File "/usr/share/vdsm/storage/hsm.py", line 633, in getSpmStatus
status = self._getSpmStatusInfo(pool)
File "/usr/share/vdsm/storage/hsm.py", line 627, in _getSpmStatusInfo
(pool.spmRole,) + pool.getSpmStatus()))
File "/usr/share/vdsm/storage/sp.py", line 126, in getSpmStatus
return self._backend.getSpmStatus()
File "/usr/share/vdsm/storage/spbackends.py", line 416, in getSpmStatus
lVer, spmId = self.masterDomain.inquireClusterLock()
File "/usr/share/vdsm/storage/sd.py", line 515, in inquireClusterLock
return self._clusterLock.inquire()
File "/usr/share/vdsm/storage/clusterlock.py", line 321, in inquire
resource = sanlock.read_resource(self._leasesPath, SDM_LEASE_OFFSET)
SanlockException: (107, 'Sanlock resource read failure', 'Transport
endpoint is not connected')
...
I noticed the gluster mount point was still shown running 'mount' but
when I tried to ls the mount point I got a "transport endpoint is not
connected" error.
I haven't been able to find anything more interested in the logs, and
the journal is blank before the recent host restart.
In the gluster client logs from the host I see:
...
[2015-12-22 22:52:23.238369] W [fuse-bridge.c:1261:fuse_err_cbk]
0-glusterfs-fuse: 31263720: REMOVEXATTR() /__DIRECT_IO_TEST__ => -1
(No dat
a available)
[2015-12-22 22:57:23.778018] W [fuse-bridge.c:1261:fuse_err_cbk]
0-glusterfs-fuse: 31316031: REMOVEXATTR() /__DIRECT_IO_TEST__ => -1
(No dat
a available)
[2015-12-22 23:02:24.376491] W [fuse-bridge.c:1261:fuse_err_cbk]
0-glusterfs-fuse: 31473552: REMOVEXATTR() /__DIRECT_IO_TEST__ => -1
(No dat
a available)
pending frames:
frame : type(1) op(FSTAT)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(1) op(READ)
frame : type(0) op(0)
frame : type(0) op(0)
...
frame : type(1) op(READ)
frame : type(0) op(0)
frame : type(1) op(OPEN)
frame : type(1) op(OPEN)
frame : type(1) op(OPEN)
frame : type(1) op(OPEN)
frame : type(0) op(0)
patchset: git://git.gluster.com/glusterfs.git
signal received: 6
time of crash:
2015-12-22 23:04:00
configuration details:
argp 1
backtrace 1
dlfcn 1
libpthread 1
llistxattr 1
setfsid 1
spinlock 1
epoll.h 1
xattr.h 1
st_atim.tv_nsec 1
package-string: glusterfs 3.6.7
/lib64/libglusterfs.so.0(_gf_msg_backtrace_nomem+0xb2)[0x7f0d091f6392]
/lib64/libglusterfs.so.0(gf_print_trace+0x32d)[0x7f0d0920d88d]
/lib64/libc.so.6(+0x35650)[0x7f0d0820f650]
/lib64/libc.so.6(gsignal+0x37)[0x7f0d0820f5d7]
/lib64/libc.so.6(abort+0x148)[0x7f0d08210cc8]
/lib64/libc.so.6(+0x75e07)[0x7f0d0824fe07]
/lib64/libc.so.6(+0x7d1fd)[0x7f0d082571fd]
/usr/lib64/glusterfs/3.6.7/xlator/protocol/client.so(client_local_wipe+0x39)[0x7f0cfe8acdf9]
/usr/lib64/glusterfs/3.6.7/xlator/protocol/client.so(client3_3_readv_cbk+0x487)[0x7f0cfe8c1197]
/lib64/libgfrpc.so.0(rpc_clnt_handle_reply+0x90)[0x7f0d08fca100]
/lib64/libgfrpc.so.0(rpc_clnt_notify+0x174)[0x7f0d08fca374]
/lib64/libgfrpc.so.0(rpc_transport_notify+0x23)[0x7f0d08fc62c3]
/usr/lib64/glusterfs/3.6.7/rpc-transport/socket.so(+0x8790)[0x7f0d047f3790]
/usr/lib64/glusterfs/3.6.7/rpc-transport/socket.so(+0xaf84)[0x7f0d047f5f84]
/lib64/libglusterfs.so.0(+0x767c2)[0x7f0d0924b7c2]
/usr/sbin/glusterfs(main+0x502)[0x7f0d096a0fe2]
/lib64/libc.so.6(__libc_start_main+0xf5)[0x7f0d081fbaf5]
/usr/sbin/glusterfs(+0x6381)[0x7f0d096a1381]
Could you provide the gluster mount logs from the client, and the
gluster brick logs from the gluster servers?
In /var/log/messages:
...
Dec 22 23:00:49 compute2 journal: metadata not found: Requested
metadata element is not present
Dec 22 23:00:59 compute2 journal: metadata not found: Requested
metadata element is not present
Dec 22 23:01:01 compute2 systemd: Created slice user-0.slice.
Dec 22 23:01:01 compute2 systemd: Starting Session 1316 of user root.
Dec 22 23:01:01 compute2 systemd: Started Session 1316 of user root.
Dec 22 23:01:01 compute2 systemd: Failed to reset devices.list on
/machine.slice: Invalid argument
Dec 22 23:01:03 compute2 journal: metadata not found: Requested
metadata element is not present
...
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: pending
frames:
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: frame :
type(1) op(FSTAT)
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: frame :
type(1) op(READ)
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: frame :
type(1) op(READ)
...
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: frame :
type(1) op(OPEN)
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: frame :
type(0) op(0)
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]:
patchset: git://git.gluster.com/glusterfs.git
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: signal
received: 6
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: time of
crash:
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]:
2015-12-22 23:04:00
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]:
configuration details:
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: argp 1
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]:
backtrace 1
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: dlfcn 1
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]:
libpthread 1
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]:
llistxattr 1
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: setfsid
1
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]:
spinlock 1
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: epoll.h
1
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: xattr.h
1
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]:
st_atim.tv_nsec 1
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]:
package-string: glusterfs 3.6.7
Dec 22 23:04:00 compute2
rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]:
---------
Dec 22 23:04:03 compute2 sanlock[944]: 2015-12-22 23:04:03+0000 944341
[948]: open error -107
/rhev/data-center/mnt/glusterSD/10.0.231.50:_vm-storage/a5a83df1-47e2-4927-9add-079199ca7ef8/dom_md/leases
Dec 22 23:04:03 compute2 sanlock[944]: 2015-12-22 23:04:03+0000 944342
[944]: ci 8 fd 17 pid -1 recv errno 104
Dec 22 23:04:03 compute2 sanlock[944]: 2015-12-22 23:04:03+0000 944342
[949]: open error -107
/rhev/data-center/mnt/glusterSD/10.0.231.50:_vm-storage/a5a83df1-47e2-4927-9add-079199ca7ef8/dom_md/leases
Dec 22 23:04:03 compute2 sanlock[944]: 2015-12-22 23:04:03+0000 944342
[944]: ci 9 fd 18 pid -1 recv errno 104
Dec 22 23:04:03 compute2 sanlock[944]: 2015-12-22 23:04:03+0000 944342
[948]: open error -1
/rhev/data-center/mnt/glusterSD/10.0.231.50:_vm-storage/a5a83df1-47e2-4927-9add-079199ca7ef8/dom_md/leases
Dec 22 23:04:03 compute2 sanlock[944]: 2015-12-22 23:04:03+0000 944342
[948]: r1 release_token open error -107
Dec 22 23:04:03 compute2 journal: vdsm root ERROR Panic: Unrecoverable
errors during SPM stop process.
Traceback (most recent call last):
File "/usr/share/vdsm/storage/sp.py", line 414, in stopSpm
self.masterDomain.releaseClusterLock()
File "/usr/share/vdsm/storage/sd.py", line 512, in releaseClusterLock
self._clusterLock.release()
File "/usr/share/vdsm/storage/clusterlock.py", line 342, in release
raise se.ReleaseLockFailure(self._sdUUID, e)
ReleaseLockFailure: Cannot release lock:
(u'a5a83df1-47e2-4927-9add-079199ca7ef8', SanlockException(107,
'Sanlock resource not released', 'Transport endpoint is not
connected'))
Dec 22 23:04:03 compute2 journal: End of file while reading data:
Input/output error
Dec 22 23:04:03 compute2 journal: End of file while reading data:
Input/output error
Dec 22 23:04:03 compute2 systemd: vdsmd.service: main process exited,
code=killed, status=9/KILL
Dec 22 23:04:03 compute2 systemd: Failed to reset devices.list on
/machine.slice: Invalid argument
Dec 22 23:04:03 compute2 vdsmd_init_common.sh: vdsm: Running run_final_hooks
Dec 22 23:04:03 compute2 systemd: Unit vdsmd.service entered failed state.
Dec 22 23:04:03 compute2 systemd: vdsmd.service holdoff time over,
scheduling restart.
Dec 22 23:04:03 compute2 systemd: Stopping Virtual Desktop Server Manager...
Dec 22 23:04:03 compute2 systemd: Starting Virtual Desktop Server Manager...
Dec 22 23:04:03 compute2 systemd: Failed to reset devices.list on
/machine.slice: Invalid argument
At this point I tried restarting vdsmd but ended up having to restart
the host. There was network connectivity to gluster before I
restarted, and I was able to manually mount the vm-storage volume on
the host and ls without issue.
After restarting the host I'm up and running again but I'm sure I'll
get hit by this again if I can't sort out what the issue is.
_______________________________________________
Users mailing list
Users(a)ovirt.org
http://lists.ovirt.org/mailman/listinfo/users
10:22 a.m.
On 12/23/2015 11:44 AM, Sahina Bose wrote:
> signal received: 6
> time of crash:
> 2015-12-22 23:04:00
> configuration details:
> argp 1
> backtrace 1
> dlfcn 1
> libpthread 1
> llistxattr 1
> setfsid 1
> spinlock 1
> epoll.h 1
> xattr.h 1
> st_atim.tv_nsec 1
> package-string: glusterfs 3.6.7
> /lib64/libglusterfs.so.0(_gf_msg_backtrace_nomem+0xb2)[0x7f0d091f6392]
> /lib64/libglusterfs.so.0(gf_print_trace+0x32d)[0x7f0d0920d88d]
> /lib64/libc.so.6(+0x35650)[0x7f0d0820f650]
> /lib64/libc.so.6(gsignal+0x37)[0x7f0d0820f5d7]
> /lib64/libc.so.6(abort+0x148)[0x7f0d08210cc8]
> /lib64/libc.so.6(+0x75e07)[0x7f0d0824fe07]
> /lib64/libc.so.6(+0x7d1fd)[0x7f0d082571fd]
>
/usr/lib64/glusterfs/3.6.7/xlator/protocol/client.so(client_local_wipe+0x39)[0x7f0cfe8acdf9]
>
>
/usr/lib64/glusterfs/3.6.7/xlator/protocol/client.so(client3_3_readv_cbk+0x487)[0x7f0cfe8c1197]
>
> /lib64/libgfrpc.so.0(rpc_clnt_handle_reply+0x90)[0x7f0d08fca100]
> /lib64/libgfrpc.so.0(rpc_clnt_notify+0x174)[0x7f0d08fca374]
> /lib64/libgfrpc.so.0(rpc_transport_notify+0x23)[0x7f0d08fc62c3]
> /usr/lib64/glusterfs/3.6.7/rpc-transport/socket.so(+0x8790)[0x7f0d047f3790]
>
> /usr/lib64/glusterfs/3.6.7/rpc-transport/socket.so(+0xaf84)[0x7f0d047f5f84]
>
> /lib64/libglusterfs.so.0(+0x767c2)[0x7f0d0924b7c2]
> /usr/sbin/glusterfs(main+0x502)[0x7f0d096a0fe2]
> /lib64/libc.so.6(__libc_start_main+0xf5)[0x7f0d081fbaf5]
> /usr/sbin/glusterfs(+0x6381)[0x7f0d096a1381]
Could you provide the gluster mount logs from the client, and the
gluster brick logs from the gluster servers?
Also, do you have a core file of the
crash?
-Ravi
6:30 p.m.
I've attached the client gluster log starting at the first log of the
same day as failure.
The brick logs are all 0 file size on all of the replica 3 nodes... I
just set 'gluster volume set vm-storage diagnostics.brick-log-level
WARNING' but I'm not immediately seeing any logging to disk.
I've also attached the compute1 vdsm.log file, which over the same
time period is able to dd successfully so perhaps this discounts a
storage side issue? I've also attached compute2 (failed node) for
comparison.
Ravi - I'm not familiar with core files, would this be in a non-devel
version of gluster? Or is this something I can enable? I don't mind
enabling it now if it could help diagnose a future issue.
On Tue, Dec 22, 2015 at 10:14 PM, Sahina Bose <sabose(a)redhat.com> wrote:
[+ Ravi, Pranith]
On 12/23/2015 06:00 AM, Steve Dainard wrote:
>
> I have two hosts, only one of them was running VM's at the time of
> this crash so I can't tell if this is a node specific problem.
>
> rpm -qa | egrep -i 'gluster|vdsm|libvirt' |sort
> glusterfs-3.6.7-1.el7.x86_64
> glusterfs-api-3.6.7-1.el7.x86_64
> glusterfs-cli-3.6.7-1.el7.x86_64
> glusterfs-fuse-3.6.7-1.el7.x86_64
> glusterfs-libs-3.6.7-1.el7.x86_64
> glusterfs-rdma-3.6.7-1.el7.x86_64
> libvirt-client-1.2.8-16.el7_1.5.x86_64
> libvirt-daemon-1.2.8-16.el7_1.5.x86_64
> libvirt-daemon-config-nwfilter-1.2.8-16.el7_1.5.x86_64
> libvirt-daemon-driver-interface-1.2.8-16.el7_1.5.x86_64
> libvirt-daemon-driver-network-1.2.8-16.el7_1.5.x86_64
> libvirt-daemon-driver-nodedev-1.2.8-16.el7_1.5.x86_64
> libvirt-daemon-driver-nwfilter-1.2.8-16.el7_1.5.x86_64
> libvirt-daemon-driver-qemu-1.2.8-16.el7_1.5.x86_64
> libvirt-daemon-driver-secret-1.2.8-16.el7_1.5.x86_64
> libvirt-daemon-driver-storage-1.2.8-16.el7_1.5.x86_64
> libvirt-daemon-kvm-1.2.8-16.el7_1.5.x86_64
> libvirt-lock-sanlock-1.2.8-16.el7_1.5.x86_64
> libvirt-python-1.2.8-7.el7_1.1.x86_64
> vdsm-4.16.30-0.el7.centos.x86_64
> vdsm-cli-4.16.30-0.el7.centos.noarch
> vdsm-jsonrpc-4.16.30-0.el7.centos.noarch
> vdsm-python-4.16.30-0.el7.centos.noarch
> vdsm-python-zombiereaper-4.16.30-0.el7.centos.noarch
> vdsm-xmlrpc-4.16.30-0.el7.centos.noarch
> vdsm-yajsonrpc-4.16.30-0.el7.centos.noarch
>
> VM's were in a paused state, with errors in UI:
>
> 2015-Dec-22, 15:06
> VM pcic-apps has paused due to unknown storage error.
> 2015-Dec-22, 15:06
> Host compute2 is not responding. It will stay in Connecting state for
> a grace period of 82 seconds and after that an attempt to fence the
> host will be issued.
> 2015-Dec-22, 15:03
> Invalid status on Data Center EDC2. Setting Data Center status to Non
> Responsive (On host compute2, Error: General Exception).
> 2015-Dec-22, 15:03
> VM pcic-storage has paused due to unknown storage error.
> 2015-Dec-22, 15:03
> VM docker1 has paused due to unknown storage error.
>
> VDSM logs look normal until:
> Dummy-99::DEBUG::2015-12-22
> 23:03:58,949::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail)
> dd
> if=/rhev/data-center/f72ec125-69a1-4c1b-a5e1-313fcb70b6ff/mastersd/dom_md/inbox
> iflag=direct,fullblock count=1 bs=1024000 (cwd None)
> Dummy-99::DEBUG::2015-12-22
> 23:03:58,963::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail)
> SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0
> MB) copied, 0.00350501 s, 292 MB/s\n'; <rc> = 0
> VM Channels Listener::INFO::2015-12-22
> 23:03:59,527::guestagent::180::vm.Vm::(_handleAPIVersion)
> vmId=`7067679e-43aa-43c0-b263-b0a711ade2e2`::Guest API version changed
> from 2 to 1
> Thread-245428::DEBUG::2015-12-22
> 23:03:59,718::libvirtconnection::151::root::(wrapper) Unknown
> libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found:
> Requested metadata element is not present
> libvirtEventLoop::INFO::2015-12-22
> 23:04:00,447::vm::4982::vm.Vm::(_onIOError)
> vmId=`376e98b7-7798-46e8-be03-5dddf6cfb54f`::abnormal vm stop device
> virtio-disk0 error eother
> libvirtEventLoop::DEBUG::2015-12-22
> 23:04:00,447::vm::5666::vm.Vm::(_onLibvirtLifecycleEvent)
> vmId=`376e98b7-7798-46e8-be03-5dddf6cfb54f`::event Suspended detail 2
> opaque None
> libvirtEventLoop::INFO::2015-12-22
> 23:04:00,447::vm::4982::vm.Vm::(_onIOError)
> vmId=`376e98b7-7798-46e8-be03-5dddf6cfb54f`::abnormal vm stop device
> virtio-disk0 error eother
> ...
> libvirtEventLoop::INFO::2015-12-22
> 23:04:00,843::vm::4982::vm.Vm::(_onIOError)
> vmId=`97fbbf97-944b-4b77-b0bf-6a831f9090d8`::abnormal vm stop device
> virtio-disk1 error eother
> libvirtEventLoop::DEBUG::2015-12-22
> 23:04:00,844::vm::5666::vm.Vm::(_onLibvirtLifecycleEvent)
> vmId=`97fbbf97-944b-4b77-b0bf-6a831f9090d8`::event Suspended detail 2
> opaque None
> Dummy-99::DEBUG::2015-12-22
> 23:04:00,973::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail)
> dd
> if=/rhev/data-center/f72ec125-69a1-4c1b-a5e1-313fcb70b6ff/mastersd/dom_md/inbox
> iflag=direct,fullblock count=1 bs=1024000 (cwd None)
> Dummy-99::DEBUG::2015-12-22
> 23:04:00,983::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail)
> FAILED: <err> = "dd: failed to open
>
>
'/rhev/data-center/f72ec125-69a1-4c1b-a5e1-313fcb70b6ff/mastersd/dom_md/inbox':
> Transport endpoint is not connected\n"; <rc> = 1
> Dummy-99::ERROR::2015-12-22
> 23:04:00,983::storage_mailbox::787::Storage.MailBox.SpmMailMonitor::(run)
> Error checking for mail
> Traceback (most recent call last):
> File "/usr/share/vdsm/storage/storage_mailbox.py", line 785, in run
> self._checkForMail()
> File "/usr/share/vdsm/storage/storage_mailbox.py", line 734, in
> _checkForMail
> "Could not read mailbox: %s" % self._inbox)
> IOError: [Errno 5] _handleRequests._checkForMail - Could not read
> mailbox:
> /rhev/data-center/f72ec125-69a1-4c1b-a5e1-313fcb70b6ff/mastersd/dom_md/inbox
> Dummy-99::DEBUG::2015-12-22
> 23:04:02,987::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail)
> dd
> if=/rhev/data-center/f72ec125-69a1-4c1b-a5e1-313fcb70b6ff/mastersd/dom_md/inbox
> iflag=direct,fullblock count=1 bs=1024000 (cwd None)
> Dummy-99::DEBUG::2015-12-22
> 23:04:02,994::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail)
> FAILED: <err> = "dd: failed to open
>
>
'/rhev/data-center/f72ec125-69a1-4c1b-a5e1-313fcb70b6ff/mastersd/dom_md/inbox':
> Transport endpoint is not connected\n"; <rc> = 1
> Dummy-99::ERROR::2015-12-22
> 23:04:02,994::storage_mailbox::787::Storage.MailBox.SpmMailMonitor::(run)
> Error checking for mail
> Traceback (most recent call last):
> File "/usr/share/vdsm/storage/storage_mailbox.py", line 785, in run
> self._checkForMail()
> File "/usr/share/vdsm/storage/storage_mailbox.py", line 734, in
> _checkForMail
> "Could not read mailbox: %s" % self._inbox)
> IOError: [Errno 5] _handleRequests._checkForMail - Could not read
> mailbox:
> /rhev/data-center/f72ec125-69a1-4c1b-a5e1-313fcb70b6ff/mastersd/dom_md/inbox
> Thread-563692::DEBUG::2015-12-22
> 23:04:03,539::__init__::481::jsonrpc.JsonRpcServer::(_serveRequest)
> Calling 'StoragePool.getSpmStatus' in bridge with {u'storagepoolID':
> u'f72ec125-69a1-4c1b-a5e1-313fcb70b6ff'}
> Thread-563692::DEBUG::2015-12-22
> 23:04:03,540::task::595::Storage.TaskManager.Task::(_updateState)
> Task=`6121360f-af29-48cf-8a8c-957480472a9d`::moving from state init ->
> state preparing
> Thread-563692::INFO::2015-12-22
> 23:04:03,540::logUtils::44::dispatcher::(wrapper) Run and protect:
> getSpmStatus(spUUID=u'f72ec125-69a1-4c1b-a5e1-313fcb70b6ff',
> options=None)
> Thread-563692::ERROR::2015-12-22
> 23:04:03,541::task::866::Storage.TaskManager.Task::(_setError)
> Task=`6121360f-af29-48cf-8a8c-957480472a9d`::Unexpected error
> Traceback (most recent call last):
> File "/usr/share/vdsm/storage/task.py", line 873, in _run
> return fn(*args, **kargs)
> File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
> res = f(*args, **kwargs)
> File "/usr/share/vdsm/storage/hsm.py", line 633, in getSpmStatus
> status = self._getSpmStatusInfo(pool)
> File "/usr/share/vdsm/storage/hsm.py", line 627, in _getSpmStatusInfo
> (pool.spmRole,) + pool.getSpmStatus()))
> File "/usr/share/vdsm/storage/sp.py", line 126, in getSpmStatus
> return self._backend.getSpmStatus()
> File "/usr/share/vdsm/storage/spbackends.py", line 416, in getSpmStatus
> lVer, spmId = self.masterDomain.inquireClusterLock()
> File "/usr/share/vdsm/storage/sd.py", line 515, in inquireClusterLock
> return self._clusterLock.inquire()
> File "/usr/share/vdsm/storage/clusterlock.py", line 321, in inquire
> resource = sanlock.read_resource(self._leasesPath, SDM_LEASE_OFFSET)
> SanlockException: (107, 'Sanlock resource read failure', 'Transport
> endpoint is not connected')
> ...
>
> I noticed the gluster mount point was still shown running 'mount' but
> when I tried to ls the mount point I got a "transport endpoint is not
> connected" error.
>
> I haven't been able to find anything more interested in the logs, and
> the journal is blank before the recent host restart.
>
> In the gluster client logs from the host I see:
> ...
> [2015-12-22 22:52:23.238369] W [fuse-bridge.c:1261:fuse_err_cbk]
> 0-glusterfs-fuse: 31263720: REMOVEXATTR() /__DIRECT_IO_TEST__ => -1
> (No dat
> a available)
> [2015-12-22 22:57:23.778018] W [fuse-bridge.c:1261:fuse_err_cbk]
> 0-glusterfs-fuse: 31316031: REMOVEXATTR() /__DIRECT_IO_TEST__ => -1
> (No dat
> a available)
> [2015-12-22 23:02:24.376491] W [fuse-bridge.c:1261:fuse_err_cbk]
> 0-glusterfs-fuse: 31473552: REMOVEXATTR() /__DIRECT_IO_TEST__ => -1
> (No dat
> a available)
> pending frames:
> frame : type(1) op(FSTAT)
> frame : type(1) op(READ)
> frame : type(1) op(READ)
> frame : type(1) op(READ)
> frame : type(1) op(READ)
> frame : type(1) op(READ)
> frame : type(1) op(READ)
> frame : type(1) op(READ)
> frame : type(1) op(READ)
> frame : type(1) op(READ)
> frame : type(1) op(READ)
> frame : type(1) op(READ)
> frame : type(1) op(READ)
> frame : type(1) op(READ)
> frame : type(1) op(READ)
> frame : type(1) op(READ)
> frame : type(1) op(READ)
> frame : type(1) op(READ)
> frame : type(1) op(READ)
> frame : type(0) op(0)
> frame : type(0) op(0)
> ...
> frame : type(1) op(READ)
> frame : type(0) op(0)
> frame : type(1) op(OPEN)
> frame : type(1) op(OPEN)
> frame : type(1) op(OPEN)
> frame : type(1) op(OPEN)
> frame : type(0) op(0)
> patchset: git://git.gluster.com/glusterfs.git
> signal received: 6
> time of crash:
> 2015-12-22 23:04:00
> configuration details:
> argp 1
> backtrace 1
> dlfcn 1
> libpthread 1
> llistxattr 1
> setfsid 1
> spinlock 1
> epoll.h 1
> xattr.h 1
> st_atim.tv_nsec 1
> package-string: glusterfs 3.6.7
> /lib64/libglusterfs.so.0(_gf_msg_backtrace_nomem+0xb2)[0x7f0d091f6392]
> /lib64/libglusterfs.so.0(gf_print_trace+0x32d)[0x7f0d0920d88d]
> /lib64/libc.so.6(+0x35650)[0x7f0d0820f650]
> /lib64/libc.so.6(gsignal+0x37)[0x7f0d0820f5d7]
> /lib64/libc.so.6(abort+0x148)[0x7f0d08210cc8]
> /lib64/libc.so.6(+0x75e07)[0x7f0d0824fe07]
> /lib64/libc.so.6(+0x7d1fd)[0x7f0d082571fd]
>
>
/usr/lib64/glusterfs/3.6.7/xlator/protocol/client.so(client_local_wipe+0x39)[0x7f0cfe8acdf9]
>
>
/usr/lib64/glusterfs/3.6.7/xlator/protocol/client.so(client3_3_readv_cbk+0x487)[0x7f0cfe8c1197]
> /lib64/libgfrpc.so.0(rpc_clnt_handle_reply+0x90)[0x7f0d08fca100]
> /lib64/libgfrpc.so.0(rpc_clnt_notify+0x174)[0x7f0d08fca374]
> /lib64/libgfrpc.so.0(rpc_transport_notify+0x23)[0x7f0d08fc62c3]
>
> /usr/lib64/glusterfs/3.6.7/rpc-transport/socket.so(+0x8790)[0x7f0d047f3790]
>
> /usr/lib64/glusterfs/3.6.7/rpc-transport/socket.so(+0xaf84)[0x7f0d047f5f84]
> /lib64/libglusterfs.so.0(+0x767c2)[0x7f0d0924b7c2]
> /usr/sbin/glusterfs(main+0x502)[0x7f0d096a0fe2]
> /lib64/libc.so.6(__libc_start_main+0xf5)[0x7f0d081fbaf5]
> /usr/sbin/glusterfs(+0x6381)[0x7f0d096a1381]
Could you provide the gluster mount logs from the client, and the gluster
brick logs from the gluster servers?
>
> In /var/log/messages:
> ...
> Dec 22 23:00:49 compute2 journal: metadata not found: Requested
> metadata element is not present
> Dec 22 23:00:59 compute2 journal: metadata not found: Requested
> metadata element is not present
> Dec 22 23:01:01 compute2 systemd: Created slice user-0.slice.
> Dec 22 23:01:01 compute2 systemd: Starting Session 1316 of user root.
> Dec 22 23:01:01 compute2 systemd: Started Session 1316 of user root.
> Dec 22 23:01:01 compute2 systemd: Failed to reset devices.list on
> /machine.slice: Invalid argument
> Dec 22 23:01:03 compute2 journal: metadata not found: Requested
> metadata element is not present
> ...
> Dec 22 23:04:00 compute2
> rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: pending
> frames:
> Dec 22 23:04:00 compute2
> rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: frame :
> type(1) op(FSTAT)
> Dec 22 23:04:00 compute2
> rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: frame :
> type(1) op(READ)
> Dec 22 23:04:00 compute2
> rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: frame :
> type(1) op(READ)
> ...
> Dec 22 23:04:00 compute2
> rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: frame :
> type(1) op(OPEN)
> Dec 22 23:04:00 compute2
> rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: frame :
> type(0) op(0)
> Dec 22 23:04:00 compute2
> rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]:
> patchset: git://git.gluster.com/glusterfs.git
> Dec 22 23:04:00 compute2
> rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: signal
> received: 6
> Dec 22 23:04:00 compute2
> rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: time of
> crash:
> Dec 22 23:04:00 compute2
> rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]:
> 2015-12-22 23:04:00
> Dec 22 23:04:00 compute2
> rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]:
> configuration details:
> Dec 22 23:04:00 compute2
> rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: argp 1
> Dec 22 23:04:00 compute2
> rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]:
> backtrace 1
> Dec 22 23:04:00 compute2
> rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: dlfcn 1
> Dec 22 23:04:00 compute2
> rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]:
> libpthread 1
> Dec 22 23:04:00 compute2
> rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]:
> llistxattr 1
> Dec 22 23:04:00 compute2
> rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: setfsid
> 1
> Dec 22 23:04:00 compute2
> rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]:
> spinlock 1
> Dec 22 23:04:00 compute2
> rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: epoll.h
> 1
> Dec 22 23:04:00 compute2
> rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]: xattr.h
> 1
> Dec 22 23:04:00 compute2
> rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]:
> st_atim.tv_nsec 1
> Dec 22 23:04:00 compute2
> rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]:
> package-string: glusterfs 3.6.7
> Dec 22 23:04:00 compute2
> rhev-data-center-mnt-glusterSD-10.0.231.50:_vm-storage[14098]:
> ---------
> Dec 22 23:04:03 compute2 sanlock[944]: 2015-12-22 23:04:03+0000 944341
> [948]: open error -107
>
>
/rhev/data-center/mnt/glusterSD/10.0.231.50:_vm-storage/a5a83df1-47e2-4927-9add-079199ca7ef8/dom_md/leases
> Dec 22 23:04:03 compute2 sanlock[944]: 2015-12-22 23:04:03+0000 944342
> [944]: ci 8 fd 17 pid -1 recv errno 104
> Dec 22 23:04:03 compute2 sanlock[944]: 2015-12-22 23:04:03+0000 944342
> [949]: open error -107
>
>
/rhev/data-center/mnt/glusterSD/10.0.231.50:_vm-storage/a5a83df1-47e2-4927-9add-079199ca7ef8/dom_md/leases
> Dec 22 23:04:03 compute2 sanlock[944]: 2015-12-22 23:04:03+0000 944342
> [944]: ci 9 fd 18 pid -1 recv errno 104
> Dec 22 23:04:03 compute2 sanlock[944]: 2015-12-22 23:04:03+0000 944342
> [948]: open error -1
>
>
/rhev/data-center/mnt/glusterSD/10.0.231.50:_vm-storage/a5a83df1-47e2-4927-9add-079199ca7ef8/dom_md/leases
> Dec 22 23:04:03 compute2 sanlock[944]: 2015-12-22 23:04:03+0000 944342
> [948]: r1 release_token open error -107
> Dec 22 23:04:03 compute2 journal: vdsm root ERROR Panic: Unrecoverable
> errors during SPM stop process.
> Traceback (most recent call last):
> File "/usr/share/vdsm/storage/sp.py", line 414, in stopSpm
> self.masterDomain.releaseClusterLock()
> File "/usr/share/vdsm/storage/sd.py", line 512, in releaseClusterLock
> self._clusterLock.release()
> File "/usr/share/vdsm/storage/clusterlock.py", line 342, in release
> raise se.ReleaseLockFailure(self._sdUUID, e)
> ReleaseLockFailure: Cannot release lock:
> (u'a5a83df1-47e2-4927-9add-079199ca7ef8', SanlockException(107,
> 'Sanlock resource not released', 'Transport endpoint is not
> connected'))
> Dec 22 23:04:03 compute2 journal: End of file while reading data:
> Input/output error
> Dec 22 23:04:03 compute2 journal: End of file while reading data:
> Input/output error
> Dec 22 23:04:03 compute2 systemd: vdsmd.service: main process exited,
> code=killed, status=9/KILL
> Dec 22 23:04:03 compute2 systemd: Failed to reset devices.list on
> /machine.slice: Invalid argument
> Dec 22 23:04:03 compute2 vdsmd_init_common.sh: vdsm: Running
> run_final_hooks
> Dec 22 23:04:03 compute2 systemd: Unit vdsmd.service entered failed state.
> Dec 22 23:04:03 compute2 systemd: vdsmd.service holdoff time over,
> scheduling restart.
> Dec 22 23:04:03 compute2 systemd: Stopping Virtual Desktop Server
> Manager...
> Dec 22 23:04:03 compute2 systemd: Starting Virtual Desktop Server
> Manager...
> Dec 22 23:04:03 compute2 systemd: Failed to reset devices.list on
> /machine.slice: Invalid argument
>
> At this point I tried restarting vdsmd but ended up having to restart
> the host. There was network connectivity to gluster before I
> restarted, and I was able to manually mount the vm-storage volume on
> the host and ls without issue.
>
> After restarting the host I'm up and running again but I'm sure I'll
> get hit by this again if I can't sort out what the issue is.
> _______________________________________________
> Users mailing list
> Users(a)ovirt.org
> http://lists.ovirt.org/mailman/listinfo/users
3:07 a.m.
On 12/23/2015 11:00 PM, Steve Dainard wrote:
I've attached the client gluster log starting at the first log of
the
same day as failure.
Nothing significant in the client log after the crash and
subsequent
remount. The ENODATA warnings can be ignored. There was a patch
(http://review.gluster.org/#/c/12015/) to change the log level, let me
check if it has made it to a recent release version.
The brick logs are all 0 file size on all of the replica 3 nodes... I
just set 'gluster volume set vm-storage diagnostics.brick-log-level
WARNING' but I'm not immediately seeing any logging to disk.
I've also attached the compute1 vdsm.log file, which over the same
time period is able to dd successfully so perhaps this discounts a
storage side issue? I've also attached compute2 (failed node) for
comparison.
Ravi - I'm not familiar with core files, would this be in a non-devel
version of gluster? Or is this something I can enable? I don't mind
enabling it now if it could help diagnose a future issue.
You should get the core files even on the non-devel versions. I think
the method to enable core files and its location is distribution
specific (depending on whether it uses abrt, systemd etc.) but you can
check for ulimit, and /proc/sys/kernel/core_pattern settings in general.
On my Fedora 23 machine, I get them on /core.pid_of_the_process>.
The timestamp from the logs should also help in identifying the core file:
frame : type(0) op(0)
patchset: git://git.gluster.com/glusterfs.git
signal received: 6
time of crash:
2015-12-22 23:04:00
Regards,
Ravi
3067
days inactive
3068
days old
4 comments
3 participants
participants (3)
-
Ravishankar N -
Sahina Bose -
Steve Dainard