azure-spring-boot icon indicating copy to clipboard operation
azure-spring-boot copied to clipboard

[BUG] Prevent "The MessageProducer was closed due to an unrecoverable error"

Open carcaryn opened this issue 5 years ago • 52 comments

Hi everyone, I've this problem with Azure Jms Spring Library. After few times of innactivity, when I try to send a message to a topic, the library throw me this exception: "The MessageProducer was closed due to an unrecoverable error; nested exception is javax.jms.IllegalStateException: The MessageProducer was closed due to an unrecoverable error".

How can I prevent this problem? Is a configuration problem? I know that azure close connection after ten minutes of inactivity, but how can I resolve the MessageProducer error in my project? Thanx

Project azure-servicebus-jms-spring-boot-starter Version 2.1.7

carcaryn avatar Jan 20 '20 12:01 carcaryn

Thanks for reporting this. Could you please provide more information, such as how to reproduce this issue?

saragluna avatar Jan 21 '20 02:01 saragluna

Ok. You should configure a simple topic in Azure. Then create a Spring Boot app with Web and Azure Spring Jms starter. Configure you connection string with read and write permission on topic. Create a simple web controller and inject JmsTemplate on it. Create a method and on it, send a text message to the topic previously created. Expose this method as web method. Start the application, call the url associated on web method and if you setup the project corrrectly, you should send a message to the topic. Leave the web app started and try to remake the test after 15 minutes. The method "jmstemplate.send" should fail with exception "javax.jms.IllegalStateException: The MessageProducer was closed due to an unrecoverable error". How can I prevent this?

carcaryn avatar Jan 21 '20 09:01 carcaryn

@carcaryn you can use this property to set the idle timeout spring.jms.servicebus.idle-timeout=[idle-timeout]

superrdean avatar Feb 05 '20 13:02 superrdean

@neuqlz @saragluna It's not that idle-timeout is not doing what it's supposed to - the connection should be dropped if the inactivity exceeds a certain threshold. (AFAIR there's the hard limit of 10min on ASB side I belive)

The BIG problem here is that jmsTemplate can no longer be used, which kind of breaks the idea of autoconfiguration - minimal setup that just works.

Let's put it like this - if it falls on me to implement reconnect logic, I'll have to override the beans created by this jms starter - then it turns out I don't need said starter at all...

So in fact, in my project, instead of using those neat @JmsListener and jmsTemplate features (all done with Apache Qpid), we had to revert to using com.microsoft.azure.servicebus.QueueClient - which for the very same scenario, handles idle disconnect/reconnect under the hood.

EDIT: attached log excerpt - the root cause says The link 'G31:502067:qpid-jms:sender:ID:343b54d6-d37d-459f-8fb8-3c9315c32258:1:3:1:XXX' is force detached. Code: publisher(link25625). Details: AmqpMessagePublisher.IdleTimerExpired: Idle timeout: 00:10:00. [condition = amqp:link:detach-forced] jms-producer-idle-disconnect.log

zoladkow avatar Feb 27 '20 11:02 zoladkow

@zoladkow, your proposal is very reasonable, now the ability of JMS starter is very single, just support set fixed idle-timeout for the connection. And don't support the other fancy features, like reconnect after revoke, never-expired and so on. It's indeed a problem that decreases the usability of the JMS starter. We will discuss it and consider adding these related features to the starter. Now you can set the idle-timeout very long to workaround. And also PR is very welcome. Please stay tuned.

superrdean avatar Mar 06 '20 08:03 superrdean

@neuqlz

Is there any update on this issue. I have tried to setup idle timeout very high but still facing same issue. Could you please provide some inputs to handle this issue.

monu18oct avatar Jun 13 '20 17:06 monu18oct

@neuqlz

Hi, we faced with the same issue. Any updates regarding JMS starter?

DzianisShaplyka1984 avatar Jun 16 '20 13:06 DzianisShaplyka1984

Sorry, currently we don't have a concrete plan about this feature mentioned above.

yiliuTo avatar Jun 19 '20 04:06 yiliuTo

Is there a workaround for this issue?

duydao avatar Jun 26 '20 11:06 duydao

I disabled cache producers like this

CachingConnectionFactory connectionFactory = (CachingConnectionFactory) jmsTemplate.getConnectionFactory();

connectionFactory.setCacheProducers(false);

Work for me.

In future i plan to implement reconect functionality.

DzianisShaplyka1984 avatar Jun 28 '20 18:06 DzianisShaplyka1984

I tried disabling the JMS Cache Producer. It is also not working for me. In my work scenario I have 50 messages to send, but when I disable this cache producer only 2 messages sent and job remaining idle without any error or anything. I would need some one step up and check this ASAP.

yuhaii avatar Oct 08 '20 23:10 yuhaii

I am facing the same issue. After timeout I am getting the same exception and can't reuse the JmsTemplate.

Arnab09 avatar Jan 07 '21 10:01 Arnab09

Hi @Arnab09 , sorry for the late response. Due to that we don't have plans to enhance the reconnect function recently, so the current workaround for this issue is to disable cache of MessageProducer like @DzianisShaplyka1984 said.

yiliuTo avatar Jan 26 '21 07:01 yiliuTo

Also want to mention that this can also occur when you modify a setting within Azure Service Bus.

For example, I can reproduce it by doing the following scenarios for Topics:

Scenario 1

  • Start App
  • Send Message
  • Change Topic Setting Max Size from 1GB to 2GB
  • Send Message
  • Receive Error

Scenario 2

  • Start App
  • Send Message
  • Change a one Subscription setting (E.g. TTL 14 -> 15 Days)
  • Send Message
  • Receive Error

So while it isn't even the timeout but rather changes on the Azure side that can also cause the problem which is arguably worse...

welsh avatar Feb 08 '21 19:02 welsh

@welsh thanks for your reporting, we will look into this.

yiliuTo avatar Feb 22 '21 06:02 yiliuTo

I disabled cache producers like this

CachingConnectionFactory connectionFactory = (CachingConnectionFactory) jmsTemplate.getConnectionFactory();

connectionFactory.setCacheProducers(false);

Work for me.

In future i plan to implement reconect functionality.

Stuck with the same issue.. :( I am not able to use workaround @DzianisShaplyka1984 provided, as I am using spring-cloud-starter-sleuth in my project and therefore the ConnectionFactory uses implementation of Sleuth. i.e. org.springframework.cloud.sleuth.brave.instrument.messaging.LazyConnectionFactory. So (CachingConnectionFactory) jmsTemplate.getConnectionFactory() gives error.

To solve this I created ConnectionFactory bean from scratch using the properties.

@Bean
public ConnectionFactory jmsConnectionFactory(AzureServiceBusJMSProperties busJMSProperties){
	final String connectionString = busJMSProperties.getConnectionString();
	final String clientId = busJMSProperties.getTopicClientId();
	final int idleTimeout = busJMSProperties.getIdleTimeout();

	final ServiceBusKey serviceBusKey = ConnectionStringResolver.getServiceBusKey(connectionString);

	final String remoteUri = String.format("amqps://%s?amqp.idleTimeout=%d&amqp.traceFrames=true",
			serviceBusKey.getHost(), idleTimeout);

	final JmsConnectionFactory jmsConnectionFactory =
			new JmsConnectionFactory(
					serviceBusKey.getSharedAccessKeyName(),
					serviceBusKey.getSharedAccessKey(),
					remoteUri
			);
	jmsConnectionFactory.setClientID(clientId);

	CachingConnectionFactory cachingConnectionFactory =
			new CachingConnectionFactory(jmsConnectionFactory);
            // set cache producers to FALSE here
	cachingConnectionFactory.setCacheProducers(false);

	return cachingConnectionFactory;
}

Is there any better way of doing this or any workaround to set cache producers FALSE..?

ismailmmd avatar Mar 10 '21 05:03 ismailmmd

Hi I had/have the same issue with Sleuth. I resolved it with BeanPostProcessor which runs before Sleuth/Brave TracingConnectionFactoryBeanPostProcessor . See:

/**
 * We need to disable cache producers because Azure Service Bus kills connections
 * after some time. Sleuth uses BeanPostProcessor for wrapping a JMS
 * ConnectionFactory and then there is no way how to get the original
 * ConnectionFactory. This BeanPostProcessor with higher precedence disables
 * cache producers before Sleuth wraps the ConnectionFactory.
 */
public class AzureServiceBusBraveBeanPostProcessor implements BeanPostProcessor, Ordered {

  @Override
  public Object postProcessAfterInitialization(Object bean, String beanName) throws BeansException {
    if (bean instanceof CachingConnectionFactory) {
      CachingConnectionFactory cachingConnectionFactory = (CachingConnectionFactory) bean;
      cachingConnectionFactory.setCacheProducers(false);
    }
    return bean;
  }

  /**
   * It has to run before Sleuth/Brave TracingConnectionFactoryBeanPostProcessor
   *
   * @return
   */
  @Override
  public int getOrder() {
    return 0;
  }

}

Do you plan fix this issue? It is open for more than one year. This is the real blocker (you have to mention this behaviour at least in your documentation) and disabling caching is not optimal. Is this real working supported library or only PoC? Because I feel it is only PoC. You should mention that this library is not production ready because it is not.

Saljack avatar Mar 10 '21 07:03 Saljack

Given that CachingConnectionFactory of Spring Jms doesn't expose the cached session, producer and consumer for us to remove when items are closed, thus we removed the usage of cache. Also we could choose to transfer the selection of cache to customers by providing configurable properties, however, we think it could make the problem more confusing. Therefore we currently choose to remove usage of cache feature directly. cc @stliu

yiliuTo avatar Mar 15 '21 01:03 yiliuTo

Hi,

This is a conclusion for this issue. We will:

  1. Give a short description of the issue background.
  2. Give a short cause analysis.
  3. Show related artifact versions and the problems users may encounter.
  4. Give a workaround of recommendation for the new 4.x.x version starter and describe how it mitigates the issue.
  5. Give a workaround if using old artifacts.

About issue background

When using the Jms starter for Service Bus, we want to use the cached feature of the JmsProducer in JmsTemplate, which is provided by the Spring-Jms framework. But when a CachingConnectionFactory is used, no matter via the auto-configuration the starter provides or created by users directly, applications will run into the issue that JmsTemplate fails to send messages after ten minutes of inactivity, which is because that Azure Service Bus closes connection from the server-side.

Cause analysis

When using CachingConnectionFactory for the JmsTemplate (user-defined or auto-configured from the starter), the internal link is force detached after 10 minutes of inactivity but the upper lever producer is cached. See AMQP errors: Link is closed for more details.

CachingConnectionFactory is a container and management utility for JMS sessions, producers, and consumers. It is unaware of the internal Service Bus connection status. When the underlying link is closed, the JMS session is dead but is not handled automatically.

So the JmsTemplate will not be available using the cached JmsProducer, which is working using the underlying link within the dead session.

Related artifact versions

artifact maven url

Starter & Version What does the auto-configuration provide Problems users may encounter
2.1.7 ~ 3.2.0 CachingConnectionFactory JmsTemplate will be not available when JmsProducer is closed.
3.3.0 ~ 3.14.0 raw JmsConnectionFactory Low efficiency for creating JmsProducer each time sending messages.
4.x.x CachingConnectionFactory, PooledConnectionFactory For default config, CachingConnectionFactory is used, JmsTemplate will be not available when JmsProducer is closed.

Workarounds

Workaround-1: Upgrade to new 4.x.x starter(This is the Recommended)

Version 4.x.x provides the pooled feature for ConnectionFactory. Enabling the pooled connection factory will mitigate this issue while we can take advantage of the caching resource feature, which can boost operation efficiency. This can work because the PooledConnectionFactory will clear the underlying connection before the session is dead for inactivity.

  1. Dependency: include spring-cloud-azure-starter-servicebus-jms:4.x.x. See maven repo

Use the following snippet:

<dependency>
  <groupId>com.azure.spring</groupId>
  <artifactId>spring-cloud-azure-dependencies</artifactId>
  <version>${version.spring.cloud.azure}</version><!-- replace it with 4.x.x version above mentioned -->
  <type>pom</type>
  <scope>import</scope>
</dependency>

<dependency>
  <groupId>com.azure.spring</groupId>
  <artifactId>spring-cloud-azure-starter-servicebus-jms</artifactId>
</dependency>
  1. Configuration. Enable the pool option.

Only this pool enabled can avoid the issue encountered while sending messages. This is important.

Use the following snippet:

spring:
  jms:
    servicebus:
      connection-string: ${SERVICEBUS_NAMESPACE_CONNECTION_STRING}
      idle-timeout: 1800000
      pricing-tier: ${PRICING_TIER}
      pool:
        enabled: true
        max-connections: ${MAX_CONNECTIONS}

Workaround-2: Use the old artifact

As the CacheConnectionFactory does not work normally, we can do the following workaround in the code to mitigate this issue by resetting the connection on condition. This will clear the JMS sessions in the context and JmsTemplate will create a new session and producer for the next sending operation.

Use the following snippet:

try {
    jmsTemplate.convertAndSend("QUEUE_NAME", "messagexxx");
} catch (Exception exception) {
    if(exception instanceof IllegalStateException && exception.getMessage().contains("MessageProducer was closed")) {
        ((CachingConnectionFactory) jmsTemplate.getConnectionFactory()).resetConnection();
        jmsTemplate.convertAndSend("QUEUE_NAME", "messagexxx");
    }
}

jialigit avatar May 17 '22 08:05 jialigit

close the summary presented. If more question, reopen this issue then.

jialigit avatar May 23 '22 03:05 jialigit

Hi, using spring-cloud-azure-starter-servicebus-jms:4.0.0 or a later version 4.3.0 with the pool:enabled: true setting makes the factory class org.messaginghub.pooled.jms.JmsPoolConnectionFactory. Can you confirm if the solution above is referring to the activemq version of PooledConnectionFactory? According to this issue getting the JmsPoolConnectionFactory is the expected behaviour.

Using JmsPoolConnectionFactory we still appear to get the issue of closed sessions. With settings spring.jms.servicebus.pool.idle-timeout=30000 and spring.jms.servicebus.pool.time-between-expiration-check=60000 in a debug session I can see that a connection is eligible to be marked expired except there is still a reference count of 1. This is with our app just started and no JMS message activity. So I don't think the connections are getting removed before we hit the issue above.

What I am seeing looks similar to this bug that was raised (albeit a long time ago) onPooledConnectionFactory where decrementReferenceCount was not being called. So I would like to clarify if there is some specific config to get the eviction behaviour working with JmsPoolConnectionFactory or if it does have an issue where the connection created on startup needs closing to get the reference count to 0?

Alternatively if it applies, could you provide an example of the specific dependency and bean configuration required to get PooledConnectionFactory working on the latest version of spring-cloud-azure-starter-servicebus-jms for use with JmsListenerContainerFactory and JmsTemplate? thanks

craigblackman2 avatar Sep 22 '22 14:09 craigblackman2

So far trying to get PooledConnectionFactory working I have added the following dependencies to the project: com.azure.spring:spring-cloud-azure-autoconfigure to get the AzureServiceBusJmsProperties and org.apache.activemq:activemq-pool to get PooledConnectionFactory.

The bean declaration is:


    @Bean
    public ConnectionFactory jmsConnectionFactory(AzureServiceBusJmsProperties serviceBusJmsProperties) {
        final String connectionString = serviceBusJmsProperties.getConnectionString();
        final String clientId = serviceBusJmsProperties.getTopicClientId();
        final Duration idleTimeout = serviceBusJmsProperties.getIdleTimeout();

        final ServiceBusKey serviceBusKey = ConnectionStringResolver.getServiceBusKey(connectionString);

        final String remoteUri = String.format("amqps://%s?amqp.idleTimeout=%d&amqp.traceFrames=true",
                serviceBusKey.getHost(), idleTimeout.get(ChronoUnit.MILLIS));

        final JmsConnectionFactory jmsConnectionFactory =
                new JmsConnectionFactory(
                        serviceBusKey.getSharedAccessKeyName(),
                        serviceBusKey.getSharedAccessKey(),
                        remoteUri
                );
        jmsConnectionFactory.setClientID(clientId);

        PooledConnectionFactory pooledConnectionFactory = new PooledConnectionFactory();
        pooledConnectionFactory.setConnectionFactory(jmsConnectionFactory);
        return pooledConnectionFactory;
    }

However I cannot seem to find the correct jar to import ServiceBusKey and ConnectionStringResolver - package com.azure.spring.autoconfigure.jms it looks like these classes weren't migrated to com.azure.spring.cloud.autoconfigure.jms in the 4.x.x versions? If you can point me to the correct dependency to get these classes or another way to get the service bus key from the connection string, that would be much appreciated. Thanks.

craigblackman2 avatar Sep 23 '22 08:09 craigblackman2

So far trying to get PooledConnectionFactory working I have added the following dependencies to the project: com.azure.spring:spring-cloud-azure-autoconfigure to get the AzureServiceBusJmsProperties and org.apache.activemq:activemq-pool to get PooledConnectionFactory.

The bean declaration is:

    @Bean
    public ConnectionFactory jmsConnectionFactory(AzureServiceBusJmsProperties serviceBusJmsProperties) {
        final String connectionString = serviceBusJmsProperties.getConnectionString();
        final String clientId = serviceBusJmsProperties.getTopicClientId();
        final Duration idleTimeout = serviceBusJmsProperties.getIdleTimeout();

        final ServiceBusKey serviceBusKey = ConnectionStringResolver.getServiceBusKey(connectionString);

        final String remoteUri = String.format("amqps://%s?amqp.idleTimeout=%d&amqp.traceFrames=true",
                serviceBusKey.getHost(), idleTimeout.get(ChronoUnit.MILLIS));

        final JmsConnectionFactory jmsConnectionFactory =
                new JmsConnectionFactory(
                        serviceBusKey.getSharedAccessKeyName(),
                        serviceBusKey.getSharedAccessKey(),
                        remoteUri
                );
        jmsConnectionFactory.setClientID(clientId);

        PooledConnectionFactory pooledConnectionFactory = new PooledConnectionFactory();
        pooledConnectionFactory.setConnectionFactory(jmsConnectionFactory);
        return pooledConnectionFactory;
    }

However I cannot seem to find the correct jar to import ServiceBusKey and ConnectionStringResolver - package com.azure.spring.autoconfigure.jms it looks like these classes weren't migrated to com.azure.spring.cloud.autoconfigure.jms in the 4.x.x versions? If you can point me to the correct dependency to get these classes or another way to get the service bus key from the connection string, that would be much appreciated. Thanks.

@craigblackman2 ServiceBusKey and ConnectionStringResolver no longer exist in 4.x.x.

hui1110 avatar Sep 23 '22 09:09 hui1110

Hi, using spring-cloud-azure-starter-servicebus-jms:4.0.0 or a later version 4.3.0 with the pool:enabled: true setting makes the factory class org.messaginghub.pooled.jms.JmsPoolConnectionFactory. Can you confirm if the solution above is referring to the activemq version of PooledConnectionFactory? According to this issue getting the JmsPoolConnectionFactory is the expected behaviour.

Using JmsPoolConnectionFactory we still appear to get the issue of closed sessions. With settings spring.jms.servicebus.pool.idle-timeout=30000 and spring.jms.servicebus.pool.time-between-expiration-check=60000 in a debug session I can see that a connection is eligible to be marked expired except there is still a reference count of 1. This is with our app just started and no JMS message activity. So I don't think the connections are getting removed before we hit the issue above.

What I am seeing looks similar to this bug that was raised (albeit a long time ago) onPooledConnectionFactory where decrementReferenceCount was not being called. So I would like to clarify if there is some specific config to get the eviction behaviour working with JmsPoolConnectionFactory or if it does have an issue where the connection created on startup needs closing to get the reference count to 0?

Alternatively if it applies, could you provide an example of the specific dependency and bean configuration required to get PooledConnectionFactory working on the latest version of spring-cloud-azure-starter-servicebus-jms for use with JmsListenerContainerFactory and JmsTemplate? thanks

I will investigate this.

hui1110 avatar Sep 23 '22 09:09 hui1110

So far trying to get PooledConnectionFactory working I have added the following dependencies to the project: com.azure.spring:spring-cloud-azure-autoconfigure to get the AzureServiceBusJmsProperties and org.apache.activemq:activemq-pool to get PooledConnectionFactory. The bean declaration is:

    @Bean
    public ConnectionFactory jmsConnectionFactory(AzureServiceBusJmsProperties serviceBusJmsProperties) {
        final String connectionString = serviceBusJmsProperties.getConnectionString();
        final String clientId = serviceBusJmsProperties.getTopicClientId();
        final Duration idleTimeout = serviceBusJmsProperties.getIdleTimeout();

        final ServiceBusKey serviceBusKey = ConnectionStringResolver.getServiceBusKey(connectionString);

        final String remoteUri = String.format("amqps://%s?amqp.idleTimeout=%d&amqp.traceFrames=true",
                serviceBusKey.getHost(), idleTimeout.get(ChronoUnit.MILLIS));

        final JmsConnectionFactory jmsConnectionFactory =
                new JmsConnectionFactory(
                        serviceBusKey.getSharedAccessKeyName(),
                        serviceBusKey.getSharedAccessKey(),
                        remoteUri
                );
        jmsConnectionFactory.setClientID(clientId);

        PooledConnectionFactory pooledConnectionFactory = new PooledConnectionFactory();
        pooledConnectionFactory.setConnectionFactory(jmsConnectionFactory);
        return pooledConnectionFactory;
    }

However I cannot seem to find the correct jar to import ServiceBusKey and ConnectionStringResolver - package com.azure.spring.autoconfigure.jms it looks like these classes weren't migrated to com.azure.spring.cloud.autoconfigure.jms in the 4.x.x versions? If you can point me to the correct dependency to get these classes or another way to get the service bus key from the connection string, that would be much appreciated. Thanks.

@craigblackman2 ServiceBusKey and ConnectionStringResolver no longer exist in 4.x.x.

Thanks, I did see a reply about using an older version but assume that was not really viable. What is the latest way of obtaining the service bus key then - it looks like class ServiceBusConnectionString - would be good to clarify?

craigblackman2 avatar Sep 23 '22 10:09 craigblackman2

@craigblackman2 Can you tell us about your usage scenarios, or have error logs? In this PR we have provided serviceBusJmsConnectionFactoryFactory. You can refer to ConnectionStringResolver and ServiceBusKey to try.

hui1110 avatar Sep 26 '22 08:09 hui1110

@hui1110 Our usage scenario is receiving a JMS message via a method annotated with @JmsListenerto trigger a Spring Batch Job, once that Job has finished, another job will be started automatically by the app sending a message via JmsTemplate. We have seen lots of errors stating closed JMS session and MessageProducer is closed so the jobs are not executed. This is mostly where the jobs run longer than 10 minutes.

We originally tried the approach of re-sending a message when IllegalStateException occurs as suggested above but this did not reliably solve. So we have tried the solution above using pool enabled but we are not seeing connections being evicted.

I expect to see o.m.pooled.jms.JmsPoolConnectionFactory: Connection has expired or was closed: ConnectionPool[null] and will be destroyed in the logs every time a connection is evicted. As mentioned, once the app starts up we do not see these logs. In a debug session I can see that the eviction check is running but there is still one reference count so it does not get evicted. We are not explicitly opening and closing connections ourselves and are relying upon the behaviour of the connection factory as is.

As an aside I attempted to get PooledConnectionFactory working but received class cast exceptions when a connection was trying to be initiated: Error while attempting to add new Connection to the pool; nested exception is java.lang.ClassCastException: class org.apache.qpid.jms.JmsConnection cannot be cast to class org.apache.activemq.ActiveMQConnection (org.apache.qpid.jms.JmsConnection

craigblackman2 avatar Sep 26 '22 13:09 craigblackman2

@hui1110 Yonghui Ye (CSI Interfusion Inc) Vendor Our usage scenario is receiving a JMS message via a method annotated with @JmsListenerto trigger a Spring Batch Job, once that Job has finished, another job will be started automatically by the app sending a message via JmsTemplate. We have seen lots of errors stating closed JMS session and MessageProducer is closed so the jobs are not executed. This is mostly where the jobs run longer than 10 minutes.

We originally tried the approach of re-sending a message when IllegalStateException occurs as suggested above but this did not reliably solve. So we have tried the solution above using pool enabled but we are not seeing connections being evicted.

I expect to see o.m.pooled.jms.JmsPoolConnectionFactory: Connection has expired or was closed: ConnectionPool[null] and will be destroyed in the logs every time a connection is evicted. As mentioned, once the app starts up we do not see these logs. In a debug session I can see that the eviction check is running but there is still one reference count so it does not get evicted. We are not explicitly opening and closing connections ourselves and are relying upon the behaviour of the connection factory as is.

As an aside I attempted to get PooledConnectionFactory working but received class cast exceptions when a connection was trying to be initiated: Error while attempting to add new Connection to the pool; nested exception is java.lang.ClassCastException: class org.apache.qpid.jms.JmsConnection cannot be cast to class org.apache.activemq.ActiveMQConnection (org.apache.qpid.jms.JmsConnection

I'll start investigating this tomorrow and will reply asap.

hui1110 avatar Sep 27 '22 10:09 hui1110

@hui1110 Best I don't share full logs here but do have some further that could be useful, is it possible via a direct message or azure support ticket? Anyway a cut down version of events:

15:49:56.113 Started Application in 42.669 seconds (JVM running for 43.438)
15:51:35.774 o.s.j.connection.JmsTransactionManager   : Participating in existing transaction` (JMS message received)
Job still running - loading csv files into DB but no other JMS related activity/Various job processing logs...

We then saw a link tracker error, but connection recovery was not attempted:

16:06:35.795  INFO 63476 --- [-a689e84fbba2:2] o.a.qpid.jms.JmsLocalTransactionContext  : Rollback failed for transaction: TX:ID:8d12d1b0-a6b8-4d2e-b2b9-a689e84fbba2:2:86
16:06:35.799  WARN 63476 --- [-a689e84fbba2:2] org.apache.qpid.jms.JmsSession           : Rollback of active transaction failed due to error:

org.apache.qpid.jms.exceptions.JmsConnectionFailedException: The JMS connection has failed: The Provider has failed
	at org.apache.qpid.jms.provider.exceptions.ProviderFailedException.toJMSException(ProviderFailedException.java:35)
	at org.apache.qpid.jms.provider.exceptions.ProviderFailedException.toJMSException(ProviderFailedException.java:21)
	at org.apache.qpid.jms.exceptions.JmsExceptionSupport.create(JmsExceptionSupport.java:80)
	at org.apache.qpid.jms.exceptions.JmsExceptionSupport.create(JmsExceptionSupport.java:112)
	at org.apache.qpid.jms.JmsConnection.rollback(JmsConnection.java:873)
	at org.apache.qpid.jms.JmsLocalTransactionContext.doRollback(JmsLocalTransactionContext.java:268)
	at org.apache.qpid.jms.JmsLocalTransactionContext.shutdown(JmsLocalTransactionContext.java:331)
	at org.apache.qpid.jms.JmsSession.shutdown(JmsSession.java:353)
	at org.apache.qpid.jms.JmsSession.sessionClosed(JmsSession.java:406)
	at org.apache.qpid.jms.JmsConnection$6.run(JmsConnection.java:1475)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: org.apache.qpid.jms.provider.exceptions.ProviderFailedException: The Provider has failed
	at org.apache.qpid.jms.provider.amqp.AmqpProvider.checkClosedOrFailed(AmqpProvider.java:1557)
	at org.apache.qpid.jms.provider.amqp.AmqpProvider.rollback(AmqpProvider.java:744)
	at org.apache.qpid.jms.JmsConnection.rollback(JmsConnection.java:867)
	... 8 common frames omitted
Caused by: org.apache.qpid.jms.provider.exceptions.ProviderConnectionRemotelyClosedException: The connection was inactive for more than the allowed 300000 milliseconds and is closed by container 'LinkTracker'. TrackingId:fa20cd9feb2340de981a72bbb0143606_G73, SystemTracker:gateway7, Timestamp:2022-09-27T15:06:38 [condition = amqp:connection:forced]
	at org.apache.qpid.jms.provider.amqp.AmqpSupport.convertToConnectionClosedException(AmqpSupport.java:128)
	at org.apache.qpid.jms.provider.amqp.AmqpConnection.processRemoteClose(AmqpConnection.java:148)
	at org.apache.qpid.jms.provider.amqp.AmqpProvider.processUpdates(AmqpProvider.java:961)
	at org.apache.qpid.jms.provider.amqp.AmqpProvider.onData(AmqpProvider.java:871)
	at org.apache.qpid.jms.transports.netty.NettyTcpTransport$NettyTcpTransportHandler.channelRead0(NettyTcpTransport.java:563)
	at org.apache.qpid.jms.transports.netty.NettyTcpTransport$NettyTcpTransportHandler.channelRead0(NettyTcpTransport.java:556)
	at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:99)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1373)
	at io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1236)
	at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1285)
	at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:510)
	at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:449)
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:279)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:722)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:658)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:584)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:496)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	... 1 common frames omitted

16:06:51.271 TRACE 63476 --- [ns-pool-evictor] o.m.pooled.jms.JmsPoolConnectionFactory  : Connection has expired or was closed: ConnectionPool[null] and will be destroyed
16:06:51.271 TRACE 63476 --- [ns-pool-evictor] o.m.pooled.jms.JmsPoolConnectionFactory  : Destroying connection: ConnectionPool[null]

More job related logs / job completes but we are not able to send the next JMS message:

16:24:41.863 ERROR Encountered an error sending JMS message
org.springframework.jms.IllegalStateException: The Session was closed due to an unrecoverable error.; nested exception is javax.jms.IllegalStateException: The Session was closed due to an unrecoverable error.
	at org.springframework.jms.support.JmsUtils.convertJmsAccessException(JmsUtils.java:274)
	at org.springframework.jms.support.JmsAccessor.convertJmsAccessException(JmsAccessor.java:185)
	at org.springframework.jms.core.JmsTemplate.execute(JmsTemplate.java:507)
	at org.springframework.jms.core.JmsTemplate.send(JmsTemplate.java:584)
	at org.springframework.jms.core.JmsTemplate.convertAndSend(JmsTemplate.java:661)
	Caused by: javax.jms.IllegalStateException: The Session was closed due to an unrecoverable error.
	at org.apache.qpid.jms.JmsSession.checkClosed(JmsSession.java:1103)
	at org.apache.qpid.jms.JmsSession.createQueue(JmsSession.java:751)
	at org.messaginghub.pooled.jms.JmsPoolSession.createQueue(JmsPoolSession.java:192)``

So we don't see the connection being evicted/renewed before and I think it should be run every 60 secs with our config.

craigblackman2 avatar Sep 28 '22 10:09 craigblackman2

@craigblackman2 Can you provide a sample that reproduces the problem, I run it locally for about 50 minutes and send and receive messages normally. Here is the log:

2022-09-28 17:52:37.431  INFO 16892 --- [nio-8090-exec-1] com.hui.jms.TopicSendController          : Sending message
2022-09-28 17:52:37.918  INFO 16892 --- [ntContainer#0-1] com.hui.jms.TopicReceiveService          : Received message from topic: hello
2022-09-28 18:08:34.836  INFO 16892 --- [nio-8090-exec-2] com.hui.jms.TopicSendController          : Sending message
2022-09-28 18:08:35.169  INFO 16892 --- [ntContainer#0-1] com.hui.jms.TopicReceiveService          : Received message from topic: hello
2022-09-28 18:37:48.096  INFO 16892 --- [nio-8090-exec-4] com.hui.jms.TopicSendController          : Sending message
2022-09-28 18:37:48.414  INFO 16892 --- [ntContainer#0-1] com.hui.jms.TopicReceiveService          : Received message from topic: hello
2022-09-28 18:46:59.209  INFO 16892 --- [nio-8090-exec-6] com.hui.jms.TopicSendController          : Sending message
2022-09-28 18:46:59.541  INFO 16892 --- [ntContainer#0-1] com.hui.jms.TopicReceiveService          : Received message from topic: hello

I use the code from this sample: servicebus-jms-topic

application.yaml

spring:
  jms:
    servicebus:
      connection-string: <connection-string>;EntityPath=tpc001
      idle-timeout: 20000
      pricing-tier: Standard
      topic-client-id: 
      pool:
        enabled: true
        max-connections: 1

hui1110 avatar Sep 28 '22 10:09 hui1110