Cannot checkout session An error occured while starting up the preloader

[Justin Patterson]

Hi,  I’m having a strange issue that appears to be tied to logroate with Passenger.   I’ve upgraded everything associated with the project but still encounter this error.

Passenger 4.0.5

Apache/2.2.15

Rvm 1.20.13

 

The problem occurs daily and here is the error in passenger_debug.log 

[ 2013-06-19 04:41:50.4874 5612/7fbc25204700 agents/HelperAgent/RequestHandler.h:1889 ]: [Client 22] Cannot checkout session. An error occured while starting up the preloader.

Error page:

Could not find i18n-0.6.4 in any of the sources (Bundler::GemNotFound)

  /home/localruby/.rvm/gems/ruby-1.9.3-p429@global/gems/bundler-1.3.5/lib/bundler/spec_set.rb:92:in `block in materialize'

  /home/localruby/.rvm/gems/ruby-1.9.3-p429@global/gems/bundler-1.3.5/lib/bundler/spec_set.rb:85:in `map!'

  /home/localruby/.rvm/gems/ruby-1.9.3-p429@global/gems/bundler-1.3.5/lib/bundler/spec_set.rb:85:in `materialize'

  /home/localruby/.rvm/gems/ruby-1.9.3-p429@global/gems/bundler-1.3.5/lib/bundler/definition.rb:114:in `specs'

  /home/localruby/.rvm/gems/ruby-1.9.3-p429@global/gems/bundler-1.3.5/lib/bundler/definition.rb:159:in `specs_for'

  /home/localruby/.rvm/gems/ruby-1.9.3-p429@global/gems/bundler-1.3.5/lib/bundler/definition.rb:148:in `requested_specs'

  /home/localruby/.rvm/gems/ruby-1.9.3-p429@global/gems/bundler-1.3.5/lib/bundler/environment.rb:18:in `requested_specs'

  /home/localruby/.rvm/gems/ruby-1.9.3-p429@global/gems/bundler-1.3.5/lib/bundler/runtime.rb:13:in `setup'

  /home/localruby/.rvm/gems/ruby-1.9.3-p429@global/gems/bundler-1.3.5/lib/bundler.rb:120:in `setup'

  /home/localruby/.rvm/gems/ruby-1.9.3-p429@global/gems/bundler-1.3.5/lib/bundler/setup.rb:17:in `<top (required)>'

  /home/localruby/.rvm/rubies/ruby-1.9.3-p429/lib/ruby/site_ruby/1.9.1/rubygems/custom_require.rb:60:in `require'

  /home/localruby/.rvm/rubies/ruby-1.9.3-p429/lib/ruby/site_ruby/1.9.1/rubygems/custom_require.rb:60:in `rescue in require'

  /home/localruby/.rvm/rubies/ruby-1.9.3-p429/lib/ruby/site_ruby/1.9.1/rubygems/custom_require.rb:35:in `require'

  /home/localruby/.rvm/gems/ruby-1....@redmine-2.2.3/gems/passenger-4.0.5/lib/phusion_passenger/loader_shared_helpers.rb:212:in `run_load_path_setup_code'

  /home/localruby/.rvm/gems/ruby-1....@redmine-2.2.3/gems/passenger-4.0.5/helper-scripts/rack-preloader.rb:73:in `preload_app'

  /home/localruby/.rvm/gems/ruby-1....@redmine-2.2.3/gems/passenger-4.0.5/helper-scripts/rack-preloader.rb:127:in `<module:App>'

  /home/localruby/.rvm/gems/ruby-1....@redmine-2.2.3/gems/passenger-4.0.5/helper-scripts/rack-preloader.rb:6:in `<module:PhusionPassenger>'

  /home/localruby/.rvm/gems/ruby-1....@redmine-2.2.3/gems/passenger-4.0.5/helper-scripts/rack-preloader.rb:5:in `<main>'

 

[ 2013-06-19 04:46:50.1980 5612/7fbc247c2700 Pool2/Spawner.h:739 ]: [App 9189 stdout]

[ 2013-06-19 04:46:50.3672 5612/7fbc247c2700 Pool2/Implementation.cpp:774 ]: Could not spawn process for group /var/www/redmine#default: An error occured while starting up the preloader.

     in 'void Passenger::ApplicationPool2::SmartSpawner::handleErrorResponse(Passenger::ApplicationPool2::SmartSpawner::StartupDetails&)' (SmartSpawner.h:455)

     in 'std::string Passenger::ApplicationPool2::SmartSpawner::negotiatePreloaderStartup(Passenger::ApplicationPool2::SmartSpawner::StartupDetails&)' (SmartSpawner.h:558)

     in 'void Passenger::ApplicationPool2::SmartSpawner::startPreloader()' (SmartSpawner.h:206)

     in 'virtual Passenger::ApplicationPool2::ProcessPtr Passenger::ApplicationPool2::SmartSpawner::spawn(const Passenger::ApplicationPool2::Options&)' (SmartSpawner.h:744)

     in 'void Passenger::ApplicationPool2::Group::spawnThreadRealMain(const Passenger::ApplicationPool2::SpawnerPtr&, const Passenger::ApplicationPool2::Options&, unsigned int)' (Implementation.cpp:707)

Here are the passenger configs:

LoadModule passenger_module /home/localruby/.rvm/gems/ruby-1....@redmine-2.2.3/gems/passenger-4.0.5/libout/apache2/mod_passenger.so

PassengerSpawnMethod smart

PassengerPoolIdleTime 1000

RailsAppSpawnerIdleTime 0

PassengerMaxRequests 5000

PassengerMinInstances 1

PassengerLogLevel 3

PassengerDebugLogFile /var/log/httpd/passenger_debug.log

 

Restarting apache fixes the problem, which is occurring daily at around 3:30 AM.

Any ideas as to what would cause this?

[Hongli Lai]

What happens if you manually trigger a logrotate, does that trigger
the problem too? Have you also checked
http://www.modrails.com/documentation/Users%20guide%20Apache.html#_caveats_amp_troubleshooting?

> --
> 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.
> For more options, visit https://groups.google.com/groups/opt_out.
>
>



--
Phusion | Ruby & Rails deployment, scaling and tuning solutions

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

[Justin Patterson]

Hongli, 

I can run logrotate manually and I haven't been able to reproduce it.  But logrotate happens nightly and most of the time it seems okay it is only certain times that it triggers it. It usually only occurs on Sunday mornings but not necessarily and always occurs though around 3:30 am.

The caveats didn't point to anything unfortunately, the application regularly runs it just fails during a certain time frame on a continual basis.

Any other ideas?

Thanks,
Justin

[Hongli Lai]

What is your PassengerRuby/PassengerDefaultRuby configuration?

On Thu, Jun 27, 2013 at 4:56 PM, Justin Patterson

[Justin Patterson]

Hongli,

Here are the directives:

    PassengerRoot /home/localruby/.rvm/gems/ruby-1....@redmine-2.2.3/gems/passenger-4.0.5
    PassengerRuby /home/localruby/.rvm/wrappers/ruby-1....@redmine-2.2.3/ruby

Thanks,
Justin

[Justin Patterson]

Hongli,

I have the debug value for the log set at PassengerLogLevel 3     The process died again yesterday after the lograte command was issued.  Is there somewhere I can send you the passenger_debug.log or a unique link to download it?   I can paste a subset of the log but I don't want to leave something out that might help track this down.  It happens nearly every week and when it does it always after this appears in the log:
[Sun Jun 30 03:33:12 2013] [notice] SIGHUP received.  Attempting to restart

For now I've attached a snippet of the log.


Thanks again for your help,
Justin

[Justin Patterson]

It happened again this past Sunday.  After logrotate passenger will not come back up, but it will last all week just fine.

[ 2013-07-07 03:08:48.0980 11126/7f3f82476700 Pool2/Implementation.cpp:774 ]: Could not spawn process for group /var/www/redmine#default: An error occured while starting up the preloader.

     in 'void Passenger::ApplicationPool2::SmartSpawner::handleErrorResponse(Passenger::ApplicationPool2::SmartSpawner::StartupDetails&)' (SmartSpawner.h:455)
     in 'std::string Passenger::ApplicationPool2::SmartSpawner::negotiatePreloaderStartup(Passenger::ApplicationPool2::SmartSpawner::StartupDetails&)' (SmartSpawner.h:558)
     in 'void Passenger::ApplicationPool2::SmartSpawner::startPreloader()' (SmartSpawner.h:206)
     in 'virtual Passenger::ApplicationPool2::ProcessPtr Passenger::ApplicationPool2::SmartSpawner::spawn(const Passenger::ApplicationPool2::Options&)' (SmartSpawner.h:744)
     in 'void Passenger::ApplicationPool2::Group::spawnThreadRealMain(const Passenger::ApplicationPool2::SpawnerPtr&, const Passenger::ApplicationPool2::Options&, unsigned int)' (Implementation.cpp:707)

[ 2013-07-07 03:08:48.1049 11126/7f3f82476700 Pool2/Group.h:445 ]: Enabling all DISABLING processes with result DR_ERROR
[ 2013-07-07 03:08:48.1049 11126/7f3f82476700 Pool2/Implementation.cpp:793 ]: Spawn loop done
[ 2013-07-07 03:08:48.1051 11126/7f3f82eb8700 agents/HelperAgent/RequestHandler.h:1889 ]: [Client 20] Cannot checkout session. An error occured while starting up the preloader.

[Hongli Lai]

Sorry for the late reply. If you want to send confidential data, you can email me directly or you can encrypt the attachment using my public key: http://www.phusion.nl/about/gpg

As for your problem: I do not see anything interesting in the logs. But one of the most common problems by you get a "Could not find XXX in any of the sources (Bundler::GemNotFound)" is because of permission problems: your application is unable to access the gems in the Bundler gem directory.

You can find the location of the Bundler gem directory in the file .bundle/config. If the file does not exist, then that means Bundler will lookup its gems from the Ruby gem directory (which you can lookup with `gem env`).

So what you need to do is to verify whether your application is running as the right user after a logrotate, and whether that user has access to the Bundler gem directory. At this time, the only place where Phusion Passenger displays information about the process's environment (user account etc) is in the Phusion Passenger browser error page. They're not displayed in the logs. Can you let the problem occur, then visit the web app, then look at the error page to find out what user the app was running as, and verify whether that's correct?

On Mon, Jul 1, 2013 at 5:41 PM, Justin Patterson <justinrp...@gmail.com> wrote:

Hongli,

I have the debug value for the log set at PassengerLogLevel 3     The process died again yesterday after the lograte command was issued.  Is there somewhere I can send you the passenger_debug.log or a unique link to download it?   I can paste a subset of the log but I don't want to leave something out that might help track this down.  It happens nearly every week and when it does it always after this appears in the log:
[Sun Jun 30 03:33:12 2013] [notice] SIGHUP received.  Attempting to restart

For now I've attached a snippet of the log.