search

ruby-amqp / bunny

Bunny is a popular, easy to use, mature Ruby client for RabbitMQ
Other
1.39k stars 303 forks source link

OpenSSL error is causing unrecoverable issue #655

Closed womblep closed 1 year ago

womblep commented 1 year ago

Bunny 2.20.3 ruby 3.1 I am connecting to RabbitMQ via TLS, everything is working correctly 99.9% of the time. During development sometimes I am killing the rabbitmq server while I have multiple clients connected. Every so often I get a client that detects rabbitmq is down, tries to connect (server is still down or coming up) and errors in a way that stops it from trying to reconnect anymore. My client is then locked up and I have to restart it.

I thought it could be an issue with the type of OpenSSL error. The reader_loop->run_loop traps OpenSSL::OpenSSLError but the actual error thrown is OpenSSL::SSL::SSLError

However as it is happening during recovery from network failure, it could be that the error needs to be captured in session->start and should follow the same logic as TCPConnectionFailed

W, [2023-02-17T11:37:14.655849 #30648]  WARN -- #<Bunny::Session:0x578 guest@localhost:5671, vhost=/, addresses=[localhost:5671]>: Could not establish TCP connection to localhost:5671: No connection could be made because the target machine actively refused it. - connect(2) for 127.0.0.1:5671
W, [2023-02-17T11:37:14.656202 #30648]  WARN -- #<Bunny::Session:0x578 guest@localhost:5671, vhost=/, addresses=[localhost:5671]>: TCP connection failed, reconnecting in 5.0 seconds
W, [2023-02-17T11:37:14.656670 #30648]  WARN -- #<Bunny::Session:0x578 guest@localhost:5671, vhost=/, addresses=[localhost:5671]>: Will recover from a network failure (no retry limit)...
W, [2023-02-17T11:37:19.668318 #30648]  WARN -- #<Bunny::Session:0x578 guest@localhost:5671, vhost=/, addresses=[localhost:5671]>: Using TLS but peer hostname verification is disabled. This is convenient for local development
but prone to man-in-the-middle attacks. Please set verify_peer: true in production. Learn more at https://www.rabbitmq.com/ssl.html

W, [2023-02-17T11:37:19.668541 #30648]  WARN -- #<Bunny::Session:0x578 guest@localhost:5671, vhost=/, addresses=[localhost:5671]>: Retrying connection on next host in line: localhost:5671
E, [2023-02-17T11:37:21.733184 #30648] ERROR -- #<Bunny::Session:0x578 guest@localhost:5671, vhost=/, addresses=[localhost:5671]>: TLS connection failed: SSL_connect SYSCALL returned=5 errno=0 peeraddr=[::1]:5671 state=SSLv3/TLS write client hello
#<Thread:0x00000238c1321b98 D:/Ruby31-x64/lib/ruby/gems/3.1.0/gems/bunny-2.20.3/lib/bunny/reader_loop.rb:35 run> terminated with exception (report_on_exception is true):
D:/Ruby31-x64/lib/ruby/gems/3.1.0/gems/bunny-2.20.3/lib/bunny/transport.rb:111:in `connect': SSL_connect SYSCALL returned=5 errno=0 peeraddr=[::1]:5671 state=SSLv3/TLS write client hello (OpenSSL::SSL::SSLError)
        from D:/Ruby31-x64/lib/ruby/gems/3.1.0/gems/bunny-2.20.3/lib/bunny/transport.rb:111:in `connect'
        from D:/Ruby31-x64/lib/ruby/gems/3.1.0/gems/bunny-2.20.3/lib/bunny/session.rb:326:in `start'
        from D:/Ruby31-x64/lib/ruby/gems/3.1.0/gems/bunny-2.20.3/lib/bunny/session.rb:778:in `recover_from_network_failure'
        from D:/Ruby31-x64/lib/ruby/gems/3.1.0/gems/bunny-2.20.3/lib/bunny/session.rb:738:in `handle_network_failure'
        from D:/Ruby31-x64/lib/ruby/gems/3.1.0/gems/bunny-2.20.3/lib/bunny/reader_loop.rb:47:in `rescue in block in run_loop'
        from D:/Ruby31-x64/lib/ruby/gems/3.1.0/gems/bunny-2.20.3/lib/bunny/reader_loop.rb:37:in `block in run_loop'
        from D:/Ruby31-x64/lib/ruby/gems/3.1.0/gems/bunny-2.20.3/lib/bunny/reader_loop.rb:36:in `loop'
        from D:/Ruby31-x64/lib/ruby/gems/3.1.0/gems/bunny-2.20.3/lib/bunny/reader_loop.rb:36:in `run_loop'
D:/Ruby31-x64/lib/ruby/gems/3.1.0/gems/amq-protocol-2.3.2/lib/amq/protocol/frame.rb:60:in `decode_header': Empty response received from the server. (AMQ::Protocol::EmptyResponseError)
        from D:/Ruby31-x64/lib/ruby/gems/3.1.0/gems/bunny-2.20.3/lib/bunny/transport.rb:286:in `read_next_frame'
        from D:/Ruby31-x64/lib/ruby/gems/3.1.0/gems/bunny-2.20.3/lib/bunny/reader_loop.rb:74:in `run_once'
        from D:/Ruby31-x64/lib/ruby/gems/3.1.0/gems/bunny-2.20.3/lib/bunny/reader_loop.rb:39:in `block in run_loop'
        from D:/Ruby31-x64/lib/ruby/gems/3.1.0/gems/bunny-2.20.3/lib/bunny/reader_loop.rb:36:in `loop'
        from D:/Ruby31-x64/lib/ruby/gems/3.1.0/gems/bunny-2.20.3/lib/bunny/reader_loop.rb:36:in `run_loop'
womblep commented 1 year ago

It could also be a symptom of a wider issue with recovery. here is a different example which doesnt have anything to do with OpenSSL

`W, [2023-02-17T00:11:06.985213 #1]  WARN -- #<Bunny::Session:0x98d0 guest@rabbitmq:5671, vhost=/, addresses=[rabbitmq:5671]>: Retrying connection on next host in line: rabbitmq:5671  `
`2023-02-17T00:11:06.985862493Z W, [2023-02-17T00:11:06.985767 #1]  WARN -- #<Bunny::Session:0x98d0 guest@rabbitmq:5671, vhost=/, addresses=[rabbitmq:5671]>: Could not establish TCP connection to rabbitmq:5671: Connection refused - connect(2) for 172.18.0.3:5671  `
`2023-02-17T00:11:06.985874053Z W, [2023-02-17T00:11:06.985816 #1]  WARN -- #<Bunny::Session:0x98d0 guest@rabbitmq:5671, vhost=/, addresses=[rabbitmq:5671]>: TCP connection failed, reconnecting in 5.0 seconds  `
`2023-02-17T00:11:06.985876603Z W, [2023-02-17T00:11:06.985829 #1]  WARN -- #<Bunny::Session:0x98d0 guest@rabbitmq:5671, vhost=/, addresses=[rabbitmq:5671]>: Will recover from a network failure (no retry limit)...  `
`2023-02-17T00:11:11.991433236Z W, [2023-02-17T00:11:11.991295 #1]  WARN -- #<Bunny::Session:0x98d0 guest@rabbitmq:5671, vhost=/, addresses=[rabbitmq:5671]>: Using TLS but peer hostname verification is disabled. This is convenient for local development  `
`2023-02-17T00:11:11.991445996Z but prone to man-in-the-middle attacks. Please set verify_peer: true in production. Learn more at https://www.rabbitmq.com/ssl.html  `
`2023-02-17T00:11:11.991448876Z  `
`2023-02-17T00:11:11.991451806Z W, [2023-02-17T00:11:11.991382 #1]  WARN -- #<Bunny::Session:0x98d0 guest@rabbitmq:5671, vhost=/, addresses=[rabbitmq:5671]>: Retrying connection on next host in line: rabbitmq:5671  `
`2023-02-17T00:11:12.008982627Z E, [2023-02-17T00:11:12.008862 #1] ERROR -- #<Bunny::Session:0x98d0 guest@rabbitmq:5671, vhost=/, addresses=[rabbitmq:5671]>: Authentication with RabbitMQ failed: 403 ACCESS_REFUSED - Login was refused using authentication mechanism EXTERNAL. For details see the broker logfile.  `
`**2023-02-17T00:11:12.009201688Z #<Thread:0x00007f91595983e0 /usr/local/bundle/gems/bunny-2.20.3/lib/bunny/reader_loop.rb:35 run> terminated with exception (report_on_exception is true):**  `
`2023-02-17T00:11:12.009209578Z /usr/local/bundle/gems/bunny-2.20.3/lib/bunny/session.rb:1238:in `open_connection': Authentication with RabbitMQ failed. Please check your connection settings. Username: guest, vhost: /, password length: 5 (Bunny::AuthenticationFailureError)  `
`2023-02-17T00:11:12.009212138Z     from /usr/local/bundle/gems/bunny-2.20.3/lib/bunny/session.rb:329:in `start'  `
`2023-02-17T00:11:12.009213558Z     from /usr/local/bundle/gems/bunny-2.20.3/lib/bunny/session.rb:778:in `recover_from_network_failure'  `
2023-02-17T00:11:12.009214968Z  from /usr/local/bundle/gems/bunny-2.20.3/lib/bunny/session.rb:738:in `handle_network_failure'  
2023-02-17T00:11:12.009216268Z  from /usr/local/bundle/gems/bunny-2.20.3/lib/bunny/reader_loop.rb:47:in `rescue in block in run_loop'  
2023-02-17T00:11:12.009217638Z  from /usr/local/bundle/gems/bunny-2.20.3/lib/bunny/reader_loop.rb:37:in `block in run_loop'  
2023-02-17T00:11:12.009227158Z  from /usr/local/bundle/gems/bunny-2.20.3/lib/bunny/reader_loop.rb:36:in `loop'  
2023-02-17T00:11:12.009228708Z  from /usr/local/bundle/gems/bunny-2.20.3/lib/bunny/reader_loop.rb:36:in `run_loop'  
2023-02-17T00:11:12.009230188Z /usr/local/lib/ruby/3.0.0/openssl/buffering.rb:205:in `sysread_nonblock': Connection reset by peer (Errno::ECONNRESET)  
2023-02-17T00:11:12.009231488Z  from /usr/local/lib/ruby/3.0.0/openssl/buffering.rb:205:in `read_nonblock'  
2023-02-17T00:11:12.009249847Z  from /usr/local/bundle/gems/bunny-2.20.3/lib/bunny/cruby/ssl_socket.rb:45:in `block in read_fully'  
2023-02-17T00:11:12.009252567Z  from /usr/local/bundle/gems/bunny-2.20.3/lib/bunny/cruby/ssl_socket.rb:44:in `loop'  
2023-02-17T00:11:12.009254097Z  from /usr/local/bundle/gems/bunny-2.20.3/lib/bunny/cruby/ssl_socket.rb:44:in `read_fully'  
2023-02-17T00:11:12.009255387Z  from /usr/local/bundle/gems/bunny-2.20.3/lib/bunny/transport.rb:263:in `read_fully'  
2023-02-17T00:11:12.009256667Z  from /usr/local/bundle/gems/bunny-2.20.3/lib/bunny/transport.rb:285:in `read_next_frame'  
2023-02-17T00:11:12.009257977Z  from /usr/local/bundle/gems/bunny-2.20.3/lib/bunny/reader_loop.rb:74:in `run_once'  
2023-02-17T00:11:12.009259247Z  from /usr/local/bundle/gems/bunny-2.20.3/lib/bunny/reader_loop.rb:39:in `block in run_loop'  
2023-02-17T00:11:12.009260527Z  from /usr/local/bundle/gems/bunny-2.20.3/lib/bunny/reader_loop.rb:36:in `loop'  
2023-02-17T00:11:12.009261787Z  from /usr/local/bundle/gems/bunny-2.20.3/lib/bunny/reader_loop.rb:36:in `run_loop'