cloudstack-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Yuriy Karpel <yu...@karpel.su>
Subject kvm, snapshot create error
Date Wed, 17 Feb 2016 13:16:17 GMT
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

Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message