Redmine Outage - Urgent help required

Added by Rupesh Helwade over 5 years ago

Hello

We have encountered amajor problem in production where I am getting following error.
Any help would be highly apreciated.

=================================================================================

[ 2014-06-25 19:53:02.5092 2395/b5a9ab40 Pool2/Implementation.cpp:762 ]:
Could not spawn process for group /opt/Redmine/apps/redmine/htdocs#default: An error occurred while starting up the preloader: it did not write a handshake message in time.
in 'void Passenger::ApplicationPool2::SmartSpawner::throwPreloaderSpawnException(const std::string&, Passenger::SpawnException::ErrorKind, boost::shared_ptr<Passenger::ApplicationPool2::Spawner::BackgroundIOCapturer>&, const boost::shared_ptr<Passenger::ApplicationPool2::Spawner::DebugDir>&)' (SmartSpawner.h:149)
in 'std::string Passenger::ApplicationPool2::SmartSpawner::negotiatePreloaderStartup(Passenger::ApplicationPool2::SmartSpawner::StartupDetails&)' (SmartSpawner.h:539)
in 'void Passenger::ApplicationPool2::SmartSpawner::startPreloader()' (SmartSpawner.h:205)
in 'virtual Passenger::ApplicationPool2::ProcessPtr Passenger::ApplicationPool2::SmartSpawner::spawn(const Passenger::ApplicationPool2::Options&)' (SmartSpawner.h:743)
in 'void Passenger::ApplicationPool2::Group::spawnThreadRealMain(const Passenger::ApplicationPool2::SpawnerPtr&, const Passenger::ApplicationPool2::Options&, unsigned int)' (Implementation.cpp:695)

[ 2014-06-25 19:53:02.5098 2395/b62dcb40 agents/HelperAgent/RequestHandler.h:1884 ]: [Client 23] Cannot checkout session. An error occurred while starting up the preloader: it did not write a handshake message in time.
[ 2014-06-25 19:53:02.5099 2395/b62dcb40 agents/HelperAgent/RequestHandler.h:1884 ]: [Client 24] Cannot checkout session. An error occurred while starting up the preloader: it did not write a handshake message in time.
[ 2014-06-25 19:53:02.5100 2395/b62dcb40 agents/HelperAgent/RequestHandler.h:1884 ]: [Client 27] Cannot checkout session. An error occurred while starting up the preloader: it did not write a handshake message in time. ========================================================================

Replies (11)

RE: Redmine Outage - Urgent help required - Added by Rupesh Helwade over 5 years ago

Ruby : ruby 1.9.3p429 (2013-05-15 revision 40747) [i686-linux]

passenger version
4.0.2

OS :
Linux 3.3.4-5.fc17.i686.PAE #1 SMP Mon May 7 17:37:39 UTC 2012 i686 i686 i386 GNU/Linux

APache
Server version: Apache/2.2.22 (Unix)

Redmine: 2.3.1 stable

rails (3.2.13)

RE: Redmine Outage - Urgent help required - Added by Jan Niggemann (redmine.org team member) over 5 years ago

Hmm, your versions look OK...
Messed up config.ru? Have you redirected stdout? Is the shell of the passenger user bash or something else?
If the server is very busy you might need to increase the timeout.

Perhaps the passenger developers can help you better than we can...

Have you tried restarting apache?

RE: Redmine Outage - Urgent help required - Added by Rupesh Helwade over 5 years ago

Hi,
It was runing OK and sudenly got down.
follwoing is config.ru and I never changed it myself.


  1. This file is used by Rack-based servers to start the application.
    require ::File.expand_path('../config/environment', FILE)
    map ActionController::Base.config.try(:relative_url_root) || "/" do
    run RedmineApp::Application
    end
    -------------------------------------
    Have you redirected stdout? - No
    Is the shell of the passenger user bash or something else? No Idea
    If the server is very busy you might need to increase the timeout. Could you help how could I do this ?

I also increased RAM to 4GB from 2GB, restarted machine - uninstaled aplication and instaled it using bitnami stacks.

But still I am geting the same eror mesage.
The apache2/logs/error_log shows following content

[Sun Jun 29 13:56:03.824641 2014] [ssl:warn] [pid 8828] AH01909: RSA certificate configured for www.exam ple.com:8443 does NOT include an ID which matches the server name
[ 2014-06-29 13:56:03.8364 8832/b76cc700 agents/HelperAgent/Main.cpp:554 ]: PassengerHelperAgent online, listening at unix:/tmp/passenger.1.0.8828/generation-0/request.socket
[ 2014-06-29 13:56:03.8439 8837/b740f700 agents/LoggingAgent/Main.cpp:272 ]: PassengerLoggingAgent online, listening at unix:/tmp/passenger.1.0.8828/generation-0/logging.socket
[Sun Jun 29 13:56:04.032237 2014] [ssl:warn] [pid 8848] AH01909: RSA certificate configured for ww w.example.com:8443 does NOT include an ID which matches the server name
[Sun Jun 29 13:56:04.032378 2014] [lbmethod_heartbeat:notice] [pid 8848] AH02282: No slotmem from mod_heartmonitor
[ 2014-06-29 13:56:04.0632 8853/b7660700 agents/HelperAgent/Main.cpp:554 ]: PassengerHelperAgent online, listening at unix:/tmp/passenger.1.0.8848/generation-0/request.socket
[ 2014-06-29 13:56:04.0662 8858/b7332700 agents/LoggingAgent/Main.cpp:272 ]: PassengerLoggingAgent online, listening at unix:/tmp/passenger.1.0.8848/generation-0/logging.socket
[Sun Jun 29 13:56:04.068767 2014] [mpm_prefork:notice] [pid 8848] AH00163: Apache/2.4.4 (Unix) OpenSSL/1.0.1e PHP/5.4.15 Phusion_Passenger/4.0.2 configured -- resuming normal operations
[Sun Jun 29 13:56:04.068837 2014] [core:notice] [pid 8848] AH00094: Command line: '/opt/Redmine/apache2/bin/httpd f /opt/Redmine/apache2/conf/httpd.conf'
[Sun Jun 29 13:57:34.612912 2014] [mpm_prefork:notice] [pid 8848] AH00169: caught SIGTERM, shutting down
[Sun Jun 29 13:57:38.861313 2014] [ssl:warn] [pid 9034] AH01909: RSA certificate configured for w ww.example.com:8443 does NOT include an ID which matches the server name
[ 2014-06-29 13:57:38.8736 9038/b767d700 agents/HelperAgent/Main.cpp:554 ]: PassengerHelperAgent online, listening at unix:/tmp/passenger.1.0.9034/generation-0/request.socket
[ 2014-06-29 13:57:38.8803 9043/b7386700 agents/LoggingAgent/Main.cpp:272 ]: PassengerLoggingAgent online, listening at unix:/tmp/passenger.1.0.9034/generation-0/logging.socket
[Sun Jun 29 13:57:39.046162 2014] [ssl:warn] [pid 9054] AH01909: RSA certificate configured for w ww.example.com:8443 does NOT include an ID which matches the server name
[Sun Jun 29 13:57:39.046296 2014] [lbmethod_heartbeat:notice] [pid 9054] AH02282: No slotmem from mod_heartmonitor
[ 2014-06-29 13:57:39.0736 9059/b7677700 agents/HelperAgent/Main.cpp:554 ]: PassengerHelperAgent online, listening at unix:/tmp/passenger.1.0.9054/generation-0/request.socket
[ 2014-06-29 13:57:39.0802 9064/b73a4700 agents/LoggingAgent/Main.cpp:272 ]: PassengerLoggingAgent online, listening at unix:/tmp/passenger.1.0.9054/generation-0/logging.socket
[Sun Jun 29 13:57:39.082762 2014] [mpm_prefork:notice] [pid 9054] AH00163: Apache/2.4.4 (Unix) OpenSSL/1.0.1e PHP/5.4.15 Phusion_Passenger/4.0.2 configured -
resuming normal operations
[Sun Jun 29 13:57:39.082832 2014] [core:notice] [pid 9054] AH00094: Command line: '/opt/Redmine/apache2/bin/httpd -f /opt/Redmine/apache2/conf/httpd.conf'
[ 2014-06-29 13:58:08.8984 9053/b76d7700 agents/Watchdog/Main.cpp:989 ]: Some Phusion Passenger agent processes did not exit in time, forcefully shutting down all.
[ 2014-06-29 14:00:40.9813 9059/b747db40 Pool2/Implementation.cpp:762 ]: Could not spawn process for group /opt/Redmine/apps/redmine/htdocs#default: An error occurred while starting up the preloader: it did not write a handshake message in time.

RE: Redmine Outage - Urgent help required - Added by Rupesh Helwade over 5 years ago

[admin@ubsdev bin]$ ./ passenger-status
bash: ./: Is a directory
[admin@ubsdev bin]$ ./passenger-status
  • Cleaning stale folder /tmp/passenger.1.0.4644
    ----------- General information -----------
    Max pool size : 6
    Processes : 0
    Requests in top-level queue : 0

----------- Application groups -----------
/opt/Redmine/apps/redmine/htdocs#default:
App root: /opt/Redmine/apps/redmine/htdocs
Requests in queue: 0

RE: Redmine Outage - Urgent help required - Added by Rupesh Helwade over 5 years ago

--------- Apache processes ---------
PID PPID VMSize Private Name
------------------------------------
9980 1 85.6 MB 3.2 MB /opt/Redmine/apache2/bin/httpd -f /opt/Redmine/apache2/conf/httpd.conf
10007 9980 85.6 MB 0.2 MB /opt/Redmine/apache2/bin/httpd -f /opt/Redmine/apache2/conf/httpd.conf
10008 9980 85.6 MB 0.2 MB /opt/Redmine/apache2/bin/httpd -f /opt/Redmine/apache2/conf/httpd.conf
10011 9980 86.9 MB 3.1 MB /opt/Redmine/apache2/bin/httpd -f /opt/Redmine/apache2/conf/httpd.conf
10053 9980 85.8 MB 0.9 MB /opt/Redmine/apache2/bin/httpd -f /opt/Redmine/apache2/conf/httpd.conf
10062 9980 85.6 MB 0.5 MB /opt/Redmine/apache2/bin/httpd -f /opt/Redmine/apache2/conf/httpd.conf
10063 9980 85.8 MB 0.9 MB /opt/Redmine/apache2/bin/httpd -f /opt/Redmine/apache2/conf/httpd.conf
10075 9980 85.6 MB 0.2 MB /opt/Redmine/apache2/bin/httpd -f /opt/Redmine/apache2/conf/httpd.conf
10076 9980 85.6 MB 0.2 MB /opt/Redmine/apache2/bin/httpd -f /opt/Redmine/apache2/conf/httpd.conf
10077 9980 85.6 MB 0.2 MB /opt/Redmine/apache2/bin/httpd -f /opt/Redmine/apache2/conf/httpd.conf
10082 9980 85.6 MB 0.2 MB /opt/Redmine/apache2/bin/httpd -f /opt/Redmine/apache2/conf/httpd.conf
  1. Processes: 11
  2. Total private dirty RSS: 9.84 MB

-------- Nginx processes --------

  1. Processes: 0
  2. Total private dirty RSS: 0.00 MB
---- Passenger processes ----
PID VMSize Private Name
-----------------------------
9990 8.0 MB 0.2 MB PassengerWatchdog
9993 33.9 MB 0.4 MB PassengerHelperAgent
9998 8.9 MB 0.4 MB PassengerLoggingAgent
  1. Processes: 3
  2. Total private dirty RSS: 0.98 MB
    [admin@ubsdev bin]$

RE: Redmine Outage - Urgent help required - Added by Jan Niggemann (redmine.org team member) over 5 years ago

Perhaps the passenger developers can help you better than we can...

RE: Redmine Outage - Urgent help required - Added by Rupesh Helwade over 5 years ago

Hi,
I posted on the forum of Passenger with following additional logs :
With the new log messages, they have again asked me to contact Redmine for more help as they say it is not the issue with passenger (Their reply attached)


Looking at the apache error_log file ( As Above )

I saw,
Command line: '/opt/Redmine/apache2/bin/httpd -f /opt/Redmine/apache2/conf/httpd.conf' created the problem.
I then tried to run it from terminal and saw that the necessary libs were not found by the command, hence I created the LIBPATH using ldconfig as suggested in (http://www.cyberciti.biz/faq/linux-setting-changing-library-path/)
This command now on terminal does not give those lib file not found messages, atleast.


After fixing the above problem now it shows a different message when application crashes

[Mon Jun 30 17:38:30.648216 2014] [core:notice] [pid 3841] AH00094: Command line: '/opt/Redmine/apache2/bin/httpd -f /opt/Redmine/apache2/conf/httpd.conf'
[ 2014-06-30 17:38:47.7696 3856/b743cb40 Pool2/Spawner.h:159 ]: [App 3898 stderr] Password:
[ 2014-06-30 17:41:47.8063 3856/b747db40 Pool2/Implementation.cpp:762 ]: Could not spawn process for group /opt/Redmine/apps/redmine/htdocs#default: An error occurred while starting up the preloader: it did not write a handshake message in time.
in 'void Passenger::ApplicationPool2::SmartSpawner::throwPreloaderSpawnException(const std::string&, Passenger::SpawnException::ErrorKind, boost::shared_ptr<Passenger::ApplicationPool2::Spawner::BackgroundIOCapturer>&, const boost::shared_ptr<Passenger::ApplicationPool2::Spawner::DebugDir>&)' (SmartSpawner.h:149)
in 'std::string Passenger::ApplicationPool2::SmartSpawner::negotiatePreloaderStartup(Passenger::ApplicationPool2::SmartSpawner::StartupDetails&)' (SmartSpawner.h:539)
in 'void Passenger::ApplicationPool2::SmartSpawner::startPreloader()' (SmartSpawner.h:205)
in 'virtual Passenger::ApplicationPool2::ProcessPtr Passenger::ApplicationPool2::SmartSpawner::spawn(const Passenger::ApplicationPool2::Options&)' (SmartSpawner.h:743)
in 'void Passenger::ApplicationPool2::Group::spawnThreadRealMain(const Passenger::ApplicationPool2::SpawnerPtr&, const Passenger::ApplicationPool2::Options&, unsigned int)' (Implementation.cpp:695)

[ 2014-06-30 17:41:47.8066 3856/b61fdb40 agents/HelperAgent/RequestHandler.h:1888 ]: [Client 23] Cannot checkout session. An error occurred while starting up the preloader: it did not write a handshake message in time.
Error page:
Password:

RE: Redmine Outage - Urgent help required - Added by Jan Niggemann (redmine.org team member) over 5 years ago

After fixing the above problem now it shows a different message when application crashes
An error occurred while starting up the preloader: it did not write a handshake message in time.

IMHO this is the very same error message as before.
I'm out, don't know what might be wrong here.

RE: Redmine Outage - Urgent help required - Added by Toshi MARUYAMA over 5 years ago

So, I removed attachment because it has Rupesh's mail address.

(1-11/11)