Description of problem: VDS error when launching a new vm or starting a excisting vm after update to 3.3.1. The error: Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.proceedBalloonCheck(VdsUpdateRunTimeInfo.java:1312) [vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.refreshVmStats(VdsUpdateRunTimeInfo.java:926) [vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.refreshVdsRunTimeInfo(VdsUpdateRunTimeInfo.java:502) [vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.Refresh(VdsUpdateRunTimeInfo.java:343) [vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.VdsManager.OnTimer(VdsManager.java:237) [vdsbroker.jar:] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_45] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_45] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_45] at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_45] 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:] Version-Release number of selected component (if applicable): Version 3.3.1 How reproducible: Steps to Reproduce: 1.Launch a new vm (or existing one) after the update from 3.3 to 3.3.1, leave the option "Memory Balloon Device Enabled" under "Resource allocation" off 2.Start the vm and check the engine.log Actual results: Your vm won't boot or sometimes after a very long time it does Expected results: Vm should boot Additional info: Before I restarted the ovirt engine I got these errors: 013-11-27 13:01:38,604 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-46) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:01:41,656 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-66) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:01:44,729 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-80) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:01:47,778 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-73) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:01:50,845 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-93) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:01:53,896 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-10) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:01:56,930 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-22) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:01:59,971 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-40) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:02:03,026 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-26) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:02:06,098 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-49) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:02:09,148 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-72) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:02:12,193 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-71) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:02:15,247 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-81) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:02:18,293 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-77) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:02:21,373 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-16) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:02:24,431 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-98) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:02:27,480 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-5) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:02:30,527 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-91) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:02:33,560 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-34) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:02:36,639 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-46) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:02:39,674 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-65) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:02:42,708 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-58) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:02:45,763 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-21) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:02:48,795 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-99) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:02:51,904 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-14) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:02:54,962 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-97) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:02:58,008 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-31) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:03:01,039 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-20) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:03:04,088 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-88) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:03:07,142 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-72) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:03:10,196 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-59) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:03:13,261 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-74) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:03:16,315 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-75) Failed to refresh VDS , vds = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d : progress, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:03:16,859 INFO [org.ovirt.engine.core.bll.StopVmCommand] (pool-6-thread-46) [439226bc] Running command: StopVmCommand internal: false. Entities affected : ID: 2bde28eb-2dad-4f70-8afb-ff7920484e72 Type: VM 2013-11-27 13:03:16,895 INFO [org.ovirt.engine.core.vdsbroker.DestroyVmVDSCommand] (pool-6-thread-46) [439226bc] START, DestroyVmVDSCommand(HostName = progress, HostId = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d, vmId=2bde28eb-2dad-4f70-8afb-ff7920484e72, force=false, secondsToWait=0, gracefully=false), log id: 2f07a3ad 2013-11-27 13:03:16,922 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (pool-6-thread-46) [439226bc] START, DestroyVDSCommand(HostName = progress, HostId = 7ab1a0d7-8c72-44d1-9cb5-320c456be77d, vmId=2bde28eb-2dad-4f70-8afb-ff7920484e72, force=false, secondsToWait=0, gracefully=false), log id: 20baf633 2013-11-27 13:03:17,612 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (pool-6-thread-46) [439226bc] FINISH, DestroyVDSCommand, log id: 20baf633 2013-11-27 13:03:17,619 INFO [org.ovirt.engine.core.vdsbroker.DestroyVmVDSCommand] (pool-6-thread-46) [439226bc] FINISH, DestroyVmVDSCommand, return: Down, log id: 2f07a3ad 2013-11-27 13:03:17,623 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (pool-6-thread-46) [439226bc] Correlation ID: 439226bc, Job ID: de21db84-39dd-433f-b1d1-aec7f53279c1, Call Stack: null, Custom Event ID: -1, Message: VM KETTLE powered off by admin@internal (Host: progress). 2013-11-27 13:03:40,585 INFO [org.ovirt.engine.core.bll.RunVmCommand] (ajp--127.0.0.1-8702-1) [14a63e9e] Lock Acquired to object EngineLock [exclusiveLocks= key: 4b583008-772d-4df3-9612-aa0c70b78e2e value: VM , sharedLocks= ] 2013-11-27 13:03:40,593 INFO [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (ajp--127.0.0.1-8702-1) [14a63e9e] START, IsVmDuringInitiatingVDSCommand( vmId = 4b583008-772d-4df3-9612-aa0c70b78e2e), log id: 77ed468e 2013-11-27 13:03:40,594 INFO [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (ajp--127.0.0.1-8702-1) [14a63e9e] FINISH, IsVmDuringInitiatingVDSCommand, return: false, log id: 77ed468e 2013-11-27 13:03:40,835 INFO [org.ovirt.engine.core.bll.RunVmCommand] (pool-6-thread-46) [14a63e9e] Running command: RunVmCommand internal: false. Entities affected : ID: 4b583008-772d-4df3-9612-aa0c70b78e2e Type: VM 2013-11-27 13:03:40,970 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.IsoPrefixVDSCommand] (pool-6-thread-46) [14a63e9e] START, IsoPrefixVDSCommand(HostName = Vostok, HostId = 2a8b1829-2235-44db-be12-ac71dc6777f8, storagePoolId=5849b030-626e-47cb-ad90-3ce782d831b3), log id: 3f2e199f 2013-11-27 13:03:40,973 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.IsoPrefixVDSCommand] (pool-6-thread-46) [14a63e9e] FINISH, IsoPrefixVDSCommand, return: /rhev/data-center/mnt/vega.brusselsairport.aero:_var_lib_exports_iso/50cf24a4-d1ef-4105-a9a5-b81d91339175/images/11111111-1111-1111-1111-111111111111, log id: 3f2e199f 2013-11-27 13:03:40,995 INFO [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (pool-6-thread-46) [14a63e9e] START, CreateVmVDSCommand(HostName = Vostok, HostId = 2a8b1829-2235-44db-be12-ac71dc6777f8, vmId=4b583008-772d-4df3-9612-aa0c70b78e2e, vm=VM [TestRPMCreations]), log id: 24464ed2 2013-11-27 13:03:41,017 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-6-thread-46) [14a63e9e] START, CreateVDSCommand(HostName = Vostok, HostId = 2a8b1829-2235-44db-be12-ac71dc6777f8, vmId=4b583008-772d-4df3-9612-aa0c70b78e2e, vm=VM [TestRPMCreations]), log id: 6a60d993 2013-11-27 13:03:41,055 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-6-thread-46) [14a63e9e] org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand spiceSslCipherSuite=DEFAULT,memSize=1024,kvmEnable=true,smp=1,vmType=kvm,emulatedMachine=rhel6.4.0,keyboardLayout=fr-be,memGuaranteedSize=1024,pitReinjection=false,nice=0,display=qxl,smartcardEnable=false,smpCoresPerSocket=1,spiceSecureChannels=smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard,timeOffset=0,transparentHugePages=true,vmId=4b583008-772d-4df3-9612-aa0c70b78e2e,devices=[Ljava.util.HashMap;@5b4522a2,acpiEnable=true,vmName=TestRPMCreations,cpuType=Westmere,custom={} 2013-11-27 13:03:41,063 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-6-thread-46) [14a63e9e] FINISH, CreateVDSCommand, log id: 6a60d993 2013-11-27 13:03:41,067 INFO [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (pool-6-thread-46) [14a63e9e] FINISH, CreateVmVDSCommand, return: WaitForLaunch, log id: 24464ed2 2013-11-27 13:03:41,070 INFO [org.ovirt.engine.core.bll.RunVmCommand] (pool-6-thread-46) [14a63e9e] Lock freed to object EngineLock [exclusiveLocks= key: 4b583008-772d-4df3-9612-aa0c70b78e2e value: VM , sharedLocks= ] 2013-11-27 13:03:41,075 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (pool-6-thread-46) [14a63e9e] Correlation ID: 14a63e9e, Job ID: 0422b9d6-8ce3-4558-98a3-6d8e64ee7c99, Call Stack: null, Custom Event ID: -1, Message: VM TestRPMCreations was started by admin@internal (Host: Vostok). 2013-11-27 13:03:41,567 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand] (DefaultQuartzScheduler_Worker-33) START, FullListVdsCommand(HostName = Vostok, HostId = 2a8b1829-2235-44db-be12-ac71dc6777f8, vds=Host[Vostok], vmIds=[4b583008-772d-4df3-9612-aa0c70b78e2e]), log id: 2baf0b8e 2013-11-27 13:03:41,575 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand] (DefaultQuartzScheduler_Worker-33) FINISH, FullListVdsCommand, return: [Ljava.util.HashMap;@711fae09, log id: 2baf0b8e 2013-11-27 13:03:44,718 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-48) Failed to refresh VDS , vds = 2a8b1829-2235-44db-be12-ac71dc6777f8 : Vostok, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:03:47,765 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-93) Failed to refresh VDS , vds = 2a8b1829-2235-44db-be12-ac71dc6777f8 : Vostok, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException 2013-11-27 13:03:50,815 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-96) Failed to refresh VDS , vds = 2a8b1829-2235-44db-be12-ac71dc6777f8 : Vostok, error = java.lang.NullPointerException, continuing.: java.lang.NullPointerException
If (unlike me) you believe that this is a Vdsm bug, please report vdsm version and supply vdsm.log (look for vmCreate and hence). Would you copy the output of `vdsClient -s 0 getAllVmStsat` from the host? I'd like to see what confuses Engine. Whatever Vdsm reports, Engine should not get itself into java.lang.NullPointerException.
Please see Dan's comments. The vdsm version, logs and Vm stats are important for debugging the engine crash as well.
Created attachment 829747 [details] vdsClient -s 0 getAllVmStats on the hypervisor Buran
Included in 3.3.2 beta
rc build done, moving to ON_QA, packages will be available on updates-testing repository.
oVirt 3.3.2 has been released resolving the problem described in this bug report.