Pass a block for peer cert / cert chain logging

[film42]

There's actually a more interesting error happening here where we have:

1. tls: true, verify_peer: false, there's a custom CA cert added, no client cert/key.
2. Rabbitmq has the following options:

    {ssl_options, [
                   {cacertfile,"/etc/path/to/ssl/certs/ca.pem"},
                   {certfile,"/etc/path/to/ssl/certs/certfile.pem"},
                   {keyfile,"/etc/rabbitmq/ssl/keyfile.pem"},
                   {verify,verify_none},
                   {fail_if_no_peer_cert,false}
                   ,{versions, ['tlsv1.2']}
                  ]},

And then when we go to create a new connection using bunny (> 2.13.0), we call x.value in peer_certificate_info:

peer_cert.extensions.map { |x| x.value }

We end up with an SSL_read: nested asn1 error (OpenSSL::SSL::SSLError) error:

         8: from /home/film42/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/bunny-2.14.1/lib/bunny/session.rb:317:in `start'
         7: from /home/film42/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/bunny-2.14.1/lib/bunny/session.rb:1164:in `init_connection'
         6: from /home/film42/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/bunny-2.14.1/lib/bunny/transport.rb:261:in `read_next_frame'
         5: from /home/film42/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/bunny-2.14.1/lib/bunny/transport.rb:239:in `read_fully'
         4: from /home/film42/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/bunny-2.14.1/lib/bunny/cruby/ssl_socket.rb:44:in `read_fully'
         3: from /home/film42/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/bunny-2.14.1/lib/bunny/cruby/ssl_socket.rb:44:in `loop'
         2: from /home/film42/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/bunny-2.14.1/lib/bunny/cruby/ssl_socket.rb:45:in `block in read_fully'
         1: from /home/film42/.rbenv/versions/2.5.1/lib/ruby/2.5.0/openssl/buffering.rb:182:in `read_nonblock'
/home/film42/.rbenv/versions/2.5.1/lib/ruby/2.5.0/openssl/buffering.rb:182:in `sysread_nonblock': SSL_read: nested asn1 error (OpenSSL::SSL::SSLError)

Not calling x.value on the cert fixes the problem. Understanding why this is failing is a bigger problem, but I haven't discovered this yet. For now, though, this ensures the code is never called unless the log_level is set to DEBUG.

[michaelklishin]

I don't think using a block ensures nothing is logged unless log level is debug. I am not convinced a library has to change how it logs things because of one problematic certificate either.

Perhaps you should inspect that certificate's extensions (both using openssl CLI tools and a Ruby REPL) before any conclusions are drawn. The mapping code could handle exceptions or other scenarios.

Certificates are public keys, so their information can be shared publicly (values such as SANs or CN can be edited out for privacy reasons).

[michaelklishin]

A quick search (one, two, three) suggests that in 3 cases out of 3, the issue ended up being a certificate format/payload problem.

I am not aware of scenarios where Erlang's TLS implementation would send an incorrectly encoded certificate. My best guess is that the local OpenSSL version might trip up on an unknown extension. Comparing openssl x509 -in /path/to/server_certificate.pem -text -noout output to what Ruby's OpenSSL library returns as peer certificate extensions would help prove this right or wrong.

Something like this:

cert = OpenSSL::X509::Certificate.new(File.read('server_certificate.pem'))
puts cert.extensions.inspect

Please start a rabbitmq-users mailing list thread.

[michaelklishin]

Or

cert = OpenSSL::X509::Certificate.new(File.read('server_certificate.pem'))
cert.extensions.map { |x| x.to_h }

[michaelklishin]

I guess we can use lazily evaluated logs regardless, in fact, we already do in a few other places.

[michaelklishin]

Backported to 2.14.x-stable. I'd be very interested in getting to the bottom of this.

[film42]

Thanks @michaelklishin . I'll open an issue with some more information.

[michaelklishin]

Please start a mailing list thread instead.