Bug 968150

Summary: [rhevm] Query GetDeviceListQuery failed. Exception message is VdcBLLException: Vds with id: <host_id> was not found
Product: Red Hat Enterprise Virtualization Manager Reporter: vvyazmin <vvyazmin>
Component: ovirt-engineAssignee: Yair Zaslavsky <yzaslavs>
Status: CLOSED INSUFFICIENT_DATA QA Contact: vvyazmin <vvyazmin>
Severity: urgent Docs Contact:
Priority: unspecified    
Version: 3.2.0CC: acathrow, amureini, bazulay, hateya, iheim, jkt, juan.hernandez, lpeer, oourfali, pstehlik, Rhev-m-bugs, sgrinber, vvyazmin, yeylon, yzaslavs
Target Milestone: ---Keywords: Triaged
Target Release: 3.2.2   
Hardware: x86_64   
OS: Linux   
Whiteboard: infra
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2013-07-08 12:10:37 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: Infra RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
## Logs rhevm, vdsm, libvirt, thread dump, vds_table
none
## Logs rhevm
none
## Logs rhevm server log none

Description vvyazmin@redhat.com 2013-05-29 05:58:32 UTC
Created attachment 754179 [details]
## Logs rhevm, vdsm, libvirt, thread dump, vds_table

Description of problem:
Query GetDeviceListQuery failed. Exception message is VdcBLLException: Vds with id: <host_id> was not found

Version-Release number of selected component (if applicable):
RHEVM 3.2 - SF17.1 environment: 

RHEVM: rhevm-3.2.0-11.28.el6ev.noarch 
VDSM: vdsm-4.10.2-21.0.el6ev.x86_64 
LIBVIRT: libvirt-0.10.2-18.el6_4.5.x86_64 
QEMU & KVM: qemu-kvm-rhev-0.12.1.2-2.355.el6_4.3.x86_64 
SANLOCK: sanlock-2.6-2.el6.x86_64

How reproducible:
unknow

Steps to Reproduce:
1. Create iSCSI DC with 50 hosts (in my case 50 fake hosts)
2. Try to add first Storage Domain
  
Actual results:
Failed create first Storage Domain

Expected results:
Succeed create first Storage Domain

Impact on user:
Can't create first Storage Domain

Workaround:
Reboot all RHEVM server (“service ovirt-engine restart” - not help)!

Additional info:

/var/log/ovirt-engine/engine.log

2013-05-28 18:11:33,583 ERROR [org.ovirt.engine.core.vdsbroker.ResourceManager] (ajp-/127.0.0.1:8702-7) Cannot get vdsManager for vdsid=e078d7ac-279d-49b3-898b-48df88d4a923
2013-05-28 18:11:33,583 ERROR [org.ovirt.engine.core.vdsbroker.ResourceManager] (ajp-/127.0.0.1:8702-7) CreateCommand failed: org.ovirt.engine.core.common.errors.VdcBLLException: VdcBLLException: V
ds with id: e078d7ac-279d-49b3-898b-48df88d4a923 was not found
        at org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.initializeVdsBroker(VdsBrokerCommand.java:50) [engine-vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.<init>(VdsBrokerCommand.java:29) [engine-vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.vdsbroker.GetDeviceListVDSCommand.<init>(GetDeviceListVDSCommand.java:32) [engine-vdsbroker.jar:]
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) [rt.jar:1.7.0_19]
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57) [rt.jar:1.7.0_19]
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) [rt.jar:1.7.0_19]
        at java.lang.reflect.Constructor.newInstance(Constructor.java:525) [rt.jar:1.7.0_19]
        at org.ovirt.engine.core.vdsbroker.ResourceManager.CreateCommand(ResourceManager.java:333) [engine-vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.ResourceManager.runVdsCommand(ResourceManager.java:370) [engine-vdsbroker.jar:]
        at org.ovirt.engine.core.bll.VDSBrokerFrontendImpl.RunVdsCommand(VDSBrokerFrontendImpl.java:33) [engine-bll.jar:]
        at org.ovirt.engine.core.bll.storage.GetDeviceListQuery.executeQueryCommand(GetDeviceListQuery.java:35) [engine-bll.jar:]
        at org.ovirt.engine.core.bll.QueriesCommandBase.ExecuteCommand(QueriesCommandBase.java:72) [engine-bll.jar:]
        at org.ovirt.engine.core.dal.VdcCommandBase.Execute(VdcCommandBase.java:28) [engine-dal.jar:]
        at org.ovirt.engine.core.bll.Backend.runQueryImpl(Backend.java:413) [engine-bll.jar:]
        at org.ovirt.engine.core.bll.Backend.RunQuery(Backend.java:390) [engine-bll.jar:]
        at sun.reflect.GeneratedMethodAccessor21.invoke(Unknown Source) [:1.7.0_19]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_19]
        at java.lang.reflect.Method.invoke(Method.java:601) [rt.jar:1.7.0_19]
        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.InterceptorContext$Invocation.proceed(InterceptorContext.java:374) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.ovirt.engine.core.utils.ThreadLocalSessionCleanerInterceptor.injectWebContextToThreadLocal(ThreadLocalSessionCleanerInterceptor.java:11) [engine-utils.jar:]
        at sun.reflect.GeneratedMethodAccessor20.invoke(Unknown Source) [:1.7.0_19]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_19]
        at java.lang.reflect.Method.invoke(Method.java:601) [rt.jar:1.7.0_19]
        at org.jboss.as.ee.component.ManagedReferenceLifecycleMethodInterceptorFactory$ManagedReferenceLifecycleMethodInterceptor.processInvocation(ManagedReferenceLifecycleMethodInterceptorFactory.java:123) [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.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.singleton.SingletonComponentInstanceAssociationInterceptor.processInvocation(SingletonComponentInstanceAssociationInterceptor.java:52) [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]
        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.interfaces.BackendLocal$$$view8.RunQuery(Unknown Source) [engine-common.jar:]
        at org.ovirt.engine.ui.frontend.server.gwt.GenericApiGWTServiceImpl.RunQuery(GenericApiGWTServiceImpl.java:59)
        at sun.reflect.GeneratedMethodAccessor26.invoke(Unknown Source) [:1.7.0_19]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_19]
        at java.lang.reflect.Method.invoke(Method.java:601) [rt.jar:1.7.0_19]
        at com.google.gwt.rpc.server.RPC.invokeAndStreamResponse(RPC.java:196)
        at com.google.gwt.rpc.server.RpcServlet.processCall(RpcServlet.java:161)
        at com.google.gwt.rpc.server.RpcServlet.processPost(RpcServlet.java:222)
        at com.google.gwt.user.server.rpc.AbstractRemoteServiceServlet.doPost(AbstractRemoteServiceServlet.java:62)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:754) [jboss-servlet-api_3.0_spec.jar:1.0.2.Final-redhat-1]
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) [jboss-servlet-api_3.0_spec.jar:1.0.2.Final-redhat-1]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:295)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)
        at org.ovirt.engine.ui.frontend.server.gwt.GwtCachingFilter.doFilter(GwtCachingFilter.java:132)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:246)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:230)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:149)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:481)
        at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:169)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:145)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:97)
        at org.jboss.web.rewrite.RewriteValve.invoke(RewriteValve.java:465)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:102)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:336)
        at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:488)
        at org.apache.coyote.ajp.AjpProtocol$AjpConnectionHandler.process(AjpProtocol.java:420)
        at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:920)
        at java.lang.Thread.run(Thread.java:722) [rt.jar:1.7.0_19]

2013-05-28 18:11:33,590 ERROR [org.ovirt.engine.core.bll.storage.GetDeviceListQuery] (ajp-/127.0.0.1:8702-7) Query GetDeviceListQuery failed. Exception message is VdcBLLException: Vds with id: e078d7ac-279d-49b3-898b-48df88d4a923 was not found

/var/log/vdsm/vdsm.log

Comment 1 Allon Mureinik 2013-05-29 08:53:35 UTC
The issue does not seem related to creating the new domain - engine cannot even send a command to VDSM:
<snip>
org.ovirt.engine.core.common.errors.VdcBLLException: VdcBLLException: V
ds with id: e078d7ac-279d-49b3-898b-48df88d4a923 was not found
        at org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.initializeVdsBroker(VdsBrokerCommand.java:50) [engine-vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.<init>(VdsBrokerCommand.java:29) [engine-vdsbroker.jar:]
</snip>

Yair, any insight?

Comment 3 Yair Zaslavsky 2013-05-29 09:22:53 UTC
(In reply to Allon Mureinik from comment #1)
> The issue does not seem related to creating the new domain - engine cannot
> even send a command to VDSM:
> <snip>
> org.ovirt.engine.core.common.errors.VdcBLLException: VdcBLLException: V
> ds with id: e078d7ac-279d-49b3-898b-48df88d4a923 was not found
>         at
> org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.
> initializeVdsBroker(VdsBrokerCommand.java:50) [engine-vdsbroker.jar:]
>         at
> org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.
> <init>(VdsBrokerCommand.java:29) [engine-vdsbroker.jar:]
> </snip>
> 
> Yair, any insight?

As Allon stated, engine cannot create a new storage domain.
The problem is that ResouceManager which has a map from vds id to VdsManager does not have an entry for the relevant Host.
This of course can happen when the host is removed from the map, but this is not the case.

However, I have a feeling that in this scale test we are not removing any host. The problem can reside in the code that adds the host to the ResourceManager.

Vlad, can you please explain how the scale test was run? 
How many hosts you are adding? at what point do you start to try adding the storage domains? Do you wait for all the hosts to be added or not?

Thanks

Comment 4 vvyazmin@redhat.com 2013-05-29 13:09:35 UTC
Attached relevant log with AddVds Command, from vds id: e078d7ac-279d-49b3-898b-48df88d4a923

xzgrep e078d7ac-279d-49b3-898b-48df88d4a923 /var/log/ovirt-engine/engine.log*.xz | less -S

/var/log/ovirt-engine/engine.log.3-20130528_034102_7492.xz:2013-05-27 14:49:05,539 INFO  [org.ovirt.engine.core.bll.AddVdsSpmIdCommand] (ajp-/127.0.0.1:8702-16) [77b0c062] Runni
ng command: AddVdsSpmIdCommand internal: true. Entities affected : ID: e078d7ac-279d-49b3-898b-48df88d4a923 Type: VDS

Steps to Reproduce:
1. Create iSCSI DC with 50 hosts (in my case 50 fake hosts)
2. After I added all 50 hosts, and they have status UP, I try to add first Storage Domain

Comment 5 vvyazmin@redhat.com 2013-05-29 13:12:27 UTC
Created attachment 754357 [details]
## Logs rhevm

Comment 6 Yair Zaslavsky 2013-05-29 20:25:36 UTC
engine.log.2 shows -

nection; nested exception is java.sql.SQLException: javax.resource.ResourceException: IJ000453: Unable to get managed connection for java:/ENGINEDataSource
2013-05-28 16:47:55,056 ERROR [org.ovirt.engine.core.bll.Backend] (ajp-/127.0.0.1:8702-2) Error in getting DB connection. The database is inaccessible. Original exception is: DataAccessResourceFailureException: Error retreiving database metadata; nested exception is org.springframework.jdbc.support.MetaDataAccessException: Could not get Connection for extracting meta data; nested exception is org.springframework.jdbc.CannotGetJdbcConnectionException: Could not get JDBC Connection; nested exception is java.sql.SQLException: javax.resource.ResourceException: IJ000453: Unable to get managed connection for java:/ENGINEDataSource
2013-05-28 16:48:00,066 ERROR [org.ovirt.engine.core.bll.Backend] (ajp-/127.0.0.1:8702-2) Error in getting DB connection. The database is inaccessible. Original exception is: DataAccessResourceFailureException: Error retreiving database metadata; nested exception is org.springframework.jdbc.support.MetaDataAccessException: Could not get Connection for extracting meta data; nested exception is org.springframework.jdbc.CannotGetJdbcConnectionException: Could not get JDBC Connection; nested exception is java.sql.SQLException: javax.resource.ResourceException: IJ000453: Unable to get managed connection for java:/ENGINEDataSource
2013-05-28 16:48:05,154 INFO  [org.ovirt.engine.core.bll.Backend] (ajp-/127.0.0.1:8702-2) Start time: 5/28/13 4:48 PM
2013-05-28 16:48:05,439 ERROR [org.ovirt.engine.core.engineencryptutils.EncryptionUtils] (ajp-/127.0.0.1:8702-2) Failed to decrypt Data must start with zero
2013-05-28 16:48:05,440 ERROR [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (ajp-/127.0.0.1:8702-2) Failed to decrypt value for property TruststorePass will be used encrypted value
2013-05-28 16:48:05,466 INFO  [org.ovirt.engine.core.bll.Backend] (ajp-/127.0.0.1:8702-2) VDSBrokerFrontend: 5/28/13 4:48 PM
2013-05-28 16:48:05,469 INFO  [org.ovirt.engine.core.bll.Backend] (ajp-/127.0.0.1:8702-2) CpuFlagsManager: 5/28/13 4:48 PM
2013-05-28 16:48:05,469 INFO  [org.ovirt.engine.core.bll.AuditLogCleanupManager] (ajp-/127.0.0.1:8702-2) Setting audit clean up manager to run at: 35 35 3 * * ?
2013-05-28 16:48:05,482 INFO  [org.ovirt.engine.core.bll.Backend] (ajp-/127.0.0.1:8702-2) AuditLogCleanupManager: 5/28/13 4:48 PM
2013-05-28 16:48:05,485 INFO  [org.ovirt.engine.core.bll.TagsDirector] (ajp-/127.0.0.1:8702-2) TagsDirector initialization
2013-05-28 16:48:05,498 INFO  [org.ovirt.engine.core.bll.TagsDirector] (ajp-/127.0.0.1:8702-2) Tag root added to tree
2013-05-28 16:48:05,508 INFO  [org.ovirt.engine.core.bll.Backend] (ajp-/127.0.0.1:8702-2) TagsDirector: 5/28/13 4:48 PM
2013-05-28 16:48:05,514 INFO  [org.ovirt.engine.core.bll.Backend] (ajp-/127.0.0.1:8702-2) IsoDomainListSyncronizer: 5/28/13 4:48 PM
2013-05-28 16:48:05,533 INFO  [org.ovirt.engine.core.bll.Backend] (ajp-/127.0.0.1:8702-2) InitHandlers: 5/28/13 4:48 PM
2013-05-28 16:48:05,543 WARN  [org.ovirt.engine.core.utils.ErrorTranslatorImpl] (ajp-/127.0.0.1:8702-2) Code MAC_ADDRESS_IS_IN_USE appears more than once in string table.
2013-05-28 16:48:05,543 INFO  [org.ovirt.engine.core.bll.Backend] (ajp-/127.0.0.1:8702-2) ErrorTranslator: 5/28/13 4:48 PM
2013-05-28 16:48:05,544 INFO  [org.ovirt.engine.core.bll.Backend] (ajp-/127.0.0.1:8702-2) VdsErrorTranslator: 5/28/13 4:48 PM
2013-05-28 16:48:05,544 INFO  [org.ovirt.engine.core.bll.Backend] (ajp-/127.0.0.1:8702-2) Mark uncompleted jobs as UNKNOWN: 5/28/13 4:48 PM
2013-05-28 16:48:05,595 INFO  [org.ovirt.engine.core.bll.Backend] (ajp-/127.0.0.1:8702-2) JobRepositoryCleanupManager: 5/28/13 4:48 PM
2013-05-28 16:48:05,597 INFO  [org.ovirt.engine.core.bll.Backend] (ajp-/127.0.0.1:8702-2) AutoRecoveryManager: 5/28/13 4:48 P





1. There was DB issue - please elaborate on this.
2. Engine starting code ran again (you can see this here -

013-05-28 16:48:05,154 INFO  [org.ovirt.engine.core.bll.Backend] (ajp-/127.0.0.1:8702-2) Start time: 5/28/13 4:48 PM )
3. InitBackendServicesOnStartupBean service which depends on backend bean did not start - (first appearance in log of this is on 2013-05-29 - on the next day ! 

013-05-29 08:38:15,585 INFO  [org.ovirt.engine.core.vdsbroker.ResourceManager] (ServerService Thread Pool -- 40) ResourceManager::ResourceManager::Entered

However, autorecovery code for example is started at backend bean, and as a result it did run, trying to get VdsManager from resource manager with no luck.

Is it possible to get the server.log/boot.log somehow?

Comment 7 vvyazmin@redhat.com 2013-05-30 07:57:35 UTC
Attached all relevant server.log

Comment 8 vvyazmin@redhat.com 2013-05-30 07:58:24 UTC
Created attachment 754703 [details]
## Logs rhevm server log

Comment 9 Yair Zaslavsky 2013-05-30 11:09:25 UTC
Hi,
In reply to comment #6 - Can you please explain what DB issues you had? How did you recover from?
Do you have a reproduce scenario here?

Comment 11 Juan Hernández 2013-06-03 09:35:46 UTC
What is really strange in this case is that the message that indicates that the backend has started comes from a thread from the pool that manages HTTP connections:

013-05-28 16:48:05,154 INFO  [org.ovirt.engine.core.bll.Backend] (ajp-/127.0.0.1:8702-2) Start time: 5/28/13 4:48 PM )

Note the name of the thread "ajp-/127.0.0.1:8702-2)". I would expect it to be invoked from one of the service threads of the application server, during startup, something like this:

2013-05-12 12:49:50,102 INFO  [org.ovirt.engine.core.bll.Backend] 
(ServerService Thread Pool -- 32) Start time: 5/12/13 12:49 PM

This is what happens in all the other logs attached to the bug.

Apparently the startup of the EJBs didn't work correctly. It may be a 
bug in EAP 6.1.

Comment 12 Barak 2013-06-06 12:11:43 UTC
Is this reproducible ?