[ovirt-devel] [ OST Failure Report ] [ oVirt master ] [ 16-11-2017 ] [ 002_bootstrap.add_dc ]

Thu Nov 16 11:01:47 UTC 2017

this patch you mentioned fixes the problem. Those errors shouldn't occur now

On Thu, 16 Nov 2017 at 12:59 Eyal Edri <eedri at redhat.com> wrote:

> https://gerrit.ovirt.org/#/c/84231/ ?
>
> On Thu, Nov 16, 2017 at 12:57 PM, Martin Perina <mperina at redhat.com>
> wrote:
>
>>
>>
>> On Thu, Nov 16, 2017 at 11:43 AM, Eyal Edri <eedri at redhat.com> wrote:
>>
>>> Please give it highest priority, we can't let it fail into the weekend.
>>>
>>> On Thu, Nov 16, 2017 at 12:40 PM, Dafna Ron <dron at redhat.com> wrote:
>>>
>>>> Hi,
>>>>
>>>> we have a CQ failure in add_dc test. I can see at engine long that we
>>>> have an issue with 'extension.aaa.jdbc.binding.api.AuthnExtension'
>>>>
>>>> I don't think that the patch reported was the actual cause of the
>>>> failure. Yesterday we were failing on missing package ovirt-cockpit-sso
>>>> which we added to our repos. and I think perhaps we now exposed an issue
>>>> with sso support which was undiscovered before.
>>>>
>>>>
>>>> *Link to suspected patches: *
>>>>
>>>> These are the reported patches:
>>>>
>>>> https://gerrit.ovirt.org/#/c/83790/
>>>>
>>>> https://gerrit.ovirt.org/#/c/83779/
>>>>
>>>>
>>>>
>>>> * Here is the original patch for the sso support:
>>>> https://gerrit.ovirt.org/#/c/82997/ <https://gerrit.ovirt.org/#/c/82997/>
>>>> Link to Job: *
>>>> http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3877/
>>>> <http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3878/>
>>>>
>>>> http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3878/
>>>>
>>>> *Link to all logs:*
>>>>
>>>>
>>>> *
>>>> http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3877/artifact/
>>>> <http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3877/artifact/>
>>>> http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3878/artifact/
>>>> <http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3878/artifact/>
>>>> (Relevant) error snippet from the log: <error> *
>>>>
>>>>
>>>> 2017-11-15 16:50:07,115-05 INFO  [org.ovirt.engine.core.extensions.mgr.ExtensionsManager] (ServerService Thread Pool -- 45) [] Loading extension 'internal-authn'
>>>> 2017-11-15 16:50:07,118-05 INFO  [org.ovirt.engine.core.extensions.mgr.ExtensionsManager] (ServerService Thread Pool -- 45) [] Extension 'internal-authn' loaded
>>>> 2017-11-15 16:50:07,118-05 DEBUG [org.ovirt.engine.core.extensions.mgr.ExtensionsManager.trace."ovirt-engine-extension-aaa-jdbc".authn.internal-authn] (ServerService Thread Pool -- 45) [] Config BEGIN
>>>> 2017-11-15 16:50:07,118-05 DEBUG [org.ovirt.engine.core.extensions.mgr.ExtensionsManager.trace."ovirt-engine-extension-aaa-jdbc".authn.internal-authn] (ServerService Thread Pool -- 45) [] ovirt.engine.aaa.authn.profile.name: internal
>>>> 2017-11-15 16:50:07,118-05 DEBUG [org.ovirt.engine.core.extensions.mgr.ExtensionsManager.trace."ovirt-engine-extension-aaa-jdbc".authn.internal-authn] (ServerService Thread Pool -- 45) [] ovirt.engine.extension.provides: org.ovirt.engine.api.extensions.aaa.Authn
>>>> 2017-11-15 16:50:07,118-05 DEBUG [org.ovirt.engine.core.extensions.mgr.ExtensionsManager.trace."ovirt-engine-extension-aaa-jdbc".authn.internal-authn] (ServerService Thread Pool -- 45) [] ovirt.engine.extension.binding.jbossmodule.class: org.ovirt.engine.extension.aaa.jdbc.binding.api.AuthnExtension
>>>> 2017-11-15 16:50:07,118-05 DEBUG [org.ovirt.engine.core.extensions.mgr.ExtensionsManager.trace."ovirt-engine-extension-aaa-jdbc".authn.internal-authn] (ServerService Thread Pool -- 45) [] ovirt.engine.aaa.authn.authz.plugin: internal-authz
>>>> 2017-11-15 16:50:07,118-05 DEBUG [org.ovirt.engine.core.extensions.mgr.ExtensionsManager.trace."ovirt-engine-extension-aaa-jdbc".authn.internal-authn] (ServerService Thread Pool -- 45) [] ovirt.engine.extension.bindings.method: jbossmodule
>>>> 2017-11-15 16:50:07,118-05 DEBUG [org.ovirt.engine.core.extensions.mgr.ExtensionsManager.trace."ovirt-engine-extension-aaa-jdbc".authn.internal-authn] (ServerService Thread Pool -- 45) [] config.datasource.file: /etc/ovirt-engine/aaa/internal.properties
>>>> 2017-11-15 16:50:07,118-05 DEBUG [org.ovirt.engine.core.extensions.mgr.ExtensionsManager.trace."ovirt-engine-extension-aaa-jdbc".authn.internal-authn] (ServerService Thread Pool -- 45) [] ovirt.engine.extension.name: internal-authn
>>>> 2017-11-15 16:50:07,118-05 DEBUG [org.ovirt.engine.core.extensions.mgr.ExtensionsManager.trace."ovirt-engine-extension-aaa-jdbc".authn.internal-authn] (ServerService Thread Pool -- 45) [] ovirt.engine.extension.binding.jbossmodule.module: org.ovirt.engine.extension.aaa.jdbc
>>>> 2017-11-15 16:50:07,118-05 DEBUG [org.ovirt.engine.core.extensions.mgr.ExtensionsManager.trace."ovirt-engine-extension-aaa-jdbc".authn.internal-authn] (ServerService Thread Pool -- 45) [] Config END
>>>> 2017-11-15 16:50:07,119-05 INFO  [org.ovirt.engine.core.extensions.mgr.ExtensionsManager] (ServerService Thread Pool -- 45) [] Loading extension 'internal-authz'
>>>> 2017-11-15 16:50:07,120-05 INFO  [org.ovirt.engine.core.extensions.mgr.ExtensionsManager] (ServerService Thread Pool -- 45) [] Extension 'internal-authz' loaded
>>>> 2017-11-15 16:50:07,120-05 DEBUG [org.ovirt.engine.core.extensions.mgr.ExtensionsManager.trace."ovirt-engine-extension-aaa-jdbc".authz.internal-authz] (ServerService Thread Pool -- 45) [] Config BEGIN
>>>> 2017-11-15 16:50:07,120-05 DEBUG [org.ovirt.engine.core.extensions.mgr.ExtensionsManager.trace."ovirt-engine-extension-aaa-jdbc".authz.internal-authz] (ServerService Thread Pool -- 45) [] ovirt.engine.extension.provides: org.ovirt.engine.api.extensions.aaa.Authz
>>>> 2017-11-15 16:50:07,120-05 DEBUG [org.ovirt.engine.core.extensions.mgr.ExtensionsManager.trace."ovirt-engine-extension-aaa-jdbc".authz.internal-authz] (ServerService Thread Pool -- 45) [] ovirt.engine.extension.binding.jbossmodule.class: org.ovirt.engine.extension.aaa.jdbc.binding.api.AuthzExtension
>>>> 2017-11-15 16:50:07,120-05 DEBUG [org.ovirt.engine.core.extensions.mgr.ExtensionsManager.trace."ovirt-engine-extension-aaa-jdbc".authz.internal-authz] (ServerService Thread Pool -- 45) [] ovirt.engine.extension.bindings.method: jbossmodule
>>>> 2017-11-15 16:50:07,120-05 DEBUG [org.ovirt.engine.core.extensions.mgr.ExtensionsManager.trace."ovirt-engine-extension-aaa-jdbc".authz.internal-authz] (ServerService Thread Pool -- 45) [] config.datasource.file: /etc/ovirt-engine/aaa/internal.properties
>>>> 2017-11-15 16:50:07,120-05 DEBUG [org.ovirt.engine.core.extensions.mgr.ExtensionsManager.trace."ovirt-engine-extension-aaa-jdbc".authz.internal-authz] (ServerService Thread Pool -- 45) [] ovirt.engine.extension.name: internal-authz
>>>> 2017-11-15 16:50:07,120-05 DEBUG [org.ovirt.engine.core.extensions.mgr.ExtensionsManager.trace."ovirt-engine-extension-aaa-jdbc".authz.internal-authz] (ServerService Thread Pool -- 45) [] ovirt.engine.extension.binding.jbossmodule.module: org.ovirt.engine.extension.aaa.jdbc
>>>> 2017-11-15 16:50:07,120-05 DEBUG [org.ovirt.engine.core.extensions.mgr.ExtensionsManager.trace."ovirt-engine-extension-aaa-jdbc".authz.internal-authz] (ServerService Thread Pool -- 45) [] Config END
>>>> 2017-11-15 16:50:07,121-05 INFO  [org.ovirt.engine.core.extensions.mgr.ExtensionsManager] (ServerService Thread Pool -- 45) [] Initializing extension 'internal-authn'
>>>> 2017-11-15 16:50:07,182-05 ERROR [org.ovirt.engine.extension.aaa.jdbc.binding.api.AuthnExtension] (ServerService Thread Pool -- 45) [] Unexpected Exception invoking: EXTENSION_INITIALIZE[e5ae1b7f-9104-4f23-a444-7b9175ff68d2]
>>>> 2017-11-15 16:50:07,182-05 DEBUG [org.ovirt.engine.extension.aaa.jdbc.binding.api.AuthnExtension] (ServerService Thread Pool -- 45) [] Exception:: org.postgresql.util.PSQLException: FATAL: the database system is shutting down
>>>>
>>>>
>> This is the main issue, who is stopping PostgreSQL database during
>> engine startup?
>>
>> I've looked at /var/log/messages and there are plenty of PostgreSQL
>> restarts:
>>
>> Nov 15 16:47:26 lago-basic-suite-master-engine systemd: Starting
>> PostgreSQL database server...
>> Nov 15 16:47:26 lago-basic-suite-master-engine postgresql-ctl: LOG:
>> redirecting log output to logging collector process
>> Nov 15 16:47:26 lago-basic-suite-master-engine postgresql-ctl: HINT:
>> Future log output will appear in directory "pg_log".
>> Nov 15 16:47:27 lago-basic-suite-master-engine systemd: Started
>> PostgreSQL database server.
>> Nov 15 16:47:28 lago-basic-suite-master-engine systemd: Stopping
>> PostgreSQL database server...
>> Nov 15 16:47:29 lago-basic-suite-master-engine systemd: Stopped
>> PostgreSQL database server.
>> Nov 15 16:47:29 lago-basic-suite-master-engine systemd: Starting
>> PostgreSQL database server...
>> Nov 15 16:47:29 lago-basic-suite-master-engine postgresql-ctl: LOG:
>> redirecting log output to logging collector process
>> Nov 15 16:47:29 lago-basic-suite-master-engine postgresql-ctl: HINT:
>> Future log output will appear in directory "pg_log".
>> Nov 15 16:47:30 lago-basic-suite-master-engine systemd: Started
>> PostgreSQL database server.
>> Nov 15 16:47:30 lago-basic-suite-master-engine systemd: Stopping
>> PostgreSQL database server...
>> Nov 15 16:47:31 lago-basic-suite-master-engine systemd: Stopped
>> PostgreSQL database server.
>> Nov 15 16:47:31 lago-basic-suite-master-engine systemd: Starting
>> PostgreSQL database server...
>> Nov 15 16:47:31 lago-basic-suite-master-engine postgresql-ctl: LOG:
>> redirecting log output to logging collector process
>> Nov 15 16:47:31 lago-basic-suite-master-engine postgresql-ctl: HINT:
>> Future log output will appear in directory "pg_log".
>> Nov 15 16:47:32 lago-basic-suite-master-engine systemd: Started
>> PostgreSQL database server.
>> Nov 15 16:47:33 lago-basic-suite-master-engine systemd: Stopping
>> PostgreSQL database server...
>> Nov 15 16:47:34 lago-basic-suite-master-engine systemd: Stopped
>> PostgreSQL database server.
>> Nov 15 16:47:34 lago-basic-suite-master-engine systemd: Starting
>> PostgreSQL database server...
>> Nov 15 16:47:34 lago-basic-suite-master-engine postgresql-ctl: LOG:
>> redirecting log output to logging collector process
>> Nov 15 16:47:34 lago-basic-suite-master-engine postgresql-ctl: HINT:
>> Future log output will appear in directory "pg_log".
>> Nov 15 16:47:35 lago-basic-suite-master-engine systemd: Started
>> PostgreSQL database server.
>> Nov 15 16:50:00 lago-basic-suite-master-engine systemd: Stopping
>> PostgreSQL database server...
>> Nov 15 16:50:08 lago-basic-suite-master-engine systemd: Starting
>> PostgreSQL database server...
>>
>>
>> So we need to take a look at PostgreSQL logs to see the cause of failures
>>
>> 	at org.postgresql.core.v3.ConnectionFactoryImpl.doAuthentication(ConnectionFactoryImpl.java:398) [postgresql.jar:]
>>>> 	at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:173) [postgresql.jar:]
>>>> 	at org.postgresql.core.ConnectionFactory.openConnection(ConnectionFactory.java:64) [postgresql.jar:]
>>>> 	at org.postgresql.jdbc2.AbstractJdbc2Connection.<init>(AbstractJdbc2Connection.java:136) [postgresql.jar:]
>>>> 	at org.postgresql.jdbc3.AbstractJdbc3Connection.<init>(AbstractJdbc3Connection.java:29) [postgresql.jar:]
>>>> 	at org.postgresql.jdbc3g.AbstractJdbc3gConnection.<init>(AbstractJdbc3gConnection.java:21) [postgresql.jar:]
>>>> 	at org.postgresql.jdbc4.AbstractJdbc4Connection.<init>(AbstractJdbc4Connection.java:31) [postgresql.jar:]
>>>> 	at org.postgresql.jdbc4.Jdbc4Connection.<init>(Jdbc4Connection.java:24) [postgresql.jar:]
>>>> 	at org.postgresql.Driver.makeConnection(Driver.java:393) [postgresql.jar:]
>>>> 	at org.postgresql.Driver.connect(Driver.java:267) [postgresql.jar:]
>>>> 	at java.sql.DriverManager.getConnection(DriverManager.java:664) [rt.jar:1.8.0_151]
>>>> 	at java.sql.DriverManager.getConnection(DriverManager.java:247) [rt.jar:1.8.0_151]
>>>> 	at org.ovirt.engine.extension.aaa.jdbc.core.datasource.DataSourceProvider$1.invoke(DataSourceProvider.java:86) [ovirt-engine-extension-aaa-jdbc.jar:]
>>>> 	at com.sun.proxy.$Proxy177.getConnection(Unknown Source)
>>>> 	at org.ovirt.engine.extension.aaa.jdbc.core.datasource.SchemaAwareDataSource.getConnection(SchemaAwareDataSource.java:41) [ovirt-engine-extension-aaa-jdbc.jar:]
>>>> 	at org.ovirt.engine.extension.aaa.jdbc.binding.api.ExtensionUtils.checkDbVersion(ExtensionUtils.java:146) [ovirt-engine-extension-aaa-jdbc.jar:]
>>>> 	at org.ovirt.engine.extension.aaa.jdbc.binding.api.AuthnExtension.doInit(AuthnExtension.java:114) [ovirt-engine-extension-aaa-jdbc.jar:]
>>>> 	at org.ovirt.engine.extension.aaa.jdbc.binding.api.AuthnExtension.invoke(AuthnExtension.java:56) [ovirt-engine-extension-aaa-jdbc.jar:]
>>>> 	at org.ovirt.engine.core.extensions.mgr.ExtensionProxy.invoke(ExtensionProxy.java:49)
>>>> 	at org.ovirt.engine.core.extensions.mgr.ExtensionProxy.invoke(ExtensionProxy.java:73)
>>>> 	at org.ovirt.engine.core.extensions.mgr.ExtensionProxy.invoke(ExtensionProxy.java:109)
>>>> 	at org.ovirt.engine.core.extensions.mgr.ExtensionsManager.initialize(ExtensionsManager.java:315)
>>>> 	at org.ovirt.engine.core.sso.utils.SsoExtensionsManager.initialize(SsoExtensionsManager.java:91)
>>>> 	at org.ovirt.engine.core.sso.utils.SsoExtensionsManager.<init>(SsoExtensionsManager.java:28)
>>>> 	at org.ovirt.engine.core.sso.context.SsoContextListener.contextInitialized(SsoContextListener.java:28)
>>>> 	at io.undertow.servlet.core.ApplicationListeners.contextInitialized(ApplicationListeners.java:187)
>>>> 	at io.undertow.servlet.core.DeploymentManagerImpl$1.call(DeploymentManagerImpl.java:205)
>>>> 	at io.undertow.servlet.core.DeploymentManagerImpl$1.call(DeploymentManagerImpl.java:174)
>>>> 	at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:42)
>>>> 	at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
>>>> 	at org.wildfly.extension.undertow.security.SecurityContextThreadSetupAction.lambda$create$0(SecurityContextThreadSetupAction.java:105)
>>>> 	at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1508)
>>>> 	at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1508)
>>>> 	at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1508)
>>>> 	at io.undertow.servlet.core.DeploymentManagerImpl.deploy(DeploymentManagerImpl.java:239)
>>>> 	at org.wildfly.extension.undertow.deployment.UndertowDeploymentService.startContext(UndertowDeploymentService.java:99)
>>>> 	at org.wildfly.extension.undertow.deployment.UndertowDeploymentService$1.run(UndertowDeploymentService.java:81)
>>>> 	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [rt.jar:1.8.0_151]
>>>> 	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [rt.jar:1.8.0_151]
>>>> 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [rt.jar:1.8.0_151]
>>>> 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [rt.jar:1.8.0_151]
>>>> 	at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_151]
>>>> 	at org.jboss.threads.JBossThread.run(JBossThread.java:320)
>>>>
>>>> 2017-11-15 16:50:07,185-05 ERROR [org.ovirt.engine.core.extensions.mgr.ExtensionsManager] (ServerService Thread Pool -- 45) [] Error in activating extension 'internal-authn': FATAL: the database system is shutting down
>>>> 2017-11-15 16:50:07,185-05 DEBUG [org.ovirt.engine.core.extensions.mgr.ExtensionsManager] (ServerService Thread Pool -- 45) [] Class: class org.ovirt.engine.core.extensions.mgr.ExtensionInvokeCommandFailedException
>>>>
>>>> *</error>*
>>>>
>>>>
>>>> _______________________________________________
>>>> Devel mailing list
>>>> Devel at ovirt.org
>>>> http://lists.ovirt.org/mailman/listinfo/devel
>>>>
>>>
>>>
>>>
>>> --
>>>
>>> Eyal edri
>>>
>>>
>>> MANAGER
>>>
>>> RHV DevOps
>>>
>>> EMEA VIRTUALIZATION R&D
>>>
>>>
>>> Red Hat EMEA <https://www.redhat.com/>
>>> <https://red.ht/sig> TRIED. TESTED. TRUSTED.
>>> <https://redhat.com/trusted>
>>> phone: +972-9-7692018 <+972%209-769-2018>
>>> irc: eedri (on #tlv #rhev-dev #rhev-integ)
>>>
>>
>>
>>
>> --
>> Martin Perina
>> Associate Manager, Software Engineering
>> Red Hat Czech s.r.o.
>>
>
>
>
> --
>
> Eyal edri
>
>
> MANAGER
>
> RHV DevOps
>
> EMEA VIRTUALIZATION R&D
>
>
> Red Hat EMEA <https://www.redhat.com/>
> <https://red.ht/sig> TRIED. TESTED. TRUSTED. <https://redhat.com/trusted>
> phone: +972-9-7692018 <+972%209-769-2018>
> irc: eedri (on #tlv #rhev-dev #rhev-integ)
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.ovirt.org/pipermail/devel/attachments/20171116/6e1e02cd/attachment-0001.html>