Closed msbit closed 5 years ago
Couple more questions: how did you install the ruby you are using? And how are you specifying the ruby to passenger? In the http context or the server context? Lastly what happens if you run passenger-config build-native-support
?
how did you install the ruby you are using?
From the BrightBox PPA (deb http://ppa.launchpad.net/brightbox/ruby-ng/ubuntu precise main
)
how are you specifying the ruby to passenger?
In the http {..}
stanza, included from passenger.conf
(as per instructions from https://www.phusionpassenger.com/library/install/nginx/install/oss/precise/).
The Ruby itself is /usr/bin/passenger_free_ruby
, which looks to do a automatic resolution of whichever Ruby is installed:
$ /usr/bin/passenger_free_ruby -v
ruby 2.1.9p490 (2016-03-30 revision 54437) [i386-linux-gnu]
what happens if you run
passenger-config build-native-support
?
$ passenger-config build-native-support
[passenger_native_support.so] trying to compile for the current user (tom) and Ruby interpreter...
(set PASSENGER_COMPILE_NATIVE_SUPPORT_BINARY=0 to disable)
Compilation successful. The logs are here:
/tmp/passenger_native_support-cbilnm.log
[passenger_native_support.so] successfully loaded.
$ cat /tmp/passenger_native_support-cbilnm.log
# current user is: tom
# mkdir -p /home/tom/.passenger/native_support/5.1.4/ruby-2.1.9-x86-linux
# cd /home/tom/.passenger/native_support/5.1.4/ruby-2.1.9-x86-linux
# /usr/bin/ruby2.1 /usr/share/passenger/ruby_extension_source/extconf.rb
checking for alloca.h... yes
checking for ruby/version.h... yes
checking for ruby/io.h... yes
checking for ruby/thread.h... yes
checking for ruby_version... no
checking for rb_thread_io_blocking_region() in ruby/io.h... yes
checking for rb_thread_call_without_gvl() in ruby/thread.h... yes
creating Makefile
# make
compiling /usr/share/passenger/ruby_extension_source/passenger_native_support.c
linking shared-object passenger_native_support.so
As a follow up, now that this is built, looking over the logs I still see:
App 1789 stdout:
App 1789 stderr: /usr/share/passenger/helper-scripts/rack-preloader.rb: No such file or directory - uname
App 1789 stderr: Rack::File headers parameter replaces cache_control after Rack 1.5.
App 1789 stderr:
App 1789 stderr: sh: 1:
App 1789 stderr: env: not found
App 1789 stderr:
which may indicate that uname
and env
/sh
can't be found due to invalid/missing PATH
.
Just as a heads-up this is the last deb package we will be providing for Ubuntu 12.04, as it EOL'd in April. (see: https://lists.ubuntu.com/archives/ubuntu-announce/2017-March/000218.html and https://www.phusionpassenger.com/library/install/standalone/apt_repo/#limited-package-support-for-non-lts-ubuntu-versions)
As for the PATH issue, can you please set the passenger_log_level to 7 and grab the logs from the startup of passenger and your app, I recreated your setup as closely as I could and didn't run into this issue so I suspect that your .bashrc
or .bash_profile
files may be to blame. Passenger in log level 7 logs the setup of the bash shell used to launch your apps so it should provide some insight there.
Just as a heads-up this is the last deb package we will be providing for Ubuntu 12.04
The writing was on that wall :) Just to confirm, by that you that mean that version 1:5.1.4-1~precise1
is the last supported/provided deb?
can you please set the passenger_log_level to 7 and grab the logs from the startup of passenger and your app
Attached is the full /var/log/nginx/error.log
(emptied before service nginx start
)
error.log.txt, and below a selection of what is likely most relevant:
$ grep 'App 1816' error.log
App 1816 stderr: + '[' '' ']'
App 1816 stderr: + '[' -d /etc/profile.d ']'
App 1816 stderr: + for i in '/etc/profile.d/*.sh'
App 1816 stderr: + '[' -r /etc/profile.d/Z97-byobu.sh ']'
App 1816 stderr: + . /etc/profile.d/Z97-byobu.sh
App 1816 stderr: ++ '[' -n '' ']'
App 1816 stderr: ++ '[' '' = byobu ']'
App 1816 stderr: ++ '[' '' = byobu-screen ']'
App 1816 stderr: ++ '[' '' = byobu-tmux ']'
App 1816 stderr: + for i in '/etc/profile.d/*.sh'
App 1816 stderr: + '[' -r /etc/profile.d/bash_completion.sh ']'
App 1816 stderr: + . /etc/profile.d/bash_completion.sh
App 1816 stderr: ++ '[' -z '4.2.25(1)-release' -o -z '' -o -n '' ']'
App 1816 stderr: ++ return
App 1816 stderr: + unset i
App 1816 stderr: + '[' -n '4.2.25(1)-release' ']'
App 1816 stderr: + '[' -f /home/tom/.bashrc ']'
App 1816 stderr: + . /home/tom/.bashrc
App 1816 stderr: ++ '[' -z '' ']'
App 1816 stderr: ++ return
App 1816 stderr: + '[' -d /home/tom/bin ']'
App 1816 stderr: + '[' -d /home/tom/.gem/ruby/2.1.0/bin ']'
App 1816 stderr: + PATH=/home/tom/.gem/ruby/2.1.0/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
App 1816 stderr: + exec /usr/lib/passenger/support-binaries/PassengerAgent spawn-preparer /home/tom/website SU5fUEFTU0VOR0VSADEAUFlUSE9OVU5CVUZGRVJFRAAxAE5PREVfUEFUSAAvdXNyL3NoYXJlL3Bhc3Nlbmdlci9ub2RlAFJBSUxTX0VOVgBwcm9kdWN0aW9uAFJBQ0tfRU5WAHByb2R1Y3Rpb24AV1NHSV9FTlYAcHJvZHVjdGlvbgBOT0RFX0VOVgBwcm9kdWN0aW9uAFBBU1NFTkdFUl9BUFBfRU5WAHByb2R1Y3Rpb24A /usr/bin/passenger_free_ruby /usr/bin/passenger_free_ruby /usr/share/passenger/helper-scripts/rack-preloader.rb
App 1816 stdout:
[ 2017-05-25 09:36:01.7035 1790/b687eb40 age/Cor/Spa/Spawner.h:704 ]: [App 1816 stdout] !> I have control 1.0
[ 2017-05-25 09:36:01.7038 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>] You have control 1.0
[ 2017-05-25 09:36:01.7038 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>] passenger_root: /usr/lib/ruby/vendor_ruby/phusion_passenger/locations.ini
[ 2017-05-25 09:36:01.7038 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>] ruby_libdir: /usr/lib/ruby/vendor_ruby
[ 2017-05-25 09:36:01.7038 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>] passenger_version: 5.1.4
[ 2017-05-25 09:36:01.7038 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>] UNIX_PATH_MAX: 108
[ 2017-05-25 09:36:01.7038 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>] connect_password: rTepLCkZ4H9btqNZ
[ 2017-05-25 09:36:01.7039 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>] instance_dir: /tmp/passenger.BoeOiNj
[ 2017-05-25 09:36:01.7039 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>] socket_dir: /tmp/passenger.BoeOiNj/apps.s
[ 2017-05-25 09:36:01.7039 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>] app_root: /home/tom/website
[ 2017-05-25 09:36:01.7039 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>] app_group_name: /home/tom/website/public
[ 2017-05-25 09:36:01.7039 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>] app_type: rack
[ 2017-05-25 09:36:01.7039 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>] start_command: /usr/bin/passenger_free_ruby /usr/share/passenger/helper-scripts/rack-loader.rb
[ 2017-05-25 09:36:01.7039 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>] startup_file: /home/tom/website/config.ru
[ 2017-05-25 09:36:01.7039 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>] process_title: Passenger RubyApp
[ 2017-05-25 09:36:01.7039 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>] log_level: 7
[ 2017-05-25 09:36:01.7040 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>] start_timeout: 90000
[ 2017-05-25 09:36:01.7040 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>] environment: production
[ 2017-05-25 09:36:01.7040 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>] base_uri: /
[ 2017-05-25 09:36:01.7040 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>] spawn_method: smart
[ 2017-05-25 09:36:01.7040 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>] default_user: nobody
[ 2017-05-25 09:36:01.7040 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>] default_group: nogroup
[ 2017-05-25 09:36:01.7040 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>] integration_mode: nginx
[ 2017-05-25 09:36:01.7040 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>] ruby: /usr/bin/passenger_free_ruby
[ 2017-05-25 09:36:01.7040 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>] python: python
[ 2017-05-25 09:36:01.7040 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>] nodejs: node
[ 2017-05-25 09:36:01.7040 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>] ust_router_address: unix:/tmp/passenger.BoeOiNj/agents.s/ust_router
[ 2017-05-25 09:36:01.7041 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>] ust_router_username: logging
[ 2017-05-25 09:36:01.7041 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>] ust_router_password: Zsu5EBYn5Sd9JYFF98Ueu3va
[ 2017-05-25 09:36:01.7041 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>] debugger: false
[ 2017-05-25 09:36:01.7041 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>] analytics: false
[ 2017-05-25 09:36:01.7041 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>] api_key: rTepLCkZ4H9btqNZ
[ 2017-05-25 09:36:01.7041 1790/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 1816 stdin >>]
App 1816 stderr: /usr/share/passenger/helper-scripts/rack-preloader.rb: No such file or directory - uname
App 1816 stderr:
App 1816 stderr: Rack::File headers parameter replaces cache_control after Rack 1.5.
App 1816 stderr:
App 1816 stderr: sh: 1:
App 1816 stderr: env: not found
App 1816 stderr:
[ 2017-05-25 09:36:08.7902 1790/b687eb40 age/Cor/Spa/Spawner.h:704 ]: [App 1816 stdout] !> Ready
[ 2017-05-25 09:36:08.7904 1790/b687eb40 age/Cor/Spa/Spawner.h:704 ]: [App 1816 stdout] !> socket: unix:/tmp/passenger.BoeOiNj/apps.s/preloader.2u01hg
[ 2017-05-25 09:36:08.7905 1790/b687eb40 age/Cor/Spa/Spawner.h:704 ]: [App 1816 stdout] !>
App 1816 stderr: [ 2017-05-25 09:36:10.2207 1843/0x82b534c(Main thread) request_handler.rb:177 ]: Entering request handler main loop
App 1816 stderr: [ 2017-05-25 09:36:10.2278 1843/0x828c014(Worker 1) request_handler/thread_handler.rb:142 ]: Accepted new request on socket main socket
App 1816 stderr: cache: [GET /] miss
App 1816 stderr: [ 2017-05-25 09:36:10.3471 1843/0x828c014(Worker 1) request_handler/thread_handler.rb:342 ]: Keep-aliving connection.
App 1816 stderr: [ 2017-05-25 09:36:10.3500 1843/0x828c014(Worker 1) request_handler/thread_handler.rb:172 ]: Request done.
Yes 1:5.1.4-1~precise1
is the last supported/provided deb for 12.04. As for the startup log, it actually looks fine which is all the stranger. Could you dump the ENV['PATH']
in /usr/share/passenger/helper-scripts/rack-preloader.rb
before the GC.copy_on_write_friendly...
line? If you leave the log level up you should be able to just write to stdout
. I'm just wondering if the ruby process inherits the PATH
correctly and then messes it up or if it's in the process of exec-ing the ruby process that the PATH
is lost.
Could you dump the ENV['PATH'] in /usr/share/passenger/helper-scripts/rack-preloader.rb
Putting the following just before GC.copy_on_write_friendly...
:
puts "ENV.keys: #{ENV.keys}"
puts "ENV['PATH']: #{ENV['PATH']}"
prints the following in the log:
App 1511 stdout: ENV.keys: ["SHELL", "PASSENGER_DEBUG_DIR", "USER", "PASSENGER_USE_FEEDBACK_FD", "PWD", "SHLVL", "HOME", "LOGNAME", "SERVER_SOFTWARE", "IN_PASSENGER", "PYTHONUNBUFFERED", "NODE_PATH", "RAILS_ENV", "RACK_ENV", "WSGI_ENV", "NODE_ENV", "PASSENGER_APP_ENV"]
App 1511 stdout: ENV['PATH']:
which seems to indicate that PATH
is actually missing altogether at this point.
Ok, so can you try setting passenger_ruby
to the path to your ruby2.1 executable directly? That should determine if the problem is with passenger_free_ruby
.
With passenger_ruby /usr/bin/ruby;
:
tom@precise:~$ /usr/bin/ruby -v
ruby 2.1.9p490 (2016-03-30 revision 54437) [i386-linux-gnu]
tom@precise:~$ grep 'App 2421' error.log
App 2421 stderr: + '[' '' ']'
App 2421 stderr: + '[' -d /etc/profile.d ']'
App 2421 stderr: + for i in '/etc/profile.d/*.sh'
App 2421 stderr: + '[' -r /etc/profile.d/Z97-byobu.sh ']'
App 2421 stderr: + . /etc/profile.d/Z97-byobu.sh
App 2421 stderr: ++ '[' -n '' ']'
App 2421 stderr: ++ '[' '' = byobu ']'
App 2421 stderr: ++ '[' '' = byobu-screen ']'
App 2421 stderr: ++ '[' '' = byobu-tmux ']'
App 2421 stderr: + for i in '/etc/profile.d/*.sh'
App 2421 stderr: + '[' -r /etc/profile.d/bash_completion.sh ']'
App 2421 stderr: + . /etc/profile.d/bash_completion.sh
App 2421 stderr: ++ '[' -z '4.2.25(1)-release' -o -z '' -o -n '' ']'
App 2421 stderr: ++ return
App 2421 stderr: + unset i
App 2421 stderr: + '[' -n '4.2.25(1)-release' ']'
App 2421 stderr: + '[' -f /home/tom/.bashrc ']'
App 2421 stderr: + . /home/tom/.bashrc
App 2421 stderr: ++ '[' -z '' ']'
App 2421 stderr: ++ return
App 2421 stderr: + '[' -d /home/tom/bin ']'
App 2421 stderr: + '[' -d /home/tom/.gem/ruby/2.1.0/bin ']'
App 2421 stderr: + PATH=/home/tom/.gem/ruby/2.1.0/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
App 2421 stderr: + exec /usr/lib/passenger/support-binaries/PassengerAgent spawn-preparer /home/tom/website SU5fUEFTU0VOR0VSADEAUFlUSE9OVU5CVUZGRVJFRAAxAE5PREVfUEFUSAAvdXNyL3NoYXJlL3Bhc3Nlbmdlci9ub2RlAFJBSUxTX0VOVgBwcm9kdWN0aW9uAFJBQ0tfRU5WAHByb2R1Y3Rpb24AV1NHSV9FTlYAcHJvZHVjdGlvbgBOT0RFX0VOVgBwcm9kdWN0aW9uAFBBU1NFTkdFUl9BUFBfRU5WAHByb2R1Y3Rpb24A /usr/bin/ruby /usr/bin/ruby /usr/share/passenger/helper-scripts/rack-preloader.rb
App 2421 stdout:
App 2421 stdout: ENV.keys: ["SHELL", "PASSENGER_DEBUG_DIR", "USER", "PASSENGER_USE_FEEDBACK_FD", "PWD", "SHLVL", "HOME", "LOGNAME", "SERVER_SOFTWARE", "IN_PASSENGER", "PYTHONUNBUFFERED", "NODE_PATH", "RAILS_ENV", "RACK_ENV", "WSGI_ENV", "NODE_ENV", "PASSENGER_APP_ENV"]
App 2421 stdout: ENV['PATH']:
[ 2017-05-27 20:37:08.0064 2394/b687eb40 age/Cor/Spa/Spawner.h:704 ]: [App 2421 stdout] !> I have control 1.0
[ 2017-05-27 20:37:08.0070 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>] You have control 1.0
[ 2017-05-27 20:37:08.0075 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>] passenger_root: /usr/lib/ruby/vendor_ruby/phusion_passenger/locations.ini
[ 2017-05-27 20:37:08.0078 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>] ruby_libdir: /usr/lib/ruby/vendor_ruby
[ 2017-05-27 20:37:08.0081 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>] passenger_version: 5.1.4
[ 2017-05-27 20:37:08.0084 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>] UNIX_PATH_MAX: 108
[ 2017-05-27 20:37:08.0088 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>] connect_password: B8bH6bJwv6lKP1mp
[ 2017-05-27 20:37:08.0092 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>] instance_dir: /tmp/passenger.nJR5nKm
[ 2017-05-27 20:37:08.0096 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>] socket_dir: /tmp/passenger.nJR5nKm/apps.s
[ 2017-05-27 20:37:08.0099 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>] app_root: /home/tom/website
[ 2017-05-27 20:37:08.0102 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>] app_group_name: /home/tom/website/public
[ 2017-05-27 20:37:08.0106 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>] app_type: rack
[ 2017-05-27 20:37:08.0110 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>] start_command: /usr/bin/ruby /usr/share/passenger/helper-scripts/rack-loader.rb
[ 2017-05-27 20:37:08.0113 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>] startup_file: /home/tom/website/config.ru
[ 2017-05-27 20:37:08.0117 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>] process_title: Passenger RubyApp
[ 2017-05-27 20:37:08.0119 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>] log_level: 7
[ 2017-05-27 20:37:08.0121 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>] start_timeout: 90000
[ 2017-05-27 20:37:08.0123 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>] environment: production
[ 2017-05-27 20:37:08.0126 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>] base_uri: /
[ 2017-05-27 20:37:08.0129 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>] spawn_method: smart
[ 2017-05-27 20:37:08.0132 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>] default_user: nobody
[ 2017-05-27 20:37:08.0134 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>] default_group: nogroup
[ 2017-05-27 20:37:08.0136 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>] integration_mode: nginx
[ 2017-05-27 20:37:08.0139 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>] ruby: /usr/bin/ruby
[ 2017-05-27 20:37:08.0141 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>] python: python
[ 2017-05-27 20:37:08.0142 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>] nodejs: node
[ 2017-05-27 20:37:08.0144 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>] ust_router_address: unix:/tmp/passenger.nJR5nKm/agents.s/ust_router
[ 2017-05-27 20:37:08.0145 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>] ust_router_username: logging
[ 2017-05-27 20:37:08.0146 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>] ust_router_password: h3dWdhReFr67cFBsBdmB3u6Y
[ 2017-05-27 20:37:08.0147 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>] debugger: false
[ 2017-05-27 20:37:08.0147 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>] analytics: false
[ 2017-05-27 20:37:08.0150 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>] api_key: B8bH6bJwv6lKP1mp
[ 2017-05-27 20:37:08.0150 2394/b687eb40 age/Cor/Spa/SmartSpawner.h:388 ]: [App 2421 stdin >>]
App 2421 stderr: /usr/share/passenger/helper-scripts/rack-preloader.rb: No such file or directory - uname
App 2421 stderr:
App 2421 stderr: Rack::File headers parameter replaces cache_control after Rack 1.5.
App 2421 stderr:
App 2421 stderr: sh: 1:
App 2421 stderr: env: not found
App 2421 stderr:
[ 2017-05-27 20:37:17.9016 2394/b687eb40 age/Cor/Spa/Spawner.h:704 ]: [App 2421 stdout] !> Ready
[ 2017-05-27 20:37:17.9021 2394/b687eb40 age/Cor/Spa/Spawner.h:704 ]: [App 2421 stdout] !> socket: unix:/tmp/passenger.nJR5nKm/apps.s/preloader.oaxsbe
[ 2017-05-27 20:37:17.9026 2394/b687eb40 age/Cor/Spa/Spawner.h:704 ]: [App 2421 stdout] !>
App 2421 stderr: [ 2017-05-27 20:37:19.0395 2438/0x933d340(Main thread) request_handler.rb:177 ]: Entering request handler main loop
App 2421 stderr: [ 2017-05-27 20:37:19.0492 2438/0x9314044(Worker 1) request_handler/thread_handler.rb:142 ]: Accepted new request on socket main socket
App 2421 stderr: cache: [GET /] miss
App 2421 stderr: [ 2017-05-27 20:37:19.2824 2438/0x9314044(Worker 1) request_handler/thread_handler.rb:342 ]: Keep-aliving connection.
App 2421 stderr: [ 2017-05-27 20:37:19.2834 2438/0x9314044(Worker 1) request_handler/thread_handler.rb:172 ]: Request done.
App 2421 stderr: [ 2017-05-27 20:37:19.2844 2438/0x9314044(Worker 1) request_handler/thread_handler.rb:142 ]: Accepted new request on socket main socket
App 2421 stderr: cache: [GET /] reload
App 2421 stderr: [ 2017-05-27 20:37:19.3098 2438/0x9314044(Worker 1) request_handler/thread_handler.rb:342 ]: Keep-aliving connection.
App 2421 stderr: [ 2017-05-27 20:37:19.3104 2438/0x9314044(Worker 1) request_handler/thread_handler.rb:172 ]: Request done.
App 2421 stderr: [ 2017-05-27 20:37:19.9258 2449/0x933d340(Main thread) request_handler.rb:177 ]: Entering request handler main loop
App 2421 stderr: [ 2017-05-27 20:37:41.6114 2438/0x933d340(Main thread) request_handler.rb:485 ]: Owner pipe closed
App 2421 stderr: [ 2017-05-27 20:37:41.6117 2438/0x933d340(Main thread) request_handler.rb:547 ]: Waiting until all threads have become idle...
App 2421 stderr: [ 2017-05-27 20:37:41.6120 2438/0x933d340(Main thread) request_handler.rb:560 ]: There are currently 2 threads
App 2421 stderr: [ 2017-05-27 20:37:41.6136 2449/0x933d340(Main thread) request_handler.rb:485 ]: Owner pipe closed
App 2421 stderr: [ 2017-05-27 20:37:41.6150 2449/0x933d340(Main thread) request_handler.rb:547 ]: Waiting until all threads have become idle...
App 2421 stderr: [ 2017-05-27 20:37:41.6163 2449/0x933d340(Main thread) request_handler.rb:560 ]: There are currently 2 threads
App 2421 stderr: [ 2017-05-27 20:37:41.7135 2438/0x933d340(Main thread) request_handler.rb:605 ]: All threads are now idle
App 2421 stderr: [ 2017-05-27 20:37:41.7177 2438/0x933d340(Main thread) request_handler.rb:533 ]: Stopping all threads
App 2421 stderr: [ 2017-05-27 20:37:41.7193 2438/0x9314044(Worker 1) request_handler/thread_handler.rb:119 ]: Thread handler main loop exited normally
App 2421 stderr: [ 2017-05-27 20:37:41.7202 2438/0x93193b4(HTTP helper worker) request_handler/thread_handler.rb:119 ]: Thread handler main loop exited normally
App 2421 stderr: [ 2017-05-27 20:37:41.7207 2438/0x933d340(Main thread) request_handler.rb:543 ]: All threads stopped
App 2421 stderr: [ 2017-05-27 20:37:41.7235 2438/0x933d340(Main thread) request_handler.rb:205 ]: Request handler main loop exited normally
App 2421 stderr: [ 2017-05-27 20:37:41.7237 2438/0x933d340(Main thread) request_handler.rb:222 ]: Exiting request handler main loop
App 2421 stderr: [ 2017-05-27 20:37:41.7328 2449/0x933d340(Main thread) request_handler.rb:605 ]: All threads are now idle
App 2421 stderr: [ 2017-05-27 20:37:41.7402 2449/0x933d340(Main thread) request_handler.rb:533 ]: Stopping all threads
App 2421 stderr: [ 2017-05-27 20:37:41.7447 2449/0x93140e4(Worker 1) request_handler/thread_handler.rb:119 ]: Thread handler main loop exited normally
App 2421 stderr: [ 2017-05-27 20:37:41.7472 2449/0x931a14c(HTTP helper worker) request_handler/thread_handler.rb:119 ]: Thread handler main loop exited normally
App 2421 stderr: [ 2017-05-27 20:37:41.7493 2449/0x933d340(Main thread) request_handler.rb:543 ]: All threads stopped
App 2421 stderr: [ 2017-05-27 20:37:41.7601 2449/0x933d340(Main thread) request_handler.rb:205 ]: Request handler main loop exited normally
App 2421 stderr: [ 2017-05-27 20:37:41.7623 2449/0x933d340(Main thread) request_handler.rb:222 ]: Exiting request handler main loop
what does file /usr/bin/ruby
return?
@CamJN sorry about the delay there, I missed the notification.
$ file /usr/bin/ruby
/usr/bin/ruby: symbolic link to `/etc/alternatives/ruby'
$ update-alternatives --list ruby
/usr/bin/ruby2.1
$ update-alternatives --display ruby
ruby - auto mode
link currently points to /usr/bin/ruby2.1
/usr/bin/ruby2.1 - priority 51
slave erb: /usr/bin/erb2.1
slave erb.1.gz: /usr/share/man/man1/erb2.1.1.gz
slave irb: /usr/bin/irb2.1
slave irb.1.gz: /usr/share/man/man1/irb2.1.1.gz
slave rake: /usr/bin/rake2.1
slave rake.1.gz: /usr/share/man/man1/rake2.1.1.gz
slave rdoc: /usr/bin/rdoc2.1
slave ri: /usr/bin/ri2.1
slave ri.1.gz: /usr/share/man/man1/ri2.1.1.gz
slave ruby.1.gz: /usr/share/man/man1/ruby2.1.1.gz
slave testrb: /usr/bin/testrb2.1
Current 'best' version is '/usr/bin/ruby2.1'.
$ /usr/bin/ruby2.1 -v
ruby 2.1.9p490 (2016-03-30 revision 54437) [i386-linux-gnu]
Ok so /usr/bin/ruby
is a symlink to /etc/alternatives/ruby
which is in turn a symlink to /usr/bin/ruby2.1
. That shouldn't cause any changes to the env.
Does the line in your bash config that looks something like this: PATH=/home/tom/.gem/ruby/2.1.0/bin:$PATH
have an export
on it? I'm just wondering if something weird is happening where the PATH
environment variable gets shadowed by a local variable in bash and then not inherited during the exec (that shouldn't happen but we're well past things making sense).
If this is not relevant to this issue I can open a separate one
I'm having the same problem on heroku, relevant logs:
Jun 07 13:41:49 app/web.1: [passenger_native_support.so] will not be used (can't compile or download)
Jun 07 13:41:49 app/web.1: --> Passenger will still operate normally.
Jun 07 13:41:49 app/web.1: =============== Phusion Passenger Standalone web server started ===============
Jun 07 13:41:49 app/web.1: PID file: /app/passenger.53286.pid
Jun 07 13:41:49 app/web.1: Log file: /app/log/passenger.53286.log
Jun 07 13:41:49 app/web.1: Environment: production
Jun 07 13:41:49 app/web.1: Accessible via: http://0.0.0.0:53286/
Jun 07 13:41:49 app/web.1: You can stop Phusion Passenger Standalone by pressing Ctrl-C.
Jun 07 13:41:49 app/web.1: Problems? Check https://www.phusionpassenger.com/library/admin/standalone/troubleshooting/
Jun 07 13:41:49 app/web.1: ===============================================================================
Jun 07 13:41:50 app/web.1: App 85 stdout:
Jun 07 13:41:51 app/web.1: App 85 stderr: [passenger_native_support.so] trying to compile for the current user (u30758) and Ruby interpreter...
Jun 07 13:41:51 app/web.1: App 85 stderr: (set PASSENGER_COMPILE_NATIVE_SUPPORT_BINARY=0 to disable)
Jun 07 13:41:51 app/web.1: [ 2017-06-07 11:41:51.2552 34/7ff4462f3700 age/Cor/SecurityUpdateChecker.h:356 ]: Security update check: no update found (next check in 24 hours)
Jun 07 13:41:52 app/web.1: App 85 stderr: Warning: compilation didn't succeed. To learn why, read this file:
Jun 07 13:41:52 app/web.1: App 85 stderr: /tmp/passenger_native_support-1e2lc2m.log
Jun 07 13:41:52 app/web.1: App 85 stderr: [passenger_native_support.so] finding downloads for the current Ruby interpreter...
Jun 07 13:41:52 app/web.1: App 85 stderr: (set PASSENGER_DOWNLOAD_NATIVE_SUPPORT_BINARY=0 to disable)
Jun 07 13:41:52 app/web.1: App 85 stderr: Could not download https://oss-binaries.phusionpassenger.com/binaries/passenger/by_release/5.1.4/rubyext-ruby-2.2.7-x86_64-linux.tar.gz: The requested URL returned error: 404 Not Found
Jun 07 13:41:52 app/web.1: App 85 stderr: Trying next mirror...
Jun 07 13:41:52 app/web.1: App 85 stderr: Could not download https://s3.amazonaws.com/phusion-passenger/binaries/passenger/by_release/5.1.4/rubyext-ruby-2.2.7-x86_64-linux.tar.gz: The requested URL returned error: 403 Forbidden
Jun 07 13:41:52 app/web.1: App 85 stderr: [passenger_native_support.so] will not be used (can't compile or download)
Jun 07 13:41:52 app/web.1: App 85 stderr: --> Passenger will still operate normally.
We are using ruby 2.2.7, but if I check https://oss-binaries.phusionpassenger.com/binaries/passenger/by_release/5.1.4/ there is only a native binary for ruby 2.2.5.
Hey @fschwahn looks like that is a bit of a different issue, as in your case there is an attempt to fetch the extension, so it would be worth creating a new issue for this. More information for what went wrong is likely in /tmp/passenger_native_support-1e2lc2m.log
, and that would be useful for adding to any issue you make.
@fschwahn the info you pasted is not enough to be considered an issue at this point. Native support is not required, and it's normal that not all binaries are available (we supply a few for convenience). It usually fails to compile if you don't have the necessary development tools installed (as @msbit said check the log).
Ok, the message threw me off, I thought this download is supposed to succeed - it seems having the download fail is the common case. Sorry for interrupting!
@CamJN interesting idea!. My PATH
is set up in ~/.profile
via:
# set PATH so it includes user's private bin if it exists
if [ -d "$HOME/bin" ] ; then
PATH="$HOME/bin:$PATH"
fi
if [ -d "$HOME/.gem/ruby/2.1.0/bin" ] ; then
PATH="$HOME/.gem/ruby/2.1.0/bin:$PATH"
fi
so no explicit export
for PATH
.
@msbit interesting, .profile
is actually a sh
config, though it is often sourced from bash for the sake of ease of use. Is there a shebang (#!
) line at the top of .profile
and if so what does it say?
No shebang, full content of ~/.profile
below:
$ cat ~/.profile
# ~/.profile: executed by the command interpreter for login shells.
# This file is not read by bash(1), if ~/.bash_profile or ~/.bash_login
# exists.
# see /usr/share/doc/bash/examples/startup-files for examples.
# the files are located in the bash-doc package.
# the default umask is set in /etc/profile; for setting the umask
# for ssh logins, install and configure the libpam-umask package.
#umask 022
# if running bash
if [ -n "$BASH_VERSION" ]; then
# include .bashrc if it exists
if [ -f "$HOME/.bashrc" ]; then
. "$HOME/.bashrc"
fi
fi
# set PATH so it includes user's private bin if it exists
if [ -d "$HOME/bin" ] ; then
PATH="$HOME/bin:$PATH"
fi
if [ -d "$HOME/.gem/ruby/2.1.0/bin" ] ; then
PATH="$HOME/.gem/ruby/2.1.0/bin:$PATH"
fi
I've been looking through the code, and it does look like a login shell is created via the -l
argument to bash, at src/agent/Core/SpawningKit/SmartSpawner.h
, lines 110 or 112, so it would make sense that ~/.profile
is included.
Using .profile
seems to be the issue, as this doesn't happen with .bash_profile
. And it can be fixed by adding an export PATH="$PATH"
line to the very end of the file.
@CamJN for me, if I replace .profile
with .bash_profile
(same contents) the issue still occurs. From https://www.gnu.org/software/bash/manual/bashref.html#Bash-Startup-Files this makes sense as:
When Bash is invoked as an interactive login shell, or as a non-interactive shell with the --login option, it first reads and executes commands from the file /etc/profile, if that file exists. After reading that file, it looks for ~/.bash_profile, ~/.bash_login, and ~/.profile, in that order, and reads and executes commands from the first one that exists and is readable. The --noprofile option may be used when the shell is started to inhibit this behavior.
I can confirm that adding export PATH=${PATH}
at the end of ~/.profile
makes sure that the PATH
is passed to the:
exec /usr/lib/passenger/support-binaries/PassengerAgent spawn-preparer /home/tom/website <BASE64_ARGS> /usr/bin/ruby2.1 /usr/bin/ruby2.1 /usr/share/passenger/helper-scripts/rack-preloader.rb
in the logs.
It's a little odd from my point of view though, as the server is effectively a completely new reinstall, and the ~/.profile
only differs from the vanilla in the addition of:
if [ -d "$HOME/.gem/ruby/2.1.0/bin" ] ; then
PATH="$HOME/.gem/ruby/2.1.0/bin:$PATH"
fi
Out of curiosity more than anything, I removed the ~/.profile
file and tried that, but it had the same affect.
I've been trying to trace the execution flow, but I'm not sure where the Nginx code initially hands off to either PassengerAgent
or whichever helper is dealing with the request.
Bash is supposed to pass environment variables to its children, and after a variable is exported once it's supposed to be treated like an environment variable even if it gets shadowed but bash isn't doing that for some reason.
@msbit did you ever solve this?
@jmeridth unfortunately not.
It was for an older, unsupported version of Ubuntu and from memory it could be worked around so I didn’t look any further. My guess is the version of bash or general sh for that version of Ubuntu didn’t pass environment variables properly, but can’t be sure.
@jmeridth feel free to include the details from your setup, especially a startup log with log level set to 7.
Still happens to me with 5.2.0 and 5.3.4 on heroku.
2018-09-07T23:13:20.525834+00:00 heroku[release.4984]: Process exited with status 0
2018-09-07T23:13:22.342532+00:00 heroku[web.1]: Restarting
2018-09-07T23:13:22.343083+00:00 heroku[web.1]: State changed from up to starting
2018-09-07T23:13:22.972234+00:00 app[web.1]: App 111 stdout: {"lib":"que","hostname":"ef411ddd-13d2-41af-bf51-cd16765c75f8","pid":111,"thread":69842201157440,"event":"job_unavailable"}
2018-09-07T23:13:23.032766+00:00 app[web.1]: Stopping web server... done
2018-09-07T23:13:23.018086+00:00 heroku[web.1]: Stopping all processes with SIGTERM
2018-09-07T23:13:23.318989+00:00 heroku[web.1]: Process exited with status 2
2018-09-07T23:13:22.116210+00:00 app[api]: Release v20 created by user jeff@7compass.com
2018-09-07T23:13:50.351216+00:00 heroku[web.1]: Starting process with command `jemalloc.sh bundle exec passenger start -p 32937 --max-pool-size 3 --min-instances 2`
2018-09-07T23:13:53.413361+00:00 app[web.1]: --> Downloading a Phusion Passenger agent binary for your platform
2018-09-07T23:13:53.645181+00:00 app[web.1]:
2018-09-07T23:13:53.645192+00:00 app[web.1]: --> Installing Nginx 1.12.2 engine
2018-09-07T23:13:53.827074+00:00 app[web.1]:
2018-09-07T23:13:53.827121+00:00 app[web.1]: --------------------------
2018-09-07T23:13:53.827123+00:00 app[web.1]:
2018-09-07T23:13:53.844791+00:00 app[web.1]: [passenger_native_support.so] trying to compile for the current user (u21582) and Ruby interpreter...
2018-09-07T23:13:53.844794+00:00 app[web.1]: (set PASSENGER_COMPILE_NATIVE_SUPPORT_BINARY=0 to disable)
2018-09-07T23:13:54.471994+00:00 app[web.1]: Warning: compilation didn't succeed. To learn why, read this file:
2018-09-07T23:13:54.472045+00:00 app[web.1]: /tmp/passenger_native_support-i93jj8.log
2018-09-07T23:13:54.472120+00:00 app[web.1]: [passenger_native_support.so] finding downloads for the current Ruby interpreter...
2018-09-07T23:13:54.472146+00:00 app[web.1]: (set PASSENGER_DOWNLOAD_NATIVE_SUPPORT_BINARY=0 to disable)
2018-09-07T23:13:55.203004+00:00 app[web.1]: Could not download https://oss-binaries.phusionpassenger.com/binaries/passenger/by_release/5.2.0/rubyext-ruby-2.5.0-x86_64-linux.tar.gz: The requested URL returned error: 404 Not Found
2018-09-07T23:13:55.203396+00:00 app[web.1]: Trying next mirror...
2018-09-07T23:13:55.544491+00:00 app[web.1]: Could not download https://s3.amazonaws.com/phusion-passenger/binaries/passenger/by_release/5.2.0/rubyext-ruby-2.5.0-x86_64-linux.tar.gz: The requested URL returned error: 403 Forbidden
2018-09-07T23:13:55.544968+00:00 app[web.1]: [passenger_native_support.so] will not be used (can't compile or download)
2018-09-07T23:13:55.544995+00:00 app[web.1]: --> Passenger will still operate normally.
2018-09-07T23:13:55.717891+00:00 heroku[web.1]: State changed from starting to up
2018-09-07T23:13:56.022078+00:00 app[web.1]: =============== Phusion Passenger Standalone web server started ===============
2018-09-07T23:13:56.022099+00:00 app[web.1]: PID file: /app/passenger.32937.pid
2018-09-07T23:13:56.022101+00:00 app[web.1]: Log file: /app/passenger.32937.log
2018-09-07T23:13:56.022103+00:00 app[web.1]: Environment: production
2018-09-07T23:13:56.022107+00:00 app[web.1]: Accessible via: http://0.0.0.0:32937/
2018-09-07T23:13:56.022109+00:00 app[web.1]:
2018-09-07T23:13:56.022132+00:00 app[web.1]: You can stop Phusion Passenger Standalone by pressing Ctrl-C.
2018-09-07T23:13:56.022161+00:00 app[web.1]: Problems? Check https://www.phusionpassenger.com/library/admin/standalone/troubleshooting/
2018-09-07T23:13:56.022163+00:00 app[web.1]: ===============================================================================
2018-09-07T23:13:58.460178+00:00 app[web.1]: [ N 2018-09-07 23:13:58.4599 34/T7 age/Cor/SecurityUpdateChecker.h:507 ]: Security update check: no update found (next check in 24 hours)
2018-09-07T23:13:58.671005+00:00 app[web.1]: App 79 stdout:
2018-09-07T23:13:59.324036+00:00 app[web.1]: App 79 stderr: [passenger_native_support.so] trying to compile for the current user (u21582) and Ruby interpreter...
2018-09-07T23:13:59.324227+00:00 app[web.1]: App 79 stderr: (set PASSENGER_COMPILE_NATIVE_SUPPORT_BINARY=0 to disable)
2018-09-07T23:14:00.069147+00:00 app[web.1]: App 79 stderr: Warning: compilation didn't succeed. To learn why, read this file:
2018-09-07T23:14:00.069336+00:00 app[web.1]: App 79 stderr: /tmp/passenger_native_support-1k21oht.log
2018-09-07T23:14:00.069375+00:00 app[web.1]: App 79 stderr: [passenger_native_support.so] finding downloads for the current Ruby interpreter...
2018-09-07T23:14:00.069399+00:00 app[web.1]: App 79 stderr: (set PASSENGER_DOWNLOAD_NATIVE_SUPPORT_BINARY=0 to disable)
2018-09-07T23:14:00.710363+00:00 app[web.1]: App 79 stderr: Could not download https://oss-binaries.phusionpassenger.com/binaries/passenger/by_release/5.2.0/rubyext-ruby-2.5.0-x86_64-linux.tar.gz: The requested URL returned error: 404 Not Found
2018-09-07T23:14:00.710395+00:00 app[web.1]: App 79 stderr: Trying next mirror...
2018-09-07T23:14:01.019868+00:00 app[web.1]: App 79 stderr: Could not download https://s3.amazonaws.com/phusion-passenger/binaries/passenger/by_release/5.2.0/rubyext-ruby-2.5.0-x86_64-linux.tar.gz: The requested URL returned error: 403 Forbidden
2018-09-07T23:14:01.019982+00:00 app[web.1]: App 79 stderr: [passenger_native_support.so] will not be used (can't compile or download)
2018-09-07T23:14:01.020068+00:00 app[web.1]: App 79 stderr: --> Passenger will still operate normally.
Ran into this today. I can compile passenger_native_support.so from similar tarball source than the (failed) url that it tried. Where do I put it to make passenger stop complaining?
A year and a half later...isn't this just an issue of putting the binaries on the proper cdn urls?
@jemminger the actual issue is not being able to compile passenger_native_support.so
due to the environment not being passed along correctly to the build script.
@Tectract the best way to compile the missing file is via:
passenger-config build-native-support
This will build the file in the correct location, for me:
/home/tom/.gem/ruby/2.5.0/gems/passenger-5.3.5/buildout/ruby/ruby-2.5.1-x86_64-linux/passenger_native_support.so
Closing as this is an issue with certain versions of bash not working correctly.
I was seeing this same problem and it turned out to be a configuration issue.
Similar to OP we have ~/.profile
and compilation of native bindings was failing. The log file showed that the Makefile
was successfully created but make
failed because it failed to find things like cat
, echo
, and sed
. Turning the log-level up to 7 I noticed that the app was being started with a bunch of environment variables that were all defined in our nginx configuration with passenger_env_var
.
For some reason we were setting passenger_env_var PATH /usr/bin
. This was overriding any PATH
set by the shell or ~/.profile
and on Ubuntu 18 echo
and friends live in /bin
, not /usr/bin
. Once I deleted the configuration that set PATH
native bindings build successfully.
Answer to questions below, but it looks like it's an issue with the
PATH
being cleared out somehow before/during invocation of/usr/share/passenger/helper-scripts/rack-preloader.rb
.Question 1: What is the problem? On start, passenger is unable to build or fetch the passenger_native_support.so. In the logs we have the following:
Contents of temp file:
Contents of
mkmf.log
:Manually running the
extconf.rb
:Presence of
curl
:Question 2: Passenger version and integration mode: Open-source 5.1.4/nginx
Question 3: OS or Linux distro, platform (including version): Ubuntu 12.04.5 LTS i386
Question 4: Passenger installation method: [ ] RubyGems + Gemfile [ ] RubyGems, no Gemfile [x] Phusion APT repo [ ] Phusion YUM repo [ ] OS X Homebrew [ ] source tarball [ ] Other, please specify:
Question 5: Your app's programming language (including any version managers) and framework (including versions): Ruby 2.1.9 Rails 3.2.22.5
Question 6: Are you using a PaaS and/or containerization? If so which one? No
Question 7: Anything else about your setup that we should know? No