azure-sdk-for-java icon indicating copy to clipboard operation
azure-sdk-for-java copied to clipboard

Published 20 hours ago • verified publisher icon Azure

[QUERY] Max delivery count configured in the portal is not honoured by JMS APIs for Azure Service Bus Topic.retrying it forever.

Open skbaji6 opened this issue 3 years ago • 4 comments

Description

Max delivery configured in Azure portal as 5 Even after 5 redeliveries it is retrying again and again untill jvm is killed. code is written as follows

<dependency>
	<groupId>com.azure.spring</groupId>
	<artifactId>spring-cloud-azure-starter-servicebus-jms</artifactId>
	<version>4.3.0</version>
</dependency>

@JmsListener(destination = "${topic-name}", containerFactory = "testTopicJmsListenerContainerFactory", subscription = "${subscription-name}")
public void receiveMessage(JmsTextMessage message) throws Exception {
    String event = message.getBody(String.class);
    try {
	    log.info("Received event: {}", event);
	    log.info("Received message: {}", message);
	    Enumeration e = message.getAllPropertyNames();
	    while (e.hasMoreElements()) {
		    String name = (String) e.nextElement();
		    System.out.println(name + ":" + message.getStringProperty(name));
	    }
	    log.info("JMSRedelivered: {}", message.getJMSRedelivered());
	    TimeUnit.SECONDS.sleep(5);
	    throwException();
	    message.acknowledge();
    } catch (Exception e) {
	    log.error("Exception while processing re-source event: " + event, e);
	    throw e;
    }
}

@Bean("testTopicJmsListenerContainerFactory")
public JmsListenerContainerFactory<?> orderReSourceTopicJmsListenerContainerFactory(
	DefaultJmsListenerContainerFactoryConfigurer configurer,
	@Qualifier("testJmsConnectionFactory") ConnectionFactory connectionFactory,ErrorHandler myErrorHandler) {
    final DefaultJmsListenerContainerFactory jmsListenerContainerFactory = new DefaultJmsListenerContainerFactory();
    configurer.configure(jmsListenerContainerFactory, connectionFactory);
    jmsListenerContainerFactory.setPubSubDomain(Boolean.FALSE);
    jmsListenerContainerFactory.setSessionTransacted(Boolean.FALSE);
    jmsListenerContainerFactory.setSessionAcknowledgeMode(Session.CLIENT_ACKNOWLEDGE);
    jmsListenerContainerFactory.setSubscriptionDurable(Boolean.TRUE);
    jmsListenerContainerFactory.setErrorHandler(myErrorHandler);
    return jmsListenerContainerFactory;
}

@Bean
public ErrorHandler myErrorHandler() {
    return t -> {
        System.out.println("In error handler"+t.getMessage());
    };
}

Exception or Stack Trace

2022-09-07 16:39:38.121  INFO [order-re-source,24afd2757dd19875,2b28fdc1577f6cec] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : Received message: JmsTextMessage { org.apache.qpid.jms.provider.amqp.message.AmqpJmsTextMessageFacade@fa5be72 }
DeadLetterErrorDescription:Message could not be consumed after 5 delivery attempts.
JMSXDeliveryCount:17
DeadLetterReason:MaxDeliveryCountExceeded
2022-09-07 16:39:38.121  INFO [order-re-source,24afd2757dd19875,2b28fdc1577f6cec] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : JMSRedelivered: true
In error handlerListener method 'public void com.example.springazureservicebusjmsconsumer.subscriber.TopicSubscribeController.receiveMessage(org.apache.qpid.jms.message.JmsTextMessage) throws java.lang.Exception' threw exception; nested exception is java.lang.RuntimeException: User Exception
2022-09-07 16:39:39.126  INFO [order-re-source,591494cc68e88d40,edb1c68b0df84d2c] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : Received event: {
    "babu": "babu"
}
2022-09-07 16:39:39.126  INFO [order-re-source,591494cc68e88d40,edb1c68b0df84d2c] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : Received message: JmsTextMessage { org.apache.qpid.jms.provider.amqp.message.AmqpJmsTextMessageFacade@1764480e }
DeadLetterErrorDescription:Message could not be consumed after 5 delivery attempts.
JMSXDeliveryCount:18
DeadLetterReason:MaxDeliveryCountExceeded
2022-09-07 16:39:39.126  INFO [order-re-source,591494cc68e88d40,edb1c68b0df84d2c] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : JMSRedelivered: true
In error handlerListener method 'public void com.example.springazureservicebusjmsconsumer.subscriber.TopicSubscribeController.receiveMessage(org.apache.qpid.jms.message.JmsTextMessage) throws java.lang.Exception' threw exception; nested exception is java.lang.RuntimeException: User Exception
2022-09-07 16:39:40.129  INFO [order-re-source,aa8ecd739be5e3aa,5db0da30054f6b34] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : Received event: {
    "babu": "babu"
}
2022-09-07 16:39:40.129  INFO [order-re-source,aa8ecd739be5e3aa,5db0da30054f6b34] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : Received message: JmsTextMessage { org.apache.qpid.jms.provider.amqp.message.AmqpJmsTextMessageFacade@cf9da1e }
DeadLetterErrorDescription:Message could not be consumed after 5 delivery attempts.
JMSXDeliveryCount:19
DeadLetterReason:MaxDeliveryCountExceeded
2022-09-07 16:39:40.129  INFO [order-re-source,aa8ecd739be5e3aa,5db0da30054f6b34] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : JMSRedelivered: true
In error handlerListener method 'public void com.example.springazureservicebusjmsconsumer.subscriber.TopicSubscribeController.receiveMessage(org.apache.qpid.jms.message.JmsTextMessage) throws java.lang.Exception' threw exception; nested exception is java.lang.RuntimeException: User Exception
2022-09-07 16:39:41.135  INFO [order-re-source,e7084e15229daec4,882980737b98bf4d] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : Received event: {
    "babu": "babu"
}
2022-09-07 16:39:41.135  INFO [order-re-source,e7084e15229daec4,882980737b98bf4d] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : Received message: JmsTextMessage { org.apache.qpid.jms.provider.amqp.message.AmqpJmsTextMessageFacade@5883505f }
DeadLetterErrorDescription:Message could not be consumed after 5 delivery attempts.
JMSXDeliveryCount:20
DeadLetterReason:MaxDeliveryCountExceeded
2022-09-07 16:39:41.135  INFO [order-re-source,e7084e15229daec4,882980737b98bf4d] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : JMSRedelivered: true
In error handlerListener method 'public void com.example.springazureservicebusjmsconsumer.subscriber.TopicSubscribeController.receiveMessage(org.apache.qpid.jms.message.JmsTextMessage) throws java.lang.Exception' threw exception; nested exception is java.lang.RuntimeException: User Exception
2022-09-07 16:39:42.139  INFO [order-re-source,c403130462a65f64,7a59da8a779685f6] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : Received event: {
    "babu": "babu"
}
2022-09-07 16:39:42.139  INFO [order-re-source,c403130462a65f64,7a59da8a779685f6] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : Received message: JmsTextMessage { org.apache.qpid.jms.provider.amqp.message.AmqpJmsTextMessageFacade@360360bd }
DeadLetterErrorDescription:Message could not be consumed after 5 delivery attempts.
JMSXDeliveryCount:21
DeadLetterReason:MaxDeliveryCountExceeded
2022-09-07 16:39:42.139  INFO [order-re-source,c403130462a65f64,7a59da8a779685f6] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : JMSRedelivered: true
In error handlerListener method 'public void com.example.springazureservicebusjmsconsumer.subscriber.TopicSubscribeController.receiveMessage(org.apache.qpid.jms.message.JmsTextMessage) throws java.lang.Exception' threw exception; nested exception is java.lang.RuntimeException: User Exception
2022-09-07 16:39:43.142  INFO [order-re-source,08b8c404fad99d74,575d322867a0a73f] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : Received event: {
    "babu": "babu"
}
2022-09-07 16:39:43.142  INFO [order-re-source,08b8c404fad99d74,575d322867a0a73f] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : Received message: JmsTextMessage { org.apache.qpid.jms.provider.amqp.message.AmqpJmsTextMessageFacade@65c86743 }
DeadLetterErrorDescription:Message could not be consumed after 5 delivery attempts.
JMSXDeliveryCount:22
DeadLetterReason:MaxDeliveryCountExceeded
2022-09-07 16:39:43.142  INFO [order-re-source,08b8c404fad99d74,575d322867a0a73f] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : JMSRedelivered: true
In error handlerListener method 'public void com.example.springazureservicebusjmsconsumer.subscriber.TopicSubscribeController.receiveMessage(org.apache.qpid.jms.message.JmsTextMessage) throws java.lang.Exception' threw exception; nested exception is java.lang.RuntimeException: User Exception
2022-09-07 16:39:44.147  INFO [order-re-source,e8aca7440fd045ae,3977a71a5d4f8ce3] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : Received event: {
    "babu": "babu"
}
2022-09-07 16:39:44.147  INFO [order-re-source,e8aca7440fd045ae,3977a71a5d4f8ce3] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : Received message: JmsTextMessage { org.apache.qpid.jms.provider.amqp.message.AmqpJmsTextMessageFacade@10905993 }
DeadLetterErrorDescription:Message could not be consumed after 5 delivery attempts.
JMSXDeliveryCount:23
DeadLetterReason:MaxDeliveryCountExceeded
2022-09-07 16:39:44.147  INFO [order-re-source,e8aca7440fd045ae,3977a71a5d4f8ce3] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : JMSRedelivered: true
In error handlerListener method 'public void com.example.springazureservicebusjmsconsumer.subscriber.TopicSubscribeController.receiveMessage(org.apache.qpid.jms.message.JmsTextMessage) throws java.lang.Exception' threw exception; nested exception is java.lang.RuntimeException: User Exception
2022-09-07 16:39:45.152  INFO [order-re-source,e472794bed6898f9,855942b25eb89083] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : Received event: {
    "babu": "babu"
}
2022-09-07 16:39:45.152  INFO [order-re-source,e472794bed6898f9,855942b25eb89083] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : Received message: JmsTextMessage { org.apache.qpid.jms.provider.amqp.message.AmqpJmsTextMessageFacade@4f6460ac }
DeadLetterErrorDescription:Message could not be consumed after 5 delivery attempts.
JMSXDeliveryCount:24
DeadLetterReason:MaxDeliveryCountExceeded
2022-09-07 16:39:45.152  INFO [order-re-source,e472794bed6898f9,855942b25eb89083] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : JMSRedelivered: true
In error handlerListener method 'public void com.example.springazureservicebusjmsconsumer.subscriber.TopicSubscribeController.receiveMessage(org.apache.qpid.jms.message.JmsTextMessage) throws java.lang.Exception' threw exception; nested exception is java.lang.RuntimeException: User Exception
2022-09-07 16:39:46.156  INFO [order-re-source,af9b674a39db82eb,4bfc513ed1ee6949] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : Received event: {
    "babu": "babu"
}
2022-09-07 16:39:46.156  INFO [order-re-source,af9b674a39db82eb,4bfc513ed1ee6949] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : Received message: JmsTextMessage { org.apache.qpid.jms.provider.amqp.message.AmqpJmsTextMessageFacade@3e7282cc }
DeadLetterErrorDescription:Message could not be consumed after 5 delivery attempts.
JMSXDeliveryCount:25
DeadLetterReason:MaxDeliveryCountExceeded
2022-09-07 16:39:46.156  INFO [order-re-source,af9b674a39db82eb,4bfc513ed1ee6949] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : JMSRedelivered: true
In error handlerListener method 'public void com.example.springazureservicebusjmsconsumer.subscriber.TopicSubscribeController.receiveMessage(org.apache.qpid.jms.message.JmsTextMessage) throws java.lang.Exception' threw exception; nested exception is java.lang.RuntimeException: User Exception
2022-09-07 16:39:47.160  INFO [order-re-source,58b73fb63371a9e7,35b95438832f736a] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : Received event: {
    "babu": "babu"
}
2022-09-07 16:39:47.160  INFO [order-re-source,58b73fb63371a9e7,35b95438832f736a] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : Received message: JmsTextMessage { org.apache.qpid.jms.provider.amqp.message.AmqpJmsTextMessageFacade@3ca41bcd }
DeadLetterErrorDescription:Message could not be consumed after 5 delivery attempts.
JMSXDeliveryCount:26
DeadLetterReason:MaxDeliveryCountExceeded
2022-09-07 16:39:47.160  INFO [order-re-source,58b73fb63371a9e7,35b95438832f736a] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : JMSRedelivered: true
In error handlerListener method 'public void com.example.springazureservicebusjmsconsumer.subscriber.TopicSubscribeController.receiveMessage(org.apache.qpid.jms.message.JmsTextMessage) throws java.lang.Exception' threw exception; nested exception is java.lang.RuntimeException: User Exception
2022-09-07 16:39:48.164  INFO [order-re-source,b65f07432b2c13a2,0e4a97650b650ff0] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : Received event: {
    "babu": "babu"
}
2022-09-07 16:39:48.164  INFO [order-re-source,b65f07432b2c13a2,0e4a97650b650ff0] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : Received message: JmsTextMessage { org.apache.qpid.jms.provider.amqp.message.AmqpJmsTextMessageFacade@5a4aba2c }
DeadLetterErrorDescription:Message could not be consumed after 5 delivery attempts.
JMSXDeliveryCount:27
DeadLetterReason:MaxDeliveryCountExceeded
2022-09-07 16:39:48.164  INFO [order-re-source,b65f07432b2c13a2,0e4a97650b650ff0] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : JMSRedelivered: true
In error handlerListener method 'public void com.example.springazureservicebusjmsconsumer.subscriber.TopicSubscribeController.receiveMessage(org.apache.qpid.jms.message.JmsTextMessage) throws java.lang.Exception' threw exception; nested exception is java.lang.RuntimeException: User Exception
2022-09-07 16:39:49.169  INFO [order-re-source,bddddc614c1717ac,43bec036d3b7a85d] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : Received event: {
    "babu": "babu"
}
2022-09-07 16:39:49.169  INFO [order-re-source,bddddc614c1717ac,43bec036d3b7a85d] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : Received message: JmsTextMessage { org.apache.qpid.jms.provider.amqp.message.AmqpJmsTextMessageFacade@5d9dcac0 }
DeadLetterErrorDescription:Message could not be consumed after 5 delivery attempts.
**JMSXDeliveryCount:28**
DeadLetterReason:MaxDeliveryCountExceeded
2022-09-07 16:39:49.169  INFO [order-re-source,bddddc614c1717ac,43bec036d3b7a85d] 12524 --- [ntContainer#0-1] c.e.s.s.TopicSubscribeController         : JMSRedelivered: true

To Reproduce code is in the description to reproduce

Code Snippet Add the code snippet that causes the issue.

Expected behavior it should stop delivering message after 5 redelivery attempts

Screenshots image

Setup (please complete the following information):

  • OS: windows
  • IDE: STS
  • Java version: 8

skbaji6 avatar Sep 07 '22 11:09 skbaji6

@yiliuTo could you please follow up with @skbaji6 on this github issue?

joshfree avatar Sep 07 '22 18:09 joshfree

@yiliuTo any update please.

skbaji6 avatar Sep 13 '22 10:09 skbaji6

@skbaji6 sorry for the late response, occupied by other issues before. I reproduced this error and find that the failed messages are not get abandoned or released to Service Bus service, which causes the delivery count in service side is not increased. One workaround is that you can explicitly abandon the message when errors are encountered, like below:

    @JmsListener(destination = TOPIC_NAME, containerFactory = "testTopicJmsListenerContainerFactory",
            subscription = SUBSCRIPTION_NAME)
    public void receiveMessage(JmsTextMessage message) throws Exception {
        String event = message.getBody(String.class);
        try {
            logger.info("Received event: {}", event);
            logger.info("Received message: {}", message);
            Enumeration e = message.getAllPropertyNames();
            while (e.hasMoreElements()) {
                String name = (String) e.nextElement();
                System.out.println(name + ":" + message.getStringProperty(name));
            }
            logger.info("JMSRedelivered: {}", message.getJMSRedelivered());
            TimeUnit.SECONDS.sleep(5);
            throwException();
            message.acknowledge();
        } catch (Exception e) {
            logger.error("Exception while processing re-source event: " + event, e);
            JmsAcknowledgeCallback acknowledgeCallback = message.getAcknowledgeCallback();
            // explicitly abandon the message.
            acknowledgeCallback.setAckType(MODIFIED_FAILED);
            message.setAcknowledgeCallback(acknowledgeCallback);
            message.acknowledge();
            throw e;
        }
    }

I will keep investigating the error for the root cause.

yiliuTo avatar Sep 14 '22 09:09 yiliuTo

Hi @skbaji6 , for the client_ack mode, when exceptions encountered during message consuming, the JMS consumer will recover back to the status where that message with exceptions hasn't been dequeued to consume, which causes the message being enqueued to the local message buffer again. Then every time the JMS consumer pulls for messages, it doesn't truly pull messages from Service Bus, but pulls that local message buffer and in the end pulls the error-handling message. Then things happen repeatedly. That's why you always receive the same message.

The solution mentioned in the last comment, can solve this case because it manually abandons the message to Service Bus, and during the call of acknowledge(), it also removes the error-handing message locally since it has been acked. Then when JMS consumer tries to recover to the status where the error-handling message hasn't been consumed, it failed to enqueue that message back to the local message buffer since that message has been removed in the acknowledge() call. Thus solves the issue.

yiliuTo avatar Sep 19 '22 14:09 yiliuTo

Hi, we're sending this friendly reminder because we haven't heard back from you in a while. We need more information about this issue to help address it. Please be sure to give us your input within the next 7 days. If we don't hear back from you within 14 days of this comment the issue will be automatically closed. Thank you!

ghost avatar Sep 27 '22 02:09 ghost

Hi, we're sending this friendly reminder because we haven't heard back from you in a while. We need more information about this issue to help address it. Please be sure to give us your input within the next 7 days. If we don't hear back from you within 14 days of this comment the issue will be automatically closed. Thank you!

ghost avatar Oct 16 '22 08:10 ghost