You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "Damodar Reddy T (JIRA)" <ji...@apache.org> on 2013/12/13 11:44:09 UTC
[jira] [Resolved] (CLOUDSTACK-4577) VMWare:Volumes: Unexpected
exception while executing
org.apache.cloudstack.api.command.user.volume.ResizeVolumeCmd
java.lang.NullPointerException
[ https://issues.apache.org/jira/browse/CLOUDSTACK-4577?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Damodar Reddy T resolved CLOUDSTACK-4577.
-----------------------------------------
Resolution: Not A Problem
Not able to re produce this in 4.3.
[~parth] Please re open if you see this issue in 4.3 again.
> VMWare:Volumes: Unexpected exception while executing org.apache.cloudstack.api.command.user.volume.ResizeVolumeCmd java.lang.NullPointerException
> -------------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: CLOUDSTACK-4577
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-4577
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the default.)
> Components: VMware, Volumes
> Affects Versions: 4.2.1
> Environment: VMWare,
> 5 Primary; 2 Zone wide and Rest Cluster.
> Attach Data Disk and attempt a Re-size.
> Reporter: Parth Jagirdar
> Assignee: Damodar Reddy T
> Priority: Critical
> Fix For: 4.3.0
>
>
> Logs attached.
> 2013-08-30 16:12:14,513 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 9-1571: Processing Seq 9-1571: { Cmd , MgmtId: -1, via: 9, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":30,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2013-08-30 16:12:14,520 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 9-1571: Sending Seq 9-1571: { Ans: , MgmtId: 7471666038533, via: 9, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2013-08-30 16:12:18,099 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) Ping from 10
> 2013-08-30 16:12:24,514 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 9-1572: Processing Seq 9-1572: { Cmd , MgmtId: -1, via: 9, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":30,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2013-08-30 16:12:24,523 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 9-1572: Sending Seq 9-1572: { Ans: , MgmtId: 7471666038533, via: 9, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2013-08-30 16:12:34,514 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-12:null) SeqA 9-1573: Processing Seq 9-1573: { Cmd , MgmtId: -1, via: 9, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":30,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2013-08-30 16:12:34,520 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-12:null) SeqA 9-1573: Sending Seq 9-1573: { Ans: , MgmtId: 7471666038533, via: 9, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2013-08-30 16:12:34,839 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) HostStatsCollector is running...
> 2013-08-30 16:12:34,849 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-492:null) Seq 1-1168048937: Executing request
> 2013-08-30 16:12:34,877 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-492:null) Seq 1-1168048937: Response Received:
> 2013-08-30 16:12:34,877 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-1168048937: Received: { Ans: , MgmtId: 7471666038533, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> 2013-08-30 16:12:34,918 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-493:null) Seq 6-580518619: Executing request
> 2013-08-30 16:12:34,940 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-493:null) Seq 6-580518619: Response Received:
> 2013-08-30 16:12:34,940 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 6-580518619: Received: { Ans: , MgmtId: 7471666038533, via: 6, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> 2013-08-30 16:12:34,957 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-494:null) Seq 8-2005992046: Executing request
> 2013-08-30 16:12:34,974 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-494:null) Seq 8-2005992046: Response Received:
> 2013-08-30 16:12:34,975 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 8-2005992046: Received: { Ans: , MgmtId: 7471666038533, via: 8, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> 2013-08-30 16:12:35,099 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
> 2013-08-30 16:12:35,261 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
> 2013-08-30 16:12:36,129 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
> 2013-08-30 16:12:36,131 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
> 2013-08-30 16:12:36,229 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
> 2013-08-30 16:12:36,230 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
> 2013-08-30 16:12:44,514 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) SeqA 9-1574: Processing Seq 9-1574: { Cmd , MgmtId: -1, via: 9, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":30,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2013-08-30 16:12:44,520 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) SeqA 9-1574: Sending Seq 9-1574: { Ans: , MgmtId: 7471666038533, via: 9, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2013-08-30 16:12:49,890 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) StorageCollector is running...
> 2013-08-30 16:12:49,967 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 10-1925054692: Received: { Ans: , MgmtId: 7471666038533, via: 10, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2013-08-30 16:12:49,974 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-216:null) Seq 1-1168048938: Executing request
> 2013-08-30 16:12:50,020 DEBUG [vmware.resource.VmwareResource] (DirectAgent-216:10.223.59.66) Datastore summary info, storageId: d89e306d-88e8-3997-ade6-fa97fed423bf, localPath: /export/home/chandan/307PB-195-103/primary1, poolType: NetworkFilesystem, capacity: 11810778316800, free: 4331362349056, used: 7479415967744
> 2013-08-30 16:12:50,020 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-216:null) Seq 1-1168048938: Response Received:
> 2013-08-30 16:12:50,021 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 1-1168048938: Received: { Ans: , MgmtId: 7471666038533, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2013-08-30 16:12:50,025 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-216:null) Seq 6-580518620: Executing request
> 2013-08-30 16:12:50,053 DEBUG [vmware.resource.VmwareResource] (DirectAgent-216:10.223.57.66) Datastore summary info, storageId: 96bc10ee-70b3-3d20-a60c-c068a024b3a7, localPath: /export/home/chandan/307PB-195-103/primary2, poolType: NetworkFilesystem, capacity: 11810778316800, free: 4328890368000, used: 7481887948800
> 2013-08-30 16:12:50,054 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-216:null) Seq 6-580518620: Response Received:
> 2013-08-30 16:12:50,054 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 6-580518620: Received: { Ans: , MgmtId: 7471666038533, via: 6, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2013-08-30 16:12:50,060 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-216:null) Seq 8-2005992047: Executing request
> 2013-08-30 16:12:50,101 DEBUG [vmware.resource.VmwareResource] (DirectAgent-216:10.223.59.67) Datastore summary info, storageId: 9de17e9b-2280-328b-b1b2-e662e7253c3f, localPath: /export/home/chandan/307PB-195-103/primary4, poolType: NetworkFilesystem, capacity: 11810778316800, free: 4324465197056, used: 7486313119744
> 2013-08-30 16:12:50,102 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-216:null) Seq 8-2005992047: Response Received:
> 2013-08-30 16:12:50,102 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 8-2005992047: Received: { Ans: , MgmtId: 7471666038533, via: 8, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2013-08-30 16:12:50,107 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-216:null) Seq 1-1168048939: Executing request
> 2013-08-30 16:12:50,137 DEBUG [vmware.resource.VmwareResource] (DirectAgent-216:10.223.59.66) Datastore summary info, storageId: 5420eab7-d6a1-31fa-958e-b10bd82dc581, localPath: /export/home/chandan/307PB-195-103/primary5, poolType: NetworkFilesystem, capacity: 11810778316800, free: 4331539972096, used: 7479238344704
> 2013-08-30 16:12:50,137 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-216:null) Seq 1-1168048939: Response Received:
> 2013-08-30 16:12:50,138 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 1-1168048939: Received: { Ans: , MgmtId: 7471666038533, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2013-08-30 16:12:54,066 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) VmStatsCollector is running...
> 2013-08-30 16:12:54,082 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-495:null) Seq 1-1168048940: Executing request
> 2013-08-30 16:12:54,225 DEBUG [vmware.mo.HostMO] (DirectAgent-495:10.223.59.66) find VM i-3-18-VMWAREFORWARD on host
> 2013-08-30 16:12:54,226 INFO [vmware.mo.HostMO] (DirectAgent-495:10.223.59.66) VM i-3-18-VMWAREFORWARD not found in host cache
> 2013-08-30 16:12:54,226 DEBUG [vmware.mo.HostMO] (DirectAgent-495:10.223.59.66) load VM cache on host
> 2013-08-30 16:12:54,242 DEBUG [vmware.mo.HostMO] (DirectAgent-495:10.223.59.66) find VM i-2-36-VMWAREFORWARD on host
> 2013-08-30 16:12:54,242 DEBUG [vmware.mo.HostMO] (DirectAgent-495:10.223.59.66) VM i-2-36-VMWAREFORWARD found in host cache
> 2013-08-30 16:12:54,245 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-495:null) Seq 1-1168048940: Response Received:
> 2013-08-30 16:12:54,246 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-1168048940: Received: { Ans: , MgmtId: 7471666038533, via: 1, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
> 2013-08-30 16:12:54,259 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-496:null) Seq 6-580518621: Executing request
> 2013-08-30 16:12:54,352 DEBUG [vmware.mo.HostMO] (DirectAgent-496:10.223.57.66) find VM i-3-27-VMWAREFORWARD on host
> 2013-08-30 16:12:54,352 INFO [vmware.mo.HostMO] (DirectAgent-496:10.223.57.66) VM i-3-27-VMWAREFORWARD not found in host cache
> 2013-08-30 16:12:54,352 DEBUG [vmware.mo.HostMO] (DirectAgent-496:10.223.57.66) load VM cache on host
> 2013-08-30 16:12:54,369 DEBUG [vmware.mo.HostMO] (DirectAgent-496:10.223.57.66) find VM i-3-28-VMWAREFORWARD on host
> 2013-08-30 16:12:54,369 DEBUG [vmware.mo.HostMO] (DirectAgent-496:10.223.57.66) VM i-3-28-VMWAREFORWARD found in host cache
> 2013-08-30 16:12:54,374 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-496:null) Seq 6-580518621: Response Received:
> 2013-08-30 16:12:54,374 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 6-580518621: Received: { Ans: , MgmtId: 7471666038533, via: 6, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
> 2013-08-30 16:12:54,384 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-43:null) Seq 8-2005992048: Executing request
> 2013-08-30 16:12:54,459 DEBUG [vmware.mo.HostMO] (DirectAgent-43:10.223.59.67) find VM i-3-20-VMWAREFORWARD on host
> 2013-08-30 16:12:54,459 INFO [vmware.mo.HostMO] (DirectAgent-43:10.223.59.67) VM i-3-20-VMWAREFORWARD not found in host cache
> 2013-08-30 16:12:54,459 DEBUG [vmware.mo.HostMO] (DirectAgent-43:10.223.59.67) load VM cache on host
> 2013-08-30 16:12:54,475 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-43:null) Seq 8-2005992048: Response Received:
> 2013-08-30 16:12:54,476 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 8-2005992048: Received: { Ans: , MgmtId: 7471666038533, via: 8, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
> 2013-08-30 16:12:54,515 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-15:null) SeqA 9-1575: Processing Seq 9-1575: { Cmd , MgmtId: -1, via: 9, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":30,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2013-08-30 16:12:54,522 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-15:null) SeqA 9-1575: Sending Seq 9-1575: { Ans: , MgmtId: 7471666038533, via: 9, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2013-08-30 16:12:56,477 DEBUG [cloud.api.ApiServlet] (catalina-exec-11:null) ===START=== 10.215.2.19 -- GET command=listDiskOfferings&response=json&sessionkey=iN1%2BFv5iLGYuxcPQU06GRgdBcU0%3D&_=1377904759038
> 2013-08-30 16:12:56,490 DEBUG [cloud.api.ApiServlet] (catalina-exec-11:null) ===END=== 10.215.2.19 -- GET command=listDiskOfferings&response=json&sessionkey=iN1%2BFv5iLGYuxcPQU06GRgdBcU0%3D&_=1377904759038
> 2013-08-30 16:12:58,202 DEBUG [cloud.api.ApiServlet] (catalina-exec-1:null) ===START=== 10.215.2.19 -- GET command=resizeVolume&id=8c27247d-e1e6-4768-92f4-d2b4e019223c&shrinkok=false&diskofferingid=80982db4-adba-48bb-ad0e-2a0c281b59cd&response=json&sessionkey=iN1%2BFv5iLGYuxcPQU06GRgdBcU0%3D&_=1377904760765
> 2013-08-30 16:12:58,231 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-1:null) submit async job-106 = [ e80aebbe-df3b-4c02-bdfa-dc778aad0d72 ], details: AsyncJobVO {id:106, userId: 2, accountId: 2, sessionKey: null, instanceType: Volume, instanceId: null, cmd: org.apache.cloudstack.api.command.user.volume.ResizeVolumeCmd, cmdOriginator: null, cmdInfo: {"response":"json","id":"8c27247d-e1e6-4768-92f4-d2b4e019223c","sessionkey":"iN1+Fv5iLGYuxcPQU06GRgdBcU0\u003d","shrinkok":"false","cmdEventType":"VOLUME.RESIZE","ctxUserId":"2","httpmethod":"GET","_":"1377904760765","ctxAccountId":"2","diskofferingid":"80982db4-adba-48bb-ad0e-2a0c281b59cd","ctxStartEventId":"877"}, cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0, processStatus: 0, resultCode: 0, result: null, initMsid: 7471666038533, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
> 2013-08-30 16:12:58,232 DEBUG [cloud.api.ApiServlet] (catalina-exec-1:null) ===END=== 10.215.2.19 -- GET command=resizeVolume&id=8c27247d-e1e6-4768-92f4-d2b4e019223c&shrinkok=false&diskofferingid=80982db4-adba-48bb-ad0e-2a0c281b59cd&response=json&sessionkey=iN1%2BFv5iLGYuxcPQU06GRgdBcU0%3D&_=1377904760765
> 2013-08-30 16:12:58,234 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-31:job-106 = [ e80aebbe-df3b-4c02-bdfa-dc778aad0d72 ]) Executing org.apache.cloudstack.api.command.user.volume.ResizeVolumeCmd for job-106 = [ e80aebbe-df3b-4c02-bdfa-dc778aad0d72 ]
> 2013-08-30 16:12:58,301 ERROR [cloud.async.AsyncJobManagerImpl] (Job-Executor-31:job-106 = [ e80aebbe-df3b-4c02-bdfa-dc778aad0d72 ]) Unexpected exception while executing org.apache.cloudstack.api.command.user.volume.ResizeVolumeCmd
> java.lang.NullPointerException
> at com.cloud.storage.VolumeManagerImpl.resizeVolume(VolumeManagerImpl.java:1147)
> at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
> at com.cloud.storage.VolumeManagerImpl.resizeVolume(VolumeManagerImpl.java:183)
> at org.apache.cloudstack.api.command.user.volume.ResizeVolumeCmd.execute(ResizeVolumeCmd.java:137)
> at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:158)
> at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:531)
> 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:679)
> 2013-08-30 16:12:58,303 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-31:job-106 = [ e80aebbe-df3b-4c02-bdfa-dc778aad0d72 ]) Complete async job-106 = [ e80aebbe-df3b-4c02-bdfa-dc778aad0d72 ], jobStatus: 2, resultCode: 530, result: Error Code: 530 Error text: null
> 2013-08-30 16:12:58,455 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-496:null) Ping from 8
> 2013-08-30 16:12:58,476 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-206:null) Ping from 1
> 2013-08-30 16:12:59,041 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-43:null) Ping from 6
> 2013-08-30 16:13:01,368 DEBUG [cloud.api.ApiServlet] (catalina-exec-8:null) ===START=== 10.215.2.19 -- GET command=queryAsyncJobResult&jobId=e80aebbe-df3b-4c02-bdfa-dc778aad0d72&response=json&sessionkey=iN1%2BFv5iLGYuxcPQU06GRgdBcU0%3D&_=1377904763932
> 2013-08-30 16:13:01,375 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-8:null) Async job-106 = [ e80aebbe-df3b-4c02-bdfa-dc778aad0d72 ] completed
> 2013-08-30 16:13:01,380 DEBUG [cloud.api.ApiServlet] (catalina-exec-8:null) ===END=== 10.215.2.19 -- GET command=queryAsyncJobResult&jobId=e80aebbe-df3b-4c02-bdfa-dc778aad0d72&response=json&sessionkey=iN1%2BFv5iLGYuxcPQU06GRgdBcU0%3D&_=1377904763932
> 2013-08-30 16:13:04,515 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-1:null) SeqA 9-1576: Processing Seq 9-1576: { Cmd , MgmtId: -1, via: 9, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":30,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2013-08-30 16:13:04,522 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-1:null) SeqA 9-1576: Sending Seq 9-1576: { Ans: , MgmtId: 7471666038533, via: 9, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2013-08-30 16:13:05,101 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
> 2013-08-30 16:13:05,252 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
> 2013-08-30 16:13:06,130 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
> 2013-08-30 16:13:06,132 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
> 2013-08-30 16:13:06,229 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
> 2013-08-30 16:13:06,231 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
> 2013-08-30 16:13:08,546 DEBUG [cloud.api.ApiServlet] (catalina-exec-14:null) ===START=== 10.215.2.19 -- GET command=detachVolume&id=8c27247d-e1e6-4768-92f4-d2b4e019223c&response=json&sessionkey=iN1%2BFv5iLGYuxcPQU06GRgdBcU0%3D&_=1377904771108
> 2013-08-30 16:13:08,572 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-14:null) submit async job-107 = [ 33d8f0b0-f545-4588-a845-39044a61db0b ], details: AsyncJobVO {id:107, userId: 2, accountId: 2, sessionKey: null, instanceType: Volume, instanceId: 44, cmd: org.apache.cloudstack.api.command.user.volume.DetachVolumeCmd, cmdOriginator: null, cmdInfo: {"response":"json","id":"8c27247d-e1e6-4768-92f4-d2b4e019223c","sessionkey":"iN1+Fv5iLGYuxcPQU06GRgdBcU0\u003d","cmdEventType":"VOLUME.DETACH","ctxUserId":"2","httpmethod":"GET","_":"1377904771108","ctxAccountId":"2","ctxStartEventId":"880"}, cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0, processStatus: 0, resultCode: 0, result: null, initMsid: 7471666038533, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
> 2013-08-30 16:13:08,574 DEBUG [cloud.api.ApiServlet] (catalina-exec-14:null) ===END=== 10.215.2.19 -- GET command=detachVolume&id=8c27247d-e1e6-4768-92f4-d2b4e019223c&response=json&sessionkey=iN1%2BFv5iLGYuxcPQU06GRgdBcU0%3D&_=1377904771108
> 2013-08-30 16:13:08,576 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-32:job-107 = [ 33d8f0b0-f545-4588-a845-39044a61db0b ]) Executing org.apache.cloudstack.api.command.user.volume.DetachVolumeCmd for job-107 = [ 33d8f0b0-f545-4588-a845-39044a61db0b ]
> 2013-08-30 16:13:08,603 DEBUG [agent.transport.Request] (Job-Executor-32:job-107 = [ 33d8f0b0-f545-4588-a845-39044a61db0b ]) Seq 1-1168048941: Sending { Cmd , MgmtId: 7471666038533, via: 1, Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.DettachCommand":{"disk":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"8c27247d-e1e6-4768-92f4-d2b4e019223c","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"9de17e9b-2280-328b-b1b2-e662e7253c3f","id":204,"poolType":"NetworkFilesystem","host":"10.223.110.232","path":"/export/home/chandan/307PB-195-103/primary4","port":2049}},"name":"new-vol","size":1073741824,"path":"5f480f78ae804e55b0e9729a25ab817f","volumeId":44,"vmName":"i-2-36-VMWAREFORWARD","accountId":2,"format":"OVA","id":44,"hypervisorType":"VMware"}},"diskSeq":2,"type":"DATADISK"},"vmName":"i-2-36-VMWAREFORWARD","_managed":false,"_storageHost":"10.223.110.232","_storagePort":2049,"wait":0}}] }
> 2013-08-30 16:13:08,604 DEBUG [agent.transport.Request] (Job-Executor-32:job-107 = [ 33d8f0b0-f545-4588-a845-39044a61db0b ]) Seq 1-1168048941: Executing: { Cmd , MgmtId: 7471666038533, via: 1, Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.DettachCommand":{"disk":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"8c27247d-e1e6-4768-92f4-d2b4e019223c","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"9de17e9b-2280-328b-b1b2-e662e7253c3f","id":204,"poolType":"NetworkFilesystem","host":"10.223.110.232","path":"/export/home/chandan/307PB-195-103/primary4","port":2049}},"name":"new-vol","size":1073741824,"path":"5f480f78ae804e55b0e9729a25ab817f","volumeId":44,"vmName":"i-2-36-VMWAREFORWARD","accountId":2,"format":"OVA","id":44,"hypervisorType":"VMware"}},"diskSeq":2,"type":"DATADISK"},"vmName":"i-2-36-VMWAREFORWARD","_managed":false,"_storageHost":"10.223.110.232","_storagePort":2049,"wait":0}}] }
> 2013-08-30 16:13:08,604 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-498:null) Seq 1-1168048941: Executing request
> 2013-08-30 16:13:08,620 DEBUG [vmware.mo.HostMO] (DirectAgent-498:10.223.59.66) find VM i-2-36-VMWAREFORWARD on host
> 2013-08-30 16:13:08,620 INFO [vmware.mo.HostMO] (DirectAgent-498:10.223.59.66) VM i-2-36-VMWAREFORWARD not found in host cache
> 2013-08-30 16:13:08,620 DEBUG [vmware.mo.HostMO] (DirectAgent-498:10.223.59.66) load VM cache on host
> 2013-08-30 16:13:08,678 INFO [vmware.mo.DatastoreMO] (DirectAgent-498:10.223.59.66) Search file 5f480f78ae804e55b0e9729a25ab817f.vmdk on [9de17e9b2280328bb1b2e662e7253c3f]
> 2013-08-30 16:13:08,697 INFO [vmware.mo.DatastoreMO] (DirectAgent-498:10.223.59.66) File [9de17e9b2280328bb1b2e662e7253c3f] 5f480f78ae804e55b0e9729a25ab817f.vmdk does not exist on datastore
> 2013-08-30 16:13:08,705 INFO [vmware.mo.VirtualMachineMO] (DirectAgent-498:10.223.59.66) Look for disk device info from volume : [9de17e9b2280328bb1b2e662e7253c3f] i-2-36-VMWAREFORWARD/5f480f78ae804e55b0e9729a25ab817f.vmdk
> 2013-08-30 16:13:08,706 INFO [vmware.mo.VirtualMachineMO] (DirectAgent-498:10.223.59.66) Test against disk device, controller key: 1000, unit number: 0
> 2013-08-30 16:13:08,706 INFO [vmware.mo.VirtualMachineMO] (DirectAgent-498:10.223.59.66) Test against disk backing : [9de17e9b2280328bb1b2e662e7253c3f] i-2-36-VMWAREFORWARD/282bc8898c8c4ccdaa515464ad7fec4a.vmdk
> 2013-08-30 16:13:08,706 INFO [vmware.mo.VirtualMachineMO] (DirectAgent-498:10.223.59.66) Test against disk device, controller key: 200, unit number: 1
> 2013-08-30 16:13:08,706 INFO [vmware.mo.VirtualMachineMO] (DirectAgent-498:10.223.59.66) Test against disk backing : [9de17e9b2280328bb1b2e662e7253c3f] i-2-36-VMWAREFORWARD/ROOT-36.vmdk
> 2013-08-30 16:13:08,706 INFO [vmware.mo.VirtualMachineMO] (DirectAgent-498:10.223.59.66) Test against disk backing : [9de17e9b2280328bb1b2e662e7253c3f] 31b1263bd2e735c5bdc2e964b291d76f/31b1263bd2e735c5bdc2e964b291d76f.vmdk
> 2013-08-30 16:13:08,706 INFO [vmware.mo.VirtualMachineMO] (DirectAgent-498:10.223.59.66) Test against disk device, controller key: 1000, unit number: 1
> 2013-08-30 16:13:08,706 INFO [vmware.mo.VirtualMachineMO] (DirectAgent-498:10.223.59.66) Test against disk backing : [9de17e9b2280328bb1b2e662e7253c3f] i-2-36-VMWAREFORWARD/5f480f78ae804e55b0e9729a25ab817f.vmdk
> 2013-08-30 16:13:08,706 INFO [vmware.mo.VirtualMachineMO] (DirectAgent-498:10.223.59.66) Disk backing : [9de17e9b2280328bb1b2e662e7253c3f] i-2-36-VMWAREFORWARD/5f480f78ae804e55b0e9729a25ab817f.vmdk matches ==> scsi0:1
> 2013-08-30 16:13:08,713 INFO [vmware.util.VmwareContext] (DirectAgent-498:10.223.59.66) Connected, conn: sun.net.www.protocol.https.DelegateHttpsURLConnection:https://10.223.52.61/folder/i-2-36-VMWAREFORWARD/5f480f78ae804e55b0e9729a25ab817f.vmdk?dcPath=VMDC&dsName=9de17e9b2280328bb1b2e662e7253c3f, retry: 0
> 2013-08-30 16:13:11,710 DEBUG [cloud.api.ApiServlet] (catalina-exec-5:null) ===START=== 10.215.2.19 -- GET command=queryAsyncJobResult&jobId=33d8f0b0-f545-4588-a845-39044a61db0b&response=json&sessionkey=iN1%2BFv5iLGYuxcPQU06GRgdBcU0%3D&_=1377904774275
> 2013-08-30 16:13:11,734 DEBUG [cloud.api.ApiServlet] (catalina-exec-5:null) ===END=== 10.215.2.19 -- GET command=queryAsyncJobResult&jobId=33d8f0b0-f545-4588-a845-39044a61db0b&response=json&sessionkey=iN1%2BFv5iLGYuxcPQU06GRgdBcU0%3D&_=1377904774275
> 2013-08-30 16:13:11,938 INFO [vmware.util.VmwareContext] (DirectAgent-498:10.223.59.66) Connected, conn: sun.net.www.protocol.https.DelegateHttpsURLConnection:https://10.223.52.61/folder/i-2-36-VMWAREFORWARD/i-2-36-VMWAREFORWARD.vmsd?dcPath=VMDC&dsName=9de17e9b2280328bb1b2e662e7253c3f, retry: 0
> 2013-08-30 16:13:12,123 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-2:null) Ping from 9
> 2013-08-30 16:13:12,562 WARN [vmware.mo.VirtualMachineMO] (DirectAgent-498:10.223.59.66) Snapshot descriptor file (vsd) does not exist anymore?
> 2013-08-30 16:13:12,571 INFO [vmware.util.VmwareContext] (DirectAgent-498:10.223.59.66) Connected, conn: sun.net.www.protocol.https.DelegateHttpsURLConnection:https://10.223.52.61/folder/i-2-36-VMWAREFORWARD/i-2-36-VMWAREFORWARD.vmsd?dcPath=VMDC&dsName=9de17e9b2280328bb1b2e662e7253c3f, retry: 0
> 2013-08-30 16:13:13,154 INFO [vmware.mo.DatastoreMO] (DirectAgent-498:10.223.59.66) Search file 5f480f78ae804e55b0e9729a25ab817f.vmdk on [9de17e9b2280328bb1b2e662e7253c3f]
> 2013-08-30 16:13:13,173 INFO [vmware.mo.DatastoreMO] (DirectAgent-498:10.223.59.66) File [9de17e9b2280328bb1b2e662e7253c3f] 5f480f78ae804e55b0e9729a25ab817f.vmdk does not exist on datastore
> 2013-08-30 16:13:13,173 INFO [vmware.mo.DatastoreMO] (DirectAgent-498:10.223.59.66) Searching file 5f480f78ae804e55b0e9729a25ab817f.vmdk in [9de17e9b2280328bb1b2e662e7253c3f]
> 2013-08-30 16:13:13,214 INFO [vmware.mo.DatastoreMO] (DirectAgent-498:10.223.59.66) Found file 5f480f78ae804e55b0e9729a25ab817f.vmdk in datastore at [9de17e9b2280328bb1b2e662e7253c3f] i-2-36-VMWAREFORWARD/
> 2013-08-30 16:13:13,217 INFO [vmware.mo.DatastoreMO] (DirectAgent-498:10.223.59.66) Search file 5f480f78ae804e55b0e9729a25ab817f-flat.vmdk on [9de17e9b2280328bb1b2e662e7253c3f] i-2-36-VMWAREFORWARD
> 2013-08-30 16:13:13,236 INFO [vmware.mo.DatastoreMO] (DirectAgent-498:10.223.59.66) File [9de17e9b2280328bb1b2e662e7253c3f] i-2-36-VMWAREFORWARD/5f480f78ae804e55b0e9729a25ab817f-flat.vmdk exists on datastore
> 2013-08-30 16:13:13,236 INFO [storage.resource.VmwareStorageLayoutHelper] (DirectAgent-498:10.223.59.66) Fixup folder-synchronization. move [9de17e9b2280328bb1b2e662e7253c3f] i-2-36-VMWAREFORWARD/5f480f78ae804e55b0e9729a25ab817f-flat.vmdk -> [9de17e9b2280328bb1b2e662e7253c3f] 5f480f78ae804e55b0e9729a25ab817f-flat.vmdk
> 2013-08-30 16:13:13,613 INFO [vmware.mo.DatastoreMO] (DirectAgent-498:10.223.59.66) Search file 5f480f78ae804e55b0e9729a25ab817f-delta.vmdk on [9de17e9b2280328bb1b2e662e7253c3f] i-2-36-VMWAREFORWARD
> 2013-08-30 16:13:13,659 INFO [vmware.mo.DatastoreMO] (DirectAgent-498:10.223.59.66) File [9de17e9b2280328bb1b2e662e7253c3f] i-2-36-VMWAREFORWARD/5f480f78ae804e55b0e9729a25ab817f-delta.vmdk does not exist on datastore
> 2013-08-30 16:13:13,660 INFO [storage.resource.VmwareStorageLayoutHelper] (DirectAgent-498:10.223.59.66) Fixup folder-synchronization. move [9de17e9b2280328bb1b2e662e7253c3f] i-2-36-VMWAREFORWARD/5f480f78ae804e55b0e9729a25ab817f.vmdk -> [9de17e9b2280328bb1b2e662e7253c3f] 5f480f78ae804e55b0e9729a25ab817f.vmdk
> 2013-08-30 16:13:14,127 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-498:null) Seq 1-1168048941: Response Received:
> 2013-08-30 16:13:14,127 DEBUG [agent.transport.Request] (DirectAgent-498:null) Seq 1-1168048941: Processing: { Ans: , MgmtId: 7471666038533, via: 1, Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.AttachAnswer":{"disk":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"8c27247d-e1e6-4768-92f4-d2b4e019223c","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"9de17e9b-2280-328b-b1b2-e662e7253c3f","id":204,"poolType":"NetworkFilesystem","host":"10.223.110.232","path":"/export/home/chandan/307PB-195-103/primary4","port":2049}},"name":"new-vol","size":1073741824,"path":"5f480f78ae804e55b0e9729a25ab817f","volumeId":44,"vmName":"i-2-36-VMWAREFORWARD","accountId":2,"format":"OVA","id":44,"hypervisorType":"VMware"}},"diskSeq":2,"vdiUuid":"[9de17e9b2280328bb1b2e662e7253c3f] i-2-36-VMWAREFORWARD/5f480f78ae804e55b0e9729a25ab817f.vmdk","type":"DATADISK"},"result":true,"wait":0}}] }
> 2013-08-30 16:13:14,128 DEBUG [agent.transport.Request] (Job-Executor-32:job-107 = [ 33d8f0b0-f545-4588-a845-39044a61db0b ]) Seq 1-1168048941: Received: { Ans: , MgmtId: 7471666038533, via: 1, Ver: v1, Flags: 10, { AttachAnswer } }
> 2013-08-30 16:13:14,150 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-32:job-107 = [ 33d8f0b0-f545-4588-a845-39044a61db0b ]) Complete async job-107 = [ 33d8f0b0-f545-4588-a845-39044a61db0b ], jobStatus: 1, resultCode: 0, result: org.apache.cloudstack.api.response.VolumeResponse@410b65cd
> 2013-08-30 16:13:14,157 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-32:job-107 = [ 33d8f0b0-f545-4588-a845-39044a61db0b ]) Done executing org.apache.cloudstack.api.command.user.volume.DetachVolumeCmd for job-107 = [ 33d8f0b0-f545-4588-a845-39044a61db0b ]
> 2013-08-30 16:13:14,516 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-3:null) SeqA 9-1578: Processing Seq 9-1578: { Cmd , MgmtId: -1, via: 9, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":30,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2013-08-30 16:13:14,522 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-3:null) SeqA 9-1578: Sending Seq 9-1578: { Ans: , MgmtId: 7471666038533, via: 9, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2013-08-30 16:13:14,710 DEBUG [cloud.api.ApiServlet] (catalina-exec-4:null) ===START=== 10.215.2.19 -- GET command=queryAsyncJobResult&jobId=33d8f0b0-f545-4588-a845-39044a61db0b&response=json&sessionkey=iN1%2BFv5iLGYuxcPQU06GRgdBcU0%3D&_=1377904777275
> 2013-08-30 16:13:14,722 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-4:null) Async job-107 = [ 33d8f0b0-f545-4588-a845-39044a61db0b ] completed
> 2013-08-30 16:13:14,729 DEBUG [cloud.api.ApiServlet] (catalina-exec-4:null) ===END=== 10.215.2.19 -- GET command=queryAsyncJobResult&jobId=33d8f0b0-f545-4588-a845-39044a61db0b&response=json&sessionkey=iN1%2BFv5iLGYuxcPQU06GRgdBcU0%3D&_=1377904777275
> 2013-08-30 16:13:14,756 DEBUG [cloud.api.ApiServlet] (catalina-exec-13:null) ===START=== 10.215.2.19 -- GET command=listVolumes&id=8c27247d-e1e6-4768-92f4-d2b4e019223c&response=json&sessionkey=iN1%2BFv5iLGYuxcPQU06GRgdBcU0%3D&_=1377904777320
> 2013-08-30 16:13:14,773 DEBUG [cloud.api.ApiServlet] (catalina-exec-13:null) ===END=== 10.215.2.19 -- GET command=listVolumes&id=8c27247d-e1e6-4768-92f4-d2b4e019223c&response=json&sessionkey=iN1%2BFv5iLGYuxcPQU06GRgdBcU0%3D&_=1377904777320
> 2013-08-30 16:13:14,887 DEBUG [cloud.api.ApiServlet] (catalina-exec-7:null) ===START=== 10.215.2.19 -- GET command=listTags&response=json&sessionkey=iN1%2BFv5iLGYuxcPQU06GRgdBcU0%3D&resourceId=8c27247d-e1e6-4768-92f4-d2b4e019223c&resourceType=Volume&listAll=true&_=1377904777450
> 2013-08-30 16:13:14,896 DEBUG [cloud.api.ApiServlet] (catalina-exec-7:null) ===END=== 10.215.2.19 -- GET command=listTags&response=json&sessionkey=iN1%2BFv5iLGYuxcPQU06GRgdBcU0%3D&resourceId=8c27247d-e1e6-4768-92f4-d2b4e019223c&resourceType=Volume&listAll=true&_=1377904777450
> 2013-08-30 16:13:16,644 DEBUG [cloud.api.ApiServlet] (catalina-exec-22:null) ===START=== 10.215.2.19 -- GET command=listDiskOfferings&response=json&sessionkey=iN1%2BFv5iLGYuxcPQU06GRgdBcU0%3D&_=1377904779208
> 2013-08-30 16:13:16,656 DEBUG [cloud.api.ApiServlet] (catalina-exec-22:null) ===END=== 10.215.2.19 -- GET command=listDiskOfferings&response=json&sessionkey=iN1%2BFv5iLGYuxcPQU06GRgdBcU0%3D&_=1377904779208
> 2013-08-30 16:13:18,096 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-5:null) Ping from 10
> 2013-08-30 16:13:19,540 DEBUG [cloud.api.ApiServlet] (catalina-exec-16:null) ===START=== 10.215.2.19 -- GET command=listVolumes&response=json&sessionkey=iN1%2BFv5iLGYuxcPQU06GRgdBcU0%3D&listAll=true&page=1&pagesize=20&_=1377904782104
> 2013-08-30 16:13:19,560 DEBUG [cloud.api.ApiServlet] (catalina-exec-16:null) ===END=== 10.215.2.19 -- GET command=listVolumes&response=json&sessionkey=iN1%2BFv5iLGYuxcPQU06GRgdBcU0%3D&listAll=true&page=1&pagesize=20&_=1377904782104
> 2013-08-30 16:13:20,685 DEBUG [cloud.api.ApiServlet] (catalina-exec-6:null) ===START=== 10.215.2.19 -- GET command=listVolumes&id=8c27247d-e1e6-4768-92f4-d2b4e019223c&response=json&sessionkey=iN1%2BFv5iLGYuxcPQU06GRgdBcU0%3D&_=1377904783248
> 2013-08-30 16:13:20,702 DEBUG [cloud.api.ApiServlet] (catalina-exec-6:null) ===END=== 10.215.2.19 -- GET command=listVolumes&id=8c27247d-e1e6-4768-92f4-d2b4e019223c&response=json&sessionkey=iN1%2BFv5iLGYuxcPQU06GRgdBcU0%3D&_=1377904783248
> 2013-08-30 16:13:20,805 DEBUG [cloud.api.ApiServlet] (catalina-exec-10:null) ===START=== 10.215.2.19 -- GET command=listTags&response=json&sessionkey=iN1%2BFv5iLGYuxcPQU06GRgdBcU0%3D&resourceId=8c27247d-e1e6-4768-92f4-d2b4e019223c&resourceType=Volume&listAll=true&_=1377904783367
> 2013-08-30 16:13:20,815 DEBUG [cloud.api.ApiServlet] (catalina-exec-10:null) ===END=== 10.215.2.19 -- GET command=listTags&response=json&sessionkey=iN1%2BFv5iLGYuxcPQU06GRgdBcU0%3D&resourceId=8c27247d-e1e6-4768-92f4-d2b4e019223c&resourceType=Volume&listAll=true&_=1377904783367
> 2013-08-30 16:13:21,994 DEBUG [cloud.api.ApiServlet] (catalina-exec-2:null) ===START=== 10.215.2.19 -- GET command=listDiskOfferings&response=json&sessionkey=iN1%2BFv5iLGYuxcPQU06GRgdBcU0%3D&_=1377904784559
> 2013-08-30 16:13:22,006 DEBUG [cloud.api.ApiServlet] (catalina-exec-2:null) ===END=== 10.215.2.19 -- GET command=listDiskOfferings&response=json&sessionkey=iN1%2BFv5iLGYuxcPQU06GRgdBcU0%3D&_=1377904784559
> 2013-08-30 16:13:24,516 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 9-1579: Processing Seq 9-1579: { Cmd , MgmtId: -1, via: 9, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":30,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2013-08-30 16:13:24,524 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 9-1579: Sending Seq 9-1579: { Ans: , MgmtId: 7471666038533, via: 9, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2013-08-30 16:13:26,021 DEBUG [cloud.api.ApiServlet] (catalina-exec-3:null) ===START=== 10.215.2.19 -- GET command=resizeVolume&id=8c27247d-e1e6-4768-92f4-d2b4e019223c&shrinkok=false&diskofferingid=80982db4-adba-48bb-ad0e-2a0c281b59cd&response=json&sessionkey=iN1%2BFv5iLGYuxcPQU06GRgdBcU0%3D&_=1377904788583
> 2013-08-30 16:13:26,068 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-3:null) submit async job-108 = [ a35c80cf-a1f4-41f6-a97a-9dcb97776f4c ], details: AsyncJobVO {id:108, userId: 2, accountId: 2, sessionKey: null, instanceType: Volume, instanceId: null, cmd: org.apache.cloudstack.api.command.user.volume.ResizeVolumeCmd, cmdOriginator: null, cmdInfo: {"response":"json","id":"8c27247d-e1e6-4768-92f4-d2b4e019223c","sessionkey":"iN1+Fv5iLGYuxcPQU06GRgdBcU0\u003d","shrinkok":"false","cmdEventType":"VOLUME.RESIZE","ctxUserId":"2","httpmethod":"GET","_":"1377904788583","ctxAccountId":"2","diskofferingid":"80982db4-adba-48bb-ad0e-2a0c281b59cd","ctxStartEventId":"883"}, cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0, processStatus: 0, resultCode: 0, result: null, initMsid: 7471666038533, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
> 2013-08-30 16:13:26,070 DEBUG [cloud.api.ApiServlet] (catalina-exec-3:null) ===END=== 10.215.2.19 -- GET command=resizeVolume&id=8c27247d-e1e6-4768-92f4-d2b4e019223c&shrinkok=false&diskofferingid=80982db4-adba-48bb-ad0e-2a0c281b59cd&response=json&sessionkey=iN1%2BFv5iLGYuxcPQU06GRgdBcU0%3D&_=1377904788583
> 2013-08-30 16:13:26,073 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-33:job-108 = [ a35c80cf-a1f4-41f6-a97a-9dcb97776f4c ]) Executing org.apache.cloudstack.api.command.user.volume.ResizeVolumeCmd for job-108 = [ a35c80cf-a1f4-41f6-a97a-9dcb97776f4c ]
> 2013-08-30 16:13:26,113 ERROR [cloud.async.AsyncJobManagerImpl] (Job-Executor-33:job-108 = [ a35c80cf-a1f4-41f6-a97a-9dcb97776f4c ]) Unexpected exception while executing org.apache.cloudstack.api.command.user.volume.ResizeVolumeCmd
> java.lang.NullPointerException
> at com.cloud.storage.VolumeManagerImpl.resizeVolume(VolumeManagerImpl.java:1147)
> at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
> at com.cloud.storage.VolumeManagerImpl.resizeVolume(VolumeManagerImpl.java:183)
> at org.apache.cloudstack.api.command.user.volume.ResizeVolumeCmd.execute(ResizeVolumeCmd.java:137)
> at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:158)
> at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:531)
> 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:679)
> 2013-08-30 16:13:26,116 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-33:job-108 = [ a35c80cf-a1f4-41f6-a97a-9dcb97776f4c ]) Complete async job-108 = [ a35c80cf-a1f4-41f6-a97a-9dcb97776f4c ], jobStatus: 2, resultCode: 530, result: Error Code: 530 Error text: null
> 2013-08-30 16:13:29,166 DEBUG [cloud.api.ApiServlet] (catalina-exec-25:null) ===START=== 10.215.2.19 -- GET command=queryAsyncJobResult&jobId=a35c80cf-a1f4-41f6-a97a-9dcb97776f4c&response=json&sessionkey=iN1%2BFv5iLGYuxcPQU06GRgdBcU0%3D&_=1377904791731
> 2013-08-30 16:13:29,178 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-25:null) Async job-108 = [ a35c80cf-a1f4-41f6-a97a-9dcb97776f4c ] completed
> 2013-08-30 16:13:29,183 DEBUG [cloud.api.ApiServlet] (catalina-exec-25:null) ===END=== 10.215.2.19 -- GET command=queryAsyncJobResult&jobId=a35c80cf-a1f4-41f6-a97a-9dcb97776f4c&response=json&sessionkey=iN1%2BFv5iLGYuxcPQU06GRgdBcU0%3D&_=1377904791731
> 2013-08-30 16:13:34,517 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 9-1580: Processing Seq 9-1580: { Cmd , MgmtId: -1, via: 9, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":30,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2013-08-30 16:13:34,525 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 9-1580: Sending Seq 9-1580: { Ans: , MgmtId: 7471666038533, via: 9, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2013-08-30 16:13:34,975 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) HostStatsCollector is running...
> 2013-08-30 16:13:34,982 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-497:null) Seq 1-1168048942: Executing request
> 2013-08-30 16:13:35,018 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-497:null) Seq 1-1168048942: Response Received:
> 2013-08-30 16:13:35,018 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 1-1168048942: Received: { Ans: , MgmtId: 7471666038533, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> 2013-08-30 16:13:35,055 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-499:null) Seq 6-580518622: Executing request
> 2013-08-30 16:13:35,082 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-499:null) Seq 6-580518622: Response Received:
> 2013-08-30 16:13:35,082 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 6-580518622: Received: { Ans: , MgmtId: 7471666038533, via: 6, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> 2013-08-30 16:13:35,098 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-93:null) Seq 8-2005992049: Executing request
> 2013-08-30 16:13:35,117 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
> 2013-08-30 16:13:35,123 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-93:null) Seq 8-2005992049: Response Received:
> 2013-08-30 16:13:35,123 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 8-2005992049: Received: { Ans: , MgmtId: 7471666038533, via: 8, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> 2013-08-30 16:13:35,251 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
> 2013-08-30 16:13:36,130 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
> 2013-08-30 16:13:36,131 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
> 2013-08-30 16:13:36,229 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
> 2013-08-30 16:13:36,230 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
> 2013-08-30 16:13:41,108 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-499:null) Seq 6-580517890: Executing request
> 2013-08-30 16:13:41,116 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-499:null) Seq 6-580517890: Response Received:
> 2013-08-30 16:13:41,116 DEBUG [agent.transport.Request] (DirectAgent-499:null) Seq 6-580517890: Processing: { Ans: , MgmtId: 7471666038533, via: 6, Ver: v1, Flags: 10, [{"com.cloud.agent.api.UnsupportedAnswer":{"result":false,"details":"Unsupported command issued:com.cloud.agent.api.CleanupNetworkRulesCmd. Are you sure you got the right type of server?","wait":0}}] }
> 2013-08-30 16:13:41,410 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Resetting hosts suitable for reconnect
> 2013-08-30 16:13:41,413 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed resetting hosts suitable for reconnect
> 2013-08-30 16:13:41,413 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters already owned by this management server
> 2013-08-30 16:13:41,414 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters already owned by this management server
> 2013-08-30 16:13:41,415 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters not owned by any management server
> 2013-08-30 16:13:41,415 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters not owned by any management server
> ^C
> [root@asfmgmt management]#
--
This message was sent by Atlassian JIRA
(v6.1.4#6159)