[ARTEMIS-650] At HEAD, Artemis does not honor the zero in 0,xxxx in STOMP Heartbeats

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 1.3.0
• Fix Version/s: 1.4.0
• Component/s: STOMP

Environment

[gmallard@tjjackson bin (dev)]$ uname -a
Linux tjjackson 3.13.0-92-generic #139-Ubuntu SMP Tue Jun 28 20:42:26 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux
[gmallard@tjjackson bin (dev)]$ ./ubuntu-ver.sh
No LSB modules are available.
Distributor ID: Ubuntu
Description: Ubuntu 14.04.4 LTS
Release: 14.04
Codename: trusty
[gmallard@tjjackson bin (dev)]$ java -version
openjdk version "1.8.0_91"
OpenJDK Runtime Environment (build 1.8.0_91-8u91-b14-0ubuntu4~14.04-b14)
OpenJDK 64-Bit Server VM (build 25.91-b14, mixed mode)

1. A 1.4 SANPSHOT build:
   [gmallard@tjjackson activemq-artemis (master)]$ git log -1
   commit 771dab13bfe9e5da2f501d035b08a5861b404566
   Merge: e8b189a e341b54
   Author: jbertram <[e-mail]>
   Date: Thu Jul 21 14:47:20 2016 -0500

This closes #648

• Assignee: Justin Bertram
• Reporter: Guy Allard
• Created: 23/Jul/16 23:11
• Updated: 03/Nov/16 20:41
• Resolved: 25/Jul/16 15:53

Description

Seems like this started between 7bf62ff and 771dab1.

It seems to be triggered by sending a CONNECT frame like:

heart-beat:0,6000

So the client is saying I cannot and will not send heartbeats.

From my test logs at 7bf62ff (where this worked previously):

2016/07/23 17:40:56.668473 ConnHeaders: [login guest passcode guest accept-version 1.1 host localhost heart-beat 0,6000]
2016/07/23 17:40:56.670278 1314019264[TestHB11NoSend connect response CONNECTED [version 1.1 session 1314019264 server ActiveMQ-Artemis/1.4.0-SNAPSHOT ActiveMQ Artemis Messaging Engine heart-beat 6000,0] ]

From my test logs at 771dab1 (where this now fails):

2016/07/23 18:59:38.982344 ConnHeaders: [login guest passcode guest accept-version 1.1 host localhost heart-beat 0,6000]
2016/07/23 18:59:39.045388 -2114425011[TestHB11NoSend connect response CONNECTED [version 1.1 session -2114425011 server ActiveMQ-Artemis/1.4.0-SNAPSHOT ActiveMQ Artemis Messaging Engine heart-beat 6000,500] ]
2016/07/23 18:59:39.045415 -2114425011[TestHB11NoSend start sleep]
2016/07/23 18:59:39.045446 -2114425011[1 Send 0 Receive 6000]
2016/07/23 18:59:42.732338 -2114425011[RDR_READFRAME

{ERROR [message AMQ119014: Did not receive data from /0:0:0:0:0:0:0:1:48576 within the 1,000ms connection TTL. The connection will now be closed.] []}

RDR_RF_ERR <nil>]

Based on broker behavior it seems that the client should be sending heartbeats every 500ms. But the client has already indicated it cannot and will not do that.

What I see in artemis.log:
18:59:25,259 INFO [org.apache.activemq.artemis] AMQ241001: HTTP Server started at http://localhost:9161
18:59:25,259 INFO [org.apache.activemq.artemis] AMQ241002: Artemis Jolokia REST API available at http://localhost:9161/jolokia
18:59:42,730 WARN [org.apache.activemq.artemis.core.server] AMQ222067: Connection failure has been detected: AMQ119014: Did not receive data from /0:0:0:0:0:0:0:1:48576 within the 1,000ms connection TTL. The connection will now be closed. [code=CONNECTION_TIMEDOUT]
18:59:48,736 WARN [org.apache.activemq.artemis.core.protocol.stomp] AMQ222068: connection closed org.apache.activemq.artemis.core.protocol.stomp.StompConnection@3c9de67e

Is is unclear where that '1,000ms' comes from - but it is also incorrect.

FWIW, this is all emanating from the unit tests of this beast:

https://github.com/gmallard/stompngo

Issue Links

• links to: GitHub Pull Request #656
• links to: GitHub Pull Request #657