Return-Path: X-Original-To: archive-asf-public-internal@cust-asf2.ponee.io Delivered-To: archive-asf-public-internal@cust-asf2.ponee.io Received: from cust-asf.ponee.io (cust-asf.ponee.io [163.172.22.183]) by cust-asf2.ponee.io (Postfix) with ESMTP id 68287200CA7 for ; Wed, 14 Jun 2017 14:05:21 +0200 (CEST) Received: by cust-asf.ponee.io (Postfix) id 66368160BDB; Wed, 14 Jun 2017 12:05:21 +0000 (UTC) Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by cust-asf.ponee.io (Postfix) with SMTP id AB673160BC0 for ; Wed, 14 Jun 2017 14:05:18 +0200 (CEST) Received: (qmail 27971 invoked by uid 500); 14 Jun 2017 12:05:17 -0000 Mailing-List: contact issues-help@cloudstack.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@cloudstack.apache.org Delivered-To: mailing list issues@cloudstack.apache.org Received: (qmail 27962 invoked by uid 500); 14 Jun 2017 12:05:17 -0000 Delivered-To: apmail-incubator-cloudstack-issues@incubator.apache.org Received: (qmail 27959 invoked by uid 99); 14 Jun 2017 12:05:17 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd3-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 14 Jun 2017 12:05:17 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd3-us-west.apache.org (ASF Mail Server at spamd3-us-west.apache.org) with ESMTP id 409111806F7 for ; Wed, 14 Jun 2017 12:05:17 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd3-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: -100.002 X-Spam-Level: X-Spam-Status: No, score=-100.002 tagged_above=-999 required=6.31 tests=[RP_MATCHES_RCVD=-0.001, SPF_PASS=-0.001, USER_IN_WHITELIST=-100] autolearn=disabled Received: from mx1-lw-us.apache.org ([10.40.0.8]) by localhost (spamd3-us-west.apache.org [10.40.0.10]) (amavisd-new, port 10024) with ESMTP id XOkHwQLx8F8B for ; Wed, 14 Jun 2017 12:05:03 +0000 (UTC) Received: from mailrelay1-us-west.apache.org (mailrelay1-us-west.apache.org [209.188.14.139]) by mx1-lw-us.apache.org (ASF Mail Server at mx1-lw-us.apache.org) with ESMTP id 3D7435FE6D for ; Wed, 14 Jun 2017 12:05:02 +0000 (UTC) Received: from jira-lw-us.apache.org (unknown [207.244.88.139]) by mailrelay1-us-west.apache.org (ASF Mail Server at mailrelay1-us-west.apache.org) with ESMTP id 1AB28E070E for ; Wed, 14 Jun 2017 12:05:01 +0000 (UTC) Received: from jira-lw-us.apache.org (localhost [127.0.0.1]) by jira-lw-us.apache.org (ASF Mail Server at jira-lw-us.apache.org) with ESMTP id 1706021D8F for ; Wed, 14 Jun 2017 12:05:00 +0000 (UTC) Date: Wed, 14 Jun 2017 12:05:00 +0000 (UTC) From: "Pavan Kumar Aravapalli (JIRA)" To: cloudstack-issues@incubator.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Created] (CLOUDSTACK-9962) Take VM Snapshot is failing for VM in stopped state, on KVM Hypervisor MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 archived-at: Wed, 14 Jun 2017 12:05:21 -0000 Pavan Kumar Aravapalli created CLOUDSTACK-9962: -------------------------------------------------- Summary: Take VM Snapshot is failing for VM in stopped state, = on KVM Hypervisor Key: CLOUDSTACK-9962 URL: https://issues.apache.org/jira/browse/CLOUDSTACK-9962 Project: CloudStack Issue Type: Bug Security Level: Public (Anyone can view this level - this is the defa= ult.) Components: KVM, Snapshot Affects Versions: 4.10.0.0 Environment: KVM Reporter: Pavan Kumar Aravapalli Steps to reproduce=20 1) launch a VM in KVM Host=20 2) Stop VM 3) Take VM Snapshot=20 Below is MS log for the exception=20 Last login: Wed Jun 14 12:30:54 on ttys000 pavankumar@HSL007960:~/ACP_HOME/cloudstack$ tail -n 500 vm vmops-mar141801.log vmops-mar141945.log vmops-mar141945.log~ = vmops.log vmops.log.2017-03-16.gz vmops.log.2017-05-09 = vmops.log.2017-05-10.gz vmops.log.2017-06-07.gz vmware-base/ pavankumar@HSL007960:~/ACP_HOME/cloudstack$ tail -n 500 vmops.log 2017-06-14 16:11:47,193 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-7:null) (logid:) Ping from 3(localhost.localdomain) 2017-06-14 16:11:47,193 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-7:null) (logid:) Process host VM state report from ping p= rocess. host: 3 2017-06-14 16:11:47,196 INFO [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-7:null) (logid:) Unable to find matched VM in CloudStack = DB. name: i-2-23-VM 2017-06-14 16:11:47,197 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-7:null) (logid:) Process VM state report. host: 3, number= of records in report: 2 2017-06-14 16:11:47,197 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-7:null) (logid:) VM state report. host: 3, vm id: 1, powe= r state: PowerOn 2017-06-14 16:11:47,200 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-7:null) (logid:) VM power state does not change, skip DB = writing. vm id: 1 2017-06-14 16:11:47,200 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-7:null) (logid:) VM state report. host: 3, vm id: 2, powe= r state: PowerOn 2017-06-14 16:11:47,202 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-7:null) (logid:) VM power state does not change, skip DB = writing. vm id: 2 2017-06-14 16:11:47,204 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-7:null) (logid:) Done with process of VM state report. ho= st: 3 2017-06-14 16:11:47,527 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-= 53a2d22e) (logid:7a254200) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:11:48,124 DEBUG [c.c.a.ApiServlet] (qtp752030228-23:ctx-6fb09= 013) (logid:4bab4c97) =3D=3D=3DSTART=3D=3D=3D 127.0.0.1 -- GET command=3D= listZones&id=3D79d64489-e87f-4b3c-8c22-5bededdb8772&response=3Djson&_=3D149= 7436908122 2017-06-14 16:11:48,137 DEBUG [c.c.a.ApiServlet] (qtp752030228-23:ctx-6fb09= 013 ctx-7a97b488) (logid:4bab4c97) =3D=3D=3DEND=3D=3D=3D 127.0.0.1 -- GET = command=3DlistZones&id=3D79d64489-e87f-4b3c-8c22-5bededdb8772&response=3Dj= son&_=3D1497436908122 2017-06-14 16:11:48,143 DEBUG [c.c.a.ApiServlet] (qtp752030228-288:ctx-5882= ef58) (logid:70b3744d) =3D=3D=3DSTART=3D=3D=3D 127.0.0.1 -- GET command= =3DlistVirtualMachines&id=3D59f8d6f5-afa0-4965-8966-4aa45726933c&response= =3Djson&_=3D1497436908141 2017-06-14 16:11:48,180 DEBUG [c.c.a.ApiServlet] (qtp752030228-288:ctx-5882= ef58 ctx-074da5b4) (logid:70b3744d) =3D=3D=3DEND=3D=3D=3D 127.0.0.1 -- GET= command=3DlistVirtualMachines&id=3D59f8d6f5-afa0-4965-8966-4aa45726933c&r= esponse=3Djson&_=3D1497436908141 2017-06-14 16:11:48,534 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-= a25a40cc) (logid:f4ccf4fd) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:11:49,538 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-= 2934a1b6) (logid:a1b6551e) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:11:50,541 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-= 4d861c88) (logid:02bd6aae) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:11:51,546 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-= 86aeb9bc) (logid:ef48c386) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:11:52,549 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-= 0e857587) (logid:03c341fe) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:11:53,554 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 50ef0be7) (logid:d8f9678c) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:11:54,560 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 205bf9ca) (logid:824dd293) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:11:55,429 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-9:null) (logid:) SeqA 4-81743: Processing Seq 4-81743: { Cmd , MgmtId:= -1, via: 4, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadRep= ortCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait= ":0}}] } 2017-06-14 16:11:55,432 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-9:null) (logid:) SeqA 4-81743: Sending Seq 4-81743: { Ans: , MgmtId: 4= 278190080, via: 4, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentCont= rolAnswer":{"result":true,"wait":0}}] } 2017-06-14 16:11:55,563 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 70b6c264) (logid:962286b6) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:11:56,051 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMg= r-Heartbeat-1:ctx-28913b1a) (logid:12baa5e1) Begin cleanup expired async-jo= bs 2017-06-14 16:11:56,055 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMg= r-Heartbeat-1:ctx-28913b1a) (logid:12baa5e1) End cleanup expired async-jobs 2017-06-14 16:11:56,571 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 5a0a0398) (logid:6d6de11d) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:11:57,055 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-20:null) (logid:) Ping from 5(s-2-VM) 2017-06-14 16:11:57,055 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-15:null) (logid:) Ping from 4(v-1-VM) 2017-06-14 16:11:57,311 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-4:null) (logid:) Ping from 3(localhost.localdomain) 2017-06-14 16:11:57,311 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-4:null) (logid:) Process host VM state report from ping p= rocess. host: 3 2017-06-14 16:11:57,314 INFO [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-4:null) (logid:) Unable to find matched VM in CloudStack = DB. name: i-2-23-VM 2017-06-14 16:11:57,315 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-4:null) (logid:) Process VM state report. host: 3, number= of records in report: 2 2017-06-14 16:11:57,315 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-4:null) (logid:) VM state report. host: 3, vm id: 1, powe= r state: PowerOn 2017-06-14 16:11:57,316 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-4:null) (logid:) VM power state does not change, skip DB = writing. vm id: 1 2017-06-14 16:11:57,316 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-4:null) (logid:) VM state report. host: 3, vm id: 2, powe= r state: PowerOn 2017-06-14 16:11:57,317 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-4:null) (logid:) VM power state does not change, skip DB = writing. vm id: 2 2017-06-14 16:11:57,318 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-4:null) (logid:) Done with process of VM state report. ho= st: 3 2017-06-14 16:11:57,575 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 27cf8a13) (logid:6875e80e) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:11:58,165 DEBUG [c.c.s.StorageManagerImpl] (StorageManager-Sc= avenger-2:ctx-3e043f62) (logid:bd3cf9a3) Storage pool garbage collector fou= nd 0 templates to clean up in storage pool: Primary 2017-06-14 16:11:58,168 DEBUG [c.c.s.StorageManagerImpl] (StorageManager-Sc= avenger-2:ctx-3e043f62) (logid:bd3cf9a3) Secondary storage garbage collecto= r found 0 templates to cleanup on template_store_ref for store: Secondary01 2017-06-14 16:11:58,170 DEBUG [c.c.s.StorageManagerImpl] (StorageManager-Sc= avenger-2:ctx-3e043f62) (logid:bd3cf9a3) Secondary storage garbage collecto= r found 0 snapshots to cleanup on snapshot_store_ref for store: Secondary01 2017-06-14 16:11:58,171 DEBUG [c.c.s.StorageManagerImpl] (StorageManager-Sc= avenger-2:ctx-3e043f62) (logid:bd3cf9a3) Secondary storage garbage collecto= r found 0 volumes to cleanup on volume_store_ref for store: Secondary01 2017-06-14 16:11:58,580 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 0beaa3eb) (logid:936b52b6) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:11:59,167 INFO [o.a.c.e.o.NetworkOrchestrator] (Network-Scav= enger-1:ctx-0eedb26d) (logid:035c69db) NetworkGarbageCollector uses '20' se= conds for GC interval. 2017-06-14 16:11:59,170 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Network-Scav= enger-1:ctx-0eedb26d) (logid:035c69db) We found network 205 to be free for = the first time. Adding it to the list: 1497436919 2017-06-14 16:11:59,587 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 03fcebde) (logid:b411c319) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:00,591 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 3af3ccf7) (logid:813d8e4b) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:01,597 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= d893b84d) (logid:5975ad24) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:02,605 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= c773d2c4) (logid:fe3a7d24) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:03,611 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 9e757a68) (logid:d07bf4e8) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:04,615 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 8de3c1cf) (logid:720b1e69) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:05,435 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-2:null) (logid:) SeqA 4-81745: Processing Seq 4-81745: { Cmd , MgmtId:= -1, via: 4, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadRep= ortCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait= ":0}}] } 2017-06-14 16:12:05,438 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-2:null) (logid:) SeqA 4-81745: Sending Seq 4-81745: { Ans: , MgmtId: 4= 278190080, via: 4, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentCont= rolAnswer":{"result":true,"wait":0}}] } 2017-06-14 16:12:05,622 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 8d08f767) (logid:6489067f) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:06,054 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMg= r-Heartbeat-1:ctx-30887c59) (logid:de2a8796) Begin cleanup expired async-jo= bs 2017-06-14 16:12:06,058 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMg= r-Heartbeat-1:ctx-30887c59) (logid:de2a8796) End cleanup expired async-jobs 2017-06-14 16:12:06,166 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] = (RouterStatusMonitor-1:ctx-1d4edaf1) (logid:ad983d97) Found 1 routers to up= date status.=20 2017-06-14 16:12:06,167 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] = (RouterStatusMonitor-1:ctx-1d4edaf1) (logid:ad983d97) Found 0 VPC networks = to update Redundant State.=20 2017-06-14 16:12:06,168 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] = (RouterStatusMonitor-1:ctx-1d4edaf1) (logid:ad983d97) Found 0 networks to u= pdate RvR status.=20 2017-06-14 16:12:06,303 INFO [c.c.u.AccountManagerImpl] (AccountChecker-1:= ctx-5dd40b03) (logid:34e9652e) Found 0 removed accounts to cleanup 2017-06-14 16:12:06,304 INFO [c.c.u.AccountManagerImpl] (AccountChecker-1:= ctx-5dd40b03) (logid:34e9652e) Found 0 disabled accounts to cleanup 2017-06-14 16:12:06,305 INFO [c.c.u.AccountManagerImpl] (AccountChecker-1:= ctx-5dd40b03) (logid:34e9652e) Found 0 inactive domains to cleanup 2017-06-14 16:12:06,306 INFO [c.c.u.AccountManagerImpl] (AccountChecker-1:= ctx-5dd40b03) (logid:34e9652e) Found 0 disabled projects to cleanup 2017-06-14 16:12:06,625 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 43c3d870) (logid:acab161c) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:06,878 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-1:null) (logid:) Ping from 4(v-1-VM) 2017-06-14 16:12:07,045 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-5:null) (logid:) Ping from 5(s-2-VM) 2017-06-14 16:12:07,185 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-14:null) (logid:) Ping from 3(localhost.localdomain) 2017-06-14 16:12:07,185 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-14:null) (logid:) Process host VM state report from ping = process. host: 3 2017-06-14 16:12:07,194 INFO [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-14:null) (logid:) Unable to find matched VM in CloudStack= DB. name: i-2-23-VM 2017-06-14 16:12:07,196 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-14:null) (logid:) Process VM state report. host: 3, numbe= r of records in report: 2 2017-06-14 16:12:07,196 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-14:null) (logid:) VM state report. host: 3, vm id: 1, pow= er state: PowerOn 2017-06-14 16:12:07,198 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-14:null) (logid:) VM power state does not change, skip DB= writing. vm id: 1 2017-06-14 16:12:07,198 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-14:null) (logid:) VM state report. host: 3, vm id: 2, pow= er state: PowerOn 2017-06-14 16:12:07,199 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-14:null) (logid:) VM power state does not change, skip DB= writing. vm id: 2 2017-06-14 16:12:07,201 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-14:null) (logid:) Done with process of VM state report. h= ost: 3 2017-06-14 16:12:07,627 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 8998d76c) (logid:ae4c4ca2) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:08,488 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy= -1:ctx-9d9715b9) (logid:a795f94a) Zone 1 is ready to launch console proxy 2017-06-14 16:12:08,529 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secsto= rage-1:ctx-cbf1e779) (logid:9e6ae55e) Zone 1 is ready to launch secondary s= torage VM 2017-06-14 16:12:08,628 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 379720ea) (logid:be583393) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:09,636 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= d6c9d793) (logid:ac97b101) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:10,285 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-10:null) (logid:) SeqA 4-81747: Processing Seq 4-81747: { Cmd , MgmtId= : -1, via: 4, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadRe= portCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wai= t":0}}] } 2017-06-14 16:12:10,287 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-10:null) (logid:) SeqA 4-81747: Sending Seq 4-81747: { Ans: , MgmtId: = 4278190080, via: 4, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentCon= trolAnswer":{"result":true,"wait":0}}] } 2017-06-14 16:12:10,642 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 034c1431) (logid:b7aef03b) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:11,389 DEBUG [c.c.s.StatsCollector] (StatsCollector-6:ctx-= b0be5653) (logid:585f44cf) StorageCollector is running... 2017-06-14 16:12:11,397 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollecto= r-6:ctx-b0be5653) (logid:585f44cf) getCommandHostDelegation: class com.clou= d.agent.api.GetStorageStatsCommand 2017-06-14 16:12:11,397 DEBUG [c.c.h.XenServerGuru] (StatsCollector-6:ctx-b= 0be5653) (logid:585f44cf) getCommandHostDelegation: class com.cloud.agent.a= pi.GetStorageStatsCommand 2017-06-14 16:12:11,645 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-= 96057699) (logid:ddeebf52) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:12,294 DEBUG [c.c.a.t.Request] (StatsCollector-6:ctx-b0be5= 653) (logid:585f44cf) Seq 5-3742209815368171539: Received: { Ans: , MgmtId= : 4278190080, via: 5(s-2-VM), Ver: v1, Flags: 10, { GetStorageStatsAnswer }= } 2017-06-14 16:12:12,295 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollecto= r-6:ctx-b0be5653) (logid:585f44cf) getCommandHostDelegation: class com.clou= d.agent.api.GetStorageStatsCommand 2017-06-14 16:12:12,295 DEBUG [c.c.h.XenServerGuru] (StatsCollector-6:ctx-b= 0be5653) (logid:585f44cf) getCommandHostDelegation: class com.cloud.agent.a= pi.GetStorageStatsCommand 2017-06-14 16:12:12,648 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-= d8cb39f8) (logid:26512c25) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:13,063 DEBUG [c.c.a.t.Request] (StatsCollector-6:ctx-b0be5= 653) (logid:585f44cf) Seq 3-5718727101830397983: Received: { Ans: , MgmtId= : 4278190080, via: 3(localhost.localdomain), Ver: v1, Flags: 10, { GetStora= geStatsAnswer } } 2017-06-14 16:12:13,654 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-= 0d620f7d) (logid:601a55fa) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:14,659 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-= f35c8bcc) (logid:e775d9e3) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:15,667 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-= 0123d94a) (logid:910cd0bf) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:16,050 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMg= r-Heartbeat-1:ctx-553641ad) (logid:98d5fd4d) Begin cleanup expired async-jo= bs 2017-06-14 16:12:16,056 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMg= r-Heartbeat-1:ctx-553641ad) (logid:98d5fd4d) End cleanup expired async-jobs 2017-06-14 16:12:16,673 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-= b86a4c20) (logid:e8c4a0dd) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:16,967 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-13:null) (logid:) Ping from 4(v-1-VM) 2017-06-14 16:12:17,041 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-3:null) (logid:) Ping from 5(s-2-VM) 2017-06-14 16:12:17,186 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-11:null) (logid:) Ping from 3(localhost.localdomain) 2017-06-14 16:12:17,186 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-11:null) (logid:) Process host VM state report from ping = process. host: 3 2017-06-14 16:12:17,190 INFO [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-11:null) (logid:) Unable to find matched VM in CloudStack= DB. name: i-2-23-VM 2017-06-14 16:12:17,192 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-11:null) (logid:) Process VM state report. host: 3, numbe= r of records in report: 2 2017-06-14 16:12:17,192 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-11:null) (logid:) VM state report. host: 3, vm id: 1, pow= er state: PowerOn 2017-06-14 16:12:17,193 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-11:null) (logid:) VM power state does not change, skip DB= writing. vm id: 1 2017-06-14 16:12:17,194 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-11:null) (logid:) VM state report. host: 3, vm id: 2, pow= er state: PowerOn 2017-06-14 16:12:17,195 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-11:null) (logid:) VM power state does not change, skip DB= writing. vm id: 2 2017-06-14 16:12:17,196 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-11:null) (logid:) Done with process of VM state report. h= ost: 3 2017-06-14 16:12:17,677 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-= 107e6f75) (logid:b3e3a389) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:18,681 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-= 31ef41ba) (logid:cfa03f41) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:19,181 INFO [o.a.c.e.o.NetworkOrchestrator] (Network-Scav= enger-1:ctx-137fa413) (logid:a8693a9b) NetworkGarbageCollector uses '20' se= conds for GC interval. 2017-06-14 16:12:19,189 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Network-Scav= enger-1:ctx-137fa413) (logid:a8693a9b) Network is already shutdown: Ntwk[20= 5|Guest|8] 2017-06-14 16:12:19,685 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-= 82042341) (logid:06643ae8) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:20,310 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-16:null) (logid:) SeqA 4-81749: Processing Seq 4-81749: { Cmd , MgmtId= : -1, via: 4, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadRe= portCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wai= t":0}}] } 2017-06-14 16:12:20,313 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-16:null) (logid:) SeqA 4-81749: Sending Seq 4-81749: { Ans: , MgmtId: = 4278190080, via: 4, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentCon= trolAnswer":{"result":true,"wait":0}}] } 2017-06-14 16:12:20,689 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-= 4c569494) (logid:f8077758) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:21,695 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-= d5ad78ce) (logid:b7861d16) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:22,702 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-= c5d1da8a) (logid:20384afb) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:23,706 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-= d730ca2d) (logid:d21ea199) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:24,711 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-= fb22715d) (logid:c1fa31cb) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:24,830 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= c735678c) (logid:c9db39b1) HostStatsCollector is running... 2017-06-14 16:12:25,546 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-c7356= 78c) (logid:c9db39b1) Seq 3-5718727101830397984: Received: { Ans: , MgmtId= : 4278190080, via: 3(localhost.localdomain), Ver: v1, Flags: 10, { GetHostS= tatsAnswer } } 2017-06-14 16:12:25,716 DEBUG [c.c.s.StatsCollector] (StatsCollector-5:ctx-= b9ddd3d6) (logid:8115a9c5) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:26,050 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMg= r-Heartbeat-1:ctx-f5096ce3) (logid:4a6eb109) Begin cleanup expired async-jo= bs 2017-06-14 16:12:26,054 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMg= r-Heartbeat-1:ctx-f5096ce3) (logid:4a6eb109) End cleanup expired async-jobs 2017-06-14 16:12:26,311 INFO [c.c.u.AccountManagerImpl] (AccountChecker-1:= ctx-202ff4de) (logid:25273d6a) Found 0 removed accounts to cleanup 2017-06-14 16:12:26,313 INFO [c.c.u.AccountManagerImpl] (AccountChecker-1:= ctx-202ff4de) (logid:25273d6a) Found 0 disabled accounts to cleanup 2017-06-14 16:12:26,315 INFO [c.c.u.AccountManagerImpl] (AccountChecker-1:= ctx-202ff4de) (logid:25273d6a) Found 0 inactive domains to cleanup 2017-06-14 16:12:26,317 INFO [c.c.u.AccountManagerImpl] (AccountChecker-1:= ctx-202ff4de) (logid:25273d6a) Found 0 disabled projects to cleanup 2017-06-14 16:12:26,721 DEBUG [c.c.s.StatsCollector] (StatsCollector-5:ctx-= c47a85f0) (logid:d039d010) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:26,890 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-18:null) (logid:) Ping from 4(v-1-VM) 2017-06-14 16:12:27,048 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-17:null) (logid:) Ping from 5(s-2-VM) 2017-06-14 16:12:27,224 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-12:null) (logid:) Ping from 3(localhost.localdomain) 2017-06-14 16:12:27,224 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-12:null) (logid:) Process host VM state report from ping = process. host: 3 2017-06-14 16:12:27,228 INFO [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-12:null) (logid:) Unable to find matched VM in CloudStack= DB. name: i-2-23-VM 2017-06-14 16:12:27,229 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-12:null) (logid:) Process VM state report. host: 3, numbe= r of records in report: 2 2017-06-14 16:12:27,229 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-12:null) (logid:) VM state report. host: 3, vm id: 1, pow= er state: PowerOn 2017-06-14 16:12:27,231 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-12:null) (logid:) VM power state does not change, skip DB= writing. vm id: 1 2017-06-14 16:12:27,231 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-12:null) (logid:) VM state report. host: 3, vm id: 2, pow= er state: PowerOn 2017-06-14 16:12:27,232 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-12:null) (logid:) VM power state does not change, skip DB= writing. vm id: 2 2017-06-14 16:12:27,233 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-12:null) (logid:) Done with process of VM state report. h= ost: 3 2017-06-14 16:12:27,725 DEBUG [c.c.s.StatsCollector] (StatsCollector-5:ctx-= 4d4bd8d8) (logid:05633553) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:28,730 DEBUG [c.c.s.StatsCollector] (StatsCollector-5:ctx-= 1606bf25) (logid:92ded977) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:29,738 DEBUG [c.c.s.StatsCollector] (StatsCollector-5:ctx-= 9434bfbb) (logid:fe427dee) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:30,337 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-7:null) (logid:) SeqA 4-81751: Processing Seq 4-81751: { Cmd , MgmtId:= -1, via: 4, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadRep= ortCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait= ":0}}] } 2017-06-14 16:12:30,342 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-7:null) (logid:) SeqA 4-81751: Sending Seq 4-81751: { Ans: , MgmtId: 4= 278190080, via: 4, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentCont= rolAnswer":{"result":true,"wait":0}}] } 2017-06-14 16:12:30,745 DEBUG [c.c.s.StatsCollector] (StatsCollector-5:ctx-= 2dceb5a0) (logid:adc40bd1) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:31,750 DEBUG [c.c.s.StatsCollector] (StatsCollector-5:ctx-= db04e955) (logid:8eac3002) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:32,751 DEBUG [c.c.s.StatsCollector] (StatsCollector-5:ctx-= a70c1507) (logid:b4dc6f0a) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:33,629 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager = Timer:ctx-5c304e8f) (logid:6c3db43d) Resetting hosts suitable for reconnect 2017-06-14 16:12:33,630 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager = Timer:ctx-5c304e8f) (logid:6c3db43d) Completed resetting hosts suitable for= reconnect 2017-06-14 16:12:33,630 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager = Timer:ctx-5c304e8f) (logid:6c3db43d) Acquiring hosts for clusters already o= wned by this management server 2017-06-14 16:12:33,631 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager = Timer:ctx-5c304e8f) (logid:6c3db43d) Completed acquiring hosts for clusters= already owned by this management server 2017-06-14 16:12:33,631 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager = Timer:ctx-5c304e8f) (logid:6c3db43d) Acquiring hosts for clusters not owned= by any management server 2017-06-14 16:12:33,631 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager = Timer:ctx-5c304e8f) (logid:6c3db43d) Completed acquiring hosts for clusters= not owned by any management server 2017-06-14 16:12:33,752 DEBUG [c.c.s.StatsCollector] (StatsCollector-5:ctx-= 781f1b88) (logid:38b7fec1) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:34,346 DEBUG [c.c.a.ApiServlet] (qtp752030228-25:ctx-dce06= 1e9) (logid:2e697ac3) =3D=3D=3DSTART=3D=3D=3D 127.0.0.1 -- GET command=3D= createVMSnapshot&virtualmachineid=3D59f8d6f5-afa0-4965-8966-4aa45726933c&sn= apshotmemory=3Dfalse&quiescevm=3Dfalse&name=3DVMSnap&description=3DVMsnap&r= esponse=3Djson&_=3D1497436954339 2017-06-14 16:12:34,421 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Execut= or-2:ctx-12b3434b job-75) (logid:79220454) Add job-75 into job monitoring 2017-06-14 16:12:34,425 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (qtp7520302= 28-25:ctx-dce061e9 ctx-1def1999) (logid:2e697ac3) submit async job-75, deta= ils: AsyncJobVO {id:75, userId: 2, accountId: 2, instanceType: None, instan= ceId: 1, cmd: org.apache.cloudstack.api.command.user.vmsnapshot.CreateVMSna= pshotCmd, cmdInfo: {"quiescevm":"false","description":"VMsnap","httpmethod"= :"GET","snapshotmemory":"false","ctxAccountId":"2","cmdEventType":"VMSNAPSH= OT.CREATE","virtualmachineid":"59f8d6f5-afa0-4965-8966-4aa45726933c","respo= nse":"json","ctxUserId":"2","name":"VMSnap","ctxStartEventId":"141","id":"1= ","ctxDetails":"{\"interface com.cloud.vm.VirtualMachine\":\"59f8d6f5-afa0-= 4965-8966-4aa45726933c\"}","_":"1497436954339"}, cmdVersion: 0, status: IN_= PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 42781900= 80, completeMsid: null, lastUpdated: null, lastPolled: null, created: null} 2017-06-14 16:12:34,426 DEBUG [c.c.a.ApiServlet] (qtp752030228-25:ctx-dce06= 1e9 ctx-1def1999) (logid:2e697ac3) =3D=3D=3DEND=3D=3D=3D 127.0.0.1 -- GET = command=3DcreateVMSnapshot&virtualmachineid=3D59f8d6f5-afa0-4965-8966-4aa4= 5726933c&snapshotmemory=3Dfalse&quiescevm=3Dfalse&name=3DVMSnap&description= =3DVMsnap&response=3Djson&_=3D1497436954339 2017-06-14 16:12:34,427 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Ex= ecutor-2:ctx-12b3434b job-75) (logid:24479ad0) Executing AsyncJobVO {id:75,= userId: 2, accountId: 2, instanceType: None, instanceId: 1, cmd: org.apach= e.cloudstack.api.command.user.vmsnapshot.CreateVMSnapshotCmd, cmdInfo: {"qu= iescevm":"false","description":"VMsnap","httpmethod":"GET","snapshotmemory"= :"false","ctxAccountId":"2","cmdEventType":"VMSNAPSHOT.CREATE","virtualmach= ineid":"59f8d6f5-afa0-4965-8966-4aa45726933c","response":"json","ctxUserId"= :"2","name":"VMSnap","ctxStartEventId":"141","id":"1","ctxDetails":"{\"inte= rface com.cloud.vm.VirtualMachine\":\"59f8d6f5-afa0-4965-8966-4aa45726933c\= "}","_":"1497436954339"}, cmdVersion: 0, status: IN_PROGRESS, processStatus= : 0, resultCode: 0, result: null, initMsid: 4278190080, completeMsid: null,= lastUpdated: null, lastPolled: null, created: null} 2017-06-14 16:12:34,488 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Ex= ecutor-2:ctx-12b3434b job-75 ctx-522b12de) (logid:24479ad0) Sync job-76 exe= cution on object VmWorkJobQueue.5 2017-06-14 16:12:34,758 DEBUG [c.c.s.StatsCollector] (StatsCollector-5:ctx-= 9d7dd58b) (logid:de2255d5) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:35,765 DEBUG [c.c.s.StatsCollector] (StatsCollector-5:ctx-= 0331fe52) (logid:9b9ac074) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:36,057 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMg= r-Heartbeat-1:ctx-e2f54b08) (logid:ae5a3a4f) Execute sync-queue item: SyncQ= ueueItemVO {id:1, queueId: 12, contentType: AsyncJob, contentId: 76, lastPr= ocessMsid: 4278190080, lastprocessNumber: 6, lastProcessTime: Wed Jun 14 16= :12:36 IST 2017, created: Wed Jun 14 16:12:34 IST 2017} 2017-06-14 16:12:36,058 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMg= r-Heartbeat-1:ctx-e2f54b08) (logid:ae5a3a4f) Schedule queued job-76 2017-06-14 16:12:36,064 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Execu= tor-1:ctx-8768bad2 job-75/job-76) (logid:7ff5cb42) Add job-76 into job moni= toring 2017-06-14 16:12:36,068 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMg= r-Heartbeat-1:ctx-a576b165) (logid:75cd8bb5) Begin cleanup expired async-jo= bs 2017-06-14 16:12:36,072 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-E= xecutor-1:ctx-8768bad2 job-75/job-76) (logid:24479ad0) Executing AsyncJobVO= {id:76, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd= : com.cloud.vm.snapshot.VmWorkCreateVMSnapshot, cmdInfo: rO0ABXNyACxjb20uY2= xvdWQudm0uc25hcHNob3QuVm1Xb3JrQ3JlYXRlVk1TbmFwc2hvdAG56JeB4A8uAgACWgAJcXVpZ= XNjZVZtTAAMdm1TbmFwc2hvdElkdAAQTGphdmEvbGFuZy9Mb25nO3hyABNjb20uY2xvdWQudm0u= Vm1Xb3Jrn5m2VvAlZ2sCAARKAAlhY2NvdW50SWRKAAZ1c2VySWRKAAR2bUlkTAALaGFuZGxlck5= hbWV0ABJMamF2YS9sYW5nL1N0cmluZzt4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAABXQAFVZNU2= 5hcHNob3RNYW5hZ2VySW1wbABzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVle= HIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAE, cmdVersion: 0, stat= us: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 4= 278190080, completeMsid: null, lastUpdated: null, lastPolled: null, created= : Wed Jun 14 16:12:34 IST 2017} 2017-06-14 16:12:36,082 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMg= r-Heartbeat-1:ctx-a576b165) (logid:75cd8bb5) End cleanup expired async-jobs 2017-06-14 16:12:36,082 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executo= r-1:ctx-8768bad2 job-75/job-76) (logid:24479ad0) Run VM work job: com.cloud= .vm.snapshot.VmWorkCreateVMSnapshot for VM 5, job origin: 75 2017-06-14 16:12:36,086 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Execu= tor-1:ctx-8768bad2 job-75/job-76 ctx-f177563d) (logid:24479ad0) Execute VM = work job: com.cloud.vm.snapshot.VmWorkCreateVMSnapshot{"vmSnapshotId":1,"qu= iesceVm":false,"userId":2,"accountId":2,"vmId":5,"handlerName":"VMSnapshotM= anagerImpl"} 2017-06-14 16:12:36,130 DEBUG [c.c.a.t.Request] (Work-Job-Executor-1:ctx-87= 68bad2 job-75/job-76 ctx-f177563d) (logid:24479ad0) Seq 3-57187271018303979= 85: Sending { Cmd , MgmtId: 4278190080, via: 3(localhost.localdomain), Ver= : v1, Flags: 100011, [{"com.cloud.agent.api.CreateVMSnapshotCommand":{"vmUu= id":"59f8d6f5-afa0-4965-8966-4aa45726933c","volumeTOs":[{"uuid":"e79c4457-4= 360-4804-82e4-7edbff85570d","volumeType":"ROOT","dataStore":{"org.apache.cl= oudstack.storage.to.PrimaryDataStoreTO":{"uuid":"2841def8-9e86-3e56-991c-46= c510e62803","id":1,"poolType":"NetworkFilesystem","host":"10.223.110.232","= path":"/export/home/pavandev/acs/kvm/primary01","port":2049,"url":"NetworkF= ilesystem://10.223.110.232/export/home/pavandev/acs/kvm/primary01/?ROLE=3DP= rimary&STOREUUID=3D2841def8-9e86-3e56-991c-46c510e62803","isManaged":false}= },"name":"ROOT-5","size":8589934592,"path":"e79c4457-4360-4804-82e4-7edbff8= 5570d","volumeId":5,"vmName":"i-2-5-VM","accountId":4,"format":"QCOW2","pro= visioningType":"THIN","id":5,"deviceId":0,"hypervisorType":"KVM"}],"target"= :{"id":1,"snapshotName":"i-2-5-VM_VS_20170614104234","type":"Disk","current= ":false,"description":"VMsnap","quiescevm":false},"vmName":"i-2-5-VM","gues= tOSType":"CentOS 5.5 (64-bit)","platformEmulator":"CentOS 5.5","wait":1800}= }] } 2017-06-14 16:12:36,169 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] = (RouterStatusMonitor-1:ctx-8511104e) (logid:85f413d9) Found 1 routers to up= date status.=20 2017-06-14 16:12:36,171 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] = (RouterStatusMonitor-1:ctx-8511104e) (logid:85f413d9) Found 0 VPC networks = to update Redundant State.=20 2017-06-14 16:12:36,173 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] = (RouterStatusMonitor-1:ctx-8511104e) (logid:85f413d9) Found 0 networks to u= pdate RvR status.=20 2017-06-14 16:12:36,591 DEBUG [c.c.s.StatsCollector] (StatsCollector-1:ctx-= e8f8f19c) (logid:2a92c8f4) AutoScaling Monitor is running... 2017-06-14 16:12:36,771 DEBUG [c.c.s.StatsCollector] (StatsCollector-6:ctx-= 7868a5fc) (logid:e81faf54) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:36,782 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-= ae3fa229) (logid:e437540d) VmStatsCollector is running... 2017-06-14 16:12:36,881 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-9:null) (logid:) Ping from 4(v-1-VM) 2017-06-14 16:12:36,941 DEBUG [c.c.a.t.Request] (AgentManager-Handler-20:nu= ll) (logid:) Seq 3-5718727101830397985: Processing: { Ans: , MgmtId: 42781= 90080, via: 3, Ver: v1, Flags: 10, [{"com.cloud.agent.api.CreateVMSnapshotA= nswer":{"result":false,"details":" Create VM snapshot failed due to org.lib= virt.LibvirtException: Domain not found: no domain with matching name 'i-2-= 5-VM'","wait":0}}] } 2017-06-14 16:12:36,941 DEBUG [c.c.a.t.Request] (Work-Job-Executor-1:ctx-87= 68bad2 job-75/job-76 ctx-f177563d) (logid:24479ad0) Seq 3-57187271018303979= 85: Received: { Ans: , MgmtId: 4278190080, via: 3(localhost.localdomain), = Ver: v1, Flags: 10, { CreateVMSnapshotAnswer } } 2017-06-14 16:12:36,941 ERROR [o.a.c.s.v.DefaultVMSnapshotStrategy] (Work-J= ob-Executor-1:ctx-8768bad2 job-75/job-76 ctx-f177563d) (logid:24479ad0) Cre= ating VM snapshot: i-2-5-VM_VS_20170614104234 failed due to Create VM snap= shot failed due to org.libvirt.LibvirtException: Domain not found: no domai= n with matching name 'i-2-5-VM' 2017-06-14 16:12:36,944 DEBUG [c.c.v.s.VMSnapshotManagerImpl] (Work-Job-Exe= cutor-1:ctx-8768bad2 job-75/job-76 ctx-f177563d) (logid:24479ad0) Failed to= create vm snapshot: 1 com.cloud.utils.exception.CloudRuntimeException: Creating VM snapshot: i-2-= 5-VM_VS_20170614104234 failed due to Create VM snapshot failed due to org.= libvirt.LibvirtException: Domain not found: no domain with matching name 'i= -2-5-VM' =09at org.apache.cloudstack.storage.vmsnapshot.DefaultVMSnapshotStrategy.ta= keVMSnapshot(DefaultVMSnapshotStrategy.java:163) =09at com.cloud.vm.snapshot.VMSnapshotManagerImpl.orchestrateCreateVMSnapsh= ot(VMSnapshotManagerImpl.java:511) =09at com.cloud.vm.snapshot.VMSnapshotManagerImpl.orchestrateCreateVMSnapsh= ot(VMSnapshotManagerImpl.java:1193) =09at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) =09at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.= java:62) =09at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcces= sorImpl.java:43) =09at java.lang.reflect.Method.invoke(Method.java:498) =09at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerPr= oxy.java:107) =09at com.cloud.vm.snapshot.VMSnapshotManagerImpl.handleVmWorkJob(VMSnapsho= tManagerImpl.java:1220) =09at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) =09at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.= java:62) =09at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcces= sorImpl.java:43) =09at java.lang.reflect.Method.invoke(Method.java:498) =09at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflecti= on(AopUtils.java:333) =09at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJo= inpoint(ReflectiveMethodInvocation.java:190) =09at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(= ReflectiveMethodInvocation.java:157) =09at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invok= e(ExposeInvocationInterceptor.java:92) =09at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(= ReflectiveMethodInvocation.java:179) =09at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynami= cAopProxy.java:213) =09at com.sun.proxy.$Proxy227.handleVmWorkJob(Unknown Source) =09at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102) =09at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runIn= Context(AsyncJobManagerImpl.java:558) =09at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(Ma= nagedContextRunnable.java:49) =09at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.ca= ll(DefaultManagedContext.java:56) =09at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.call= WithContext(DefaultManagedContext.java:103) =09at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runW= ithContext(DefaultManagedContext.java:53) =09at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(Mana= gedContextRunnable.java:46) =09at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(A= syncJobManagerImpl.java:506) =09at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:51= 1) =09at java.util.concurrent.FutureTask.run(FutureTask.java:266) =09at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.= java:1142) =09at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor= .java:617) =09at java.lang.Thread.run(Thread.java:745) 2017-06-14 16:12:36,945 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Execu= tor-1:ctx-8768bad2 job-75/job-76 ctx-f177563d) (logid:24479ad0) Invocation = exception, caused by: java.lang.NullPointerException 2017-06-14 16:12:36,945 INFO [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Execu= tor-1:ctx-8768bad2 job-75/job-76 ctx-f177563d) (logid:24479ad0) Rethrow exc= eption java.lang.NullPointerException 2017-06-14 16:12:36,945 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executo= r-1:ctx-8768bad2 job-75/job-76) (logid:24479ad0) Done with run of VM work j= ob: com.cloud.vm.snapshot.VmWorkCreateVMSnapshot for VM 5, job origin: 75 2017-06-14 16:12:36,946 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executo= r-1:ctx-8768bad2 job-75/job-76) (logid:24479ad0) Unable to complete AsyncJo= bVO {id:76, userId: 2, accountId: 2, instanceType: null, instanceId: null, = cmd: com.cloud.vm.snapshot.VmWorkCreateVMSnapshot, cmdInfo: rO0ABXNyACxjb20= uY2xvdWQudm0uc25hcHNob3QuVm1Xb3JrQ3JlYXRlVk1TbmFwc2hvdAG56JeB4A8uAgACWgAJcX= VpZXNjZVZtTAAMdm1TbmFwc2hvdElkdAAQTGphdmEvbGFuZy9Mb25nO3hyABNjb20uY2xvdWQud= m0uVm1Xb3Jrn5m2VvAlZ2sCAARKAAlhY2NvdW50SWRKAAZ1c2VySWRKAAR2bUlkTAALaGFuZGxl= ck5hbWV0ABJMamF2YS9sYW5nL1N0cmluZzt4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAABXQAFVZ= NU25hcHNob3RNYW5hZ2VySW1wbABzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbH= VleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAE, cmdVersion: 0, s= tatus: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid= : 4278190080, completeMsid: null, lastUpdated: null, lastPolled: null, crea= ted: Wed Jun 14 16:12:34 IST 2017}, job origin:75 java.lang.NullPointerException =09at com.cloud.vm.snapshot.VMSnapshotManagerImpl.orchestrateCreateVMSnapsh= ot(VMSnapshotManagerImpl.java:1195) =09at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) =09at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.= java:62) =09at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcces= sorImpl.java:43) =09at java.lang.reflect.Method.invoke(Method.java:498) =09at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerPr= oxy.java:107) =09at com.cloud.vm.snapshot.VMSnapshotManagerImpl.handleVmWorkJob(VMSnapsho= tManagerImpl.java:1220) =09at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) =09at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.= java:62) =09at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcces= sorImpl.java:43) =09at java.lang.reflect.Method.invoke(Method.java:498) =09at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflecti= on(AopUtils.java:333) =09at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJo= inpoint(ReflectiveMethodInvocation.java:190) =09at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(= ReflectiveMethodInvocation.java:157) =09at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invok= e(ExposeInvocationInterceptor.java:92) =09at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(= ReflectiveMethodInvocation.java:179) =09at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynami= cAopProxy.java:213) =09at com.sun.proxy.$Proxy227.handleVmWorkJob(Unknown Source) =09at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102) =09at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runIn= Context(AsyncJobManagerImpl.java:558) =09at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(Ma= nagedContextRunnable.java:49) =09at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.ca= ll(DefaultManagedContext.java:56) =09at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.call= WithContext(DefaultManagedContext.java:103) =09at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runW= ithContext(DefaultManagedContext.java:53) =09at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(Mana= gedContextRunnable.java:46) =09at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(A= syncJobManagerImpl.java:506) =09at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:51= 1) =09at java.util.concurrent.FutureTask.run(FutureTask.java:266) =09at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.= java:1142) =09at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor= .java:617) =09at java.lang.Thread.run(Thread.java:745) 2017-06-14 16:12:36,958 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-E= xecutor-1:ctx-8768bad2 job-75/job-76) (logid:24479ad0) Complete async job-7= 6, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyAB5qYXZhLmxhbmcuTnVsbF= BvaW50ZXJFeGNlcHRpb25HpaGO_zHhuAIAAHhyABpqYXZhLmxhbmcuUnVudGltZUV4Y2VwdGlvb= p5fBkcKNIPlAgAAeHIAE2phdmEubGFuZy5FeGNlcHRpb27Q_R8-GjscxAIAAHhyABNqYXZhLmxh= bmcuVGhyb3dhYmxl1cY1Jzl3uMsDAARMAAVjYXVzZXQAFUxqYXZhL2xhbmcvVGhyb3dhYmxlO0w= ADWRldGFpbE1lc3NhZ2V0ABJMamF2YS9sYW5nL1N0cmluZztbAApzdGFja1RyYWNldAAeW0xqYX= ZhL2xhbmcvU3RhY2tUcmFjZUVsZW1lbnQ7TAAUc3VwcHJlc3NlZEV4Y2VwdGlvbnN0ABBMamF2Y= S91dGlsL0xpc3Q7eHBxAH4ACHB1cgAeW0xqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnQ7AkYq= PDz9IjkCAAB4cAAAAB9zcgAbamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50YQnFmiY23YUCAAR= JAApsaW5lTnVtYmVyTAAOZGVjbGFyaW5nQ2xhc3NxAH4ABUwACGZpbGVOYW1lcQB-AAVMAAptZX= Rob2ROYW1lcQB-AAV4cAAABKt0ACtjb20uY2xvdWQudm0uc25hcHNob3QuVk1TbmFwc2hvdE1hb= mFnZXJJbXBsdAAaVk1TbmFwc2hvdE1hbmFnZXJJbXBsLmphdmF0ABtvcmNoZXN0cmF0ZUNyZWF0= ZVZNU25hcHNob3RzcQB-AAv____-dAAkc3VuLnJlZmxlY3QuTmF0aXZlTWV0aG9kQWNjZXNzb3J= JbXBsdAAdTmF0aXZlTWV0aG9kQWNjZXNzb3JJbXBsLmphdmF0AAdpbnZva2Uwc3EAfgALAAAAPn= EAfgARcQB-ABJ0AAZpbnZva2VzcQB-AAsAAAArdAAoc3VuLnJlZmxlY3QuRGVsZWdhdGluZ01ld= GhvZEFjY2Vzc29ySW1wbHQAIURlbGVnYXRpbmdNZXRob2RBY2Nlc3NvckltcGwuamF2YXEAfgAV= c3EAfgALAAAB8nQAGGphdmEubGFuZy5yZWZsZWN0Lk1ldGhvZHQAC01ldGhvZC5qYXZhcQB-ABV= zcQB-AAsAAABrdAAiY29tLmNsb3VkLnZtLlZtV29ya0pvYkhhbmRsZXJQcm94eXQAGlZtV29ya0= pvYkhhbmRsZXJQcm94eS5qYXZhdAAPaGFuZGxlVm1Xb3JrSm9ic3EAfgALAAAExHEAfgANcQB-A= A5xAH4AH3NxAH4AC_____5xAH4AEXEAfgAScQB-ABNzcQB-AAsAAAA-cQB-ABFxAH4AEnEAfgAV= c3EAfgALAAAAK3EAfgAXcQB-ABhxAH4AFXNxAH4ACwAAAfJxAH4AGnEAfgAbcQB-ABVzcQB-AAs= AAAFNdAAob3JnLnNwcmluZ2ZyYW1ld29yay5hb3Auc3VwcG9ydC5Bb3BVdGlsc3QADUFvcFV0aW= xzLmphdmF0AB5pbnZva2VKb2lucG9pbnRVc2luZ1JlZmxlY3Rpb25zcQB-AAsAAAC-dAA8b3JnL= nNwcmluZ2ZyYW1ld29yay5hb3AuZnJhbWV3b3JrLlJlZmxlY3RpdmVNZXRob2RJbnZvY2F0aW9u= dAAfUmVmbGVjdGl2ZU1ldGhvZEludm9jYXRpb24uamF2YXQAD2ludm9rZUpvaW5wb2ludHNxAH4= ACwAAAJ1xAH4AKnEAfgArdAAHcHJvY2VlZHNxAH4ACwAAAFx0AD9vcmcuc3ByaW5nZnJhbWV3b3= JrLmFvcC5pbnRlcmNlcHRvci5FeHBvc2VJbnZvY2F0aW9uSW50ZXJjZXB0b3J0ACBFeHBvc2VJb= nZvY2F0aW9uSW50ZXJjZXB0b3IuamF2YXEAfgAVc3EAfgALAAAAs3EAfgAqcQB-ACtxAH4ALnNx= AH4ACwAAANV0ADRvcmcuc3ByaW5nZnJhbWV3b3JrLmFvcC5mcmFtZXdvcmsuSmRrRHluYW1pY0F= vcFByb3h5dAAXSmRrRHluYW1pY0FvcFByb3h5LmphdmFxAH4AFXNxAH4AC_____90ABdjb20uc3= VuLnByb3h5LiRQcm94eTIyN3BxAH4AH3NxAH4ACwAAAGZ0ACBjb20uY2xvdWQudm0uVm1Xb3JrS= m9iRGlzcGF0Y2hlcnQAGFZtV29ya0pvYkRpc3BhdGNoZXIuamF2YXQABnJ1bkpvYnNxAH4ACwAA= Ai50AD9vcmcuYXBhY2hlLmNsb3Vkc3RhY2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1= hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0AAxydW5JbkNvbnRleHRzcQ= B-AAsAAAAxdAA-b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ= 29udGV4dFJ1bm5hYmxlJDF0ABtNYW5hZ2VkQ29udGV4dFJ1bm5hYmxlLmphdmF0AANydW5zcQB-= AAsAAAA4dABCb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF= 1bHRNYW5hZ2VkQ29udGV4dCQxdAAaRGVmYXVsdE1hbmFnZWRDb250ZXh0LmphdmF0AARjYWxsc3= EAfgALAAAAZ3QAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZ= WZhdWx0TWFuYWdlZENvbnRleHRxAH4ARnQAD2NhbGxXaXRoQ29udGV4dHNxAH4ACwAAADVxAH4A= SXEAfgBGdAAOcnVuV2l0aENvbnRleHRzcQB-AAsAAAAudAA8b3JnLmFwYWNoZS5jbG91ZHN0YWN= rLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlcQB-AEJxAH4AQ3NxAH4ACw= AAAfpxAH4APXEAfgA-cQB-AENzcQB-AAsAAAH_dAAuamF2YS51dGlsLmNvbmN1cnJlbnQuRXhlY= 3V0b3JzJFJ1bm5hYmxlQWRhcHRlcnQADkV4ZWN1dG9ycy5qYXZhcQB-AEdzcQB-AAsAAAEKdAAf= amF2YS51dGlsLmNvbmN1cnJlbnQuRnV0dXJlVGFza3QAD0Z1dHVyZVRhc2suamF2YXEAfgBDc3E= AfgALAAAEdnQAJ2phdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvcnQAF1Rocm= VhZFBvb2xFeGVjdXRvci5qYXZhdAAJcnVuV29ya2Vyc3EAfgALAAACaXQALmphdmEudXRpbC5jb= 25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvciRXb3JrZXJxAH4AWHEAfgBDc3EAfgALAAAC6XQA= EGphdmEubGFuZy5UaHJlYWR0AAtUaHJlYWQuamF2YXEAfgBDc3IAJmphdmEudXRpbC5Db2xsZWN= 0aW9ucyRVbm1vZGlmaWFibGVMaXN0_A8lMbXsjhACAAFMAARsaXN0cQB-AAd4cgAsamF2YS51dG= lsLkNvbGxlY3Rpb25zJFVubW9kaWZpYWJsZUNvbGxlY3Rpb24ZQgCAy173HgIAAUwAAWN0ABZMa= mF2YS91dGlsL0NvbGxlY3Rpb247eHBzcgATamF2YS51dGlsLkFycmF5TGlzdHiB0h2Zx2GdAwAB= SQAEc2l6ZXhwAAAAAHcEAAAAAHhxAH4AZHg 2017-06-14 16:12:36,960 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-E= xecutor-1:ctx-8768bad2 job-75/job-76) (logid:24479ad0) Publish async job-76= complete on message bus 2017-06-14 16:12:36,960 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-E= xecutor-1:ctx-8768bad2 job-75/job-76) (logid:24479ad0) Wake up jobs related= to job-76 2017-06-14 16:12:36,960 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-E= xecutor-1:ctx-8768bad2 job-75/job-76) (logid:24479ad0) Update db status for= job-76 2017-06-14 16:12:36,961 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-E= xecutor-1:ctx-8768bad2 job-75/job-76) (logid:24479ad0) Wake up jobs joined = with job-76 and disjoin all subjobs created from job- 76 2017-06-14 16:12:36,969 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-E= xecutor-1:ctx-8768bad2 job-75/job-76) (logid:24479ad0) Done executing com.c= loud.vm.snapshot.VmWorkCreateVMSnapshot for job-76 2017-06-14 16:12:36,970 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Execu= tor-1:ctx-8768bad2 job-75/job-76) (logid:24479ad0) Remove job-76 from job m= onitoring 2017-06-14 16:12:36,984 ERROR [c.c.a.ApiAsyncJobDispatcher] (API-Job-Execut= or-2:ctx-12b3434b job-75) (logid:24479ad0) Unexpected exception while execu= ting org.apache.cloudstack.api.command.user.vmsnapshot.CreateVMSnapshotCmd java.lang.RuntimeException: Unexpected exception =09at com.cloud.vm.snapshot.VMSnapshotManagerImpl.createVMSnapshot(VMSnapsh= otManagerImpl.java:479) =09at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) =09at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.= java:62) =09at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcces= sorImpl.java:43) =09at java.lang.reflect.Method.invoke(Method.java:498) =09at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflecti= on(AopUtils.java:333) =09at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJo= inpoint(ReflectiveMethodInvocation.java:190) =09at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(= ReflectiveMethodInvocation.java:157) =09at org.apache.cloudstack.network.contrail.management.EventUtils$EventInt= erceptor.invoke(EventUtils.java:107) =09at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(= ReflectiveMethodInvocation.java:168) =09at com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.= java:51) =09at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(= ReflectiveMethodInvocation.java:168) =09at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invok= e(ExposeInvocationInterceptor.java:92) =09at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(= ReflectiveMethodInvocation.java:179) =09at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynami= cAopProxy.java:213) =09at com.sun.proxy.$Proxy227.createVMSnapshot(Unknown Source) =09at org.apache.cloudstack.api.command.user.vmsnapshot.CreateVMSnapshotCmd= .execute(CreateVMSnapshotCmd.java:113) =09at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:150) =09at com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java= :108) =09at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runIn= Context(AsyncJobManagerImpl.java:558) =09at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(Ma= nagedContextRunnable.java:49) =09at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.ca= ll(DefaultManagedContext.java:56) =09at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.call= WithContext(DefaultManagedContext.java:103) =09at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runW= ithContext(DefaultManagedContext.java:53) =09at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(Mana= gedContextRunnable.java:46) =09at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(A= syncJobManagerImpl.java:506) =09at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:51= 1) =09at java.util.concurrent.FutureTask.run(FutureTask.java:266) =09at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.= java:1142) =09at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor= .java:617) =09at java.lang.Thread.run(Thread.java:745) Caused by: java.lang.NullPointerException =09at com.cloud.vm.snapshot.VMSnapshotManagerImpl.orchestrateCreateVMSnapsh= ot(VMSnapshotManagerImpl.java:1195) =09at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) =09at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.= java:62) =09... 28 more 2017-06-14 16:12:36,986 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Ex= ecutor-2:ctx-12b3434b job-75) (logid:24479ad0) Complete async job-75, jobSt= atus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.E= xceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Unexpecte= d exception"} 2017-06-14 16:12:36,988 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Ex= ecutor-2:ctx-12b3434b job-75) (logid:24479ad0) Publish async job-75 complet= e on message bus 2017-06-14 16:12:36,988 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Ex= ecutor-2:ctx-12b3434b job-75) (logid:24479ad0) Wake up jobs related to job-= 75 2017-06-14 16:12:36,988 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Ex= ecutor-2:ctx-12b3434b job-75) (logid:24479ad0) Update db status for job-75 2017-06-14 16:12:36,990 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Ex= ecutor-2:ctx-12b3434b job-75) (logid:24479ad0) Wake up jobs joined with job= -75 and disjoin all subjobs created from job- 75 2017-06-14 16:12:36,993 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Ex= ecutor-2:ctx-12b3434b job-75) (logid:24479ad0) Done executing org.apache.cl= oudstack.api.command.user.vmsnapshot.CreateVMSnapshotCmd for job-75 2017-06-14 16:12:36,994 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Execut= or-2:ctx-12b3434b job-75) (logid:24479ad0) Remove job-75 from job monitorin= g 2017-06-14 16:12:37,041 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-15:null) (logid:) Ping from 5(s-2-VM) 2017-06-14 16:12:37,173 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-4:null) (logid:) Ping from 3(localhost.localdomain) 2017-06-14 16:12:37,173 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-4:null) (logid:) Process host VM state report from ping p= rocess. host: 3 2017-06-14 16:12:37,177 INFO [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-4:null) (logid:) Unable to find matched VM in CloudStack = DB. name: i-2-23-VM 2017-06-14 16:12:37,179 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-4:null) (logid:) Process VM state report. host: 3, number= of records in report: 2 2017-06-14 16:12:37,179 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-4:null) (logid:) VM state report. host: 3, vm id: 1, powe= r state: PowerOn 2017-06-14 16:12:37,181 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-4:null) (logid:) VM power state does not change, skip DB = writing. vm id: 1 2017-06-14 16:12:37,181 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-4:null) (logid:) VM state report. host: 3, vm id: 2, powe= r state: PowerOn 2017-06-14 16:12:37,182 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-4:null) (logid:) VM power state does not change, skip DB = writing. vm id: 2 2017-06-14 16:12:37,183 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-4:null) (logid:) Done with process of VM state report. ho= st: 3 2017-06-14 16:12:37,453 DEBUG [c.c.a.ApiServlet] (qtp752030228-289:ctx-169f= 367e) (logid:7c88bb8b) =3D=3D=3DSTART=3D=3D=3D 127.0.0.1 -- GET command= =3DqueryAsyncJobResult&jobId=3D24479ad0-5286-4f69-8566-5e113e2b0230&respons= e=3Djson&_=3D1497436957447 2017-06-14 16:12:37,471 DEBUG [c.c.a.ApiServlet] (qtp752030228-289:ctx-169f= 367e ctx-c458c183) (logid:7c88bb8b) =3D=3D=3DEND=3D=3D=3D 127.0.0.1 -- GET= command=3DqueryAsyncJobResult&jobId=3D24479ad0-5286-4f69-8566-5e113e2b023= 0&response=3Djson&_=3D1497436957447 2017-06-14 16:12:37,773 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= e99964be) (logid:79e9d09d) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:38,188 DEBUG [c.c.s.StorageManagerImpl] (StorageManager-Sc= avenger-2:ctx-073f359c) (logid:df5991dc) Storage pool garbage collector fou= nd 0 templates to clean up in storage pool: Primary 2017-06-14 16:12:38,191 DEBUG [c.c.s.StorageManagerImpl] (StorageManager-Sc= avenger-2:ctx-073f359c) (logid:df5991dc) Secondary storage garbage collecto= r found 0 templates to cleanup on template_store_ref for store: Secondary01 2017-06-14 16:12:38,192 DEBUG [c.c.s.StorageManagerImpl] (StorageManager-Sc= avenger-2:ctx-073f359c) (logid:df5991dc) Secondary storage garbage collecto= r found 0 snapshots to cleanup on snapshot_store_ref for store: Secondary01 2017-06-14 16:12:38,192 DEBUG [c.c.s.StorageManagerImpl] (StorageManager-Sc= avenger-2:ctx-073f359c) (logid:df5991dc) Secondary storage garbage collecto= r found 0 volumes to cleanup on volume_store_ref for store: Secondary01 2017-06-14 16:12:38,489 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy= -1:ctx-32c0b081) (logid:6bc75ea0) Zone 1 is ready to launch console proxy 2017-06-14 16:12:38,534 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secsto= rage-1:ctx-075ec500) (logid:f0a89d6d) Zone 1 is ready to launch secondary s= torage VM 2017-06-14 16:12:38,778 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= fbf96fb7) (logid:bc00e2d9) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:39,196 INFO [o.a.c.e.o.NetworkOrchestrator] (Network-Scav= enger-1:ctx-f59b219a) (logid:e42ade1f) NetworkGarbageCollector uses '20' se= conds for GC interval. 2017-06-14 16:12:39,201 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Network-Scav= enger-1:ctx-f59b219a) (logid:e42ade1f) We found network 205 to be free for = the first time. Adding it to the list: 1497436959 2017-06-14 16:12:39,785 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 65f87af1) (logid:15a41c88) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:40,445 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-2:null) (logid:) SeqA 4-81753: Processing Seq 4-81753: { Cmd , MgmtId:= -1, via: 4, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadRep= ortCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait= ":0}}] } 2017-06-14 16:12:40,449 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-2:null) (logid:) SeqA 4-81753: Sending Seq 4-81753: { Ans: , MgmtId: 4= 278190080, via: 4, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentCont= rolAnswer":{"result":true,"wait":0}}] } 2017-06-14 16:12:40,792 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 019f3056) (logid:8921db90) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:41,799 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 96506e08) (logid:ab9dff42) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:42,802 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 6be0ecad) (logid:5fe2297e) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:43,806 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= a0a674b3) (logid:0fe05e76) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:44,814 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 6e530ed5) (logid:da67969a) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:45,354 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-1:null) (logid:) SeqA 4-81754: Processing Seq 4-81754: { Cmd , MgmtId:= -1, via: 4, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadRep= ortCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait= ":0}}] } 2017-06-14 16:12:45,356 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-1:null) (logid:) SeqA 4-81754: Sending Seq 4-81754: { Ans: , MgmtId: 4= 278190080, via: 4, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentCont= rolAnswer":{"result":true,"wait":0}}] } 2017-06-14 16:12:45,818 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 462d8d0a) (logid:2597abdc) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:46,046 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMg= r-Heartbeat-1:ctx-9772b804) (logid:89c6cee5) Begin cleanup expired async-jo= bs 2017-06-14 16:12:46,052 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMg= r-Heartbeat-1:ctx-9772b804) (logid:89c6cee5) End cleanup expired async-jobs 2017-06-14 16:12:46,307 INFO [c.c.u.AccountManagerImpl] (AccountChecker-1:= ctx-7600f192) (logid:af984f73) Found 0 removed accounts to cleanup 2017-06-14 16:12:46,308 INFO [c.c.u.AccountManagerImpl] (AccountChecker-1:= ctx-7600f192) (logid:af984f73) Found 0 disabled accounts to cleanup 2017-06-14 16:12:46,310 INFO [c.c.u.AccountManagerImpl] (AccountChecker-1:= ctx-7600f192) (logid:af984f73) Found 0 inactive domains to cleanup 2017-06-14 16:12:46,311 INFO [c.c.u.AccountManagerImpl] (AccountChecker-1:= ctx-7600f192) (logid:af984f73) Found 0 disabled projects to cleanup 2017-06-14 16:12:46,820 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 43287fd8) (logid:dfd90d08) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:46,942 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-5:null) (logid:) Ping from 4(v-1-VM) 2017-06-14 16:12:47,049 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-14:null) (logid:) Ping from 5(s-2-VM) 2017-06-14 16:12:47,184 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-10:null) (logid:) Ping from 3(localhost.localdomain) 2017-06-14 16:12:47,184 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-10:null) (logid:) Process host VM state report from ping = process. host: 3 2017-06-14 16:12:47,188 INFO [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-10:null) (logid:) Unable to find matched VM in CloudStack= DB. name: i-2-23-VM 2017-06-14 16:12:47,190 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-10:null) (logid:) Process VM state report. host: 3, numbe= r of records in report: 2 2017-06-14 16:12:47,190 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-10:null) (logid:) VM state report. host: 3, vm id: 1, pow= er state: PowerOn 2017-06-14 16:12:47,191 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-10:null) (logid:) VM power state does not change, skip DB= writing. vm id: 1 2017-06-14 16:12:47,191 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-10:null) (logid:) VM state report. host: 3, vm id: 2, pow= er state: PowerOn 2017-06-14 16:12:47,193 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-10:null) (logid:) VM power state does not change, skip DB= writing. vm id: 2 2017-06-14 16:12:47,195 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-10:null) (logid:) Done with process of VM state report. h= ost: 3 2017-06-14 16:12:47,824 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 2a28e1e9) (logid:570f3bcf) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:48,831 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= f4511774) (logid:8d33f667) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:49,838 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 308a1018) (logid:0f6cf156) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:50,841 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 9b461d18) (logid:61801806) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:51,843 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= cd8023ee) (logid:9671975e) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:52,851 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= ea69f749) (logid:379983a0) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:53,855 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 18e055ea) (logid:27353426) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:54,858 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= b14d188d) (logid:e4e27ec7) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:55,290 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-8:null) (logid:) SeqA 4-81756: Processing Seq 4-81756: { Cmd , MgmtId:= -1, via: 4, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadRep= ortCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait= ":0}}] } 2017-06-14 16:12:55,292 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-8:null) (logid:) SeqA 4-81756: Sending Seq 4-81756: { Ans: , MgmtId: 4= 278190080, via: 4, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentCont= rolAnswer":{"result":true,"wait":0}}] } 2017-06-14 16:12:55,863 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 114c9900) (logid:089e81c3) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:56,051 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMg= r-Heartbeat-1:ctx-5b1c0bde) (logid:6a6fd84f) Begin cleanup expired async-jo= bs 2017-06-14 16:12:56,055 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMg= r-Heartbeat-1:ctx-5b1c0bde) (logid:6a6fd84f) End cleanup expired async-jobs 2017-06-14 16:12:56,869 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= e7cf5d61) (logid:397bc273) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:56,873 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-6:null) (logid:) Ping from 4(v-1-VM) 2017-06-14 16:12:57,039 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-13:null) (logid:) Ping from 5(s-2-VM) 2017-06-14 16:12:57,207 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-3:null) (logid:) Ping from 3(localhost.localdomain) 2017-06-14 16:12:57,207 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-3:null) (logid:) Process host VM state report from ping p= rocess. host: 3 2017-06-14 16:12:57,212 INFO [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-3:null) (logid:) Unable to find matched VM in CloudStack = DB. name: i-2-23-VM 2017-06-14 16:12:57,213 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-3:null) (logid:) Process VM state report. host: 3, number= of records in report: 2 2017-06-14 16:12:57,213 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-3:null) (logid:) VM state report. host: 3, vm id: 1, powe= r state: PowerOn 2017-06-14 16:12:57,215 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-3:null) (logid:) VM power state does not change, skip DB = writing. vm id: 1 2017-06-14 16:12:57,215 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-3:null) (logid:) VM state report. host: 3, vm id: 2, powe= r state: PowerOn 2017-06-14 16:12:57,216 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-3:null) (logid:) VM power state does not change, skip DB = writing. vm id: 2 2017-06-14 16:12:57,217 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-3:null) (logid:) Done with process of VM state report. ho= st: 3 2017-06-14 16:12:57,872 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= b27772ce) (logid:f596c81d) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:58,879 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= f3d13567) (logid:10d13171) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:12:59,210 INFO [o.a.c.e.o.NetworkOrchestrator] (Network-Scav= enger-1:ctx-fb5bbe09) (logid:6997571a) NetworkGarbageCollector uses '20' se= conds for GC interval. 2017-06-14 16:12:59,221 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Network-Scav= enger-1:ctx-fb5bbe09) (logid:6997571a) Network is already shutdown: Ntwk[20= 5|Guest|8] 2017-06-14 16:12:59,883 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 5c9f8a91) (logid:611b94f3) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:13:00,311 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-11:null) (logid:) SeqA 4-81758: Processing Seq 4-81758: { Cmd , MgmtId= : -1, via: 4, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadRe= portCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wai= t":0}}] } 2017-06-14 16:13:00,316 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-11:null) (logid:) SeqA 4-81758: Sending Seq 4-81758: { Ans: , MgmtId: = 4278190080, via: 4, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentCon= trolAnswer":{"result":true,"wait":0}}] } 2017-06-14 16:13:00,887 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= ff01d3a5) (logid:6dc568ea) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:13:01,890 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= f8d69e98) (logid:71901fb3) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:13:02,895 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= eff0654d) (logid:6a27a647) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:13:03,900 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 5443f4c0) (logid:d496109e) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:13:04,903 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 7f429c5f) (logid:957c8b64) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:13:05,908 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 924f2953) (logid:228be278) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:13:06,047 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMg= r-Heartbeat-1:ctx-327fcbbf) (logid:7d15f769) Begin cleanup expired async-jo= bs 2017-06-14 16:13:06,053 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMg= r-Heartbeat-1:ctx-327fcbbf) (logid:7d15f769) End cleanup expired async-jobs 2017-06-14 16:13:06,069 DEBUG [c.c.n.ExternalDeviceUsageManagerImpl] (Exter= nalNetworkMonitor-1:ctx-59b686ef) (logid:0f54b1ee) External devices are not= used. Skipping external device usage collection 2017-06-14 16:13:06,161 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] = (RouterMonitor-1:ctx-a05e1f3e) (logid:9248a263) Found 0 running routers.=20 2017-06-14 16:13:06,162 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] = (RouterStatusMonitor-1:ctx-0e4c7eb7) (logid:1ecf5950) Found 1 routers to up= date status.=20 2017-06-14 16:13:06,163 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] = (RouterStatusMonitor-1:ctx-0e4c7eb7) (logid:1ecf5950) Found 0 VPC networks = to update Redundant State.=20 2017-06-14 16:13:06,164 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] = (RouterStatusMonitor-1:ctx-0e4c7eb7) (logid:1ecf5950) Found 0 networks to u= pdate RvR status.=20 2017-06-14 16:13:06,311 INFO [c.c.u.AccountManagerImpl] (AccountChecker-1:= ctx-14326169) (logid:8e75d2e3) Found 0 removed accounts to cleanup 2017-06-14 16:13:06,313 INFO [c.c.u.AccountManagerImpl] (AccountChecker-1:= ctx-14326169) (logid:8e75d2e3) Found 0 disabled accounts to cleanup 2017-06-14 16:13:06,315 INFO [c.c.u.AccountManagerImpl] (AccountChecker-1:= ctx-14326169) (logid:8e75d2e3) Found 0 inactive domains to cleanup 2017-06-14 16:13:06,316 INFO [c.c.u.AccountManagerImpl] (AccountChecker-1:= ctx-14326169) (logid:8e75d2e3) Found 0 disabled projects to cleanup 2017-06-14 16:13:06,912 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 8f87a697) (logid:90db1973) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:13:07,008 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-16:null) (logid:) Ping from 4(v-1-VM) 2017-06-14 16:13:07,183 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-19:null) (logid:) Ping from 5(s-2-VM) 2017-06-14 16:13:07,242 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Hand= ler-18:null) (logid:) Ping from 3(localhost.localdomain) 2017-06-14 16:13:07,243 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-18:null) (logid:) Process host VM state report from ping = process. host: 3 2017-06-14 16:13:07,245 INFO [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-18:null) (logid:) Unable to find matched VM in CloudStack= DB. name: i-2-23-VM 2017-06-14 16:13:07,247 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-18:null) (logid:) Process VM state report. host: 3, numbe= r of records in report: 2 2017-06-14 16:13:07,247 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-18:null) (logid:) VM state report. host: 3, vm id: 1, pow= er state: PowerOn 2017-06-14 16:13:07,249 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-18:null) (logid:) VM power state does not change, skip DB= writing. vm id: 1 2017-06-14 16:13:07,249 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-18:null) (logid:) VM state report. host: 3, vm id: 2, pow= er state: PowerOn 2017-06-14 16:13:07,251 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-18:null) (logid:) VM power state does not change, skip DB= writing. vm id: 2 2017-06-14 16:13:07,252 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (Age= ntManager-Handler-18:null) (logid:) Done with process of VM state report. h= ost: 3 2017-06-14 16:13:07,914 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 8e5194eb) (logid:4fd65b6d) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:13:08,490 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy= -1:ctx-c5cf0859) (logid:2108e5dd) Zone 1 is ready to launch console proxy 2017-06-14 16:13:08,531 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secsto= rage-1:ctx-18247b6a) (logid:6b5bfee9) Zone 1 is ready to launch secondary s= torage VM 2017-06-14 16:13:08,834 INFO [c.c.a.m.AgentManagerImpl] (AgentMonitor-1:ct= x-b6c685ed) (logid:2002cffe) Found the following agents behind on ping: [3,= 4, 5] 2017-06-14 16:13:08,837 DEBUG [c.c.h.Status] (AgentMonitor-1:ctx-b6c685ed) = (logid:2002cffe) Ping timeout for agent 3, do invstigation 2017-06-14 16:13:08,838 WARN [c.c.a.m.AgentManagerImpl] (AgentMonitor-1:ct= x-b6c685ed) (logid:2002cffe) Disconnect agent for CPVM/SSVM due to physical= connection close. host: 4 2017-06-14 16:13:08,839 INFO [c.c.a.m.AgentManagerImpl] (AgentTaskPool-3:c= tx-d46f2f55) (logid:22aa214e) Investigating why host 3 has disconnected wit= h event PingTimeout 2017-06-14 16:13:08,840 INFO [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:c= tx-51c0151c) (logid:a372c9fc) Host 4 is disconnecting with event ShutdownRe= quested 2017-06-14 16:13:08,842 WARN [c.c.a.m.AgentManagerImpl] (AgentMonitor-1:ct= x-b6c685ed) (logid:2002cffe) Disconnect agent for CPVM/SSVM due to physical= connection close. host: 5 2017-06-14 16:13:08,842 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-3:c= tx-d46f2f55) (logid:22aa214e) checking if agent (3) is alive 2017-06-14 16:13:08,843 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:c= tx-51c0151c) (logid:a372c9fc) The next status of agent 4is Disconnected, cu= rrent status is Up 2017-06-14 16:13:08,843 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:c= tx-51c0151c) (logid:a372c9fc) Deregistering link for 4 with state Disconnec= ted 2017-06-14 16:13:08,843 INFO [c.c.a.m.AgentManagerImpl] (AgentTaskPool-5:c= tx-8f81c0d6) (logid:bef9a8ba) Host 5 is disconnecting with event ShutdownRe= quested 2017-06-14 16:13:08,843 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:c= tx-51c0151c) (logid:a372c9fc) Remove Agent : 4 2017-06-14 16:13:08,843 DEBUG [c.c.a.m.ConnectedAgentAttache] (AgentTaskPoo= l-4:ctx-51c0151c) (logid:a372c9fc) Processing Disconnect. 2017-06-14 16:13:08,843 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:c= tx-51c0151c) (logid:a372c9fc) Sending Disconnect to listener: com.cloud.hyp= ervisor.xenserver.discoverer.XcpServerDiscoverer 2017-06-14 16:13:08,843 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:c= tx-51c0151c) (logid:a372c9fc) Sending Disconnect to listener: com.cloud.hyp= ervisor.hyperv.discoverer.HypervServerDiscoverer 2017-06-14 16:13:08,843 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:c= tx-51c0151c) (logid:a372c9fc) Sending Disconnect to listener: com.cloud.sto= rage.listener.StoragePoolMonitor 2017-06-14 16:13:08,843 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:c= tx-51c0151c) (logid:a372c9fc) Sending Disconnect to listener: com.cloud.sto= rage.secondary.SecondaryStorageListener 2017-06-14 16:13:08,843 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:c= tx-51c0151c) (logid:a372c9fc) Sending Disconnect to listener: com.cloud.net= work.security.SecurityGroupListener 2017-06-14 16:13:08,843 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:c= tx-51c0151c) (logid:a372c9fc) Sending Disconnect to listener: org.apache.cl= oudstack.engine.orchestration.NetworkOrchestrator 2017-06-14 16:13:08,843 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:c= tx-51c0151c) (logid:a372c9fc) Sending Disconnect to listener: com.cloud.vm.= ClusteredVirtualMachineManagerImpl 2017-06-14 16:13:08,844 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:c= tx-51c0151c) (logid:a372c9fc) Sending Disconnect to listener: com.cloud.dep= loy.DeploymentPlanningManagerImpl 2017-06-14 16:13:08,844 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:c= tx-51c0151c) (logid:a372c9fc) Sending Disconnect to listener: com.cloud.cap= acity.StorageCapacityListener 2017-06-14 16:13:08,844 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:c= tx-51c0151c) (logid:a372c9fc) Sending Disconnect to listener: com.cloud.cap= acity.ComputeCapacityListener 2017-06-14 16:13:08,844 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:c= tx-51c0151c) (logid:a372c9fc) Sending Disconnect to listener: com.cloud.net= work.NetworkUsageManagerImpl$DirectNetworkStatsListener 2017-06-14 16:13:08,844 DEBUG [c.c.n.NetworkUsageManagerImpl] (AgentTaskPoo= l-4:ctx-51c0151c) (logid:a372c9fc) Disconnected called on 4 with status Dis= connected 2017-06-14 16:13:08,844 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:c= tx-51c0151c) (logid:a372c9fc) Sending Disconnect to listener: com.cloud.net= work.SshKeysDistriMonitor 2017-06-14 16:13:08,844 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:c= tx-51c0151c) (logid:a372c9fc) Sending Disconnect to listener: com.cloud.net= work.router.VpcVirtualNetworkApplianceManagerImpl 2017-06-14 16:13:08,845 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:c= tx-51c0151c) (logid:a372c9fc) Sending Disconnect to listener: com.cloud.age= nt.manager.AgentManagerImpl$BehindOnPingListener 2017-06-14 16:13:08,845 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:c= tx-51c0151c) (logid:a372c9fc) Sending Disconnect to listener: com.cloud.age= nt.manager.AgentManagerImpl$SetHostParamsListener 2017-06-14 16:13:08,845 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:c= tx-51c0151c) (logid:a372c9fc) Sending Disconnect to listener: com.cloud.net= work.SshKeysDistriMonitor 2017-06-14 16:13:08,845 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:c= tx-51c0151c) (logid:a372c9fc) Sending Disconnect to listener: com.cloud.net= work.router.VirtualNetworkApplianceManagerImpl 2017-06-14 16:13:08,845 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:c= tx-51c0151c) (logid:a372c9fc) Sending Disconnect to listener: com.cloud.sto= rage.download.DownloadListener 2017-06-14 16:13:08,845 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:c= tx-51c0151c) (logid:a372c9fc) Sending Disconnect to listener: com.cloud.sto= rage.upload.UploadListener 2017-06-14 16:13:08,845 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-5:c= tx-8f81c0d6) (logid:bef9a8ba) The next status of agent 5is Disconnected, cu= rrent status is Up 2017-06-14 16:13:08,845 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-5:c= tx-8f81c0d6) (logid:bef9a8ba) Deregistering link for 5 with state Disconnec= ted 2017-06-14 16:13:08,845 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-5:c= tx-8f81c0d6) (logid:bef9a8ba) Remove Agent : 5 2017-06-14 16:13:08,845 DEBUG [c.c.a.m.ConnectedAgentAttache] (AgentTaskPoo= l-5:ctx-8f81c0d6) (logid:bef9a8ba) Processing Disconnect. 2017-06-14 16:13:08,845 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-5:c= tx-8f81c0d6) (logid:bef9a8ba) Sending Disconnect to listener: com.cloud.hyp= ervisor.xenserver.discoverer.XcpServerDiscoverer 2017-06-14 16:13:08,845 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-5:c= tx-8f81c0d6) (logid:bef9a8ba) Sending Disconnect to listener: com.cloud.hyp= ervisor.hyperv.discoverer.HypervServerDiscoverer 2017-06-14 16:13:08,845 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-5:c= tx-8f81c0d6) (logid:bef9a8ba) Sending Disconnect to listener: com.cloud.sto= rage.listener.StoragePoolMonitor 2017-06-14 16:13:08,846 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-5:c= tx-8f81c0d6) (logid:bef9a8ba) Sending Disconnect to listener: com.cloud.sto= rage.secondary.SecondaryStorageListener 2017-06-14 16:13:08,846 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-5:c= tx-8f81c0d6) (logid:bef9a8ba) Sending Disconnect to listener: com.cloud.net= work.security.SecurityGroupListener 2017-06-14 16:13:08,846 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-5:c= tx-8f81c0d6) (logid:bef9a8ba) Sending Disconnect to listener: org.apache.cl= oudstack.engine.orchestration.NetworkOrchestrator 2017-06-14 16:13:08,846 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-5:c= tx-8f81c0d6) (logid:bef9a8ba) Sending Disconnect to listener: com.cloud.vm.= ClusteredVirtualMachineManagerImpl 2017-06-14 16:13:08,846 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-5:c= tx-8f81c0d6) (logid:bef9a8ba) Sending Disconnect to listener: com.cloud.dep= loy.DeploymentPlanningManagerImpl 2017-06-14 16:13:08,846 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-5:c= tx-8f81c0d6) (logid:bef9a8ba) Sending Disconnect to listener: com.cloud.cap= acity.StorageCapacityListener 2017-06-14 16:13:08,846 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-5:c= tx-8f81c0d6) (logid:bef9a8ba) Sending Disconnect to listener: com.cloud.cap= acity.ComputeCapacityListener 2017-06-14 16:13:08,846 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-5:c= tx-8f81c0d6) (logid:bef9a8ba) Sending Disconnect to listener: com.cloud.net= work.NetworkUsageManagerImpl$DirectNetworkStatsListener 2017-06-14 16:13:08,846 DEBUG [c.c.n.NetworkUsageManagerImpl] (AgentTaskPoo= l-5:ctx-8f81c0d6) (logid:bef9a8ba) Disconnected called on 5 with status Dis= connected 2017-06-14 16:13:08,847 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-5:c= tx-8f81c0d6) (logid:bef9a8ba) Sending Disconnect to listener: com.cloud.net= work.SshKeysDistriMonitor 2017-06-14 16:13:08,847 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:c= tx-51c0151c) (logid:a372c9fc) Sending Disconnect to listener: com.cloud.con= soleproxy.ConsoleProxyListener 2017-06-14 16:13:08,847 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-5:c= tx-8f81c0d6) (logid:bef9a8ba) Sending Disconnect to listener: com.cloud.net= work.router.VpcVirtualNetworkApplianceManagerImpl 2017-06-14 16:13:08,847 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-5:c= tx-8f81c0d6) (logid:bef9a8ba) Sending Disconnect to listener: com.cloud.age= nt.manager.AgentManagerImpl$BehindOnPingListener 2017-06-14 16:13:08,847 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-5:c= tx-8f81c0d6) (logid:bef9a8ba) Sending Disconnect to listener: com.cloud.age= nt.manager.AgentManagerImpl$SetHostParamsListener 2017-06-14 16:13:08,847 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-5:c= tx-8f81c0d6) (logid:bef9a8ba) Sending Disconnect to listener: com.cloud.net= work.SshKeysDistriMonitor 2017-06-14 16:13:08,847 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-5:c= tx-8f81c0d6) (logid:bef9a8ba) Sending Disconnect to listener: com.cloud.net= work.router.VirtualNetworkApplianceManagerImpl 2017-06-14 16:13:08,847 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-5:c= tx-8f81c0d6) (logid:bef9a8ba) Sending Disconnect to listener: com.cloud.sto= rage.download.DownloadListener 2017-06-14 16:13:08,847 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-5:c= tx-8f81c0d6) (logid:bef9a8ba) Sending Disconnect to listener: com.cloud.sto= rage.upload.UploadListener 2017-06-14 16:13:08,847 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-5:c= tx-8f81c0d6) (logid:bef9a8ba) Sending Disconnect to listener: com.cloud.con= soleproxy.ConsoleProxyListener 2017-06-14 16:13:08,849 DEBUG [c.c.a.t.Request] (AgentTaskPool-3:ctx-d46f2f= 55) (logid:22aa214e) Seq 3-5718727101830397986: Sending { Cmd , MgmtId: 42= 78190080, via: 3(localhost.localdomain), Ver: v1, Flags: 100011, [{"com.clo= ud.agent.api.CheckHealthCommand":{"wait":50}}] } 2017-06-14 16:13:08,849 INFO [c.c.c.ConsoleProxyManagerImpl] (AgentTaskPoo= l-4:ctx-51c0151c) (logid:a372c9fc) Console proxy agent disconnected, proxy:= v-1-VM 2017-06-14 16:13:08,849 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-5:c= tx-8f81c0d6) (logid:bef9a8ba) Sending Disconnect to listener: com.cloud.sto= rage.LocalStoragePoolListener 2017-06-14 16:13:08,849 DEBUG [c.c.h.Status] (AgentTaskPool-5:ctx-8f81c0d6)= (logid:bef9a8ba) Transition:[Resource state =3D Enabled, Agent event =3D S= hutdownRequested, Host id =3D 5, name =3D s-2-VM] 2017-06-14 16:13:08,851 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:c= tx-51c0151c) (logid:a372c9fc) Sending Disconnect to listener: com.cloud.sto= rage.LocalStoragePoolListener 2017-06-14 16:13:08,852 DEBUG [c.c.a.m.ClusteredAgentManagerImpl] (AgentTas= kPool-5:ctx-8f81c0d6) (logid:bef9a8ba) Notifying other nodes of to disconne= ct 2017-06-14 16:13:08,852 DEBUG [c.c.h.Status] (AgentTaskPool-4:ctx-51c0151c)= (logid:a372c9fc) Transition:[Resource state =3D Enabled, Agent event =3D S= hutdownRequested, Host id =3D 4, name =3D v-1-VM] 2017-06-14 16:13:08,855 DEBUG [c.c.a.m.ClusteredAgentManagerImpl] (AgentTas= kPool-4:ctx-51c0151c) (logid:a372c9fc) Notifying other nodes of to disconne= ct 2017-06-14 16:13:08,921 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 60881bc7) (logid:1af97e25) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:13:09,690 DEBUG [c.c.a.t.Request] (AgentManager-Handler-17:nu= ll) (logid:) Seq 3-5718727101830397986: Processing: { Ans: , MgmtId: 42781= 90080, via: 3, Ver: v1, Flags: 10, [{"com.cloud.agent.api.CheckHealthAnswer= ":{"result":true,"details":"resource is alive","wait":0}}] } 2017-06-14 16:13:09,690 DEBUG [c.c.a.t.Request] (AgentTaskPool-3:ctx-d46f2f= 55) (logid:22aa214e) Seq 3-5718727101830397986: Received: { Ans: , MgmtId:= 4278190080, via: 3(localhost.localdomain), Ver: v1, Flags: 10, { CheckHeal= thAnswer } } 2017-06-14 16:13:09,690 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-3:c= tx-d46f2f55) (logid:22aa214e) Details from executing class com.cloud.agent.= api.CheckHealthCommand: resource is alive 2017-06-14 16:13:09,690 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-3:c= tx-d46f2f55) (logid:22aa214e) agent (3) responded to checkHeathCommand, rep= orting that agent is Up 2017-06-14 16:13:09,690 INFO [c.c.a.m.AgentManagerImpl] (AgentTaskPool-3:c= tx-d46f2f55) (logid:22aa214e) The agent from host 3 state determined is Up 2017-06-14 16:13:09,690 INFO [c.c.a.m.AgentManagerImpl] (AgentTaskPool-3:c= tx-d46f2f55) (logid:22aa214e) Agent is determined to be up and running 2017-06-14 16:13:09,690 DEBUG [c.c.h.Status] (AgentTaskPool-3:ctx-d46f2f55)= (logid:22aa214e) Transition:[Resource state =3D Enabled, Agent event =3D P= ing, Host id =3D 3, name =3D localhost.localdomain] 2017-06-14 16:13:09,925 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 7dd268d5) (logid:422a2299) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:13:10,930 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 77b629ec) (logid:224e2438) HostOutOfBandManagementStatsCollector is running= ... 2017-06-14 16:13:11,937 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-= 56adfc46) (logid:c33ba65b) HostOutOfBandManagementStatsCollector is running= ... pavankumar@HSL007960:~/ACP_HOME/cloudstack$=20 pavankumar@HSL007960:~/ACP_HOME/cloudstack$=20 pavankumar@HSL007960:~/ACP_HOME/cloudstack$ tail -f vmops.log >> vmsnap.log= =20 ^C pavankumar@HSL007960:~/ACP_HOME/cloudstack$ vi vmops.log pavankumar@HSL007960:~/ACP_HOME/cloudstack$ vi vmsnap.log=20 at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.r= un(ManagedContextRunnable.java:49) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext= $1.call(DefaultManagedContext.java:56) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext= .callWithContext(DefaultManagedContext.java:103) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext= .runWithContext(DefaultManagedContext.java:53) at org.apache.cloudstack.managed.context.ManagedContextRunnable.run= (ManagedContextRunnable.java:46) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.= run(AsyncJobManagerImpl.java:506) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.ja= va:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExec= utor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExe= cutor.java:617) at java.lang.Thread.run(Thread.java:745) Caused by: java.lang.NullPointerException at com.cloud.vm.snapshot.VMSnapshotManagerImpl.orchestrateCreateVMS= napshot(VMSnapshotManagerImpl.java:1195) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessor= Impl.java:62) ... 28 more 2017-06-14 16:18:51,043 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Ex= ecutor-5:ctx-0343c9fd job-84) (logid:acb0fe06) Complete async job-84, jobSt= atus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.E= xceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Unexpecte= d exception"} 2017-06-14 16:18:51,044 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Ex= ecutor-5:ctx-0343c9fd job-84) (logid:acb0fe06) Publish async job-84 complet= e on message bus 2017-06-14 16:18:51,045 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Ex= ecutor-5:ctx-0343c9fd job-84) (logid:acb0fe06) Wake up jobs related to job-= 84 2017-06-14 16:18:51,045 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Ex= ecutor-5:ctx-0343c9fd job-84) (logid:acb0fe06) Update db status for job-84 2017-06-14 16:18:51,046 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Ex= ecutor-5:ctx-0343c9fd job-84) (logid:acb0fe06) Wake up jobs joined with job= -84 and disjoin all subjobs created from job- 84 2017-06-14 16:18:51,048 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Ex= ecutor-5:ctx-0343c9fd job-84) (logid:acb0fe06) Done executing org.apache.cl= oudstack.api.command.user.vmsnapshot.CreateVMSnapshotCmd for job-84 2017-06-14 16:18:51,048 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Execut= or-5:ctx-0343c9fd job-84) (logid:acb0fe06) Remove job-84 from job monitorin= g 2017-06-14 16:18:51,437 DEBUG [c.c.a.ApiServlet] (qtp752030228-26:ctx-5144f= ab9) (logid:0ab596f6) =3D=3D=3DSTART=3D=3D=3D 127.0.0.1 -- GET command=3D= queryAsyncJobResult&jobId=3Dacb0fe06-516a-4176-9b9b-8695552ef4e8&response= =3Djson&_=3D1497437331430 2017-06-14 16:18:51,453 DEBUG [c.c.a.ApiServlet] (qtp752030228-26:ctx-5144f= ab9 ctx-6bfbb028) (logid:0ab596f6) =3D=3D=3DEND=3D=3D=3D 127.0.0.1 -- GET = command=3DqueryAsyncJobResult&jobId=3Dacb0fe06-516a-4176-9b9b-8695552ef4e8= &response=3Djson&_=3D1497437331430 2017-06-14 16:18:51,532 DEBUG KVM libvirt Log=20 2017-06-14 17:50:51.909+0000: 25824: warning : qemuDomainObjTaint:1459 : Do= main id=3D10 name=3D'r-6-VM' uuid=3D0b38c8d0-381e-491b-870e-3ac582731cde is= tainted: high-privileges 2017-06-14 17:51:18.103+0000: 25821: warning : qemuAgentNotifyEvent:1279 : = Received unexpected event 3 2017-06-14 17:51:59.696+0000: 25822: warning : qemuDomainObjTaint:1459 : Do= main id=3D11 name=3D'i-2-5-VM' uuid=3D59f8d6f5-afa0-4965-8966-4aa45726933c = is tainted: high-privileges 2017-06-14 17:52:51.000+0000: 25826: error : qemuAgentSend:889 : Guest agen= t is not responding: Guest agent not available for now 2017-06-14 17:55:25.592+0000: 25821: error : qemuMonitorIO:615 : internal e= rror End of file from monitor 2017-06-14 17:58:46.249+0000: 25822: warning : qemuDomainObjTaint:1459 : Do= main id=3D12 name=3D'r-6-VM' uuid=3D0b38c8d0-381e-491b-870e-3ac582731cde is= tainted: high-privileges 2017-06-14 17:59:19.581+0000: 25824: warning : qemuDomainObjTaint:1459 : Do= main id=3D13 name=3D'i-2-5-VM' uuid=3D59f8d6f5-afa0-4965-8966-4aa45726933c = is tainted: high-privileges 2017-06-14 18:00:17.001+0000: 25825: error : qemuAgentSend:889 : Guest agen= t is not responding: Guest agent not available for now 2017-06-14 18:00:43.265+0000: 25821: error : qemuMonitorIO:615 : internal e= rror End of file from monitor 2017-06-14 18:01:15.531+0000: 25821: error : qemuMonitorIO:615 : internal e= rror End of file from monitor -- This message was sent by Atlassian JIRA (v6.4.14#64029)