Error during shutdown on Heroku with 5.1.7 #1970

fschwahn · 2017-08-17T09:23:44Z

Issue report

Question 1: What is the problem?
After upgrade to 5.1.7 (from 5.1.4) the following error happens during shutdown. It's not a huge problem as the dyno is killed afterwards anyway, but didn't happen before the update.

Aug 17 10:51:45 heroku/web.1:  Stopping all processes with SIGTERM 
Aug 17 10:51:45 app/web.1:  Stopping web server...bundler: failed to load command: passenger (/app/vendor/bundle/ruby/2.2.0/bin/passenger) 
Aug 17 10:51:45 app/web.1:  PhusionPassenger::DaemonController::StopError: nginx: [alert] could not open error log file: open() "/tmp/passenger-standalone.3bkoss/logs/error.log" failed (2: No such file or directory) 
Aug 17 10:51:45 app/web.1:  2017/08/17 08:51:45 [emerg] 25477#0: open() "/tmp/passenger-standalone.3bkoss/nginx.conf" failed (2: No such file or directory) 
Aug 17 10:51:45 app/web.1:    /app/vendor/bundle/ruby/2.2.0/gems/passenger-5.1.7/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller.rb:436:in `rescue in kill_daemon' 
Aug 17 10:51:45 app/web.1:    /app/vendor/bundle/ruby/2.2.0/gems/passenger-5.1.7/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller.rb:433:in `kill_daemon' 
Aug 17 10:51:45 app/web.1:    /app/vendor/bundle/ruby/2.2.0/gems/passenger-5.1.7/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller.rb:295:in `block (2 levels) in stop' 
Aug 17 10:51:45 app/web.1:    /app/vendor/ruby-2.2.7/lib/ruby/2.2.0/timeout.rb:88:in `block in timeout' 
Aug 17 10:51:45 app/web.1:    /app/vendor/ruby-2.2.7/lib/ruby/2.2.0/timeout.rb:98:in `call' 
Aug 17 10:51:45 app/web.1:    /app/vendor/ruby-2.2.7/lib/ruby/2.2.0/timeout.rb:98:in `timeout' 
Aug 17 10:51:45 app/web.1:    /app/vendor/bundle/ruby/2.2.0/gems/passenger-5.1.7/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller.rb:294:in `block in stop' 
Aug 17 10:51:45 app/web.1:    /app/vendor/bundle/ruby/2.2.0/gems/passenger-5.1.7/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller/lock_file.rb:68:in `block in exclusive_lock' 
Aug 17 10:51:45 app/web.1:    /app/vendor/bundle/ruby/2.2.0/gems/passenger-5.1.7/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller/lock_file.rb:63:in `open' 
Aug 17 10:51:45 app/web.1:    /app/vendor/bundle/ruby/2.2.0/gems/passenger-5.1.7/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller/lock_file.rb:63:in `exclusive_lock' 
Aug 17 10:51:45 app/web.1:    /app/vendor/bundle/ruby/2.2.0/gems/passenger-5.1.7/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller.rb:292:in `stop' 
Aug 17 10:51:45 app/web.1:    /app/vendor/bundle/ruby/2.2.0/gems/passenger-5.1.7/src/ruby_supportlib/phusion_passenger/standalone/start_command.rb:535:in `block in trapsafe_shutdown_and_cleanup' 
Aug 17 10:51:45 app/web.1:    /app/vendor/bundle/ruby/2.2.0/gems/passenger-5.1.7/src/ruby_supportlib/phusion_passenger/standalone/start_command.rb:532:in `synchronize' 
Aug 17 10:51:45 app/web.1:    /app/vendor/bundle/ruby/2.2.0/gems/passenger-5.1.7/src/ruby_supportlib/phusion_passenger/standalone/start_command.rb:532:in `trapsafe_shutdown_and_cleanup' 
Aug 17 10:51:45 app/web.1:    /app/vendor/bundle/ruby/2.2.0/gems/passenger-5.1.7/src/ruby_supportlib/phusion_passenger/standalone/start_command.rb:76:in `rescue in run' 
Aug 17 10:51:45 app/web.1:    /app/vendor/bundle/ruby/2.2.0/gems/passenger-5.1.7/src/ruby_supportlib/phusion_passenger/standalone/start_command.rb:89:in `run'  
Aug 17 10:51:45 app/web.1:    /app/vendor/bundle/ruby/2.2.0/gems/passenger-5.1.7/src/ruby_supportlib/phusion_passenger/standalone/main.rb:51:in `run!' 
Aug 17 10:51:45 app/web.1:    /app/vendor/bundle/ruby/2.2.0/gems/passenger-5.1.7/bin/passenger:45:in `<top (required)>' 
Aug 17 10:51:45 app/web.1:    /app/vendor/bundle/ruby/2.2.0/bin/passenger:23:in `load' 
Aug 17 10:51:45 app/web.1:    /app/vendor/bundle/ruby/2.2.0/bin/passenger:23:in `<top (required)>' 
Aug 17 10:51:45 heroku/web.1:  Process exited with status 1

Question 2: Passenger version and integration mode:
open source 5.1.7 standalone (on Heroku)

Question 3: OS or Linux distro, platform (including version):
Heroku, cedar-14 stack

Question 4: Passenger installation method:
RubyGems + Gemfile

Question 5: Your app's programming language (including any version managers) and framework (including versions):
Ruby 2.2.7, Rails 4.2.9

Question 6: Are you using a PaaS and/or containerization? If so which one?
Heroku

Question 7: Anything else about your setup that we should know?
/

The text was updated successfully, but these errors were encountered:

CamJN · 2017-08-22T14:46:47Z

It looks like the tmp dir is being cleaned up before the nginx process exits. And nginx complains if it's config is missing when it shuts down. This may be a race condition between the tempdirtoucher and the webapp/nginx shutting down.

fschwahn · 2017-08-23T07:27:08Z

Just some more info: this didn't happen in 5.1.4, so it must be some kind of regression. I don't know about the versions between (5.1.5, 5.1.6). Also, this happens deterministically on every dyno shutdown.

CamJN · 2017-08-29T19:06:36Z

Does this still occur if you delete the lines added in this commit? 80b64fd9

fschwahn · 2017-08-31T08:50:47Z

I'm not quite sure how I can delete these lines? Fork the repo? Or is there an easier way?

CamJN · 2017-08-31T14:15:53Z

You can just edit the file at $(dirname $(gem which phusion_passenger))/phusion_passenger/standalone/start_command/nginx_engine.rb.

fschwahn · 2017-08-31T14:23:54Z

I don't believe this possible on Heroku, or can you point me in the right direction?

CamJN · 2017-08-31T14:38:26Z

I believe you would have to heroku run bash to get a dyno you can run commands in, make the changes, then restart passenger manually without closing the bash shell, so that the dyno doesn't go away.

This isn't meant to be a "fix" just a diagnostic step.

xtagon · 2017-09-05T16:37:36Z

@CamJN heroku run gives you a new one-off dyno that isn't running Passenger.

I'm experiencing this issue as well, also on Heroku, and willing to help debug. But I'm kinda stumped.

CamJN · 2017-09-05T16:39:39Z

Yes you'd have to go through the setup process which for heroku would mean gem installing passenger first, assuming that the heroku run bash dyno doesn't bundle install your gemfile for you.

xtagon · 2017-09-05T16:43:33Z

@CamJN I tried starting Passenger in a one-off dyno, without modifying any files, but it didn't produce the stop error. I think this is because one-off dynos are not configured with nginx to be web facing like Heroku's web dynos are.

CamJN · 2017-09-05T20:09:24Z

You can send requests to Passenger using curl.

xtagon · 2017-09-05T20:20:54Z

To clarify....I can't reproduce the error in a one-off dyno. When I run Passenger and then stop it, I don't get the stop error. However, when I stop a normal web dyno that is running passenger, I do get the stop error.

So I can reproduce only in a web dyno - but I can't edit files on the filesystem of a running dyno due to Heroku's limitations (you can't SSH into it).

Is there anything else to try?

fschwahn · 2017-09-06T06:04:35Z

@xtagon this is a beta feature, but you can ssh into running instances since March, see https://devcenter.heroku.com/articles/heroku-exec . I haven't had the time yet to try it.

xtagon · 2017-09-06T19:33:22Z

I used heroku-exec and the ed[1] text editor to find and delete those lines. However, when I restarted the dyno it still failed with the stop error.

[1]: Heroku dynos don't have vim or vi

xtagon · 2017-09-06T19:34:39Z

I will also note that I'm seeing this problem on one of my apps that is still using 5.1.6 (so now we know it was a problem before 5.1.7)

CamJN · 2017-09-06T19:35:46Z

Would it be possible to try and find the first version of Passenger that introduced this issue?

alexpedrosag · 2018-02-23T16:38:35Z

In case it helps:

I have tried to configure via ENV
PASSENGER_PID_FILE: /tmp/passsenger_pid.pid

Connecting through "heroku ps:exec" the file is indeed at
/tmp/passsenger_pid.pid

Then, restarting the web dyno I can get 2 different results (without changing anything, just consecutive restarts):

Sometimes I just get

Stopping web server... done
Process exited with status 2

Other times I get

Stopping web server...bundler: failed to load command: passenger (/app/vendor/bundle/ruby/2.3.0/bin/passenger)
PhusionPassenger::DaemonController::StopError: nginx: [error] open() "/tmp/passsenger_pid.pid" failed (2: No such file or directory)
/app/vendor/bundle/ruby/2.3.0/gems/passenger-5.2.0/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller.rb:448:in `rescue in kill_daemon'
/app/vendor/bundle/ruby/2.3.0/gems/passenger-5.2.0/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller.rb:445:in `kill_daemon'
/app/vendor/bundle/ruby/2.3.0/gems/passenger-5.2.0/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller.rb:304:in `block (2 levels) in stop'
/app/vendor/ruby-2.3.6/lib/ruby/2.3.0/timeout.rb:91:in `block in timeout'
/app/vendor/ruby-2.3.6/lib/ruby/2.3.0/timeout.rb:101:in `timeout'
/app/vendor/bundle/ruby/2.3.0/gems/passenger-5.2.0/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller.rb:303:in `block in stop'
/app/vendor/bundle/ruby/2.3.0/gems/passenger-5.2.0/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller/lock_file.rb:68:in `block in exclusive_lock'
/app/vendor/bundle/ruby/2.3.0/gems/passenger-5.2.0/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller/lock_file.rb:63:in `open'
/app/vendor/bundle/ruby/2.3.0/gems/passenger-5.2.0/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller/lock_file.rb:63:in `exclusive_lock'
/app/vendor/bundle/ruby/2.3.0/gems/passenger-5.2.0/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller.rb:301:in `stop'
/app/vendor/bundle/ruby/2.3.0/gems/passenger-5.2.0/src/ruby_supportlib/phusion_passenger/standalone/start_command.rb:531:in `block in trapsafe_shutdown_and_cleanup'
/app/vendor/bundle/ruby/2.3.0/gems/passenger-5.2.0/src/ruby_supportlib/phusion_passenger/standalone/start_command.rb:528:in `synchronize'
/app/vendor/bundle/ruby/2.3.0/gems/passenger-5.2.0/src/ruby_supportlib/phusion_passenger/standalone/start_command.rb:528:in `trapsafe_shutdown_and_cleanup'
/app/vendor/bundle/ruby/2.3.0/gems/passenger-5.2.0/src/ruby_supportlib/phusion_passenger/standalone/start_command.rb:76:in `rescue in run'
/app/vendor/bundle/ruby/2.3.0/gems/passenger-5.2.0/src/ruby_supportlib/phusion_passenger/standalone/start_command.rb:89:in `run'
/app/vendor/bundle/ruby/2.3.0/gems/passenger-5.2.0/src/ruby_supportlib/phusion_passenger/standalone/main.rb:51:in `run!'
/app/vendor/bundle/ruby/2.3.0/gems/passenger-5.2.0/bin/passenger:45:in `<top (required)>'
/app/vendor/bundle/ruby/2.3.0/bin/passenger:22:in `load'
/app/vendor/bundle/ruby/2.3.0/bin/passenger:22:in `<top (required)>'
Process exited with status 1

CamJN · 2018-02-23T19:35:37Z

Ok so I recreated your environment as described and still can't replicate this, however I created a heroku_testing branch with more logging on startup that should help figure out why the passenger pid file ended up in /. It'd be great if you could try that version and report the logging (the logs print before the =============== Phusion Passenger Standalone web server started =============== message if that helps narrow things down.

CamJN · 2018-02-23T19:38:31Z

Here's how I was working with the branch on heroku without too much trouble:
Gemfile: gem 'passenger', :github => 'phusion/passenger', :branch => "heroku_testing", :submodules => true
Procfile: web: mkdir -p ~/.passenger/support-binaries/5.2.0/ && cp PassengerAgent nginx-* ~/.passenger/support-binaries/5.2.0/ && bundle exec passenger start --port $PORT --max-pool-size 1 --min-instances 1 --max-request-queue-size 100 --nginx-config-template config/passenger_nginx.config.erb
Both PassengerAgent and nginx-1.12.2 exeecutables built with heroku docker image in the top level dir of the app on deploy.

alexpedrosag · 2018-02-26T17:17:04Z

I have updated Gemfile and Procfile as suggested. Here is the log when starting the dyno:

cp: cannot stat 'PassengerAgent': No such file or directory
cp: cannot stat 'nginx-*': No such file or directory
State changed from starting to crashed

I understand that it has something to do with

Both PassengerAgent and nginx-1.12.2 exeecutables built with heroku docker image in the top level dir of the app on deploy.

What would I need to add to build them on deploy? Is that something that would also be recommended for a production app? I initially followed the steps on
https://www.phusionpassenger.com/library/walkthroughs/deploy/ruby/heroku/standalone/oss/deploy_app_main.html

CamJN · 2018-02-26T18:18:29Z

What I did was just mount my passenger source dir into docker running the heroku/heroku:16 image, installed the build tools I needed and then compiled the binaries with passenger-config install-agent and passenger-config install-standalone-runtime. Then I copied the binaries out of the docker image using docker cp, and added them to my heroku test app.

This isn't IMO a good production setup, but it's fine for debugging purposes.

alexpedrosag · 2018-03-08T16:23:57Z

Thank you for the tips. I managed to compile the binaries using docker image heroku/heroku:16-build, and copied PassengerAgent and nginx-1.12.2 to the root of the app. Results below.
(all tests include ENV var PASSENGER_PID_FILE=/tmp/passsenger_pid.pid)

Test 1

Gemfile
gem 'passenger', :github => 'phusion/passenger', :branch => "heroku_testing", :submodules => true
Procfile
web: mkdir -p ~/.passenger/support-binaries/5.2.0/ && cp PassengerAgent nginx-* ~/.passenger/support-binaries/5.2.0/ && bundle exec passenger start --port $PORT --max-pool-size 1 --min-instances 1 --max-request-queue-size 100 --nginx-config-template config/passenger_nginx.config.erb

web.1 - - Starting process with command `mkdir -p ~/.passenger/support-binaries/5.2.0/ && cp PassengerAgent nginx-* ~/.passenger/support-binaries/5.2.0/ && bundle exec passenger start --port 17962 --max-pool-size 1 --min-instances 1 --max-request-queue-size 100 --nginx-config-template config/passenger_nginx.config.erb`
web.1 - - [heroku-exec] Starting
web.1 - - [passenger_native_support.so] not compiling because PASSENGER_COMPILE_NATIVE_SUPPORT_BINARY=0
web.1 - - [passenger_native_support.so] not downloading because passenger wasn't installed from a release package
web.1 - - [passenger_native_support.so] will not be used (can't compile or download)
web.1 - - --> Passenger will still operate normally.
web.1 - - find_apps
web.1 - - []
web.1 - - initialize
web.1 - - []
web.1 - - determine_mode_and_execution_root
web.1 - - []
web.1 - - "/app"
web.1 - - "/app"
web.1 - - find_app_root
web.1 - - []
web.1 - - "/app"
web.1 - - "/app"
web.1 - - find_pid_and_log_file
web.1 - - "/app"
web.1 - - "/tmp/passsenger_pid.pid"
web.1 - - =============== Phusion Passenger Standalone web server started ===============
web.1 - - PID file: /tmp/passsenger_pid.pid
web.1 - - Log file: /app/log/passenger.17962.log
web.1 - - Environment: production
web.1 - - Accessible via: http://0.0.0.0:17962/
web.1 - -
web.1 - - You can stop Phusion Passenger Standalone by pressing Ctrl-C.
web.1 - - Problems? Check https://www.phusionpassenger.com/library/admin/standalone/troubleshooting/
web.1 - - ===============================================================================
web.1 - - State changed from starting to up
web.1 - - App 109 stdout:
web.1 - - [ N 2018-03-08 13:36:38.9973 61/T5 age/Cor/SecurityUpdateChecker.h:507 ]: Security update check: no update found (next check in 24 hours)
web.1 - - App 109 stderr: [passenger_native_support.so] not compiling because PASSENGER_COMPILE_NATIVE_SUPPORT_BINARY=0
web.1 - - App 109 stderr:
web.1 - - App 109 stderr: [passenger_native_support.so] not downloading because passenger wasn't installed from a release package
web.1 - - App 109 stderr:
web.1 - - App 109 stderr: [passenger_native_support.so] will not be used (can't compile or download)
web.1 - - App 109 stderr:
web.1 - - App 109 stderr: --> Passenger will still operate normally.
>>>>>[heroku restart]
web.1 - - Restarting
web.1 - - State changed from up to starting
web.1 - - Stopping all processes with SIGTERM
web.1 - - Process exited with status 143
web.1 - - Starting process with command `mkdir -p ~/.passenger/support-binaries/5.2.0/ && cp PassengerAgent nginx-* ~/.passenger/support-binaries/5.2.0/ && bundle exec passenger start --port 43108 --max-pool-size 1 --min-instances 1 --max-request-queue-size 100 --nginx-config-template config/passenger_nginx.config.erb`
web.1 - - [heroku-exec] Starting
web.1 - - [passenger_native_support.so] not compiling because PASSENGER_COMPILE_NATIVE_SUPPORT_BINARY=0
web.1 - - [passenger_native_support.so] not downloading because passenger wasn't installed from a release package
web.1 - - [passenger_native_support.so] will not be used (can't compile or download)
web.1 - - --> Passenger will still operate normally.
web.1 - - find_apps
web.1 - - []
web.1 - - initialize
web.1 - - []
web.1 - - determine_mode_and_execution_root
web.1 - - []
web.1 - - "/app"
web.1 - - "/app"
web.1 - - find_app_root
web.1 - - []
web.1 - - "/app"
web.1 - - "/app"
web.1 - - find_pid_and_log_file
web.1 - - "/app"
web.1 - - "/tmp/passsenger_pid.pid"
web.1 - - =============== Phusion Passenger Standalone web server started ===============
web.1 - - PID file: /tmp/passsenger_pid.pid
web.1 - - Log file: /app/log/passenger.43108.log
web.1 - - Environment: production
web.1 - - Accessible via: http://0.0.0.0:43108/
web.1 - -
web.1 - - You can stop Phusion Passenger Standalone by pressing Ctrl-C.
web.1 - - Problems? Check https://www.phusionpassenger.com/library/admin/standalone/troubleshooting/
web.1 - - ===============================================================================
web.1 - - State changed from starting to up
web.1 - - App 109 stdout:
web.1 - - [ N 2018-03-08 13:39:53.6925 61/T5 age/Cor/SecurityUpdateChecker.h:507 ]: Security update check: no update found (next check in 24 hours)
web.1 - - App 109 stderr: [passenger_native_support.so] not compiling because PASSENGER_COMPILE_NATIVE_SUPPORT_BINARY=0
web.1 - - App 109 stderr: [passenger_native_support.so] not downloading because passenger wasn't installed from a release package
web.1 - - App 109 stderr: [passenger_native_support.so] will not be used (can't compile or download)
web.1 - - App 109 stderr: --> Passenger will still operate normally.

Test 2

Gemfile
gem 'passenger', '5.2.0'
Procfile
web: mkdir -p ~/.passenger/support-binaries/5.2.0/ && cp PassengerAgent nginx-* ~/.passenger/support-binaries/5.2.0/ && bundle exec passenger start --port $PORT --max-pool-size 1 --min-instances 1 --max-request-queue-size 100 --nginx-config-template config/passenger_nginx.config.erb

As far as I can tell, I would be using standard passenger 5.2.0 but with manually-compiled binaries, right?. In this case, the log is similar and always restarts with:
Process exited with status 143

Test 3

Gemfile
gem 'passenger', '5.2.0'
Procfile
web: bundle exec passenger start --port $PORT --max-pool-size 1 --min-instances 1 --max-request-queue-size 100 --nginx-config-template config/passenger_nginx.config.erb

Going back to standard passenger 5.2.0 and downloaded-at-boot binaries. Restarting the web dyno I get 2 different results (randomly):

Sometimes I just get

Stopping web server... done
Process exited with status 2

Other times

web.1 - - Starting process with command `bundle exec passenger start --port 44996 --max-pool-size 1 --min-instances 1 --max-request-queue-size 100 --nginx-config-template config/passenger_nginx.config.erb`
web.1 - - [heroku-exec] Starting
web.1 - - --> Downloading a Phusion Passenger agent binary for your platform
web.1 - -
web.1 - - --> Installing Nginx 1.12.2 engine
web.1 - -
web.1 - - --------------------------
web.1 - -
web.1 - - [passenger_native_support.so] not compiling because PASSENGER_COMPILE_NATIVE_SUPPORT_BINARY=0
web.1 - - [passenger_native_support.so] finding downloads for the current Ruby interpreter...
web.1 - - (set PASSENGER_DOWNLOAD_NATIVE_SUPPORT_BINARY=0 to disable)
web.1 - - Could not download https://oss-binaries.phusionpassenger.com/binaries/passenger/by_release/5.2.0/rubyext-ruby-2.3.6-x86_64-linux.tar.gz: The requested URL returned error: 404 Not Found
web.1 - - Trying next mirror...
web.1 - - Could not download https://s3.amazonaws.com/phusion-passenger/binaries/passenger/by_release/5.2.0/rubyext-ruby-2.3.6-x86_64-linux.tar.gz: The requested URL returned error: 403 Forbidden
web.1 - - [passenger_native_support.so] will not be used (can't compile or download)
web.1 - - --> Passenger will still operate normally.
web.1 - - =============== Phusion Passenger Standalone web server started ===============
web.1 - - PID file: /tmp/passsenger_pid.pid
web.1 - - Log file: /app/log/passenger.44996.log
web.1 - - Environment: production
web.1 - - Accessible via: http://0.0.0.0:44996/
web.1 - -
web.1 - - You can stop Phusion Passenger Standalone by pressing Ctrl-C.
web.1 - - Problems? Check https://www.phusionpassenger.com/library/admin/standalone/troubleshooting/
web.1 - - ===============================================================================
web.1 - - State changed from starting to up
web.1 - - App 121 stdout:
web.1 - - [ N 2018-03-08 15:27:57.1873 74/T5 age/Cor/SecurityUpdateChecker.h:507 ]: Security update check: no update found (next check in 24 hours)
web.1 - - App 121 stderr: [passenger_native_support.so] not compiling because PASSENGER_COMPILE_NATIVE_SUPPORT_BINARY=0
web.1 - - App 121 stderr: [passenger_native_support.so] finding downloads for the current Ruby interpreter...
web.1 - - App 121 stderr: (set PASSENGER_DOWNLOAD_NATIVE_SUPPORT_BINARY=0 to disable)
web.1 - - App 121 stderr: Could not download https://oss-binaries.phusionpassenger.com/binaries/passenger/by_release/5.2.0/rubyext-ruby-2.3.6-x86_64-linux.tar.gz: The requested URL returned error: 404 Not Found
web.1 - - App 121 stderr: Trying next mirror...
web.1 - - App 121 stderr: Could not download https://s3.amazonaws.com/phusion-passenger/binaries/passenger/by_release/5.2.0/rubyext-ruby-2.3.6-x86_64-linux.tar.gz: The requested URL returned error: 403 Forbidden
web.1 - - App 121 stderr: [passenger_native_support.so] will not be used (can't compile or download)
web.1 - - App 121 stderr: --> Passenger will still operate normally.
>>>>>[heroku restart]
web.1 - - Restarting
web.1 - - State changed from up to starting
web.1 - - Stopping all processes with SIGTERM
web.1 - - Stopping web server...bundler: failed to load command: passenger (/app/vendor/bundle/ruby/2.3.0/bin/passenger)
web.1 - - PhusionPassenger::DaemonController::StopError: nginx: [error] open() "/tmp/passsenger_pid.pid" failed (2: No such file or directory)
web.1 - - /app/vendor/bundle/ruby/2.3.0/gems/passenger-5.2.0/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller.rb:448:in `rescue in kill_daemon'
web.1 - - /app/vendor/bundle/ruby/2.3.0/gems/passenger-5.2.0/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller.rb:445:in `kill_daemon'
web.1 - - /app/vendor/bundle/ruby/2.3.0/gems/passenger-5.2.0/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller.rb:304:in `block (2 levels) in stop'
web.1 - - /app/vendor/ruby-2.3.6/lib/ruby/2.3.0/timeout.rb:91:in `block in timeout'
web.1 - - /app/vendor/ruby-2.3.6/lib/ruby/2.3.0/timeout.rb:101:in `timeout'
web.1 - - /app/vendor/bundle/ruby/2.3.0/gems/passenger-5.2.0/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller.rb:303:in `block in stop'
web.1 - - /app/vendor/bundle/ruby/2.3.0/gems/passenger-5.2.0/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller/lock_file.rb:68:in `block in exclusive_lock'
web.1 - - /app/vendor/bundle/ruby/2.3.0/gems/passenger-5.2.0/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller/lock_file.rb:63:in `open'
web.1 - - /app/vendor/bundle/ruby/2.3.0/gems/passenger-5.2.0/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller/lock_file.rb:63:in `exclusive_lock'
web.1 - - /app/vendor/bundle/ruby/2.3.0/gems/passenger-5.2.0/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller.rb:301:in `stop'
web.1 - - /app/vendor/bundle/ruby/2.3.0/gems/passenger-5.2.0/src/ruby_supportlib/phusion_passenger/standalone/start_command.rb:531:in `block in trapsafe_shutdown_and_cleanup'
web.1 - - /app/vendor/bundle/ruby/2.3.0/gems/passenger-5.2.0/src/ruby_supportlib/phusion_passenger/standalone/start_command.rb:528:in `synchronize'
web.1 - - /app/vendor/bundle/ruby/2.3.0/gems/passenger-5.2.0/src/ruby_supportlib/phusion_passenger/standalone/start_command.rb:528:in `trapsafe_shutdown_and_cleanup'
web.1 - - /app/vendor/bundle/ruby/2.3.0/gems/passenger-5.2.0/src/ruby_supportlib/phusion_passenger/standalone/start_command.rb:76:in `rescue in run'
web.1 - - /app/vendor/bundle/ruby/2.3.0/gems/passenger-5.2.0/src/ruby_supportlib/phusion_passenger/standalone/start_command.rb:89:in `run'
web.1 - - /app/vendor/bundle/ruby/2.3.0/gems/passenger-5.2.0/src/ruby_supportlib/phusion_passenger/standalone/main.rb:51:in `run!'
web.1 - - /app/vendor/bundle/ruby/2.3.0/gems/passenger-5.2.0/bin/passenger:45:in `<top (required)>'
web.1 - - /app/vendor/bundle/ruby/2.3.0/bin/passenger:22:in `load'
web.1 - - /app/vendor/bundle/ruby/2.3.0/bin/passenger:22:in `<top (required)>'
web.1 - - Process exited with status 1
web.1 - - Starting process with command `bundle exec passenger start --port 46583 --max-pool-size 1 --min-instances 1 --max-request-queue-size 100 --nginx-config-template config/passenger_nginx.config.erb`
web.1 - - [heroku-exec] Starting
web.1 - - --> Downloading a Phusion Passenger agent binary for your platform
web.1 - -
web.1 - - --> Installing Nginx 1.12.2 engine
web.1 - -
web.1 - - --------------------------
web.1 - -
web.1 - - [passenger_native_support.so] not compiling because PASSENGER_COMPILE_NATIVE_SUPPORT_BINARY=0
web.1 - - [passenger_native_support.so] finding downloads for the current Ruby interpreter...
web.1 - - (set PASSENGER_DOWNLOAD_NATIVE_SUPPORT_BINARY=0 to disable)
web.1 - - Could not download https://oss-binaries.phusionpassenger.com/binaries/passenger/by_release/5.2.0/rubyext-ruby-2.3.6-x86_64-linux.tar.gz: The requested URL returned error: 404 Not Found
web.1 - - Trying next mirror...
web.1 - - Could not download https://s3.amazonaws.com/phusion-passenger/binaries/passenger/by_release/5.2.0/rubyext-ruby-2.3.6-x86_64-linux.tar.gz: The requested URL returned error: 403 Forbidden
web.1 - - [passenger_native_support.so] will not be used (can't compile or download)
web.1 - - --> Passenger will still operate normally.

Test 4

Gemfile
gem 'passenger', '5.2.1'
Procfile
web: bundle exec passenger start --port $PORT --max-pool-size 1 --min-instances 1 --max-request-queue-size 100 --nginx-config-template config/passenger_nginx.config.erb

Standard passenger 5.2.1 and downloaded-at-boot binaries. Same results as in 5.2.0:

Sometimes I just get

Stopping web server... done
Process exited with status 2

Other times
PhusionPassenger::DaemonController::StopError: nginx: [error] open() "/tmp/passsenger_pid.pid" failed (2: No such file or directory)

Hope this helps!

CamJN · 2018-03-12T17:56:58Z

Test 1 is the only one where the supplemental startup logs are provided and it does not display the problem, so unfortunately this does not help clarify the issue.

alexpedrosag · 2018-03-12T18:19:01Z

I'm sorry, I thought the main issue was the error during shutdown, specifically as @mwmeyer also reported
PhusionPassenger::DaemonController::StopError: nginx: [error] open() "/tmp/passsenger_pid.pid" failed (2: No such file or directory)
and the fact that the behavior is not deterministic (sometimes it throws this error, and other times finishes with status 2).

If there is any new information that can be provided please let me know. Thank you!

CamJN · 2018-03-12T18:21:22Z

The problem is that the pid file doesn't seem to be where it is supposed to be, therefore when passenger shuts down it throws this error. So i'm trying to figure out why the pid file is being saved to the wrong location, that's what the extra logging is attempting to reveal.

I force-pushed to the heroku_testing branch which is now rebased off the most recent release. So there should be no need to do the whole dance with the binaries. Just gem 'passenger', :github => 'phusion/passenger', :branch => "heroku_testing" should be sufficient.

alexpedrosag · 2018-03-12T18:49:17Z

Thank you for your prompt reply! On the tests I have done with ENV var
PASSENGER_PID_FILE=/tmp/passsenger_pid.pid
connecting through "heroku ps:exec" the file is indeed at
/tmp/passsenger_pid.pid
So the pid file is saved where it is supposed to be in the right location (AFAIK). Also, 50%-60% of the times, the restart log just shows

Stopping web server... done
Process exited with status 2

In all other cases where the log is
PhusionPassenger::DaemonController::StopError: nginx: [error] open() "/tmp/passsenger_pid.pid" failed (2: No such file or directory)
Could it be possible that, although the file has just been there (and it has, since heroku ps:exec shows it), it has been removed before running the command open() mentioned in the error?

CamJN · 2019-05-09T18:36:10Z

Is this still an issue?

alexpedrosag · 2019-05-09T20:37:29Z

Yes, I include below the logs for passenger v6.0.2:

2019-05-08T22:31:29.135548+00:00 heroku web.2 - - Stopping all processes with SIGTERM
2019-05-08T22:31:29.937574+00:00 app web.2 - - Stopping web server...bundler: failed to load command: passenger (/app/vendor/bundle/ruby/2.3.0/bin/passenger)
2019-05-08T22:31:29.937595+00:00 app web.2 - - PhusionPassenger::DaemonController::StopError: nginx: [error] open() "/app/passenger.30546.pid" failed (2: No such file or directory)
2019-05-08T22:31:29.937601+00:00 app web.2 - - /app/vendor/bundle/ruby/2.3.0/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller.rb:448:in `rescue in kill_daemon'
2019-05-08T22:31:29.937603+00:00 app web.2 - - /app/vendor/bundle/ruby/2.3.0/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller.rb:445:in `kill_daemon'
2019-05-08T22:31:29.937605+00:00 app web.2 - - /app/vendor/bundle/ruby/2.3.0/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller.rb:304:in `block (2 levels) in stop'
2019-05-08T22:31:29.937607+00:00 app web.2 - - /app/vendor/ruby-2.3.8/lib/ruby/2.3.0/timeout.rb:91:in `block in timeout'
2019-05-08T22:31:29.937609+00:00 app web.2 - - /app/vendor/ruby-2.3.8/lib/ruby/2.3.0/timeout.rb:101:in `timeout'
2019-05-08T22:31:29.937610+00:00 app web.2 - - /app/vendor/bundle/ruby/2.3.0/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller.rb:303:in `block in stop'
2019-05-08T22:31:29.937613+00:00 app web.2 - - /app/vendor/bundle/ruby/2.3.0/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller/lock_file.rb:68:in `block in exclusive_lock'
2019-05-08T22:31:29.937615+00:00 app web.2 - - /app/vendor/bundle/ruby/2.3.0/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller/lock_file.rb:63:in `open'
2019-05-08T22:31:29.937617+00:00 app web.2 - - /app/vendor/bundle/ruby/2.3.0/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller/lock_file.rb:63:in `exclusive_lock'
2019-05-08T22:31:29.937618+00:00 app web.2 - - /app/vendor/bundle/ruby/2.3.0/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller.rb:301:in `stop'
2019-05-08T22:31:29.937620+00:00 app web.2 - - /app/vendor/bundle/ruby/2.3.0/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/standalone/start_command.rb:531:in `block in trapsafe_shutdown_and_cleanup'
2019-05-08T22:31:29.937622+00:00 app web.2 - - /app/vendor/bundle/ruby/2.3.0/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/standalone/start_command.rb:528:in `synchronize'
2019-05-08T22:31:29.937623+00:00 app web.2 - - /app/vendor/bundle/ruby/2.3.0/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/standalone/start_command.rb:528:in `trapsafe_shutdown_and_cleanup'
2019-05-08T22:31:29.937625+00:00 app web.2 - - /app/vendor/bundle/ruby/2.3.0/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/standalone/start_command.rb:76:in `rescue in run'
2019-05-08T22:31:29.937627+00:00 app web.2 - - /app/vendor/bundle/ruby/2.3.0/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/standalone/start_command.rb:89:in `run'
2019-05-08T22:31:29.937629+00:00 app web.2 - - /app/vendor/bundle/ruby/2.3.0/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/standalone/main.rb:51:in `run!'
2019-05-08T22:31:29.937632+00:00 app web.2 - - /app/vendor/bundle/ruby/2.3.0/gems/passenger-6.0.2/bin/passenger:45:in `<top (required)>'
2019-05-08T22:31:29.937634+00:00 app web.2 - - /app/vendor/bundle/ruby/2.3.0/bin/passenger:22:in `load'
2019-05-08T22:31:29.937635+00:00 app web.2 - - /app/vendor/bundle/ruby/2.3.0/bin/passenger:22:in `<top (required)>'
2019-05-08T22:31:30.898752+00:00 heroku web.2 - - Process exited with status 1

Thank you for reviewing this issue!

FooBarWidget · 2025-03-25T08:08:17Z

This is a race condition. Heroku terminates both Nginx and the Passenger Standalone CLI process simultaneously. When Passenger Standalone stops, it tries to stop Nginx. If by that point Nginx is already stopped, then the PID file is already gone, so stopping Nginx again (by invoking nginx -s QUIT) raises an error, complaining that the PID file does not exist.

You can reproduce this by sending SIGTERM to Nginx and the Passenger Standalone CLI process simultaneously.

There have been two attempts in the past to fix this:

In d983fe8 we passed a dont_stop_if_pid_file_invalid option to DaemonController, which instructs it not to run the Nginx stop command if the PID file is invalid.
In 1697850 (a later commit) we modified DaemonController's #stop method to return early if Nginx is not running.

The latter fix was actually redundant because it essentially does the same thing as the former. And neither fix helped in the end, because what we have here is a race condition. If Nginx deletes its PID file after DaemonController determines that Nginx is still running (and thus needs to run the stop command) then that results in the error @alexpedrosag is seeing.

We need to fix this in a race condition free manner. Here are possible strategies:

Don't have DaemonController invoke the Nginx stop command. Instead, have DaemonController just terminate Nginx directly (send signal). If sending signal fails (no such process) then ignore the error.
Invoke the Nginx stop command, but introduce a way to ignore certain errors (such as the stop command complaining that the PID file does not exist).

FooBarWidget added the SupportCentral label Aug 17, 2017

FooBarWidget removed the SupportCentral label Aug 22, 2017

FooBarWidget added the SupportCentral label Aug 23, 2017

FooBarWidget removed the SupportCentral label Aug 29, 2017

FooBarWidget added the SupportCentral label Aug 31, 2017

FooBarWidget removed the SupportCentral label Aug 31, 2017

FooBarWidget added the SupportCentral label Aug 31, 2017

FooBarWidget removed the SupportCentral label Aug 31, 2017

FooBarWidget added the SupportCentral label Sep 5, 2017

FooBarWidget removed the SupportCentral label Sep 5, 2017

FooBarWidget added the SupportCentral label Sep 5, 2017

FooBarWidget removed the SupportCentral label Sep 5, 2017

FooBarWidget added the SupportCentral label Sep 5, 2017

FooBarWidget removed the SupportCentral label Sep 6, 2017

FooBarWidget added the SupportCentral label Feb 23, 2018

FooBarWidget removed the SupportCentral label Feb 23, 2018

OnixGH added the NeedsFeedback label Feb 26, 2018

FooBarWidget added the SupportCentral label Feb 26, 2018

FooBarWidget removed the SupportCentral label Feb 26, 2018

FooBarWidget added the SupportCentral label Mar 8, 2018

FooBarWidget removed the SupportCentral label Mar 12, 2018

FooBarWidget added the SupportCentral label Mar 12, 2018

FooBarWidget removed the SupportCentral label Mar 12, 2018

FooBarWidget added the SupportCentral label Mar 12, 2018

CamJN removed the SupportCentral label May 9, 2018

FooBarWidget removed this from the 5.2.0 milestone Sep 20, 2018

FooBarWidget added the SupportCentral label May 9, 2019

CamJN added SupportCentral and removed SupportCentral NeedsFeedback labels Dec 23, 2019

FooBarWidget linked a pull request Apr 10, 2025 that will close this issue

Standalone: Improve detecting Nginx startup error messages #2611

Open

Error during shutdown on Heroku with 5.1.7 #1970

Error during shutdown on Heroku with 5.1.7 #1970

Comments

fschwahn commented Aug 17, 2017

Issue report

CamJN commented Aug 22, 2017

Uh oh!

fschwahn commented Aug 23, 2017

Uh oh!

CamJN commented Aug 29, 2017

Uh oh!

fschwahn commented Aug 31, 2017

Uh oh!

CamJN commented Aug 31, 2017

Uh oh!

fschwahn commented Aug 31, 2017

Uh oh!

CamJN commented Aug 31, 2017

Uh oh!

xtagon commented Sep 5, 2017

Uh oh!

CamJN commented Sep 5, 2017

Uh oh!

xtagon commented Sep 5, 2017

Uh oh!

CamJN commented Sep 5, 2017

Uh oh!

xtagon commented Sep 5, 2017

Uh oh!

fschwahn commented Sep 6, 2017

Uh oh!

xtagon commented Sep 6, 2017

Uh oh!

xtagon commented Sep 6, 2017

Uh oh!

CamJN commented Sep 6, 2017

Uh oh!

alexpedrosag commented Feb 23, 2018

Uh oh!

CamJN commented Feb 23, 2018

Uh oh!

CamJN commented Feb 23, 2018

Uh oh!

alexpedrosag commented Feb 26, 2018

Uh oh!

CamJN commented Feb 26, 2018

Uh oh!

alexpedrosag commented Mar 8, 2018

Test 1

Test 2

Test 3

Test 4

Uh oh!

CamJN commented Mar 12, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

alexpedrosag commented Mar 12, 2018

Uh oh!

CamJN commented Mar 12, 2018

Uh oh!

alexpedrosag commented Mar 12, 2018

Uh oh!

CamJN commented May 9, 2019

Uh oh!

alexpedrosag commented May 9, 2019

Uh oh!

FooBarWidget commented Mar 25, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

CamJN commented Mar 12, 2018 •

edited

Loading

FooBarWidget commented Mar 25, 2025 •

edited

Loading