Puma errors and performs badly when receiving a non-HTTPS request while TLSv1.3-configured

[nakwa]

The bug: Timeout / Puma throwing an error when querying Rails through a reverse proxy.

This is similar to #1708 but I thought it was worth summarizing/detailing again, in a separate issue (also because the context/usage is different).

~$ bundle exec rails s -b 'ssl://localhost:3000?key=$SSL_KEY&cert=$SSL_CERT'
=> Booting Puma
=> Rails 6.0.2.1 application starting in development
=> Run `rails server --help` for more startup options
W, [2020-02-13T21:27:50.354171 #6604]  WARN -- : Meta::Organization: overriding method 'invalid?'!
Puma starting in single mode...
* Version 4.3.1 (ruby 2.6.5-p114), codename: Mysterious Traveller
* Min threads: 0, max threads: 16
* Environment: development
* Listening on ssl://localhost:3000?key=/Users/[REDACTED]/app/private/ssl-dev/dev-key.key&cert=/Users/[REDACTED]/app/private/ssl-dev/dev-certificate.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.6.5/gems/puma-4.3.1/lib/puma/minissl.rb:43:in `read'
/Users/[REDACTED]/.rvm/gems/ruby-2.6.5/gems/puma-4.3.1/lib/puma/minissl.rb:43:in `engine_read_all'
/Users/[REDACTED]/.rvm/gems/ruby-2.6.5/gems/puma-4.3.1/lib/puma/minissl.rb:54:in `read_nonblock'
/Users/[REDACTED]/.rvm/gems/ruby-2.6.5/gems/puma-4.3.1/lib/puma/minissl.rb:128:in `read_and_drop'
/Users/[REDACTED]/.rvm/gems/ruby-2.6.5/gems/puma-4.3.1/lib/puma/minissl.rb:145:in `close'
/Users/[REDACTED]/.rvm/gems/ruby-2.6.5/gems/puma-4.3.1/lib/puma/client.rb:145:in `close'
/Users/[REDACTED]/.rvm/gems/ruby-2.6.5/gems/puma-4.3.1/lib/puma/reactor.rb:266:in `rescue in block in run_internal'
/Users/[REDACTED]/.rvm/gems/ruby-2.6.5/gems/puma-4.3.1/lib/puma/reactor.rb:218:in `block in run_internal'
/Users/[REDACTED]/.rvm/gems/ruby-2.6.5/gems/puma-4.3.1/lib/puma/reactor.rb:157:in `each'
/Users/[REDACTED]/.rvm/gems/ruby-2.6.5/gems/puma-4.3.1/lib/puma/reactor.rb:157:in `run_internal'
/Users/[REDACTED]/.rvm/gems/ruby-2.6.5/gems/puma-4.3.1/lib/puma/reactor.rb:313:in `block in run_in_thread'

SSH Outputs (reverse proxy forwarding):

debug1: client_input_channel_open: ctype forwarded-tcpip rchan 2 win 2097152 max 32768
debug1: client_request_forwarded_tcpip: listen  port 80, originator [REDACTED_IP] port 53504
debug1: connect_next: host localhost ([::1]:3000) in progress, fd=7
debug1: channel 0: new [REDACTED_IP]
debug1: confirm forwarded-tcpip
debug1: channel 0: connected to localhost port 3000

The browser ends-up with a gateway time-out response from Nginx (reverse-proxy server):

504 Gateway Time-out
nginx/1.17.6

The error above is only thrown on timeout, or on canceling the request.

Puma config:

$ rails runner "require 'puma/minissl'; require 'puma/puma_http11'; Puma::Server.class; Puma::MiniSSL.check; puts Puma::MiniSSL::OPENSSL_VERSION"
> OpenSSL 1.1.1d  10 Sep 2019

$ rails runner "require 'puma/minissl'; require 'puma/puma_http11'; Puma::Server.class; Puma::MiniSSL.check; puts Puma::MiniSSL::OPENSSL_LIBRARY_VERSION"
> OpenSSL 1.1.1d  10 Sep 2019

$ which openssl
> /usr/local/opt/openssl@1.1/bin/openssl

$ openssl version -a
> OpenSSL 1.1.1d  10 Sep 2019
built on: Sat Sep 28 13:18:07 2019 UTC
platform: darwin64-x86_64-cc
options:  bn(64,64) rc4(16x,int) des(int) idea(int) blowfish(ptr)
compiler: clang -fPIC -arch x86_64 -O3 -Wall -DL_ENDIAN -DOPENSSL_PIC -DOPENSSL_CPUID_OBJ -DOPENSSL_IA32_SSE2 -DOPENSSL_BN_ASM_MONT -DOPENSSL_BN_ASM_MONT5 -DOPENSSL_BN_ASM_GF2m -DSHA1_ASM -DSHA256_ASM -DSHA512_ASM -DKECCAK1600_ASM -DRC4_ASM -DMD5_ASM -DVPAES_ASM -DGHASH_ASM -DECP_NISTZ256_ASM -DX25519_ASM -DPOLY1305_ASM -D_REENTRANT -DNDEBUG
OPENSSLDIR: "/usr/local/etc/openssl@1.1"
ENGINESDIR: "/usr/local/Cellar/openssl@1.1/1.1.1d/lib/engines-1.1"
Seeding source: os-specific

To Reproduce

1. Clean install the latest openssl (also tried with libressl) on OSX:

brew install openssl@1.1
ln -s /usr/local/opt/openssl@1.1/lib/libssl.1.1.dylib /usr/local/lib/libssl.1.1.dylib
ln -s /usr/local/opt/openssl@1.1/lib/libssl.1.1.dylib /usr/local/lib/libssl.dylib
ln -s /usr/local/opt/openssl@1.1/lib/libcrypto.1.1.dylib /usr/local/lib/libcrypto.1.1.dylib
ln -s /usr/local/opt/openssl@1.1/lib/libcrypto.1.1.dylib /usr/local/lib/libcrypto.dylib

2. Clean install latest ruby version, specifying openssl dir

rvm --autolibs=disable install 2.6.5 --with-openssl-dir=/usr/local/etc/openssl@1.1/

3. Setting up reverse proxy server, using:

https://github.com/robzhu/nginx-local-tunnel
https://github.com/jwilder/nginx-proxy
https://github.com/JrCs/docker-letsencrypt-nginx-proxy-companion

It works fine. Of course, both 80 and 443 are open and accessible. LetsEncrypt certificate is valid.

4. Gemfile as follow:

ruby '2.6.5'
gem 'puma', '4.3.1'
gem 'pg', '1.2.2'
gem 'rails', '~> 6.0.2.1'
gem 'openssl', '~> 2.1.0'

6. Generate Self-Signed Certificates

openssl req -x509 -newkey rsa:4096 -sha256 -days 3650 -nodes \
  -keyout dev-key.key -out dev-certificate.crt -subj /CN=example.com

7. Run Rails

export SSL_KEY="/[REDACTED]/railsapp/private/ssl-dev/dev-key.key"
export SSL_CERT="/[REDACTED]/railsapp/private/ssl-dev/dev-certificate.crt"
~$ bundle exec rails s -b 'ssl://localhost:3000?key=$SSL_KEY&cert=$SSL_CERT'

8. Run proxy server

ssh -NR :80:localhost:3000 -p 2222 user@my.proxy.server.tld -v

Expected behavior

• Proxy server works fine (tried with a node.js app).
• Querying rails using https locally works fine.
  I expect to be able to query the rails app using https, through the proxy server.

I tried many different configurations, clean install, ways of installing OpenSSL/LibreSSL, using ngrok, Serveo, setting up owner reverse proxy (current setup described), different ways of generating the SSL certificates. No chance so far.

I also tried forking and updating Puma/reactor.rb accordingly to the suggestion of @MSP-Greg in #1708 (#1708 (comment)). In that case it doesn't throw anything right away, but ends up timing-out and crashing.
I am not comfortable playing with OpenSSL & co, so I am still not sure whether this is an issue from Puma, or if something could be fixed in my setup.

Desktop:

• OSX Catalina 10.15.3
• Chrome Version 80.0.3987.100 (Official Build) (64-bit)

Question:
Referring to #1708 (comment) , would attempting to disable/prevent Tls 1.3 on Nginx be of any help?

[nakwa]

Ok, so it seems like there is both a problem with my setup and with Puma:

• The problem with my setup is that my proxy server is using SSL, then forwarding through SSH to my localhost which is also using SSL. Of course, the SSL certificates on the server (using Letsencrypt) and those on my local machine (self-signed) are not the same, which obviously causes a problem (HTST).

• As for Puma, it seems like the error is thrown and the timeout happening when making a plain HTTP request to a server using SSL (whether Passenger/NGINX throw something like “The plain HTTP request was sent to HTTPS port” which is a bit more explicit - but not sure if it should be acceptable and if that's the correct behavior either). I could even reproduce the problem locally by setting Rails config.force_ssl to false.

[MSP-Greg]

As for Puma, it seems like the error is thrown and the timeout happening when making a plain HTTP request to a server using SSL

What version of OpenSSL are you using? Could this be using TLSv1.3? If so, somewhere I have code for this (guard against HTTP req to HTTPS). It was specific to TLSv1.3, TLSv1.2 seemed ok?

[nakwa]

OpenSSL 1.1.1d 10 Sep 2019 and TLS 1.3

The connection to this site is encrypted and authenticated using TLS 1.3, X25519, and AES_128_GCM.

What exactly do you mean by "guarding" HTTP request to HTTPS port? I am not sure I understand what behavior should be expected in that case.

[nateberkopec]

I reopened #986, which is about error messages to SSL-conf pumas. In that case though, people get Puma::HttpParserError when making a non-SSL request to an SSL-configured Puma.

[MSP-Greg]

What exactly do you mean by "guarding" HTTP request to HTTPS port?

I don't recall the details, as some of this goes back to when 1.1.1 was in beta. It is TLSv1.3 specific.

I might equate "How should OpenSSL respond to a HTTP/non-SSL request when the server connection is HTTPS/SSL?" to the question of "How should a mail server respond to dictionary attacks?".

Somewhere, maybe the OpenSSL wiki, they specifically mention TLSv1.3, how the new behavior is different, and how it may affect servers designed to handle multiple requests, with obviously the ability to only handle a finite number of them.

I'll look for my old code. In the meantime, maybe someone can use the test framework to throw a bunch of HTTP requests at a Puma server configured for SSL (using OpenSSL 1.1.1d) and see what happens? All the CI on Actions using Ruby 2.5 and later uses 1.1.1d...

[nakwa]

Thanks, @MSP-Greg for the detailed answer.

To whomever might be interested in the setup, I managed to get everything working with Puma:
https://gist.github.com/nakwa/652daaf5f87c038189eb65b9ac68476c

Therefore I am indeed pretty sure that the issue is only happening when sending a plain HTTP request to an HTTPS port - at least when using TLS 1.3 (since the same setup with Serveo was working in the past - the only thing that I can think about that changed are the OpenSSL/TLS version)

[nateberkopec]

Awesome. I will close, as this issue is now linked to our main issue for "we need more descriptive errors when Puma gets a HTTP connection when configured for HTTPS" 👍

[nakwa]

@nateberkopec fine, but I believe it's a bit more than just needing "more descriptive errors".
Puma doesn't seem to behave as expected in that case (not responding at all, request timing out, also managed a few times to crash it entirely somehow, etc).

[nateberkopec]

@MSP-Greg agree?

[MSP-Greg]

@MSP-Greg agree?

Yes. I think.

Considering:

Puma doesn't seem to behave as expected in that case (not responding at all, request timing out, also managed a few times to crash it entirely somehow, etc)

That's more in line with what I recall. IOW, the http connection was not closed ASAP and held server resources.

From what I recall, the code I had set a fixed time that a connection's handshake had to be completed in. If it wasn't, it was closed and removed. I think it only did so if the connection was considered TLSv1.3, which seems to happen with an HTTP connection since there's no 'downgrade' mechanism. I think.

Let me find that code.

[MSP-Greg]

@nakwa

Can you try #2116 and see if it fixes the problems you've seen?

[MSP-Greg]

@nakwa

If you've had the time to see if PR #2116 helped with your issue, any thoughts?

[nakwa]

@MSP-Greg sorry for the delay. Thanks for the PR !

So, I did the following: Using the same config as above while simply removing the --env "VIRTUAL_PROTO=https" on the docker dev-proxy container.

1. Reproducing the error again, using the latest Puma, same error as above (as expected).

2. Using your PR :

gem 'puma', git: 'https://github.com/MSP-Greg/puma', branch: 'ssl-vers'

Using puma 4.3.1 from https://github.com/MSP-Greg/puma (at ssl-vers@83bbe7d)

SSH log shows that the requet is going through:

proxy_1    | debug1: client_input_channel_open: ctype forwarded-tcpip rchan 4 win 2097152 max 32768
proxy_1    | debug1: client_request_forwarded_tcpip: listen  port 80, originator [REDACTED] port 37064
proxy_1    | debug1: connect_next: host host.docker.internal ([192.168.65.2]:3000) in progress, fd=5
proxy_1    | debug1: channel 0: new [REDACTED]
proxy_1    | debug1: confirm forwarded-tcpip
proxy_1    | debug1: channel 0: connected to host.docker.internal port 3000
proxy_1    | debug1: channel 0: free: [REDACTED], nchannels 1

=> Booting Puma
=> Rails 6.0.2.1 application starting in development
=> Run `rails server --help` for more startup options
Puma starting in single mode...
* Version 4.3.1 (ruby 2.6.5-p114), codename: Mysterious Traveller
* Min threads: 0, max threads: 16
* Environment: development
* Listening on ssl://localhost:3000?key=/Users/[REDACTED]/app/private/ssl/development.key&cert=/Users/[REDACTED]/app/private/ssl/development.crt
Use Ctrl-C to stop

Rails and Puma are logging nothing.
Browser is showing 502 Bad Gateway, but that's coming from Nginx/my reverse-proxy setup.

So bottom line, it works in the sense that it is not throwing errors anymore nor timed out, but it's also not indicative at all of what's happening, which could be confusing for some. Not sure if that's the intended behavior.

My suggestion is to make it a bit more verbose - if not actually responding to requests like Passenger does - maybe at least showing that the request was received & closed in the logs.

EDIT:

From what I recall, the code I had set a fixed time that a connection's handshake had to be completed in. If it wasn't, it was closed and removed. I think it only did so if the connection was considered TLSv1.3, which seems to happen with an HTTP connection since there's no 'downgrade' mechanism. I think.

I won't be of much help on the PR itself as I am not familiar with Puma internals, but as I understand it what I suggested above might be a bit more tricky than I thought.

[dentarg]

Puma errors and performs badly when receiving a non-HTTPS request while TLSv1.3-configured

I tried to reproduce this directly against Puma 4.3.3 in macOS (using curl-openssl from Homebrew so I get TLS 1.3 capable curl in macOS)

• curl -k --tlsv1.3 https://localhost:9292 works, so I assume my Puma server is TLSv1.3-configured?
• curl http://localhost:9292 returns "Empty reply from server" after 30s, no errors from Puma (nor logs)
  • maybe these 30 seconds is what we want changed? (bad performance)

@nakwa you are only able to trigger the error using your proxy setup, right?

[nakwa]

@dentarg , not necessarily, I was able to isolate the problem and reproduce it with the proxy setup, but I am pretty sure I also ran into this in other contexts, for instance while querying rails locally from other services (that is, other microservices in my setup).