stompgem / stomp

A ruby gem for sending and receiving messages from a Stomp protocol compliant message queue. Includes: failover logic, ssl support.
http://stomp.github.com
Apache License 2.0
152 stars 80 forks source link

Ruby process crashes after creating Stomp::Client #136

Closed glyoko closed 7 years ago

glyoko commented 7 years ago

I just started looking into this gem to work with ArtemisMQ and I'm running into a problem where my interpreter just straight up crashes about a minute after calling Stomp::Client.new(CLIENT_CONFIG).

I suspect that something about heartbeat functionality is causing this. I'm working against an Artemis instance which expects a heartbeat and disconnects if it doesn't receive one after a minute. The error message I'm getting (which appears immediately before the interpreter crash) is:

/Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/input-method.rb:151:in `readline': AMQ119014: Did not receive data from /172.17.0.1:53236 within the 60,000ms connection TTL. The connection will now be closed. (Stomp::Error::BrokerException)

I'm using ruby 2.3.1 and the Artemis instance I'm working against is dockerized at https://github.com/vromero/activemq-artemis-docker. I'm running OSX 10.11.6.

The client config I'm initializing Stomp::Client with is:

{
  hosts: [
    {login: "artemis", passcode: "simetraehcapa", host: "localhost", port: 61613}
  ],
  reliable: true,
  initial_reconnect_delay: 0.01,
  max_reconnect_delay: 30.0,
  use_exponential_back_off: true,
  back_off_multiplier: 2,
  max_reconnect_attempts: 0,
  randomize: false,
  connect_timeout: 0,
  connect_headers: {},
  parse_timeout: 5,
  logger: nil,
  dmh: false,
  closed_check: true,
  hbser: true,
  stompconn: false,
  usecrlf: false,
  max_hbread_fails: 0,
  max_hbrlck_fails: 0,
  fast_hbs_adjust: 20.0,
  tcp_nodelay: true,
  start_timeout: 0,
  sslctx_newparm: nil,
  ssl_post_conn_check: true
}
glyoko commented 7 years ago

Some more information...

Here's the full error trace for the crash, including the output from Slogger and the lower level stuff. The only thing I changed in the output is my username.

(The username/password in the output is just the default credentials for https://github.com/vromero/activemq-artemis-docker so it doesn't matter that they're exposed)

2.3.1 :003 > c = Stomp::Client.new( CLIENT_CONFIG )
 => #<Stomp::Client:0x007f97ec01f230 @parameters={:hosts=>[{:login=>"artemis", :passcode=>"simetraehcapa", :host=>"localhost", :port=>61613}], :reliable=>true, :initial_reconnect_delay=>0.01, :max_reconnect_delay=>30.0, :use_exponential_back_off=>true, :back_off_multiplier=>2, :max_reconnect_attempts=>0, :randomize=>false, :connect_timeout=>0, :connect_headers=>{}, :parse_timeout=>5, :logger=>#<Stomp::NullLogger:0x007f97ec01f168>, :dmh=>false, :closed_check=>true, :hbser=>true, :stompconn=>false, :usecrlf=>false, :max_hbread_fails=>0, :max_hbrlck_fails=>0, :fast_hbs_adjust=>20.0, :tcp_nodelay=>true, :start_timeout=>0, :sslctx_newparm=>nil, :ssl_post_conn_check=>true}, @logger=#<Stomp::NullLogger:0x007f97ec01f168>, @start_timeout=0, @error_listener=#<Proc:0x007f97ec01f0a0@/Users/my-user-name/.rvm/gems/ruby-2.3.1@my-gemset/gems/stomp-1.4.3/lib/stomp/client.rb:111 (lambda)>, @connection=#<Stomp::Connection:0x007f97ec01f028 @protocol="1.0", @hb_received=true, @hb_sent=true, @hbr=false, @hbs=false, @jruby=false, @st=nil, @rt=nil, @hhas10=false, @socket=#<TCPSocket:fd 11>, @closed=false, @parameters={:connect_headers=>{}, :reliable=>true, :initial_reconnect_delay=>0.01, :max_reconnect_delay=>30.0, :use_exponential_back_off=>true, :back_off_multiplier=>2, :max_reconnect_attempts=>0, :randomize=>false, :connect_timeout=>0, :parse_timeout=>5, :dmh=>false, :closed_check=>true, :hbser=>true, :stompconn=>false, :max_hbread_fails=>0, :max_hbrlck_fails=>0, :fast_hbs_adjust=>20.0, :connread_timeout=>0, :tcp_nodelay=>true, :start_timeout=>0, :sslctx_newparm=>nil, :ssl_post_conn_check=>true, :hosts=>[{:login=>"artemis", :passcode=>"simetraehcapa", :host=>"localhost", :port=>61613}], :logger=>#<Stomp::NullLogger:0x007f97ec01f168>, :usecrlf=>false}, @reliable=true, @reconnect_delay=0.01, @connect_headers={}, @parse_timeout=5, @connect_timeout=0, @logger=#<Stomp::NullLogger:0x007f97ec01f168>, @autoflush=false, @closed_check=true, @hbser=true, @stompconn=false, @usecrlf=false, @max_hbread_fails=0, @max_hbrlck_fails=0, @fast_hbs_adjust=20.0, @connread_timeout=0, @sslctx_newparm=nil, @ssl_post_conn_check=true, @ssl=nil, @host="localhost", @port=61613, @login="artemis", @passcode="simetraehcapa", @transmit_semaphore=#<Thread::Mutex:0x007f97ec81f930>, @read_semaphore=#<Thread::Mutex:0x007f97ec81f908>, @socket_semaphore=#<Thread::Mutex:0x007f97ec81f890>, @subscriptions={}, @failure=nil, @connection_attempts=0, @iosto=5.0, @connection_frame=#<Stomp::Message:0x007f97ec81ea58 @command="CONNECTED", @headers={"session"=>"-1113647778"}, @body="", @original="CONNECTED\nsession:-1113647778\n\n\u0000">, @disconnect_receipt=nil, @session="-1113647778">, @listeners={}, @receipt_listeners={}, @replay_messages_by_txn={}, @listener_map={"MESSAGE"=>#<Proc:0x007f97ec81e148@/Users/my-user-name/.rvm/gems/ruby-2.3.1@my-gemset/gems/stomp-1.4.3/lib/client/utils.rb:179 (lambda)>, "RECEIPT"=>#<Proc:0x007f97ec81e0f8@/Users/my-user-name/.rvm/gems/ruby-2.3.1@my-gemset/gems/stomp-1.4.3/lib/client/utils.rb:180 (lambda)>, "ERROR"=>#<Proc:0x007f97ec01f0a0@/Users/my-user-name/.rvm/gems/ruby-2.3.1@my-gemset/gems/stomp-1.4.3/lib/stomp/client.rb:111 (lambda)>}, @listener_thread=#<Thread:0x007f97ec81e058@/Users/my-user-name/.rvm/gems/ruby-2.3.1@my-gemset/gems/stomp-1.4.3/lib/client/utils.rb:188 sleep>> 
2.3.1 :004 > 
2.3.1 :005 > # after about 60 seconds, the below happened  
2.3.1 :006 >   
on_miscerr
{:connect_headers=>{}, :reliable=>true, :initial_reconnect_delay=>0.01, :max_reconnect_delay=>30.0, :use_exponential_back_off=>true, :back_off_multiplier=>2, :max_reconnect_attempts=>0, :randomize=>false, :connect_timeout=>0, :parse_timeout=>5, :dmh=>false, :closed_check=>true, :hbser=>true, :stompconn=>false, :max_hbread_fails=>0, :max_hbrlck_fails=>0, :fast_hbs_adjust=>20.0, :connread_timeout=>0, :tcp_nodelay=>true, :start_timeout=>0, :sslctx_newparm=>nil, :ssl_post_conn_check=>true, :hosts=>[{:login=>"artemis", :passcode=>"simetraehcapa", :host=>"localhost", :port=>61613}], :logger=>#<Stomp::NullLogger:0x007f97ec01f168>, :usecrlf=>false, :cur_host=>"localhost", :cur_port=>61613, :cur_login=>"artemis", :cur_passcode=>"simetraehcapa", :cur_ssl=>nil, :cur_recondelay=>0.01, :cur_parseto=>5, :cur_conattempts=>0, :cur_failure=>nil, :openstat=>true}
es_recv: connection.receive returning EOF as nil - resetting connection.

/Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/input-method.rb:151:in `readline': AMQ119014: Did not receive data from /172.17.0.1:53236 within the 60,000ms connection TTL. The connection will now be closed. (Stomp::Error::BrokerException)
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/input-method.rb:151:in `gets'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb.rb:469:in `block (2 levels) in eval_input'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb.rb:623:in `signal_status'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb.rb:468:in `block in eval_input'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/ruby-lex.rb:189:in `buf_input'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/ruby-lex.rb:104:in `getc'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/slex.rb:206:in `match_io'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/slex.rb:76:in `match'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/ruby-lex.rb:283:in `token'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/ruby-lex.rb:265:in `lex'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/ruby-lex.rb:236:in `block (2 levels) in each_top_level_statement'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/ruby-lex.rb:232:in `loop'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/ruby-lex.rb:232:in `block in each_top_level_statement'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/ruby-lex.rb:231:in `catch'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/ruby-lex.rb:231:in `each_top_level_statement'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb.rb:485:in `eval_input'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb.rb:395:in `block in start'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb.rb:394:in `catch'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb.rb:394:in `start'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/bin/irb:11:in `<main>'

The only stacktrace has to do with irb IO. I put those steps into a stomp-test.sh file with the following:

#!/usr/bin/env /Users/my-user-name/.rvm/rubies/ruby-2.3.1/bin/ruby
Stomp::Client.new CLIENT_CONFIG
sleep 120 # prevent the script from exiting for at least a minute.

And the results were similar, but excluded the irb stuff. It actually has the error tracing back to the sleep line...

./stomp-test.sh:3:in `sleep': AMQ119014: Did not receive data from /172.17.0.1:53240 within the 60,000ms connection TTL. The connection will now be closed. (Stomp::Error::BrokerException)
  from ./stomp-test.sh:3:in `<main>'
gmallard commented 7 years ago

Thanks for all the details in this report.

However, this is not a gem problem. Please read on.

You are not using STOMP heartbeats. Per your connection hash, you are using a STOMP 1.0 connection, and 1.0 does not "do heartbeats".

Your problem is also not related to Ruby version, OSX or docker.

It is triggered by default Artemis behavior.

Please get the latest Artemis documentation. It can be found here:

https://activemq.apache.org/artemis/docs.html

Read the section on STOMP and Artemis TTLs. Beginning on page 353. In particular note this part:

Since Stomp 1.0 does not support heart-beating then all connections from Stomp 1.0
clients will have a connection TTL imposed upon them by the broker based on the
aforementioned configuration options.

I struggled with this same thing when I first started testing against Artemis. It is the only broker I know of that exhibits this kind of behavior by default.

You have two choices:

1) Reconfigure your Artemis STOMP acceptor element to have a default connection TTL of a high value. I do this here when I test against Artemis. The Artemis configuration I use can be seen here:

https://gist.github.com/gmallard/43f64ee1364feaf57842e76b1c67e1d6

2) Reconfigure your stomp client to use protocol level 1.2, and really ask for STOMP heartbeats that are sufficiently frequent that they satisfy artemis. Assuming that your stomp client does nothing "unusual", you should not require code changes to use STOMP 1.2. Add something like the following to your connection hash

 :connect_headers => {"accept-version" => "1.2",
  "host" => "localhost",
  "heart-beat" => "30000,30000",
  },

What ever you do, let me know if you need assistance. I am willing to help.

To summarize: not a gem issue. Please close this at your first convenience.

Regards, Guy

gmallard commented 7 years ago

In the absence of further information I am closing this. If you need to add additional background information, please re-open.

glyoko commented 7 years ago

Sorry for taking so long to get to you on this. I was able to get things working with your advice and I am no longer having disconnect/crashing problems. I had that tome of documentation in front of me, but it would have taken forever to hunt down that problem myself, so thank you for the help.

However, this still seems like a problem to me. While a disconnect (or maybe raising an Exception?) would make sense in this situation, I was getting a total interpreter crash. That shouldn't happen regardless of other behavior... I'll leave this closed and let you decide whether this is worth addressing.

gmallard commented 7 years ago

What version (exactly) of Artemis are you running? For the original problem I saw, I opened a Jira issue against Artemis. And it was reported as fixed in Artemis 1.4. See:

Artemis Jira 650 https://issues.apache.org/jira/browse/ARTEMIS-650

They have not really fixed it to my satisfaction. And I do not now think that they will. They have some unusual ideas about "protecting the broker".

However, you might be seeing something different. Show me a stack trace please.

When I first saw this I was getting a 'Broken Pipe' runtime exception. Hardly an interpreter crash, just a runtime exception. You should handle that in your code using 'begin/rescue/end'. Just like you would in Java, C#, .... or almost any other OO language with try/catch logic.

An example: https://gist.github.com/gmallard/52c9a2137db0c48721364775647a9f89

I could put exception processing into the gem. But to what point? The only reasonable thing I could do would be to re-raise. And you would then have to catch that in a begin/rescue

I do not understand your comment about 'disconnect'. The broker has already closed the connection. A STOMP DISCONNECT would be pointless. The broker would never see it, and it would likely fail in the gem trying to write it to a closed (non-existent) connection.

In any case send the stack trace please.

Regards, Guy

On 01/10/2017 05:21 PM, Adam Braman wrote:

Sorry for taking so long to get to you on this. I was able to get things working with your advice and I am no longer having disconnect/crashing problems. I had that tome of documentation in front of me, but it would have taken forever to hunt down that problem myself, so thank you for the help.

However, this still seems like a problem to me. While a disconnect (or maybe raising an Exception?) would make sense in this situation, I was getting a total interpreter crash. That shouldn't happen regardless of other behavior... I'll leave this closed and let you decide whether this is worth addressing.

— You are receiving this because you modified the open/close state. Reply to this email directly, view it on GitHub https://github.com/stompgem/stomp/issues/136#issuecomment-271716927, or mute the thread https://github.com/notifications/unsubscribe-auth/AAAbv9-4DWIv_3Rr2jen7vbDJ5xVXNBUks5rRASFgaJpZM4LX9CZ.

glyoko commented 7 years ago

The Artemis instance I'm testing against is version 1.5.0. If you want to poke around in it, you can find a dockerized version of the artemis instance at https://github.com/vromero/activemq-artemis-docker. (I'm using the latest tag)

I never got a broken pipe exception, but instead had a complete interpreter crash. The stack trace–printed just before the interpreter crashed–is in my second comment in this thread.

When I said "disconnect/crashing problems", I should have just said "crashing problems". But more generally it would nice if there were a programatic way to detect when an unexpected disconnect occurs. I was suggesting that this could be done by raising an exception. Apologies, you have Stomp::Error::BrokerException doing precisely this. I wasn't seeing it because the irb crash was overshadowing it.

Reproducing the stack trace here:

2.3.1 :010 > Stomp::Client.new DEFAULT_CLIENT_CONFIG
 => #<Stomp::Client:0x007fd3458a6590 @parameters={:hosts=>[{:login=>"artemis", :passcode=>"simetraehcapa", :host=>"localhost", :port=>61613}], :reliable=>true, :initial_reconnect_delay=>0.01, :max_reconnect_delay=>30.0, :use_exponential_back_off=>true, :back_off_multiplier=>2, :max_reconnect_attempts=>0, :randomize=>false, :connect_timeout=>0, :connect_headers=>{}, :parse_timeout=>5, :logger=>#<Stomp::NullLogger:0x007fd3458a6518>, :dmh=>false, :closed_check=>true, :hbser=>true, :stompconn=>false, :usecrlf=>false, :max_hbread_fails=>0, :max_hbrlck_fails=>0, :fast_hbs_adjust=>20.0, :tcp_nodelay=>true, :start_timeout=>0, :sslctx_newparm=>nil, :ssl_post_conn_check=>true}, @logger=#<Stomp::NullLogger:0x007fd3458a6518>, @start_timeout=0, @error_listener=#<Proc:0x007fd3458a6478@/Users/my-user-name/.rvm/gems/ruby-2.3.1@fern/gems/stomp-1.4.3/lib/stomp/client.rb:111 (lambda)>, @connection=#<Stomp::Connection:0x007fd3458a6450 @protocol="1.0", @hb_received=true, @hb_sent=true, @hbr=false, @hbs=false, @jruby=false, @st=nil, @rt=nil, @hhas10=false, @socket=#<TCPSocket:fd 11>, @closed=false, @parameters={:connect_headers=>{}, :reliable=>true, :initial_reconnect_delay=>0.01, :max_reconnect_delay=>30.0, :use_exponential_back_off=>true, :back_off_multiplier=>2, :max_reconnect_attempts=>0, :randomize=>false, :connect_timeout=>0, :parse_timeout=>5, :dmh=>false, :closed_check=>true, :hbser=>true, :stompconn=>false, :max_hbread_fails=>0, :max_hbrlck_fails=>0, :fast_hbs_adjust=>20.0, :connread_timeout=>0, :tcp_nodelay=>true, :start_timeout=>0, :sslctx_newparm=>nil, :ssl_post_conn_check=>true, :hosts=>[{:login=>"artemis", :passcode=>"simetraehcapa", :host=>"localhost", :port=>61613}], :logger=>#<Stomp::NullLogger:0x007fd3458a6518>, :usecrlf=>false}, @reliable=true, @reconnect_delay=0.01, @connect_headers={}, @parse_timeout=5, @connect_timeout=0, @logger=#<Stomp::NullLogger:0x007fd3458a6518>, @autoflush=false, @closed_check=true, @hbser=true, @stompconn=false, @usecrlf=false, @max_hbread_fails=0, @max_hbrlck_fails=0, @fast_hbs_adjust=20.0, @connread_timeout=0, @sslctx_newparm=nil, @ssl_post_conn_check=true, @ssl=nil, @host="localhost", @port=61613, @login="artemis", @passcode="simetraehcapa", @transmit_semaphore=#<Thread::Mutex:0x007fd3458a43d0>, @read_semaphore=#<Thread::Mutex:0x007fd3458a43a8>, @socket_semaphore=#<Thread::Mutex:0x007fd3458a4380>, @subscriptions={}, @failure=nil, @connection_attempts=0, @iosto=5.0, @connection_frame=#<Stomp::Message:0x007fd3441ebc88 @command="CONNECTED", @headers={"session"=>"357602514"}, @body="", @original="CONNECTED\nsession:357602514\n\n\u0000">, @disconnect_receipt=nil, @session="357602514">, @listeners={}, @receipt_listeners={}, @replay_messages_by_txn={}, @listener_map={"MESSAGE"=>#<Proc:0x007fd3441eb5a8@/Users/my-user-name/.rvm/gems/ruby-2.3.1@fern/gems/stomp-1.4.3/lib/client/utils.rb:179 (lambda)>, "RECEIPT"=>#<Proc:0x007fd3441eb558@/Users/my-user-name/.rvm/gems/ruby-2.3.1@fern/gems/stomp-1.4.3/lib/client/utils.rb:180 (lambda)>, "ERROR"=>#<Proc:0x007fd3458a6478@/Users/my-user-name/.rvm/gems/ruby-2.3.1@fern/gems/stomp-1.4.3/lib/stomp/client.rb:111 (lambda)>}, @listener_thread=#<Thread:0x007fd3441eb4b8@/Users/my-user-name/.rvm/gems/ruby-2.3.1@fern/gems/stomp-1.4.3/lib/client/utils.rb:188 sleep>> 
2.3.1 :011 > sc = _
 => #<Stomp::Client:0x007fd3458a6590 @parameters={:hosts=>[{:login=>"artemis", :passcode=>"simetraehcapa", :host=>"localhost", :port=>61613}], :reliable=>true, :initial_reconnect_delay=>0.01, :max_reconnect_delay=>30.0, :use_exponential_back_off=>true, :back_off_multiplier=>2, :max_reconnect_attempts=>0, :randomize=>false, :connect_timeout=>0, :connect_headers=>{}, :parse_timeout=>5, :logger=>#<Stomp::NullLogger:0x007fd3458a6518>, :dmh=>false, :closed_check=>true, :hbser=>true, :stompconn=>false, :usecrlf=>false, :max_hbread_fails=>0, :max_hbrlck_fails=>0, :fast_hbs_adjust=>20.0, :tcp_nodelay=>true, :start_timeout=>0, :sslctx_newparm=>nil, :ssl_post_conn_check=>true}, @logger=#<Stomp::NullLogger:0x007fd3458a6518>, @start_timeout=0, @error_listener=#<Proc:0x007fd3458a6478@/Users/my-user-name/.rvm/gems/ruby-2.3.1@fern/gems/stomp-1.4.3/lib/stomp/client.rb:111 (lambda)>, @connection=#<Stomp::Connection:0x007fd3458a6450 @protocol="1.0", @hb_received=true, @hb_sent=true, @hbr=false, @hbs=false, @jruby=false, @st=nil, @rt=nil, @hhas10=false, @socket=#<TCPSocket:fd 11>, @closed=false, @parameters={:connect_headers=>{}, :reliable=>true, :initial_reconnect_delay=>0.01, :max_reconnect_delay=>30.0, :use_exponential_back_off=>true, :back_off_multiplier=>2, :max_reconnect_attempts=>0, :randomize=>false, :connect_timeout=>0, :parse_timeout=>5, :dmh=>false, :closed_check=>true, :hbser=>true, :stompconn=>false, :max_hbread_fails=>0, :max_hbrlck_fails=>0, :fast_hbs_adjust=>20.0, :connread_timeout=>0, :tcp_nodelay=>true, :start_timeout=>0, :sslctx_newparm=>nil, :ssl_post_conn_check=>true, :hosts=>[{:login=>"artemis", :passcode=>"simetraehcapa", :host=>"localhost", :port=>61613}], :logger=>#<Stomp::NullLogger:0x007fd3458a6518>, :usecrlf=>false}, @reliable=true, @reconnect_delay=0.01, @connect_headers={}, @parse_timeout=5, @connect_timeout=0, @logger=#<Stomp::NullLogger:0x007fd3458a6518>, @autoflush=false, @closed_check=true, @hbser=true, @stompconn=false, @usecrlf=false, @max_hbread_fails=0, @max_hbrlck_fails=0, @fast_hbs_adjust=20.0, @connread_timeout=0, @sslctx_newparm=nil, @ssl_post_conn_check=true, @ssl=nil, @host="localhost", @port=61613, @login="artemis", @passcode="simetraehcapa", @transmit_semaphore=#<Thread::Mutex:0x007fd3458a43d0>, @read_semaphore=#<Thread::Mutex:0x007fd3458a43a8>, @socket_semaphore=#<Thread::Mutex:0x007fd3458a4380>, @subscriptions={}, @failure=nil, @connection_attempts=0, @iosto=5.0, @connection_frame=#<Stomp::Message:0x007fd3441ebc88 @command="CONNECTED", @headers={"session"=>"357602514"}, @body="", @original="CONNECTED\nsession:357602514\n\n\u0000">, @disconnect_receipt=nil, @session="357602514">, @listeners={}, @receipt_listeners={}, @replay_messages_by_txn={}, @listener_map={"MESSAGE"=>#<Proc:0x007fd3441eb5a8@/Users/my-user-name/.rvm/gems/ruby-2.3.1@fern/gems/stomp-1.4.3/lib/client/utils.rb:179 (lambda)>, "RECEIPT"=>#<Proc:0x007fd3441eb558@/Users/my-user-name/.rvm/gems/ruby-2.3.1@fern/gems/stomp-1.4.3/lib/client/utils.rb:180 (lambda)>, "ERROR"=>#<Proc:0x007fd3458a6478@/Users/my-user-name/.rvm/gems/ruby-2.3.1@fern/gems/stomp-1.4.3/lib/stomp/client.rb:111 (lambda)>}, @listener_thread=#<Thread:0x007fd3441eb4b8@/Users/my-user-name/.rvm/gems/ruby-2.3.1@fern/gems/stomp-1.4.3/lib/client/utils.rb:188 sleep>> 
2.3.1 :012 > # I waited ~60 seconds, and the below was written to my terminal and my irb crashed.
on_miscerr
{:connect_headers=>{}, :reliable=>true, :initial_reconnect_delay=>0.01, :max_reconnect_delay=>30.0, :use_exponential_back_off=>true, :back_off_multiplier=>2, :max_reconnect_attempts=>0, :randomize=>false, :connect_timeout=>0, :parse_timeout=>5, :dmh=>false, :closed_check=>true, :hbser=>true, :stompconn=>false, :max_hbread_fails=>0, :max_hbrlck_fails=>0, :fast_hbs_adjust=>20.0, :connread_timeout=>0, :tcp_nodelay=>true, :start_timeout=>0, :sslctx_newparm=>nil, :ssl_post_conn_check=>true, :hosts=>[{:login=>"artemis", :passcode=>"simetraehcapa", :host=>"localhost", :port=>61613}], :logger=>#<Stomp::NullLogger:0x007fd3458a6518>, :usecrlf=>false, :cur_host=>"localhost", :cur_port=>61613, :cur_login=>"artemis", :cur_passcode=>"simetraehcapa", :cur_ssl=>nil, :cur_recondelay=>0.01, :cur_parseto=>5, :cur_conattempts=>0, :cur_failure=>nil, :openstat=>true}
es_recv: connection.receive returning EOF as nil - resetting connection.

/Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/input-method.rb:151:in `readline': AMQ119014: Did not receive data from /172.17.0.1:57530 within the 60,000ms connection TTL. The connection will now be closed. (Stomp::Error::BrokerException)
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/input-method.rb:151:in `gets'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb.rb:469:in `block (2 levels) in eval_input'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb.rb:623:in `signal_status'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb.rb:468:in `block in eval_input'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/ruby-lex.rb:189:in `buf_input'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/ruby-lex.rb:104:in `getc'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/slex.rb:206:in `match_io'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/slex.rb:76:in `match'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/ruby-lex.rb:283:in `token'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/ruby-lex.rb:265:in `lex'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/ruby-lex.rb:236:in `block (2 levels) in each_top_level_statement'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/ruby-lex.rb:232:in `loop'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/ruby-lex.rb:232:in `block in each_top_level_statement'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/ruby-lex.rb:231:in `catch'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/ruby-lex.rb:231:in `each_top_level_statement'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb.rb:485:in `eval_input'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb.rb:395:in `block in start'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb.rb:394:in `catch'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb.rb:394:in `start'
  from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/bin/irb:11:in `<main>'
$ 

As you can see, the Stomp::Error::BrokerException is raised, which is correct, but then the entire irb dies, which is the problem here. Could this be a ruby 2.3 problem?

gmallard commented 7 years ago

Please show me that in a real application. Without irb in the mix.

Thanks, Guy

On 01/11/2017 03:20 PM, Adam Braman wrote:

The Artemis instance I'm testing against is version 1.5.0. If you want to poke around in it, you can find a dockerized version of the artemis instance at https://github.com/vromero/activemq-artemis-docker. (I'm using the latest tag)

I never got a broken pipe exception, but instead had a complete interpreter crash. The stack trace–printed just before the interpreter crashed–is in my second comment in this thread.

When I said "disconnect/crashing problems", I should have just said "crashing problems". But more generally it would nice if there were a programatic way to detect when an unexpected disconnect occurs. I was suggesting that this could be done by raising an exception.

Reproducing the stack trace here:

|2.3.1 :010 > Stomp::Client.new DEFAULT_CLIENT_CONFIG =>

<Stomp::Client:0x007fd3458a6590

@parameters={:hosts=>[{:login=>"artemis", :passcode=>"simetraehcapa", :host=>"localhost", :port=>61613}], :reliable=>true, :initial_reconnect_delay=>0.01, :max_reconnect_delay=>30.0, :use_exponential_back_off=>true, :back_off_multiplier=>2, :max_reconnect_attempts=>0, :randomize=>false, :connect_timeout=>0, :connect_headers=>{}, :parse_timeout=>5, :logger=>#, :dmh=>false, :closed_check=>true, :hbser=>true, :stompconn=>false, :usecrlf=>false, :max_hbread_fails=>0, :max_hbrlck_fails=>0, :fast_hbs_adjust=>20.0, :tcp_nodelay=>true, :start_timeout=>0, :sslctx_newparm=>nil, :ssl_post_conn_check=>true}, @logger=#, @start_timeout=0, @error_listener=#<Proc:0x007fd3458a6478@/Users/my-user-name/.rvm/gems/ruby-2.3.1@fern/gems/stomp-1.4.3/lib/stomp/client.rb:111 (lambda)>, @connection=#<Stomp::Connection:0x007fd3458a6450 @protocol="1.0", @hb_received=true, @hb_sent=true, @hbr=false, @hbs=false, @jruby=false, @st=nil, @rt=nil, @hhas10=false, @socket=#<TCPSocket:fd 11>, @closed=false, @parameters={:connect_headers=>{}, :reliable=>true, :initial_reconnect_delay=>0.01, :max_reconnect_delay=>30.0, :use_exponential_back_off=>true, :back_off_multiplier=>2, :max_reconnect_attempts=>0, :randomize=>false, :connect_timeout=>0, :parse_timeout=>5, :dmh=>false, :closed_check=>true, :hbser=>true, :stompconn=>false, :max_hbread_fails=>0, :max_hbrlck_fails=>0, :fast_hbs_adjust=>20.0, :connread_timeout=>0, :tcp_nodelay=>true, :start_timeout=>0, :sslctx_newparm=>nil, :ssl_post_conn_check=>true, :hosts=>[{:login=>"artemis", :passcode=>"simetraehcapa", :host=>"localhost", :port=>61613}], :logger=>#, :usecrlf=>false}, @reliable=true, @reconnect_delay=0.01, @connect_headers={}, @parse_timeout=5, @connect_timeout=0, @logger=#, @autoflush=false, @closed_check=true, @hbser=true, @stompconn=false, @usecrlf=false, @max_hbread_fails=0, @max_hbrlck_fails=0, @fast_hbs_adjust=20.0, @connread_timeout=0, @sslctx_newparm=nil, @ssl_post_conn_check=true, @ssl=nil, @host="localhost", @port=61613, @login="artemis", @passcode="simetraehcapa", @transmit_semaphore=#, @read_semaphore=#, @socket_semaphore=#, @subscriptions={}, @failure=nil, @connection_attempts=0, @iosto=5.0, @connection_frame=#<Stomp::Message:0x007fd3441ebc88 @command="CONNECTED", @headers={"session"=>"357602514"}, @body="", @original="CONNECTED\nsession:357602514\n\n\u0000">, @disconnect_receipt=nil, @session="357602514">, @listeners={}, @receipt_listeners={}, @replay_messages_by_txn={}, @listener_map={"MESSAGE"=>#<Proc:0x007fd3441eb5a8@/Users/my-user-name/.rvm/gems/ruby-2.3.1@fern/gems/stomp-1.4.3/lib/client/utils.rb:179 (lambda)>, "RECEIPT"=>#<Proc:0x007fd3441eb558@/Users/my-user-name/.rvm/gems/ruby-2.3.1@fern/gems/stomp-1.4.3/lib/client/utils.rb:180 (lambda)>, "ERROR"=>#<Proc:0x007fd3458a6478@/Users/my-user-name/.rvm/gems/ruby-2.3.1@fern/gems/stomp-1.4.3/lib/stomp/client.rb:111 (lambda)>}, @listenerthread=#<Thread:0x007fd3441eb4b8@/Users/my-user-name/.rvm/gems/ruby-2.3.1@fern/gems/stomp-1.4.3/lib/client/utils.rb:188 sleep>> 2.3.1 :011 > sc = => #<Stomp::Client:0x007fd3458a6590 @parameters={:hosts=>[{:login=>"artemis", :passcode=>"simetraehcapa", :host=>"localhost", :port=>61613}], :reliable=>true, :initial_reconnect_delay=>0.01, :max_reconnect_delay=>30.0, :use_exponential_back_off=>true, :back_off_multiplier=>2, :max_reconnect_attempts=>0, :randomize=>false, :connect_timeout=>0, :connect_headers=>{}, :parse_timeout=>5, :logger=>#, :dmh=>false, :closed_check=>true, :hbser=>true, :stompconn=>false, :usecrlf=>false, :max_hbread_fails=>0, :max_hbrlck_fails=>0, :fast_hbs_adjust=>20.0, :tcp_nodelay=>true, :start_timeout=>0, :sslctx_newparm=>nil, :ssl_post_conn_check=>true}, @logger=#, @start_timeout=0, @error_listener=#<Proc:0x007fd3458a6478@/Users/my-user-name/.rvm/gems/ruby-2.3.1@fern/gems/stomp-1.4.3/lib/stomp/client.rb:111 (lambda)>, @connection=#<Stomp::Connection:0x007fd3458a6450 @protocol="1.0", @hb_received=true, @hb_sent=true, @hbr=false, @hbs=false, @jruby=false, @st=nil, @rt=nil, @hhas10=false, @socket=#<TCPSocket:fd 11>, @closed=false, @parameters={:connect_headers=>{}, :reliable=>true, :initial_reconnect_delay=>0.01, :max_reconnect_delay=>30.0, :use_exponential_back_off=>true, :back_off_multiplier=>2, :max_reconnect_attempts=>0, :randomize=>false, :connect_timeout=>0, :parse_timeout=>5, :dmh=>false, :closed_check=>true, :hbser=>true, :stompconn=>false, :max_hbread_fails=>0, :max_hbrlck_fails=>0, :fast_hbs_adjust=>20.0, :connread_timeout=>0, :tcp_nodelay=>true, :start_timeout=>0, :sslctx_newparm=>nil, :ssl_post_conn_check=>true, :hosts=>[{:login=>"artemis", :passcode=>"simetraehcapa", :host=>"localhost", :port=>61613}], :logger=>#, :usecrlf=>false}, @reliable=true, @reconnect_delay=0.01, @connect_headers={}, @parse_timeout=5, @connect_timeout=0, @logger=#, @autoflush=false, @closed_check=true, @hbser=true, @stompconn=false, @usecrlf=false, @max_hbread_fails=0, @max_hbrlck_fails=0, @fast_hbs_adjust=20.0, @connread_timeout=0, @sslctx_newparm=nil, @ssl_post_conn_check=true, @ssl=nil, @host="localhost", @port=61613, @login="artemis", @passcode="simetraehcapa", @transmit_semaphore=#, @read_semaphore=#, @socket_semaphore=#, @subscriptions={}, @failure=nil, @connection_attempts=0, @iosto=5.0, @connection_frame=#<Stomp::Message:0x007fd3441ebc88 @command="CONNECTED", @headers={"session"=>"357602514"}, @body="", @original="CONNECTED\nsession:357602514\n\n\u0000">, @disconnect_receipt=nil, @session="357602514">, @listeners={}, @receipt_listeners={}, @replay_messages_by_txn={}, @listener_map={"MESSAGE"=>#<Proc:0x007fd3441eb5a8@/Users/my-user-name/.rvm/gems/ruby-2.3.1@fern/gems/stomp-1.4.3/lib/client/utils.rb:179 (lambda)>, "RECEIPT"=>#<Proc:0x007fd3441eb558@/Users/my-user-name/.rvm/gems/ruby-2.3.1@fern/gems/stomp-1.4.3/lib/client/utils.rb:180 (lambda)>, "ERROR"=>#<Proc:0x007fd3458a6478@/Users/my-user-name/.rvm/gems/ruby-2.3.1@fern/gems/stomp-1.4.3/lib/stomp/client.rb:111 (lambda)>}, @listener_thread=#<Thread:0x007fd3441eb4b8@/Users/my-user-name/.rvm/gems/ruby-2.3.1@fern/gems/stomp-1.4.3/lib/client/utils.rb:188 sleep>> 2.3.1 :012 > # I waited ~60 seconds, and the below was written to my terminal and my irb crashed. on_miscerr {:connect_headers=>{}, :reliable=>true, :initial_reconnect_delay=>0.01, :max_reconnect_delay=>30.0, :use_exponential_back_off=>true, :back_off_multiplier=>2, :max_reconnect_attempts=>0, :randomize=>false, :connect_timeout=>0, :parse_timeout=>5, :dmh=>false, :closed_check=>true, :hbser=>true, :stompconn=>false, :max_hbread_fails=>0, :max_hbrlck_fails=>0, :fast_hbs_adjust=>20.0, :connread_timeout=>0, :tcp_nodelay=>true, :start_timeout=>0, :sslctx_newparm=>nil, :ssl_post_conn_check=>true, :hosts=>[{:login=>"artemis", :passcode=>"simetraehcapa", :host=>"localhost", :port=>61613}], :logger=>#, :usecrlf=>false, :cur_host=>"localhost", :cur_port=>61613, :cur_login=>"artemis", :cur_passcode=>"simetraehcapa", :cur_ssl=>nil, :cur_recondelay=>0.01, :cur_parseto=>5, :cur_conattempts=>0, :cur_failure=>nil, :openstat=>true} es_recv: connection.receive returning EOF as nil - resetting connection. /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/input-method.rb:151:in readline': AMQ119014: Did not receive data from /172.17.0.1:57530 within the 60,000ms connection TTL. The connection will now be closed. (Stomp::Error::BrokerException) from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/input-method.rb:151:in gets' from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb.rb:469:in block (2 levels) in eval_input' from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb.rb:623:in signal_status' from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb.rb:468:in block in eval_input' from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/ruby-lex.rb:189:in buf_input' from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/ruby-lex.rb:104:in getc' from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/slex.rb:206:in match_io' from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/slex.rb:76:in match' from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/ruby-lex.rb:283:in token' from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/ruby-lex.rb:265:in lex' from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/ruby-lex.rb:236:in block (2 levels) in each_top_level_statement' from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/ruby-lex.rb:232:in loop' from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/ruby-lex.rb:232:in block in each_top_level_statement' from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/ruby-lex.rb:231:in catch' from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb/ruby-lex.rb:231:in each_top_level_statement' from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb.rb:485:in eval_input' from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb.rb:395:in block in start' from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb.rb:394:in catch' from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/lib/ruby/2.3.0/irb.rb:394:in start' from /Users/my-user-name/.rvm/rubies/ruby-2.3.1/bin/irb:11:in `

' |

— You are receiving this because you modified the open/close state. Reply to this email directly, view it on GitHub https://github.com/stompgem/stomp/issues/136#issuecomment-271982357, or mute the thread https://github.com/notifications/unsubscribe-auth/AAAbv4NOBmqk0oBYd6yOOwEyeulqnMNtks5rRTlwgaJpZM4LX9CZ.

glyoko commented 7 years ago

See the bottom of my second comment where I call sleep 120. That sleep traceback at the bottom of that comment is the entire traceback.

The traceback only ever goes to the line that was executing in the main thread when the interpreter dies. There's no traceback beyond that.

glyoko commented 7 years ago

My project is open source, so you can take a look at the whole thing in context at https://github.com/mGageTechOps/stomp_job. It's basically a job framework setup around this gem. I plan to use it in a rails app myself.

You can reproduce the issue in this gem as follows:

$ git clone https://github.com/mGageTechOps/stomp_job
$ cd stomp_job
$ docker run -d --name artemis -p 61613:61613 vromero/activemq-artemis
$ gem install bundler # if needed
$ bundle # has rails as a dev dependency to support some rails features, so this bundle may take some time.
$ bundle console
> StompJob::Configuration.setup { |config| config[:connect_headers] = {} } # default config uses the connect headers you suggested above and that circumvents the issue. This config line resets it to the empty hash to reproduce it.
> require './examples/scream_worker'
> # After 1 minute the interpreter crashes. You'll see bundler stuff in the traceback, but no more useful info than you'd see otherwise.

Regardless, I get the same bug in a fresh context (fresh ruby install, no libs or deps beyond this gem) too.