[CLOUDSTACK-6900] If we download a volume and then migrate the same volume, then migration fails.

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 4.4.0
• Fix Version/s: 4.6.0
• Component/s: Management Server, Storage Controller
• Security Level: Public (Anyone can view this level - this is the default.)
• Environment: Hyper-V
• Assignee: Anshul Gangwar
• Reporter: Abhinav Roy
• Created: 12/Jun/14 12:10
• Updated: 19/Mar/15 10:13
• Resolved: 19/Mar/15 10:13

Description

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.