Bug 855786 - [log][engine] java InvocationTargetException in logs during ProcessDomainRecovery after adding a host
[log][engine] java InvocationTargetException in logs during ProcessDomainReco...
Status: CLOSED WORKSFORME
Product: Red Hat Enterprise Virtualization Manager
Classification: Red Hat
Component: ovirt-engine (Show other bugs)
3.1.0
All Linux
unspecified Severity medium
: ---
: 3.1.0
Assigned To: Asaf Shakarchi
Gadi Ickowicz
storage
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2012-09-10 05:40 EDT by Gadi Ickowicz
Modified: 2016-02-10 11:59 EST (History)
11 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2012-11-25 10:22:30 EST
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: Storage
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
vdsm + engine logs (2.74 MB, application/x-bzip)
2012-09-10 05:40 EDT, Gadi Ickowicz
no flags Details

  None (edit)
Description Gadi Ickowicz 2012-09-10 05:40:02 EDT
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 02:38:16 EST
Can you supply reproduce steps? the above is not really clear.
Comment 2 Gadi Ickowicz 2012-11-25 10:22:30 EST
Not sure about the scenario which closed this, and I haven't seen it since either.

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