cloudstack-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "ASF subversion and git services (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (CLOUDSTACK-6900) If we download a volume and then migrate the same volume, then migration fails.
Date Mon, 02 Mar 2015 11:12:05 GMT

    [ https://issues.apache.org/jira/browse/CLOUDSTACK-6900?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14343037#comment-14343037 ] 

ASF subversion and git services commented on CLOUDSTACK-6900:
-------------------------------------------------------------

Commit 91e1881be82b06963903b7ee6aa15cdbcc04705f in cloudstack's branch refs/heads/master from [~anshulg]
[ https://git-wip-us.apache.org/repos/asf?p=cloudstack.git;h=91e1881 ]

CLOUDSTACK-6900: This fixes volume migration failing after that volume is downloaded.

When we download volume then we create entry in volume_store_ref table.
We mark the volume entry to ready state once download_url gets generated.
When we migrate that volume, then again one more entry is created with same volume id.
Its state is marked as allocated. Later we try to list only one dataobject in datastore
for state transition during volume migration. If the listed volume's state is allocated
then migration passes otherwise it fails.

Below fix will remove the randomness and give priority to volume entry which is made for
migration (download_url/extracturl will be null in case of migration). Giving priority to
download volume case is not needed as there will be only one entry in that case so no randomness.


> If we download a volume and then migrate the same volume, then migration fails.
> -------------------------------------------------------------------------------
>
>                 Key: CLOUDSTACK-6900
>                 URL: https://issues.apache.org/jira/browse/CLOUDSTACK-6900
>             Project: CloudStack
>          Issue Type: Bug
>      Security Level: Public(Anyone can view this level - this is the default.) 
>          Components: Management Server, Storage Controller
>    Affects Versions: 4.4.0
>         Environment: Hyper-V
>            Reporter: Abhinav Roy
>            Assignee: Anshul Gangwar
>             Fix For: Future
>
>         Attachments: CS-6900.zip
>
>
> Steps:
> ======================
> 1. Deploy advanced zone hyper-v setup.
> 2. create a vm, v1
> 3. stop v1 ( stop vm if you want to do operation on root volume, and detach the datadisk if you want to do operation on data disk. In this example I am using root volume. )
> 4. Goto the root volume of v1 and download the volume.
> 5. After download is finished, migrate the root volume.
> Expected behavior :
> ==========================
> Migration of the volume should succeed.
> Observed behavior :
> =========================
> Migration fails with the following error :
> 2014-06-12 16:46:26,814 DEBUG [c.c.a.ApiServlet] (catalina-exec-22:ctx-2542e5b1) ===START===  10.144.6.9 -- GET  command=migrateVolume&livemigrate=true&storageid=b3fcb49c-b870-33e6-86f2-bb1eb72cceef&volumeid=b3f11294-032e-4de2-b6c3-aed65fd86ba8&response=json&sessionkey=fFhNiWQ7rfYWJRz28KaKz5M%2BFkM%3D&_=1402571443688
> 2014-06-12 16:46:26,835 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (catalina-exec-22:ctx-2542e5b1 ctx-1c5b4ecf) submit async job-250, details: AsyncJobVO {id:250, userId: 2, accountId: 2, instanceType: None, instanceId: null, cmd: org.apache.cloudstack.api.command.admin.volume.MigrateVolumeCmdByAdmin, cmdInfo: {"response":"json","sessionkey":"fFhNiWQ7rfYWJRz28KaKz5M+FkM\u003d","ctxDetails":"{\"com.cloud.storage.Volume\":40,\"com.cloud.storage.StoragePool\":5}","cmdEventType":"VOLUME.MIGRATE","ctxUserId":"2","storageid":"b3fcb49c-b870-33e6-86f2-bb1eb72cceef","livemigrate":"true","httpmethod":"GET","volumeid":"b3f11294-032e-4de2-b6c3-aed65fd86ba8","_":"1402571443688","ctxAccountId":"2","ctxStartEventId":"412"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 213737702773493, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
> 2014-06-12 16:46:26,836 DEBUG [c.c.a.ApiServlet] (catalina-exec-22:ctx-2542e5b1 ctx-1c5b4ecf) ===END===  10.144.6.9 -- GET  command=migrateVolume&livemigrate=true&storageid=b3fcb49c-b870-33e6-86f2-bb1eb72cceef&volumeid=b3f11294-032e-4de2-b6c3-aed65fd86ba8&response=json&sessionkey=fFhNiWQ7rfYWJRz28KaKz5M%2BFkM%3D&_=1402571443688
> 2014-06-12 16:46:26,837 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-21:ctx-4b7caee5 job-250) Add job-250 into job monitoring
> 2014-06-12 16:46:26,837 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-21:ctx-4b7caee5 job-250) Executing AsyncJobVO {id:250, userId: 2, accountId: 2, instanceType: None, instanceId: null, cmd: org.apache.cloudstack.api.command.admin.volume.MigrateVolumeCmdByAdmin, cmdInfo: {"response":"json","sessionkey":"fFhNiWQ7rfYWJRz28KaKz5M+FkM\u003d","ctxDetails":"{\"com.cloud.storage.Volume\":40,\"com.cloud.storage.StoragePool\":5}","cmdEventType":"VOLUME.MIGRATE","ctxUserId":"2","storageid":"b3fcb49c-b870-33e6-86f2-bb1eb72cceef","livemigrate":"true","httpmethod":"GET","volumeid":"b3f11294-032e-4de2-b6c3-aed65fd86ba8","_":"1402571443688","ctxAccountId":"2","ctxStartEventId":"412"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 213737702773493, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
> 2014-06-12 16:46:26,843 WARN  [c.c.a.d.ParamGenericValidationWorker] (API-Job-Executor-21:ctx-4b7caee5 job-250 ctx-b55eef92) Received unknown parameters for command migrateVolume. Unknown parameters : ctxdetails
> 2014-06-12 16:46:26,854 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-21:ctx-4b7caee5 job-250 ctx-b55eef92) Sync job-251 execution on object VmWorkJobQueue.20
> 2014-06-12 16:46:26,857 WARN  [c.c.u.d.Merovingian2] (API-Job-Executor-21:ctx-4b7caee5 job-250 ctx-b55eef92) Was unable to find lock for the key vm_instance20 and thread id 399445600
> 2014-06-12 16:46:27,079 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-eab33c28) Zone 1 is ready to launch secondary storage VM
> 2014-06-12 16:46:27,226 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-2401b544) Zone 1 is ready to launch console proxy
> 2014-06-12 16:46:27,763 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgentCronJob-254:ctx-c37c0893) POST request to https://10.102.244.25:8250/api/HypervResource/org.apache.cloudstack.HostVmStateReportCommand with contents {}
> 2014-06-12 16:46:27,765 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgentCronJob-314:ctx-6aa43526) POST request to https://10.102.244.20:8250/api/HypervResource/org.apache.cloudstack.HostVmStateReportCommand with contents {}
> 2014-06-12 16:46:27,769 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgentCronJob-314:ctx-6aa43526) Sending cmd to https://10.102.244.20:8250/api/HypervResource/org.apache.cloudstack.HostVmStateReportCommand cmd data:{}
> 2014-06-12 16:46:27,771 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgentCronJob-254:ctx-c37c0893) Sending cmd to https://10.102.244.25:8250/api/HypervResource/org.apache.cloudstack.HostVmStateReportCommand cmd data:{}
> 2014-06-12 16:46:27,790 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgentCronJob-135:ctx-fa05e280) POST request to https://10.102.244.21:8250/api/HypervResource/org.apache.cloudstack.HostVmStateReportCommand with contents {}
> 2014-06-12 16:46:27,793 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgentCronJob-135:ctx-fa05e280) Sending cmd to https://10.102.244.21:8250/api/HypervResource/org.apache.cloudstack.HostVmStateReportCommand cmd data:{}
> 2014-06-12 16:46:27,845 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgentCronJob-254:ctx-c37c0893) POST response is [{"i-2-15-VM":"PowerOn"},{"i-2-6-VM":"PowerOn"}]
> 2014-06-12 16:46:27,846 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgentCronJob-254:ctx-c37c0893) HostVmStateReportCommand received response [{"i-2-15-VM":"PowerOn"},{"i-2-6-VM":"PowerOn"}]
> 2014-06-12 16:46:27,846 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgentCronJob-254:ctx-c37c0893) Ping host 10.102.244.25 (IP 10.102.244.25)
> 2014-06-12 16:46:27,846 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgentCronJob-254:ctx-c37c0893) POST request to https://10.102.244.25:8250/api/HypervResource/com.cloud.agent.api.PingRoutingCommand with contents {"_hostVmStateReport":{"i-2-6-VM":{"state":"PowerOn","host":"0ede929f-e4be-31e7-a0fa-6d29aa133276-HypervResource"},"i-2-15-VM":{"state":"PowerOn","host":"0ede929f-e4be-31e7-a0fa-6d29aa133276-HypervResource"}},"_gatewayAccessible":true,"_vnetAccessible":true,"hostType":"Routing","hostId":5,"contextMap":{},"wait":0}
> 2014-06-12 16:46:27,847 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgentCronJob-314:ctx-6aa43526) POST response is [{"s-2-VM":"PowerOn"},{"r-4-VM":"PowerOn"},{"v-1-VM":"PowerOn"},{"i-2-9-VM":"PowerOn"}]
> 2014-06-12 16:46:27,847 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgentCronJob-314:ctx-6aa43526) HostVmStateReportCommand received response [{"s-2-VM":"PowerOn"},{"r-4-VM":"PowerOn"},{"v-1-VM":"PowerOn"},{"i-2-9-VM":"PowerOn"}]
> 2014-06-12 16:46:27,847 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgentCronJob-314:ctx-6aa43526) Ping host 10.102.244.20 (IP 10.102.244.20)
> 2014-06-12 16:46:27,848 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgentCronJob-314:ctx-6aa43526) POST request to https://10.102.244.20:8250/api/HypervResource/com.cloud.agent.api.PingRoutingCommand with contents {"_hostVmStateReport":{"i-2-9-VM":{"state":"PowerOn","host":"c5034950-d1a2-3368-8c8f-77a2cb0d49d2-HypervResource"},"r-4-VM":{"state":"PowerOn","host":"c5034950-d1a2-3368-8c8f-77a2cb0d49d2-HypervResource"},"v-1-VM":{"state":"PowerOn","host":"c5034950-d1a2-3368-8c8f-77a2cb0d49d2-HypervResource"},"s-2-VM":{"state":"PowerOn","host":"c5034950-d1a2-3368-8c8f-77a2cb0d49d2-HypervResource"}},"_gatewayAccessible":true,"_vnetAccessible":true,"hostType":"Routing","hostId":1,"contextMap":{},"wait":0}
> 2014-06-12 16:46:27,853 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgentCronJob-254:ctx-c37c0893) Sending cmd to https://10.102.244.25:8250/api/HypervResource/com.cloud.agent.api.PingRoutingCommand cmd data:{"_hostVmStateReport":{"i-2-6-VM":{"state":"PowerOn","host":"0ede929f-e4be-31e7-a0fa-6d29aa133276-HypervResource"},"i-2-15-VM":{"state":"PowerOn","host":"0ede929f-e4be-31e7-a0fa-6d29aa133276-HypervResource"}},"_gatewayAccessible":true,"_vnetAccessible":true,"hostType":"Routing","hostId":5,"contextMap":{},"wait":0}
> 2014-06-12 16:46:27,854 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgentCronJob-314:ctx-6aa43526) Sending cmd to https://10.102.244.20:8250/api/HypervResource/com.cloud.agent.api.PingRoutingCommand cmd data:{"_hostVmStateReport":{"i-2-9-VM":{"state":"PowerOn","host":"c5034950-d1a2-3368-8c8f-77a2cb0d49d2-HypervResource"},"r-4-VM":{"state":"PowerOn","host":"c5034950-d1a2-3368-8c8f-77a2cb0d49d2-HypervResource"},"v-1-VM":{"state":"PowerOn","host":"c5034950-d1a2-3368-8c8f-77a2cb0d49d2-HypervResource"},"s-2-VM":{"state":"PowerOn","host":"c5034950-d1a2-3368-8c8f-77a2cb0d49d2-HypervResource"}},"_gatewayAccessible":true,"_vnetAccessible":true,"hostType":"Routing","hostId":1,"contextMap":{},"wait":0}
> 2014-06-12 16:46:27,866 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgentCronJob-135:ctx-fa05e280) POST response is [{"i-2-17-VM":"PowerOn"}]
> 2014-06-12 16:46:27,866 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgentCronJob-135:ctx-fa05e280) HostVmStateReportCommand received response [{"i-2-17-VM":"PowerOn"}]
> 2014-06-12 16:46:27,866 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgentCronJob-135:ctx-fa05e280) Ping host 10.102.244.21 (IP 10.102.244.21)
> 2014-06-12 16:46:27,866 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgentCronJob-135:ctx-fa05e280) POST request to https://10.102.244.21:8250/api/HypervResource/com.cloud.agent.api.PingRoutingCommand with contents {"_hostVmStateReport":{"i-2-17-VM":{"state":"PowerOn","host":"c03aa877-a1af-315c-a2c2-2b10f128b1a3-HypervResource"}},"_gatewayAccessible":true,"_vnetAccessible":true,"hostType":"Routing","hostId":4,"contextMap":{},"wait":0}
> 2014-06-12 16:46:27,869 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgentCronJob-135:ctx-fa05e280) Sending cmd to https://10.102.244.21:8250/api/HypervResource/com.cloud.agent.api.PingRoutingCommand cmd data:{"_hostVmStateReport":{"i-2-17-VM":{"state":"PowerOn","host":"c03aa877-a1af-315c-a2c2-2b10f128b1a3-HypervResource"}},"_gatewayAccessible":true,"_vnetAccessible":true,"hostType":"Routing","hostId":4,"contextMap":{},"wait":0}
> 2014-06-12 16:46:27,912 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgentCronJob-314:ctx-6aa43526) POST response is [{"com.cloud.agent.api.Answer":{"result":true,"details":"success - NOP for PingRoutingCommand","_reconnect":false,"contextMap":{}}}]
> 2014-06-12 16:46:27,912 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgentCronJob-314:ctx-6aa43526) executeRequest received response [Lcom.cloud.agent.api.Answer;@3e6708a4
> 2014-06-12 16:46:27,912 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgentCronJob-314:ctx-6aa43526) Ping from 1(10.102.244.20)
> 2014-06-12 16:46:27,912 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-314:ctx-6aa43526) Process host VM state report from ping process. host: 1
> 2014-06-12 16:46:27,920 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgentCronJob-254:ctx-c37c0893) POST response is [{"com.cloud.agent.api.Answer":{"result":true,"details":"success - NOP for PingRoutingCommand","_reconnect":false,"contextMap":{}}}]
> 2014-06-12 16:46:27,920 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgentCronJob-254:ctx-c37c0893) executeRequest received response [Lcom.cloud.agent.api.Answer;@5f5988cb
> 2014-06-12 16:46:27,920 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgentCronJob-254:ctx-c37c0893) Ping from 5(10.102.244.25)
> 2014-06-12 16:46:27,920 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-254:ctx-c37c0893) Process host VM state report from ping process. host: 5
> 2014-06-12 16:46:27,925 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-254:ctx-c37c0893) Process VM state report. host: 5, number of records in report: 2
> 2014-06-12 16:46:27,926 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-254:ctx-c37c0893) VM state report. host: 5, vm id: 6, power state: PowerOn
> 2014-06-12 16:46:27,926 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-314:ctx-6aa43526) Process VM state report. host: 1, number of records in report: 4
> 2014-06-12 16:46:27,928 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-314:ctx-6aa43526) VM state report. host: 1, vm id: 1, power state: PowerOn
> 2014-06-12 16:46:27,931 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-254:ctx-c37c0893) VM power state does not change, skip DB writing. vm id: 6
> 2014-06-12 16:46:27,931 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-254:ctx-c37c0893) VM state report. host: 5, vm id: 15, power state: PowerOn
> 2014-06-12 16:46:27,932 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgentCronJob-135:ctx-fa05e280) POST response is [{"com.cloud.agent.api.Answer":{"result":true,"details":"success - NOP for PingRoutingCommand","_reconnect":false,"contextMap":{}}}]
> 2014-06-12 16:46:27,932 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgentCronJob-135:ctx-fa05e280) executeRequest received response [Lcom.cloud.agent.api.Answer;@2ad4e251
> 2014-06-12 16:46:27,932 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgentCronJob-135:ctx-fa05e280) Ping from 4(10.102.244.21)
> 2014-06-12 16:46:27,932 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-135:ctx-fa05e280) Process host VM state report from ping process. host: 4
> 2014-06-12 16:46:27,934 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-135:ctx-fa05e280) Process VM state report. host: 4, number of records in report: 1
> 2014-06-12 16:46:27,934 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-135:ctx-fa05e280) VM state report. host: 4, vm id: 17, power state: PowerOn
> 2014-06-12 16:46:27,937 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-314:ctx-6aa43526) VM power state does not change, skip DB writing. vm id: 1
> 2014-06-12 16:46:27,938 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-314:ctx-6aa43526) VM state report. host: 1, vm id: 2, power state: PowerOn
> 2014-06-12 16:46:27,941 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-135:ctx-fa05e280) VM power state does not change, skip DB writing. vm id: 17
> 2014-06-12 16:46:27,943 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-135:ctx-fa05e280) Done with process of VM state report. host: 4
> 2014-06-12 16:46:27,943 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-314:ctx-6aa43526) VM power state does not change, skip DB writing. vm id: 2
> 2014-06-12 16:46:27,944 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-314:ctx-6aa43526) VM state report. host: 1, vm id: 4, power state: PowerOn
> 2014-06-12 16:46:27,943 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-254:ctx-c37c0893) VM power state does not change, skip DB writing. vm id: 15
> 2014-06-12 16:46:27,947 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-254:ctx-c37c0893) Done with process of VM state report. host: 5
> 2014-06-12 16:46:27,951 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-314:ctx-6aa43526) VM power state does not change, skip DB writing. vm id: 4
> 2014-06-12 16:46:27,952 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-314:ctx-6aa43526) VM state report. host: 1, vm id: 9, power state: PowerOn
> 2014-06-12 16:46:27,956 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-314:ctx-6aa43526) VM power state does not change, skip DB writing. vm id: 9
> 2014-06-12 16:46:27,960 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-314:ctx-6aa43526) Done with process of VM state report. host: 1
> 2014-06-12 16:46:28,034 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-12:null) SeqA 2-147872: Processing Seq 2-147872:  { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
> 2014-06-12 16:46:28,038 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-12:null) SeqA 2-147872: Sending Seq 2-147872:  { Ans: , MgmtId: 213737702773493, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-06-12 16:46:28,122 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-0e4aadab) Execute sync-queue item: SyncQueueItemVO {id:101, queueId: 99, contentType: AsyncJob, contentId: 251, lastProcessMsid: null, lastprocessNumber: null, lastProcessTime: null, created: Thu Jun 12 16:46:26 IST 2014}
> 2014-06-12 16:46:28,124 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-0e4aadab) Schedule queued job-251
> 2014-06-12 16:46:28,129 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-16:ctx-6063e5f5 job-250/job-251) Add job-251 into job monitoring
> 2014-06-12 16:46:28,130 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-16:ctx-6063e5f5 job-250/job-251) Executing AsyncJobVO {id:251, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.storage.VmWorkMigrateVolume, cmdInfo: rO0ABXNyACVjb20uY2xvdWQuc3RvcmFnZS5WbVdvcmtNaWdyYXRlVm9sdW1l-CXzb7zvU-YCAANKAApkZXN0UG9vbElkWgALbGl2ZU1pZ3JhdGVKAAh2b2x1bWVJZHhyABNjb20uY2xvdWQudm0uVm1Xb3Jrn5m2VvAlZ2sCAARKAAlhY2NvdW50SWRKAAZ1c2VySWRKAAR2bUlkTAALaGFuZGxlck5hbWV0ABJMamF2YS9sYW5nL1N0cmluZzt4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAFHQAFFZvbHVtZUFwaVNlcnZpY2VJbXBsAAAAAAAAAAUAAAAAAAAAACg, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 213737702773493, completeMsid: null, lastUpdated: null, lastPolled: null, created: Thu Jun 12 16:46:26 IST 2014}
> 2014-06-12 16:46:28,130 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-16:ctx-6063e5f5 job-250/job-251) Run VM work job: com.cloud.storage.VmWorkMigrateVolume for VM 20, job origin: 250
> 2014-06-12 16:46:28,132 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-16:ctx-6063e5f5 job-250/job-251 ctx-024db267) Execute VM work job: com.cloud.storage.VmWorkMigrateVolume{"volumeId":40,"destPoolId":5,"liveMigrate":false,"userId":2,"accountId":2,"vmId":20,"handlerName":"VolumeApiServiceImpl"}
> 2014-06-12 16:46:28,180 DEBUG [o.a.c.s.m.AncientDataMotionStrategy] (Work-Job-Executor-16:ctx-6063e5f5 job-250/job-251 ctx-024db267) copyAsync inspecting src type VOLUME copyAsync inspecting dest type VOLUME
> 2014-06-12 16:46:28,183 DEBUG [o.a.c.s.c.a.StorageCacheRandomAllocator] (Work-Job-Executor-16:ctx-6063e5f5 job-250/job-251 ctx-024db267) Can't find staging storage in zone: 1
> 2014-06-12 16:46:28,219 DEBUG [c.c.a.t.Request] (Work-Job-Executor-16:ctx-6063e5f5 job-250/job-251 ctx-024db267) Seq 5-4892879520161343077: Sending  { Cmd , MgmtId: 213737702773493, via: 5(10.102.244.25), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"b3f11294-032e-4de2-b6c3-aed65fd86ba8","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"3f754d4f-365c-3bd1-93d1-c3c9947fb3cc","id":9,"poolType":"SMB","host":"SMB19","path":"/hyperv-share/abhinav-ps6?user=abhinavroy&domain=BLR","port":445,"url":"SMB://SMB19/hyperv-share/abhinav-ps6?user=abhinavroy&domain=BLR/?ROLE=Primary&STOREUUID=3f754d4f-365c-3bd1-93d1-c3c9947fb3cc"}},"name":"ROOT-20","size":10737418240,"path":"b3f11294-032e-4de2-b6c3-aed65fd86ba8","volumeId":40,"vmName":"i-2-20-VM","accountId":2,"format":"VHD","id":40,"deviceId":0,"hypervisorType":"Hyperv"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"b3f11294-032e-4de2-b6c3-aed65fd86ba8","volumeType":"ROOT","dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"cifs://10.102.192.19/hyperv-share/abhinav-ss1?user=abhinavroy&domain=BLR","_role":"Image"}},"name":"ROOT-20","size":10737418240,"path":"volumes/2/40","volumeId":40,"vmName":"i-2-20-VM","accountId":2,"format":"VHD","id":40,"deviceId":0,"hypervisorType":"Hyperv"}},"executeInSequence":false,"options":{},"wait":10800}}] }
> 2014-06-12 16:46:28,220 DEBUG [c.c.a.t.Request] (Work-Job-Executor-16:ctx-6063e5f5 job-250/job-251 ctx-024db267) Seq 5-4892879520161343077: Executing:  { Cmd , MgmtId: 213737702773493, via: 5(10.102.244.25), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"b3f11294-032e-4de2-b6c3-aed65fd86ba8","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"3f754d4f-365c-3bd1-93d1-c3c9947fb3cc","id":9,"poolType":"SMB","host":"SMB19","path":"/hyperv-share/abhinav-ps6?user=abhinavroy&domain=BLR","port":445,"url":"SMB://SMB19/hyperv-share/abhinav-ps6?user=abhinavroy&domain=BLR/?ROLE=Primary&STOREUUID=3f754d4f-365c-3bd1-93d1-c3c9947fb3cc"}},"name":"ROOT-20","size":10737418240,"path":"b3f11294-032e-4de2-b6c3-aed65fd86ba8","volumeId":40,"vmName":"i-2-20-VM","accountId":2,"format":"VHD","id":40,"deviceId":0,"hypervisorType":"Hyperv"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"b3f11294-032e-4de2-b6c3-aed65fd86ba8","volumeType":"ROOT","dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"cifs://10.102.192.19/hyperv-share/abhinav-ss1?user=abhinavroy&domain=BLR","_role":"Image"}},"name":"ROOT-20","size":10737418240,"path":"volumes/2/40","volumeId":40,"vmName":"i-2-20-VM","accountId":2,"format":"VHD","id":40,"deviceId":0,"hypervisorType":"Hyperv"}},"executeInSequence":false,"options":{},"wait":10800}}] }
> 2014-06-12 16:46:28,220 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-246:ctx-c26c3041) Seq 5-4892879520161343077: Executing request
> 2014-06-12 16:46:28,221 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-246:ctx-c26c3041) POST request to https://10.102.244.25:8250/api/HypervResource/org.apache.cloudstack.storage.command.CopyCommand with contents {"srcTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"b3f11294-032e-4de2-b6c3-aed65fd86ba8","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"3f754d4f-365c-3bd1-93d1-c3c9947fb3cc","id":9,"poolType":"SMB","host":"SMB19","path":"/hyperv-share/abhinav-ps6?user=abhinavroy&domain=BLR","port":445,"url":"SMB://SMB19/hyperv-share/abhinav-ps6?user=abhinavroy&domain=BLR/?ROLE=Primary&STOREUUID=3f754d4f-365c-3bd1-93d1-c3c9947fb3cc"}},"name":"ROOT-20","size":10737418240,"path":"b3f11294-032e-4de2-b6c3-aed65fd86ba8","volumeId":40,"vmName":"i-2-20-VM","accountId":2,"format":"VHD","id":40,"deviceId":0,"hypervisorType":"Hyperv"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"b3f11294-032e-4de2-b6c3-aed65fd86ba8","volumeType":"ROOT","dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"cifs://10.102.192.19/hyperv-share/abhinav-ss1?user=abhinavroy&domain=BLR","_role":"Image"}},"name":"ROOT-20","size":10737418240,"path":"volumes/2/40","volumeId":40,"vmName":"i-2-20-VM","accountId":2,"format":"VHD","id":40,"deviceId":0,"hypervisorType":"Hyperv"}},"executeInSequence":false,"options":{},"contextMap":{},"wait":10800}
> 2014-06-12 16:46:28,224 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-246:ctx-c26c3041) Sending cmd to https://10.102.244.25:8250/api/HypervResource/org.apache.cloudstack.storage.command.CopyCommand cmd data:{"srcTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"b3f11294-032e-4de2-b6c3-aed65fd86ba8","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"3f754d4f-365c-3bd1-93d1-c3c9947fb3cc","id":9,"poolType":"SMB","host":"SMB19","path":"/hyperv-share/abhinav-ps6?user=abhinavroy&domain=BLR","port":445,"url":"SMB://SMB19/hyperv-share/abhinav-ps6?user=abhinavroy&domain=BLR/?ROLE=Primary&STOREUUID=3f754d4f-365c-3bd1-93d1-c3c9947fb3cc"}},"name":"ROOT-20","size":10737418240,"path":"b3f11294-032e-4de2-b6c3-aed65fd86ba8","volumeId":40,"vmName":"i-2-20-VM","accountId":2,"format":"VHD","id":40,"deviceId":0,"hypervisorType":"Hyperv"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"b3f11294-032e-4de2-b6c3-aed65fd86ba8","volumeType":"ROOT","dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"cifs://10.102.192.19/hyperv-share/abhinav-ss1?user=abhinavroy&domain=BLR","_role":"Image"}},"name":"ROOT-20","size":10737418240,"path":"volumes/2/40","volumeId":40,"vmName":"i-2-20-VM","accountId":2,"format":"VHD","id":40,"deviceId":0,"hypervisorType":"Hyperv"}},"executeInSequence":false,"options":{},"contextMap":{},"wait":10800}
> 2014-06-12 16:46:29,878 DEBUG [c.c.a.ApiServlet] (catalina-exec-13:ctx-71be4cf9) ===START===  10.144.6.9 -- GET  command=queryAsyncJobResult&jobId=e533b45d-994b-4646-95d8-3d149a173929&response=json&sessionkey=fFhNiWQ7rfYWJRz28KaKz5M%2BFkM%3D&_=1402571446316
> 2014-06-12 16:46:29,895 DEBUG [c.c.a.ApiServlet] (catalina-exec-13:ctx-71be4cf9 ctx-e2dd679e) ===END===  10.144.6.9 -- GET  command=queryAsyncJobResult&jobId=e533b45d-994b-4646-95d8-3d149a173929&response=json&sessionkey=fFhNiWQ7rfYWJRz28KaKz5M%2BFkM%3D&_=1402571446316
> 2014-06-12 16:46:32,848 DEBUG [c.c.a.ApiServlet] (catalina-exec-6:ctx-573b632f) ===START===  10.144.6.9 -- GET  command=queryAsyncJobResult&jobId=e533b45d-994b-4646-95d8-3d149a173929&response=json&sessionkey=fFhNiWQ7rfYWJRz28KaKz5M%2BFkM%3D&_=1402571448949
> 2014-06-12 16:46:32,864 DEBUG [c.c.a.ApiServlet] (catalina-exec-6:ctx-573b632f ctx-f615d91b) ===END===  10.144.6.9 -- GET  command=queryAsyncJobResult&jobId=e533b45d-994b-4646-95d8-3d149a173929&response=json&sessionkey=fFhNiWQ7rfYWJRz28KaKz5M%2BFkM%3D&_=1402571448949
> 2014-06-12 16:46:33,040 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-15:null) SeqA 2-147873: Processing Seq 2-147873:  { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
> 2014-06-12 16:46:33,043 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-15:null) SeqA 2-147873: Sending Seq 2-147873:  { Ans: , MgmtId: 213737702773493, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-06-12 16:46:34,233 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-0f1ab709) StorageCollector is running...
> 2014-06-12 16:46:34,286 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-0f1ab709) Seq 3-4590575395174090470: Received:  { Ans: , MgmtId: 213737702773493, via: 3, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2014-06-12 16:46:34,289 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-124:ctx-0fb950ea) Seq 1-4843621399236976990: Executing request
> 2014-06-12 16:46:34,289 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-124:ctx-0fb950ea) POST request to https://10.102.244.20:8250/api/HypervResource/com.cloud.agent.api.GetStorageStatsCommand with contents {"id":"c5034950-d1a2-3368-8c8f-77a2cb0d49d2-HypervResource","localPath":"C:\Users\Public\Documents\Hyper-V\Virtual Hard Disks","pooltype":"Filesystem","contextMap":{},"wait":0}
> 2014-06-12 16:46:34,293 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-124:ctx-0fb950ea) Sending cmd to https://10.102.244.20:8250/api/HypervResource/com.cloud.agent.api.GetStorageStatsCommand cmd data:{"id":"c5034950-d1a2-3368-8c8f-77a2cb0d49d2-HypervResource","localPath":"C:\Users\Public\Documents\Hyper-V\Virtual Hard Disks","pooltype":"Filesystem","contextMap":{},"wait":0}
> 2014-06-12 16:46:34,366 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-124:ctx-0fb950ea) POST response is [{"com.cloud.agent.api.GetStorageStatsAnswer":{"result":true,"details":null,"capacity":497917358080,"used":16945373184,"contextMap":{}}}]
> 2014-06-12 16:46:34,367 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-124:ctx-0fb950ea) executeRequest received response [Lcom.cloud.agent.api.Answer;@10e5ce6c
> 2014-06-12 16:46:34,367 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-124:ctx-0fb950ea) Seq 1-4843621399236976990: Response Received:
> 2014-06-12 16:46:34,367 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-0f1ab709) Seq 1-4843621399236976990: Received:  { Ans: , MgmtId: 213737702773493, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2014-06-12 16:46:34,371 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-247:ctx-f13ffe3d) Seq 4-7623186794254703065: Executing request
> 2014-06-12 16:46:34,371 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-247:ctx-f13ffe3d) POST request to https://10.102.244.21:8250/api/HypervResource/com.cloud.agent.api.GetStorageStatsCommand with contents {"id":"641da331-d6d6-3224-b53a-0dad93667d30","localPath":"/hyperv-share/abhinav-ps1?user=abhinavroy&domain=BLR","pooltype":"SMB","contextMap":{},"wait":0}
> 2014-06-12 16:46:34,374 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-247:ctx-f13ffe3d) Sending cmd to https://10.102.244.21:8250/api/HypervResource/com.cloud.agent.api.GetStorageStatsCommand cmd data:{"id":"641da331-d6d6-3224-b53a-0dad93667d30","localPath":"/hyperv-share/abhinav-ps1?user=abhinavroy&domain=BLR","pooltype":"SMB","contextMap":{},"wait":0}
> 2014-06-12 16:46:34,450 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-247:ctx-f13ffe3d) POST response is [{"com.cloud.agent.api.GetStorageStatsAnswer":{"result":true,"details":null,"capacity":998772830208,"used":148309569536,"contextMap":{}}}]
> 2014-06-12 16:46:34,451 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-247:ctx-f13ffe3d) executeRequest received response [Lcom.cloud.agent.api.Answer;@6ac5a4c9
> 2014-06-12 16:46:34,451 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-247:ctx-f13ffe3d) Seq 4-7623186794254703065: Response Received:
> 2014-06-12 16:46:34,451 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-0f1ab709) Seq 4-7623186794254703065: Received:  { Ans: , MgmtId: 213737702773493, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2014-06-12 16:46:34,454 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-494:ctx-b6bcac14) Seq 4-7623186794254703066: Executing request
> 2014-06-12 16:46:34,454 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-494:ctx-b6bcac14) POST request to https://10.102.244.21:8250/api/HypervResource/com.cloud.agent.api.GetStorageStatsCommand with contents {"id":"c03aa877-a1af-315c-a2c2-2b10f128b1a3-HypervResource","localPath":"C:\Users\Public\Documents\Hyper-V\Virtual Hard Disks","pooltype":"Filesystem","contextMap":{},"wait":0}
> 2014-06-12 16:46:34,457 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-494:ctx-b6bcac14) Sending cmd to https://10.102.244.21:8250/api/HypervResource/com.cloud.agent.api.GetStorageStatsCommand cmd data:{"id":"c03aa877-a1af-315c-a2c2-2b10f128b1a3-HypervResource","localPath":"C:\Users\Public\Documents\Hyper-V\Virtual Hard Disks","pooltype":"Filesystem","contextMap":{},"wait":0}
> 2014-06-12 16:46:34,526 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-494:ctx-b6bcac14) POST response is [{"com.cloud.agent.api.GetStorageStatsAnswer":{"result":true,"details":null,"capacity":499738734592,"used":14508425216,"contextMap":{}}}]
> 2014-06-12 16:46:34,526 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-494:ctx-b6bcac14) executeRequest received response [Lcom.cloud.agent.api.Answer;@a69b1af
> 2014-06-12 16:46:34,526 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-494:ctx-b6bcac14) Seq 4-7623186794254703066: Response Received:
> 2014-06-12 16:46:34,526 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-0f1ab709) Seq 4-7623186794254703066: Received:  { Ans: , MgmtId: 213737702773493, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2014-06-12 16:46:34,529 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-32:ctx-3b941566) Seq 5-4892879520161343078: Executing request
> 2014-06-12 16:46:34,529 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-32:ctx-3b941566) POST request to https://10.102.244.25:8250/api/HypervResource/com.cloud.agent.api.GetStorageStatsCommand with contents {"id":"0ede929f-e4be-31e7-a0fa-6d29aa133276-HypervResource","localPath":"C:\Users\Public\Documents\Hyper-V\Virtual Hard Disks","pooltype":"Filesystem","contextMap":{},"wait":0}
> 2014-06-12 16:46:34,533 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-32:ctx-3b941566) Sending cmd to https://10.102.244.25:8250/api/HypervResource/com.cloud.agent.api.GetStorageStatsCommand cmd data:{"id":"0ede929f-e4be-31e7-a0fa-6d29aa133276-HypervResource","localPath":"C:\Users\Public\Documents\Hyper-V\Virtual Hard Disks","pooltype":"Filesystem","contextMap":{},"wait":0}
> 2014-06-12 16:46:34,629 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-32:ctx-3b941566) POST response is [{"com.cloud.agent.api.GetStorageStatsAnswer":{"result":true,"details":null,"capacity":491474907136,"used":14998237184,"contextMap":{}}}]
> 2014-06-12 16:46:34,629 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-32:ctx-3b941566) executeRequest received response [Lcom.cloud.agent.api.Answer;@3849b481
> 2014-06-12 16:46:34,629 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-32:ctx-3b941566) Seq 5-4892879520161343078: Response Received:
> 2014-06-12 16:46:34,630 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-0f1ab709) Seq 5-4892879520161343078: Received:  { Ans: , MgmtId: 213737702773493, via: 5, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2014-06-12 16:46:34,633 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-495:ctx-299d7921) Seq 5-4892879520161343079: Executing request
> 2014-06-12 16:46:34,633 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-495:ctx-299d7921) POST request to https://10.102.244.25:8250/api/HypervResource/com.cloud.agent.api.GetStorageStatsCommand with contents {"id":"b3fcb49c-b870-33e6-86f2-bb1eb72cceef","localPath":"/hyperv-share/abhinav-ps2?user=abhinavroy&domain=BLR","pooltype":"SMB","contextMap":{},"wait":0}
> 2014-06-12 16:46:34,637 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-495:ctx-299d7921) Sending cmd to https://10.102.244.25:8250/api/HypervResource/com.cloud.agent.api.GetStorageStatsCommand cmd data:{"id":"b3fcb49c-b870-33e6-86f2-bb1eb72cceef","localPath":"/hyperv-share/abhinav-ps2?user=abhinavroy&domain=BLR","pooltype":"SMB","contextMap":{},"wait":0}
> 2014-06-12 16:46:34,755 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-495:ctx-299d7921) POST response is [{"com.cloud.agent.api.GetStorageStatsAnswer":{"result":true,"details":null,"capacity":998772830208,"used":148309569536,"contextMap":{}}}]
> 2014-06-12 16:46:34,755 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-495:ctx-299d7921) executeRequest received response [Lcom.cloud.agent.api.Answer;@789beb76
> 2014-06-12 16:46:34,755 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-495:ctx-299d7921) Seq 5-4892879520161343079: Response Received:
> 2014-06-12 16:46:34,755 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-0f1ab709) Seq 5-4892879520161343079: Received:  { Ans: , MgmtId: 213737702773493, via: 5, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2014-06-12 16:46:34,759 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-493:ctx-099d403f) Seq 5-4892879520161343080: Executing request
> 2014-06-12 16:46:34,759 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-493:ctx-099d403f) POST request to https://10.102.244.25:8250/api/HypervResource/com.cloud.agent.api.GetStorageStatsCommand with contents {"id":"fb292e87-e9a0-3f42-b42e-63c6f5ca3b43","localPath":"/hyperv-share/abhinav-ps3?user=abhinavroy&domain=BLR","pooltype":"SMB","contextMap":{},"wait":0}
> 2014-06-12 16:46:34,763 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-493:ctx-099d403f) Sending cmd to https://10.102.244.25:8250/api/HypervResource/com.cloud.agent.api.GetStorageStatsCommand cmd data:{"id":"fb292e87-e9a0-3f42-b42e-63c6f5ca3b43","localPath":"/hyperv-share/abhinav-ps3?user=abhinavroy&domain=BLR","pooltype":"SMB","contextMap":{},"wait":0}
> 2014-06-12 16:46:34,880 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-493:ctx-099d403f) POST response is [{"com.cloud.agent.api.GetStorageStatsAnswer":{"result":true,"details":null,"capacity":998772830208,"used":148309569536,"contextMap":{}}}]
> 2014-06-12 16:46:34,881 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-493:ctx-099d403f) executeRequest received response [Lcom.cloud.agent.api.Answer;@30c6d8c8
> 2014-06-12 16:46:34,881 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-493:ctx-099d403f) Seq 5-4892879520161343080: Response Received:
> 2014-06-12 16:46:34,881 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-0f1ab709) Seq 5-4892879520161343080: Received:  { Ans: , MgmtId: 213737702773493, via: 5, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2014-06-12 16:46:34,885 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-496:ctx-7c00fef4) Seq 1-4843621399236976991: Executing request
> 2014-06-12 16:46:34,885 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-496:ctx-7c00fef4) POST request to https://10.102.244.20:8250/api/HypervResource/com.cloud.agent.api.GetStorageStatsCommand with contents {"id":"86d1df09-9da8-3f83-89cf-35dac0770b9d","localPath":"/hyperv-share/abhinav-ps4?user=abhinavroy&domain=BLR","pooltype":"SMB","contextMap":{},"wait":0}
> 2014-06-12 16:46:34,888 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-496:ctx-7c00fef4) Sending cmd to https://10.102.244.20:8250/api/HypervResource/com.cloud.agent.api.GetStorageStatsCommand cmd data:{"id":"86d1df09-9da8-3f83-89cf-35dac0770b9d","localPath":"/hyperv-share/abhinav-ps4?user=abhinavroy&domain=BLR","pooltype":"SMB","contextMap":{},"wait":0}
> 2014-06-12 16:46:34,960 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-496:ctx-7c00fef4) POST response is [{"com.cloud.agent.api.GetStorageStatsAnswer":{"result":true,"details":null,"capacity":998772830208,"used":148309569536,"contextMap":{}}}]
> 2014-06-12 16:46:34,961 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-496:ctx-7c00fef4) executeRequest received response [Lcom.cloud.agent.api.Answer;@2ac3210
> 2014-06-12 16:46:34,961 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-496:ctx-7c00fef4) Seq 1-4843621399236976991: Response Received:
> 2014-06-12 16:46:34,961 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-0f1ab709) Seq 1-4843621399236976991: Received:  { Ans: , MgmtId: 213737702773493, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2014-06-12 16:46:34,965 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-497:ctx-eef272cb) Seq 4-7623186794254703067: Executing request
> 2014-06-12 16:46:34,965 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-497:ctx-eef272cb) POST request to https://10.102.244.21:8250/api/HypervResource/com.cloud.agent.api.GetStorageStatsCommand with contents {"id":"38aee7de-07f1-3f23-8f8d-6a772fb9811d","localPath":"/hyperv-share/abhinav-ps5?user=abhinavroy&domain=BLR","pooltype":"SMB","contextMap":{},"wait":0}
> 2014-06-12 16:46:34,968 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-497:ctx-eef272cb) Sending cmd to https://10.102.244.21:8250/api/HypervResource/com.cloud.agent.api.GetStorageStatsCommand cmd data:{"id":"38aee7de-07f1-3f23-8f8d-6a772fb9811d","localPath":"/hyperv-share/abhinav-ps5?user=abhinavroy&domain=BLR","pooltype":"SMB","contextMap":{},"wait":0}
> 2014-06-12 16:46:35,049 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-497:ctx-eef272cb) POST response is [{"com.cloud.agent.api.GetStorageStatsAnswer":{"result":true,"details":null,"capacity":998772830208,"used":148309569536,"contextMap":{}}}]
> 2014-06-12 16:46:35,049 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-497:ctx-eef272cb) executeRequest received response [Lcom.cloud.agent.api.Answer;@8963e4f
> 2014-06-12 16:46:35,049 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-497:ctx-eef272cb) Seq 4-7623186794254703067: Response Received:
> 2014-06-12 16:46:35,050 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-0f1ab709) Seq 4-7623186794254703067: Received:  { Ans: , MgmtId: 213737702773493, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2014-06-12 16:46:35,053 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-16:ctx-287e1921) Seq 5-4892879520161343081: Executing request
> 2014-06-12 16:46:35,053 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-16:ctx-287e1921) POST request to https://10.102.244.25:8250/api/HypervResource/com.cloud.agent.api.GetStorageStatsCommand with contents {"id":"3f754d4f-365c-3bd1-93d1-c3c9947fb3cc","localPath":"/hyperv-share/abhinav-ps6?user=abhinavroy&domain=BLR","pooltype":"SMB","contextMap":{},"wait":0}
> 2014-06-12 16:46:35,057 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-16:ctx-287e1921) Sending cmd to https://10.102.244.25:8250/api/HypervResource/com.cloud.agent.api.GetStorageStatsCommand cmd data:{"id":"3f754d4f-365c-3bd1-93d1-c3c9947fb3cc","localPath":"/hyperv-share/abhinav-ps6?user=abhinavroy&domain=BLR","pooltype":"SMB","contextMap":{},"wait":0}
> 2014-06-12 16:46:35,199 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-16:ctx-287e1921) POST response is [{"com.cloud.agent.api.GetStorageStatsAnswer":{"result":true,"details":null,"capacity":998772830208,"used":148309569536,"contextMap":{}}}]
> 2014-06-12 16:46:35,200 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-16:ctx-287e1921) executeRequest received response [Lcom.cloud.agent.api.Answer;@4b48eed1
> 2014-06-12 16:46:35,200 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-16:ctx-287e1921) Seq 5-4892879520161343081: Response Received:
> 2014-06-12 16:46:35,200 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-0f1ab709) Seq 5-4892879520161343081: Received:  { Ans: , MgmtId: 213737702773493, via: 5, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2014-06-12 16:46:35,874 DEBUG [c.c.a.ApiServlet] (catalina-exec-19:ctx-52accc10) ===START===  10.144.6.9 -- GET  command=queryAsyncJobResult&jobId=e533b45d-994b-4646-95d8-3d149a173929&response=json&sessionkey=fFhNiWQ7rfYWJRz28KaKz5M%2BFkM%3D&_=1402571451823
> 2014-06-12 16:46:35,890 DEBUG [c.c.a.ApiServlet] (catalina-exec-19:ctx-52accc10 ctx-5e1e73a7) ===END===  10.144.6.9 -- GET  command=queryAsyncJobResult&jobId=e533b45d-994b-4646-95d8-3d149a173929&response=json&sessionkey=fFhNiWQ7rfYWJRz28KaKz5M%2BFkM%3D&_=1402571451823
> 2014-06-12 16:46:36,967 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-1:null) Ping from 3
> 2014-06-12 16:46:37,021 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-14:null) Ping from 2
> 2014-06-12 16:46:37,916 DEBUG [c.c.s.StatsCollector] (StatsCollector-4:ctx-3071753b) AutoScaling Monitor is running...
> 2014-06-12 16:46:38,046 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 2-147875: Processing Seq 2-147875:  { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
> 2014-06-12 16:46:38,059 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 2-147875: Sending Seq 2-147875:  { Ans: , MgmtId: 213737702773493, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-06-12 16:46:38,874 DEBUG [c.c.a.ApiServlet] (catalina-exec-10:ctx-c9aef811) ===START===  10.144.6.9 -- GET  command=queryAsyncJobResult&jobId=e533b45d-994b-4646-95d8-3d149a173929&response=json&sessionkey=fFhNiWQ7rfYWJRz28KaKz5M%2BFkM%3D&_=1402571454359
> 2014-06-12 16:46:38,891 DEBUG [c.c.a.ApiServlet] (catalina-exec-10:ctx-c9aef811 ctx-4df3cb39) ===END===  10.144.6.9 -- GET  command=queryAsyncJobResult&jobId=e533b45d-994b-4646-95d8-3d149a173929&response=json&sessionkey=fFhNiWQ7rfYWJRz28KaKz5M%2BFkM%3D&_=1402571454359
> 2014-06-12 16:46:41,865 DEBUG [c.c.a.ApiServlet] (catalina-exec-3:ctx-ca648e33) ===START===  10.144.6.9 -- GET  command=queryAsyncJobResult&jobId=e533b45d-994b-4646-95d8-3d149a173929&response=json&sessionkey=fFhNiWQ7rfYWJRz28KaKz5M%2BFkM%3D&_=1402571456898
> 2014-06-12 16:46:41,882 DEBUG [c.c.a.ApiServlet] (catalina-exec-3:ctx-ca648e33 ctx-835e936e) ===END===  10.144.6.9 -- GET  command=queryAsyncJobResult&jobId=e533b45d-994b-4646-95d8-3d149a173929&response=json&sessionkey=fFhNiWQ7rfYWJRz28KaKz5M%2BFkM%3D&_=1402571456898
> 2014-06-12 16:46:43,052 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 2-147876: Processing Seq 2-147876:  { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
> 2014-06-12 16:46:43,055 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 2-147876: Sending Seq 2-147876:  { Ans: , MgmtId: 213737702773493, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-06-12 16:46:44,851 DEBUG [c.c.a.ApiServlet] (catalina-exec-18:ctx-8328891d) ===START===  10.144.6.9 -- GET  command=queryAsyncJobResult&jobId=e533b45d-994b-4646-95d8-3d149a173929&response=json&sessionkey=fFhNiWQ7rfYWJRz28KaKz5M%2BFkM%3D&_=1402571459466
> 2014-06-12 16:46:44,868 DEBUG [c.c.a.ApiServlet] (catalina-exec-18:ctx-8328891d ctx-3bd01ada) ===END===  10.144.6.9 -- GET  command=queryAsyncJobResult&jobId=e533b45d-994b-4646-95d8-3d149a173929&response=json&sessionkey=fFhNiWQ7rfYWJRz28KaKz5M%2BFkM%3D&_=1402571459466
> 2014-06-12 16:46:47,865 DEBUG [c.c.a.ApiServlet] (catalina-exec-16:ctx-d416b9f3) ===START===  10.144.6.9 -- GET  command=queryAsyncJobResult&jobId=e533b45d-994b-4646-95d8-3d149a173929&response=json&sessionkey=fFhNiWQ7rfYWJRz28KaKz5M%2BFkM%3D&_=1402571461946
> 2014-06-12 16:46:47,882 DEBUG [c.c.a.ApiServlet] (catalina-exec-16:ctx-d416b9f3 ctx-09245f00) ===END===  10.144.6.9 -- GET  command=queryAsyncJobResult&jobId=e533b45d-994b-4646-95d8-3d149a173929&response=json&sessionkey=fFhNiWQ7rfYWJRz28KaKz5M%2BFkM%3D&_=1402571461946
> 2014-06-12 16:46:48,056 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-3:null) SeqA 2-147877: Processing Seq 2-147877:  { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
> 2014-06-12 16:46:48,060 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-3:null) SeqA 2-147877: Sending Seq 2-147877:  { Ans: , MgmtId: 213737702773493, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-06-12 16:46:50,377 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-6c4d94b2) Found 1 routers to update status.
> 2014-06-12 16:46:50,379 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-6c4d94b2) Found 0 networks to update RvR status.
> 2014-06-12 16:46:50,913 DEBUG [c.c.a.ApiServlet] (catalina-exec-17:ctx-87650967) ===START===  10.144.6.9 -- GET  command=queryAsyncJobResult&jobId=e533b45d-994b-4646-95d8-3d149a173929&response=json&sessionkey=fFhNiWQ7rfYWJRz28KaKz5M%2BFkM%3D&_=1402571464947
> 2014-06-12 16:46:50,930 DEBUG [c.c.a.ApiServlet] (catalina-exec-17:ctx-87650967 ctx-fb505962) ===END===  10.144.6.9 -- GET  command=queryAsyncJobResult&jobId=e533b45d-994b-4646-95d8-3d149a173929&response=json&sessionkey=fFhNiWQ7rfYWJRz28KaKz5M%2BFkM%3D&_=1402571464947
> 2014-06-12 16:46:53,062 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 2-147878: Processing Seq 2-147878:  { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
> 2014-06-12 16:46:53,067 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 2-147878: Sending Seq 2-147878:  { Ans: , MgmtId: 213737702773493, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-06-12 16:46:53,870 DEBUG [c.c.a.ApiServlet] (catalina-exec-20:ctx-176edfea) ===START===  10.144.6.9 -- GET  command=queryAsyncJobResult&jobId=e533b45d-994b-4646-95d8-3d149a173929&response=json&sessionkey=fFhNiWQ7rfYWJRz28KaKz5M%2BFkM%3D&_=1402571467486
> 2014-06-12 16:46:53,887 DEBUG [c.c.a.ApiServlet] (catalina-exec-20:ctx-176edfea ctx-ec6b47a5) ===END===  10.144.6.9 -- GET  command=queryAsyncJobResult&jobId=e533b45d-994b-4646-95d8-3d149a173929&response=json&sessionkey=fFhNiWQ7rfYWJRz28KaKz5M%2BFkM%3D&_=1402571467486
> 2014-06-12 16:46:55,733 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-9fcf2e86) Resetting hosts suitable for reconnect
> 2014-06-12 16:46:55,735 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-9fcf2e86) Completed resetting hosts suitable for reconnect
> 2014-06-12 16:46:55,735 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-9fcf2e86) Acquiring hosts for clusters already owned by this management server
> 2014-06-12 16:46:55,736 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-9fcf2e86) Completed acquiring hosts for clusters already owned by this management server
> 2014-06-12 16:46:55,736 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-9fcf2e86) Acquiring hosts for clusters not owned by any management server
> 2014-06-12 16:46:55,737 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-9fcf2e86) Completed acquiring hosts for clusters not owned by any management server
> 2014-06-12 16:46:56,858 DEBUG [c.c.a.ApiServlet] (catalina-exec-4:ctx-78da024b) ===START===  10.144.6.9 -- GET  command=queryAsyncJobResult&jobId=e533b45d-994b-4646-95d8-3d149a173929&response=json&sessionkey=fFhNiWQ7rfYWJRz28KaKz5M%2BFkM%3D&_=1402571470003
> 2014-06-12 16:46:56,874 DEBUG [c.c.a.ApiServlet] (catalina-exec-4:ctx-78da024b ctx-60ea179d) ===END===  10.144.6.9 -- GET  command=queryAsyncJobResult&jobId=e533b45d-994b-4646-95d8-3d149a173929&response=json&sessionkey=fFhNiWQ7rfYWJRz28KaKz5M%2BFkM%3D&_=1402571470003
> 2014-06-12 16:46:57,079 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-dbf28984) Zone 1 is ready to launch secondary storage VM
> 2014-06-12 16:46:57,227 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-85827ba9) Zone 1 is ready to launch console proxy
> 2014-06-12 16:46:58,068 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 2-147879: Processing Seq 2-147879:  { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
> 2014-06-12 16:46:58,071 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 2-147879: Sending Seq 2-147879:  { Ans: , MgmtId: 213737702773493, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-06-12 16:46:59,875 DEBUG [c.c.a.ApiServlet] (catalina-exec-1:ctx-c47b9693) ===START===  10.144.6.9 -- GET  command=queryAsyncJobResult&jobId=e533b45d-994b-4646-95d8-3d149a173929&response=json&sessionkey=fFhNiWQ7rfYWJRz28KaKz5M%2BFkM%3D&_=1402571472506
> 2014-06-12 16:46:59,891 DEBUG [c.c.a.ApiServlet] (catalina-exec-1:ctx-c47b9693 ctx-69303abb) ===END===  10.144.6.9 -- GET  command=queryAsyncJobResult&jobId=e533b45d-994b-4646-95d8-3d149a173929&response=json&sessionkey=fFhNiWQ7rfYWJRz28KaKz5M%2BFkM%3D&_=1402571472506
> 2014-06-12 16:47:01,742 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-2b76b39b) VmStatsCollector is running...
> 2014-06-12 16:47:01,754 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-125:ctx-368ee128) Seq 1-4843621399236976992: Executing request
> 2014-06-12 16:47:01,754 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-125:ctx-368ee128) POST request to https://10.102.244.20:8250/api/HypervResource/com.cloud.agent.api.GetVmStatsCommand with contents {"vmNames":["i-2-9-VM"],"hostGuid":"c5034950-d1a2-3368-8c8f-77a2cb0d49d2-HypervResource","hostName":"10.102.244.20","contextMap":{},"wait":0}
> 2014-06-12 16:47:01,757 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-125:ctx-368ee128) Sending cmd to https://10.102.244.20:8250/api/HypervResource/com.cloud.agent.api.GetVmStatsCommand cmd data:{"vmNames":["i-2-9-VM"],"hostGuid":"c5034950-d1a2-3368-8c8f-77a2cb0d49d2-HypervResource","hostName":"10.102.244.20","contextMap":{},"wait":0}
> 2014-06-12 16:47:01,983 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-125:ctx-368ee128) POST response is [{"com.cloud.agent.api.GetVmStatsAnswer":{"vmStatsMap":{"i-2-9-VM":{"cpuUtilization":0.0,"networkReadKBs":1.0,"networkWriteKBs":1.0,"numCPUs":1,"entityType":"vm"}},"result":true,"contextMap":{}}}]
> 2014-06-12 16:47:01,984 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-125:ctx-368ee128) executeRequest received response [Lcom.cloud.agent.api.Answer;@55b77cf5
> 2014-06-12 16:47:01,984 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-125:ctx-368ee128) Seq 1-4843621399236976992: Response Received:
> 2014-06-12 16:47:01,984 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-2b76b39b) Seq 1-4843621399236976992: Received:  { Ans: , MgmtId: 213737702773493, via: 1, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
> 2014-06-12 16:47:01,994 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-498:ctx-b3bfcacc) Seq 4-7623186794254703068: Executing request
> 2014-06-12 16:47:01,994 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-498:ctx-b3bfcacc) POST request to https://10.102.244.21:8250/api/HypervResource/com.cloud.agent.api.GetVmStatsCommand with contents {"vmNames":["i-2-17-VM"],"hostGuid":"c03aa877-a1af-315c-a2c2-2b10f128b1a3-HypervResource","hostName":"10.102.244.21","contextMap":{},"wait":0}
> 2014-06-12 16:47:01,998 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-498:ctx-b3bfcacc) Sending cmd to https://10.102.244.21:8250/api/HypervResource/com.cloud.agent.api.GetVmStatsCommand cmd data:{"vmNames":["i-2-17-VM"],"hostGuid":"c03aa877-a1af-315c-a2c2-2b10f128b1a3-HypervResource","hostName":"10.102.244.21","contextMap":{},"wait":0}
> 2014-06-12 16:47:02,218 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-498:ctx-b3bfcacc) POST response is [{"com.cloud.agent.api.GetVmStatsAnswer":{"vmStatsMap":{"i-2-17-VM":{"cpuUtilization":0.0,"networkReadKBs":1.0,"networkWriteKBs":1.0,"numCPUs":1,"entityType":"vm"}},"result":true,"contextMap":{}}}]
> 2014-06-12 16:47:02,219 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-498:ctx-b3bfcacc) executeRequest received response [Lcom.cloud.agent.api.Answer;@791998c
> 2014-06-12 16:47:02,220 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-498:ctx-b3bfcacc) Seq 4-7623186794254703068: Response Received:
> 2014-06-12 16:47:02,220 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-2b76b39b) Seq 4-7623186794254703068: Received:  { Ans: , MgmtId: 213737702773493, via: 4, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
> 2014-06-12 16:47:02,233 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-249:ctx-5cbe3599) Seq 5-4892879520161343082: Executing request
> 2014-06-12 16:47:02,233 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-249:ctx-5cbe3599) POST request to https://10.102.244.25:8250/api/HypervResource/com.cloud.agent.api.GetVmStatsCommand with contents {"vmNames":["i-2-6-VM","i-2-15-VM"],"hostGuid":"0ede929f-e4be-31e7-a0fa-6d29aa133276-HypervResource","hostName":"10.102.244.25","contextMap":{},"wait":0}
> 2014-06-12 16:47:02,236 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-249:ctx-5cbe3599) Sending cmd to https://10.102.244.25:8250/api/HypervResource/com.cloud.agent.api.GetVmStatsCommand cmd data:{"vmNames":["i-2-6-VM","i-2-15-VM"],"hostGuid":"0ede929f-e4be-31e7-a0fa-6d29aa133276-HypervResource","hostName":"10.102.244.25","contextMap":{},"wait":0}
> 2014-06-12 16:47:02,634 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-249:ctx-5cbe3599) POST response is [{"com.cloud.agent.api.GetVmStatsAnswer":{"vmStatsMap":{"i-2-6-VM":{"cpuUtilization":0.0,"networkReadKBs":1.0,"networkWriteKBs":1.0,"numCPUs":1,"entityType":"vm"},"i-2-15-VM":{"cpuUtilization":0.0,"networkReadKBs":1.0,"networkWriteKBs":1.0,"numCPUs":1,"entityType":"vm"}},"result":true,"contextMap":{}}}]
> 2014-06-12 16:47:02,635 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-249:ctx-5cbe3599) executeRequest received response [Lcom.cloud.agent.api.Answer;@21ab0634
> 2014-06-12 16:47:02,635 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-249:ctx-5cbe3599) Seq 5-4892879520161343082: Response Received:
> 2014-06-12 16:47:02,636 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-2b76b39b) Seq 5-4892879520161343082: Received:  { Ans: , MgmtId: 213737702773493, via: 5, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
> 2014-06-12 16:47:02,874 DEBUG [c.c.a.ApiServlet] (catalina-exec-7:ctx-8f177199) ===START===  10.144.6.9 -- GET  command=queryAsyncJobResult&jobId=e533b45d-994b-4646-95d8-3d149a173929&response=json&sessionkey=fFhNiWQ7rfYWJRz28KaKz5M%2BFkM%3D&_=1402571474899
> 2014-06-12 16:47:02,890 DEBUG [c.c.a.ApiServlet] (catalina-exec-7:ctx-8f177199 ctx-823e6aab) ===END===  10.144.6.9 -- GET  command=queryAsyncJobResult&jobId=e533b45d-994b-4646-95d8-3d149a173929&response=json&sessionkey=fFhNiWQ7rfYWJRz28KaKz5M%2BFkM%3D&_=1402571474899
> 2014-06-12 16:47:03,073 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 2-147880: Processing Seq 2-147880:  { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
> 2014-06-12 16:47:03,076 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 2-147880: Sending Seq 2-147880:  { Ans: , MgmtId: 213737702773493, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-06-12 16:47:03,799 DEBUG [c.c.s.StatsCollector] (StatsCollector-1:ctx-5f2719c6) HostStatsCollector is running...
> 2014-06-12 16:47:03,808 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-499:ctx-9efc3a92) Seq 1-4843621399236976993: Executing request
> 2014-06-12 16:47:03,808 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-499:ctx-9efc3a92) POST request to https://10.102.244.20:8250/api/HypervResource/com.cloud.agent.api.GetHostStatsCommand with contents {"hostGuid":"c5034950-d1a2-3368-8c8f-77a2cb0d49d2-HypervResource","hostName":"10.102.244.20","hostId":1,"contextMap":{},"wait":0}
> 2014-06-12 16:47:03,812 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-499:ctx-9efc3a92) Sending cmd to https://10.102.244.20:8250/api/HypervResource/com.cloud.agent.api.GetHostStatsCommand cmd data:{"hostGuid":"c5034950-d1a2-3368-8c8f-77a2cb0d49d2-HypervResource","hostName":"10.102.244.20","hostId":1,"contextMap":{},"wait":0}
> 2014-06-12 16:47:04,185 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-499:ctx-9efc3a92) POST response is [{"com.cloud.agent.api.GetHostStatsAnswer":{"result":true,"hostStats":{"hostId":1,"entityType":"host","cpuUtilization":6.0,"networkReadKBs":93038433452.0,"networkWriteKBs":365393146419.0,"totalMemoryKBs":8357712.0,"freeMemoryKBs":4701772.0},"details":null,"contextMap":{}}}]
> 2014-06-12 16:47:04,186 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-499:ctx-9efc3a92) executeRequest received response [Lcom.cloud.agent.api.Answer;@49da9bf3
> 2014-06-12 16:47:04,186 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-499:ctx-9efc3a92) Seq 1-4843621399236976993: Response Received:
> 2014-06-12 16:47:04,186 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-5f2719c6) Seq 1-4843621399236976993: Received:  { Ans: , MgmtId: 213737702773493, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> 2014-06-12 16:47:04,194 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-248:ctx-769f0855) Seq 4-7623186794254703069: Executing request
> 2014-06-12 16:47:04,194 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-248:ctx-769f0855) POST request to https://10.102.244.21:8250/api/HypervResource/com.cloud.agent.api.GetHostStatsCommand with contents {"hostGuid":"c03aa877-a1af-315c-a2c2-2b10f128b1a3-HypervResource","hostName":"10.102.244.21","hostId":4,"contextMap":{},"wait":0}
> 2014-06-12 16:47:04,197 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-248:ctx-769f0855) Sending cmd to https://10.102.244.21:8250/api/HypervResource/com.cloud.agent.api.GetHostStatsCommand cmd data:{"hostGuid":"c03aa877-a1af-315c-a2c2-2b10f128b1a3-HypervResource","hostName":"10.102.244.21","hostId":4,"contextMap":{},"wait":0}
> 2014-06-12 16:47:04,598 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-248:ctx-769f0855) POST response is [{"com.cloud.agent.api.GetHostStatsAnswer":{"result":true,"hostStats":{"hostId":4,"entityType":"host","cpuUtilization":0.0,"networkReadKBs":343548005868.0,"networkWriteKBs":97204087926.0,"totalMemoryKBs":8357712.0,"freeMemoryKBs":6120116.0},"details":null,"contextMap":{}}}]
> 2014-06-12 16:47:04,599 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-248:ctx-769f0855) executeRequest received response [Lcom.cloud.agent.api.Answer;@6ad5387f
> 2014-06-12 16:47:04,599 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-248:ctx-769f0855) Seq 4-7623186794254703069: Response Received:
> 2014-06-12 16:47:04,599 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-5f2719c6) Seq 4-7623186794254703069: Received:  { Ans: , MgmtId: 213737702773493, via: 4, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> 2014-06-12 16:47:04,606 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-250:ctx-9715ae60) Seq 5-4892879520161343083: Executing request
> 2014-06-12 16:47:04,607 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-250:ctx-9715ae60) POST request to https://10.102.244.25:8250/api/HypervResource/com.cloud.agent.api.GetHostStatsCommand with contents {"hostGuid":"0ede929f-e4be-31e7-a0fa-6d29aa133276-HypervResource","hostName":"10.102.244.25","hostId":5,"contextMap":{},"wait":0}
> 2014-06-12 16:47:04,610 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-250:ctx-9715ae60) Sending cmd to https://10.102.244.25:8250/api/HypervResource/com.cloud.agent.api.GetHostStatsCommand cmd data:{"hostGuid":"0ede929f-e4be-31e7-a0fa-6d29aa133276-HypervResource","hostName":"10.102.244.25","hostId":5,"contextMap":{},"wait":0}
> 2014-06-12 16:47:05,027 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-250:ctx-9715ae60) POST response is [{"com.cloud.agent.api.GetHostStatsAnswer":{"result":true,"hostStats":{"hostId":5,"entityType":"host","cpuUtilization":15.0,"networkReadKBs":272810313869.0,"networkWriteKBs":249057240611.0,"totalMemoryKBs":8357712.0,"freeMemoryKBs":6254444.0},"details":null,"contextMap":{}}}]
> 2014-06-12 16:47:05,030 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-250:ctx-9715ae60) executeRequest received response [Lcom.cloud.agent.api.Answer;@7aad5f0b
> 2014-06-12 16:47:05,030 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-250:ctx-9715ae60) Seq 5-4892879520161343083: Response Received:
> 2014-06-12 16:47:05,030 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-5f2719c6) Seq 5-4892879520161343083: Received:  { Ans: , MgmtId: 213737702773493, via: 5, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> 2014-06-12 16:47:05,810 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-246:ctx-c26c3041) POST response is [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":true,"details":null,"newData":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"cifs://10.102.192.19/hyperv-share/abhinav-ss1?user=abhinavroy&domain=BLR","_role":"Image"}},"format":"VHD","name":"ROOT-20","path":"volumes/2/40/b3f11294-032e-4de2-b6c3-aed65fd86ba8.vhd","uuid":"b3f11294-032e-4de2-b6c3-aed65fd86ba8","size":10737418240,"primaryDataStore":null,"nfsDataStore":{"uri":"cifs://10.102.192.19/hyperv-share/abhinav-ss1?user=abhinavroy&domain=BLR","_role":"Image","UncPath":"\\10.102.192.19/hyperv-share/abhinav-ss1","User":"abhinavroy",,"Domain":"BLR"},"FullFileName":"\\10.102.192.19\hyperv-share\abhinav-ss1\volumes\2\40\b3f11294-032e-4de2-b6c3-aed65fd86ba8.vhd"}},"contextMap":{}}}]
> 2014-06-12 16:47:05,811 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-246:ctx-c26c3041) executeRequest received response [Lcom.cloud.agent.api.Answer;@4ffcbf69
> 2014-06-12 16:47:05,811 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-246:ctx-c26c3041) Seq 5-4892879520161343077: Response Received:
> 2014-06-12 16:47:05,811 DEBUG [c.c.a.t.Request] (DirectAgent-246:ctx-c26c3041) Seq 5-4892879520161343077: Processing:  { Ans: , MgmtId: 213737702773493, via: 5, Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"newData":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"b3f11294-032e-4de2-b6c3-aed65fd86ba8","dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"cifs://10.102.192.19/hyperv-share/abhinav-ss1?user=abhinavroy&domain=BLR","_role":"Image"}},"name":"ROOT-20","size":10737418240,"path":"volumes/2/40/b3f11294-032e-4de2-b6c3-aed65fd86ba8.vhd","accountId":0,"format":"VHD","id":0}},"result":true,"wait":0}}] }
> 2014-06-12 16:47:05,811 DEBUG [c.c.a.t.Request] (Work-Job-Executor-16:ctx-6063e5f5 job-250/job-251 ctx-024db267) Seq 5-4892879520161343077: Received:  { Ans: , MgmtId: 213737702773493, via: 5, Ver: v1, Flags: 10, { CopyCmdAnswer } }
> 2014-06-12 16:47:05,820 DEBUG [o.a.c.s.v.VolumeObject] (Work-Job-Executor-16:ctx-6063e5f5 job-250/job-251 ctx-024db267) Failed to update state
> com.cloud.utils.fsm.NoTransitionException: Unable to transition to a new state from Creating via CopyingRequested
>         at com.cloud.utils.fsm.StateMachine2.getNextState(StateMachine2.java:86)
>         at com.cloud.utils.fsm.StateMachine2.transitTo(StateMachine2.java:102)
>         at org.apache.cloudstack.storage.datastore.ObjectInDataStoreManagerImpl.update(ObjectInDataStoreManagerImpl.java:296)
>         at org.apache.cloudstack.storage.volume.VolumeObject.processEvent(VolumeObject.java:293)
>         at org.apache.cloudstack.storage.motion.AncientDataMotionStrategy.copyVolumeBetweenPools(AncientDataMotionStrategy.java:327)
>         at org.apache.cloudstack.storage.motion.AncientDataMotionStrategy.copyAsync(AncientDataMotionStrategy.java:429)
>         at org.apache.cloudstack.storage.motion.DataMotionServiceImpl.copyAsync(DataMotionServiceImpl.java:68)
>         at org.apache.cloudstack.storage.motion.DataMotionServiceImpl.copyAsync(DataMotionServiceImpl.java:73)
>         at org.apache.cloudstack.storage.volume.VolumeServiceImpl.copyVolume(VolumeServiceImpl.java:991)
>         at org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.migrateVolume(VolumeOrchestrator.java:877)
>         at com.cloud.storage.VolumeApiServiceImpl.orchestrateMigrateVolume(VolumeApiServiceImpl.java:1655)
>         at com.cloud.storage.VolumeApiServiceImpl.orchestrateMigrateVolume(VolumeApiServiceImpl.java:2497)
>         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>         at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
>         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>         at java.lang.reflect.Method.invoke(Method.java:601)
>         at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
>         at com.cloud.storage.VolumeApiServiceImpl.handleVmWorkJob(VolumeApiServiceImpl.java:2512)
>         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>         at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
>         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>         at java.lang.reflect.Method.invoke(Method.java:601)
>         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 $Proxy181.handleVmWorkJob(Unknown Source)
>         at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
>         at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:503)
>         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:460)
>         at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
>         at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
>         at java.util.concurrent.FutureTask.run(FutureTask.java:166)
>         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
>         at java.lang.Thread.run(Thread.java:722)
> 2014-06-12 16:47:05,820 DEBUG [o.a.c.s.m.AncientDataMotionStrategy] (Work-Job-Executor-16:ctx-6063e5f5 job-250/job-251 ctx-024db267) copy failed
> com.cloud.utils.exception.CloudRuntimeException: Failed to update state:com.cloud.utils.fsm.NoTransitionException: Unable to transition to a new state from Creating via CopyingRequested
>         at org.apache.cloudstack.storage.volume.VolumeObject.processEvent(VolumeObject.java:327)
>         at org.apache.cloudstack.storage.motion.AncientDataMotionStrategy.copyVolumeBetweenPools(AncientDataMotionStrategy.java:327)
>         at org.apache.cloudstack.storage.motion.AncientDataMotionStrategy.copyAsync(AncientDataMotionStrategy.java:429)
>         at org.apache.cloudstack.storage.motion.DataMotionServiceImpl.copyAsync(DataMotionServiceImpl.java:68)
>         at org.apache.cloudstack.storage.motion.DataMotionServiceImpl.copyAsync(DataMotionServiceImpl.java:73)
>         at org.apache.cloudstack.storage.volume.VolumeServiceImpl.copyVolume(VolumeServiceImpl.java:991)
>         at org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.migrateVolume(VolumeOrchestrator.java:877)
>         at com.cloud.storage.VolumeApiServiceImpl.orchestrateMigrateVolume(VolumeApiServiceImpl.java:1655)
>         at com.cloud.storage.VolumeApiServiceImpl.orchestrateMigrateVolume(VolumeApiServiceImpl.java:2497)
>         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>         at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
>         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>         at java.lang.reflect.Method.invoke(Method.java:601)
>         at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
>         at com.cloud.storage.VolumeApiServiceImpl.handleVmWorkJob(VolumeApiServiceImpl.java:2512)
>         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>         at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
>         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>         at java.lang.reflect.Method.invoke(Method.java:601)
>         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 $Proxy181.handleVmWorkJob(Unknown Source)
>         at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
>         at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:503)
>         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:460)
>         at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
>         at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
>         at java.util.concurrent.FutureTask.run(FutureTask.java:166)
>         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
>         at java.lang.Thread.run(Thread.java:722)
> 2014-06-12 16:47:05,848 WARN  [o.a.c.s.d.ObjectInDataStoreManagerImpl] (Work-Job-Executor-16:ctx-6063e5f5 job-250/job-251 ctx-024db267) Unsupported data object (VOLUME, org.apache.cloudstack.storage.datastore.PrimaryDataStoreImpl@73000fde), no need to delete from object in store ref table
> 2014-06-12 16:47:05,857 WARN  [o.a.c.s.d.ObjectInDataStoreManagerImpl] (Work-Job-Executor-16:ctx-6063e5f5 job-250/job-251 ctx-024db267) Unsupported data object (VOLUME, org.apache.cloudstack.storage.datastore.PrimaryDataStoreImpl@2bb14da0), no need to delete from object in store ref table
> 2014-06-12 16:47:05,859 DEBUG [c.c.a.ApiServlet] (catalina-exec-23:ctx-1a7e1662) ===START===  10.144.6.9 -- GET  command=queryAsyncJobResult&jobId=e533b45d-994b-4646-95d8-3d149a173929&response=json&sessionkey=fFhNiWQ7rfYWJRz28KaKz5M%2BFkM%3D&_=1402571477841
> 2014-06-12 16:47:05,895 DEBUG [c.c.a.ApiServlet] (catalina-exec-23:ctx-1a7e1662 ctx-ed1625c6) ===END===  10.144.6.9 -- GET  command=queryAsyncJobResult&jobId=e533b45d-994b-4646-95d8-3d149a173929&response=json&sessionkey=fFhNiWQ7rfYWJRz28KaKz5M%2BFkM%3D&_=1402571477841
> 2014-06-12 16:47:05,926 DEBUG [c.c.a.t.Request] (Work-Job-Executor-16:ctx-6063e5f5 job-250/job-251 ctx-024db267) Seq 5-4892879520161343084: Sending  { Cmd , MgmtId: 213737702773493, via: 5(10.102.244.25), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"4a0665ef-70f0-4c9a-a80e-e4d592243c0e","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"b3fcb49c-b870-33e6-86f2-bb1eb72cceef","id":5,"poolType":"SMB","host":"SMB19","path":"/hyperv-share/abhinav-ps2?user=abhinavroy&domain=BLR","port":445,"url":"SMB://SMB19/hyperv-share/abhinav-ps2?user=abhinavroy&domain=BLR/?ROLE=Primary&STOREUUID=b3fcb49c-b870-33e6-86f2-bb1eb72cceef"}},"name":"ROOT-20","size":10737418240,"path":"b3f11294-032e-4de2-b6c3-aed65fd86ba8","volumeId":41,"vmName":"i-2-20-VM","accountId":2,"format":"VHD","id":41,"deviceId":0,"hypervisorType":"Hyperv"}},"wait":0}}] }
> 2014-06-12 16:47:05,926 DEBUG [c.c.a.t.Request] (Work-Job-Executor-16:ctx-6063e5f5 job-250/job-251 ctx-024db267) Seq 5-4892879520161343084: Executing:  { Cmd , MgmtId: 213737702773493, via: 5(10.102.244.25), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"4a0665ef-70f0-4c9a-a80e-e4d592243c0e","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"b3fcb49c-b870-33e6-86f2-bb1eb72cceef","id":5,"poolType":"SMB","host":"SMB19","path":"/hyperv-share/abhinav-ps2?user=abhinavroy&domain=BLR","port":445,"url":"SMB://SMB19/hyperv-share/abhinav-ps2?user=abhinavroy&domain=BLR/?ROLE=Primary&STOREUUID=b3fcb49c-b870-33e6-86f2-bb1eb72cceef"}},"name":"ROOT-20","size":10737418240,"path":"b3f11294-032e-4de2-b6c3-aed65fd86ba8","volumeId":41,"vmName":"i-2-20-VM","accountId":2,"format":"VHD","id":41,"deviceId":0,"hypervisorType":"Hyperv"}},"wait":0}}] }
> 2014-06-12 16:47:05,927 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-17:ctx-3f6dd9f0) Seq 5-4892879520161343084: Executing request
> 2014-06-12 16:47:05,928 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-17:ctx-3f6dd9f0) POST request to https://10.102.244.25:8250/api/HypervResource/org.apache.cloudstack.storage.command.DeleteCommand with contents {"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"4a0665ef-70f0-4c9a-a80e-e4d592243c0e","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"b3fcb49c-b870-33e6-86f2-bb1eb72cceef","id":5,"poolType":"SMB","host":"SMB19","path":"/hyperv-share/abhinav-ps2?user=abhinavroy&domain=BLR","port":445,"url":"SMB://SMB19/hyperv-share/abhinav-ps2?user=abhinavroy&domain=BLR/?ROLE=Primary&STOREUUID=b3fcb49c-b870-33e6-86f2-bb1eb72cceef"}},"name":"ROOT-20","size":10737418240,"path":"b3f11294-032e-4de2-b6c3-aed65fd86ba8","volumeId":41,"vmName":"i-2-20-VM","accountId":2,"format":"VHD","id":41,"deviceId":0,"hypervisorType":"Hyperv"}},"contextMap":{},"wait":0}
> 2014-06-12 16:47:05,931 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-17:ctx-3f6dd9f0) Sending cmd to https://10.102.244.25:8250/api/HypervResource/org.apache.cloudstack.storage.command.DeleteCommand cmd data:{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"4a0665ef-70f0-4c9a-a80e-e4d592243c0e","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"b3fcb49c-b870-33e6-86f2-bb1eb72cceef","id":5,"poolType":"SMB","host":"SMB19","path":"/hyperv-share/abhinav-ps2?user=abhinavroy&domain=BLR","port":445,"url":"SMB://SMB19/hyperv-share/abhinav-ps2?user=abhinavroy&domain=BLR/?ROLE=Primary&STOREUUID=b3fcb49c-b870-33e6-86f2-bb1eb72cceef"}},"name":"ROOT-20","size":10737418240,"path":"b3f11294-032e-4de2-b6c3-aed65fd86ba8","volumeId":41,"vmName":"i-2-20-VM","accountId":2,"format":"VHD","id":41,"deviceId":0,"hypervisorType":"Hyperv"}},"contextMap":{},"wait":0}
> 2014-06-12 16:47:06,005 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-17:ctx-3f6dd9f0) POST response is [{"com.cloud.agent.api.Answer":{"result":true,"details":null,"contextMap":{}}}]
> 2014-06-12 16:47:06,005 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-17:ctx-3f6dd9f0) executeRequest received response [Lcom.cloud.agent.api.Answer;@369fbe03
> 2014-06-12 16:47:06,005 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-17:ctx-3f6dd9f0) Seq 5-4892879520161343084: Response Received:
> 2014-06-12 16:47:06,006 DEBUG [c.c.a.t.Request] (DirectAgent-17:ctx-3f6dd9f0) Seq 5-4892879520161343084: Processing:  { Ans: , MgmtId: 213737702773493, via: 5, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
> 2014-06-12 16:47:06,006 DEBUG [c.c.a.t.Request] (Work-Job-Executor-16:ctx-6063e5f5 job-250/job-251 ctx-024db267) Seq 5-4892879520161343084: Received:  { Ans: , MgmtId: 213737702773493, via: 5, Ver: v1, Flags: 10, { Answer } }
> 2014-06-12 16:47:06,012 INFO  [o.a.c.s.v.VolumeServiceImpl] (Work-Job-Executor-16:ctx-6063e5f5 job-250/job-251 ctx-024db267) Volume 41 is not referred anywhere, remove it from volumes table
> 2014-06-12 16:47:06,038 ERROR [o.a.c.e.o.VolumeOrchestrator] (Work-Job-Executor-16:ctx-6063e5f5 job-250/job-251 ctx-024db267) migrate volume failed:com.cloud.utils.exception.CloudRuntimeException: Failed to update state:com.cloud.utils.fsm.NoTransitionException: Unable to transition to a new state from Creating via CopyingRequested
> 2014-06-12 16:47:06,039 DEBUG [c.c.s.VolumeApiServiceImpl] (Work-Job-Executor-16:ctx-6063e5f5 job-250/job-251 ctx-024db267) Failed to migrate volume
> com.cloud.exception.StorageUnavailableException: Resource [StoragePool:5] is unreachable: migrate volume failed: com.cloud.utils.exception.CloudRuntimeException: Failed to update state:com.cloud.utils.fsm.NoTransitionException: Unable to transition to a new state from Creating via CopyingRequested
>         at org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.migrateVolume(VolumeOrchestrator.java:882)
>         at com.cloud.storage.VolumeApiServiceImpl.orchestrateMigrateVolume(VolumeApiServiceImpl.java:1655)
>         at com.cloud.storage.VolumeApiServiceImpl.orchestrateMigrateVolume(VolumeApiServiceImpl.java:2497)
>         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>         at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
>         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>         at java.lang.reflect.Method.invoke(Method.java:601)
>         at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
>         at com.cloud.storage.VolumeApiServiceImpl.handleVmWorkJob(VolumeApiServiceImpl.java:2512)
>         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>         at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
>         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>         at java.lang.reflect.Method.invoke(Method.java:601)
>         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 $Proxy181.handleVmWorkJob(Unknown Source)
>         at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
>         at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:503)
>         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:460)
>         at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
>         at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
>         at java.util.concurrent.FutureTask.run(FutureTask.java:166)
>         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
>         at java.lang.Thread.run(Thread.java:722)
> 2014-06-12 16:47:06,039 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-16:ctx-6063e5f5 job-250/job-251 ctx-024db267) Invocation exception, caused by: java.lang.NullPointerException
> 2014-06-12 16:47:06,039 INFO  [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-16:ctx-6063e5f5 job-250/job-251 ctx-024db267) Rethrow exception java.lang.NullPointerException
> 2014-06-12 16:47:06,040 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-16:ctx-6063e5f5 job-250/job-251) Done with run of VM work job: com.cloud.storage.VmWorkMigrateVolume for VM 20, job origin: 250
> 2014-06-12 16:47:06,040 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-16:ctx-6063e5f5 job-250/job-251) Unable to complete AsyncJobVO {id:251, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.storage.VmWorkMigrateVolume, cmdInfo: rO0ABXNyACVjb20uY2xvdWQuc3RvcmFnZS5WbVdvcmtNaWdyYXRlVm9sdW1l-CXzb7zvU-YCAANKAApkZXN0UG9vbElkWgALbGl2ZU1pZ3JhdGVKAAh2b2x1bWVJZHhyABNjb20uY2xvdWQudm0uVm1Xb3Jrn5m2VvAlZ2sCAARKAAlhY2NvdW50SWRKAAZ1c2VySWRKAAR2bUlkTAALaGFuZGxlck5hbWV0ABJMamF2YS9sYW5nL1N0cmluZzt4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAFHQAFFZvbHVtZUFwaVNlcnZpY2VJbXBsAAAAAAAAAAUAAAAAAAAAACg, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 213737702773493, completeMsid: null, lastUpdated: null, lastPolled: null, created: Thu Jun 12 16:46:26 IST 2014}, job origin:250
> java.lang.NullPointerException
>         at com.cloud.storage.VolumeApiServiceImpl.orchestrateMigrateVolume(VolumeApiServiceImpl.java:2498)
>         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>         at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
>         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>         at java.lang.reflect.Method.invoke(Method.java:601)
>         at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
>         at com.cloud.storage.VolumeApiServiceImpl.handleVmWorkJob(VolumeApiServiceImpl.java:2512)
>         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>         at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
>         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>         at java.lang.reflect.Method.invoke(Method.java:601)
>         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 $Proxy181.handleVmWorkJob(Unknown Source)
>         at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
>         at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:503)
>         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:460)
>         at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
>         at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
>         at java.util.concurrent.FutureTask.run(FutureTask.java:166)
>         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
>         at java.lang.Thread.run(Thread.java:722)
> 2014-06-12 16:47:06,043 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-16:ctx-6063e5f5 job-250/job-251) Complete async job-251, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyABpqYXZhLmxhbmcuUnVudGltZUV4Y2VwdGlvbp5fBkcKNIPlAgAAeHIAE2phdmEubGFuZy5FeGNlcHRpb27Q_R8-GjscxAIAAHhyABNqYXZhLmxhbmcuVGhyb3dhYmxl1cY1Jzl3uMsDAARMAAVjYXVzZXQAFUxqYXZhL2xhbmcvVGhyb3dhYmxlO0wADWRldGFpbE1lc3NhZ2V0ABJMamF2YS9sYW5nL1N0cmluZztbAApzdGFja1RyYWNldAAeW0xqYXZhL2xhbmcvU3RhY2tUcmFjZUVsZW1lbnQ7TAAUc3VwcHJlc3NlZEV4Y2VwdGlvbnN0ABBMamF2YS91dGlsL0xpc3Q7eHBxAH4AB3QAIEpvYiBmYWlsZWQgZHVlIHRvIGV4Y2VwdGlvbiBudWxsdXIAHltMamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50OwJGKjw8_SI5AgAAeHAAAAAOc3IAG2phdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudGEJxZomNt2FAgAESQAKbGluZU51bWJlckwADmRlY2xhcmluZ0NsYXNzcQB-AARMAAhmaWxlTmFtZXEAfgAETAAKbWV0aG9kTmFtZXEAfgAEeHAAAABydAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRpc3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JzcQB-AAsAAAH3dAA_b3JnLmFwYWNoZS5jbG91ZHN0YWNrLmZyYW1ld29yay5qb2JzLmltcGwuQXN5bmNKb2JNYW5hZ2VySW1wbCQ1dAAYQXN5bmNKb2JNYW5hZ2VySW1wbC5qYXZhdAAMcnVuSW5Db250ZXh0c3EAfgALAAAAMXQAPm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZSQxdAAbTWFuYWdlZENvbnRleHRSdW5uYWJsZS5qYXZhdAADcnVuc3EAfgALAAAAOHQAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbHNxAH4ACwAAAGd0AEBvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0cQB-ABp0AA9jYWxsV2l0aENvbnRleHRzcQB-AAsAAAA1cQB-AB1xAH4AGnQADnJ1bldpdGhDb250ZXh0c3EAfgALAAAALnQAPG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgAWcQB-ABdzcQB-AAsAAAHMcQB-ABFxAH4AEnEAfgAXc3EAfgALAAAB13QALmphdmEudXRpbC5jb25jdXJyZW50LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgAbc3EAfgALAAABTnQAJGphdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2skU3luY3QAD0Z1dHVyZVRhc2suamF2YXQACGlubmVyUnVuc3EAfgALAAAApnQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2txAH4AKXEAfgAXc3EAfgALAAAEVnQAJ2phdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvcnQAF1RocmVhZFBvb2xFeGVjdXRvci5qYXZhdAAJcnVuV29ya2Vyc3EAfgALAAACW3QALmphdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvciRXb3JrZXJxAH4AL3EAfgAXc3EAfgALAAAC0nQAEGphdmEubGFuZy5UaHJlYWR0AAtUaHJlYWQuamF2YXEAfgAXc3IAJmphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVMaXN0_A8lMbXsjhACAAFMAARsaXN0cQB-AAZ4cgAsamF2YS51dGlsLkNvbGxlY3Rpb25zJFVubW9kaWZpYWJsZUNvbGxlY3Rpb24ZQgCAy173HgIAAUwAAWN0ABZMamF2YS91dGlsL0NvbGxlY3Rpb247eHBzcgATamF2YS51dGlsLkFycmF5TGlzdHiB0h2Zx2GdAwABSQAEc2l6ZXhwAAAAAHcEAAAAAHhxAH4AO3g
> 2014-06-12 16:47:06,072 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-16:ctx-6063e5f5 job-250/job-251) Done executing com.cloud.storage.VmWorkMigrateVolume for job-251
> 2014-06-12 16:47:06,081 ERROR [c.c.a.ApiAsyncJobDispatcher] (API-Job-Executor-21:ctx-4b7caee5 job-250) Unexpected exception while executing org.apache.cloudstack.api.command.admin.volume.MigrateVolumeCmdByAdmin
> java.lang.RuntimeException: Unexpected exception
>         at com.cloud.storage.VolumeApiServiceImpl.migrateVolume(VolumeApiServiceImpl.java:1630)
>         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>         at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
>         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>         at java.lang.reflect.Method.invoke(Method.java:601)
>         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 $Proxy181.migrateVolume(Unknown Source)
>         at org.apache.cloudstack.api.command.admin.volume.MigrateVolumeCmdByAdmin.execute(MigrateVolumeCmdByAdmin.java:37)
>         at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:141)
>         at com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:108)
>         at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:503)
>         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:460)
>         at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
>         at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
>         at java.util.concurrent.FutureTask.run(FutureTask.java:166)
>         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
>         at java.lang.Thread.run(Thread.java:722)
> Caused by: java.lang.RuntimeException: Job failed due to exception null
>         ... 27 more
> 2014-06-12 16:47:06,088 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-21:ctx-4b7caee5 job-250) Complete async job-250, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Unexpected exception"}
> 2014-06-12 16:47:06,101 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-21:ctx-4b7caee5 job-250) Done executing org.apache.cloudstack.api.command.admin.volume.MigrateVolumeCmdByAdmin for job-250
> -----------------------------------------------------
> DB  entries :
> =====================
>  mysql> select * from volumes where id=40\G
>                         id: 40
>                 account_id: 2
>                  domain_id: 1
>                    pool_id: 9
>               last_pool_id: NULL
>                instance_id: 20
>                  device_id: 0
>                       name: ROOT-20
>                       uuid: b3f11294-032e-4de2-b6c3-aed65fd86ba8
>                       size: 10737418240
>                     folder: NULL
>                       path: b3f11294-032e-4de2-b6c3-aed65fd86ba8
>                     pod_id: NULL
>             data_center_id: 1
>                 iscsi_name: NULL
>                    host_ip: NULL
>                volume_type: ROOT
>                  pool_type: NULL
>           disk_offering_id: 1
>                template_id: 6
> first_snapshot_backup_uuid: NULL
>                recreatable: 0
>                    created: 2014-06-12 11:11:05
>                   attached: NULL
>                    updated: 2014-06-12 11:17:05
>                    removed: NULL
>                      state: Ready
>                 chain_info: NULL
>               update_count: 6
>                  disk_type: NULL
>     vm_snapshot_chain_size: NULL
>                     iso_id: NULL
>             display_volume: 1
>                     format: VHD
>                   min_iops: NULL
>                   max_iops: NULL
>              hv_ss_reserve: NULL
> 1 row in set (0.00 sec)
> Entry for the volume created during migration 
> mysql> select * from volumes where id=41\G
>                         id: 41
>                 account_id: 2
>                  domain_id: 1
>                    pool_id: 5
>               last_pool_id: 9
>                instance_id: 20
>                  device_id: 0
>                       name: ROOT-20
>                       uuid: 4a0665ef-70f0-4c9a-a80e-e4d592243c0e
>                       size: 10737418240
>                     folder: /hyperv-share/abhinav-ps2
>                       path: b3f11294-032e-4de2-b6c3-aed65fd86ba8
>                     pod_id: 1
>             data_center_id: 1
>                 iscsi_name: NULL
>                    host_ip: NULL
>                volume_type: ROOT
>                  pool_type: NULL
>           disk_offering_id: 1
>                template_id: 6
> first_snapshot_backup_uuid: NULL
>                recreatable: 0
>                    created: 2014-06-12 11:16:28
>                   attached: NULL
>                    updated: 2014-06-12 11:17:06
>                    removed: 2014-06-12 11:17:06
>                      state: Expunged
>                 chain_info: NULL
>               update_count: 6
>                  disk_type: NULL
>     vm_snapshot_chain_size: NULL
>                     iso_id: NULL
>             display_volume: 1
>                     format: VHD
>                   min_iops: NULL
>                   max_iops: NULL
>              hv_ss_reserve: NULL
> NOTE : This behavior is seen only if we migrate the volume after download, if we migrate it before download then it succeeds.



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Mime
View raw message