Problem:
We’re facing some strange issues on our ancient production Katello (Foreman 1.15/Katello 3.4):
The virt-who hypervisor tasks get stuck at 17% progress (in Dynflow “3: Actions::Candlepin::AsyncHypervisors (waiting for Candlepin to finish the task)”).
That has started this weekend without any changes to the system. In the chandlepin log, I can see a lot of “Method marked for pagination, but no page exists in the context.” and “Rolling back hornetq transaction.” alongside some http 400, but none of those seem to be related to the Hypervisor task. Any tips on what could be the cause or where to search?
Expected outcome:
Hypervisor Task finishes
Foreman and Proxy versions:
1.15.6
Foreman and Proxy plugin versions:
bastion 5.0.10
foreman-tasks 0.9.4
foreman_docker 3.2.1
foreman_hooks 0.3.14
foreman_remote_execution 1.3.3
foreman_scc_manager 1.0.1
foreman_snapshot_management 1.0.0
foreman_templates 5.0.1
katello 3.4.5
Other relevant data:
[e.g. logs from Foreman and/or the Proxy, modified templates, commands issued, etc]
(for logs, surround with three back-ticks to get proper formatting, e.g.)
A lot of the following messages in /var/log/candlepin/candlepin.log
org.candlepin.common.resteasy.filter.LinkHeaderResponseFilter - Method marked for pagination, but no page exists in the context.
org.candlepin.audit.EventSinkImpl - Rolling back hornetq transaction.
org.candlepin.common.filter.LoggingFilter - Response: status=400, content-type="application/json", time=31
I doubt any of those are related, though, since those also appear when no Hypervisor task is running.
I found some more funky stuff in the logs, but I don’t know If any of these any related.
In /var/log/candlepin/error.log, I found the following stacktraces that do not look healthy to me.
2019-07-01 11:00:46,853 [thread=Thread-3 (HornetQ-remoting-threads-HornetQServerImpl::serverUUID=4088e4d4-54ac-11e6-abd1-e93fb5f9822d-1832623475-1787137074)] [req=bc0397cd-af2a-45c9-b9a6-fa348e5827fe, org=ITM, csid=] ERROR org.hornetq.core
.server - HQ224016: Caught exception
java.lang.IllegalStateException: Can't write records bigger than the bufferSize(102400) on the journal
at org.hornetq.core.journal.impl.TimedBuffer.checkSize(TimedBuffer.java:227) ~[hornetq-journal-2.4.7.Final.jar:na]
at org.hornetq.core.journal.impl.AbstractSequentialFile.fits(AbstractSequentialFile.java:217) ~[hornetq-journal-2.4.7.Final.jar:na]
at org.hornetq.core.journal.impl.JournalImpl.switchFileIfNecessary(JournalImpl.java:3156) ~[hornetq-journal-2.4.7.Final.jar:na]
at org.hornetq.core.journal.impl.JournalImpl.appendRecord(JournalImpl.java:2779) ~[hornetq-journal-2.4.7.Final.jar:na]
at org.hornetq.core.journal.impl.JournalImpl.appendAddRecordTransactional(JournalImpl.java:974) ~[hornetq-journal-2.4.7.Final.jar:na]
at org.hornetq.core.persistence.impl.journal.JournalStorageManager.storeMessageTransactional(JournalStorageManager.java:1076) ~[hornetq-server-2.4.7.Final.jar:na]
at org.hornetq.core.postoffice.impl.PostOfficeImpl.processRoute(PostOfficeImpl.java:1094) ~[hornetq-server-2.4.7.Final.jar:na]
at org.hornetq.core.postoffice.impl.PostOfficeImpl.route(PostOfficeImpl.java:729) ~[hornetq-server-2.4.7.Final.jar:na]
at org.hornetq.core.postoffice.impl.PostOfficeImpl.route(PostOfficeImpl.java:624) ~[hornetq-server-2.4.7.Final.jar:na]
at org.hornetq.core.server.impl.ServerSessionImpl.doSend(ServerSessionImpl.java:1729) ~[hornetq-server-2.4.7.Final.jar:na]
at org.hornetq.core.server.impl.ServerSessionImpl.send(ServerSessionImpl.java:1394) ~[hornetq-server-2.4.7.Final.jar:na]
at org.hornetq.core.protocol.core.ServerSessionPacketHandler.handlePacket(ServerSessionPacketHandler.java:470) ~[hornetq-server-2.4.7.Final.jar:na]
at org.hornetq.core.protocol.core.impl.ChannelImpl.handlePacket(ChannelImpl.java:641) [hornetq-core-client-2.4.7.Final.jar:na]
at org.hornetq.core.protocol.core.impl.RemotingConnectionImpl.doBufferReceived(RemotingConnectionImpl.java:523) [hornetq-core-client-2.4.7.Final.jar:na]
at org.hornetq.core.protocol.core.impl.RemotingConnectionImpl.bufferReceived(RemotingConnectionImpl.java:502) [hornetq-core-client-2.4.7.Final.jar:na]
at org.hornetq.core.remoting.server.impl.RemotingServiceImpl$DelegatingBufferHandler.bufferReceived(RemotingServiceImpl.java:669) [hornetq-server-2.4.7.Final.jar:na]
at org.hornetq.core.remoting.impl.invm.InVMConnection$1.run(InVMConnection.java:166) [hornetq-server-2.4.7.Final.jar:na]
at org.hornetq.utils.OrderedExecutorFactory$OrderedExecutor$1.run(OrderedExecutorFactory.java:104) [hornetq-core-client-2.4.7.Final.jar:na]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_171]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_171]
at java.lang.Thread.run(Thread.java:748) [na:1.8.0_171]
2019-07-01 14:01:57,503 [thread=http-bio-8443-exec-11] [req=88b3082d-a870-4beb-b595-66b1590df273, org=, csid=] ERROR org.candlepin.common.exceptions.mappers.CandlepinExceptionMapper - Runtime Error Could not find resource for full path: ht
tps://deployp001.srv.muenchen.de:8443/candlepin/consumers//compliance at org.jboss.resteasy.core.registry.SegmentNode.match:112
javax.ws.rs.NotFoundException: Could not find resource for full path: https://deployp001.srv.muenchen.de:8443/candlepin/consumers//compliance
at org.jboss.resteasy.core.registry.SegmentNode.match(SegmentNode.java:112) ~[resteasy-jaxrs-3.0.10.Final.jar:na]
at org.jboss.resteasy.core.registry.RootNode.match(RootNode.java:43) ~[resteasy-jaxrs-3.0.10.Final.jar:na]
at org.jboss.resteasy.core.registry.RootClassNode.match(RootClassNode.java:48) ~[resteasy-jaxrs-3.0.10.Final.jar:na]
at org.jboss.resteasy.core.ResourceMethodRegistry.getResourceInvoker(ResourceMethodRegistry.java:444) ~[resteasy-jaxrs-3.0.10.Final.jar:na]
at org.jboss.resteasy.core.SynchronousDispatcher.getInvoker(SynchronousDispatcher.java:234) ~[resteasy-jaxrs-3.0.10.Final.jar:na]
at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:171) ~[resteasy-jaxrs-3.0.10.Final.jar:na]
at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:220) [resteasy-jaxrs-3.0.10.Final.jar:na]
at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56) [resteasy-jaxrs-3.0.10.Final.jar:na]
at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51) [resteasy-jaxrs-3.0.10.Final.jar:na]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:731) [tomcat-servlet-3.0-api.jar:na]
at com.google.inject.servlet.ServletDefinition.doService(ServletDefinition.java:263) [guice-servlet-3.0.jar:na]
at com.google.inject.servlet.ServletDefinition.service(ServletDefinition.java:178) [guice-servlet-3.0.jar:na]
at com.google.inject.servlet.ManagedServletPipeline.service(ManagedServletPipeline.java:91) [guice-servlet-3.0.jar:na]
at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:62) [guice-servlet-3.0.jar:na]
at org.candlepin.servlet.filter.EventFilter.doFilter(EventFilter.java:61) [EventFilter.class:na]
at com.google.inject.servlet.FilterDefinition.doFilter(FilterDefinition.java:163) [guice-servlet-3.0.jar:na]
at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:58) [guice-servlet-3.0.jar:na]
at org.candlepin.servlet.filter.ContentTypeHackFilter.doFilter(ContentTypeHackFilter.java:58) [ContentTypeHackFilter.class:na]
at com.google.inject.servlet.FilterDefinition.doFilter(FilterDefinition.java:163) [guice-servlet-3.0.jar:na]
at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:58) [guice-servlet-3.0.jar:na]
at org.candlepin.common.filter.LoggingFilter.doFilter(LoggingFilter.java:112) [candlepin-common-2.0.3.jar:na]
at com.google.inject.servlet.FilterDefinition.doFilter(FilterDefinition.java:163) [guice-servlet-3.0.jar:na]
at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:58) [guice-servlet-3.0.jar:na]
at org.candlepin.servlet.filter.CandlepinPersistFilter.doFilter(CandlepinPersistFilter.java:48) [CandlepinPersistFilter.class:na]
at com.google.inject.servlet.FilterDefinition.doFilter(FilterDefinition.java:163) [guice-servlet-3.0.jar:na]
at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:58) [guice-servlet-3.0.jar:na]
at org.candlepin.servlet.filter.CandlepinScopeFilter.doFilter(CandlepinScopeFilter.java:68) [CandlepinScopeFilter.class:na]
at com.google.inject.servlet.FilterDefinition.doFilter(FilterDefinition.java:163) [guice-servlet-3.0.jar:na]
at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:58) [guice-servlet-3.0.jar:na]
at com.google.inject.servlet.ManagedFilterPipeline.dispatch(ManagedFilterPipeline.java:118) [guice-servlet-3.0.jar:na]
at com.google.inject.servlet.GuiceFilter.doFilter(GuiceFilter.java:113) [guice-servlet-3.0.jar:na]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) [catalina.jar:7.0.76]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [catalina.jar:7.0.76]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:218) [catalina.jar:7.0.76]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:110) [catalina.jar:7.0.76]
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:506) [catalina.jar:7.0.76]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:169) [catalina.jar:7.0.76]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103) [catalina.jar:7.0.76]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116) [catalina.jar:7.0.76]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:445) [catalina.jar:7.0.76]
at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1087) [tomcat-coyote.jar:7.0.76]
at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:637) [tomcat-coyote.jar:7.0.76]
at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:316) [tomcat-coyote.jar:7.0.76]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_171]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_171]
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-coyote.jar:7.0.76]
at java.lang.Thread.run(Thread.java:748) [na:1.8.0_171]
2019-07-01 10:09:52,685 [thread=Thread-19 (HornetQ-remoting-threads-HornetQServerImpl::serverUUID=4088e4d4-54ac-11e6-abd1-e93fb5f9822d-1154962918-1595256087)] [req=2b8ba17d-802a-47ea-a9be-0cfa0e549154, org=ITM, csid=] ERROR org.hornetq.cor
e.server - HQ224016: Caught exception
java.lang.IllegalStateException: Can't write records bigger than the bufferSize(102400) on the journal
at org.hornetq.core.journal.impl.TimedBuffer.checkSize(TimedBuffer.java:227) ~[hornetq-journal-2.4.7.Final.jar:na]
at org.hornetq.core.journal.impl.AbstractSequentialFile.fits(AbstractSequentialFile.java:217) ~[hornetq-journal-2.4.7.Final.jar:na]
at org.hornetq.core.journal.impl.JournalImpl.switchFileIfNecessary(JournalImpl.java:3156) ~[hornetq-journal-2.4.7.Final.jar:na]
at org.hornetq.core.journal.impl.JournalImpl.appendRecord(JournalImpl.java:2779) ~[hornetq-journal-2.4.7.Final.jar:na]
at org.hornetq.core.journal.impl.JournalImpl.appendAddRecordTransactional(JournalImpl.java:974) ~[hornetq-journal-2.4.7.Final.jar:na]
at org.hornetq.core.persistence.impl.journal.JournalStorageManager.storeMessageTransactional(JournalStorageManager.java:1076) ~[hornetq-server-2.4.7.Final.jar:na]
at org.hornetq.core.postoffice.impl.PostOfficeImpl.processRoute(PostOfficeImpl.java:1094) ~[hornetq-server-2.4.7.Final.jar:na]
at org.hornetq.core.postoffice.impl.PostOfficeImpl.route(PostOfficeImpl.java:729) ~[hornetq-server-2.4.7.Final.jar:na]
at org.hornetq.core.postoffice.impl.PostOfficeImpl.route(PostOfficeImpl.java:624) ~[hornetq-server-2.4.7.Final.jar:na]
at org.hornetq.core.server.impl.ServerSessionImpl.doSend(ServerSessionImpl.java:1729) ~[hornetq-server-2.4.7.Final.jar:na]
at org.hornetq.core.server.impl.ServerSessionImpl.send(ServerSessionImpl.java:1394) ~[hornetq-server-2.4.7.Final.jar:na]
at org.hornetq.core.protocol.core.ServerSessionPacketHandler.handlePacket(ServerSessionPacketHandler.java:470) ~[hornetq-server-2.4.7.Final.jar:na]
at org.hornetq.core.protocol.core.impl.ChannelImpl.handlePacket(ChannelImpl.java:641) [hornetq-core-client-2.4.7.Final.jar:na]
at org.hornetq.core.protocol.core.impl.RemotingConnectionImpl.doBufferReceived(RemotingConnectionImpl.java:523) [hornetq-core-client-2.4.7.Final.jar:na]
at org.hornetq.core.protocol.core.impl.RemotingConnectionImpl.bufferReceived(RemotingConnectionImpl.java:502) [hornetq-core-client-2.4.7.Final.jar:na]
at org.hornetq.core.remoting.server.impl.RemotingServiceImpl$DelegatingBufferHandler.bufferReceived(RemotingServiceImpl.java:669) [hornetq-server-2.4.7.Final.jar:na]
at org.hornetq.core.remoting.impl.invm.InVMConnection$1.run(InVMConnection.java:166) [hornetq-server-2.4.7.Final.jar:na]
at org.hornetq.utils.OrderedExecutorFactory$OrderedExecutor$1.run(OrderedExecutorFactory.java:104) [hornetq-core-client-2.4.7.Final.jar:na]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_171]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_171]
at java.lang.Thread.run(Thread.java:748) [na:1.8.0_171]
All of these seem to appear randomly and not related to any hypervisor tasks specifically.
We found the issue and were able to resolve it.
Looks like we were affected by Bug #21110: virt-who cant talk to foreman anymore - Katello - Foreman.
The proposed workaround in Comment 32 fixed the issue.
