ccycv opened a new issue #4118: URL: https://github.com/apache/cloudstack/issues/4118
##### ISSUE TYPE `Bug Report` ##### COMPONENT NAME `KVM, CloudStack Agent.` ##### CLOUDSTACK VERSION `CloudStack 4.13.0 ` ##### CONFIGURATION `Advanced Networking with Local Storage and Ceph storage RBD.` ##### OS / ENVIRONMENT ``` CentOS Linux release 7.8.2003 (Core) qemu-kvm 1.5.3 cloudstack-agent 4.13.0.0 libvirt 4.5.0 ``` ##### SUMMARY This issue started from nothing, we wanted to deploy a new VM and we started to get this error in the UI, after this we saw that the state was changed for each KVM from connected to "connecting". From this point we started to check the logs for agent, libvirtd also on Ceph storage. We didn't' found any error on Ceph. ![Untitled2](https://user-images.githubusercontent.com/23322009/83228544-2e747200-a18f-11ea-9e2f-b056a39ab80b.png) ![Untitled](https://user-images.githubusercontent.com/23322009/83228573-3af8ca80-a18f-11ea-872f-fd2686675596.png) Cloudstack Agent Logs: ~~~ Full log : https://gist.github.com/ccycv/b026c0d4edd19ac8ef012d334dff8b84 2020-05-29 09:48:38,110 INFO [cloud.agent.AgentShell] (main:null) (logid:) Agent started 2020-05-29 09:48:38,113 INFO [cloud.agent.AgentShell] (main:null) (logid:) Implementation Version is 4.13.0.0 2020-05-29 09:48:38,115 INFO [cloud.agent.AgentShell] (main:null) (logid:) agent.properties found at /etc/cloudstack/agent/agent.properties 2020-05-29 09:48:38,131 DEBUG [cloud.agent.AgentShell] (main:null) (logid:) Found property: guest.network.device 2020-05-29 09:48:38,131 DEBUG [cloud.agent.AgentShell] (main:null) (logid:) Found property: workers 2020-05-29 09:48:38,131 DEBUG [cloud.agent.AgentShell] (main:null) (logid:) Found property: private.network.device 2020-05-29 09:48:38,131 DEBUG [cloud.agent.AgentShell] (main:null) (logid:) Found property: port 2020-05-29 09:48:38,131 DEBUG [cloud.agent.AgentShell] (main:null) (logid:) Found property: resource 2020-05-29 09:48:38,131 DEBUG [cloud.agent.AgentShell] (main:null) (logid:) Found property: pod 2020-05-29 09:48:38,131 DEBUG [cloud.agent.AgentShell] (main:null) (logid:) Found property: storage.network.device 2020-05-29 09:48:38,131 DEBUG [cloud.agent.AgentShell] (main:null) (logid:) Found property: zone 2020-05-29 09:48:38,132 DEBUG [cloud.agent.AgentShell] (main:null) (logid:) Found property: guid 2020-05-29 09:48:38,132 DEBUG [cloud.agent.AgentShell] (main:null) (logid:) Found property: hypervisor.type 2020-05-29 09:48:38,132 DEBUG [cloud.agent.AgentShell] (main:null) (logid:) Found property: cluster 2020-05-29 09:48:38,132 DEBUG [cloud.agent.AgentShell] (main:null) (logid:) Found property: public.network.device 2020-05-29 09:48:38,136 DEBUG [cloud.agent.AgentShell] (main:null) (logid:) Found property: local.storage.uuid 2020-05-29 09:48:38,136 DEBUG [cloud.agent.AgentShell] (main:null) (logid:) Found property: domr.scripts.dir 2020-05-29 09:48:38,136 DEBUG [cloud.agent.AgentShell] (main:null) (logid:) Found property: keystore.passphrase 2020-05-29 09:48:38,136 DEBUG [cloud.agent.AgentShell] (main:null) (logid:) Found property: host 2020-05-29 09:48:38,136 DEBUG [cloud.agent.AgentShell] (main:null) (logid:) Found property: LibvirtComputingResource.id 2020-05-29 09:48:38,136 INFO [cloud.agent.AgentShell] (main:null) (logid:) Defaulting to using properties file for storage 2020-05-29 09:48:38,138 INFO [cloud.agent.AgentShell] (main:null) (logid:) Defaulting to the constant time backoff algorithm 2020-05-29 09:48:38,153 INFO [cloud.utils.LogUtils] (main:null) (logid:) log4j configuration found at /etc/cloudstack/agent/log4j-cloud.xml 2020-05-29 09:48:38,167 INFO [cloud.agent.AgentShell] (main:null) (logid:) Using default Java settings for IPv6 preference for agent connection 2020-05-29 09:48:38,168 DEBUG [cloud.agent.AgentShell] (main:null) (logid:) Checking to see if agent.pid exists. 2020-05-29 09:48:38,179 DEBUG [cloud.utils.ProcessUtil] (main:null) (logid:) Executing: bash -c echo $PPID 2020-05-29 09:48:38,257 DEBUG [cloud.utils.ProcessUtil] (main:null) (logid:) Executing while with timeout : 120000 2020-05-29 09:48:38,257 DEBUG [cloud.utils.ProcessUtil] (main:null) (logid:) Execution is successful. 2020-05-29 09:48:38,326 INFO [cloud.agent.Agent] (main:null) (logid:) id is 0 2020-05-29 09:48:38,327 DEBUG [cloud.resource.ServerResourceBase] (main:null) (logid:) Retrieving network interface: cloudbr0 2020-05-29 09:48:38,328 DEBUG [cloud.resource.ServerResourceBase] (main:null) (logid:) Retrieving network interface: cloudbr2 2020-05-29 09:48:38,328 DEBUG [cloud.resource.ServerResourceBase] (main:null) (logid:) Unable to get network interface for cloudbr2 2020-05-29 09:48:38,328 DEBUG [cloud.resource.ServerResourceBase] (main:null) (logid:) Retrieving network interface: cloudbr249 2020-05-29 09:48:38,328 DEBUG [cloud.resource.ServerResourceBase] (main:null) (logid:) Retrieving network interface: null 2020-05-29 09:48:38,343 DEBUG [resource.virtualnetwork.VirtualRoutingResource] (main:null) (logid:) The router.aggregation.command.each.timeout in seconds is set to 600 2020-05-29 09:48:38,344 DEBUG [utils.script.Script] (main:null) (logid:) Looking for update_host_passwd.sh in the classpath 2020-05-29 09:48:38,344 DEBUG [utils.script.Script] (main:null) (logid:) System resource: null 2020-05-29 09:48:38,344 DEBUG [utils.script.Script] (main:null) (logid:) Classpath resource: null 2020-05-29 09:48:38,344 DEBUG [utils.script.Script] (main:null) (logid:) Looking for update_host_passwd.sh 2020-05-29 09:48:38,345 DEBUG [utils.script.Script] (main:null) (logid:) Current binaries reside at /usr/share/cloudstack-agent/lib 2020-05-29 09:48:38,345 DEBUG [utils.script.Script] (main:null) (logid:) Looking for update_host_passwd.sh in /usr/share/cloudstack-agent/lib/scripts/vm/hypervisor/update_host_passwd.sh 2020-05-29 09:48:38,345 DEBUG [utils.script.Script] (main:null) (logid:) Looking for update_host_passwd.sh in /usr/share/cloudstack-agent/lib/scripts/vm/update_host_passwd.sh 2020-05-29 09:48:38,345 DEBUG [utils.script.Script] (main:null) (logid:) Looking for update_host_passwd.sh in /usr/share/cloudstack-agent/lib/scripts/update_host_passwd.sh 2020-05-29 09:48:38,345 DEBUG [utils.script.Script] (main:null) (logid:) Looking for update_host_passwd.sh in /usr/share/cloudstack-agent/lib/update_host_passwd.sh 2020-05-29 09:48:38,345 DEBUG [utils.script.Script] (main:null) (logid:) Looking for update_host_passwd.sh in /usr/share/cloudstack-agent/update_host_passwd.sh 2020-05-29 09:48:38,345 DEBUG [utils.script.Script] (main:null) (logid:) Looking for update_host_passwd.sh in /usr/share/update_host_passwd.sh 2020-05-29 09:48:38,345 DEBUG [utils.script.Script] (main:null) (logid:) Looking for update_host_passwd.sh in /usr/update_host_passwd.sh 2020-05-29 09:48:38,345 DEBUG [utils.script.Script] (main:null) (logid:) Looking for update_host_passwd.sh in /update_host_passwd.sh 2020-05-29 09:48:38,346 DEBUG [utils.script.Script] (main:null) (logid:) Searching in environment.properties 2020-05-29 09:48:38,346 DEBUG [utils.script.Script] (main:null) (logid:) environment.properties says scripts should be in /usr/share/cloudstack-common 2020-05-29 09:48:38,346 DEBUG [utils.script.Script] (main:null) (logid:) Looking for update_host_passwd.sh in /usr/share/cloudstack-common/scripts/vm/hypervisor/update_host_passwd.sh 2020-05-29 09:48:38,346 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvlan.sh in the classpath 2020-05-29 09:48:38,346 DEBUG [utils.script.Script] (main:null) (logid:) System resource: null 2020-05-29 09:48:38,347 DEBUG [utils.script.Script] (main:null) (logid:) Classpath resource: null 2020-05-29 09:48:38,347 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvlan.sh 2020-05-29 09:48:38,347 DEBUG [utils.script.Script] (main:null) (logid:) Current binaries reside at /usr/share/cloudstack-agent/lib 2020-05-29 09:48:38,347 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvlan.sh in /usr/share/cloudstack-agent/lib/scripts/vm/network/vnet/modifyvlan.sh 2020-05-29 09:48:38,347 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvlan.sh in /usr/share/cloudstack-agent/lib/scripts/vm/network/modifyvlan.sh 2020-05-29 09:48:38,347 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvlan.sh in /usr/share/cloudstack-agent/lib/scripts/vm/modifyvlan.sh 2020-05-29 09:48:38,347 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvlan.sh in /usr/share/cloudstack-agent/lib/scripts/modifyvlan.sh 2020-05-29 09:48:38,347 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvlan.sh in /usr/share/cloudstack-agent/lib/modifyvlan.sh 2020-05-29 09:48:38,348 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvlan.sh in /usr/share/cloudstack-agent/modifyvlan.sh 2020-05-29 09:48:38,348 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvlan.sh in /usr/share/modifyvlan.sh 2020-05-29 09:48:38,348 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvlan.sh in /usr/modifyvlan.sh 2020-05-29 09:48:38,348 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvlan.sh in /modifyvlan.sh 2020-05-29 09:48:38,348 DEBUG [utils.script.Script] (main:null) (logid:) Searching in environment.properties 2020-05-29 09:48:38,349 DEBUG [utils.script.Script] (main:null) (logid:) environment.properties says scripts should be in /usr/share/cloudstack-common 2020-05-29 09:48:38,349 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvlan.sh in /usr/share/cloudstack-common/scripts/vm/network/vnet/modifyvlan.sh 2020-05-29 09:48:38,349 DEBUG [utils.script.Script] (main:null) (logid:) Looking for versions.sh in the classpath 2020-05-29 09:48:38,350 DEBUG [utils.script.Script] (main:null) (logid:) System resource: null 2020-05-29 09:48:38,350 DEBUG [utils.script.Script] (main:null) (logid:) Classpath resource: null 2020-05-29 09:48:38,350 DEBUG [utils.script.Script] (main:null) (logid:) Looking for versions.sh 2020-05-29 09:48:38,350 DEBUG [utils.script.Script] (main:null) (logid:) Current binaries reside at /usr/share/cloudstack-agent/lib 2020-05-29 09:48:38,350 DEBUG [utils.script.Script] (main:null) (logid:) Looking for versions.sh in /usr/share/cloudstack-agent/lib/scripts/vm/hypervisor/kvm/versions.sh 2020-05-29 09:48:38,350 DEBUG [utils.script.Script] (main:null) (logid:) Looking for versions.sh in /usr/share/cloudstack-agent/lib/scripts/vm/hypervisor/versions.sh 2020-05-29 09:48:38,350 DEBUG [utils.script.Script] (main:null) (logid:) Looking for versions.sh in /usr/share/cloudstack-agent/lib/scripts/vm/versions.sh 2020-05-29 09:48:38,350 DEBUG [utils.script.Script] (main:null) (logid:) Looking for versions.sh in /usr/share/cloudstack-agent/lib/scripts/versions.sh 2020-05-29 09:48:38,350 DEBUG [utils.script.Script] (main:null) (logid:) Looking for versions.sh in /usr/share/cloudstack-agent/lib/versions.sh 2020-05-29 09:48:38,351 DEBUG [utils.script.Script] (main:null) (logid:) Looking for versions.sh in /usr/share/cloudstack-agent/versions.sh 2020-05-29 09:48:38,351 DEBUG [utils.script.Script] (main:null) (logid:) Looking for versions.sh in /usr/share/versions.sh 2020-05-29 09:48:38,351 DEBUG [utils.script.Script] (main:null) (logid:) Looking for versions.sh in /usr/versions.sh 2020-05-29 09:48:38,351 DEBUG [utils.script.Script] (main:null) (logid:) Looking for versions.sh in /versions.sh 2020-05-29 09:48:38,351 DEBUG [utils.script.Script] (main:null) (logid:) Searching in environment.properties 2020-05-29 09:48:38,351 DEBUG [utils.script.Script] (main:null) (logid:) environment.properties says scripts should be in /usr/share/cloudstack-common 2020-05-29 09:48:38,352 DEBUG [utils.script.Script] (main:null) (logid:) Looking for versions.sh in /usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/versions.sh 2020-05-29 09:48:38,352 DEBUG [utils.script.Script] (main:null) (logid:) Looking for versions.sh in /usr/share/cloudstack-common/scripts/vm/hypervisor/versions.sh 2020-05-29 09:48:38,352 DEBUG [utils.script.Script] (main:null) (logid:) Looking for patch.sh in the classpath 2020-05-29 09:48:38,352 DEBUG [utils.script.Script] (main:null) (logid:) System resource: null 2020-05-29 09:48:38,352 DEBUG [utils.script.Script] (main:null) (logid:) Classpath resource: null 2020-05-29 09:48:38,352 DEBUG [utils.script.Script] (main:null) (logid:) Looking for patch.sh 2020-05-29 09:48:38,353 DEBUG [utils.script.Script] (main:null) (logid:) Current binaries reside at /usr/share/cloudstack-agent/lib 2020-05-29 09:48:38,353 DEBUG [utils.script.Script] (main:null) (logid:) Looking for patch.sh in /usr/share/cloudstack-agent/lib/scripts/vm/hypervisor/kvm/patch.sh 2020-05-29 09:48:38,353 DEBUG [utils.script.Script] (main:null) (logid:) Looking for patch.sh in /usr/share/cloudstack-agent/lib/scripts/vm/hypervisor/patch.sh 2020-05-29 09:48:38,353 DEBUG [utils.script.Script] (main:null) (logid:) Looking for patch.sh in /usr/share/cloudstack-agent/lib/scripts/vm/patch.sh 2020-05-29 09:48:38,353 DEBUG [utils.script.Script] (main:null) (logid:) Looking for patch.sh in /usr/share/cloudstack-agent/lib/scripts/patch.sh 2020-05-29 09:48:38,353 DEBUG [utils.script.Script] (main:null) (logid:) Looking for patch.sh in /usr/share/cloudstack-agent/lib/patch.sh 2020-05-29 09:48:38,353 DEBUG [utils.script.Script] (main:null) (logid:) Looking for patch.sh in /usr/share/cloudstack-agent/patch.sh 2020-05-29 09:48:38,353 DEBUG [utils.script.Script] (main:null) (logid:) Looking for patch.sh in /usr/share/patch.sh 2020-05-29 09:48:38,353 DEBUG [utils.script.Script] (main:null) (logid:) Looking for patch.sh in /usr/patch.sh 2020-05-29 09:48:38,354 DEBUG [utils.script.Script] (main:null) (logid:) Looking for patch.sh in /patch.sh 2020-05-29 09:48:38,354 DEBUG [utils.script.Script] (main:null) (logid:) Searching in environment.properties 2020-05-29 09:48:38,354 DEBUG [utils.script.Script] (main:null) (logid:) environment.properties says scripts should be in /usr/share/cloudstack-common 2020-05-29 09:48:38,354 DEBUG [utils.script.Script] (main:null) (logid:) Looking for patch.sh in /usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/patch.sh 2020-05-29 09:48:38,354 DEBUG [utils.script.Script] (main:null) (logid:) Looking for kvmheartbeat.sh in the classpath 2020-05-29 09:48:38,354 DEBUG [utils.script.Script] (main:null) (logid:) System resource: null 2020-05-29 09:48:38,355 DEBUG [utils.script.Script] (main:null) (logid:) Classpath resource: null 2020-05-29 09:48:38,355 DEBUG [utils.script.Script] (main:null) (logid:) Looking for kvmheartbeat.sh 2020-05-29 09:48:38,355 DEBUG [utils.script.Script] (main:null) (logid:) Current binaries reside at /usr/share/cloudstack-agent/lib 2020-05-29 09:48:38,355 DEBUG [utils.script.Script] (main:null) (logid:) Looking for kvmheartbeat.sh in /usr/share/cloudstack-agent/lib/scripts/vm/hypervisor/kvm/kvmheartbeat.sh 2020-05-29 09:48:38,355 DEBUG [utils.script.Script] (main:null) (logid:) Looking for kvmheartbeat.sh in /usr/share/cloudstack-agent/lib/scripts/vm/hypervisor/kvmheartbeat.sh 2020-05-29 09:48:38,355 DEBUG [utils.script.Script] (main:null) (logid:) Looking for kvmheartbeat.sh in /usr/share/cloudstack-agent/lib/scripts/vm/kvmheartbeat.sh 2020-05-29 09:48:38,355 DEBUG [utils.script.Script] (main:null) (logid:) Looking for kvmheartbeat.sh in /usr/share/cloudstack-agent/lib/scripts/kvmheartbeat.sh 2020-05-29 09:48:38,355 DEBUG [utils.script.Script] (main:null) (logid:) Looking for kvmheartbeat.sh in /usr/share/cloudstack-agent/lib/kvmheartbeat.sh 2020-05-29 09:48:38,356 DEBUG [utils.script.Script] (main:null) (logid:) Looking for kvmheartbeat.sh in /usr/share/cloudstack-agent/kvmheartbeat.sh 2020-05-29 09:48:38,356 DEBUG [utils.script.Script] (main:null) (logid:) Looking for kvmheartbeat.sh in /usr/share/kvmheartbeat.sh 2020-05-29 09:48:38,356 DEBUG [utils.script.Script] (main:null) (logid:) Looking for kvmheartbeat.sh in /usr/kvmheartbeat.sh 2020-05-29 09:48:38,356 DEBUG [utils.script.Script] (main:null) (logid:) Looking for kvmheartbeat.sh in /kvmheartbeat.sh 2020-05-29 09:48:38,356 DEBUG [utils.script.Script] (main:null) (logid:) Searching in environment.properties 2020-05-29 09:48:38,356 DEBUG [utils.script.Script] (main:null) (logid:) environment.properties says scripts should be in /usr/share/cloudstack-common 2020-05-29 09:48:38,357 DEBUG [utils.script.Script] (main:null) (logid:) Looking for kvmheartbeat.sh in /usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/kvmheartbeat.sh 2020-05-29 09:48:38,357 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createvm.sh in the classpath 2020-05-29 09:48:38,357 DEBUG [utils.script.Script] (main:null) (logid:) System resource: null 2020-05-29 09:48:38,357 DEBUG [utils.script.Script] (main:null) (logid:) Classpath resource: null 2020-05-29 09:48:38,357 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createvm.sh 2020-05-29 09:48:38,358 DEBUG [utils.script.Script] (main:null) (logid:) Current binaries reside at /usr/share/cloudstack-agent/lib 2020-05-29 09:48:38,358 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createvm.sh in /usr/share/cloudstack-agent/lib/scripts/storage/qcow2/createvm.sh 2020-05-29 09:48:38,358 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createvm.sh in /usr/share/cloudstack-agent/lib/scripts/storage/createvm.sh 2020-05-29 09:48:38,358 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createvm.sh in /usr/share/cloudstack-agent/lib/scripts/createvm.sh 2020-05-29 09:48:38,358 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createvm.sh in /usr/share/cloudstack-agent/lib/createvm.sh 2020-05-29 09:48:38,359 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createvm.sh in /usr/share/cloudstack-agent/createvm.sh 2020-05-29 09:48:38,359 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createvm.sh in /usr/share/createvm.sh 2020-05-29 09:48:38,359 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createvm.sh in /usr/createvm.sh 2020-05-29 09:48:38,359 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createvm.sh in /createvm.sh 2020-05-29 09:48:38,359 DEBUG [utils.script.Script] (main:null) (logid:) Searching in environment.properties 2020-05-29 09:48:38,360 DEBUG [utils.script.Script] (main:null) (logid:) environment.properties says scripts should be in /usr/share/cloudstack-common 2020-05-29 09:48:38,360 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createvm.sh in /usr/share/cloudstack-common/scripts/storage/qcow2/createvm.sh 2020-05-29 09:48:38,360 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh in the classpath 2020-05-29 09:48:38,360 DEBUG [utils.script.Script] (main:null) (logid:) System resource: null 2020-05-29 09:48:38,360 DEBUG [utils.script.Script] (main:null) (logid:) Classpath resource: null 2020-05-29 09:48:38,360 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh 2020-05-29 09:48:38,361 DEBUG [utils.script.Script] (main:null) (logid:) Current binaries reside at /usr/share/cloudstack-agent/lib 2020-05-29 09:48:38,361 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh in /usr/share/cloudstack-agent/lib/scripts/storage/qcow2/managesnapshot.sh 2020-05-29 09:48:38,361 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh in /usr/share/cloudstack-agent/lib/scripts/storage/managesnapshot.sh 2020-05-29 09:48:38,361 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh in /usr/share/cloudstack-agent/lib/scripts/managesnapshot.sh 2020-05-29 09:48:38,361 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh in /usr/share/cloudstack-agent/lib/managesnapshot.sh 2020-05-29 09:48:38,361 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh in /usr/share/cloudstack-agent/managesnapshot.sh 2020-05-29 09:48:38,361 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh in /usr/share/managesnapshot.sh 2020-05-29 09:48:38,361 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh in /usr/managesnapshot.sh 2020-05-29 09:48:38,361 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh in /managesnapshot.sh 2020-05-29 09:48:38,361 DEBUG [utils.script.Script] (main:null) (logid:) Searching in environment.properties 2020-05-29 09:48:38,362 DEBUG [utils.script.Script] (main:null) (logid:) environment.properties says scripts should be in /usr/share/cloudstack-common 2020-05-29 09:48:38,362 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh in /usr/share/cloudstack-common/scripts/storage/qcow2/managesnapshot.sh 2020-05-29 09:48:38,362 DEBUG [utils.script.Script] (main:null) (logid:) Looking for resizevolume.sh in the classpath 2020-05-29 09:48:38,362 DEBUG [utils.script.Script] (main:null) (logid:) System resource: null 2020-05-29 09:48:38,362 DEBUG [utils.script.Script] (main:null) (logid:) Classpath resource: null 2020-05-29 09:48:38,362 DEBUG [utils.script.Script] (main:null) (logid:) Looking for resizevolume.sh 2020-05-29 09:48:38,363 DEBUG [utils.script.Script] (main:null) (logid:) Current binaries reside at /usr/share/cloudstack-agent/lib 2020-05-29 09:48:38,363 DEBUG [utils.script.Script] (main:null) (logid:) Looking for resizevolume.sh in /usr/share/cloudstack-agent/lib/scripts/storage/qcow2/resizevolume.sh 2020-05-29 09:48:38,363 DEBUG [utils.script.Script] (main:null) (logid:) Looking for resizevolume.sh in /usr/share/cloudstack-agent/lib/scripts/storage/resizevolume.sh 2020-05-29 09:48:38,363 DEBUG [utils.script.Script] (main:null) (logid:) Looking for resizevolume.sh in /usr/share/cloudstack-agent/lib/scripts/resizevolume.sh 2020-05-29 09:48:38,363 DEBUG [utils.script.Script] (main:null) (logid:) Looking for resizevolume.sh in /usr/share/cloudstack-agent/lib/resizevolume.sh 2020-05-29 09:48:38,363 DEBUG [utils.script.Script] (main:null) (logid:) Looking for resizevolume.sh in /usr/share/cloudstack-agent/resizevolume.sh 2020-05-29 09:48:38,363 DEBUG [utils.script.Script] (main:null) (logid:) Looking for resizevolume.sh in /usr/share/resizevolume.sh 2020-05-29 09:48:38,363 DEBUG [utils.script.Script] (main:null) (logid:) Looking for resizevolume.sh in /usr/resizevolume.sh 2020-05-29 09:48:38,363 DEBUG [utils.script.Script] (main:null) (logid:) Looking for resizevolume.sh in /resizevolume.sh 2020-05-29 09:48:38,363 DEBUG [utils.script.Script] (main:null) (logid:) Searching in environment.properties 2020-05-29 09:48:38,364 DEBUG [utils.script.Script] (main:null) (logid:) environment.properties says scripts should be in /usr/share/cloudstack-common 2020-05-29 09:48:38,364 DEBUG [utils.script.Script] (main:null) (logid:) Looking for resizevolume.sh in /usr/share/cloudstack-common/scripts/storage/qcow2/resizevolume.sh 2020-05-29 09:48:38,364 DEBUG [utils.script.Script] (main:null) (logid:) Looking for kvmvmactivity.sh in the classpath 2020-05-29 09:48:38,364 DEBUG [utils.script.Script] (main:null) (logid:) System resource: null 2020-05-29 09:48:38,364 DEBUG [utils.script.Script] (main:null) (logid:) Classpath resource: null 2020-05-29 09:48:38,365 DEBUG [utils.script.Script] (main:null) (logid:) Looking for kvmvmactivity.sh 2020-05-29 09:48:38,365 DEBUG [utils.script.Script] (main:null) (logid:) Current binaries reside at /usr/share/cloudstack-agent/lib 2020-05-29 09:48:38,365 DEBUG [utils.script.Script] (main:null) (logid:) Looking for kvmvmactivity.sh in /usr/share/cloudstack-agent/lib/scripts/vm/hypervisor/kvm/kvmvmactivity.sh 2020-05-29 09:48:38,365 DEBUG [utils.script.Script] (main:null) (logid:) Looking for kvmvmactivity.sh in /usr/share/cloudstack-agent/lib/scripts/vm/hypervisor/kvmvmactivity.sh 2020-05-29 09:48:38,365 DEBUG [utils.script.Script] (main:null) (logid:) Looking for kvmvmactivity.sh in /usr/share/cloudstack-agent/lib/scripts/vm/kvmvmactivity.sh 2020-05-29 09:48:38,365 DEBUG [utils.script.Script] (main:null) (logid:) Looking for kvmvmactivity.sh in /usr/share/cloudstack-agent/lib/scripts/kvmvmactivity.sh 2020-05-29 09:48:38,365 DEBUG [utils.script.Script] (main:null) (logid:) Looking for kvmvmactivity.sh in /usr/share/cloudstack-agent/lib/kvmvmactivity.sh 2020-05-29 09:48:38,365 DEBUG [utils.script.Script] (main:null) (logid:) Looking for kvmvmactivity.sh in /usr/share/cloudstack-agent/kvmvmactivity.sh 2020-05-29 09:48:38,365 DEBUG [utils.script.Script] (main:null) (logid:) Looking for kvmvmactivity.sh in /usr/share/kvmvmactivity.sh 2020-05-29 09:48:38,365 DEBUG [utils.script.Script] (main:null) (logid:) Looking for kvmvmactivity.sh in /usr/kvmvmactivity.sh 2020-05-29 09:48:38,365 DEBUG [utils.script.Script] (main:null) (logid:) Looking for kvmvmactivity.sh in /kvmvmactivity.sh 2020-05-29 09:48:38,365 DEBUG [utils.script.Script] (main:null) (logid:) Searching in environment.properties 2020-05-29 09:48:38,366 DEBUG [utils.script.Script] (main:null) (logid:) environment.properties says scripts should be in /usr/share/cloudstack-common 2020-05-29 09:48:38,366 DEBUG [utils.script.Script] (main:null) (logid:) Looking for kvmvmactivity.sh in /usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/kvmvmactivity.sh 2020-05-29 09:48:38,366 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createtmplt.sh in the classpath 2020-05-29 09:48:38,366 DEBUG [utils.script.Script] (main:null) (logid:) System resource: null 2020-05-29 09:48:38,367 DEBUG [utils.script.Script] (main:null) (logid:) Classpath resource: null 2020-05-29 09:48:38,367 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createtmplt.sh 2020-05-29 09:48:38,367 DEBUG [utils.script.Script] (main:null) (logid:) Current binaries reside at /usr/share/cloudstack-agent/lib 2020-05-29 09:48:38,367 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createtmplt.sh in /usr/share/cloudstack-agent/lib/scripts/storage/qcow2/createtmplt.sh 2020-05-29 09:48:38,367 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createtmplt.sh in /usr/share/cloudstack-agent/lib/scripts/storage/createtmplt.sh 2020-05-29 09:48:38,368 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createtmplt.sh in /usr/share/cloudstack-agent/lib/scripts/createtmplt.sh 2020-05-29 09:48:38,368 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createtmplt.sh in /usr/share/cloudstack-agent/lib/createtmplt.sh 2020-05-29 09:48:38,368 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createtmplt.sh in /usr/share/cloudstack-agent/createtmplt.sh 2020-05-29 09:48:38,368 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createtmplt.sh in /usr/share/createtmplt.sh 2020-05-29 09:48:38,368 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createtmplt.sh in /usr/createtmplt.sh 2020-05-29 09:48:38,368 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createtmplt.sh in /createtmplt.sh 2020-05-29 09:48:38,368 DEBUG [utils.script.Script] (main:null) (logid:) Searching in environment.properties 2020-05-29 09:48:38,369 DEBUG [utils.script.Script] (main:null) (logid:) environment.properties says scripts should be in /usr/share/cloudstack-common 2020-05-29 09:48:38,369 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createtmplt.sh in /usr/share/cloudstack-common/scripts/storage/qcow2/createtmplt.sh 2020-05-29 09:48:38,369 DEBUG [utils.script.Script] (main:null) (logid:) Looking for security_group.py in the classpath 2020-05-29 09:48:38,369 DEBUG [utils.script.Script] (main:null) (logid:) System resource: null 2020-05-29 09:48:38,370 DEBUG [utils.script.Script] (main:null) (logid:) Classpath resource: null 2020-05-29 09:48:38,370 DEBUG [utils.script.Script] (main:null) (logid:) Looking for security_group.py 2020-05-29 09:48:38,370 DEBUG [utils.script.Script] (main:null) (logid:) Current binaries reside at /usr/share/cloudstack-agent/lib 2020-05-29 09:48:38,370 DEBUG [utils.script.Script] (main:null) (logid:) Looking for security_group.py in /usr/share/cloudstack-agent/lib/scripts/vm/network/vnet/security_group.py 2020-05-29 09:48:38,370 DEBUG [utils.script.Script] (main:null) (logid:) Looking for security_group.py in /usr/share/cloudstack-agent/lib/scripts/vm/network/security_group.py 2020-05-29 09:48:38,370 DEBUG [utils.script.Script] (main:null) (logid:) Looking for security_group.py in /usr/share/cloudstack-agent/lib/scripts/vm/security_group.py 2020-05-29 09:48:38,370 DEBUG [utils.script.Script] (main:null) (logid:) Looking for security_group.py in /usr/share/cloudstack-agent/lib/scripts/security_group.py 2020-05-29 09:48:38,370 DEBUG [utils.script.Script] (main:null) (logid:) Looking for security_group.py in /usr/share/cloudstack-agent/lib/security_group.py 2020-05-29 09:48:38,371 DEBUG [utils.script.Script] (main:null) (logid:) Looking for security_group.py in /usr/share/cloudstack-agent/security_group.py 2020-05-29 09:48:38,371 DEBUG [utils.script.Script] (main:null) (logid:) Looking for security_group.py in /usr/share/security_group.py 2020-05-29 09:48:38,371 DEBUG [utils.script.Script] (main:null) (logid:) Looking for security_group.py in /usr/security_group.py 2020-05-29 09:48:38,371 DEBUG [utils.script.Script] (main:null) (logid:) Looking for security_group.py in /security_group.py 2020-05-29 09:48:38,371 DEBUG [utils.script.Script] (main:null) (logid:) Searching in environment.properties 2020-05-29 09:48:38,371 DEBUG [utils.script.Script] (main:null) (logid:) environment.properties says scripts should be in /usr/share/cloudstack-common 2020-05-29 09:48:38,371 DEBUG [utils.script.Script] (main:null) (logid:) Looking for security_group.py in /usr/share/cloudstack-common/scripts/vm/network/vnet/security_group.py 2020-05-29 09:48:38,372 DEBUG [utils.script.Script] (main:null) (logid:) Looking for security_group.py in /usr/share/cloudstack-common/scripts/vm/network/security_group.py 2020-05-29 09:48:38,372 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovstunnel.py in the classpath 2020-05-29 09:48:38,372 DEBUG [utils.script.Script] (main:null) (logid:) System resource: null 2020-05-29 09:48:38,372 DEBUG [utils.script.Script] (main:null) (logid:) Classpath resource: null 2020-05-29 09:48:38,373 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovstunnel.py 2020-05-29 09:48:38,373 DEBUG [utils.script.Script] (main:null) (logid:) Current binaries reside at /usr/share/cloudstack-agent/lib 2020-05-29 09:48:38,373 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovstunnel.py in /usr/share/cloudstack-agent/lib/scripts/vm/network/vnet/ovstunnel.py 2020-05-29 09:48:38,373 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovstunnel.py in /usr/share/cloudstack-agent/lib/scripts/vm/network/ovstunnel.py 2020-05-29 09:48:38,373 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovstunnel.py in /usr/share/cloudstack-agent/lib/scripts/vm/ovstunnel.py 2020-05-29 09:48:38,373 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovstunnel.py in /usr/share/cloudstack-agent/lib/scripts/ovstunnel.py 2020-05-29 09:48:38,373 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovstunnel.py in /usr/share/cloudstack-agent/lib/ovstunnel.py 2020-05-29 09:48:38,373 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovstunnel.py in /usr/share/cloudstack-agent/ovstunnel.py 2020-05-29 09:48:38,373 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovstunnel.py in /usr/share/ovstunnel.py 2020-05-29 09:48:38,373 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovstunnel.py in /usr/ovstunnel.py 2020-05-29 09:48:38,373 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovstunnel.py in /ovstunnel.py 2020-05-29 09:48:38,374 DEBUG [utils.script.Script] (main:null) (logid:) Searching in environment.properties 2020-05-29 09:48:38,374 DEBUG [utils.script.Script] (main:null) (logid:) environment.properties says scripts should be in /usr/share/cloudstack-common 2020-05-29 09:48:38,374 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovstunnel.py in /usr/share/cloudstack-common/scripts/vm/network/vnet/ovstunnel.py 2020-05-29 09:48:38,374 DEBUG [utils.script.Script] (main:null) (logid:) Looking for router_proxy.sh in the classpath 2020-05-29 09:48:38,375 DEBUG [utils.script.Script] (main:null) (logid:) System resource: null 2020-05-29 09:48:38,375 DEBUG [utils.script.Script] (main:null) (logid:) Classpath resource: null 2020-05-29 09:48:38,375 DEBUG [utils.script.Script] (main:null) (logid:) Looking for router_proxy.sh 2020-05-29 09:48:38,375 DEBUG [utils.script.Script] (main:null) (logid:) Current binaries reside at /usr/share/cloudstack-agent/lib 2020-05-29 09:48:38,375 DEBUG [utils.script.Script] (main:null) (logid:) Looking for router_proxy.sh in /usr/share/cloudstack-agent/lib/scripts/network/domr/router_proxy.sh 2020-05-29 09:48:38,375 DEBUG [utils.script.Script] (main:null) (logid:) Looking for router_proxy.sh in /usr/share/cloudstack-agent/lib/scripts/network/router_proxy.sh 2020-05-29 09:48:38,375 DEBUG [utils.script.Script] (main:null) (logid:) Looking for router_proxy.sh in /usr/share/cloudstack-agent/lib/scripts/router_proxy.sh 2020-05-29 09:48:38,375 DEBUG [utils.script.Script] (main:null) (logid:) Looking for router_proxy.sh in /usr/share/cloudstack-agent/lib/router_proxy.sh 2020-05-29 09:48:38,375 DEBUG [utils.script.Script] (main:null) (logid:) Looking for router_proxy.sh in /usr/share/cloudstack-agent/router_proxy.sh 2020-05-29 09:48:38,376 DEBUG [utils.script.Script] (main:null) (logid:) Looking for router_proxy.sh in /usr/share/router_proxy.sh 2020-05-29 09:48:38,376 DEBUG [utils.script.Script] (main:null) (logid:) Looking for router_proxy.sh in /usr/router_proxy.sh 2020-05-29 09:48:38,376 DEBUG [utils.script.Script] (main:null) (logid:) Looking for router_proxy.sh in /router_proxy.sh 2020-05-29 09:48:38,376 DEBUG [utils.script.Script] (main:null) (logid:) Searching in environment.properties 2020-05-29 09:48:38,376 DEBUG [utils.script.Script] (main:null) (logid:) environment.properties says scripts should be in /usr/share/cloudstack-common 2020-05-29 09:48:38,376 DEBUG [utils.script.Script] (main:null) (logid:) Looking for router_proxy.sh in /usr/share/cloudstack-common/scripts/network/domr/router_proxy.sh 2020-05-29 09:48:38,377 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovs-pvlan-dhcp-host.sh in the classpath 2020-05-29 09:48:38,377 DEBUG [utils.script.Script] (main:null) (logid:) System resource: null 2020-05-29 09:48:38,377 DEBUG [utils.script.Script] (main:null) (logid:) Classpath resource: null 2020-05-29 09:48:38,377 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovs-pvlan-dhcp-host.sh 2020-05-29 09:48:38,377 DEBUG [utils.script.Script] (main:null) (logid:) Current binaries reside at /usr/share/cloudstack-agent/lib 2020-05-29 09:48:38,378 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovs-pvlan-dhcp-host.sh in /usr/share/cloudstack-agent/lib/scripts/vm/network/vnet/ovs-pvlan-dhcp-host.sh 2020-05-29 09:48:38,378 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovs-pvlan-dhcp-host.sh in /usr/share/cloudstack-agent/lib/scripts/vm/network/ovs-pvlan-dhcp-host.sh 2020-05-29 09:48:38,378 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovs-pvlan-dhcp-host.sh in /usr/share/cloudstack-agent/lib/scripts/vm/ovs-pvlan-dhcp-host.sh 2020-05-29 09:48:38,378 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovs-pvlan-dhcp-host.sh in /usr/share/cloudstack-agent/lib/scripts/ovs-pvlan-dhcp-host.sh 2020-05-29 09:48:38,378 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovs-pvlan-dhcp-host.sh in /usr/share/cloudstack-agent/lib/ovs-pvlan-dhcp-host.sh 2020-05-29 09:48:38,378 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovs-pvlan-dhcp-host.sh in /usr/share/cloudstack-agent/ovs-pvlan-dhcp-host.sh 2020-05-29 09:48:38,378 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovs-pvlan-dhcp-host.sh in /usr/share/ovs-pvlan-dhcp-host.sh 2020-05-29 09:48:38,378 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovs-pvlan-dhcp-host.sh in /usr/ovs-pvlan-dhcp-host.sh 2020-05-29 09:48:38,378 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovs-pvlan-dhcp-host.sh in /ovs-pvlan-dhcp-host.sh 2020-05-29 09:48:38,378 DEBUG [utils.script.Script] (main:null) (logid:) Searching in environment.properties 2020-05-29 09:48:38,379 DEBUG [utils.script.Script] (main:null) (logid:) environment.properties says scripts should be in /usr/share/cloudstack-common 2020-05-29 09:48:38,379 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovs-pvlan-dhcp-host.sh in /usr/share/cloudstack-common/scripts/vm/network/vnet/ovs-pvlan-dhcp-host.sh 2020-05-29 09:48:38,379 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovs-pvlan-dhcp-host.sh in /usr/share/cloudstack-common/scripts/vm/network/ovs-pvlan-dhcp-host.sh 2020-05-29 09:48:38,379 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovs-pvlan-vm.sh in the classpath 2020-05-29 09:48:38,379 DEBUG [utils.script.Script] (main:null) (logid:) System resource: null 2020-05-29 09:48:38,380 DEBUG [utils.script.Script] (main:null) (logid:) Classpath resource: null 2020-05-29 09:48:38,380 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovs-pvlan-vm.sh 2020-05-29 09:48:38,380 DEBUG [utils.script.Script] (main:null) (logid:) Current binaries reside at /usr/share/cloudstack-agent/lib 2020-05-29 09:48:38,380 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovs-pvlan-vm.sh in /usr/share/cloudstack-agent/lib/scripts/vm/network/vnet/ovs-pvlan-vm.sh 2020-05-29 09:48:38,380 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovs-pvlan-vm.sh in /usr/share/cloudstack-agent/lib/scripts/vm/network/ovs-pvlan-vm.sh 2020-05-29 09:48:38,380 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovs-pvlan-vm.sh in /usr/share/cloudstack-agent/lib/scripts/vm/ovs-pvlan-vm.sh 2020-05-29 09:48:38,380 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovs-pvlan-vm.sh in /usr/share/cloudstack-agent/lib/scripts/ovs-pvlan-vm.sh 2020-05-29 09:48:38,380 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovs-pvlan-vm.sh in /usr/share/cloudstack-agent/lib/ovs-pvlan-vm.sh 2020-05-29 09:48:38,380 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovs-pvlan-vm.sh in /usr/share/cloudstack-agent/ovs-pvlan-vm.sh 2020-05-29 09:48:38,380 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovs-pvlan-vm.sh in /usr/share/ovs-pvlan-vm.sh 2020-05-29 09:48:38,381 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovs-pvlan-vm.sh in /usr/ovs-pvlan-vm.sh 2020-05-29 09:48:38,381 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovs-pvlan-vm.sh in /ovs-pvlan-vm.sh 2020-05-29 09:48:38,381 DEBUG [utils.script.Script] (main:null) (logid:) Searching in environment.properties 2020-05-29 09:48:38,381 DEBUG [utils.script.Script] (main:null) (logid:) environment.properties says scripts should be in /usr/share/cloudstack-common 2020-05-29 09:48:38,381 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovs-pvlan-vm.sh in /usr/share/cloudstack-common/scripts/vm/network/vnet/ovs-pvlan-vm.sh 2020-05-29 09:48:38,381 DEBUG [utils.script.Script] (main:null) (logid:) Looking for ovs-pvlan-vm.sh in /usr/share/cloudstack-common/scripts/vm/network/ovs-pvlan-vm.sh 2020-05-29 09:48:38,383 DEBUG [utils.script.Script] (main:null) (logid:) Looking for pingtest.sh in the classpath 2020-05-29 09:48:38,383 DEBUG [utils.script.Script] (main:null) (logid:) System resource: null 2020-05-29 09:48:38,383 DEBUG [utils.script.Script] (main:null) (logid:) Classpath resource: null 2020-05-29 09:48:38,383 DEBUG [utils.script.Script] (main:null) (logid:) Looking for pingtest.sh 2020-05-29 09:48:38,383 DEBUG [utils.script.Script] (main:null) (logid:) Current binaries reside at /usr/share/cloudstack-agent/lib 2020-05-29 09:48:38,384 DEBUG [utils.script.Script] (main:null) (logid:) Looking for pingtest.sh in /usr/share/cloudstack-agent/lib/scripts/vm/hypervisor/kvm/pingtest.sh 2020-05-29 09:48:38,384 DEBUG [utils.script.Script] (main:null) (logid:) Looking for pingtest.sh in /usr/share/cloudstack-agent/lib/scripts/vm/hypervisor/pingtest.sh 2020-05-29 09:48:38,384 DEBUG [utils.script.Script] (main:null) (logid:) Looking for pingtest.sh in /usr/share/cloudstack-agent/lib/scripts/vm/pingtest.sh 2020-05-29 09:48:38,384 DEBUG [utils.script.Script] (main:null) (logid:) Looking for pingtest.sh in /usr/share/cloudstack-agent/lib/scripts/pingtest.sh 2020-05-29 09:48:38,384 DEBUG [utils.script.Script] (main:null) (logid:) Looking for pingtest.sh in /usr/share/cloudstack-agent/lib/pingtest.sh 2020-05-29 09:48:38,384 DEBUG [utils.script.Script] (main:null) (logid:) Looking for pingtest.sh in /usr/share/cloudstack-agent/pingtest.sh 2020-05-29 09:48:38,384 DEBUG [utils.script.Script] (main:null) (logid:) Looking for pingtest.sh in /usr/share/pingtest.sh 2020-05-29 09:48:38,384 DEBUG [utils.script.Script] (main:null) (logid:) Looking for pingtest.sh in /usr/pingtest.sh 2020-05-29 09:48:38,384 DEBUG [utils.script.Script] (main:null) (logid:) Looking for pingtest.sh in /pingtest.sh 2020-05-29 09:48:38,384 DEBUG [utils.script.Script] (main:null) (logid:) Searching in environment.properties 2020-05-29 09:48:38,384 DEBUG [utils.script.Script] (main:null) (logid:) environment.properties says scripts should be in /usr/share/cloudstack-common 2020-05-29 09:48:38,384 DEBUG [utils.script.Script] (main:null) (logid:) Looking for pingtest.sh in /usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/pingtest.sh 2020-05-29 09:48:38,384 DEBUG [utils.script.Script] (main:null) (logid:) Looking for pingtest.sh in /usr/share/cloudstack-common/scripts/vm/hypervisor/pingtest.sh 2020-05-29 09:48:38,384 DEBUG [utils.script.Script] (main:null) (logid:) Looking for pingtest.sh in /usr/share/cloudstack-common/scripts/vm/pingtest.sh 2020-05-29 09:48:38,385 DEBUG [kvm.resource.LibvirtConnection] (main:null) (logid:) Looking for libvirtd connection at: qemu:///system 2020-05-29 09:48:38,385 INFO [kvm.resource.LibvirtConnection] (main:null) (logid:) No existing libvirtd connection found. Opening a new one 2020-05-29 09:48:38,525 DEBUG [kvm.resource.LibvirtConnection] (main:null) (logid:) Successfully connected to libvirt at: qemu:///system 2020-05-29 09:48:38,529 DEBUG [kvm.resource.LibvirtComputingResource] (main:null) (logid:) Found libvirt default network, destroying it and setting autostart to false 2020-05-29 09:48:38,594 DEBUG [kvm.resource.LibvirtCapXMLParser] (main:null) (logid:) Found /usr/libexec/qemu-kvm as a suiteable emulator 2020-05-29 09:48:38,619 DEBUG [kvm.resource.LibvirtCapXMLParser] (main:null) (logid:) Found /usr/libexec/qemu-kvm as a suiteable emulator 2020-05-29 09:48:38,638 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh in the classpath 2020-05-29 09:48:38,638 DEBUG [utils.script.Script] (main:null) (logid:) System resource: null 2020-05-29 09:48:38,638 DEBUG [utils.script.Script] (main:null) (logid:) Classpath resource: null 2020-05-29 09:48:38,638 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh 2020-05-29 09:48:38,638 DEBUG [utils.script.Script] (main:null) (logid:) Current binaries reside at /usr/share/cloudstack-agent/lib 2020-05-29 09:48:38,638 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh in /usr/share/cloudstack-agent/lib/scripts/storage/qcow2/managesnapshot.sh 2020-05-29 09:48:38,638 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh in /usr/share/cloudstack-agent/lib/scripts/storage/managesnapshot.sh 2020-05-29 09:48:38,638 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh in /usr/share/cloudstack-agent/lib/scripts/managesnapshot.sh 2020-05-29 09:48:38,638 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh in /usr/share/cloudstack-agent/lib/managesnapshot.sh 2020-05-29 09:48:38,638 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh in /usr/share/cloudstack-agent/managesnapshot.sh 2020-05-29 09:48:38,639 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh in /usr/share/managesnapshot.sh 2020-05-29 09:48:38,639 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh in /usr/managesnapshot.sh 2020-05-29 09:48:38,639 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh in /managesnapshot.sh 2020-05-29 09:48:38,639 DEBUG [utils.script.Script] (main:null) (logid:) Searching in environment.properties 2020-05-29 09:48:38,639 DEBUG [utils.script.Script] (main:null) (logid:) environment.properties says scripts should be in /usr/share/cloudstack-common 2020-05-29 09:48:38,639 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh in /usr/share/cloudstack-common/scripts/storage/qcow2/managesnapshot.sh 2020-05-29 09:48:38,672 DEBUG [org.reflections.Reflections] (main:null) (logid:) going to scan these urls: jar:file:/usr/share/cloudstack-agent/lib/cloud-plugin-hypervisor-kvm-4.13.0.0.jar!/ 2020-05-29 09:48:38,734 INFO [org.reflections.Reflections] (main:null) (logid:) Reflections took 60 ms to scan 1 urls, producing 7 keys and 10 values 2020-05-29 09:48:38,757 DEBUG [kvm.storage.KVMStoragePoolManager] (main:null) (logid:) Registered a StorageAdaptor for libvirt 2020-05-29 09:48:38,758 DEBUG [kvm.storage.KVMStoragePoolManager] (main:null) (logid:) Registered a StorageAdaptor for Iscsi 2020-05-29 09:48:38,758 DEBUG [kvm.storage.KVMStoragePoolManager] (main:null) (logid:) Registered a StorageAdaptor for ManagedNFS 2020-05-29 09:48:38,758 INFO [kvm.resource.LibvirtComputingResource] (main:null) (logid:) No libvirt.vif.driver specified. Defaults to BridgeVifDriver. 2020-05-29 09:48:38,761 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/vnet2/bridge 2020-05-29 09:48:38,761 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/cloudbr249/bridge 2020-05-29 09:48:38,761 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) Found bridge cloudbr249 2020-05-29 09:48:38,761 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/bond1.2278/bridge 2020-05-29 09:48:38,761 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/brbond1-2216/bridge 2020-05-29 09:48:38,761 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) Found bridge brbond1-2216 2020-05-29 09:48:38,761 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/bond1.2022/bridge 2020-05-29 09:48:38,761 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/brbond1-2101/bridge 2020-05-29 09:48:38,761 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) Found bridge brbond1-2101 2020-05-29 09:48:38,761 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/bond1.2483/bridge 2020-05-29 09:48:38,761 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/brbond1-2158/bridge 2020-05-29 09:48:38,762 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) Found bridge brbond1-2158 2020-05-29 09:48:38,762 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/brbond1-2242/bridge 2020-05-29 09:48:38,762 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) Found bridge brbond1-2242 2020-05-29 09:48:38,762 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/bond1.2596/bridge 2020-05-29 09:48:38,762 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/bond3/bridge 2020-05-29 09:48:38,762 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/bond1.2216/bridge 2020-05-29 09:48:38,762 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/bond1/bridge 2020-05-29 09:48:38,762 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/cloudbr2/bridge 2020-05-29 09:48:38,762 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) Found bridge cloudbr2 2020-05-29 09:48:38,762 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/bond1.2101/bridge 2020-05-29 09:48:38,762 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/bond1.2158/bridge 2020-05-29 09:48:38,762 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/brbond1-2011/bridge 2020-05-29 09:48:38,763 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) Found bridge brbond1-2011 2020-05-29 09:48:38,763 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/bond1.2242/bridge 2020-05-29 09:48:38,763 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/cloudbr0/bridge 2020-05-29 09:48:38,763 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) Found bridge cloudbr0 2020-05-29 09:48:38,763 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/vnet3/bridge 2020-05-29 09:48:38,763 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/vnet11/bridge 2020-05-29 09:48:38,763 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/cloud0/bridge 2020-05-29 09:48:38,763 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) Found bridge cloud0 2020-05-29 09:48:38,763 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/vnet1/bridge 2020-05-29 09:48:38,763 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/bond1.2011/bridge 2020-05-29 09:48:38,763 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/brbond1-2553/bridge 2020-05-29 09:48:38,763 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) Found bridge brbond1-2553 2020-05-29 09:48:38,763 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/lo/bridge 2020-05-29 09:48:38,763 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/bond2/bridge 2020-05-29 09:48:38,764 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/bond3.249/bridge 2020-05-29 09:48:38,764 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/cloudbr3/bridge 2020-05-29 09:48:38,764 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) Found bridge cloudbr3 2020-05-29 09:48:38,764 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/brbond1-2278/bridge 2020-05-29 09:48:38,764 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) Found bridge brbond1-2278 2020-05-29 09:48:38,764 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/brbond1-2022/bridge 2020-05-29 09:48:38,764 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) Found bridge brbond1-2022 2020-05-29 09:48:38,764 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/bond0/bridge 2020-05-29 09:48:38,764 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/cloudbr1/bridge 2020-05-29 09:48:38,764 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) Found bridge cloudbr1 2020-05-29 09:48:38,764 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/brbond1-2483/bridge 2020-05-29 09:48:38,764 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) Found bridge brbond1-2483 2020-05-29 09:48:38,764 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/bond1.2553/bridge 2020-05-29 09:48:38,764 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/brbond1-2596/bridge 2020-05-29 09:48:38,764 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) Found bridge brbond1-2596 2020-05-29 09:48:38,764 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking in file /sys/devices/virtual/net/vnet12/bridge 2020-05-29 09:48:38,764 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking for pif for bridge cloudbr249 2020-05-29 09:48:38,765 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) matchPifFileInDirectory: file name 'bond3.249' 2020-05-29 09:48:38,766 DEBUG [utils.script.Script] (main:null) (logid:) Executing: /bin/bash -c grep ^Device\: /proc/net/vlan/bond3.249 | awk {'print $2'} 2020-05-29 09:48:38,768 DEBUG [utils.script.Script] (main:null) (logid:) Executing while with timeout : 3600000 2020-05-29 09:48:38,772 DEBUG [utils.script.Script] (main:null) (logid:) Execution is successful. 2020-05-29 09:48:38,772 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking for pif for bridge brbond1-2216 2020-05-29 09:48:38,772 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) matchPifFileInDirectory: file name 'vnet12' 2020-05-29 09:48:38,773 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) matchPifFileInDirectory: file name 'bond1.2216' 2020-05-29 09:48:38,773 DEBUG [utils.script.Script] (main:null) (logid:) Executing: /bin/bash -c grep ^Device\: /proc/net/vlan/bond1.2216 | awk {'print $2'} 2020-05-29 09:48:38,774 DEBUG [utils.script.Script] (main:null) (logid:) Executing while with timeout : 3600000 2020-05-29 09:48:38,778 DEBUG [utils.script.Script] (main:null) (logid:) Execution is successful. 2020-05-29 09:48:38,778 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking for pif for bridge brbond1-2101 2020-05-29 09:48:38,779 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) matchPifFileInDirectory: file name 'bond1.2101' 2020-05-29 09:48:38,779 DEBUG [utils.script.Script] (main:null) (logid:) Executing: /bin/bash -c grep ^Device\: /proc/net/vlan/bond1.2101 | awk {'print $2'} 2020-05-29 09:48:38,780 DEBUG [utils.script.Script] (main:null) (logid:) Executing while with timeout : 3600000 2020-05-29 09:48:38,784 DEBUG [utils.script.Script] (main:null) (logid:) Execution is successful. 2020-05-29 09:48:38,784 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking for pif for bridge brbond1-2158 2020-05-29 09:48:38,784 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) matchPifFileInDirectory: file name 'bond1.2158' 2020-05-29 09:48:38,784 DEBUG [utils.script.Script] (main:null) (logid:) Executing: /bin/bash -c grep ^Device\: /proc/net/vlan/bond1.2158 | awk {'print $2'} 2020-05-29 09:48:38,785 DEBUG [utils.script.Script] (main:null) (logid:) Executing while with timeout : 3600000 2020-05-29 09:48:38,789 DEBUG [utils.script.Script] (main:null) (logid:) Execution is successful. 2020-05-29 09:48:38,789 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking for pif for bridge brbond1-2242 2020-05-29 09:48:38,789 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) matchPifFileInDirectory: file name 'vnet2' 2020-05-29 09:48:38,790 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) matchPifFileInDirectory: file name 'bond1.2242' 2020-05-29 09:48:38,790 DEBUG [utils.script.Script] (main:null) (logid:) Executing: /bin/bash -c grep ^Device\: /proc/net/vlan/bond1.2242 | awk {'print $2'} 2020-05-29 09:48:38,791 DEBUG [utils.script.Script] (main:null) (logid:) Executing while with timeout : 3600000 2020-05-29 09:48:38,794 DEBUG [utils.script.Script] (main:null) (logid:) Execution is successful. 2020-05-29 09:48:38,795 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking for pif for bridge cloudbr2 2020-05-29 09:48:38,795 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) matchPifFileInDirectory: file name 'bond2' 2020-05-29 09:48:38,795 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking for pif for bridge brbond1-2011 2020-05-29 09:48:38,795 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) matchPifFileInDirectory: file name 'bond1.2011' 2020-05-29 09:48:38,795 DEBUG [utils.script.Script] (main:null) (logid:) Executing: /bin/bash -c grep ^Device\: /proc/net/vlan/bond1.2011 | awk {'print $2'} 2020-05-29 09:48:38,796 DEBUG [utils.script.Script] (main:null) (logid:) Executing while with timeout : 3600000 2020-05-29 09:48:38,799 DEBUG [utils.script.Script] (main:null) (logid:) Execution is successful. 2020-05-29 09:48:38,799 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking for pif for bridge cloudbr0 2020-05-29 09:48:38,800 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) matchPifFileInDirectory: file name 'bond0' 2020-05-29 09:48:38,800 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking for pif for bridge cloud0 2020-05-29 09:48:38,800 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) failing to get physical interface from bridge cloud0, did not find an eth*, bond*, team*, vlan*, em*, p*p*, ens*, eno*, enp*, or enx* in /sys/devices/virtual/net/cloud0/brif 2020-05-29 09:48:38,800 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking for pif for bridge brbond1-2553 2020-05-29 09:48:38,800 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) matchPifFileInDirectory: file name 'bond1.2553' 2020-05-29 09:48:38,801 DEBUG [utils.script.Script] (main:null) (logid:) Executing: /bin/bash -c grep ^Device\: /proc/net/vlan/bond1.2553 | awk {'print $2'} 2020-05-29 09:48:38,802 DEBUG [utils.script.Script] (main:null) (logid:) Executing while with timeout : 3600000 2020-05-29 09:48:38,805 DEBUG [utils.script.Script] (main:null) (logid:) Execution is successful. 2020-05-29 09:48:38,805 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking for pif for bridge cloudbr3 2020-05-29 09:48:38,805 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) matchPifFileInDirectory: file name 'bond3' 2020-05-29 09:48:38,805 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking for pif for bridge brbond1-2278 2020-05-29 09:48:38,805 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) matchPifFileInDirectory: file name 'bond1.2278' 2020-05-29 09:48:38,806 DEBUG [utils.script.Script] (main:null) (logid:) Executing: /bin/bash -c grep ^Device\: /proc/net/vlan/bond1.2278 | awk {'print $2'} 2020-05-29 09:48:38,807 DEBUG [utils.script.Script] (main:null) (logid:) Executing while with timeout : 3600000 2020-05-29 09:48:38,810 DEBUG [utils.script.Script] (main:null) (logid:) Execution is successful. 2020-05-29 09:48:38,810 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking for pif for bridge brbond1-2022 2020-05-29 09:48:38,810 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) matchPifFileInDirectory: file name 'bond1.2022' 2020-05-29 09:48:38,811 DEBUG [utils.script.Script] (main:null) (logid:) Executing: /bin/bash -c grep ^Device\: /proc/net/vlan/bond1.2022 | awk {'print $2'} 2020-05-29 09:48:38,812 DEBUG [utils.script.Script] (main:null) (logid:) Executing while with timeout : 3600000 2020-05-29 09:48:38,815 DEBUG [utils.script.Script] (main:null) (logid:) Execution is successful. 2020-05-29 09:48:38,816 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking for pif for bridge cloudbr1 2020-05-29 09:48:38,816 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) matchPifFileInDirectory: file name 'bond1' 2020-05-29 09:48:38,816 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking for pif for bridge brbond1-2483 2020-05-29 09:48:38,816 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) matchPifFileInDirectory: file name 'bond1.2483' 2020-05-29 09:48:38,817 DEBUG [utils.script.Script] (main:null) (logid:) Executing: /bin/bash -c grep ^Device\: /proc/net/vlan/bond1.2483 | awk {'print $2'} 2020-05-29 09:48:38,818 DEBUG [utils.script.Script] (main:null) (logid:) Executing while with timeout : 3600000 2020-05-29 09:48:38,821 DEBUG [utils.script.Script] (main:null) (logid:) Execution is successful. 2020-05-29 09:48:38,821 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) looking for pif for bridge brbond1-2596 2020-05-29 09:48:38,821 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) matchPifFileInDirectory: file name 'bond1.2596' 2020-05-29 09:48:38,822 DEBUG [utils.script.Script] (main:null) (logid:) Executing: /bin/bash -c grep ^Device\: /proc/net/vlan/bond1.2596 | awk {'print $2'} 2020-05-29 09:48:38,823 DEBUG [utils.script.Script] (main:null) (logid:) Executing while with timeout : 3600000 2020-05-29 09:48:38,826 DEBUG [utils.script.Script] (main:null) (logid:) Execution is successful. 2020-05-29 09:48:38,826 DEBUG [kvm.resource.BridgeVifDriver] (main:null) (logid:) done looking for pifs, no more bridges 2020-05-29 09:48:38,834 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvlan.sh in the classpath 2020-05-29 09:48:38,835 DEBUG [utils.script.Script] (main:null) (logid:) System resource: null 2020-05-29 09:48:38,835 DEBUG [utils.script.Script] (main:null) (logid:) Classpath resource: null 2020-05-29 09:48:38,835 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvlan.sh 2020-05-29 09:48:38,835 DEBUG [utils.script.Script] (main:null) (logid:) Current binaries reside at /usr/share/cloudstack-agent/lib 2020-05-29 09:48:38,835 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvlan.sh in /usr/share/cloudstack-agent/lib/scripts/vm/network/vnet/modifyvlan.sh 2020-05-29 09:48:38,835 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvlan.sh in /usr/share/cloudstack-agent/lib/scripts/vm/network/modifyvlan.sh 2020-05-29 09:48:38,835 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvlan.sh in /usr/share/cloudstack-agent/lib/scripts/vm/modifyvlan.sh 2020-05-29 09:48:38,836 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvlan.sh in /usr/share/cloudstack-agent/lib/scripts/modifyvlan.sh 2020-05-29 09:48:38,836 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvlan.sh in /usr/share/cloudstack-agent/lib/modifyvlan.sh 2020-05-29 09:48:38,836 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvlan.sh in /usr/share/cloudstack-agent/modifyvlan.sh 2020-05-29 09:48:38,836 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvlan.sh in /usr/share/modifyvlan.sh 2020-05-29 09:48:38,836 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvlan.sh in /usr/modifyvlan.sh 2020-05-29 09:48:38,836 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvlan.sh in /modifyvlan.sh 2020-05-29 09:48:38,836 DEBUG [utils.script.Script] (main:null) (logid:) Searching in environment.properties 2020-05-29 09:48:38,836 DEBUG [utils.script.Script] (main:null) (logid:) environment.properties says scripts should be in /usr/share/cloudstack-common 2020-05-29 09:48:38,837 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvlan.sh in /usr/share/cloudstack-common/scripts/vm/network/vnet/modifyvlan.sh 2020-05-29 09:48:38,837 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvxlan.sh in the classpath 2020-05-29 09:48:38,837 DEBUG [utils.script.Script] (main:null) (logid:) System resource: null 2020-05-29 09:48:38,837 DEBUG [utils.script.Script] (main:null) (logid:) Classpath resource: null 2020-05-29 09:48:38,837 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvxlan.sh 2020-05-29 09:48:38,837 DEBUG [utils.script.Script] (main:null) (logid:) Current binaries reside at /usr/share/cloudstack-agent/lib 2020-05-29 09:48:38,838 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvxlan.sh in /usr/share/cloudstack-agent/lib/scripts/vm/network/vnet/modifyvxlan.sh 2020-05-29 09:48:38,838 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvxlan.sh in /usr/share/cloudstack-agent/lib/scripts/vm/network/modifyvxlan.sh 2020-05-29 09:48:38,838 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvxlan.sh in /usr/share/cloudstack-agent/lib/scripts/vm/modifyvxlan.sh 2020-05-29 09:48:38,838 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvxlan.sh in /usr/share/cloudstack-agent/lib/scripts/modifyvxlan.sh 2020-05-29 09:48:38,838 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvxlan.sh in /usr/share/cloudstack-agent/lib/modifyvxlan.sh 2020-05-29 09:48:38,838 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvxlan.sh in /usr/share/cloudstack-agent/modifyvxlan.sh 2020-05-29 09:48:38,838 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvxlan.sh in /usr/share/modifyvxlan.sh 2020-05-29 09:48:38,838 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvxlan.sh in /usr/modifyvxlan.sh 2020-05-29 09:48:38,838 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvxlan.sh in /modifyvxlan.sh 2020-05-29 09:48:38,838 DEBUG [utils.script.Script] (main:null) (logid:) Searching in environment.properties 2020-05-29 09:48:38,839 DEBUG [utils.script.Script] (main:null) (logid:) environment.properties says scripts should be in /usr/share/cloudstack-common 2020-05-29 09:48:38,839 DEBUG [utils.script.Script] (main:null) (logid:) Looking for modifyvxlan.sh in /usr/share/cloudstack-common/scripts/vm/network/vnet/modifyvxlan.sh 2020-05-29 09:48:38,839 DEBUG [kvm.resource.LibvirtComputingResource] (main:null) (logid:) Found pif: bond1 on cloudbr0, pif: bond2 on cloudbr2 2020-05-29 09:48:38,839 DEBUG [kvm.resource.LibvirtComputingResource] (main:null) (logid:) Executing: /usr/share/cloudstack-common/scripts/vm/network/security_group.py can_bridge_firewall --privnic bond2 2020-05-29 09:48:38,840 DEBUG [kvm.resource.LibvirtComputingResource] (main:null) (logid:) Executing while with timeout : 1800000 2020-05-29 09:48:39,041 DEBUG [kvm.resource.LibvirtComputingResource] (main:null) (logid:) Execution is successful. 2020-05-29 09:48:39,042 DEBUG [utils.script.Script] (main:null) (logid:) Executing: /bin/bash -c ip route show default 0.0.0.0/0|head -1|awk '{print $3}' 2020-05-29 09:48:39,043 DEBUG [utils.script.Script] (main:null) (logid:) Executing while with timeout : 3600000 2020-05-29 09:48:39,048 DEBUG [utils.script.Script] (main:null) (logid:) Execution is successful. 2020-05-29 09:48:39,048 DEBUG [utils.script.Script] (main:null) (logid:) Executing: /bin/bash -c ethtool bond2 |grep Speed | cut -d \ -f 2 2020-05-29 09:48:39,050 DEBUG [utils.script.Script] (main:null) (logid:) Executing while with timeout : 3600000 2020-05-29 09:48:39,054 DEBUG [utils.script.Script] (main:null) (logid:) Execution is successful. 2020-05-29 09:48:39,054 DEBUG [kvm.resource.LibvirtComputingResource] (main:null) (logid:) device bond2 has speed: 2000 2020-05-29 09:48:39,055 DEBUG [utils.script.Script] (main:null) (logid:) Executing: /bin/bash -c ip route | grep 169.254.0.0/16 2020-05-29 09:48:39,056 DEBUG [utils.script.Script] (main:null) (logid:) Executing while with timeout : 1800000 2020-05-29 09:48:39,061 DEBUG [utils.script.Script] (main:null) (logid:) Execution is successful. 2020-05-29 09:48:39,082 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createtmplt.sh in the classpath 2020-05-29 09:48:39,083 DEBUG [utils.script.Script] (main:null) (logid:) System resource: null 2020-05-29 09:48:39,083 DEBUG [utils.script.Script] (main:null) (logid:) Classpath resource: null 2020-05-29 09:48:39,083 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createtmplt.sh 2020-05-29 09:48:39,083 DEBUG [utils.script.Script] (main:null) (logid:) Current binaries reside at /usr/share/cloudstack-agent/lib 2020-05-29 09:48:39,083 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createtmplt.sh in /usr/share/cloudstack-agent/lib/scripts/storage/qcow2/createtmplt.sh 2020-05-29 09:48:39,084 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createtmplt.sh in /usr/share/cloudstack-agent/lib/scripts/storage/createtmplt.sh 2020-05-29 09:48:39,084 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createtmplt.sh in /usr/share/cloudstack-agent/lib/scripts/createtmplt.sh 2020-05-29 09:48:39,084 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createtmplt.sh in /usr/share/cloudstack-agent/lib/createtmplt.sh 2020-05-29 09:48:39,084 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createtmplt.sh in /usr/share/cloudstack-agent/createtmplt.sh 2020-05-29 09:48:39,084 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createtmplt.sh in /usr/share/createtmplt.sh 2020-05-29 09:48:39,084 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createtmplt.sh in /usr/createtmplt.sh 2020-05-29 09:48:39,084 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createtmplt.sh in /createtmplt.sh 2020-05-29 09:48:39,084 DEBUG [utils.script.Script] (main:null) (logid:) Searching in environment.properties 2020-05-29 09:48:39,084 DEBUG [utils.script.Script] (main:null) (logid:) environment.properties says scripts should be in /usr/share/cloudstack-common 2020-05-29 09:48:39,084 DEBUG [utils.script.Script] (main:null) (logid:) Looking for createtmplt.sh in /usr/share/cloudstack-common/scripts/storage/qcow2/createtmplt.sh 2020-05-29 09:48:39,084 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh in the classpath 2020-05-29 09:48:39,085 DEBUG [utils.script.Script] (main:null) (logid:) System resource: null 2020-05-29 09:48:39,085 DEBUG [utils.script.Script] (main:null) (logid:) Classpath resource: null 2020-05-29 09:48:39,085 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh 2020-05-29 09:48:39,085 DEBUG [utils.script.Script] (main:null) (logid:) Current binaries reside at /usr/share/cloudstack-agent/lib 2020-05-29 09:48:39,085 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh in /usr/share/cloudstack-agent/lib/scripts/storage/qcow2/managesnapshot.sh 2020-05-29 09:48:39,085 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh in /usr/share/cloudstack-agent/lib/scripts/storage/managesnapshot.sh 2020-05-29 09:48:39,085 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh in /usr/share/cloudstack-agent/lib/scripts/managesnapshot.sh 2020-05-29 09:48:39,085 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh in /usr/share/cloudstack-agent/lib/managesnapshot.sh 2020-05-29 09:48:39,085 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh in /usr/share/cloudstack-agent/managesnapshot.sh 2020-05-29 09:48:39,085 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh in /usr/share/managesnapshot.sh 2020-05-29 09:48:39,086 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh in /usr/managesnapshot.sh 2020-05-29 09:48:39,086 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh in /managesnapshot.sh 2020-05-29 09:48:39,086 DEBUG [utils.script.Script] (main:null) (logid:) Searching in environment.properties 2020-05-29 09:48:39,086 DEBUG [utils.script.Script] (main:null) (logid:) environment.properties says scripts should be in /usr/share/cloudstack-common 2020-05-29 09:48:39,086 DEBUG [utils.script.Script] (main:null) (logid:) Looking for managesnapshot.sh in /usr/share/cloudstack-common/scripts/storage/qcow2/managesnapshot.sh 2020-05-29 09:48:39,103 DEBUG [cloud.agent.Agent] (main:null) (logid:) Adding shutdown hook 2020-05-29 09:48:39,103 INFO [cloud.agent.Agent] (main:null) (logid:) Agent [id = 0 : type = LibvirtComputingResource : zone = 2 : pod = 2 : workers = 5 : host = 10.222.0.200 : port = 8251 2020-05-29 09:48:39,103 DEBUG [utils.script.Script] (main:null) (logid:) Looking for keystore-setup in the classpath 2020-05-29 09:48:39,104 DEBUG [utils.script.Script] (main:null) (logid:) System resource: null 2020-05-29 09:48:39,104 DEBUG [utils.script.Script] (main:null) (logid:) Classpath resource: null 2020-05-29 09:48:39,104 DEBUG [utils.script.Script] (main:null) (logid:) Looking for keystore-setup 2020-05-29 09:48:39,104 DEBUG [utils.script.Script] (main:null) (logid:) Current binaries reside at /usr/share/cloudstack-agent/lib 2020-05-29 09:48:39,104 DEBUG [utils.script.Script] (main:null) (logid:) Looking for keystore-setup in /usr/share/cloudstack-agent/lib/scripts/util/keystore-setup 2020-05-29 09:48:39,104 DEBUG [utils.script.Script] (main:null) (logid:) Looking for keystore-setup in /usr/share/cloudstack-agent/lib/scripts/keystore-setup 2020-05-29 09:48:39,104 DEBUG [utils.script.Script] (main:null) (logid:) Looking for keystore-setup in /usr/share/cloudstack-agent/lib/keystore-setup 2020-05-29 09:48:39,104 DEBUG [utils.script.Script] (main:null) (logid:) Looking for keystore-setup in /usr/share/cloudstack-agent/keystore-setup 2020-05-29 09:48:39,104 DEBUG [utils.script.Script] (main:null) (logid:) Looking for keystore-setup in /usr/share/keystore-setup 2020-05-29 09:48:39,104 DEBUG [utils.script.Script] (main:null) (logid:) Looking for keystore-setup in /usr/keystore-setup 2020-05-29 09:48:39,105 DEBUG [utils.script.Script] (main:null) (logid:) Looking for keystore-setup in /keystore-setup 2020-05-29 09:48:39,105 DEBUG [utils.script.Script] (main:null) (logid:) Searching in environment.properties 2020-05-29 09:48:39,105 DEBUG [utils.script.Script] (main:null) (logid:) environment.properties says scripts should be in /usr/share/cloudstack-common 2020-05-29 09:48:39,105 DEBUG [utils.script.Script] (main:null) (logid:) Looking for keystore-setup in /usr/share/cloudstack-common/scripts/util/keystore-setup 2020-05-29 09:48:39,105 DEBUG [utils.script.Script] (main:null) (logid:) Looking for keystore-cert-import in the classpath 2020-05-29 09:48:39,105 DEBUG [utils.script.Script] (main:null) (logid:) System resource: null 2020-05-29 09:48:39,106 DEBUG [utils.script.Script] (main:null) (logid:) Classpath resource: null 2020-05-29 09:48:39,106 DEBUG [utils.script.Script] (main:null) (logid:) Looking for keystore-cert-import 2020-05-29 09:48:39,106 DEBUG [utils.script.Script] (main:null) (logid:) Current binaries reside at /usr/share/cloudstack-agent/lib 2020-05-29 09:48:39,106 DEBUG [utils.script.Script] (main:null) (logid:) Looking for keystore-cert-import in /usr/share/cloudstack-agent/lib/scripts/util/keystore-cert-import 2020-05-29 09:48:39,106 DEBUG [utils.script.Script] (main:null) (logid:) Looking for keystore-cert-import in /usr/share/cloudstack-agent/lib/scripts/keystore-cert-import 2020-05-29 09:48:39,106 DEBUG [utils.script.Script] (main:null) (logid:) Looking for keystore-cert-import in /usr/share/cloudstack-agent/lib/keystore-cert-import 2020-05-29 09:48:39,106 DEBUG [utils.script.Script] (main:null) (logid:) Looking for keystore-cert-import in /usr/share/cloudstack-agent/keystore-cert-import 2020-05-29 09:48:39,106 DEBUG [utils.script.Script] (main:null) (logid:) Looking for keystore-cert-import in /usr/share/keystore-cert-import 2020-05-29 09:48:39,106 DEBUG [utils.script.Script] (main:null) (logid:) Looking for keystore-cert-import in /usr/keystore-cert-import 2020-05-29 09:48:39,106 DEBUG [utils.script.Script] (main:null) (logid:) Looking for keystore-cert-import in /keystore-cert-import 2020-05-29 09:48:39,106 DEBUG [utils.script.Script] (main:null) (logid:) Searching in environment.properties 2020-05-29 09:48:39,107 DEBUG [utils.script.Script] (main:null) (logid:) environment.properties says scripts should be in /usr/share/cloudstack-common 2020-05-29 09:48:39,107 DEBUG [utils.script.Script] (main:null) (logid:) Looking for keystore-cert-import in /usr/share/cloudstack-common/scripts/util/keystore-cert-import 2020-05-29 09:48:39,113 INFO [utils.nio.NioClient] (main:null) (logid:) Connecting to 10.222.0.200:8251 2020-05-29 09:48:39,118 INFO [utils.nio.Link] (main:null) (logid:) Conf file found: /etc/cloudstack/agent/agent.properties 2020-05-29 09:48:39,508 INFO [utils.nio.NioClient] (main:null) (logid:) SSL: Handshake done 2020-05-29 09:48:39,508 INFO [utils.nio.NioClient] (main:null) (logid:) Connected to 10.222.0.200:8251 2020-05-29 09:48:39,512 DEBUG [kvm.resource.LibvirtConnection] (Agent-Handler-1:null) (logid:) Looking for libvirtd connection at: qemu:///system 2020-05-29 09:48:39,563 DEBUG [kvm.resource.LibvirtCapXMLParser] (Agent-Handler-1:null) (logid:) Found /usr/libexec/qemu-kvm as a suiteable emulator 2020-05-29 09:48:39,573 DEBUG [cloud.resource.ServerResourceBase] (Agent-Handler-1:null) (logid:) Parameters for private nic: 10.222.5.10 - 90:e2:ba:35:34:a0-255.255.252.0 2020-05-29 09:48:39,573 DEBUG [cloud.resource.ServerResourceBase] (Agent-Handler-1:null) (logid:) Storage has its now nic: cloudbr249 2020-05-29 09:48:39,574 DEBUG [cloud.resource.ServerResourceBase] (Agent-Handler-1:null) (logid:) Parameters for storage nic: 10.223.5.10 - a0:36:9f:20:28:5c-255.255.0.0 2020-05-29 09:48:39,574 DEBUG [kvm.resource.LibvirtComputingResource] (Agent-Handler-1:null) (logid:) Executing: /usr/share/cloudstack-common/scripts/vm/hypervisor/versions.sh 2020-05-29 09:48:39,575 DEBUG [kvm.resource.LibvirtComputingResource] (Agent-Handler-1:null) (logid:) Executing while with timeout : 1800000 2020-05-29 09:48:39,592 DEBUG [kvm.resource.LibvirtComputingResource] (Agent-Handler-1:null) (logid:) Execution is successful. 2020-05-29 09:48:39,627 DEBUG [kvm.resource.LibvirtComputingResource] (Agent-Handler-1:null) (logid:) Executing: sudo grep InitiatorName= /etc/iscsi/initiatorname.iscsi 2020-05-29 09:48:39,628 DEBUG [kvm.resource.LibvirtComputingResource] (Agent-Handler-1:null) (logid:) Executing while with timeout : 3600000 2020-05-29 09:48:39,675 DEBUG [kvm.resource.LibvirtComputingResource] (Agent-Handler-1:null) (logid:) Execution is successful. 2020-05-29 09:48:39,675 INFO [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:null) (logid:) Attempting to create storage pool 6fba7a90-a3e4-460b-9c21-b1c66ebbd1ad (Filesystem) in libvirt 2020-05-29 09:48:39,675 DEBUG [kvm.resource.LibvirtConnection] (Agent-Handler-1:null) (logid:) Looking for libvirtd connection at: qemu:///system 2020-05-29 09:48:39,683 ERROR [kvm.resource.LibvirtConnection] (Agent-Handler-1:null) (logid:) Connection with libvirtd is broken: invalid connection pointer in virConnectGetVersion 2020-05-29 09:48:39,683 DEBUG [kvm.resource.LibvirtConnection] (Agent-Handler-1:null) (logid:) Opening a new libvirtd connection to: qemu:///system 2020-05-29 09:48:39,701 INFO [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:null) (logid:) Found existing defined storage pool 6fba7a90-a3e4-460b-9c21-b1c66ebbd1ad, using it. 2020-05-29 09:48:39,704 INFO [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:null) (logid:) Trying to fetch storage pool 6fba7a90-a3e4-460b-9c21-b1c66ebbd1ad from libvirt 2020-05-29 09:48:39,704 DEBUG [kvm.resource.LibvirtConnection] (Agent-Handler-1:null) (logid:) Looking for libvirtd connection at: qemu:///system 2020-05-29 09:48:39,741 DEBUG [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:null) (logid:) Succesfully refreshed pool 6fba7a90-a3e4-460b-9c21-b1c66ebbd1ad Capacity: 80491315200 Used: 5097652224 Available: 75393662976 2020-05-29 09:48:39,745 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null) (logid:) Executing: hostname 2020-05-29 09:48:39,746 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null) (logid:) Executing while with timeout : 500 2020-05-29 09:48:39,747 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null) (logid:) Execution is successful. 2020-05-29 09:48:39,748 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null) (logid:) Executing: hostname 2020-05-29 09:48:39,749 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null) (logid:) Executing while with timeout : 500 2020-05-29 09:48:39,750 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null) (logid:) Execution is successful. 2020-05-29 09:48:39,800 INFO [cloud.serializer.GsonHelper] (Agent-Handler-1:null) (logid:) Default Builder inited. 2020-05-29 09:48:39,825 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null) (logid:) Sending Startup: Seq 0-0: { Cmd , MgmtId: -1, via: 0, Ver: v1, Flags: 1, [{"com.cloud.agent.api.StartupRoutingCommand":{"cpuSockets":2,"cpus":16,"speed":2395,"memory":66469244928,"dom0MinMemory":1073741824,"poolSync":false,"supportsClonedVolumes":false,"caps":"hvm,snapshot","pool":"/root","hypervisorType":"KVM","hostDetails":{"Host.OS.Kernel.Version":"4.17.13-1.el7.elrepo.x86_64","com.cloud.network.Networks.RouterPrivateIpStrategy":"HostLocal","Host.OS.Version":"7.8.2003","secured":"true","Host.OS":"CentOS"},"hostTags":[],"groupDetails":{},"type":"Routing","dataCenter":"2","pod":"2","cluster":"18","guid":"862603de-4865-3241-8055-e5bde9e25f6b-LibvirtComputingResource","name":"kvm0201","id":0,"version":"4.13.0.0","iqn":"iqn.1994-05.com.redhat:b487e3cd1fa2","privateIpAddress":"10.222.5.10","privateMacAddress":"90:e2:ba:35:34:a0","privateNetmask":"255.255.252.0","storageIpAddress":"10.223.5.10","storageNetmask":"255.255.0.0","storageMacAddress":"a0:36:9f:20:28:5c","resourceName":"LibvirtComputingResource","gatewayIpAddress":"10.222.4.1","msHostList":"10.222.0.200@static","wait":0}},{"com.cloud.agent.api.StartupStorageCommand":{"totalSize":0,"poolInfo":{"uuid":"6fba7a90-a3e4-460b-9c21-b1c66ebbd1ad","host":"10.222.5.10","localPath":"/var/lib/libvirt/images","hostPath":"/var/lib/libvirt/images","poolType":"Filesystem","capacityBytes":80491315200,"availableBytes":75393662976},"resourceType":"STORAGE_POOL","hostDetails":{},"type":"Storage","dataCenter":"2","pod":"2","guid":"862603de-4865-3241-8055-e5bde9e25f6b-LibvirtComputingResource","name":"kvm0201","id":0,"version":"4.13.0.0","resourceName":"LibvirtComputingResource","msHostList":"10.222.0.200@static","wait":0}}] } 2020-05-29 09:48:39,825 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null) (logid:) Startup task created 2020-05-29 09:48:40,110 DEBUG [cloud.agent.Agent] (Agent-Handler-2:null) (logid:) Received response: Seq 0-0: { Ans: , MgmtId: 249302044940158, via: -1, Ver: v1, Flags: 100000, [{"com.cloud.agent.api.StartupAnswer":{"hostId":0,"pingInterval":60,"result":true,"wait":0}}] } 2020-05-29 09:48:40,111 DEBUG [cloud.agent.Agent] (Agent-Handler-2:null) (logid:) Startup task cancelled 2020-05-29 09:48:40,111 INFO [cloud.agent.Agent] (Agent-Handler-2:null) (logid:) Proccess agent startup answer, agent id = 0 2020-05-29 09:48:40,111 INFO [cloud.agent.Agent] (Agent-Handler-2:null) (logid:) Set agent id 0 2020-05-29 09:48:40,117 DEBUG [cloud.agent.Agent] (Agent-Handler-2:null) (logid:) Adding a watch list 2020-05-29 09:48:40,118 INFO [cloud.agent.Agent] (Agent-Handler-2:null) (logid:) Startup Response Received: agent id = 0 2020-05-29 09:48:40,119 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-1:null) (logid:) Executing: /usr/share/cloudstack-common/scripts/vm/network/security_group.py get_rule_logs_for_vms 2020-05-29 09:48:40,121 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-1:null) (logid:) Executing while with timeout : 1800000 2020-05-29 09:48:40,333 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:03755f2c) Request:Seq 98-4044513940355416065: { Cmd , MgmtId: 249302044940158, via: 98, Ver: v1, Flags: 100011, [{"com.cloud.agent.api.CleanupNetworkRulesCmd":{"interval":1995,"wait":0}}] } 2020-05-29 09:48:40,334 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:03755f2c) Processing command: com.cloud.agent.api.CleanupNetworkRulesCmd 2020-05-29 09:48:40,334 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:03755f2c) Adding a watch list 2020-05-29 09:48:40,335 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:03755f2c) Seq 98-4044513940355416065: { Ans: , MgmtId: 249302044940158, via: 98, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] } 2020-05-29 09:48:40,337 DEBUG [org.reflections.Reflections] (Agent-Handler-4:null) (logid:03755f2c) going to scan these urls: jar:file:/usr/share/cloudstack-agent/lib/cloud-plugin-hypervisor-kvm-4.13.0.0.jar!/ 2020-05-29 09:48:40,345 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) (logid:03755f2c) Request:Seq 98-4044513940355416066: { Cmd , MgmtId: 249302044940158, via: 98, Ver: v1, Flags: 100011, [{"com.cloud.agent.api.ModifyStoragePoolCommand":{"add":true,"pool":{"id":20,"uuid":"2258aa76-7813-354d-b274-961fb337e716","host":"ceph-mon","path":"rbd","userInfo":"admin:AQDWA1pbHMIfCBAAlO-Sl5U5QGHM_+nH3u7K7A==","port":6789,"type":"RBD"},"localPath":"/mnt//9e8299eb-132c-3dc7-931e-a1591aacdf1a","wait":0}}] } 2020-05-29 09:48:40,345 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) (logid:03755f2c) Processing command: com.cloud.agent.api.ModifyStoragePoolCommand 2020-05-29 09:48:40,366 INFO [org.reflections.Reflections] (Agent-Handler-4:null) (logid:03755f2c) Reflections took 28 ms to scan 1 urls, producing 5 keys and 153 values 2020-05-29 09:48:40,368 DEBUG [org.reflections.Reflections] (Agent-Handler-4:null) (logid:03755f2c) expanded subtype java.lang.Comparable -> java.lang.Enum 2020-05-29 09:48:40,368 DEBUG [org.reflections.Reflections] (Agent-Handler-4:null) (logid:03755f2c) expanded subtype java.io.Serializable -> java.lang.Enum 2020-05-29 09:48:40,375 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-1:null) (logid:) Execution is successful. 2020-05-29 09:48:40,376 DEBUG [kvm.resource.LibvirtConnection] (UgentTask-1:null) (logid:) Looking for libvirtd connection at: qemu:///system 2020-05-29 09:48:40,417 DEBUG [cloud.agent.Agent] (UgentTask-1:null) (logid:) Sending ping: Seq 0-1: { Cmd , MgmtId: -1, via: 0, Ver: v1, Flags: 11, [{"com.cloud.agent.api.PingRoutingWithNwGroupsCommand":{"newGroupStates":{},"_hostVmStateReport":{"i-169-1740-VM":{"state":"PowerOn","host":"kvm0201"},"i-145-1541-VM":{"state":"PowerOn","host":"kvm0201"},"i-145-1529-VM":{"state":"PowerOn","host":"kvm0201"},"i-151-1641-VM":{"state":"PowerOn","host":"kvm0201"},"i-129-1522-VM":{"state":"PowerOn","host":"kvm0201"}},"_gatewayAccessible":true,"_vnetAccessible":true,"hostType":"Routing","hostId":0,"wait":0}}] } 2020-05-29 09:48:40,463 DEBUG [kvm.resource.LibvirtComputingResource] (Agent-Handler-4:null) (logid:03755f2c) Executing: /usr/share/cloudstack-common/scripts/vm/network/security_group.py cleanup_rules 2020-05-29 09:48:40,463 INFO [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:03755f2c) Attempting to create storage pool 2258aa76-7813-354d-b274-961fb337e716 (RBD) in libvirt 2020-05-29 09:48:40,463 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-3:null) (logid:03755f2c) Looking for libvirtd connection at: qemu:///system 2020-05-29 09:48:40,464 DEBUG [kvm.resource.LibvirtComputingResource] (Agent-Handler-4:null) (logid:03755f2c) Executing while with timeout : 1800000 2020-05-29 09:48:40,469 WARN [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:03755f2c) Storage pool 2258aa76-7813-354d-b274-961fb337e716 was not found running in libvirt. Need to create it. 2020-05-29 09:48:40,469 INFO [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:03755f2c) Didn't find an existing storage pool 2258aa76-7813-354d-b274-961fb337e716 by UUID, checking for pools with duplicate paths 2020-05-29 09:48:40,474 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:03755f2c) Checking path of existing pool 6fba7a90-a3e4-460b-9c21-b1c66ebbd1ad against pool we want to create 2020-05-29 09:48:40,482 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:03755f2c) Checking path of existing pool 31bf418a-be32-3a18-8c5d-c62eb4358eda against pool we want to create 2020-05-29 09:48:40,489 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:03755f2c) Checking path of existing pool b9a8ad4a-9032-3db2-ba98-938b891e1af1 against pool we want to create 2020-05-29 09:48:40,492 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null) (logid:) Received response: Seq 0-1: { Ans: , MgmtId: 249302044940158, via: 98, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.PingAnswer":{"_command":{"hostType":"Routing","hostId":0,"wait":0},"result":true,"wait":0}}] } 2020-05-29 09:48:40,495 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:03755f2c) Attempting to create storage pool 2258aa76-7813-354d-b274-961fb337e716 2020-05-29 09:48:40,496 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:03755f2c) <secret ephemeral='no' private='no'> <uuid>2258aa76-7813-354d-b274-961fb337e716</uuid> <usage type='ceph'> <name>admin@ceph-mon:6789/rbd</name> </usage> </secret> 2020-05-29 09:48:40,542 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:03755f2c) <pool type='rbd'> <name>2258aa76-7813-354d-b274-961fb337e716</name> <uuid>2258aa76-7813-354d-b274-961fb337e716</uuid> <source> <host name='ceph-mon' port='6789'/> <name>rbd</name> <auth username='admin' type='ceph'> <secret uuid='2258aa76-7813-354d-b274-961fb337e716'/> </auth> </source> </pool> 2020-05-29 09:48:40,665 DEBUG [kvm.resource.LibvirtComputingResource] (Agent-Handler-4:null) (logid:03755f2c) Execution is successful. 2020-05-29 09:48:40,666 DEBUG [cloud.agent.Agent] (Agent-Handler-4:null) (logid:03755f2c) Watch Sent: Seq 98-4044513940355416065: { Ans: , MgmtId: 249302044940158, via: 98, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"details":"","wait":0}}] } 2020-05-29 09:49:26,202 ERROR [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:03755f2c) Failed to create RBD storage pool: org.libvirt.LibvirtException: failed to open the RBD image 'c47d7221-a664-41c6-a791-1148ec6f0850': No such file or directory 2020-05-29 09:49:26,202 ERROR [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:03755f2c) Failed to create the RBD storage pool, cleaning up the libvirt secret 2020-05-29 09:49:26,207 WARN [cloud.agent.Agent] (agentRequest-Handler-3:null) (logid:03755f2c) Caught: com.cloud.utils.exception.CloudRuntimeException: Failed to create storage pool: 2258aa76-7813-354d-b274-961fb337e716 at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.createStoragePool(LibvirtStorageAdaptor.java:585) at com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.createStoragePool(KVMStoragePoolManager.java:329) at com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.createStoragePool(KVMStoragePoolManager.java:323) at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtModifyStoragePoolCommandWrapper.execute(LibvirtModifyStoragePoolCommandWrapper.java:42) at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtModifyStoragePoolCommandWrapper.execute(LibvirtModifyStoragePoolCommandWrapper.java:35) at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtRequestWrapper.execute(LibvirtRequestWrapper.java:78) at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1476) at com.cloud.agent.Agent.processRequest(Agent.java:640) at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:1053) at com.cloud.utils.nio.Task.call(Task.java:83) at com.cloud.utils.nio.Task.call(Task.java:29) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748) 2020-05-29 09:49:26,211 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) (logid:03755f2c) Seq 98-4044513940355416066: { Ans: , MgmtId: 249302044940158, via: 98, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":false,"details":"com.cloud.utils.exception.CloudRuntimeException: Failed to create storage pool: 2258aa76-7813-354d-b274-961fb337e716\n\tat com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.createStoragePool(LibvirtStorageAdaptor.java:585)\n\tat com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.createStoragePool(KVMStoragePoolManager.java:329)\n\tat com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.createStoragePool(KVMStoragePoolManager.java:323)\n\tat com.cloud.hypervisor.kvm.resource.wrapper.LibvirtModifyStoragePoolCommandWrapper.execute(LibvirtModifyStoragePoolCommandWrapper.java:42)\n\tat com.cloud.hypervisor.kvm.resource.wrapper.LibvirtModifyStoragePoolCommandWrapper.execute(LibvirtModifyStoragePoolCommandWrapper.java:35)\n\tat com.cloud.hypervisor.kvm.resource.wrapper.LibvirtRequestWrapper.execute(LibvirtRequestWrapper.java:78)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1476)\n\tat com.cloud.agent.Agent.processRequest(Agent.java:640)\n\tat com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:1053)\n\tat com.cloud.utils.nio.Task.call(Task.java:83)\n\tat com.cloud.utils.nio.Task.call(Task.java:29)\n\tat java.util.concurrent.FutureTask.run(FutureTask.java:266)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)\n\tat java.lang.Thread.run(Thread.java:748)\n","wait":0}}] } 2020-05-29 09:49:26,279 DEBUG [utils.nio.NioConnection] (Agent-NioConnectionHandler-1:null) (logid:) Location 1: Socket Socket[addr=/10.222.0.200,port=8251,localport=33962] closed on read. Probably -1 returned: Connection closed with -1 on reading size. 2020-05-29 09:49:26,279 DEBUG [utils.nio.NioConnection] (Agent-NioConnectionHandler-1:null) (logid:) Closing socket Socket[addr=/10.222.0.200,port=8251,localport=33962] 2020-05-29 09:49:26,280 DEBUG [cloud.agent.Agent] (Agent-Handler-2:null) (logid:) Clearing watch list: 2 2020-05-29 09:49:26,281 INFO [cloud.agent.Agent] (Agent-Handler-2:null) (logid:) Lost connection to host: 10.222.0.200. Attempting reconnection while we still have 0 commands in progress. 2020-05-29 09:49:26,281 INFO [utils.nio.NioClient] (Agent-Handler-2:null) (logid:) NioClient connection closed 2020-05-29 09:49:26,281 INFO [cloud.agent.Agent] (Agent-Handler-2:null) (logid:) Reconnecting to host:10.222.0.200 2020-05-29 09:49:26,282 INFO [utils.nio.NioClient] (Agent-Handler-2:null) (logid:) Connecting to 10.222.0.200:8251 2020-05-29 09:49:26,283 INFO [utils.nio.Link] (Agent-Handler-2:null) (logid:) Conf file found: /etc/cloudstack/agent/agent.properties 2020-05-29 09:49:26,375 INFO [utils.nio.NioClient] (Agent-Handler-2:null) (logid:) SSL: Handshake done 2020-05-29 09:49:26,375 INFO [utils.nio.NioClient] (Agent-Handler-2:null) (logid:) Connected to 10.222.0.200:8251 2020-05-29 09:49:26,376 DEBUG [kvm.resource.LibvirtConnection] (Agent-Handler-1:null) (logid:) Looking for libvirtd connection at: qemu:///system 2020-05-29 09:49:26,428 DEBUG [kvm.resource.LibvirtCapXMLParser] (Agent-Handler-1:null) (logid:) Found /usr/libexec/qemu-kvm as a suiteable emulator 2020-05-29 09:49:26,433 DEBUG [cloud.resource.ServerResourceBase] (Agent-Handler-1:null) (logid:) Parameters for private nic: 10.222.5.10 - 90:e2:ba:35:34:a0-255.255.252.0 2020-05-29 09:49:26,433 DEBUG [cloud.resource.ServerResourceBase] (Agent-Handler-1:null) (logid:) Storage has its now nic: cloudbr249 2020-05-29 09:49:26,433 DEBUG [cloud.resource.ServerResourceBase] (Agent-Handler-1:null) (logid:) Parameters for storage nic: 10.223.5.10 - a0:36:9f:20:28:5c-255.255.0.0 2020-05-29 09:49:26,433 DEBUG [kvm.resource.LibvirtComputingResource] (Agent-Handler-1:null) (logid:) Executing: /usr/share/cloudstack-common/scripts/vm/hypervisor/versions.sh 2020-05-29 09:49:26,435 DEBUG [kvm.resource.LibvirtComputingResource] (Agent-Handler-1:null) (logid:) Executing while with timeout : 1800000 2020-05-29 09:49:26,449 DEBUG [kvm.resource.LibvirtComputingResource] (Agent-Handler-1:null) (logid:) Execution is successful. 2020-05-29 09:49:26,484 DEBUG [kvm.resource.LibvirtComputingResource] (Agent-Handler-1:null) (logid:) Executing: sudo grep InitiatorName= /etc/iscsi/initiatorname.iscsi 2020-05-29 09:49:26,486 DEBUG [kvm.resource.LibvirtComputingResource] (Agent-Handler-1:null) (logid:) Executing while with timeout : 3600000 2020-05-29 09:49:26,532 DEBUG [kvm.resource.LibvirtComputingResource] (Agent-Handler-1:null) (logid:) Execution is successful. 2020-05-29 09:49:26,534 INFO [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:null) (logid:) Attempting to create storage pool 6fba7a90-a3e4-460b-9c21-b1c66ebbd1ad (Filesystem) in libvirt 2020-05-29 09:49:26,534 DEBUG [kvm.resource.LibvirtConnection] (Agent-Handler-1:null) (logid:) Looking for libvirtd connection at: qemu:///system 2020-05-29 09:49:26,535 ERROR [kvm.resource.LibvirtConnection] (Agent-Handler-1:null) (logid:) Connection with libvirtd is broken: invalid connection pointer in virConnectGetVersion 2020-05-29 09:49:26,535 DEBUG [kvm.resource.LibvirtConnection] (Agent-Handler-1:null) (logid:) Opening a new libvirtd connection to: qemu:///system 2020-05-29 09:49:26,553 INFO [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:null) (logid:) Found existing defined storage pool 6fba7a90-a3e4-460b-9c21-b1c66ebbd1ad, using it. 2020-05-29 09:49:26,556 INFO [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:null) (logid:) Trying to fetch storage pool 6fba7a90-a3e4-460b-9c21-b1c66ebbd1ad from libvirt 2020-05-29 09:49:26,556 DEBUG [kvm.resource.LibvirtConnection] (Agent-Handler-1:null) (logid:) Looking for libvirtd connection at: qemu:///system 2020-05-29 09:49:26,583 DEBUG [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:null) (logid:) Succesfully refreshed pool 6fba7a90-a3e4-460b-9c21-b1c66ebbd1ad Capacity: 80491315200 Used: 5097652224 Available: 75393662976 2020-05-29 09:49:26,583 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null) (logid:) Executing: hostname 2020-05-29 09:49:26,584 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null) (logid:) Executing while with timeout : 500 2020-05-29 09:49:26,585 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null) (logid:) Execution is successful. 2020-05-29 09:49:26,587 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null) (logid:) Executing: hostname 2020-05-29 09:49:26,588 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null) (logid:) Executing while with timeout : 500 2020-05-29 09:49:26,589 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null) (logid:) Execution is successful. 2020-05-29 09:49:26,593 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null) (logid:) Sending Startup: Seq 0-2: { Cmd , MgmtId: -1, via: 0, Ver: v1, Flags: 1, [{"com.cloud.agent.api.StartupRoutingCommand":{"cpuSockets":2,"cpus":16,"speed":2395,"memory":66469244928,"dom0MinMemory":1073741824,"poolSync":false,"supportsClonedVolumes":false,"caps":"hvm,snapshot","pool":"/root","hypervisorType":"KVM","hostDetails":{"Host.OS.Kernel.Version":"4.17.13-1.el7.elrepo.x86_64","com.cloud.network.Networks.RouterPrivateIpStrategy":"HostLocal","Host.OS.Version":"7.8.2003","secured":"true","Host.OS":"CentOS"},"hostTags":[],"groupDetails":{},"type":"Routing","dataCenter":"2","pod":"2","cluster":"18","guid":"862603de-4865-3241-8055-e5bde9e25f6b-LibvirtComputingResource","name":"kvm0201","id":0,"version":"4.13.0.0","iqn":"iqn.1994-05.com.redhat:b487e3cd1fa2","privateIpAddress":"10.222.5.10","privateMacAddress":"90:e2:ba:35:34:a0","privateNetmask":"255.255.252.0","storageIpAddress":"10.223.5.10","storageNetmask":"255.255.0.0","storageMacAddress":"a0:36:9f:20:28:5c","resourceName":"LibvirtComputingResource","gatewayIpAddress":"10.222.4.1","msHostList":"10.222.0.200@static","wait":0}},{"com.cloud.agent.api.StartupStorageCommand":{"totalSize":0,"poolInfo":{"uuid":"6fba7a90-a3e4-460b-9c21-b1c66ebbd1ad","host":"10.222.5.10","localPath":"/var/lib/libvirt/images","hostPath":"/var/lib/libvirt/images","poolType":"Filesystem","capacityBytes":80491315200,"availableBytes":75393662976},"resourceType":"STORAGE_POOL","hostDetails":{},"type":"Storage","dataCenter":"2","pod":"2","guid":"862603de-4865-3241-8055-e5bde9e25f6b-LibvirtComputingResource","name":"kvm0201","id":0,"version":"4.13.0.0","resourceName":"LibvirtComputingResource","msHostList":"10.222.0.200@static","wait":0}}] } 2020-05-29 09:49:26,594 DEBUG [cloud.agent.Agent] (Agent-Handler-1:null) (logid:) Startup task created 2020-05-29 09:49:30,432 DEBUG [cloud.agent.Agent] (Agent-Handler-2:null) (logid:) Received response: Seq 0-2: { Ans: , MgmtId: 249302044940158, via: -1, Ver: v1, Flags: 100000, [{"com.cloud.agent.api.StartupAnswer":{"hostId":0,"pingInterval":60,"result":true,"wait":0}}] } 2020-05-29 09:49:30,433 DEBUG [cloud.agent.Agent] (Agent-Handler-2:null) (logid:) Startup task cancelled 2020-05-29 09:49:30,434 INFO [cloud.agent.Agent] (Agent-Handler-2:null) (logid:) Proccess agent startup answer, agent id = 0 2020-05-29 09:49:30,434 INFO [cloud.agent.Agent] (Agent-Handler-2:null) (logid:) Set agent id 0 2020-05-29 09:49:30,435 DEBUG [cloud.agent.Agent] (Agent-Handler-2:null) (logid:) Adding a watch list 2020-05-29 09:49:30,435 INFO [cloud.agent.Agent] (Agent-Handler-2:null) (logid:) Startup Response Received: agent id = 0 2020-05-29 09:49:30,436 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-2:null) (logid:) Executing: /usr/share/cloudstack-common/scripts/vm/network/security_group.py get_rule_logs_for_vms 2020-05-29 09:49:30,438 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-2:null) (logid:) Executing while with timeout : 1800000 2020-05-29 09:49:30,551 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:f9ab491a) Request:Seq 98-3748683739832516609: { Cmd , MgmtId: 249302044940158, via: 98, Ver: v1, Flags: 100011, [{"com.cloud.agent.api.CleanupNetworkRulesCmd":{"interval":2600,"wait":0}}] } 2020-05-29 09:49:30,552 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:f9ab491a) Processing command: com.cloud.agent.api.CleanupNetworkRulesCmd 2020-05-29 09:49:30,552 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:f9ab491a) Adding a watch list 2020-05-29 09:49:30,553 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:f9ab491a) Seq 98-3748683739832516609: { Ans: , MgmtId: 249302044940158, via: 98, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] } 2020-05-29 09:49:30,553 DEBUG [kvm.resource.LibvirtComputingResource] (Agent-Handler-4:null) (logid:f9ab491a) Executing: /usr/share/cloudstack-common/scripts/vm/network/security_group.py cleanup_rules 2020-05-29 09:49:30,555 DEBUG [kvm.resource.LibvirtComputingResource] (Agent-Handler-4:null) (logid:f9ab491a) Executing while with timeout : 1800000 2020-05-29 09:49:30,602 DEBUG [cloud.agent.Agent] (agentRequest-Handler-5:null) (logid:f9ab491a) Request:Seq 98-3748683739832516610: { Cmd , MgmtId: 249302044940158, via: 98, Ver: v1, Flags: 100011, [{"com.cloud.agent.api.ModifyStoragePoolCommand":{"add":true,"pool":{"id":20,"uuid":"2258aa76-7813-354d-b274-961fb337e716","host":"ceph-mon","path":"rbd","userInfo":"admin:AQDWA1pbHMIfCBAAlO-Sl5U5QGHM_+nH3u7K7A==","port":6789,"type":"RBD"},"localPath":"/mnt//9e8299eb-132c-3dc7-931e-a1591aacdf1a","wait":0}}] } 2020-05-29 09:49:30,602 DEBUG [cloud.agent.Agent] (agentRequest-Handler-5:null) (logid:f9ab491a) Processing command: com.cloud.agent.api.ModifyStoragePoolCommand 2020-05-29 09:49:30,602 INFO [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) (logid:f9ab491a) Attempting to create storage pool 2258aa76-7813-354d-b274-961fb337e716 (RBD) in libvirt 2020-05-29 09:49:30,602 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-5:null) (logid:f9ab491a) Looking for libvirtd connection at: qemu:///system 2020-05-29 09:49:30,620 WARN [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) (logid:f9ab491a) Storage pool 2258aa76-7813-354d-b274-961fb337e716 was not found running in libvirt. Need to create it. 2020-05-29 09:49:30,620 INFO [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) (logid:f9ab491a) Didn't find an existing storage pool 2258aa76-7813-354d-b274-961fb337e716 by UUID, checking for pools with duplicate paths 2020-05-29 09:49:30,626 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) (logid:f9ab491a) Checking path of existing pool 6fba7a90-a3e4-460b-9c21-b1c66ebbd1ad against pool we want to create 2020-05-29 09:49:30,634 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) (logid:f9ab491a) Checking path of existing pool 31bf418a-be32-3a18-8c5d-c62eb4358eda against pool we want to create 2020-05-29 09:49:30,640 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) (logid:f9ab491a) Checking path of existing pool b9a8ad4a-9032-3db2-ba98-938b891e1af1 against pool we want to create 2020-05-29 09:49:30,648 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) (logid:f9ab491a) Attempting to create storage pool 2258aa76-7813-354d-b274-961fb337e716 2020-05-29 09:49:30,648 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) (logid:f9ab491a) <secret ephemeral='no' private='no'> <uuid>2258aa76-7813-354d-b274-961fb337e716</uuid> <usage type='ceph'> <name>admin@ceph-mon:6789/rbd</name> </usage> </secret> 2020-05-29 09:49:30,688 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) (logid:f9ab491a) <pool type='rbd'> <name>2258aa76-7813-354d-b274-961fb337e716</name> <uuid>2258aa76-7813-354d-b274-961fb337e716</uuid> <source> <host name='ceph-mon' port='6789'/> <name>rbd</name> <auth username='admin' type='ceph'> <secret uuid='2258aa76-7813-354d-b274-961fb337e716'/> </auth> </source> </pool> ~~~ Libvirtd Log : ~~~ https://gist.github.com/ccycv/1cd74f3ea432ed17ee1e260051380107 ~~~ ##### STEPS TO REPRODUCE ~~~ Deploy new VM ~~~ <!-- You can also paste gist.github.com links for larger files --> ##### EXPECTED RESULTS ~~~ No Issue ~~~ ##### ACTUAL RESULTS ~~~ Issue is persisting ~~~ ---------------------------------------------------------------- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. For queries about this service, please contact Infrastructure at: us...@infra.apache.org