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:29:25 UTC
[jira] [Created] (CLOUDSTACK-5014) vmware:deployVM with data disk
failed with exception
sadhu suresh created CLOUDSTACK-5014:
----------------------------------------
Summary: 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
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)