Puma: Error in reactor loop escaped: System error: Undefined error: 0 - 0 (Puma::MiniSSL::SSLError)

[coneybeare]

I am setting up capybara to use SSL through puma. It all works in terms of connectivity, but this gets putsed out to STDOUT and I can find no way to fix it or silence it. I'm ok with either as a solution.

Steps to reproduce

1) Setup SSL as such:

````ruby

https://gist.github.com/tadast/9932075

if Rails.env.test?
unless File.exist?(Rails.root.join('config', 'ssl', 'localhost.test.key'))
def generate_root_cert(root_key)
root_ca = OpenSSL::X509::Certificate.new
root_ca.version = 2 # cf. RFC 5280 - to make it a "v3" certificate
root_ca.serial = 0x0
root_ca.subject = OpenSSL::X509::Name.parse "/C=BE/O=A1/OU=A/CN=localhost.test"
root_ca.issuer = root_ca.subject # root CA's are "self-signed"
root_ca.public_key = root_key.public_key
root_ca.not_before = Time.now
root_ca.not_after = root_ca.not_before + 2 * 365 * 24 * 60 * 60 # 2 years validity
root_ca.sign(root_key, OpenSSL::Digest::SHA256.new)
root_ca
end

root_key = OpenSSL::PKey::RSA.new(2048)
file = File.new( Rails.root.join('config', 'ssl', 'localhost.test.key'), "wb")
file.write(root_key)
file.close

root_cert = generate_root_cert(root_key)

file = File.new( Rails.root.join('config','ssl', 'localhost.test.crt'), "wb")
file.write(root_cert)
file.close

end

ssl_bind 'localhost.test', 3000, {
key: Rails.root.join('config','ssl', 'localhost.test.key'),
cert: Rails.root.join('config','ssl', 'localhost.test.crt'),
verify_mode: 'none'
}
end
````

2) Run Rspec feature specs using capybara, headless chrome, and puma

````ruby

https://robots.thoughtbot.com/headless-feature-specs-with-chrome

Capybara.register_driver :chrome do |app|
Capybara::Selenium::Driver.new(app, browser: :chrome)
end

Capybara.register_driver :headless_chrome do |app|
capabilities = Selenium::WebDriver::Remote::Capabilities.chrome(
chromeOptions: {
args: %w(headless disable-gpu),
'profile.managed_default_content_settings.notifications': 2,
}
)

profile = Selenium::WebDriver::Chrome::Profile.new
profile["profile.default_content_settings"] = { images: '2' }

options = Selenium::WebDriver::Chrome::Options.new(args: ['headless', '--blink-settings=imagesEnabled=false'])

Capybara::Selenium::Driver.new app,
browser: :chrome,
desired_capabilities: capabilities,
profile: profile,
options: options
end

Capybara.javascript_driver = :headless_chrome

If you’d like to watch the tests execute while debugging, you can change the driver to chrome.

Capybara.javascript_driver = :chrome

Screenshot with save_and_open_screenshot

key_file = Rails.root.join('config', 'ssl', 'localhost.test.key')
cert_file = Rails.root.join('config', 'ssl', 'localhost.test.crt')

Capybara.server = :puma, {
Silent: true,
Host: "ssl://#{Capybara.server_host}:#{Capybara.server_port}?key=#{key_file}&cert=#{cert_file}"
}
````

Expected behavior

I would expect Silent: true to actually keep things silent.

Actual behavior

I get the following puts on every run:

Error in reactor loop escaped: System error: Undefined error: 0 - 0 (Puma::MiniSSL::SSLError) /Users/[REDACTED]/.rvm/gems/ruby-2.5.3@[REDACTED]/gems/puma-3.12.0/lib/puma/minissl.rb:41:in `read' /Users/[REDACTED]/.rvm/gems/ruby-2.5.3@[REDACTED]/gems/puma-3.12.0/lib/puma/minissl.rb:41:in `engine_read_all' /Users/[REDACTED]/.rvm/gems/ruby-2.5.3@[REDACTED]/gems/puma-3.12.0/lib/puma/minissl.rb:52:in `read_nonblock' /Users/[REDACTED]/.rvm/gems/ruby-2.5.3@[REDACTED]/gems/puma-3.12.0/lib/puma/minissl.rb:127:in `read_and_drop' /Users/[REDACTED]/.rvm/gems/ruby-2.5.3@[REDACTED]/gems/puma-3.12.0/lib/puma/minissl.rb:144:in `close' /Users/[REDACTED]/.rvm/gems/ruby-2.5.3@[REDACTED]/gems/puma-3.12.0/lib/puma/client.rb:123:in `close' /Users/[REDACTED]/.rvm/gems/ruby-2.5.3@[REDACTED]/gems/puma-3.12.0/lib/puma/reactor.rb:212:in `rescue in block in run_internal' /Users/[REDACTED]/.rvm/gems/ruby-2.5.3@[REDACTED]/gems/puma-3.12.0/lib/puma/reactor.rb:170:in `block in run_internal' /Users/[REDACTED]/.rvm/gems/ruby-2.5.3@[REDACTED]/gems/puma-3.12.0/lib/puma/reactor.rb:140:in `each' /Users/[REDACTED]/.rvm/gems/ruby-2.5.3@[REDACTED]/gems/puma-3.12.0/lib/puma/reactor.rb:140:in `run_internal' /Users/[REDACTED]/.rvm/gems/ruby-2.5.3@[REDACTED]/gems/puma-3.12.0/lib/puma/reactor.rb:251:in `block in run_in_thread'

System configuration

Ruby version: 2.5.3
Rails version: 5.2.2
Puma version: 3.12.0

[nakwa]

Any update on this one ?
I get a similar error when reaching out to my rails server using SSL, but only when accessing it with through Serveo (reverse proxy with autossh).

=> Booting Puma
=> Rails 5.2.3 application starting in development
=> Run `rails server -h` for more startup options
Puma starting in single mode...
* Version 4.0.1 (ruby 2.4.4-p296), codename: 4 Fast 4 Furious
* Min threads: 0, max threads: 16
* Environment: development
* Listening on ssl://localhost:3000?key=/Users/[REDACTED]/private/ssl-dev/core.key&cert=/Users/[REDACTED]/private/ssl-dev/core.crt
Use Ctrl-C to stop
Error in reactor loop escaped: System error: Undefined error: 0 - 0 (Puma::MiniSSL::SSLError)
/Users/[REDACTED]/.rvm/gems/ruby-2.4.4/gems/puma-4.0.1/lib/puma/minissl.rb:43:in `read'
/Users/[REDACTED]/.rvm/gems/ruby-2.4.4/gems/puma-4.0.1/lib/puma/minissl.rb:43:in `engine_read_all'
/Users/[REDACTED]/.rvm/gems/ruby-2.4.4/gems/puma-4.0.1/lib/puma/minissl.rb:54:in `read_nonblock'
/Users/[REDACTED]/.rvm/gems/ruby-2.4.4/gems/puma-4.0.1/lib/puma/minissl.rb:129:in `read_and_drop'
/Users/[REDACTED]/.rvm/gems/ruby-2.4.4/gems/puma-4.0.1/lib/puma/minissl.rb:146:in `close'
/Users/[REDACTED]/.rvm/gems/ruby-2.4.4/gems/puma-4.0.1/lib/puma/client.rb:138:in `close'
/Users/[REDACTED]/.rvm/gems/ruby-2.4.4/gems/puma-4.0.1/lib/puma/reactor.rb:265:in `rescue in block in run_internal'
/Users/[REDACTED]/.rvm/gems/ruby-2.4.4/gems/puma-4.0.1/lib/puma/reactor.rb:218:in `block in run_internal'
/Users/[REDACTED]/.rvm/gems/ruby-2.4.4/gems/puma-4.0.1/lib/puma/reactor.rb:157:in `each'
/Users/[REDACTED]/.rvm/gems/ruby-2.4.4/gems/puma-4.0.1/lib/puma/reactor.rb:157:in `run_internal'
/Users/[REDACTED]/.rvm/gems/ruby-2.4.4/gems/puma-4.0.1/lib/puma/reactor.rb:311:in `block in run_in_thread'

2019-08-20 18:26:27 +0200: SSL error, peer: <unknown>, peer cert: , #<Puma::MiniSSL::SSLError: System error: Undefined error: 0 - 0>
Error in reactor loop escaped: System error: Undefined error: 0 - 0 (Puma::MiniSSL::SSLError)
/Users/[REDACTED]/.rvm/gems/ruby-2.4.4/gems/puma-4.0.1/lib/puma/minissl.rb:43:in `read'
/Users/[REDACTED]/.rvm/gems/ruby-2.4.4/gems/puma-4.0.1/lib/puma/minissl.rb:43:in `engine_read_all'
/Users/[REDACTED]/.rvm/gems/ruby-2.4.4/gems/puma-4.0.1/lib/puma/minissl.rb:54:in `read_nonblock'
/Users/[REDACTED]/.rvm/gems/ruby-2.4.4/gems/puma-4.0.1/lib/puma/minissl.rb:129:in `read_and_drop'
/Users/[REDACTED]/.rvm/gems/ruby-2.4.4/gems/puma-4.0.1/lib/puma/minissl.rb:146:in `close'
/Users/[REDACTED]/.rvm/gems/ruby-2.4.4/gems/puma-4.0.1/lib/puma/client.rb:138:in `close'
/Users/[REDACTED]/.rvm/gems/ruby-2.4.4/gems/puma-4.0.1/lib/puma/reactor.rb:265:in `rescue in block in run_internal'
/Users/[REDACTED]/.rvm/gems/ruby-2.4.4/gems/puma-4.0.1/lib/puma/reactor.rb:218:in `block in run_internal'
/Users/[REDACTED]/.rvm/gems/ruby-2.4.4/gems/puma-4.0.1/lib/puma/reactor.rb:157:in `each'
/Users/[REDACTED]/.rvm/gems/ruby-2.4.4/gems/puma-4.0.1/lib/puma/reactor.rb:157:in `run_internal'
/Users/[REDACTED]/.rvm/gems/ruby-2.4.4/gems/puma-4.0.1/lib/puma/reactor.rb:311:in `block in run_in_thread'

serveo_1   | + ssh-keygen -f /root/.ssh/id_rsa -t rsa -b 4096 -N [REDACTED]
serveo_1   | Generating public/private rsa key pair.
serveo_1   | Created directory '/root/.ssh'.
serveo_1   | Your identification has been saved in /root/.ssh/id_rsa.
serveo_1   | Your public key has been saved in /root/.ssh/id_rsa.pub.
serveo_1   | The key fingerprint is:
serveo_1   | + [REDACTED]
serveo_1   | + autossh -M 0 -R mylocalhost:80:host.docker.internal:3000 serveo.net -f '-oStrictHostKeyChecking=no'
serveo_1   | Pseudo-terminal will not be allocated because stdin is not a terminal.
serveo_1   | Warning: Permanently added 'serveo.net,159.89.214.31' (RSA) to the list of known hosts.
serveo_1   | Forwarding HTTP traffic from https://mylocalhost.serveo.net
serveo_1   | HTTP request from 1.1.1.1 to https://mylocalhost.serveo.net/
serveo_1   | Connection to serveo.net closed by remote host.
serveo_1   | Pseudo-terminal will not be allocated because stdin is not a terminal.
serveo_1   | Forwarding HTTP traffic from https://mylocalhost.serveo.net/

[MSP-Greg]

I've seen a similar error with TLSv1.3. What version of OpenSSL is being used with Puma?

Puma::MiniSSL::OPENSSL_LIBRARY_VERSION

[nakwa]

gem 'puma', '4.0.1'
gem 'openssl', '~> 2.1.2'

and

nakwa~$ openssl version
LibreSSL 2.6.5

on OSX

EDIT: Not an expert in the matter, but I see that my OpenSSL/LibreSSL version seems to be outdated, trying to update it with homebrew now ...

[nateberkopec]

@nakwa in your console run rails runner -e "Puma::MiniSSL::OPENSSL_LIBRARY_VERSION" and paste the output here.

[nakwa]

@nateberkopec
Whether it is with rails runner "Puma::MiniSSL::OPENSSL_LIBRARY_VERSION" or displaying it in rails c, Puma::MiniSSL is undefined

nakwa:~/projects/ (master)$ rails runner "Puma::MiniSSL::OPENSSL_LIBRARY_VERSION"
Please specify a valid ruby command or the path of a script to run.
Run 'bin/rails runner -h' for help.

uninitialized constant Puma::MiniSSL

EDIT: Updating OpenSSL with homebrew did not help:

openssl version
OpenSSL 1.0.2s  28 May 2019

[nateberkopec]

Sorry there's a bit more to the incantation than I thought.

rails runner "require 'puma/minissl'; require 'puma/puma_http11'; Puma::Server.class; Puma::MiniSSL.check; puts Puma::MiniSSL::OPENSSL_LIBRARY_VERSION"

[nakwa]

Ahah, yes, indeed. Thanks!

nakwa:~/projects (master)$ rails runner "require 'puma/minissl'; require 'puma/puma_http11'; Puma::Server.class; Puma::MiniSSL.check; puts Puma::MiniSSL::OPENSSL_LIBRARY_VERSION"

OpenSSL 1.1.1c  28 May 2019

[MSP-Greg]

With OpenSSL 1.1.1, which is the fist version supporting TLSv1.3, I've seen the error when an 'http:' connection is made to a SSL host.

Both 1.0.2 and 1.1.1 seem to be appearing, maybe check both Puma::MiniSSL::OPENSSL_VERSION and Puma::MiniSSL::OPENSSL_LIBRARY_VERSION, as building with one version and running with another may not work well. I've never tried it...

[nakwa]

Both Puma::MiniSSL::OPENSSL_VERSION and Puma::MiniSSL::OPENSSL_LIBRARY_VERSION are set to OpenSSL 1.1.1c 28 May 2019

[MSP-Greg]

@nakwa

Thanks. I noticed from above:

serveo_1   | Forwarding HTTP traffic from https://mylocalhost.serveo.net
serveo_1   | HTTP request from 1.1.1.1 to https://mylocalhost.serveo.net/

Haven't worked with Serveo. Is it forwarding HTTP (not HTTPS) traffic?

Regardless, I've got a patch that closes HTTP connections to a Puma SSL server using 1.1.1/TLSv1.3, as TLSv1.3 handles HTTP connections differently than previous TLS versions.

I was kind of waiting for some of the current issues to be resolved, along with one last small concern/change to the code...

[nakwa]

@MSP-Greg
Serveo supports both HTTP and HTTPS (I made it work in the past with a different setup/OS), so I think this is just an omission in the log. Plus, the connectivity seems to be there since the request is reaching the rails server.

Anyway, I will drop HTTPS and Serveo on my dev environment, for now ...

Thanks for the support!

[hwhelchel]

I'm seeing the same error message in my logs though it's not preventing tests from running.

Here's the log message without Silent: true being passed to Capybara.server.

Here's the log message with Silent: true passed to Capybara.server.

[alexsanderson]

I'm getting the same error.
Works on local machine (macOS), throws an error when running Heroku CI:

Capybara starting Puma...
* Version 4.3.0 , codename: Mysterious Traveller
* Min threads: 0, max threads: 4
* Listening on ssl://127.0.0.1:41238?key=certs/localhost-key.pem&cert=certs/localhost.pem
Error in reactor loop escaped: System error: Success - 0 (Puma::MiniSSL::SSLError)
/app/vendor/bundle/ruby/2.6.0/gems/puma-4.3.0/lib/puma/minissl.rb:43:in `read'
/app/vendor/bundle/ruby/2.6.0/gems/puma-4.3.0/lib/puma/minissl.rb:43:in `engine_read_all'
/app/vendor/bundle/ruby/2.6.0/gems/puma-4.3.0/lib/puma/minissl.rb:54:in `read_nonblock'
/app/vendor/bundle/ruby/2.6.0/gems/puma-4.3.0/lib/puma/minissl.rb:128:in `read_and_drop'
/app/vendor/bundle/ruby/2.6.0/gems/puma-4.3.0/lib/puma/minissl.rb:145:in `close'
/app/vendor/bundle/ruby/2.6.0/gems/puma-4.3.0/lib/puma/client.rb:145:in `close'
/app/vendor/bundle/ruby/2.6.0/gems/puma-4.3.0/lib/puma/reactor.rb:266:in `rescue in block in run_internal'
/app/vendor/bundle/ruby/2.6.0/gems/puma-4.3.0/lib/puma/reactor.rb:218:in `block in run_internal'
/app/vendor/bundle/ruby/2.6.0/gems/puma-4.3.0/lib/puma/reactor.rb:157:in `each'
/app/vendor/bundle/ruby/2.6.0/gems/puma-4.3.0/lib/puma/reactor.rb:157:in `run_internal'
/app/vendor/bundle/ruby/2.6.0/gems/puma-4.3.0/lib/puma/reactor.rb:313:in `block in run_in_thread'
2019-11-09 08:38:07 +0000: SSL error, peer: <unknown>, peer cert: , #<Puma::MiniSSL::SSLError: System error: Success - 0>

macOS:

OpenSSL> version
LibreSSL 2.6.5

Heroku:

OpenSSL> version
OpenSSL 1.1.1  11 Sep 2018

I've tried copying the certificates across from development to CI with no luck, it shows the same error. The tests don't fail, but with or without silent being set, it still shows the error.

I also had this error with Puma Version 4.2.1 (ruby 2.6.3-p62), codename: Distant Airhorns

Certificates have been generated with both:

openssl req \
  -x509 \
  -newkey rsa:4096 \
  -keyout certs/localhost-key.pem \
  -out certs/localhost.pem \
  -days 3 \
  -nodes \
  -subj '/CN=localhost'

and

openssl req\
  -x509 \
  -newkey rsa:4096 \
  -keyout certs/localhost-key.pem \
  -out certs/localhost.pem \
  -days 3 \
  -nodes \
  -subj '/CN=localhost' \
  -reqexts SAN \
  -config <(cat /etc/ssl/openssl.cnf <(printf "[SAN]\nsubjectAltName=DNS:localhost"))

(neither have made a difference)

[MSP-Greg]

This sounds familiar. If you're running locally, try changing the following line:
https://github.com/puma/puma/blob/5fef2b715fdb69697161b21585c118995b6ee399/lib/puma/reactor.rb#L247

to:

                # may generate another SSL error, continue to remove the monitor
                c.close rescue nil

Taken from a closed PR. We're in a rescue block, and then we're trying to close the socket which put us there in the first place...

[hwhelchel]

@MSP-Greg hmm just tried that and it still errored.

[MSP-Greg]

@hwhelchel

Thanks. Sorry, I'll really check this time. I know I've seen that exact error with 1.1.1, and I've got patch somewhere. As I recall, it was specific to trying an tcp (http) connection with a Puma SSL server running 1.1.1. Might that be happening here?

[hwhelchel]

@MSP-Greg hmm not sure. I'm not an SSL expert. I am on OpenSSL 1.1.1d

Then I'm using RSpec and Capybara for rails system tests.

Perhaps the way Capybara interacts with the Puma SSL server is causing the issue.

RSpec.configure do |config|
  config.before(:each, type: :system, js: true) do
    Capybara.server_port = 5000
    Capybara.server = :puma, {
      Host: "ssl://#{Capybara.server_host}?key=#{Rails.root}/config/ssl/key.pem&cert=#{Rails.root}/config/ssl/cert.pem",
    }
    driven_by(:selenium, using: :headless_chrome)
  end
end

I have a very similar line like "ssl://#{Capybara.server_host}?key=#{Rails.root}/config/ssl/key.pem&cert=#{Rails.root}/config/ssl/cert.pem" in my script for local development on SSL and I've never seen that error when developing locally so my hunch is it's something to do with the interaction between Capybara and the Puma SSL server.

#!/bin/bash
if [ "$RACK_ENV" == "production" ]; then
  bundle exec puma -C config/puma.rb
else
  bundle exec puma -w 1 -b 'ssl://127.0.0.1:5000?key=config/ssl/key.pem&cert=config/ssl/cert.pem'
fi

[MSP-Greg]

@nateberkopec

In Reactor#run_internal, starting at line 218, there is a begin block with four rescue statements. Most of the rescues involve socket related errors. But, every rescue block includes a Socket#close statement.

So an object is throwing an error, then in a rescue block another operation/method is performed with it. That is why I have often added rescue nil to statements of this type.

Another method could be added to Reactor to catch close errors and log them, rescue nil could be used, or something else...

[MSP-Greg]

@hwhelchel

Two other suggestions, replace:
https://github.com/puma/puma/blob/5fef2b715fdb69697161b21585c118995b6ee399/lib/puma/reactor.rb#L266
with:

c.lose unless c.closed?

or

c.close rescue nil

[hwhelchel]

@MSP-Greg switching to c.close rescue nil on line 266 silenced the error. Switching to c.close unless c.closed? had no effect. Looks like c.close rescue nil on line 266 is what we want.

[hwhelchel]

@MSP-Greg are you working on a PR or would you like me to create one? I'm not knowledgeable enough to write a good automated test for this but can get a PR started if helpful.

[MSP-Greg]

@hwhelchel

are you working on a PR

Not right now. This is a bit messy, as I'm not sure if the issue is specific to OpenSSL 1.1.1 or not. If it is, it might point to an issue in minissl.rb or minissl.c.

Regardless, I think expecting a socket to close when it has already generated an error is dicey. The main thing Puma should be doing is removing it from the reactor, closing it might even be something that GC could do, especially if we assume autoclose is always true. Haven't checked.

It could be a malicious connection, which might be better to ignore.

Sorry for generalizing things.

[natebird]

Changing line 266 in reactor.rb from c.close to c.close rescue nil worked for me too.

[nateberkopec]

Looks like this needs someone to think through Greg's concerns a bit more and then submit a PR.

[HoneyryderChuck]

We're also having this issue while trying to run capybara tests with ssl, which are a requirement for our use-case. Switching to webrick in the meantime.

[camilova]

Adding rescue nil to the line 266 in reactor.rb works for me too!.
For me the error occurs with Chrome 80.0.3987.162 (Build oficial) (64 bits) but not with Brave 1.5.123 Chromium: 80.0.3987.163 (Official Build) (64-bit).
I dont know, but I think Chrome uses something different from Brave (Chromium) with SSL and it may raise the error, but only when I start an HTTP request to an HTTPS endpoint. I became whit this error when I bind Puma with SSL and then I wanted to run my test over SSL binding too, and that was the error!

[nateberkopec]

Is anyone still experiencing this issue with Puma 5.0.3+? I'm not sure it was fixed, but the stacktrace should have at least changed to a different spot.

[natebird]

I can try it out next week. It really only affects me in the test environment.

[alexsanderson]

Appears to work for me. I replicated the problem with 4.3.5. Doing the same with 5.0.4 simply results in this:

2020-11-19 17:35:50 +0000 SSL error, peer: 127.0.0.1, peer cert: : #<Puma::MiniSSL::SSLError: HTTP connection?>

and the cURL response comes back straight away (it hung on 4.3.5) with curl: (52) Empty reply from server.

[MSP-Greg]

@alexsanderson

Thanks for checking. This is issue is a bit messy, as 'Error in reactor loop escaped' can be triggered by a few things, including a client connection dropping at exactly the right (wrong) time. We're trying to write tests for misbehaving clients, but hitting Puma at just the right time can be difficult...

Re your check, there was also an issue where, if Puma was using OpenSSL 1.1.1 (TLSv1.3), and a client tried to connect with http, Puma didn't reject the connection properly.

It wasn't a problem with TLSv1.2 or earlier, only TLSv1.3. Anyway, I believe that was fixed in 5.0.2.

To clarify, is that what you've tested?

[alexsanderson]

Sorry @MSP-Greg , ignore me. The issue you describe that was fixed in 5.0.2 I believe is what I was experiencing.

[nateberkopec]

Marking as fixed in 5.0.4+