Yuriy, This looks like a bug. There was a similar reported issue quite a while back on S3 (but with KVM). Please open an issue on it.
Have you tried using the S3 secondary storage option instead? It's probably more widely deployed than swift on CloudStack. There are a bunch of other bugs that are currently being addressed in the swift implementation related to templates. - Si ________________________________________ From: Yuriy Karpel <[email protected]> Sent: Wednesday, February 17, 2016 7:16 AM To: [email protected] Subject: kvm, snapshot create error My test stend: CentOS 7, Cloudstack 4.7, qemu-kvm 10:1.5.3-105.el7_2.3 Primary storage: Ceph RBD, Secondary storage: RadosGW Swift + NFS staging store When you create a disk snapshot I get an error: 2016-02-17 14:41:57,693 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-82:ctx-3b960545 job-2524) (logid:e60ab5a4) Add job-2524 into job monitoring 2016-02-17 14:41:57,710 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (catalina-exec-20:ctx-35c895a8 ctx-a26caf1e) (logid:b023f26d) submit async job-2524, details: AsyncJobVO {id:2524, userId: 10, accountId: 7, instanceType: Snapshot, instanceId: 16, cmd: org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd, cmdInfo: {"quiescevm":"false","httpmethod":"GET","ctxAccountId":"7","uuid":"b487a5b5-b990-4f75-91d4-4acb1b9aa8dd","cmdEventType":"SNAPSHOT.CREATE","response":"json","ctxUserId":"10","volumeId":"c935a963-2990-4bc4-86fd-facf5e711e5b","name":"test","ctxStartEventId":"6871","id":"16","ctxDetails":"{\"interface com.cloud.storage.Snapshot\":\"b487a5b5-b990-4f75-91d4-4acb1b9aa8dd\",\"interface com.cloud.storage.Volume\":\"c935a963-2990-4bc4-86fd-facf5e711e5b\"}","_":"1455709317187"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 90212275930085, completeMsid: null, lastUpdated: null, lastPolled: null, created: null} 2016-02-17 14:41:57,711 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-82:ctx-3b960545 job-2524) (logid:0a96ee1e) Executing AsyncJobVO {id:2524, userId: 10, accountId: 7, instanceType: Snapshot, instanceId: 16, cmd: org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd, cmdInfo: {"quiescevm":"false","httpmethod":"GET","ctxAccountId":"7","uuid":"b487a5b5-b990-4f75-91d4-4acb1b9aa8dd","cmdEventType":"SNAPSHOT.CREATE","response":"json","ctxUserId":"10","volumeId":"c935a963-2990-4bc4-86fd-facf5e711e5b","name":"test","ctxStartEventId":"6871","id":"16","ctxDetails":"{\"interface com.cloud.storage.Snapshot\":\"b487a5b5-b990-4f75-91d4-4acb1b9aa8dd\",\"interface com.cloud.storage.Volume\":\"c935a963-2990-4bc4-86fd-facf5e711e5b\"}","_":"1455709317187"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 90212275930085, completeMsid: null, lastUpdated: null, lastPolled: null, created: null} 2016-02-17 14:41:57,714 DEBUG [c.c.a.ApiServlet] (catalina-exec-20:ctx-35c895a8 ctx-a26caf1e) (logid:b023f26d) ===END=== 10.30.10.41 -- GET command=createSnapshot&response=json&volumeId=c935a963-2990-4bc4-86fd-facf5e711e5b&quiescevm=false&name=test&_=1455709317187 2016-02-17 14:41:57,751 DEBUG [c.c.u.AccountManagerImpl] (API-Job-Executor-82:ctx-3b960545 job-2524 ctx-acd8bf64) (logid:0a96ee1e) Access to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] granted to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] by DomainChecker 2016-02-17 14:41:57,874 INFO [o.a.c.a.c.u.s.CreateSnapshotCmd] (API-Job-Executor-82:ctx-3b960545 job-2524 ctx-acd8bf64) (logid:0a96ee1e) VOLSS: createSnapshotCmd starts:1455709317874 2016-02-17 14:41:57,956 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-82:ctx-3b960545 job-2524 ctx-acd8bf64) (logid:0a96ee1e) Sync job-2527 execution on object VmWorkJobQueue.99 2016-02-17 14:41:58,866 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-c113b5a4) (logid:d6f846a6) Execute sync-queue item: SyncQueueItemVO {id:1246, queueId: 1240, contentType: AsyncJob, contentId: 2527, lastProcessMsid: 90212275930085, lastprocessNumber: 2, lastProcessTime: Wed Feb 17 14:41:58 MSK 2016, created: Wed Feb 17 14:41:57 MSK 2016} 2016-02-17 14:41:58,871 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-c113b5a4) (logid:d6f846a6) Schedule queued job-2527 2016-02-17 14:41:58,888 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-51:ctx-f6739a2f job-2524/job-2527) (logid:afae7d3f) Add job-2527 into job monitoring 2016-02-17 14:41:58,902 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-feb21635) (logid:27fa58a0) Begin cleanup expired async-jobs 2016-02-17 14:41:58,906 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-51:ctx-f6739a2f job-2524/job-2527) (logid:0a96ee1e) Executing AsyncJobVO {id:2527, userId: 10, accountId: 7, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkTakeVolumeSnapshot, cmdInfo: rO0ABXNyACVjb20uY2xvdWQudm0uVm1Xb3JrVGFrZVZvbHVtZVNuYXBzaG90BL5gG4Li1c8CAARaAAlxdWllc2NlVm1MAAhwb2xpY3lJZHQAEExqYXZhL2xhbmcvTG9uZztMAApzbmFwc2hvdElkcQB-AAFMAAh2b2x1bWVJZHEAfgABeHIAE2NvbS5jbG91ZC52bS5WbVdvcmufmbZW8CVnawIABEoACWFjY291bnRJZEoABnVzZXJJZEoABHZtSWRMAAtoYW5kbGVyTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO3hwAAAAAAAAAAcAAAAAAAAACgAAAAAAAABjdAAUVm9sdW1lQXBpU2VydmljZUltcGwAc3IADmphdmEubGFuZy5Mb25nO4vkkMyPI98CAAFKAAV2YWx1ZXhyABBqYXZhLmxhbmcuTnVtYmVyhqyVHQuU4IsCAAB4cAAAAAAAAAAAc3EAfgAGAAAAAAAAABBzcQB-AAYAAAAAAAABYw, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 90212275930085, completeMsid: null, lastUpdated: null, lastPolled: null, created: Wed Feb 17 14:41:57 MSK 2016} 2016-02-17 14:41:58,906 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-51:ctx-f6739a2f job-2524/job-2527) (logid:0a96ee1e) Run VM work job: com.cloud.vm.VmWorkTakeVolumeSnapshot for VM 99, job origin: 2524 2016-02-17 14:41:58,912 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-51:ctx-f6739a2f job-2524/job-2527 ctx-85ee1822) (logid:0a96ee1e) Execute VM work job: com.cloud.vm.VmWorkTakeVolumeSnapshot{"volumeId":355,"policyId":0,"snapshotId":16,"quiesceVm":false,"userId":10,"accountId":7,"vmId":99,"handlerName":"VolumeApiServiceImpl"} 2016-02-17 14:41:58,930 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-feb21635) (logid:27fa58a0) End cleanup expired async-jobs 2016-02-17 14:41:59,183 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (Work-Job-Executor-51:ctx-f6739a2f job-2524/job-2527 ctx-85ee1822) (logid:0a96ee1e) getCommandHostDelegation: class org.apache.cloudstack.storage.command.CreateObjectCommand 2016-02-17 14:41:59,183 DEBUG [c.c.h.XenServerGuru] (Work-Job-Executor-51:ctx-f6739a2f job-2524/job-2527 ctx-85ee1822) (logid:0a96ee1e) getCommandHostDelegation: class org.apache.cloudstack.storage.command.CreateObjectCommand 2016-02-17 14:41:59,200 DEBUG [c.c.a.t.Request] (Work-Job-Executor-51:ctx-f6739a2f job-2524/job-2527 ctx-85ee1822) (logid:0a96ee1e) Seq 121-2842334314824210223: Sending { Cmd , MgmtId: 90212275930085, via: 121(srv-kvm01.cloud.bst.su), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CreateObjectCommand":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"volume":{"uuid":"c935a963-2990-4bc4-86fd-facf5e711e5b","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"f5efdbfb-8fe7-3dfd-bc07-5088222d8b84","id":52,"poolType":"RBD","host":" ceph-mon.cloud.bst.su","path":"rbd-cl","port":6789,"url":"RBD:// ceph-mon.cloud.bst.su/rbd-cl/?ROLE=Primary&STOREUUID=f5efdbfb-8fe7-3dfd-bc07-5088222d8b84 "}},"name":"ROOT-99","size":472312242,"path":"c935a963-2990-4bc4-86fd-facf5e711e5b","volumeId":355,"vmName":"i-7-99-VM","accountId":7,"format":"RAW","provisioningType":"THIN","id":355,"deviceId":0,"hypervisorType":"KVM"},"dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"f5efdbfb-8fe7-3dfd-bc07-5088222d8b84","id":52,"poolType":"RBD","host":" ceph-mon.cloud.bst.su","path":"rbd-cl","port":6789,"url":"RBD:// ceph-mon.cloud.bst.su/rbd-cl/?ROLE=Primary&STOREUUID=f5efdbfb-8fe7-3dfd-bc07-5088222d8b84"}},"vmName":"i-7-99-VM","name":"test","hypervisorType":"KVM","id":16,"quiescevm":false,"physicalSize":0}},"wait":0}}] } 2016-02-17 14:41:59,597 DEBUG [c.c.a.t.Request] (AgentManager-Handler-6:null) (logid:) Seq 121-2842334314824210223: Processing: { Ans: , MgmtId: 90212275930085, via: 121, Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.CreateObjectAnswer":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"rbd-cl/c935a963-2990-4bc4-86fd-facf5e711e5b/a26adf8e-6665-45bf-b6a8-37d164b825c6","id":0,"quiescevm":false,"physicalSize":0}},"result":true,"wait":0}}] } 2016-02-17 14:41:59,598 DEBUG [c.c.a.t.Request] (Work-Job-Executor-51:ctx-f6739a2f job-2524/job-2527 ctx-85ee1822) (logid:0a96ee1e) Seq 121-2842334314824210223: Received: { Ans: , MgmtId: 90212275930085, via: 121(srv-kvm01.cloud.bst.su), Ver: v1, Flags: 10, { CreateObjectAnswer } } 2016-02-17 14:41:59,789 DEBUG [o.a.c.s.m.AncientDataMotionStrategy] (Work-Job-Executor-51:ctx-f6739a2f job-2524/job-2527 ctx-85ee1822) (logid:0a96ee1e) copyAsync inspecting src type SNAPSHOT copyAsync inspecting dest type SNAPSHOT 2016-02-17 14:41:59,884 DEBUG [o.a.c.s.m.AncientDataMotionStrategy] (Work-Job-Executor-51:ctx-f6739a2f job-2524/job-2527 ctx-85ee1822) (logid:0a96ee1e) needCacheStorage true, dest at snapshots/7/355 dest role Imagerbd-cl/c935a963-2990-4bc4-86fd-facf5e711e5b/a26adf8e-6665-45bf-b6a8-37d164b825c6 src role Primary 2016-02-17 14:42:00,095 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (Work-Job-Executor-51:ctx-f6739a2f job-2524/job-2527 ctx-85ee1822) (logid:0a96ee1e) getCommandHostDelegation: class org.apache.cloudstack.storage.command.CopyCommand 2016-02-17 14:42:00,095 DEBUG [c.c.h.XenServerGuru] (Work-Job-Executor-51:ctx-f6739a2f job-2524/job-2527 ctx-85ee1822) (logid:0a96ee1e) getCommandHostDelegation: class org.apache.cloudstack.storage.command.CopyCommand 2016-02-17 14:42:00,100 DEBUG [c.c.a.t.Request] (Work-Job-Executor-51:ctx-f6739a2f job-2524/job-2527 ctx-85ee1822) (logid:0a96ee1e) Seq 121-2842334314824210224: Sending { Cmd , MgmtId: 90212275930085, via: 121(srv-kvm01.cloud.bst.su), Ver: v1, Flags: 100111, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"rbd-cl/c935a963-2990-4bc4-86fd-facf5e711e5b/a26adf8e-6665-45bf-b6a8-37d164b825c6","volume":{"uuid":"c935a963-2990-4bc4-86fd-facf5e711e5b","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"f5efdbfb-8fe7-3dfd-bc07-5088222d8b84","id":52,"poolType":"RBD","host":" ceph-mon.cloud.bst.su","path":"rbd-cl","port":6789,"url":"RBD:// ceph-mon.cloud.bst.su/rbd-cl/?ROLE=Primary&STOREUUID=f5efdbfb-8fe7-3dfd-bc07-5088222d8b84 "}},"name":"ROOT-99","size":472312242,"path":"c935a963-2990-4bc4-86fd-facf5e711e5b","volumeId":355,"vmName":"i-7-99-VM","accountId":7,"format":"RAW","provisioningType":"THIN","id":355,"deviceId":0,"hypervisorType":"KVM"},"dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"f5efdbfb-8fe7-3dfd-bc07-5088222d8b84","id":52,"poolType":"RBD","host":" ceph-mon.cloud.bst.su","path":"rbd-cl","port":6789,"url":"RBD:// ceph-mon.cloud.bst.su/rbd-cl/?ROLE=Primary&STOREUUID=f5efdbfb-8fe7-3dfd-bc07-5088222d8b84 "}},"vmName":"i-7-99-VM","name":"test","hypervisorType":"KVM","id":16,"quiescevm":false,"physicalSize":0}},"destTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/7/355","volume":{"uuid":"c935a963-2990-4bc4-86fd-facf5e711e5b","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"f5efdbfb-8fe7-3dfd-bc07-5088222d8b84","id":52,"poolType":"RBD","host":" ceph-mon.cloud.bst.su","path":"rbd-cl","port":6789,"url":"RBD:// ceph-mon.cloud.bst.su/rbd-cl/?ROLE=Primary&STOREUUID=f5efdbfb-8fe7-3dfd-bc07-5088222d8b84 "}},"name":"ROOT-99","size":472312242,"path":"c935a963-2990-4bc4-86fd-facf5e711e5b","volumeId":355,"vmName":"i-7-99-VM","accountId":7,"format":"RAW","provisioningType":"THIN","id":355,"deviceId":0,"hypervisorType":"KVM"},"dataStore":{"com.cloud.agent.api.to.SwiftTO":{"id":73,"url":" http://ceph-rgw.cloud.bst.su:8080/auth/v1.0/ ","account":"cloudstack","userName":"swift","key":"VPGpdk5ppNgCepV58NNa1E1x4j5RDP9xyIxB7XMB"}},"vmName":"i-7-99-VM","name":"test","hypervisorType":"KVM","id":16,"quiescevm":false,"physicalSize":0}},"cacheTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/7/355","volume":{"uuid":"c935a963-2990-4bc4-86fd-facf5e711e5b","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"f5efdbfb-8fe7-3dfd-bc07-5088222d8b84","id":52,"poolType":"RBD","host":" ceph-mon.cloud.bst.su","path":"rbd-cl","port":6789,"url":"RBD:// ceph-mon.cloud.bst.su/rbd-cl/?ROLE=Primary&STOREUUID=f5efdbfb-8fe7-3dfd-bc07-5088222d8b84 "}},"name":"ROOT-99","size":472312242,"path":"c935a963-2990-4bc4-86fd-facf5e711e5b","volumeId":355,"vmName":"i-7-99-VM","accountId":7,"format":"RAW","provisioningType":"THIN","id":355,"deviceId":0,"hypervisorType":"KVM"},"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs:// srv-nfs.cloud.bst.su/nfs","_role":"ImageCache"}},"vmName":"i-7-99-VM","name":"test","hypervisorType":"KVM","id":16,"quiescevm":false,"physicalSize":0}},"executeInSequence":true,"options":{"fullSnapshot":"true"},"options2":{},"wait":21600}}] } 2016-02-17 14:42:00,743 DEBUG [c.c.a.ApiServlet] (catalina-exec-24:ctx-e717f61f) (logid:01fce183) ===START=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709320685 2016-02-17 14:42:00,803 DEBUG [c.c.u.AccountManagerImpl] (catalina-exec-24:ctx-e717f61f ctx-f1954731) (logid:01fce183) Access to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] granted to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] by DomainChecker 2016-02-17 14:42:00,843 DEBUG [c.c.a.ApiServlet] (catalina-exec-24:ctx-e717f61f ctx-f1954731) (logid:01fce183) ===END=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709320685 2016-02-17 14:42:03,752 DEBUG [c.c.a.ApiServlet] (catalina-exec-10:ctx-2218d665) (logid:7bf93934) ===START=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709323687 2016-02-17 14:42:03,813 DEBUG [c.c.u.AccountManagerImpl] (catalina-exec-10:ctx-2218d665 ctx-21c82669) (logid:7bf93934) Access to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] granted to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] by DomainChecker 2016-02-17 14:42:03,852 DEBUG [c.c.a.ApiServlet] (catalina-exec-10:ctx-2218d665 ctx-21c82669) (logid:7bf93934) ===END=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709323687 2016-02-17 14:42:04,332 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-8:null) (logid:) SeqA 127-27657: Processing Seq 127-27657: { Cmd , MgmtId: -1, via: 127, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":79,"_loadInfo":"{\n \"connections\": [\n {\n \"id\": 28,\n \"clientInfo\": \"\",\n \"host\": \"10.30.16.10\",\n \"port\": 5904,\n \"tag\": \"4535bf74-d255-4634-b873-d4185b3e6433\",\n \"createTime\": 1455702716959,\n \"lastUsedTime\": 1455709322174\n }\n ]\n}","wait":0}}] } 2016-02-17 14:42:04,344 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-8:null) (logid:) SeqA 127-27657: Sending Seq 127-27657: { Ans: , MgmtId: 90212275930085, via: 127, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } 2016-02-17 14:42:04,766 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-f5f85727) (logid:8a939115) Zone 4 is ready to launch secondary storage VM 2016-02-17 14:42:04,837 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-2e943c4f) (logid:c78e8ca9) Zone 4 is ready to launch console proxy 2016-02-17 14:42:06,754 DEBUG [c.c.a.ApiServlet] (catalina-exec-23:ctx-456ba9fc) (logid:93d89c41) ===START=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709326685 2016-02-17 14:42:06,819 DEBUG [c.c.u.AccountManagerImpl] (catalina-exec-23:ctx-456ba9fc ctx-8d92ea82) (logid:93d89c41) Access to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] granted to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] by DomainChecker 2016-02-17 14:42:06,862 DEBUG [c.c.a.ApiServlet] (catalina-exec-23:ctx-456ba9fc ctx-8d92ea82) (logid:93d89c41) ===END=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709326685 2016-02-17 14:42:08,874 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-6bbebfec) (logid:81494643) Begin cleanup expired async-jobs 2016-02-17 14:42:08,902 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-6bbebfec) (logid:81494643) End cleanup expired async-jobs 2016-02-17 14:42:09,756 DEBUG [c.c.a.ApiServlet] (catalina-exec-19:ctx-516a5879) (logid:843735ea) ===START=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709329686 2016-02-17 14:42:09,834 DEBUG [c.c.u.AccountManagerImpl] (catalina-exec-19:ctx-516a5879 ctx-034669ac) (logid:843735ea) Access to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] granted to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] by DomainChecker 2016-02-17 14:42:09,895 DEBUG [c.c.a.ApiServlet] (catalina-exec-19:ctx-516a5879 ctx-034669ac) (logid:843735ea) ===END=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709329686 2016-02-17 14:42:11,628 DEBUG [c.c.a.m.ClusteredAgentAttache] (AgentManager-Handler-15:null) (logid:) Seq 121-6638305850744116094: Routing from 121491073759284 2016-02-17 14:42:11,631 DEBUG [c.c.a.m.ClusteredAgentManagerImpl] (AgentManager-Handler-11:null) (logid:) Seq 121-6638305850744116094: MgmtId 121491073759284: Resp: Routing to peer 2016-02-17 14:42:12,753 DEBUG [c.c.a.ApiServlet] (catalina-exec-11:ctx-f52ee770) (logid:902a3aff) ===START=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709332686 2016-02-17 14:42:12,817 DEBUG [c.c.u.AccountManagerImpl] (catalina-exec-11:ctx-f52ee770 ctx-c987af1f) (logid:902a3aff) Access to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] granted to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] by DomainChecker 2016-02-17 14:42:12,858 DEBUG [c.c.a.ApiServlet] (catalina-exec-11:ctx-f52ee770 ctx-c987af1f) (logid:902a3aff) ===END=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709332686 2016-02-17 14:42:14,333 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-5:null) (logid:) SeqA 127-27658: Processing Seq 127-27658: { Cmd , MgmtId: -1, via: 127, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":79,"_loadInfo":"{\n \"connections\": [\n {\n \"id\": 28,\n \"clientInfo\": \"\",\n \"host\": \"10.30.16.10\",\n \"port\": 5904,\n \"tag\": \"4535bf74-d255-4634-b873-d4185b3e6433\",\n \"createTime\": 1455702716959,\n \"lastUsedTime\": 1455709331340\n }\n ]\n}","wait":0}}] } 2016-02-17 14:42:14,344 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-5:null) (logid:) SeqA 127-27658: Sending Seq 127-27658: { Ans: , MgmtId: 90212275930085, via: 127, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } 2016-02-17 14:42:15,754 DEBUG [c.c.a.ApiServlet] (catalina-exec-25:ctx-9319ad12) (logid:cea4e95d) ===START=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709335686 2016-02-17 14:42:15,817 DEBUG [c.c.u.AccountManagerImpl] (catalina-exec-25:ctx-9319ad12 ctx-64ce6d52) (logid:cea4e95d) Access to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] granted to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] by DomainChecker 2016-02-17 14:42:15,858 DEBUG [c.c.a.ApiServlet] (catalina-exec-25:ctx-9319ad12 ctx-64ce6d52) (logid:cea4e95d) ===END=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709335686 2016-02-17 14:42:18,753 DEBUG [c.c.a.ApiServlet] (catalina-exec-7:ctx-adcc4b0d) (logid:878a5f9c) ===START=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709338685 2016-02-17 14:42:18,816 DEBUG [c.c.u.AccountManagerImpl] (catalina-exec-7:ctx-adcc4b0d ctx-4375a027) (logid:878a5f9c) Access to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] granted to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] by DomainChecker 2016-02-17 14:42:18,862 DEBUG [c.c.a.ApiServlet] (catalina-exec-7:ctx-adcc4b0d ctx-4375a027) (logid:878a5f9c) ===END=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709338685 2016-02-17 14:42:18,877 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-8181dd1a) (logid:f826bc0e) Begin cleanup expired async-jobs 2016-02-17 14:42:18,904 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-8181dd1a) (logid:f826bc0e) End cleanup expired async-jobs 2016-02-17 14:42:18,938 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-58b72550) (logid:d64b4182) Found 1 routers to update status. 2016-02-17 14:42:18,944 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-58b72550) (logid:d64b4182) Found 0 VPC networks to update Redundant State. 2016-02-17 14:42:18,950 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-58b72550) (logid:d64b4182) Found 0 networks to update RvR status. 2016-02-17 14:42:19,064 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-f9dd85a6) (logid:ba2f902a) Found 1 routers to update status. 2016-02-17 14:42:19,070 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-f9dd85a6) (logid:ba2f902a) Found 0 VPC networks to update Redundant State. 2016-02-17 14:42:19,076 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-f9dd85a6) (logid:ba2f902a) Found 0 networks to update RvR status. 2016-02-17 14:42:19,983 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-13:null) (logid:) Ping from 127(v-79-VM) 2016-02-17 14:42:20,207 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-14:null) (logid:) Ping from 130(s-78-VM) 2016-02-17 14:42:21,754 DEBUG [c.c.a.ApiServlet] (catalina-exec-20:ctx-4c92529b) (logid:aea56580) ===START=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709341686 2016-02-17 14:42:21,816 DEBUG [c.c.u.AccountManagerImpl] (catalina-exec-20:ctx-4c92529b ctx-8a691200) (logid:aea56580) Access to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] granted to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] by DomainChecker 2016-02-17 14:42:21,856 DEBUG [c.c.a.ApiServlet] (catalina-exec-20:ctx-4c92529b ctx-8a691200) (logid:aea56580) ===END=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709341686 2016-02-17 14:42:22,762 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-1:null) (logid:) Ping from 121(srv-kvm01.cloud.bst.su) 2016-02-17 14:42:22,763 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-1:null) (logid:) Process host VM state report from ping process. host: 121 2016-02-17 14:42:22,809 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-1:null) (logid:) Process VM state report. host: 121, number of records in report: 6 2016-02-17 14:42:22,809 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-1:null) (logid:) VM state report. host: 121, vm id: 97, power state: PowerOn 2016-02-17 14:42:22,819 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-1:null) (logid:) VM power state does not change, skip DB writing. vm id: 97 2016-02-17 14:42:22,819 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-1:null) (logid:) VM state report. host: 121, vm id: 98, power state: PowerOn 2016-02-17 14:42:22,828 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-1:null) (logid:) VM power state does not change, skip DB writing. vm id: 98 2016-02-17 14:42:22,829 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-1:null) (logid:) VM state report. host: 121, vm id: 99, power state: PowerOn 2016-02-17 14:42:22,841 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-1:null) (logid:) VM state report is updated. host: 121, vm id: 99, power state: PowerOn 2016-02-17 14:42:22,850 INFO [c.c.v.VirtualMachineManagerImpl] (AgentManager-Handler-1:null) (logid:) There is pending job or HA tasks working on the VM. vm id: 99, postpone power-change report by resetting power-change counters 2016-02-17 14:42:22,865 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-1:null) (logid:) VM state report. host: 121, vm id: 78, power state: PowerOn 2016-02-17 14:42:22,875 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-1:null) (logid:) VM power state does not change, skip DB writing. vm id: 78 2016-02-17 14:42:22,875 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-1:null) (logid:) VM state report. host: 121, vm id: 79, power state: PowerOn 2016-02-17 14:42:22,884 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-1:null) (logid:) VM power state does not change, skip DB writing. vm id: 79 2016-02-17 14:42:22,884 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-1:null) (logid:) VM state report. host: 121, vm id: 95, power state: PowerOn 2016-02-17 14:42:22,893 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-1:null) (logid:) VM power state does not change, skip DB writing. vm id: 95 2016-02-17 14:42:22,904 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-1:null) (logid:) Done with process of VM state report. host: 121 2016-02-17 14:42:24,334 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-10:null) (logid:) SeqA 127-27660: Processing Seq 127-27660: { Cmd , MgmtId: -1, via: 127, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":79,"_loadInfo":"{\n \"connections\": [\n {\n \"id\": 28,\n \"clientInfo\": \"\",\n \"host\": \"10.30.16.10\",\n \"port\": 5904,\n \"tag\": \"4535bf74-d255-4634-b873-d4185b3e6433\",\n \"createTime\": 1455702716959,\n \"lastUsedTime\": 1455709343561\n }\n ]\n}","wait":0}}] } 2016-02-17 14:42:24,344 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-10:null) (logid:) SeqA 127-27660: Sending Seq 127-27660: { Ans: , MgmtId: 90212275930085, via: 127, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } 2016-02-17 14:42:24,407 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-c5881dc5) (logid:1517cc52) Resetting hosts suitable for reconnect 2016-02-17 14:42:24,416 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-c5881dc5) (logid:1517cc52) Completed resetting hosts suitable for reconnect 2016-02-17 14:42:24,416 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-c5881dc5) (logid:1517cc52) Acquiring hosts for clusters already owned by this management server 2016-02-17 14:42:24,418 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-c5881dc5) (logid:1517cc52) Completed acquiring hosts for clusters already owned by this management server 2016-02-17 14:42:24,418 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-c5881dc5) (logid:1517cc52) Acquiring hosts for clusters not owned by any management server 2016-02-17 14:42:24,420 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-c5881dc5) (logid:1517cc52) Completed acquiring hosts for clusters not owned by any management server 2016-02-17 14:42:24,757 DEBUG [c.c.a.ApiServlet] (catalina-exec-1:ctx-a2d8e6d1) (logid:fdbcedc1) ===START=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709344683 2016-02-17 14:42:24,828 DEBUG [c.c.u.AccountManagerImpl] (catalina-exec-1:ctx-a2d8e6d1 ctx-5135eef0) (logid:fdbcedc1) Access to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] granted to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] by DomainChecker 2016-02-17 14:42:24,874 DEBUG [c.c.a.ApiServlet] (catalina-exec-1:ctx-a2d8e6d1 ctx-5135eef0) (logid:fdbcedc1) ===END=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709344683 2016-02-17 14:42:25,250 DEBUG [c.c.s.StatsCollector] (StatsCollector-4:ctx-c1a20ac2) (logid:b7064d0c) VmStatsCollector is running... 2016-02-17 14:42:25,349 DEBUG [c.c.a.t.Request] (StatsCollector-4:ctx-c1a20ac2) (logid:b7064d0c) Seq 121-2842334314824210225: Received: { Ans: , MgmtId: 90212275930085, via: 121(srv-kvm01.cloud.bst.su), Ver: v1, Flags: 10, { GetVmStatsAnswer } } 2016-02-17 14:42:27,756 DEBUG [c.c.a.ApiServlet] (catalina-exec-10:ctx-b706cef7) (logid:a71b8b76) ===START=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709347689 2016-02-17 14:42:27,824 DEBUG [c.c.u.AccountManagerImpl] (catalina-exec-10:ctx-b706cef7 ctx-4a7005e7) (logid:a71b8b76) Access to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] granted to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] by DomainChecker 2016-02-17 14:42:27,870 DEBUG [c.c.a.ApiServlet] (catalina-exec-10:ctx-b706cef7 ctx-4a7005e7) (logid:a71b8b76) ===END=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709347689 2016-02-17 14:42:28,878 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-46abae78) (logid:0c233f0d) Begin cleanup expired async-jobs 2016-02-17 14:42:28,908 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-46abae78) (logid:0c233f0d) End cleanup expired async-jobs 2016-02-17 14:42:30,757 DEBUG [c.c.a.ApiServlet] (catalina-exec-8:ctx-f88cb125) (logid:37518ba5) ===START=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709350683 2016-02-17 14:42:30,819 DEBUG [c.c.u.AccountManagerImpl] (catalina-exec-8:ctx-f88cb125 ctx-9cf26608) (logid:37518ba5) Access to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] granted to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] by DomainChecker 2016-02-17 14:42:30,862 DEBUG [c.c.a.ApiServlet] (catalina-exec-8:ctx-f88cb125 ctx-9cf26608) (logid:37518ba5) ===END=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709350683 2016-02-17 14:42:33,753 DEBUG [c.c.a.ApiServlet] (catalina-exec-12:ctx-31e13dd3) (logid:5eb61ab6) ===START=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709353683 2016-02-17 14:42:33,817 DEBUG [c.c.u.AccountManagerImpl] (catalina-exec-12:ctx-31e13dd3 ctx-fb580cc8) (logid:5eb61ab6) Access to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] granted to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] by DomainChecker 2016-02-17 14:42:33,859 DEBUG [c.c.a.ApiServlet] (catalina-exec-12:ctx-31e13dd3 ctx-fb580cc8) (logid:5eb61ab6) ===END=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709353683 2016-02-17 14:42:34,337 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-3:null) (logid:) SeqA 127-27661: Processing Seq 127-27661: { Cmd , MgmtId: -1, via: 127, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":79,"_loadInfo":"{\n \"connections\": [\n {\n \"id\": 28,\n \"clientInfo\": \"\",\n \"host\": \"10.30.16.10\",\n \"port\": 5904,\n \"tag\": \"4535bf74-d255-4634-b873-d4185b3e6433\",\n \"createTime\": 1455702716959,\n \"lastUsedTime\": 1455709352740\n }\n ]\n}","wait":0}}] } 2016-02-17 14:42:34,349 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-3:null) (logid:) SeqA 127-27661: Sending Seq 127-27661: { Ans: , MgmtId: 90212275930085, via: 127, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } 2016-02-17 14:42:34,763 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-19feb311) (logid:3b1ae194) Zone 4 is ready to launch secondary storage VM 2016-02-17 14:42:34,834 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-3525dc1e) (logid:949d40ea) Zone 4 is ready to launch console proxy 2016-02-17 14:42:36,740 DEBUG [c.c.a.ApiServlet] (catalina-exec-11:ctx-3f579fb7) (logid:4ddb3f86) ===START=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709356682 2016-02-17 14:42:36,835 DEBUG [c.c.u.AccountManagerImpl] (catalina-exec-11:ctx-3f579fb7 ctx-c5484f70) (logid:4ddb3f86) Access to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] granted to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] by DomainChecker 2016-02-17 14:42:36,895 DEBUG [c.c.a.ApiServlet] (catalina-exec-11:ctx-3f579fb7 ctx-c5484f70) (logid:4ddb3f86) ===END=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709356682 2016-02-17 14:42:38,876 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-f20bc02c) (logid:c1f1a56b) Begin cleanup expired async-jobs 2016-02-17 14:42:38,901 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-f20bc02c) (logid:c1f1a56b) End cleanup expired async-jobs 2016-02-17 14:42:39,758 DEBUG [c.c.a.ApiServlet] (catalina-exec-13:ctx-c125e815) (logid:a54a004b) ===START=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709359688 2016-02-17 14:42:39,819 DEBUG [c.c.u.AccountManagerImpl] (catalina-exec-13:ctx-c125e815 ctx-7db89eda) (logid:a54a004b) Access to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] granted to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] by DomainChecker 2016-02-17 14:42:39,860 DEBUG [c.c.a.ApiServlet] (catalina-exec-13:ctx-c125e815 ctx-7db89eda) (logid:a54a004b) ===END=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709359688 2016-02-17 14:42:42,754 DEBUG [c.c.a.ApiServlet] (catalina-exec-7:ctx-e388f44d) (logid:d14628b8) ===START=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709362683 2016-02-17 14:42:42,818 DEBUG [c.c.u.AccountManagerImpl] (catalina-exec-7:ctx-e388f44d ctx-0e07e3be) (logid:d14628b8) Access to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] granted to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] by DomainChecker 2016-02-17 14:42:42,863 DEBUG [c.c.a.ApiServlet] (catalina-exec-7:ctx-e388f44d ctx-0e07e3be) (logid:d14628b8) ===END=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709362683 2016-02-17 14:42:44,336 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-12:null) (logid:) SeqA 127-27662: Processing Seq 127-27662: { Cmd , MgmtId: -1, via: 127, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":79,"_loadInfo":"{\n \"connections\": [\n {\n \"id\": 28,\n \"clientInfo\": \"\",\n \"host\": \"10.30.16.10\",\n \"port\": 5904,\n \"tag\": \"4535bf74-d255-4634-b873-d4185b3e6433\",\n \"createTime\": 1455702716959,\n \"lastUsedTime\": 1455709361905\n }\n ]\n}","wait":0}}] } 2016-02-17 14:42:44,347 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-12:null) (logid:) SeqA 127-27662: Sending Seq 127-27662: { Ans: , MgmtId: 90212275930085, via: 127, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } 2016-02-17 14:42:45,753 DEBUG [c.c.a.ApiServlet] (catalina-exec-18:ctx-fa009cf4) (logid:0564cb71) ===START=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709365682 2016-02-17 14:42:45,821 DEBUG [c.c.u.AccountManagerImpl] (catalina-exec-18:ctx-fa009cf4 ctx-c631c841) (logid:0564cb71) Access to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] granted to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] by DomainChecker 2016-02-17 14:42:45,864 DEBUG [c.c.a.ApiServlet] (catalina-exec-18:ctx-fa009cf4 ctx-c631c841) (logid:0564cb71) ===END=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709365682 2016-02-17 14:42:47,473 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-6290e24b) (logid:ba691574) AutoScaling Monitor is running... 2016-02-17 14:42:48,756 DEBUG [c.c.a.ApiServlet] (catalina-exec-21:ctx-6f46f10a) (logid:fd06240c) ===START=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709368688 2016-02-17 14:42:48,823 DEBUG [c.c.u.AccountManagerImpl] (catalina-exec-21:ctx-6f46f10a ctx-c9bf5115) (logid:fd06240c) Access to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] granted to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] by DomainChecker 2016-02-17 14:42:48,869 DEBUG [c.c.a.ApiServlet] (catalina-exec-21:ctx-6f46f10a ctx-c9bf5115) (logid:fd06240c) ===END=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709368688 2016-02-17 14:42:48,883 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-89f8fe29) (logid:b8f61b84) Begin cleanup expired async-jobs 2016-02-17 14:42:48,913 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-89f8fe29) (logid:b8f61b84) End cleanup expired async-jobs 2016-02-17 14:42:48,931 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-9e4ea762) (logid:77f09669) Found 1 routers to update status. 2016-02-17 14:42:48,938 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-9e4ea762) (logid:77f09669) Found 0 VPC networks to update Redundant State. 2016-02-17 14:42:48,944 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-9e4ea762) (logid:77f09669) Found 0 networks to update RvR status. 2016-02-17 14:42:49,063 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-479db730) (logid:587e8d61) Found 1 routers to update status. 2016-02-17 14:42:49,069 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-479db730) (logid:587e8d61) Found 0 VPC networks to update Redundant State. 2016-02-17 14:42:49,075 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-479db730) (logid:587e8d61) Found 0 networks to update RvR status. 2016-02-17 14:42:50,035 DEBUG [c.c.a.m.ClusteredAgentAttache] (AgentManager-Handler-2:null) (logid:) Seq 121-6638305850744116095: Routing from 121491073759284 2016-02-17 14:42:50,097 DEBUG [c.c.a.m.ClusteredAgentManagerImpl] (AgentManager-Handler-9:null) (logid:) Seq 121-6638305850744116095: MgmtId 121491073759284: Resp: Routing to peer 2016-02-17 14:42:51,755 DEBUG [c.c.a.ApiServlet] (catalina-exec-10:ctx-e0ab94a5) (logid:7c7050f3) ===START=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709371682 2016-02-17 14:42:51,820 DEBUG [c.c.u.AccountManagerImpl] (catalina-exec-10:ctx-e0ab94a5 ctx-786de8bd) (logid:7c7050f3) Access to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] granted to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] by DomainChecker 2016-02-17 14:42:51,871 DEBUG [c.c.a.ApiServlet] (catalina-exec-10:ctx-e0ab94a5 ctx-786de8bd) (logid:7c7050f3) ===END=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709371682 2016-02-17 14:42:53,146 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-82829583) (logid:d7658d5e) StorageCollector is running... 2016-02-17 14:42:53,173 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollector-3:ctx-82829583) (logid:d7658d5e) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand 2016-02-17 14:42:53,173 DEBUG [c.c.h.XenServerGuru] (StatsCollector-3:ctx-82829583) (logid:d7658d5e) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand 2016-02-17 14:42:53,223 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-82829583) (logid:d7658d5e) Seq 130-1390486384950642428: Received: { Ans: , MgmtId: 90212275930085, via: 130(s-78-VM), Ver: v1, Flags: 10, { GetStorageStatsAnswer } } 2016-02-17 14:42:53,229 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollector-3:ctx-82829583) (logid:d7658d5e) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand 2016-02-17 14:42:53,230 DEBUG [c.c.h.XenServerGuru] (StatsCollector-3:ctx-82829583) (logid:d7658d5e) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand 2016-02-17 14:42:53,348 DEBUG [c.c.a.m.ClusteredAgentAttache] (AgentManager-Handler-6:null) (logid:) Seq 130-4066468988538848895: Routing from 121491073759284 2016-02-17 14:42:53,390 DEBUG [c.c.a.m.ClusteredAgentManagerImpl] (AgentManager-Handler-8:null) (logid:) Seq 130-4066468988538848895: MgmtId 121491073759284: Resp: Routing to peer 2016-02-17 14:42:53,405 DEBUG [c.c.a.m.ClusteredAgentAttache] (AgentManager-Handler-15:null) (logid:) Seq 121-6638305850744116096: Routing from 121491073759284 2016-02-17 14:42:53,452 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-82829583) (logid:d7658d5e) Seq 121-2842334314824210226: Received: { Ans: , MgmtId: 90212275930085, via: 121(srv-kvm01.cloud.bst.su), Ver: v1, Flags: 10, { GetStorageStatsAnswer } } 2016-02-17 14:42:53,602 DEBUG [c.c.a.m.ClusteredAgentManagerImpl] (AgentManager-Handler-5:null) (logid:) Seq 121-6638305850744116096: MgmtId 121491073759284: Resp: Routing to peer 2016-02-17 14:42:54,337 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-13:null) (logid:) SeqA 127-27663: Processing Seq 127-27663: { Cmd , MgmtId: -1, via: 127, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":79,"_loadInfo":"{\n \"connections\": [\n {\n \"id\": 28,\n \"clientInfo\": \"\",\n \"host\": \"10.30.16.10\",\n \"port\": 5904,\n \"tag\": \"4535bf74-d255-4634-b873-d4185b3e6433\",\n \"createTime\": 1455702716959,\n \"lastUsedTime\": 1455709374152\n }\n ]\n}","wait":0}}] } 2016-02-17 14:42:54,350 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-13:null) (logid:) SeqA 127-27663: Sending Seq 127-27663: { Ans: , MgmtId: 90212275930085, via: 127, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } 2016-02-17 14:42:54,755 DEBUG [c.c.a.ApiServlet] (catalina-exec-2:ctx-033d8622) (logid:a74966c6) ===START=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709374683 2016-02-17 14:42:54,819 DEBUG [c.c.u.AccountManagerImpl] (catalina-exec-2:ctx-033d8622 ctx-da3d563e) (logid:a74966c6) Access to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] granted to Acct[69296515-f19c-407c-859e-42f4599e4653-ykarpel] by DomainChecker 2016-02-17 14:42:54,861 DEBUG [c.c.a.ApiServlet] (catalina-exec-2:ctx-033d8622 ctx-da3d563e) (logid:a74966c6) ===END=== 10.30.10.41 -- GET command=queryAsyncJobResult&jobId=0a96ee1e-408a-4f4f-988a-3fa0974cec69&response=json&_=1455709374683 2016-02-17 14:42:55,045 DEBUG [c.c.a.t.Request] (AgentManager-Handler-14:null) (logid:) Seq 121-2842334314824210224: Processing: { Ans: , MgmtId: 90212275930085, via: 121, Ver: v1, Flags: 110, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"details":"Unsupported protocol","wait":0}}] } 2016-02-17 14:42:55,045 DEBUG [c.c.a.m.AgentAttache] (AgentManager-Handler-14:null) (logid:) Seq 121-2842334314824210224: No more commands found 2016-02-17 14:42:55,045 DEBUG [c.c.a.t.Request] (Work-Job-Executor-51:ctx-f6739a2f job-2524/job-2527 ctx-85ee1822) (logid:0a96ee1e) Seq 121-2842334314824210224: Received: { Ans: , MgmtId: 90212275930085, via: 121(srv-kvm01.cloud.bst.su), Ver: v1, Flags: 110, { CopyCmdAnswer } } 2016-02-17 14:42:55,069 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (Work-Job-Executor-51:ctx-f6739a2f job-2524/job-2527 ctx-85ee1822) (logid:0a96ee1e) getCommandHostDelegation: class org.apache.cloudstack.storage.command.DeleteCommand 2016-02-17 14:42:55,070 DEBUG [c.c.h.XenServerGuru] (Work-Job-Executor-51:ctx-f6739a2f job-2524/job-2527 ctx-85ee1822) (logid:0a96ee1e) getCommandHostDelegation: class org.apache.cloudstack.storage.command.DeleteCommand 2016-02-17 14:42:55,075 DEBUG [c.c.a.t.Request] (Work-Job-Executor-51:ctx-f6739a2f job-2524/job-2527 ctx-85ee1822) (logid:0a96ee1e) Seq 130-1390486384950642429: Sending { Cmd , MgmtId: 90212275930085, via: 130(s-78-VM), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/7/355","volume":{"uuid":"c935a963-2990-4bc4-86fd-facf5e711e5b","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"f5efdbfb-8fe7-3dfd-bc07-5088222d8b84","id":52,"poolType":"RBD","host":" ceph-mon.cloud.bst.su","path":"rbd-cl","port":6789,"url":"RBD:// ceph-mon.cloud.bst.su/rbd-cl/?ROLE=Primary&STOREUUID=f5efdbfb-8fe7-3dfd-bc07-5088222d8b84 "}},"name":"ROOT-99","size":472312242,"path":"c935a963-2990-4bc4-86fd-facf5e711e5b","volumeId":355,"vmName":"i-7-99-VM","accountId":7,"format":"RAW","provisioningType":"THIN","id":355,"deviceId":0,"hypervisorType":"KVM"},"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs:// srv-nfs.cloud.bst.su/nfs","_role":"ImageCache"}},"vmName":"i-7-99-VM","name":"test","hypervisorType":"KVM","id":16,"quiescevm":false,"physicalSize":0}},"wait":0}}] } 2016-02-17 14:42:55,182 DEBUG [c.c.a.t.Request] (AgentManager-Handler-1:null) (logid:) Seq 130-1390486384950642429: Processing: { Ans: , MgmtId: 90212275930085, via: 130, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] } 2016-02-17 14:42:55,182 DEBUG [c.c.a.t.Request] (Work-Job-Executor-51:ctx-f6739a2f job-2524/job-2527 ctx-85ee1822) (logid:0a96ee1e) Seq 130-1390486384950642429: Received: { Ans: , MgmtId: 90212275930085, via: 130(s-78-VM), Ver: v1, Flags: 10, { Answer } } 2016-02-17 14:42:55,197 DEBUG [c.c.s.StatsCollector] (StatsCollector-1:ctx-0ffd116a) (logid:d8a68bc7) HostStatsCollector is running... 2016-02-17 14:42:55,242 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-0ffd116a) (logid:d8a68bc7) Seq 121-2842334314824210227: Received: { Ans: , MgmtId: 90212275930085, via: 121(srv-kvm01.cloud.bst.su), Ver: v1, Flags: 10, { GetHostStatsAnswer } } 2016-02-17 14:42:55,290 DEBUG [c.c.s.s.SnapshotManagerImpl] (Work-Job-Executor-51:ctx-f6739a2f job-2524/job-2527 ctx-85ee1822) (logid:0a96ee1e) Failed to create snapshot com.cloud.utils.exception.CloudRuntimeException: Unsupported protocol at org.apache.cloudstack.storage.snapshot.SnapshotServiceImpl.backupSnapshot(SnapshotServiceImpl.java:285) at org.apache.cloudstack.storage.snapshot.XenserverSnapshotStrategy.backupSnapshot(XenserverSnapshotStrategy.java:155) at org.apache.cloudstack.storage.snapshot.XenserverSnapshotStrategy.takeSnapshot(XenserverSnapshotStrategy.java:322) at com.cloud.storage.snapshot.SnapshotManagerImpl.takeSnapshot(SnapshotManagerImpl.java:1007) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:497) at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317) at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150) at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:91) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204) at com.sun.proxy.$Proxy189.takeSnapshot(Unknown Source) at org.apache.cloudstack.storage.volume.VolumeServiceImpl.takeSnapshot(VolumeServiceImpl.java:1591) at com.cloud.storage.VolumeApiServiceImpl.orchestrateTakeVolumeSnapshot(VolumeApiServiceImpl.java:2091) at com.cloud.storage.VolumeApiServiceImpl.orchestrateTakeVolumeSnapshot(VolumeApiServiceImpl.java:2883) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:497) at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107) at com.cloud.storage.VolumeApiServiceImpl.handleVmWorkJob(VolumeApiServiceImpl.java:2891) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:497) at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317) at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150) at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:91) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204) at com.sun.proxy.$Proxy194.handleVmWorkJob(Unknown Source) at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:554) at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53) at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:502) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) 2016-02-17 14:42:55,338 DEBUG [o.a.c.s.v.VolumeServiceImpl] (Work-Job-Executor-51:ctx-f6739a2f job-2524/job-2527 ctx-85ee1822) (logid:0a96ee1e) Take snapshot: 355 failed com.cloud.utils.exception.CloudRuntimeException: Failed to create snapshot at com.cloud.storage.snapshot.SnapshotManagerImpl.takeSnapshot(SnapshotManagerImpl.java:1023) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:497) at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317) at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150) at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:91) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204) at com.sun.proxy.$Proxy189.takeSnapshot(Unknown Source) at org.apache.cloudstack.storage.volume.VolumeServiceImpl.takeSnapshot(VolumeServiceImpl.java:1591) at com.cloud.storage.VolumeApiServiceImpl.orchestrateTakeVolumeSnapshot(VolumeApiServiceImpl.java:2091) at com.cloud.storage.VolumeApiServiceImpl.orchestrateTakeVolumeSnapshot(VolumeApiServiceImpl.java:2883) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:497) at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107) at com.cloud.storage.VolumeApiServiceImpl.handleVmWorkJob(VolumeApiServiceImpl.java:2891) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:497) at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317) at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150) at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:91) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204) at com.sun.proxy.$Proxy194.handleVmWorkJob(Unknown Source) at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:554) at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53) at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:502) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) Caused by: com.cloud.utils.exception.CloudRuntimeException: Unsupported protocol at org.apache.cloudstack.storage.snapshot.SnapshotServiceImpl.backupSnapshot(SnapshotServiceImpl.java:285) at org.apache.cloudstack.storage.snapshot.XenserverSnapshotStrategy.backupSnapshot(XenserverSnapshotStrategy.java:155) at org.apache.cloudstack.storage.snapshot.XenserverSnapshotStrategy.takeSnapshot(XenserverSnapshotStrategy.java:322) ... 45 more 2016-02-17 14:42:55,340 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-51:ctx-f6739a2f job-2524/job-2527 ctx-85ee1822) (logid:0a96ee1e) Invocation exception, caused by: com.cloud.utils.exception.CloudRuntimeException: Failed to take snapshot 2016-02-17 14:42:55,344 INFO [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-51:ctx-f6739a2f job-2524/job-2527 ctx-85ee1822) (logid:0a96ee1e) Rethrow exception com.cloud.utils.exception.CloudRuntimeException: Failed to take snapshot 2016-02-17 14:42:55,344 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-51:ctx-f6739a2f job-2524/job-2527) (logid:0a96ee1e) Done with run of VM work job: com.cloud.vm.VmWorkTakeVolumeSnapshot for VM 99, job origin: 2524 2016-02-17 14:42:55,344 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-51:ctx-f6739a2f job-2524/job-2527) (logid:0a96ee1e) Unable to complete AsyncJobVO {id:2527, userId: 10, accountId: 7, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkTakeVolumeSnapshot, cmdInfo: rO0ABXNyACVjb20uY2xvdWQudm0uVm1Xb3JrVGFrZVZvbHVtZVNuYXBzaG90BL5gG4Li1c8CAARaAAlxdWllc2NlVm1MAAhwb2xpY3lJZHQAEExqYXZhL2xhbmcvTG9uZztMAApzbmFwc2hvdElkcQB-AAFMAAh2b2x1bWVJZHEAfgABeHIAE2NvbS5jbG91ZC52bS5WbVdvcmufmbZW8CVnawIABEoACWFjY291bnRJZEoABnVzZXJJZEoABHZtSWRMAAtoYW5kbGVyTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO3hwAAAAAAAAAAcAAAAAAAAACgAAAAAAAABjdAAUVm9sdW1lQXBpU2VydmljZUltcGwAc3IADmphdmEubGFuZy5Mb25nO4vkkMyPI98CAAFKAAV2YWx1ZXhyABBqYXZhLmxhbmcuTnVtYmVyhqyVHQuU4IsCAAB4cAAAAAAAAAAAc3EAfgAGAAAAAAAAABBzcQB-AAYAAAAAAAABYw, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 90212275930085, completeMsid: null, lastUpdated: null, lastPolled: null, created: Wed Feb 17 14:41:57 MSK 2016}, job origin:2524 com.cloud.utils.exception.CloudRuntimeException: Failed to take snapshot at org.apache.cloudstack.storage.volume.VolumeServiceImpl.takeSnapshot(VolumeServiceImpl.java:1594) at com.cloud.storage.VolumeApiServiceImpl.orchestrateTakeVolumeSnapshot(VolumeApiServiceImpl.java:2091) at com.cloud.storage.VolumeApiServiceImpl.orchestrateTakeVolumeSnapshot(VolumeApiServiceImpl.java:2883) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:497) at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107) at com.cloud.storage.VolumeApiServiceImpl.handleVmWorkJob(VolumeApiServiceImpl.java:2891) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:497) at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317) at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150) at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:91) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204) at com.sun.proxy.$Proxy194.handleVmWorkJob(Unknown Source) at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:554) at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53) at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:502) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) Caused by: com.cloud.utils.exception.CloudRuntimeException: Failed to create snapshot at com.cloud.storage.snapshot.SnapshotManagerImpl.takeSnapshot(SnapshotManagerImpl.java:1023) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ... 42 more Caused by: com.cloud.utils.exception.CloudRuntimeException: Unsupported protocol at org.apache.cloudstack.storage.snapshot.SnapshotServiceImpl.backupSnapshot(SnapshotServiceImpl.java:285) at org.apache.cloudstack.storage.snapshot.XenserverSnapshotStrategy.backupSnapshot(XenserverSnapshotStrategy.java:155) at org.apache.cloudstack.storage.snapshot.XenserverSnapshotStrategy.takeSnapshot(XenserverSnapshotStrategy.java:322) ... 45 more 2016-02-17 14:42:55,367 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-51:ctx-f6739a2f job-2524/job-2527) (logid:0a96ee1e) Complete async job-2527, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyAC9jb20uY2xvdWQudXRpbHMuZXhjZXB0aW9uLkNsb3VkUnVudGltZUV4Y2VwdGlvbgAAAABWTU9yAwABSQALY3NFcnJvckNvZGV4cgAaamF2YS5sYW5nLlJ1bnRpbWVFeGNlcHRpb26eXwZHCjSD5QIAAHhyABNqYXZhLmxhbmcuRXhjZXB0aW9u0P0fPho7HMQCAAB4cgATamF2YS5sYW5nLlRocm93YWJsZdXGNSc5d7jLAwAETAAFY2F1c2V0ABVMamF2YS9sYW5nL1Rocm93YWJsZTtMAA1kZXRhaWxNZXNzYWdldAASTGphdmEvbGFuZy9TdHJpbmc7WwAKc3RhY2tUcmFjZXQAHltMamF2YS9sYW5nL1N0YWNrVHJhY2VFbGVtZW50O0wAFHN1cHByZXNzZWRFeGNlcHRpb25zdAAQTGphdmEvdXRpbC9MaXN0O3hwc3EAfgAAc3EAfgAAcQB-AAp0ABRVbnN1cHBvcnRlZCBwcm90b2NvbHVyAB5bTGphdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudDsCRio8PP0iOQIAAHhwAAAAMHNyABtqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnRhCcWaJjbdhQIABEkACmxpbmVOdW1iZXJMAA5kZWNsYXJpbmdDbGFzc3EAfgAFTAAIZmlsZU5hbWVxAH4ABUwACm1ldGhvZE5hbWVxAH4ABXhwAAABHXQAOm9yZy5hcGFjaGUuY2xvdWRzdGFjay5zdG9yYWdlLnNuYXBzaG90LlNuYXBzaG90U2VydmljZUltcGx0ABhTbmFwc2hvdFNlcnZpY2VJbXBsLmphdmF0AA5iYWNrdXBTbmFwc2hvdHNxAH4ADgAAAJt0AEBvcmcuYXBhY2hlLmNsb3Vkc3RhY2suc3RvcmFnZS5zbmFwc2hvdC5YZW5zZXJ2ZXJTbmFwc2hvdFN0cmF0ZWd5dAAeWGVuc2VydmVyU25hcHNob3RTdHJhdGVneS5qYXZhcQB-ABJzcQB-AA4AAAFCcQB-ABRxAH4AFXQADHRha2VTbmFwc2hvdHNxAH4ADgAAA-90AC5jb20uY2xvdWQuc3RvcmFnZS5zbmFwc2hvdC5TbmFwc2hvdE1hbmFnZXJJbXBsdAAYU25hcHNob3RNYW5hZ2VySW1wbC5qYXZhcQB-ABdzcQB-AA7____-dAAkc3VuLnJlZmxlY3QuTmF0aXZlTWV0aG9kQWNjZXNzb3JJbXBsdAAdTmF0aXZlTWV0aG9kQWNjZXNzb3JJbXBsLmphdmF0AAdpbnZva2Uwc3EAfgAOAAAAPnEAfgAccQB-AB10AAZpbnZva2VzcQB-AA4AAAArdAAoc3VuLnJlZmxlY3QuRGVsZWdhdGluZ01ldGhvZEFjY2Vzc29ySW1wbHQAIURlbGVnYXRpbmdNZXRob2RBY2Nlc3NvckltcGwuamF2YXEAfgAgc3EAfgAOAAAB8XQAGGphdmEubGFuZy5yZWZsZWN0Lk1ldGhvZHQAC01ldGhvZC5qYXZhcQB-ACBzcQB-AA4AAAE9dAAob3JnLnNwcmluZ2ZyYW1ld29yay5hb3Auc3VwcG9ydC5Bb3BVdGlsc3QADUFvcFV0aWxzLmphdmF0AB5pbnZva2VKb2lucG9pbnRVc2luZ1JlZmxlY3Rpb25zcQB-AA4AAAC3dAA8b3JnLnNwcmluZ2ZyYW1ld29yay5hb3AuZnJhbWV3b3JrLlJlZmxlY3RpdmVNZXRob2RJbnZvY2F0aW9udAAfUmVmbGVjdGl2ZU1ldGhvZEludm9jYXRpb24uamF2YXQAD2ludm9rZUpvaW5wb2ludHNxAH4ADgAAAJZxAH4ALHEAfgAtdAAHcHJvY2VlZHNxAH4ADgAAAFt0AD9vcmcuc3ByaW5nZnJhbWV3b3JrLmFvcC5pbnRlcmNlcHRvci5FeHBvc2VJbnZvY2F0aW9uSW50ZXJjZXB0b3J0ACBFeHBvc2VJbnZvY2F0aW9uSW50ZXJjZXB0b3IuamF2YXEAfgAgc3EAfgAOAAAArHEAfgAscQB-AC1xAH4AMHNxAH4ADgAAAMx0ADRvcmcuc3ByaW5nZnJhbWV3b3JrLmFvcC5mcmFtZXdvcmsuSmRrRHluYW1pY0FvcFByb3h5dAAXSmRrRHluYW1pY0FvcFByb3h5LmphdmFxAH4AIHNxAH4ADv____90ABdjb20uc3VuLnByb3h5LiRQcm94eTE4OXBxAH4AF3NxAH4ADgAABjd0ADZvcmcuYXBhY2hlLmNsb3Vkc3RhY2suc3RvcmFnZS52b2x1bWUuVm9sdW1lU2VydmljZUltcGx0ABZWb2x1bWVTZXJ2aWNlSW1wbC5qYXZhcQB-ABdzcQB-AA4AAAgrdAAmY29tLmNsb3VkLnN0b3JhZ2UuVm9sdW1lQXBpU2VydmljZUltcGx0ABlWb2x1bWVBcGlTZXJ2aWNlSW1wbC5qYXZhdAAdb3JjaGVzdHJhdGVUYWtlVm9sdW1lU25hcHNob3RzcQB-AA4AAAtDcQB-AD5xAH4AP3EAfgBAc3EAfgAO_____nEAfgAccQB-AB1xAH4AHnNxAH4ADgAAAD5xAH4AHHEAfgAdcQB-ACBzcQB-AA4AAAArcQB-ACJxAH4AI3EAfgAgc3EAfgAOAAAB8XEAfgAlcQB-ACZxAH4AIHNxAH4ADgAAAGt0ACJjb20uY2xvdWQudm0uVm1Xb3JrSm9iSGFuZGxlclByb3h5dAAaVm1Xb3JrSm9iSGFuZGxlclByb3h5LmphdmF0AA9oYW5kbGVWbVdvcmtKb2JzcQB-AA4AAAtLcQB-AD5xAH4AP3EAfgBJc3EAfgAO_____nEAfgAccQB-AB1xAH4AHnNxAH4ADgAAAD5xAH4AHHEAfgAdcQB-ACBzcQB-AA4AAAArcQB-ACJxAH4AI3EAfgAgc3EAfgAOAAAB8XEAfgAlcQB-ACZxAH4AIHNxAH4ADgAAAT1xAH4AKHEAfgApcQB-ACpzcQB-AA4AAAC3cQB-ACxxAH4ALXEAfgAuc3EAfgAOAAAAlnEAfgAscQB-AC1xAH4AMHNxAH4ADgAAAFtxAH4AMnEAfgAzcQB-ACBzcQB-AA4AAACscQB-ACxxAH4ALXEAfgAwc3EAfgAOAAAAzHEAfgA2cQB-ADdxAH4AIHNxAH4ADv____90ABdjb20uc3VuLnByb3h5LiRQcm94eTE5NHBxAH4ASXNxAH4ADgAAAGZ0ACBjb20uY2xvdWQudm0uVm1Xb3JrSm9iRGlzcGF0Y2hlcnQAGFZtV29ya0pvYkRpc3BhdGNoZXIuamF2YXQABnJ1bkpvYnNxAH4ADgAAAip0AD9vcmcuYXBhY2hlLmNsb3Vkc3RhY2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0AAxydW5JbkNvbnRleHRzcQB-AA4AAAAxdAA-b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlJDF0ABtNYW5hZ2VkQ29udGV4dFJ1bm5hYmxlLmphdmF0AANydW5zcQB-AA4AAAA4dABCb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dCQxdAAaRGVmYXVsdE1hbmFnZWRDb250ZXh0LmphdmF0AARjYWxsc3EAfgAOAAAAZ3QAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHRxAH4AZXQAD2NhbGxXaXRoQ29udGV4dHNxAH4ADgAAADVxAH4AaHEAfgBldAAOcnVuV2l0aENvbnRleHRzcQB-AA4AAAAudAA8b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlcQB-AGFxAH4AYnNxAH4ADgAAAfZxAH4AXHEAfgBdcQB-AGJzcQB-AA4AAAH_dAAuamF2YS51dGlsLmNvbmN1cnJlbnQuRXhlY3V0b3JzJFJ1bm5hYmxlQWRhcHRlcnQADkV4ZWN1dG9ycy5qYXZhcQB-AGZzcQB-AA4AAAEKdAAfamF2YS51dGlsLmNvbmN1cnJlbnQuRnV0dXJlVGFza3QAD0Z1dHVyZVRhc2suamF2YXEAfgBic3EAfgAOAAAEdnQAJ2phdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvcnQAF1RocmVhZFBvb2xFeGVjdXRvci5qYXZhdAAJcnVuV29ya2Vyc3EAfgAOAAACaXQALmphdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvciRXb3JrZXJxAH4Ad3EAfgBic3EAfgAOAAAC6XQAEGphdmEubGFuZy5UaHJlYWR0AAtUaHJlYWQuamF2YXEAfgBic3IAJmphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVMaXN0_A8lMbXsjhACAAFMAARsaXN0cQB-AAd4cgAsamF2YS51dGlsLkNvbGxlY3Rpb25zJFVubW9kaWZpYWJsZUNvbGxlY3Rpb24ZQgCAy173HgIAAUwAAWN0ABZMamF2YS91dGlsL0NvbGxlY3Rpb247eHBzcgATamF2YS51dGlsLkFycmF5TGlzdHiB0h2Zx2GdAwABSQAEc2l6ZXhwAAAAAHcEAAAAAHhxAH4Ag3gAABCadwgAAAAAAAAAAHh0ABlGYWlsZWQgdG8gY3JlYXRlIHNuYXBzaG90dXEAfgAMAAAALXNxAH4ADgAAA_9xAH4AGXEAfgAacQB-ABdzcQB-AA7____-cQB-ABxxAH4AHXEAfgAec3EAfgAOAAAAPnEAfgAccQB-AB1xAH4AIHNxAH4ADgAAACtxAH4AInEAfgAjcQB-ACBzcQB-AA4AAAHxcQB-ACVxAH4AJnEAfgAgc3EAfgAOAAABPXEAfgAocQB-AClxAH4AKnNxAH4ADgAAALdxAH4ALHEAfgAtcQB-AC5zcQB-AA4AAACWcQB-ACxxAH4ALXEAfgAwc3EAfgAOAAAAW3EAfgAycQB-ADNxAH4AIHNxAH4ADgAAAKxxAH4ALHEAfgAtcQB-ADBzcQB-AA4AAADMcQB-ADZxAH4AN3EAfgAgc3EAfgAO_____3EAfgA5cHEAfgAXc3EAfgAOAAAGN3EAfgA7cQB-ADxxAH4AF3NxAH4ADgAACCtxAH4APnEAfgA_cQB-AEBzcQB-AA4AAAtDcQB-AD5xAH4AP3EAfgBAc3EAfgAO_____nEAfgAccQB-AB1xAH4AHnNxAH4ADgAAAD5xAH4AHHEAfgAdcQB-ACBzcQB-AA4AAAArcQB-ACJxAH4AI3EAfgAgc3EAfgAOAAAB8XEAfgAlcQB-ACZxAH4AIHNxAH4ADgAAAGtxAH4AR3EAfgBIcQB-AElzcQB-AA4AAAtLcQB-AD5xAH4AP3EAfgBJc3EAfgAO_____nEAfgAccQB-AB1xAH4AHnNxAH4ADgAAAD5xAH4AHHEAfgAdcQB-ACBzcQB-AA4AAAArcQB-ACJxAH4AI3EAfgAgc3EAfgAOAAAB8XEAfgAlcQB-ACZxAH4AIHNxAH4ADgAAAT1xAH4AKHEAfgApcQB-ACpzcQB-AA4AAAC3cQB-ACxxAH4ALXEAfgAuc3EAfgAOAAAAlnEAfgAscQB-AC1xAH4AMHNxAH4ADgAAAFtxAH4AMnEAfgAzcQB-ACBzcQB-AA4AAACscQB-ACxxAH4ALXEAfgAwc3EAfgAOAAAAzHEAfgA2cQB-ADdxAH4AIHNxAH4ADv____9xAH4AVnBxAH4ASXNxAH4ADgAAAGZxAH4AWHEAfgBZcQB-AFpzcQB-AA4AAAIqcQB-AFxxAH4AXXEAfgBec3EAfgAOAAAAMXEAfgBgcQB-AGFxAH4AYnNxAH4ADgAAADhxAH4AZHEAfgBlcQB-AGZzcQB-AA4AAABncQB-AGhxAH4AZXEAfgBpc3EAfgAOAAAANXEAfgBocQB-AGVxAH4Aa3NxAH4ADgAAAC5xAH4AbXEAfgBhcQB-AGJzcQB-AA4AAAH2cQB-AFxxAH4AXXEAfgBic3EAfgAOAAAB_3EAfgBwcQB-AHFxAH4AZnNxAH4ADgAAAQpxAH4Ac3EAfgB0cQB-AGJzcQB-AA4AAAR2cQB-AHZxAH4Ad3EAfgB4c3EAfgAOAAACaXEAfgB6cQB-AHdxAH4AYnNxAH4ADgAAAulxAH4AfHEAfgB9cQB-AGJxAH4AgXgAABCadwgAAAAAAAAAAHh0ABdGYWlsZWQgdG8gdGFrZSBzbmFwc2hvdHVxAH4ADAAAACFzcQB-AA4AAAY6cQB-ADtxAH4APHEAfgAXc3EAfgAOAAAIK3EAfgA-cQB-AD9xAH4AQHNxAH4ADgAAC0NxAH4APnEAfgA_cQB-AEBzcQB-AA7____-cQB-ABxxAH4AHXEAfgAec3EAfgAOAAAAPnEAfgAccQB-AB1xAH4AIHNxAH4ADgAAACtxAH4AInEAfgAjcQB-ACBzcQB-AA4AAAHxcQB-ACVxAH4AJnEAfgAgc3EAfgAOAAAAa3EAfgBHcQB-AEhxAH4ASXNxAH4ADgAAC0txAH4APnEAfgA_cQB-AElzcQB-AA7____-cQB-ABxxAH4AHXEAfgAec3EAfgAOAAAAPnEAfgAccQB-AB1xAH4AIHNxAH4ADgAAACtxAH4AInEAfgAjcQB-ACBzcQB-AA4AAAHxcQB-ACVxAH4AJnEAfgAgc3EAfgAOAAABPXEAfgAocQB-AClxAH4AKnNxAH4ADgAAALdxAH4ALHEAfgAtcQB-AC5zcQB-AA4AAACWcQB-ACxxAH4ALXEAfgAwc3EAfgAOAAAAW3EAfgAycQB-ADNxAH4AIHNxAH4ADgAAAKxxAH4ALHEAfgAtcQB-ADBzcQB-AA4AAADMcQB-ADZxAH4AN3EAfgAgc3EAfgAO_____3EAfgBWcHEAfgBJc3EAfgAOAAAAZnEAfgBYcQB-AFlxAH4AWnNxAH4ADgAAAipxAH4AXHEAfgBdcQB-AF5zcQB-AA4AAAAxcQB-AGBxAH4AYXEAfgBic3EAfgAOAAAAOHEAfgBkcQB-AGVxAH4AZnNxAH4ADgAAAGdxAH4AaHEAfgBlcQB-AGlzcQB-AA4AAAA1cQB-AGhxAH4AZXEAfgBrc3EAfgAOAAAALnEAfgBtcQB-AGFxAH4AYnNxAH4ADgAAAfZxAH4AXHEAfgBdcQB-AGJzcQB-AA4AAAH_cQB-AHBxAH4AcXEAfgBmc3EAfgAOAAABCnEAfgBzcQB-AHRxAH4AYnNxAH4ADgAABHZxAH4AdnEAfgB3cQB-AHhzcQB-AA4AAAJpcQB-AHpxAH4Ad3EAfgBic3EAfgAOAAAC6XEAfgB8cQB-AH1xAH4AYnEAfgCBeAAAEJp3CAAAAAAAAAAAeA 2016-02-17 14:42:55,376 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-51:ctx-f6739a2f job-2524/job-2527) (logid:0a96ee1e) Publish async job-2527 complete on message bus 2016-02-17 14:42:55,377 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-51:ctx-f6739a2f job-2524/job-2527) (logid:0a96ee1e) Wake up jobs related to job-2527 2016-02-17 14:42:55,377 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-51:ctx-f6739a2f job-2524/job-2527) (logid:0a96ee1e) Update db status for job-2527 2016-02-17 14:42:55,383 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-51:ctx-f6739a2f job-2524/job-2527) (logid:0a96ee1e) Wake up jobs joined with job-2527 and disjoin all subjobs created from job- 2527 2016-02-17 14:42:55,400 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-51:ctx-f6739a2f job-2524/job-2527) (logid:0a96ee1e) Done executing com.cloud.vm.VmWorkTakeVolumeSnapshot for job-2527 2016-02-17 14:42:55,409 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-51:ctx-f6739a2f job-2524/job-2527) (logid:0a96ee1e) Remove job-2527 from job monitoring 2016-02-17 14:42:55,456 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-82:ctx-3b960545 job-2524) (logid:0a96ee1e) Complete async job-2524, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Failed to create snapshot due to an internal error creating snapshot for volume 355"} 2016-02-17 14:42:55,462 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-82:ctx-3b960545 job-2524) (logid:0a96ee1e) Publish async job-2524 complete on message bus 2016-02-17 14:42:55,462 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-82:ctx-3b960545 job-2524) (logid:0a96ee1e) Wake up jobs related to job-2524 2016-02-17 14:42:55,462 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-82:ctx-3b960545 job-2524) (logid:0a96ee1e) Update db status for job-2524 2016-02-17 14:42:55,467 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-82:ctx-3b960545 job-2524) (logid:0a96ee1e) Wake up jobs joined with job-2524 and disjoin all subjobs created from job- 2524 2016-02-17 14:42:55,475 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-82:ctx-3b960545 job-2524) (logid:0a96ee1e) Done executing org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd for job-2524 2016-02-17 14:42:55,475 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-82:ctx-3b960545 job-2524) (logid:0a96ee1e) Remove job-2524 from job monitoring
