Missing/mishandled heartbeats after a few messages

[sobjerke]

consumer.zip

Server: ActiveMQ (5.16.0) with stomp+nio+ssl transport connector
Producer: stomp.py 6.1.0 sending timestamped message every 10 seconds
Consumer: stomp.py (Tested both 6.1.0 and Dev)

Typical output:
2021-01-21 14:02:04: received message: "test message at 2021-01-21 14:02:04"
2021-01-21 14:02:10: received heartbeat
2021-01-21 14:02:14: received heartbeat
2021-01-21 14:02:15: received message: "test message at 2021-01-21 14:02:14"
Heartbeat timeout: diff_receive=6.000141425989568, time=5618406.807629671, lastrec=5618400.807488245
[Errno 0] Error
2021-01-21 14:02:21: stomp disconnected, try to reconnect
2021-01-21 14:02:21: receiver loop ended
2021-01-21 14:02:21: heartbeat timeout
2021-01-21 14:02:25: received message: "test message at 2021-01-21 14:02:25"
2021-01-21 14:02:29: received heartbeat
2021-01-21 14:02:33: received heartbeat
2021-01-21 14:02:43: receiver loop ended
2021-01-21 14:02:43: stomp disconnected, try to reconnect
2021-01-21 14:02:45: received message: "test message at 2021-01-21 14:02:45"
2021-01-21 14:02:51: received heartbeat
2021-01-21 14:02:55: received message: "test message at 2021-01-21 14:02:55"
2021-01-21 14:03:09: receiver loop ended
2021-01-21 14:03:09: stomp disconnected, try to reconnect

Observations:

• until first message is received, heartbeats are received and handled as expected
• after a few messages (typically 1-3), a heartbeat gets missed and on_heartbeat_timeout() is called
• error message "Heartbeat timeout: diff_receive..." is printed only first time a heartbeat is missed
• if a new message is received within the heartbeat interval, the connection in stable and there are no errors
• after the first reconnect, heartbeats are missed (on_heartbeat() not called) and without a call to on_heartbeat_timout()
• on_receiver_loop_completed() is called when a heartbeat is missed
• tcpdump on client shows incoming traffic from MQ server at least every heartbeat interval.

[sobjerke]

To eliminate an incorrectly configured ActiveMQ server, I replaced the configuration with the one supplied in the downloaded tar-file and changed the python code to not use SSL. When analyzing the tcp traffic, I was able to see that the first packet after a message, was not a heartbeat as I believed when I looked at the SSL traffic.

The first heartbeat from ActiveMQ after a message can take up to twice the heartbeat interval to arrive. It seems there is a bug in ActiveMQ that was reported in 2013 and still not resolved even if several patches has been proposed: https://issues.apache.org/jira/browse/AMQ-4710

I worked around the ActiveMQ issue by setting heart_beat_receive_scale=3 in stomp.Connection.

However it still seems there is an issue with stomp.py. After a reconnect, the consumer's receiver loop ends every 2 to 3 heartbeats.