Bug #4497
VM in power off state after live migration
| Status: | Closed | Start date: | 05/28/2016 | |
|---|---|---|---|---|
| Priority: | Normal | Due date: | ||
| Assignee: |  Ruben S. Montero | % Done: | 0% | |
| Category: | Core & System | |||
| Target version: | Release 5.0 | |||
| Resolution: | worksforme | Pull request: | ||
| Affected Versions: | Development |
Description
After live migrating a VM, the state of the VM is "POWEROFF" although the VM is running correctly on the destination host.
Please find the log of the VM below :
Sat May 28 14:23:35 2016 [Z0][VM][I]: New LCM state is RUNNING
Sat May 28 14:28:10 2016 [Z0][VM][I]: New LCM state is MIGRATE
Sat May 28 14:28:12 2016 [Z0][VMM][I]: Successfully execute transfer manager driver operation: tm_premigrate.
Sat May 28 14:28:12 2016 [Z0][VMM][I]: Successfully execute network driver operation: pre.
Sat May 28 14:28:15 2016 [Z0][VMM][I]: ExitCode: 0
Sat May 28 14:28:15 2016 [Z0][VMM][I]: Successfully execute virtualization driver operation: migrate.
Sat May 28 14:28:15 2016 [Z0][VMM][I]: Successfully execute network driver operation: clean.
Sat May 28 14:28:15 2016 [Z0][VMM][I]: Successfully execute network driver operation: post.
Sat May 28 14:28:16 2016 [Z0][VMM][I]: Successfully execute transfer manager driver operation: tm_postmigrate.
Sat May 28 14:28:16 2016 [Z0][VM][I]: New LCM state is RUNNING
Sat May 28 14:29:30 2016 [Z0][LCM][I]: VM running but monitor state is POWEROFF
Sat May 28 14:29:30 2016 [Z0][VM][I]: New LCM state is SHUTDOWN_POWEROFF
Sat May 28 14:29:30 2016 [Z0][VM][I]: New state is POWEROFF
Sat May 28 14:29:30 2016 [Z0][VM][I]: New LCM state is LCM_INIT
I suspect the sub-system that monitors VMs states to be the issue here.
History
#1
Updated by Ruben S. Montero about 5 years ago
does it show up as running after a while, or it stays poweroff?
#2
Updated by Ruben S. Montero about 5 years ago
- Category set to Core & System
#3
Updated by Guillaume Oberlé about 5 years ago
VM seems to stay poweroff.
#4
Updated by Ruben S. Montero about 5 years ago
Would you have the oned.log messages corresponding to Sat May 28 14:29:30 2016 [Z0][LCM][I].
The monitoring process has been improved for shared system ds, so now VM information comes from two different sources. My best bet is that somehow this is messing up when the VM is migrating from one host to the other... The VM xx successfully monitored messages will come in handy.
What is stranger is that the VM is not showing as RUNNING when the new messages arrive from the new host.
#5
Updated by Guillaume Oberlé about 5 years ago
I'm sorry, I don't have the log anymore, I dropped everything when I re-installed but I will try to reproduce it and come back to you.
#6
Updated by Ruben S. Montero about 5 years ago
Perfect THANKS!!!, I could not reproduce so far, so I think it should be a condition related to the monitoring timing
#7
Updated by Ruben S. Montero about 5 years ago
- Assignee set to Ruben S. Montero
#8
Updated by Guillaume Oberlé about 5 years ago
VM log :
Tue May 31 10:12:00 2016 [Z0][VM][I]: New LCM state is MIGRATE
Tue May 31 10:12:00 2016 [Z0][VMM][I]: Successfully execute transfer manager driver operation: tm_premigrate.
Tue May 31 10:12:00 2016 [Z0][VMM][I]: Successfully execute network driver operation: pre.
Tue May 31 10:12:04 2016 [Z0][VMM][I]: ExitCode: 0
Tue May 31 10:12:04 2016 [Z0][VMM][I]: Successfully execute virtualization driver operation: migrate.
Tue May 31 10:12:04 2016 [Z0][VMM][I]: Successfully execute network driver operation: clean.
Tue May 31 10:12:04 2016 [Z0][VMM][I]: Successfully execute network driver operation: post.
Tue May 31 10:12:04 2016 [Z0][VMM][I]: Successfully execute transfer manager driver operation: tm_postmigrate.
Tue May 31 10:12:04 2016 [Z0][VM][I]: New LCM state is RUNNING
Tue May 31 10:17:40 2016 [Z0][LCM][I]: VM running but monitor state is POWEROFF
Tue May 31 10:17:40 2016 [Z0][VM][I]: New LCM state is SHUTDOWN_POWEROFF
Tue May 31 10:17:40 2016 [Z0][VM][I]: New state is POWEROFF
Tue May 31 10:17:40 2016 [Z0][VM][I]: New LCM state is LCM_INIT
oned log :
Tue May 31 10:17:35 2016 [Z0][MKP][D]: Marketplace OpenNebula Public (0) successfully monitored.
Tue May 31 10:17:37 2016 [Z0][ReM][D]: Req:1920 UID:0 VirtualMachinePoolInfo invoked , -2, -1, -1, -1
Tue May 31 10:17:37 2016 [Z0][ReM][D]: Req:1920 UID:0 VirtualMachinePoolInfo result SUCCESS, "<VM_POOL><VM><ID>3Tue May 31 10:17:38 2016 [Z0][ReM][D]: Req:7600 UID:0 VirtualMachinePoolInfo invoked , -2, -1, -1, -1
Tue May 31 10:17:38 2016 [Z0][ReM][D]: Req:7600 UID:0 VirtualMachinePoolInfo result SUCCESS, "<VM_POOL><VM><ID>3Tue May 31 10:17:40 2016 [Z0][InM][D]: Host ivs1.u-strasbg.fr (0) successfully monitored.
Tue May 31 10:17:45 2016 [Z0][InM][D]: Host ivs2.u-strasbg.fr (1) successfully monitored.
Tue May 31 10:18:00 2016 [Z0][InM][D]: Host ivs1.u-strasbg.fr (0) successfully monitored.
Tue May 31 10:18:05 2016 [Z0][InM][D]: Host ivs2.u-strasbg.fr (1) successfully monitored.
Tue May 31 10:18:07 2016 [Z0][ReM][D]: Req:1120 UID:0 VirtualMachinePoolInfo invoked , -2, -1, -1, -1
Tue May 31 10:18:07 2016 [Z0][ReM][D]: Req:1120 UID:0 VirtualMachinePoolInfo result SUCCESS, "<VM_POOL><VM><ID>3
#9
Updated by Guillaume Oberlé about 5 years ago
Hi Ruben,
I found the problem ! It was that I had a ghost host running the KVM probes from a previous installation and therefore not tracked by my current OpenNebula installation. Two host were having the same ID 0 updating the same OpenNebula core ...
I guess you can close the issue :).
Many thanks for your help and sorry for the inconvenience.
#10
Updated by Ruben S. Montero about 5 years ago
- Status changed from Pending to Closed
- Resolution set to worksforme
Great, I was lost. We had this several times in our testing cloud, we have thought in including a oned UUID in the messages, but I guess this is no so common failure....
THANKS!!!!!!