Candlepin_events FAIL

zmandic · November 11, 2020, 9:25pm

Problem:
Hi,
I have upgraded my Katello 3.15 to Katello 3.16 and upgrade was successfull, no errors. But “hammer ping” is throwing this error:

hammer ping

database:
Status: ok
Server Response: Duration: 0ms
candlepin:
Status: ok
Server Response: Duration: 21ms
candlepin_events:
Status: FAIL
** message: Not running**
Server Response: Duration: 0ms
candlepin_auth:
Status: ok
Server Response: Duration: 20ms
katello_events:
Status: ok
message: 1 Processed, 0 Failed
Server Response: Duration: 0ms
pulp:
Status: ok
Server Response: Duration: 70ms
pulp_auth:
Status: ok
Server Response: Duration: 25ms
foreman_tasks:
Status: ok
Server Response: Duration: 2ms

My RedHat VDC subscriptions are not working correctly, not showing the right amount of consumed licences.On my test environment hammer ping is working correctly.
Later upgraded to Katello 3.17 successfully but with the same problem.

Expected outcome:

hammer ping

database:
Status: ok
Server Response: Duration: 0ms
candlepin:
Status: ok
Server Response: Duration: 32ms
candlepin_events:
Status: ok
message: 0 Processed, 0 Failed
Server Response: Duration: 0ms
candlepin_auth:
Status: ok
Server Response: Duration: 19ms
katello_events:
Status: ok
message: 0 Processed, 0 Failed
Server Response: Duration: 0ms
pulp:
Status: ok
Server Response: Duration: 47ms
pulp_auth:
Status: ok
Server Response: Duration: 25ms
foreman_tasks:
Status: ok
Server Response: Duration: 3ms

Foreman and Proxy versions:
foreman-2.1.4-1.el7.noarch
foreman-proxy-2.1.4-1.el7.noarch

Foreman and Proxy plugin versions:

Distribution and version:
CentOS Linux release 7.8.2003 (Core)
Other relevant data:

jeremylenz · November 12, 2020, 6:00pm

On the server, try restarting Candlepin:

foreman-maintain service restart --only tomcat

or restarting all services:

foreman-maintain service restart

let us know if the issue persists after that.

zmandic · November 12, 2020, 6:47pm

Hi jeremylenz,
I tried that but “hammer” is showing the same problem.
All services are working fine. Tomcat service output:

● tomcat.service - Apache Tomcat Web Application Container
Loaded: loaded (/usr/lib/systemd/system/tomcat.service; enabled; vendor preset: disabled)
Active: active (running) since Thu 2020-11-12 19:34:16 CET; 2min 58s ago
Main PID: 52938 (java)
Tasks: 62
CGroup: /system.slice/tomcat.service
└─52938 /usr/lib/jvm/jre/bin/java -Xms1024m -Xmx4096m -Djava.security.auth.login.config=/usr/share/tomcat/conf/login.config -classpath /usr/share/tomcat/bin/bootstrap.jar:/usr/share/tomcat/bin/tomcat-juli.jar:/usr/share/java/commons-daemon.jar -Dcatalina.base=/usr/share/tomcat -Dcatalina.home=/usr/shar…

Nov 12 19:34:26 puppet.mstart.local server[52938]: Nov 12, 2020 7:34:26 PM com.google.inject.internal.ProxyFactory
Nov 12 19:34:26 puppet.mstart.local server[52938]: WARNING: 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@6dc06258]. This could indicate a bug. The…
Nov 12 19:34:26 puppet.mstart.local server[52938]: Nov 12, 2020 7:34:26 PM com.google.inject.internal.ProxyFactory
Nov 12 19:34:26 puppet.mstart.local server[52938]: WARNING: 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@6dc06258]. This could indicate a bug. The method …
Nov 12 19:34:34 puppet.mstart.local server[52938]: Nov 12, 2020 7:34:34 PM org.apache.catalina.startup.HostConfig deployDirectory
Nov 12 19:34:34 puppet.mstart.local server[52938]: INFO: Deployment of web application directory /var/lib/tomcat/webapps/candlepin has finished in 16,842 ms
Nov 12 19:34:34 puppet.mstart.local server[52938]: Nov 12, 2020 7:34:34 PM org.apache.coyote.AbstractProtocol start
Nov 12 19:34:34 puppet.mstart.local server[52938]: INFO: Starting ProtocolHandler [“http-bio-127.0.0.1-8443”]
Nov 12 19:34:34 puppet.mstart.local server[52938]: Nov 12, 2020 7:34:34 PM org.apache.catalina.startup.Catalina start
Nov 12 19:34:34 puppet.mstart.local server[52938]: INFO: Server startup in 16887 ms
Hint: Some lines were ellipsized, use -l to show in full.

Katello is working fine, only what i noticed is that i have problem with consumed “Red Hat Enterprise Linux for Virtual Datacenters, Standard” licences that are configured throught virt-who configuration. Hammer is not showing my new content hosts subscribed on that licence but there are subscribed and pulling repos. Content hosts subscribed on that licence before upgrade are showing.

I have find simular bug on:

Only problem is that that bug is related to selinux but on my Katello selinux is disabled.

Tnx

jeremylenz · November 12, 2020, 7:34pm

Thanks for finding that @zmandic

Do you see any errors in Foreman’s /var/log/foreman/production.log similar to the one in that bz?

zmandic · November 12, 2020, 7:45pm

Here is the log:
/var/log/foreman/production.log

2020-11-12T20:43:11 [E|app|e3b63f4a] Error occurred while starting Katello::CandlepinEventListener
2020-11-12T20:43:11 [E|app|e3b63f4a] SSL_connect returned=1 errno=0 state=SSLv2/v3 read server hello A: unknown protocol
2020-11-12T20:43:11 [E|app|e3b63f4a] /opt/theforeman/tfm/root/usr/share/gems/gems/stomp-1.4.9/lib/connection/netio.rb:465:in connect' /opt/theforeman/tfm/root/usr/share/gems/gems/stomp-1.4.9/lib/connection/netio.rb:465:in block in open_ssl_socket’
/opt/rh/rh-ruby25/root/usr/share/ruby/timeout.rb:76:in timeout' /opt/theforeman/tfm/root/usr/share/gems/gems/stomp-1.4.9/lib/connection/netio.rb:460:in open_ssl_socket’
/opt/theforeman/tfm/root/usr/share/gems/gems/stomp-1.4.9/lib/connection/netio.rb:520:in open_socket' /opt/theforeman/tfm/root/usr/share/gems/gems/stomp-1.4.9/lib/connection/utils.rb:116:in block in socket’
/opt/theforeman/tfm/root/usr/share/gems/gems/stomp-1.4.9/lib/connection/utils.rb:109:in synchronize' /opt/theforeman/tfm/root/usr/share/gems/gems/stomp-1.4.9/lib/connection/utils.rb:109:in socket’
/opt/theforeman/tfm/root/usr/share/gems/gems/stomp-1.4.9/lib/stomp/connection.rb:173:in initialize' /opt/theforeman/tfm/root/usr/share/gems/gems/stomp-1.4.9/lib/stomp/client.rb:134:in new’
/opt/theforeman/tfm/root/usr/share/gems/gems/stomp-1.4.9/lib/stomp/client.rb:134:in create_connection' /opt/theforeman/tfm/root/usr/share/gems/gems/stomp-1.4.9/lib/stomp/client.rb:101:in block in initialize’
/opt/rh/rh-ruby25/root/usr/share/ruby/timeout.rb:93:in block in timeout' /opt/rh/rh-ruby25/root/usr/share/ruby/timeout.rb:33:in block in catch’
/opt/rh/rh-ruby25/root/usr/share/ruby/timeout.rb:33:in catch' /opt/rh/rh-ruby25/root/usr/share/ruby/timeout.rb:33:in catch’
/opt/rh/rh-ruby25/root/usr/share/ruby/timeout.rb:108:in timeout' /opt/theforeman/tfm/root/usr/share/gems/gems/stomp-1.4.9/lib/stomp/client.rb:99:in initialize’

jeremylenz · November 13, 2020, 5:33pm

Hi @zmandic

SSL_connect returned=1 errno=0 state=SSLv2/v3 read server hello A: unknown protocol

Are you using custom certs? If so, were you using them before the upgrade?

zmandic · November 13, 2020, 5:53pm

Hi @jeremylenz,

No I am not using custom certs. I have them on my test Katello environment where everything is running fine. My next step was to apply custom certs to production but I had this problem first. Even tried to reapply the certs and everything went ok but didnt help resolving my problem.

Other then that Katello is running fine, number of consumed RedHat VDC subscritions are fine but I can’t see which content hosts are using that subscription (only if I manually do “subscription-manager list --consumed” on content host).

ehelms · January 6, 2021, 8:46pm

We think this is related to an issue with the truststore not getting updated when a certificate gets updated. Could you try the following:

rm /etc/candlepin/certs/truststore
foreman-installer

This should force the re-build of the truststore with the latest certificates. We are aiming to fix this officially: https://github.com/theforeman/puppet-certs/pull/311

zmandic · January 8, 2021, 3:45pm

Thanks for the response. I removed the truststore and foreman-installer finished successfully but didnt help. I have the same error in production.log and my candlepin_events are not running (FAILED).

zmandic · January 11, 2021, 2:46pm

I dont think that I have a problem with a trustore:

[root@certs]# keytool -list -keystore /etc/candlepin/certs/keystore
Enter keystore password:
Keystore type: PKCS12
Keystore provider: SUN

Your keystore contains 3 entries

artemis-client, Oct 26, 2020, PrivateKeyEntry,
Certificate fingerprint (SHA1): 43:E4:BA:37:77:8E:E6:0A:E9:D6:BE:F2:E5:7B:DF:6D:F4:91:10:42
candlepin-ca, Jan 11, 2021, trustedCertEntry,
Certificate fingerprint (SHA1): 86:F6:77:38:E9:A1:89:89:BC:51:0B:E0:1F:34:04:B8:4A:F5:DD:65
tomcat, Jan 11, 2021, PrivateKeyEntry,
Certificate fingerprint (SHA1): C5:89:D5:93:0D:89:55:92:64:FC:56:7F:43:2F:D9:9E:D6:E4:99:91
[root@certs]#
[root@certs]# openssl x509 -noout -fingerprint -sha1 -inform pem -in java-client.crt
SHA1 Fingerprint=43:E4:BA:37:77:8E:E6:0A:E9:D6:BE:F2:E5:7B:DF:6D:F4:91:10:42

I have some errors in candlepin.log:

2021-01-11 15:36:18,472 [thread=localhost-startStop-1] [=, org=, csid=] ERROR org.apache.activemq.artemis.core.server - AMQ224104: Error starting the Acceptor stomp {needClientAuth=true, trustStorePassword=xxxxxxxxxxxxxxxxx, scheme=tcp, port=61613, keyStorePassword=xxxxxxxxxxxxxxx, ss
lEnabled=true, host=localhost, trustStorePath=/etc/candlepin/certs/truststore, protocols=STOMP, useEpoll=false, keyStorePath=/etc/candlepin/certs/keystore}
2021-01-11 15:36:18,475 [thread=localhost-startStop-1] [=, org=, csid=] ERROR org.apache.activemq.artemis.core.server - AMQ224000: Failure in initialisation
java.lang.IllegalStateException: AMQ229230: Failed to bind acceptor stomp to localhost:61613
at org.apache.activemq.artemis.core.remoting.impl.netty.NettyAcceptor.startServerChannels(NettyAcceptor.java:687)
at org.apache.activemq.artemis.core.remoting.impl.netty.NettyAcceptor.start(NettyAcceptor.java:455)
at org.apache.activemq.artemis.core.remoting.server.impl.RemotingServiceImpl.startAcceptors(RemotingServiceImpl.java:312)
at org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl.completeActivation(ActiveMQServerImpl.java:3021)
at org.apache.activemq.artemis.core.server.impl.LiveOnlyActivation.run(LiveOnlyActivation.java:78)
at org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl.internalStart(ActiveMQServerImpl.java:599)
at org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl.start(ActiveMQServerImpl.java:526)
at org.apache.activemq.artemis.core.server.embedded.EmbeddedActiveMQ.start(EmbeddedActiveMQ.java:116)
at org.candlepin.messaging.impl.artemis.ArtemisContextListener.initialize(ArtemisContextListener.java:92)
at org.candlepin.guice.CandlepinContextListener.initializeSubsystems(CandlepinContextListener.java:171)
at org.candlepin.guice.CandlepinContextListener.withInjector(CandlepinContextListener.java:153)
at org.jboss.resteasy.plugins.guice.GuiceResteasyBootstrapServletContextListener.contextInitialized(GuiceResteasyBootstrapServletContextListener.java:59)
at org.candlepin.guice.CandlepinContextListener.contextInitialized(CandlepinContextListener.java:146)
at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:5127)
at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5643)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:145)
at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:899)
at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:875)
at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:652)
at org.apache.catalina.startup.HostConfig.deployDirectory(HostConfig.java:1260)
at org.apache.catalina.startup.HostConfig$DeployDirectory.run(HostConfig.java:2002)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Caused by: java.net.BindException: Address already in use
at sun.nio.ch.Net.bind0(Native Method)
at sun.nio.ch.Net.bind(Net.java:461)
at sun.nio.ch.Net.bind(Net.java:453)
at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:222)
at io.netty.channel.socket.nio.NioServerSocketChannel.doBind(NioServerSocketChannel.java:134)
at io.netty.channel.AbstractChannel$AbstractUnsafe.bind(AbstractChannel.java:550)
at io.netty.channel.DefaultChannelPipeline$HeadContext.bind(DefaultChannelPipeline.java:1334)
at io.netty.channel.AbstractChannelHandlerContext.invokeBind(AbstractChannelHandlerContext.java:506)
at io.netty.channel.AbstractChannelHandlerContext.bind(AbstractChannelHandlerContext.java:491)
at io.netty.channel.DefaultChannelPipeline.bind(DefaultChannelPipeline.java:973)
at io.netty.channel.AbstractChannel.bind(AbstractChannel.java:248)
at io.netty.bootstrap.AbstractBootstrap$2.run(AbstractBootstrap.java:356)
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:500)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at org.apache.activemq.artemis.utils.ActiveMQThreadFactory$1.run(ActiveMQThreadFactory.java:118)
2021-01-11 15:36:18,476 [thread=localhost-startStop-1] [=, org=, csid=] INFO org.candlepin.messaging.impl.artemis.ArtemisContextListener - Embedded Artemis server started successfully
2021-01-11 15:36:18,476 [thread=localhost-startStop-1] [=, org=, csid=] INFO org.candlepin.messaging.impl.artemis.ArtemisSessionFactory - Connecting to Artemis server at vm://0
2021-01-11 15:36:18,493 [thread=localhost-startStop-1] [=, org=, csid=] INFO org.candlepin.messaging.impl.artemis.ArtemisSessionFactory - Artemis session factory initialized
2021-01-11 15:36:18,589 [thread=localhost-startStop-1] [=, org=, csid=] INFO org.candlepin.controller.ActiveMQStatusMonitor - Connection to ActiveMQ is available.
2021-01-11 15:36:18,590 [thread=localhost-startStop-1] [=, org=, csid=] INFO org.candlepin.audit.ArtemisMessageSource - ActiveMQ status has been updated: UNKNOWN:CONNECTED
2021-01-11 15:36:18,590 [thread=localhost-startStop-1] [=, org=, csid=] INFO org.candlepin.audit.ArtemisMessageSource - Connecting to message broker and initializing all message listeners.
2021-01-11 15:36:18,650 [thread=localhost-startStop-1] [=, org=, csid=] INFO org.candlepin.async.JobManager - Initializing job manager
2021-01-11 15:36:18,817 [thread=localhost-startStop-1] [=, org=, csid=] INFO org.candlepin.async.JobMessageReceiver - Creating 10 job receiver threads with filter: null
2021-01-11 15:36:19,022 [thread=localhost-startStop-1] [=, org=, csid=] INFO org.candlepin.async.JobManager - Job manager initialization complete
2021-01-11 15:36:19,023 [thread=localhost-startStop-1] [=, org=, csid=] INFO org.candlepin.async.JobManager - Job manager started
2021-01-11 15:36:19,275 [thread=localhost-startStop-1] [=, org=, csid=] INFO org.candlepin.guice.CandlepinContextListener - Candlepin context initialized.

metalcated · January 13, 2021, 3:39pm

I have the same issue. Watching this thread.

I will say this much, the removal of the truststore and re-creation via foreman-installer worked for me on this specific issue.

Thanks

zmandic · January 28, 2021, 10:22am

I am not able to communicate with the localhost (openssl s_client -connect localhost:8443 | openssl x509 -text).

Error message:

socket: Bad file descriptor
connect:errno=9
unable to load certificate
140223429691280:error:0906D06C:PEM routines:PEM_read_bio:no start line:pem_lib.c:707:Expecting: TRUSTED CERTIFICATE

zmandic · January 28, 2021, 12:03pm

My bad,

Candlepin changed ports and now it is running on port: 23443 and it can communicate with the localhost.