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

[carcaryn]

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

[saragluna]

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

[carcaryn]

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?

[superrdean]

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

[zoladkow]

@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

[superrdean]

@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.

[monu18oct]

@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.

[DzianisShaplyka1984]

@neuqlz

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

[yiliuTo]

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

[duydao]

Is there a workaround for this issue?

[DzianisShaplyka1984]

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.

[yuhaii]

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.

[Arnab09]

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

[yiliuTo]

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.

[welsh]

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...

[yiliuTo]

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

[ismailmmd]

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..?

[Saljack]

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.

[yiliuTo]

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

[jialigit]

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>

2. 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]

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

[craigblackman2]

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]

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.

[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.

[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.

[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.

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?

[hui1110]

@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.

[craigblackman2]

@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

[hui1110]

@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.

[craigblackman2]

@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.

[hui1110]

@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

[craigblackman2]

@hui1110 thanks, I will look at that example although the queue version - we are using a queue not a topic on the service bus. Can I ask the significance of using spring.jms.servicebus.idle-timeout: 20000 as that is different to the value of spring.jms.servicebus.idle-timeout:1800000 provided in the solution/workaround above on 17th May?
1800000 is the default value so we removed that config from our properties completely.

I will amend our config and carry out some further tests. If the value should be 20000 or as long as it's less than 300000 for that error The connection was inactive for more than the allowed 300000 milliseconds and is closed by container 'LinkTracker'? I think the solution post needs amending to be specific about that.

[hui1110]

@craigblackman2 Referring to this sample, when the property spring.jms.servicebus.idle-timeout is removed, my application works fine. If you could provide a sample that reproduces the problem, it might speed me up to reproduce the problem and solve it.

application.yaml

spring:
  jms:
    servicebus:
      connection-string: 
      pricing-tier: Standard
      pool:
        enabled: true
        max-connections: 1

[Saljack]

@craigblackman2 I am not from Azure but we had a lot of issues with Azure Service Bus JMS (from my point of view it is only for really simple use cases). From my observation your problem is that the job is running too long and during this time its session for the received message is closed (message lock duration). Maximum time which can be used for processing a message is 5 minutes. JMS does not support renew messages. So for long running jobs is Azure Service Bus JMS useless and you have to implement some custom mechanism how to do it.

[subbaiahd]

@hui1110 Put a thread.sleep for 20 mins in your receiver ( In the sample code) . See if you can reproduce the issue

[subbaiahd]

I have long running job once i receive the message. It is not working as well

[craigblackman2]

Thanks for the input @Saljack, that is very helpful - have been looking into this for a long time. @hui1110 if I put a Thread.sleep(330000) in the sample code I see the following in the logs - we have seen many of these errors in our logs over the last few months so it's definitely part of our issue. If we cannot have a message processing time of longer than five minutes that's quite a limitation for us.

2022-09-30 17:01:31.231  WARN 24868 --- [ntContainer#0-1] o.s.j.l.DefaultMessageListenerContainer  : Execution of JMS message listener failed, and no ErrorHandler has been set.

javax.jms.TransactionRolledBackException: Transaction is not declared Reference:307364a2-2dd3-4e19-a305-9ced2b040edd, TrackingId:cbbe89b1-d1fa-4000-b34b-462e0c137419_G73, SystemTracker:gtm, Timestamp:2022-09-30T16:01:31 [condition = amqp:transaction:unknown-id]
    at org.apache.qpid.jms.provider.exceptions.ProviderTransactionRolledBackException.toJMSException(ProviderTransactionRolledBackException.java:40) ~[qpid-jms-client-0.53.0.jar:na]
    at org.apache.qpid.jms.provider.exceptions.ProviderTransactionRolledBackException.toJMSException(ProviderTransactionRolledBackException.java:26) ~[qpid-jms-client-0.53.0.jar:na]
    at org.apache.qpid.jms.exceptions.JmsExceptionSupport.create(JmsExceptionSupport.java:80) ~[qpid-jms-client-0.53.0.jar:na]
    at org.apache.qpid.jms.exceptions.JmsExceptionSupport.create(JmsExceptionSupport.java:112) ~[qpid-jms-client-0.53.0.jar:na]
    at org.apache.qpid.jms.JmsConnection.commit(JmsConnection.java:852) ~[qpid-jms-client-0.53.0.jar:na]
    at org.apache.qpid.jms.JmsLocalTransactionContext.commit(JmsLocalTransactionContext.java:186) ~[qpid-jms-client-0.53.0.jar:na]
    at org.apache.qpid.jms.JmsSession.commit(JmsSession.java:258) ~[qpid-jms-client-0.53.0.jar:na]
    at org.messaginghub.pooled.jms.JmsPoolSession.commit(JmsPoolSession.java:266) ~[pooled-jms-1.2.4.jar:na]
    at org.springframework.jms.support.JmsUtils.commitIfNecessary(JmsUtils.java:218) ~[spring-jms-5.3.21.jar:5.3.21]
    at org.springframework.jms.listener.AbstractMessageListenerContainer.commitIfNecessary(AbstractMessageListenerContainer.java:776) ~[spring-jms-5.3.21.jar:5.3.21]
    at org.springframework.jms.listener.AbstractMessageListenerContainer.doExecuteListener(AbstractMessageListenerContainer.java:680) ~[spring-jms-5.3.21.jar:5.3.21]
    at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.doReceiveAndExecute(AbstractPollingMessageListenerContainer.java:331) ~[spring-jms-5.3.21.jar:5.3.21]
    at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:270) ~[spring-jms-5.3.21.jar:5.3.21]
    at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:1237) ~[spring-jms-5.3.21.jar:5.3.21]
    at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.executeOngoingLoop(DefaultMessageListenerContainer.java:1227) ~[spring-jms-5.3.21.jar:5.3.21]
    at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:1120) ~[spring-jms-5.3.21.jar:5.3.21]
    at java.base/java.lang.Thread.run(Thread.java:829) ~[na:na]
Caused by: org.apache.qpid.jms.provider.exceptions.ProviderTransactionRolledBackException: Transaction is not declared Reference:307364a2-2dd3-4e19-a305-9ced2b040edd, TrackingId:cbbe89b1-d1fa-4000-b34b-462e0c137419_G73, SystemTracker:gtm, Timestamp:2022-09-30T16:01:31 [condition = amqp:transaction:unknown-id]
    at org.apache.qpid.jms.provider.amqp.AmqpTransactionCoordinator.processDeliveryUpdates(AmqpTransactionCoordinator.java:91) ~[qpid-jms-client-0.53.0.jar:na]
    at org.apache.qpid.jms.provider.amqp.AmqpProvider.processUpdates(AmqpProvider.java:1009) ~[qpid-jms-client-0.53.0.jar:na]
    at org.apache.qpid.jms.provider.amqp.AmqpProvider.onData(AmqpProvider.java:871) ~[qpid-jms-client-0.53.0.jar:na]
    at org.apache.qpid.jms.transports.netty.NettyTcpTransport$NettyTcpTransportHandler.channelRead0(NettyTcpTransport.java:563) ~[qpid-jms-client-0.53.0.jar:na]
    at org.apache.qpid.jms.transports.netty.NettyTcpTransport$NettyTcpTransportHandler.channelRead0(NettyTcpTransport.java:556) ~[qpid-jms-client-0.53.0.jar:na]
    at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:99) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1373) ~[netty-handler-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1236) ~[netty-handler-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1285) ~[netty-handler-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:510) ~[netty-codec-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:449) ~[netty-codec-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:279) ~[netty-codec-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:722) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:658) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:584) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:496) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) ~[netty-common-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[netty-common-4.1.78.Final.jar:4.1.78.Final]
    ... 1 common frames omitted
Caused by: org.apache.qpid.jms.provider.ProviderException: Transaction is not declared Reference:307364a2-2dd3-4e19-a305-9ced2b040edd, TrackingId:cbbe89b1-d1fa-4000-b34b-462e0c137419_G73, SystemTracker:gtm, Timestamp:2022-09-30T16:01:31 [condition = amqp:transaction:unknown-id]
    at org.apache.qpid.jms.provider.amqp.AmqpSupport.convertToNonFatalException(AmqpSupport.java:181) ~[qpid-jms-client-0.53.0.jar:na]
    at org.apache.qpid.jms.provider.amqp.AmqpTransactionCoordinator.processDeliveryUpdates(AmqpTransactionCoordinator.java:89) ~[qpid-jms-client-0.53.0.jar:na]
    ... 29 common frames omitted

[zoladkow]

@craigblackman2 Perhaps it's a misunderstanding.

The "message processing" should not be understood as the job that is started as a result of receiving a message.

Any time you see that a documentation makes a distinction between these tree steps: a.client receives a message, b.client processes the message, c.client acks/rejects the message, it's in fact still a single logical action that should be executed and finished ASAP. Even if you set the session or receive mode to CLIENT_ACKNOWLEDGE or PEEKLOCK or some such this needs to happen fast.

If your solution expects to start a job, then any result (or error) of this job should be communicated as a separate message.

If your solution expects to start and finish a job within the same transaction, then you need to find other ways to accomplish this. Also it might not be the best idea to have transactions hanging for so long.

[zoladkow]

@superrdean It's not a "fancy feature" just a valid expectation that a starter package should not contain such a trivial and unreasonable limitation like a timeout exception that is not being handled.

I mean there are workarounds, true, but those should not be required on the client code, which just has JmsTemplate instance provided by injection.

@jialigit Which brings me to your problem summary. As you clearly stated this, those are all workarounds - even the pool property in recent version. Why not fix this instead? Permanently, for all use cases?

I mean, my biggest problem is that it is a STARTER and starters are meant to be just plug&play with bare minimum config required. And having some background job sending messages with undetermined intervals is a VERY COMMON use case. Heck, pooling should not be even needed for that.

[craigblackman2]

@zoladkow thanks for the post, yes I take your point. Long running transactions are not ideal and we will likely have to look at an alternative approach.

@hui1110 I am coming to the conclusion that the connection eviction will not happen in an app where a JmsListener and JmsTemplate instance are used as the JmsListener will always have a reference to the connection so even if the connection is eligible for eviction by the idle time out thread it will not happen as referenceCount is 1.

[hui1110]

@craigblackman2 There are two points that need to be confirmed with you. After add the following configuration in yaml

spring:
  jms:
    servicebus:
      pool:
        enabled: true
        max-connections: 

1. When the job that needs to be completed after receiving the message takes very little time, such as 3 seconds, the application can work normally without the following exceptions:

The MessageProducer was closed due to an unrecoverable error; 
nested exception is javax.jms.IllegalStateException: The MessageProducer was closed due to an unrecoverable error

2. When the work that needs to be done after receiving the message takes a long time, such as 5 minutes, the application does not have the following exceptions:

The MessageProducer was closed due to an unrecoverable error; 
nested exception is javax.jms.IllegalStateException: The MessageProducer was closed due to an unrecoverable error

But when the job after receiving the message is completed, there will be the following exception:

2022-10-10 18:31:23.762  WARN 1876 --- [ntContainer#0-6] o.s.j.l.DefaultMessageListenerContainer  : Execution of JMS message listener failed, and no ErrorHandler has been set.

javax.jms.TransactionRolledBackException: Transaction is not declared Reference:47811c6a-829a-406c-bbc0-e63cffe26c65, TrackingId:869403c6-4846-40b9-bb4c-c12fb5ecc868_G3, SystemTracker:gtm, Timestamp:2022-10-10T10:31:24 [condition = amqp:transaction:unknown-id]
    at org.apache.qpid.jms.provider.exceptions.ProviderTransactionRolledBackException.toJMSException(ProviderTransactionRolledBackException.java:40) ~[qpid-jms-client-0.53.0.jar:na]
    at org.apache.qpid.jms.provider.exceptions.ProviderTransactionRolledBackException.toJMSException(ProviderTransactionRolledBackException.java:26) ~[qpid-jms-client-0.53.0.jar:na]
    at org.apache.qpid.jms.exceptions.JmsExceptionSupport.create(JmsExceptionSupport.java:80) ~[qpid-jms-client-0.53.0.jar:na]
    at org.apache.qpid.jms.exceptions.JmsExceptionSupport.create(JmsExceptionSupport.java:112) ~[qpid-jms-client-0.53.0.jar:na]
    at org.apache.qpid.jms.JmsConnection.commit(JmsConnection.java:852) ~[qpid-jms-client-0.53.0.jar:na]
    at org.apache.qpid.jms.JmsLocalTransactionContext.commit(JmsLocalTransactionContext.java:186) ~[qpid-jms-client-0.53.0.jar:na]
    at org.apache.qpid.jms.JmsSession.commit(JmsSession.java:258) ~[qpid-jms-client-0.53.0.jar:na]
    at org.messaginghub.pooled.jms.JmsPoolSession.commit(JmsPoolSession.java:266) ~[pooled-jms-1.2.4.jar:na]
    at org.springframework.jms.support.JmsUtils.commitIfNecessary(JmsUtils.java:218) ~[spring-jms-5.3.21.jar:5.3.21]
    at org.springframework.jms.listener.AbstractMessageListenerContainer.commitIfNecessary(AbstractMessageListenerContainer.java:776) ~[spring-jms-5.3.21.jar:5.3.21]
    at org.springframework.jms.listener.AbstractMessageListenerContainer.doExecuteListener(AbstractMessageListenerContainer.java:680) ~[spring-jms-5.3.21.jar:5.3.21]
    at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.doReceiveAndExecute(AbstractPollingMessageListenerContainer.java:331) ~[spring-jms-5.3.21.jar:5.3.21]
    at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:270) ~[spring-jms-5.3.21.jar:5.3.21]
    at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:1237) ~[spring-jms-5.3.21.jar:5.3.21]
    at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.executeOngoingLoop(DefaultMessageListenerContainer.java:1227) ~[spring-jms-5.3.21.jar:5.3.21]
    at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:1120) ~[spring-jms-5.3.21.jar:5.3.21]
    at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]
Caused by: org.apache.qpid.jms.provider.exceptions.ProviderTransactionRolledBackException: Transaction is not declared Reference:47811c6a-829a-406c-bbc0-e63cffe26c65, TrackingId:869403c6-4846-40b9-bb4c-c12fb5ecc868_G3, SystemTracker:gtm, Timestamp:2022-10-10T10:31:24 [condition = amqp:transaction:unknown-id]
    at org.apache.qpid.jms.provider.amqp.AmqpTransactionCoordinator.processDeliveryUpdates(AmqpTransactionCoordinator.java:91) ~[qpid-jms-client-0.53.0.jar:na]
    at org.apache.qpid.jms.provider.amqp.AmqpProvider.processUpdates(AmqpProvider.java:1009) ~[qpid-jms-client-0.53.0.jar:na]
    at org.apache.qpid.jms.provider.amqp.AmqpProvider.onData(AmqpProvider.java:871) ~[qpid-jms-client-0.53.0.jar:na]
    at org.apache.qpid.jms.transports.netty.NettyTcpTransport$NettyTcpTransportHandler.channelRead0(NettyTcpTransport.java:563) ~[qpid-jms-client-0.53.0.jar:na]
    at org.apache.qpid.jms.transports.netty.NettyTcpTransport$NettyTcpTransportHandler.channelRead0(NettyTcpTransport.java:556) ~[qpid-jms-client-0.53.0.jar:na]
    at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:99) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1373) ~[netty-handler-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1236) ~[netty-handler-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1285) ~[netty-handler-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:510) ~[netty-codec-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:449) ~[netty-codec-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:279) ~[netty-codec-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:722) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:658) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:584) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:496) ~[netty-transport-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) ~[netty-common-4.1.78.Final.jar:4.1.78.Final]
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[netty-common-4.1.78.Final.jar:4.1.78.Final]
    ... 1 common frames omitted
Caused by: org.apache.qpid.jms.provider.ProviderException: Transaction is not declared Reference:47811c6a-829a-406c-bbc0-e63cffe26c65, TrackingId:869403c6-4846-40b9-bb4c-c12fb5ecc868_G3, SystemTracker:gtm, Timestamp:2022-10-10T10:31:24 [condition = amqp:transaction:unknown-id]
    at org.apache.qpid.jms.provider.amqp.AmqpSupport.convertToNonFatalException(AmqpSupport.java:181) ~[qpid-jms-client-0.53.0.jar:na]
    at org.apache.qpid.jms.provider.amqp.AmqpTransactionCoordinator.processDeliveryUpdates(AmqpTransactionCoordinator.java:89) ~[qpid-jms-client-0.53.0.jar:na]
    ... 29 common frames omitted
2022-10-10 18:31:29.288  WARN 1876 --- [ntContainer#0-6] o.s.j.l.DefaultMessageListenerContainer  : Setup of JMS message listener invoker failed for destination 'tpc001' - trying to recover. Cause: Transaction is not declared Reference:47811c6a-829a-406c-bbc0-e63cffe26c65, TrackingId:869403c6-4846-40b9-bb4c-c12fb5ecc868_G3, SystemTracker:gtm, Timestamp:2022-10-10T10:31:24 [condition = amqp:transaction:unknown-id]
2022-10-10 18:36:59.817  INFO 1876 --- [ntContainer#0-7] com.hui.jms.TopicReceiveService          : Received message from topic: hello
2022-10-10 18:37:00.064  INFO 1876 --- [ntContainer#0-7] o.a.qpid.jms.JmsLocalTransactionContext  : Commit failed for transaction: TX:ID:99647ace-de58-4bb3-9bbf-f471594abd18:1:13

[hui1110]

@craigblackman2 Can you help confirm the above two points?

[craigblackman2]

@hui1110 sorry for the delay. Point 1 - yes this is the case.

Point 2 - yes to an extent - it does not have MessageProducer errors if a job is around 5 minutes but we still see other session closed errors as in the logs shared above if a job is 10 minutes or more. We will then see the Transaction is not declared Reference error.

If a job lasts between 5 and 10 minutes, the sending succeeds but the JMS listener fails so the message for the second job is lost.

[chenrujun]

@hui1110

Could you please update the status of this issue?

[hui1110]

This issue is for tracking the exception: The MessageProducer was closed due to an unrecoverable error, which has been fixed. Currently investigating the referencecount refresh issue.

[chenrujun]

which has been fixed.

Can we close it now?

Currently investigating the referencecount refresh issue.

How about creating a new issue?

[Saljack]

Sorry, I do not want to be a prude but how is this issue fixed? By this: https://github.com/microsoft/azure-spring-boot/issues/817#issuecomment-1128550965 ? Because there is no fix for this issue, there are just workarounds. There is still no fix for it. Why do you want to close it if it is not fixed yet? If you think it is enough for closing this issue then it is pretty sad.

[zoladkow]

That's not being prude at all. This situation is just silly. The issue is NOT FIXED, as the underlying problem is not addressed in any way - the error handling.

Since Apache Qpid JMS client employed in this starter as a shortcut to have an easy win, while it does speak the right protocol AMQP, it does not recognize particular ASB specific states or error messages, it has no way to employ any sort of reasonable strategies.

Conversely, the proper library for working with Azure Service Bus - azure-servicebus, has no such issues whatsoever - you create a client once, and it will just handle dropped connections without issue.

Suggestion, @chenrujun, @hui1110, maybe, instead of blaming Spring JMS + qpid-jms-client combo for not exposing "session, producer and consumer" to mitigate the "unrecoverable" error, why not to reimplement this starter on top of azure-servicebus, the proper way, by implementing JMS interfaces to allow for that library to be used with Spring JMS. No shortcuts. Seems to me like this would actually PREVENT those errors. Or is that too unreasonable?

edit: let me rephrase that a bit...

The reasonable thing would be to acknowledge that the current solution on top of just Apache Qpid JMS client has limitations with regard to particular behavior of ASB, which prevent a basic use case of this starter from working properly. As such, the decision should be made to employ a proper ASB client library, which would prevent such failures.

After all spring boot starters are not meant to replace a full fledged library, they are not meant to result in the smallest dependency tree and lightest overall weight of resulting artifact. They are expected to take the original library and provide reasonable defaults with minimal coding needed on the client part.

[stliu]

This issue is for tracking the exception: The MessageProducer was closed due to an unrecoverable error, which has been fixed. Currently investigating the referencecount refresh issue.

@hui1110 what's the fix when you say 'has been fixed'?

[hui1110]

This issue is for tracking the exception: The MessageProducer was closed due to an unrecoverable error, which has been fixed. Currently investigating the referencecount refresh issue.

@hui1110 what's the fix when you say 'has been fixed'?

Enable pools to avoid exceptions thrown when sending messages: The MessageProducer was closed due to an unrecoverable error

[Saljack]

Enable pools to avoid exceptions thrown when sending messages: The MessageProducer was closed due to an unrecoverable error

Really? Where is it enabled? It is starting ridiculous. This is just a workaround (which all users of this library have to use). It is not described anywhere (only in one comment in this issue). If you think it is enough then it is really sad. If you think it is the solution then you should enable it by default. You should definitely write it to your reference documentation. It is completely missing there. It is really funny that someone have time to advocate this solution as fix (pretend it is no problem) but he/they do not have time to write it to reference documentation or enable it in autoconfiguration (I can understand that it is not backward compatible). Do you really want to solve this issue again and again?