STOMP plugin heartbeats not being honored (using web STOMP)

[Doug Reese]

Here is what I observe in the connect frames:

STOMP

accept-version:1.2

host:<host>

login:<user>

passcode:<pass>

heartbeat:5000,5000

CONNECTED

server:RabbitMQ/3.7.8

session:session-TjFWCy6CuEaLIKoRmgNu1Q

heart-beat:0,0

version:1.2

Notice the response heart-beat:0,0.  I am using all the default configuration for the STOMP plugin -- nothing in the config file for the plugin.  I am also using the web STOMP plugin.  The output above is from the Chrome dev tools Network information.

I started down this path because my (web) STOMP connection is being killed after 60 seconds of inactivity.  I have read through the docs, and searched the various help sites (SO, etc.), but cannot find anything similar to my situation.  I was initially not using a heart-beat value, and theorized not having a heart-beat might be the reason for the connection being killed.  There is nothing in the log related to the STOMP plugins.

Non-STOMP connections work fine and do not time out.  I have tried different heart-beat values and the CONNECTED response is always 0.

Ubuntu 16.04.5 LTS

Startup sequence from log file follows.

Side question: why is "rabbit_stomp: default user 'guest' enabled" when there are no "stomp.*" options in the config file?  I tested setting default_user to an empty string, and then get "default user '""' enabled" instead of 'guest'.  I cannot seem to disable a default user login for the STOMP plugin.  Am I missing a configuration setting in the docs?

Thanks

2018-10-24 20:12:13.315 [info] <0.7.0> Log file opened with Lager

2018-10-24 20:12:14.238 [info] <0.238.0> 

 Starting RabbitMQ 3.7.8 on Erlang 21.1

 Copyright (C) 2007-2018 Pivotal Software, Inc.

 Licensed under the MPL.  See http://www.rabbitmq.com/

2018-10-24 20:12:14.240 [info] <0.238.0> 

 node           : rabbit@msg01-dev

 home dir       : /var/lib/rabbitmq

 config file(s) : /etc/rabbitmq/rabbitmq.conf

 cookie hash    : iVscnDfFmHK9oOLnGA+ZTA==

 log(s)         : /var/log/rabbitmq/rab...@msg01-dev.log

                : /var/log/rabbitmq/rabbit@msg01-dev_upgrade.log

 database dir   : /var/lib/rabbitmq/mnesia/rabbit@msg01-dev

2018-10-24 20:12:14.473 [info] <0.280.0> Memory high watermark set to 800 MiB (838868992 bytes) of 2000 MiB (2097172480 bytes) total

2018-10-24 20:12:14.476 [info] <0.282.0> Enabling free disk space monitoring

2018-10-24 20:12:14.476 [info] <0.282.0> Disk free limit set to 50MB

2018-10-24 20:12:14.479 [info] <0.285.0> Limiting to approx 32668 file handles (29399 sockets)

2018-10-24 20:12:14.479 [info] <0.286.0> FHC read buffering:  OFF

2018-10-24 20:12:14.479 [info] <0.286.0> FHC write buffering: ON

2018-10-24 20:12:14.480 [info] <0.238.0> Waiting for Mnesia tables for 30000 ms, 9 retries left

2018-10-24 20:12:14.503 [info] <0.238.0> Waiting for Mnesia tables for 30000 ms, 9 retries left

2018-10-24 20:12:14.503 [info] <0.238.0> Peer discovery backend rabbit_peer_discovery_classic_config does not support registration, skipping registration.

2018-10-24 20:12:14.504 [info] <0.238.0> Priority queues enabled, real BQ is rabbit_variable_queue

2018-10-24 20:12:14.514 [info] <0.306.0> Starting rabbit_node_monitor

2018-10-24 20:12:14.535 [info] <0.238.0> Management plugin: using rates mode 'basic'

2018-10-24 20:12:14.536 [info] <0.338.0> Making sure data directory '/var/lib/rabbitmq/mnesia/rabbit@msg01-dev/msg_stores/vhosts/628WB79CIFDYO9LJI6DKMI09L' for vhost '/' exists

2018-10-24 20:12:14.552 [info] <0.338.0> Starting message stores for vhost '/'

2018-10-24 20:12:14.552 [info] <0.342.0> Message store "628WB79CIFDYO9LJI6DKMI09L/msg_store_transient": using rabbit_msg_store_ets_index to provide index

2018-10-24 20:12:14.552 [info] <0.338.0> Started message store of type transient for vhost '/'

2018-10-24 20:12:14.552 [info] <0.345.0> Message store "628WB79CIFDYO9LJI6DKMI09L/msg_store_persistent": using rabbit_msg_store_ets_index to provide index

2018-10-24 20:12:14.553 [info] <0.338.0> Started message store of type persistent for vhost '/'

2018-10-24 20:12:14.555 [info] <0.380.0> started TCP Listener on [::]:5672

2018-10-24 20:12:14.556 [info] <0.396.0> started SSL Listener on [::]:5671

2018-10-24 20:12:14.557 [info] <0.238.0> Setting up a table for connection tracking on this node: 'tracked_connection_on_node_rabbit@msg01-dev'

2018-10-24 20:12:14.557 [info] <0.238.0> Setting up a table for per-vhost connection counting on this node: 'tracked_connection_per_vhost_on_node_rabbit@msg01-dev'

2018-10-24 20:12:14.561 [info] <0.449.0> rabbit_stomp: default user 'guest' enabled

2018-10-24 20:12:14.561 [info] <0.465.0> started STOMP TCP Listener on [::]:61613

2018-10-24 20:12:14.564 [info] <0.478.0> rabbit_web_stomp: listening for HTTP connections on 0.0.0.0:15674

2018-10-24 20:12:14.585 [info] <0.501.0> Management plugin started. Port: 15672

2018-10-24 20:12:14.585 [info] <0.607.0> Statistics database started.

2018-10-24 20:12:14.614 [notice] <0.115.0> Changed loghwm of /var/log/rabbitmq/rab...@msg01-dev.log to 50

2018-10-24 20:12:14.702 [info] <0.7.0> Server startup complete; 8 plugins started.

 * rabbitmq_tracing

 * rabbitmq_management

 * rabbitmq_web_dispatch

 * rabbitmq_web_stomp

 * rabbitmq_auth_backend_cache

 * rabbitmq_stomp

 * rabbitmq_auth_backend_http

 * rabbitmq_management_agent

[Loïc Hoguin]

Hello,

If I recall the heartbeat from the server will always be 0 when
connecting via Websocket, and you are expected to use Websocket's ping
mechanism instead.

But I could be wrong, it's been a while since I looked at this.

Cheers,

> --
> You received this message because you are subscribed to the Google
> Groups "rabbitmq-users" group.
> To unsubscribe from this group and stop receiving emails from it, send
> an email to rabbitmq-user...@googlegroups.com
> <mailto:rabbitmq-user...@googlegroups.com>.
> To post to this group, send email to rabbitm...@googlegroups.com
> <mailto:rabbitm...@googlegroups.com>.
> For more options, visit https://groups.google.com/d/optout.

--
Loïc Hoguin
https://ninenines.eu

[Michael Klishin]

Do you have a way to reproduce? We'd be happy to revisit some of these decisions in 3.7.10 where

we'll likely be upgrading Ranch and Cowboy and refactoring Web STOMP and Web MQTT to go with that.

--
You received this message because you are subscribed to the Google Groups "rabbitmq-users" group.

To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-user...@googlegroups.com.
To post to this group, send email to rabbitm...@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--

MK

Staff Software Engineer, Pivotal/RabbitMQ

[Doug Reese]

Hi Michael,

Thanks for your response.  After digging a little more, yes, I can reproduce with netcat, and it does not seem to be related to the web STOMP plugin.

From Linux CLI, not using websockets:

nc <RabbitMQ server> 61613
STOMP                   <-- entered or pasted in

accept-version:1.2
host:<host>
login:<user>
passcode:<pass>
heartbeat:5000,5000
 

^@                      <-- NULL character

Response:

 

CONNECTED
server:RabbitMQ/3.7.8
session:session-O4WICKEdA_ceYNZGfuNa_w
heart-beat:0,0
version:1.2

However, contrary to my browser situation, my nc "client" is not disconnected after a period of inactivity.  So perhaps my disconnect is in the client, but still related to the 0,0 heartbeat response.  I have to do some more digging in my client, but the 0,0 heartbeat response still exists.

Did I stumble into two legitimate issues?

• 0,0 heart-beat in CONNECTED response
• "rabbit_stomp: default user 'guest' enabled" when there are no "stomp.*" options in the config file (now highlighted in my quoted log output from initial post)
  

Doug

 log(s)         : /var/log/rabbitmq/rabbit@msg01-dev.log

2018-10-24 20:12:14.614 [notice] <0.115.0> Changed loghwm of /var/log/rabbitmq/rabbit@msg01-dev.log to 50

2018-10-24 20:12:14.702 [info] <0.7.0> Server startup complete; 8 plugins started.

 * rabbitmq_tracing

 * rabbitmq_management

 * rabbitmq_web_dispatch

 * rabbitmq_web_stomp

 * rabbitmq_auth_backend_cache

 * rabbitmq_stomp

 * rabbitmq_auth_backend_http

 * rabbitmq_management_agent

--
You received this message because you are subscribed to the Google Groups "rabbitmq-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-user...@googlegroups.com.
To post to this group, send email to rabbitm...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Michael Klishin]

Heartbeats are *negotiated* between peers, including in STOMP (IIRC).

Plugins have default settings, as does the broker. Credentials are needed to support implicit connections [1].

You can disable implicit connect and the default credentials won't be used. They won't be used if your clients authenticate

with their own, obviously.

1. https://github.com/rabbitmq/rabbitmq-stomp/blob/master/priv/schema/rabbitmq_stomp.schema#L100

[Michael Klishin]

Implicit connection has a doc section [1], I didn't mean to link to the schema file.

1. http://www.rabbitmq.com/stomp.html#cta.ic

[Michael Klishin]

Implicit connection has a doc section [1], I didn't mean to link to the schema file.

1. http://www.rabbitmq.com/stomp.html#cta.ic

On Thursday, October 25, 2018 at 10:37:41 PM UTC+3, Michael Klishin wrote:

[Doug Reese]

Thanks again for responding.  I didn't intend for this thread to be an analysis of STOMP heart-beating (or plugin configuration defaults).  I was initially trying to understand why my connection is closing and figured I would try adding the heart-beat values.  When I saw the 0,0 my initial thought was I am likely missing something.  And I still may be missing something.

Based on my basic understanding of the heart-beating section in the STOMP Protocol Specification, I expect the server to respond to client initial heart-beat values with heart-beat values that are at least non-zero, and ideally match the client request.  The 0,0 value indicates the server does not support heart-beating, which may be the case.  I can't find anything in the docs.  I tried looking through the the plugin source code, but erlang makes no sense to me.  Maybe some day.  I think I found a test for heart-beat values, which implies heart-beat values are supported, but it's not clear to me how the test is verified as passing.  Again, the erlang thing.


Regarding the plugin default settings and credentials:  

I think I understand what is happening now, and I believe it was the stomp guest related log entry that was confusing me.  I tested a few scenarios in an attempt to hopefully better understand what is happening.

My client logins are authenticated using

• auth_backends.1 = internal
  
• auth_backends.2 = cache
  
• auth_backends.3 = http
  

There are no client user/pass combinations in RabbitMQ users -- only in the backend systems.  The vhost exists in RabbitMQ.

Scenario 1

No stomp related options in config file.

Startup message in log file:

2018-10-25 19:49:48.369 [info] <0.708.0> rabbit_stomp: default user 'guest' enabled

App client login result: client auth succeeds (my response from previous post)

Login using no specified login/passcode:

STOMP
accept-version:1.2

Result:

ERROR
message:Bad CONNECT
content-type:text/plain
version:1.0,1.1,1.2
content-length:32


Access refused for user 'guest'

The failed login is expected, since there is no guest user in RabbitMQ or in my backend. The "default user 'guest' enabled" log message implies the guest/guest login is enabled, which is verified by the error message.  It is not documented that having no default_user/default_pass in the config file results in the 'guest' default user being enabled.

Scenario 2

Stomp related options in config:

stomp.implicit_connect = true

Startup message in log file:

2018-10-25 20:28:04.433 [info] <0.708.0> rabbit_stomp: default user 'guest' enabled
2018-10-25 20:28:04.433 [info] <0.708.0> rabbit_stomp: implicit connect enabled~n   <-- not a copy/paste artifact; it's in the log file

Result: app client auth succeeds

Login using no specified login/passcode:  Access refused for user 'guest'

Expected, as I'm not eliminating the connect frame and I'm not using an SSL cert in my dev environment.  Still the default_user seems to be set to 'guest' based on my log file and login error.

Scenario 3

Stomp related options in config:

stomp.default_user = guest
stomp.default_pass = guest
stomp.implicit_connect = true

Log:

2018-10-25 20:32:38.822 [info] <0.538.0> rabbit_stomp: default user 'guest' enabled
2018-10-25 20:32:38.822 [info] <0.538.0> rabbit_stomp: implicit connect enabled~n

Result: app client auth succeeds

Login using no specified login/passcode:  Access refused for user 'guest'

In this case the log file and no specified login response matches config settings.

Scenario 4

Stomp related options in config:

stomp.default_user = <user that exists in my backend>
stomp.default_pass = <password that exists in my backend>
stomp.implicit_connect = false

Log:

2018-10-25 20:58:06.154 [info] <0.582.0> rabbit_stomp: default user '<user that exists in my backend>' enabled

Client auth result: succeeds

Login using no specified login/passcode: succeeds

Expected behavior, with the log file and no specified login matches config settings.

So my takeaway from this is that even without stomp.default_user/stomp.default_pass config settings, guest/guest is being used.  While that is not a problem for me, since I don't have any guest/guest logins anywhere, it is not documented as guest/guest being enabled as a default.  As such, the default user log entry had me initially thinking there was a guest user enabled somewhere.  I now know that is not the case, but that was not initially clear.

Thanks again for your time and indulging me here.

Doug

[Luke Bakken]

Hi Doug,

You aren't formatting the connect frame correctly. It appears that you are using an extra newline after STOMP which confuses the parser and prevents the headers from being parsed correctly.

https://stomp.github.io/stomp-specification-1.2.html#STOMP_Frames

I've attached a file that has a correctly-formatted connect frame and tested it against my local RabbitMQ server this way:

nc localhost 61613 < stomp.bin

Output:

$ nc localhost 61613 < stomp.bin

CONNECTED

server:RabbitMQ/3.7.8+15.g819d49a

session:session-okDaQZqezxSnOyrXGoVdUw

heart-beat:5000,5000

version:1.2

If I let the connection sit idle the heartbeat mechanism closes it as expected.

I haven't had a chance to investigate your other question just yet, with regard to the guest user.

Thanks,

Luke

[Doug Reese]

Hi Luke,

Thanks for that.  An extra newline wasn't the problem, but comparing your binary to mine showed me the actual problem:  heartbeat vs. heart-beat

This is a problem in the client library I'm using (not written by me).

I was actually just pasting the frame text (copied from the Chrome WS info) into the terminal, not using a file.  Even pasting it into the terminal, the output is correct with the proper header name.

I feel silly not noticing it before, but I learned a bit more about STOMP today than I had planned.  Not a bad thing.

Doug

[Michael Klishin]

Thank you for reporting back. I definitely recall being bit by the same spelling difference.

What client is that? It should be possible to support both options on the RabbitMQ end but we could also

consider contributing a non-breaking change to the client.

--

You received this message because you are subscribed to the Google Groups "rabbitmq-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-user...@googlegroups.com.
To post to this group, send email to rabbitm...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Michael Klishin]

Thank you for your contribution and getting back to the list!

On Sat, Nov 3, 2018 at 2:20 AM Doug Reese <do...@reesesystems.com> wrote:

This is a Dart package.  https://pub.dartlang.org/packages/stomp

I submitted a pull request, which was merged into master.  There are a lot of breaking changes in my pull request, related to Dart 2 being released, so backward compatibility is not really a concern.  

https://github.com/rikulo/stomp/pull/17

Thanks for everyone's help on tracking this down.