Bug 855786

Summary:

[log][engine] java InvocationTargetException in logs during ProcessDomainRecovery after adding a host

Product:

Red Hat Enterprise Virtualization Manager

Reporter:

Gadi Ickowicz <gickowic>

Component:

ovirt-engine

Assignee:

Asaf Shakarchi <asaf>

Status:

CLOSED WORKSFORME

QA Contact:

Gadi Ickowicz <gickowic>

Severity:

medium

Docs Contact:

Priority:

unspecified

Version:

3.1.0

CC:

amureini, dyasny, ecohen, hateya, iheim, lpeer, nlevinki, Rhev-m-bugs, sgrinber, yeylon, ykaul

Target Milestone:

---

Target Release:

3.1.0

Hardware:

All

OS:

Linux

Whiteboard:

storage

Fixed In Version:

Doc Type:

Bug Fix

Doc Text:

Story Points:

---

Clone Of:

Environment:

Last Closed:

2012-11-25 15:22:30 UTC

Type:

Bug

Regression:

---

Mount Type:

---

Documentation:

---

CRM:

Verified Versions:

Category:

---

oVirt Team:

Storage

RHEL 7.3 requirements from Atomic Host:

Cloudforms Team:

---

Target Upstream Version:

Embargoed:

Attachments:

Description	Flags
vdsm + engine logs	none

Description Gadi Ickowicz 2012-09-10 09:40:02 UTC

Created attachment 611371 [details]
vdsm + engine logs

Description of problem:
java.lang.reflect.InvocationTargetException is visible in the logs about a domain which was removed and formatted (WipeOnDelete) before  (FormatStorageDomain returned successfully). Also all hosts (2) were set to maintenance and removed gracefully before adding them again, and the ProcessDomainRecovery runs right after adding one of the hosts, visible during the installation of the second host in the logs:

2012-09-10 09:33:37,617 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.FormatStorageDomainVDSCommand] (ajp-/127.0.0.1:8009-9) [6917eb4f] START, FormatStorageDomainVDSCommand(vdsId = 33892284-fb0e-11e1-ae6f-001a4
a169773, storageDomainId=46dd00e5-95e7-48a4-b096-9a19b8d2a7a1), log id: 4ffa0c44
2012-09-10 09:33:41,741 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.FormatStorageDomainVDSCommand] (ajp-/127.0.0.1:8009-9) [6917eb4f] FINISH, FormatStorageDomainVDSCommand, log id: 4ffa0c44
2012-09-10 09:33:41,741 WARN  [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (ajp-/127.0.0.1:8009-9) [6917eb4f] Didnt find the value of IsNeedSupportForOldVgAPI in DB for version 3.1 - using default: f
alse
2012-09-10 09:33:41,749 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DisconnectStorageServerVDSCommand] (ajp-/127.0.0.1:8009-9) [6917eb4f] START, DisconnectStorageServerVDSCommand(vdsId = 33892284-fb0e-11e1-ae
6f-001a4a169773, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = ISCSI, connectionList = [{ id: a86c72b4-b0a8-4aff-83ca-91c1cdb9110c, connection: 10.35.160.7, iqn: iqn.2008-05.com.xtremio:001b2
1b545c0, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };]), log id: b5593f5
2012-09-10 09:33:42,186 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (QuartzScheduler_Worker-30) Setting new tasks map. The map contains now 0 tasks
2012-09-10 09:33:42,186 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (QuartzScheduler_Worker-30) Cleared all tasks of pool 1ab91c14-a6d3-40fa-a2eb-2241e2f294a9.
2012-09-10 09:33:42,627 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DisconnectStorageServerVDSCommand] (ajp-/127.0.0.1:8009-9) [6917eb4f] FINISH, DisconnectStorageServerVDSCommand, return: {a86c72b4-b0a8-4aff
-83ca-91c1cdb9110c=0}, log id: b5593f5

**** snip *****

2012-09-10 09:33:43,212 INFO  [org.ovirt.engine.core.bll.MaintananceNumberOfVdssCommand] (ajp-/127.0.0.1:8009-4) [316566b6] Running command: MaintananceNumberOfVdssCommand internal: false. Entities affected :  ID:
 33892284-fb0e-11e1-ae6f-001a4a169773 Type: VDS
2012-09-10 09:33:43,212 INFO  [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (ajp-/127.0.0.1:8009-4) [316566b6] START, SetVdsStatusVDSCommand(vdsId = 33892284-fb0e-11e1-ae6f-001a4a169773, status=Preparin
gForMaintenance, nonOperationalReason=NONE), log id: 7d4fb053
2012-09-10 09:33:43,252 INFO  [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (ajp-/127.0.0.1:8009-4) [316566b6] FINISH, SetVdsStatusVDSCommand, log id: 7d4fb053
2012-09-10 09:33:43,354 INFO  [org.ovirt.engine.core.bll.MaintananceVdsCommand] (ajp-/127.0.0.1:8009-4) [316566b6] Running command: MaintananceVdsCommand internal: true. Entities affected :  ID: 33892284-fb0e-11e1
-ae6f-001a4a169773 Type: VDS
2012-09-10 09:33:44,302 INFO  [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-36) vds::Updated vds status from Preparing for Maintenance to Maintenance in database,  vds = 33892284-f
b0e-11e1-ae6f-001a4a169773 : 10.35.160.97
2012-09-10 09:33:54,839 INFO  [org.ovirt.engine.core.bll.MaintananceNumberOfVdssCommand] (ajp-/127.0.0.1:8009-3) [3f81c346] Running command: MaintananceNumberOfVdssCommand internal: false. Entities affected :  ID:
 42e7ecbe-fb0f-11e1-87f4-001a4a169773 Type: VDS
2012-09-10 09:33:54,841 INFO  [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (ajp-/127.0.0.1:8009-3) [3f81c346] START, SetVdsStatusVDSCommand(vdsId = 42e7ecbe-fb0f-11e1-87f4-001a4a169773, status=Preparin
gForMaintenance, nonOperationalReason=NONE), log id: 63a074db
2012-09-10 09:33:55,253 INFO  [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (ajp-/127.0.0.1:8009-3) [3f81c346] FINISH, SetVdsStatusVDSCommand, log id: 63a074db
2012-09-10 09:33:55,330 INFO  [org.ovirt.engine.core.bll.MaintananceVdsCommand] (ajp-/127.0.0.1:8009-3) [3f81c346] Running command: MaintananceVdsCommand internal: true. Entities affected :  ID: 42e7ecbe-fb0f-11e1
-87f4-001a4a169773 Type: VDS
2012-09-10 09:33:56,886 INFO  [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-56) vds::Updated vds status from Preparing for Maintenance to Maintenance in database,  vds = 42e7ecbe-f
b0f-11e1-87f4-001a4a169773 : 10.35.160.95
2012-09-10 09:34:06,011 INFO  [org.ovirt.engine.core.bll.RemoveVdsCommand] (ajp-/127.0.0.1:8009-8) [c9fb88] Lock Acquired to object EngineLock [exclusiveLocks= key: 33892284-fb0e-11e1-ae6f-001a4a169773 value: VDS
, sharedLocks= ]
2012-09-10 09:34:06,023 INFO  [org.ovirt.engine.core.bll.RemoveVdsCommand] (ajp-/127.0.0.1:8009-8) [c9fb88] Running command: RemoveVdsCommand internal: false. Entities affected :  ID: 33892284-fb0e-11e1-ae6f-001a4
a169773 Type: VDS
2012-09-10 09:34:06,050 INFO  [org.ovirt.engine.core.vdsbroker.RemoveVdsVDSCommand] (ajp-/127.0.0.1:8009-8) [c9fb88] START, RemoveVdsVDSCommand(vdsId = 33892284-fb0e-11e1-ae6f-001a4a169773), log id: 6ffa28d7
2012-09-10 09:34:06,050 INFO  [org.ovirt.engine.core.vdsbroker.VdsManager] (ajp-/127.0.0.1:8009-8) [c9fb88] vdsManager::disposing
2012-09-10 09:34:06,051 INFO  [org.ovirt.engine.core.vdsbroker.RemoveVdsVDSCommand] (ajp-/127.0.0.1:8009-8) [c9fb88] FINISH, RemoveVdsVDSCommand, log id: 6ffa28d7
2012-09-10 09:34:06,052 INFO  [org.ovirt.engine.core.bll.RemoveVdsCommand] (ajp-/127.0.0.1:8009-8) [c9fb88] Lock freed to object EngineLock [exclusiveLocks= key: 33892284-fb0e-11e1-ae6f-001a4a169773 value: VDS
, sharedLocks= ]
2012-09-10 09:34:07,288 INFO  [org.ovirt.engine.core.bll.RemoveVdsCommand] (ajp-/127.0.0.1:8009-1) [76ca1f4c] Lock Acquired to object EngineLock [exclusiveLocks= key: 42e7ecbe-fb0f-11e1-87f4-001a4a169773 value: VDS
, sharedLocks= ]
2012-09-10 09:34:07,297 INFO  [org.ovirt.engine.core.bll.RemoveVdsCommand] (ajp-/127.0.0.1:8009-1) [76ca1f4c] Running command: RemoveVdsCommand internal: false. Entities affected :  ID: 42e7ecbe-fb0f-11e1-87f4-001a4a169773 Type: VDS
2012-09-10 09:34:07,311 INFO  [org.ovirt.engine.core.vdsbroker.RemoveVdsVDSCommand] (ajp-/127.0.0.1:8009-1) [76ca1f4c] START, RemoveVdsVDSCommand(vdsId = 42e7ecbe-fb0f-11e1-87f4-001a4a169773), log id: 61dc8f4f
2012-09-10 09:34:07,311 INFO  [org.ovirt.engine.core.vdsbroker.VdsManager] (ajp-/127.0.0.1:8009-1) [76ca1f4c] vdsManager::disposing
2012-09-10 09:34:07,311 INFO  [org.ovirt.engine.core.vdsbroker.RemoveVdsVDSCommand] (ajp-/127.0.0.1:8009-1) [76ca1f4c] FINISH, RemoveVdsVDSCommand, log id: 61dc8f4f


***** snip ******
012-09-10 09:34:25,665 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-16) Installation of 10.35.160.97. Received message: <BSTRAP component='VDS PACKAGES' status='OK' result='sanlock-python' message='sanlock-python-2.3-3.el6_3.x86_64 '/>. FYI. (Stage: Running first installation script on Host)
2012-09-10 09:35:00,000 INFO  [org.ovirt.engine.core.bll.AutoRecoveryManager] (QuartzScheduler_Worker-10) Autorecovering hosts is disabled, skipping
2012-09-10 09:35:00,001 INFO  [org.ovirt.engine.core.bll.AutoRecoveryManager] (QuartzScheduler_Worker-10) Autorecovering storage domains is disabled, skipping
2012-09-10 09:35:02,103 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (QuartzScheduler_Worker-11) starting ProcessDomainRecovery for domain 46dd00e5-95e7-48a4-b096-9a19b8d2a7a1
2012-09-10 09:35:02,138 ERROR [org.ovirt.engine.core.utils.timer.SchedulerUtilQuartzImpl] (QuartzScheduler_Worker-11) failed to invoke sceduled method OnTimer: java.lang.reflect.InvocationTargetException
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_05-icedtea]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_05-icedtea]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_05-icedtea]
        at java.lang.reflect.Method.invoke(Method.java:601) [rt.jar:1.7.0_05-icedtea]
        at org.ovirt.engine.core.utils.timer.JobWrapper.execute(JobWrapper.java:64) [engine-scheduler.jar:]
        at org.quartz.core.JobRunShell.run(JobRunShell.java:213) [quartz-2.1.2.jar:]
        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:557) [quartz-2.1.2.jar:]
Caused by: java.lang.NullPointerException
        at org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand$IrsProxyData$7.runInTransaction(IrsBrokerCommand.java:1317) [engine-vdsbroker.jar:]
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInSuppressed(TransactionSupport.java:168) [engine-utils.jar:]
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:107) [engine-utils.jar:]
        at org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand$IrsProxyData.ProcessDomainRecovery(IrsBrokerCommand.java:1235) [engine-vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand$IrsProxyData.OnTimer(IrsBrokerCommand.java:1215) [engine-vdsbroker.jar:]
        ... 7 more

2012-09-10 09:35:38,697 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-16) Installation of 10.35.160.97. Received message: <BSTRAP component='VDS PACKAGES'

Version-Release number of selected component (if applicable):
rhevm-3.1.0-15.el6ev.noarch

Comment 1 Ayal Baron 2012-11-05 07:38:16 UTC

Can you supply reproduce steps? the above is not really clear.

Comment 2 Gadi Ickowicz 2012-11-25 15:22:30 UTC

Not sure about the scenario which closed this, and I haven't seen it since either.