RA health check is always UP, even if target broker is down

[vsevel]

I am using quarkus artemis 3.4.1 with the new io.quarkus.artemis.jms.ra.runtime.ConnectionFactoryHealthCheck.
I start my app with the hornetq cluster running, and check I can send and receive messages. I check that the Artemis JMS Resource Adaptor health check is UP
I shut down all hornetq nodes, and start seeing exceptions such as:

IJ000604: Throwable while attempting to get a new connection: null

jakarta.resource.ResourceException: Failed to create session factory
	at org.apache.activemq.artemis.ra.ActiveMQRAManagedConnection.setup(ActiveMQRAManagedConnection.java:725)
	at org.apache.activemq.artemis.ra.ActiveMQRAManagedConnection.<init>(ActiveMQRAManagedConnection.java:161)
	at org.apache.activemq.artemis.ra.ActiveMQRAManagedConnectionFactory.createManagedConnection(ActiveMQRAManagedConnectionFactory.java:144)
	at org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreArrayListManagedConnectionPool.createConnectionEventListener(SemaphoreArrayListManagedConnectionPool.java:1267)
	at org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreArrayListManagedConnectionPool.getConnection(SemaphoreArrayListManagedConnectionPool.java:495)
	at org.jboss.jca.core.connectionmanager.pool.AbstractPool.getTransactionNewConnection(AbstractPool.java:770)
	at org.jboss.jca.core.connectionmanager.pool.AbstractPool.getConnection(AbstractPool.java:666)
	at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.getManagedConnection(AbstractConnectionManager.java:624)
	at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.getManagedConnection(TxConnectionManagerImpl.java:440)
	at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:789)
	at org.apache.activemq.artemis.ra.ActiveMQRASessionFactoryImpl.allocateConnection(ActiveMQRASessionFactoryImpl.java:792)
	at org.apache.activemq.artemis.ra.ActiveMQRASessionFactoryImpl.createSession(ActiveMQRASessionFactoryImpl.java:482)
	at org.apache.activemq.artemis.ra.ActiveMQRASessionFactoryImpl.createSession(ActiveMQRASessionFactoryImpl.java:673)
	at org.apache.activemq.artemis.ra.ActiveMQRASessionFactoryImpl.createSession(ActiveMQRASessionFactoryImpl.java:678)
	at org.apache.activemq.artemis.ra.ActiveMQRAConnectionFactoryImpl.validateUser(ActiveMQRAConnectionFactoryImpl.java:422)
	at org.apache.activemq.artemis.ra.ActiveMQRAConnectionFactoryImpl.createContext(ActiveMQRAConnectionFactoryImpl.java:379)
	at org.apache.activemq.artemis.ra.ActiveMQRAConnectionFactoryImpl.createContext(ActiveMQRAConnectionFactoryImpl.java:369)
	at org.apache.activemq.artemis.ra.ActiveMQRAConnectionFactoryImpl.createContext(ActiveMQRAConnectionFactoryImpl.java:364)
	at com.x.quarkus.MyJMSProducer.send(MyJMSProducer.java:52)
	at com.x.quarkus.MyJMSProducer_Subclass.send$$superforward(Unknown Source)
	at com.x.quarkus.MyJMSProducer_Subclass$$function$$2.apply(Unknown Source)
	at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:73)
	at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:62)
	at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:136)
	at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:107)
	at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.doIntercept(TransactionalInterceptorRequired.java:38)
	at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.intercept(TransactionalInterceptorBase.java:61)
	at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.intercept(TransactionalInterceptorRequired.java:32)
	at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired_Bean.intercept(Unknown Source)
	at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:42)
	at io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:30)
	at io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:27)
	at com.x.quarkus.MyJMSProducer_Subclass.send(Unknown Source)
	at com.x.quarkus.MyJMSProducer.produceOneMessage(MyJMSProducer.java:45)
	at com.x.quarkus.MyJMSProducer_Subclass.produceOneMessage$$superforward(Unknown Source)
	at com.x.quarkus.MyJMSProducer_Subclass$$function$$1.apply(Unknown Source)
	at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:73)
	at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:62)
	at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:42)
	at io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:30)
	at io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:27)
	at com.x.quarkus.MyJMSProducer_Subclass.produceOneMessage(Unknown Source)
	at com.x.quarkus.MyJMSProducer_ClientProxy.produceOneMessage(Unknown Source)
	at com.x.quarkus.MyJMSProducer_ScheduledInvoker_produceOneMessage_32bc737e9e482a38cc2b6a3ccc5169371526db3c.invokeBean(Unknown Source)
	at io.quarkus.scheduler.common.runtime.DefaultInvoker.invoke(DefaultInvoker.java:24)
	at io.quarkus.scheduler.common.runtime.StatusEmitterInvoker.invoke(StatusEmitterInvoker.java:35)
	at io.quarkus.scheduler.common.runtime.SkipPredicateInvoker.invoke(SkipPredicateInvoker.java:43)
	at io.quarkus.scheduler.runtime.SimpleScheduler$ScheduledTask.doInvoke(SimpleScheduler.java:463)
	at io.quarkus.scheduler.runtime.SimpleScheduler$ScheduledTask$2.call(SimpleScheduler.java:445)
	at io.quarkus.scheduler.runtime.SimpleScheduler$ScheduledTask$2.call(SimpleScheduler.java:442)
	at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$0(ContextImpl.java:178)
	at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:279)
	at io.vertx.core.impl.ContextImpl.lambda$internalExecuteBlocking$2(ContextImpl.java:210)
	at io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:640)
	at org.jboss.threads.EnhancedQueueExecutor$Task.doRunWith(EnhancedQueueExecutor.java:2516)
	at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2495)
	at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1495)
	at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:11)
	at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:11)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:1583)
Caused by: jakarta.jms.JMSException: Failed to create session factory
	at org.apache.activemq.artemis.jms.client.ActiveMQConnectionFactory.createConnectionInternal(ActiveMQConnectionFactory.java:912)
	at org.apache.activemq.artemis.jms.client.ActiveMQConnectionFactory.createXAConnection(ActiveMQConnectionFactory.java:384)
	at org.apache.activemq.artemis.ra.ActiveMQRAManagedConnection.setup(ActiveMQRAManagedConnection.java:713)
	... 62 more
Caused by: ActiveMQNotConnectedException[errorType=NOT_CONNECTED message=AMQ219007: Cannot connect to server(s). Tried with all available servers.]
	at org.apache.activemq.artemis.core.client.impl.ServerLocatorImpl.createSessionFactory(ServerLocatorImpl.java:729)
	at org.apache.activemq.artemis.jms.client.ActiveMQConnectionFactory.createConnectionInternal(ActiveMQConnectionFactory.java:910)
	... 64 more

and yet, the readiness check is still UP:

$ curl -s localhost:9000/q/health/ready | grep -A 5 -B 5 -i artemis
{
    "status": "UP",
    "checks": [
        {
            "name": "Artemis JMS Resource Adaptor health check",
            "status": "UP",
            "data": {
                "<default>": "UP"
            }
        },

the issue is that createConnection() is always returning a connection even if no broker node is up:

closed = false
reference = null
userName = null
password = null
clientID = null
type = 0
started = false
mcf = {ActiveMQRAManagedConnectionFactory@15476} 
tsr = {NarayanaJtaProducers_ProducerMethod_transactionSynchronizationRegistry_bBrh9sABV2TvKl0YN2UrqpBUvbU_ClientProxy@15477} "io.quarkus.narayana.jta.runtime.internal.tsr.TransactionSynchronizationRegistryWrapper@47e01c97"
cm = {TxConnectionManagerImpl@15478} 
sessions = {HashSet@15479}  size = 0
tempQueues = {HashSet@15480}  size = 0
tempTopics = {HashSet@15481}  size = 0
allowLocalTransaction = false
refCounter = {ReferenceCounterUtil@15482} 
threadAwareContext = {ThreadAwareContext@15483} 

I tried using Session session = ignored.createSession() in the health check, but the call never returns (might be missing a read timeout).

expectation: the health check should always return a relevant status immediately (no blocking waiting for a response from the check).

cc @zhfeng

[zhfeng]

Thanks @vsevel - Does this still happen if there is only one backend node ? (No cluster setting)

[vsevel]

I do not know. and I do not have that particular setup available to test easily.

[zhfeng]

Is it possible to set userName and password ? It seems that it can validate user when creating ConnectionFactory. see here

[vsevel]

where? in the health check?

I was wondering if an other approach could be to check how many connections are in the pool. if greater than 0, and min connection is greater than 0 as well, this could be a minimal relevant check.
in SR reactive messaging there are different checks, depending if you configure an admin client to connect on the server.

[zhfeng]

where? in the health check?

Yeah.

I was wondering if an other approach could be to check how many connections are in the pool. if greater than 0, and min connection is greater than 0 as well, this could be a minimal relevant check.

I'm not a expert of JCA, maybe @gastaldi can answer it.

[vsevel]

Is it possible to set userName and password ? It seems that it can validate user when creating ConnectionFactory

I tried. it does attempt to create a session, which results in the call being blocked forever, if broker is down when I start the app. does not seem encouraging. if I start the broker, start the app, then kill the broker, the health check continues to report UP for a while, then blocks for 90 seconds, but still report UP??

[vsevel]

something like this for instance:

public class MyJMSHealthCheck implements HealthCheck {

    private final Set<String> connectionFactoryNames;

    private final Instance<IronJacamarContainer> containers;

    public MyJMSHealthCheck(IronJacamarBuildtimeConfig buildTimeConfigs, @Any Instance<IronJacamarContainer> containers) {
        this.connectionFactoryNames = buildTimeConfigs.resourceAdapters().keySet();
        this.containers = containers;
    }

    public HealthCheckResponse call() {

        HealthCheckResponseBuilder builder = HealthCheckResponse.named("Artemis JMS Resource Adaptor health check").up();

        for (String name : connectionFactoryNames) {
            Annotation identifier = ArtemisUtil.toIdentifier(name);
            IronJacamarContainer container = containers.select(identifier).get();
            PoolStatistics stats = container.getConnectionManager().getPool().getStatistics();
            int activeCount = stats.getActiveCount();
            String s = String.format(
                    "avail=%s active=%s created=%s idel=%s destroyed=%s in-use=%s wait=%s, blocking-failure=%s",
                    stats.getAvailableCount(), activeCount, stats.getCreatedCount(), stats.getIdleCount(),
                    stats.getDestroyedCount(), stats.getInUseCount(), stats.getWaitCount(), stats.getBlockingFailureCount());
            builder.withData(name, s);
            if (activeCount == 0) {
                builder.down();
            }
        }

        return builder.build();
    }
}

what do you think @gastaldi ?

[gastaldi]

@vsevel that's an interesting approach, but bear in mind that inbound communication doesn't use the pool (at least in Artemis, but the spec doesn't mandate that - https://issues.apache.org/jira/browse/ARTEMIS-4429), so the active count will always return zero when using only MessageListeners in your application

FYI we also publish the same metrics in https://github.com/quarkiverse/quarkus-ironjacamar/blob/main/runtime/src/main/java/io/quarkiverse/ironjacamar/runtime/metrics/IronJacamarMetricsRecorder.java

[vsevel]

bear in mind that inbound communication doesn't use the pool

ah yes right. it reminds me of a conversation.

we also publish the same metrics

yes. that is where I got my inspiration from.

the active count will always return zero when using only MessageListeners in your application

so I do not see a viable solution at this point @zhfeng . getting a connection and a session may be a valid approach but only if we can exercise it, and as long as we have a short read and connect timeout.

[zhfeng]

@vsevel can you try to add such connect-timeout-millis=3000 setting with the quarkus.ironjacamar.ra.config.connection-parameters to see if it works?

[vsevel]

I tried connection-parameters: host=x;port=x;protocols=CORE;connect-timeout-millis=10000,host=x;port=x;x=CORE;connect-timeout-millis=10000

and

    public HealthCheckResponse call() {
        HealthCheckResponseBuilder builder = HealthCheckResponse.named("Artemis JMS Resource Adaptor health check").up();
        for (String name : connectionFactoryNames) {
            Annotation identifier = ArtemisUtil.toIdentifier(name);
            try (
                    Connection conn = connectionFactories.select(identifier).get().createConnection();
                    Session session = conn.createSession()) {
                builder.withData(name, "UP");
            } catch (Exception e) {
                builder.withData(name, "DOWN").down();
            }
        }
        return builder.build();
    }

it blocked for a long time (I did not wait).

I tried:

            try (Connection conn = connectionFactories.select(identifier).get().createConnection("x", "x")) {

and it blocked for 2 mins 20 secs.

[vsevel]

bear in mind that inbound communication doesn't use the pool

@gastaldi I tried setting a min-size for the pool, but even with the following config, the active connection count stays at 0 in my app without an active producer. I was expecting a connection to be created,

...
  ironjacamar:
    ra:
      kind: artemis
      config:
        connection-parameters: host=x;port=x;protocols=CORE;connect-timeout-millis=10000,host=x;port=x;protocols=CORE;connect-timeout-millis=10000
        protocol-manager-factory: org.apache.activemq.artemis.core.protocol.hornetq.client.HornetQClientProtocolManagerFactory
        user: x
        password: x
      cm:
        pool:
          config:
            min-size: 1
            initial-size: 1
            prefill: true
            strict-min: true
...