Hi Eric, This looks like a Libvirt specific error [1] outside of the scope of CloudStack. Can you try the CentOS SIG Virtualisation repos (the qemu-ev releases) [2] which usually requires installing centos-release-qemu-ev on the CentOS KVM hosts and doing an upgrade (or installation of the qemu* packages).
[1] Similar issue: https://bugzilla.redhat.com/show_bug.cgi?id=1090551 [2] https://wiki.centos.org/SpecialInterestGroup/Virtualizatio<https://wiki.centos.org/SpecialInterestGroup/Virtualization> Regards. ________________________________ From: Eric Lee Green <eric.lee.gr...@gmail.com> Sent: Saturday, August 8, 2020 08:44 To: users@cloudstack.apache.org <users@cloudstack.apache.org> Subject: Has anybody gotten Cloudstack 4.13.1.0 or 4.14.0.0 working on Centos 7.7 or 7.8? I've tried multiple times now and it's refusing to start the virtual routers and thus refusing to start anything else. Or rather, it's starting them, I see the VM appear in the process list (ps -ax | grep kvm) and I see log messages in /var/log/messages saying it's started and I see the log, but then the agent is refusing to connect and then shutting them down. This happened with both 4.13 and 4.14. 4.13 worked with an earlier version of Centos, but had issues with creating new virtual machines (as versus starting them) so I am trying to get things running on a modern Centos (i.e., one that's not a security breach just by existing). Any ideas? Example: /var/log/messages: ---------------------------------------------snip------------------------------------------------------ Aug 7 19:57:49 cloud1 java: INFO [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:) (logid:35b3a97e) Trying to fetch storage pool f7c824aa-e6e4-3c40-b890-36a459245385 from libvirt Aug 7 19:57:49 cloud1 java: INFO [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:) (logid:35b3a97e) Asking libvirt to refresh storage pool f7c824aa-e6e4-3c40-b890-36a459245385 Aug 7 19:57:50 cloud1 java: INFO [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:) (logid:35b3a97e) Trying to fetch storage pool 0ab13de9-2310-334c-b438-94dfb0b8ec84 from libvirt Aug 7 19:57:50 cloud1 java: INFO [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:) (logid:35b3a97e) Asking libvirt to refresh storage pool 0ab13de9-2310-334c-b438-94dfb0b8ec84 Aug 7 19:58:29 cloud1 java: INFO [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-4:) (logid:1051f59c) Trying to fetch storage pool 0ab13de9-2310-334c-b438-94dfb0b8ec84 from libvirt Aug 7 19:58:29 cloud1 java: INFO [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-4:) (logid:1051f59c) Trying to fetch storage pool 0ab13de9-2310-334c-b438-94dfb0b8ec84 from libvirt Aug 7 19:58:29 cloud1 kernel: brbond0-102: port 1(bond0.102) entered blocking state Aug 7 19:58:29 cloud1 kernel: brbond0-102: port 1(bond0.102) entered disabled state Aug 7 19:58:29 cloud1 kernel: device bond0.102 entered promiscuous mode Aug 7 19:58:29 cloud1 kernel: brbond0-102: port 1(bond0.102) entered blocking state Aug 7 19:58:29 cloud1 kernel: brbond0-102: port 1(bond0.102) entered forwarding state Aug 7 19:58:29 cloud1 java: WARNING: An illegal reflective access operation has occurred Aug 7 19:58:29 cloud1 java: WARNING: Illegal reflective access by org.codehaus.groovy.reflection.CachedClass (file:/usr/share/cloudstack-agent/lib/groovy-all-2.4.17.jar) to method java.lang.Object.finalize() Aug 7 19:58:29 cloud1 java: WARNING: Please consider reporting this to the maintainers of org.codehaus.groovy.reflection.CachedClass Aug 7 19:58:29 cloud1 java: WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations Aug 7 19:58:29 cloud1 java: WARNING: All illegal access operations will be denied in a future release Aug 7 19:58:29 cloud1 java: WARN [kvm.resource.LibvirtKvmAgentHook] (agentRequest-Handler-4:) (logid:1051f59c) Groovy script '/etc/cloudstack/agent/hooks/libvirt-vm-xml-transformer.groovy' is not available. Transformations will not be applied. Aug 7 19:58:29 cloud1 java: WARN [kvm.resource.LibvirtKvmAgentHook] (agentRequest-Handler-4:) (logid:1051f59c) Groovy scripting engine is not initialized. Data transformation skipped. Aug 7 19:58:29 cloud1 java: libvirt: QEMU Driver error : Domain not found: no domain with matching name 'r-739-VM' Aug 7 19:58:29 cloud1 kernel: brbond0-102: port 2(vnet0) entered blocking state Aug 7 19:58:29 cloud1 kernel: brbond0-102: port 2(vnet0) entered disabled state Aug 7 19:58:29 cloud1 kernel: device vnet0 entered promiscuous mode Aug 7 19:58:29 cloud1 kernel: brbond0-102: port 2(vnet0) entered blocking state Aug 7 19:58:29 cloud1 kernel: brbond0-102: port 2(vnet0) entered forwarding state Aug 7 19:58:29 cloud1 kernel: cloud0: port 1(vnet1) entered blocking state Aug 7 19:58:29 cloud1 kernel: cloud0: port 1(vnet1) entered disabled state Aug 7 19:58:29 cloud1 kernel: device vnet1 entered promiscuous mode Aug 7 19:58:29 cloud1 kernel: cloud0: port 1(vnet1) entered blocking state Aug 7 19:58:29 cloud1 kernel: cloud0: port 1(vnet1) entered forwarding state Aug 7 19:58:29 cloud1 libvirtd: 2020-08-08 02:58:29.657+0000: 8966: warning : qemuDomainObjTaint:7530 : Domain id=1 name='r-739-VM' uuid=7f5bcd06-3c91-4b6c-a67f-f031a18db38a is tainted: high-privileges Aug 7 19:58:29 cloud1 dbus[1143]: [system] Activating via systemd: service name='org.freedesktop.machine1' unit='dbus-org.freedesktop.machine1.service' Aug 7 19:58:29 cloud1 systemd: Starting Virtual Machine and Container Registration Service... Aug 7 19:58:29 cloud1 dbus[1143]: [system] Successfully activated service 'org.freedesktop.machine1' Aug 7 19:58:29 cloud1 systemd: Started Virtual Machine and Container Registration Service. Aug 7 19:58:29 cloud1 systemd-machined: New machine qemu-1-r-739-VM. Aug 7 19:58:29 cloud1 systemd: Started Virtual Machine qemu-1-r-739-VM. Aug 7 19:58:29 cloud1 kvm: 1 guest now active Aug 7 19:58:29 cloud1 java: WARN [kvm.resource.LibvirtKvmAgentHook] (agentRequest-Handler-4:) (logid:1051f59c) Groovy script '/etc/cloudstack/agent/hooks/libvirt-vm-state-change.groovy' is not available. Transformations will not be applied. Aug 7 19:58:29 cloud1 java: WARN [kvm.resource.LibvirtKvmAgentHook] (agentRequest-Handler-4:) (logid:1051f59c) Groovy scripting engine is not initialized. Data transformation skipped. Aug 7 19:58:29 cloud1 libvirtd: 2020-08-08 02:58:29.888+0000: 8963: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:30 cloud1 libvirtd: 2020-08-08 02:58:30.004+0000: 8966: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:30 cloud1 libvirtd: 2020-08-08 02:58:30.120+0000: 8965: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:30 cloud1 libvirtd: 2020-08-08 02:58:30.237+0000: 8967: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:30 cloud1 libvirtd: 2020-08-08 02:58:30.353+0000: 8964: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:30 cloud1 libvirtd: 2020-08-08 02:58:30.476+0000: 8963: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:30 cloud1 libvirtd: 2020-08-08 02:58:30.592+0000: 8966: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:30 cloud1 libvirtd: 2020-08-08 02:58:30.707+0000: 8965: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:30 cloud1 libvirtd: 2020-08-08 02:58:30.824+0000: 8967: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:30 cloud1 libvirtd: 2020-08-08 02:58:30.940+0000: 8964: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:31 cloud1 libvirtd: 2020-08-08 02:58:31.056+0000: 8963: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:31 cloud1 libvirtd: 2020-08-08 02:58:31.172+0000: 8966: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:31 cloud1 libvirtd: 2020-08-08 02:58:31.288+0000: 8965: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:31 cloud1 kernel: kvm [9959]: vcpu0 disabled perfctr wrmsr: 0xc2 data 0xffff Aug 7 19:58:31 cloud1 libvirtd: 2020-08-08 02:58:31.405+0000: 8967: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:31 cloud1 libvirtd: 2020-08-08 02:58:31.521+0000: 8964: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:31 cloud1 libvirtd: 2020-08-08 02:58:31.637+0000: 8963: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:31 cloud1 libvirtd: 2020-08-08 02:58:31.753+0000: 8966: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:31 cloud1 libvirtd: 2020-08-08 02:58:31.868+0000: 8965: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:31 cloud1 libvirtd: 2020-08-08 02:58:31.986+0000: 8967: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:32 cloud1 libvirtd: 2020-08-08 02:58:32.102+0000: 8964: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:32 cloud1 libvirtd: 2020-08-08 02:58:32.219+0000: 8963: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:32 cloud1 libvirtd: 2020-08-08 02:58:32.335+0000: 8966: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:32 cloud1 libvirtd: 2020-08-08 02:58:32.452+0000: 8965: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:32 cloud1 libvirtd: 2020-08-08 02:58:32.568+0000: 8967: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:32 cloud1 libvirtd: 2020-08-08 02:58:32.686+0000: 8964: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:32 cloud1 libvirtd: 2020-08-08 02:58:32.803+0000: 8963: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:32 cloud1 libvirtd: 2020-08-08 02:58:32.921+0000: 8966: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:33 cloud1 libvirtd: 2020-08-08 02:58:33.037+0000: 8965: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:33 cloud1 libvirtd: 2020-08-08 02:58:33.154+0000: 8967: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:33 cloud1 libvirtd: 2020-08-08 02:58:33.270+0000: 8964: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:33 cloud1 libvirtd: 2020-08-08 02:58:33.387+0000: 8963: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:33 cloud1 libvirtd: 2020-08-08 02:58:33.505+0000: 8966: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:33 cloud1 libvirtd: 2020-08-08 02:58:33.623+0000: 8965: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:33 cloud1 libvirtd: 2020-08-08 02:58:33.740+0000: 8967: error : qemuDomainAgentAvailable:9144 : Guest agent is not responding: QEMU guest agent is not connected Aug 7 19:58:33 cloud1 libvirtd: 2020-08-08 02:58:33.856+0000: 8964: warning : qemuDomainObjTaint:7530 : Domain id=1 name='r-739-VM' uuid=7f5bcd06-3c91-4b6c-a67f-f031a18db38a is tainted: custom-ga-command Aug 7 19:58:33 cloud1 ntpd[1165]: Listen normally on 22 bond0.102 fe80::202:c9ff:fe52:2bc6 UDP 123 Aug 7 19:58:33 cloud1 ntpd[1165]: Listen normally on 23 brbond0-102 2001:1890:16b9:5008:202:c9ff:fe52:2bc6 UDP 123 Aug 7 19:58:33 cloud1 virtlogd: 2020-08-08 02:58:33.857+0000: 5817: info : libvirt version: 4.5.0, package: 23.el7_7.6 (CentOS BuildSystem <http://bugs.centos.org>, 2020-03-17-23:39:10, x86-01.bsys.centos.org) Aug 7 19:58:33 cloud1 virtlogd: 2020-08-08 02:58:33.857+0000: 5817: info : hostname: cloud1.viakoo.com Aug 7 19:58:33 cloud1 virtlogd: 2020-08-08 02:58:33.857+0000: 5817: error : virLogHandlerDomainOpenLogFile:390 : Cannot open log file: '/var/log/libvirt/qemu/r-739-VM.log': Device or resource busy Aug 7 19:58:33 cloud1 ntpd[1165]: Listen normally on 24 vnet1 fe80::fc00:a9ff:fefe:255 UDP 123 Aug 7 19:58:33 cloud1 libvirtd: 2020-08-08 02:58:33.857+0000: 8964: error : virNetClientProgramDispatchError:174 : Cannot open log file: '/var/log/libvirt/qemu/r-739-VM.log': Device or resource busy Aug 7 19:58:33 cloud1 libvirtd: 2020-08-08 02:58:33.857+0000: 8964: warning : qemuDomainObjTaint:7544 : Unable to open domainlog Aug 7 19:58:33 cloud1 ntpd[1165]: Listen normally on 25 vnet0 fe80::fc00:6dff:fe02:8f01 UDP 123 Aug 7 19:58:33 cloud1 ntpd[1165]: Listen normally on 26 brbond0-102 fe80::8c1a:dfff:fe00:c2e5 UDP 123 Aug 7 19:58:41 cloud1 kernel: brbond0-102: port 2(vnet0) entered disabled state Aug 7 19:58:41 cloud1 kernel: device vnet0 left promiscuous mode Aug 7 19:58:41 cloud1 kernel: brbond0-102: port 2(vnet0) entered disabled state Aug 7 19:58:41 cloud1 kernel: cloud0: port 1(vnet1) entered disabled state Aug 7 19:58:41 cloud1 kernel: device vnet1 left promiscuous mode Aug 7 19:58:41 cloud1 kernel: cloud0: port 1(vnet1) entered disabled state Aug 7 19:58:41 cloud1 libvirtd: 2020-08-08 02:58:41.936+0000: 8962: error : qemuMonitorIO:718 : internal error: End of file from qemu monitor Aug 7 19:58:41 cloud1 kvm: 0 guests now active Aug 7 19:58:41 cloud1 systemd-machined: Machine qemu-1-r-739-VM terminated. Aug 7 19:58:43 cloud1 java: libvirt: QEMU Driver error : Domain not found: no domain with matching uuid '7f5bcd06-3c91-4b6c-a67f-f031a18db38a' (r-739-VM) Aug 7 19:58:43 cloud1 java: WARN [kvm.resource.LibvirtKvmAgentHook] (agentRequest-Handler-2:) (logid:1051f59c) Groovy script '/etc/cloudstack/agent/hooks/libvirt-vm-state-change.groovy' is not available. Transformations will not be applied. Aug 7 19:58:43 cloud1 java: WARN [kvm.resource.LibvirtKvmAgentHook] (agentRequest-Handler-2:) (logid:1051f59c) Groovy scripting engine is not initialized. Data transformation skipped. Aug 7 19:58:43 cloud1 kernel: brbond0-102: port 1(bond0.102) entered disabled state Aug 7 19:58:43 cloud1 kernel: device bond0.102 left promiscuous mode Aug 7 19:58:43 cloud1 kernel: brbond0-102: port 1(bond0.102) entered disabled state Aug 7 19:58:43 cloud1 java: libvirt: QEMU Driver error : Domain not found: no domain with matching name 'r-739-VM' Aug 7 19:58:43 cloud1 java: INFO [kvm.resource.LibvirtConnection] (agentRequest-Handler-5:) (logid:1051f59c) No existing libvirtd connection found. Opening a new one Aug 7 19:58:43 cloud1 java: libvirt: LXC Driver error : Domain not found: No domain with matching name 'r-739-VM' Aug 7 19:58:43 cloud1 java: WARN [kvm.resource.LibvirtConnection] (agentRequest-Handler-5:) (logid:1051f59c) Can not find a connection for Instance r-739-VM. Assuming the default connection. Aug 7 19:58:43 cloud1 java: libvirt: QEMU Driver error : Domain not found: no domain with matching name 'r-739-VM' Aug 7 19:58:43 cloud1 java: libvirt: QEMU Driver error : Domain not found: no domain with matching name 'r-739-VM' Aug 7 19:58:43 cloud1 java: libvirt: QEMU Driver error : Domain not found: no domain with matching name 'r-739-VM' Aug 7 19:58:43 cloud1 java: libvirt: QEMU Driver error : Domain not found: no domain with matching name 'r-739-VM' Aug 7 19:58:43 cloud1 java: WARN [kvm.resource.LibvirtKvmAgentHook] (agentRequest-Handler-5:) (logid:1051f59c) Groovy script '/etc/cloudstack/agent/hooks/libvirt-vm-state-change.groovy' is not available. Transformations will not be applied. Aug 7 19:58:43 cloud1 java: WARN [kvm.resource.LibvirtKvmAgentHook] (agentRequest-Handler-5:) (logid:1051f59c) Groovy scripting engine is not initialized. Data transformation skipped. Aug 7 19:58:44 cloud1 ntpd[1165]: Deleting interface #26 brbond0-102, fe80::8c1a:dfff:fe00:c2e5#123, interface stats: received=0, sent=0, dropped=0, active_time=11 secs Aug 7 19:58:44 cloud1 ntpd[1165]: Deleting interface #25 vnet0, fe80::fc00:6dff:fe02:8f01#123, interface stats: received=0, sent=0, dropped=0, active_time=11 secs Aug 7 19:58:44 cloud1 ntpd[1165]: Deleting interface #24 vnet1, fe80::fc00:a9ff:fefe:255#123, interface stats: received=0, sent=0, dropped=0, active_time=11 secs Aug 7 19:58:44 cloud1 ntpd[1165]: Deleting interface #23 brbond0-102, 2001:1890:16b9:5008:202:c9ff:fe52:2bc6#123, interface stats: received=0, sent=0, dropped=0, active_time=11 secs Aug 7 19:58:44 cloud1 ntpd[1165]: Deleting interface #22 bond0.102, fe80::202:c9ff:fe52:2bc6#123, interface stats: received=0, sent=0, dropped=0, active_time=11 secs --------------------------------/snip-------------------------------------------- /var/log/libvirt/qemu/r-739-VM.log -------------------------------------------snip----------------------------------------------------------------------------------------------- 2020-08-08 02:58:29.657+0000: starting up libvirt version: 4.5.0, package: 23.el7_7.6 (CentOS BuildSystem <http://bugs.centos.org>, 2020-03-17-23:39:10, x86-01.bsys.centos.org), qemu version: 1.5.3 (qemu-kvm-1.5.3-167.el7_7.4), kernel: 3.10.0-862.14.4.el7.x86_64, hostname: cloud1.viakoo.com LC_ALL=C \ PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin \ QEMU_AUDIO_DRV=none \ /usr/libexec/qemu-kvm \ -name r-739-VM \ -S \ -machine pc-i440fx-rhel7.0.0,accel=kvm,usb=off,dump-guest-core=off \ -m 256 \ -realtime mlock=off \ -smp 1,sockets=1,cores=1,threads=1 \ -uuid 7f5bcd06-3c91-4b6c-a67f-f031a18db38a \ -smbios 'type=1,manufacturer=Apache Software Foundation,product=CloudStack KVM Hypervisor,uuid=7f5bcd06-3c91-4b6c-a67f-f031a18db38a' \ -no-user-config \ -nodefaults \ -chardev socket,id=charmonitor,path=/var/lib/libvirt/qemu/domain-1-r-739-VM/monitor.sock,server,nowait \ -mon chardev=charmonitor,id=monitor,mode=control \ -rtc base=utc \ -no-shutdown \ -boot strict=on \ -device piix3-usb-uhci,id=usb,bus=pci.0,addr=0x1.0x2 \ -device virtio-serial-pci,id=virtio-serial0,bus=pci.0,addr=0x5 \ -drive file=/mnt/0ab13de9-2310-334c-b438-94dfb0b8ec84/daf7616b-f13b-4d4f-89cc-614709a31aad,format=qcow2,if=none,id=drive-virtio-disk0,serial=daf7616bf13b4d4f89cc,cache=none \ -device virtio-blk-pci,scsi=off,bus=pci.0,addr=0x6,drive=drive-virtio-disk0,id=virtio-disk0,bootindex=2 \ -drive file=/usr/share/cloudstack-common/vms/systemvm.iso,format=raw,if=none,id=drive-ide0-1-0,readonly=on \ -device ide-cd,bus=ide.1,unit=0,drive=drive-ide0-1-0,id=ide0-1-0,bootindex=1 \ -netdev tap,fd=28,id=hostnet0,vhost=on,vhostfd=30 \ -device virtio-net-pci,netdev=hostnet0,id=net0,mac=1e:00:6d:02:8f:01,bus=pci.0,addr=0x3,rombar=0,romfile= \ -netdev tap,fd=31,id=hostnet1,vhost=on,vhostfd=33 \ -device virtio-net-pci,netdev=hostnet1,id=net1,mac=0e:00:a9:fe:02:55,bus=pci.0,addr=0x4,rombar=0,romfile= \ -chardev pty,id=charserial0 \ -device isa-serial,chardev=charserial0,id=serial0 \ -chardev socket,id=charchannel0,path=/var/lib/libvirt/qemu/r-739-VM.org.qemu.guest_agent.0,server,nowait \ -device virtserialport,bus=virtio-serial0.0,nr=1,chardev=charchannel0,id=channel0,name=org.qemu.guest_agent.0 \ -device usb-tablet,id=input0,bus=usb.0,port=1 \ -vnc 10.100.255.1:0,password \ -vga cirrus \ -device i6300esb,id=watchdog0,bus=pci.0,addr=0x8 \ -watchdog-action none \ -device virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x7 \ -msg timestamp=on 2020-08-08 02:58:29.657+0000: Domain id=1 is tainted: high-privileges char device redirected to /dev/pts/4 (label charserial0) qemu: terminating on signal 15 from pid 8962 2020-08-08 02:58:42.136+0000: shutting down, reason=shutdown [----------------------------------------------------- snip ----------------------------------------------] management_server.log says what you'd expect if the agent can't connect: ------------------------------- snip ---------------------------------------------- 2020-08-08 02:57:49,925 DEBUG [c.c.s.StatsCollector] (StatsCollector-5:ctx-303590ea) (logid:35b3a97e) There is no secondary storage VM for secondary storage host secondary2 2020-08-08 02:57:49,926 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollector-5:ctx-303590ea) (logid:35b3a97e) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand 2020-08-08 02:57:49,926 DEBUG [c.c.h.XenServerGuru] (StatsCollector-5:ctx-303590ea) (logid:35b3a97e) We are returning the default host to execute commands because the command is not of Copy type. 2020-08-08 02:57:50,338 DEBUG [c.c.a.t.Request] (StatsCollector-5:ctx-303590ea) (logid:35b3a97e) Seq 26-6280551155344867397: Received: { Ans: , MgmtId: 11967559506, via: 26(cloud1.viakoo.com), Ver: v1, Flags: 10, { GetStorageStatsAnswer } } 2020-08-08 02:57:50,339 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollector-5:ctx-303590ea) (logid:35b3a97e) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand 2020-08-08 02:57:50,339 DEBUG [c.c.h.XenServerGuru] (StatsCollector-5:ctx-303590ea) (logid:35b3a97e) We are returning the default host to execute commands because the command is not of Copy type. 2020-08-08 02:57:50,559 DEBUG [c.c.a.t.Request] (StatsCollector-5:ctx-303590ea) (logid:35b3a97e) Seq 26-6280551155344867398: Received: { Ans: , MgmtId: 11967559506, via: 26(cloud1.viakoo.com), Ver: v1, Flags: 10, { GetStorageStatsAnswer } } 2020-08-08 02:57:56,168 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-c3bcee9d) (logid:6c188e96) Found 0 routers to update status. 2020-08-08 02:57:56,169 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-c3bcee9d) (logid:6c188e96) Found 0 VPC's to update Redundant State. 2020-08-08 02:57:56,170 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-c3bcee9d) (logid:6c188e96) Found 0 networks to update RvR status. 2020-08-08 02:58:02,877 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-8:null) (logid:) Ping from Routing host 26(cloud1.viakoo.com) 2020-08-08 02:58:02,877 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-8:null) (logid:) Process host VM state report from ping process. host: 26 2020-08-08 02:58:02,877 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-8:null) (logid:) Process VM state report. host: 26, number of records in report: 0 2020-08-08 02:58:02,878 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-8:null) (logid:) Done with process of VM state report. host: 26 2020-08-08 02:58:06,316 DEBUG [c.c.a.ApiServlet] (qtp873610597-716:ctx-89680f8b) (logid:25f4c5ea) ===START=== 172.31.254.254 -- GET listall=true&projectid=-1&page=1&pagesize=20&command=listRouters&response=json 2020-08-08 02:58:06,325 DEBUG [c.c.a.ApiServer] (qtp873610597-716:ctx-89680f8b ctx-4340b9a3) (logid:25f4c5ea) CIDRs from which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2020-08-08 02:58:06,349 DEBUG [c.c.a.ApiServlet] (qtp873610597-716:ctx-89680f8b ctx-4340b9a3) (logid:25f4c5ea) ===END=== 172.31.254.254 -- GET listall=true&projectid=-1&page=1&pagesize=20&command=listRouters&response=json 2020-08-08 02:58:10,178 DEBUG [c.c.a.ApiServlet] (qtp873610597-660:ctx-369b56f0) (logid:fb2f9e11) ===START=== 172.31.254.254 -- GET listall=true&projectid=-1&id=7f5bcd06-3c91-4b6c-a67f-f031a18db38a&page=1&pagesize=20&command=listRouters&response=json 2020-08-08 02:58:10,188 DEBUG [c.c.a.ApiServer] (qtp873610597-660:ctx-369b56f0 ctx-82e3b5e1) (logid:fb2f9e11) CIDRs from which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2020-08-08 02:58:10,205 DEBUG [c.c.a.ApiServlet] (qtp873610597-660:ctx-369b56f0 ctx-82e3b5e1) (logid:fb2f9e11) ===END=== 172.31.254.254 -- GET listall=true&projectid=-1&id=7f5bcd06-3c91-4b6c-a67f-f031a18db38a&page=1&pagesize=20&command=listRouters&response=json 2020-08-08 02:58:17,075 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-08c09898) (logid:e7d511bf) Zone 1 is not ready to launch console proxy yet 2020-08-08 02:58:26,169 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-c117276a) (logid:c45cd8af) Found 0 routers to update status. 2020-08-08 02:58:26,170 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-c117276a) (logid:c45cd8af) Found 0 VPC's to update Redundant State. 2020-08-08 02:58:26,172 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-c117276a) (logid:c45cd8af) Found 0 networks to update RvR status. 2020-08-08 02:58:26,894 DEBUG [c.c.a.ApiServlet] (qtp873610597-704:ctx-f389cc54) (logid:9a378b74) ===START=== 172.31.254.254 -- GET id=7f5bcd06-3c91-4b6c-a67f-f031a18db38a&command=startRouter&response=json 2020-08-08 02:58:26,903 DEBUG [c.c.a.ApiServer] (qtp873610597-704:ctx-f389cc54 ctx-f61d9f91) (logid:9a378b74) CIDRs from which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2020-08-08 02:58:26,959 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-11:ctx-b6673908 job-132458) (logid:031ef431) Add job-132458 into job monitoring 2020-08-08 02:58:26,962 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (qtp873610597-704:ctx-f389cc54 ctx-f61d9f91) (logid:9a378b74) submit async job-132458, details: AsyncJobVO {id:132458, userId: 2, accountId: 2, instanceType: DomainRouter, instanceId: 739, cmd: org.apache.cloudstack.api.command.admin.router.StartRouterCmd, cmdInfo: {"response":"json","ctxUserId":"2","httpmethod":"GET","ctxStartEventId":"12212","id":"7f5bcd06-3c91-4b6c-a67f-f031a18db38a","ctxDetails":"{\"interface com.cloud.vm.VirtualMachine\":\"7f5bcd06-3c91-4b6c-a67f-f031a18db38a\"}","ctxAccountId":"2","uuid":"7f5bcd06-3c91-4b6c-a67f-f031a18db38a","cmdEventType":"ROUTER.START"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 11967559506, completeMsid: null, lastUpdated: null, lastPolled: null, created: null, removed: null} 2020-08-08 02:58:26,963 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-11:ctx-b6673908 job-132458) (logid:1051f59c) Executing AsyncJobVO {id:132458, userId: 2, accountId: 2, instanceType: DomainRouter, instanceId: 739, cmd: org.apache.cloudstack.api.command.admin.router.StartRouterCmd, cmdInfo: {"response":"json","ctxUserId":"2","httpmethod":"GET","ctxStartEventId":"12212","id":"7f5bcd06-3c91-4b6c-a67f-f031a18db38a","ctxDetails":"{\"interface com.cloud.vm.VirtualMachine\":\"7f5bcd06-3c91-4b6c-a67f-f031a18db38a\"}","ctxAccountId":"2","uuid":"7f5bcd06-3c91-4b6c-a67f-f031a18db38a","cmdEventType":"ROUTER.START"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 11967559506, completeMsid: null, lastUpdated: null, lastPolled: null, created: null, removed: null} 2020-08-08 02:58:26,963 DEBUG [c.c.a.ApiServlet] (qtp873610597-704:ctx-f389cc54 ctx-f61d9f91) (logid:9a378b74) ===END=== 172.31.254.254 -- GET id=7f5bcd06-3c91-4b6c-a67f-f031a18db38a&command=startRouter&response=json 2020-08-08 02:58:27,002 DEBUG [c.c.a.ApiServlet] (qtp873610597-720:ctx-93876239) (logid:fd2e4787) ===START=== 172.31.254.254 -- GET jobId=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json 2020-08-08 02:58:27,008 DEBUG [c.c.a.ApiServer] (qtp873610597-720:ctx-93876239 ctx-83dfeeb7) (logid:fd2e4787) CIDRs from which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2020-08-08 02:58:27,024 DEBUG [o.a.c.e.o.NetworkOrchestrator] (API-Job-Executor-11:ctx-b6673908 job-132458 ctx-b0e5ebe4) (logid:1051f59c) Starting network Ntwk[217|Guest|7]... 2020-08-08 02:58:27,029 DEBUG [o.a.c.e.o.NetworkOrchestrator] (API-Job-Executor-11:ctx-b6673908 job-132458 ctx-b0e5ebe4) (logid:1051f59c) Network id=217 is already implemented 2020-08-08 02:58:27,030 DEBUG [o.a.c.e.o.NetworkOrchestrator] (API-Job-Executor-11:ctx-b6673908 job-132458 ctx-b0e5ebe4) (logid:1051f59c) Starting network Ntwk[202|Control|3]... 2020-08-08 02:58:27,031 DEBUG [o.a.c.e.o.NetworkOrchestrator] (API-Job-Executor-11:ctx-b6673908 job-132458 ctx-b0e5ebe4) (logid:1051f59c) Network id=202 is already implemented 2020-08-08 02:58:27,033 DEBUG [c.c.n.r.NetworkHelperImpl] (API-Job-Executor-11:ctx-b6673908 job-132458 ctx-b0e5ebe4) (logid:1051f59c) Starting router VM[DomainRouter|r-739-VM] 2020-08-08 02:58:27,036 DEBUG [c.c.a.ApiServlet] (qtp873610597-720:ctx-93876239 ctx-83dfeeb7) (logid:fd2e4787) ===END=== 172.31.254.254 -- GET jobId=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json 2020-08-08 02:58:27,060 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-11:ctx-b6673908 job-132458 ctx-b0e5ebe4) (logid:1051f59c) Sync job-132459 execution on object VmWorkJobQueue.739 2020-08-08 02:58:27,647 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-a1435850) (logid:4fbdbb7b) Execute sync-queue item: SyncQueueItemVO {id:273, queueId: 121029, contentType: AsyncJob, contentId: 132459, lastProcessMsid: 11967559506, lastprocessNumber: 15, lastProcessTime: Sat Aug 08 02:58:27 UTC 2020, created: Sat Aug 08 02:58:27 UTC 2020} 2020-08-08 02:58:27,648 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-a1435850) (logid:4fbdbb7b) Schedule queued job-132459 2020-08-08 02:58:27,688 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459) (logid:51547bf6) Add job-132459 into job monitoring 2020-08-08 02:58:27,695 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459) (logid:1051f59c) Executing AsyncJobVO {id:132459, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAC43QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AA5SZXN0YXJ0TmV0d29ya3QAP3JPMEFCWE55QUJGcVlYWmhMbXhoYm1jdVFtOXZiR1ZoYnMwZ2NvRFZuUHJ1QWdBQldnQUZkbUZzZFdWNGNBRXhw, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 11967559506, completeMsid: null, lastUpdated: null, lastPolled: null, created: Sat Aug 08 02:58:27 UTC 2020, removed: null} 2020-08-08 02:58:27,696 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459) (logid:1051f59c) Run VM work job: com.cloud.vm.VmWorkStart for VM 739, job origin: 132458 2020-08-08 02:58:27,699 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Execute VM work job: com.cloud.vm.VmWorkStart{"dcId":0,"rawParams":{"RestartNetwork":"rO0ABXNyABFqYXZhLmxhbmcuQm9vbGVhbs0gcoDVnPruAgABWgAFdmFsdWV4cAE"},"userId":2,"accountId":2,"vmId":739,"handlerName":"VirtualMachineManagerImpl"} 2020-08-08 02:58:27,708 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: null new host id: null host id before state transition: null 2020-08-08 02:58:27,708 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Successfully transitioned to start state for VM[DomainRouter|r-739-VM] reservation id = 604856f5-c66a-40a4-8634-f2f7223295f9 2020-08-08 02:58:27,731 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Deploy avoids pods: null, clusters: null, hosts: null 2020-08-08 02:58:27,735 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Root volume is ready, need to place VM in volume's cluster 2020-08-08 02:58:27,736 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Vol[874|vm=739|ROOT] is READY, changing deployment plan to use this pool's dcId: 1 , podId: null , and clusterId: null 2020-08-08 02:58:27,736 INFO [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Uefi params UefiFlag: null Boot Type: null Boot Mode: null 2020-08-08 02:58:27,743 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) DeploymentPlanner allocation algorithm: null 2020-08-08 02:58:27,743 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Trying to allocate a host and storage pools from dc:1, pod:null,cluster:null, requested cpu: 500, requested ram: 268435456 2020-08-08 02:58:27,743 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Is ROOT volume READY (pool already allocated)?: Yes 2020-08-08 02:58:27,743 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Deploy avoids pods: [], clusters: [], hosts: [] 2020-08-08 02:58:27,744 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Searching all possible resources under this Zone: 1 2020-08-08 02:58:27,745 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Zone: 1 2020-08-08 02:58:27,747 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Removing from the clusterId list these clusters from avoid set: [] 2020-08-08 02:58:27,752 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Checking resources in Cluster: 1 under Pod: 1 2020-08-08 02:58:27,753 INFO [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99 FirstFitRoutingAllocator) (logid:1051f59c) Guest VM is requested with Cusotm[UEFI] Boot Type false 2020-08-08 02:58:27,753 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99 FirstFitRoutingAllocator) (logid:1051f59c) Looking for hosts in dc: 1 pod:1 cluster:1 2020-08-08 02:58:27,755 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99 FirstFitRoutingAllocator) (logid:1051f59c) FirstFitAllocator has 1 hosts to check for allocation: [Host[-26-Routing]] 2020-08-08 02:58:27,757 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99 FirstFitRoutingAllocator) (logid:1051f59c) Found 1 hosts for allocation after prioritization: [Host[-26-Routing]] 2020-08-08 02:58:27,757 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99 FirstFitRoutingAllocator) (logid:1051f59c) Looking for speed=500Mhz, Ram=256 2020-08-08 02:58:27,761 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99 FirstFitRoutingAllocator) (logid:1051f59c) Host: 26 has cpu capability (cpu:24, speed:3068) to support requested CPU: 1 and requested speed: 500 2020-08-08 02:58:27,761 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99 FirstFitRoutingAllocator) (logid:1051f59c) Checking if host: 26 has enough capacity for requested CPU: 500 and requested RAM: 268435456 , cpuOverprovisioningFactor: 2.0 2020-08-08 02:58:27,762 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99 FirstFitRoutingAllocator) (logid:1051f59c) Hosts's actual total CPU: 73632 and CPU after applying overprovisioning: 147264 2020-08-08 02:58:27,762 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99 FirstFitRoutingAllocator) (logid:1051f59c) Free CPU: 147264 , Requested CPU: 500 2020-08-08 02:58:27,762 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99 FirstFitRoutingAllocator) (logid:1051f59c) Free RAM: 250977878016 , Requested RAM: 268435456 2020-08-08 02:58:27,762 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99 FirstFitRoutingAllocator) (logid:1051f59c) Host has enough CPU and RAM available 2020-08-08 02:58:27,762 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99 FirstFitRoutingAllocator) (logid:1051f59c) STATS: Can alloc CPU from host: 26, used: 0, reserved: 0, actual total: 73632, total with overprovisioning: 147264; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true 2020-08-08 02:58:27,762 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99 FirstFitRoutingAllocator) (logid:1051f59c) STATS: Can alloc MEM from host: 26, used: 0, reserved: 0, total: 250977878016; requested mem: 268435456,alloc_from_last_host?:false ,considerReservedCapacity?: true 2020-08-08 02:58:27,762 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99 FirstFitRoutingAllocator) (logid:1051f59c) Found a suitable host, adding to list: 26 2020-08-08 02:58:27,762 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99 FirstFitRoutingAllocator) (logid:1051f59c) Host Allocator returning 1 suitable hosts 2020-08-08 02:58:27,764 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Checking suitable pools for volume (Id, Type): (874,ROOT) 2020-08-08 02:58:27,764 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Volume has pool already allocated, checking if pool can be reused, poolId: 5 2020-08-08 02:58:27,766 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Planner need not allocate a pool for this volume since its READY 2020-08-08 02:58:27,766 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM 2020-08-08 02:58:27,766 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Checking if host: 26 can access any suitable storage pool for volume: ROOT 2020-08-08 02:58:27,767 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Host: 26 can access pool: 5 2020-08-08 02:58:27,787 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Found a potential host id: 26 name: cloud1.viakoo.com and associated storage pools for this VM 2020-08-08 02:58:27,788 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(26)-Storage()] 2020-08-08 02:58:27,788 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Deployment found - P0=VM[DomainRouter|r-739-VM], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(26)-Storage()] 2020-08-08 02:58:27,923 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: null new host id: 26 host id before state transition: null 2020-08-08 02:58:27,931 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Hosts's actual total CPU: 73632 and CPU after applying overprovisioning: 147264 2020-08-08 02:58:27,931 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) We are allocating VM, increasing the used capacity of this host:26 2020-08-08 02:58:27,931 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Current Used CPU: 0 , Free CPU:147264 ,Requested CPU: 500 2020-08-08 02:58:27,931 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Current Used RAM: 0 , Free RAM:250977878016 ,Requested RAM: 268435456 2020-08-08 02:58:27,931 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) CPU STATS after allocation: for host: 26, old used: 0, old reserved: 0, actual total: 73632, total with overprovisioning: 147264; new used:500, reserved:0; requested cpu:500,alloc_from_last:false 2020-08-08 02:58:27,932 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) RAM STATS after allocation: for host: 26, old used: 0, old reserved: 0, total: 250977878016; new used: 268435456, reserved: 0; requested mem: 268435456,alloc_from_last:false 2020-08-08 02:58:27,934 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Host: 26 has cpu capability (cpu:24, speed:3068) to support requested CPU: 1 and requested speed: 500 2020-08-08 02:58:27,934 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Checking if host: 26 has enough capacity for requested CPU: 500 and requested RAM: 268435456 , cpuOverprovisioningFactor: 2.0 2020-08-08 02:58:27,935 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Hosts's actual total CPU: 73632 and CPU after applying overprovisioning: 147264 2020-08-08 02:58:27,935 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) We need to allocate to the last host again, so checking if there is enough reserved capacity 2020-08-08 02:58:27,935 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Reserved CPU: 0 , Requested CPU: 500 2020-08-08 02:58:27,935 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Reserved RAM: 0 , Requested RAM: 268435456 2020-08-08 02:58:27,935 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) STATS: Failed to alloc resource from host: 26 reservedCpu: 0, requested cpu: 500, reservedMem: 0, requested mem: 268435456 2020-08-08 02:58:27,935 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Host does not have enough reserved CPU available, cannot allocate to this host. 2020-08-08 02:58:27,935 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Checking if host: 26 has enough capacity for requested CPU: 500 and requested RAM: 268435456 , cpuOverprovisioningFactor: 2.0 2020-08-08 02:58:27,936 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Hosts's actual total CPU: 73632 and CPU after applying overprovisioning: 147264 2020-08-08 02:58:27,936 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Free CPU: 147264 , Requested CPU: 500 2020-08-08 02:58:27,936 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Free RAM: 250977878016 , Requested RAM: 268435456 2020-08-08 02:58:27,936 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Host has enough CPU and RAM available 2020-08-08 02:58:27,936 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) STATS: Can alloc CPU from host: 26, used: 0, reserved: 0, actual total: 73632, total with overprovisioning: 147264; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true 2020-08-08 02:58:27,936 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) STATS: Can alloc MEM from host: 26, used: 0, reserved: 0, total: 250977878016; requested mem: 268435456,alloc_from_last_host?:false ,considerReservedCapacity?: true 2020-08-08 02:58:27,970 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Service SecurityGroup is not supported in the network id=217 2020-08-08 02:58:28,000 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Asking VirtualRouter to prepare for Nic[1846-739-null-10.102.1.0] 2020-08-08 02:58:28,001 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Service SecurityGroup is not supported in the network id=217 2020-08-08 02:58:28,057 DEBUG [c.c.n.g.ControlNetworkGuru] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Reserved NIC for r-739-VM [ipv4:169.254.2.85 netmask:255.255.0.0 gateway:169.254.0.1] 2020-08-08 02:58:28,086 DEBUG [o.a.c.e.o.VolumeOrchestrator] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) No need to recreate the volume: Vol[874|vm=739|ROOT], since it already has a pool assigned: 5, adding disk to VM 2020-08-08 02:58:28,113 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Boot Args for VM[DomainRouter|r-739-VM]: template=domP name=r-739-VM eth0ip=10.102.1.0 eth0mask=255.255.0.0 gateway=10.102.0.1 domain=cloud.viakoo.com cidrsize=16 dhcprange=10.102.0.1 eth1ip=169.254.2.85 eth1mask=255.255.0.0 type=dhcpsrvr disable_rp_filter=true dns1=10.120.0.5 dns2=10.31.1.2 exposedns=true baremetalnotificationsecuritykey=DBIgxuilvx4rI2SiwghbxHZy/Rurqu36y3SWPNuEL0bJbjoOlbagUROZYbeNTCAd5rdvjGfTISs4e6CHaHEZh1LS7LxYurSzdLhmsPiL8OuvYpK7J6XR68QOwqJY6xVa baremetalnotificationapikey=zXh634lHNEMDgxQnXOiD-2KGhp6QHm6AetMPiMcRsY3kf8Wrx5AyxIyv0EIwz35rgc-DY0_3zEjU1od_bj_xhw host=10.100.255.2 port=8080 2020-08-08 02:58:28,117 DEBUG [c.c.a.ApiServlet] (qtp873610597-705:ctx-6a424cc2) (logid:c4c0c75f) ===START=== 172.31.254.254 -- GET jobid=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json 2020-08-08 02:58:28,122 DEBUG [c.c.a.ApiServer] (qtp873610597-705:ctx-6a424cc2 ctx-331fec93) (logid:c4c0c75f) CIDRs from which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2020-08-08 02:58:28,152 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Resending ipAssoc, port forwarding, load balancing rules as a part of Virtual router start 2020-08-08 02:58:28,155 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Found 0 firewall Egress rule(s) to apply as a part of domR VM[DomainRouter|r-739-VM] start. 2020-08-08 02:58:28,159 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Found0ip Aliases to revoke on the router as a part of dhcp configuration 2020-08-08 02:58:28,159 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Found0ip Aliases to apply on the router as a part of dhcp configuration 2020-08-08 02:58:28,161 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Creating monitoring services on VM[DomainRouter|r-739-VM] start... 2020-08-08 02:58:28,164 DEBUG [c.c.a.ApiServlet] (qtp873610597-705:ctx-6a424cc2 ctx-331fec93) (logid:c4c0c75f) ===END=== 172.31.254.254 -- GET jobid=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json 2020-08-08 02:58:28,167 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) IP of control NIC 169.254.2.85 2020-08-08 02:58:29,297 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Reapplying dhcp entries as a part of domR VM[DomainRouter|r-739-VM] start... 2020-08-08 02:58:29,301 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Reapplying vm data (userData and metaData) entries as a part of domR VM[DomainRouter|r-739-VM] start... 2020-08-08 02:58:29,331 DEBUG [c.c.a.t.Request] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Seq 26-6280551155344867399: Sending { Cmd , MgmtId: 11967559506, via: 26(cloud1.viakoo.com), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StartCommand":{"vm":{"id":739,"name":"r-739-VM","state":"Starting","type":"DomainRouter","cpus":1,"minSpeed":250,"maxSpeed":500,"minRam":134217728,"maxRam":268435456,"arch":"x86_64","os":"Debian GNU/Linux 8 (64-bit)","platformEmulator":"Debian GNU/Linux 8 (64-bit)","bootArgs":" template=domP name=r-739-VM eth0ip=10.102.1.0 eth0mask=255.255.0.0 gateway=10.102.0.1 domain=cloud.viakoo.com cidrsize=16 dhcprange=10.102.0.1 eth1ip=169.254.2.85 eth1mask=255.255.0.0 type=dhcpsrvr disable_rp_filter=true dns1=10.120.0.5 dns2=10.31.1.2 exposedns=true baremetalnotificationsecuritykey=DBIgxuilvx4rI2SiwghbxHZy/Rurqu36y3SWPNuEL0bJbjoOlbagUROZYbeNTCAd5rdvjGfTISs4e6CHaHEZh1LS7LxYurSzdLhmsPiL8OuvYpK7J6XR68QOwqJY6xVa baremetalnotificationapikey=zXh634lHNEMDgxQnXOiD-2KGhp6QHm6AetMPiMcRsY3kf8Wrx5AyxIyv0EIwz35rgc-DY0_3zEjU1od_bj_xhw host=10.100.255.2 port=8080","enableHA":true,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"agjSclA5om3tBly6Uel-8A","params":{"cpuOvercommitRatio":"2.0","memoryOvercommitRatio":"2.0"},"uuid":"7f5bcd06-3c91-4b6c-a67f-f031a18db38a","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"daf7616b-f13b-4d4f-89cc-614709a31aad","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"0ab13de9-2310-334c-b438-94dfb0b8ec84","id":5,"poolType":"NetworkFilesystem","host":"10.100.255.3","path":"/storage/primary3","port":2049,"url":"NetworkFilesystem://10.100.255.3/storage/primary3/?ROLE=Primary&STOREUUID=0ab13de9-2310-334c-b438-94dfb0b8ec84","isManaged":false}},"name":"ROOT-739","size":2097152000,"path":"daf7616b-f13b-4d4f-89cc-614709a31aad","volumeId":874,"vmName":"r-739-VM","accountId":1,"format":"QCOW2","provisioningType":"THIN","id":874,"deviceId":0,"bytesReadRate":0,"bytesWriteRate":0,"iopsReadRate":0,"iopsWriteRate":0,"hypervisorType":"KVM","directDownload":false}},"diskSeq":0,"path":"daf7616b-f13b-4d4f-89cc-614709a31aad","type":"ROOT","_details":{"storageHost":"10.100.255.3","managed":"false","storagePort":"2049","volumeSize":"2097152000"}}],"nics":[{"deviceId":0,"networkRateMbps":-1,"defaultNic":true,"pxeDisable":true,"nicUuid":"71b1fd0b-4562-4773-87f8-925681933b04","details":{"PromiscuousMode":"false","MacAddressChanges":"true","ForgedTransmits":"true"},"dpdkEnabled":false,"uuid":"924eda5f-9a1f-4a8e-9423-18000dc92093","ip":"10.102.1.0","netmask":"255.255.0.0","gateway":"10.102.0.1","mac":"1e:00:6d:02:8f:01","dns1":"10.120.0.5","dns2":"10.31.1.2","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://102","isolationUri":"vlan://102","isSecurityGroupEnabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"pxeDisable":true,"nicUuid":"1c5258fa-4234-4120-b0c4-c25c4d94053d","details":{"PromiscuousMode":"false","MacAddressChanges":"true","ForgedTransmits":"true"},"dpdkEnabled":false,"uuid":"6eff5bd9-4f4d-48fe-b6ed-f50fc115947b","ip":"169.254.2.85","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:02:55","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false}],"guestOsDetails":{},"extraConfig":{}},"hostIp":"10.100.255.1","executeInSequence":false,"wait":0}},{"com.cloud.agent.api.check.CheckSshCommand":{"ip":"169.254.2.85","port":3922,"interval":6,"retries":100,"name":"r-739-VM","wait":0}},{"com.cloud.agent.api.GetDomRVersionCmd":{"accessDetails":{"router.name":"r-739-VM","router.ip":"169.254.2.85"},"wait":0}},{},{"com.cloud.agent.api.routing.AggregationControlCommand":{"action":"Start","accessDetails":{"router.name":"r-739-VM","router.ip":"169.254.2.85","router.guest.ip":"10.102.1.0"},"wait":0}},{"com.cloud.agent.api.routing.SetMonitorServiceCommand":{"services":[{"id":0,"service":"dhcp","processname":"dnsmasq","serviceName":"dnsmasq","servicePath":"/var/run/dnsmasq/dnsmasq.pid","pidFile":"/var/run/dnsmasq/dnsmasq.pid","isDefault":false},{"id":0,"service":"ssh","processname":"sshd","serviceName":"ssh","servicePath":"/var/run/sshd.pid","pidFile":"/var/run/sshd.pid","isDefault":true},{"id":0,"service":"webserver","processname":"apache2","serviceName":"apache2","servicePath":"/var/run/apache2/apache2.pid","pidFile":"/var/run/apache2/apache2.pid","isDefault":true}],"healthChecksConfig":{"gateways":"gatewaysIps=10.102.0.1 169.254.0.1 ","portForwarding":"","systemThresholds":"minDiskNeeded=100.0,maxCpuUsage=100.0,maxMemoryUsage=100.0;","haproxyData":"","virtualMachines":""},"reconfigureAfterUpdate":false,"deleteFromProcessedCache":false,"accessDetails":{"router.health.checks.enabled":"true","router.guest.ip":"10.102.1.0","router.ip":"169.254.2.85","router.name":"r-739-VM","router.health.checks.advanced.interval":"10","router.health.checks.basic.interval":"3","router.health.checks.excluded":""},"wait":0}},{"com.cloud.agent.api.routing.AggregationControlCommand":{"action":"Finish","accessDetails":{"router.name":"r-739-VM","router.ip":"169.254.2.85","router.guest.ip":"10.102.1.0"},"wait":0}}] } 2020-08-08 02:58:30,072 DEBUG [c.c.a.ApiServlet] (qtp873610597-489:ctx-6b7e5001) (logid:b884b0f5) ===START=== 172.31.254.254 -- GET jobId=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json 2020-08-08 02:58:30,081 DEBUG [c.c.a.ApiServer] (qtp873610597-489:ctx-6b7e5001 ctx-aa87b22a) (logid:b884b0f5) CIDRs from which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2020-08-08 02:58:30,121 DEBUG [c.c.a.ApiServlet] (qtp873610597-489:ctx-6b7e5001 ctx-aa87b22a) (logid:b884b0f5) ===END=== 172.31.254.254 -- GET jobId=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json 2020-08-08 02:58:32,110 DEBUG [c.c.a.ApiServlet] (qtp873610597-718:ctx-c7650e1d) (logid:903036b2) ===START=== 172.31.254.254 -- GET jobid=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json 2020-08-08 02:58:32,118 DEBUG [c.c.a.ApiServer] (qtp873610597-718:ctx-c7650e1d ctx-c5ca5c96) (logid:903036b2) CIDRs from which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2020-08-08 02:58:32,147 DEBUG [c.c.a.ApiServlet] (qtp873610597-718:ctx-c7650e1d ctx-c5ca5c96) (logid:903036b2) ===END=== 172.31.254.254 -- GET jobid=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json 2020-08-08 02:58:33,161 DEBUG [c.c.a.ApiServlet] (qtp873610597-719:ctx-aec411b5) (logid:efb92a3b) ===START=== 172.31.254.254 -- GET jobId=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json 2020-08-08 02:58:33,169 DEBUG [c.c.a.ApiServer] (qtp873610597-719:ctx-aec411b5 ctx-4fabeb59) (logid:efb92a3b) CIDRs from which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2020-08-08 02:58:33,212 DEBUG [c.c.a.ApiServlet] (qtp873610597-719:ctx-aec411b5 ctx-4fabeb59) (logid:efb92a3b) ===END=== 172.31.254.254 -- GET jobId=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json 2020-08-08 02:58:36,109 DEBUG [c.c.a.ApiServlet] (qtp873610597-575:ctx-38e14f95) (logid:3e9dcafa) ===START=== 172.31.254.254 -- GET jobid=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json 2020-08-08 02:58:36,117 DEBUG [c.c.a.ApiServer] (qtp873610597-575:ctx-38e14f95 ctx-e71fc6d6) (logid:3e9dcafa) CIDRs from which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2020-08-08 02:58:36,158 DEBUG [c.c.a.ApiServlet] (qtp873610597-575:ctx-38e14f95 ctx-e71fc6d6) (logid:3e9dcafa) ===END=== 172.31.254.254 -- GET jobid=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json 2020-08-08 02:58:36,243 DEBUG [c.c.a.ApiServlet] (qtp873610597-660:ctx-e81164ca) (logid:cc069eb1) ===START=== 172.31.254.254 -- GET jobId=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json 2020-08-08 02:58:36,252 DEBUG [c.c.a.ApiServer] (qtp873610597-660:ctx-e81164ca ctx-caca2a16) (logid:cc069eb1) CIDRs from which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2020-08-08 02:58:36,280 DEBUG [c.c.a.ApiServlet] (qtp873610597-660:ctx-e81164ca ctx-caca2a16) (logid:cc069eb1) ===END=== 172.31.254.254 -- GET jobId=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json 2020-08-08 02:58:39,311 DEBUG [c.c.a.ApiServlet] (qtp873610597-574:ctx-fb9c9d97) (logid:d04e2728) ===START=== 172.31.254.254 -- GET jobId=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json 2020-08-08 02:58:39,319 DEBUG [c.c.a.ApiServer] (qtp873610597-574:ctx-fb9c9d97 ctx-7349af94) (logid:d04e2728) CIDRs from which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2020-08-08 02:58:39,346 DEBUG [c.c.a.ApiServlet] (qtp873610597-574:ctx-fb9c9d97 ctx-7349af94) (logid:d04e2728) ===END=== 172.31.254.254 -- GET jobId=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json 2020-08-08 02:58:40,116 DEBUG [c.c.a.ApiServlet] (qtp873610597-715:ctx-b6428afd) (logid:23804e39) ===START=== 172.31.254.254 -- GET jobid=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json 2020-08-08 02:58:40,125 DEBUG [c.c.a.ApiServer] (qtp873610597-715:ctx-b6428afd ctx-8ae3fa36) (logid:23804e39) CIDRs from which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2020-08-08 02:58:40,169 DEBUG [c.c.a.ApiServlet] (qtp873610597-715:ctx-b6428afd ctx-8ae3fa36) (logid:23804e39) ===END=== 172.31.254.254 -- GET jobid=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json 2020-08-08 02:58:41,130 DEBUG [c.c.a.t.Request] (AgentManager-Handler-10:null) (logid:) Seq 26-6280551155344867399: Processing: { Ans: , MgmtId: 11967559506, via: 26, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StartAnswer":{"vm":{"id":739,"name":"r-739-VM","state":"Starting","type":"DomainRouter","cpus":1,"minSpeed":250,"maxSpeed":500,"minRam":134217728,"maxRam":268435456,"arch":"x86_64","os":"Debian GNU/Linux 8 (64-bit)","platformEmulator":"Debian GNU/Linux 8 (64-bit)","bootArgs":" template=domP name=r-739-VM eth0ip=10.102.1.0 eth0mask=255.255.0.0 gateway=10.102.0.1 domain=cloud.viakoo.com cidrsize=16 dhcprange=10.102.0.1 eth1ip=169.254.2.85 eth1mask=255.255.0.0 type=dhcpsrvr disable_rp_filter=true dns1=10.120.0.5 dns2=10.31.1.2 exposedns=true baremetalnotificationsecuritykey=DBIgxuilvx4rI2SiwghbxHZy/Rurqu36y3SWPNuEL0bJbjoOlbagUROZYbeNTCAd5rdvjGfTISs4e6CHaHEZh1LS7LxYurSzdLhmsPiL8OuvYpK7J6XR68QOwqJY6xVa baremetalnotificationapikey=zXh634lHNEMDgxQnXOiD-2KGhp6QHm6AetMPiMcRsY3kf8Wrx5AyxIyv0EIwz35rgc-DY0_3zEjU1od_bj_xhw host=10.100.255.2 port=8080","enableHA":true,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"agjSclA5om3tBly6Uel-8A","vncAddr":"10.100.255.1","params":{"cpuOvercommitRatio":"2.0","memoryOvercommitRatio":"2.0"},"uuid":"7f5bcd06-3c91-4b6c-a67f-f031a18db38a","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"daf7616b-f13b-4d4f-89cc-614709a31aad","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"0ab13de9-2310-334c-b438-94dfb0b8ec84","id":5,"poolType":"NetworkFilesystem","host":"10.100.255.3","path":"/storage/primary3","port":2049,"url":"NetworkFilesystem://10.100.255.3/storage/primary3/?ROLE=Primary&STOREUUID=0ab13de9-2310-334c-b438-94dfb0b8ec84","isManaged":false}},"name":"ROOT-739","size":2097152000,"path":"daf7616b-f13b-4d4f-89cc-614709a31aad","volumeId":874,"vmName":"r-739-VM","accountId":1,"format":"QCOW2","provisioningType":"THIN","id":874,"deviceId":0,"bytesReadRate":0,"bytesWriteRate":0,"iopsReadRate":0,"iopsWriteRate":0,"hypervisorType":"KVM","directDownload":false}},"diskSeq":0,"path":"daf7616b-f13b-4d4f-89cc-614709a31aad","type":"ROOT","_details":{"storageHost":"10.100.255.3","managed":"false","storagePort":"2049","volumeSize":"2097152000"}}],"nics":[{"deviceId":0,"networkRateMbps":-1,"defaultNic":true,"pxeDisable":true,"nicUuid":"71b1fd0b-4562-4773-87f8-925681933b04","details":{"PromiscuousMode":"false","MacAddressChanges":"true","ForgedTransmits":"true"},"dpdkEnabled":false,"uuid":"924eda5f-9a1f-4a8e-9423-18000dc92093","ip":"10.102.1.0","netmask":"255.255.0.0","gateway":"10.102.0.1","mac":"1e:00:6d:02:8f:01","dns1":"10.120.0.5","dns2":"10.31.1.2","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://102","isolationUri":"vlan://102","isSecurityGroupEnabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"pxeDisable":true,"nicUuid":"1c5258fa-4234-4120-b0c4-c25c4d94053d","details":{"PromiscuousMode":"false","MacAddressChanges":"true","ForgedTransmits":"true"},"dpdkEnabled":false,"uuid":"6eff5bd9-4f4d-48fe-b6ed-f50fc115947b","ip":"169.254.2.85","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:02:55","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false}],"guestOsDetails":{},"extraConfig":{}},"result":true,"wait":0}},{"com.cloud.agent.api.check.CheckSshAnswer":{"result":true,"wait":0}},{"com.cloud.agent.api.GetDomRVersionAnswer":{"result":false,"details":"GetDomRVersionCmd failed","wait":0}},{"com.cloud.agent.api.Answer":{"result":false,"details":"Stopped by previous failure","wait":0}},{"com.cloud.agent.api.Answer":{"result":false,"details":"Stopped by previous failure","wait":0}},{"com.cloud.agent.api.Answer":{"result":false,"details":"Stopped by previous failure","wait":0}},{"com.cloud.agent.api.Answer":{"result":false,"details":"Stopped by previous failure","wait":0}}] } 2020-08-08 02:58:41,130 DEBUG [c.c.a.t.Request] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Seq 26-6280551155344867399: Received: { Ans: , MgmtId: 11967559506, via: 26(cloud1.viakoo.com), Ver: v1, Flags: 10, { StartAnswer, CheckSshAnswer, GetDomRVersionAnswer, Answer, Answer, Answer, Answer } } 2020-08-08 02:58:41,169 WARN [c.c.a.AlertManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) AlertType:: 9 | dataCenterId:: 1 | podId:: 1 | clusterId:: null | message:: Command: com.cloud.agent.api.GetDomRVersionCommand failed while starting virtual router 2020-08-08 02:58:41,193 ERROR [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) GetDomRVersionCmd failed 2020-08-08 02:58:41,193 WARN [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Command: com.cloud.agent.api.GetDomRVersionCommand failed while starting virtual router 2020-08-08 02:58:41,194 INFO [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) The guru did not like the answers so stopping VM[DomainRouter|r-739-VM] 2020-08-08 02:58:41,197 DEBUG [c.c.a.t.Request] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Seq 26-6280551155344867400: Sending { Cmd , MgmtId: 11967559506, via: 26(cloud1.viakoo.com), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"controlIp":"169.254.2.130","forceStop":false,"volumesToDisconnect":[],"vmName":"r-739-VM","executeInSequence":false,"wait":0}}] } 2020-08-08 02:58:41,667 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-11392b38) (logid:d3c5e4e9) AutoScaling Monitor is running... 2020-08-08 02:58:42,377 DEBUG [c.c.a.ApiServlet] (qtp873610597-704:ctx-b3661e00) (logid:337d2228) ===START=== 172.31.254.254 -- GET jobId=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json 2020-08-08 02:58:42,386 DEBUG [c.c.a.ApiServer] (qtp873610597-704:ctx-b3661e00 ctx-274fb045) (logid:337d2228) CIDRs from which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2020-08-08 02:58:42,413 DEBUG [c.c.a.ApiServlet] (qtp873610597-704:ctx-b3661e00 ctx-274fb045) (logid:337d2228) ===END=== 172.31.254.254 -- GET jobId=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json 2020-08-08 02:58:43,486 DEBUG [c.c.a.t.Request] (AgentManager-Handler-6:null) (logid:) Seq 26-6280551155344867400: Processing: { Ans: , MgmtId: 11967559506, via: 26, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] } 2020-08-08 02:58:43,486 DEBUG [c.c.a.t.Request] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Seq 26-6280551155344867400: Received: { Ans: , MgmtId: 11967559506, via: 26(cloud1.viakoo.com), Ver: v1, Flags: 10, { StopAnswer } } 2020-08-08 02:58:43,486 ERROR [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Failed to start instance VM[DomainRouter|r-739-VM] com.cloud.utils.exception.ExecutionException: Unable to start VM:7f5bcd06-3c91-4b6c-a67f-f031a18db38a due to error in finalizeStart, not retrying at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1240) at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5227) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:566) at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107) at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5390) at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:603) at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53) at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:551) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:834) 2020-08-08 02:58:43,539 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Cleaning up resources for the vm VM[DomainRouter|r-739-VM] in Starting state 2020-08-08 02:58:43,547 DEBUG [c.c.a.t.Request] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Seq 26-6280551155344867401: Sending { Cmd , MgmtId: 11967559506, via: 26(cloud1.viakoo.com), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"controlIp":"169.254.2.130","forceStop":false,"volumesToDisconnect":[],"vmName":"r-739-VM","executeInSequence":false,"wait":0}}] } 2020-08-08 02:58:43,555 DEBUG [c.c.a.t.Request] (AgentManager-Handler-15:null) (logid:) Seq 26-6280551155344867401: Processing: { Ans: , MgmtId: 11967559506, via: 26, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] } 2020-08-08 02:58:43,555 DEBUG [c.c.a.t.Request] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Seq 26-6280551155344867401: Received: { Ans: , MgmtId: 11967559506, via: 26(cloud1.viakoo.com), Ver: v1, Flags: 10, { StopAnswer } } 2020-08-08 02:58:43,560 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Successfully updated user statistics as a part of domR VM[DomainRouter|r-739-VM] reboot/stop 2020-08-08 02:58:43,680 DEBUG [c.c.n.g.ControlNetworkGuru] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Released nic: NicProfile[1847-739-null-null-null 2020-08-08 02:58:43,723 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Successfully released network resources for the vm VM[DomainRouter|r-739-VM] 2020-08-08 02:58:43,723 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Successfully cleaned up resources for the VM VM[DomainRouter|r-739-VM] in Starting state 2020-08-08 02:58:43,781 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 26 2020-08-08 02:58:43,790 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Hosts's actual total CPU: 73632 and CPU after applying overprovisioning: 147264 2020-08-08 02:58:43,790 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Hosts's actual total RAM: 125488934912 and RAM after applying overprovisioning: 250977878016 2020-08-08 02:58:43,790 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) release cpu from host: 26, old used: 500,reserved: 0, actual total: 73632, total with overprovisioning: 147264; new used: 0,reserved:0; movedfromreserved: false,moveToReserveredfalse 2020-08-08 02:58:43,790 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) release mem from host: 26, old used: 268435456,reserved: 0, total: 250977878016; new used: 0,reserved:0; movedfromreserved: false,moveToReserveredfalse 2020-08-08 02:58:43,809 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Invocation exception, caused by: com.cloud.exception.AgentUnavailableException: Resource [Host:26] is unreachable: Host 26: Unable to start instance due to Unable to start VM:7f5bcd06-3c91-4b6c-a67f-f031a18db38a due to error in finalizeStart, not retrying 2020-08-08 02:58:43,809 INFO [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459 ctx-caee4f99) (logid:1051f59c) Rethrow exception com.cloud.exception.AgentUnavailableException: Resource [Host:26] is unreachable: Host 26: Unable to start instance due to Unable to start VM:7f5bcd06-3c91-4b6c-a67f-f031a18db38a due to error in finalizeStart, not retrying 2020-08-08 02:58:43,809 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459) (logid:1051f59c) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 739, job origin: 132458 2020-08-08 02:58:43,809 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459) (logid:1051f59c) Unable to complete AsyncJobVO {id:132459, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAC43QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AA5SZXN0YXJ0TmV0d29ya3QAP3JPMEFCWE55QUJGcVlYWmhMbXhoYm1jdVFtOXZiR1ZoYnMwZ2NvRFZuUHJ1QWdBQldnQUZkbUZzZFdWNGNBRXhw, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 11967559506, completeMsid: null, lastUpdated: null, lastPolled: null, created: Sat Aug 08 02:58:27 UTC 2020, removed: null}, job origin:132458 com.cloud.exception.AgentUnavailableException: Resource [Host:26] is unreachable: Host 26: Unable to start instance due to Unable to start VM:7f5bcd06-3c91-4b6c-a67f-f031a18db38a due to error in finalizeStart, not retrying at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1276) at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5227) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:566) at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107) at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5390) at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:603) at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53) at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:551) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:834) Caused by: com.cloud.utils.exception.ExecutionException: Unable to start VM:7f5bcd06-3c91-4b6c-a67f-f031a18db38a due to error in finalizeStart, not retrying at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1240) at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5227) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ... 18 more 2020-08-08 02:58:43,823 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459) (logid:1051f59c) Complete async job-132459, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyAC1jb20uY2xvdWQuZXhjZXB0aW9uLkFnZW50VW5hdmFpbGFibGVFeGNlcHRpb24AAAAAVk1PdwIAAHhyADBjb20uY2xvdWQuZXhjZXB0aW9uLlJlc291cmNlVW5hdmFpbGFibGVFeGNlcHRpb24AAAAAVk1PfwIAAkoAA19pZEwABl9zY29wZXQAEUxqYXZhL2xhbmcvQ2xhc3M7eHIAImNvbS5jbG91ZC5leGNlcHRpb24uQ2xvdWRFeGNlcHRpb2556I4b8eRExwIAAkwAC2NzRXJyb3JDb2RldAATTGphdmEvbGFuZy9JbnRlZ2VyO0wABmlkTGlzdHQAFUxqYXZhL3V0aWwvQXJyYXlMaXN0O3hyABNqYXZhLmxhbmcuRXhjZXB0aW9u0P0fPho7HMQCAAB4cgATamF2YS5sYW5nLlRocm93YWJsZdXGNSc5d7jLAwAETAAFY2F1c2V0ABVMamF2YS9sYW5nL1Rocm93YWJsZTtMAA1kZXRhaWxNZXNzYWdldAASTGphdmEvbGFuZy9TdHJpbmc7WwAKc3RhY2tUcmFjZXQAHltMamF2YS9sYW5nL1N0YWNrVHJhY2VFbGVtZW50O0wAFHN1cHByZXNzZWRFeGNlcHRpb25zdAAQTGphdmEvdXRpbC9MaXN0O3hwc3IALGNvbS5jbG91ZC51dGlscy5leGNlcHRpb24uRXhlY3V0aW9uRXhjZXB0aW9uAAAAAFZNT34CAAFJAAtjc0Vycm9yQ29kZXhxAH4ABnEAfgAOdABkVW5hYmxlIHRvIHN0YXJ0ICBWTTo3ZjViY2QwNi0zYzkxLTRiNmMtYTY3Zi1mMDMxYTE4ZGIzOGEgZHVlIHRvIGVycm9yIGluIGZpbmFsaXplU3RhcnQsIG5vdCByZXRyeWluZ3VyAB5bTGphdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudDsCRio8PP0iOQIAAHhwAAAAFXNyABtqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnRhCcWaJjbdhQIACEIABmZvcm1hdEkACmxpbmVOdW1iZXJMAA9jbGFzc0xvYWRlck5hbWVxAH4ACUwADmRlY2xhcmluZ0NsYXNzcQB-AAlMAAhmaWxlTmFtZXEAfgAJTAAKbWV0aG9kTmFtZXEAfgAJTAAKbW9kdWxlTmFtZXEAfgAJTAANbW9kdWxlVmVyc2lvbnEAfgAJeHABAAAE2HQAA2FwcHQAJmNvbS5jbG91ZC52bS5WaXJ0dWFsTWFjaGluZU1hbmFnZXJJbXBsdAAeVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbC5qYXZhdAAQb3JjaGVzdHJhdGVTdGFydHBwc3EAfgASAQAAFGtxAH4AFHEAfgAVcQB-ABZxAH4AF3Bwc3EAfgASAv____5wdAAtamRrLmludGVybmFsLnJlZmxlY3QuTmF0aXZlTWV0aG9kQWNjZXNzb3JJbXBsdAAdTmF0aXZlTWV0aG9kQWNjZXNzb3JJbXBsLmphdmF0AAdpbnZva2UwdAAJamF2YS5iYXNldAAGMTEuMC43c3EAfgASAgAAAD5wcQB-ABpxAH4AG3QABmludm9rZXEAfgAdcQB-AB5zcQB-ABICAAAAK3B0ADFqZGsuaW50ZXJuYWwucmVmbGVjdC5EZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsdAAhRGVsZWdhdGluZ01ldGhvZEFjY2Vzc29ySW1wbC5qYXZhcQB-ACBxAH4AHXEAfgAec3EAfgASAgAAAjZwdAAYamF2YS5sYW5nLnJlZmxlY3QuTWV0aG9kdAALTWV0aG9kLmphdmFxAH4AIHEAfgAdcQB-AB5zcQB-ABIBAAAAa3EAfgAUdAAiY29tLmNsb3VkLnZtLlZtV29ya0pvYkhhbmRsZXJQcm94eXQAGlZtV29ya0pvYkhhbmRsZXJQcm94eS5qYXZhdAAPaGFuZGxlVm1Xb3JrSm9icHBzcQB-ABIBAAAVDnEAfgAUcQB-ABVxAH4AFnEAfgAqcHBzcQB-ABIBAAAAZnEAfgAUdAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRpc3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JwcHNxAH4AEgEAAAJbcQB-ABR0AD9vcmcuYXBhY2hlLmNsb3Vkc3RhY2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0AAxydW5JbkNvbnRleHRwcHNxAH4AEgEAAAAxcQB-ABR0AD5vcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGUkMXQAG01hbmFnZWRDb250ZXh0UnVubmFibGUuamF2YXQAA3J1bnBwc3EAfgASAQAAADhxAH4AFHQAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbHBwc3EAfgASAQAAAGdxAH4AFHQAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHRxAH4AOnQAD2NhbGxXaXRoQ29udGV4dHBwc3EAfgASAQAAADVxAH4AFHEAfgA9cQB-ADp0AA5ydW5XaXRoQ29udGV4dHBwc3EAfgASAQAAAC5xAH4AFHQAPG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgA2cQB-ADdwcHNxAH4AEgEAAAIncQB-ABRxAH4AMXEAfgAycQB-ADdwcHNxAH4AEgIAAAIDcHQALmphdmEudXRpbC5jb25jdXJyZW50LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgA7cQB-AB1xAH4AHnNxAH4AEgIAAAEIcHQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0AA9GdXR1cmVUYXNrLmphdmFxAH4AN3EAfgAdcQB-AB5zcQB-ABICAAAEaHB0ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnEAfgAdcQB-AB5zcQB-ABICAAACdHB0AC5qYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-AExxAH4AN3EAfgAdcQB-AB5zcQB-ABICAAADQnB0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4AN3EAfgAdcQB-AB5zcgAfamF2YS51dGlsLkNvbGxlY3Rpb25zJEVtcHR5TGlzdHq4F7Q8p57eAgAAeHB4AAAAAHQAsFJlc291cmNlIFtIb3N0OjI2XSBpcyB1bnJlYWNoYWJsZTogSG9zdCAyNjogVW5hYmxlIHRvIHN0YXJ0IGluc3RhbmNlIGR1ZSB0byBVbmFibGUgdG8gc3RhcnQgIFZNOjdmNWJjZDA2LTNjOTEtNGI2Yy1hNjdmLWYwMzFhMThkYjM4YSBkdWUgdG8gZXJyb3IgaW4gZmluYWxpemVTdGFydCwgbm90IHJldHJ5aW5ndXEAfgAQAAAAFXNxAH4AEgEAAAT8cQB-ABRxAH4AFXEAfgAWcQB-ABdwcHNxAH4AEgEAABRrcQB-ABRxAH4AFXEAfgAWcQB-ABdwcHNxAH4AEgL____-cHEAfgAacQB-ABtxAH4AHHEAfgAdcQB-AB5zcQB-ABICAAAAPnBxAH4AGnEAfgAbcQB-ACBxAH4AHXEAfgAec3EAfgASAgAAACtwcQB-ACJxAH4AI3EAfgAgcQB-AB1xAH4AHnNxAH4AEgIAAAI2cHEAfgAlcQB-ACZxAH4AIHEAfgAdcQB-AB5zcQB-ABIBAAAAa3EAfgAUcQB-AChxAH4AKXEAfgAqcHBzcQB-ABIBAAAVDnEAfgAUcQB-ABVxAH4AFnEAfgAqcHBzcQB-ABIBAAAAZnEAfgAUcQB-AC1xAH4ALnEAfgAvcHBzcQB-ABIBAAACW3EAfgAUcQB-ADFxAH4AMnEAfgAzcHBzcQB-ABIBAAAAMXEAfgAUcQB-ADVxAH4ANnEAfgA3cHBzcQB-ABIBAAAAOHEAfgAUcQB-ADlxAH4AOnEAfgA7cHBzcQB-ABIBAAAAZ3EAfgAUcQB-AD1xAH4AOnEAfgA-cHBzcQB-ABIBAAAANXEAfgAUcQB-AD1xAH4AOnEAfgBAcHBzcQB-ABIBAAAALnEAfgAUcQB-AEJxAH4ANnEAfgA3cHBzcQB-ABIBAAACJ3EAfgAUcQB-ADFxAH4AMnEAfgA3cHBzcQB-ABICAAACA3BxAH4ARXEAfgBGcQB-ADtxAH4AHXEAfgAec3EAfgASAgAAAQhwcQB-AEhxAH4ASXEAfgA3cQB-AB1xAH4AHnNxAH4AEgIAAARocHEAfgBLcQB-AExxAH4ATXEAfgAdcQB-AB5zcQB-ABICAAACdHBxAH4AT3EAfgBMcQB-ADdxAH4AHXEAfgAec3EAfgASAgAAA0JwcQB-AFFxAH4AUnEAfgA3cQB-AB1xAH4AHnEAfgBUeHNyABFqYXZhLmxhbmcuSW50ZWdlchLioKT3gYc4AgABSQAFdmFsdWV4cgAQamF2YS5sYW5nLk51bWJlcoaslR0LlOCLAgAAeHAAABC9c3IAE2phdmEudXRpbC5BcnJheUxpc3R4gdIdmcdhnQMAAUkABHNpemV4cAAAAAB3BAAAAAB4AAAAAAAAABp2cgATY29tLmNsb3VkLmhvc3QuSG9zdJYzfa477cOJAgAAeHA 2020-08-08 02:58:43,824 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459) (logid:1051f59c) Publish async job-132459 complete on message bus 2020-08-08 02:58:43,824 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459) (logid:1051f59c) Wake up jobs related to job-132459 2020-08-08 02:58:43,824 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459) (logid:1051f59c) Update db status for job-132459 2020-08-08 02:58:43,825 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459) (logid:1051f59c) Wake up jobs joined with job-132459 and disjoin all subjobs created from job- 132459 2020-08-08 02:58:43,851 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459) (logid:1051f59c) Done executing com.cloud.vm.VmWorkStart for job-132459 2020-08-08 02:58:43,853 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-9:ctx-17f1d510 job-132458/job-132459) (logid:1051f59c) Remove job-132459 from job monitoring 2020-08-08 02:58:43,903 ERROR [c.c.a.ApiAsyncJobDispatcher] (API-Job-Executor-11:ctx-b6673908 job-132458) (logid:1051f59c) Unexpected exception while executing org.apache.cloudstack.api.command.admin.router.StartRouterCmd com.cloud.exception.AgentUnavailableException: Resource [Host:26] is unreachable: Host 26: Unable to start instance due to Unable to start VM:7f5bcd06-3c91-4b6c-a67f-f031a18db38a due to error in finalizeStart, not retrying at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1276) at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5227) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:566) at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107) at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5390) at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:603) at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53) at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:551) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:834) Caused by: com.cloud.utils.exception.ExecutionException: Unable to start VM:7f5bcd06-3c91-4b6c-a67f-f031a18db38a due to error in finalizeStart, not retrying at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1240) at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5227) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ... 18 more 2020-08-08 02:58:43,905 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-11:ctx-b6673908 job-132458) (logid:1051f59c) Complete async job-132458, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Resource [Host:26] is unreachable: Host 26: Unable to start instance due to Unable to start VM:7f5bcd06-3c91-4b6c-a67f-f031a18db38a due to error in finalizeStart, not retrying"} 2020-08-08 02:58:43,906 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-11:ctx-b6673908 job-132458) (logid:1051f59c) Publish async job-132458 complete on message bus 2020-08-08 02:58:43,906 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-11:ctx-b6673908 job-132458) (logid:1051f59c) Wake up jobs related to job-132458 2020-08-08 02:58:43,906 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-11:ctx-b6673908 job-132458) (logid:1051f59c) Update db status for job-132458 2020-08-08 02:58:43,907 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-11:ctx-b6673908 job-132458) (logid:1051f59c) Wake up jobs joined with job-132458 and disjoin all subjobs created from job- 132458 2020-08-08 02:58:43,929 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-11:ctx-b6673908 job-132458) (logid:1051f59c) Done executing org.apache.cloudstack.api.command.admin.router.StartRouterCmd for job-132458 2020-08-08 02:58:43,929 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-11:ctx-b6673908 job-132458) (logid:1051f59c) Remove job-132458 from job monitoring 2020-08-08 02:58:44,110 DEBUG [c.c.a.ApiServlet] (qtp873610597-720:ctx-8a868b80) (logid:4cdef68a) ===START=== 172.31.254.254 -- GET jobid=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json 2020-08-08 02:58:44,118 DEBUG [c.c.a.ApiServer] (qtp873610597-720:ctx-8a868b80 ctx-54db7537) (logid:4cdef68a) CIDRs from which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2020-08-08 02:58:44,148 DEBUG [c.c.a.ApiServlet] (qtp873610597-720:ctx-8a868b80 ctx-54db7537) (logid:4cdef68a) ===END=== 172.31.254.254 -- GET jobid=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json 2020-08-08 02:58:45,458 DEBUG [c.c.a.ApiServlet] (qtp873610597-544:ctx-2294155c) (logid:3611626e) ===START=== 172.31.254.254 -- GET jobId=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json 2020-08-08 02:58:45,467 DEBUG [c.c.a.ApiServer] (qtp873610597-544:ctx-2294155c ctx-756b571f) (logid:3611626e) CIDRs from which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2020-08-08 02:58:45,496 DEBUG [c.c.a.ApiServlet] (qtp873610597-544:ctx-2294155c ctx-756b571f) (logid:3611626e) ===END=== 172.31.254.254 -- GET jobId=1051f59c-efaf-45f3-9c1e-e5b82474d7c7&command=queryAsyncJobResult&response=json 2020-08-08 02:58:45,554 DEBUG [c.c.a.ApiServlet] (qtp873610597-489:ctx-bfe2d642) (logid:a8a181dd) ===START=== 172.31.254.254 -- GET listall=true&projectid=-1&id=7f5bcd06-3c91-4b6c-a67f-f031a18db38a&page=1&pagesize=20&command=listRouters&response=json 2020-08-08 02:58:45,562 DEBUG [c.c.a.ApiServer] (qtp873610597-489:ctx-bfe2d642 ctx-8abf67d5) (logid:a8a181dd) CIDRs from which account 'Acct[eaf96ac1-7583-11e7-8cfa-0025900b6586-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2020-08-08 02:58:45,574 DEBUG [c.c.a.ApiServlet] (qtp873610597-489:ctx-bfe2d642 ctx-8abf67d5) (logid:a8a181dd) ===END=== 172.31.254.254 -- GET listall=true&projectid=-1&id=7f5bcd06-3c91-4b6c-a67f-f031a18db38a&page=1&pagesize=20&command=listRouters&response=json 2020-08-08 02:58:47,074 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-d5862246) (logid:3cd62b0c) Zone 1 is not ready to launch console proxy yet 2020-08-08 02:58:48,642 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-9c5808ec) (logid:fea58b3f) HostStatsCollector is running... 2020-08-08 02:58:48,695 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-9c5808ec) (logid:fea58b3f) Seq 26-6280551155344867402: Received: { Ans: , MgmtId: 11967559506, via: 26(cloud1.viakoo.com), Ver: v1, Flags: 10, { GetHostStatsAnswer } } 2020-08-08 02:58:50,559 DEBUG [c.c.s.StatsCollector] (StatsCollector-4:ctx-a7908f9e) (logid:0426fb7e) StorageCollector is running... 2020-08-08 02:58:50,568 DEBUG [c.c.s.StatsCollector] (StatsCollector-4:ctx-a7908f9e) (logid:0426fb7e) There is no secondary storage VM for secondary storage host secondary1 2020-08-08 02:58:50,571 DEBUG [c.c.s.StatsCollector] (StatsCollector-4:ctx-a7908f9e) (logid:0426fb7e) There is no secondary storage VM for secondary storage host secondary2 2020-08-08 02:58:50,573 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollector-4:ctx-a7908f9e) (logid:0426fb7e) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand 2020-08-08 02:58:50,573 DEBUG [c.c.h.XenServerGuru] (StatsCollector-4:ctx-a7908f9e) (logid:0426fb7e) We are returning the default host to execute commands because the command is not of Copy type. 2020-08-08 02:58:50,921 DEBUG [c.c.a.t.Request] (StatsCollector-4:ctx-a7908f9e) (logid:0426fb7e) Seq 26-6280551155344867403: Received: { Ans: , MgmtId: 11967559506, via: 26(cloud1.viakoo.com), Ver: v1, Flags: 10, { GetStorageStatsAnswer } } 2020-08-08 02:58:50,922 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollector-4:ctx-a7908f9e) (logid:0426fb7e) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand 2020-08-08 02:58:50,922 DEBUG [c.c.h.XenServerGuru] (StatsCollector-4:ctx-a7908f9e) (logid:0426fb7e) We are returning the default host to execute commands because the command is not of Copy type. 2020-08-08 02:58:51,110 DEBUG [c.c.a.t.Request] (StatsCollector-4:ctx-a7908f9e) (logid:0426fb7e) Seq 26-6280551155344867404: Received: { Ans: , MgmtId: 11967559506, via: 26(cloud1.viakoo.com), Ver: v1, Flags: 10, { GetStorageStatsAnswer } } 2020-08-08 02:58:56,169 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-ff58463b) (logid:fd41b754) Found 0 routers to update status. 2020-08-08 02:58:56,170 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-ff58463b) (logid:fd41b754) Found 0 VPC's to update Redundant State. 2020-08-08 02:58:56,171 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-ff58463b) (logid:fd41b754) Found 0 networks to update RvR status. 2020-08-08 02:59:00,743 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-ae913929) (logid:8f37d206) Resetting hosts suitable for reconnect 2020-08-08 02:59:00,744 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-ae913929) (logid:8f37d206) Completed resetting hosts suitable for reconnect 2020-08-08 02:59:00,744 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-ae913929) (logid:8f37d206) Acquiring hosts for clusters already owned by this management server 2020-08-08 02:59:00,745 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-ae913929) (logid:8f37d206) Completed acquiring hosts for clusters already owned by this management server 2020-08-08 02:59:00,745 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-ae913929) (logid:8f37d206) Acquiring hosts for clusters not owned by any management server 2020-08-08 02:59:00,746 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-ae913929) (logid:8f37d206) Completed acquiring hosts for clusters not owned by any management server ^ [-------------------------------------------------------/snip---------------------------------------------------------------------] Some versions (I've been playing around with downgrading and trying different versions, currently running the Centos 7.7 versions on Centos 7.8): [root@cloud1 qemu]# rpm -q qemu-kvm qemu-kvm-1.5.3-167.el7_7.4.x86_64 [root@cloud1 qemu]# rpm -q libvirt libvirt-4.5.0-23.el7_7.6.x86_64 rohit.ya...@shapeblue.com www.shapeblue.com 3 London Bridge Street, 3rd floor, News Building, London SE1 9SGUK @shapeblue
