This service will be undergoing maintenance at 00:00 UTC, 2017-10-23 It is expected to last about 30 minutes
Bug 844306 - [engine-core] locking mechanism: host is stuck in unassigned state for 10 minutes if activate and remove takes place (vds_proxy for this host is lost)
[engine-core] locking mechanism: host is stuck in unassigned state for 10 min...
Status: CLOSED CURRENTRELEASE
Product: Red Hat Enterprise Virtualization Manager
Classification: Red Hat
Component: ovirt-engine (Show other bugs)
3.1.0
x86_64 Linux
unspecified Severity high
: ---
: ---
Assigned To: mkublin
Pavel Stehlik
infra
:
: 844182 (view as bug list)
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2012-07-30 05:18 EDT by Haim
Modified: 2016-02-10 14:01 EST (History)
10 users (show)

See Also:
Fixed In Version: si13
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2012-12-04 15:07:19 EST
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: Infra
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
engine.log (49.71 KB, application/x-gzip)
2012-07-30 05:21 EDT, Haim
no flags Details

  None (edit)
Description Haim 2012-07-30 05:18:58 EDT
Description of problem:

I have the following case were host is stuck in unassigned state till transaction is dead (rolled back), afterwards, host moves to active state, but engine deletes its vdsm-proxy, and bad things happen (reconstruct fails for example).

later on, I get the following log: 


2012-07-30 15:38:40,106 ERROR [org.ovirt.engine.core.vdsbroker.ResourceManager] (QuartzScheduler_Worker-87) [50059c70] Cannot get vdsManager for vdsid=78e0bf24-d979-11e1-9e8e-001a4a16970e
2012-07-30 15:38:40,106 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (QuartzScheduler_Worker-87) [50059c70] ERROR, org.ovirt.engine.core.vdsbroker.irsbroker.GetStoragePoolInfoVDSCommand, exception: RuntimeException: VdcBLLException: Vds with id: 78e0bf24-d979-11e1-9e8e-001a4a16970e was not found, log id: 2d159d5e: java.lang.RuntimeException: VdcBLLException: Vds with id: 78e0bf24-d979-11e1-9e8e-001a4a16970e was not found
        at org.ovirt.engine.core.vdsbroker.ResourceManager.CreateCommand(ResourceManager.java:349) [engine-vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.ResourceManager.runVdsCommand(ResourceManager.java:387) [engine-vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand$IrsProxyData.gethostFromVds(IrsBrokerCommand.java:652) [engine-vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand$IrsProxyData.access$400(IrsBrokerCommand.java:124) [engine-vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand$IrsProxyData$3.runInTransaction(IrsBrokerCommand.java:550) [engine-vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand$IrsProxyData$3.runInTransaction(IrsBrokerCommand.java:547) [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.getIrsProxy(IrsBrokerCommand.java:547) [engine-vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand.getIrsProxy(IrsBrokerCommand.java:1511) [engine-vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand.ExecuteVDSCommand(IrsBrokerCommand.java:1519) [engine-vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.VDSCommandBase.ExecuteCommand(VDSCommandBase.java:60) [engine-vdsbroker.jar:]
        at org.ovirt.engine.core.dal.VdcCommandBase.Execute(VdcCommandBase.java:41) [engine-dal.jar:]
        at org.ovirt.engine.core.vdsbroker.ResourceManager.runVdsCommand(ResourceManager.java:390) [engine-vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand$IrsProxyData.ProceedStoragePoolStats(IrsBrokerCommand.java:300) [engine-vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand$IrsProxyData.access$200(IrsBrokerCommand.java:124) [engine-vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand$IrsProxyData$1.runInTransaction(IrsBrokerCommand.java:205) [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._updatingTimer_Elapsed(IrsBrokerCommand.java:195) [engine-vdsbroker.jar:]
        at sun.reflect.GeneratedMethodAccessor8.invoke(Unknown Source) [: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: org.ovirt.engine.core.common.errors.VdcBLLException: VdcBLLException: Vds with id: 78e0bf24-d979-11e1-9e8e-001a4a16970e was not found
        at org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.initializeVdsBroker(VdsBrokerCommand.java:52) [engine-vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.<init>(VdsBrokerCommand.java:45) [engine-vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStatusVDSCommand.<init>(SpmStatusVDSCommand.java:20) [engine-vdsbroker.jar:]
        at sun.reflect.GeneratedConstructorAccessor66.newInstance(Unknown Source) [:1.7.0_05-icedtea]
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) [rt.jar:1.7.0_05-icedtea]
        at java.lang.reflect.Constructor.newInstance(Constructor.java:525) [rt.jar:1.7.0_05-icedtea]
        at org.ovirt.engine.core.vdsbroker.ResourceManager.CreateCommand(ResourceManager.java:344) [engine-vdsbroker.jar:]


[root@hateya-rhevm ~]# grep 50d11f7f  /var/log/ovirt-engine/engine.log
2012-07-30 15:25:00,005 INFO  [org.ovirt.engine.core.bll.ActivateVdsCommand] (QuartzScheduler_Worker-7) [50d11f7f] Lock Acquired to object EngineLock [exclusiveLocks= key: 16cbcf58-d97a-11e1-bba6-001a4a16970e value: VDS
2012-07-30 15:25:00,006 INFO  [org.ovirt.engine.core.bll.ActivateVdsCommand] (QuartzScheduler_Worker-7) [50d11f7f] Running command: ActivateVdsCommand internal: true. Entities affected :  ID: 16cbcf58-d97a-11e1-bba6-001a4a16970e Type: VDS
2012-07-30 15:25:00,009 ERROR [org.ovirt.engine.core.vdsbroker.ResourceManager] (QuartzScheduler_Worker-7) [50d11f7f] Cannot get vdsManager for vdsid=16cbcf58-d97a-11e1-bba6-001a4a16970e
2012-07-30 15:25:00,009 INFO  [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (QuartzScheduler_Worker-7) [50d11f7f] START, SetVdsStatusVDSCommand(vdsId = 16cbcf58-d97a-11e1-bba6-001a4a16970e, status=Unassigned, nonOperationalReason=NONE), log id: 6eeb761
2012-07-30 15:25:00,009 INFO  [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (QuartzScheduler_Worker-7) [50d11f7f] FINISH, SetVdsStatusVDSCommand, log id: 6eeb761
2012-07-30 15:25:00,182 ERROR [org.ovirt.engine.core.vdsbroker.ResourceManager] (QuartzScheduler_Worker-7) [50d11f7f] Cannot get vdsManager for vdsid=16cbcf58-d97a-11e1-bba6-001a4a16970e
2012-07-30 15:25:00,182 INFO  [org.ovirt.engine.core.vdsbroker.ActivateVdsVDSCommand] (QuartzScheduler_Worker-7) [50d11f7f] START, ActivateVdsVDSCommand(vdsId = 16cbcf58-d97a-11e1-bba6-001a4a16970e), log id: 78859b39
2012-07-30 15:25:00,182 INFO  [org.ovirt.engine.core.vdsbroker.ActivateVdsVDSCommand] (QuartzScheduler_Worker-7) [50d11f7f] FINISH, ActivateVdsVDSCommand, log id: 78859b39
2012-07-30 15:25:00,186 INFO  [org.ovirt.engine.core.bll.ActivateVdsCommand] (QuartzScheduler_Worker-7) [50d11f7f] Command [id=ca65ffe2-3b9c-47ed-bc38-1e44569dc5d1]: Compensating CHANGED_STATUS_ONLY of org.ovirt.engine.core.common.businessentities.VdsDynamic; snapshot: EntityStatusSnapshot [id=16cbcf58-d97a-11e1-bba6-001a4a16970e, status=NonOperational].
2012-07-30 15:25:00,223 ERROR [org.ovirt.engine.core.bll.ActivateVdsCommand] (QuartzScheduler_Worker-7) [50d11f7f] Transaction rolled-back for command: org.ovirt.engine.core.bll.ActivateVdsCommand.
2012-07-30 15:25:00,223 INFO  [org.ovirt.engine.core.bll.ActivateVdsCommand] (QuartzScheduler_Worker-7) [50d11f7f] Lock freed to object EngineLock [exclusiveLocks= key: 16cbcf58-d97a-11e1-bba6-001a4a16970e value: VDS
2012-07-30 15:25:00,232 INFO  [org.ovirt.engine.core.bll.AutoRecoveryManager] (QuartzScheduler_Worker-7) [50d11f7f] Checking autorecoverable hosts done
2012-07-30 15:25:00,232 INFO  [org.ovirt.engine.core.bll.AutoRecoveryManager] (QuartzScheduler_Worker-7) [50d11f7f] Checking autorecoverable storage domains
2012-07-30 15:25:00,232 INFO  [org.ovirt.engine.core.bll.AutoRecoveryManager] (QuartzScheduler_Worker-7) [50d11f7f] Autorecovering 0 storage domains
2012-07-30 15:25:00,232 INFO  [org.ovirt.engine.core.bll.AutoRecoveryManager] (QuartzScheduler_Worker-7) [50d11f7f] Checking autorecoverable storage domains done
Comment 1 Haim 2012-07-30 05:21:51 EDT
Created attachment 601162 [details]
engine.log
Comment 2 mkublin 2012-07-30 07:31:56 EDT
*** Bug 844182 has been marked as a duplicate of this bug. ***
Comment 3 mkublin 2012-07-31 08:39:12 EDT
http://gerrit.ovirt.org/#/c/6778/

Remove will not remove proxy with out entry at DB

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