Stomp+SSL and ActiveMQ times out for most recent message on stomp 1.4+

[steveforse]

I'm using ActiveMQ 5.14.3 configured from stomp+ssl. I'm using the following code for testing:

ssl_params = Stomp::SSLParams.new
stomp_options = { hosts: [ { host: 'amq-broker', port: 61612, ssl: ssl_params } ] }
$msg_num = 0

$client = Stomp::Client.new(stomp_options)
$client.subscribe("/queue/my-queue" ) do |message|
  puts "You are reading message: #{message.body} on #{message.headers['destination']}"
end

def send_msg
  $msg_num += 1
  puts "Sending msg #{$msg_num}"
  $client.publish("/queue/my-queue", "msg_num: #{$msg_num}" )
end

On stomp 1.4.0+, calling send_msg has a very quirky behavior. If I call send_msg, nothing will happen and eventually I hit the parse_timeout error:

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=>false, :stompconn=>false, :max_hbread_fails=>0, :max_hbrlck_fails=>0, :fast_hbs_adjust=>0.0, :connread_timeout=>0, :tcp_nodelay=>true, :start_timeout=>0, :sslctx_newparm=>nil, :hosts=>[{:host=>"amq-broker", :port=>61612, :ssl=>#<Stomp::SSLParams:0x005618b093d310 @ts_files=nil, @cert_file=nil, @key_file=nil, @key_password=nil, @ciphers=nil, @use_ruby_ciphers=false, @ssl_ctxopts=nil, @ctx=#<OpenSSL::SSL::SSLContext:0x005618b0a92990 @cert=nil, @key=nil, @client_ca=nil, @ca_file=nil, @ca_path=nil, @timeout=nil, @verify_mode=0, @verify_depth=nil, @renegotiation_cb=nil, @verify_callback=nil, @cert_store=nil, @extra_chain_cert=nil, @client_cert_cb=nil, @session_id_context=nil, @tmp_dh_callback=nil, @session_get_cb=nil, @session_new_cb=nil, @session_remove_cb=nil, @tmp_ecdh_callback=nil, @servername_cb=nil, @npn_protocols=nil, @alpn_protocols=nil, @alpn_select_cb=nil, @npn_select_cb=nil>, @verify_result=19, @peer_cert=#<OpenSSL::X509::Certificate: subject=#<OpenSSL::X509::Name:0x005618b0d2a400>, issuer=#<OpenSSL::X509::Name:0x005618b0d2a4c8>, serial=#<OpenSSL::BN:0x005618b0d2a4f0>, not_before=2017-02-13 06:38:17 UTC, not_after=2027-02-11 06:38:17 UTC>>}], :logger=>#<Stomp::NullLogger:0x005618b0a93778>, :cur_host=>"amq-broker", :cur_port=>61612, :cur_login=>"", :cur_passcode=>"", :cur_ssl=>#<Stomp::SSLParams:0x005618b093d310 @ts_files=nil, @cert_file=nil, @key_file=nil, @key_password=nil, @ciphers=nil, @use_ruby_ciphers=false, @ssl_ctxopts=nil, @ctx=#<OpenSSL::SSL::SSLContext:0x005618b0a92990 @cert=nil, @key=nil, @client_ca=nil, @ca_file=nil, @ca_path=nil, @timeout=nil, @verify_mode=0, @verify_depth=nil, @renegotiation_cb=nil, @verify_callback=nil, @cert_store=nil, @extra_chain_cert=nil, @client_cert_cb=nil, @session_id_context=nil, @tmp_dh_callback=nil, @session_get_cb=nil, @session_new_cb=nil, @session_remove_cb=nil, @tmp_ecdh_callback=nil, @servername_cb=nil, @npn_protocols=nil, @alpn_protocols=nil, @alpn_select_cb=nil, @npn_select_cb=nil>, @verify_result=19, @peer_cert=#<OpenSSL::X509::Certificate: subject=#<OpenSSL::X509::Name:0x005618b0d28f38>, issuer=#<OpenSSL::X509::Name:0x005618b0d28f60>, serial=#<OpenSSL::BN:0x005618b0d28fb0>, not_before=2017-02-13 06:38:17 UTC, not_after=2027-02-11 06:38:17 UTC>>, :cur_recondelay=>0.01, :cur_parseto=>5, :cur_conattempts=>0, :cur_failure=>#<Stomp::Error::ReceiveTimeout: Stomp::Error::ReceiveTimeout>, :openstat=>true}
es1_oldrecv: receive failed: Stomp::Error::ReceiveTimeout

However, if I make multiple calls to send_msg, each new message looks like it's pushing the previous message through the queue. It will correctly dequeue and process each message, except the most recent, which will cause the timeout above:

(irb) send_msg
Sending msg 1

(irb) send_msg
Sending msg 2
You are reading message: msg_num: 1 on /queue/my-queue

(irb) send_msg
Sending msg 3
You are reading message: msg_num: 2 on /queue/my-queue

[snip]
es1_oldrecv: receive failed: Stomp::Error::ReceiveTimeout

I only get this behavior using stomp+ssl on 1.4.0+. If I use stomp+ssl with 1.3.5 or stomp without ssl on 1.4.0+, then everything is fine.

[gmallard]

Before I address this issue: if you are writing new code then please please add connect headers to your connect hash asking for STOMP protocol level 1.2:

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

Regarding this issue: thanks for the report. And thanks for the sample code. The code made it easy for me to understand exactly what you are seeing.

Are you aware that this bizarre (and incorrect) gem behavior only occurs for ssl connections?

There was a fairly recent code change that modified how read timeouts were implemented (that change eliminated large memory leaks due to use of Ruby's Timeout implementation).

It turns out that code needs to be 'more ssl aware'.

I have a local fix here that seems to work. But I have only tested it so far on my Mac. I will test Linux and Windows tomorrow.

If all goes well, I will push that to dev late tomorrow.

[steveforse]

Yes, I only get this behavior for SSL. I only tested use case 1 and 2 so far, but thought that was sufficient to file a report.

[gmallard]

Indeed, it is quite sufficient for an issue creation. Please test the subcases: broker does/does not require client authorization. Eight total tests. Regards, Guy

…

On 02/16/2017 10:31 AM, Steve Forse wrote: Yes, I only get this behavior for SSL. I only tested use case 1 and 2 so far, but thought that was sufficient to file a report. — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#139 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAAbv2nFl-bSqzeIqSjijHCtjkJuWH0vks5rdGvegaJpZM4MCU_A>.

[gmallard]

Commit c022d37 addresses this issue.

That commit is on the dev branch only at present.

Clone this repo and build from the HEAD of dev if you can. If you cannot, let me know and I will build a test gem for you to install.

[MikaelSmith]

The mcollective project is affected by this, and the commit you mention fixes the issue for me. Any chance we can get a new gem?

[gmallard]

This went out the door with version 1.4.4.

Belatedly closing this issue.