Rayees Namathponnan created CLOUDSTACK-7110: -----------------------------------------------
Summary: [Automation] Create volume failing with NPE in KVM Key: CLOUDSTACK-7110 URL: https://issues.apache.org/jira/browse/CLOUDSTACK-7110 Project: CloudStack Issue Type: Bug Security Level: Public (Anyone can view this level - this is the default.) Components: KVM, Storage Controller Affects Versions: 4.5.0 Environment: KVM - RHEL 6.3 4.5 build Reporter: Rayees Namathponnan Priority: Blocker Fix For: 4.5.0 Steps to reproduce 1 ) Create advanced zone in KVM 2 ) Create a volume 3) Deploy a VM 4) Attach a volume Result Attach volume failed with below NPE Type":"KVM"}},"wait":0}}] } 2014-07-15 12:57:33,050 DEBUG [c.c.a.t.Request] (AgentManager-Handler-7:null) Seq 1-5112992951949074670: Processing: { Ans: , MgmtId: 29066118877352, via: 1, Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.CreateObjectAnswer":{"result":false,"details":"jav a.lang.NullPointerException","wait":0}}] } 2014-07-15 12:57:33,051 DEBUG [c.c.a.t.Request] (Work-Job-Executor-68:ctx-07b5ac75 job-6770/job-6771 ctx-cb80d35b) Seq 1-51129929519490 74670: Received: { Ans: , MgmtId: 29066118877352, via: 1, Ver: v1, Flags: 10, { CreateObjectAnswer } } 2014-07-15 12:57:33,057 WARN [o.a.c.s.d.ObjectInDataStoreManagerImpl] (Work-Job-Executor-68:ctx-07b5ac75 job-6770/job-6771 ctx-cb80d35 b) Unsupported data object (VOLUME, org.apache.cloudstack.storage.datastore.PrimaryDataStoreImpl@45836dfb), no need to delete from obje ct in store ref table 2014-07-15 12:57:33,057 DEBUG [o.a.c.e.o.VolumeOrchestrator] (Work-Job-Executor-68:ctx-07b5ac75 job-6770/job-6771 ctx-cb80d35b) create volume failed: java.lang.NullPointerException 2014-07-15 12:57:33,057 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-68:ctx-07b5ac75 job-6770/job-6771 ctx-cb80d35b) Invocati on exception, caused by: com.cloud.utils.exception.CloudRuntimeException: create volume failed:java.lang.NullPointerException 2014-07-15 12:57:33,057 INFO [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-68:ctx-07b5ac75 job-6770/job-6771 ctx-cb80d35b) Rethrow exception com.cloud.utils.exception.CloudRuntimeException: create volume failed:java.lang.NullPointerException 2014-07-15 12:57:33,057 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-68:ctx-07b5ac75 job-6770/job-6771) Done with run of VM wor k job: com.cloud.storage.VmWorkAttachVolume for VM 1105, job origin: 6770 2014-07-15 12:57:33,057 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-68:ctx-07b5ac75 job-6770/job-6771) Unable to complete Asyn cJobVO {id:6771, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.storage.VmWorkAttachVolume, cmdInfo: rO0 ABXNyACRjb20uY2xvdWQuc3RvcmFnZS5WbVdvcmtBdHRhY2hWb2x1bWUHra_5YYfiHAIAAkwACGRldmljZUlkdAAQTGphdmEvbGFuZy9Mb25nO0wACHZvbHVtZUlkcQB-AAF4cg ATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1ldAASTGphdmEvbGFuZy9TdHJpbmc7eHAAAAAAA AAAAgAAAAAAAAACAAAAAAAABFF0ABRWb2x1bWVBcGlTZXJ2aWNlSW1wbHBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKG rJUdC5TgiwIAAHhwAAAAAAAABJA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 2906611887735 2, completeMsid: null, lastUpdated: null, lastPolled: null, created: Tue Jul 15 12:57:30 PDT 2014}, job origin:6770 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:1222) at com.cloud.storage.VolumeApiServiceImpl.orchestrateAttachVolumeToVM(VolumeApiServiceImpl.java:1089) at com.cloud.storage.VolumeApiServiceImpl.orchestrateAttachVolumeToVM(VolumeApiServiceImpl.java:2517) at sun.reflect.GeneratedMethodAccessor833.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:2556) at sun.reflect.GeneratedMethodAccessor645.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) Here the NPE found in agent 2014-07-15 11:57:55,299 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) Request:Seq 1-5112992951949074670: { Cmd , MgmtId: 29066118877352, via: 1, Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CreateObjectCommand":{"da ta":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"876bb787-7ecb-4bba-806a-5081dc79e20f","volumeType":"DATADIS K","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"4f3ad80a-b796-3db3-b126-9c12b5b5eafc","id":1 ,"poolType":"NetworkFilesystem","host":"nfs1-ccp.citrix.com","path":"/home/common/automation/SC_QA_AUTO4/primary","port":20 49,"url":"NetworkFilesystem://nfs1-ccp.citrix.com/home/common/automation/SC_QA_AUTO4/primary/?ROLE=Primary&STOREUUID=4f3ad8 0a-b796-3db3-b126-9c12b5b5eafc"}},"name":"Rayees","size":5368709120,"volumeId":1168,"accountId":2,"provisioningType":"THIN" ,"id":1168,"hypervisorType":"KVM"}},"wait":0}}] } 2014-07-15 11:57:55,299 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) Processing command: org.apache.cloudstack.s torage.command.CreateObjectCommand 2014-07-15 11:57:55,299 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) Trying to fetch storage poo l 4f3ad80a-b796-3db3-b126-9c12b5b5eafc from libvirt 2014-07-15 11:57:55,441 DEBUG [kvm.storage.KVMStorageProcessor] (agentRequest-Handler-3:null) Failed to create volume: java .lang.NullPointerException 2014-07-15 11:57:55,441 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) Seq 1-5112992951949074670: { Ans: , MgmtId : 29066118877352, via: 1, Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.CreateObjectAnswer":{"result":false, "details":"java.lang.NullPointerException","wait":0}}] } 2014-07-15 11:58:03,937 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) Processing command: com.cloud.agent.api.Get HostStatsCommand 2014-07-15 11:58:03,937 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-2:null) Executing: /bin/bash -c idle=$(top -b -n 1|grep Cpu\(s\):|cut -d% -f4|cut -d, -f2);echo $idle 2014-07-15 11:58:04,453 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-2:null) Execution is successful . 2014-07-15 11:58:04,453 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-2:null) Executing: /bin/bash -c freeMem=$(free|grep cache:|awk '{print $4}');echo $freeMem -- This message was sent by Atlassian JIRA (v6.2#6252)