You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "sadhu suresh (JIRA)" <ji...@apache.org> on 2013/10/31 08:33:25 UTC
[jira] [Updated] (CLOUDSTACK-5014) vmware:deployVM with data disk
failed with exception
[ https://issues.apache.org/jira/browse/CLOUDSTACK-5014?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
sadhu suresh updated CLOUDSTACK-5014:
-------------------------------------
Attachment: management-server.rar
management log
> 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
> Reporter: sadhu suresh
> Priority: Critical
> 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)