Return-Path: X-Original-To: apmail-cloudstack-issues-archive@www.apache.org Delivered-To: apmail-cloudstack-issues-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 3A21D1003E for ; Fri, 25 Oct 2013 19:58:41 +0000 (UTC) Received: (qmail 97611 invoked by uid 500); 25 Oct 2013 19:58:40 -0000 Delivered-To: apmail-cloudstack-issues-archive@cloudstack.apache.org Received: (qmail 97408 invoked by uid 500); 25 Oct 2013 19:58:34 -0000 Mailing-List: contact issues-help@cloudstack.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@cloudstack.apache.org Delivered-To: mailing list issues@cloudstack.apache.org Received: (qmail 97300 invoked by uid 500); 25 Oct 2013 19:58:32 -0000 Delivered-To: apmail-incubator-cloudstack-issues@incubator.apache.org Received: (qmail 97288 invoked by uid 99); 25 Oct 2013 19:58:31 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 25 Oct 2013 19:58:31 +0000 Date: Fri, 25 Oct 2013 19:58:31 +0000 (UTC) From: "Ariel Liguori (JIRA)" To: cloudstack-issues@incubator.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Created] (CLOUDSTACK-4965) Unable to deploy VM instance on VMware MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 Ariel Liguori created CLOUDSTACK-4965: ----------------------------------------- Summary: Unable to deploy VM instance on VMware Key: CLOUDSTACK-4965 URL: https://issues.apache.org/jira/browse/CLOUDSTACK-4965 Project: CloudStack Issue Type: Bug Security Level: Public (Anyone can view this level - this is the default.) Components: Management Server Affects Versions: 4.2.0 Environment: VMware vSphere 5.1 Reporter: Ariel Liguori Unable to deploy OVF of the VM (CentOS) on vSphere, router and other system templates vms are running and created fine. Attached log: 2013-10-25 16:48:12,561 DEBUG [api.query.QueryManagerImpl] (catalina-exec-13:null) >>>Searching for hosts>>> 2013-10-25 16:48:12,564 DEBUG [api.query.QueryManagerImpl] (catalina-exec-13:null) >>>Generating Response>>> 2013-10-25 16:48:12,564 DEBUG [cloud.api.ApiServlet] (catalina-exec-13:null) ===END=== 10.200.40.84 -- GET command=listHosts&response=json&sessionkey=kNtaYAKCgGu1k1tLfedSjo3LmR4%3D&state=Alert&page=1&pageSize=4&_=1382730491491 2013-10-25 16:48:12,569 DEBUG [cloud.api.ApiServlet] (catalina-exec-15:null) ===START=== 10.200.40.84 -- GET command=listCapacity&response=json&sessionkey=kNtaYAKCgGu1k1tLfedSjo3LmR4%3D&fetchLatest=false&sortBy=usage&page=0&pagesize=8&_=1382730491504 2013-10-25 16:48:12,582 DEBUG [cloud.api.ApiServlet] (catalina-exec-15:null) ===END=== 10.200.40.84 -- GET command=listCapacity&response=json&sessionkey=kNtaYAKCgGu1k1tLfedSjo3LmR4%3D&fetchLatest=false&sortBy=usage&page=0&pagesize=8&_=1382730491504 2013-10-25 16:48:13,165 DEBUG [cloud.api.ApiServlet] (catalina-exec-14:null) ===START=== 10.200.40.84 -- GET command=listVirtualMachines&response=json&sessionkey=kNtaYAKCgGu1k1tLfedSjo3LmR4%3D&listAll=true&page=1&pagesize=20&_=1382730492099 2013-10-25 16:48:13,193 DEBUG [cloud.api.ApiServlet] (catalina-exec-14:null) ===END=== 10.200.40.84 -- GET command=listVirtualMachines&response=json&sessionkey=kNtaYAKCgGu1k1tLfedSjo3LmR4%3D&listAll=true&page=1&pagesize=20&_=1382730492099 2013-10-25 16:48:13,712 DEBUG [cloud.api.ApiServlet] (catalina-exec-18:null) ===START=== 10.200.40.84 -- GET command=listVirtualMachines&id=f72eec25-fc0f-42f4-8ce3-cbdc0cfadf78&response=json&sessionkey=kNtaYAKCgGu1k1tLfedSjo3LmR4%3D&_=1382730492635 2013-10-25 16:48:13,729 DEBUG [cloud.api.ApiServlet] (catalina-exec-18:null) ===END=== 10.200.40.84 -- GET command=listVirtualMachines&id=f72eec25-fc0f-42f4-8ce3-cbdc0cfadf78&response=json&sessionkey=kNtaYAKCgGu1k1tLfedSjo3LmR4%3D&_=1382730492635 2013-10-25 16:48:13,740 DEBUG [cloud.api.ApiServlet] (catalina-exec-19:null) ===START=== 10.200.40.84 -- GET command=listOsTypes&response=json&sessionkey=kNtaYAKCgGu1k1tLfedSjo3LmR4%3D&_=1382730492675 2013-10-25 16:48:13,952 DEBUG [cloud.api.ApiServlet] (catalina-exec-19:null) ===END=== 10.200.40.84 -- GET command=listOsTypes&response=json&sessionkey=kNtaYAKCgGu1k1tLfedSjo3LmR4%3D&_=1382730492675 2013-10-25 16:48:14,024 DEBUG [cloud.api.ApiServlet] (catalina-exec-20:null) ===START=== 10.200.40.84 -- GET command=queryAsyncJobResult&jobId=5a123f7f-1930-4ccb-8c73-2518587811cd&response=json&sessionkey=kNtaYAKCgGu1k1tLfedSjo3LmR4%3D&_=1382730492959 2013-10-25 16:48:14,043 DEBUG [cloud.api.ApiServlet] (catalina-exec-20:null) ===END=== 10.200.40.84 -- GET command=queryAsyncJobResult&jobId=5a123f7f-1930-4ccb-8c73-2518587811cd&response=json&sessionkey=kNtaYAKCgGu1k1tLfedSjo3LmR4%3D&_=1382730492959 2013-10-25 16:48:14,951 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM 2013-10-25 16:48:15,096 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy 2013-10-25 16:48:15,579 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 1 routers to update status. 2013-10-25 16:48:15,580 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status. 2013-10-25 16:48:15,607 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 1 routers to update status. 2013-10-25 16:48:15,608 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status. 2013-10-25 16:48:16,786 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) Ping from 3 2013-10-25 16:48:17,024 DEBUG [cloud.api.ApiServlet] (catalina-exec-21:null) ===START=== 10.200.40.84 -- GET command=queryAsyncJobResult&jobId=5a123f7f-1930-4ccb-8c73-2518587811cd&response=json&sessionkey=kNtaYAKCgGu1k1tLfedSjo3LmR4%3D&_=1382730495960 2013-10-25 16:48:17,044 DEBUG [cloud.api.ApiServlet] (catalina-exec-21:null) ===END=== 10.200.40.84 -- GET command=queryAsyncJobResult&jobId=5a123f7f-1930-4ccb-8c73-2518587811cd&response=json&sessionkey=kNtaYAKCgGu1k1tLfedSjo3LmR4%3D&_=1382730495960 2013-10-25 16:48:17,748 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:null) Ping from 4 2013-10-25 16:48:19,700 DEBUG [agent.transport.Request] (AgentManager-Handler-9:null) Seq 4-2026438666: Processing: { Ans: , MgmtId: 345051900587, via: 4, Ver: v1, Flags: 110, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"details":"Unable to copy template to primary storage due to exception:Exception: java.lang.Exception\nMessage: Unable to connect to sun.net.www.protocol.https.DelegateHttpsURLConnection:https://10.120.4.61/nfc/529a9d8c-59b8-c3f0-426f-86dc86ca9e9e/disk-0.vmdk\n","wait":0}}] } 2013-10-25 16:48:19,700 DEBUG [agent.transport.Request] (Job-Executor-1:job-36 = [ 5a123f7f-1930-4ccb-8c73-2518587811cd ]) Seq 4-2026438666: Received: { Ans: , MgmtId: 345051900587, via: 4, Ver: v1, Flags: 110, { CopyCmdAnswer } } 2013-10-25 16:48:19,716 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-9:null) Seq 4-2026438666: No more commands found 2013-10-25 16:48:19,730 INFO [storage.volume.VolumeServiceImpl] (Job-Executor-1:job-36 = [ 5a123f7f-1930-4ccb-8c73-2518587811cd ]) releasing lock for VMTemplateStoragePool 2 2013-10-25 16:48:19,730 WARN [utils.db.Merovingian2] (Job-Executor-1:job-36 = [ 5a123f7f-1930-4ccb-8c73-2518587811cd ]) Was unable to find lock for the key template_spool_ref2 and thread id 105361403 2013-10-25 16:48:19,734 DEBUG [cloud.storage.VolumeManagerImpl] (Job-Executor-1:job-36 = [ 5a123f7f-1930-4ccb-8c73-2518587811cd ]) Unable to create Vol[10|vm=10|ROOT]:Unable to copy template to primary storage due to exception:Exception: java.lang.Exception Message: Unable to connect to sun.net.www.protocol.https.DelegateHttpsURLConnection:https://10.120.4.61/nfc/529a9d8c-59b8-c3f0-426f-86dc86ca9e9e/disk-0.vmdk 2013-10-25 16:48:19,753 INFO [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-1:job-36 = [ 5a123f7f-1930-4ccb-8c73-2518587811cd ]) Unable to contact resource. com.cloud.exception.StorageUnavailableException: Resource [StoragePool:1] is unreachable: Unable to create Vol[10|vm=10|ROOT]:Unable to copy template to primary storage due to exception:Exception: java.lang.Exception Message: Unable to connect to sun.net.www.protocol.https.DelegateHttpsURLConnection:https://10.120.4.61/nfc/529a9d8c-59b8-c3f0-426f-86dc86ca9e9e/disk-0.vmdk at com.cloud.storage.VolumeManagerImpl.recreateVolume(VolumeManagerImpl.java:2560) at com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.java:2611) at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:889) at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:578) 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:3406) at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2966) at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2952) 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:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:724) 2013-10-25 16:48:19,759 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-1:job-36 = [ 5a123f7f-1930-4ccb-8c73-2518587811cd ]) Cleaning up resources for the vm VM[User|2fe71442-3246-4a2b-975a-29f0085b2344] in Starting state 2013-10-25 16:48:19,761 DEBUG [agent.transport.Request] (Job-Executor-1:job-36 = [ 5a123f7f-1930-4ccb-8c73-2518587811cd ]) Seq 2-595984404: Sending { Cmd , MgmtId: 345051900587, via: 2, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-2-10-VM","wait":0}}] } 2013-10-25 16:48:19,761 DEBUG [agent.transport.Request] (Job-Executor-1:job-36 = [ 5a123f7f-1930-4ccb-8c73-2518587811cd ]) Seq 2-595984404: Executing: { Cmd , MgmtId: 345051900587, via: 2, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-2-10-VM","wait":0}}] } 2013-10-25 16:48:19,761 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-28:null) Seq 2-595984404: Executing request 2013-10-25 16:48:19,762 INFO [vmware.resource.VmwareResource] (DirectAgent-28:10.120.4.48) Executing resource StopCommand: {"isProxy":false,"executeInSequence":true,"vmName":"i-2-10-VM","wait":0} 2013-10-25 16:48:19,762 DEBUG [vmware.mo.HostMO] (DirectAgent-28:10.120.4.48) find VM i-2-10-VM on host 2013-10-25 16:48:19,762 INFO [vmware.mo.HostMO] (DirectAgent-28:10.120.4.48) VM i-2-10-VM not found in host cache 2013-10-25 16:48:19,762 DEBUG [vmware.mo.HostMO] (DirectAgent-28:10.120.4.48) load VM cache on host 2013-10-25 16:48:19,779 INFO [vmware.resource.VmwareResource] (DirectAgent-28:10.120.4.48) VM i-2-10-VM is no longer in vSphere 2013-10-25 16:48:19,780 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-28:null) Seq 2-595984404: Response Received: 2013-10-25 16:48:19,780 DEBUG [agent.transport.Request] (DirectAgent-28:null) Seq 2-595984404: Processing: { Ans: , MgmtId: 345051900587, via: 2, Ver: v1, Flags: 110, [{"com.cloud.agent.api.StopAnswer":{"vncPort":0,"result":true,"details":"VM i-2-10-VM is no longer in vSphere","wait":0}}] } 2013-10-25 16:48:19,780 DEBUG [agent.manager.AgentAttache] (DirectAgent-28:null) Seq 2-595984404: No more commands found -- This message was sent by Atlassian JIRA (v6.1#6144)