Open mitomm opened 4 years ago
Can you provide the contents of the passenger log? Perhaps something got logged there that can help.
Sure, but could see anything really helpful in there:
[ N 2020-05-27 20:47:01.0040 3922/T1 age/Wat/WatchdogMain.cpp:1373 ]: Starting Passenger watchdog...
[ N 2020-05-27 20:47:01.0276 3925/T1 age/Cor/CoreMain.cpp:1340 ]: Starting Passenger core...
[ N 2020-05-27 20:47:01.0278 3925/T1 age/Cor/CoreMain.cpp:256 ]: Passenger core running in multi-application mode.
[ N 2020-05-27 20:47:01.0412 3925/T1 age/Cor/CoreMain.cpp:1015 ]: Passenger core online, PID 3925
[ N 2020-05-27 20:47:03.1744 3925/T5 age/Cor/SecurityUpdateChecker.h:519 ]: Security update check: no update found (next check in 24 hours)
[ E 2020-05-27 20:48:33.1787 3925/Tj age/Cor/App/Implementation.cpp:221 ]: Could not spawn process for application /var/www/vhosts/mydomain.com/httpdocs/home/platform/dist-server: A timeout occurred while spawning an application process.
Error ID: 983f8bfd
Error details saved to: /tmp/passenger-error-laBJSq.html
[ E 2020-05-27 20:48:33.1856 3925/T9 age/Cor/Con/CheckoutSession.cpp:276 ]: [Client 1-1] Cannot checkout session because a spawning error occurred. The identifier of the error is 983f8bfd. Please see earlier logs for details about the error.
You might need to increase the log level to 7 then to get more info.
Sorry, didn't know about that possibility.
Here is the log:
2020/05/27 21:52:01 [warn] 8666#0: 4096 worker_connections exceed open file resource limit: 1024
2020/05/27 21:52:01 [notice] 8668#0: using the "epoll" event method
2020/05/27 21:52:01 [warn] 8668#0: 4096 worker_connections exceed open file resource limit: 1024
[ D 2020-05-27 21:52:01.4078 8669/T1 age/Sha/Fun/Initialization.cpp:509 ]: Starting agent: Passenger watchdog
[ D 2020-05-27 21:52:01.4080 8669/T1 age/Sha/Fun/Initialization.cpp:619 ]: Passenger watchdog config: {
"admin_panel_auth_type" : "basic",
"admin_panel_close_timeout" : 10.0,
"admin_panel_connect_timeout" : 30.0,
"admin_panel_data_debug" : false,
"admin_panel_password" : null,
"admin_panel_password_file" : null,
"admin_panel_ping_interval" : 30.0,
"admin_panel_ping_timeout" : 30.0,
"admin_panel_proxy_password" : null,
"admin_panel_proxy_timeout" : 30.0,
"admin_panel_proxy_url" : null,
"admin_panel_proxy_username" : null,
"admin_panel_reconnect_timeout" : 5.0,
"admin_panel_url" : null,
"admin_panel_username" : null,
"admin_panel_websocketpp_debug_access" : false,
"admin_panel_websocketpp_debug_error" : false,
"app_output_log_level" : "notice",
"benchmark_mode" : null,
"config_manifest" : "[OMITTED]",
"controller_accept_burst_count" : 32,
"controller_addresses" : null,
"controller_client_freelist_limit" : 0,
"controller_cpu_affine" : false,
"controller_file_buffered_channel_auto_start_mover" : true,
"controller_file_buffered_channel_auto_truncate_file" : true,
"controller_file_buffered_channel_buffer_dir" : "/tmp",
"controller_file_buffered_channel_delay_in_file_mode_switching" : 0,
"controller_file_buffered_channel_max_disk_chunk_read_size" : 0,
"controller_file_buffered_channel_threshold" : 131072,
"controller_mbuf_block_chunk_size" : 4096,
"controller_min_spare_clients" : 0,
"controller_pid_file" : null,
"controller_request_freelist_limit" : 1024,
"controller_secure_headers_password" : "tj9Jf95AhbgppytARdsag4aC",
"controller_socket_backlog" : 4000,
"controller_start_reading_after_accept" : true,
"controller_threads" : 4,
"core_api_server_accept_burst_count" : 32,
"core_api_server_addresses" : [],
"core_api_server_authorizations" : [],
"core_api_server_client_freelist_limit" : 0,
"core_api_server_file_buffered_channel_auto_start_mover" : true,
"core_api_server_file_buffered_channel_auto_truncate_file" : true,
"core_api_server_file_buffered_channel_buffer_dir" : "/tmp",
"core_api_server_file_buffered_channel_delay_in_file_mode_switching" : 0,
"core_api_server_file_buffered_channel_max_disk_chunk_read_size" : 0,
"core_api_server_file_buffered_channel_threshold" : 131072,
"core_api_server_mbuf_block_chunk_size" : 4096,
"core_api_server_min_spare_clients" : 0,
"core_api_server_request_freelist_limit" : 1024,
"core_api_server_start_reading_after_accept" : true,
"core_file_descriptor_ulimit" : 50000,
"core_pid_file" : null,
"daemonize" : false,
"default_abort_websockets_on_process_shutdown" : true,
"default_app_file_descriptor_ulimit" : null,
"default_environment" : "production",
"default_force_max_concurrent_requests_per_process" : -1,
"default_friendly_error_pages" : "auto",
"default_group" : "root",
"default_load_shell_envvars" : true,
"default_max_preloader_idle_time" : 300,
"default_max_request_queue_size" : 100,
"default_max_requests" : 0,
"default_meteor_app_settings" : null,
"default_min_instances" : 1,
"default_nodejs" : "node",
"default_python" : "python",
"default_ruby" : "/usr/bin/ruby2.3",
"default_server_name" : "127.0.0.1",
"default_server_port" : 3000,
"default_spawn_method" : "smart",
"default_sticky_sessions" : false,
"default_sticky_sessions_cookie_name" : "_passenger_route",
"default_user" : "root",
"disable_log_prefix" : false,
"file_descriptor_log_target" : null,
"graceful_exit" : true,
"hook_after_watchdog_initialization" : null,
"hook_after_watchdog_shutdown" : null,
"hook_attached_process" : null,
"hook_before_watchdog_initialization" : null,
"hook_before_watchdog_shutdown" : null,
"hook_detached_process" : null,
"hook_queue_full_error" : null,
"hook_spawn_failed" : null,
"instance_registry_dir" : "/tmp",
"integration_mode" : "standalone",
"log_level" : "debug3",
"log_target" : {
"path" : "/var/www/vhosts/mydomain.com/httpdocs/home/platform/dist-server/passenger.5000.log",
"stderr" : true
},
"max_instances_per_app" : null,
"max_pool_size" : 6,
"multi_app" : true,
"passenger_root" : "/usr/lib/ruby/vendor_ruby/phusion_passenger/locations.ini",
"pidfiles_to_delete_on_exit" : [ "/tmp/passenger-standalone.1jijolu/temp_dir_toucher.pid" ],
"pool_idle_time" : 300,
"pool_selfchecks" : false,
"prestart_urls" : [ "http://0.0.0.0:5000/" ],
"response_buffer_high_watermark" : 134217728,
"security_update_checker_certificate_path" : null,
"security_update_checker_disabled" : false,
"security_update_checker_interval" : 86400,
"security_update_checker_proxy_url" : null,
"security_update_checker_url" : "https://securitycheck.phusionpassenger.com/v1/check.json",
"server_software" : "nginx/1.17.3 Phusion_Passenger/6.0.4",
"setsid" : false,
"show_version_in_header" : true,
"single_app_mode_app_root" : "/var/www/vhosts/mydomain.com/httpdocs/home/platform/dist-server",
"single_app_mode_app_start_command" : null,
"single_app_mode_app_type" : null,
"single_app_mode_startup_file" : null,
"spawn_dir" : "/tmp",
"standalone_engine" : "nginx",
"startup_report_file" : null,
"stat_throttle_rate" : 10,
"telemetry_collector_ca_certificate_path" : null,
"telemetry_collector_debug_curl" : false,
"telemetry_collector_disabled" : false,
"telemetry_collector_final_run_timeout" : 5,
"telemetry_collector_first_interval" : 7200,
"telemetry_collector_interval" : 21600,
"telemetry_collector_interval_jitter" : 7200,
"telemetry_collector_proxy_url" : null,
"telemetry_collector_timeout" : 180,
"telemetry_collector_url" : "https://anontelemetry.phusionpassenger.com/v1/collect.json",
"telemetry_collector_verify_server" : true,
"turbocaching" : true,
"user" : "root",
"user_switching" : false,
"vary_turbocache_by_cookie" : null,
"watchdog_api_server_accept_burst_count" : 32,
"watchdog_api_server_addresses" : [],
"watchdog_api_server_authorizations" : [],
"watchdog_api_server_client_freelist_limit" : 0,
"watchdog_api_server_file_buffered_channel_auto_start_mover" : true,
"watchdog_api_server_file_buffered_channel_auto_truncate_file" : true,
"watchdog_api_server_file_buffered_channel_buffer_dir" : "/tmp",
"watchdog_api_server_file_buffered_channel_delay_in_file_mode_switching" : 0,
"watchdog_api_server_file_buffered_channel_max_disk_chunk_read_size" : 0,
"watchdog_api_server_file_buffered_channel_threshold" : 131072,
"watchdog_api_server_mbuf_block_chunk_size" : 4096,
"watchdog_api_server_min_spare_clients" : 0,
"watchdog_api_server_request_freelist_limit" : 1024,
"watchdog_api_server_start_reading_after_accept" : true,
"watchdog_pid_file" : null,
"watchdog_pid_file_autodelete" : true,
"web_server_module_version" : "6.0.4",
"web_server_version" : "1.17.3"
}
[ D 2020-05-27 21:52:01.4093 8669/T1 age/Sha/Fun/Initialization.cpp:620 ]: Passenger watchdog random seed: 1590609121
[ N 2020-05-27 21:52:01.4094 8669/T1 age/Wat/WatchdogMain.cpp:1373 ]: Starting Passenger watchdog...
[ D 2020-05-27 21:52:01.4110 8669/T1 age/Wat/WatchdogMain.cpp:1233 ]: API server will listen on unix:/tmp/passenger.khTl2xj/agents.s/watchdog_api
[ D 2020-05-27 21:52:01.4160 8669/T1 age/Wat/WatchdogMain.cpp:1272 ]: Starting agent: Passenger core
[ D 2020-05-27 21:52:01.4357 8672/T1 age/Sha/Fun/Initialization.cpp:509 ]: Starting agent: Passenger core
[ D 2020-05-27 21:52:01.4359 8672/T1 age/Sha/Fun/Initialization.cpp:619 ]: Passenger core config: {
"admin_panel_auth_type" : "basic",
"admin_panel_close_timeout" : 10.0,
"admin_panel_connect_timeout" : 30.0,
"admin_panel_data_debug" : false,
"admin_panel_password" : null,
"admin_panel_password_file" : null,
"admin_panel_ping_interval" : 30.0,
"admin_panel_ping_timeout" : 30.0,
"admin_panel_proxy_password" : null,
"admin_panel_proxy_timeout" : 30.0,
"admin_panel_proxy_url" : null,
"admin_panel_proxy_username" : null,
"admin_panel_reconnect_timeout" : 5.0,
"admin_panel_url" : null,
"admin_panel_username" : null,
"admin_panel_websocketpp_debug_access" : false,
"admin_panel_websocketpp_debug_error" : false,
"api_server_accept_burst_count" : 32,
"api_server_addresses" : [ "unix:/tmp/passenger.khTl2xj/agents.s/core_api" ],
"api_server_authorizations" : [
{
"level" : "readonly",
"password_file" : "/tmp/passenger.khTl2xj/read_only_admin_password.txt",
"username" : "ro_admin"
},
{
"level" : "full",
"password_file" : "/tmp/passenger.khTl2xj/full_admin_password.txt",
"username" : "admin"
}
],
"api_server_client_freelist_limit" : 0,
"api_server_file_buffered_channel_auto_start_mover" : true,
"api_server_file_buffered_channel_auto_truncate_file" : true,
"api_server_file_buffered_channel_buffer_dir" : "/tmp",
"api_server_file_buffered_channel_delay_in_file_mode_switching" : 0,
"api_server_file_buffered_channel_max_disk_chunk_read_size" : 0,
"api_server_file_buffered_channel_threshold" : 131072,
"api_server_mbuf_block_chunk_size" : 4096,
"api_server_min_spare_clients" : 0,
"api_server_request_freelist_limit" : 1024,
"api_server_start_reading_after_accept" : true,
"app_output_log_level" : "notice",
"benchmark_mode" : null,
"config_manifest" : "[OMITTED]",
"controller_accept_burst_count" : 32,
"controller_addresses" : [ "unix:/tmp/passenger.khTl2xj/agents.s/core" ],
"controller_client_freelist_limit" : 0,
"controller_cpu_affine" : false,
"controller_file_buffered_channel_auto_start_mover" : true,
"controller_file_buffered_channel_auto_truncate_file" : true,
"controller_file_buffered_channel_buffer_dir" : "/tmp",
"controller_file_buffered_channel_delay_in_file_mode_switching" : 0,
"controller_file_buffered_channel_max_disk_chunk_read_size" : 0,
"controller_file_buffered_channel_threshold" : 131072,
"controller_mbuf_block_chunk_size" : 4096,
"controller_min_spare_clients" : 0,
"controller_request_freelist_limit" : 1024,
"controller_secure_headers_password" : "tj9Jf95AhbgppytARdsag4aC",
"controller_socket_backlog" : 4000,
"controller_start_reading_after_accept" : true,
"controller_threads" : 4,
"default_abort_websockets_on_process_shutdown" : true,
"default_app_file_descriptor_ulimit" : null,
"default_environment" : "production",
"default_force_max_concurrent_requests_per_process" : -1,
"default_friendly_error_pages" : "auto",
"default_group" : "root",
"default_load_shell_envvars" : true,
"default_max_preloader_idle_time" : 300,
"default_max_request_queue_size" : 100,
"default_max_requests" : 0,
"default_meteor_app_settings" : null,
"default_min_instances" : 1,
"default_nodejs" : "node",
"default_python" : "python",
"default_ruby" : "/usr/bin/ruby2.3",
"default_server_name" : "127.0.0.1",
"default_server_port" : 3000,
"default_spawn_method" : "smart",
"default_sticky_sessions" : false,
"default_sticky_sessions_cookie_name" : "_passenger_route",
"default_user" : "root",
"disable_log_prefix" : false,
"file_descriptor_log_target" : null,
"file_descriptor_ulimit" : 50000,
"graceful_exit" : true,
"hook_attached_process" : null,
"hook_detached_process" : null,
"hook_queue_full_error" : null,
"hook_spawn_failed" : null,
"instance_dir" : "/tmp/passenger.khTl2xj",
"integration_mode" : "standalone",
"log_level" : "debug3",
"log_target" : {
"path" : "/var/www/vhosts/mydomain.com/httpdocs/home/platform/dist-server/passenger.5000.log",
"stderr" : true
},
"max_instances_per_app" : null,
"max_pool_size" : 6,
"multi_app" : true,
"oom_score" : "0\n",
"passenger_root" : "/usr/lib/ruby/vendor_ruby/phusion_passenger/locations.ini",
"pid_file" : "/tmp/passenger.khTl2xj/core.pid",
"pool_idle_time" : 300,
"pool_selfchecks" : false,
"prestart_urls" : [ "http://0.0.0.0:5000/" ],
"response_buffer_high_watermark" : 134217728,
"security_update_checker_certificate_path" : null,
"security_update_checker_disabled" : false,
"security_update_checker_interval" : 86400,
"security_update_checker_proxy_url" : null,
"security_update_checker_url" : "https://securitycheck.phusionpassenger.com/v1/check.json",
"server_software" : "nginx/1.17.3 Phusion_Passenger/6.0.4",
"show_version_in_header" : true,
"single_app_mode_app_root" : "/var/www/vhosts/mydomain.com/httpdocs/home/platform/dist-server",
"single_app_mode_app_start_command" : null,
"single_app_mode_app_type" : null,
"single_app_mode_startup_file" : null,
"spawn_dir" : "/tmp",
"standalone_engine" : "nginx",
"stat_throttle_rate" : 10,
"telemetry_collector_ca_certificate_path" : null,
"telemetry_collector_debug_curl" : false,
"telemetry_collector_disabled" : false,
"telemetry_collector_final_run_timeout" : 5,
"telemetry_collector_first_interval" : 7200,
"telemetry_collector_interval" : 21600,
"telemetry_collector_interval_jitter" : 7200,
"telemetry_collector_proxy_url" : null,
"telemetry_collector_timeout" : 180,
"telemetry_collector_url" : "https://anontelemetry.phusionpassenger.com/v1/collect.json",
"telemetry_collector_verify_server" : true,
"turbocaching" : true,
"user_switching" : false,
"vary_turbocache_by_cookie" : null,
"watchdog_fd_passing_password" : "bKCensgR9Ba7hvrLioQd8Sxc",
"web_server_module_version" : "6.0.4",
"web_server_version" : "1.17.3"
}
[ D 2020-05-27 21:52:01.4363 8672/T1 age/Sha/Fun/Initialization.cpp:620 ]: Passenger core random seed: 1590609121
[ N 2020-05-27 21:52:01.4363 8672/T1 age/Cor/CoreMain.cpp:1340 ]: Starting Passenger core...
[ N 2020-05-27 21:52:01.4364 8672/T1 age/Cor/CoreMain.cpp:256 ]: Passenger core running in multi-application mode.
[ D 2020-05-27 21:52:01.4499 8672/T5 age/Cor/TelemetryCollector.h:186 ]: Next anonymous telemetry collection in 2h 45m 31s
[ N 2020-05-27 21:52:01.4501 8672/T1 age/Cor/CoreMain.cpp:1015 ]: Passenger core online, PID 8672
[ I 2020-05-27 21:52:01.4504 8669/T1 age/Wat/WatchdogMain.cpp:1419 ]: All Phusion Passenger agents started!
2020/05/27 21:52:01 [notice] 8668#0: nginx/1.17.3
2020/05/27 21:52:01 [notice] 8668#0: built by gcc 5.4.0 20160609 (Ubuntu 5.4.0-6ubuntu1~16.04.9)
2020/05/27 21:52:01 [notice] 8668#0: OS: Linux 4.4.0-042stab140.1
2020/05/27 21:52:01 [notice] 8668#0: getrlimit(RLIMIT_NOFILE): 1024:1048576
2020/05/27 21:52:01 [notice] 8691#0: start worker processes
2020/05/27 21:52:01 [notice] 8691#0: start worker process 8692
2020/05/27 21:52:01 [info] 8692#0: *1 client closed connection while waiting for request, client: 127.0.0.1, server: 0.0.0.0:5000
2020/05/27 21:52:01 [info] 8692#0: *2 client closed connection while waiting for request, client: 127.0.0.1, server: 0.0.0.0:5000
[ D 2020-05-27 21:52:03.4503 8672/T6 age/Cor/SecurityUpdateChecker.h:619 ]: sending: {
"curl_static" : false,
"nonce" : "1590609123450140C9CDaaKMrCSPaf9tExSv1w==",
"passenger_version" : "6.0.4",
"server_integration" : "standalone nginx",
"server_version" : "1.17.3"
}
[ D2 2020-05-27 21:52:03.5103 8672/Ti Ser/AcceptLoadBalancer.h:136 ]: Accepted client file descriptor: 53
[ D2 2020-05-27 21:52:03.5103 8672/Ti Ser/AcceptLoadBalancer.h:164 ]: Feeding client to server thread 0: file descriptor 53
[ D 2020-05-27 21:52:03.5104 8672/T8 age/Cor/Con/TurboCaching.h:246 ]: Clearing turbocache
[ D3 2020-05-27 21:52:03.5104 8672/T
8 Ser/Server.h:475 ]: [ServerThr.1] Creating new client object
[ D2 2020-05-27 21:52:03.5105 8672/T8 Ser/Server.h:715 ]: [Client 1-1] Client associated with file descriptor: 53
[ D 2020-05-27 21:52:03.5105 8672/T8 Ser/Server.h:880 ]: [ServerThr.1] 1 new client(s) accepted; there are now 1 active client(s)
[ D3 2020-05-27 21:52:03.5105 8672/T8 Ser/HttpServer.h:775 ]: [Client 1-1] Event: onClientAccepted
[ D3 2020-05-27 21:52:03.5105 8672/T8 Ser/HttpServer.h:310 ]: [Client 1-1] Refcount increased; it is now 3
[ D3 2020-05-27 21:52:03.5105 8672/T8 Ser/FileBufferedChannel.h:1460 ]: [FBC 0x7f04b8000a30] Deinitialize
[ D3 2020-05-27 21:52:03.5105 8672/T8 Ser/HttpServer.h:196 ]: [ServerThr.1] Creating new request object
[ D3 2020-05-27 21:52:03.5106 8672/T8 Ser/Server.h:567 ]: [Client 1-1] Processing 1292 bytes of client data
[ D3 2020-05-27 21:52:03.5107 8672/T8 Ser/HttpServer.h:783 ]: [Client 1-1] Event: onClientDataReceived
[ D3 2020-05-27 21:52:03.5107 8672/T8 Ser/HttpServer.h:786 ]: [Client 1-1] Request refcount increased; it is now 2
[ D3 2020-05-27 21:52:03.5107 8672/T8 Ser/HttpServer.h:331 ]: [Client 1-1] Parsing 1292 bytes of HTTP header: "HEAD / HTTP/1.1\r\nConnection: close\r\nHost: 0.0.0.0\r\nConnection: close\r\n!~: tj9Jf95AhbgppytARdsag4aC\r\n!~DOCUMENT_ROOT: /var/www/vhosts/mydomain.com/httpdocs/home/platform/dist-server/public\r\n!~REMOTE_ADDR: 127.0.0.1\r\n!~REMOTE_PORT: 59074\r\n!~PASSENGER_APP_GROUP_NAME: /var/www/vhosts/mydomain.com/httpdocs/home/platform/dist-server (development)\r\n!~PASSENGER_APP_TYPE: nodejs\r\n!~PASSENGER_RUBY: /usr/bin/ruby2.3\r\n!~PASSENGER_PYTHON: python\r\n!~PASSENGER_NODEJS: node\r\n!~PASSENGER_APP_ENV: development\r\n!~PASSENGER_MIN_PROCESSES: 1\r\n!~PASSENGER_START_TIMEOUT: 90\r\n!~PASSENGER_USER: root\r\n!~PASSENGER_APP_ROOT: /var/www/vhosts/mydomain.com/httpdocs/home/platform/dist-server\r\n!~PASSENGER_DEBUGGER: f\r\n!~PASSENGER_MAX_PRELOADER_IDLE_TIME: 300\r\n!~PASSENGER_SPAWN_METHOD: smart\r\n!~PASSENGER_LOAD_SHELL_ENVVARS: f\r\n!~PASSENGER_MAX_REQUEST_QUEUE_SIZE: 100\r\n!~PASSENGER_STARTUP_FILE: /var/www/vhosts/mydomain.com/httpdocs/home/platform/dist-server/main.js\r\n!~PASSENGER_RESTART_DIR: tmp\r\n!~PASSENGER_ABORT_WEBSOCKETS_ON_PROCESS_SHUTDOWN: t\r\n!~PASSENGER_MAX_REQUESTS: 0\r\n!~PASSENGER_REQUEST_QUEUE_OVERFLOW_STATUS_CODE: 503\r\n!~PASSENGER_STICKY_SESSIONS: t\r\n!~PASSENGER_STICKY_SESSIONS_COOKIE_NAME: _passenger_route\r\n!~PASSENGER_ENV_VARS: c2VydmVyX3R5cGUAbWFpbl9zZXJ2ZXIAc2VydmVyX2RvbWFpbgBkZXZrZWUubHUA\r\n!~FLAGS: CD\r\n\r\n"
[ D2 2020-05-27 21:52:03.5108 8672/T8 Ser/HttpServer.h:340 ]: [Client 1-1] New request received: #1
[ D2 2020-05-27 21:52:03.5108 8672/T8 age/Cor/Con/InitRequest.cpp:458 ]: [Client 1-1] Initiating request
[ D2 2020-05-27 21:52:03.5108 8672/T8 age/Cor/Con/InitRequest.cpp:87 ]: [Client 1-1] Dechunk flag detected
[ D2 2020-05-27 21:52:03.5108 8672/T8 age/Cor/Con/InitRequest.cpp:96 ]: [Client 1-1] Stripping 100 Continue header
[ D2 2020-05-27 21:52:03.5108 8672/T8 age/Cor/Con/InitRequest.cpp:109 ]: [Client 1-1] Turbocaching: trying to reply from cache (key "H0.0.0.0\n/")
[ D2 2020-05-27 21:52:03.5108 8672/T8 age/Cor/Con/InitRequest.cpp:110 ]: [Client 1-1] Turbocache entries:
#0: valid=0, hash=0, expiryDate=0, keySize=0, key=""
#1: valid=0, hash=0, expiryDate=0, keySize=0, key=""
#2: valid=0, hash=0, expiryDate=0, keySize=0, key=""
#3: valid=0, hash=0, expiryDate=0, keySize=0, key=""
#4: valid=0, hash=0, expiryDate=0, keySize=0, key=""
#5: valid=0, hash=0, expiryDate=0, keySize=0, key=""
#6: valid=0, hash=0, expiryDate=0, keySize=0, key=""
#7: valid=0, hash=0, expiryDate=0, keySize=0, key=""
[ D2 2020-05-27 21:52:03.5108 8672/T8 age/Cor/Con/InitRequest.cpp:126 ]: [Client 1-1] Turbocaching: cache miss: NOT_FOUND (key "H0.0.0.0\n/")
[ D2 2020-05-27 21:52:03.5108 8672/T8 age/Cor/Con/InitRequest.cpp:292 ]: [Client 1-1] Creating new pool options: app group name=/var/www/vhosts/mydomain.com/httpdocs/home/platform/dist-server (development)
[ D2 2020-05-27 21:52:03.5109 8672/T8 age/Cor/Con/CheckoutSession.cpp:56 ]: [Client 1-1] Checking out session: appRoot=/var/www/vhosts/mydomain.com/httpdocs/home/platform/dist-server
[ D3 2020-05-27 21:52:03.5109 8672/T8 age/Cor/Con/CheckoutSession.cpp:70 ]: [Client 1-1] Request refcount increased; it is now 3
[ D2 2020-05-27 21:52:03.5109 8672/T8 age/Cor/App/Poo/Miscellaneous.cpp:49 ]: asyncGet(appGroupName=/var/www/vhosts/mydomain.com/httpdocs/home/platform/dist-server (development))
[ D 2020-05-27 21:52:03.5109 8672/T8 age/Cor/App/Poo/Miscellaneous.cpp:73 ]: Spawning new Group
[ D 2020-05-27 21:52:03.5110 8672/T8 age/Cor/App/Gro/SpawningAndRestarting.cpp:436 ]: Requested spawning of new process for group /var/www/vhosts/mydomain.com/httpdocs/home/platform/dist-server (development)
[ D 2020-05-27 21:52:03.5111 8672/T8 age/Cor/App/Gro/SessionManagement.cpp:315 ]: No session checked out yet: group is spawning or restarting
[ D 2020-05-27 21:52:03.5111 8672/T8 age/Cor/App/Poo/Miscellaneous.cpp:78 ]: asyncGet() finished
[ D3 2020-05-27 21:52:03.5112 8672/T8 Ser/HttpServer.h:786 ]: [Client 1-1] Request refcount decreased; it is now 2
[ D2 2020-05-27 21:52:03.5112 8672/T8 Ser/Server.h:594 ]: [Client 1-1] 1292 bytes of client data consumed in this callback
[ D3 2020-05-27 21:52:03.5112 8672/T8 Ser/Server.h:645 ]: [Client 1-1] Refcount decreased; it is now 2
[ D 2020-05-27 21:52:03.5112 8672/T3 age/Cor/App/Poo/GarbageCollection.cpp:150 ]: Garbage collection time...
[ D 2020-05-27 21:52:03.5112 8672/T3 age/Cor/App/Poo/GarbageCollection.cpp:185 ]: Garbage collection done; next garbage collect in 300.000 sec
[ D 2020-05-27 21:52:03.5113 8672/Tj age/Cor/Spa/DirectSpawner.h:239 ]: Spawning new process: appRoot=/var/www/vhosts/mydomain.com/httpdocs/home/platform/dist-server
[ D 2020-05-27 21:52:03.5128 8672/Tj age/Cor/Spa/Han/Prepare.h:284 ]: [App spawn arg] {
"UNIX_PATH_MAX" : 107,
"api_key" : "iZ3yhVzxziB3ygpF",
"app_env" : "development",
"app_group_name" : "/var/www/vhosts/mydomain.com/httpdocs/home/platform/dist-server (development)",
"app_root" : "/var/www/vhosts/mydomain.com/httpdocs/home/platform/dist-server",
"app_type" : "nodejs",
"base_uri" : "/",
"connect_password" : "iZ3yhVzxziB3ygpF",
"environment_variables" : {
"server_domain" : "mydomain.com",
"server_type" : "main_server"
},
"generic_app" : false,
"group" : "root",
"group_uuid" : "gKcQEhkXPpJXzppxmaIc",
"gupid" : "1948348-U0gygdLBoV",
"instance_dir" : "/tmp/passenger.khTl2xj",
"integration_mode" : "standalone",
"load_shell_envvars" : false,
"log_file" : "",
"log_level" : 7,
"node_libdir" : "/usr/share/passenger/node",
"passenger_agent_path" : "/usr/lib/passenger/support-binaries/PassengerAgent",
"passenger_root" : "/usr/lib/ruby/vendor_ruby/phusion_passenger/locations.ini",
"passenger_version" : "6.0.4",
"ruby_libdir" : "/usr/lib/ruby/vendor_ruby",
"socket_dir" : "/tmp/passenger.khTl2xj/apps.s",
"spawn_method" : "direct",
"start_command" : "node /usr/share/passenger/helper-scripts/node-loader.js",
"starts_using_wrapper" : true,
"startup_file" : "/var/www/vhosts/mydomain.com/httpdocs/home/platform/dist-server/main.js",
"user" : "root",
"wrapper_supplied_by_third_party" : false
}
[ D 2020-05-27 21:52:03.5140 8672/Tj LveLoggingDecorator.h:45 ]: LVE lib is not available
[ D 2020-05-27 21:52:03.5140 8672/Tj LveLoggingDecorator.h:67 ]: LVE not in [pid 8672, uid 0, min_uid 500]
[ D 2020-05-27 21:52:03.5148 8672/Tj age/Cor/Spa/DirectSpawner.h:213 ]: Process forked for appRoot=/var/www/vhosts/mydomain.com/httpdocs/home/platform/dist-server: PID 8714
[ D 2020-05-27 21:52:03.5575 8672/T6 age/Cor/SecurityUpdateChecker.h:637 ]: received: {"data":"eyJ1cGRhdGUiOjAsImxvZyI6IiIsImJhY2tvZmYiOi03MjAsIm5vbmNlIjoiMTU5MDYwOTEyMzQ1MDE0MEM5Q0RhYUtNckNTUGFmOXRFeFN2MXc9PSJ9","signature":"N/A0+I0qv+v/V+8ti6tf/UPHvSAQBsCskbsv5GJjKxZgK9TtsiZgJ652exr/sIwYWt07Br1kAro/Sx2m/8w9rslXdcaNnmcAoTwLrlrj2DTyLP2gEgVyokVn0jOjxM4ESUaqmo3c1xyqKUhyrZ7XjcYYRIq0i4zU0lMQ8S8+7fk8O03zPs2+OqJ1CEuTyMgu7sZfECxksbQOfRyw+s5fq5kTpWXBRUslA8JASmleFRLiQUBBe0dMSEHb2Hij3G4UMDasSBJkFQIYBTDgrjxJVmLcaUHSBpmTUTFd3/L5J9wN4TkGRo/k9ivmOxlIoSDumT5wFgyfOkSSQRzreFidzTRtdnqPS29H55CZMCKlq9B51/7ey/nMAVI8RwTOTWC9e7AbXKBM6jcRMcKV0tZMR5Z4BkC8FvZcnVp8Rbyr04Ao5PXKncZf3vMPVRaY2OWXDeVGpjWfqkaNhz8LFlECaj5uT8XL2NrsdTbMAPBDmiKeBZio+VnINQmglP0fRE21CwCG1okx/gV05C+85JRRnteLzu6f2v9t7hW9wraDrLkMQj1sY9sxs1iZaf9/f9LNlPgBN7KI9uDaXD0UN6Rv2LBQN+wGf9X7mU1i/O+KthWt43MSuFUgPDId28qLsu6St/7YjxAf8OnDGUweJCsYYn/xH+Mx2W0p4n4QmxdLJWQ="}
[ D 2020-05-27 21:52:03.5579 8672/T6 age/Cor/SecurityUpdateChecker.h:680 ]: data content (signature OK): {
"backoff" : -720,
"log" : "",
"nonce" : "1590609123450140C9CDaaKMrCSPaf9tExSv1w==",
"update" : 0
}
[ N 2020-05-27 21:52:03.5579 8672/T6 age/Cor/SecurityUpdateChecker.h:519 ]: Security update check: no update found (next check in 24 hours)
[ D 2020-05-27 21:52:04.4408 8672/T4 age/Cor/App/Poo/AnalyticsCollection.cpp:116 ]: Analytics collection time...
[ D 2020-05-27 21:52:04.4408 8672/T4 age/Cor/App/Poo/AnalyticsCollection.cpp:143 ]: Collecting process metrics
[ D 2020-05-27 21:52:04.4409 8672/T4 age/Cor/App/Poo/AnalyticsCollection.cpp:151 ]: Collecting system metrics
[ D 2020-05-27 21:52:04.4411 8672/T4 age/Cor/App/Poo/AnalyticsCollection.cpp:69 ]: Analytics collection done; next analytics collection in 0.559 sec
[ D 2020-05-27 21:52:05.0003 8672/T4 age/Cor/App/Poo/AnalyticsCollection.cpp:116 ]: Analytics collection time...
[ D 2020-05-27 21:52:05.0003 8672/T4 age/Cor/App/Poo/AnalyticsCollection.cpp:143 ]: Collecting process metrics
[ D 2020-05-27 21:52:05.0003 8672/T4 age/Cor/App/Poo/AnalyticsCollection.cpp:151 ]: Collecting system metrics
[ D 2020-05-27 21:52:05.0005 8672/T4 age/Cor/App/Poo/AnalyticsCollection.cpp:69 ]: Analytics collection done; next analytics collection in 4.999 sec
[ D 2020-05-27 21:52:06.4166 8669/T6 Ser/Server.h:691 ]: [WatchdogApiServer] Updating statistics
[...]
[ D 2020-05-27 21:53:30.0001 8672/T4 age/Cor/App/Poo/AnalyticsCollection.cpp:143 ]: Collecting process metrics
[ D 2020-05-27 21:53:30.0003 8672/T4 age/Cor/App/Poo/AnalyticsCollection.cpp:151 ]: Collecting system metrics
[ D 2020-05-27 21:53:30.0005 8672/T4 age/Cor/App/Poo/AnalyticsCollection.cpp:69 ]: Analytics collection done; next analytics collection in 4.999 sec
[ D 2020-05-27 21:53:30.0040 8672/Ta age/Cor/Con/TurboCaching.h:246 ]: Clearing turbocache
[ D 2020-05-27 21:53:30.0040 8672/Ta Ser/Server.h:691 ]: [ServerThr.2] Updating statistics
[ D 2020-05-27 21:53:30.0040 8672/Td age/Cor/Con/TurboCaching.h:246 ]: Clearing turbocache
[ D 2020-05-27 21:53:30.0040 8672/Td Ser/Server.h:691 ]: [ServerThr.3] Updating statistics
[ D 2020-05-27 21:53:30.0041 8669/T6 Ser/Server.h:691 ]: [WatchdogApiServer] Updating statistics
[ D 2020-05-27 21:53:30.0047 8672/Th Ser/Server.h:691 ]: [ApiServer] Updating statistics
[ D 2020-05-27 21:53:30.0048 8672/Tf age/Cor/Con/TurboCaching.h:246 ]: Clearing turbocache
[ D 2020-05-27 21:53:30.0048 8672/Tf Ser/Server.h:691 ]: [ServerThr.4] Updating statistics
[ D 2020-05-27 21:53:30.0048 8672/T8 age/Cor/Con/TurboCaching.h:246 ]: Clearing turbocache
[ D 2020-05-27 21:53:30.0048 8672/T8 Ser/Server.h:691 ]: [ServerThr.1] Updating statistics
[ D 2020-05-27 21:53:33.5621 8672/Tj age/Cor/Spa/Han/Perform.h:1782 ]: [App 8714 journey] Loading state from /tmp/passenger.spawn.XXXXiiB4Mv/response
[ D 2020-05-27 21:53:33.5622 8672/Tj age/Cor/Spa/Han/Perform.h:1208 ]: [App 8714 journey] Step SUBPROCESS_BEFORE_FIRST_EXEC: setting state to STEP_PERFORMED
[ D 2020-05-27 21:53:33.5622 8672/Tj age/Cor/Spa/Han/Perform.h:1419 ]: [App 8714 journey] Step SUBPROCESS_BEFORE_FIRST_EXEC: monotonic begin time is "8506.599584"
[ D 2020-05-27 21:53:33.5622 8672/Tj age/Cor/Spa/Han/Perform.h:1441 ]: [App 8714 journey] Step SUBPROCESS_BEFORE_FIRST_EXEC: monotonic end time is "8506.599584"
[ D 2020-05-27 21:53:33.5622 8672/Tj age/Cor/Spa/Han/Perform.h:1208 ]: [App 8714 journey] Step SUBPROCESS_SPAWN_ENV_SETUPPER_BEFORE_SHELL: setting state to STEP_PERFORMED
[ D 2020-05-27 21:53:33.5623 8672/Tj age/Cor/Spa/Han/Perform.h:1419 ]: [App 8714 journey] Step SUBPROCESS_SPAWN_ENV_SETUPPER_BEFORE_SHELL: monotonic begin time is "8506.599584"
[ D 2020-05-27 21:53:33.5623 8672/Tj age/Cor/Spa/Han/Perform.h:1441 ]: [App 8714 journey] Step SUBPROCESS_SPAWN_ENV_SETUPPER_BEFORE_SHELL: monotonic end time is "8506.618584"
[ D 2020-05-27 21:53:33.5623 8672/Tj age/Cor/Spa/Han/Perform.h:1208 ]: [App 8714 journey] Step SUBPROCESS_OS_SHELL: setting state to STEP_NOT_STARTED
[ D 2020-05-27 21:53:33.5623 8672/Tj age/Cor/Spa/Han/Perform.h:1419 ]: [App 8714 journey] Step SUBPROCESS_OS_SHELL: monotonic begin time is "8506.632584"
[ D 2020-05-27 21:53:33.5623 8672/Tj age/Cor/Spa/Han/Perform.h:1441 ]: [App 8714 journey] Step SUBPROCESS_OS_SHELL: monotonic end time is "8506.633584"
[ D 2020-05-27 21:53:33.5623 8672/Tj age/Cor/Spa/Han/Perform.h:1208 ]: [App 8714 journey] Step SUBPROCESS_SPAWN_ENV_SETUPPER_AFTER_SHELL: setting state to STEP_PERFORMED
[ D 2020-05-27 21:53:33.5624 8672/Tj age/Cor/Spa/Han/Perform.h:1419 ]: [App 8714 journey] Step SUBPROCESS_SPAWN_ENV_SETUPPER_AFTER_SHELL: monotonic begin time is "8506.625584"
[ D 2020-05-27 21:53:33.5624 8672/Tj age/Cor/Spa/Han/Perform.h:1441 ]: [App 8714 journey] Step SUBPROCESS_SPAWN_ENV_SETUPPER_AFTER_SHELL: monotonic end time is "8506.636584"
[ D 2020-05-27 21:53:33.5624 8672/Tj age/Cor/Spa/Han/Perform.h:1208 ]: [App 8714 journey] Step SUBPROCESS_EXEC_WRAPPER: setting state to STEP_IN_PROGRESS
[ D 2020-05-27 21:53:33.5624 8672/Tj age/Cor/Spa/Han/Perform.h:1419 ]: [App 8714 journey] Step SUBPROCESS_EXEC_WRAPPER: monotonic begin time is "8506.636584"
[ D 2020-05-27 21:53:33.5624 8672/Tj age/Cor/Spa/Han/Perform.h:1450 ]: [App 8714 journey] Step SUBPROCESS_EXEC_WRAPPER: end time is "1590609123.603", monotonic conversion is 8506.679199
[ D 2020-05-27 21:53:33.5625 8672/Tj age/Cor/Spa/Han/Perform.h:1208 ]: [App 8714 journey] Step SUBPROCESS_WRAPPER_PREPARATION: setting state to STEP_IN_PROGRESS
[ D 2020-05-27 21:53:33.5625 8672/Tj age/Cor/Spa/Han/Perform.h:1428 ]: [App 8714 journey] Step SUBPROCESS_WRAPPER_PREPARATION: begin time is "1590609123.603", monotonic conversion is 8506.679198
[ D 2020-05-27 21:53:33.5625 8672/Tj age/Cor/Spa/Han/Perform.h:1450 ]: [App 8714 journey] Step SUBPROCESS_WRAPPER_PREPARATION: end time is "1590609123.627", monotonic conversion is 8506.703198
[ D 2020-05-27 21:53:33.5625 8672/Tj age/Cor/Spa/Han/Perform.h:1208 ]: [App 8714 journey] Step SUBPROCESS_APP_LOAD_OR_EXEC: setting state to STEP_IN_PROGRESS
[ D 2020-05-27 21:53:33.5625 8672/Tj age/Cor/Spa/Han/Perform.h:1428 ]: [App 8714 journey] Step SUBPROCESS_APP_LOAD_OR_EXEC: begin time is "1590609123.627", monotonic conversion is 8506.703198
[ D 2020-05-27 21:53:33.5625 8672/Tj age/Cor/Spa/Han/Perform.h:1454 ]: [App 8714 journey] Step SUBPROCESS_APP_LOAD_OR_EXEC: no end time known
[ D 2020-05-27 21:53:33.5626 8672/Tj age/Cor/Spa/Han/Perform.h:1176 ]: [App 8714 journey] Step SUBPROCESS_LISTEN: state file does not exist
[ E 2020-05-27 21:53:33.5837 8672/Tj age/Cor/App/Implementation.cpp:221 ]: Could not spawn process for application /var/www/vhosts/mydomain.com/httpdocs/home/platform/dist-server: A timeout occurred while spawning an application process.
Error ID: bc43d659
Error details saved to: /tmp/passenger-error-ywMsF5.html
[ D 2020-05-27 21:53:33.5907 8672/Tj age/Cor/App/Gro/ProcessListManagement.cpp:256 ]: Enabling all DISABLING processes with result DR_ERROR
[ D 2020-05-27 21:53:33.5907 8672/Tj age/Cor/App/Gro/SpawningAndRestarting.cpp:194 ]: Spawn loop done
[ D 2020-05-27 21:53:33.5908 8672/T8 age/Cor/Con/TurboCaching.h:246 ]: Clearing turbocache
[ D3 2020-05-27 21:53:33.5908 8672/T8 age/Cor/Con/CheckoutSession.cpp:112 ]: [Client 1-1] Event: sessionCheckedOutFromAnotherThread
[ E 2020-05-27 21:53:33.5908 8672/T8 age/Cor/Con/CheckoutSession.cpp:276 ]: [Client 1-1] Cannot checkout session because a spawning error occurred. The identifier of the error is bc43d659. Please see earlier logs for details about the error.
[ D3 2020-05-27 21:53:33.5922 8672/T8 Ser/FileBufferedChannel.h:1416 ]: [FBC 0x7f04b8000a30] Feeding 247 bytes
[ D3 2020-05-27 21:53:33.5922 8672/T8 Ser/FileBufferedChannel.h:486 ]: [FBC 0x7f04b8000a30] pushBuffer() completed: nbuffers = 1, bytesBuffered = 247
[ D3 2020-05-27 21:53:33.5922 8672/T8 Ser/FileBufferedChannel.h:554 ]: [FBC 0x7f04b8000a30] Reader: reading next
[ D3 2020-05-27 21:53:33.5922 8672/T8 Ser/FileBufferedChannel.h:586 ]: [FBC 0x7f04b8000a30] Reader: found buffer, 247 bytes
[ D3 2020-05-27 21:53:33.5923 8672/T8 Ser/FileBufferedChannel.h:493 ]: [FBC 0x7f04b8000a30] popBuffer() completed: nbuffers = 0, bytesBuffered = 0
[ D3 2020-05-27 21:53:33.5923 8672/T8 Ser/FileBufferedChannel.h:594 ]: [FBC 0x7f04b8000a30] Reader: feeding buffer, 247 bytes
[ D3 2020-05-27 21:53:33.5923 8672/T8 Ser/FileBufferedFdSinkChannel.h:67 ]: [FBC 0x7f04b8000a30] Setting error: errno=32 (Broken pipe)
[ D3 2020-05-27 21:53:33.5923 8672/T8 Ser/FileBufferedChannel.h:1201 ]: [FBC 0x7f04b8000a30] Waiting until underlying channel becomes idle for error feeding
[ D3 2020-05-27 21:53:33.5923 8672/T8 Ser/Server.h:675 ]: [Client 1-1] Event: onClientOutputError
[ I 2020-05-27 21:53:33.5923 8672/T8 Ser/Server.h:1079 ]: [Client 1-1] Disconnecting client with error: client socket write error: Broken pipe (errno=32)
[ D2 2020-05-27 21:53:33.5923 8672/T8 Ser/Server.h:1046 ]: [Client 1-1] Disconnecting; there are now 0 active clients
[ D3 2020-05-27 21:53:33.5923 8672/T8 Ser/FileBufferedChannel.h:1460 ]: [FBC 0x7f04b80012c8] Deinitialize
[ D3 2020-05-27 21:53:33.5924 8672/T8 Ser/HttpServer.h:840 ]: [Client 1-1] Request refcount decreased; it is now 1
[ D3 2020-05-27 21:53:33.5924 8672/T8 Ser/FileBufferedChannel.h:1460 ]: [FBC 0x7f04b8000a30] Deinitialize
[ D2 2020-05-27 21:53:33.5924 8672/T8 Ser/Server.h:1056 ]: [Client 1-1] Closing client file descriptor: 53
[ D3 2020-05-27 21:53:33.5924 8672/T8 Ser/Server.h:1067 ]: [Client 1-1] Refcount decreased; it is now 1
I see that we don't start a shell wrapper for your app, is there any env variable or ulimit set in your shell which would be needed for your app to start up?
By any chance are you using something like https.createServer(options, app).listen(port);
?
I've just done a deep dive on a very similar issue and the root cause in that case was the app using https, you must use http in your app when using passenger, and have passenger or apache or nginx terminate the ssl.
I think that the problem is related to way of starting generated main.js of angular app by using require(), can be reproduced easily by creating a simple nodejs file with require("./server/main.js");
, the app will not load, but if we execute directly node server/main.js
it works fine.
I think that the problem is related to way of starting generated main.js of angular app by using require(), can be reproduced easily by creating a simple nodejs file with
require("./server/main.js");
, the app will not load, but if we execute directlynode server/main.js
it works fine.
I've found a workaround for this app by using this apache configuration instead of recommended node app configuration:
<IfModule mod_passenger.c>
<Directory "/var/www/vhosts/mysite.es/content/betaweb/browser">
PassengerEnabled on
#PassengerAppType node
#PassengerNodejs "/opt/plesk/node/12/bin/node"
PassengerUser "mysite"
PassengerGroup "psacln"
PassengerAppRoot "/var/www/vhosts/mysite.es/content/betaweb"
#PassengerStartupFile "server/main.js"
PassengerAppStartCommand "/opt/plesk/node/12/bin/node server/main.js"
#PassengerAppEnv "development"
</Directory>
</IfModule>
@arsa-dev and or @mitomm can you provide a minimal sample app?
@mitomm if you are running angular ssr, make sure you also check moduleFilename.includes('node-loader.js')
for calling run()
method. ie
if (moduleFilename === __filename || moduleFilename.includes('iisnode') || moduleFilename.includes('node-loader.js')) {
run()
}
Or try running this method w/o any condition.
@mitomm if you are running angular ssr, make sure you also check
moduleFilename.includes('node-loader.js')
for callingrun()
method. ieif (moduleFilename === __filename || moduleFilename.includes('iisnode') || moduleFilename.includes('node-loader.js')) { run() }
Or try running this method w/o any condition.
Thank You very much I add ""moduleFilename.includes('node-loader.js')"" in if (...) {run( )} condition and it is OK for me 😁
Hi there,
I'm using Passenger 6.0.4 in Standalone mode to start a Node.js application on our server.
The file I'm trying to start is a minified js file generate by Angular Universal for Server Side Rendering (not sure if that's of relevance). If I start node with:
node main.js
everything works perfectly fine.However, if I try to start it with passenger I keep getting a timeout on startup after 90 seconds.
I also uploaded the html error file here. Hopefully that helps: https://s3.eu-central-1.amazonaws.com/public.salonkee.dev/dev/passenger-error-l0D4cx.html
Since everything is working fine locally + on the server if started with
node main.js
I really don't know where this could be coming from.I used passenger with other node applications already and it always worked fine. It's also not related to CPU usage or the like as it's only a test server with not much going on and enough resources.
Any help would be greatly appreciated. Let me know if you need more details.