[
https://issues.apache.org/jira/browse/CLOUDSTACK-7130?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14090027#comment-14090027
]
edison su commented on CLOUDSTACK-7130:
---------------------------------------
Hi Gaurav, if the issue is observed, could you attach the latest error logs of
both mgt server and kvm agent? The issue is fixed in certain period of time,
then occurred again, means some new code changes recently break it.
> [Automation] Attach volume to VM failing in KVM with "Unexpected exception"
> ---------------------------------------------------------------------------
>
> Key: CLOUDSTACK-7130
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-7130
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the
> default.)
> Components: Volumes
> Affects Versions: 4.5.0
> Environment: KVM
> Reporter: Gaurav Aradhye
> Assignee: edison su
> Labels: automation
> Fix For: 4.5.0
>
> Attachments: KVMAttachVolumeFailureLog.txt, agent.zip
>
>
> Steps to reproduce:
> 1. Deploy a VM
> 2. Create a data volume
> 3. Attach volume to VM
> The operation fails with "Unexpected exception"
> Log:
> 2014-07-18 05:27:37,182 DEBUG [o.a.c.e.o.VolumeOrchestrator]
> (Work-Job-Executor-108:ctx-4fd8d076 job-5653/job-5654 ctx-4c56de83) create
> volume failed: java.lang.NullPo
> interException
> 2014-07-18 05:27:37,182 ERROR [c.c.v.VmWorkJobHandlerProxy]
> (Work-Job-Executor-108:ctx-4fd8d076 job-5653/job-5654 ctx-4c56de83)
> Invocation exception, caused by: com.cl
> oud.utils.exception.CloudRuntimeException: create volume
> failed:java.lang.NullPointerException
> 2014-07-18 05:27:37,183 INFO [c.c.v.VmWorkJobHandlerProxy]
> (Work-Job-Executor-108:ctx-4fd8d076 job-5653/job-5654 ctx-4c56de83) Rethrow
> exception com.cloud.utils.excep
> tion.CloudRuntimeException: create volume
> failed:java.lang.NullPointerException
> 2014-07-18 05:27:37,183 DEBUG [c.c.v.VmWorkJobDispatcher]
> (Work-Job-Executor-108:ctx-4fd8d076 job-5653/job-5654) Done with run of VM
> work job: com.cloud.storage.VmWork
> AttachVolume for VM 864, job origin: 5653
> 2014-07-18 05:27:37,183 ERROR [c.c.v.VmWorkJobDispatcher]
> (Work-Job-Executor-108:ctx-4fd8d076 job-5653/job-5654) Unable to complete
> AsyncJobVO {id:5654, userId: 2, acc
> ountId: 2, instanceType: null, instanceId: null, cmd:
> com.cloud.storage.VmWorkAttachVolume, cmdInfo:
> rO0ABXNyACRjb20uY2xvdWQuc3RvcmFnZS5WbVdvcmtBdHRhY2hWb2x1bWUHra_5YY
> fiHAIAAkwACGRldmljZUlkdAAQTGphdmEvbGFuZy9Mb25nO0wACHZvbHVtZUlkcQB-AAF4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOY
> W1ldAASTGphdmEvbGFuZy9TdHJpbmc7eHAAAAAAAAAAAgAAAAAAAAACAAAAAAAAA2B0ABRWb2x1bWVBcGlTZXJ2aWNlSW1wbHBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5O
> dW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAA5g, cmdVersion: 0, status: IN_PROGRESS,
> processStatus: 0, resultCode: 0, result: null, initMsid: 29066118877352,
> completeMsid: null, l
> astUpdated: null, lastPolled: null, created: Fri Jul 18 05:27:35 PDT 2014},
> job origin:5653
> com.cloud.utils.exception.CloudRuntimeException: create volume
> failed:java.lang.NullPointerException
> at
> org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.createVolume(VolumeOrchestrator.java:482)
> at
> org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.createVolumeOnPrimaryStorage(VolumeOrchestrator.java:763)
> at
> com.cloud.storage.VolumeApiServiceImpl.attachVolumeToVM(VolumeApiServiceImpl.java:1306)
> at
> com.cloud.storage.VolumeApiServiceImpl.orchestrateAttachVolumeToVM(VolumeApiServiceImpl.java:1173)
> at
> com.cloud.storage.VolumeApiServiceImpl.orchestrateAttachVolumeToVM(VolumeApiServiceImpl.java:2601)
> at sun.reflect.GeneratedMethodAccessor790.invoke(Unknown Source)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:606)
> at
> com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
> at
> com.cloud.storage.VolumeApiServiceImpl.handleVmWorkJob(VolumeApiServiceImpl.java:2640)
> at sun.reflect.GeneratedMethodAccessor668.invoke(Unknown Source)
> 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.$Proxy183.handleVmWorkJob(Unknown Source)
> at
> com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
> at
> org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:507)
> 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
> org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:464)
> at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
> 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)
> 2014-07-18 05:27:37,191 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-108:ctx-4fd8d076 job-5653/job-5654) Complete async
> job-5654, jobStatus: FAILED, resu
> ltCode: 0, result:
> rO0ABXNyABpqYXZhLmxhbmcuUnVudGltZUV4Y2VwdGlvbp5fBkcKNIPlAgAAeHIAE2phdmEubGFuZy5FeGNlcHRpb27Q_R8-GjscxAIAAHhyABNqYXZhLmxhbmcuVGhyb3dhYmxl1cY1Jzl3uMsD
> AARMAAVjYXVzZXQAFUxqYXZhL2xhbmcvVGhyb3dhYmxlO0wADWRldGFpbE1lc3NhZ2V0ABJMamF2YS9sYW5nL1N0cmluZztbAApzdGFja1RyYWNldAAeW0xqYXZhL2xhbmcvU3RhY2tUcmFjZUVsZW1lbnQ7TAAUc3VwcHJ
> lc3NlZEV4Y2VwdGlvbnN0ABBMamF2YS91dGlsL0xpc3Q7eHBxAH4AB3QAT0pvYiBmYWlsZWQgZHVlIHRvIGV4Y2VwdGlvbiBjcmVhdGUgdm9sdW1lIGZhaWxlZDpqYXZhLmxhbmcuTnVsbFBvaW50ZXJFeGNlcHRpb251cg
> AeW0xqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnQ7AkYqPDz9IjkCAAB4cAAAAA1zcgAbamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50YQnFmiY23YUCAARJAApsaW5lTnVtYmVyTAAOZGVjbGFyaW5nQ2xhc3NxAH4AB
> EwACGZpbGVOYW1lcQB-AARMAAptZXRob2ROYW1lcQB-AAR4cAAAAHJ0ACBjb20uY2xvdWQudm0uVm1Xb3JrSm9iRGlzcGF0Y2hlcnQAGFZtV29ya0pvYkRpc3BhdGNoZXIuamF2YXQABnJ1bkpvYnNxAH4ACwAAAft0AD9v
> cmcuYXBhY2hlLmNsb3Vkc3RhY2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0AAxydW5JbkNvbnRleHRzcQB-AAsAAAAxdAA-b3JnLmFwYWN
> oZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlJDF0ABtNYW5hZ2VkQ29udGV4dFJ1bm5hYmxlLmphdmF0AANydW5zcQB-AAsAAAA4dABCb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm
> 1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dCQxdAAaRGVmYXVsdE1hbmFnZWRDb250ZXh0LmphdmF0AARjYWxsc3EAfgALAAAAZ3QAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvb
> nRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHRxAH4AGnQAD2NhbGxXaXRoQ29udGV4dHNxAH4ACwAAADVxAH4AHXEAfgAadAAOcnVuV2l0aENvbnRleHRzcQB-AAsAAAAudAA8b3JnLmFwYWNoZS5jbG91ZHN0YWNr
> Lm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlcQB-ABZxAH4AF3NxAH4ACwAAAdBxAH4AEXEAfgAScQB-ABdzcQB-AAsAAAHXdAAuamF2YS51dGlsLmNvbmN1cnJlbnQuRXhlY3V0b3JzJFJ1bm5hYmx
> lQWRhcHRlcnQADkV4ZWN1dG9ycy5qYXZhcQB-ABtzcQB-AAsAAAEGdAAfamF2YS51dGlsLmNvbmN1cnJlbnQuRnV0dXJlVGFza3QAD0Z1dHVyZVRhc2suamF2YXEAfgAXc3EAfgALAAAEeXQAJ2phdmEudXRpbC5jb25jdX
> JyZW50LlRocmVhZFBvb2xFeGVjdXRvcnQAF1RocmVhZFBvb2xFeGVjdXRvci5qYXZhdAAJcnVuV29ya2Vyc3EAfgALAAACZ3QALmphdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvciRXb3JrZXJxAH4AL
> HEAfgAXc3EAfgALAAAC6HQAEGphdmEubGFuZy5UaHJlYWR0AAtUaHJlYWQuamF2YXEAfgAXc3IAJmphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVMaXN0_A8lMbXsjhACAAFMAARsaXN0cQB-AAZ4cgAsamF2
> YS51dGlsLkNvbGxlY3Rpb25zJFVubW9kaWZpYWJsZUNvbGxlY3Rpb24ZQgCAy173HgIAAUwAAWN0ABZMamF2YS91dGlsL0NvbGxlY3Rpb247eHBzcgATamF2YS51dGlsLkFycmF5TGlzdHiB0h2Zx2GdAwABSQAEc2l6ZXh
> wAAAAAHcEAAAAAHhxAH4AOHg
> 2014-07-18 05:27:37,191 DEBUG [c.c.u.AccountManagerImpl]
> (API-Job-Executor-98:ctx-edfbaaad job-5626 ctx-603d061b) Access granted to
> Acct[6c1f4112-0e3c-11e4-b040-1a6f7b
> b0d0a8-admin] to Domain:1/ by AffinityGroupAccessChecker
> 2014-07-18 05:27:37,196 DEBUG [c.c.a.ApiServlet]
> (catalina-exec-18:ctx-97285f9a ctx-3c862f88 ctx-cd3889d2) ===END===
> 10.223.240.194 -- GET jobid=2b42f4a8-889e-46b1-a
> c4d-0119e34486c7&apiKey=f9YPqloMoF-X1F_WwTICLVc-hJZc1S9kh3vBiLss1LCdw2RRHx2ZNulLpoXnxVFd9_tceNkH1adteoVEg6HToA&command=queryAsyncJobResult&response=json&signature=MAja
> itWQuzjYlYh1OFSGfBA8iT8%3D
> 2014-07-18 05:27:37,196 INFO [c.c.r.ResourceLimitManagerImpl]
> (API-Job-Executor-98:ctx-edfbaaad job-5626 ctx-603d061b) Discrepency in the
> resource count (original cou
> nt=8589934592 correct count = 0) for type primary_storage for account ID 548
> is fixed during resource count recalculation.
> 2014-07-18 05:27:37,203 DEBUG [c.c.a.ApiServlet]
> (catalina-exec-4:ctx-9c10b178) ===START=== 10.223.240.194 -- GET
> account=test-TestTemplates-test_01_create_template-
> FAA0XP&domainid=100ceaf0-0e3c-11e4-b040-1a6f7bb0d0a8&response=json&apiKey=f9YPqloMoF-X1F_WwTICLVc-hJZc1S9kh3vBiLss1LCdw2RRHx2ZNulLpoXnxVFd9_tceNkH1adteoVEg6HToA&comman
> d=listVirtualMachines&signature=sGFKKxkiF%2BHEBsJ5ON9cjoSx0Tw%3D&id=a79520dd-8e3e-43e8-b630-3d4cc2d8cc4f&listall=True
> 2014-07-18 05:27:37,211 DEBUG [c.c.v.UserVmManagerImpl]
> (API-Job-Executor-98:ctx-edfbaaad job-5626 ctx-603d061b) Starting cleaning up
> vm VM[User|i-548-858-VM] resource
> s...
> 2014-07-18 05:27:37,212 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-108:ctx-4fd8d076 job-5653/job-5654) Done executing
> com.cloud.storage.VmWorkAttachVol
> ume for job-5654
> 2014-07-18 05:27:37,230 ERROR [c.c.a.ApiAsyncJobDispatcher]
> (API-Job-Executor-111:ctx-5bced597 job-5653) Unexpected exception while
> executing org.apache.cloudstack.api
> .command.admin.volume.AttachVolumeCmdByAdmin
> java.lang.RuntimeException: Unexpected exception
> at
> com.cloud.storage.VolumeApiServiceImpl.attachVolumeToVM(VolumeApiServiceImpl.java:1163)
> at sun.reflect.GeneratedMethodAccessor789.invoke(Unknown Source)
> 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.$Proxy183.attachVolumeToVM(Unknown Source)
> at
> org.apache.cloudstack.api.command.admin.volume.AttachVolumeCmdByAdmin.execute(AttachVolumeCmdByAdmin.java:38)
> at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:141)
> at
> com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:108)
> at
> org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:507)
> 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
> org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:464)
> at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
> 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)
> Caused by: java.lang.RuntimeException: Job failed due to exception create
> volume failed:java.lang.NullPointerException
> ... 25 more
> 2014-07-18 05:27:37,234 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-111:ctx-5bced597 job-5653) Complete async job-5653,
> jobStatus: FAILED, resultCode: 53
> 0, result:
> org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Unexpected
> exception"}
--
This message was sent by Atlassian JIRA
(v6.2#6252)
