10:58 a.m.
I have a 2 node oVirt 3.3.2 cluster setup and am evaluating the setup
for production use on our HPC system for managing our VM
infrastructure. Currently I'm trying to utilize our DDR InfiniBand
fabric for the storage domains in oVirt using NFS over RDMA. I've
noticed some unstable behavior and it seems in every case to begin
with sanlock.
The ovirt web admin interface shows the following message as first
sign of trouble on 2014-Feb-03 07:45.
"Invalid status on Data Center Default. Setting Data Center status to
Non Responsive (On host vm01.brazos.tamu.edu, Error: Network error
during communication with the Host.).".
The single VM I had running is stuck in the "Migrating From" state.
virsh shows the VM paused on the crashed host and the one it attempted
to migrate to.
Right now I have a few concerns.
1) The cause of the sanlock (or other instability) and if it's related
to a bug or an issue using NFSoRDMA.
2) Why the VM failed to migrate if the second host had no issues. If
the first host is down should the VM be considered offline and booted
on the second host after first is fenced?
Attached are logs from the failed host (vm01) and the healthy host
(vm02) as well as engine. The failed host's /var/log/message is also
attached (vm01_message.log).
Thanks
- Trey
4:15 p.m.
On 02/03/2014 06:58 PM, Trey Dockendorf wrote:
I have a 2 node oVirt 3.3.2 cluster setup and am evaluating the
setup
for production use on our HPC system for managing our VM
infrastructure. Currently I'm trying to utilize our DDR InfiniBand
fabric for the storage domains in oVirt using NFS over RDMA. I've
noticed some unstable behavior and it seems in every case to begin
with sanlock.
The ovirt web admin interface shows the following message as first
sign of trouble on 2014-Feb-03 07:45.
"Invalid status on Data Center Default. Setting Data Center status to
Non Responsive (On host vm01.brazos.tamu.edu, Error: Network error
during communication with the Host.).".
The single VM I had running is stuck in the "Migrating From" state.
virsh shows the VM paused on the crashed host and the one it attempted
to migrate to.
Right now I have a few concerns.
1) The cause of the sanlock (or other instability) and if it's related
to a bug or an issue using NFSoRDMA.
2) Why the VM failed to migrate if the second host had no issues. If
the first host is down should the VM be considered offline and booted
on the second host after first is fenced?
Attached are logs from the failed host (vm01) and the healthy host
(vm02) as well as engine. The failed host's /var/log/message is also
attached (vm01_message.log).
Thanks
- Trey
_______________________________________________
Users mailing list
Users(a)ovirt.org
http://lists.ovirt.org/mailman/listinfo/users
was this resolved?
7:03 p.m.
No, in fact I just had the issue arise again after trying to figure
out what about my setup causes this crash. So far it only seems to
occur if both nodes are running NFS over RDMA, but I'm unsure if it's
VM traffic or the host being SPM that causes it to misbehave.
vm02 was running a single VM and was SPM. The crash was on vm02
"Invalid status on Data Center Default. Setting Data Center status to
Non Responsive (On host vm02, Error: Network error during
communication with the Host).". SPM successfully switched to vm01 but
the VM is stuck in migration and unresponsive. Both engine and nodes
using ovirt 3.3.3.
vm01 and vm02 both have the following in vdsm.conf
[addresses]
management_port = 54321
[vars]
ssl = true
[irs]
nfs_mount_options = rdma,port=20049
This is the ovirt NFS mount lines in /proc/mounts for each:
vm01:
192.168.211.245:/tank/ovirt/import_export
/rhev/data-center/mnt/192.168.211.245:_tank_ovirt_import__export nfs
rw,relatime,vers=3,rsize=32768,wsize=32768,namlen=255,hard,proto=rdma,port=20049,timeo=600,retrans=2,sec=sys,mountaddr=192.168.211.245,mountvers=3,mountproto=tcp,local_lock=none,addr=192.168.211.245
0 0
192.168.211.245:/tank/ovirt/iso
/rhev/data-center/mnt/192.168.211.245:_tank_ovirt_iso nfs
rw,relatime,vers=3,rsize=32768,wsize=32768,namlen=255,hard,proto=rdma,port=20049,timeo=600,retrans=2,sec=sys,mountaddr=192.168.211.245,mountvers=3,mountproto=tcp,local_lock=none,addr=192.168.211.245
0 0
192.168.211.245:/tank/ovirt/data
/rhev/data-center/mnt/192.168.211.245:_tank_ovirt_data nfs
rw,relatime,vers=3,rsize=32768,wsize=32768,namlen=255,hard,proto=rdma,port=20049,timeo=600,retrans=2,sec=sys,mountaddr=192.168.211.245,mountvers=3,mountproto=tcp,local_lock=none,addr=192.168.211.245
0 0
vm02:
192.168.211.245:/tank/ovirt/import_export
/rhev/data-center/mnt/192.168.211.245:_tank_ovirt_import__export nfs
rw,relatime,vers=3,rsize=32768,wsize=32768,namlen=255,hard,proto=rdma,port=20049,timeo=600,retrans=2,sec=sys,mountaddr=192.168.211.245,mountvers=3,mountproto=tcp,local_lock=none,addr=192.168.211.245
0 0
192.168.211.245:/tank/ovirt/iso
/rhev/data-center/mnt/192.168.211.245:_tank_ovirt_iso nfs
rw,relatime,vers=3,rsize=32768,wsize=32768,namlen=255,hard,proto=rdma,port=20049,timeo=600,retrans=2,sec=sys,mountaddr=192.168.211.245,mountvers=3,mountproto=tcp,local_lock=none,addr=192.168.211.245
0 0
192.168.211.245:/tank/ovirt/data
/rhev/data-center/mnt/192.168.211.245:_tank_ovirt_data nfs
rw,relatime,vers=3,rsize=32768,wsize=32768,namlen=255,hard,proto=rdma,port=20049,timeo=600,retrans=2,sec=sys,mountaddr=192.168.211.245,mountvers=3,mountproto=tcp,local_lock=none,addr=192.168.211.245
0 0
The NFS server had these 2 log entries in /var/log/messages around the
time vm02 went Non-operational.
Feb 9 17:27:59 vmstore1 kernel: svcrdma: Error fast registering
memory for xprt ffff882014683400
Feb 9 17:28:21 vmstore1 kernel: svcrdma: Error fast registering
memory for xprt ffff882025bf1400
Attached is tar of the logs from vm01, vm02 and the engine server.
vm01 & vm02 folders contain files from '/var/log/messages
/var/log/sanlock.log /var/log/vdsm/*.log'
engine from '/var/log/messages /var/log/ovirt-engine/*.log'
Thanks
- Trey
On Sun, Feb 9, 2014 at 4:15 PM, Itamar Heim <iheim(a)redhat.com> wrote:
On 02/03/2014 06:58 PM, Trey Dockendorf wrote:
>
> I have a 2 node oVirt 3.3.2 cluster setup and am evaluating the setup
> for production use on our HPC system for managing our VM
> infrastructure. Currently I'm trying to utilize our DDR InfiniBand
> fabric for the storage domains in oVirt using NFS over RDMA. I've
> noticed some unstable behavior and it seems in every case to begin
> with sanlock.
>
> The ovirt web admin interface shows the following message as first
> sign of trouble on 2014-Feb-03 07:45.
>
> "Invalid status on Data Center Default. Setting Data Center status to
> Non Responsive (On host vm01.brazos.tamu.edu, Error: Network error
> during communication with the Host.).".
>
> The single VM I had running is stuck in the "Migrating From" state.
> virsh shows the VM paused on the crashed host and the one it attempted
> to migrate to.
>
> Right now I have a few concerns.
>
> 1) The cause of the sanlock (or other instability) and if it's related
> to a bug or an issue using NFSoRDMA.
> 2) Why the VM failed to migrate if the second host had no issues. If
> the first host is down should the VM be considered offline and booted
> on the second host after first is fenced?
>
> Attached are logs from the failed host (vm01) and the healthy host
> (vm02) as well as engine. The failed host's /var/log/message is also
> attached (vm01_message.log).
>
> Thanks
> - Trey
>
>
>
> _______________________________________________
> Users mailing list
> Users(a)ovirt.org
> http://lists.ovirt.org/mailman/listinfo/users
>
was this resolved?
3:04 a.m.
New subject: [Users] Host Non-Operational from sanlock and VM fails to migrate
----- Original Message -----
From: "Trey Dockendorf" <treydock(a)gmail.com>
To: "Itamar Heim" <iheim(a)redhat.com>
Cc: "users" <users(a)ovirt.org>
Sent: Monday, February 10, 2014 3:03:05 AM
Subject: Re: [Users] Host Non-Operational from sanlock and VM fails to migrate
No, in fact I just had the issue arise again after trying to figure
out what about my setup causes this crash. So far it only seems to
occur if both nodes are running NFS over RDMA, but I'm unsure if it's
VM traffic or the host being SPM that causes it to misbehave.
vm02 was running a single VM and was SPM. The crash was on vm02
"Invalid status on Data Center Default. Setting Data Center status to
Non Responsive (On host vm02, Error: Network error during
communication with the Host).". SPM successfully switched to vm01 but
the VM is stuck in migration and unresponsive. Both engine and nodes
using ovirt 3.3.3.
vm01 and vm02 both have the following in vdsm.conf
[addresses]
management_port = 54321
[vars]
ssl = true
[irs]
nfs_mount_options = rdma,port=20049
This is the ovirt NFS mount lines in /proc/mounts for each:
vm01:
192.168.211.245:/tank/ovirt/import_export
/rhev/data-center/mnt/192.168.211.245:_tank_ovirt_import__export nfs
rw,relatime,vers=3,rsize=32768,wsize=32768,namlen=255,hard,proto=rdma,port=20049,timeo=600,retrans=2,sec=sys,mountaddr=192.168.211.245,mountvers=3,mountproto=tcp,local_lock=none,addr=192.168.211.245
0 0
192.168.211.245:/tank/ovirt/iso
/rhev/data-center/mnt/192.168.211.245:_tank_ovirt_iso nfs
rw,relatime,vers=3,rsize=32768,wsize=32768,namlen=255,hard,proto=rdma,port=20049,timeo=600,retrans=2,sec=sys,mountaddr=192.168.211.245,mountvers=3,mountproto=tcp,local_lock=none,addr=192.168.211.245
0 0
192.168.211.245:/tank/ovirt/data
/rhev/data-center/mnt/192.168.211.245:_tank_ovirt_data nfs
rw,relatime,vers=3,rsize=32768,wsize=32768,namlen=255,hard,proto=rdma,port=20049,timeo=600,retrans=2,sec=sys,mountaddr=192.168.211.245,mountvers=3,mountproto=tcp,local_lock=none,addr=192.168.211.245
0 0
vm02:
192.168.211.245:/tank/ovirt/import_export
/rhev/data-center/mnt/192.168.211.245:_tank_ovirt_import__export nfs
rw,relatime,vers=3,rsize=32768,wsize=32768,namlen=255,hard,proto=rdma,port=20049,timeo=600,retrans=2,sec=sys,mountaddr=192.168.211.245,mountvers=3,mountproto=tcp,local_lock=none,addr=192.168.211.245
0 0
192.168.211.245:/tank/ovirt/iso
/rhev/data-center/mnt/192.168.211.245:_tank_ovirt_iso nfs
rw,relatime,vers=3,rsize=32768,wsize=32768,namlen=255,hard,proto=rdma,port=20049,timeo=600,retrans=2,sec=sys,mountaddr=192.168.211.245,mountvers=3,mountproto=tcp,local_lock=none,addr=192.168.211.245
0 0
192.168.211.245:/tank/ovirt/data
/rhev/data-center/mnt/192.168.211.245:_tank_ovirt_data nfs
rw,relatime,vers=3,rsize=32768,wsize=32768,namlen=255,hard,proto=rdma,port=20049,timeo=600,retrans=2,sec=sys,mountaddr=192.168.211.245,mountvers=3,mountproto=tcp,local_lock=none,addr=192.168.211.245
0 0
The NFS server had these 2 log entries in /var/log/messages around the
time vm02 went Non-operational.
Feb 9 17:27:59 vmstore1 kernel: svcrdma: Error fast registering
memory for xprt ffff882014683400
Feb 9 17:28:21 vmstore1 kernel: svcrdma: Error fast registering
memory for xprt ffff882025bf1400
This looks like the root cause - failure on the storage server
This leads to failure in the hosts connected to this storage:
Feb 2 13:37:11 vm01 kernel: rpcrdma: connection to 192.168.211.245:20049 closed (-103)
...
Feb 3 07:44:31 vm01 kernel: ------------[ cut here ]------------
Feb 3 07:44:31 vm01 kernel: WARNING: at kernel/softirq.c:159
local_bh_enable_ip+0x7d/0xb0() (Not tainted)
Feb 3 07:44:31 vm01 kernel: Hardware name: H8DMT-IBX
Feb 3 07:44:31 vm01 kernel: Modules linked in: ebt_arp xprtrdma nfs fscache auth_rpcgss
nfs_acl bonding ebtable_nat ebtables softdog lockd sunrpc powernow_k8 freq_table mperf
8021q garp bridge stp llc xt_physdev ipt_REJECT nf_conntrack_ipv4 nf_defrag_ipv4
xt_multiport iptable_filter ip_tables ip6t_REJECT nf_conntrack_ipv6 nf_defrag_ipv6
xt_state nf_
conntrack ip6table_filter ip6_tables ib_ipoib rdma_ucm ib_ucm ib_uverbs ib_umad rdma_cm
ib_cm iw_cm ib_addr ipv6 dm_round_robin dm_multipath vhost_net macvtap macvlan tun kvm_a
md kvm microcode serio_raw k10temp amd64_edac_mod edac_core edac_mce_amd igb dca
i2c_algo_bit ptp pps_core mlx4_ib ib_sa ib_mad ib_core mlx4_en mlx4_core sg i2c_nforce2
i2c_cor
e ext4 jbd2 mbcache raid1 sd_mod crc_t10dif sata_nv ata_generic pata_acpi pata_amd
dm_mirror dm_region_hash dm_log dm_mod [last unloaded: scsi_wait_scan]
Feb 3 07:44:31 vm01 kernel: Pid: 0, comm: swapper Not tainted 2.6.32-431.3.1.el6.x86_64
#1
Feb 3 07:44:31 vm01 kernel: Call Trace:
Feb 3 07:44:31 vm01 kernel: <IRQ> [<ffffffff81071e27>] ?
warn_slowpath_common+0x87/0xc0
Feb 3 07:44:31 vm01 kernel: [<ffffffff81071e7a>] ? warn_slowpath_null+0x1a/0x20
Feb 3 07:44:31 vm01 kernel: [<ffffffff8107a3ed>] ? local_bh_enable_ip+0x7d/0xb0
Feb 3 07:44:31 vm01 kernel: [<ffffffff8152a4fb>] ? _spin_unlock_bh+0x1b/0x20
Feb 3 07:44:31 vm01 kernel: [<ffffffffa044c4f0>] ? rpc_wake_up_status+0x70/0x80
[sunrpc]
Feb 3 07:44:31 vm01 kernel: [<ffffffffa044579c>] ?
xprt_wake_pending_tasks+0x2c/0x30 [sunrpc]
Feb 3 07:44:31 vm01 kernel: [<ffffffffa02782fc>] ? rpcrdma_conn_func+0x9c/0xb0
[xprtrdma]
Feb 3 07:44:31 vm01 kernel: [<ffffffff81065df0>] ? default_wake_function+0x0/0x20
Feb 3 07:44:31 vm01 kernel: [<ffffffffa027b450>] ?
rpcrdma_qp_async_error_upcall+0x40/0x80 [xprtrdma]
Feb 3 07:44:31 vm01 kernel: [<ffffffffa019a1cb>] ? mlx4_ib_qp_event+0x8b/0x100
[mlx4_ib]
Feb 3 07:44:31 vm01 kernel: [<ffffffffa0138c54>] ? mlx4_qp_event+0x74/0xf0
[mlx4_core]
Feb 3 07:44:31 vm01 kernel: [<ffffffffa01bd396>] ? igb_poll+0xb66/0x1020 [igb]
Feb 3 07:44:31 vm01 kernel: [<ffffffffa0126057>] ? mlx4_eq_int+0x557/0xcb0
[mlx4_core]
Feb 3 07:44:31 vm01 kernel: [<ffffffff8109a9a0>] ? posix_timer_fn+0x0/0xe0
Feb 3 07:44:31 vm01 kernel: [<ffffffff8109a982>] ? posix_timer_event+0x42/0x60
Feb 3 07:44:31 vm01 kernel: [<ffffffff810a7159>] ? ktime_get+0x69/0xf0
Feb 3 07:44:31 vm01 kernel: [<ffffffffa01267c4>] ? mlx4_msi_x_interrupt+0x14/0x20
[mlx4_core]
Feb 3 07:44:31 vm01 kernel: [<ffffffff810e6ed0>] ? handle_IRQ_event+0x60/0x170
Feb 3 07:44:31 vm01 kernel: [<ffffffff810e982e>] ? handle_edge_irq+0xde/0x180
Feb 3 07:44:31 vm01 kernel: [<ffffffff8100faf9>] ? handle_irq+0x49/0xa0
Feb 3 07:44:31 vm01 kernel: [<ffffffff81530fec>] ? do_IRQ+0x6c/0xf0
Feb 3 07:44:31 vm01 kernel: [<ffffffff8100b9d3>] ? ret_from_intr+0x0/0x11
Feb 3 07:44:31 vm01 kernel: <EOI> [<ffffffff8103eacb>] ?
native_safe_halt+0xb/0x10
Feb 3 07:44:31 vm01 kernel: [<ffffffff810167bd>] ? default_idle+0x4d/0xb0
Feb 3 07:44:31 vm01 kernel: [<ffffffff810168bd>] ? c1e_idle+0x9d/0x120
Feb 3 07:44:31 vm01 kernel: [<ffffffff81009fc6>] ? cpu_idle+0xb6/0x110
Feb 3 07:44:31 vm01 kernel: [<ffffffff81520e2c>] ? start_secondary+0x2ac/0x2ef
Feb 3 07:44:31 vm01 kernel: ---[ end trace 9d97672873a67a1f ]---
This looks like an error in the kernel. You should consult kernel/rpcrdma folks with this
error.
Which cause sanlock to fail to update the lease on the storage (expected):
Feb 3 07:44:58 vm01 sanlock[2536]: 2014-02-03 07:44:58-0600 240689 [2536]: s1
check_our_lease failed 80
Then sanlock try to kill vdsm, the owner of the lease:
Feb 3 07:44:58 vm01 sanlock[2536]: 2014-02-03 07:44:58-0600 240689 [2536]: s1 kill 3030
sig 15 count 1
...
Feb 3 07:45:06 vm01 sanlock[2536]: 2014-02-03 07:45:06-0600 240698 [2536]: s1 kill 3030
sig 15 count 10
Feb 3 07:45:07 vm01 sanlock[2536]: 2014-02-03 07:45:07-0600 240698 [2536]: dead 3030 ci 3
count 10
This makes the host Non-Responsive (expected).
Now vdsm is restarted, which will make it responsive again:
Feb 3 07:45:07 vm01 respawn: slave '/usr/share/vdsm/vdsm --pidfile
/var/run/vdsm/vdsmd.pid' died, respawning slave
But sanlock since there is no access to storage, the host is Non Operational (expected).
The vm was starting a migration to the other host:
Thread-26::DEBUG::2014-02-03 07:49:18,067::BindingXMLRPC::965::vds::(wrapper) client
[192.168.202.99]::call vmMigrate with ({'tunneled': 'false',
'dstqemu': '192.168.202.103',
'src': 'vm01.brazos.tamu.edu', 'dst':
'vm02.brazos.tamu.edu:54321', 'vmId':
'741f9811-db68-4dc4-a88a-7cb9be576e57', 'method': 'online'},) {}
flowID [7829ae2a]
Thread-26::DEBUG::2014-02-03 07:49:18,067::API::463::vds::(migrate) {'tunneled':
'false', 'dstqemu': '192.168.202.103', 'src':
'vm01.brazos.tamu.edu', 'dst': 'vm02.brazos.tamu.
edu:54321', 'vmId': '741f9811-db68-4dc4-a88a-7cb9be576e57',
'method': 'online'}
Thread-26::DEBUG::2014-02-03 07:49:18,068::BindingXMLRPC::972::vds::(wrapper) return
vmMigrate with {'status': {'message': 'Migration in progress',
'code': 0}, 'progress': 0}
The migration was almost complete after 20 seconds:
Thread-29::INFO::2014-02-03 07:49:38,329::vm::815::vm.Vm::(run)
vmId=`741f9811-db68-4dc4-a88a-7cb9be576e57`::Migration Progress: 20 seconds elapsed, 99%
of data processed, 99% of mem processed
But it never completed:
Thread-29::WARNING::2014-02-03 07:54:38,383::vm::792::vm.Vm::(run)
vmId=`741f9811-db68-4dc4-a88a-7cb9be576e57`::Migration is stuck: Hasn't progressed in
300.054134846 seconds. Aborting.
CCing Michal to inspect why the migration has failed.
Attached is tar of the logs from vm01, vm02 and the engine server.
vm01 & vm02 folders contain files from '/var/log/messages
/var/log/sanlock.log /var/log/vdsm/*.log'
engine from '/var/log/messages /var/log/ovirt-engine/*.log'
Thanks
- Trey
On Sun, Feb 9, 2014 at 4:15 PM, Itamar Heim <iheim(a)redhat.com> wrote:
> On 02/03/2014 06:58 PM, Trey Dockendorf wrote:
>>
>> I have a 2 node oVirt 3.3.2 cluster setup and am evaluating the setup
>> for production use on our HPC system for managing our VM
>> infrastructure. Currently I'm trying to utilize our DDR InfiniBand
>> fabric for the storage domains in oVirt using NFS over RDMA. I've
>> noticed some unstable behavior and it seems in every case to begin
>> with sanlock.
>>
>> The ovirt web admin interface shows the following message as first
>> sign of trouble on 2014-Feb-03 07:45.
>>
>> "Invalid status on Data Center Default. Setting Data Center status to
>> Non Responsive (On host vm01.brazos.tamu.edu, Error: Network error
>> during communication with the Host.).".
>>
>> The single VM I had running is stuck in the "Migrating From" state.
>> virsh shows the VM paused on the crashed host and the one it attempted
>> to migrate to.
>>
>> Right now I have a few concerns.
>>
>> 1) The cause of the sanlock (or other instability) and if it's related
>> to a bug or an issue using NFSoRDMA.
vdsm and sanlock seem to behave as they should when storage is not accessible.
>> 2) Why the VM failed to migrate if the second host had no
issues. If
Virt team will have to answer this.
>> the first host is down should the VM be considered offline
and booted
>> on the second host after first is fenced?
The host was not fenced, and was not down. It was up and the vm was still
running, possibly accessing the storage.
>>
>> Attached are logs from the failed host (vm01) and the healthy host
>> (vm02) as well as engine. The failed host's /var/log/message is also
>> attached (vm01_message.log).
>>
>> Thanks
>> - Trey
>>
>>
>>
>> _______________________________________________
>> Users mailing list
>> Users(a)ovirt.org
>> http://lists.ovirt.org/mailman/listinfo/users
>>
>
> was this resolved?
_______________________________________________
Users mailing list
Users(a)ovirt.org
http://lists.ovirt.org/mailman/listinfo/users
3:26 a.m.
New subject: [Users] Host Non-Operational from sanlock and VM fails to migrate
----- Original Message -----
From: "Nir Soffer" <nsoffer(a)redhat.com>
To: "Trey Dockendorf" <treydock(a)gmail.com>
Cc: "users" <users(a)ovirt.org>, "Michal Skrivanek"
<mskrivan(a)redhat.com>
Sent: Wednesday, February 12, 2014 10:04:04 AM
Subject: Re: [Users] Host Non-Operational from sanlock and VM fails to migrate
[...]
The vm was starting a migration to the other host:
Thread-26::DEBUG::2014-02-03 07:49:18,067::BindingXMLRPC::965::vds::(wrapper)
client [192.168.202.99]::call vmMigrate with ({'tunneled': 'false',
'dstqemu': '192.168.202.103',
'src': 'vm01.brazos.tamu.edu', 'dst':
'vm02.brazos.tamu.edu:54321', 'vmId':
'741f9811-db68-4dc4-a88a-7cb9be576e57', 'method': 'online'},) {}
flowID
[7829ae2a]
Thread-26::DEBUG::2014-02-03 07:49:18,067::API::463::vds::(migrate)
{'tunneled': 'false', 'dstqemu': '192.168.202.103',
'src':
'vm01.brazos.tamu.edu', 'dst': 'vm02.brazos.tamu.
edu:54321', 'vmId': '741f9811-db68-4dc4-a88a-7cb9be576e57',
'method':
'online'}
Thread-26::DEBUG::2014-02-03 07:49:18,068::BindingXMLRPC::972::vds::(wrapper)
return vmMigrate with {'status': {'message': 'Migration in
progress',
'code': 0}, 'progress': 0}
The migration was almost complete after 20 seconds:
Thread-29::INFO::2014-02-03 07:49:38,329::vm::815::vm.Vm::(run)
vmId=`741f9811-db68-4dc4-a88a-7cb9be576e57`::Migration Progress: 20 seconds
elapsed, 99% of data processed, 99% of mem processed
But it never completed:
Thread-29::WARNING::2014-02-03 07:54:38,383::vm::792::vm.Vm::(run)
vmId=`741f9811-db68-4dc4-a88a-7cb9be576e57`::Migration is stuck: Hasn't
progressed in 300.054134846 seconds. Aborting.
CCing Michal to inspect why the migration has failed.
Hi,
I had a look at the logs, and this looks like another libvirt/qemu I/O related issue.
If QEMU on the src hosts cannot reliably access storage, migration may get stuck;
this seems the case given the information provided; VDSM detected the migration
was not progressing and aborted it.
libvirt has an option (which we already use) to detect those scenarios, the
VIR_MIGRATE_ABORT_ON_ERROR flag, but unfortunately this is not 100% reliable yet,
for reasons outlined below in this mail.
We are aware of this issue and we are actively working to improve the handling
of such scenarios, but actually this is mostly on QEMU.
The core issue here is that when we use NFS (or ISCSI), and there is an I/O error,
QEMU can get blocked inside the kernel, waiting for the faulty I/O operation to complete,
and thus fail to report an I/O error.
It really depends on what specific operation fails, and there are many possible cases
and error scenarios.
Of course, if QEMU is blocked and fails to report the I/O error, libvirt can do nothing
to report/recover error, so VDSM can do even less.
This is known and acknowledged both by libvirt and QEMU developers.
But there are some good news, because newer versions of QEMU have improvements on this
field: QEMU recently gained native block devices[1], which, among other things, will make
it more robust in presence of I/O errors, and should improve the error reporting as well.
RHEL7 should have a version of QEMU with native ISCSI; hopefully NFS will follow soon
enough.
HTH,
+++
[1] for example, ISCSI, recently merged:
http://comments.gmane.org/gmane.comp.emulators.qemu/92599
work on NFS is ongoing.
--
Francesco Romani
RedHat Engineering Virtualization R & D
IRC: fromani
6:20 p.m.
Thanks for the thorough response!
This looks like an error in the kernel. You should consult
kernel/rpcrdma folks with this error.
Mind pointing me in the direction of how to get in contact with the
appropriate mailing list to begin a dialog with the kernel/rpcrdma
folks?
Thanks
- Trey
On Wed, Feb 12, 2014 at 3:04 AM, Nir Soffer <nsoffer(a)redhat.com> wrote:
> ----- Original Message -----
>> From: "Trey Dockendorf" <treydock(a)gmail.com>
>> To: "Itamar Heim" <iheim(a)redhat.com>
>> Cc: "users" <users(a)ovirt.org>
>> Sent: Monday, February 10, 2014 3:03:05 AM
>> Subject: Re: [Users] Host Non-Operational from sanlock and VM fails to
migrate
>>
>> No, in fact I just had the issue arise again after trying to figure
>> out what about my setup causes this crash. So far it only seems to
>> occur if both nodes are running NFS over RDMA, but I'm unsure if it's
>> VM traffic or the host being SPM that causes it to misbehave.
>>
>> vm02 was running a single VM and was SPM. The crash was on vm02
>> "Invalid status on Data Center Default. Setting Data Center status to
>> Non Responsive (On host vm02, Error: Network error during
>> communication with the Host).". SPM successfully switched to vm01 but
>> the VM is stuck in migration and unresponsive. Both engine and nodes
>> using ovirt 3.3.3.
>>
>> vm01 and vm02 both have the following in vdsm.conf
>>
>> [addresses]
>> management_port = 54321
>>
>> [vars]
>> ssl = true
>>
>>
>> [irs]
>> nfs_mount_options = rdma,port=20049
>>
>> This is the ovirt NFS mount lines in /proc/mounts for each:
>>
>> vm01:
>>
>> 192.168.211.245:/tank/ovirt/import_export
>> /rhev/data-center/mnt/192.168.211.245:_tank_ovirt_import__export nfs
>>
rw,relatime,vers=3,rsize=32768,wsize=32768,namlen=255,hard,proto=rdma,port=20049,timeo=600,retrans=2,sec=sys,mountaddr=192.168.211.245,mountvers=3,mountproto=tcp,local_lock=none,addr=192.168.211.245
>> 0 0
>> 192.168.211.245:/tank/ovirt/iso
>> /rhev/data-center/mnt/192.168.211.245:_tank_ovirt_iso nfs
>>
rw,relatime,vers=3,rsize=32768,wsize=32768,namlen=255,hard,proto=rdma,port=20049,timeo=600,retrans=2,sec=sys,mountaddr=192.168.211.245,mountvers=3,mountproto=tcp,local_lock=none,addr=192.168.211.245
>> 0 0
>> 192.168.211.245:/tank/ovirt/data
>> /rhev/data-center/mnt/192.168.211.245:_tank_ovirt_data nfs
>>
rw,relatime,vers=3,rsize=32768,wsize=32768,namlen=255,hard,proto=rdma,port=20049,timeo=600,retrans=2,sec=sys,mountaddr=192.168.211.245,mountvers=3,mountproto=tcp,local_lock=none,addr=192.168.211.245
>> 0 0
>>
>> vm02:
>>
>> 192.168.211.245:/tank/ovirt/import_export
>> /rhev/data-center/mnt/192.168.211.245:_tank_ovirt_import__export nfs
>>
rw,relatime,vers=3,rsize=32768,wsize=32768,namlen=255,hard,proto=rdma,port=20049,timeo=600,retrans=2,sec=sys,mountaddr=192.168.211.245,mountvers=3,mountproto=tcp,local_lock=none,addr=192.168.211.245
>> 0 0
>> 192.168.211.245:/tank/ovirt/iso
>> /rhev/data-center/mnt/192.168.211.245:_tank_ovirt_iso nfs
>>
rw,relatime,vers=3,rsize=32768,wsize=32768,namlen=255,hard,proto=rdma,port=20049,timeo=600,retrans=2,sec=sys,mountaddr=192.168.211.245,mountvers=3,mountproto=tcp,local_lock=none,addr=192.168.211.245
>> 0 0
>> 192.168.211.245:/tank/ovirt/data
>> /rhev/data-center/mnt/192.168.211.245:_tank_ovirt_data nfs
>>
rw,relatime,vers=3,rsize=32768,wsize=32768,namlen=255,hard,proto=rdma,port=20049,timeo=600,retrans=2,sec=sys,mountaddr=192.168.211.245,mountvers=3,mountproto=tcp,local_lock=none,addr=192.168.211.245
>> 0 0
>>
>> The NFS server had these 2 log entries in /var/log/messages around the
>> time vm02 went Non-operational.
>>
>> Feb 9 17:27:59 vmstore1 kernel: svcrdma: Error fast registering
>> memory for xprt ffff882014683400
>> Feb 9 17:28:21 vmstore1 kernel: svcrdma: Error fast registering
>> memory for xprt ffff882025bf1400
>
> This looks like the root cause - failure on the storage server
>
> This leads to failure in the hosts connected to this storage:
>
> Feb 2 13:37:11 vm01 kernel: rpcrdma: connection to 192.168.211.245:20049 closed
(-103)
> ...
> Feb 3 07:44:31 vm01 kernel: ------------[ cut here ]------------
> Feb 3 07:44:31 vm01 kernel: WARNING: at kernel/softirq.c:159
local_bh_enable_ip+0x7d/0xb0() (Not tainted)
> Feb 3 07:44:31 vm01 kernel: Hardware name: H8DMT-IBX
> Feb 3 07:44:31 vm01 kernel: Modules linked in: ebt_arp xprtrdma nfs fscache
auth_rpcgss nfs_acl bonding ebtable_nat ebtables softdog lockd sunrpc powernow_k8
freq_table mperf
> 8021q garp bridge stp llc xt_physdev ipt_REJECT nf_conntrack_ipv4 nf_defrag_ipv4
xt_multiport iptable_filter ip_tables ip6t_REJECT nf_conntrack_ipv6 nf_defrag_ipv6
xt_state nf_
> conntrack ip6table_filter ip6_tables ib_ipoib rdma_ucm ib_ucm ib_uverbs ib_umad
rdma_cm ib_cm iw_cm ib_addr ipv6 dm_round_robin dm_multipath vhost_net macvtap macvlan tun
kvm_a
> md kvm microcode serio_raw k10temp amd64_edac_mod edac_core edac_mce_amd igb dca
i2c_algo_bit ptp pps_core mlx4_ib ib_sa ib_mad ib_core mlx4_en mlx4_core sg i2c_nforce2
i2c_cor
> e ext4 jbd2 mbcache raid1 sd_mod crc_t10dif sata_nv ata_generic pata_acpi pata_amd
dm_mirror dm_region_hash dm_log dm_mod [last unloaded: scsi_wait_scan]
> Feb 3 07:44:31 vm01 kernel: Pid: 0, comm: swapper Not tainted
2.6.32-431.3.1.el6.x86_64 #1
> Feb 3 07:44:31 vm01 kernel: Call Trace:
> Feb 3 07:44:31 vm01 kernel: <IRQ> [<ffffffff81071e27>] ?
warn_slowpath_common+0x87/0xc0
> Feb 3 07:44:31 vm01 kernel: [<ffffffff81071e7a>] ?
warn_slowpath_null+0x1a/0x20
> Feb 3 07:44:31 vm01 kernel: [<ffffffff8107a3ed>] ?
local_bh_enable_ip+0x7d/0xb0
> Feb 3 07:44:31 vm01 kernel: [<ffffffff8152a4fb>] ? _spin_unlock_bh+0x1b/0x20
> Feb 3 07:44:31 vm01 kernel: [<ffffffffa044c4f0>] ?
rpc_wake_up_status+0x70/0x80 [sunrpc]
> Feb 3 07:44:31 vm01 kernel: [<ffffffffa044579c>] ?
xprt_wake_pending_tasks+0x2c/0x30 [sunrpc]
> Feb 3 07:44:31 vm01 kernel: [<ffffffffa02782fc>] ? rpcrdma_conn_func+0x9c/0xb0
[xprtrdma]
> Feb 3 07:44:31 vm01 kernel: [<ffffffff81065df0>] ?
default_wake_function+0x0/0x20
> Feb 3 07:44:31 vm01 kernel: [<ffffffffa027b450>] ?
rpcrdma_qp_async_error_upcall+0x40/0x80 [xprtrdma]
> Feb 3 07:44:31 vm01 kernel: [<ffffffffa019a1cb>] ? mlx4_ib_qp_event+0x8b/0x100
[mlx4_ib]
> Feb 3 07:44:31 vm01 kernel: [<ffffffffa0138c54>] ? mlx4_qp_event+0x74/0xf0
[mlx4_core]
> Feb 3 07:44:31 vm01 kernel: [<ffffffffa01bd396>] ? igb_poll+0xb66/0x1020
[igb]
> Feb 3 07:44:31 vm01 kernel: [<ffffffffa0126057>] ? mlx4_eq_int+0x557/0xcb0
[mlx4_core]
> Feb 3 07:44:31 vm01 kernel: [<ffffffff8109a9a0>] ? posix_timer_fn+0x0/0xe0
> Feb 3 07:44:31 vm01 kernel: [<ffffffff8109a982>] ?
posix_timer_event+0x42/0x60
> Feb 3 07:44:31 vm01 kernel: [<ffffffff810a7159>] ? ktime_get+0x69/0xf0
> Feb 3 07:44:31 vm01 kernel: [<ffffffffa01267c4>] ?
mlx4_msi_x_interrupt+0x14/0x20 [mlx4_core]
> Feb 3 07:44:31 vm01 kernel: [<ffffffff810e6ed0>] ?
handle_IRQ_event+0x60/0x170
> Feb 3 07:44:31 vm01 kernel: [<ffffffff810e982e>] ? handle_edge_irq+0xde/0x180
> Feb 3 07:44:31 vm01 kernel: [<ffffffff8100faf9>] ? handle_irq+0x49/0xa0
> Feb 3 07:44:31 vm01 kernel: [<ffffffff81530fec>] ? do_IRQ+0x6c/0xf0
> Feb 3 07:44:31 vm01 kernel: [<ffffffff8100b9d3>] ? ret_from_intr+0x0/0x11
> Feb 3 07:44:31 vm01 kernel: <EOI> [<ffffffff8103eacb>] ?
native_safe_halt+0xb/0x10
> Feb 3 07:44:31 vm01 kernel: [<ffffffff810167bd>] ? default_idle+0x4d/0xb0
> Feb 3 07:44:31 vm01 kernel: [<ffffffff810168bd>] ? c1e_idle+0x9d/0x120
> Feb 3 07:44:31 vm01 kernel: [<ffffffff81009fc6>] ? cpu_idle+0xb6/0x110
> Feb 3 07:44:31 vm01 kernel: [<ffffffff81520e2c>] ?
start_secondary+0x2ac/0x2ef
> Feb 3 07:44:31 vm01 kernel: ---[ end trace 9d97672873a67a1f ]---
>
This looks like an error in the kernel. You should consult
kernel/rpcrdma folks with this error.
>
> Which cause sanlock to fail to update the lease on the storage (expected):
>
> Feb 3 07:44:58 vm01 sanlock[2536]: 2014-02-03 07:44:58-0600 240689 [2536]: s1
check_our_lease failed 80
>
> Then sanlock try to kill vdsm, the owner of the lease:
>
> Feb 3 07:44:58 vm01 sanlock[2536]: 2014-02-03 07:44:58-0600 240689 [2536]: s1 kill
3030 sig 15 count 1
> ...
> Feb 3 07:45:06 vm01 sanlock[2536]: 2014-02-03 07:45:06-0600 240698 [2536]: s1 kill
3030 sig 15 count 10
> Feb 3 07:45:07 vm01 sanlock[2536]: 2014-02-03 07:45:07-0600 240698 [2536]: dead 3030
ci 3 count 10
>
> This makes the host Non-Responsive (expected).
>
> Now vdsm is restarted, which will make it responsive again:
>
> Feb 3 07:45:07 vm01 respawn: slave '/usr/share/vdsm/vdsm --pidfile
/var/run/vdsm/vdsmd.pid' died, respawning slave
>
> But sanlock since there is no access to storage, the host is Non Operational
(expected).
>
> The vm was starting a migration to the other host:
>
> Thread-26::DEBUG::2014-02-03 07:49:18,067::BindingXMLRPC::965::vds::(wrapper) client
[192.168.202.99]::call vmMigrate with ({'tunneled': 'false',
'dstqemu': '192.168.202.103',
> 'src': 'vm01.brazos.tamu.edu', 'dst':
'vm02.brazos.tamu.edu:54321', 'vmId':
'741f9811-db68-4dc4-a88a-7cb9be576e57', 'method': 'online'},) {}
flowID [7829ae2a]
> Thread-26::DEBUG::2014-02-03 07:49:18,067::API::463::vds::(migrate)
{'tunneled': 'false', 'dstqemu': '192.168.202.103',
'src': 'vm01.brazos.tamu.edu', 'dst': 'vm02.brazos.tamu.
> edu:54321', 'vmId': '741f9811-db68-4dc4-a88a-7cb9be576e57',
'method': 'online'}
> Thread-26::DEBUG::2014-02-03 07:49:18,068::BindingXMLRPC::972::vds::(wrapper) return
vmMigrate with {'status': {'message': 'Migration in progress',
'code': 0}, 'progress': 0}
>
> The migration was almost complete after 20 seconds:
>
> Thread-29::INFO::2014-02-03 07:49:38,329::vm::815::vm.Vm::(run)
vmId=`741f9811-db68-4dc4-a88a-7cb9be576e57`::Migration Progress: 20 seconds elapsed, 99%
of data processed, 99% of mem processed
>
> But it never completed:
>
> Thread-29::WARNING::2014-02-03 07:54:38,383::vm::792::vm.Vm::(run)
vmId=`741f9811-db68-4dc4-a88a-7cb9be576e57`::Migration is stuck: Hasn't progressed in
300.054134846 seconds. Aborting.
>
> CCing Michal to inspect why the migration has failed.
>
>>
>> Attached is tar of the logs from vm01, vm02 and the engine server.
>>
>> vm01 & vm02 folders contain files from '/var/log/messages
>> /var/log/sanlock.log /var/log/vdsm/*.log'
>> engine from '/var/log/messages /var/log/ovirt-engine/*.log'
>>
>> Thanks
>> - Trey
>>
>> On Sun, Feb 9, 2014 at 4:15 PM, Itamar Heim <iheim(a)redhat.com> wrote:
>> > On 02/03/2014 06:58 PM, Trey Dockendorf wrote:
>> >>
>> >> I have a 2 node oVirt 3.3.2 cluster setup and am evaluating the setup
>> >> for production use on our HPC system for managing our VM
>> >> infrastructure. Currently I'm trying to utilize our DDR InfiniBand
>> >> fabric for the storage domains in oVirt using NFS over RDMA. I've
>> >> noticed some unstable behavior and it seems in every case to begin
>> >> with sanlock.
>> >>
>> >> The ovirt web admin interface shows the following message as first
>> >> sign of trouble on 2014-Feb-03 07:45.
>> >>
>> >> "Invalid status on Data Center Default. Setting Data Center status
to
>> >> Non Responsive (On host vm01.brazos.tamu.edu, Error: Network error
>> >> during communication with the Host.).".
>> >>
>> >> The single VM I had running is stuck in the "Migrating From"
state.
>> >> virsh shows the VM paused on the crashed host and the one it attempted
>> >> to migrate to.
>> >>
>> >> Right now I have a few concerns.
>> >>
>> >> 1) The cause of the sanlock (or other instability) and if it's
related
>> >> to a bug or an issue using NFSoRDMA.
>
> vdsm and sanlock seem to behave as they should when storage is not accessible.
>
>> >> 2) Why the VM failed to migrate if the second host had no issues. If
>
> Virt team will have to answer this.
>
>> >> the first host is down should the VM be considered offline and booted
>> >> on the second host after first is fenced?
>
> The host was not fenced, and was not down. It was up and the vm was still
> running, possibly accessing the storage.
>
>> >>
>> >> Attached are logs from the failed host (vm01) and the healthy host
>> >> (vm02) as well as engine. The failed host's /var/log/message is
also
>> >> attached (vm01_message.log).
>> >>
>> >> Thanks
>> >> - Trey
>> >>
>> >>
>> >>
>> >> _______________________________________________
>> >> Users mailing list
>> >> Users(a)ovirt.org
>> >> http://lists.ovirt.org/mailman/listinfo/users
>> >>
>> >
>> > was this resolved?
>>
>> _______________________________________________
>> Users mailing list
>> Users(a)ovirt.org
>> http://lists.ovirt.org/mailman/listinfo/users
>>
6:16 p.m.
----- Original Message -----
From: "Trey Dockendorf" <treydock(a)gmail.com>
To: "Nir Soffer" <nsoffer(a)redhat.com>
Cc: "users" <users(a)ovirt.org>, "Michal Skrivanek"
<mskrivan(a)redhat.com>, "Ayal Baron" <abaron(a)redhat.com>,
"Itamar
Heim" <iheim(a)redhat.com>
Sent: Wednesday, February 19, 2014 2:20:52 AM
Subject: Re: [Users] Host Non-Operational from sanlock and VM fails to migrate
Thanks for the thorough response!
> This looks like an error in the kernel. You should consult kernel/rpcrdma
> folks with this error.
Mind pointing me in the direction of how to get in contact with the
appropriate mailing list to begin a dialog with the kernel/rpcrdma
folks?
Probably using the kernel mailing list, irc channel or bug tracking system of
your distribution.
Nir
3739
days inactive
3757
days old
6 comments
4 participants
participants (4)
-
Francesco Romani -
Itamar Heim -
Nir Soffer -
Trey Dockendorf