Problem with migrating vms after host error hook launched

Sebastian · August 28, 2017, 11:44am

Hello Support,
Our plan is to migrate from Opennebula 5.2 to 5.4. We are in the lucky situation, that we have some spare servers to test the new version. So we set up a frontend cluster with three (the new HA mode) nodes and added two KVM nodes. We used GlusterFS, so on all frontends and kvms are shared datastores. We deployed two vm on each node for testing purposes. Live migration and cold migration works fine, when triggered from the frontend. Everything is working fine except the host error hook.
Our assumption is the following:

The host goes down initiated by a IPMI poweroff
Opennebula recognizes that the host is down (we can see this via “onehost list” and in the oned.log)
Since only cold migration could work on host down we assume that this should happen
The host hook is launched, the fencing works and the vms seem to be reschuled (we can see this in sched.log and host_error.log). Whats confusing us, is that the oned.log shows “Live-migrating VM XY”
Sometimes only one vm is “migrated” to the other sometimes both but allways they are stuck in state MIGRATE

oned.log:

Mon Aug 28 13:28:45 2017 [Z0][InM][D]: Host one-mgmrz-01 (0) successfully monitored.
Mon Aug 28 13:28:46 2017 [Z0][InM][I]: Command execution fail: ‘if [ -x “/var/tmp/one/im/run_probes” ]; then /var/tmp/one/im/run_probes kvm /var/lib/one//datastores 4124 20 1 one-mgmrz-02; else exit 42; fi’
Mon Aug 28 13:28:46 2017 [Z0][InM][I]: ssh: connect to host one-mgmrz-02 port 22: Connection timed out
Mon Aug 28 13:28:46 2017 [Z0][InM][I]: ExitCode: 255
Mon Aug 28 13:28:48 2017 [Z0][InM][I]: Command execution fail: ‘if [ -x “/var/tmp/one/im/run_probes” ]; then /var/tmp/one/im/run_probes kvm /var/lib/one//datastores 4124 20 1 one-mgmrz-02; else exit 42; fi’
Mon Aug 28 13:28:48 2017 [Z0][InM][I]: ssh: connect to host one-mgmrz-02 port 22: No route to host
Mon Aug 28 13:28:48 2017 [Z0][InM][I]: ExitCode: 255
Mon Aug 28 13:28:51 2017 [Z0][InM][I]: Command execution fail: ‘if [ -x “/var/tmp/one/im/run_probes” ]; then /var/tmp/one/im/run_probes kvm /var/lib/one//datastores 4124 20 1 one-mgmrz-02; else exit 42; fi’
Mon Aug 28 13:28:51 2017 [Z0][InM][I]: ssh: connect to host one-mgmrz-02 port 22: No route to host
Mon Aug 28 13:28:51 2017 [Z0][InM][I]: ExitCode: 255
Mon Aug 28 13:28:54 2017 [Z0][InM][I]: Command execution fail: ‘if [ -x “/var/tmp/one/im/run_probes” ]; then /var/tmp/one/im/run_probes kvm /var/lib/one//datastores 4124 20 1 one-mgmrz-02; else exit 42; fi’
Mon Aug 28 13:28:54 2017 [Z0][InM][I]: ssh: connect to host one-mgmrz-02 port 22: No route to host
Mon Aug 28 13:28:54 2017 [Z0][InM][I]: ExitCode: 255
Mon Aug 28 13:28:54 2017 [Z0][ONE][E]: Error monitoring Host one-mgmrz-02 (1): -
Mon Aug 28 13:29:05 2017 [Z0][InM][D]: Host one-mgmrz-01 (0) successfully monitored.
Mon Aug 28 13:29:12 2017 [Z0][MKP][D]: Monitoring marketplace OpenNebula Public (0)
Mon Aug 28 13:29:13 2017 [Z0][InM][D]: Monitoring datastore default (1)
Mon Aug 28 13:29:13 2017 [Z0][InM][D]: Monitoring datastore files (2)
Mon Aug 28 13:29:13 2017 [Z0][InM][D]: Monitoring datastore system-qcow2 (100)
Mon Aug 28 13:29:13 2017 [Z0][InM][D]: Monitoring datastore image-qcow2 (101)
Mon Aug 28 13:29:13 2017 [Z0][InM][D]: Monitoring datastore image-raw (102)
Mon Aug 28 13:29:13 2017 [Z0][ImM][D]: Datastore default (1) successfully monitored.
Mon Aug 28 13:29:13 2017 [Z0][ImM][D]: Datastore image-raw (102) successfully monitored.
Mon Aug 28 13:29:14 2017 [Z0][ImM][D]: Datastore image-qcow2 (101) successfully monitored.
Mon Aug 28 13:29:14 2017 [Z0][ImM][D]: Datastore files (2) successfully monitored.
Mon Aug 28 13:29:14 2017 [Z0][MKP][D]: Marketplace OpenNebula Public (0) successfully monitored.
Mon Aug 28 13:29:14 2017 [Z0][VMM][D]: VM 76 successfully monitored: DISK_SIZE=[ID=0,SIZE=8] SNAPSHOT_SIZE=[ID=0,DISK_ID=0,SIZE=8] DISK_SIZE=[ID=1,SIZE=1]
Mon Aug 28 13:29:14 2017 [Z0][ImM][D]: Datastore system-qcow2 (100) successfully monitored.
Mon Aug 28 13:29:25 2017 [Z0][InM][D]: Host one-mgmrz-01 (0) successfully monitored.
Mon Aug 28 13:29:29 2017 [Z0][DiM][D]: Setting rescheduling flag on VM 76
Mon Aug 28 13:29:29 2017 [Z0][HKM][D]: Message received: EXECUTE SUCCESS 1 error:
Mon Aug 28 13:29:35 2017 [Z0][DiM][D]: Live-migrating VM 76
Mon Aug 28 13:29:37 2017 [Z0][InM][D]: Monitoring host one-mgmrz-02 (1)
Mon Aug 28 13:29:40 2017 [Z0][InM][I]: Command execution fail: ‘if [ -x “/var/tmp/one/im/run_probes” ]; then /var/tmp/one/im/run_probes kvm /var/lib/one//datastores 4124 20 1 one-mgmrz-02; else exit 42; fi’
Mon Aug 28 13:29:40 2017 [Z0][InM][I]: ssh: connect to host one-mgmrz-02 port 22: No route to host
Mon Aug 28 13:29:40 2017 [Z0][InM][I]: ExitCode: 255
Mon Aug 28 13:29:42 2017 [Z0][MKP][D]: Monitoring marketplace OpenNebula Public (0)
Mon Aug 28 13:29:43 2017 [Z0][InM][D]: Monitoring datastore default (1)
Mon Aug 28 13:29:43 2017 [Z0][InM][D]: Monitoring datastore files (2)
Mon Aug 28 13:29:43 2017 [Z0][InM][D]: Monitoring datastore system-qcow2 (100)
Mon Aug 28 13:29:43 2017 [Z0][InM][D]: Monitoring datastore image-qcow2 (101)
Mon Aug 28 13:29:43 2017 [Z0][InM][D]: Monitoring datastore image-raw (102)
Mon Aug 28 13:29:43 2017 [Z0][InM][I]: Command execution fail: ‘if [ -x “/var/tmp/one/im/run_probes” ]; then /var/tmp/one/im/run_probes kvm /var/lib/one//datastores 4124 20 1 one-mgmrz-02; else exit 42; fi’
Mon Aug 28 13:29:43 2017 [Z0][InM][I]: ssh: connect to host one-mgmrz-02 port 22: No route to host
Mon Aug 28 13:29:43 2017 [Z0][InM][I]: ExitCode: 255
Mon Aug 28 13:29:43 2017 [Z0][ImM][D]: Datastore files (2) successfully monitored.
Mon Aug 28 13:29:43 2017 [Z0][ImM][D]: Datastore default (1) successfully monitored.
Mon Aug 28 13:29:43 2017 [Z0][ImM][D]: Datastore image-qcow2 (101) successfully monitored.
Mon Aug 28 13:29:44 2017 [Z0][ImM][D]: Datastore image-raw (102) successfully monitored.
Mon Aug 28 13:29:44 2017 [Z0][VMM][D]: VM 76 successfully monitored: DISK_SIZE=[ID=0,SIZE=8] SNAPSHOT_SIZE=[ID=0,DISK_ID=0,SIZE=8] DISK_SIZE=[ID=1,SIZE=1]
Mon Aug 28 13:29:44 2017 [Z0][ImM][D]: Datastore system-qcow2 (100) successfully monitored.
Mon Aug 28 13:29:44 2017 [Z0][MKP][D]: Marketplace OpenNebula Public (0) successfully monitored.
Mon Aug 28 13:29:46 2017 [Z0][InM][I]: Command execution fail: ‘if [ -x “/var/tmp/one/im/run_probes” ]; then /var/tmp/one/im/run_probes kvm /var/lib/one//datastores 4124 20 1 one-mgmrz-02; else exit 42; fi’
Mon Aug 28 13:29:46 2017 [Z0][InM][I]: ssh: connect to host one-mgmrz-02 port 22: No route to host
Mon Aug 28 13:29:46 2017 [Z0][InM][I]: ExitCode: 255
Mon Aug 28 13:29:49 2017 [Z0][InM][I]: Command execution fail: ‘if [ -x “/var/tmp/one/im/run_probes” ]; then /var/tmp/one/im/run_probes kvm /var/lib/one//datastores 4124 20 1 one-mgmrz-02; else exit 42; fi’
Mon Aug 28 13:29:49 2017 [Z0][InM][I]: ssh: connect to host one-mgmrz-02 port 22: No route to host
Mon Aug 28 13:29:49 2017 [Z0][InM][I]: ExitCode: 255
Mon Aug 28 13:29:49 2017 [Z0][ONE][E]: Error monitoring Host one-mgmrz-02 (1): -
Mon Aug 28 13:29:50 2017 [Z0][InM][D]: Host one-mgmrz-01 (0) successfully monitored.

vm.log:

Mon Aug 28 13:10:40 2017 [Z0][VM][I]: New LCM state is RUNNING
Mon Aug 28 13:28:54 2017 [Z0][VM][I]: New LCM state is UNKNOWN
Mon Aug 28 13:29:14 2017 [Z0][LCM][I]: VM found again by the drivers
Mon Aug 28 13:29:14 2017 [Z0][VM][I]: New LCM state is RUNNING
Mon Aug 28 13:29:35 2017 [Z0][VM][I]: New LCM state is MIGRATE

sched.log:

Mon Aug 28 13:29:34 2017 [Z0][SCHED][D]: Getting scheduled actions information. Total time: 0.01s
Mon Aug 28 13:29:34 2017 [Z0][VM][D]: Pending/rescheduling VM and capacity requirements:
ACTION VM CPU Memory PCI System DS Image DS
RESCHED 76 50 524288 0 2048 DS 101: 0
Mon Aug 28 13:29:34 2017 [Z0][HOST][D]: Discovered Hosts (enabled):
ID : 0
CLUSTER_ID : 0
MEM_USAGE : 0
CPU_USAGE : 0
MAX_MEM : 8127736
MAX_CPU : 400
FREE_DISK : 442067
RUNNING_VMS : 0
PUBLIC : 0
DSID FREE_MB
0 442067
PCI ADDRESS CLASS VENDOR DEVICE VMID
Mon Aug 28 13:29:34 2017 [Z0][VM][D]: VMs in VMGroups:
Mon Aug 28 13:29:34 2017 [Z0][SCHED][D]: Getting VM and Host information. Total time: 0.04s
Mon Aug 28 13:29:34 2017 [Z0][VMGRP][D]: VM Group Scheduling information
Mon Aug 28 13:29:34 2017 [Z0][SCHED][D]: Setting VM groups placement constraints. Total time: 0.00s
Mon Aug 28 13:29:34 2017 [Z0][SCHED][D]: Match Making statistics:
Number of VMs: 1
Total time: 0s
Total Cluster Match time: 0s
Total Host Match time: 0.00s
Total Host Ranking time: 0.00s
Total DS Match time: 0s
Total DS Ranking time: 0s
Mon Aug 28 13:29:34 2017 [Z0][SCHED][D]: Scheduling Results:
Virtual Machine: 76
PRI ID - HOSTS
0 0
PRI ID - DATASTORES
0 100
Mon Aug 28 13:29:35 2017 [Z0][SCHED][D]: Dispatching VMs to hosts:
VMID Priority Host System DS
76 0 0 100
Mon Aug 28 13:29:35 2017 [Z0][SCHED][D]: Dispatching VMs to hosts. Total time: 0.55s
Mon Aug 28 13:30:05 2017 [Z0][SCHED][D]: Getting scheduled actions information. Total time: 0.01s
Mon Aug 28 13:30:05 2017 [Z0][SCHED][D]: Getting VM and Host information. Total time: 0.00s

host_error.log:

[2017-08-28 13:28:54 +0200][HOST 1][I] Hook launched
[2017-08-28 13:28:54 +0200][HOST 1][I] hostname: one-mgmrz-02
[2017-08-28 13:28:54 +0200][HOST 1][I] Wait 1 cycles.
[2017-08-28 13:28:54 +0200][HOST 1][I] Sleeping 30 seconds.
[2017-08-28 13:29:24 +0200][HOST 1][I] Fencing enabled
[2017-08-28 13:29:29 +0200][HOST 1][I] Success: Rebooted
[2017-08-28 13:29:29 +0200][HOST 1][I] Fencing success
[2017-08-28 13:29:29 +0200][HOST 1][I] states: 3, 5, 8
[2017-08-28 13:29:29 +0200][HOST 1][I] vms: [“76”]
[2017-08-28 13:29:29 +0200][HOST 1][I] resched 76
[2017-08-28 13:29:29 +0200][HOST 1][I] Hook finished

Some Questions:

Why is the oned.log showing this “Mon Aug 28 13:29:14 2017 [Z0][VMM][D]: VM 76 successfully monitored: DISK_SIZE=[ID=0,SIZE=8] SNAPSHOT_SIZE=[ID=0,DISK_ID=0,SIZE=8] DISK_SIZE=[ID=1,SIZE=1]”, but the host is down where the vm was running? The vm.log show at the same time “VM found again by the drivers”. This could not be possible
Why is the oned.log showing “Mon Aug 28 13:29:29 2017 [Z0][DiM][D]: Setting rescheduling flag on VM 76
Mon Aug 28 13:29:29 2017 [Z0][HKM][D]: Message received: EXECUTE SUCCESS 1 error:
Mon Aug 28 13:29:35 2017 [Z0][DiM][D]: Live-migrating VM 76”? Shouldnt this be a cold migration? What means “EXECUTIVE SUCCESS 1 error”?
Why is the VM stuck in state MIGRATE?
How can we fix this behaviour?

THX 4 UR HELP

jfontan · August 29, 2017, 2:37pm

It seems that there is a bug that causes the VM to change to running state when disk monitoring arrives. I’ve opened an issue:

https://dev.opennebula.org/issues/5331

EXECUTE SUCCESS 1 error: means that the hook was successfully executed and wrote no error message
The VM changed from UNKNOWN to RUNNING before the scheduler picked it for rescheduling. That made it think it’s really running and tried to do a live migration. On UNKNOWN state the VM is not migrated, it’s redeployed. This was caused by the bug you’ve found.
We aim to fix the bug in version 5.4.1. Meanwhile, as a workaround, you can disable disk monitoring. To do this you can comment the following lines from /var/lib/one/remotes/tm/qcow2/monitor and issue the command onehost sync --force in the frontend:

github.com

OpenNebula/one/blob/release-5.4.0/src/tm_mad/shared/monitor#L78-L106


for vm in \$vms; do
vmdir="${BASE_PATH}/\${vm}"
disks=\$(ls "\$vmdir" | grep '^disk\.[0-9]\+$')


[ -z \$disks ] && continue


echo -n "VM=[ID=\$vm,POLL=\""


for disk in \$disks; do
    disk_id="\$(echo "\$disk" | cut -d. -f2)"
    disk_size="\$(du -mL "\${vmdir}/\${disk}" | awk '{print \$1}')"
    snap_dir="\${vmdir}/\${disk}.snap"


    [ -z "\$disk_size" ] && continue
    echo -n "DISK_SIZE=[ID=\${disk_id},SIZE=\${disk_size}] "


    if [ -e "\$snap_dir" ]; then
        snaps="\$(ls "\$snap_dir" | grep '^[0-9]$')"


        for snap in \$snaps; do

This file has been truncated. show original

Sebastian · September 12, 2017, 12:32pm

A BIG THX for the help. Now everything works as “expected”

Topic		Replies	Views
HOST failure HOOK execution failed Community Support	17	1752	October 24, 2019
Host in ERROR after hard reboot Community Support	1	620	August 22, 2019
Opennebula 5.0 Beta - Host Hook Community Support	10	1524	June 23, 2016
Host state ‘ERROR’ but still working? Community Support	0	430	August 22, 2018
Host error hook not working (5.4.13) Community Support	6	1580	July 12, 2018

Problem with migrating vms after host error hook launched

Related topics