0
votes

I'm using spring-integration (and boot) to setup a session transacted JMS listener. However i'm observing an issue where messages seem to be being acknowledged and committed one second late (even though they are processed much faster by the spring-integration app.

Setup:

#Properties
spring.activemq.broker-url=nio://localhost:61616
spring.activemq.pool.enabled=true
spring.activemq.pool.max-connections=15
spring.activemq.pool.block-if-full=false

#ConnectionFactory
    @Bean
    public ActiveMQConnectionFactoryCustomizer activeMQConnectionFactoryCustomizer() {
        return factory -> {
            factory.setClientIDPrefix(amqClientId);
        };
    }

#Inbound Gateway
    @Bean
    public IntegrationFlow jmsInFlow(ConnectionFactory connectionFactory, JmsMessageConverter messageConverter) {
        TracingMessageListenerContainer tracingMessageListenerContainer = new TracingMessageListenerContainer();
        tracingMessageListenerContainer.setConnectionFactory(connectionFactory);
        ActiveMQQueue destination = new ActiveMQQueue(jmsIn);
        tracingMessageListenerContainer.setDestination(destination);
        tracingMessageListenerContainer.setSessionTransacted(true);
        tracingMessageListenerContainer.setSessionAcknowledgeMode(CLIENT_ACKNOWLEDGE);
        tracingMessageListenerContainer.setConcurrency("100-200");
        tracingMessageListenerContainer.setCacheLevel(CACHE_CONSUMER);
        return IntegrationFlows.from(Jms.inboundGateway(tracingMessageListenerContainer)
                .jmsMessageConverter(messageConverter)
                .explicitQosEnabledForReplies(true)
                .replyDeliveryPersistent(false)
                .errorChannel("integrationError"))
                .log(INFO, "InboundMessage")
                .headerFilter("jms_type") //FIXME Needed as header is copied from source message to response, should replace with headerFilter on jms gateway
                .channel(INFRA_IN)
                .get();
    }

#Outbound Adapter
    @Bean
    public IntegrationFlow jmsOutFlow(ConnectionFactory connectionFactory, JmsMessageConverter messageConverter) {
        return IntegrationFlows.from(INFRA_OUT)
                .log(INFO, "OutboundMessage")
                .handle(Jms.outboundAdapter(connectionFactory)
                        .configureJmsTemplate(jmsTemplateSpec -> {
                            jmsTemplateSpec.jmsMessageConverter(messageConverter);
                            jmsTemplateSpec.sessionTransacted(true);
                            jmsTemplateSpec.sessionAcknowledgeMode(CLIENT_ACKNOWLEDGE);
                            jmsTemplateSpec.explicitQosEnabled(true);
                        })
                        .deliveryModeFunction((Function<org.springframework.messaging.Message<JsonMessage>, Integer>)
                                message -> Optional.ofNullable(message.getHeaders().get(SEND_PERSISTED_HEADER, Boolean.class))
                                        .map(value -> value ? PERSISTENT : NON_PERSISTENT)
                                        .orElse(NON_PERSISTENT)
                        )
                        .destination(jmsOut))
                .get();
    }

These are the logs from the broker, you can see the final acknowledge and commit is exactly 1 second late (from the App's logs i can see it finished processing earlier also):

2020-03-24 14:39:24,372 | INFO  | Sending message: ActiveMQTextMessage {commandId = 154, responseRequired = true, messageId = ID:s-p.n-39946-1584976128611-12:1:100:1:7, originalDestination = queue://connectionproxy.out, originalTransactionId = null, producerId = testBrokers-p->testBrokers-reg-39946-1584976128611-20:2:1:1, destination = queue://testengine.in, transactionId = null, expiration = 0, timestamp = 1585060764371, arrival = 0, brokerInTime = 1585060764371, brokerOutTime = 1585060764371, correlationId = 8d216a4c-d9d4-4607-be60-f5aaa7159603, replyTo = null, persistent = false, type = DoPlayerAction, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content = org.apache.activemq.util.ByteSequence@5f1e98fd, marshalledProperties = org.apache.activemq.util.ByteSequence@58037850, dataStructure = null, redeliveryCounter = 0, size = 1565, properties = {CometdClientId=mg1tq4fa2hfpp6ceztgm0e33q3f, lag=65, deviceSessionId=9999, breadcrumbId=ID-s-reg-novalocal-43151-1584976153021-0-4170, audit_channel=/service/hand/action, ventureId=1, CamelJmsDeliveryMode=1, partnerId=1300, authenticator=c.t.c.i.a.v.TestVentureAuthenticator, memberId=123, RouteLogging=true}, readOnlyProperties = false, readOnlyBody = false, droppable = false, jmsXGroupFirstForConsumer = false, text = {"tableId":8,"player":{"id":123,"ve...sequence":8}} | LBP | ActiveMQ NIO Worker 42
2020-03-24 14:39:24,372 | INFO  | Adding destination: Queue:testengine.in | LBP | ActiveMQ NIO Worker 42
2020-03-24 14:39:24,372 | INFO  | preProcessDispatch: MessageDispatch {commandId = 0, responseRequired = false, consumerId = ID:s-r.n-39302-1585056153756-1:1:39:1, destination = queue://testengine.in, message = ActiveMQTextMessage {} | LBP | ActiveMQ BrokerService[testBrokers-reg] Task-258
2020-03-24 14:39:24,372 | INFO  | postProcessDispatch: MessageDispatch {commandId = 0, responseRequired = false, consumerId = ID:s-r.n-39302-1585056153756-1:1:39:1, destination = queue://testengine.in, message = ActiveMQTextMessage {} | LBP | ActiveMQ BrokerService[testBrokers-reg] Task-258
2020-03-24 14:39:24,373 | INFO  | Beginning transaction: TX:ID:s-r.n-39302-1585056153756-1:1:42 | LBP | ActiveMQ NIO Worker 42
2020-03-24 14:39:24,389 | INFO  | Adding Producer: ProducerInfo {commandId = 411, responseRequired = true, producerId = ID:s-r.n-39302-1585056153756-1:1:39:1, destination = null, brokerPath = null, dispatchAsync = false, windowSize = 0, sentCount = 0} | LBP | ActiveMQ NIO Worker 42
2020-03-24 14:39:24,390 | INFO  | Sending message: ActiveMQTextMessage {commandId = 412, responseRequired = false, messageId = ID:s-r.n-39302-1585056153756-1:1:39:1:1, originalDestination = null, originalTransactionId = null, producerId = ID:s-r.n-39302-1585056153756-1:1:39:1, destination = queue://testengine.out, transactionId = TX:ID:s-r.n-39302-1585056153756-1:1:42, expiration = 0, timestamp = 1585060764390, arrival = 0, brokerInTime = 0, brokerOutTime = 0, correlationId = 8d216a4c-d9d4-4607-be60-f5aaa7159603, replyTo = null, persistent = false, type = HandUpdatedEvent, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content = org.apache.activemq.util.ByteSequence@1ab48393, marshalledProperties = org.apache.activemq.util.ByteSequence@5105a072, dataStructure = null, redeliveryCounter = 0, size = 3372, properties = {CometdClientId=mg1tq4fa2hfpp6ceztgm0e33q3f, ventureId=1, CamelJmsDeliveryMode=1, SendPersisted=false, API_VERSION=2.0, RouteLogging=true, lag=65, deviceSessionId=9999, breadcrumbId=ID-s-reg-novalocal-43151-1584976153021-0-4170, SERIALISATION_VERSION=2.0, audit_channel=/service/hand/action, tableId=8, partnerId=1300, authenticator=c.t.c.i.a.v.TestVentureAuthenticator, memberId=123, timestamp=1585060764389}, readOnlyProperties = false, readOnlyBody = false, droppable = false, jmsXGroupFirstForConsumer = false, text = {"timestamp":1585060764388,"correlationId":"8...quence":8}}}} | LBP | ActiveMQ NIO Worker 42
2020-03-24 14:39:24,391 | INFO  | Adding destination: Queue:testengine.out | LBP | ActiveMQ NIO Worker 42
2020-03-24 14:39:24,391 | INFO  | Sending message: ActiveMQTextMessage {commandId = 413, responseRequired = false, messageId = ID:s-r.n-39302-1585056153756-1:1:39:1:2, originalDestination = null, originalTransactionId = null, producerId = ID:s-r.n-39302-1585056153756-1:1:39:1, destination = queue://testengine.out, transactionId = TX:ID:s-r.n-39302-1585056153756-1:1:42, expiration = 0, timestamp = 1585060764391, arrival = 0, brokerInTime = 0, brokerOutTime = 0, correlationId = 8d216a4c-d9d4-4607-be60-f5aaa7159603, replyTo = null, persistent = false, type = PlayerUpdated, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content = org.apache.activemq.util.ByteSequence@7af713df, marshalledProperties = org.apache.activemq.util.ByteSequence@39f53529, dataStructure = null, redeliveryCounter = 0, size = 1733, properties = {tableId=8, SendPersisted=false, API_VERSION=2.0, SERIALISATION_VERSION=2.0, playerId=1_123, timestamp=1585060764391}, readOnlyProperties = false, readOnlyBody = false, droppable = false, jmsXGroupFirstForConsumer = false, text = {"timestamp":1585060764390,"correlationId":"8...handId":1}]}} | LBP | ActiveMQ NIO Worker 42
2020-03-24 14:39:24,391 | INFO  | Adding destination: Queue:testengine.out | LBP | ActiveMQ NIO Worker 42
2020-03-24 14:39:24,393 | INFO  | Sending message: ActiveMQTextMessage {commandId = 414, responseRequired = false, messageId = ID:s-r.n-39302-1585056153756-1:1:39:1:3, originalDestination = null, originalTransactionId = null, producerId = ID:s-r.n-39302-1585056153756-1:1:39:1, destination = queue://testengine.out, transactionId = TX:ID:s-r.n-39302-1585056153756-1:1:42, expiration = 0, timestamp = 1585060764392, arrival = 0, brokerInTime = 0, brokerOutTime = 0, correlationId = 8d216a4c-d9d4-4607-be60-f5aaa7159603, replyTo = null, persistent = false, type = PlayerUpdated, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content = org.apache.activemq.util.ByteSequence@763819f, marshalledProperties = org.apache.activemq.util.ByteSequence@7b99b731, dataStructure = null, redeliveryCounter = 0, size = 1735, properties = {tableId=8, SendPersisted=false, API_VERSION=2.0, SERIALISATION_VERSION=2.0, playerId=1_1585060648037, timestamp=1585060764391}, readOnlyProperties = false, readOnlyBody = false, droppable = false, jmsXGroupFirstForConsumer = false, text = {"timestamp":1585060764390,"correlationId":"8...handId":1}]}} | LBP | ActiveMQ NIO Worker 42
2020-03-24 14:39:24,393 | INFO  | Adding destination: Queue:testengine.out | LBP | ActiveMQ NIO Worker 42
2020-03-24 14:39:24,394 | INFO  | Sending message: ActiveMQTextMessage {commandId = 415, responseRequired = false, messageId = ID:s-r.n-39302-1585056153756-1:1:39:1:4, originalDestination = null, originalTransactionId = null, producerId = ID:s-r.n-39302-1585056153756-1:1:39:1, destination = queue://testengine.out, transactionId = TX:ID:s-r.n-39302-1585056153756-1:1:42, expiration = 0, timestamp = 1585060764393, arrival = 0, brokerInTime = 0, brokerOutTime = 0, correlationId = 8d216a4c-d9d4-4607-be60-f5aaa7159603, replyTo = null, persistent = false, type = TableSequenceUpdatedEvent, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content = org.apache.activemq.util.ByteSequence@39b22a76, marshalledProperties = org.apache.activemq.util.ByteSequence@297e1c14, dataStructure = null, redeliveryCounter = 0, size = 2414, properties = {CometdClientId=mg1tq4fa2hfpp6ceztgm0e33q3f, ventureId=1, CamelJmsDeliveryMode=1, SendPersisted=false, API_VERSION=2.0, RouteLogging=true, lag=65, deviceSessionId=9999, breadcrumbId=ID-s-reg-novalocal-43151-1584976153021-0-4170, SERIALISATION_VERSION=2.0, audit_channel=/service/hand/action, tableId=8, partnerId=1300, authenticator=c.t.c.i.a.v.TestVentureAuthenticator, memberId=123, timestamp=1585060764393}, readOnlyProperties = false, readOnlyBody = false, droppable = false, jmsXGroupFirstForConsumer = false, text = {"timestamp":1585060764392,"correlationId":"8...675519:0"}]}} | LBP | ActiveMQ NIO Worker 42
2020-03-24 14:39:24,394 | INFO  | Adding destination: Queue:testengine.out | LBP | ActiveMQ NIO Worker 42
2020-03-24 14:39:25,394 | INFO  | Acknowledging message for client ID: thisIsMyClientAppId-39302-1585056153756-0:1, ID:s-p.n-39946-1584976128611-12:1:100:1:7 | LBP | ActiveMQ NIO Worker 42
2020-03-24 14:39:25,394 | INFO  | Committing transaction: TX:ID:s-r.n-39302-1585056153756-1:1:42 | LBP | ActiveMQ NIO Worker 42

Does anyone have any idea what i've got wrong in my setup that is causing this latency issue?

Update: These are the logs from the actual application (as opposed to broker logs above). Not for the same timestamp, but for the set of messages so it should be comparable. The delay does not seem to be present here.

2020-03-27 10:12:29.556 DEBUG 21528 --- [nerContainer-87] org.apache.activemq.TransactionContext   : Begin:TX:ID:s-r.n-39350-1585303832228-1:1:7
2020-03-27 10:12:29.557 DEBUG 21528 --- [nerContainer-87] onConfig$TracingMessageListenerContainer : Received message of type [class org.apache.activemq.command.ActiveMQTextMessage] from consumer [JmsPoolMessageConsumer { ActiveMQMessageConsumer { value=ID:s-r.n-39350-1585303832228-1:1:40:1, started=true } }] of session [JmsPoolSession { ActiveMQSession {id=ID:s-r.n-39350-1585303832228-1:1:40,started=true} java.lang.Object@5a3a13ad }]
2020-03-27 10:12:29.558 DEBUG 21528 --- [nerContainer-87] .i.j.ChannelPublishingJmsMessageListener : converted JMS Message [ActiveMQTextMessage {commandId = 41, responseRequired = true, messageId = ID:s-p.n-39946-1584976128611-12:11:29:1:1, originalDestination = queue://connectionproxy.out, originalTransactionId = null, producerId = gameBrokers-p->gameBrokers-r-39946-1584976128611-125:2:1:1, destination = queue://gameengine.in, transactionId = null, expiration = 0, timestamp = 1585303949554, arrival = 0, brokerInTime = 1585303949555, brokerOutTime = 1585303949556, correlationId = 800da7b4-717b-43a0-b146-428a789dc960, replyTo = null, persistent = false, type = DoPlayerAction, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content = null, marshalledProperties = org.apache.activemq.util.ByteSequence@5562cdea, dataStructure = null, redeliveryCounter = 0, size = 0, properties = {CometdClientId=abc, lag=49, deviceSessionId=9999, breadcrumbId=ID-s-r-novalocal-43151-1584976153021-0-9607, audit_channel=/service/round/action, ventureId=1, CamelJmsDeliveryMode=1, partnerId=1300, authenticator=c.g.c.i.a.TestVentureAuthenticator, memberId=123, RouteLogging=true}, readOnlyProperties = true, readOnlyBody = true, droppable = false, jmsXGroupFirstForConsumer = false, text = {"tableId":14,"player":{"id":123,"v...sequence":3}}] to integration Message payload [DoPlayerActionMessage{action=ACTION3, player=MessageGamePlayerTokenInfo{name='test-console4', instanceId='null', gameSessionId='null'}, tableId=14, amount=MessageCashAmountInfo [amount=5, currencyId=7, currencyIso=TCH], seatNumber=null, sequence=3} JsonMessage{timestamp=Fri Mar 27 10:12:29 UTC 2020, correlationId='800da7b4-717b-43a0-b146-428a789dc960', venture='null', ventureId=null, headers={CometdClientId=abc, lag=49, deviceSessionId=9999, breadcrumbId=ID-s-r-novalocal-43151-1584976153021-0-9607, audit_channel=/service/round/action, ventureId=1, CamelJmsDeliveryMode=1, JMSCorrelationID=800da7b4-717b-43a0-b146-428a789dc960, partnerId=1300, authenticator=c.g.c.i.a.TestVentureAuthenticator, memberId=123, RouteLogging=true}, loggingMessage=true}]
2020-03-27 10:12:29.558 DEBUG 21528 --- [nerContainer-87] o.s.integration.channel.DirectChannel    : preSend on channel 'bean 'jmsInFlow.channel#0'; defined in: 'class path resource [c/g/g/c/i/j/JmsIntegrationConfig.class]'; from source: 'bean method jmsInFlow'', message: GenericMessage [payload={} JsonMessage{timestamp=Fri Mar 27 10:12:29 UTC 2020, correlationId='800da7b4-717b-43a0-b146-428a789dc960', venture='null', ventureId=null, headers={CometdClientId=abc, lag=49, deviceSessionId=9999, breadcrumbId=ID-s-r-novalocal-43151-1584976153021-0-9607, audit_channel=/service/round/action, ventureId=1, CamelJmsDeliveryMode=1, JMSCorrelationID=800da7b4-717b-43a0-b146-428a789dc960, partnerId=1300, authenticator=c.g.c.i.a.TestVentureAuthenticator, memberId=123, RouteLogging=true}, loggingMessage=true}, headers={CometdClientId=abc, errorChannel=org.springframework.messaging.core.GenericMessagingTemplate$TemporaryReplyChannel@77054e87, jms_destination=queue://gameengine.in, ventureId=1, CamelJmsDeliveryMode=1, priority=4, jms_timestamp=1585303949554, RouteLogging=true, replyChannel=org.springframework.messaging.core.GenericMessagingTemplate$TemporaryReplyChannel@77054e87, jms_redelivered=false, lag=49, deviceSessionId=9999, breadcrumbId=ID-s-r-novalocal-43151-1584976153021-0-9607, audit_channel=/service/round/action, jms_correlationId=800da7b4-717b-43a0-b146-428a789dc960, jms_type=DoPlayerAction, partnerId=1300, id=3037b982-083d-b7df-27d3-1a2eff1ee67e, authenticator=c.g.c.i.a.TestVentureAuthenticator, jms_messageId=ID:s-p.n-39946-1584976128611-12:11:29:1:1, memberId=123, timestamp=1585303949558}]
...
2020-03-27 10:12:29.598 DEBUG 21528 --- [nerContainer-87] o.s.integration.channel.DirectChannel    : preSend on channel 'bean 'jmsOutFlow.channel#1'; defined in: 'class path resource [c/g/g/c/i/j/JmsIntegrationConfig.class]'; from source: 'bean method jmsOutFlow'', message: GenericMessage [payload={}, headers={SendPersisted=false, id=acd19c61-0cec-78e8-34ec-7e2f6531a6be, timestamp=1585303949597}]
2020-03-27 10:12:29.598 DEBUG 21528 --- [nerContainer-87] o.s.i.jms.JmsSendingMessageRoundler       : bean 'jmsOutFlow.jms:outbound-channel-adapter#0' for component 'jmsOutFlow.org.springframework.integration.config.ConsumerEndpointFactoryBean#1'; defined in: 'class path resource [c/g/g/c/i/j/JmsIntegrationConfig.class]'; from source: 'bean method jmsOutFlow' received message: GenericMessage [payload={}, headers={SendPersisted=false, id=acd19c61-0cec-78e8-34ec-7e2f6531a6be, timestamp=1585303949597}]
2020-03-27 10:12:29.598 DEBUG 21528 --- [nerContainer-87] o.s.integration.jms.DynamicJmsTemplate   : Executing callback on JMS Session: JmsPoolSession { ActiveMQSession {id=ID:s-r.n-39350-1585303832228-1:1:40,started=true} java.lang.Object@5a3a13ad }
2020-03-27 10:12:29.600 DEBUG 21528 --- [nerContainer-87] o.s.integration.jms.DynamicJmsTemplate   : Sending created message: ActiveMQTextMessage {commandId = 0, responseRequired = false, messageId = null, originalDestination = null, originalTransactionId = null, producerId = null, destination = null, transactionId = null, expiration = 0, timestamp = 0, arrival = 0, brokerInTime = 0, brokerOutTime = 0, correlationId = 800da7b4-717b-43a0-b146-428a789dc960, replyTo = null, persistent = false, type = RoundUpdatedEvent, priority = 0, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content = null, marshalledProperties = null, dataStructure = null, redeliveryCounter = 0, size = 0, properties = {CometdClientId=abc, ventureId=1, CamelJmsDeliveryMode=1, SendPersisted=false, API_VERSION=2.0, RouteLogging=true, lag=49, deviceSessionId=9999, breadcrumbId=ID-s-r-novalocal-43151-1584976153021-0-9607, SERIALISATION_VERSION=2.0, audit_channel=/service/round/action, tableId=14, partnerId=1300, authenticator=c.g.c.i.a.TestVentureAuthenticator, memberId=123, timestamp=1585303949597}, readOnlyProperties = false, readOnlyBody = false, droppable = false, jmsXGroupFirstForConsumer = false, text = {"timestamp":1585303949596,"correlationId":"8...quence":3}}}}
2020-03-27 10:12:29.601 DEBUG 21528 --- [nerContainer-87] o.s.integration.channel.DirectChannel    : postSend (sent=true) on channel 'bean 'jmsOutFlow.channel#1'; defined in: 'class path resource [c/g/g/c/i/j/JmsIntegrationConfig.class]'; from source: 'bean method jmsOutFlow'', message: GenericMessage [payload={}, headers={SendPersisted=false, id=acd19c61-0cec-78e8-34ec-7e2f6531a6be, timestamp=1585303949597}]
2020-03-27 10:12:29.601 DEBUG 21528 --- [nerContainer-87] o.s.integration.channel.DirectChannel    : postSend (sent=true) on channel 'bean 'infraOut'; defined in: 'class path resource [c/g/g/c/i/j/JmsIntegrationConfig.class]'; from source: 'bean method appOutFlow'', message: GenericMessage [payload={}, headers={SendPersisted=false, id=acd19c61-0cec-78e8-34ec-7e2f6531a6be, timestamp=1585303949597}]
2020-03-27 10:12:29.601 DEBUG 21528 --- [nerContainer-87] o.s.integration.channel.DirectChannel    : postSend (sent=true) on channel 'bean 'appOut'; defined in: 'class path resource [c/g/g/c/i/j/JmsIntegrationConfig.class]'; from source: 'bean method appOutManyFlow'', message: GenericMessage [payload={}, headers={SendPersisted=false, id=c0d9e1f5-9f00-b60d-b991-ef6b11e8b436, timestamp=1585303949597}]
2020-03-27 10:12:29.602 DEBUG 21528 --- [nerContainer-87] o.s.i.roundler.ServiceActivatingRoundler   : roundler 'ServiceActivator for [org.springframework.integration.roundler.MethodInvokingMessageProcessor@675fdd0] (appInFlow.org.springframework.integration.config.ConsumerEndpointFactoryBean#0)' produced no reply for request Message: GenericMessage [payload={} JsonMessage{timestamp=Fri Mar 27 10:12:29 UTC 2020, correlationId='800da7b4-717b-43a0-b146-428a789dc960', venture='null', ventureId=null, headers={CometdClientId=abc, lag=49, deviceSessionId=9999, breadcrumbId=ID-s-r-novalocal-43151-1584976153021-0-9607, audit_channel=/service/round/action, ventureId=1, CamelJmsDeliveryMode=1, JMSCorrelationID=800da7b4-717b-43a0-b146-428a789dc960, partnerId=1300, authenticator=c.g.c.i.a.TestVentureAuthenticator, memberId=123, RouteLogging=true}, loggingMessage=true}, headers={CometdClientId=abc, errorChannel=org.springframework.messaging.core.GenericMessagingTemplate$TemporaryReplyChannel@77054e87, jms_destination=queue://gameengine.in, ventureId=1, CamelJmsDeliveryMode=1, priority=4, jms_timestamp=1585303949554, RouteLogging=true, replyChannel=org.springframework.messaging.core.GenericMessagingTemplate$TemporaryReplyChannel@77054e87, jms_redelivered=false, lag=49, deviceSessionId=9999, breadcrumbId=ID-s-r-novalocal-43151-1584976153021-0-9607, audit_channel=/service/round/action, jms_correlationId=800da7b4-717b-43a0-b146-428a789dc960, partnerId=1300, id=6728c2b8-869b-4df5-a0e4-316a6a95d087, authenticator=c.g.c.i.a.TestVentureAuthenticator, jms_messageId=ID:s-p.n-39946-1584976128611-12:11:29:1:1, memberId=123, timestamp=1585303949559}]
2020-03-27 10:12:29.602 DEBUG 21528 --- [nerContainer-87] o.s.integration.channel.DirectChannel    : postSend (sent=true) on channel 'bean 'appIn'; defined in: 'class path resource [companynew/game/gs/config/application/ApplicationConfig.class]'; from source: 'bean method appInFlow'', message: GenericMessage [payload={} JsonMessage{timestamp=Fri Mar 27 10:12:29 UTC 2020, correlationId='800da7b4-717b-43a0-b146-428a789dc960', venture='null', ventureId=null, headers={CometdClientId=abc, lag=49, deviceSessionId=9999, breadcrumbId=ID-s-r-novalocal-43151-1584976153021-0-9607, audit_channel=/service/round/action, ventureId=1, CamelJmsDeliveryMode=1, JMSCorrelationID=800da7b4-717b-43a0-b146-428a789dc960, partnerId=1300, authenticator=c.g.c.i.a.TestVentureAuthenticator, memberId=123, RouteLogging=true}, loggingMessage=true}, headers={CometdClientId=abc, errorChannel=org.springframework.messaging.core.GenericMessagingTemplate$TemporaryReplyChannel@77054e87, jms_destination=queue://gameengine.in, ventureId=1, CamelJmsDeliveryMode=1, priority=4, jms_timestamp=1585303949554, RouteLogging=true, replyChannel=org.springframework.messaging.core.GenericMessagingTemplate$TemporaryReplyChannel@77054e87, jms_redelivered=false, lag=49, deviceSessionId=9999, breadcrumbId=ID-s-r-novalocal-43151-1584976153021-0-9607, audit_channel=/service/round/action, jms_correlationId=800da7b4-717b-43a0-b146-428a789dc960, partnerId=1300, id=6728c2b8-869b-4df5-a0e4-316a6a95d087, authenticator=c.g.c.i.a.TestVentureAuthenticator, jms_messageId=ID:s-p.n-39946-1584976128611-12:11:29:1:1, memberId=123, timestamp=1585303949559}]
2020-03-27 10:12:29.602 DEBUG 21528 --- [nerContainer-87] o.s.integration.channel.DirectChannel    : postSend (sent=true) on channel 'bean 'appInUnAuthenticated'; defined in: 'class path resource [c/g/g/c/i/j/JmsIntegrationConfig.class]'; from source: 'bean method infraInFlow'', message: GenericMessage [payload={} JsonMessage{timestamp=Fri Mar 27 10:12:29 UTC 2020, correlationId='800da7b4-717b-43a0-b146-428a789dc960', venture='null', ventureId=null, headers={CometdClientId=abc, lag=49, deviceSessionId=9999, breadcrumbId=ID-s-r-novalocal-43151-1584976153021-0-9607, audit_channel=/service/round/action, ventureId=1, CamelJmsDeliveryMode=1, JMSCorrelationID=800da7b4-717b-43a0-b146-428a789dc960, partnerId=1300, authenticator=c.g.c.i.a.TestVentureAuthenticator, memberId=123, RouteLogging=true}, loggingMessage=true}, headers={CometdClientId=abc, errorChannel=org.springframework.messaging.core.GenericMessagingTemplate$TemporaryReplyChannel@77054e87, jms_destination=queue://gameengine.in, ventureId=1, CamelJmsDeliveryMode=1, priority=4, jms_timestamp=1585303949554, RouteLogging=true, replyChannel=org.springframework.messaging.core.GenericMessagingTemplate$TemporaryReplyChannel@77054e87, jms_redelivered=false, lag=49, deviceSessionId=9999, breadcrumbId=ID-s-r-novalocal-43151-1584976153021-0-9607, audit_channel=/service/round/action, jms_correlationId=800da7b4-717b-43a0-b146-428a789dc960, partnerId=1300, id=6728c2b8-869b-4df5-a0e4-316a6a95d087, authenticator=c.g.c.i.a.TestVentureAuthenticator, jms_messageId=ID:s-p.n-39946-1584976128611-12:11:29:1:1, memberId=123, timestamp=1585303949559}]
2020-03-27 10:12:29.602 DEBUG 21528 --- [nerContainer-87] o.s.integration.channel.DirectChannel    : postSend (sent=true) on channel 'bean 'infraIn'; defined in: 'class path resource [c/g/g/c/i/j/JmsIntegrationConfig.class]'; from source: 'bean method jmsInFlow'', message: GenericMessage [payload={} JsonMessage{timestamp=Fri Mar 27 10:12:29 UTC 2020, correlationId='800da7b4-717b-43a0-b146-428a789dc960', venture='null', ventureId=null, headers={CometdClientId=abc, lag=49, deviceSessionId=9999, breadcrumbId=ID-s-r-novalocal-43151-1584976153021-0-9607, audit_channel=/service/round/action, ventureId=1, CamelJmsDeliveryMode=1, JMSCorrelationID=800da7b4-717b-43a0-b146-428a789dc960, partnerId=1300, authenticator=c.g.c.i.a.TestVentureAuthenticator, memberId=123, RouteLogging=true}, loggingMessage=true}, headers={CometdClientId=abc, errorChannel=org.springframework.messaging.core.GenericMessagingTemplate$TemporaryReplyChannel@77054e87, jms_destination=queue://gameengine.in, ventureId=1, CamelJmsDeliveryMode=1, priority=4, jms_timestamp=1585303949554, RouteLogging=true, replyChannel=org.springframework.messaging.core.GenericMessagingTemplate$TemporaryReplyChannel@77054e87, jms_redelivered=false, lag=49, deviceSessionId=9999, breadcrumbId=ID-s-r-novalocal-43151-1584976153021-0-9607, audit_channel=/service/round/action, jms_correlationId=800da7b4-717b-43a0-b146-428a789dc960, partnerId=1300, id=6728c2b8-869b-4df5-a0e4-316a6a95d087, authenticator=c.g.c.i.a.TestVentureAuthenticator, jms_messageId=ID:s-p.n-39946-1584976128611-12:11:29:1:1, memberId=123, timestamp=1585303949559}]
2020-03-27 10:12:29.602 DEBUG 21528 --- [nerContainer-87] o.s.integration.channel.DirectChannel    : postSend (sent=true) on channel 'bean 'jmsInFlow.channel#0'; defined in: 'class path resource [c/g/g/c/i/j/JmsIntegrationConfig.class]'; from source: 'bean method jmsInFlow'', message: GenericMessage [payload={} JsonMessage{timestamp=Fri Mar 27 10:12:29 UTC 2020, correlationId='800da7b4-717b-43a0-b146-428a789dc960', venture='null', ventureId=null, headers={CometdClientId=abc, lag=49, deviceSessionId=9999, breadcrumbId=ID-s-r-novalocal-43151-1584976153021-0-9607, audit_channel=/service/round/action, ventureId=1, CamelJmsDeliveryMode=1, JMSCorrelationID=800da7b4-717b-43a0-b146-428a789dc960, partnerId=1300, authenticator=c.g.c.i.a.TestVentureAuthenticator, memberId=123, RouteLogging=true}, loggingMessage=true}, headers={CometdClientId=abc, errorChannel=org.springframework.messaging.core.GenericMessagingTemplate$TemporaryReplyChannel@77054e87, jms_destination=queue://gameengine.in, ventureId=1, CamelJmsDeliveryMode=1, priority=4, jms_timestamp=1585303949554, RouteLogging=true, replyChannel=org.springframework.messaging.core.GenericMessagingTemplate$TemporaryReplyChannel@77054e87, jms_redelivered=false, lag=49, deviceSessionId=9999, breadcrumbId=ID-s-r-novalocal-43151-1584976153021-0-9607, audit_channel=/service/round/action, jms_correlationId=800da7b4-717b-43a0-b146-428a789dc960, jms_type=DoPlayerAction, partnerId=1300, id=3037b982-083d-b7df-27d3-1a2eff1ee67e, authenticator=c.g.c.i.a.TestVentureAuthenticator, jms_messageId=ID:s-p.n-39946-1584976128611-12:11:29:1:1, memberId=123, timestamp=1585303949558}]
2020-03-27 10:12:30.602 DEBUG 21528 --- [nerContainer-87] .i.j.ChannelPublishingJmsMessageListener : expected a reply but none was received
2020-03-27 10:12:30.603 DEBUG 21528 --- [nerContainer-87] org.apache.activemq.ActiveMQSession      : ID:s-r.n-39350-1585303832228-1:1:40 Transaction Commit :TX:ID:s-r.n-39350-1585303832228-1:1:7
2020-03-27 10:12:30.603 DEBUG 21528 --- [nerContainer-87] org.apache.activemq.TransactionContext   : Commit: TX:ID:s-r.n-39350-1585303832228-1:1:7 syncCount: 1
2020-03-27 10:12:32.355 DEBUG 21528 --- [WriteCheckTimer] o.a.a.t.AbstractInactivityMonitor        : WriteChecker: 10001ms elapsed since last write check.
1
It's hard to say without seeing the rest of the flow and a debug log. Turn on DEBUG logging for org.springframework.integration and check the log timestamps of the message flow through the app.Gary Russell
I think the TracingMessageListenerContainer has to be a bean. I believe it is some extension of an existing container, so some initialization logic has to be done in the afterPropertiesSet().Artem Bilan
Also it would be great to see the code calling that acknowledgement and how your flow looks before that ack call.Artem Bilan
@GaryRussell I've added example of the application side logs to the questionJames
@GaryRussell I half understand now, noticing the log expected a reply but none was received. It turns out in my spring-integration flow I have a service activator that returns null/void. Reading the docs I understand this effectively terminates the flow. The inbound JMS message does not expect a response, and for some reason the flow terminating early causes this delay (rather than acknowleding the JMS message immediately). Perhaps you know why or can suggest workarounds? How to implement a JMS gateway that can handle request-reply and non request-reply on the same queue?James

1 Answers

1
votes

If there is a possibility of no reply, and as long as you don't use any async handoff in your flow (queue channels, executor channels), you can set .replyTimeOut(0L) on the inbound gateway to prevent the default 1 second delay which is intended to wait for an async reply.