Address already in use error when attempting to bind to local SSL cert for 3.12.1

[melriffe]

Steps to reproduce

1. Upgrade puma gem from 3.12.0 to 3.12.1

2. Run rails server

3. Receive error:

gems/puma-3.12.1/lib/puma/binder.rb:312:in `initialize': Address already in use - \
bind(2) for "127.0.0.1" port 3000 (Errno::EADDRINUSE)

Expected behavior

I expected to see the following output, as I do with 3.12.0 (well, with the correct version text):

Puma starting in single mode...
* Version 3.12.0 (ruby 2.5.3-p105), codename: Llamas in Pajamas
* Min threads: 5, max threads: 5
* Environment: development
* Listening on tcp://0.0.0.0:3000
* Listening on ssl://127.0.0.1:3000?cert=[snip]
Use Ctrl-C to stop

Actual behavior

However, with 3.12.1 I get a stack trace:

Puma starting in single mode...
* Version 3.12.1 (ruby 2.5.3-p105), codename: Llamas in Pajamas
* Min threads: 5, max threads: 5
* Environment: development
* Listening on tcp://localhost:3000
Exiting
Traceback (most recent call last):
	41: from bin/rails:3:in `<main>'
	40: from bin/rails:3:in `load'
	39: from /Users/mriffe/dev/work/system13/thcic_api/bin/spring:15:in `<top (required)>'
	38: from /Users/mriffe/.rbenv/versions/2.5.3/lib/ruby/site_ruby/2.5.0/rubygems/core_ext/kernel_require.rb:65:in `require'
	37: from /Users/mriffe/.rbenv/versions/2.5.3/lib/ruby/site_ruby/2.5.0/rubygems/core_ext/kernel_require.rb:65:in `require'
	36: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/spring-2.0.2/lib/spring/binstub.rb:31:in `<top (required)>'
	35: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/spring-2.0.2/lib/spring/binstub.rb:31:in `load'
	34: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/spring-2.0.2/bin/spring:49:in `<top (required)>'
	33: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/spring-2.0.2/lib/spring/client.rb:30:in `run'
	32: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/spring-2.0.2/lib/spring/client/command.rb:7:in `call'
	31: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/spring-2.0.2/lib/spring/client/rails.rb:28:in `call'
	30: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/spring-2.0.2/lib/spring/client/rails.rb:28:in `load'
	29: from /Users/mriffe/dev/work/system13/thcic_api/bin/rails:9:in `<top (required)>'
	28: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/activesupport-5.2.3/lib/active_support/dependencies.rb:291:in `require'
	27: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/activesupport-5.2.3/lib/active_support/dependencies.rb:257:in `load_dependency'
	26: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/activesupport-5.2.3/lib/active_support/dependencies.rb:291:in `block in require'
	25: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/bootsnap-1.4.3/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:30:in `require'
	24: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/bootsnap-1.4.3/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:21:in `require_with_bootsnap_lfi'
	23: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/bootsnap-1.4.3/lib/bootsnap/load_path_cache/loaded_features_index.rb:92:in `register'
	22: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/bootsnap-1.4.3/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:22:in `block in require_with_bootsnap_lfi'
	21: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/bootsnap-1.4.3/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:22:in `require'
	20: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/railties-5.2.3/lib/rails/commands.rb:18:in `<main>'
	19: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/railties-5.2.3/lib/rails/command.rb:46:in `invoke'
	18: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/railties-5.2.3/lib/rails/command/base.rb:65:in `perform'
	17: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/thor-0.20.3/lib/thor.rb:387:in `dispatch'
	16: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/thor-0.20.3/lib/thor/invocation.rb:126:in `invoke_command'
	15: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/thor-0.20.3/lib/thor/command.rb:27:in `run'
	14: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/railties-5.2.3/lib/rails/commands/server/server_command.rb:142:in `perform'
	13: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/railties-5.2.3/lib/rails/commands/server/server_command.rb:142:in `tap'
	12: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/railties-5.2.3/lib/rails/commands/server/server_command.rb:147:in `block in perform'
	11: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/railties-5.2.3/lib/rails/commands/server/server_command.rb:53:in `start'
	10: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/rack-2.0.7/lib/rack/server.rb:297:in `start'
	 9: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/puma-3.12.1/lib/rack/handler/puma.rb:73:in `run'
	 8: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/puma-3.12.1/lib/puma/launcher.rb:186:in `run'
	 7: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/puma-3.12.1/lib/puma/single.rb:98:in `run'
	 6: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/puma-3.12.1/lib/puma/runner.rb:153:in `load_and_bind'
	 5: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/puma-3.12.1/lib/puma/binder.rb:90:in `parse'
	 4: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/puma-3.12.1/lib/puma/binder.rb:90:in `each'
	 3: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/puma-3.12.1/lib/puma/binder.rb:211:in `block in parse'
	 2: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/puma-3.12.1/lib/puma/binder.rb:312:in `add_ssl_listener'
	 1: from /Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/puma-3.12.1/lib/puma/binder.rb:312:in `new'
/Users/mriffe/.rbenv/versions/2.5.3/gemsets/thcic_api/gems/puma-3.12.1/lib/puma/binder.rb:312:in `initialize': Address already in use - bind(2) for "127.0.0.1" port 3000 (Errno::EADDRINUSE)

System configuration

Ruby version: 2.5.3
Rails version: 5.2.3
Puma version: 3.12.1

config/puma.rb

# Puma can serve each request in a thread from an internal thread pool.
# The `threads` method setting takes two numbers: a minimum and maximum.
# Any libraries that use thread pools should be configured to match
# the maximum value specified for Puma. Default is set to 5 threads for minimum
# and maximum; this matches the default thread size of Active Record.
#
threads_count = ENV.fetch("RAILS_MAX_THREADS") { 5 }
threads threads_count, threads_count

# Specifies the `port` that Puma will listen on to receive requests; default is 3000.
#
port        ENV.fetch("PORT") { 3000 }

# Specifies the `environment` that Puma will run in.
#
environment ENV.fetch("RAILS_ENV") { "development" }

# Specifies the number of `workers` to boot in clustered mode.
# Workers are forked webserver processes. If using threads and workers together
# the concurrency of the application would be max `threads` * `workers`.
# Workers do not work on JRuby or Windows (both of which do not support
# processes).
#
# workers ENV.fetch("WEB_CONCURRENCY") { 2 }

# Use the `preload_app!` method when specifying a `workers` number.
# This directive tells Puma to first boot the application and load code
# before forking the application. This takes advantage of Copy On Write
# process behavior so workers use less memory. If you use this option
# you need to make sure to reconnect any threads in the `on_worker_boot`
# block.
#
# preload_app!

# If you are preloading your application and using Active Record, it's
# recommended that you close any connections to the database before workers
# are forked to prevent connection leakage.
#
# before_fork do
#   ActiveRecord::Base.connection_pool.disconnect! if defined?(ActiveRecord)
# end

# The code in the `on_worker_boot` will be called if you are using
# clustered mode by specifying a number of `workers`. After each worker
# process is booted, this block will be run. If you are using the `preload_app!`
# option, you will want to use this block to reconnect to any threads
# or connections that may have been created at application boot, as Ruby
# cannot share connections between processes.
#
# on_worker_boot do
#   ActiveRecord::Base.establish_connection if defined?(ActiveRecord)
# end
#

# Allow puma to be restarted by `rails restart` command.
plugin :tmp_restart

# Configure SSL on development
if Rails.env.development?
  STDOUT.puts "Setting development SSL certificate..."
  if `which openssl`.present?
    output_dir = "#{Rails.root}/.ssl/development"
    key_file = "#{output_dir}/localhost.key"
    cert_file = "#{output_dir}/localhost.crt"

    STDOUT.puts "* Looking for SSL certificate in #{output_dir}."
    unless File.exist?(key_file) && File.exist?(cert_file)
      STDOUT.puts "* Development SSL certificate not found.  Creating new certificate with OpenSSL."
      FileUtils.mkdir_p output_dir
      `openssl req -x509 -sha256 -nodes -newkey rsa:2048 -days 365 \
         -subj "/C=US/ST=./L=./O=System13 Development/CN=*.system13.test" \
         -keyout #{output_dir}/localhost.key \
         -out #{output_dir}/localhost.crt`
    else
      STDOUT.puts "* Development SSL certificate found."
    end

    STDOUT.puts "* Binding SSL certificate to localhost."
    ssl_bind '127.0.0.1', '3000', {
      key: key_file,
      cert: cert_file,
      verify_mode: 'none'
    }
  else
    STDOUT.puts "OpenSSL not found.  Cannot set SSL certificate in development."
  end
end

[dannyfallon]

A bunch of things have collided here to cause this issue. Let's take a closer look at the output 🕵

Puma 3.12.0

* Listening on tcp://0.0.0.0:3000     <<<<<<<<
* Listening on ssl://127.0.0.1:3000?cert=/Users/danny/src/myapp/.ssl/development/localhost.crt&key=/Users/danny/src/myapp/.ssl/development/localhost.key&verify_mode=none
Use Ctrl-C to stop

And Puma 3.12.1

* Listening on tcp://localhost:3000    <<<<<<<<
Exiting
Traceback (most recent call last):

It turns out that the use of Puma::DSL#port (on Line 12 in your config/puma.rb) will automatically call bind:

    # Define the TCP port to bind to. Use +bind+ for more advanced options.
    #
    def port(port, host=nil)
      host ||= default_host
      bind "tcp://#{host}:#{port}"
    end

So your use of port causes a binding on port 3000 of default_host. What’s default_host? It turns out that has changed between 3.12.0 and 3.12.1:

In #1699 Puma was changed to use the environment option that rails s provides and if it's set to development we now change the default host to be localhost, not 0.0.0.0 😅 Additionally in #1700 Puma::DSL#port was changed because it was not obeying this change of host - it was using Configuration::DefaultTCPHost (0.0.0.0) as the default, regardless of environment.

So on config/puma.rb#L12 the use of port causes a bind on localhost:3000 and later on in your config you're attempting an ssl_bind on 127.0.0.1 on port 3000. This is why it's throwing an errorr bind(2) for "127.0.0.1" port 3000 (Errno::EADDRINUSE). Note: bindings to 0.0.0.0 do not prevent bindings on the same port with more specific IPs:

➜  netstat -an | grep 3000
tcp4       0      0  127.0.0.1.3000         *.*                    LISTEN
tcp4       0      0  *.3000                 *.*                    LISTEN

So how do you fix this? You’ve a decent set of choices:

1. Change your non-SSL or SSL port.
2. Add set_default_host '0.0.0.0' to your config to return to the pre-3.12.0 knowing that it’ll listen across any IP
3. Remove/comment out port if you have no need to bind to 0.0.0.0. Even if you bind to 0.0.0.0:3000 you cannot visit http://127.0.0.1:3000 or http://localhost:3000 - the SSL binding takes precedence and you're given an exception so the use case seems pretty limited:

2019-05-04 18:51:32 -0500: SSL error, peer: 127.0.0.1, peer cert: , #<Puma::MiniSSL::SSLError: OpenSSL error: error:1407609C:SSL routines:SSL23_GET_CLIENT_HELLO:http request - 336027804>

[nateberkopec]

It turns out that the use of Puma::DSL#port (on Line 12 in your config/puma.rb) will automatically call bind:

hmmm... I wonder if this is a Good Thing? I'm sure that's tripped up others too.

[melriffe]

...
snip
...

Thanks @dannyfallon for the information. I'll give it go but it won't be for a while because puma is not critical to the success of the project in which we're using it. We're using puma only for local development purposes, and, so, 3.12.0 fits our needs.

[dannyfallon]

It turns out that the use of Puma::DSL#port (on Line 12 in your config/puma.rb) will automatically call bind:

hmmm... I wonder if this is a Good Thing? I'm sure that's tripped up others too.

Yep, I was surprised by this. It's a bit spooky that port calls bind, and optionally takes a host for that bind call - it's not the clearest :) I wonder how many people are relying on that behaviour right now? I guess what I'm asking is "is it safe to change?"

[tiagoit]

You just have to kill the puma process that is using the port.
netstat -pan | grep 3000
sudo kill PID
check again for child processes
netstat -pan | grep 3000

[pailoro]

This code will automate the process of fixing it for you https://github.com/pailoro/rails_server_killer