[
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)
