cloudstack-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Eric Lee Green <eric.lee.gr...@gmail.com>
Subject Has anybody gotten Cloudstack 4.13.1.0 or 4.14.0.0 working on Centos 7.7 or 7.8?
Date Sat, 08 Aug 2020 03:14:56 GMT
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





Mime
View raw message