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