OpenSSL error is causing unrecoverable issue
womblep opened this issue · 1 comments
womblep commented
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
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'