Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

There is already a server bound to: /var/run/puma/puma.sock (after OS + ruby upgrade) #2638

Closed
gingerlime opened this issue Jun 3, 2021 · 20 comments · Fixed by #2643
Closed

Comments

@gingerlime
Copy link
Contributor

Describe the bug
I'm using the exact same systemd scripts, codebase and puma config, but after an OS upgrade from Ubuntu 18.04 to 20.04 and ruby upgrade from 2.6.5 to 3.0.1 ... Somehow though I get a problem starting the puma.socket process


$ journalctl -x 

...

Jun 03 06:55:03 stage.app.com bundle[2440]: /var/local/app/app.d/2/vendor/bundle/ruby/3.0.0/gems/puma-5.3.2/lib/puma/binder.rb:380:in `add_unix_listener': There is already a server bound to: /var/run/puma/puma.sock (RuntimeError)
Jun 03 06:55:03 stage.app.com bundle[2440]:         from /var/local/app/app.d/2/vendor/bundle/ruby/3.0.0/gems/puma-5.3.2/lib/puma/binder.rb:217:in `block in parse'
Jun 03 06:55:03 stage.app.com bundle[2440]:         from /var/local/app/app.d/2/vendor/bundle/ruby/3.0.0/gems/puma-5.3.2/lib/puma/binder.rb:152:in `each'
Jun 03 06:55:03 stage.app.com bundle[2440]:         from /var/local/app/app.d/2/vendor/bundle/ruby/3.0.0/gems/puma-5.3.2/lib/puma/binder.rb:152:in `parse'
Jun 03 06:55:03 stage.app.com bundle[2440]:         from /var/local/app/app.d/2/vendor/bundle/ruby/3.0.0/gems/puma-5.3.2/lib/puma/cluster.rb:372:in `run'
Jun 03 06:55:03 stage.app.com bundle[2440]:         from /var/local/app/app.d/2/vendor/bundle/ruby/3.0.0/gems/puma-5.3.2/lib/puma/launcher.rb:181:in `run'
Jun 03 06:55:03 stage.app.com bundle[2440]:         from /var/local/app/app.d/2/vendor/bundle/ruby/3.0.0/gems/puma-5.3.2/lib/puma/cli.rb:80:in `run'
Jun 03 06:55:03 stage.app.com bundle[2440]:         from /var/local/app/app.d/2/vendor/bundle/ruby/3.0.0/gems/puma-5.3.2/bin/puma-wild:25:in `<main>'
Jun 03 06:55:03 stage.app.com systemd[1]: puma.service: Main process exited, code=exited, status=1/FAILURE

Puma config:

#!/usr/bin/env puma

# The directory to operate out of.
#
# The default is the current directory.
#
directory "/var/local/app/app"

# Set the environment in which the rack's app will run. The value must be a string.
#
# The default is "development".
#
environment ENV["RAILS_ENV"] || "development"

# Store the pid of the server in the file at "path".
#
pidfile "/var/run/puma/puma.pid"

# Use "path" as the file to store the server info state. This is
# used by "pumactl" to query and control the server.
#
state_path "/var/run/puma/puma.state"

# Redirect STDOUT and STDERR to files specified. The 3rd parameter
# ("append") specifies whether the output is appended, the default is
# "false".
#
stdout_redirect "/var/log/app/puma.log", "/var/log/app/puma.log", true

# Configure "min" to be the minimum number of threads to use to answer
# requests and "max" the maximum.
#
# The default is "0, 16".
#
# threads 0, 16
threads 8, 8


# Bind the server to "url". "tcp://", "unix://" and "ssl://" are the only
# accepted protocols.
#
# The default is "tcp://0.0.0.0:9292".
#
bind 'unix:///var/run/puma/puma.sock'


# === Cluster mode ===

# How many worker processes to run.  Typically this is set to
# to the number of available cores.
#
# The default is "0".
#
workers ENV["PUMA_WORKERS"] || 16

# Allow workers to reload bundler context when master process is issued
# a USR1 signal. This allows proper reloading of gems while the master
# is preserved across a phased-restart. (incompatible with preload_app)
# (off by default)

# see https://github.com/puma/puma/blob/master/docs/deployment.md#restarting
prune_bundler

systemd scripts

puma.service

[Unit]
Description=Puma HTTP Server
After=network.target

# Uncomment for socket activation (see below)
Requires=puma.socket

[Service]
# Foreground process (do not use --daemon in ExecStart or config.rb)
Type=simple

# Preferably configure a non-privileged user
# User=

# The path to the puma application root
# Also replace the "<WD>" place holders below with this path.
WorkingDirectory=/var/local/app/app

# Helpful for debugging socket activation, etc.
# Environment=PUMA_DEBUG=1
Environment=RAILS_ENV=staging
Environment=PUMA_WORKERS=8

# The command to start Puma. This variant uses a binstub generated via
# `bundle binstubs puma --path ./sbin` in the WorkingDirectory
# (replace "<WD>" below)
ExecStart=/usr/bin/bundle exec --keep-file-descriptors puma -C /var/local/app/app/config/puma.rb
ExecReload=/usr/bin/bundle exec pumactl -F /var/local/app/app/config/puma.rb phased-restart

# Variant: Use config file with `bind` directives instead:
# ExecStart=<WD>/sbin/puma -C config.rb
# Variant: Use `bundle exec --keep-file-descriptors puma` instead of binstub

Restart=always

[Install]
WantedBy=multi-user.target

puma.socket

[Unit]
Description=Puma HTTP Server Accept Sockets

[Socket]
; ListenStream=0.0.0.0:9292
; ListenStream=0.0.0.0:9293

# AF_UNIX domain socket
# SocketUser, SocketGroup, etc. may be needed for Unix domain sockets
ListenStream=/var/run/puma/puma.sock
SocketUser=www-data
SocketGroup=www-data

# Socket options matching Puma defaults
NoDelay=true
ReusePort=true
Backlog=1024

[Install]
WantedBy=sockets.target

To Reproduce
Using the above systemd script and puma config, I see the error I attached when starting puma. I tried clearing the sock file from /var/run/puma but to no avail.

Expected behavior
The exact same files and puma config, on a different host (Ubuntu 18.04, ruby 2.6.5) work just fine...

Desktop (please complete the following information):

  • OS: Ubuntu 20.04
  • Puma Version 5.3.2
@MSP-Greg
Copy link
Member

MSP-Greg commented Jun 3, 2021

@gingerlime

Just to clarify, both OS/Ruby combinations are using Puma 5.3.2?

@gingerlime
Copy link
Contributor Author

@MSP-Greg hey 👋 yes that’s correct. Both are using 5.3.2

@MSP-Greg
Copy link
Member

MSP-Greg commented Jun 3, 2021

Thanks. It may be hard to do, but knowing if the problem happens with Ubuntu 20.04 and Ruby 2.6.x would be helpful. I'll try to have a look soon...

@gingerlime
Copy link
Contributor Author

That's a good idea. Not hard as such, but time consuming. I have some build scripts for the server, so I can bootstrap a new one with ruby 2.7.3 or 2.6.x and see if it happens there. It's not exactly the same environment, but might give us a hint or two?

If you have other ideas of things I could test/check, I'm happy to try (mind you, going to be on holiday soon, so my availability is more limited, but will do my best. Just thought better to report this first in case someone bumped into something similar)

@gingerlime
Copy link
Contributor Author

I'm seeing this issue also with ruby 2.6.5 so I guess we can eliminate ruby 3 as the culprit here? maybe it's related to Ubuntu 20.04 / systemd ? any tips/suggestions for (other) things to try would be most welcome :)

@MSP-Greg
Copy link
Member

MSP-Greg commented Jun 3, 2021

Thanks for testing that. I'll try to see if I can repo.

The conf option DSL#bind_to_activated_sockets may affect it, but confused as to the differences with Ubuntu 18.04 & 20.04...

@gingerlime
Copy link
Contributor Author

I bootstrapped another box with ruby 3 and Ubuntu 18.04, otherwise, same systemd scripts, same code, etc. And it seems to work just fine. So I think there's something between 18.04 and 20.04 that's causing this issue...

@nateberkopec since this isn't something easy to repro inside docker, do you have any suggestions on how to reproduce this simply? is there a sample puma app repo I could potentially use? although it means bootstrapping a VM or something ...

@MSP-Greg
Copy link
Member

@gingerlime

Can you test locally? If so, add the following line as the first line of Binder#create_activated_fds

@events.debug "ENV['LISTEN_FDS'] #{ENV['LISTEN_FDS']}  env_hash['LISTEN_PID'] #{env_hash['LISTEN_PID']}"

and add debug to your Puma config. That should show/log what setting are being passed from systemd to Puma?

@gingerlime
Copy link
Contributor Author

@MSP-Greg not sure what you mean locally ... it's a remote VM. If there's a puma branch that I can point my Gemfile to, this might be the easiest. Also happy to manually tweak the puma config and retry, sure.

@gingerlime
Copy link
Contributor Author

Ok, I added the line with bundle open and then set PUMA_DEBUG=1 inside my systemd script, and here's the output from journalctl -x

Jun 14 14:35:05 stage.app.com bundle[16895]: % ENV['LISTEN_FDS'] 1  env_hash['LISTEN_PID'] 16895
Jun 14 14:35:05 stage.app.com bundle[16895]: % Registered unix:/run/puma/puma.sock for activation from LISTEN_FDS
Jun 14 14:35:05 stage.app.com bundle[16895]: [16895] * Pruning Bundler environment
Jun 14 14:35:05 stage.app.com bundle[16895]: % ENV['LISTEN_FDS'] 1  env_hash['LISTEN_PID'] 16895
Jun 14 14:35:05 stage.app.com bundle[16895]: % Registered unix:/run/puma/puma.sock for activation from LISTEN_FDS
Jun 14 14:35:05 stage.app.com bundle[16895]: [16895] Puma starting in cluster mode...
Jun 14 14:35:05 stage.app.com bundle[16895]: [16895] * Puma version: 5.3.2 (ruby 3.0.1-p64) ("Sweetnighter")
Jun 14 14:35:05 stage.app.com bundle[16895]: [16895] *  Min threads: 8
Jun 14 14:35:05 stage.app.com bundle[16895]: [16895] *  Max threads: 8
Jun 14 14:35:05 stage.app.com bundle[16895]: [16895] *  Environment: staging
Jun 14 14:35:05 stage.app.com bundle[16895]: [16895] *   Master PID: 16895
Jun 14 14:35:05 stage.app.com bundle[16895]: [16895] *      Workers: 8
Jun 14 14:35:05 stage.app.com bundle[16895]: [16895] *     Restarts: (✔) hot (✔) phased
Jun 14 14:35:05 stage.app.com bundle[16895]: /var/local/app/app.d/2/vendor/bundle/ruby/3.0.0/gems/puma-5.3.2/lib/puma/binder.rb:381:in `add_unix_listener': There is alre>
Jun 14 14:35:05 stage.app.com bundle[16895]:         from /var/local/app/app.d/2/vendor/bundle/ruby/3.0.0/gems/puma-5.3.2/lib/puma/binder.rb:218:in `block in parse'
Jun 14 14:35:05 stage.app.com bundle[16895]:         from /var/local/app/app.d/2/vendor/bundle/ruby/3.0.0/gems/puma-5.3.2/lib/puma/binder.rb:153:in `each'
Jun 14 14:35:05 stage.app.com bundle[16895]:         from /var/local/app/app.d/2/vendor/bundle/ruby/3.0.0/gems/puma-5.3.2/lib/puma/binder.rb:153:in `parse'
Jun 14 14:35:05 stage.app.com bundle[16895]:         from /var/local/app/app.d/2/vendor/bundle/ruby/3.0.0/gems/puma-5.3.2/lib/puma/cluster.rb:372:in `run'
Jun 14 14:35:05 stage.app.com bundle[16895]:         from /var/local/app/app.d/2/vendor/bundle/ruby/3.0.0/gems/puma-5.3.2/lib/puma/launcher.rb:181:in `run'
Jun 14 14:35:05 stage.app.com bundle[16895]:         from /var/local/app/app.d/2/vendor/bundle/ruby/3.0.0/gems/puma-5.3.2/lib/puma/cli.rb:80:in `run'
Jun 14 14:35:05 stage.app.com bundle[16895]:         from /var/local/app/app.d/2/vendor/bundle/ruby/3.0.0/gems/puma-5.3.2/bin/puma-wild:25:in `<main>'
Jun 14 14:35:05 stage.app.com systemd[1]: puma.service: Main process exited, code=exited, status=1/FAILURE
-- Subject: Unit process exited

@MSP-Greg
Copy link
Member

@gingerlime

Thanks. That helps. The debug shows run/puma/puma.sock, but it should be /var/run/puma/puma.sock. I'll see what might be causing that...

@gingerlime
Copy link
Contributor Author

Yes, I think I spotted it before when digging through the error. The folders are symlinked on both Ubuntu 18.04 and 20.04 as far as I can tell

# ls -ltra /var/run
lrwxrwxrwx 1 root root 4 May 10 23:36 /var/run -> /run

@MSP-Greg
Copy link
Member

Ok. Let me see if I can repo. There are a few ways to return the unix path, not sure how symlinks are handled with the various ways...

@MSP-Greg
Copy link
Member

Possible reason for this would be that systemd is now creating the socket on the real path, and not the symlink path? Note that if I create a socket from a symlink (in Ruby), the address is shown as the symlink, not the realpath.

Puma is trying to match the paths, it's using the symlink, but systemd provided the real path... Wondering how to fix, as abstract sockets may affect the code...

@MSP-Greg
Copy link
Member

I made a change in a branch in my fork, MSP-Greg/puma, branch 2638-systemd. CI passed, but I don't think anything like this has a test. It may fix the startup issue, but I can't easily test whether it will restart correctly.

I left the debug line in it, but the change was:

elsif sock = @activated_sockets.delete([ :unix, path ])

to

elsif sock = @activated_sockets.delete([ :unix, path ]) ||
    @activated_sockets.delete([ :unix, File.realdirpath(path) ])

@MSP-Greg
Copy link
Member

To clarify, the UNIXSocket path is a symlink, and systemd appears to be using the real path for it.

The code in Binder#parse tries to match the two for systemd provided sockets, and the match fails. It's then assumed that the UNIX bind should be created by Puma, and it fails since systemd has provided a socket listening on the UNIX path...

@gingerlime
Copy link
Contributor Author

Makes sense @MSP-Greg ... I wonder what changes between Ubuntu 18.04 and 20.04 that changes systemd's behaviour. I'll try your branch and see if it works with Ubuntu 20.04 and report back.

@gingerlime
Copy link
Contributor Author

Yep, seems to do the trick 💯

@MSP-Greg
Copy link
Member

@gingerlime Thanks for testing, created a PR...

@gingerlime
Copy link
Contributor Author

Great, thanks so much for your help, @MSP-Greg !

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants