Humm … interesting
I had another Foreman/Katello instance that was updated from 3.9/4.11 to 3.11/4.13 on 7/23 and at that time it was candelpin 4.4.10 that was installed (no downgrade at that time, either no 4.4.12 available or my cache was too old and not expired) and everything worked as expected.
Then, I refreshed the cache and launched the update to get latest packages and the update is stuck right now at the candlepin startup.
It is the exact same issue I had with the other instance updated on 7/19… no liquibase logs in catalina logs at candelpin startup and production.log filled with errors:
[...]
2024-07-31T18:42:08 [I|app|323e5e42] Started GET "/" for 10.140.0.10 at 2024-07-31 18:42:08 +0200
2024-07-31T18:42:21 [E|app|cb18b8c7] Error occurred while starting Katello::CandlepinEventListener
2024-07-31T18:42:21 [E|app|cb18b8c7] Connection refused - connect(2) for "localhost" port 61613
2024-07-31T18:42:21 [E|app|cb18b8c7] /usr/share/gems/gems/stomp-1.4.10/lib/connection/netio.rb:461:in `initialize'
[...]
Checked again to be sure:
# rpm -qa |grep candlepin
candlepin-4.4.13-1.el8.noarch
candlepin-selinux-4.4.13-1.el8.noarch
I just installed rng-tools package and enabled rngd.service, and without doing anything else, while foreman-installer wass still trying to run foreman-rake upgrade:run, candlepin startup finished !!
As you can see in the following catalina log file, there is a gap between the last startup log at 18.28.25 and the start of liquibase at 18:45:59:
31-Jul-2024 18:28:19.483 INFOS [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent Un version ancienne [1.2.35] de la bibliothèque Apache Tomcat Native basée sur APR est installée, alors que Tomcat recommande au minimum la version [1.2.38]
31-Jul-2024 18:28:19.490 INFOS [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent Chargement de la librairie Apache Tomcat Native [1.2.35] en utilisant APR version [1.6.3]
31-Jul-2024 18:28:19.491 INFOS [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent Fonctionnalités d'APR : IPv6 [true], sendfile [true], accept filters [false], random [true], UDS [true]
31-Jul-2024 18:28:19.491 INFOS [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent Configuration de APR/OpenSSL : useAprConnector [false], useOpenSSL [true]
31-Jul-2024 18:28:19.496 INFOS [main] org.apache.catalina.core.AprLifecycleListener.initializeSSL OpenSSL a été initialisé avec succès [OpenSSL 1.1.1k FIPS 25 Mar 2021]
31-Jul-2024 18:28:19.932 INFOS [main] org.apache.coyote.AbstractProtocol.init Initialisation du gestionnaire de protocole ["https-openssl-nio-127.0.0.1-23443"]
31-Jul-2024 18:28:19.963 AVERTISSEMENT [main] org.apache.tomcat.util.net.SSLUtilBase.getEnabled Tomcat interprête l'attribut [ciphers] de manière à être cohérent ave la dernière branche de développement d'OpenSSL. Certains de ceux qui ont été spéifiés [ciphers] ne sont pas suportés par le moteur SSL configré pour ce connecteur (qui pourrait utiliser JSSE ou une version antérieure d'OpenSSL) et ont été ignorés: [[TLS_ECDH_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDH_RSA_WITH_AES_256_GCM_SHA384, TLS_ECDH_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_RSA_WITH_AES_128_GCM_SHA256]]
31-Jul-2024 18:28:20.689 INFOS [main] org.apache.tomcat.util.net.AbstractEndpoint.logCertificate Connecteur [https-openssl-nio-127.0.0.1-23443], hôte virtuel TLS [_default_], type de certificat [UNDEFINED] configuré depuis [/etc/candlepin/certs/keystore] avec l'alias [tomcat] et la trust store [/etc/candlepin/certs/truststore]
31-Jul-2024 18:28:20.701 INFOS [main] org.apache.catalina.startup.Catalina.load L'initialisation du serveur a pris [1513] millisecondes
31-Jul-2024 18:28:20.744 INFOS [main] org.apache.catalina.core.StandardService.startInternal Démarrage du service [Catalina]
31-Jul-2024 18:28:20.744 INFOS [main] org.apache.catalina.core.StandardEngine.startInternal Démarrage du moteur de Servlets : [Apache Tomcat/9.0.87]
31-Jul-2024 18:28:20.751 INFOS [main] org.apache.catalina.startup.HostConfig.deployDirectory Déploiement du répertoire d'application web [/var/lib/tomcat/webapps/candlepin]
31-Jul-2024 18:28:25.525 INFOS [main] org.apache.jasper.servlet.TldScanner.scanJars Au moins un fichier JAR a été analysé pour trouver des TLDs mais il n'en contenait pas, le mode "debug" du journal peut être activé pour obtenir une liste complète de JAR scannés sans succès ; éviter d'analyser des JARs inutilement peut améliorer sensiblement le temps de démarrage et le temps de compilation des JSPs
31-Jul-2024 18:45:59.814 INFOS [main] liquibase.database.null Set default schema name to public
31-Jul-2024 18:45:59.843 INFOS [main] liquibase.changelog.null Reading from public.databasechangelog
31-Jul-2024 18:46:01.555 AVERTISSEMENT [main] com.google.inject.internal.ProxyFactory.<init> Method [public void org.candlepin.model.EntitlementCurator.delete(org.candlepin.model.Persisted)] is synthetic and is being intercepted by [com.google.inject.persist.jpa.JpaLocalTxnInterceptor@1d57e7e5]. This could indicate a bug. The method may be intercepted twice, or may not be intercepted at all.
31-Jul-2024 18:46:01.591 AVERTISSEMENT [main] com.google.inject.internal.ProxyFactory.<init> Method [public void org.candlepin.model.EntitlementCertificateCurator.delete(org.candlepin.model.Persisted)] is synthetic and is being intercepted by [com.google.inject.persist.jpa.JpaLocalTxnInterceptor@1d57e7e5]. This could indicate a bug. The method may be intercepted twice, or may not be intercepted at all.
31-Jul-2024 18:46:01.597 AVERTISSEMENT [main] com.google.inject.internal.ProxyFactory.<init> Method [public org.candlepin.model.Persisted org.candlepin.model.OwnerCurator.create(org.candlepin.model.Persisted)] is synthetic and is being intercepted by [com.google.inject.persist.jpa.JpaLocalTxnInterceptor@1d57e7e5]. This could indicate a bug. The method may be intercepted twice, or may not be intercepted at all.
31-Jul-2024 18:46:01.625 AVERTISSEMENT [main] com.google.inject.internal.ProxyFactory.<init> Method [public org.candlepin.model.Persisted org.candlepin.model.ProductCurator.create(org.candlepin.model.Persisted)] is synthetic and is being intercepted by [com.google.inject.persist.jpa.JpaLocalTxnInterceptor@1d57e7e5]. This could indicate a bug. The method may be intercepted twice, or may not be intercepted at all.
31-Jul-2024 18:46:01.625 AVERTISSEMENT [main] com.google.inject.internal.ProxyFactory.<init> Method [public void org.candlepin.model.ProductCurator.delete(org.candlepin.model.Persisted)] is synthetic and is being intercepted by [com.google.inject.persist.jpa.JpaLocalTxnInterceptor@1d57e7e5]. This could indicate a bug. The method may be intercepted twice, or may not be intercepted at all.
31-Jul-2024 18:46:01.625 AVERTISSEMENT [main] com.google.inject.internal.ProxyFactory.<init> Method [public org.candlepin.model.Persisted org.candlepin.model.ProductCurator.merge(org.candlepin.model.Persisted)] is synthetic and is being intercepted by [com.google.inject.persist.jpa.JpaLocalTxnInterceptor@1d57e7e5]. This could indicate a bug. The method may be intercepted twice, or may not be intercepted at all.
31-Jul-2024 18:46:01.631 AVERTISSEMENT [main] com.google.inject.internal.ProxyFactory.<init> Method [public void org.candlepin.model.ContentCurator.delete(org.candlepin.model.Persisted)] is synthetic and is being intercepted by [com.google.inject.persist.jpa.JpaLocalTxnInterceptor@1d57e7e5]. This could indicate a bug. The method may be intercepted twice, or may not be intercepted at all.
31-Jul-2024 18:46:01.646 AVERTISSEMENT [main] com.google.inject.internal.ProxyFactory.<init> Method [public org.candlepin.model.Persisted org.candlepin.model.ConsumerCurator.create(org.candlepin.model.Persisted,boolean)] is synthetic and is being intercepted by [com.google.inject.persist.jpa.JpaLocalTxnInterceptor@1d57e7e5]. This could indicate a bug. The method may be intercepted twice, or may not be intercepted at all.
31-Jul-2024 18:46:01.647 AVERTISSEMENT [main] com.google.inject.internal.ProxyFactory.<init> Method [public void org.candlepin.model.ConsumerCurator.delete(org.candlepin.model.Persisted)] is synthetic and is being intercepted by [com.google.inject.persist.jpa.JpaLocalTxnInterceptor@1d57e7e5]. This could indicate a bug. The method may be intercepted twice, or may not be intercepted at all.
31-Jul-2024 18:46:01.683 AVERTISSEMENT [main] com.google.inject.internal.ProxyFactory.<init> Method [public void org.candlepin.model.CdnCurator.delete(org.candlepin.model.Persisted)] is synthetic and is being intercepted by [com.google.inject.persist.jpa.JpaLocalTxnInterceptor@1d57e7e5]. This could indicate a bug. The method may be intercepted twice, or may not be intercepted at all.
31-Jul-2024 18:46:01.690 AVERTISSEMENT [main] com.google.inject.internal.ProxyFactory.<init> Method [public void org.candlepin.model.PoolCurator.delete(org.candlepin.model.Persisted)] is synthetic and is being intercepted by [com.google.inject.persist.jpa.JpaLocalTxnInterceptor@1d57e7e5]. This could indicate a bug. The method may be intercepted twice, or may not be intercepted at all.
31-Jul-2024 18:46:01.745 AVERTISSEMENT [main] com.google.inject.internal.ProxyFactory.<init> Method [public org.candlepin.model.Persisted org.candlepin.model.RulesCurator.create(org.candlepin.model.Persisted)] is synthetic and is being intercepted by [com.google.inject.persist.jpa.JpaLocalTxnInterceptor@1d57e7e5]. This could indicate a bug. The method may be intercepted twice, or may not be intercepted at all.
31-Jul-2024 18:46:01.745 AVERTISSEMENT [main] com.google.inject.internal.ProxyFactory.<init> Method [public void org.candlepin.model.RulesCurator.delete(org.candlepin.model.Persisted)] is synthetic and is being intercepted by [com.google.inject.persist.jpa.JpaLocalTxnInterceptor@1d57e7e5]. This could indicate a bug. The method may be intercepted twice, or may not be intercepted at all.
31-Jul-2024 18:46:12.504 INFOS [main] org.apache.catalina.startup.HostConfig.deployDirectory Le déploiement du répertoire [/var/lib/tomcat/webapps/candlepin] de l'application web s'est terminé en [1 071 753] ms
31-Jul-2024 18:46:12.509 INFOS [main] org.apache.coyote.AbstractProtocol.start Démarrage du gestionnaire de protocole ["https-openssl-nio-127.0.0.1-23443"]
31-Jul-2024 18:46:12.521 INFOS [main] org.apache.catalina.startup.Catalina.start Le démarrage du serveur a pris [1071819] millisecondes
The liquibase part started right after the rngd.service launch:
● rngd.service - Hardware RNG Entropy Gatherer Daemon
Loaded: loaded (/usr/lib/systemd/system/rngd.service; enabled; vendor preset: enabled)
Active: active (running) since Wed 2024-07-31 18:45:53 CEST; 7min ago
Main PID: 1290235 (rngd)
Seems that there is something more in some setups and the new candlepin release did not fully fix it 