This service will be undergoing maintenance at 00:00 UTC, 2017-10-23 It is expected to last about 30 minutes
Bug 1000824 - Failed Migrate VM - NullPointerException
Failed Migrate VM - NullPointerException
Status: CLOSED CURRENTRELEASE
Product: Red Hat Enterprise Virtualization Manager
Classification: Red Hat
Component: ovirt-engine (Show other bugs)
3.3.0
x86_64 Linux
high Severity high
: ---
: 3.3.0
Assigned To: Arik
Pavel Novotny
virt
: Regression
Depends On:
Blocks: 3.3snap1
  Show dependency treegraph
 
Reported: 2013-08-25 13:46 EDT by vvyazmin@redhat.com
Modified: 2015-09-22 09 EDT (History)
7 users (show)

See Also:
Fixed In Version: is19
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed:
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
## Logs rhevm, vdsm, libvirt, thread dump, superVdsm (4.46 MB, application/x-gzip)
2013-08-25 13:46 EDT, vvyazmin@redhat.com
no flags Details


External Trackers
Tracker ID Priority Status Summary Last Updated
oVirt gerrit 19683 None None None Never
oVirt gerrit 19885 None None None Never

  None (edit)
Description vvyazmin@redhat.com 2013-08-25 13:46:11 EDT
Created attachment 790122 [details]
## Logs rhevm, vdsm, libvirt, thread dump, superVdsm

Failed Migrate VM - NullPointerException

Version-Release number of selected component (if applicable):
RHEVM 3.3 - IS11 environment:

RHEVM:  rhevm-3.3.0-0.16.master.el6ev.noarch
PythonSDK:  rhevm-sdk-python-3.3.0.11-1.el6ev.noarch
VDSM:  vdsm-4.12.0-72.git287bb7e.el6ev.x86_64
LIBVIRT:  libvirt-0.10.2-18.el6_4.9.x86_64
QEMU & KVM:  qemu-kvm-rhev-0.12.1.2-2.355.el6_4.5.x86_64
SANLOCK:  sanlock-2.8-1.el6.x86_64

How reproducible:
100%

Steps to Reproduce:
Create iSCSI Data Center with 2 hosts
Create VM
Migrate VM

Actual results:
Failed Migrate VM - NullPointerException

Expected results:
Succeed Migrate VM

Impact on user:
Failed Migrate VM

Workaround:
none

Additional info:

/var/log/ovirt-engine/engine.log
2013-08-25 20:29:42,587 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-82) Rerun vm fca68c1d-bc4f-4a5e-9eb2-02b10f0fc2fa. Called fro
m vds tigris01.scl.lab.tlv.redhat.com
2013-08-25 20:29:42,821 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (pool-5-thread-36) START, MigrateStatusVDSCommand(HostName = tigris01.scl.lab.t
lv.redhat.com, HostId = 9576d8ca-4466-46e6-bebc-ccd922075ac6, vmId=fca68c1d-bc4f-4a5e-9eb2-02b10f0fc2fa), log id: 6658612a
2013-08-25 20:29:42,827 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (pool-5-thread-36) Failed in MigrateStatusVDS method
2013-08-25 20:29:42,827 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (pool-5-thread-36) Error code migrateErr and error message VDSGenericException:
 VDSErrorException: Failed to MigrateStatusVDS, error = Fatal error during migration
2013-08-25 20:29:42,827 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (pool-5-thread-36) Command org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateSta
tusVDSCommand return value 
 StatusOnlyReturnForXmlRpc [mStatus=StatusForXmlRpc [mCode=12, mMessage=Fatal error during migration]]
2013-08-25 20:29:42,827 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (pool-5-thread-36) HostName = tigris01.scl.lab.tlv.redhat.com
2013-08-25 20:29:42,827 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (pool-5-thread-36) Command MigrateStatusVDS execution failed. Exception: VDSErr
orException: VDSGenericException: VDSErrorException: Failed to MigrateStatusVDS, error = Fatal error during migration
2013-08-25 20:29:42,827 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (pool-5-thread-36) FINISH, MigrateStatusVDSCommand, log id: 6658612a
2013-08-25 20:29:42,831 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (pool-5-thread-36) Correlation ID: 55388c4f, Job ID: 12ef410d-97aa-4cc7-93f5
-6a7f05338906, Call Stack: null, Custom Event ID: -1, Message: Migration failed due to Error: Fatal error during migration. Trying to migrate to another Host (VM: vm-move-move, 
Source: tigris01.scl.lab.tlv.redhat.com, Destination: tigris02.scl.lab.tlv.redhat.com).
2013-08-25 20:29:42,921 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-82) ResourceManager::RerunFailedCommand: Error: EJBException:
 java.lang.NullPointerException, vds = 9576d8ca-4466-46e6-bebc-ccd922075ac6 : tigris01.scl.lab.tlv.redhat.com
2013-08-25 20:29:42,921 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-82) EJBException: java.lang.NullPointerException: javax.ejb.EJBException: java.lang.NullPointerException
        at org.jboss.as.ejb3.tx.CMTTxInterceptor.handleExceptionInNoTx(CMTTxInterceptor.java:191) [jboss-as-ejb3.jar:7.2.0.Final-redhat-8]
        at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInNoTx(CMTTxInterceptor.java:237) [jboss-as-ejb3.jar:7.2.0.Final-redhat-8]
        at org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:374) [jboss-as-ejb3.jar:7.2.0.Final-redhat-8]
        at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:218) [jboss-as-ejb3.jar:7.2.0.Final-redhat-8]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [jboss-as-ejb3.jar:7.2.0.Final-redhat-8]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64) [jboss-as-ejb3.jar:7.2.0.Final-redhat-8]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59) [jboss-as-ejb3.jar:7.2.0.Final-redhat-8]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) [jboss-as-ee.jar:7.2.0.Final-redhat-8]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45) [jboss-as-ee.jar:7.2.0.Final-redhat-8]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:165) [jboss-as-ee.jar:7.2.0.Final-redhat-8]
        at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:182) [jboss-as-ee.jar:7.2.0.Final-redhat-8]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:72) [jboss-as-ee.jar:7.2.0.Final-redhat-8]
        at org.ovirt.engine.core.common.businessentities.IVdsEventListener$$$view6.processOnVmPoweringUp(Unknown Source)
        at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.AfterRefreshTreatment(VdsUpdateRunTimeInfo.java:490) [vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.VdsManager.OnTimer(VdsManager.java:259) [vdsbroker.jar:]
        at sun.reflect.GeneratedMethodAccessor12.invoke(Unknown Source) [:1.7.0_25]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_25]
        at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_25]
        at org.ovirt.engine.core.utils.timer.JobWrapper.execute(JobWrapper.java:60) [scheduler.jar:]
        at org.quartz.core.JobRunShell.run(JobRunShell.java:213) [quartz.jar:]
        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:557) [quartz.jar:]
Caused by: java.lang.NullPointerException
        at org.ovirt.engine.core.bll.RunVmCommandBase.decreasePendingVms(RunVmCommandBase.java:280) [bll.jar:]
        at org.ovirt.engine.core.bll.RunVmCommandBase.onPowerringUp(RunVmCommandBase.java:334) [bll.jar:]
        at org.ovirt.engine.core.bll.VdsEventListener.processOnVmPoweringUp(VdsEventListener.java:220) [bll.jar:]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_25]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_25]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_25]
        at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_25]
        at org.jboss.as.ee.component.ManagedReferenceMethodInterceptorFactory$ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptorFactory.java:72) [jboss-as-ee.jar:7.2.0.Final-redhat-8]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:58) [jboss-as-ee.jar:7.2.0.Final-redhat-8]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:58) [jboss-as-ee.jar:7.2.0.Final-redhat-8]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43) [jboss-as-ejb3.jar:7.2.0.Final-redhat-8]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.as.jpa.interceptor.SBInvocationInterceptor.processInvocation(SBInvocationInterceptor.java:47)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:53) [jboss-as-ee.jar:7.2.0.Final-redhat-8]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.as.ejb3.component.pool.PooledInstanceInterceptor.processInvocation(PooledInstanceInterceptor.java:51) [jboss-as-ejb3.jar:7.2.0.Final-redhat-8]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInNoTx(CMTTxInterceptor.java:235) [jboss-as-ejb3.jar:7.2.0.Final-redhat-8]
        ... 28 more

2013-08-25 20:29:42,982 WARN  [org.ovirt.engine.core.bll.MigrateVmCommand] (pool-5-thread-36) CanDoAction of action MigrateVm failed. Reasons:VAR__ACTION__MIGRATE,VAR__TYPE__VM,VAR__ACTION__MIGRATE,VAR__TYPE__VM,VAR__ACTION__MIGRATE,VAR__TYPE__VM


/var/log/vdsm/vdsm.log
Comment 2 Omer Frenkel 2013-08-26 10:54:49 EDT
update: migration fails with the same error as in Bug 996146
im still looking at the NPE that follows
Comment 4 Arik 2013-09-18 05:04:45 EDT
We can make a fix that will, most probably, solve this one by adding null-check. but I think we should understand how is it possible to get the problematic null value.

vvyazmin, can you please try to reproduce it again?
Comment 5 Arik 2013-09-30 09:01:10 EDT
I managed to reproduce it (in a hacked way though) - there was a race that the attached patch prevents (the trade-off is another access to the DB, but it is only to get the static part of the VM and only when the VM reach powerring up/up state which is not supposed to happen to frequently).

Note though that the NPE is a side effect of the failed migration and not the other way around (the migration didn't fail because of it) so the classification of the bug (urgent priority and severity) is a too harsh.
Comment 9 Pavel Novotny 2013-10-18 08:52:56 EDT
Verified in vdsm-4.13.0-0.3.beta1.el6ev.x86_64 (is19).
  qemu-kvm-rhev-0.12.1.2-2.408.el6.x86_64
  sanlock-2.8-1.el6.x86_64
  libvirt-0.10.2-29.el6.x86_64

VM migration completes successfully now, no errors in engine nor vdsm logs.
Comment 11 Itamar Heim 2014-01-21 17:23:30 EST
Closing - RHEV 3.3 Released
Comment 12 Itamar Heim 2014-01-21 17:24:35 EST
Closing - RHEV 3.3 Released
Comment 13 Itamar Heim 2014-01-21 17:28:14 EST
Closing - RHEV 3.3 Released

Note You need to log in before you can comment on or make changes to this bug.