cloudstack-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Sateesh Chodapuneedi (JIRA)" <j...@apache.org>
Subject [jira] [Comment Edited] (CLOUDSTACK-5447) [Automation] Volume migration failing with NullPointerException in vmware and KVM
Date Thu, 02 Jan 2014 09:38:52 GMT

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

Mime
View raw message