EspoCRM doesn't come online after server reboot

[msbt]

Just rebooted a server with three EspoCRM instances and one of those just wouldn't come online. The other two were fine, just the third one was stuck somehow. Restarting the app didn't work, starting and stopping didn't work, only entering recovery mode and exiting did the trick. This is the startup error (weird part: it said it was "Running" after restart, even though it was showing the Cloudron error page):

...
Jul 18 12:07:51 => Running cron job
Jul 18 12:07:51 => Starting EspoCRM
Jul 18 12:07:52 2020-07-18 10:07:52,077 CRIT Supervisor running as root (no user in config file)
Jul 18 12:07:52 2020-07-18 10:07:52,078 INFO Included extra file "/etc/supervisor/conf.d/web.conf" during parsing
Jul 18 12:07:52 2020-07-18 10:07:52,078 INFO Included extra file "/etc/supervisor/conf.d/ws.conf" during parsing
Jul 18 12:07:52 2020-07-18 10:07:52,088 INFO RPC interface 'supervisor' initialized
Jul 18 12:07:52 2020-07-18 10:07:52,088 CRIT Server 'unix_http_server' running without any HTTP authentication checking
Jul 18 12:07:52 2020-07-18 10:07:52,088 INFO supervisord started with pid 1
Jul 18 12:07:53 2020-07-18 10:07:53,093 INFO spawned: 'web' with pid 34
Jul 18 12:07:53 2020-07-18 10:07:53,102 INFO spawned: 'ws' with pid 35
Jul 18 12:07:53 AH00558: apache2: Could not reliably determine the server's fully qualified domain name, using 172.18.0.12. Set the 'ServerName' directive globally to suppress this message
Jul 18 12:07:53 httpd (pid 35) already running
Jul 18 12:07:53 2020-07-18 10:07:53,189 INFO exited: web (exit status 0; not expected)
Jul 18 12:07:54 2020-07-18 10:07:54,193 INFO spawned: 'web' with pid 39
Jul 18 12:07:54 2020-07-18 10:07:54,194 INFO success: ws entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
Jul 18 12:07:54 AH00558: apache2: Could not reliably determine the server's fully qualified domain name, using 172.18.0.12. Set the 'ServerName' directive globally to suppress this message
Jul 18 12:07:54 httpd (pid 35) already running
Jul 18 12:07:54 2020-07-18 10:07:54,247 INFO exited: web (exit status 0; not expected)
Jul 18 12:07:56 2020-07-18 10:07:56,254 INFO spawned: 'web' with pid 41
Jul 18 12:07:56 AH00558: apache2: Could not reliably determine the server's fully qualified domain name, using 172.18.0.12. Set the 'ServerName' directive globally to suppress this message
Jul 18 12:07:56 httpd (pid 35) already running
Jul 18 12:07:56 2020-07-18 10:07:56,310 INFO exited: web (exit status 0; not expected)
Jul 18 12:07:59 2020-07-18 10:07:59,319 INFO spawned: 'web' with pid 43
Jul 18 12:07:59 AH00558: apache2: Could not reliably determine the server's fully qualified domain name, using 172.18.0.12. Set the 'ServerName' directive globally to suppress this message
Jul 18 12:07:59 httpd (pid 35) already running
Jul 18 12:07:59 2020-07-18 10:07:59,380 INFO exited: web (exit status 0; not expected)
Jul 18 12:08:00 2020-07-18 10:08:00,382 INFO gave up: web entered FATAL state, too many start retries too quickly

[nebulon]

This looks like a bug in the apache handling through supervisor. I will see how this can be fixed.

[nebulon]

This should be fixed with latest version

[msbt]

thanks @nebulon, will keep you posted!

[jensbee4]

Hi,
got the same situation. In the morning when we get to work sometime ESPO show time out.
When i restart the app it does not work after restart and i got the same Log:

Sep 11 08:54:28 172.18.0.1 - - [11/Sep/2020:06:21:26 +0000] "GET /wss?authToken=25d42c15ebe92b32848bcacdd4afea99&userId=5d7f329de51b1ed1b HTTP/1.1" 200 411 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.102 Safari/537.36"
Sep 11 08:54:28 172.18.0.1 - - [11/Sep/2020:06:25:34 +0000] "GET /wss?authToken=ddaa4f9384347a9dd9cf43adafbedee2&userId=5d81fc47394db142f HTTP/1.1" 200 555 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:80.0) Gecko/20100101 Firefox/80.0"
Sep 11 08:54:28 172.18.0.1 - - [11/Sep/2020:06:49:20 +0000] "GET /wss?authToken=ddaa4f9384347a9dd9cf43adafbedee2&userId=5d81fc47394db142f HTTP/1.1" 200 247 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:80.0) Gecko/20100101 Firefox/80.0"
Sep 11 08:54:28 172.18.0.1 - - [11/Sep/2020:06:25:30 +0000] "GET /wss?authToken=ddaa4f9384347a9dd9cf43adafbedee2&userId=5d81fc47394db142f HTTP/1.1" 200 329 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:80.0) Gecko/20100101 Firefox/80.0"
Sep 11 08:54:28 172.18.0.1 - - [11/Sep/2020:06:37:22 +0000] "GET /wss?authToken=1813560ebf60b4ae00cca88765c9f208&userId=5da5ac83185c2cb8a HTTP/1.1" 200 328 "-" "Mozilla/5.0 (Windows NT 6.3; Win64; x64; rv:80.0) Gecko/20100101 Firefox/80.0"
Sep 11 08:54:28 2020-09-11 06:54:28,974 INFO stopped: ws (exit status 15)
Sep 11 08:54:29 2020-09-11 06:54:29,120 INFO stopped: web (exit status 0)
Sep 11 08:54:31 => Fixing up modules
Sep 11 08:54:31 box:tasks 4621: {"percent":100,"message":"Done"}
Sep 11 08:54:31 box:apptask crm.4pl-intermodal.com updating app with values: {"installationState":"installed","error":null,"health":null}
Sep 11 08:54:31 box:taskworker Task took 2.544 seconds
Sep 11 08:54:31 box:tasks setCompleted - 4621: {"result":null,"error":null}
Sep 11 08:54:31 box:tasks 4621: {"percent":100,"result":null,"error":null}
Sep 11 08:54:31 => update config
Sep 11 08:54:31 => Data version is 5.9.3. Expecting 5.9.3
Sep 11 08:54:31 => Up to date. Nothing to upgrade
Sep 11 08:54:31 => Rebuild backend and clear cache
Sep 11 08:54:33 => Running cron job
Sep 11 08:54:37 => Starting EspoCRM
Sep 11 08:54:37 2020-09-11 06:54:37,316 CRIT Supervisor running as root (no user in config file)
Sep 11 08:54:37 2020-09-11 06:54:37,316 INFO Included extra file "/etc/supervisor/conf.d/web.conf" during parsing
Sep 11 08:54:37 2020-09-11 06:54:37,316 INFO Included extra file "/etc/supervisor/conf.d/ws.conf" during parsing
Sep 11 08:54:37 2020-09-11 06:54:37,336 INFO RPC interface 'supervisor' initialized
Sep 11 08:54:37 2020-09-11 06:54:37,336 CRIT Server 'unix_http_server' running without any HTTP authentication checking
Sep 11 08:54:37 2020-09-11 06:54:37,336 INFO supervisord started with pid 1
Sep 11 08:54:38 2020-09-11 06:54:38,341 INFO spawned: 'web' with pid 36
Sep 11 08:54:38 2020-09-11 06:54:38,349 INFO spawned: 'ws' with pid 37
Sep 11 08:54:38 AH00558: apache2: Could not reliably determine the server's fully qualified domain name, using 172.18.0.4. Set the 'ServerName' directive globally to suppress this message
Sep 11 08:54:38 httpd (pid 39) already running
Sep 11 08:54:38 2020-09-11 06:54:38,631 INFO exited: web (exit status 0; not expected)
Sep 11 08:54:39 2020-09-11 06:54:39,637 INFO spawned: 'web' with pid 41
Sep 11 08:54:39 2020-09-11 06:54:39,639 INFO success: ws entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
Sep 11 08:54:39 AH00558: apache2: Could not reliably determine the server's fully qualified domain name, using 172.18.0.4. Set the 'ServerName' directive globally to suppress this message
Sep 11 08:54:39 httpd (pid 39) already running
Sep 11 08:54:39 2020-09-11 06:54:39,859 INFO exited: web (exit status 0; not expected)
Sep 11 08:54:41 2020-09-11 06:54:41,866 INFO spawned: 'web' with pid 43
Sep 11 08:54:42 AH00558: apache2: Could not reliably determine the server's fully qualified domain name, using 172.18.0.4. Set the 'ServerName' directive globally to suppress this message
Sep 11 08:54:42 httpd (pid 39) already running
Sep 11 08:54:42 2020-09-11 06:54:42,087 INFO exited: web (exit status 0; not expected)
Sep 11 08:54:45 2020-09-11 06:54:45,096 INFO spawned: 'web' with pid 45
Sep 11 08:54:45 AH00558: apache2: Could not reliably determine the server's fully qualified domain name, using 172.18.0.4. Set the 'ServerName' directive globally to suppress this message
Sep 11 08:54:45 httpd (pid 39) already running
Sep 11 08:54:45 2020-09-11 06:54:45,315 INFO exited: web (exit status 0; not expected)
Sep 11 08:54:46 2020-09-11 06:54:46,317 INFO gave up: web entered FATAL state, too many start retries too quickly

The Terminal window is empty. I need to restart the whole Server.

[nebulon]

This looks like some wrong apache process state handling in the package. Can you open a terminal into the app and run rm /run/apache2/apache2.pid then supervisorctl restart web

Ideally keep an eye on the logs while doing that.

[girish]

@jensbee4 said in EspoCRM doesn't come online after server reboot:

The Terminal window is empty. I need to restart the whole Server.

@jensbee4 Does this mean you got it working after you restarted the whole server?

[jensbee4]

@girish said in EspoCRM doesn't come online after server reboot:

@jensbee4 Does this mean you got it working after you restarted the whole server?

Yes, after restarting the Server Espo is available again.
Today i got the same situation.
Espo stopped responding. But now i entered supervisorctl restart web in the Terminal and Espo was available again.

[jensbee4]

Hi,
this is not our main problem. Today we restartet and espocrm came up with the server.

Our problem is that espocrm stops responding. We got a red Timeout message in the espocrm UI.
Using supervisorctl restart web in the Terminal resolves the problem.

I will open an extra THread for this.