Failed to start proper after 4.1.0, works fine in 4.0.1.

[Eric-Guo]

Steps to reproduce

Just upgrade to 4.1.0.

puma.rb file:

#!/usr/bin/env puma

directory '/var/www/mixtint/current'
rackup "/var/www/mixtint/current/config.ru"
environment 'production'

tag ''

pidfile "/var/www/mixtint/shared/tmp/pids/puma.pid"
state_path "/var/www/mixtint/shared/tmp/pids/puma.state"
stdout_redirect '/var/www/mixtint/shared/log/puma_access.log', '/var/www/mixtint/shared/log/puma_error.log', true


threads 0,16



bind 'unix:///var/www/mixtint/shared/tmp/sockets/puma.sock'

workers 0





prune_bundler


on_restart do
  puts 'Refreshing Gemfile'
  ENV["BUNDLE_GEMFILE"] = ""
end

Expected behavior

Should start properly.

Actual behavior

Not start properly.

=== puma startup: 2019-08-12 09:55:50 +0800 ===
Errno::EPIPE: Broken pipe @ io_writev - <STDOUT>
  /var/www/mixtint/shared/bundle/ruby/2.6.0/gems/puma-4.1.0/lib/puma/events.rb:69:in `write'
  /var/www/mixtint/shared/bundle/ruby/2.6.0/gems/puma-4.1.0/lib/puma/events.rb:69:in `puts'
  /var/www/mixtint/shared/bundle/ruby/2.6.0/gems/puma-4.1.0/lib/puma/events.rb:69:in `log'
  /var/www/mixtint/shared/bundle/ruby/2.6.0/gems/puma-4.1.0/lib/puma/runner.rb:33:in `log'
  /var/www/mixtint/shared/bundle/ruby/2.6.0/gems/puma-4.1.0/lib/puma/single.rb:37:in `stop_blocked'
  /var/www/mixtint/shared/bundle/ruby/2.6.0/gems/puma-4.1.0/lib/puma/launcher.rb:305:in `graceful_stop'
  /var/www/mixtint/shared/bundle/ruby/2.6.0/gems/puma-4.1.0/lib/puma/launcher.rb:399:in `block in setup_signals'
  /var/www/mixtint/shared/bundle/ruby/2.6.0/gems/puma-4.1.0/lib/puma/single.rb:117:in `join'
  /var/www/mixtint/shared/bundle/ruby/2.6.0/gems/puma-4.1.0/lib/puma/single.rb:117:in `run'
  /var/www/mixtint/shared/bundle/ruby/2.6.0/gems/puma-4.1.0/lib/puma/launcher.rb:188:in `run'
  /var/www/mixtint/shared/bundle/ruby/2.6.0/gems/puma-4.1.0/lib/puma/cli.rb:80:in `run'
  /var/www/mixtint/shared/bundle/ruby/2.6.0/gems/puma-4.1.0/bin/puma:10:in `<top (required)>'
  /var/www/mixtint/shared/bundle/ruby/2.6.0/bin/puma:23:in `load'
  /var/www/mixtint/shared/bundle/ruby/2.6.0/bin/puma:23:in `<top (required)>'

System configuration

Ruby version: 2.6.3
Rails version: 5.2.3/6.0.0.rc2
Puma version: 4.1.0

[nateberkopec]

Probably related to #1837

[dentarg]

Probably related to #1837

Global STDOUT/STDERR is used in Puma::Runner. Not sure what needs changing though. Maybe @montanalow knows?

puma/lib/puma/runner.rb

Lines 114 to 138 in a3e18cb

	def redirect_io
	stdout = @options[:redirect_stdout]
	stderr = @options[:redirect_stderr]
	append = @options[:redirect_append]
	if stdout
	unless Dir.exist?(File.dirname(stdout))
	raise "Cannot redirect STDOUT to #{stdout}"
	end
	STDOUT.reopen stdout, (append ? "a" : "w")
	STDOUT.sync = true
	STDOUT.puts "=== puma startup: #{Time.now} ==="
	end
	if stderr
	unless Dir.exist?(File.dirname(stderr))
	raise "Cannot redirect STDERR to #{stderr}"
	end
	STDERR.reopen stderr, (append ? "a" : "w")
	STDERR.sync = true
	STDERR.puts "=== puma startup: #{Time.now} ==="
	end
	end

[montanalow]

https://github.com/puma/puma/blob/v4.1.0/lib/puma/launcher.rb#L399

I'm not terribly familiar with this section, but this stack trace indicates SIGTERM is being raised which is killing the processes?

[Eric-Guo]

@nafaabout Yes, confirm with #1837 , after rollback 2 line changes, now puma can start properly.

[montanalow]

@Eric-Guo your puma.rb works for me with minor path changes on 4.1.0 on OS X using config.ru:

run Proc.new { |env| ['200', {'Content-Type' => 'text/html'}, [env]] }

#!/usr/bin/env puma

directory '.'
rackup "./config.ru"
environment 'production'

tag ''

pidfile "./puma.pid"
state_path "./puma.state"
stdout_redirect './puma_access.log', './puma_error.log', true


threads 0,16



bind 'unix://./puma.sock'

workers 0





prune_bundler


on_restart do
  puts 'Refreshing Gemfile'
  ENV["BUNDLE_GEMFILE"] = ""
end

Puma starting in single mode...
* Version 4.1.0 (ruby 2.6.3-p62), codename: Fourth and One
* Min threads: 0, max threads: 16
* Environment: production
* Listening on unix://./puma.sock
Use Ctrl-C to stop
^C- Gracefully stopping, waiting for requests to finish
=== puma shutdown: 2019-08-13 10:13:58 -0700 ===
- Goodbye!

What OS are you using?

[Eric-Guo]

It's a production server running CentOS 7 and deploys using capistrano3-puma, puma.rb file is generated by capistrano3-puma

[idoo]

have exactly the same issue — rolled back to 4.0.1
@montanalow it's a catcher for signals — it's blocking a code to be run when the signal is raised and then we're stopping runner with

    def graceful_stop
      @runner.stop_blocked
      log "=== puma shutdown: #{Time.now} ==="
      log "- Goodbye!"
    end

[montanalow]

1 potential fix is to revert #1837 , and expect people who want sync = false to explicitly set that on_worker_boot e.g.

puma.rb:

on_worker_boot do
  STDERR.sync = STDOUT.sync = false
end

The other potential fix would be to not dup STDOUT and avoid setting sync = true in Event.initialize to preserve the original intent, and allow the Event pipe to be disconnected during demonization.

We can add explicit flush to Event calls that would preserve the current sync behavior of events only, but it seems like there are other Puma use cases (#1906) that currently expect STDOUT.sync = true

[nateberkopec]

Closing to merge with #1906