cloudstack-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Yuriy Karpel <yu...@karpel.su>
Subject Re: kvm, snapshot create error
Date Thu, 18 Feb 2016 07:26:53 GMT
UPD:
s3. RadosGW config:

[client.rgw.srv-rgw01]
rgw_print_continue = false
host = srv-rgw01
rgw dns name = s3.cloud.bst.su
rgw_frontends = civetweb port=80
rgw_socket_path = /tmp/radosgw.sock

[client.rgw.srv-rgw02]
rgw_print_continue = false
host = srv-rgw01
rgw dns name = s3.cloud.bst.su
rgw_frontends = civetweb port=80
rgw_socket_path = /tmp/radosgw.sock



[ceph@ceph-adm ~]s3cmd -c s3test.cfg ls
2016-02-18 06:37  s3://cl-images
[ceph@ceph-adm ~]$ s3cmd -c s3test.cfg put s3test.cfg s3://cl-images
upload: 's3test.cfg' -> 's3://cl-images/s3test.cfg'  [1 of 1]
 1949 of 1949   100% in    0s   241.14 kB/s  done
upload: 's3test.cfg' -> 's3://cl-images/s3test.cfg'  [1 of 1]
 1949 of 1949   100% in    0s    99.51 kB/s  done
[ceph@ceph-adm ~]$ s3cmd -c s3test.cfg la
2016-02-18 07:23      1949   s3://cl-images/s3test.cfg
[ceph@ceph-adm ~]$ s3cmd -c s3test.cfg rm s3://cl-images/s3test.cfg
delete: 's3://cl-images/s3test.cfg'
[ceph@ceph-adm ~]$ s3cmd -c s3test.cfg ls
2016-02-18 06:37  s3://cl-images


2016-02-18 10:16 GMT+03:00 Yuriy Karpel <yuriy@karpel.su>:

> S3 Error:
> 2016-02-18 10:12:30,707 DEBUG [c.c.a.ApiServlet]
> (catalina-exec-22:ctx-692943aa) (logid:b587a934) ===START===  10.30.10.41
> -- GET
>  command=addImageStore&response=json&name=Images&provider=S3&details%5B2%5D.key=bucket&details%5B2%5D.value=cl-images&details%5B3%5D.key=usehttps&details%5B3%5D.value=false&details%5B4%5D.key=endpoint&details%5B4%5D.value=
> s3.cloud.bst.su&_=1455779550451
> 2016-02-18 10:12:30,741 INFO  [o.a.c.s.d.l.S3ImageStoreLifeCycleImpl]
> (catalina-exec-22:ctx-692943aa ctx-dcc03fdb) (logid:b587a934) Trying to add
> a S3 store with endpoint: s3.cloud.bst.su
> 2016-02-18 10:12:30,913 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl]
> (catalina-exec-22:ctx-692943aa ctx-dcc03fdb) (logid:b587a934) template 3 is
> already in store:91, type:Image
> 2016-02-18 10:12:30,931 DEBUG [o.a.c.s.i.BaseImageStoreDriverImpl]
> (catalina-exec-22:ctx-692943aa ctx-dcc03fdb) (logid:b587a934) Downloading
> template to data store 91
> 2016-02-18 10:12:31,002 DEBUG [o.a.c.s.i.BaseImageStoreDriverImpl]
> (catalina-exec-22:ctx-692943aa ctx-dcc03fdb) (logid:b587a934) Performing
> image store createTemplate async callback
> 2016-02-18 10:12:31,317 INFO  [o.a.c.s.i.d.TemplateDataStoreDaoImpl]
> (catalina-exec-22:ctx-692943aa ctx-dcc03fdb) (logid:b587a934) Duplicate 0
> template cache store records to region store
> 2016-02-18 10:12:31,322 INFO  [o.a.c.s.i.d.SnapshotDataStoreDaoImpl]
> (catalina-exec-22:ctx-692943aa ctx-dcc03fdb) (logid:b587a934) Duplicate 0
> snapshot cache store records to region store
> 2016-02-18 10:12:31,339 INFO  [o.a.c.s.i.d.VolumeDataStoreDaoImpl]
> (catalina-exec-22:ctx-692943aa ctx-dcc03fdb) (logid:b587a934) Duplicate 0
> volume cache store records to region store
> 2016-02-18 10:12:31,351 DEBUG [c.c.a.ApiServlet]
> (catalina-exec-22:ctx-692943aa ctx-dcc03fdb) (logid:b587a934) ===END===
>  10.30.10.41 -- GET
>  command=addImageStore&response=json&name=Images&provider=S3&details%5B2%5D.key=bucket&details%5B2%5D.value=cl-images&details%5B3%5D.key=usehttps&details%5B3%5D.value=false&details%5B4%5D.key=endpoint&details%5B4%5D.value=s3.cloud.bst-su&_=1455779550451
> 2016-02-18 10:12:38,882 INFO  [o.a.c.f.j.i.AsyncJobManagerImpl]
> (AsyncJobMgr-Heartbeat-1:ctx-b7b15564) (logid:a3fcba8f) Begin cleanup
> expired async-jobs
> 2016-02-18 10:12:38,909 INFO  [o.a.c.f.j.i.AsyncJobManagerImpl]
> (AsyncJobMgr-Heartbeat-1:ctx-b7b15564) (logid:a3fcba8f) End cleanup expired
> async-jobs
> 2016-02-18 10:12:41,020 DEBUG [c.c.u.n.HTTPUtils]
> (pool-10-thread-1:ctx-38ab02de) (logid:a6a55e58) Initializing new
> HttpMethodRetryHandler with retry count 5
> 2016-02-18 10:12:41,030 INFO  [c.c.s.t.S3TemplateDownloader]
> (pool-9-thread-1:ctx-d4d0b7c3) (logid:c652699b) Starting download from
> http://10.30.10.3/mrepo/ISO/systemvm64template-4.6.0-kvm.qcow2.bz2 to S3
> bucket cl-images and size 319401369 bytes
> 2016-02-18 10:12:41,030 DEBUG [c.c.u.s.S.S3Utils]
> (pool-9-thread-1:ctx-d4d0b7c3) (logid:c652699b) Sending stream as S3 object
> template/tmpl/1/3/routing-3/systemvm64template-4.6.0-kvm.qcow2.bz2 in
> bucket cl-images using PutObjectRequest
> 2016-02-18 10:12:41,030 DEBUG [c.c.u.s.S.S3Utils]
> (pool-9-thread-1:ctx-d4d0b7c3) (logid:c652699b) Creating S3 client with
> configuration: [protocol: http, signer: null, connectionTimeOut: 50000,
> maxErrorRetry: -1, socketTimeout: 50000, useTCPKeepAlive: null,
> connectionTtl: null]
> 2016-02-18 10:12:41,038 DEBUG [c.c.u.s.S.S3Utils]
> (pool-9-thread-1:ctx-d4d0b7c3) (logid:c652699b) Setting the end point for
> S3 client with access key IONTKFQF1TUIRZ1BLGAO to s3.cloud.bst.su.
> 2016-02-18 10:12:44,021 DEBUG [o.a.c.s.i.BaseImageStoreDriverImpl]
> (pool-10-thread-1:ctx-38ab02de) (logid:a6a55e58) Performing image store
> createTemplate async callback
> 2016-02-18 10:12:44,076 WARN  [o.a.c.alerts]
> (pool-10-thread-1:ctx-38ab02de) (logid:a6a55e58)  alertType:: 28 //
> dataCenterId:: 4 // podId:: null // clusterId:: null // message:: Failed to
> register template: dc7e53a0-4615-43a1-8bf0-2ce51b246a33 with error:
> 2016-02-18 10:12:44,091 ERROR [o.a.c.s.i.BaseImageStoreDriverImpl]
> (pool-10-thread-1:ctx-38ab02de) (logid:a6a55e58) Failed to register
> template: dc7e53a0-4615-43a1-8bf0-2ce51b246a33 with error:
> 2016-02-18 10:12:44,815 DEBUG [c.c.a.m.ClusteredAgentAttache]
> (AgentManager-Handler-13:null) (logid:) Seq 121-6638305850744119545:
> Routing from 121491073759284
> 2016-02-18 10:12:44,818 DEBUG [c.c.a.m.ClusteredAgentManagerImpl]
> (AgentManager-Handler-2:null) (logid:) Seq 121-6638305850744119545: MgmtId
> 121491073759284: Resp: Routing to peer
> 2016-02-18 10:12:48,883 INFO  [o.a.c.f.j.i.AsyncJobManagerImpl]
> (AsyncJobMgr-Heartbeat-1:ctx-e47445ff) (logid:1c1cc9e3) Begin cleanup
> expired async-jobs
> 2016-02-18 10:12:48,913 INFO  [o.a.c.f.j.i.AsyncJobManagerImpl]
> (AsyncJobMgr-Heartbeat-1:ctx-e47445ff) (logid:1c1cc9e3) End cleanup expired
> async-jobs
> 2016-02-18 10:12:48,929 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:ctx-7f832e66) (logid:1df7dab6) Found 0 routers to
> update status.
> 2016-02-18 10:12:48,935 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:ctx-7f832e66) (logid:1df7dab6) Found 0 VPC networks
> to update Redundant State.
> 2016-02-18 10:12:48,941 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:ctx-7f832e66) (logid:1df7dab6) Found 0 networks to
> update RvR status.
> 2016-02-18 10:12:49,062 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:ctx-94526f96) (logid:c7046ad8) Found 0 routers to
> update status.
> 2016-02-18 10:12:49,068 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:ctx-94526f96) (logid:c7046ad8) Found 0 VPC networks
> to update Redundant State.
> 2016-02-18 10:12:49,074 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:ctx-94526f96) (logid:c7046ad8) Found 0 networks to
> update RvR status.
>
>
> 2016-02-17 23:20 GMT+03:00 Simon Weller <sweller@ena.com>:
>
>> 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 <yuriy@karpel.su>
>> Sent: Wednesday, February 17, 2016 7:16 AM
>> To: users@cloudstack.apache.org
>> 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
>>
>
>

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