rabbitmq 3.7.7 amqp ssl issue

[Bowen Liu]

Hi all,

I'm trying to set up amqp ssl on rabbitmq 3.7.7-1 and erlang 1.21.1-1. The server can be started successfully and listen on 5671. 

[

  {rabbit, [

    {tcp_listen_options, [

           {sndbuf,       196608},

           {linger,       {true,0}},

           {recbuf,       196608},

           {exit_on_close,       false},

           {nodelay,       true},

           {backlog,       4096}

    ]},

    {vm_memory_high_watermark,  0.7},

    {hipe_compile,  true},

    {msg_store_file_size_limit,  167772160},

    {handshake_timeout,  20000},

    {tcp_listeners,  [5672]},

    {disk_free_limit,  {mem_relative, 0.3}},

    {log_levels, [{connection, debug},{channel, debug}]},

    {ssl_listeners, [5671]},

    {ssl_options, [ {cacertfile,   "/etc/ssl/llnw/certs/CA.crt"},

                    {certfile,   "/etc/ssl/llnw/certs/cert.crt"},

                    {keyfile,   "/etc/ssl/llnw/keys/key.key"},

                    {verify,    verify_peer},

                    {fail_if_no_peer_cert, false}]}

  ]},

  {rabbit_mochiweb, [ {port, 15672} ] },

  {rabbit_management_agent, [ { force_fine_statistics, false } ] }

].

2018-12-19 19:15:17.426 [info] <0.6174.0> started SSL Listener on [::]:5671

root@rmq:~# rabbitmqctl status

Status of node rabbit@rmq ...

[{pid,6523},

 {running_applications,

     [{rabbitmq_shovel_management,

          "Management extension for the Shovel plugin","3.7.7"},

      {rabbitmq_top,"RabbitMQ Top","3.7.7"},

      {rabbitmq_management,"RabbitMQ Management Console","3.7.7"},

      {rabbitmq_management_agent,"RabbitMQ Management Agent","3.7.7"},

      {rabbitmq_event_exchange,"Event Exchange Type","3.7.7"},

      {rabbitmq_amqp1_0,"AMQP 1.0 support for RabbitMQ","3.7.7"},

      {rabbitmq_shovel,"Data Shovel for RabbitMQ","3.7.7"},

      {rabbitmq_web_dispatch,"RabbitMQ Web Dispatcher","3.7.7"},

      {rabbit,"RabbitMQ","3.7.7"},

      {amqp_client,"RabbitMQ AMQP Client","3.7.7"},

      {rabbit_common,

          "Modules shared by rabbitmq-server and rabbitmq-erlang-client",

          "3.7.7"},

      {recon,"Diagnostic tools for production use","2.3.2"},

      {jsx,"a streaming, evented json parsing toolkit","2.8.2"},

      {cowboy,"Small, fast, modern HTTP server.","2.2.2"},

      {mnesia,"MNESIA  CXC 138 12","4.15.5"},

      {ranch_proxy_protocol,"Ranch Proxy Protocol Transport","1.5.0"},

      {ranch,"Socket acceptor pool for TCP protocols.","1.5.0"},

      {amqp10_client,"AMQP 1.0 client from the RabbitMQ Project","3.7.7"},

      {ssl,"Erlang/OTP SSL application","9.0.2"},

      {public_key,"Public key infrastructure","1.6.2"},

      {asn1,"The Erlang ASN1 compiler version 5.0.7","5.0.7"},

      {cowlib,"Support library for manipulating Web protocols.","2.1.0"},

      {crypto,"CRYPTO","4.3.3"},

      {amqp10_common,

          "Modules shared by rabbitmq-amqp1.0 and rabbitmq-amqp1.0-client",

          "3.7.7"},

      {inets,"INETS  CXC 138 49","7.0.2"},

      {os_mon,"CPO  CXC 138 46","2.4.6"},

      {xmerl,"XML parser","1.3.18"},

      {lager,"Erlang logging framework","3.6.3"},

      {goldrush,"Erlang event stream processor","0.1.9"},

      {compiler,"ERTS  CXC 138 10","7.2.5"},

      {syntax_tools,"Syntax tools","2.1.6"},

      {syslog,"An RFC 3164 and RFC 5424 compliant logging framework.","3.4.2"},

      {sasl,"SASL  CXC 138 11","3.2.1"},

      {stdlib,"ERTS  CXC 138 10","3.6"},

      {kernel,"ERTS  CXC 138 10","6.1"}]},

 {os,{unix,linux}},

 {erlang_version,

     "Erlang/OTP 21 [erts-10.1] [source] [64-bit] [smp:16:16] [ds:16:16:10] [async-threads:128] [hipe]\n"},

 {memory,

     [{connection_readers,0},

      {connection_writers,0},

      {connection_channels,0},

      {connection_other,123080},

      {queue_procs,0},

      {queue_slave_procs,0},

      {plugins,3696800},

      {other_proc,27707848},

      {metrics,198236},

      {mgmt_db,506476},

      {mnesia,93936},

      {other_ets,2958664},

      {binary,403824},

      {msg_index,56032},

      {code,27280919},

      {atom,1484961},

      {other_system,25321568},

      {allocated_unused,31421544},

      {reserved_unallocated,37416960},

      {strategy,rss},

      {total,[{erlang,89832344},{rss,158670848},{allocated,121253888}]}]},

 {alarms,[]},

 {listeners,

     [{clustering,25672,"::"},

      {amqp,5672,"::"},

      {'amqp/ssl',5671,"::"},

      {http,15672,"::"}]},

 {vm_memory_calculation_strategy,rss},

 {vm_memory_high_watermark,0.7},

 {vm_memory_limit,35447486054},

 {disk_free_limit,15191779738},

 {disk_free,899116085248},

 {file_descriptors,

     [{total_limit,65436},

      {total_used,4},

      {sockets_limit,58890},

      {sockets_used,0}]},

 {processes,[{limit,1048576},{used,434}]},

 {run_queue,1},

 {uptime,2400},

 {kernel,{net_ticktime,60}}]

The cert files can be verified successfully in openssl. I also set up https working in apache2 with the same certificate files. But rabbitmq ssl connections seem not be rejected. openssl s_client output write:errno=104. Meanwhile, no loggings can be captured in rabbitmq server. 

Enter code root@rmq:~# openssl s_client -connect rmq:5671 -debug

CONNECTED(00000003)

write to 0x20c7a40 [0x20c7ac0] (295 bytes => 295 (0x127))

0000 - 16 03 01 01 22 01 00 01-1e 03 03 2d 85 f5 e9 4c   ...."......-...L

0010 - 6d 50 91 8a 19 dc bf bd-cd 06 8e c9 4f 77 4a 75   mP..........OwJu

0020 - 9f a5 5d 95 24 bb 67 61-a6 94 f2 00 00 88 c0 30   ..].$.ga.......0

0030 - c0 2c c0 28 c0 24 c0 14-c0 0a 00 a3 00 9f 00 6b   .,.(.$.........k

0040 - 00 6a 00 39 00 38 00 88-00 87 c0 32 c0 2e c0 2a   .j.9.8.....2...*

0050 - c0 26 c0 0f c0 05 00 9d-00 3d 00 35 00 84 c0 12   .&.......=.5....

0060 - c0 08 00 16 00 13 c0 0d-c0 03 00 0a c0 2f c0 2b   ............./.+

0070 - c0 27 c0 23 c0 13 c0 09-00 a2 00 9e 00 67 00 40   .'.#.........g.@

0080 - 00 33 00 32 00 9a 00 99-00 45 00 44 c0 31 c0 2d   .3.2.....E.D.1.-

0090 - c0 29 c0 25 c0 0e c0 04-00 9c 00 3c 00 2f 00 96   .).%.......<./..

00a0 - 00 41 c0 11 c0 07 c0 0c-c0 02 00 05 00 04 00 15   .A..............

00b0 - 00 12 00 09 00 ff 01 00-00 6d 00 0b 00 04 03 00   .........m......

00c0 - 01 02 00 0a 00 34 00 32-00 0e 00 0d 00 19 00 0b   .....4.2........

▽

00d0 - 00 0c 00 18 00 09 00 0a-00 16 00 17 00 08 00 06   ................

00e0 - 00 07 00 14 00 15 00 04-00 05 00 12 00 13 00 01   ................

00f0 - 00 02 00 03 00 0f 00 10-00 11 00 23 00 00 00 0d   ...........#....

0100 - 00 20 00 1e 06 01 06 02-06 03 05 01 05 02 05 03   . ..............

0110 - 04 01 04 02 04 03 03 01-03 02 03 03 02 01 02 02   ................

0120 - 02 03 00 0f 00 01 01                              .......

read from 0x20c7a40 [0x20cd020] (7 bytes => -1 (0xFFFFFFFFFFFFFFFF))

write:errno=104

---

no peer certificate available

---

No client certificate CA names sent

---

SSL handshake has read 0 bytes and written 295 bytes

---

New, (NONE), Cipher is (NONE)

Secure Renegotiation IS NOT supported

Compression: NONE

Expansion: NONE

---ere...

I also paste the tcpdump for one trial of openssl s_client. 

root@rmq:~# tcpdump -i eth0 -vv 'port 5671'

tcpdump: listening on eth0, link-type EN10MB (Ethernet), capture size 65535 bytes

19:29:50.327515 IP (tos 0x20, ttl 63, id 28092, offset 0, flags [DF], proto TCP (6), length 60)

    lab.43440 > rmq.5671: Flags [S], cksum 0x8ba8 (correct), seq 4084649281, win 29200, options [mss 1460,sackOK,TS val 4074217725 ecr 0,nop,wscale 7], length 0

19:29:50.327558 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 60)

    rmq.5671 > lab.43440: Flags [S.], cksum 0x3610 (incorrect -> 0x715c), seq 2602076729, ack 4084649282, win 28960, options [mss 1460,sackOK,TS val 1131065971 ecr 4074217725,nop,wscale 2], length 0

19:29:50.327763 IP (tos 0x20, ttl 63, id 28093, offset 0, flags [DF], proto TCP (6), length 52)

    lab.43440 > rmq.5671: Flags [.], cksum 0x105f (correct), seq 1, ack 1, win 229, options [nop,nop,TS val 4074217725 ecr 1131065971], length 0

19:29:50.328482 IP (tos 0x0, ttl 64, id 14409, offset 0, flags [DF], proto TCP (6), length 52)

    rmq.5671 > lab.43440: Flags [R.], cksum 0x3608 (incorrect -> 0xf4f7), seq 1, ack 1, win 7240, options [nop,nop,TS val 1131065971 ecr 4074217725], length 0

Does anyone have any clue what is going wrong with the rabbitmq server? 

[Michael Klishin]

Can we please take a step back and explain what problem is being solved here? What are the expectations?

*When* do you expect RabbitMQ to reject connections and *why*? It is not at all clear from your post.

You have fail_if_no_peer_cert set to `false` which means RabbitMQ won't reject a client that sends

no certificate chain, and that's exactly what you instruct `openssl s_client` to do in one of the posted snippets.

Honestly using fail_if_no_peer_cert = false and verify = verify_peer makes little sense to me.

Also, I'm not sure where you are getting the config example from but

 * rabbit_mochiweb hasn't been around since 3.6.0 or and even then wasn't the recommended way of configuring the port


* Debug logging, while unlikely to be particularly useful here, is enabled differently in 3.7.x [1]




1. http://www.rabbitmq.com/logging.html


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

[Michael Klishin]

Perhaps going through [1] to clarify how peer verification works would be a good first step.

Then converting to the new config format to make sure you are not using any materials from several years ago.

Then posting an example of what you are trying to achieve using OpenSSL CLI tools and optionally a separate set

of certificates (tls-gen [2] or similar can help quickly produce any number of those, including less trivial chains).

1. http://www.rabbitmq.com/ssl.html#peer-verification

2. https://github.com/michaelklishin/tls-gen

[Bowen Liu]

Hi Michael, thank you for the reply. I modified the config and generated the cerver/ca pairs using the linked tls tool. But the issue is till there as previous.

[

  {rabbit, [

    {tcp_listen_options, [

           {sndbuf,       196608},

           {linger,       {true,0}},

           {recbuf,       196608},

           {exit_on_close,       false},

           {nodelay,       true},

           {backlog,       4096}

    ]},

    {vm_memory_high_watermark,  0.7},

    {hipe_compile,  true},

    {msg_store_file_size_limit,  167772160},

    {handshake_timeout,  20000},

    {tcp_listeners,  [5672]},

    {disk_free_limit,  {mem_relative, 0.3}},

    {log, [

           {file, [{file, "/var/log/rabbitmq/rab...@rmq.log"}, %% log.file

                    {level, debug},        %% log.file.info

                    {date, ""},           %% log.file.rotation.date

                    {size, 0},            %% log.file.rotation.size

                    {count, 1}            %% log.file.rotation.count

            ]}

    ]},

    {ssl_listeners, [5671]},

    {ssl_options, [ {cacertfile,   "/home/rmq/certs/ca_certification.pem"},

    {certfile,   "/home/rmq/certs/server_certification.pem"},

                    {keyfile,   "/home/rmq/keys/server_key.pem"},

                    {verify,    verify_peer},

                    {fail_if_no_peer_cert, false}]}

  ]},

  {rabbitmq_management, [{listener, [{port, 15672}]}]}

].

The openssl server/client test is successfull with Verify return code: 0 (ok), but the ssl connection to rabbitmq server is still failing as the following. 

root@rmq-11-lab-cl-2:~/result# openssl s_client -connect rmq:5671 -cert client_certificate.pem -key client_key.pem -CAfile ca_certificate.pem  -debug

CONNECTED(00000003)

write to 0x158d900 [0x158d980] (295 bytes => 295 (0x127))

0000 - 16 03 01 01 22 01 00 01-1e 03 03 17 43 9f 12 c0   ....".......C...

0010 - 4c e3 10 de fc d9 a8 19-26 2a 0b cf fc 01 50 f9   L.......&*....P.

0020 - 1a 6e ed 57 ac 20 55 e6-ea 22 48 00 00 88 c0 30   .n.W. U.."H....0

0030 - c0 2c c0 28 c0 24 c0 14-c0 0a 00 a3 00 9f 00 6b   .,.(.$.........k

0040 - 00 6a 00 39 00 38 00 88-00 87 c0 32 c0 2e c0 2a   .j.9.8.....2...*

0050 - c0 26 c0 0f c0 05 00 9d-00 3d 00 35 00 84 c0 12   .&.......=.5....

0060 - c0 08 00 16 00 13 c0 0d-c0 03 00 0a c0 2f c0 2b   ............./.+

0070 - c0 27 c0 23 c0 13 c0 09-00 a2 00 9e 00 67 00 40   .'.#.........g.@

0080 - 00 33 00 32 00 9a 00 99-00 45 00 44 c0 31 c0 2d   .3.2.....E.D.1.-

0090 - c0 29 c0 25 c0 0e c0 04-00 9c 00 3c 00 2f 00 96   .).%.......<./..

00a0 - 00 41 c0 11 c0 07 c0 0c-c0 02 00 05 00 04 00 15   .A..............

00b0 - 00 12 00 09 00 ff 01 00-00 6d 00 0b 00 04 03 00   .........m......

00c0 - 01 02 00 0a 00 34 00 32-00 0e 00 0d 00 19 00 0b   .....4.2........

00d0 - 00 0c 00 18 00 09 00 0a-00 16 00 17 00 08 00 06   ................

00e0 - 00 07 00 14 00 15 00 04-00 05 00 12 00 13 00 01   ................

00f0 - 00 02 00 03 00 0f 00 10-00 11 00 23 00 00 00 0d   ...........#....

0100 - 00 20 00 1e 06 01 06 02-06 03 05 01 05 02 05 03   . ..............

0110 - 04 01 04 02 04 03 03 01-03 02 03 03 02 01 02 02   ................

0120 - 02 03 00 0f 00 01 01                              .......

read from 0x158d900 [0x1592ee0] (7 bytes => -1 (0xFFFFFFFFFFFFFFFF))

[Bowen Liu]

Another finding is telnet 5671 is closed right away. It looks like rmq server rejects any connections to the port 5671

root@rmq:~/result# telnet rmq-11-lab-cl-2.phx7.llnw.net 5671

Trying 10.14.209.11...

Connected to rmq.

Escape character is '^]'.

Connection closed by foreign host.

On Wednesday, December 19, 2018 at 7:58:12 PM UTC-7, Bowen Liu wrote:

[Bowen Liu]

By specifying the ssl versions supported by erlang including -tls1, -tls1_1, -tls1_2, -ssl3, it output the final SSL sessions with Verify return code: 0 (ok). Does it mean the rabbitmq ssl is working properly?

root@rmq:~/result# erl

Erlang/OTP 21 [erts-10.1] [source] [64-bit] [smp:16:16] [ds:16:16:10] [async-threads:1] [hipe]

Eshell V10.1  (abort with ^G)

1> ssl:versions().

[{ssl_app,"9.0.2"},

 {supported,['tlsv1.2','tlsv1.1',tlsv1]},

 {supported_dtls,['dtlsv1.2',dtlsv1]},

 {available,['tlsv1.2','tlsv1.1',tlsv1,sslv3]},

 {available_dtls,['dtlsv1.2',dtlsv1]}]

root@rmq:~/result# openssl s_client -connect rmq:5671 -tls1_2

CONNECTED(00000003)

write:errno=104

---

no peer certificate available

---

No client certificate CA names sent

---

SSL handshake has read 0 bytes and written 0 bytes

---

New, (NONE), Cipher is (NONE)

Secure Renegotiation IS NOT supported

Compression: NONE

Expansion: NONE

SSL-Session:

    Protocol  : TLSv1.2

    Cipher    : 0000

    Session-ID:

    Session-ID-ctx:

    Master-Key:

    Key-Arg   : None

    PSK identity: None

    PSK identity hint: None

    SRP username: None

    Start Time: 1545332082

    Timeout   : 7200 (sec)

    Verify return code: 0 (ok)

---

On Wednesday, December 19, 2018 at 7:58:12 PM UTC-7, Bowen Liu wrote:

[Luke Bakken]

Hello,

No, TLS/SSL is probably still not working.

What do you see in your RabbitMQ log files? Or, share the entire log as an attachment so we can see what is in it.

Thanks,

Luke

[Bowen Liu]

Hi Luke,

I hope rabbitmq could log anything with debug level around the ssl test. But there were no such log output. The followings are the entries since the server start.

2018-12-20 12:19:05.504 [info] <0.5864.0>

 Starting RabbitMQ 3.7.7 on Erlang 21.1

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

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

2018-12-20 12:19:05.505 [info] <0.5864.0>

 node           : rabbit@rmq

 home dir       : /var/lib/rabbitmq

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

 cookie hash    : dk6LgZo4NWOB8n3S7kTClA==

 log(s)         : /var/log/rabbitmq/rab...@rmq.log

                : /var/log/rabbitmq/rabbit@rmq_upgrade.log

 database dir   : /data/rabbit@rmq

2018-12-20 12:19:06.782 [debug] <0.5957.0> Supervisor rabbit_alarm_sup started rabbit_alarm:start_link() at pid <0.5958.0>

2018-12-20 12:19:06.786 [info] <0.5960.0> Memory high watermark set to 33805 MiB (35447486054 bytes) of 48293 MiB (50639265792 bytes) total

2018-12-20 12:19:06.787 [debug] <0.5959.0> Supervisor vm_memory_monitor_sup started vm_memory_monitor:start_link(0.7, #Fun<rabbit_alarm.0.123076882>, #Fun<rabbit_alarm.1.123076882>) at pid <0.5960.0>

2018-12-20 12:19:06.791 [info] <0.5962.0> Enabling free disk space monitoring

2018-12-20 12:19:06.791 [info] <0.5962.0> Disk free limit set to 15191MB

2018-12-20 12:19:06.795 [debug] <0.5961.0> Supervisor rabbit_disk_monitor_sup started rabbit_disk_monitor:start_link({mem_relative,0.3}) at pid <0.5962.0>

2018-12-20 12:19:06.795 [info] <0.5964.0> Limiting to approx 65436 file handles (58890 sockets)

2018-12-20 12:19:06.795 [info] <0.5965.0> FHC read buffering:  OFF

2018-12-20 12:19:06.795 [info] <0.5965.0> FHC write buffering: ON

2018-12-20 12:19:06.795 [debug] <0.5963.0> Supervisor file_handle_cache_sup started file_handle_cache:start_link(fun rabbit_alarm:set_alarm/1, fun rabbit_alarm:clear_alarm/1) at pid <0.5964.0>

2018-12-20 12:19:06.799 [info] <0.5864.0> Waiting for Mnesia tables for 30000 ms, 9 retries left

2018-12-20 12:19:06.822 [info] <0.5864.0> Waiting for Mnesia tables for 30000 ms, 9 retries left

2018-12-20 12:19:06.900 [info] <0.5864.0> Waiting for Mnesia tables for 30000 ms, 9 retries left

2018-12-20 12:19:06.900 [info] <0.5864.0> Peer discovery backend rabbit_peer_discovery_classic_config does not support registration, skipping registration.

2018-12-20 12:19:06.900 [debug] <0.5994.0> Supervisor rabbit_event_sup started rabbit_event:start_link() at pid <0.5995.0>

2018-12-20 12:19:06.901 [info] <0.5864.0> Priority queues enabled, real BQ is rabbit_variable_queue

2018-12-20 12:19:06.902 [debug] <0.5996.0> Supervisor rabbit_epmd_monitor_sup started rabbit_epmd_monitor:start_link() at pid <0.5997.0>

2018-12-20 12:19:06.918 [debug] <0.5998.0> Supervisor rabbit_guid_sup started rabbit_guid:start_link() at pid <0.5999.0>

2018-12-20 12:19:06.919 [info] <0.6001.0> Starting rabbit_node_monitor

2018-12-20 12:19:06.919 [debug] <0.6000.0> Supervisor rabbit_node_monitor_sup started rabbit_node_monitor:start_link() at pid <0.6001.0>

2018-12-20 12:19:06.921 [debug] <0.6020.0> Supervisor rabbit_memory_monitor_sup started rabbit_memory_monitor:start_link() at pid <0.6021.0>

2018-12-20 12:19:06.964 [info] <0.5864.0> Management plugin: using rates mode 'basic'

2018-12-20 12:19:06.967 [debug] <0.6034.0> Recovering data for VHost <<"/">>

2018-12-20 12:19:06.967 [info] <0.6034.0> Making sure data directory '/data/rabbit@rmq/msg_stores/vhosts/628WB79CIFDYO9LJI6DKMI09L' for vhost '/' exists

2018-12-20 12:19:06.968 [debug] <0.6033.0> Supervisor {<0.6033.0>,rabbit_vhost_sup} started rabbit_recovery_terms:start_link(<<"/">>) at pid <0.6035.0>

2018-12-20 12:19:06.991 [info] <0.6034.0> Starting message stores for vhost '/'

2018-12-20 12:19:06.991 [info] <0.6038.0> Message store "628WB79CIFDYO9LJI6DKMI09L/msg_store_transient": using rabbit_msg_store_ets_index to provide index

2018-12-20 12:19:06.992 [info] <0.6034.0> Started message store of type transient for vhost '/'

2018-12-20 12:19:06.992 [debug] <0.6033.0> Supervisor {<0.6033.0>,rabbit_vhost_sup} started rabbit_msg_store:start_link(msg_store_transient, "/data/rabbit@rmq/msg_stores/vhosts/628WB79CIFDYO9LJI6DKMI09L", undefined, {#Fun<rabbit_variable_queue.2.44586449>,ok}) at pid <0.6038.0>

2018-12-20 12:19:06.993 [info] <0.6041.0> Message store "628WB79CIFDYO9LJI6DKMI09L/msg_store_persistent": using rabbit_msg_store_ets_index to provide index

2018-12-20 12:19:06.994 [info] <0.6034.0> Started message store of type persistent for vhost '/'

2018-12-20 12:19:06.994 [debug] <0.6033.0> Supervisor {<0.6033.0>,rabbit_vhost_sup} started rabbit_msg_store:start_link(msg_store_persistent, "/data/rabbit@rmq/msg_stores/vhosts/628WB79CIFDYO9LJI6DKMI09L", [], {#Fun<rabbit_queue_index.2.122888644>,{start,[]}}) at pid <0.6041.0>

2018-12-20 12:19:06.994 [debug] <0.6033.0> Supervisor {<0.6033.0>,rabbit_vhost_sup} started rabbit_amqqueue_sup_sup:start_link() at pid <0.6047.0>

2018-12-20 12:19:06.998 [debug] <0.6069.0> Recovering data for VHost <<"/provision">>

2018-12-20 12:19:06.999 [info] <0.6069.0> Making sure data directory '/data/rabbit@rmq/msg_stores/vhosts/CPBXSPXHBW94V5EERVFTYR71G' for vhost '/provision' exists

2018-12-20 12:19:07.000 [debug] <0.6068.0> Supervisor {<0.6068.0>,rabbit_vhost_sup} started rabbit_recovery_terms:start_link(<<"/provision">>) at pid <0.6070.0>

2018-12-20 12:19:07.021 [info] <0.6069.0> Starting message stores for vhost '/provision'

2018-12-20 12:19:07.021 [info] <0.6074.0> Message store "CPBXSPXHBW94V5EERVFTYR71G/msg_store_transient": using rabbit_msg_store_ets_index to provide index

2018-12-20 12:19:07.023 [info] <0.6069.0> Started message store of type transient for vhost '/provision'

2018-12-20 12:19:07.023 [debug] <0.6068.0> Supervisor {<0.6068.0>,rabbit_vhost_sup} started rabbit_msg_store:start_link(msg_store_transient, "/data/rabbit@rmq/msg_stores/vhosts/CPBXSPXHBW94V5EERVFTYR71G", undefined, {#Fun<rabbit_variable_queue.2.44586449>,ok}) at pid <0.6074.0>

2018-12-20 12:19:07.023 [info] <0.6077.0> Message store "CPBXSPXHBW94V5EERVFTYR71G/msg_store_persistent": using rabbit_msg_store_ets_index to provide index

2018-12-20 12:19:07.025 [info] <0.6069.0> Started message store of type persistent for vhost '/provision'

2018-12-20 12:19:07.025 [debug] <0.6068.0> Supervisor {<0.6068.0>,rabbit_vhost_sup} started rabbit_msg_store:start_link(msg_store_persistent, "/data/rabbit@rmq/msg_stores/vhosts/CPBXSPXHBW94V5EERVFTYR71G", [], {#Fun<rabbit_queue_index.2.122888644>,{start,[]}}) at pid <0.6077.0>

2018-12-20 12:19:07.025 [debug] <0.6068.0> Supervisor {<0.6068.0>,rabbit_vhost_sup} started rabbit_amqqueue_sup_sup:start_link() at pid <0.6083.0>

2018-12-20 12:19:07.029 [debug] <0.6103.0> Supervisor rabbit_core_metrics_gc_sup started rabbit_core_metrics_gc:start_link() at pid <0.6104.0>

2018-12-20 12:19:07.029 [debug] <0.6105.0> Supervisor background_gc_sup started background_gc:start_link() at pid <0.6106.0>

2018-12-20 12:19:07.032 [info] <0.6122.0> started TCP Listener on [::]:5672

2018-12-20 12:19:07.035 [info] <0.6138.0> started SSL Listener on [::]:5671

2018-12-20 12:19:07.036 [info] <0.5864.0> Setting up a table for connection tracking on this node: 'tracked_connection_on_node_rabbit@rmq'

2018-12-20 12:19:07.037 [info] <0.5864.0> Setting up a table for per-vhost connection counting on this node: 'tracked_connection_per_vhost_on_node_rabbit@rmq'

2018-12-20 12:19:07.037 [info] <0.6001.0> rabbit on node 'rabbit@rmq-11-lab-cl-1' up

2018-12-20 12:19:07.037 [debug] <0.6145.0> Supervisor rabbit_shovel_sup started rabbit_shovel_status:start_link() at pid <0.6146.0>

2018-12-20 12:19:07.038 [debug] <0.6147.0> Supervisor rabbit_shovel_dyn_worker_sup_sup started supervisor2:start_link(mirrored_supervisor_sups, {delegate,{one_for_one,3,10}}) at pid <0.6148.0>

2018-12-20 12:19:07.038 [debug] <0.6147.0> Supervisor rabbit_shovel_dyn_worker_sup_sup started mirrored_supervisor:start_internal(rabbit_shovel_dyn_worker_sup_sup, fun rabbit_misc:execute_mnesia_transaction/1, []) at pid <0.6149.0>

2018-12-20 12:19:07.040 [debug] <0.6145.0> Supervisor rabbit_shovel_sup started rabbit_shovel_dyn_worker_sup_sup:start_link() at pid <0.6147.0>

2018-12-20 12:19:07.078 [debug] <0.6155.0> Supervisor rabbit_mgmt_agent_sup_sup started rabbit_mgmt_agent_sup:start_link() at pid <0.6156.0>

2018-12-20 12:19:07.120 [info] <0.6199.0> Management plugin started. Port: 15672

2018-12-20 12:19:07.120 [info] <0.6305.0> Statistics database started.

2018-12-20 12:19:07.120 [debug] <0.6303.0> Supervisor rabbit_mgmt_sup_sup started rabbit_mgmt_sup:start_link() at pid <0.6304.0>

2018-12-20 12:19:07.128 [notice] <0.5692.0> Changed loghwm of /var/log/rabbitmq/rab...@rmq.log to 50

2018-12-20 12:19:07.230 [info] <0.7.0> Server startup complete; 8 plugins started.

 * rabbitmq_shovel_management

 * rabbitmq_amqp1_0

 * rabbitmq_top

 * rabbitmq_management

 * rabbitmq_web_dispatch

 * rabbitmq_management_agent

 * rabbitmq_event_exchange

 * rabbitmq_shovel

On Wednesday, December 19, 2018 at 7:58:12 PM UTC-7, Bowen Liu wrote:

[Luke Bakken]

Thanks for sharing that.

What is the output of these commands? The reason I ask is that the rabbitmq user must be able to read your certs.

ls -ld /etc
ls -ld /etc/ssl
ls -ld /etc/ssl/llnw
ls -la /etc/ssl/llnw/certs

[Bowen Liu]

The permissions on read to others. rabbitmq should be able to read cert/key files

-rw-r--r-- 1 root ssl-cert

--

[Luke Bakken]

Hello,

It's important to run a sequence of commands exactly as we give them. Please run those four commands and provide all of the output. If you'd like to redirect the output to a text file and attach it, that would be even better.

If those directory names aren't what you are using, modify the commands to show the permissions the entire way down the directory tree.

Thanks,

Luke

On Thursday, December 20, 2018 at 1:47:13 PM UTC-8, Bowen Liu wrote:

The permissions on read to others. rabbitmq should be able to read cert/key files

-rw-r--r-- 1 root ssl-cert

On Thu, Dec 20, 2018 at 1:19 PM Luke Bakken <lba...@pivotal.io> wrote:

Thanks for sharing that.

What is the output of these commands? The reason I ask is that the rabbitmq user must be able to read your certs.

ls -ld /etc
ls -ld /etc/ssl
ls -ld /etc/ssl/llnw
ls -la /etc/ssl/llnw/certs

On Thursday, December 20, 2018 at 11:59:09 AM UTC-8, Bowen Liu wrote:

Hi Luke,

I hope rabbitmq could log anything with debug level around the ssl test. But there were no such log output. The followings are the entries since the server start.

--
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-users+unsubscribe@googlegroups.com.
To post to this group, send email to rabbitmq-users@googlegroups.com.

[Bowen Liu]

Please check the output.

root@rmq:~# ls -ld /etc

drwxr-xr-x 104 root root 12288 Dec 19 18:07 /etc

root@rmq:~# ls -ld /etc/ssl

drwxr-xr-x 5 root root 4096 Dec 28  2017 /etc/ssl

root@rmq:~# ls -ld /etc/ssl/llnw

drwxr-xr-x 4 root root 4096 Dec 28  2017 /etc/ssl/llnw

root@rmq:~# ls -la /etc/ssl/llnw/certs

drwxr-xr-x 2 root ssl-cert  4096 Dec 20 09:09 .

drwxr-xr-x 4 root root      4096 Dec 28  2017 ..

-rw-r--r-- 1 root ssl-cert 11705 Dec 29  2017 ca.crt

-rw-r--r-- 1 root ssl-cert  8882 Dec 29  2017 cert.crt

root@rmq:~# ls -la /etc/ssl/llnw/keys/

drwx--x--- 2 root ssl-cert 4096 Dec 20 09:09 .

drwxr-xr-x 4 root root     4096 Dec 28  2017 ..

-rw-r--r-- 1 root ssl-cert 1704 Dec 29  2017 key.key

On Thu, Dec 20, 2018 at 2:50 PM Luke Bakken <lba...@pivotal.io> wrote:

Hello,

It's important to run a sequence of commands exactly as we give them. Please run those four commands and provide all of the output. If you'd like to redirect the output to a text file and attach it, that would be even better.

If those directory names aren't what you are using, modify the commands to show the permissions the entire way down the directory tree.

Thanks,

Luke

On Thursday, December 20, 2018 at 1:47:13 PM UTC-8, Bowen Liu wrote:

The permissions on read to others. rabbitmq should be able to read cert/key files

-rw-r--r-- 1 root ssl-cert

On Thu, Dec 20, 2018 at 1:19 PM Luke Bakken <lba...@pivotal.io> wrote:

Thanks for sharing that.

What is the output of these commands? The reason I ask is that the rabbitmq user must be able to read your certs.

ls -ld /etc
ls -ld /etc/ssl
ls -ld /etc/ssl/llnw
ls -la /etc/ssl/llnw/certs

On Thursday, December 20, 2018 at 11:59:09 AM UTC-8, Bowen Liu wrote:

Hi Luke,

I hope rabbitmq could log anything with debug level around the ssl test. But there were no such log output. The followings are the entries since the server start.

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

--

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.

[Luke Bakken]

Thanks for providing that output, now we can move on to my next suggestion. You may be running into an issue with limited cipher suite availability. Using Erlang 21.1, notice that the default number of available suites is less than the total (on my machine):

2> length(ssl:cipher_suites()).

36

3> length(ssl:cipher_suites(all)).

74

To test out the cipher suites theory, please do this:

• Run the erl command
  
• Run this command in the shell (the period is significant): rp(ssl:cipher_suites(all)).

You will see a list of all supported suites on your platform. I have taken your configuration from earlier in the discussion, simplified it, and copied in the suites from my machine to give you an idea. Your list of ciphers might be a little different, or it might be the same as what I've attached. Save the file as /etc/rabbitmq/rabbitmq.config, restart RabbitMQ, and re-try your openssl commands and / or connections from clients.

Please use the simplified version of the configuration as it removes extra items that you don't need to use at this point.

Thanks,

Luke

[Bowen Liu]

Thanks for the suggestion! Unfortunately, it doesn't change anything in the test. 

rp(ssl:cipher_suites(all)). output is attached in text file

root@rmq:/etc/rabbitmq# openssl s_client -connect rmq:5671 -tls1_2

CONNECTED(00000003)

write:errno=104

---

no peer certificate available

---

No client certificate CA names sent

---

SSL handshake has read 0 bytes and written 0 bytes

---

New, (NONE), Cipher is (NONE)

Secure Renegotiation IS NOT supported

Compression: NONE

Expansion: NONE

SSL-Session:

    Protocol  : TLSv1.2

    Cipher    : 0000

    Session-ID:

    Session-ID-ctx:

    Master-Key:

    Key-Arg   : None

    PSK identity: None

    PSK identity hint: None

    SRP username: None

    Start Time: 1545351009

    Timeout   : 7200 (sec)

    Verify return code: 0 (ok)

---

018-12-20 17:09:21.683 [info] <0.7.0> Log file opened with Lager

2018-12-20 17:09:22.831 [info] <0.254.0>

 Starting RabbitMQ 3.7.7 on Erlang 21.1

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

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

2018-12-20 17:09:22.832 [info] <0.254.0>

 node           : rabbit@rmq

 home dir       : /var/lib/rabbitmq

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

 cookie hash    : dk6LgZo4NWOB8n3S7kTClA==

 log(s)         : /var/log/rabbitmq/rab...@rmq.log

                : /var/log/rabbitmq/rabbit@rmq_upgrade.log

 database dir   : /data/rabbit@rmq

2018-12-20 17:09:24.069 [info] <0.314.0> Memory high watermark set to 19317 MiB (20255706316 bytes) of 48293 MiB (50639265792 bytes) total

2018-12-20 17:09:24.074 [info] <0.317.0> Enabling free disk space monitoring

2018-12-20 17:09:24.074 [info] <0.317.0> Disk free limit set to 50MB

2018-12-20 17:09:24.078 [info] <0.319.0> Limiting to approx 65436 file handles (58890 sockets)

2018-12-20 17:09:24.078 [info] <0.320.0> FHC read buffering:  OFF

2018-12-20 17:09:24.078 [info] <0.320.0> FHC write buffering: ON

2018-12-20 17:09:24.081 [info] <0.254.0> Waiting for Mnesia tables for 30000 ms, 9 retries left

2018-12-20 17:09:24.187 [info] <0.254.0> Waiting for Mnesia tables for 30000 ms, 9 retries left

2018-12-20 17:09:24.187 [info] <0.254.0> Peer discovery backend rabbit_peer_discovery_classic_config does not support registration, skipping registration.

2018-12-20 17:09:24.189 [info] <0.254.0> Priority queues enabled, real BQ is rabbit_variable_queue

2018-12-20 17:09:24.204 [info] <0.355.0> Starting rabbit_node_monitor

2018-12-20 17:09:24.247 [info] <0.254.0> Management plugin: using rates mode 'basic'

2018-12-20 17:09:24.248 [info] <0.387.0> Making sure data directory '/data/rabbit@rmq/msg_stores/vhosts/628WB79CIFDYO9LJI6DKMI09L' for vhost '/' exists

2018-12-20 17:09:24.273 [info] <0.387.0> Starting message stores for vhost '/'

2018-12-20 17:09:24.274 [info] <0.392.0> Message store "628WB79CIFDYO9LJI6DKMI09L/msg_store_transient": using rabbit_msg_store_ets_index to provide index

2018-12-20 17:09:24.275 [info] <0.387.0> Started message store of type transient for vhost '/'

2018-12-20 17:09:24.275 [info] <0.395.0> Message store "628WB79CIFDYO9LJI6DKMI09L/msg_store_persistent": using rabbit_msg_store_ets_index to provide index

2018-12-20 17:09:24.276 [info] <0.387.0> Started message store of type persistent for vhost '/'

2018-12-20 17:09:24.280 [info] <0.423.0> Making sure data directory '/data/rabbit@rmq/msg_stores/vhosts/CPBXSPXHBW94V5EERVFTYR71G' for vhost '/provision' exists

2018-12-20 17:09:24.304 [info] <0.423.0> Starting message stores for vhost '/provision'

2018-12-20 17:09:24.304 [info] <0.427.0> Message store "CPBXSPXHBW94V5EERVFTYR71G/msg_store_transient": using rabbit_msg_store_ets_index to provide index

2018-12-20 17:09:24.306 [info] <0.423.0> Started message store of type transient for vhost '/provision'

2018-12-20 17:09:24.306 [info] <0.430.0> Message store "CPBXSPXHBW94V5EERVFTYR71G/msg_store_persistent": using rabbit_msg_store_ets_index to provide index

2018-12-20 17:09:24.308 [info] <0.423.0> Started message store of type persistent for vhost '/provision'

2018-12-20 17:09:24.316 [info] <0.475.0> started TCP Listener on [::]:5672

2018-12-20 17:09:24.319 [info] <0.491.0> started SSL Listener on [::]:5671

2018-12-20 17:09:24.320 [info] <0.254.0> Setting up a table for connection tracking on this node: 'tracked_connection_on_node_rabbit@rmq'

2018-12-20 17:09:24.320 [info] <0.254.0> Setting up a table for per-vhost connection counting on this node: 'tracked_connection_per_vhost_on_node_rabbit@rmq'

2018-12-20 17:09:24.369 [info] <0.553.0> Management plugin started. Port: 15672

2018-12-20 17:09:24.370 [info] <0.660.0> Statistics database started.

2018-12-20 17:09:24.377 [notice] <0.109.0> Changed loghwm of /var/log/rabbitmq/rab...@rmq.log to 50

2018-12-20 17:09:24.475 [info] <0.7.0> Server startup complete; 8 plugins started.

 * rabbitmq_top

 * rabbitmq_shovel_management

 * rabbitmq_management

 * rabbitmq_shovel

 * rabbitmq_amqp1_0

 * rabbitmq_event_exchange

 * rabbitmq_management_agent

 * rabbitmq_web_dispatch

--

[Bowen Liu]

Hi Luke, good news, looks like it's still the permission issue. key dir doesn't have exec perm for user rabbitmq, although it has the read for the key file. Adding rabbitmq user into the ssl-cert group. It's working now

-rw-r--r-- 1 root ssl-cert 1704 Dec 29  2017 key.key

root@rmq:~# id rabbitmq

uid=107(rabbitmq) gid=116(rabbitmq) groups=116(rabbitmq),112(ssl-cert)

But the openssl test gives the following rabbitmq log

2018-12-20 17:26:15.566 [info] <0.10607.0> TLS server: In state certify received CLIENT ALERT: Fatal - Unexpected Message

2018-12-20 17:36:46.496 [info] <0.10784.0> TLS server: In state certify received CLIENT ALERT: Fatal - Decrypt Error

Meanwhile, perf test codes output:

export uri='amqps://XXX:XXX@rmq:5671'

bliu@lab:~/rabbitmq-perf-test-2.1.2$ bin/runjava com.rabbitmq.perf.PerfTest --uri $uri

17:26:15.417 [main] WARN com.rabbitmq.client.TrustEverythingTrustManager - This trust manager trusts every certificate, effectively disabling peer verification. This is convenient for local development but prone to man-in-the-middle attacks. Please see http://www.rabbitmq.com/ssl.html#validating-cerficates to learn more about peer certificate validation.

Main thread caught exception: javax.net.ssl.SSLKeyException: Invalid signature on ECDH server key exchange message

javax.net.ssl.SSLKeyException: Invalid signature on ECDH server key exchange message

at sun.security.ssl.HandshakeMessage$ECDH_ServerKeyExchange.<init>(HandshakeMessage.java:1117)

at sun.security.ssl.ClientHandshaker.processMessage(ClientHandshaker.java:284)

at sun.security.ssl.Handshaker.processLoop(Handshaker.java:1026)

at sun.security.ssl.Handshaker.process_record(Handshaker.java:961)

at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:1072)

at sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1385)

at sun.security.ssl.SSLSocketImpl.writeRecord(SSLSocketImpl.java:757)

at sun.security.ssl.AppOutputStream.write(AppOutputStream.java:123)

at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)

at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)

at java.io.DataOutputStream.flush(DataOutputStream.java:123)

at com.rabbitmq.client.impl.SocketFrameHandler.sendHeader(SocketFrameHandler.java:147)

at com.rabbitmq.client.impl.SocketFrameHandler.sendHeader(SocketFrameHandler.java:153)

at com.rabbitmq.client.impl.AMQConnection.start(AMQConnection.java:303)

at com.rabbitmq.client.impl.recovery.RecoveryAwareAMQConnectionFactory.newConnection(RecoveryAwareAMQConnectionFactory.java:64)

at com.rabbitmq.client.impl.recovery.AutorecoveringConnection.init(AutorecoveringConnection.java:134)

at com.rabbitmq.client.ConnectionFactory.newConnection(ConnectionFactory.java:997)

at com.rabbitmq.client.ConnectionFactory.newConnection(ConnectionFactory.java:956)

at com.rabbitmq.client.ConnectionFactory.newConnection(ConnectionFactory.java:1084)

at com.rabbitmq.perf.MulticastSet.run(MulticastSet.java:89)

at com.rabbitmq.perf.PerfTest.main(PerfTest.java:239)

at com.rabbitmq.perf.PerfTest.main(PerfTest.java:313)

[Michael Klishin]

After double checking configuration, the next in troubleshooting connectivity is checking server logs.

Please follow the methodology in [1] and post your findings. We really cannot suggest much from a single `openssl s_client` output.

RabbitMQ has a protocol handshake (negotiation) timeout of 10 seconds. It will clearly log when a connection is closed

due to the handshake timeout. That's what is very likely happening in your case.

A telnet connection to an unbound port produces a very different message:

> Trying 127.0.0.1...
> telnet: connect to address 127.0.0.1: Connection refused
> telnet: Unable to connect to remote host

which is pretty specific. "Unable to connect" vs. "connection closed by foreign [remote] host".

1. https://www.rabbitmq.com/troubleshooting-networking.html

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

Key permissions has a dedicated section in [1]. Please follow our troubleshooting docs in the future,

they are produced from years of experience answering mostly the same questions on this list.

If you switch to the new style config format, file existence and readability would have been checked at node startup.

There is also a known bug in Erlang, which was fixed in 21.2, where if a key cannot be read from disk, no sensible

errors would be produced and TLS connection would go into a "limbo state". We originally reported

it in [2], which should have all the details.

1. https://www.rabbitmq.com/troubleshooting-ssl.html#verify-file-permissions

2. https://github.com/ninenines/ranch/issues/196

[Bowen Liu]

Thank you all! The issue has been resolved. The reasons are 1) rabbitmq user didn't have exec permission to the priv key dir. 2) The certificate itself is not right.

[Luke Bakken]

Thank you very much for following up and letting us know what the issues were.

On Friday, December 21, 2018 at 10:29:48 AM UTC-8, Bowen Liu wrote:

Thank you all! The issue has been resolved. The reasons are 1) rabbitmq user didn't have exec permission to the priv key dir. 2) The certificate itself is not right.