cloudstack-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Likitha Shetty (JIRA)" <j...@apache.org>
Subject [jira] [Resolved] (CLOUDSTACK-5014) vmware:deployVM with data disk failed with exception
Date Thu, 28 Nov 2013 09:57:35 GMT

     [ https://issues.apache.org/jira/browse/CLOUDSTACK-5014?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]

Likitha Shetty resolved CLOUDSTACK-5014.
----------------------------------------

    Resolution: Fixed

Use Cloudstack global config 'vmware.vcenter.session.timeout' to increase the default timeout
value. 
In vCenter under Tasks and Events, check how long the task that times out in CS takes (for
e.g. in this case Clone VM task) and increase the timeout value i.e. 'vmware.vcenter.session.timeout'
accordingly.

> vmware:deployVM with data disk failed with exception
> ----------------------------------------------------
>
>                 Key: CLOUDSTACK-5014
>                 URL: https://issues.apache.org/jira/browse/CLOUDSTACK-5014
>             Project: CloudStack
>          Issue Type: Bug
>      Security Level: Public(Anyone can view this level - this is the default.) 
>          Components: VMware
>    Affects Versions: 4.2.1
>         Environment: vmware esx5.1,CS4.2.1,single cluster with 2 hosts
>            Reporter: sadhu suresh
>            Assignee: Likitha Shetty
>            Priority: Critical
>             Fix For: 4.3.0
>
>         Attachments: management-server.rar
>
>
> I am seeing issue while deploying a vm with data disk.with out data disk deployment of
of VM is successful.
> step:
> deploy a vm with data disk from Instance wizrd.
> actual restul:
> it failed to deploy a vm with data disk and failed with below exception.
> content of management log:
> oxyVmId":2,"_loadInfo":"{\n  \"connections\": [\n    {\n      \"id\": 3,\n      \"clientInfo\":
\"\",\n      \"host\": \"10.147.40.30\",\n      \"port\": 5908,\n      \"tag\": \"d6210c9b-1a45-42eb-8168-19f52514962a\",\n
     \"createTime\": 1383199413793,\n      \"lastUsedTime\": 1383203890630\n    }\n  ]\n}","wait":0}}]
}
> 2013-10-31 18:11:51,347 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:null)
SeqA 2-19966: Sending Seq 2-19966:  { Ans: , MgmtId: 7363452993625, via: 2, Ver: v1, Flags:
100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2013-10-31 18:11:52,546 DEBUG [cloud.api.ApiServlet] (catalina-exec-19:null) ===START===
 10.252.192.84 -- GET  command=queryAsyncJobResult&jobId=9cf7cabd-9b44-4fc2-8884-9db545f0e1a3&response=json&sessionkey=aAQt9Yyfw4w6FrqI7b8inoH61XQ%3D&_=1383203895429
> 2013-10-31 18:11:52,579 DEBUG [cloud.api.ApiServlet] (catalina-exec-19:null) ===END===
 10.252.192.84 -- GET  command=queryAsyncJobResult&jobId=9cf7cabd-9b44-4fc2-8884-9db545f0e1a3&response=json&sessionkey=aAQt9Yyfw4w6FrqI7b8inoH61XQ%3D&_=1383203895429
> 2013-10-31 18:11:55,494 DEBUG [cloud.api.ApiServlet] (catalina-exec-13:null) ===START===
 10.252.192.84 -- GET  command=queryAsyncJobResult&jobId=9cf7cabd-9b44-4fc2-8884-9db545f0e1a3&response=json&sessionkey=aAQt9Yyfw4w6FrqI7b8inoH61XQ%3D&_=1383203898430
> 2013-10-31 18:11:55,529 DEBUG [cloud.api.ApiServlet] (catalina-exec-13:null) ===END===
 10.252.192.84 -- GET  command=queryAsyncJobResult&jobId=9cf7cabd-9b44-4fc2-8884-9db545f0e1a3&response=json&sessionkey=aAQt9Yyfw4w6FrqI7b8inoH61XQ%3D&_=1383203898430
> 2013-10-31 18:11:57,460 INFO  [vmware.resource.VmwareResource] (DirectAgent-45:null)
Scan hung worker VM to recycle
> 2013-10-31 18:11:57,496 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-45:null)
Ping from 1
> 2013-10-31 18:11:58,493 DEBUG [cloud.api.ApiServlet] (catalina-exec-21:null) ===START===
 10.252.192.84 -- GET  command=queryAsyncJobResult&jobId=9cf7cabd-9b44-4fc2-8884-9db545f0e1a3&response=json&sessionkey=aAQt9Yyfw4w6FrqI7b8inoH61XQ%3D&_=1383203901431
> 2013-10-31 18:11:58,526 DEBUG [cloud.api.ApiServlet] (catalina-exec-21:null) ===END===
 10.252.192.84 -- GET  command=queryAsyncJobResult&jobId=9cf7cabd-9b44-4fc2-8884-9db545f0e1a3&response=json&sessionkey=aAQt9Yyfw4w6FrqI7b8inoH61XQ%3D&_=1383203901431
> 2013-10-31 18:12:01,339 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null)
SeqA 2-19967: Processing Seq 2-19967:  { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
 \"connections\": [\n    {\n      \"id\": 3,\n      \"clientInfo\": \"\",\n      \"host\":
\"10.147.40.30\",\n      \"port\": 5908,\n      \"tag\": \"d6210c9b-1a45-42eb-8168-19f52514962a\",\n
     \"createTime\": 1383199413793,\n      \"lastUsedTime\": 1383203902626\n    }\n  ]\n}","wait":0}}]
}
> 2013-10-31 18:12:01,348 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null)
SeqA 2-19967: Sending Seq 2-19967:  { Ans: , MgmtId: 7363452993625, via: 2, Ver: v1, Flags:
100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2013-10-31 18:12:01,545 DEBUG [cloud.api.ApiServlet] (catalina-exec-16:null) ===START===
 10.252.192.84 -- GET  command=queryAsyncJobResult&jobId=9cf7cabd-9b44-4fc2-8884-9db545f0e1a3&response=json&sessionkey=aAQt9Yyfw4w6FrqI7b8inoH61XQ%3D&_=1383203904431
> 2013-10-31 18:12:01,576 DEBUG [cloud.api.ApiServlet] (catalina-exec-16:null) ===END===
 10.252.192.84 -- GET  command=queryAsyncJobResult&jobId=9cf7cabd-9b44-4fc2-8884-9db545f0e1a3&response=json&sessionkey=aAQt9Yyfw4w6FrqI7b8inoH61XQ%3D&_=1383203904431
> 2013-10-31 18:12:04,502 DEBUG [cloud.api.ApiServlet] (catalina-exec-15:null) ===START===
 10.252.192.84 -- GET  command=queryAsyncJobResult&jobId=9cf7cabd-9b44-4fc2-8884-9db545f0e1a3&response=json&sessionkey=aAQt9Yyfw4w6FrqI7b8inoH61XQ%3D&_=1383203907430
> 2013-10-31 18:12:04,538 DEBUG [cloud.api.ApiServlet] (catalina-exec-15:null) ===END===
 10.252.192.84 -- GET  command=queryAsyncJobResult&jobId=9cf7cabd-9b44-4fc2-8884-9db545f0e1a3&response=json&sessionkey=aAQt9Yyfw4w6FrqI7b8inoH61XQ%3D&_=1383203907430
> 2013-10-31 18:12:05,317 ERROR [storage.resource.VmwareStorageProcessor] (DirectAgent-134:10.147.40.30)
clone volume from base image failed due to Exception: javax.xml.ws.WebServiceException
> Message: java.net.SocketTimeoutException: Read timed out
> ssage: java.net.SocketTimeoutException: Read timed out
> javax.xml.ws.WebServiceException: java.net.SocketTimeoutException: Read timed out
>         at com.sun.xml.internal.ws.transport.http.client.HttpClientTransport.readResponseCodeAndMessage(HttpClientTransport.java:201)
>         at com.sun.xml.internal.ws.transport.http.client.HttpTransportPipe.process(HttpTransportPipe.java:151)
>         at com.sun.xml.internal.ws.transport.http.client.HttpTransportPipe.processRequest(HttpTransportPipe.java:83)
>         at com.sun.xml.internal.ws.transport.DeferredTransportPipe.processRequest(DeferredTransportPipe.java:78)
>         at com.sun.xml.internal.ws.api.pipe.Fiber.__doRun(Fiber.java:587)
>         at com.sun.xml.internal.ws.api.pipe.Fiber._doRun(Fiber.java:546)
>         at com.sun.xml.internal.ws.api.pipe.Fiber.doRun(Fiber.java:531)
>         at com.sun.xml.internal.ws.api.pipe.Fiber.runSync(Fiber.java:428)
>         at com.sun.xml.internal.ws.client.Stub.process(Stub.java:211)
>         at com.sun.xml.internal.ws.client.sei.SEIStub.doProcess(SEIStub.java:124)
>         at com.sun.xml.internal.ws.client.sei.SyncMethodHandler.invoke(SyncMethodHandler.java:98)
>         at com.sun.xml.internal.ws.client.sei.SyncMethodHandler.invoke(SyncMethodHandler.java:78)
>         at com.sun.xml.internal.ws.client.sei.SEIStub.invoke(SEIStub.java:107)
>         at $Proxy90.waitForUpdates(Unknown Source)
>         at com.cloud.hypervisor.vmware.util.VmwareClient.waitForValues(VmwareClient.java:462)
>         at com.cloud.hypervisor.vmware.util.VmwareClient.waitForTask(VmwareClient.java:404)
>         at com.cloud.hypervisor.vmware.mo.VirtualMachineMO.createFullClone(VirtualMachineMO.java:602)
>         at com.cloud.storage.resource.VmwareStorageProcessor.createVMFullClone(VmwareStorageProcessor.java:296)
>         at com.cloud.storage.resource.VmwareStorageProcessor.cloneVolumeFromBaseTemplate(VmwareStorageProcessor.java:382)
>         at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.execute(StorageSubsystemCommandHandlerBase.java:73)
>         at com.cloud.storage.resource.VmwareStorageSubsystemCommandHandler.execute(VmwareStorageSubsystemCommandHandler.java:155)
>         at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.handleStorageCommands(StorageSubsystemCommandHandlerBase.java:49)
>         at com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:559)
>         at com.cloud.agent.manager.DirectAgentAttache$Task.run(DirectAgentAttache.java:186)
>         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.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165)
>         at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)
>         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)
> Caused by: java.net.SocketTimeoutException: Read timed out
>         at java.net.SocketInputStream.socketRead0(Native Method)
>         at java.net.SocketInputStream.read(SocketInputStream.java:146)
>         at sun.security.ssl.InputRecord.readFully(InputRecord.java:312)
>         at sun.security.ssl.InputRecord.read(InputRecord.java:350)
>         at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:850)
>         at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:807)
>         at sun.security.ssl.AppInputStream.read(AppInputStream.java:94)
>         at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)
>         at java.io.BufferedInputStream.read1(BufferedInputStream.java:275)
>         at java.io.BufferedInputStream.read(BufferedInputStream.java:334)
>         at sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:688)
>         at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:633)
>         at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1162)
>         at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:397)
>         at sun.net.www.protocol.https.HttpsURLConnectionImpl.getResponseCode(HttpsURLConnectionImpl.java:338)
>         at com.sun.xml.internal.ws.transport.http.client.HttpClientTransport.readResponseCodeAndMessage(HttpClientTransport.java:198)
>         ... 31 more
> 2013-10-31 18:12:05,321 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-134:null)
Seq 4-464984010: Response Received:
> 2013-10-31 18:12:05,323 DEBUG [agent.transport.Request] (DirectAgent-134:null) Seq 4-464984010:
Processing:  { Ans: , MgmtId: 7363452993625, via: 4, Ver: v1, Flags: 110, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"details":"javax.xml.ws.WebServiceException:
java.net.SocketTimeoutException: Read timed out","wait":0}}] }
> 2013-10-31 18:12:05,323 DEBUG [agent.transport.Request] (Job-Executor-78:job-211 = [
9cf7cabd-9b44-4fc2-8884-9db545f0e1a3 ]) Seq 4-464984010: Received:  { Ans: , MgmtId: 7363452993625,
via: 4, Ver: v1, Flags: 110, { CopyCmdAnswer } }
> 2013-10-31 18:12:05,327 DEBUG [agent.manager.AgentAttache] (DirectAgent-134:null) Seq
4-464984010: No more commands found
> 2013-10-31 18:12:05,333 WARN  [storage.datastore.ObjectInDataStoreManagerImpl] (Job-Executor-78:job-211
= [ 9cf7cabd-9b44-4fc2-8884-9db545f0e1a3 ]) Unsupported data object (VOLUME, org.apache.cloudstack.storage.datastore.PrimaryDataStoreImpl@7e3ced98),
no need to delete from object in store ref table
> 2013-10-31 18:12:05,335 DEBUG [cloud.storage.VolumeManagerImpl] (Job-Executor-78:job-211
= [ 9cf7cabd-9b44-4fc2-8884-9db545f0e1a3 ]) Unable to create Vol[55|vm=53|ROOT]:javax.xml.ws.WebServiceException:
java.net.SocketTimeoutException: Read timed out
> 2013-10-31 18:12:05,335 INFO  [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-78:job-211
= [ 9cf7cabd-9b44-4fc2-8884-9db545f0e1a3 ]) Unable to contact resource.
> com.cloud.exception.StorageUnavailableException: Resource [StoragePool:1] is unreachable:
Unable to create Vol[55|vm=53|ROOT]:javax.xml.ws.WebServiceException: java.net.SocketTimeoutException:
Read timed out
>         at com.cloud.storage.VolumeManagerImpl.recreateVolume(VolumeManagerImpl.java:2580)
>         at com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.java:2631)
>         at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:888)
>         at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:577)
>         at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:227)
>         at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
>         at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3425)
>         at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2985)
>         at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2971)
>         at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
>         at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:420)
>         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-10-31 18:12:05,342 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-78:job-211
= [ 9cf7cabd-9b44-4fc2-8884-9db545f0e1a3 ]) Cleaning up resources for the vm VM[User|babu]
in Starting state
> 2013-10-31 18:12:05,345 DEBUG [agent.transport.Request] (Job-Executor-78:job-211 = [
9cf7cabd-9b44-4fc2-8884-9db545f0e1a3 ]) Seq 4-464984033: Sending  { Cmd , MgmtId: 7363452993625,
via: 4, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-2-53-VM","wait":0}}]
}
> 2013-10-31 18:12:05,346 DEBUG [agent.transport.Request] (Job-Executor-78:job-211 = [
9cf7cabd-9b44-4fc2-8884-9db545f0e1a3 ]) Seq 4-464984033: Executing:  { Cmd , MgmtId: 7363452993625,
via: 4, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-2-53-VM","wait":0}}]
}
> 2013-10-31 18:12:05,346 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-20:null)
Seq 4-464984033: Executing request
> 2013-10-31 18:12:05,346 INFO  [vmware.resource.VmwareResource] (DirectAgent-20:10.147.40.30)
Executing resource StopCommand: {"isProxy":false,"executeInSequence":true,"vmName":"i-2-53-VM","wait":0}
> 2013-10-31 18:12:05,386 DEBUG [vmware.mo.HostMO] (DirectAgent-20:10.147.40.30) find VM
i-2-53-VM on host
> 2013-10-31 18:12:05,387 INFO  [vmware.mo.HostMO] (DirectAgent-20:10.147.40.30) VM i-2-53-VM
not found in host cache
> 2013-10-31 18:12:05,387 DEBUG [vmware.mo.HostMO] (DirectAgent-20:10.147.40.30) load VM
cache on host
> 2013-10-31 18:12:05,404 INFO  [vmware.resource.VmwareResource] (DirectAgent-20:10.147.40.30)
VM i-2-53-VM is no longer in vSphere
> 2013-10-31 18:12:05,405 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-20:null)
Seq 4-464984033: Response Received:
> 2013-10-31 18:12:05,406 DEBUG [agent.transport.Request] (DirectAgent-20:null) Seq 4-464984033:
Processing:  { Ans: , MgmtId: 7363452993625, via: 4, Ver: v1, Flags: 110, [{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"VM
i-2-53-VM is no longer in vSphere","wait":0}}] }



--
This message was sent by Atlassian JIRA
(v6.1#6144)

Mime
View raw message