cloudstack-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Rohit Yadav <rohit.ya...@shapeblue.com>
Subject Re: Has anybody gotten Cloudstack 4.13.1.0 or 4.14.0.0 working on Centos 7.7 or 7.8?
Date Sun, 09 Aug 2020 15:42:22 GMT
Hi Eric,

This looks like a Libvirt specific error [1] outside of the scope of CloudStack. Can you try the CentOS SIG Virtualisation repos (the qemu-ev releases) [2] which usually requires installing centos-release-qemu-ev on the CentOS KVM hosts and doing an upgrade (or installation of the qemu* packages).

[1] Similar issue: https://bugzilla.redhat.com/show_bug.cgi?id=1090551

[2] https://wiki.centos.org/SpecialInterestGroup/Virtualizatio<https://wiki.centos.org/SpecialInterestGroup/Virtualization>



Regards.

________________________________
From: Eric Lee Green <eric.lee.green@gmail.com>
Sent: Saturday, August 8, 2020 08:44
To: users@cloudstack.apache.org <users@cloudstack.apache.org>
Subject: Has anybody gotten Cloudstack 4.13.1.0 or 4.14.0.0 working on Centos 7.7 or 7.8?

I've tried multiple times now and it's refusing to start the virtual
routers and thus refusing to start anything else. Or rather, it's
starting them, I see the VM appear in the process list (ps -ax | grep
kvm) and I see log messages in /var/log/messages saying it's started and
I see the log,  but then the agent is refusing to connect and then
shutting them down. This happened with both 4.13 and 4.14.  4.13 worked
with an earlier version of Centos, but had issues with creating new
virtual machines (as versus starting them) so I am trying to get things
running on a modern Centos (i.e., one that's not a security breach just
by existing).

Any ideas?

Example:

/var/log/messages:

---------------------------------------------snip------------------------------------------------------
Aug  7 19:57:49 cloud1 java: INFO [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-1:) (logid:35b3a97e) Trying to fetch storage pool
f7c824aa-e6e4-3c40-b890-36a459245385 from libvirt
Aug  7 19:57:49 cloud1 java: INFO [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-1:) (logid:35b3a97e) Asking libvirt to refresh
storage pool f7c824aa-e6e4-3c40-b890-36a459245385
Aug  7 19:57:50 cloud1 java: INFO [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-3:) (logid:35b3a97e) Trying to fetch storage pool
0ab13de9-2310-334c-b438-94dfb0b8ec84 from libvirt
Aug  7 19:57:50 cloud1 java: INFO [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-3:) (logid:35b3a97e) Asking libvirt to refresh
storage pool 0ab13de9-2310-334c-b438-94dfb0b8ec84
Aug  7 19:58:29 cloud1 java: INFO [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-4:) (logid:1051f59c) Trying to fetch storage pool
0ab13de9-2310-334c-b438-94dfb0b8ec84 from libvirt
Aug  7 19:58:29 cloud1 java: INFO [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-4:) (logid:1051f59c) Trying to fetch storage pool
0ab13de9-2310-334c-b438-94dfb0b8ec84 from libvirt
Aug  7 19:58:29 cloud1 kernel: brbond0-102: port 1(bond0.102) entered
blocking state
Aug  7 19:58:29 cloud1 kernel: brbond0-102: port 1(bond0.102) entered
disabled state
Aug  7 19:58:29 cloud1 kernel: device bond0.102 entered promiscuous mode
Aug  7 19:58:29 cloud1 kernel: brbond0-102: port 1(bond0.102) entered
blocking state
Aug  7 19:58:29 cloud1 kernel: brbond0-102: port 1(bond0.102) entered
forwarding state
Aug  7 19:58:29 cloud1 java: WARNING: An illegal reflective access
operation has occurred
Aug  7 19:58:29 cloud1 java: WARNING: Illegal reflective access by
org.codehaus.groovy.reflection.CachedClass
(file:/usr/share/cloudstack-agent/lib/groovy-all-2.4.17.jar) to method
java.lang.Object.finalize()
Aug  7 19:58:29 cloud1 java: WARNING: Please consider reporting this to
the maintainers of org.codehaus.groovy.reflection.CachedClass
Aug  7 19:58:29 cloud1 java: WARNING: Use --illegal-access=warn to
enable warnings of further illegal reflective access operations
Aug  7 19:58:29 cloud1 java: WARNING: All illegal access operations will
be denied in a future release
Aug  7 19:58:29 cloud1 java: WARN [kvm.resource.LibvirtKvmAgentHook]
(agentRequest-Handler-4:) (logid:1051f59c) Groovy script
'/etc/cloudstack/agent/hooks/libvirt-vm-xml-transformer.groovy' is not
available. Transformations will not be applied.
Aug  7 19:58:29 cloud1 java: WARN [kvm.resource.LibvirtKvmAgentHook]
(agentRequest-Handler-4:) (logid:1051f59c) Groovy scripting engine is
not initialized. Data transformation skipped.
Aug  7 19:58:29 cloud1 java: libvirt: QEMU Driver error : Domain not
found: no domain with matching name 'r-739-VM'
Aug  7 19:58:29 cloud1 kernel: brbond0-102: port 2(vnet0) entered
blocking state
Aug  7 19:58:29 cloud1 kernel: brbond0-102: port 2(vnet0) entered
disabled state
Aug  7 19:58:29 cloud1 kernel: device vnet0 entered promiscuous mode
Aug  7 19:58:29 cloud1 kernel: brbond0-102: port 2(vnet0) entered
blocking state
Aug  7 19:58:29 cloud1 kernel: brbond0-102: port 2(vnet0) entered
forwarding state
Aug  7 19:58:29 cloud1 kernel: cloud0: port 1(vnet1) entered blocking state
Aug  7 19:58:29 cloud1 kernel: cloud0: port 1(vnet1) entered disabled state
Aug  7 19:58:29 cloud1 kernel: device vnet1 entered promiscuous mode
Aug  7 19:58:29 cloud1 kernel: cloud0: port 1(vnet1) entered blocking state
Aug  7 19:58:29 cloud1 kernel: cloud0: port 1(vnet1) entered forwarding
state
Aug  7 19:58:29 cloud1 libvirtd: 2020-08-08 02:58:29.657+0000: 8966:
warning : qemuDomainObjTaint:7530 : Domain id=1 name='r-739-VM'
uuid=7f5bcd06-3c91-4b6c-a67f-f031a18db38a is tainted: high-privileges
Aug  7 19:58:29 cloud1 dbus[1143]: [system] Activating via systemd:
service name='org.freedesktop.machine1'
unit='dbus-org.freedesktop.machine1.service'
Aug  7 19:58:29 cloud1 systemd: Starting Virtual Machine and Container
Registration Service...
Aug  7 19:58:29 cloud1 dbus[1143]: [system] Successfully activated
service 'org.freedesktop.machine1'
Aug  7 19:58:29 cloud1 systemd: Started Virtual Machine and Container
Registration Service.
Aug  7 19:58:29 cloud1 systemd-machined: New machine qemu-1-r-739-VM.
Aug  7 19:58:29 cloud1 systemd: Started Virtual Machine qemu-1-r-739-VM.
Aug  7 19:58:29 cloud1 kvm: 1 guest now active
Aug  7 19:58:29 cloud1 java: WARN [kvm.resource.LibvirtKvmAgentHook]
(agentRequest-Handler-4:) (logid:1051f59c) Groovy script
'/etc/cloudstack/agent/hooks/libvirt-vm-state-change.groovy' is not
available. Transformations will not be applied.
Aug  7 19:58:29 cloud1 java: WARN [kvm.resource.LibvirtKvmAgentHook]
(agentRequest-Handler-4:) (logid:1051f59c) Groovy scripting engine is
not initialized. Data transformation skipped.
Aug  7 19:58:29 cloud1 libvirtd: 2020-08-08 02:58:29.888+0000: 8963:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:30 cloud1 libvirtd: 2020-08-08 02:58:30.004+0000: 8966:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:30 cloud1 libvirtd: 2020-08-08 02:58:30.120+0000: 8965:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:30 cloud1 libvirtd: 2020-08-08 02:58:30.237+0000: 8967:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:30 cloud1 libvirtd: 2020-08-08 02:58:30.353+0000: 8964:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:30 cloud1 libvirtd: 2020-08-08 02:58:30.476+0000: 8963:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:30 cloud1 libvirtd: 2020-08-08 02:58:30.592+0000: 8966:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:30 cloud1 libvirtd: 2020-08-08 02:58:30.707+0000: 8965:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:30 cloud1 libvirtd: 2020-08-08 02:58:30.824+0000: 8967:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:30 cloud1 libvirtd: 2020-08-08 02:58:30.940+0000: 8964:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:31 cloud1 libvirtd: 2020-08-08 02:58:31.056+0000: 8963:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:31 cloud1 libvirtd: 2020-08-08 02:58:31.172+0000: 8966:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:31 cloud1 libvirtd: 2020-08-08 02:58:31.288+0000: 8965:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:31 cloud1 kernel: kvm [9959]: vcpu0 disabled perfctr wrmsr:
0xc2 data 0xffff
Aug  7 19:58:31 cloud1 libvirtd: 2020-08-08 02:58:31.405+0000: 8967:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:31 cloud1 libvirtd: 2020-08-08 02:58:31.521+0000: 8964:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:31 cloud1 libvirtd: 2020-08-08 02:58:31.637+0000: 8963:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:31 cloud1 libvirtd: 2020-08-08 02:58:31.753+0000: 8966:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:31 cloud1 libvirtd: 2020-08-08 02:58:31.868+0000: 8965:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:31 cloud1 libvirtd: 2020-08-08 02:58:31.986+0000: 8967:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:32 cloud1 libvirtd: 2020-08-08 02:58:32.102+0000: 8964:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:32 cloud1 libvirtd: 2020-08-08 02:58:32.219+0000: 8963:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:32 cloud1 libvirtd: 2020-08-08 02:58:32.335+0000: 8966:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:32 cloud1 libvirtd: 2020-08-08 02:58:32.452+0000: 8965:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:32 cloud1 libvirtd: 2020-08-08 02:58:32.568+0000: 8967:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:32 cloud1 libvirtd: 2020-08-08 02:58:32.686+0000: 8964:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:32 cloud1 libvirtd: 2020-08-08 02:58:32.803+0000: 8963:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:32 cloud1 libvirtd: 2020-08-08 02:58:32.921+0000: 8966:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:33 cloud1 libvirtd: 2020-08-08 02:58:33.037+0000: 8965:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:33 cloud1 libvirtd: 2020-08-08 02:58:33.154+0000: 8967:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:33 cloud1 libvirtd: 2020-08-08 02:58:33.270+0000: 8964:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:33 cloud1 libvirtd: 2020-08-08 02:58:33.387+0000: 8963:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:33 cloud1 libvirtd: 2020-08-08 02:58:33.505+0000: 8966:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:33 cloud1 libvirtd: 2020-08-08 02:58:33.623+0000: 8965:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:33 cloud1 libvirtd: 2020-08-08 02:58:33.740+0000: 8967:
error : qemuDomainAgentAvailable:9144 : Guest agent is not responding:
QEMU guest agent is not connected
Aug  7 19:58:33 cloud1 libvirtd: 2020-08-08 02:58:33.856+0000: 8964:
warning : qemuDomainObjTaint:7530 : Domain id=1 name='r-739-VM'
uuid=7f5bcd06-3c91-4b6c-a67f-f031a18db38a is tainted: custom-ga-command
Aug  7 19:58:33 cloud1 ntpd[1165]: Listen normally on 22 bond0.102
fe80::202:c9ff:fe52:2bc6 UDP 123
Aug  7 19:58:33 cloud1 ntpd[1165]: Listen normally on 23 brbond0-102
2001:1890:16b9:5008:202:c9ff:fe52:2bc6 UDP 123
Aug  7 19:58:33 cloud1 virtlogd: 2020-08-08 02:58:33.857+0000: 5817:
info : libvirt version: 4.5.0, package: 23.el7_7.6 (CentOS BuildSystem
<http://bugs.centos.org>, 2020-03-17-23:39:10, x86-01.bsys.centos.org)
Aug  7 19:58:33 cloud1 virtlogd: 2020-08-08 02:58:33.857+0000: 5817:
info : hostname: cloud1.viakoo.com
Aug  7 19:58:33 cloud1 virtlogd: 2020-08-08 02:58:33.857+0000: 5817:
error : virLogHandlerDomainOpenLogFile:390 : Cannot open log file:
'/var/log/libvirt/qemu/r-739-VM.log': Device or resource busy
Aug  7 19:58:33 cloud1 ntpd[1165]: Listen normally on 24 vnet1
fe80::fc00:a9ff:fefe:255 UDP 123
Aug  7 19:58:33 cloud1 libvirtd: 2020-08-08 02:58:33.857+0000: 8964:
error : virNetClientProgramDispatchError:174 : Cannot open log file:
'/var/log/libvirt/qemu/r-739-VM.log': Device or resource busy
Aug  7 19:58:33 cloud1 libvirtd: 2020-08-08 02:58:33.857+0000: 8964:
warning : qemuDomainObjTaint:7544 : Unable to open domainlog
Aug  7 19:58:33 cloud1 ntpd[1165]: Listen normally on 25 vnet0
fe80::fc00:6dff:fe02:8f01 UDP 123
Aug  7 19:58:33 cloud1 ntpd[1165]: Listen normally on 26 brbond0-102
fe80::8c1a:dfff:fe00:c2e5 UDP 123
Aug  7 19:58:41 cloud1 kernel: brbond0-102: port 2(vnet0) entered
disabled state
Aug  7 19:58:41 cloud1 kernel: device vnet0 left promiscuous mode
Aug  7 19:58:41 cloud1 kernel: brbond0-102: port 2(vnet0) entered
disabled state
Aug  7 19:58:41 cloud1 kernel: cloud0: port 1(vnet1) entered disabled state
Aug  7 19:58:41 cloud1 kernel: device vnet1 left promiscuous mode
Aug  7 19:58:41 cloud1 kernel: cloud0: port 1(vnet1) entered disabled state
Aug  7 19:58:41 cloud1 libvirtd: 2020-08-08 02:58:41.936+0000: 8962:
error : qemuMonitorIO:718 : internal error: End of file from qemu monitor
Aug  7 19:58:41 cloud1 kvm: 0 guests now active
Aug  7 19:58:41 cloud1 systemd-machined: Machine qemu-1-r-739-VM terminated.
Aug  7 19:58:43 cloud1 java: libvirt: QEMU Driver error : Domain not
found: no domain with matching uuid
'7f5bcd06-3c91-4b6c-a67f-f031a18db38a' (r-739-VM)
Aug  7 19:58:43 cloud1 java: WARN [kvm.resource.LibvirtKvmAgentHook]
(agentRequest-Handler-2:) (logid:1051f59c) Groovy script
'/etc/cloudstack/agent/hooks/libvirt-vm-state-change.groovy' is not
available. Transformations will not be applied.
Aug  7 19:58:43 cloud1 java: WARN [kvm.resource.LibvirtKvmAgentHook]
(agentRequest-Handler-2:) (logid:1051f59c) Groovy scripting engine is
not initialized. Data transformation skipped.
Aug  7 19:58:43 cloud1 kernel: brbond0-102: port 1(bond0.102) entered
disabled state
Aug  7 19:58:43 cloud1 kernel: device bond0.102 left promiscuous mode
Aug  7 19:58:43 cloud1 kernel: brbond0-102: port 1(bond0.102) entered
disabled state
Aug  7 19:58:43 cloud1 java: libvirt: QEMU Driver error : Domain not
found: no domain with matching name 'r-739-VM'
Aug  7 19:58:43 cloud1 java: INFO [kvm.resource.LibvirtConnection]
(agentRequest-Handler-5:) (logid:1051f59c) No existing libvirtd
connection found. Opening a new one
Aug  7 19:58:43 cloud1 java: libvirt: LXC Driver error : Domain not
found: No domain with matching name 'r-739-VM'
Aug  7 19:58:43 cloud1 java: WARN [kvm.resource.LibvirtConnection]
(agentRequest-Handler-5:) (logid:1051f59c) Can not find a connection for
Instance r-739-VM. Assuming the default connection.
Aug  7 19:58:43 cloud1 java: libvirt: QEMU Driver error : Domain not
found: no domain with matching name 'r-739-VM'
Aug  7 19:58:43 cloud1 java: libvirt: QEMU Driver error : Domain not
found: no domain with matching name 'r-739-VM'
Aug  7 19:58:43 cloud1 java: libvirt: QEMU Driver error : Domain not
found: no domain with matching name 'r-739-VM'
Aug  7 19:58:43 cloud1 java: libvirt: QEMU Driver error : Domain not
found: no domain with matching name 'r-739-VM'
Aug  7 19:58:43 cloud1 java: WARN [kvm.resource.LibvirtKvmAgentHook]
(agentRequest-Handler-5:) (logid:1051f59c) Groovy script
'/etc/cloudstack/agent/hooks/libvirt-vm-state-change.groovy' is not
available. Transformations will not be applied.
Aug  7 19:58:43 cloud1 java: WARN [kvm.resource.LibvirtKvmAgentHook]
(agentRequest-Handler-5:) (logid:1051f59c) Groovy scripting engine is
not initialized. Data transformation skipped.
Aug  7 19:58:44 cloud1 ntpd[1165]: Deleting interface #26 brbond0-102,
fe80::8c1a:dfff:fe00:c2e5#123, interface stats: received=0, sent=0,
dropped=0, active_time=11 secs
Aug  7 19:58:44 cloud1 ntpd[1165]: Deleting interface #25 vnet0,
fe80::fc00:6dff:fe02:8f01#123, interface stats: received=0, sent=0,
dropped=0, active_time=11 secs
Aug  7 19:58:44 cloud1 ntpd[1165]: Deleting interface #24 vnet1,
fe80::fc00:a9ff:fefe:255#123, interface stats: received=0, sent=0,
dropped=0, active_time=11 secs
Aug  7 19:58:44 cloud1 ntpd[1165]: Deleting interface #23 brbond0-102,
2001:1890:16b9:5008:202:c9ff:fe52:2bc6#123, interface stats: received=0,
sent=0, dropped=0, active_time=11 secs
Aug  7 19:58:44 cloud1 ntpd[1165]: Deleting interface #22 bond0.102,
fe80::202:c9ff:fe52:2bc6#123, interface stats: received=0, sent=0,
dropped=0, active_time=11 secs

--------------------------------/snip--------------------------------------------


/var/log/libvirt/qemu/r-739-VM.log

-------------------------------------------snip-----------------------------------------------------------------------------------------------

2020-08-08 02:58:29.657+0000: starting up libvirt version: 4.5.0,
package: 23.el7_7.6 (CentOS BuildSystem <http://bugs.centos.org>,
2020-03-17-23:39:10, x86-01.bsys.centos.org), qemu version: 1.5.3
(qemu-kvm-1.5.3-167.el7_7.4), kernel: 3.10.0-862.14.4.el7.x86_64,
hostname: cloud1.viakoo.com
LC_ALL=C \
PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin \
QEMU_AUDIO_DRV=none \
/usr/libexec/qemu-kvm \
-name r-739-VM \
-S \
-machine pc-i440fx-rhel7.0.0,accel=kvm,usb=off,dump-guest-core=off \
-m 256 \
-realtime mlock=off \
-smp 1,sockets=1,cores=1,threads=1 \
-uuid 7f5bcd06-3c91-4b6c-a67f-f031a18db38a \
-smbios 'type=1,manufacturer=Apache Software
Foundation,product=CloudStack KVM
Hypervisor,uuid=7f5bcd06-3c91-4b6c-a67f-f031a18db38a' \
-no-user-config \
-nodefaults \
-chardev
socket,id=charmonitor,path=/var/lib/libvirt/qemu/domain-1-r-739-VM/monitor.sock,server,nowait
\
-mon chardev=charmonitor,id=monitor,mode=control \
-rtc base=utc \
-no-shutdown \
-boot strict=on \
-device piix3-usb-uhci,id=usb,bus=pci.0,addr=0x1.0x2 \
-device virtio-serial-pci,id=virtio-serial0,bus=pci.0,addr=0x5 \
-drive
file=/mnt/0ab13de9-2310-334c-b438-94dfb0b8ec84/daf7616b-f13b-4d4f-89cc-614709a31aad,format=qcow2,if=none,id=drive-virtio-disk0,serial=daf7616bf13b4d4f89cc,cache=none
\
-device
virtio-blk-pci,scsi=off,bus=pci.0,addr=0x6,drive=drive-virtio-disk0,id=virtio-disk0,bootindex=2
\
-drive
file=/usr/share/cloudstack-common/vms/systemvm.iso,format=raw,if=none,id=drive-ide0-1-0,readonly=on
\
-device
ide-cd,bus=ide.1,unit=0,drive=drive-ide0-1-0,id=ide0-1-0,bootindex=1 \
-netdev tap,fd=28,id=hostnet0,vhost=on,vhostfd=30 \
-device
virtio-net-pci,netdev=hostnet0,id=net0,mac=1e:00:6d:02:8f:01,bus=pci.0,addr=0x3,rombar=0,romfile=
\
-netdev tap,fd=31,id=hostnet1,vhost=on,vhostfd=33 \
-device
virtio-net-pci,netdev=hostnet1,id=net1,mac=0e:00:a9:fe:02:55,bus=pci.0,addr=0x4,rombar=0,romfile=
\
-chardev pty,id=charserial0 \
-device isa-serial,chardev=charserial0,id=serial0 \
-chardev
socket,id=charchannel0,path=/var/lib/libvirt/qemu/r-739-VM.org.qemu.guest_agent.0,server,nowait
\
-device
virtserialport,bus=virtio-serial0.0,nr=1,chardev=charchannel0,id=channel0,name=org.qemu.guest_agent.0
\
-device usb-tablet,id=input0,bus=usb.0,port=1 \
-vnc 10.100.255.1:0,password \
-vga cirrus \
-device i6300esb,id=watchdog0,bus=pci.0,addr=0x8 \
-watchdog-action none \
-device virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x7 \
-msg timestamp=on
2020-08-08 02:58:29.657+0000: Domain id=1 is tainted: high-privileges
char device redirected to /dev/pts/4 (label charserial0)
qemu: terminating on signal 15 from pid 8962
2020-08-08 02:58:42.136+0000: shutting down, reason=shutdown
[----------------------------------------------------- snip
----------------------------------------------]

management_server.log says what you'd expect if the agent can't connect:


------------------------------- snip
----------------------------------------------

2020-08-08 02:57:49,925 DEBUG [c.c.s.StatsCollector]
(StatsCollector-5:ctx-303590ea) (logid:35b3a97e) There is no secondary
storage VM for secondary storage host secondary2
2020-08-08 02:57:49,926 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(StatsCollector-5:ctx-303590ea) (logid:35b3a97e)
getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand
2020-08-08 02:57:49,926 DEBUG [c.c.h.XenServerGuru]
(StatsCollector-5:ctx-303590ea) (logid:35b3a97e) We are returning the
default host to execute commands because the command is not of Copy type.
2020-08-08 02:57:50,338 DEBUG [c.c.a.t.Request]
(StatsCollector-5:ctx-303590ea) (logid:35b3a97e) Seq
26-6280551155344867397: Received:  { Ans: , MgmtId: 11967559506, via:
26(cloud1.viakoo.com), Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2020-08-08 02:57:50,339 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(StatsCollector-5:ctx-303590ea) (logid:35b3a97e)
getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand
2020-08-08 02:57:50,339 DEBUG [c.c.h.XenServerGuru]
(StatsCollector-5:ctx-303590ea) (logid:35b3a97e) We are returning the
default host to execute commands because the command is not of Copy type.
2020-08-08 02:57:50,559 DEBUG [c.c.a.t.Request]
(StatsCollector-5:ctx-303590ea) (logid:35b3a97e) Seq
26-6280551155344867398: Received:  { Ans: , MgmtId: 11967559506, via:
26(cloud1.viakoo.com), Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2020-08-08 02:57:56,168 DEBUG
[c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-c3bcee9d) (logid:6c188e96) Found 0 routers to
update status.
2020-08-08 02:57:56,169 DEBUG
[c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-c3bcee9d) (logid:6c188e96) Found 0 VPC's to
update Redundant State.
2020-08-08 02:57:56,170 DEBUG
[c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-c3bcee9d) (logid:6c188e96) Found 0 networks
to update RvR status.
2020-08-08 02:58:02,877 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-8:null) (logid:) Ping from Routing host
26(cloud1.viakoo.com)
2020-08-08 02:58:02,877 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-8:null) (logid:) Process host VM state report from
ping process. host: 26
2020-08-08 02:58:02,877 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-8:null) (logid:) Process VM state report. host:
26, number of records in report: 0
2020-08-08 02:58:02,878 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-8:null) (logid:) Done with process of VM state
report. host: 26
2020-08-08 02:58:06,316 DEBUG [c.c.a.ApiServlet]
(qtp873610597-716:ctx-89680f8b) (logid:25f4c5ea) ===START===
172.31.254.254 -- GET
listall=true&projectid=-1&page=1&pagesize=20&command=listRouters&response=json
2020-08-08 02:58:06,325 DEBUG [c.c.a.ApiServer]
(qtp873610597-716:ctx-89680f8b ctx-4340b9a3) (logid:25f4c5ea) CIDRs from
which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is
allowed to perform API calls: 0.0.0.0/0,::/0
2020-08-08 02:58:06,349 DEBUG [c.c.a.ApiServlet]
(qtp873610597-716:ctx-89680f8b ctx-4340b9a3) (logid:25f4c5ea) ===END===
172.31.254.254 -- GET
listall=true&projectid=-1&page=1&pagesize=20&command=listRouters&response=json
2020-08-08 02:58:10,178 DEBUG [c.c.a.ApiServlet]
(qtp873610597-660:ctx-369b56f0) (logid:fb2f9e11) ===START===
172.31.254.254 -- GET
listall=true&projectid=-1&id=7f5bcd06-3c91-4b6c-a67f-f031a18db38a&page=1&pagesize=20&command=listRouters&response=json
2020-08-08 02:58:10,188 DEBUG [c.c.a.ApiServer]
(qtp873610597-660:ctx-369b56f0 ctx-82e3b5e1) (logid:fb2f9e11) CIDRs from
which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is
allowed to perform API calls: 0.0.0.0/0,::/0
2020-08-08 02:58:10,205 DEBUG [c.c.a.ApiServlet]
(qtp873610597-660:ctx-369b56f0 ctx-82e3b5e1) (logid:fb2f9e11) ===END===
172.31.254.254 -- GET
listall=true&projectid=-1&id=7f5bcd06-3c91-4b6c-a67f-f031a18db38a&page=1&pagesize=20&command=listRouters&response=json
2020-08-08 02:58:17,075 DEBUG [c.c.c.ConsoleProxyManagerImpl]
(consoleproxy-1:ctx-08c09898) (logid:e7d511bf) Zone 1 is not ready to
launch console proxy yet
2020-08-08 02:58:26,169 DEBUG
[c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-c117276a) (logid:c45cd8af) Found 0 routers to
update status.
2020-08-08 02:58:26,170 DEBUG
[c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-c117276a) (logid:c45cd8af) Found 0 VPC's to
update Redundant State.
2020-08-08 02:58:26,172 DEBUG
[c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-c117276a) (logid:c45cd8af) Found 0 networks
to update RvR status.
2020-08-08 02:58:26,894 DEBUG [c.c.a.ApiServlet]
(qtp873610597-704:ctx-f389cc54) (logid:9a378b74) ===START===
172.31.254.254 -- GET
id=7f5bcd06-3c91-4b6c-a67f-f031a18db38a&command=startRouter&response=json
2020-08-08 02:58:26,903 DEBUG [c.c.a.ApiServer]
(qtp873610597-704:ctx-f389cc54 ctx-f61d9f91) (logid:9a378b74) CIDRs from
which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is
allowed to perform API calls: 0.0.0.0/0,::/0
2020-08-08 02:58:26,959 INFO  [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-11:ctx-b6673908 job-132458) (logid:031ef431) Add
job-132458 into job monitoring
2020-08-08 02:58:26,962 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(qtp873610597-704:ctx-f389cc54 ctx-f61d9f91) (logid:9a378b74) submit
async job-132458, details: AsyncJobVO {id:132458, userId: 2, accountId:
2, instanceType: DomainRouter, instanceId: 739, cmd:
org.apache.cloudstack.api.command.admin.router.StartRouterCmd, cmdInfo:
{"response":"json","ctxUserId":"2","httpmethod":"GET","ctxStartEventId":"12212","id":"7f5bcd06-3c91-4b6c-a67f-f031a18db38a","ctxDetails":"{\"interface
com.cloud.vm.VirtualMachine\":\"7f5bcd06-3c91-4b6c-a67f-f031a18db38a\"}","ctxAccountId":"2","uuid":"7f5bcd06-3c91-4b6c-a67f-f031a18db38a","cmdEventType":"ROUTER.START"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
result: null, initMsid: 11967559506, completeMsid: null, lastUpdated:
null, lastPolled: null, created: null, removed: null}
2020-08-08 02:58:26,963 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-11:ctx-b6673908 job-132458) (logid:1051f59c) Executing
AsyncJobVO {id:132458, userId: 2, accountId: 2, instanceType:
DomainRouter, instanceId: 739, cmd:
org.apache.cloudstack.api.command.admin.router.StartRouterCmd, cmdInfo:
{"response":"json","ctxUserId":"2","httpmethod":"GET","ctxStartEventId":"12212","id":"7f5bcd06-3c91-4b6c-a67f-f031a18db38a","ctxDetails":"{\"interface
com.cloud.vm.VirtualMachine\":\"7f5bcd06-3c91-4b6c-a67f-f031a18db38a\"}","ctxAccountId":"2","uuid":"7f5bcd06-3c91-4b6c-a67f-f031a18db38a","cmdEventType":"ROUTER.START"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
result: null, initMsid: 11967559506, completeMsid: null, lastUpdated:
null, lastPolled: null, created: null, removed: null}
2020-08-08 02:58:26,963 DEBUG [c.c.a.ApiServlet]
(qtp873610597-704:ctx-f389cc54 ctx-f61d9f91) (logid:9a378b74) ===END===
172.31.254.254 -- GET
id=7f5bcd06-3c91-4b6c-a67f-f031a18db38a&command=startRouter&response=json
2020-08-08 02:58:27,002 DEBUG [c.c.a.ApiServlet]
(qtp873610597-720:ctx-93876239) (logid:fd2e4787) ===START===
172.31.254.254 -- GET
jobId=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json
2020-08-08 02:58:27,008 DEBUG [c.c.a.ApiServer]
(qtp873610597-720:ctx-93876239 ctx-83dfeeb7) (logid:fd2e4787) CIDRs from
which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is
allowed to perform API calls: 0.0.0.0/0,::/0
2020-08-08 02:58:27,024 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-11:ctx-b6673908 job-132458 ctx-b0e5ebe4)
(logid:1051f59c) Starting network Ntwk[217|Guest|7]...
2020-08-08 02:58:27,029 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-11:ctx-b6673908 job-132458 ctx-b0e5ebe4)
(logid:1051f59c) Network id=217 is already implemented
2020-08-08 02:58:27,030 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-11:ctx-b6673908 job-132458 ctx-b0e5ebe4)
(logid:1051f59c) Starting network Ntwk[202|Control|3]...
2020-08-08 02:58:27,031 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-11:ctx-b6673908 job-132458 ctx-b0e5ebe4)
(logid:1051f59c) Network id=202 is already implemented
2020-08-08 02:58:27,033 DEBUG [c.c.n.r.NetworkHelperImpl]
(API-Job-Executor-11:ctx-b6673908 job-132458 ctx-b0e5ebe4)
(logid:1051f59c) Starting router VM[DomainRouter|r-739-VM]
2020-08-08 02:58:27,036 DEBUG [c.c.a.ApiServlet]
(qtp873610597-720:ctx-93876239 ctx-83dfeeb7) (logid:fd2e4787) ===END===
172.31.254.254 -- GET
jobId=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json
2020-08-08 02:58:27,060 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-11:ctx-b6673908 job-132458 ctx-b0e5ebe4)
(logid:1051f59c) Sync job-132459 execution on object VmWorkJobQueue.739
2020-08-08 02:58:27,647 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-a1435850) (logid:4fbdbb7b) Execute
sync-queue item: SyncQueueItemVO {id:273, queueId: 121029, contentType:
AsyncJob, contentId: 132459, lastProcessMsid: 11967559506,
lastprocessNumber: 15, lastProcessTime: Sat Aug 08 02:58:27 UTC 2020,
created: Sat Aug 08 02:58:27 UTC 2020}
2020-08-08 02:58:27,648 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-a1435850) (logid:4fbdbb7b) Schedule queued
job-132459
2020-08-08 02:58:27,688 INFO  [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459)
(logid:51547bf6) Add job-132459 into job monitoring
2020-08-08 02:58:27,695 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459)
(logid:1051f59c) Executing AsyncJobVO {id:132459, userId: 2, accountId:
2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart,
cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAC43QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AA5SZXN0YXJ0TmV0d29ya3QAP3JPMEFCWE55QUJGcVlYWmhMbXhoYm1jdVFtOXZiR1ZoYnMwZ2NvRFZuUHJ1QWdBQldnQUZkbUZzZFdWNGNBRXhw,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
result: null, initMsid: 11967559506, completeMsid: null, lastUpdated:
null, lastPolled: null, created: Sat Aug 08 02:58:27 UTC 2020, removed:
null}
2020-08-08 02:58:27,696 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459)
(logid:1051f59c) Run VM work job: com.cloud.vm.VmWorkStart for VM 739,
job origin: 132458
2020-08-08 02:58:27,699 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Execute VM work job:
com.cloud.vm.VmWorkStart{"dcId":0,"rawParams":{"RestartNetwork":"rO0ABXNyABFqYXZhLmxhbmcuQm9vbGVhbs0gcoDVnPruAgABWgAFdmFsdWV4cAE"},"userId":2,"accountId":2,"vmId":739,"handlerName":"VirtualMachineManagerImpl"}
2020-08-08 02:58:27,708 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) VM state transitted from :Stopped to Starting with
event: StartRequestedvm's original host id: null new host id: null host
id before state transition: null
2020-08-08 02:58:27,708 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Successfully transitioned to start state for
VM[DomainRouter|r-739-VM] reservation id =
604856f5-c66a-40a4-8634-f2f7223295f9
2020-08-08 02:58:27,731 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Deploy avoids pods: null, clusters: null, hosts: null
2020-08-08 02:58:27,735 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Root volume is ready, need to place VM in volume's cluster
2020-08-08 02:58:27,736 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Vol[874|vm=739|ROOT] is READY, changing deployment plan
to use this pool's dcId: 1 , podId: null , and clusterId: null
2020-08-08 02:58:27,736 INFO  [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c)  Uefi params UefiFlag: null Boot Type: null Boot Mode: null
2020-08-08 02:58:27,743 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) DeploymentPlanner allocation algorithm: null
2020-08-08 02:58:27,743 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Trying to allocate a host and storage pools from dc:1,
pod:null,cluster:null, requested cpu: 500, requested ram: 268435456
2020-08-08 02:58:27,743 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Is ROOT volume READY (pool already allocated)?: Yes
2020-08-08 02:58:27,743 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Deploy avoids pods: [], clusters: [], hosts: []
2020-08-08 02:58:27,744 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Searching all possible resources under this Zone: 1
2020-08-08 02:58:27,745 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Listing clusters in order of aggregate capacity, that
have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
2020-08-08 02:58:27,747 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Removing from the clusterId list these clusters from
avoid set: []
2020-08-08 02:58:27,752 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Checking resources in Cluster: 1 under Pod: 1
2020-08-08 02:58:27,753 INFO  [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99
FirstFitRoutingAllocator) (logid:1051f59c)  Guest VM is requested with
Cusotm[UEFI] Boot Type false
2020-08-08 02:58:27,753 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99
FirstFitRoutingAllocator) (logid:1051f59c) Looking for hosts in dc: 1
pod:1  cluster:1
2020-08-08 02:58:27,755 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99
FirstFitRoutingAllocator) (logid:1051f59c) FirstFitAllocator has 1 hosts
to check for allocation: [Host[-26-Routing]]
2020-08-08 02:58:27,757 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99
FirstFitRoutingAllocator) (logid:1051f59c) Found 1 hosts for allocation
after prioritization: [Host[-26-Routing]]
2020-08-08 02:58:27,757 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99
FirstFitRoutingAllocator) (logid:1051f59c) Looking for speed=500Mhz, Ram=256
2020-08-08 02:58:27,761 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99
FirstFitRoutingAllocator) (logid:1051f59c) Host: 26 has cpu capability
(cpu:24, speed:3068) to support requested CPU: 1 and requested speed: 500
2020-08-08 02:58:27,761 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99
FirstFitRoutingAllocator) (logid:1051f59c) Checking if host: 26 has
enough capacity for requested CPU: 500 and requested RAM: 268435456 ,
cpuOverprovisioningFactor: 2.0
2020-08-08 02:58:27,762 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99
FirstFitRoutingAllocator) (logid:1051f59c) Hosts's actual total CPU:
73632 and CPU after applying overprovisioning: 147264
2020-08-08 02:58:27,762 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99
FirstFitRoutingAllocator) (logid:1051f59c) Free CPU: 147264 , Requested
CPU: 500
2020-08-08 02:58:27,762 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99
FirstFitRoutingAllocator) (logid:1051f59c) Free RAM: 250977878016 ,
Requested RAM: 268435456
2020-08-08 02:58:27,762 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99
FirstFitRoutingAllocator) (logid:1051f59c) Host has enough CPU and RAM
available
2020-08-08 02:58:27,762 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99
FirstFitRoutingAllocator) (logid:1051f59c) STATS: Can alloc CPU from
host: 26, used: 0, reserved: 0, actual total: 73632, total with
overprovisioning: 147264; requested cpu:500,alloc_from_last_host?:false
,considerReservedCapacity?: true
2020-08-08 02:58:27,762 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99
FirstFitRoutingAllocator) (logid:1051f59c) STATS: Can alloc MEM from
host: 26, used: 0, reserved: 0, total: 250977878016; requested mem:
268435456,alloc_from_last_host?:false ,considerReservedCapacity?: true
2020-08-08 02:58:27,762 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99
FirstFitRoutingAllocator) (logid:1051f59c) Found a suitable host, adding
to list: 26
2020-08-08 02:58:27,762 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99
FirstFitRoutingAllocator) (logid:1051f59c) Host Allocator returning 1
suitable hosts
2020-08-08 02:58:27,764 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Checking suitable pools for volume (Id, Type): (874,ROOT)
2020-08-08 02:58:27,764 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Volume has pool already allocated, checking if pool can
be reused, poolId: 5
2020-08-08 02:58:27,766 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Planner need not allocate a pool for this volume since
its READY
2020-08-08 02:58:27,766 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Trying to find a potenial host and associated storage
pools from the suitable host/pool lists for this VM
2020-08-08 02:58:27,766 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Checking if host: 26 can access any suitable storage
pool for volume: ROOT
2020-08-08 02:58:27,767 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Host: 26 can access pool: 5
2020-08-08 02:58:27,787 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Found a potential host id: 26 name: cloud1.viakoo.com
and associated storage pools for this VM
2020-08-08 02:58:27,788 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Returning Deployment Destination:
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(26)-Storage()]
2020-08-08 02:58:27,788 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Deployment found  - P0=VM[DomainRouter|r-739-VM],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(26)-Storage()]
2020-08-08 02:58:27,923 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) VM state transitted from :Starting to Starting with
event: OperationRetryvm's original host id: null new host id: 26 host id
before state transition: null
2020-08-08 02:58:27,931 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Hosts's actual total CPU: 73632 and CPU after applying
overprovisioning: 147264
2020-08-08 02:58:27,931 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) We are allocating VM, increasing the used capacity of
this host:26
2020-08-08 02:58:27,931 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Current Used CPU: 0 , Free CPU:147264 ,Requested CPU: 500
2020-08-08 02:58:27,931 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Current Used RAM: 0 , Free RAM:250977878016 ,Requested
RAM: 268435456
2020-08-08 02:58:27,931 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) CPU STATS after allocation: for host: 26, old used: 0,
old reserved: 0, actual total: 73632, total with overprovisioning:
147264; new used:500, reserved:0; requested cpu:500,alloc_from_last:false
2020-08-08 02:58:27,932 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) RAM STATS after allocation: for host: 26, old used: 0,
old reserved: 0, total: 250977878016; new used: 268435456, reserved: 0;
requested mem: 268435456,alloc_from_last:false
2020-08-08 02:58:27,934 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Host: 26 has cpu capability (cpu:24, speed:3068) to
support requested CPU: 1 and requested speed: 500
2020-08-08 02:58:27,934 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Checking if host: 26 has enough capacity for requested
CPU: 500 and requested RAM: 268435456 , cpuOverprovisioningFactor: 2.0
2020-08-08 02:58:27,935 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Hosts's actual total CPU: 73632 and CPU after applying
overprovisioning: 147264
2020-08-08 02:58:27,935 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) We need to allocate to the last host again, so checking
if there is enough reserved capacity
2020-08-08 02:58:27,935 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Reserved CPU: 0 , Requested CPU: 500
2020-08-08 02:58:27,935 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Reserved RAM: 0 , Requested RAM: 268435456
2020-08-08 02:58:27,935 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) STATS: Failed to alloc resource from host: 26
reservedCpu: 0, requested cpu: 500, reservedMem: 0, requested mem: 268435456
2020-08-08 02:58:27,935 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Host does not have enough reserved CPU available,
cannot allocate to this host.
2020-08-08 02:58:27,935 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Checking if host: 26 has enough capacity for requested
CPU: 500 and requested RAM: 268435456 , cpuOverprovisioningFactor: 2.0
2020-08-08 02:58:27,936 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Hosts's actual total CPU: 73632 and CPU after applying
overprovisioning: 147264
2020-08-08 02:58:27,936 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Free CPU: 147264 , Requested CPU: 500
2020-08-08 02:58:27,936 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Free RAM: 250977878016 , Requested RAM: 268435456
2020-08-08 02:58:27,936 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Host has enough CPU and RAM available
2020-08-08 02:58:27,936 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) STATS: Can alloc CPU from host: 26, used: 0, reserved:
0, actual total: 73632, total with overprovisioning: 147264; requested
cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true
2020-08-08 02:58:27,936 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) STATS: Can alloc MEM from host: 26, used: 0, reserved:
0, total: 250977878016; requested mem:
268435456,alloc_from_last_host?:false ,considerReservedCapacity?: true
2020-08-08 02:58:27,970 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Service SecurityGroup is not supported in the network
id=217
2020-08-08 02:58:28,000 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Asking VirtualRouter to prepare for
Nic[1846-739-null-10.102.1.0]
2020-08-08 02:58:28,001 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Service SecurityGroup is not supported in the network
id=217
2020-08-08 02:58:28,057 DEBUG [c.c.n.g.ControlNetworkGuru]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Reserved NIC for r-739-VM [ipv4:169.254.2.85
netmask:255.255.0.0 gateway:169.254.0.1]
2020-08-08 02:58:28,086 DEBUG [o.a.c.e.o.VolumeOrchestrator]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) No need to recreate the volume: Vol[874|vm=739|ROOT],
since it already has a pool assigned: 5, adding disk to VM
2020-08-08 02:58:28,113 DEBUG
[c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Boot Args for VM[DomainRouter|r-739-VM]:  template=domP
name=r-739-VM eth0ip=10.102.1.0 eth0mask=255.255.0.0 gateway=10.102.0.1
domain=cloud.viakoo.com cidrsize=16 dhcprange=10.102.0.1
eth1ip=169.254.2.85 eth1mask=255.255.0.0 type=dhcpsrvr
disable_rp_filter=true dns1=10.120.0.5 dns2=10.31.1.2 exposedns=true
baremetalnotificationsecuritykey=DBIgxuilvx4rI2SiwghbxHZy/Rurqu36y3SWPNuEL0bJbjoOlbagUROZYbeNTCAd5rdvjGfTISs4e6CHaHEZh1LS7LxYurSzdLhmsPiL8OuvYpK7J6XR68QOwqJY6xVa
baremetalnotificationapikey=zXh634lHNEMDgxQnXOiD-2KGhp6QHm6AetMPiMcRsY3kf8Wrx5AyxIyv0EIwz35rgc-DY0_3zEjU1od_bj_xhw
host=10.100.255.2 port=8080
2020-08-08 02:58:28,117 DEBUG [c.c.a.ApiServlet]
(qtp873610597-705:ctx-6a424cc2) (logid:c4c0c75f) ===START===
172.31.254.254 -- GET
jobid=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json
2020-08-08 02:58:28,122 DEBUG [c.c.a.ApiServer]
(qtp873610597-705:ctx-6a424cc2 ctx-331fec93) (logid:c4c0c75f) CIDRs from
which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is
allowed to perform API calls: 0.0.0.0/0,::/0
2020-08-08 02:58:28,152 DEBUG
[c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Resending ipAssoc, port forwarding, load balancing
rules as a part of Virtual router start
2020-08-08 02:58:28,155 DEBUG
[c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Found 0 firewall Egress rule(s) to apply as a part of
domR VM[DomainRouter|r-739-VM] start.
2020-08-08 02:58:28,159 DEBUG
[c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Found0ip Aliases to revoke on the router as a part of
dhcp configuration
2020-08-08 02:58:28,159 DEBUG
[c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Found0ip Aliases to apply on the router as a part of
dhcp configuration
2020-08-08 02:58:28,161 DEBUG
[c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Creating  monitoring services on
VM[DomainRouter|r-739-VM] start...
2020-08-08 02:58:28,164 DEBUG [c.c.a.ApiServlet]
(qtp873610597-705:ctx-6a424cc2 ctx-331fec93) (logid:c4c0c75f) ===END===
172.31.254.254 -- GET
jobid=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json
2020-08-08 02:58:28,167 DEBUG
[c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) IP of control NIC 169.254.2.85
2020-08-08 02:58:29,297 DEBUG
[c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Reapplying dhcp entries as a part of domR
VM[DomainRouter|r-739-VM] start...
2020-08-08 02:58:29,301 DEBUG
[c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Reapplying vm data (userData and metaData) entries as a
part of domR VM[DomainRouter|r-739-VM] start...
2020-08-08 02:58:29,331 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Seq 26-6280551155344867399: Sending  { Cmd , MgmtId:
11967559506, via: 26(cloud1.viakoo.com), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StartCommand":{"vm":{"id":739,"name":"r-739-VM","state":"Starting","type":"DomainRouter","cpus":1,"minSpeed":250,"maxSpeed":500,"minRam":134217728,"maxRam":268435456,"arch":"x86_64","os":"Debian
GNU/Linux 8 (64-bit)","platformEmulator":"Debian GNU/Linux 8
(64-bit)","bootArgs":" template=domP name=r-739-VM eth0ip=10.102.1.0
eth0mask=255.255.0.0 gateway=10.102.0.1 domain=cloud.viakoo.com
cidrsize=16 dhcprange=10.102.0.1 eth1ip=169.254.2.85
eth1mask=255.255.0.0 type=dhcpsrvr disable_rp_filter=true
dns1=10.120.0.5 dns2=10.31.1.2 exposedns=true
baremetalnotificationsecuritykey=DBIgxuilvx4rI2SiwghbxHZy/Rurqu36y3SWPNuEL0bJbjoOlbagUROZYbeNTCAd5rdvjGfTISs4e6CHaHEZh1LS7LxYurSzdLhmsPiL8OuvYpK7J6XR68QOwqJY6xVa
baremetalnotificationapikey=zXh634lHNEMDgxQnXOiD-2KGhp6QHm6AetMPiMcRsY3kf8Wrx5AyxIyv0EIwz35rgc-DY0_3zEjU1od_bj_xhw
host=10.100.255.2
port=8080","enableHA":true,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"agjSclA5om3tBly6Uel-8A","params":{"cpuOvercommitRatio":"2.0","memoryOvercommitRatio":"2.0"},"uuid":"7f5bcd06-3c91-4b6c-a67f-f031a18db38a","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"daf7616b-f13b-4d4f-89cc-614709a31aad","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"0ab13de9-2310-334c-b438-94dfb0b8ec84","id":5,"poolType":"NetworkFilesystem","host":"10.100.255.3","path":"/storage/primary3","port":2049,"url":"NetworkFilesystem://10.100.255.3/storage/primary3/?ROLE=Primary&STOREUUID=0ab13de9-2310-334c-b438-94dfb0b8ec84","isManaged":false}},"name":"ROOT-739","size":2097152000,"path":"daf7616b-f13b-4d4f-89cc-614709a31aad","volumeId":874,"vmName":"r-739-VM","accountId":1,"format":"QCOW2","provisioningType":"THIN","id":874,"deviceId":0,"bytesReadRate":0,"bytesWriteRate":0,"iopsReadRate":0,"iopsWriteRate":0,"hypervisorType":"KVM","directDownload":false}},"diskSeq":0,"path":"daf7616b-f13b-4d4f-89cc-614709a31aad","type":"ROOT","_details":{"storageHost":"10.100.255.3","managed":"false","storagePort":"2049","volumeSize":"2097152000"}}],"nics":[{"deviceId":0,"networkRateMbps":-1,"defaultNic":true,"pxeDisable":true,"nicUuid":"71b1fd0b-4562-4773-87f8-925681933b04","details":{"PromiscuousMode":"false","MacAddressChanges":"true","ForgedTransmits":"true"},"dpdkEnabled":false,"uuid":"924eda5f-9a1f-4a8e-9423-18000dc92093","ip":"10.102.1.0","netmask":"255.255.0.0","gateway":"10.102.0.1","mac":"1e:00:6d:02:8f:01","dns1":"10.120.0.5","dns2":"10.31.1.2","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://102","isolationUri":"vlan://102","isSecurityGroupEnabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"pxeDisable":true,"nicUuid":"1c5258fa-4234-4120-b0c4-c25c4d94053d","details":{"PromiscuousMode":"false","MacAddressChanges":"true","ForgedTransmits":"true"},"dpdkEnabled":false,"uuid":"6eff5bd9-4f4d-48fe-b6ed-f50fc115947b","ip":"169.254.2.85","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:02:55","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false}],"guestOsDetails":{},"extraConfig":{}},"hostIp":"10.100.255.1","executeInSequence":false,"wait":0}},{"com.cloud.agent.api.check.CheckSshCommand":{"ip":"169.254.2.85","port":3922,"interval":6,"retries":100,"name":"r-739-VM","wait":0}},{"com.cloud.agent.api.GetDomRVersionCmd":{"accessDetails":{"router.name":"r-739-VM","router.ip":"169.254.2.85"},"wait":0}},{},{"com.cloud.agent.api.routing.AggregationControlCommand":{"action":"Start","accessDetails":{"router.name":"r-739-VM","router.ip":"169.254.2.85","router.guest.ip":"10.102.1.0"},"wait":0}},{"com.cloud.agent.api.routing.SetMonitorServiceCommand":{"services":[{"id":0,"service":"dhcp","processname":"dnsmasq","serviceName":"dnsmasq","servicePath":"/var/run/dnsmasq/dnsmasq.pid","pidFile":"/var/run/dnsmasq/dnsmasq.pid","isDefault":false},{"id":0,"service":"ssh","processname":"sshd","serviceName":"ssh","servicePath":"/var/run/sshd.pid","pidFile":"/var/run/sshd.pid","isDefault":true},{"id":0,"service":"webserver","processname":"apache2","serviceName":"apache2","servicePath":"/var/run/apache2/apache2.pid","pidFile":"/var/run/apache2/apache2.pid","isDefault":true}],"healthChecksConfig":{"gateways":"gatewaysIps=10.102.0.1
169.254.0.1
","portForwarding":"","systemThresholds":"minDiskNeeded=100.0,maxCpuUsage=100.0,maxMemoryUsage=100.0;","haproxyData":"","virtualMachines":""},"reconfigureAfterUpdate":false,"deleteFromProcessedCache":false,"accessDetails":{"router.health.checks.enabled":"true","router.guest.ip":"10.102.1.0","router.ip":"169.254.2.85","router.name":"r-739-VM","router.health.checks.advanced.interval":"10","router.health.checks.basic.interval":"3","router.health.checks.excluded":""},"wait":0}},{"com.cloud.agent.api.routing.AggregationControlCommand":{"action":"Finish","accessDetails":{"router.name":"r-739-VM","router.ip":"169.254.2.85","router.guest.ip":"10.102.1.0"},"wait":0}}]
}
2020-08-08 02:58:30,072 DEBUG [c.c.a.ApiServlet]
(qtp873610597-489:ctx-6b7e5001) (logid:b884b0f5) ===START===
172.31.254.254 -- GET
jobId=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json
2020-08-08 02:58:30,081 DEBUG [c.c.a.ApiServer]
(qtp873610597-489:ctx-6b7e5001 ctx-aa87b22a) (logid:b884b0f5) CIDRs from
which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is
allowed to perform API calls: 0.0.0.0/0,::/0
2020-08-08 02:58:30,121 DEBUG [c.c.a.ApiServlet]
(qtp873610597-489:ctx-6b7e5001 ctx-aa87b22a) (logid:b884b0f5) ===END===
172.31.254.254 -- GET
jobId=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json
2020-08-08 02:58:32,110 DEBUG [c.c.a.ApiServlet]
(qtp873610597-718:ctx-c7650e1d) (logid:903036b2) ===START===
172.31.254.254 -- GET
jobid=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json
2020-08-08 02:58:32,118 DEBUG [c.c.a.ApiServer]
(qtp873610597-718:ctx-c7650e1d ctx-c5ca5c96) (logid:903036b2) CIDRs from
which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is
allowed to perform API calls: 0.0.0.0/0,::/0
2020-08-08 02:58:32,147 DEBUG [c.c.a.ApiServlet]
(qtp873610597-718:ctx-c7650e1d ctx-c5ca5c96) (logid:903036b2) ===END===
172.31.254.254 -- GET
jobid=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json
2020-08-08 02:58:33,161 DEBUG [c.c.a.ApiServlet]
(qtp873610597-719:ctx-aec411b5) (logid:efb92a3b) ===START===
172.31.254.254 -- GET
jobId=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json
2020-08-08 02:58:33,169 DEBUG [c.c.a.ApiServer]
(qtp873610597-719:ctx-aec411b5 ctx-4fabeb59) (logid:efb92a3b) CIDRs from
which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is
allowed to perform API calls: 0.0.0.0/0,::/0
2020-08-08 02:58:33,212 DEBUG [c.c.a.ApiServlet]
(qtp873610597-719:ctx-aec411b5 ctx-4fabeb59) (logid:efb92a3b) ===END===
172.31.254.254 -- GET
jobId=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json
2020-08-08 02:58:36,109 DEBUG [c.c.a.ApiServlet]
(qtp873610597-575:ctx-38e14f95) (logid:3e9dcafa) ===START===
172.31.254.254 -- GET
jobid=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json
2020-08-08 02:58:36,117 DEBUG [c.c.a.ApiServer]
(qtp873610597-575:ctx-38e14f95 ctx-e71fc6d6) (logid:3e9dcafa) CIDRs from
which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is
allowed to perform API calls: 0.0.0.0/0,::/0
2020-08-08 02:58:36,158 DEBUG [c.c.a.ApiServlet]
(qtp873610597-575:ctx-38e14f95 ctx-e71fc6d6) (logid:3e9dcafa) ===END===
172.31.254.254 -- GET
jobid=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json
2020-08-08 02:58:36,243 DEBUG [c.c.a.ApiServlet]
(qtp873610597-660:ctx-e81164ca) (logid:cc069eb1) ===START===
172.31.254.254 -- GET
jobId=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json
2020-08-08 02:58:36,252 DEBUG [c.c.a.ApiServer]
(qtp873610597-660:ctx-e81164ca ctx-caca2a16) (logid:cc069eb1) CIDRs from
which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is
allowed to perform API calls: 0.0.0.0/0,::/0
2020-08-08 02:58:36,280 DEBUG [c.c.a.ApiServlet]
(qtp873610597-660:ctx-e81164ca ctx-caca2a16) (logid:cc069eb1) ===END===
172.31.254.254 -- GET
jobId=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json
2020-08-08 02:58:39,311 DEBUG [c.c.a.ApiServlet]
(qtp873610597-574:ctx-fb9c9d97) (logid:d04e2728) ===START===
172.31.254.254 -- GET
jobId=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json
2020-08-08 02:58:39,319 DEBUG [c.c.a.ApiServer]
(qtp873610597-574:ctx-fb9c9d97 ctx-7349af94) (logid:d04e2728) CIDRs from
which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is
allowed to perform API calls: 0.0.0.0/0,::/0
2020-08-08 02:58:39,346 DEBUG [c.c.a.ApiServlet]
(qtp873610597-574:ctx-fb9c9d97 ctx-7349af94) (logid:d04e2728) ===END===
172.31.254.254 -- GET
jobId=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json
2020-08-08 02:58:40,116 DEBUG [c.c.a.ApiServlet]
(qtp873610597-715:ctx-b6428afd) (logid:23804e39) ===START===
172.31.254.254 -- GET
jobid=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json
2020-08-08 02:58:40,125 DEBUG [c.c.a.ApiServer]
(qtp873610597-715:ctx-b6428afd ctx-8ae3fa36) (logid:23804e39) CIDRs from
which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is
allowed to perform API calls: 0.0.0.0/0,::/0
2020-08-08 02:58:40,169 DEBUG [c.c.a.ApiServlet]
(qtp873610597-715:ctx-b6428afd ctx-8ae3fa36) (logid:23804e39) ===END===
172.31.254.254 -- GET
jobid=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json
2020-08-08 02:58:41,130 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-10:null) (logid:) Seq 26-6280551155344867399:
Processing:  { Ans: , MgmtId: 11967559506, via: 26, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.StartAnswer":{"vm":{"id":739,"name":"r-739-VM","state":"Starting","type":"DomainRouter","cpus":1,"minSpeed":250,"maxSpeed":500,"minRam":134217728,"maxRam":268435456,"arch":"x86_64","os":"Debian
GNU/Linux 8 (64-bit)","platformEmulator":"Debian GNU/Linux 8
(64-bit)","bootArgs":" template=domP name=r-739-VM eth0ip=10.102.1.0
eth0mask=255.255.0.0 gateway=10.102.0.1 domain=cloud.viakoo.com
cidrsize=16 dhcprange=10.102.0.1 eth1ip=169.254.2.85
eth1mask=255.255.0.0 type=dhcpsrvr disable_rp_filter=true
dns1=10.120.0.5 dns2=10.31.1.2 exposedns=true
baremetalnotificationsecuritykey=DBIgxuilvx4rI2SiwghbxHZy/Rurqu36y3SWPNuEL0bJbjoOlbagUROZYbeNTCAd5rdvjGfTISs4e6CHaHEZh1LS7LxYurSzdLhmsPiL8OuvYpK7J6XR68QOwqJY6xVa
baremetalnotificationapikey=zXh634lHNEMDgxQnXOiD-2KGhp6QHm6AetMPiMcRsY3kf8Wrx5AyxIyv0EIwz35rgc-DY0_3zEjU1od_bj_xhw
host=10.100.255.2
port=8080","enableHA":true,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"agjSclA5om3tBly6Uel-8A","vncAddr":"10.100.255.1","params":{"cpuOvercommitRatio":"2.0","memoryOvercommitRatio":"2.0"},"uuid":"7f5bcd06-3c91-4b6c-a67f-f031a18db38a","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"daf7616b-f13b-4d4f-89cc-614709a31aad","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"0ab13de9-2310-334c-b438-94dfb0b8ec84","id":5,"poolType":"NetworkFilesystem","host":"10.100.255.3","path":"/storage/primary3","port":2049,"url":"NetworkFilesystem://10.100.255.3/storage/primary3/?ROLE=Primary&STOREUUID=0ab13de9-2310-334c-b438-94dfb0b8ec84","isManaged":false}},"name":"ROOT-739","size":2097152000,"path":"daf7616b-f13b-4d4f-89cc-614709a31aad","volumeId":874,"vmName":"r-739-VM","accountId":1,"format":"QCOW2","provisioningType":"THIN","id":874,"deviceId":0,"bytesReadRate":0,"bytesWriteRate":0,"iopsReadRate":0,"iopsWriteRate":0,"hypervisorType":"KVM","directDownload":false}},"diskSeq":0,"path":"daf7616b-f13b-4d4f-89cc-614709a31aad","type":"ROOT","_details":{"storageHost":"10.100.255.3","managed":"false","storagePort":"2049","volumeSize":"2097152000"}}],"nics":[{"deviceId":0,"networkRateMbps":-1,"defaultNic":true,"pxeDisable":true,"nicUuid":"71b1fd0b-4562-4773-87f8-925681933b04","details":{"PromiscuousMode":"false","MacAddressChanges":"true","ForgedTransmits":"true"},"dpdkEnabled":false,"uuid":"924eda5f-9a1f-4a8e-9423-18000dc92093","ip":"10.102.1.0","netmask":"255.255.0.0","gateway":"10.102.0.1","mac":"1e:00:6d:02:8f:01","dns1":"10.120.0.5","dns2":"10.31.1.2","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://102","isolationUri":"vlan://102","isSecurityGroupEnabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"pxeDisable":true,"nicUuid":"1c5258fa-4234-4120-b0c4-c25c4d94053d","details":{"PromiscuousMode":"false","MacAddressChanges":"true","ForgedTransmits":"true"},"dpdkEnabled":false,"uuid":"6eff5bd9-4f4d-48fe-b6ed-f50fc115947b","ip":"169.254.2.85","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:02:55","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false}],"guestOsDetails":{},"extraConfig":{}},"result":true,"wait":0}},{"com.cloud.agent.api.check.CheckSshAnswer":{"result":true,"wait":0}},{"com.cloud.agent.api.GetDomRVersionAnswer":{"result":false,"details":"GetDomRVersionCmd
failed","wait":0}},{"com.cloud.agent.api.Answer":{"result":false,"details":"Stopped
by previous
failure","wait":0}},{"com.cloud.agent.api.Answer":{"result":false,"details":"Stopped
by previous
failure","wait":0}},{"com.cloud.agent.api.Answer":{"result":false,"details":"Stopped
by previous
failure","wait":0}},{"com.cloud.agent.api.Answer":{"result":false,"details":"Stopped
by previous failure","wait":0}}] }
2020-08-08 02:58:41,130 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Seq 26-6280551155344867399: Received:  { Ans: , MgmtId:
11967559506, via: 26(cloud1.viakoo.com), Ver: v1, Flags: 10, {
StartAnswer, CheckSshAnswer, GetDomRVersionAnswer, Answer, Answer,
Answer, Answer } }
2020-08-08 02:58:41,169 WARN  [c.c.a.AlertManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) AlertType:: 9 | dataCenterId:: 1 | podId:: 1 |
clusterId:: null | message:: Command:
com.cloud.agent.api.GetDomRVersionCommand failed while starting virtual
router
2020-08-08 02:58:41,193 ERROR
[c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) GetDomRVersionCmd failed
2020-08-08 02:58:41,193 WARN
[c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Command: com.cloud.agent.api.GetDomRVersionCommand
failed while starting virtual router
2020-08-08 02:58:41,194 INFO  [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) The guru did not like the answers so stopping
VM[DomainRouter|r-739-VM]
2020-08-08 02:58:41,197 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Seq 26-6280551155344867400: Sending  { Cmd , MgmtId:
11967559506, via: 26(cloud1.viakoo.com), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"controlIp":"169.254.2.130","forceStop":false,"volumesToDisconnect":[],"vmName":"r-739-VM","executeInSequence":false,"wait":0}}]
}
2020-08-08 02:58:41,667 DEBUG [c.c.s.StatsCollector]
(StatsCollector-2:ctx-11392b38) (logid:d3c5e4e9) AutoScaling Monitor is
running...
2020-08-08 02:58:42,377 DEBUG [c.c.a.ApiServlet]
(qtp873610597-704:ctx-b3661e00) (logid:337d2228) ===START===
172.31.254.254 -- GET
jobId=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json
2020-08-08 02:58:42,386 DEBUG [c.c.a.ApiServer]
(qtp873610597-704:ctx-b3661e00 ctx-274fb045) (logid:337d2228) CIDRs from
which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is
allowed to perform API calls: 0.0.0.0/0,::/0
2020-08-08 02:58:42,413 DEBUG [c.c.a.ApiServlet]
(qtp873610597-704:ctx-b3661e00 ctx-274fb045) (logid:337d2228) ===END===
172.31.254.254 -- GET
jobId=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json
2020-08-08 02:58:43,486 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-6:null) (logid:) Seq 26-6280551155344867400:
Processing:  { Ans: , MgmtId: 11967559506, via: 26, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] }
2020-08-08 02:58:43,486 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Seq 26-6280551155344867400: Received:  { Ans: , MgmtId:
11967559506, via: 26(cloud1.viakoo.com), Ver: v1, Flags: 10, {
StopAnswer } }
2020-08-08 02:58:43,486 ERROR [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Failed to start instance VM[DomainRouter|r-739-VM]
com.cloud.utils.exception.ExecutionException: Unable to start
VM:7f5bcd06-3c91-4b6c-a67f-f031a18db38a due to error in finalizeStart,
not retrying
         at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1240)
         at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5227)
         at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native
Method)
         at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
         at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
         at java.base/java.lang.reflect.Method.invoke(Method.java:566)
         at
com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
         at
com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5390)
         at
com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
         at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:603)
         at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
         at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
         at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
         at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
         at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
         at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:551)
         at
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
         at
java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
         at
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
         at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
         at java.base/java.lang.Thread.run(Thread.java:834)
2020-08-08 02:58:43,539 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Cleaning up resources for the vm
VM[DomainRouter|r-739-VM] in Starting state
2020-08-08 02:58:43,547 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Seq 26-6280551155344867401: Sending  { Cmd , MgmtId:
11967559506, via: 26(cloud1.viakoo.com), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"controlIp":"169.254.2.130","forceStop":false,"volumesToDisconnect":[],"vmName":"r-739-VM","executeInSequence":false,"wait":0}}]
}
2020-08-08 02:58:43,555 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-15:null) (logid:) Seq 26-6280551155344867401:
Processing:  { Ans: , MgmtId: 11967559506, via: 26, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] }
2020-08-08 02:58:43,555 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Seq 26-6280551155344867401: Received:  { Ans: , MgmtId:
11967559506, via: 26(cloud1.viakoo.com), Ver: v1, Flags: 10, {
StopAnswer } }
2020-08-08 02:58:43,560 DEBUG
[c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Successfully updated user statistics as a part of domR
VM[DomainRouter|r-739-VM] reboot/stop
2020-08-08 02:58:43,680 DEBUG [c.c.n.g.ControlNetworkGuru]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Released nic: NicProfile[1847-739-null-null-null
2020-08-08 02:58:43,723 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Successfully released network resources for the vm
VM[DomainRouter|r-739-VM]
2020-08-08 02:58:43,723 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Successfully cleaned up resources for the VM
VM[DomainRouter|r-739-VM] in Starting state
2020-08-08 02:58:43,781 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) VM state transitted from :Starting to Stopped with
event: OperationFailedvm's original host id: null new host id: null host
id before state transition: 26
2020-08-08 02:58:43,790 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Hosts's actual total CPU: 73632 and CPU after applying
overprovisioning: 147264
2020-08-08 02:58:43,790 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Hosts's actual total RAM: 125488934912 and RAM after
applying overprovisioning: 250977878016
2020-08-08 02:58:43,790 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) release cpu from host: 26, old used: 500,reserved: 0,
actual total: 73632, total with overprovisioning: 147264; new used:
0,reserved:0; movedfromreserved: false,moveToReserveredfalse
2020-08-08 02:58:43,790 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) release mem from host: 26, old used:
268435456,reserved: 0, total: 250977878016; new used: 0,reserved:0;
movedfromreserved: false,moveToReserveredfalse
2020-08-08 02:58:43,809 ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Invocation exception, caused by:
com.cloud.exception.AgentUnavailableException: Resource [Host:26] is
unreachable: Host 26: Unable to start instance due to Unable to start
VM:7f5bcd06-3c91-4b6c-a67f-f031a18db38a due to error in finalizeStart,
not retrying
2020-08-08 02:58:43,809 INFO  [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99)
(logid:1051f59c) Rethrow exception
com.cloud.exception.AgentUnavailableException: Resource [Host:26] is
unreachable: Host 26: Unable to start instance due to Unable to start
VM:7f5bcd06-3c91-4b6c-a67f-f031a18db38a due to error in finalizeStart,
not retrying
2020-08-08 02:58:43,809 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459)
(logid:1051f59c) Done with run of VM work job: com.cloud.vm.VmWorkStart
for VM 739, job origin: 132458
2020-08-08 02:58:43,809 ERROR [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459)
(logid:1051f59c) Unable to complete AsyncJobVO {id:132459, userId: 2,
accountId: 2, instanceType: null, instanceId: null, cmd:
com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAC43QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AA5SZXN0YXJ0TmV0d29ya3QAP3JPMEFCWE55QUJGcVlYWmhMbXhoYm1jdVFtOXZiR1ZoYnMwZ2NvRFZuUHJ1QWdBQldnQUZkbUZzZFdWNGNBRXhw,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
result: null, initMsid: 11967559506, completeMsid: null, lastUpdated:
null, lastPolled: null, created: Sat Aug 08 02:58:27 UTC 2020, removed:
null}, job origin:132458
com.cloud.exception.AgentUnavailableException: Resource [Host:26] is
unreachable: Host 26: Unable to start instance due to Unable to start
VM:7f5bcd06-3c91-4b6c-a67f-f031a18db38a due to error in finalizeStart,
not retrying
         at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1276)
         at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5227)
         at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native
Method)
         at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
         at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
         at java.base/java.lang.reflect.Method.invoke(Method.java:566)
         at
com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
         at
com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5390)
         at
com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
         at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:603)
         at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
         at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
         at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
         at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
         at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
         at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:551)
         at
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
         at
java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
         at
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
         at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
         at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: com.cloud.utils.exception.ExecutionException: Unable to
start  VM:7f5bcd06-3c91-4b6c-a67f-f031a18db38a due to error in
finalizeStart, not retrying
         at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1240)
         at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5227)
         at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native
Method)
         ... 18 more
2020-08-08 02:58:43,823 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459)
(logid:1051f59c) Complete async job-132459, jobStatus: FAILED,
resultCode: 0, result:
rO0ABXNyAC1jb20uY2xvdWQuZXhjZXB0aW9uLkFnZW50VW5hdmFpbGFibGVFeGNlcHRpb24AAAAAVk1PdwIAAHhyADBjb20uY2xvdWQuZXhjZXB0aW9uLlJlc291cmNlVW5hdmFpbGFibGVFeGNlcHRpb24AAAAAVk1PfwIAAkoAA19pZEwABl9zY29wZXQAEUxqYXZhL2xhbmcvQ2xhc3M7eHIAImNvbS5jbG91ZC5leGNlcHRpb24uQ2xvdWRFeGNlcHRpb2556I4b8eRExwIAAkwAC2NzRXJyb3JDb2RldAATTGphdmEvbGFuZy9JbnRlZ2VyO0wABmlkTGlzdHQAFUxqYXZhL3V0aWwvQXJyYXlMaXN0O3hyABNqYXZhLmxhbmcuRXhjZXB0aW9u0P0fPho7HMQCAAB4cgATamF2YS5sYW5nLlRocm93YWJsZdXGNSc5d7jLAwAETAAFY2F1c2V0ABVMamF2YS9sYW5nL1Rocm93YWJsZTtMAA1kZXRhaWxNZXNzYWdldAASTGphdmEvbGFuZy9TdHJpbmc7WwAKc3RhY2tUcmFjZXQAHltMamF2YS9sYW5nL1N0YWNrVHJhY2VFbGVtZW50O0wAFHN1cHByZXNzZWRFeGNlcHRpb25zdAAQTGphdmEvdXRpbC9MaXN0O3hwc3IALGNvbS5jbG91ZC51dGlscy5leGNlcHRpb24uRXhlY3V0aW9uRXhjZXB0aW9uAAAAAFZNT34CAAFJAAtjc0Vycm9yQ29kZXhxAH4ABnEAfgAOdABkVW5hYmxlIHRvIHN0YXJ0ICBWTTo3ZjViY2QwNi0zYzkxLTRiNmMtYTY3Zi1mMDMxYTE4ZGIzOGEgZHVlIHRvIGVycm9yIGluIGZpbmFsaXplU3RhcnQsIG5vdCByZXRyeWluZ3VyAB5bTGphdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudDsCRio8PP0iOQIAAHhwAAAAFXNyABtqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnRhCcWaJjbdhQIACEIABmZvcm1hdEkACmxpbmVOdW1iZXJMAA9jbGFzc0xvYWRlck5hbWVxAH4ACUwADmRlY2xhcmluZ0NsYXNzcQB-AAlMAAhmaWxlTmFtZXEAfgAJTAAKbWV0aG9kTmFtZXEAfgAJTAAKbW9kdWxlTmFtZXEAfgAJTAANbW9kdWxlVmVyc2lvbnEAfgAJeHABAAAE2HQAA2FwcHQAJmNvbS5jbG91ZC52bS5WaXJ0dWFsTWFjaGluZU1hbmFnZXJJbXBsdAAeVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbC5qYXZhdAAQb3JjaGVzdHJhdGVTdGFydHBwc3EAfgASAQAAFGtxAH4AFHEAfgAVcQB-ABZxAH4AF3Bwc3EAfgASAv____5wdAAtamRrLmludGVybmFsLnJlZmxlY3QuTmF0aXZlTWV0aG9kQWNjZXNzb3JJbXBsdAAdTmF0aXZlTWV0aG9kQWNjZXNzb3JJbXBsLmphdmF0AAdpbnZva2UwdAAJamF2YS5iYXNldAAGMTEuMC43c3EAfgASAgAAAD5wcQB-ABpxAH4AG3QABmludm9rZXEAfgAdcQB-AB5zcQB-ABICAAAAK3B0ADFqZGsuaW50ZXJuYWwucmVmbGVjdC5EZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsdAAhRGVsZWdhdGluZ01ldGhvZEFjY2Vzc29ySW1wbC5qYXZhcQB-ACBxAH4AHXEAfgAec3EAfgASAgAAAjZwdAAYamF2YS5sYW5nLnJlZmxlY3QuTWV0aG9kdAALTWV0aG9kLmphdmFxAH4AIHEAfgAdcQB-AB5zcQB-ABIBAAAAa3EAfgAUdAAiY29tLmNsb3VkLnZtLlZtV29ya0pvYkhhbmRsZXJQcm94eXQAGlZtV29ya0pvYkhhbmRsZXJQcm94eS5qYXZhdAAPaGFuZGxlVm1Xb3JrSm9icHBzcQB-ABIBAAAVDnEAfgAUcQB-ABVxAH4AFnEAfgAqcHBzcQB-ABIBAAAAZnEAfgAUdAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRpc3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JwcHNxAH4AEgEAAAJbcQB-ABR0AD9vcmcuYXBhY2hlLmNsb3Vkc3RhY2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0AAxydW5JbkNvbnRleHRwcHNxAH4AEgEAAAAxcQB-ABR0AD5vcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGUkMXQAG01hbmFnZWRDb250ZXh0UnVubmFibGUuamF2YXQAA3J1bnBwc3EAfgASAQAAADhxAH4AFHQAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbHBwc3EAfgASAQAAAGdxAH4AFHQAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHRxAH4AOnQAD2NhbGxXaXRoQ29udGV4dHBwc3EAfgASAQAAADVxAH4AFHEAfgA9cQB-ADp0AA5ydW5XaXRoQ29udGV4dHBwc3EAfgASAQAAAC5xAH4AFHQAPG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgA2cQB-ADdwcHNxAH4AEgEAAAIncQB-ABRxAH4AMXEAfgAycQB-ADdwcHNxAH4AEgIAAAIDcHQALmphdmEudXRpbC5jb25jdXJyZW50LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgA7cQB-AB1xAH4AHnNxAH4AEgIAAAEIcHQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0AA9GdXR1cmVUYXNrLmphdmFxAH4AN3EAfgAdcQB-AB5zcQB-ABICAAAEaHB0ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnEAfgAdcQB-AB5zcQB-ABICAAACdHB0AC5qYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-AExxAH4AN3EAfgAdcQB-AB5zcQB-ABICAAADQnB0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4AN3EAfgAdcQB-AB5zcgAfamF2YS51dGlsLkNvbGxlY3Rpb25zJEVtcHR5TGlzdHq4F7Q8p57eAgAAeHB4AAAAAHQAsFJlc291cmNlIFtIb3N0OjI2XSBpcyB1bnJlYWNoYWJsZTogSG9zdCAyNjogVW5hYmxlIHRvIHN0YXJ0IGluc3RhbmNlIGR1ZSB0byBVbmFibGUgdG8gc3RhcnQgIFZNOjdmNWJjZDA2LTNjOTEtNGI2Yy1hNjdmLWYwMzFhMThkYjM4YSBkdWUgdG8gZXJyb3IgaW4gZmluYWxpemVTdGFydCwgbm90IHJldHJ5aW5ndXEAfgAQAAAAFXNxAH4AEgEAAAT8cQB-ABRxAH4AFXEAfgAWcQB-ABdwcHNxAH4AEgEAABRrcQB-ABRxAH4AFXEAfgAWcQB-ABdwcHNxAH4AEgL____-cHEAfgAacQB-ABtxAH4AHHEAfgAdcQB-AB5zcQB-ABICAAAAPnBxAH4AGnEAfgAbcQB-ACBxAH4AHXEAfgAec3EAfgASAgAAACtwcQB-ACJxAH4AI3EAfgAgcQB-AB1xAH4AHnNxAH4AEgIAAAI2cHEAfgAlcQB-ACZxAH4AIHEAfgAdcQB-AB5zcQB-ABIBAAAAa3EAfgAUcQB-AChxAH4AKXEAfgAqcHBzcQB-ABIBAAAVDnEAfgAUcQB-ABVxAH4AFnEAfgAqcHBzcQB-ABIBAAAAZnEAfgAUcQB-AC1xAH4ALnEAfgAvcHBzcQB-ABIBAAACW3EAfgAUcQB-ADFxAH4AMnEAfgAzcHBzcQB-ABIBAAAAMXEAfgAUcQB-ADVxAH4ANnEAfgA3cHBzcQB-ABIBAAAAOHEAfgAUcQB-ADlxAH4AOnEAfgA7cHBzcQB-ABIBAAAAZ3EAfgAUcQB-AD1xAH4AOnEAfgA-cHBzcQB-ABIBAAAANXEAfgAUcQB-AD1xAH4AOnEAfgBAcHBzcQB-ABIBAAAALnEAfgAUcQB-AEJxAH4ANnEAfgA3cHBzcQB-ABIBAAACJ3EAfgAUcQB-ADFxAH4AMnEAfgA3cHBzcQB-ABICAAACA3BxAH4ARXEAfgBGcQB-ADtxAH4AHXEAfgAec3EAfgASAgAAAQhwcQB-AEhxAH4ASXEAfgA3cQB-AB1xAH4AHnNxAH4AEgIAAARocHEAfgBLcQB-AExxAH4ATXEAfgAdcQB-AB5zcQB-ABICAAACdHBxAH4AT3EAfgBMcQB-ADdxAH4AHXEAfgAec3EAfgASAgAAA0JwcQB-AFFxAH4AUnEAfgA3cQB-AB1xAH4AHnEAfgBUeHNyABFqYXZhLmxhbmcuSW50ZWdlchLioKT3gYc4AgABSQAFdmFsdWV4cgAQamF2YS5sYW5nLk51bWJlcoaslR0LlOCLAgAAeHAAABC9c3IAE2phdmEudXRpbC5BcnJheUxpc3R4gdIdmcdhnQMAAUkABHNpemV4cAAAAAB3BAAAAAB4AAAAAAAAABp2cgATY29tLmNsb3VkLmhvc3QuSG9zdJYzfa477cOJAgAAeHA
2020-08-08 02:58:43,824 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459)
(logid:1051f59c) Publish async job-132459 complete on message bus
2020-08-08 02:58:43,824 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459)
(logid:1051f59c) Wake up jobs related to job-132459
2020-08-08 02:58:43,824 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459)
(logid:1051f59c) Update db status for job-132459
2020-08-08 02:58:43,825 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459)
(logid:1051f59c) Wake up jobs joined with job-132459 and disjoin all
subjobs created from job- 132459
2020-08-08 02:58:43,851 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459)
(logid:1051f59c) Done executing com.cloud.vm.VmWorkStart for job-132459
2020-08-08 02:58:43,853 INFO  [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459)
(logid:1051f59c) Remove job-132459 from job monitoring
2020-08-08 02:58:43,903 ERROR [c.c.a.ApiAsyncJobDispatcher]
(API-Job-Executor-11:ctx-b6673908 job-132458) (logid:1051f59c)
Unexpected exception while executing
org.apache.cloudstack.api.command.admin.router.StartRouterCmd
com.cloud.exception.AgentUnavailableException: Resource [Host:26] is
unreachable: Host 26: Unable to start instance due to Unable to start
VM:7f5bcd06-3c91-4b6c-a67f-f031a18db38a due to error in finalizeStart,
not retrying
         at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1276)
         at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5227)
         at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native
Method)
         at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
         at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
         at java.base/java.lang.reflect.Method.invoke(Method.java:566)
         at
com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
         at
com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5390)
         at
com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
         at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:603)
         at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
         at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
         at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
         at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
         at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
         at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:551)
         at
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
         at
java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
         at
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
         at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
         at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: com.cloud.utils.exception.ExecutionException: Unable to
start  VM:7f5bcd06-3c91-4b6c-a67f-f031a18db38a due to error in
finalizeStart, not retrying
         at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1240)
         at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5227)
         at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native
Method)
         ... 18 more
2020-08-08 02:58:43,905 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-11:ctx-b6673908 job-132458) (logid:1051f59c) Complete
async job-132458, jobStatus: FAILED, resultCode: 530, result:
org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Resource
[Host:26] is unreachable: Host 26: Unable to start instance due to
Unable to start  VM:7f5bcd06-3c91-4b6c-a67f-f031a18db38a due to error in
finalizeStart, not retrying"}
2020-08-08 02:58:43,906 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-11:ctx-b6673908 job-132458) (logid:1051f59c) Publish
async job-132458 complete on message bus
2020-08-08 02:58:43,906 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-11:ctx-b6673908 job-132458) (logid:1051f59c) Wake up
jobs related to job-132458
2020-08-08 02:58:43,906 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-11:ctx-b6673908 job-132458) (logid:1051f59c) Update db
status for job-132458
2020-08-08 02:58:43,907 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-11:ctx-b6673908 job-132458) (logid:1051f59c) Wake up
jobs joined with job-132458 and disjoin all subjobs created from job- 132458
2020-08-08 02:58:43,929 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-11:ctx-b6673908 job-132458) (logid:1051f59c) Done
executing org.apache.cloudstack.api.command.admin.router.StartRouterCmd
for job-132458
2020-08-08 02:58:43,929 INFO  [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-11:ctx-b6673908 job-132458) (logid:1051f59c) Remove
job-132458 from job monitoring
2020-08-08 02:58:44,110 DEBUG [c.c.a.ApiServlet]
(qtp873610597-720:ctx-8a868b80) (logid:4cdef68a) ===START===
172.31.254.254 -- GET
jobid=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json
2020-08-08 02:58:44,118 DEBUG [c.c.a.ApiServer]
(qtp873610597-720:ctx-8a868b80 ctx-54db7537) (logid:4cdef68a) CIDRs from
which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is
allowed to perform API calls: 0.0.0.0/0,::/0
2020-08-08 02:58:44,148 DEBUG [c.c.a.ApiServlet]
(qtp873610597-720:ctx-8a868b80 ctx-54db7537) (logid:4cdef68a) ===END===
172.31.254.254 -- GET
jobid=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json
2020-08-08 02:58:45,458 DEBUG [c.c.a.ApiServlet]
(qtp873610597-544:ctx-2294155c) (logid:3611626e) ===START===
172.31.254.254 -- GET
jobId=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json
2020-08-08 02:58:45,467 DEBUG [c.c.a.ApiServer]
(qtp873610597-544:ctx-2294155c ctx-756b571f) (logid:3611626e) CIDRs from
which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is
allowed to perform API calls: 0.0.0.0/0,::/0
2020-08-08 02:58:45,496 DEBUG [c.c.a.ApiServlet]
(qtp873610597-544:ctx-2294155c ctx-756b571f) (logid:3611626e) ===END===
172.31.254.254 -- GET
jobId=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json
2020-08-08 02:58:45,554 DEBUG [c.c.a.ApiServlet]
(qtp873610597-489:ctx-bfe2d642) (logid:a8a181dd) ===START===
172.31.254.254 -- GET
listall=true&projectid=-1&id=7f5bcd06-3c91-4b6c-a67f-f031a18db38a&page=1&pagesize=20&command=listRouters&response=json
2020-08-08 02:58:45,562 DEBUG [c.c.a.ApiServer]
(qtp873610597-489:ctx-bfe2d642 ctx-8abf67d5) (logid:a8a181dd) CIDRs from
which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is
allowed to perform API calls: 0.0.0.0/0,::/0
2020-08-08 02:58:45,574 DEBUG [c.c.a.ApiServlet]
(qtp873610597-489:ctx-bfe2d642 ctx-8abf67d5) (logid:a8a181dd) ===END===
172.31.254.254 -- GET
listall=true&projectid=-1&id=7f5bcd06-3c91-4b6c-a67f-f031a18db38a&page=1&pagesize=20&command=listRouters&response=json
2020-08-08 02:58:47,074 DEBUG [c.c.c.ConsoleProxyManagerImpl]
(consoleproxy-1:ctx-d5862246) (logid:3cd62b0c) Zone 1 is not ready to
launch console proxy yet
2020-08-08 02:58:48,642 DEBUG [c.c.s.StatsCollector]
(StatsCollector-3:ctx-9c5808ec) (logid:fea58b3f) HostStatsCollector is
running...
2020-08-08 02:58:48,695 DEBUG [c.c.a.t.Request]
(StatsCollector-3:ctx-9c5808ec) (logid:fea58b3f) Seq
26-6280551155344867402: Received:  { Ans: , MgmtId: 11967559506, via:
26(cloud1.viakoo.com), Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2020-08-08 02:58:50,559 DEBUG [c.c.s.StatsCollector]
(StatsCollector-4:ctx-a7908f9e) (logid:0426fb7e) StorageCollector is
running...
2020-08-08 02:58:50,568 DEBUG [c.c.s.StatsCollector]
(StatsCollector-4:ctx-a7908f9e) (logid:0426fb7e) There is no secondary
storage VM for secondary storage host secondary1
2020-08-08 02:58:50,571 DEBUG [c.c.s.StatsCollector]
(StatsCollector-4:ctx-a7908f9e) (logid:0426fb7e) There is no secondary
storage VM for secondary storage host secondary2
2020-08-08 02:58:50,573 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(StatsCollector-4:ctx-a7908f9e) (logid:0426fb7e)
getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand
2020-08-08 02:58:50,573 DEBUG [c.c.h.XenServerGuru]
(StatsCollector-4:ctx-a7908f9e) (logid:0426fb7e) We are returning the
default host to execute commands because the command is not of Copy type.
2020-08-08 02:58:50,921 DEBUG [c.c.a.t.Request]
(StatsCollector-4:ctx-a7908f9e) (logid:0426fb7e) Seq
26-6280551155344867403: Received:  { Ans: , MgmtId: 11967559506, via:
26(cloud1.viakoo.com), Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2020-08-08 02:58:50,922 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(StatsCollector-4:ctx-a7908f9e) (logid:0426fb7e)
getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand
2020-08-08 02:58:50,922 DEBUG [c.c.h.XenServerGuru]
(StatsCollector-4:ctx-a7908f9e) (logid:0426fb7e) We are returning the
default host to execute commands because the command is not of Copy type.
2020-08-08 02:58:51,110 DEBUG [c.c.a.t.Request]
(StatsCollector-4:ctx-a7908f9e) (logid:0426fb7e) Seq
26-6280551155344867404: Received:  { Ans: , MgmtId: 11967559506, via:
26(cloud1.viakoo.com), Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2020-08-08 02:58:56,169 DEBUG
[c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-ff58463b) (logid:fd41b754) Found 0 routers to
update status.
2020-08-08 02:58:56,170 DEBUG
[c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-ff58463b) (logid:fd41b754) Found 0 VPC's to
update Redundant State.
2020-08-08 02:58:56,171 DEBUG
[c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-ff58463b) (logid:fd41b754) Found 0 networks
to update RvR status.
2020-08-08 02:59:00,743 DEBUG [c.c.h.d.HostDaoImpl]
(ClusteredAgentManager Timer:ctx-ae913929) (logid:8f37d206) Resetting
hosts suitable for reconnect
2020-08-08 02:59:00,744 DEBUG [c.c.h.d.HostDaoImpl]
(ClusteredAgentManager Timer:ctx-ae913929) (logid:8f37d206) Completed
resetting hosts suitable for reconnect
2020-08-08 02:59:00,744 DEBUG [c.c.h.d.HostDaoImpl]
(ClusteredAgentManager Timer:ctx-ae913929) (logid:8f37d206) Acquiring
hosts for clusters already owned by this management server
2020-08-08 02:59:00,745 DEBUG [c.c.h.d.HostDaoImpl]
(ClusteredAgentManager Timer:ctx-ae913929) (logid:8f37d206) Completed
acquiring hosts for clusters already owned by this management server
2020-08-08 02:59:00,745 DEBUG [c.c.h.d.HostDaoImpl]
(ClusteredAgentManager Timer:ctx-ae913929) (logid:8f37d206) Acquiring
hosts for clusters not owned by any management server
2020-08-08 02:59:00,746 DEBUG [c.c.h.d.HostDaoImpl]
(ClusteredAgentManager Timer:ctx-ae913929) (logid:8f37d206) Completed
acquiring hosts for clusters not owned by any management server
^

[-------------------------------------------------------/snip---------------------------------------------------------------------]


Some versions (I've been playing around with downgrading and trying
different versions, currently running the Centos 7.7 versions on Centos
7.8):

[root@cloud1 qemu]# rpm -q qemu-kvm
qemu-kvm-1.5.3-167.el7_7.4.x86_64

[root@cloud1 qemu]# rpm -q libvirt
libvirt-4.5.0-23.el7_7.6.x86_64





rohit.yadav@shapeblue.comĀ 
www.shapeblue.com
3 London Bridge Street,  3rd floor, News Building, London  SE1 9SGUK
@shapeblue
  
 

Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message