Spring Sending message to ActiveMQ takes longer than the specified timeout

Affects: org.springframework:spring-jms:5.3.14

Setup

Service with Spring Version 5.3.14
ActiveMQ mq.t3.micro with no free space
application.config:

  activemq:
    broker-url: failover:(ssl://<someURL>:61617,ssl://<someURL>:61617)?randomize=true&maxReconnectAttempts=1&startupMaxReconnectAttempts=1&maxReconnectDelay=2000
    user:<someUser>
    password: <somePassword>
    send-timeout: 3000
    pool:
      enabled: true
      max-connections: 20
  jms:
    template:
      qos-enabled: true
      time-to-live: 86400000
    pub-sub-domain: true
    cache:
      enabled: false

Expected behavior

If the method public void send(final String destinationName, final MessageCreator messageCreator) throws JmsException in the JmsTemplate class is executed, the maximum running time is as in send-timeout configured, about 3 seconds.

Observed behavior

We see some calls that go up to 5 minutes in execution time, when this jms method is called.

It is interesting, however, as soon as a TCP connection to the MQ is established, the 3 seconds are running out and the Lib then throws a timeout as expected org.apache.activemq.transport.RequestTimedOutIOException the activemq log does not contain any useful information. The only warnings we see are:

2022-03-02 06:58:12,093 | WARN | Transport Connection to: tcp://<someIP>:40600 failed | org.apache.activemq.broker.TransportConnection.Transport | ActiveMQ InactivityMonitor Worker
java.net.SocketException: Connection reset
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:115)[:1.8.0_322]
at java.net.SocketOutputStream.write(SocketOutputStream.java:155)[:1.8.0_322]
at sun.security.ssl.SSLSocketOutputRecord.deliver(SSLSocketOutputRecord.java:319)[:1.8.0_322]
at sun.security.ssl.SSLSocketImpl$AppOutputStream.write(SSLSocketImpl.java:1214)[:1.8.0_322]
at org.apache.activemq.transport.tcp.TcpBufferedOutputStream.flush(TcpBufferedOutputStream.java:115)[activemq-client-5.15.15.jar:5.15.15]
at java.io.DataOutputStream.flush(DataOutputStream.java:123)[:1.8.0_322]
at org.apache.activemq.transport.tcp.TcpTransport.oneway(TcpTransport.java:194)[activemq-client-5.15.15.jar:5.15.15]
at org.apache.activemq.transport.AbstractInactivityMonitor.doOnewaySend(AbstractInactivityMonitor.java:335)[activemq-client-5.15.15.jar:5.15.15]
at org.apache.activemq.transport.AbstractInactivityMonitor.access$800(AbstractInactivityMonitor.java:42)[activemq-client-5.15.15.jar:5.15.15]
at org.apache.activemq.transport.AbstractInactivityMonitor$4.run(AbstractInactivityMonitor.java:201)[activemq-client-5.15.15.jar:5.15.15]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)[:1.8.0_322]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)[:1.8.0_322]
at java.lang.Thread.run(Thread.java:750)[:1.8.0_322]

2022-03-02 06:58:12,093 | WARN | Transport Connection to: tcp://<someIP>:40600 failed | org.apache.activemq.broker.TransportConnection.Transport | ActiveMQ InactivityMonitor Worker java.net.SocketException: Connection reset at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:115)[:1.8.0_322] at java.net.SocketOutputStream.write(SocketOutputStream.java:155)[:1.8.0_322] at sun.security.ssl.SSLSocketOutputRecord.deliver(SSLSocketOutputRecord.java:319)[:1.8.0_322] at sun.security.ssl.SSLSocketImpl$AppOutputStream.write(SSLSocketImpl.java:1214)[:1.8.0_322] at org.apache.activemq.transport.tcp.TcpBufferedOutputStream.flush(TcpBufferedOutputStream.java:115)[activemq-client-5.15.15.jar:5.15.15] at java.io.DataOutputStream.flush(DataOutputStream.java:123)[:1.8.0_322] at org.apache.activemq.transport.tcp.TcpTransport.oneway(TcpTransport.java:194)[activemq-client-5.15.15.jar:5.15.15] at org.apache.activemq.transport.AbstractInactivityMonitor.doOnewaySend(AbstractInactivityMonitor.java:335)[activemq-client-5.15.15.jar:5.15.15] at org.apache.activemq.transport.AbstractInactivityMonitor.access$800(AbstractInactivityMonitor.java:42)[activemq-client-5.15.15.jar:5.15.15] at org.apache.activemq.transport.AbstractInactivityMonitor$4.run(AbstractInactivityMonitor.java:201)[activemq-client-5.15.15.jar:5.15.15] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)[:1.8.0_322] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)[:1.8.0_322] at java.lang.Thread.run(Thread.java:750)[:1.8.0_322]

However, we could not determine any temporal connection between these warnings and the behavior that occurred. In our application are also no debug logs which could help us to identify the root cause.

Conclusion

There seems to be something in the send messag methode, that in some cases is taking too much time, till it starts to connect to the ActiveMQ

Edit: There seems to be a connection to failover of an mq. We could observe the same behavior when we changed our broker's configuration (disable multi-A-Z).

Thank you in advance for your help. :)

Comment From: snicoll

There seems to be a connection to failover of an mq. We could observe the same behavior when we changed our broker's configuration (disable multi-A-Z).

If you can observe such difference in behavior by changing the configuration of the broker, that looks like a broker problem to me. If you feel differently, please share a small sample that we can run ourselves to reproduce the problem as I am afraid a config snippet is not enough. You can attach a zip to this issue or push the code to a separate GitHub repository.

Comment From: spring-projects-issues

If you would like us to look at this issue, please provide the requested information. If the information is not provided within the next 7 days this issue will be closed.

Comment From: spring-projects-issues

Closing due to lack of requested feedback. If you would like us to look at this issue, please provide the requested information and we will re-open the issue.