{handshake_timeout,handshake} error in RabbitMQ server log

[bostonne...@gmail.com]

The following error frequently appear in the RabbitMQ server log with our C# client and I want to know why, so, I wrote a simple C# program to reproduce it.

Can someone explain why the rabbitmq server has the handshake_timeout log? And how to avoid it?

C# client version 3.6.2

RabbitMQ server version 3.6.1

both Server and client run on Windows7 64-bit machine

I simply stopped and started RabbitMQ service and run my reproduce program and got the following rabbitmq server log. 

=INFO REPORT==== 1-Jul-2016::11:26:13 ===

Starting RabbitMQ 3.6.1 on Erlang 18.2.1

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

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

=INFO REPORT==== 1-Jul-2016::11:26:13 ===

node           : rabbit@NB-DTP-269

home dir       : C:\Windows

config file(s) : c:/Users/YNiu/AppData/Roaming/RabbitMQ/rabbitmq.config

cookie hash    : Uy7p4Ds6oBg0M0XZMefMnA==

log            : C:/Users/YNiu/AppData/Roaming/RabbitMQ/log/RABBIT~1.LOG

sasl log       : C:/Users/YNiu/AppData/Roaming/RabbitMQ/log/RABBIT~2.LOG

database dir   : c:/Users/YNiu/AppData/Roaming/RabbitMQ/db/RABBIT~1

=WARNING REPORT==== 1-Jul-2016::11:26:13 ===

Kernel poll (epoll, kqueue, etc) is disabled. Throughput and CPU utilization may worsen.

=INFO REPORT==== 1-Jul-2016::11:26:15 ===

Memory limit set to 9793MB of 24484MB total.

=INFO REPORT==== 1-Jul-2016::11:26:15 ===

Disk free limit set to 50MB

=INFO REPORT==== 1-Jul-2016::11:26:15 ===

Limiting to approx 8092 file handles (7280 sockets)

=INFO REPORT==== 1-Jul-2016::11:26:15 ===

FHC read buffering:  OFF

FHC write buffering: ON

=INFO REPORT==== 1-Jul-2016::11:26:15 ===

Priority queues enabled, real BQ is rabbit_variable_queue

=INFO REPORT==== 1-Jul-2016::11:26:15 ===

Management plugin: using rates mode 'basic'

=INFO REPORT==== 1-Jul-2016::11:26:15 ===

msg_store_transient: using rabbit_msg_store_ets_index to provide index

=INFO REPORT==== 1-Jul-2016::11:26:15 ===

msg_store_persistent: using rabbit_msg_store_ets_index to provide index

=INFO REPORT==== 1-Jul-2016::11:26:15 ===

started TCP Listener on [::]:5672

=INFO REPORT==== 1-Jul-2016::11:26:15 ===

started TCP Listener on 0.0.0.0:5672

=INFO REPORT==== 1-Jul-2016::11:26:16 ===

Management plugin started. Port: 15672

=INFO REPORT==== 1-Jul-2016::11:26:16 ===

Statistics database started.

=INFO REPORT==== 1-Jul-2016::11:26:16 ===

Server startup complete; 6 plugins started.

 * rabbitmq_management

 * rabbitmq_management_agent

 * rabbitmq_web_dispatch

 * webmachine

 * mochiweb

 * amqp_client

=INFO REPORT==== 1-Jul-2016::11:26:55 ===

accepting AMQP connection <0.699.0> (192.168.32.36:60905 -> 192.168.32.36:5672)

=INFO REPORT==== 1-Jul-2016::11:26:55 ===

closing AMQP connection <0.699.0> (192.168.32.36:60905 -> 192.168.32.36:5672)

=INFO REPORT==== 1-Jul-2016::11:27:08 ===

accepting AMQP connection <0.696.0> (192.168.32.36:60904 -> 192.168.32.36:5672)

=ERROR REPORT==== 1-Jul-2016::11:27:08 ===

closing AMQP connection <0.696.0> (192.168.32.36:60904 -> 192.168.32.36:5672):

{handshake_timeout,handshake}

My sample C# program are as simple as this:

using RabbitMQ.Client;

using System;

using System.Collections.Generic;

using System.Linq;

using System.Text;

using System.Threading.Tasks;

namespace YniuTest

{

    class Program

    {

        static void Main(string[] args)

        {

            string h1 = "192.168.32.36";

            var factory = new ConnectionFactory()

            {

                HostName = h1

            };

            factory.AutomaticRecoveryEnabled = true;

            var con = factory.CreateConnection();

            con.Close();

 

            Console.ReadKey(false);

            Console.WriteLine("now I am exiting...");

        }

    }

}

[Michael Klishin]

That means the client connects but sends no data. Most often that means

that a non-TLS client connects to the TLS port but doesn't perform TLS handshake.

However, this handhsake is not a TLS one but an AMQP 0-9-1 one.

Your code opens a connection and immediately closes it: that might be why the above is going on.

--
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

[bostonne...@gmail.com]

Michael,

If I commented the con.Close(), I still get the same error. We can see the 61990 is the one connection that my program explicitly created, but the 61989 is the mysterious one.  Again, can you point me to the TLS handshake doc or to how to fix this ?

=INFO REPORT==== 1-Jul-2016::11:50:05 ===

accepting AMQP connection <0.11866.0> (192.168.32.36:61990 -> 192.168.32.36:5672)

=INFO REPORT==== 1-Jul-2016::11:50:18 ===

accepting AMQP connection <0.11863.0> (192.168.32.36:61989 -> 192.168.32.36:5672)

=ERROR REPORT==== 1-Jul-2016::11:50:18 ===

closing AMQP connection <0.11863.0> (192.168.32.36:61989 -> 192.168.32.36:5672):

{handshake_timeout,handshake}

[Michael Klishin]

Then it can be something else. Some beginners point Web browsers at port 5672

and expect things to work, for example, even though port 5672 serves a different protocol.

You can do a traffic capture with Wireshark and see what process connects

to the port and what data it sends:

http://www.rabbitmq.com/amqp-wireshark.html

[bostonne...@gmail.com]

Hi Mike,

No, it is not something else. This error server log happens and only happens when run a rabbitmq C# client program (e.g, the sample one I pasted here)

I finally figured out a very likely code in the c# client library that caused this. But I want to hear your opinion about it. 

The line is fh = m_factory.CreateFrameHandler(endPoint); line 

in rabbitmq-dotnet-client-3.6.2\projects\client\rabbitmq.client\src\client\impl\autorecoveringconnection.cs. 

By printing out the localport on the screen, I confirmed that the connection created by this line is the exactly the one complained by the rabbitmq server and closed by the rabbitmq server.

Basically, this line created a frame handler which will created connection, but this frame handler is never used.

But I still don't know what's different in this connection so that server will have the handshake error, but the connection created in m_delegate = new Connection(m_factory, false,

                m_factory.CreateFrameHandlerForHostname(hostname),

                this.ClientProvidedName);

is totally accepted by the rabbitmq server.

The code:

       public void Init(IList<string> hostnames)

        {

            this.hostnames = hostnames;

            string reachableHostname = null;

            IFrameHandler fh = null;

            Exception e = null;

            foreach (var h in hostnames)

            {

                try

                {

                    var endPoint = CloneEndpointWithHostname(h);

                    //fh = m_factory.CreateFrameHandler(endPoint); <--------------- This line will create a frame handler which will in turn created connection, and complained by and closed by the server. the variable 'fh' is never used.

                    reachableHostname = h;

                } 

                catch (Exception caught)

                {

                    e = caught;

                }

            }

            if (reachableHostname == null)

            {

                throw e;

            }

            this.Init(reachableHostname);

        }

        protected void Init(string hostname)

        {

            m_delegate = new Connection(m_factory, false,

                m_factory.CreateFrameHandlerForHostname(hostname),                 // <--------------- this line will created the connection that shows normal in rabbitmq server.

                this.ClientProvidedName);

      ...

[Michael Klishin]

Can you  reproduce it with 3.6.3 RC2, too?

[bostonne...@gmail.com]

Michael

No, I could not reproduce it with 3.6.3 RC3. (note I used the latest RC3, not RC2). 

What does that mean then, from your point of view?

[Michael Klishin]

There were no code changes between RC3 and RC2, so there's likely something

else that's different between the two attempts.

[bostonne...@gmail.com]

Michael,

Sorry, I did not make myself clear. I meant I only tried 3.6.3 RC3, I did not try 3.6.3 RC2 (the one you asked me to). 

So, what's your thought on the fact that it is reproducible in 3.6.2 but not in 3.6.3 RC3 (probably not reproducible in 3.6.3 Rc2 either)

Thanks,