11:51 p.m.
This is a multi-part message in MIME format.
--------------040602070308070206010302
Content-Type: text/plain; charset=utf-8; format=flowed
Content-Transfer-Encoding: 7bit
Hi Nir / Liron,
On 29-04-2015 16:41, Nir Soffer wrote:
[...]
Your probably have storage issues, revealed by sanlock - it reads and
write to all storage domains every 10 seconds, so flaky storage will
cause failure to acquire a host id. Please attach to the bug these
logs: Hypervisor: /var/log/sanlock.log /var/log/messages
/var/log/glusterfs/<glusterhost>:_<volumename>.log Gluster server:
server logs showing what happened when sanlock failed access the
gluster volume.
We have 3 hosts with a 1 GbE LAN connection (idle) so it's probably soft
related.
On host H5, we are constantly receiving sanlock warnings:
May 1 17:26:37 h5 sanlock[637]: 2015-05-01 17:26:37-0300 9118
[643]: s909 add_lockspace fail result -5
May 1 17:26:46 h5 sanlock[637]: 2015-05-01 17:26:46-0300 9128
[12892]: read_sectors delta_leader offset 512 rv -5
/rhev/data-center/mnt/glusterSD/h4.imatronix.com:vdisks/ba7be27f-aee5-4436-ae9a-0764f551f9a7/dom_md/ids
I thought it was normal, but want to be sure.
A Gluster Statedump reveals this locks:
[xlator.features.locks.vdisks-locks.inode]
path=/ba7be27f-aee5-4436-ae9a-0764f551f9a7/dom_md/ids
mandatory=0
conn.1.id=<Host H5>-3016-2015/05/01-17:54:57:109200-vdisks-client-0-0-0
conn.1.ref=1
conn.1.bound_xl=/mnt/disk1/gluster-bricks/vdisks
conn.2.id=<Host H6>-3369-2015/04/30-05:40:59:928550-vdisks-client-0-0-0
conn.2.ref=1
conn.2.bound_xl=/mnt/disk1/gluster-bricks/vdisks
conn.3.id=<Host H4>-31780-2015/04/30-05:57:15:152009-vdisks-client-0-0-0
conn.3.ref=1
conn.3.bound_xl=/mnt/disk1/gluster-bricks/vdisks
conn.4.id=<Host H6>-16034-2015/04/30-16:40:26:355759-vdisks-client-0-0-0
conn.4.ref=1
conn.4.bound_xl=/mnt/disk1/gluster-bricks/vdisks
The first lease is hold by sanlock:
# ps aux | grep 637
sanlock 637 0.0 0.0 545240 19172 ? SLsl 14:54 0:01
sanlock daemon -U sanlock -G sanlock
Host is up since 14:54:39, so this lease was taken after the boot.
Threads:
|-sanlock(637)-+-sanlock-helper(641)
| |-{sanlock}(642)
| |-{sanlock}(643)
| |-{sanlock}(644)
| |-{sanlock}(645)
| |-{sanlock}(3281)
| `-{sanlock}(3428)
Strace:
h5:~# strace -p 637
Process 637 attached
restart_syscall(<... resuming interrupted call ...>) = 0
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=-1},
{fd=-1}], 4, 1000) = 0 (Timeout)
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=-1},
{fd=-1}], 4, 1000) = 0 (Timeout)
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=-1},
{fd=-1}], 4, 1000) = 0 (Timeout)
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=-1},
{fd=-1}], 4, 1000) = 0 (Timeout)
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=-1},
{fd=-1}], 4, 1000) = 0 (Timeout)
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=-1},
{fd=-1}], 4, 1000) = 0 (Timeout)
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=-1},
{fd=-1}], 4, 1000) = 1 ([{fd=7, revents=POLLIN}])
accept(7, 0, NULL) = 11
setsockopt(11, SOL_SOCKET, SO_PASSCRED, [1], 4) = 0
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=11,
events=POLLIN}, {fd=-1}], 4, 1000) = 1 ([{fd=11, revents=POLLIN}])
recvfrom(11, "\20
(\4\1\0\0\0\20\0\0\0\0\0\0\0p\4\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 32,
MSG_WAITALL, NULL, NULL) = 32
futex(0x7f0f3f99442c, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f0f3f994428,
{FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x7f0f3f994400, FUTEX_WAKE_PRIVATE, 1) = 1
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=11,
events=POLLIN}, {fd=-1}], 4, 1000) = 1 ([{fd=11,
revents=POLLIN|POLLHUP}])
recvfrom(11, "", 32, MSG_WAITALL, NULL, NULL) = 0
close(11) = 0
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=-1},
{fd=-1}], 4, 1000) = 1 ([{fd=7, revents=POLLIN}])
accept(7, 0, NULL) = 11
setsockopt(11, SOL_SOCKET, SO_PASSCRED, [1], 4) = 0
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=11,
events=POLLIN}, {fd=-1}], 4, 1000) = 1 ([{fd=11, revents=POLLIN}])
recvfrom(11, "\20
(\4\1\0\0\0\2\0\0\0\1\0\0\0p\4\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 32,
MSG_WAITALL, NULL, NULL) = 32
futex(0x7f0f3f99442c, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f0f3f994428,
{FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x7f0f3f994400, FUTEX_WAKE_PRIVATE, 1) = 1
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=-1},
{fd=-1}], 4, 1000) = 0 (Timeout)
futex(0x7f0f3fa97640, FUTEX_WAKE_PRIVATE, 1) = 1
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=11,
events=POLLIN}, {fd=-1}], 4, 1000) = 1 ([{fd=11,
revents=POLLIN|POLLHUP}])
recvfrom(11, "", 32, MSG_WAITALL, NULL, NULL) = 0
close(11) = 0
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=-1},
{fd=-1}], 4, 1000) = 0 (Timeout)
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=-1},
{fd=-1}], 4, 1000) = 0 (Timeout)
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=-1},
{fd=-1}], 4, 1000) = 1 ([{fd=7, revents=POLLIN}])
accept(7, 0, NULL) = 11
setsockopt(11, SOL_SOCKET, SO_PASSCRED, [1], 4) = 0
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=11,
events=POLLIN}, {fd=-1}], 4, 824) = 1 ([{fd=11, revents=POLLIN}])
recvfrom(11, "\20
(\4\1\0\0\0\20\0\0\0\0\0\0\0p\4\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 32,
MSG_WAITALL, NULL, NULL) = 32
futex(0x7f0f3f99442c, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f0f3f994428,
{FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x7f0f3f994400, FUTEX_WAKE_PRIVATE, 1) = 1
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=11,
events=POLLIN}, {fd=-1}], 4, 824) = 1 ([{fd=11,
revents=POLLIN|POLLHUP}])
recvfrom(11, "", 32, MSG_WAITALL, NULL, NULL) = 0
close(11) = 0
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=-1},
{fd=-1}], 4, 824) = 0 (Timeout)
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=-1},
{fd=-1}], 4, 1000^CProcess 637 detached
Maybe I'm doing something wrong?
Do you have any idea?
The funny thing is that this CentOS 7 host is getting constantly in a
state where the whole root FS is not accesible any more.
All you have is a bash returning I/O errors for any stored command (eg:
"ls").
I thought it was hardware related (2 x 500 GB SSD disks), but maybe we
are lucky and found something kernel related.
Best regards,
Christopher.
--------------040602070308070206010302
Content-Type: text/html; charset=utf-8
Content-Transfer-Encoding: 8bit
<html>
<head>
<meta content="text/html; charset=utf-8"
http-equiv="Content-Type">
</head>
<body bgcolor="#FFFFFF" text="#000000">
Hi Nir / Liron,<br>
<br>
<div class="moz-cite-prefix">On 29-04-2015 16:41, Nir Soffer
wrote:<br>
</div>
<blockquote
cite="mid:733821506.7219611.1430336460762.JavaMail.zimbra@redhat.com"
type="cite">
[...]<br>
Your probably have storage issues, revealed by sanlock - it reads
and write
to all storage domains every 10 seconds, so flaky storage will
cause failure
to acquire a host id.
Please attach to the bug these logs:
Hypervisor:
/var/log/sanlock.log
/var/log/messages
/var/log/glusterfs/<glusterhost>:_<volumename>.log
Gluster server:
server logs showing what happened when sanlock failed access the
gluster volume.
</blockquote>
<br>
We have 3 hosts with a 1 GbE LAN connection (idle) so it's probably
soft related.<br>
<br>
On host H5, we are constantly receiving sanlock warnings:<br>
<blockquote>May 1 17:26:37 h5 sanlock[637]: 2015-05-01
17:26:37-0300 9118 [643]: s909 add_lockspace fail result -5<br>
May 1 17:26:46 h5 sanlock[637]: 2015-05-01 17:26:46-0300 9128
[12892]: read_sectors delta_leader offset 512 rv -5
/rhev/data-center/mnt/glusterSD/h4.imatronix.com:vdisks/ba7be27f-aee5-4436-ae9a-0764f551f9a7/dom_md/ids<br>
</blockquote>
I thought it was normal, but want to be sure.<br>
<br>
A Gluster Statedump reveals this locks:<br>
<blockquote>[xlator.features.locks.vdisks-locks.inode]<br>
path=/ba7be27f-aee5-4436-ae9a-0764f551f9a7/dom_md/ids<br>
mandatory=0<br>
conn.1.id=<Host
H5>-3016-2015/05/01-17:54:57:109200-vdisks-client-0-0-0<br>
conn.1.ref=1<br>
conn.1.bound_xl=/mnt/disk1/gluster-bricks/vdisks<br>
conn.2.id=<Host
H6>-3369-2015/04/30-05:40:59:928550-vdisks-client-0-0-0<br>
conn.2.ref=1<br>
conn.2.bound_xl=/mnt/disk1/gluster-bricks/vdisks<br>
conn.3.id=<Host
H4>-31780-2015/04/30-05:57:15:152009-vdisks-client-0-0-0<br>
conn.3.ref=1<br>
conn.3.bound_xl=/mnt/disk1/gluster-bricks/vdisks<br>
conn.4.id=<Host
H6>-16034-2015/04/30-16:40:26:355759-vdisks-client-0-0-0<br>
conn.4.ref=1<br>
conn.4.bound_xl=/mnt/disk1/gluster-bricks/vdisks<br>
</blockquote>
The first lease is hold by sanlock:<br>
<blockquote># ps aux | grep 637<br>
sanlock 637 0.0 0.0 545240 19172 ? SLsl 14:54 0:01
sanlock daemon -U sanlock -G sanlock<br>
</blockquote>
Host is up since 14:54:39, so this lease was taken after the boot.<br>
<br>
Threads:<br>
<br>
|-sanlock(637)-+-sanlock-helper(641)<br>
| |-{sanlock}(642)<br>
| |-{sanlock}(643)<br>
| |-{sanlock}(644)<br>
| |-{sanlock}(645)<br>
| |-{sanlock}(3281)<br>
| `-{sanlock}(3428)<br>
<br>
Strace:<br>
<br>
<blockquote>h5:~# strace -p 637<br>
Process 637 attached<br>
restart_syscall(<... resuming interrupted call ...>) = 0<br>
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=-1},
{fd=-1}], 4, 1000) = 0 (Timeout)<br>
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=-1},
{fd=-1}], 4, 1000) = 0 (Timeout)<br>
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=-1},
{fd=-1}], 4, 1000) = 0 (Timeout)<br>
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=-1},
{fd=-1}], 4, 1000) = 0 (Timeout)<br>
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=-1},
{fd=-1}], 4, 1000) = 0 (Timeout)<br>
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=-1},
{fd=-1}], 4, 1000) = 0 (Timeout)<br>
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=-1},
{fd=-1}], 4, 1000) = 1 ([{fd=7, revents=POLLIN}])<br>
accept(7, 0, NULL) = 11<br>
setsockopt(11, SOL_SOCKET, SO_PASSCRED, [1], 4) = 0<br>
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=11,
events=POLLIN}, {fd=-1}], 4, 1000) = 1 ([{fd=11, revents=POLLIN}])<br>
recvfrom(11, "\20
(\4\1\0\0\0\20\0\0\0\0\0\0\0p\4\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 32,
MSG_WAITALL, NULL, NULL) = 32<br>
futex(0x7f0f3f99442c, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f0f3f994428,
{FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1<br>
futex(0x7f0f3f994400, FUTEX_WAKE_PRIVATE, 1) = 1<br>
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=11,
events=POLLIN}, {fd=-1}], 4, 1000) = 1 ([{fd=11,
revents=POLLIN|POLLHUP}])<br>
recvfrom(11, "", 32, MSG_WAITALL, NULL, NULL) = 0<br>
close(11) = 0<br>
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=-1},
{fd=-1}], 4, 1000) = 1 ([{fd=7, revents=POLLIN}])<br>
accept(7, 0, NULL) = 11<br>
setsockopt(11, SOL_SOCKET, SO_PASSCRED, [1], 4) = 0<br>
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=11,
events=POLLIN}, {fd=-1}], 4, 1000) = 1 ([{fd=11, revents=POLLIN}])<br>
recvfrom(11, "\20
(\4\1\0\0\0\2\0\0\0\1\0\0\0p\4\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 32,
MSG_WAITALL, NULL, NULL) = 32<br>
futex(0x7f0f3f99442c, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f0f3f994428,
{FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1<br>
futex(0x7f0f3f994400, FUTEX_WAKE_PRIVATE, 1) = 1<br>
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=-1},
{fd=-1}], 4, 1000) = 0 (Timeout)<br>
futex(0x7f0f3fa97640, FUTEX_WAKE_PRIVATE, 1) = 1<br>
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=11,
events=POLLIN}, {fd=-1}], 4, 1000) = 1 ([{fd=11,
revents=POLLIN|POLLHUP}])<br>
recvfrom(11, "", 32, MSG_WAITALL, NULL, NULL) = 0<br>
close(11) = 0<br>
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=-1},
{fd=-1}], 4, 1000) = 0 (Timeout)<br>
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=-1},
{fd=-1}], 4, 1000) = 0 (Timeout)<br>
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=-1},
{fd=-1}], 4, 1000) = 1 ([{fd=7, revents=POLLIN}])<br>
accept(7, 0, NULL) = 11<br>
setsockopt(11, SOL_SOCKET, SO_PASSCRED, [1], 4) = 0<br>
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=11,
events=POLLIN}, {fd=-1}], 4, 824) = 1 ([{fd=11, revents=POLLIN}])<br>
recvfrom(11, "\20
(\4\1\0\0\0\20\0\0\0\0\0\0\0p\4\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 32,
MSG_WAITALL, NULL, NULL) = 32<br>
futex(0x7f0f3f99442c, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f0f3f994428,
{FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1<br>
futex(0x7f0f3f994400, FUTEX_WAKE_PRIVATE, 1) = 1<br>
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=11,
events=POLLIN}, {fd=-1}], 4, 824) = 1 ([{fd=11,
revents=POLLIN|POLLHUP}])<br>
recvfrom(11, "", 32, MSG_WAITALL, NULL, NULL) = 0<br>
close(11) = 0<br>
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=-1},
{fd=-1}], 4, 824) = 0 (Timeout)<br>
poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=-1},
{fd=-1}], 4, 1000^CProcess 637 detached<br>
</blockquote>
Maybe I'm doing something wrong?<br>
Do you have any idea?<br>
<br>
The funny thing is that this CentOS 7 host is getting constantly in
a state where the whole root FS is not accesible any more.<br>
All you have is a bash returning I/O errors for any stored command
(eg: "ls").<br>
I thought it was hardware related (2 x 500 GB SSD disks), but maybe
we are lucky and found something kernel related.<br>
<br>
Best regards,<br>
<br>
Christopher.<br>
</body>
</html>
--------------040602070308070206010302--