passenger_version: 4.0.44 gets ruby exception on startup and keeps going

[Tony Primerano]

I'm running passenger_version: 4.0.44 on redhat and I recently noticed that anytime it spawns a rails app it gets an exception but it doesn't seem to stop it from running.

The machine has Ruby 1.8, 1.9 and 2.1 and from the looks of it, it is reading from a 1.8 directory.


App 4882 stderr: /opt/ruby2/lib/ruby/gems/2.1.0/gems/bundler-1.6.2/lib/bundler/rubygems_integration.rb:366: warning: parenthesize argument(s) for future version
App 4882 stderr: /opt/ruby2/lib/ruby/gems/2.1.0/gems/bundler-1.6.2/lib/bundler/rubygems_integration.rb:8:in `version'
App 4882 stderr: : uninitialized constant Gem::VERSION (NameError)
App 4882 stderr:     from /opt/ruby2/lib/ruby/gems/2.1.0/gems/bundler-1.6.2/lib/bundler/rubygems_integration.rb:12:in `provides?'
App 4882 stderr:     from /opt/ruby2/lib/ruby/gems/2.1.0/gems/bundler-1.6.2/lib/bundler/rubygems_integration.rb:555
App 4882 stderr:     from /usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:31:in `gem_original_require'
App 4882 stderr:     from /usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:31:in `require'
App 4882 stderr:     from /opt/ruby2/lib/ruby/gems/2.1.0/gems/bundler-1.6.2/lib/bundler/shared_helpers.rb:5
App 4882 stderr:     from /opt/ruby2/lib/ruby/gems/2.1.0/gems/bundler-1.6.2/lib/bundler/setup.rb:1:in `require'
App 4882 stderr:     from /opt/ruby2/lib/ruby/gems/2.1.0/gems/bundler-1.6.2/lib/bundler/setup.rb:1

PassengerDefaultRuby /opt/ruby/bin/ruby   # this is our 1.9 ruby
PassengerRuby /opt/ruby2/bin/ruby # this is our 2.1 ruby and is what this app is running.
/usr/bin has ruby 1.8

Is the spawner detecting this exception and trying again?  The application starts fine but I'm wondering if this exception is slowing things down.

Here is the full log if useful.  (yes..  i know this machine is slow).

Thanks in advance for any help!
Tony


[ 2015-03-17 10:34:08.0751 32082/2b5be4da8940 Pool2/Group.h:1186 ]: Requested spawning of new process for group /var/www/rails_projects/msd/live#default
[ 2015-03-17 10:34:08.0756 32082/2b5be4da8940 Pool2/Implementation.cpp:1029 ]: Restart of group /var/www/rails_projects/msd/live#default done
[ 2015-03-17 10:34:08.0757 32082/2b5be4a82940 Pool2/SmartSpawner.h:736 ]: Spawning new process: appRoot=/var/www/rails_projects/msd/live
[ 2015-03-17 10:34:08.0758 32082/2b5be4a82940 Pool2/SmartSpawner.h:206 ]: Spawning new preloader: appRoot=/var/www/rails_projects/msd/live
[ 2015-03-17 10:34:08.0810 32082/2b5be4a82940 Pool2/SmartSpawner.h:252 ]: Preloader process forked for appRoot=/var/www/rails_projects/msd/live: PID 4882
[ 2015-03-17 10:34:08.1445 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
App 4882 stdout:
[ 2015-03-17 10:34:08.2820 32082/2b5be4a82940 Pool2/Spawner.h:787 ]: [App 4882 stdout] !  I have control 1.0
[ 2015-03-17 10:34:08.2824 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin   ] You have control 1.0
[ 2015-03-17 10:34:08.2825 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin   ] passenger_root: /var/appl/httpd/passenger/passenger4
[ 2015-03-17 10:34:08.2825 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin   ] ruby_libdir: /var/appl/httpd/passenger/passenger4/lib
[ 2015-03-17 10:34:08.2826 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin   ] passenger_version: 4.0.44
[ 2015-03-17 10:34:08.2826 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin   ] generation_dir: /tmp/passenger.1.0.8358/generation-3
[ 2015-03-17 10:34:08.2826 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin   ] app_root: /var/www/rails_projects/msd/live
[ 2015-03-17 10:34:08.2827 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin   ] app_group_name: /var/www/rails_projects/msd/live
[ 2015-03-17 10:34:08.2827 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin   ] app_type: rack
[ 2015-03-17 10:34:08.2828 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin   ] start_command: /opt/ruby2/bin/ruby    /var/appl/httpd/passenger/passenger4/helper-scripts/rack-loader.rb
[ 2015-03-17 10:34:08.2828 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin   ] startup_file: config.ru
[ 2015-03-17 10:34:08.2828 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin   ] process_title: Passenger RackApp
[ 2015-03-17 10:34:08.2829 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin   ] log_level: 7
[ 2015-03-17 10:34:08.2829 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin   ] start_timeout: 90000
[ 2015-03-17 10:34:08.2829 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin   ] environment: www_dev
[ 2015-03-17 10:34:08.2830 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin   ] base_uri: /rails/var/msd
[ 2015-03-17 10:34:08.2830 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin   ] spawn_method: smart
[ 2015-03-17 10:34:08.2830 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin   ] default_user: nobody
[ 2015-03-17 10:34:08.2831 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin   ] default_group: nobody
[ 2015-03-17 10:34:08.2831 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin   ] ruby: /opt/ruby2/bin/ruby
[ 2015-03-17 10:34:08.2832 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin   ] python: python
[ 2015-03-17 10:34:08.2832 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin   ] nodejs: node
[ 2015-03-17 10:34:08.2832 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin   ] logging_agent_address: unix:/tmp/passenger.1.0.8358/generation-3/logging
[ 2015-03-17 10:34:08.2833 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin   ] logging_agent_username: logging
[ 2015-03-17 10:34:08.2833 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin   ] logging_agent_password: SzXMwjsZI9jeVijzSsCIhMc3EDZnzIQED87y6hpTE19bNNyLg6PtHapdxUGzAHHy
[ 2015-03-17 10:34:08.2833 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin   ] debugger: false
[ 2015-03-17 10:34:08.2834 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin   ] analytics: false
[ 2015-03-17 10:34:08.2834 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin   ]
[ 2015-03-17 10:34:08.4421 32082/2b5bdf0c5940 Pool2/Pool.h:676 ]: Garbage collection time...
[ 2015-03-17 10:34:08.4424 32082/2b5bdf0c5940 Pool2/Pool.h:660 ]: Garbage collect idle spawner: group=/var/www/rails_projects/cfp/live#default
[ 2015-03-17 10:34:08.4425 32082/2b5bdf0c5940 Pool2/Pool.h:725 ]: Garbage collection done; next garbage collect in 190.515 sec
[ 2015-03-17 10:34:11.0005 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:34:11.0506 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.949 sec
[ 2015-03-17 10:34:13.1464 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:34:16.0013 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:34:16.0546 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.945 sec
[ 2015-03-17 10:34:18.1452 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:34:21.0011 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:34:21.0523 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.948 sec
[ 2015-03-17 10:34:23.1451 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:34:26.0010 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:34:26.0506 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.949 sec
[ 2015-03-17 10:34:28.1449 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:34:31.0008 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:34:31.0513 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.949 sec
[ 2015-03-17 10:34:33.1448 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:34:36.0016 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:34:36.0505 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.950 sec
[ 2015-03-17 10:34:38.1446 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:34:41.0015 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:34:41.0514 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.949 sec
[ 2015-03-17 10:34:43.1445 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:34:46.0013 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:34:46.0502 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.950 sec
[ 2015-03-17 10:34:48.1444 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:34:51.0012 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:34:51.0497 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.950 sec
[ 2015-03-17 10:34:53.1451 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:34:56.0020 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:34:56.0529 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.947 sec
App 4882 stderr: /opt/ruby2/lib/ruby/gems/2.1.0/gems/bundler-1.6.2/lib/bundler/rubygems_integration.rb:366: warning: parenthesize argument(s) for future version
App 4882 stderr: /opt/ruby2/lib/ruby/gems/2.1.0/gems/bundler-1.6.2/lib/bundler/rubygems_integration.rb:8:in `version'
App 4882 stderr: : uninitialized constant Gem::VERSION (NameError)
App 4882 stderr:     from /opt/ruby2/lib/ruby/gems/2.1.0/gems/bundler-1.6.2/lib/bundler/rubygems_integration.rb:12:in `provides?'
App 4882 stderr:     from /opt/ruby2/lib/ruby/gems/2.1.0/gems/bundler-1.6.2/lib/bundler/rubygems_integration.rb:555
App 4882 stderr:     from /usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:31:in `gem_original_require'
App 4882 stderr:     from /usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:31:in `require'
App 4882 stderr:     from /opt/ruby2/lib/ruby/gems/2.1.0/gems/bundler-1.6.2/lib/bundler/shared_helpers.rb:5
App 4882 stderr:     from /opt/ruby2/lib/ruby/gems/2.1.0/gems/bundler-1.6.2/lib/bundler/setup.rb:1:in `require'
App 4882 stderr:     from /opt/ruby2/lib/ruby/gems/2.1.0/gems/bundler-1.6.2/lib/bundler/setup.rb:1
[ 2015-03-17 10:34:58.1329 32082/2b5be4a82940 Pool2/Spawner.h:787 ]: [App 4882 stdout] !  Ready
[ 2015-03-17 10:34:58.1330 32082/2b5be4a82940 Pool2/Spawner.h:787 ]: [App 4882 stdout] !  socket: unix:/tmp/passenger.1.0.8358/generation-3/backends/preloader.4882
[ 2015-03-17 10:34:58.1330 32082/2b5be4a82940 Pool2/Spawner.h:787 ]: [App 4882 stdout] ! 
[ 2015-03-17 10:34:58.1344 32082/2b5be4a82940 Pool2/SmartSpawner.h:297 ]: Preloader for /var/www/rails_projects/msd/live started on PID 4882, listening on unix:/tmp/passenger.1.0.8358/generation-3/backends/preloader.4882
[ 2015-03-17 10:34:58.1450 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:34:58.2781 32082/2b5be4a82940 Pool2/Spawner.h:787 ]: [App 4984 stdout] !  I have control 1.0
[ 2015-03-17 10:34:58.2784 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin   ] You have control 1.0
[ 2015-03-17 10:34:58.2785 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin   ] passenger_root: /var/appl/httpd/passenger/passenger4
[ 2015-03-17 10:34:58.2785 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin   ] passenger_version: 4.0.44
[ 2015-03-17 10:34:58.2786 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin   ] ruby_libdir: /var/appl/httpd/passenger/passenger4/lib
[ 2015-03-17 10:34:58.2786 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin   ] generation_dir: /tmp/passenger.1.0.8358/generation-3
[ 2015-03-17 10:34:58.2786 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin   ] gupid: 16acdca-w2yaQWoXaag
[ 2015-03-17 10:34:58.2787 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin   ] connect_password: 1gHzKypLukttxP05QJ0bUN5WZUBInnlfdMgGFgBIypC
[ 2015-03-17 10:34:58.2787 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin   ] app_root: /var/www/rails_projects/msd/live
[ 2015-03-17 10:34:58.2788 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin   ] app_group_name: /var/www/rails_projects/msd/live
[ 2015-03-17 10:34:58.2788 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin   ] app_type: rack
[ 2015-03-17 10:34:58.2788 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin   ] start_command: /opt/ruby2/bin/ruby    /var/appl/httpd/passenger/passenger4/helper-scripts/rack-loader.rb
[ 2015-03-17 10:34:58.2789 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin   ] startup_file: config.ru
[ 2015-03-17 10:34:58.2789 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin   ] process_title: Passenger RackApp
[ 2015-03-17 10:34:58.2790 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin   ] log_level: 7
[ 2015-03-17 10:34:58.2790 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin   ] start_timeout: 90000
[ 2015-03-17 10:34:58.2791 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin   ] environment: www_dev
[ 2015-03-17 10:34:58.2791 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin   ] base_uri: /rails/var/msd
[ 2015-03-17 10:34:58.2791 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin   ] spawn_method: smart
[ 2015-03-17 10:34:58.2792 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin   ] default_user: nobody
[ 2015-03-17 10:34:58.2792 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin   ] default_group: nobody
[ 2015-03-17 10:34:58.2793 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin   ] ruby: /opt/ruby2/bin/ruby
[ 2015-03-17 10:34:58.2793 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin   ] python: python
[ 2015-03-17 10:34:58.2794 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin   ] nodejs: node
[ 2015-03-17 10:34:58.2794 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin   ] logging_agent_address: unix:/tmp/passenger.1.0.8358/generation-3/logging
[ 2015-03-17 10:34:58.2794 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin   ] logging_agent_username: logging
[ 2015-03-17 10:34:58.2795 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin   ] logging_agent_password: SzXMwjsZI9jeVijzSsCIhMc3EDZnzIQED87y6hpTE19bNNyLg6PtHapdxUGzAHHy
[ 2015-03-17 10:34:58.2796 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin   ] debugger: false
[ 2015-03-17 10:34:58.2796 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin   ] analytics: false
[ 2015-03-17 10:34:58.2796 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin   ] group_secret: JQ74lIPgf3S4gtka1dxsH5ozD3Ueli6D25A6tryCG6m
[ 2015-03-17 10:34:58.2797 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin   ]
App 4984 stdout:
[ 2015-03-17 10:34:58.2865 32082/2b5be4a82940 Pool2/Spawner.h:787 ]: [App 4984 stdout] !  Ready
[ 2015-03-17 10:34:58.2865 32082/2b5be4a82940 Pool2/Spawner.h:787 ]: [App 4984 stdout] !  socket: main;unix:/tmp/passenger.1.0.8358/generation-3/backends/ruby.6iPAX2V969RDNnZsHSskeXS5A2dmWPXwpMgHqobRRQgTt1V;session;1
[ 2015-03-17 10:34:58.2867 32082/2b5be4a82940 Pool2/Spawner.h:787 ]: [App 4984 stdout] !  socket: http;tcp://127.0.0.1:51631;http;1
[ 2015-03-17 10:34:58.2867 32082/2b5be4a82940 Pool2/Spawner.h:787 ]: [App 4984 stdout] ! 
[ 2015-03-17 10:34:58.2870 32082/2b5be4a82940 Pool2/SmartSpawner.h:771 ]: Process spawning done: appRoot=/var/www/rails_projects/msd/live, pid=4984
[ 2015-03-17 10:34:58.2872 32082/2b5be4a82940 Pool2/Group.h:989 ]: Attaching process (pid=4984, group=/var/www/rails_projects/msd/live#default)
[ 2015-03-17 10:34:58.2873 32082/2b5be4a82940 Pool2/Implementation.cpp:870 ]: New process count = 1, remaining get waiters = 0
[ 2015-03-17 10:34:58.2874 32082/2b5be4a82940 Pool2/Implementation.cpp:898 ]: Spawn loop done
[ 2015-03-17 10:34:58.2876 32082/2b5bdf0c5940 Pool2/Pool.h:676 ]: Garbage collection time...
[ 2015-03-17 10:34:58.2878 32082/2b5be4a00940 agents/HelperAgent/RequestHandler.h:2168 ]: [Client 23] Event: sessionCheckedOut
[ 2015-03-17 10:34:58.2879 32082/2b5be4a00940 agents/HelperAgent/RequestHandler.h:2196 ]: [Client 23] Session checked out: pid=4984, gupid=16acdca-w2yaQWoXaag
[ 2015-03-17 10:34:58.2880 32082/2b5be4a00940 Pool2/Socket.h:85 ]: Connecting to unix:/tmp/passenger.1.0.8358/generation-3/backends/ruby.6iPAX2V969RDNnZsHSskeXS5A2dmWPXwpMgHqobRRQgTt1V
[ 2015-03-17 10:34:58.2879 32082/2b5bdf0c5940 Pool2/Pool.h:725 ]: Garbage collection done; next garbage collect in 140.670 sec
[ 2015-03-17 10:34:58.2885 32082/2b5be4a00940 agents/HelperAgent/RequestHandler.h:2291 ]: [Client 23] Session initiated: fd=30
[ 2015-03-17 10:34:58.2886 32082/2b5be4a00940 EventedBufferedInput.h:361 ]: [EventedBufferedInput 0x2b5be0006ea0 fd=-1, state=LIVE, buffer(0)="", paused=1, socketPaused=1, nextTickInstalled=0, generation=1, error=0] reset()
[ 2015-03-17 10:34:58.2886 32082/2b5be4a00940 EventedBufferedInput.h:381 ]: [EventedBufferedInput 0x2b5be0006ea0 fd=30, state=LIVE, buffer(0)="", paused=1, socketPaused=1, nextTickInstalled=0, generation=2, error=0] start()
[ 2015-03-17 10:34:58.2887 32082/2b5be4a00940 agents/HelperAgent/RequestHandler.h:2312 ]: [Client 23] Sending headers to application
[ 2015-03-17 10:34:58.2888 32082/2b5be4a00940 agents/HelperAgent/RequestHandler.h:2458 ]: [Client 23] Begin sending body to application
[ 2015-03-17 10:34:58.2889 32082/2b5be4a00940 agents/HelperAgent/RequestHandler.h:2528 ]: [Client 23] End of (unbuffered) client body reached; done sending data to application
App 4882 stderr: [ 2015-03-17 10:34:58.2870 4984/0x002af6e694a798(Main thread) request_handler.rb:181 ]: Entering request handler main loop
App 4882 stderr: [ 2015-03-17 10:34:58.3279 4984/0x002af6e69192d8(Worker 1) request_handler/thread_handler.rb:131 ]: Accepted new request on socket main socket
[ 2015-03-17 10:35:01.0019 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:35:01.0725 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.928 sec
[ 2015-03-17 10:35:03.1448 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:35:06.0007 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:35:06.0741 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.926 sec
[ 2015-03-17 10:35:08.1447 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:35:11.0006 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:35:11.0733 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.927 sec
[ 2015-03-17 10:35:13.1445 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:35:16.0014 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:35:16.0642 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.936 sec
[ 2015-03-17 10:35:18.1444 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:35:21.0012 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:35:21.0738 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.926 sec
[ 2015-03-17 10:35:23.1443 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:35:26.0011 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:35:26.0746 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.925 sec
[ 2015-03-17 10:35:28.1450 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:35:31.0009 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:35:31.0745 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.926 sec
[ 2015-03-17 10:35:33.1449 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:35:36.0018 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:35:36.0713 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.929 sec
[ 2015-03-17 10:35:38.1448 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:35:41.0016 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:35:41.0751 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.925 sec
[ 2015-03-17 10:35:43.1446 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:35:46.0014 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:35:46.0670 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.933 sec
[ 2015-03-17 10:35:48.1444 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks


 

[Hongli Lai]

That looks like a Ruby installation problem to me. Gem::VERSION should
always be available. Maybe your install is broken.

> --
> You received this message because you are subscribed to the Google Groups
> "Phusion Passenger Discussions" group.
> To unsubscribe from this group and stop receiving emails from it, send an
> email to phusion-passen...@googlegroups.com.
> To post to this group, send email to phusion-...@googlegroups.com.
> Visit this group at http://groups.google.com/group/phusion-passenger.
> To view this discussion on the web visit
> https://groups.google.com/d/msgid/phusion-passenger/5b4fe4dc-22d0-42f3-983c-0385bfd5844c%40googlegroups.com.
> For more options, visit https://groups.google.com/d/optout.



--
Phusion | Web Application deployment, scaling, and monitoring solutions

Web: http://www.phusion.nl/
E-mail: in...@phusion.nl
Chamber of commerce no: 08173483 (The Netherlands)

[Tony Primerano]

Can you explain how passenger is recovering from this error?  

My rails applications continue to start fine after this error.   Does passenger catch the error and adjust the GEM_PATH?

More info.. 

The system installed ruby is 1.8.5.   does that pre-date Gem::VERSION?  (as mentioned I have PassengerRuby set to 2.1 and PassengerDefaultRuby is on 1.9)

Here is the system irb/ruby that we do not use

 /usr/bin/irb --version
irb 0.9.5(05/04/13)
addlx1: /add/lib% /usr/bin/irb
irb(main):001:0> RUBY_VERSION
=> "1.8.5"
irb(main):002:0> Gem::VERSION
NameError: uninitialized constant Gem
        from (irb):2

Here is our ruby 2.1 version that PassengerRuby uses - PassengerRuby /opt/ruby2/bin/ruby
/opt/ruby2/bin/irb
addlx1: /add/lib% /opt/ruby2/bin/irb
irb(main):001:0> RUBY_VERSION
=> "2.1.2"
irb(main):002:0>  Gem::VERSION
=> "2.2.2"

It seems like passenger is reaching into the 1.8.6 code based on the backtrace.

/usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:31

[Hongli Lai]

On Fri, Mar 20, 2015 at 3:44 PM, Tony Primerano <prim...@tonycode.com> wrote:
> Can you explain how passenger is recovering from this error?

I do not know. This should have been an unrecoverable error.

> My rails applications continue to start fine after this error. Does
> passenger catch the error and adjust the GEM_PATH?

No.

> More info..
>
> The system installed ruby is 1.8.5. does that pre-date Gem::VERSION? (as
> mentioned I have PassengerRuby set to 2.1 and PassengerDefaultRuby is on
> 1.9)

Passenger is configured in such a way that Ruby 1.8.5 is never used,
so that could not have been related.

> /usr/bin/irb --version
> irb 0.9.5(05/04/13)
> addlx1: /add/lib% /usr/bin/irb
> irb(main):001:0> RUBY_VERSION
> => "1.8.5"
> irb(main):002:0> Gem::VERSION
> NameError: uninitialized constant Gem
> from (irb):2

In version 1.8.5 you need to "require 'rubgyems'" first.

[Tony Primerano]

On Friday, March 20, 2015 at 10:48:21 AM UTC-4, Hongli Lai wrote:

On Fri, Mar 20, 2015 at 3:44 PM, Tony Primerano <prim...@tonycode.com> wrote:
> Can you explain how passenger is recovering from this error?

I do not know. This should have been an unrecoverable error.

Maybe it is hitting this block in SmartSpawner.h

   writeExact(details.adminSocket, data, &details.timeout);
         writeExact(details.adminSocket, "\n", &details.timeout);
      } catch (const SystemException &e) {
         if (e.code() == EPIPE) {
            /* Ignore this. Process might have written an
             * error response before reading the arguments,
             * in which case we'll want to show that instead.
             */


 

> My rails applications continue to start fine after this error.   Does
> passenger catch the error and adjust the GEM_PATH?

No.


> More info..
>
> The system installed ruby is 1.8.5.   does that pre-date Gem::VERSION?  (as
> mentioned I have PassengerRuby set to 2.1 and PassengerDefaultRuby is on
> 1.9)

Passenger is configured in such a way that Ruby 1.8.5 is never used,
so that could not have been related.


>  /usr/bin/irb --version
> irb 0.9.5(05/04/13)
> addlx1: /add/lib% /usr/bin/irb
> irb(main):001:0> RUBY_VERSION
> => "1.8.5"
> irb(main):002:0> Gem::VERSION
> NameError: uninitialized constant Gem
>         from (irb):2

In version 1.8.5 you need to "require 'rubgyems'" first.

This seems to pre-date rubygems 1.3.1 but I'm still not sure why it would be looking there.  :-)

/usr/bin/gem --version
1.3.1
addlx1: /add/home/m1abp00% /usr/bin/irb
irb(main):001:0> require 'rubygems'
=> true

irb(main):002:0> Gem::VERSION

NameError: uninitialized constant Gem::VERSION
        from (irb):2

Thanks for all your pointers up to this point..    Maybe I should get our ops guys to install Passenger 5!

[Tony Primerano]

Still stumped on this..

The preloader gives the error but continues and the mail process spawns correctly.  

11898 33.8  0.2 218312 89412 ?        Sl   11:47   0:17 Passenger AppPreloader: /add/www/rails_projects/cfp//live
11959  0.7  0.2 287864 86260 ?        Sl   11:48   0:00 Passenger RackApp: /add/www/rails_projects/cfp/live

ps  xo pid,ppid,pgid,sid,comm | grep -i ruby
10365     1 25386 25383 ruby
11898 25386 25386 25383 ruby   -- This is the preloader
11959 11898 25386 25383 ruby   -- this is is spawn
16264 15831 16264 15831 ruby
28831     1 25386 25383 ruby

After a few minutes the preloader does go away and 11959 is owned by 1/init.


I've even run
 /opt/ruby2/bin/ruby /var/appl/httpd/passenger/passenger4/helper-scripts/rack-loader.rb
directly and injected the commands to start the preloader with no issues. 

I updated my path to have the ruby 1.8 version 1st which I thought might be the issue but it still works.   

since my apps are still running I'm going to move on unless you have something you would like me to try.    I don't think upgrading to 5 is going to happen until later this year for us.

Thanks
Tony





There are no errors with the application and I can't seem to reproduce this