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 AD5CA186FE for ; Mon, 1 Feb 2016 16:00:51 +0000 (UTC) Received: (qmail 24590 invoked by uid 500); 1 Feb 2016 16:00:41 -0000 Delivered-To: apmail-cloudstack-issues-archive@cloudstack.apache.org Received: (qmail 24486 invoked by uid 500); 1 Feb 2016 16:00:41 -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 24461 invoked by uid 500); 1 Feb 2016 16:00:41 -0000 Delivered-To: apmail-incubator-cloudstack-issues@incubator.apache.org Received: (qmail 24450 invoked by uid 99); 1 Feb 2016 16:00:41 -0000 Received: from arcas.apache.org (HELO arcas) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 01 Feb 2016 16:00:41 +0000 Received: from arcas.apache.org (localhost [127.0.0.1]) by arcas (Postfix) with ESMTP id 5CB732C14F7 for ; Mon, 1 Feb 2016 16:00:41 +0000 (UTC) Date: Mon, 1 Feb 2016 16:00:41 +0000 (UTC) From: "ASF GitHub Bot (JIRA)" To: cloudstack-issues@incubator.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Commented] (CLOUDSTACK-8830) VM snapshot fails for 12 min after instance creation MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/CLOUDSTACK-8830?page=3Dcom.atla= ssian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId= =3D15126444#comment-15126444 ]=20 ASF GitHub Bot commented on CLOUDSTACK-8830: -------------------------------------------- Github user alexandrelimassantana commented on the pull request: https://github.com/apache/cloudstack/pull/798#issuecomment-178042092 =20 Hi @maneesha-p I see you did the extraction, but could you also write t= he method javadoc along with it? As simple as it is, it can help people und= erstand it when using it. =20 Thanks for your time. > VM snapshot fails for 12 min after instance creation > ---------------------------------------------------- > > Key: CLOUDSTACK-8830 > URL: https://issues.apache.org/jira/browse/CLOUDSTACK-883= 0 > Project: CloudStack > Issue Type: Bug > Security Level: Public(Anyone can view this level - this is the defa= ult.)=20 > Reporter: Maneesha > Assignee: Maneesha > > ISSUE > =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D > VM snapshot fails for 12 min after instance creation > Environment > =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D > Product Name: Cloudstack > Hypervisor: VMWare VSphere 6 > VM DETAILS > =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D > i-84987-16119-VM > STORAGE CONFIGURATION > =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D > NA > TROUBLESHOOTING > =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D > I see that the following failure and immediate success result for the Cre= ateVMSnapshot call > {noformat} > 2015-07-24 08:20:55,363 DEBUG [c.c.a.t.Request] (Work-Job-Executor-61:ctx= -03fad7f2 job-64835/job-64836 ctx-746f3965) (logid:8b87ab8a) Seq 80-6161487= 240196259878: Sending { Cmd , MgmtId: 345051581208, via: 80(ussfoldcsesx11= 2.adslab.local), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.CreateVMSna= pshotCommand":{"volumeTOs":[{"uuid":"a89b4ad5-f23f-4df6-84a8-89c4f40b2edb",= "volumeType":"ROOT","volumeState":"Ready","dataStore":{"org.apache.cloudsta= ck.storage.to.PrimaryDataStoreTO":{"uuid":"346b381a-8543-3f7b-9eff-fa909ad2= 43c7","id":205,"poolType":"NetworkFilesystem","host":"10.144.35.110","path"= :"/tintri/ECS-SR-CLD200","port":2049,"url":"NetworkFilesystem://10.144.35.1= 10/tintri/ECS-SR-CLD200/?ROLE=3DPrimary&STOREUUID=3D346b381a-8543-3f7b-9eff= -fa909ad243c7"}},"name":"ROOT-16119","size":1073741824,"path":"ROOT-16119",= "volumeId":19311,"vmName":"i-84987-16119-VM","vmState":"Running","accountId= ":84987,"chainInfo":"{\"diskDeviceBusName\":\"ide0:1\",\"diskChain\":[\"[34= 6b381a85433f7b9efffa909ad243c7] i-84987-16119-VM/ROOT-16119.vmdk\",\"[346b3= 81a85433f7b9efffa909ad243c7] 49f59e1a4ce23fec8890c8b9e5891d56/49f59e1a4ce23= fec8890c8b9e5891d56.vmdk\"]}","format":"OVA","provisioningType":"THIN","id"= :19311,"deviceId":0,"cacheMode":"NONE","hypervisorType":"VMware"}],"target"= :{"id":962,"snapshotName":"i-84987-16119-VM_VS_20150724152053","type":"Disk= ","current":false,"description":"unit-test-instance-snapshot","quiescevm":f= alse},"vmName":"i-84987-16119-VM","guestOSType":"None","wait":1800}}] } > 2015-07-24 08:20:55,373 DEBUG [c.c.a.t.Request] (Work-Job-Executor-61:ctx= -03fad7f2 job-64835/job-64836 ctx-746f3965) (logid:8b87ab8a) Seq 80-6161487= 240196259878: Executing: { Cmd , MgmtId: 345051581208, via: 80(ussfoldcses= x112.adslab.local), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.CreateVM= SnapshotCommand":{"volumeTOs":[{"uuid":"a89b4ad5-f23f-4df6-84a8-89c4f40b2ed= b","volumeType":"ROOT","volumeState":"Ready","dataStore":{"org.apache.cloud= stack.storage.to.PrimaryDataStoreTO":{"uuid":"346b381a-8543-3f7b-9eff-fa909= ad243c7","id":205,"poolType":"NetworkFilesystem","host":"10.144.35.110","pa= th":"/tintri/ECS-SR-CLD200","port":2049,"url":"NetworkFilesystem://10.144.3= 5.110/tintri/ECS-SR-CLD200/?ROLE=3DPrimary&STOREUUID=3D346b381a-8543-3f7b-9= eff-fa909ad243c7"}},"name":"ROOT-16119","size":1073741824,"path":"ROOT-1611= 9","volumeId":19311,"vmName":"i-84987-16119-VM","vmState":"Running","accoun= tId":84987,"chainInfo":"{\"diskDeviceBusName\":\"ide0:1\",\"diskChain\":[\"= [346b381a85433f7b9efffa909ad243c7] i-84987-16119-VM/ROOT-16119.vmdk\",\"[34= 6b381a85433f7b9efffa909ad243c7] 49f59e1a4ce23fec8890c8b9e5891d56/49f59e1a4c= e23fec8890c8b9e5891d56.vmdk\"]}","format":"OVA","provisioningType":"THIN","= id":19311,"deviceId":0,"cacheMode":"NONE","hypervisorType":"VMware"}],"targ= et":{"id":962,"snapshotName":"i-84987-16119-VM_VS_20150724152053","type":"D= isk","current":false,"description":"unit-test-instance-snapshot","quiescevm= ":false},"vmName":"i-84987-16119-VM","guestOSType":"None","wait":1800}}] } > 2015-07-24 08:20:55,374 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-6= 6:ctx-5fbdccd8) (logid:710814a5) Seq 80-6161487240196259878: Executing requ= est > 2015-07-24 08:20:55,523 ERROR [c.c.h.v.m.VmwareStorageManagerImpl] (Direc= tAgent-66:ctx-5fbdccd8 ussfoldcsesx112.adslab.local, job-64835/job-64836, c= md: CreateVMSnapshotCommand) (logid:8b87ab8a) failed to create snapshot for= vm:i-84987-16119-VM due to null > 2015-07-24 08:20:55,524 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-6= 6:ctx-5fbdccd8) (logid:8b87ab8a) Seq 80-6161487240196259878: Response Recei= ved:=20 > 2015-07-24 08:20:55,525 DEBUG [c.c.a.t.Request] (DirectAgent-66:ctx-5fbdc= cd8) (logid:8b87ab8a) Seq 80-6161487240196259878: Processing: { Ans: , Mgm= tId: 345051581208, via: 80, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Crea= teVMSnapshotAnswer":{"result":false,"wait":0}}] } > 2015-07-24 08:20:55,525 DEBUG [c.c.a.t.Request] (Work-Job-Executor-61:ctx= -03fad7f2 job-64835/job-64836 ctx-746f3965) (logid:8b87ab8a) Seq 80-6161487= 240196259878: Received: { Ans: , MgmtId: 345051581208, via: 80, Ver: v1, F= lags: 10, { CreateVMSnapshotAnswer } } > 2015-07-24 08:20:55,525 ERROR [o.a.c.s.v.DefaultVMSnapshotStrategy] (Work= -Job-Executor-61:ctx-03fad7f2 job-64835/job-64836 ctx-746f3965) (logid:8b87= ab8a) Creating VM snapshot: i-84987-16119-VM_VS_20150724152053 failed > 2015-07-24 08:20:55,531 DEBUG [c.c.v.s.VMSnapshotManagerImpl] (Work-Job-E= xecutor-61:ctx-03fad7f2 job-64835/job-64836 ctx-746f3965) (logid:8b87ab8a) = Failed to create vm snapshot: 962 > com.cloud.utils.exception.CloudRuntimeException: Creating VM snapshot: i-= 84987-16119-VM_VS_20150724152053 failed > =09at org.apache.cloudstack.storage.vmsnapshot.DefaultVMSnapshotStrategy.= takeVMSnapshot(DefaultVMSnapshotStrategy.java:163) > =09at com.cloud.vm.snapshot.VMSnapshotManagerImpl.orchestrateCreateVMSnap= shot(VMSnapshotManagerImpl.java:438) > =09at com.cloud.vm.snapshot.VMSnapshotManagerImpl.orchestrateCreateVMSnap= shot(VMSnapshotManagerImpl.java:994) > =09at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > =09at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImp= l.java:57) > =09at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcc= essorImpl.java:43) > =09at java.lang.reflect.Method.invoke(Method.java:606) > =09at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandler= Proxy.java:107) > =09at com.cloud.vm.snapshot.VMSnapshotManagerImpl.handleVmWorkJob(VMSnaps= hotManagerImpl.java:1021) > =09at sun.reflect.GeneratedMethodAccessor797.invoke(Unknown Source) > =09at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcc= essorImpl.java:43) > =09at java.lang.reflect.Method.invoke(Method.java:606) > =09at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflec= tion(AopUtils.java:317) > =09at org.springframework.aop.framework.ReflectiveMethodInvocation.invoke= Joinpoint(ReflectiveMethodInvocation.java:183) > =09at org.springframework.aop.framework.ReflectiveMethodInvocation.procee= d(ReflectiveMethodInvocation.java:150) > =09at org.springframework.aop.interceptor.ExposeInvocationInterceptor.inv= oke(ExposeInvocationInterceptor.java:91) > =09at org.springframework.aop.framework.ReflectiveMethodInvocation.procee= d(ReflectiveMethodInvocation.java:172) > =09at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDyna= micAopProxy.java:204) > =09at com.sun.proxy.$Proxy198.handleVmWorkJob(Unknown Source) > =09at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:10= 3) > =09at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run= InContext(AsyncJobManagerImpl.java:549) > =09at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(= ManagedContextRunnable.java:49) > =09at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.= call(DefaultManagedContext.java:56) > =09at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.ca= llWithContext(DefaultManagedContext.java:103) > =09at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.ru= nWithContext(DefaultManagedContext.java:53) > =09at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(Ma= nagedContextRunnable.java:46) > =09at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run= (AsyncJobManagerImpl.java:500) > =09at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:= 471) > =09at java.util.concurrent.FutureTask.run(FutureTask.java:262) > =09at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecuto= r.java:1145) > =09at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecut= or.java:615) > =09at java.lang.Thread.run(Thread.java:745) > {noformat} > {noformat} > 2015-07-24 08:23:01,359 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-1= 37:ctx-bcdafb76) (logid:a20017dd) Seq 80-6161487240196259885: Response Rece= ived:=20 > 2015-07-24 08:23:01,370 DEBUG [c.c.a.t.Request] (DirectAgent-137:ctx-bcda= fb76) (logid:a20017dd) Seq 80-6161487240196259885: Processing: { Ans: , Mg= mtId: 345051581208, via: 80, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Cre= ateVMSnapshotAnswer":{"volumeTOs":[{"uuid":"a89b4ad5-f23f-4df6-84a8-89c4f40= b2edb","volumeType":"ROOT","volumeState":"Ready","dataStore":{"org.apache.c= loudstack.storage.to.PrimaryDataStoreTO":{"uuid":"346b381a-8543-3f7b-9eff-f= a909ad243c7","id":205,"poolType":"NetworkFilesystem","host":"10.144.35.110"= ,"path":"/tintri/ECS-SR-CLD200","port":2049,"url":"NetworkFilesystem://10.1= 44.35.110/tintri/ECS-SR-CLD200/?ROLE=3DPrimary&STOREUUID=3D346b381a-8543-3f= 7b-9eff-fa909ad243c7"}},"name":"ROOT-16119","size":33386,"path":"ROOT-16119= -000001","volumeId":19311,"vmName":"i-84987-16119-VM","vmState":"Running","= accountId":84987,"chainInfo":"{\"diskDeviceBusName\":\"ide0:1\",\"diskChain= \":[\"[346b381a85433f7b9efffa909ad243c7] i-84987-16119-VM/ROOT-16119.vmdk\"= ,\"[346b381a85433f7b9efffa909ad243c7] 49f59e1a4ce23fec8890c8b9e5891d56/49f5= 9e1a4ce23fec8890c8b9e5891d56.vmdk\"]}","format":"OVA","provisioningType":"T= HIN","id":19311,"deviceId":0,"cacheMode":"NONE","hypervisorType":"VMware"}]= ,"vmSnapshotTo":{"id":964,"snapshotName":"i-84987-16119-VM_VS_2015072415225= 3","type":"Disk","current":false,"description":"unit-test-instance-snapshot= ","quiescevm":false},"result":true,"details":"","wait":0}}] } > 2015-07-24 08:23:01,370 DEBUG [c.c.a.t.Request] (Work-Job-Executor-63:ctx= -f077facb job-64839/job-64840 ctx-85ac1d8c) (logid:a20017dd) Seq 80-6161487= 240196259885: Received: { Ans: , MgmtId: 345051581208, via: 80, Ver: v1, F= lags: 10, { CreateVMSnapshotAnswer } } > 2015-07-24 08:23:01,382 DEBUG [o.a.c.s.v.DefaultVMSnapshotStrategy] (Work= -Job-Executor-63:ctx-f077facb job-64839/job-64840 ctx-85ac1d8c) (logid:a200= 17dd) Create vm snapshot i-84987-16119-VM_VS_20150724152253 succeeded for v= m: i-84987-16119-VM > 2015-07-24 08:23:01,396 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Exe= cutor-63:ctx-f077facb job-64839/job-64840 ctx-85ac1d8c) (logid:a20017dd) Do= ne executing VM work job: com.cloud.vm.snapshot.VmWorkCreateVMSnapshot{"vmS= napshotId":964,"quiesceVm":false,"userId":1,"accountId":1,"vmId":16119,"han= dlerName":"VMSnapshotManagerImpl"} > {noformat} > It is not clear from this log what is causing this error "failed to creat= e snapshot for vm:i-84987-16119-VM due to null" > Interestingly, this VM has guest OS type set to None (138). > REPRO STEPS > =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D > I tried couple of times with different options, could not repro this > EXPECTED BEHAVIOR > =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D > VMSnapshot should be successful from the moment the VM is ready > ACTUAL BEHAVIOR > =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D > VMSnapshot is not successful for ~12 minutes -- This message was sent by Atlassian JIRA (v6.3.4#6332)