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 2337910651 for ; Thu, 2 Jan 2014 09:40:26 +0000 (UTC) Received: (qmail 12097 invoked by uid 500); 2 Jan 2014 09:39:13 -0000 Delivered-To: apmail-cloudstack-issues-archive@cloudstack.apache.org Received: (qmail 11995 invoked by uid 500); 2 Jan 2014 09:39:04 -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 11985 invoked by uid 500); 2 Jan 2014 09:39:02 -0000 Delivered-To: apmail-incubator-cloudstack-issues@incubator.apache.org Received: (qmail 11867 invoked by uid 99); 2 Jan 2014 09:38:52 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 02 Jan 2014 09:38:52 +0000 Date: Thu, 2 Jan 2014 09:38:52 +0000 (UTC) From: "Sateesh Chodapuneedi (JIRA)" To: cloudstack-issues@incubator.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Comment Edited] (CLOUDSTACK-5447) [Automation] Volume migration failing with NullPointerException in vmware and KVM MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/CLOUDSTACK-5447?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13860097#comment-13860097 ] Sateesh Chodapuneedi edited comment on CLOUDSTACK-5447 at 1/2/14 9:38 AM: -------------------------------------------------------------------------- Issue reported in this defect is fixed. From the logs it is evident that MigrateVolumeCommand execution was successful. That means volume was successfully migrated. Without fix for the below issue, MigrateVolumeCommand would fail with NullPointerException. Issue is NullPointerException encounter when vmware resource is trying to execute MigrateVolumeCommand send by agent manager. Injection of VolumeOrchestrationService is failing yielding _volMgr as NULL. Due to this, the following snippet is failing with NullPointerException. final String vmName = volMgr.getVmNameFromVolumeId(cmd.getVolumeId()); >From latest logs ---- 2014-01-01 21:38:21,932 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-75:ctx-5bc5c41b 10.223.250.130) Executing resource MigrateVolumeCommand: {"volumeId":294,"volumePath":"ROOT-271","pool":{"id":1,"uuid":"4faf04c2-6dd8-3025-b43f-65d32cc49d02","host":"10.223.110.232","path":"/export/home/automation/SC-CLOUD-QA03/primary1","port":2049,"type":"NetworkFilesystem"},"attachedVmName":"i-138-271-TestVM","wait":0} 2014-01-01 21:38:32,254 DEBUG [c.c.a.t.Request] (StorageManager-Scavenger-2:ctx-9c57df2c) Seq 2-834934157: Waiting for Seq 834934155 Scheduling: { Cmd , MgmtId: 90928106758026, via: 2(10.223.250.130), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.storage.DestroyCommand":{"volume":{"id":9,"mountPoint":"/export/home/automation/SC-CLOUD-QA03/primary2","path":"26af4375b1d13ff69a51cbbac2347bb8","size":0,"storagePoolType":"NetworkFilesystem","storagePoolUuid":"16c8ee2e-3f26-3062-8878-b7d6c53c5797","deviceId":0},"wait":0}}] } 2014-01-01 21:39:20,454 DEBUG [c.c.a.ApiServlet] (catalina-exec-23:ctx-73099f71) ===START=== 10.216.51.177 -- GET command=queryAsyncJobResult&jobId=92480032-09e0-44ec-9a11-766b78a78523&response=json&sessionkey=NovfJtY6A9F6dYRHk%2BPwCgqvTq4%3D&_=1388643648238 2014-01-01 21:39:20,468 DEBUG [c.c.a.ApiServlet] (catalina-exec-23:ctx-73099f71 ctx-9ab9ac15) ===END=== 10.216.51.177 -- GET command=queryAsyncJobResult&jobId=92480032-09e0-44ec-9a11-766b78a78523&response=json&sessionkey=NovfJtY6A9F6dYRHk%2BPwCgqvTq4%3D&_=1388643648238 2014-01-01 21:39:22,465 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-75:ctx-5bc5c41b 10.223.250.130) Successfully migrated volume ROOT-271 to target datastore 4faf04c26dd83025b43f65d32cc49d02 2014-01-01 21:39:22,466 DEBUG [c.c.a.t.Request] (DirectAgent-75:ctx-5bc5c41b) Seq 2-834934155: Processing: { Ans: , MgmtId: 90928106758026, via: 2, Ver: v1, Flags: 110, [{"com.cloud.agent.api.storage.MigrateVolumeAnswer":{"volumePath":"ROOT-271","result":true,"wait":0}}] } 2014-01-01 21:39:22,466 DEBUG [c.c.a.t.Request] (Job-Executor-6:ctx-f66dc601 ctx-78f38e0b) Seq 2-834934155: Received: { Ans: , MgmtId: 90928106758026, via: 2, Ver: v1, Flags: 110, { MigrateVolumeAnswer } } ------ Latest logs are indicating 2 issues, 1. 2014-01-01 21:39:22,502 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Job-Executor-93:ctx-b606242c) Done executing org.apache.cloudstack.api.command.user.volume.MigrateVolumeCmd for job-4761 2014-01-01 21:39:22,505 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Job-Executor-56:ctx-bb7ebc62) Complete async job-4761, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Failed to migrate volume"} Post volume migration, job result processing has some problem. Due to this we see failure result. It's a bug and this bug is already reported - CLOUDSTACK-5660 2. 2014-01-01 21:39:22,468 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-56:ctx-dff965fd 10.223.250.130) Executing resource DestroyCommand to evict template from storage pool: {"volume":{"id":9,"mountPoint":"/export/home/automation/SC-CLOUD-QA03/primary2","path":"26af4375b1d13ff69a51cbbac2347bb8","size":0,"storagePoolType":"NetworkFilesystem","storagePoolUuid":"16c8ee2e-3f26-3062-8878-b7d6c53c5797","deviceId":0},"wait":0} 2014-01-01 21:39:23,036 ERROR [c.c.h.v.r.VmwareResource] (DirectAgent-56:ctx-dff965fd 10.223.250.130) DestroyCommand failed due to Exception: java.lang.RuntimeException Message: Invalid configuration for device '0'. DestroyCommand executed by StorageManager-Scavenger thread failed due to some issue. This has to be reported as a separate bug. This is a different thread and is not relevant to volume migration job. was (Author: sateeshc): Issue reported in this defect is fixed. From the logs it is evident that MigrateVolumeCommand execution was successful. That means volume was successfully migrated. Without fix for the below issue, MigrateVolumeCommand would fail with NullPointerException. Issue is NullPointerException encounter when vmware resource is trying to execute MigrateVolumeCommand send by agent manager. Injection of VolumeOrchestrationService is failing yielding _volMgr as NULL. Due to this, the following snippet is failing with NullPointerException. final String vmName = volMgr.getVmNameFromVolumeId(cmd.getVolumeId()); >From latest logs ---- 2014-01-01 21:38:21,932 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-75:ctx-5bc5c41b 10.223.250.130) Executing resource MigrateVolumeCommand: {"volumeId":294,"volumePath":"ROOT-271","pool":{"id":1,"uuid":"4faf04c2-6dd8-3025-b43f-65d32cc49d02","host":"10.223.110.232","path":"/export/home/automation/SC-CLOUD-QA03/primary1","port":2049,"type":"NetworkFilesystem"},"attachedVmName":"i-138-271-TestVM","wait":0} 2014-01-01 21:38:32,254 DEBUG [c.c.a.t.Request] (StorageManager-Scavenger-2:ctx-9c57df2c) Seq 2-834934157: Waiting for Seq 834934155 Scheduling: { Cmd , MgmtId: 90928106758026, via: 2(10.223.250.130), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.storage.DestroyCommand":{"volume":{"id":9,"mountPoint":"/export/home/automation/SC-CLOUD-QA03/primary2","path":"26af4375b1d13ff69a51cbbac2347bb8","size":0,"storagePoolType":"NetworkFilesystem","storagePoolUuid":"16c8ee2e-3f26-3062-8878-b7d6c53c5797","deviceId":0},"wait":0}}] } 2014-01-01 21:39:20,454 DEBUG [c.c.a.ApiServlet] (catalina-exec-23:ctx-73099f71) ===START=== 10.216.51.177 -- GET command=queryAsyncJobResult&jobId=92480032-09e0-44ec-9a11-766b78a78523&response=json&sessionkey=NovfJtY6A9F6dYRHk%2BPwCgqvTq4%3D&_=1388643648238 2014-01-01 21:39:20,468 DEBUG [c.c.a.ApiServlet] (catalina-exec-23:ctx-73099f71 ctx-9ab9ac15) ===END=== 10.216.51.177 -- GET command=queryAsyncJobResult&jobId=92480032-09e0-44ec-9a11-766b78a78523&response=json&sessionkey=NovfJtY6A9F6dYRHk%2BPwCgqvTq4%3D&_=1388643648238 2014-01-01 21:39:22,465 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-75:ctx-5bc5c41b 10.223.250.130) Successfully migrated volume ROOT-271 to target datastore 4faf04c26dd83025b43f65d32cc49d02 2014-01-01 21:39:22,466 DEBUG [c.c.a.t.Request] (DirectAgent-75:ctx-5bc5c41b) Seq 2-834934155: Processing: { Ans: , MgmtId: 90928106758026, via: 2, Ver: v1, Flags: 110, [{"com.cloud.agent.api.storage.MigrateVolumeAnswer":{"volumePath":"ROOT-271","result":true,"wait":0}}] } 2014-01-01 21:39:22,466 DEBUG [c.c.a.t.Request] (Job-Executor-6:ctx-f66dc601 ctx-78f38e0b) Seq 2-834934155: Received: { Ans: , MgmtId: 90928106758026, via: 2, Ver: v1, Flags: 110, { MigrateVolumeAnswer } } ------ Latest logs are indicating 2 issues, 1. 2014-01-01 21:39:22,502 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Job-Executor-93:ctx-b606242c) Done executing org.apache.cloudstack.api.command.user.volume.MigrateVolumeCmd for job-4761 2014-01-01 21:39:22,505 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Job-Executor-56:ctx-bb7ebc62) Complete async job-4761, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Failed to migrate volume"} This bug is already reported - CLOUDSTACK-5660 2. 2014-01-01 21:39:22,468 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-56:ctx-dff965fd 10.223.250.130) Executing resource DestroyCommand to evict template from storage pool: {"volume":{"id":9,"mountPoint":"/export/home/automation/SC-CLOUD-QA03/primary2","path":"26af4375b1d13ff69a51cbbac2347bb8","size":0,"storagePoolType":"NetworkFilesystem","storagePoolUuid":"16c8ee2e-3f26-3062-8878-b7d6c53c5797","deviceId":0},"wait":0} 2014-01-01 21:39:23,036 ERROR [c.c.h.v.r.VmwareResource] (DirectAgent-56:ctx-dff965fd 10.223.250.130) DestroyCommand failed due to Exception: java.lang.RuntimeException Message: Invalid configuration for device '0'. DestroyCommand executed by StorageManager-Scavenger thread failed due to some issue. This has to be reported as a separate bug. This is a different thread and is not relevant to volume migration job. > [Automation] Volume migration failing with NullPointerException in vmware and KVM > --------------------------------------------------------------------------------- > > Key: CLOUDSTACK-5447 > URL: https://issues.apache.org/jira/browse/CLOUDSTACK-5447 > Project: CloudStack > Issue Type: Bug > Security Level: Public(Anyone can view this level - this is the default.) > Components: KVM, VMware, Volumes > Affects Versions: 4.3.0 > Environment: vmware 5.0 > branch 4.3 > Reporter: Rayees Namathponnan > Assignee: Sateesh Chodapuneedi > Priority: Blocker > Fix For: 4.3.0 > > Attachments: management-server.rar, management-server.rar > > > Steps to reproduce > Step 1 : Deploy advanced zone in vm ware with two primary storage in a cluster > Step 2 : Deploy VM vm1 > Step 3 : migrate volume of vm to second primary storage > Actual result > Migration failed with below error > 2013-12-10 11:39:20,642 DEBUG [c.c.a.t.Request] (DirectAgent-320:ctx-47dcbdc1) Seq 2-34478645: Executing: { Cmd , MgmtId: 90928106758026, via: 2(10.223.250.130), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.storage.MigrateVolumeCommand":{"volumeId":374,"volumePath":"ROOT-324","pool":{"id":1,"uuid":"6cfb1cb3-1909-3295-a4d3-8920e5cf0b00","host":"10.223.240.164","path":"/home/common/automation/SC-CLOUD-QA03/primary1","port":2049,"type":"NetworkFilesystem"},"wait":0}}] } > 2013-12-10 11:39:20,643 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-75:ctx-5c8b7163) Seq 2-34478645: Executing request > 2013-12-10 11:39:20,643 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-75:ctx-5c8b7163 10.223.250.130) Executing resource MigrateVolumeCommand: {"volumeId":374,"volumePath":"ROOT-324","pool":{"id":1,"uuid":"6cfb1cb3-1909-3295-a4d3-8920e5cf0b00","host":"10.223.240.164","path":"/home/common/automation/SC-CLOUD-QA03/primary1","port":2049,"type":"NetworkFilesystem"},"wait":0} > 2013-12-10 11:39:20,643 WARN [c.c.a.m.DirectAgentAttache] (DirectAgent-75:ctx-5c8b7163) Seq 2-34478645: Exception Caught while executing command > java.lang.NullPointerException > at com.cloud.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:4347) > at com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:457) > at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:216) > at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49) > at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56) > at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103) > at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53) > at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46) > at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) > at java.util.concurrent.FutureTask.run(FutureTask.java:262) > at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178) > at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292) > 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:744) > 2013-12-10 11:39:20,643 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-75:ctx-5c8b7163) Seq 2-34478645: Response Received: > 2013-12-10 11:39:20,643 DEBUG [c.c.a.t.Request] (DirectAgent-75:ctx-5c8b7163) Seq 2-34478645: Processing: { Ans: , MgmtId: 90928106758026, via: 2, Ver: v1, Flags: 110, [{"com.cloud.agent.api.Answer":{"result":false,"details":"java.lang.NullPointerException","wait":0}}] } > 2013-12-10 11:39:20,643 DEBUG [c.c.a.t.Request] (Job-Executor-142:ctx-1d4fa953 ctx-f2be2981) Seq 2-34478645: Received: { Ans: , MgmtId: 90928106758026, via: 2, Ver: v1, Flags: 110, { Answer } } > 2013-12-10 11:39:20,644 DEBUG [o.a.c.s.m.AncientDataMotionStrategy] (Job-Executor-142:ctx-1d4fa953 ctx-f2be2981) copy failed > com.cloud.utils.exception.CloudRuntimeException: Failed to migrate volume org.apache.cloudstack.storage.volume.VolumeObject@16ed3557 to storage pool org.apache.cloudstack.storage.datastore.PrimaryDataStoreImpl@2f48ee83 > at org.apache.cloudstack.storage.motion.AncientDataMotionStrategy.migrateVolumeToPool(AncientDataMotionStrategy.java:381) > at org.apache.cloudstack.storage.motion.AncientDataMotionStrategy.copyAsync(AncientDataMotionStrategy.java:416) > at org.apache.cloudstack.storage.motion.DataMotionServiceImpl.copyAsync(DataMotionServiceImpl.java:70) > at org.apache.cloudstack.storage.volume.VolumeServiceImpl.migrateVolume(VolumeServiceImpl.java:910) > at com.cloud.storage.VolumeApiServiceImpl.liveMigrateVolume(VolumeApiServiceImpl.java:1452) > at com.cloud.storage.VolumeApiServiceImpl.migrateVolume(VolumeApiServiceImpl.java:1438) > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) > at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) > at java.lang.reflect.Method.invoke(Method.java:606) > at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317) > at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183) > at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150) > at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:91) > at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) > at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204) > at com.sun.proxy.$Proxy233.migrateVolume(Unknown Source) > at org.apache.cloudstack.api.command.user.volume.MigrateVolumeCmd.execute(MigrateVolumeCmd.java:103) > at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:161) > at com.cloud.api.ApiAsyncJobDispatcher.runJobInContext(ApiAsyncJobDispatcher.java:109) > at com.cloud.api.ApiAsyncJobDispatcher$1.run(ApiAsyncJobDispatcher.java:66) > at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56) > at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103) > at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53) > at com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:63) -- This message was sent by Atlassian JIRA (v6.1.5#6160)