Search code examples
spring-bootspring-integrationjmsspring-jms

Spring integration JMS late transaction acknowledgement & commit


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.

Solution

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