meteorhacks / kadira

Performance Monitoring for Meteor
https://kadira.io/platform/kadira-apm/overview
MIT License
216 stars 110 forks source link

it takes an error at phusion passenger #122

Open miraten opened 9 years ago

miraten commented 9 years ago

I'm running my app at phusion passenger. 4.0.53 And the server OS is centOS 6.3

Running the app, there is an error as following:

Error: EACCES, permission denied App 34327 stderr: at [object Object].SystemModel.buildPayload (/home/www/bookpal/site_www/programs/server/packages/meteorhacks_kadira.js:1082:28) App 34327 stderr: at Object.Kadira._buildPayload (/home/www/bookpal/site_www/programs/server/packages/meteorhacks_kadira.js:1341:42) App 34327 stderr: at /home/www/bookpal/site_www/programs/server/packages/meteorhacks_kadira.js:1420:26

At first, the server seems to work well. However, after some seconds, the app tries to restart to fail several times. About 1~3 minutes later, the server works but to restart again, again.

Excluding the Kadira configuration, the server works well and does not restart again.

What is the solution?

arunoda commented 9 years ago

Okay now I know the issue. Seems like /proc file system is disabled for your instance. It's a readonly file system and we read system info like CPU usage and memory from there. Try to give read permission to that.

It will fix the issue.

On Wed Dec 10 2014 at 10:51:43 AM Lee Sangwon notifications@github.com wrote:

I'm running my app at phusion passenger. 4.0.53 And the server OS is centOS 6.3 Running the app, there is an error as following:

Error: EACCES, permission denied App 34327 stderr: at [object Object].SystemModel.buildPayload (/home/www/bookpal/site_www/programs/server/packages/meteorhacks_kadira.js:1082:28) App 34327 stderr: at Object.Kadira._buildPayload (/home/www/bookpal/site_www/programs/server/packages/meteorhacks_kadira.js:1341:42) App 34327 stderr: at /home/www/bookpal/site_www/programs/server/packages/meteorhacks_kadira.js:1420:26

At first, the server seems to work well. However, after some seconds, the app tries to restart to fail several times. About 1~3 minutes later, the server works but to restart again, again.

Excluding the Kadira configuration, the server works well and does not restart again.

What is the solution?

— Reply to this email directly or view it on GitHub https://github.com/meteorhacks/kadira/issues/122.

miraten commented 9 years ago

There are so many sub-directories and files at '/proc' directory. They are almost root:root owner and r-x or r mode.

Should All of them be changed to 'rwx' or 'rw' mode?

arunoda commented 9 years ago

Not rw Just r-x is enough. However passenger might do some blocking also. Try to contact them also. We can also do a fix from our end. Will do that too.

On Wed Dec 10 2014 at 11:01:26 AM Lee Sangwon notifications@github.com wrote:

There are so many sub-directories and files at '/proc' directory. They are almost root:root owner and r-x or r mode.

Should All of them be changed to 'rwx' or 'rw' mode?

— Reply to this email directly or view it on GitHub https://github.com/meteorhacks/kadira/issues/122#issuecomment-66406641.

miraten commented 9 years ago

After changed the mode of '/proc' from 'rwx------' to 'rwxr-xr-x', the error message did not take any more.

However, other error still took place.

Actually a series of errors have taken place. The first is 'Error: EACCES, permission denied', and the next is as following:

Exception in callback of async function: Error: No valid replicaset instance servers found at /home/www/bookpal/site_www/programs/server/npm/mongo/node_modules/mongodb/lib/mongodb/connection/repl_set/repl_set.js:446:45 at null.<anonymous> (/home/www/bookpal/site_www/programs/server/npm/mongo/node_modules/mongodb/lib/mongodb/connection/server.js:546:7) at emit (events.js:106:17) at null.<anonymous> (/home/www/bookpal/site_www/programs/server/npm/mongo/node_modules/mongodb/lib/mongodb/connection/connection_pool.js:150:15) at emit (events.js:98:17) at Socket.<anonymous> (/home/www/bookpal/site_www/programs/server/npm/mongo/node_modules/mongodb/lib/mongodb/connection/connection.js:516:10) at Socket.emit (events.js:95:17) at net.js:833:16 at process._tickCallback (node.js:419:13)

I thought that the main cause was Kadira and if the first error were to disappear, all the following errors would also be gone.

But, all the other errors still be there.

It is certain that the cause of the error is from kadira, but the other causes have still been remained unsolved.

I will ask to Passenger team.

Thanks arunoda.

arunoda commented 9 years ago

Hmm. This one comes when trying to connect with MongoDB. It's better to ask them.

On Wed Dec 10 2014 at 11:17:59 AM Lee Sangwon notifications@github.com wrote:

After changed the mode of '/proc' from 'rwx------' to 'rwxr-xr-x', the error message did not take any more.

However, other error still took place.

Actually a series of errors have taken place. The first is 'Error: EACCES, permission denied', and the next is as following:

Exception in callback of async function: Error: No valid replicaset instance servers found at /home/www/bookpal/site_www/programs/server/npm/mongo/node_modules/mongodb/lib/mongodb/connection/repl_set/repl_set.js:446:45 at null. (/home/www/bookpal/site_www/programs/server/npm/mongo/node_modules/mongodb/lib/mongodb/connection/server.js:546:7) at emit (events.js:106:17) at null. (/home/www/bookpal/site_www/programs/server/npm/mongo/node_modules/mongodb/lib/mongodb/connection/connection_pool.js:150:15) at emit (events.js:98:17) at Socket. (/home/www/bookpal/site_www/programs/server/npm/mongo/node_modules/mongodb/lib/mongodb/connection/connection.js:516:10) at Socket.emit (events.js:95:17) at net.js:833:16 at process._tickCallback (node.js:419:13)

I thought that the main cause was Kadira and if the first error were to disappear, all the following errors would also be gone.

But, all the other errors still be there.

It is certain that the cause of the error is from kadira, but the other causes have still been remained unsolved.

I will ask to Passenger team.

Thanks arunoda.

— Reply to this email directly or view it on GitHub https://github.com/meteorhacks/kadira/issues/122#issuecomment-66407596.

miraten commented 9 years ago

It seems that kadira sometimes make the startup unstable. Trying to restart the app serveral times, if the kadira works well, all the process works well. But if the kadira does not start well sometimes, then the app also makes errors.

The startup process of the kadira seems to prevent the mongodb connection process of the nginx-passenger module.

miraten commented 9 years ago

In the startup process of the app, kadira tries to read system information at ‘/proc’. System default permission of ‘/proc’ directory was ‘rwx------‘. And kadira made errors as follwing:

Error: EACCES, permission denied
App 34327 stderr: at [object Object].SystemModel.buildPayload (/home/www/appname/site_www/programs/server/packages/meteorhacks_kadira.js:1082:28)
App 34327 stderr: at Object.Kadira._buildPayload (/home/www/appname/site_www/programs/server/packages/meteorhacks_kadira.js:1341:42)
App 34327 stderr: at /home/www/appname/site_www/programs/server/packages/meteorhacks_kadira.js:1420:26

I changed the mode of the directory ‘/proc' to ‘rwxr-xr-x’. And the error disappeared. However the next step still make errors as following.

As you can see, the app startup succeeded eventually but with some struggle. It seems that the startup of kadira prevent the mongodb connection of the app startup process.

[ 2014-12-10 15:12:00.7666 36847/7f079a657720 agents/Watchdog/Main.cpp:538 ]: Options: { 'analytics_log_user' => 'nobody', 'default_group' => 'nobody', 'default_python' => 'python', 'default_ruby' => '/usr/bin/ruby', 'default_user' => 'nobody', 'log_level' => '0', 'max_pool_size' => '10', 'passenger_root' => '/usr/lib/ruby/gems/1.8/gems/passenger-4.0.53', 'passenger_version' => '4.0.53', 'pool_idle_time' => '300', 'prestart_urls' => 'aHR0cDovL2FkbWluLmJvb2twLmFsAGh0dHA6Ly9ub3ZlbC5ib29rcC5hbABodHRwczovL2FkbWluLmJvb2twLmFsAGh0dHBzOi8vbm92ZWwuYm9va3AuYWwA', 'temp_dir' => '/tmp', 'union_station_gateway_address' => 'gateway.unionstationapp.com', 'union_station_gateway_port' => '443', 'user_switching' => 'true', 'web_server_passenger_version' => '4.0.53', 'web_server_pid' => '36846', 'web_server_type' => 'nginx', 'web_server_worker_gid' => '99', 'web_server_worker_uid' => '99' }
[ 2014-12-10 15:12:00.7751 36850/7f6529a68720 agents/HelperAgent/Main.cpp:650 ]: PassengerHelperAgent online, listening at unix:/tmp/passenger.1.0.36846/generation-0/request
[ 2014-12-10 15:12:00.7820 36855/7f60edd417e0 agents/LoggingAgent/Main.cpp:321 ]: PassengerLoggingAgent online, listening at unix:/tmp/passenger.1.0.36846/generation-0/logging
[ 2014-12-10 15:12:00.7823 36847/7f079a657720 agents/Watchdog/Main.cpp:728 ]: All Phusion Passenger agents started!
App 36872 stdout: 
App 36872 stdout: Exception in callback of async function: Error: No valid replicaset instance servers found
App 36872 stdout:     at /home/www/appname/site_www/programs/server/npm/mongo/node_modules/mongodb/lib/mongodb/connection/repl_set/repl_set.js:446:45
App 36872 stdout:     at null.<anonymous> (/home/www/appname/site_www/programs/server/npm/mongo/node_modules/mongodb/lib/mongodb/connection/server.js:546:7)
App 36872 stdout:     at emit (events.js:106:17)
App 36872 stdout:     at null.<anonymous> (/home/www/appname/site_www/programs/server/npm/mongo/node_modules/mongodb/lib/mongodb/connection/connection_pool.js:150:15)
App 36872 stdout:     at emit (events.js:98:17)
App 36872 stdout:     at Socket.<anonymous> (/home/www/appname/site_www/programs/server/npm/mongo/node_modules/mongodb/lib/mongodb/connection/connection.js:516:10)
App 36872 stdout:     at Socket.emit (events.js:95:17)
App 36872 stdout:     at net.js:833:16
App 36872 stdout:     at process._tickCallback (node.js:419:13)
[ 2014-12-10 15:13:31.0816 36850/7f65285c2700 Pool2/Implementation.cpp:287 ]: Could not spawn process for application /home/www/appname/site_www: An error occurred while starting the web application: it did not write a startup response in time.
  Error ID: 29e7c357
  Error details saved to: /tmp/passenger-error-jwT4bk.html
  Message from application: An error occurred while starting the web application: it did not write a startup response in time. Please read <a href="https://github.com/phusion/passenger/wiki/Debugging-application-startup-problems">this article</a> for more information about this problem.<br>
<h2>Raw process output:</h2>
<pre>
Exception in callback of async function: Error: No valid replicaset instance servers found
    at /home/www/appname/site_www/programs/server/npm/mongo/node_modules/mongodb/lib/mongodb/connection/repl_set/repl_set.js:446:45
    at null.&lt;anonymous&gt; (/home/www/appname/site_www/programs/server/npm/mongo/node_modules/mongodb/lib/mongodb/connection/server.js:546:7)
    at emit (events.js:106:17)
    at null.&lt;anonymous&gt; (/home/www/appname/site_www/programs/server/npm/mongo/node_modules/mongodb/lib/mongodb/connection/connection_pool.js:150:15)
    at emit (events.js:98:17)
    at Socket.&lt;anonymous&gt; (/home/www/appname/site_www/programs/server/npm/mongo/node_modules/mongodb/lib/mongodb/connection/connection.js:516:10)
    at Socket.emit (events.js:95:17)
    at net.js:833:16
    at process._tickCallback (node.js:419:13)
</pre>

[ 2014-12-10 15:13:31.0952 36850/7f651bfff700 agents/HelperAgent/RequestHandler.h:2306 ]: [Client 20] Cannot checkout session because a spawning error occurred. The identifier of the error is 29e7c357. Please see earlier logs for details about the error.
[ 2014-12-10 15:13:31.0955 36850/7f651bfff700 agents/HelperAgent/RequestHandler.h:2306 ]: [Client 21] Cannot checkout session because a spawning error occurred. The identifier of the error is 29e7c357. Please see earlier logs for details about the error.
[ 2014-12-10 15:13:31.0958 36850/7f651bfff700 agents/HelperAgent/RequestHandler.h:2306 ]: [Client 24] Cannot checkout session because a spawning error occurred. The identifier of the error is 29e7c357. Please see earlier logs for details about the error.
[ 2014-12-10 15:13:31.0964 36850/7f651bfff700 agents/HelperAgent/RequestHandler.h:2306 ]: [Client 25] Cannot checkout session because a spawning error occurred. The identifier of the error is 29e7c357. Please see earlier logs for details about the error.
[ 2014-12-10 15:13:31.0966 36850/7f651bfff700 agents/HelperAgent/RequestHandler.h:2306 ]: [Client 26] Cannot checkout session because a spawning error occurred. The identifier of the error is 29e7c357. Please see earlier logs for details about the error.
[ 2014-12-10 15:13:31.0968 36850/7f651bfff700 agents/HelperAgent/RequestHandler.h:2306 ]: [Client 27] Cannot checkout session because a spawning error occurred. The identifier of the error is 29e7c357. Please see earlier logs for details about the error.
[ 2014-12-10 15:13:31.0970 36850/7f651bfff700 agents/HelperAgent/RequestHandler.h:2306 ]: [Client 28] Cannot checkout session because a spawning error occurred. The identifier of the error is 29e7c357. Please see earlier logs for details about the error.
[ 2014-12-10 15:13:31.0971 36850/7f651bfff700 agents/HelperAgent/RequestHandler.h:2306 ]: [Client 29] Cannot checkout session because a spawning error occurred. The identifier of the error is 29e7c357. Please see earlier logs for details about the error.
[ 2014-12-10 15:13:31.0972 36850/7f651bfff700 agents/HelperAgent/RequestHandler.h:2306 ]: [Client 30] Cannot checkout session because a spawning error occurred. The identifier of the error is 29e7c357. Please see earlier logs for details about the error.
[ 2014-12-10 15:13:31.0974 36850/7f651bfff700 agents/HelperAgent/RequestHandler.h:2306 ]: [Client 31] Cannot checkout session because a spawning error occurred. The identifier of the error is 29e7c357. Please see earlier logs for details about the error.
[ 2014-12-10 15:13:31.0975 36850/7f651bfff700 agents/HelperAgent/RequestHandler.h:2306 ]: [Client 32] Cannot checkout session because a spawning error occurred. The identifier of the error is 29e7c357. Please see earlier logs for details about the error.
[ 2014-12-10 15:13:31.0976 36850/7f651bfff700 agents/HelperAgent/RequestHandler.h:2306 ]: [Client 33] Cannot checkout session because a spawning error occurred. The identifier of the error is 29e7c357. Please see earlier logs for details about the error.
[ 2014-12-10 15:13:31.0978 36850/7f651bfff700 agents/HelperAgent/RequestHandler.h:2306 ]: [Client 34] Cannot checkout session because a spawning error occurred. The identifier of the error is 29e7c357. Please see earlier logs for details about the error.
[ 2014-12-10 15:13:31.0980 36850/7f651bfff700 agents/HelperAgent/RequestHandler.h:2306 ]: [Client 35] Cannot checkout session because a spawning error occurred. The identifier of the error is 29e7c357. Please see earlier logs for details about the error.
[ 2014-12-10 15:13:31.0982 36850/7f651bfff700 agents/HelperAgent/RequestHandler.h:2306 ]: [Client 36] Cannot checkout session because a spawning error occurred. The identifier of the error is 29e7c357. Please see earlier logs for details about the error.
[ 2014-12-10 15:13:31.0984 36850/7f651bfff700 agents/HelperAgent/RequestHandler.h:2306 ]: [Client 37] Cannot checkout session because a spawning error occurred. The identifier of the error is 29e7c357. Please see earlier logs for details about the error.
App 36941 stdout: 
App 36941 stdout: Exception in callback of async function: Error: No valid replicaset instance servers found
App 36941 stdout:     at /home/www/appname/site_www/programs/server/npm/mongo/node_modules/mongodb/lib/mongodb/connection/repl_set/repl_set.js:446:45
App 36941 stdout:     at null.<anonymous> (/home/www/appname/site_www/programs/server/npm/mongo/node_modules/mongodb/lib/mongodb/connection/server.js:546:7)
App 36941 stdout:     at emit (events.js:106:17)
App 36941 stdout:     at null.<anonymous> (/home/www/appname/site_www/programs/server/npm/mongo/node_modules/mongodb/lib/mongodb/connection/connection_pool.js:150:15)
App 36941 stdout:     at emit (events.js:98:17)
App 36941 stdout:     at Socket.<anonymous> (/home/www/appname/site_www/programs/server/npm/mongo/node_modules/mongodb/lib/mongodb/connection/connection.js:516:10)
App 36941 stdout:     at Socket.emit (events.js:95:17)
App 36941 stdout:     at net.js:833:16
App 36941 stdout:     at process._tickCallback (node.js:419:13)
[ 2014-12-10 15:13:57.6557 36972/7fbba61b6720 agents/Watchdog/Main.cpp:538 ]: Options: { 'analytics_log_user' => 'nobody', 'default_group' => 'nobody', 'default_python' => 'python', 'default_ruby' => '/usr/bin/ruby', 'default_user' => 'nobody', 'log_level' => '0', 'max_pool_size' => '10', 'passenger_root' => '/usr/lib/ruby/gems/1.8/gems/passenger-4.0.53', 'passenger_version' => '4.0.53', 'pool_idle_time' => '300', 'prestart_urls' => 'aHR0cDovL2FkbWluLmJvb2twLmFsAGh0dHA6Ly9ub3ZlbC5ib29rcC5hbABodHRwczovL2FkbWluLmJvb2twLmFsAGh0dHBzOi8vbm92ZWwuYm9va3AuYWwA', 'temp_dir' => '/tmp', 'union_station_gateway_address' => 'gateway.unionstationapp.com', 'union_station_gateway_port' => '443', 'user_switching' => 'true', 'web_server_passenger_version' => '4.0.53', 'web_server_pid' => '36971', 'web_server_type' => 'nginx', 'web_server_worker_gid' => '99', 'web_server_worker_uid' => '99' }
[ 2014-12-10 15:13:57.6642 36975/7ff993377720 agents/HelperAgent/Main.cpp:650 ]: PassengerHelperAgent online, listening at unix:/tmp/passenger.1.0.36971/generation-0/request
[ 2014-12-10 15:13:57.6703 36980/7f1c20a6d7e0 agents/LoggingAgent/Main.cpp:321 ]: PassengerLoggingAgent online, listening at unix:/tmp/passenger.1.0.36971/generation-0/logging
[ 2014-12-10 15:13:57.6706 36972/7fbba61b6720 agents/Watchdog/Main.cpp:728 ]: All Phusion Passenger agents started!
[ 2014-12-10 15:13:57.6824 36980/7f1c20a6d7e0 agents/LoggingAgent/Main.cpp:289 ]: Caught signal, exiting...
[ 2014-12-10 15:13:57.8011 36997/7fc9c82ca720 agents/Watchdog/Main.cpp:538 ]: Options: { 'analytics_log_user' => 'nobody', 'default_group' => 'nobody', 'default_python' => 'python', 'default_ruby' => '/usr/bin/ruby', 'default_user' => 'nobody', 'log_level' => '0', 'max_pool_size' => '10', 'passenger_root' => '/usr/lib/ruby/gems/1.8/gems/passenger-4.0.53', 'passenger_version' => '4.0.53', 'pool_idle_time' => '300', 'prestart_urls' => 'aHR0cDovL2FkbWluLmJvb2twLmFsAGh0dHA6Ly9ub3ZlbC5ib29rcC5hbABodHRwczovL2FkbWluLmJvb2twLmFsAGh0dHBzOi8vbm92ZWwuYm9va3AuYWwA', 'temp_dir' => '/tmp', 'union_station_gateway_address' => 'gateway.unionstationapp.com', 'union_station_gateway_port' => '443', 'user_switching' => 'true', 'web_server_passenger_version' => '4.0.53', 'web_server_pid' => '36996', 'web_server_type' => 'nginx', 'web_server_worker_gid' => '99', 'web_server_worker_uid' => '99' }
[ 2014-12-10 15:13:57.8105 37000/7fb667a51720 agents/HelperAgent/Main.cpp:650 ]: PassengerHelperAgent online, listening at unix:/tmp/passenger.1.0.36996/generation-0/request
[ 2014-12-10 15:13:57.8167 37005/7ff57b3217e0 agents/LoggingAgent/Main.cpp:321 ]: PassengerLoggingAgent online, listening at unix:/tmp/passenger.1.0.36996/generation-0/logging
[ 2014-12-10 15:13:57.8171 36997/7fc9c82ca720 agents/Watchdog/Main.cpp:728 ]: All Phusion Passenger agents started!
App 37036 stdout: 
App 37036 stdout: info: Meteor Logger initialized...
App 37036 stdout: Kadira: completed instrumenting the app
App 37036 stdout: Kadira: successfully authenticated
[ 2014-12-10 15:14:27.6804 36992/7f079a657720 agents/Watchdog/Main.cpp:386 ]: Some Phusion Passenger agent processes did not exit in time, forcefully shutting down all.
App 37036 stdout: info: query: {"currency":"krw","state":10,"group":10}
App 37036 stdout: info: options: {"sort":{"seq":1}}
App 37036 stdout: info: query: {"currency":"krw","state":10,"group":10}
App 37036 stdout: info: options: {"sort":{"seq":1}}
App 37036 stdout: info: query: {"currency":"krw","state":10,"group":10}
App 37036 stdout: info: options: {"sort":{"seq":1}}
App 37036 stdout: info: search chapter query = 다시
App 37036 stdout: info: search author query = 다시
App 37036 stdout: info: search chapter query = 다시
App 37036 stdout: info: query: {"currency":"krw","state":10,"group":10}
App 37036 stdout: info: options: {"sort":{"seq":1}}
App 37036 stdout: info: query: {"currency":"krw","state":10,"group":10}
App 37036 stdout: info: options: {"sort":{"seq":1}}
arunoda commented 9 years ago

Hi,

We run phusion on a centos and we couldn't found any issues with Kadira. I assume, this is something to do with your Mongo Setup.

miraten commented 9 years ago

Thanks Aurunoda,

My database is served by Mongolab.com

I think that the initial setup process of kadira affect the connection process to the mongodb. I am also asking to Mongolab.com by email.

If I got to know something about it, I will inform you.

arunoda commented 9 years ago

Sure. I'm quite not sure how Kadira affects, but I'll try to look at more. On Thu Dec 11 2014 at 11:04:21 AM Lee Sangwon notifications@github.com wrote:

Thanks Aurunoda,

My database is served by Mongolab.com

I think that the initial setup process of kadira affect the connection process to the mongodb. I am also asking to Mongolab.com by email.

If I got to know something about it, I will inform you.

— Reply to this email directly or view it on GitHub https://github.com/meteorhacks/kadira/issues/122#issuecomment-66573392.

miraten commented 9 years ago

After various test, I have concluded that this error was NOT related with kadira.

I eventually made the same error without kadira.

The cause of the error may be database connection problem.

Sorry, Arunoda.

arunoda commented 9 years ago

That's okay. BTW: We did some experiments with passenger because of that.

On Thu Dec 11 2014 at 2:33:48 PM Lee Sangwon notifications@github.com wrote:

After various test, I have concluded that this error was NOT related with kadira.

I eventually made the same error without kadira.

The cause of the error may be database connection problem.

Sorry, Arunoda.

— Reply to this email directly or view it on GitHub https://github.com/meteorhacks/kadira/issues/122#issuecomment-66590335.

ghost commented 9 years ago

@arunoda might be very interesting to read about your experience with passenger and what do you think about the compatibility with meteor at all, thanks in advise

PS: It's ok when it's not in this topic ;)