Apache timeout after every restart

Hi
I have bought a pioneer HSK from Olimex but had to reflash the SD with the image provided by Olimex - here

Every time I restart, apache (and hence freedombox interface) fails to start, receiving a SIGTERM and timeout. Even ‘sudo systemctl reload apache2’ doesn’t work.

The only thing that works is using ‘/etc/init.d/apache2 start’

I’m not a Linux expert so, I would appreciate any support in debugging this issue - what logs should I paste for more information, next steps etc. Any help is appreciated!

Thanks

EDIT:
Here are some relevant entries from /var/log/syslog after restart

May 22 03:37:29 freedombox systemd[1]: apache2.service: Start operation timed out. Terminating.
May 22 03:37:29 freedombox systemd[1]: apache2.service: Control process exited, code=killed, status=15/TERM
May 22 03:37:29 freedombox systemd[1]: apache2.service: Failed with result ‘timeout’.
May 22 03:38:29 freedombox /usr/bin/plinth[336]: Module load order - [‘apache’, ‘api’, ‘avahi’, ‘backups’, ‘bind’, ‘cockpit’, ‘firewall’, ‘names’, ‘config’, ‘datetime’, ‘deluge’, ‘diagnostics’, ‘dynamicdns’, ‘ejabberd’, ‘first_boot’, ‘help’, ‘ikiwiki’, ‘infinoted’, ‘jsxc’, ‘letsencrypt’, ‘matrixsynapse’, ‘mediawiki’, ‘minetest’, ‘mldonkey’, ‘monkeysphere’, ‘mumble’, ‘networks’, ‘openvpn’, ‘pagekite’, ‘power’, ‘privoxy’, ‘quassel’, ‘radicale’, ‘roundcube’, ‘searx’, ‘security’, ‘shadowsocks’, ‘sharing’, ‘snapshot’, ‘ssh’, ‘sso’, ‘storage’, ‘syncthing’, ‘tahoe’, ‘tor’, ‘transmission’, ‘ttrss’, ‘upgrades’, ‘users’]

Please, if anyone has any ideas on how to figure this out it’d be great to hear them!

Hi @samael,

It is certainly unusual that trying to start Apache times out. Could you please post the contents of the file /var/log/apache2/error.log and perhaps the output of running journalctl -u apache2?

We can check if Apache is indeed taking too much time to start by checking the difference between the timestamps for messages ‘Starting …’ and ‘Start operation timed out’. If this is true, then I would suspect that perhaps SD card reading is too slow. You can watch IO speed by running iostat -d 1 (part of sysstat package installed with apt install sysstat). Further, you can plugin the SD card into a Linux machine try reading the files from it and see if the copying speed is too slow.

Hi @sunil

The SD card copies at around 75 MB/s on my macbook when burning the image (It’s a sandisk extreme pro 32GB)

Contents of /var/log/apache2/error.log-

[Wed May 22 00:55:16.845411 2019] [mpm_event:notice] [pid 540:tid 3069701552] AH00489: Apache/2.4.38 (Debian) mod_auth_pubtkt/0.13 configured – resuming normal operations
[Wed May 22 00:55:16.846791 2019] [core:notice] [pid 540:tid 3069701552] AH00094: Command line: ‘/usr/sbin/apache2’
[Wed May 22 00:56:57.641204 2019] [mpm_event:notice] [pid 540:tid 3069701552] AH00491: caught SIGTERM, shutting down
[Wed May 22 00:56:57.987022 2019] [ssl:warn] [pid 999:tid 3070074288] AH01909: 127.0.1.1:443:0 server certificate does NOT include an ID which matches the server name
[Wed May 22 00:56:58.143063 2019] [ssl:warn] [pid 1000:tid 3070074288] AH01909: 127.0.1.1:443:0 server certificate does NOT include an ID which matches the server name
[Wed May 22 00:56:58.161694 2019] [mpm_event:notice] [pid 1000:tid 3070074288] AH00489: Apache/2.4.38 (Debian) mod_auth_pubtkt/0.13 OpenSSL/1.1.1b configured – resuming normal operations
[Wed May 22 00:56:58.168987 2019] [core:notice] [pid 1000:tid 3070074288] AH00094: Command line: ‘/usr/sbin/apache2’
[Wed May 22 00:58:36.686161 2019] [mpm_event:notice] [pid 1000:tid 3070074288] AH00493: SIGUSR1 received. Doing graceful restart
AH00558: apache2: Could not reliably determine the server’s fully qualified domain name, using 127.0.1.1. Set the ‘ServerName’ directive globally to suppress this message
[Wed May 22 00:58:36.913464 2019] [ssl:warn] [pid 1000:tid 3070074288] AH01909: 127.0.1.1:443:0 server certificate does NOT include an ID which matches the server name
[Wed May 22 00:58:36.916404 2019] [mpm_event:notice] [pid 1000:tid 3070074288] AH00489: Apache/2.4.38 (Debian) mod_auth_pubtkt/0.13 OpenSSL/1.1.1b configured – resuming normal operations
[Wed May 22 00:58:36.916867 2019] [core:notice] [pid 1000:tid 3070074288] AH00094: Command line: ‘/usr/sbin/apache2’
[Wed May 22 02:59:58.882833 2019] [mpm_event:notice] [pid 1000:tid 3070074288] AH00491: caught SIGTERM, shutting down
[Wed May 22 03:34:08.126903 2019] [ssl:warn] [pid 878:tid 3069734320] AH01909: 127.0.1.1:443:0 server certificate does NOT include an ID which matches the server name
[Wed May 22 03:34:08.276145 2019] [ssl:warn] [pid 879:tid 3069734320] AH01909: 127.0.1.1:443:0 server certificate does NOT include an ID which matches the server name
[Wed May 22 03:34:08.290461 2019] [mpm_event:notice] [pid 879:tid 3069734320] AH00489: Apache/2.4.38 (Debian) mod_auth_pubtkt/0.13 OpenSSL/1.1.1b configured – resuming normal operations
[Wed May 22 03:34:08.290850 2019] [core:notice] [pid 879:tid 3069734320] AH00094: Command line: ‘/usr/sbin/apache2’
[Wed May 22 03:35:01.671126 2019] [mpm_event:notice] [pid 879:tid 3069734320] AH00491: caught SIGTERM, shutting down
[Wed May 22 03:44:13.398040 2019] [ssl:warn] [pid 917:tid 3070033328] AH01909: 127.0.1.1:443:0 server certificate does NOT include an ID which matches the server name
[Wed May 22 03:44:13.541186 2019] [ssl:warn] [pid 918:tid 3070033328] AH01909: 127.0.1.1:443:0 server certificate does NOT include an ID which matches the server name
[Wed May 22 03:44:13.551987 2019] [mpm_event:notice] [pid 918:tid 3070033328] AH00489: Apache/2.4.38 (Debian) mod_auth_pubtkt/0.13 OpenSSL/1.1.1b configured – resuming normal operations
[Wed May 22 03:44:13.552372 2019] [core:notice] [pid 918:tid 3070033328] AH00094: Command line: ‘/usr/sbin/apache2’
[Wed May 22 03:47:52.679100 2019] [mpm_event:notice] [pid 918:tid 3070033328] AH00493: SIGUSR1 received. Doing graceful restart
AH00558: apache2: Could not reliably determine the server’s fully qualified domain name, using 127.0.1.1. Set the ‘ServerName’ directive globally to suppress this message
[Wed May 22 03:47:53.123252 2019] [ssl:warn] [pid 918:tid 3070033328] AH01909: 127.0.1.1:443:0 server certificate does NOT include an ID which matches the server name
[Wed May 22 03:47:53.137811 2019] [mpm_event:notice] [pid 918:tid 3070033328] AH00489: Apache/2.4.38 (Debian) mod_auth_pubtkt/0.13 OpenSSL/1.1.1b configured – resuming normal operations
[Wed May 22 03:47:53.138118 2019] [core:notice] [pid 918:tid 3070033328] AH00094: Command line: ‘/usr/sbin/apache2’
[Wed May 22 03:54:49.601604 2019] [mpm_event:notice] [pid 918:tid 3070033328] AH00491: caught SIGTERM, shutting down
[Wed May 22 04:03:56.638157 2019] [ssl:warn] [pid 1145:tid 3070090672] AH01909: 127.0.1.1:443:0 server certificate does NOT include an ID which matches the server name
[Wed May 22 04:03:56.789999 2019] [ssl:warn] [pid 1146:tid 3070090672] AH01909: 127.0.1.1:443:0 server certificate does NOT include an ID which matches the server name
[Wed May 22 04:03:56.801724 2019] [mpm_event:notice] [pid 1146:tid 3070090672] AH00489: Apache/2.4.38 (Debian) mod_auth_pubtkt/0.13 OpenSSL/1.1.1b configured – resuming normal operations
[Wed May 22 04:03:56.802137 2019] [core:notice] [pid 1146:tid 3070090672] AH00094: Command line: ‘/usr/sbin/apache2’
[Wed May 22 04:06:47.751169 2019] [mpm_event:notice] [pid 1146:tid 3070090672] AH00491: caught SIGTERM, shutting down
[Wed May 22 04:12:14.167386 2019] [ssl:warn] [pid 1045:tid 3069533616] AH01909: 127.0.1.1:443:0 server certificate does NOT include an ID which matches the server name
[Wed May 22 04:12:14.516070 2019] [ssl:warn] [pid 1046:tid 3069533616] AH01909: 127.0.1.1:443:0 server certificate does NOT include an ID which matches the server name
[Wed May 22 04:12:14.552936 2019] [mpm_event:notice] [pid 1046:tid 3069533616] AH00489: Apache/2.4.38 (Debian) mod_auth_pubtkt/0.13 OpenSSL/1.1.1b configured – resuming normal operations
[Wed May 22 04:12:14.558684 2019] [core:notice] [pid 1046:tid 3069533616] AH00094: Command line: ‘/usr/sbin/apache2’
[Wed May 22 04:38:45.157213 2019] [ssl:warn] [pid 1002:tid 3069185456] AH01909: 127.0.1.1:443:0 server certificate does NOT include an ID which matches the server name
[Wed May 22 04:38:45.587366 2019] [ssl:warn] [pid 1003:tid 3069185456] AH01909: 127.0.1.1:443:0 server certificate does NOT include an ID which matches the server name
[Wed May 22 04:38:45.623857 2019] [mpm_event:notice] [pid 1003:tid 3069185456] AH00489: Apache/2.4.38 (Debian) mod_auth_pubtkt/0.13 OpenSSL/1.1.1b configured – resuming normal operations
[Wed May 22 04:38:45.629564 2019] [core:notice] [pid 1003:tid 3069185456] AH00094: Command line: ‘/usr/sbin/apache2’
[Wed May 22 04:38:54.784867 2019] [mpm_event:notice] [pid 1003:tid 3069185456] AH00491: caught SIGTERM, shutting down
[Wed May 22 04:38:55.663877 2019] [ssl:warn] [pid 1071:tid 3069820336] AH01909: 127.0.1.1:443:0 server certificate does NOT include an ID which matches the server name
[Wed May 22 04:38:56.057630 2019] [ssl:warn] [pid 1072:tid 3069820336] AH01909: 127.0.1.1:443:0 server certificate does NOT include an ID which matches the server name
[Wed May 22 04:38:56.093756 2019] [mpm_event:notice] [pid 1072:tid 3069820336] AH00489: Apache/2.4.38 (Debian) mod_auth_pubtkt/0.13 OpenSSL/1.1.1b configured – resuming normal operations
[Wed May 22 04:38:56.108151 2019] [core:notice] [pid 1072:tid 3069820336] AH00094: Command line: ‘/usr/sbin/apache2’
[Wed May 22 05:03:35.349050 2019] [mpm_event:notice] [pid 1072:tid 3069820336] AH00493: SIGUSR1 received. Doing graceful restart
AH00558: apache2: Could not reliably determine the server’s fully qualified domain name, using 127.0.1.1. Set the ‘ServerName’ directive globally to suppress this message
[Wed May 22 05:03:35.632309 2019] [ssl:warn] [pid 1072:tid 3069820336] AH01909: 127.0.1.1:443:0 server certificate does NOT include an ID which matches the server name
[Wed May 22 05:03:35.634981 2019] [mpm_event:notice] [pid 1072:tid 3069820336] AH00489: Apache/2.4.38 (Debian) mod_auth_pubtkt/0.13 OpenSSL/1.1.1b configured – resuming normal operations
[Wed May 22 05:03:35.635318 2019] [core:notice] [pid 1072:tid 3069820336] AH00094: Command line: ‘/usr/sbin/apache2’

Output of ‘journalctl -u apache2’ -

– Logs begin at Wed 2019-05-22 04:34:29 UTC, end at Wed 2019-05-22 17:57:23 UTC. –
May 22 04:35:00 freedombox systemd[1]: Starting The Apache HTTP Server…
May 22 04:35:01 freedombox apachectl[767]: AH00558: apache2: Could not reliably determine the server’s fully qualified domain name, using 12
May 22 04:36:36 freedombox systemd[1]: apache2.service: Start operation timed out. Terminating.
May 22 04:36:36 freedombox systemd[1]: apache2.service: Control process exited, code=killed, status=15/TERM
May 22 04:36:36 freedombox systemd[1]: apache2.service: Failed with result ‘timeout’.
May 22 04:36:36 freedombox systemd[1]: Failed to start The Apache HTTP Server.
May 22 04:38:44 freedombox systemd[1]: Starting The Apache HTTP Server…
May 22 04:38:45 freedombox apachectl[999]: AH00558: apache2: Could not reliably determine the server’s fully qualified domain name, using 12
May 22 04:38:45 freedombox systemd[1]: Started The Apache HTTP Server.
May 22 04:38:53 freedombox systemd[1]: Stopping The Apache HTTP Server…
May 22 04:38:54 freedombox apachectl[1063]: AH00558: apache2: Could not reliably determine the server’s fully qualified domain name, using 1
May 22 04:38:54 freedombox systemd[1]: apache2.service: Succeeded.
May 22 04:38:54 freedombox systemd[1]: Stopped The Apache HTTP Server.
May 22 04:38:54 freedombox systemd[1]: Starting The Apache HTTP Server…
May 22 04:38:55 freedombox apachectl[1068]: AH00558: apache2: Could not reliably determine the server’s fully qualified domain name, using 1
May 22 04:38:55 freedombox systemd[1]: Started The Apache HTTP Server.
May 22 05:03:34 freedombox systemd[1]: Reloading The Apache HTTP Server.
May 22 05:03:35 freedombox apachectl[2223]: AH00558: apache2: Could not reliably determine the server’s fully qualified domain name, using 1
May 22 05:03:35 freedombox systemd[1]: Reloaded The Apache HTTP Server.

Thanks for the info, this helps a lot. We need to debug further.

It looks starting at 04:36 failed but after that starting at 04:38 succeeded and reloading at 05:03 succeeded as well. When the failure happened, there was nothing in apache error.log which leads me to believe that Apache didn’t get control at all or failed very early. Also it certainly is a timeout with about 95 seconds between logs messages.

I see the following message Could not reliably determine the server’s fully qualified domain name, using 1. Did you set your hostname and domain name properly in FreedomBox interface? If they are unusual, could you please try to set them to something simple? (they don’t have to be a valid, perhaps something like: freedombox and freedombox.example). Did the problem start after some customization such as domain name? Were you able to get web interface of FreedomBox on first boot (to be able to complete the first run wizard)?

On the Pioneer Kit, apart from using a different SD card, did you make any other changes? Does this problem with the default SD card provided with the Pioneer Kit? (it is fine to reflash it using the image you pointed to).

Does Apache fails to start only during boot and succeed if you do systemctl start apache2?

Have you customized Apache configuration manually?

After system boots, do you see another service failures? You can run systemctl and check the output.

Host was always (by default) freedombox but I had not set a domain (as it implied to use a FQDN which I don’t have yet). Interface started fine at first boot. Problem appeared at first reboot.

However, I just tried to use your example of freedombox.example and it did not work.

No other changes whatsoever other than a different SD with the image from the link!

This problem did not occur on the “default” image loaded on the default SD card which worked fine.
The entire reason I abandoned that and created a new one was because cockpit was not working (still doesnt, and I think it’s just broken on freedombox, however this is a separate issue).

I did not try flashing the default card with the image from the link though as I didn’t think the SD card should cause an Apache issue (seems more like an image thing). However, I have tested that the default SD card is 1/3 the speed on the Sandisk Extreme Pro that I am using. SO it should not be related to speed!

Yes it fails only during boot, and yet is starts with ‘systemctl start apache2’

No

There is only one other failure - " php7.3-fpm.service loaded failed failed The PHP 7.3 FastCGI Proce"
systemctl statys pfp7/3-fpm also gives same as apache2 below -

May 24 05:22:41 freedombox systemd[1]: Starting The PHP 7.3 FastCGI Process Manager…
May 24 05:24:17 freedombox systemd[1]: php7.3-fpm.service: Start operation timed out. Terminating.
May 24 05:24:17 freedombox systemd[1]: php7.3-fpm.service: Main process exited, code=killed, status=15/TERM
May 24 05:24:17 freedombox systemd[1]: php7.3-fpm.service: Failed with result ‘timeout’.
May 24 05:24:17 freedombox systemd[1]: Failed to start The PHP 7.3 FastCGI Process Manager.

[…]

This problem did not occur on the “default” image loaded on the default
SD card which worked fine.
The entire reason I abandoned that and created a new one was because
cockpit was not working (still doesnt, and I think it’s just broken on
freedombox, however this is a separate issue).

Pioneer image is the same as what was shipped with kits. There shouldn’t
be any difference there. Perhaps trying another image reflash on the new
card is worth a try if you don’t already have a lot of data.

Also we have confirmed that Cockpit issue comes up only when you try to
access using an IP address. If you configure a domain name and use the
domain name to access cockpit, then the problem is not present.

I did not try flashing the default card with the image from the link
though as I didn’t think the SD card should cause an Apache issue (seems
more like an image thing). However, I have tested that the default SD
card is 1/3 the speed on the Sandisk Extreme Pro that I am using. SO it
should not be related to speed!

Indeed.

[…]

There is only one other failure - " php7.3-fpm.service loaded failed
failed The PHP 7.3 FastCGI Proce"
systemctl statys pfp7/3-fpm also gives same as apache2 below -

May 24 05:22:41 freedombox systemd[1]: Starting The PHP 7.3 FastCGI
Process Manager…
May 24 05:24:17 freedombox systemd[1]: php7.3-fpm.service: Start
operation timed out. Terminating.
May 24 05:24:17 freedombox systemd[1]: php7.3-fpm.service: Main
process exited, code=killed, status=15/TERM
May 24 05:24:17 freedombox systemd[1]: php7.3-fpm.service: Failed
with result ‘timeout’.
May 24 05:24:17 freedombox systemd[1]: Failed to start The PHP 7.3
FastCGI Process Manager.

This is interesting. Both Apache and php-fpm are timing out. Php-fpm
will not cause any issues for you untill you install PHP applications
like MediaWiki, Roundcube etc.

Thank you for the extensive information you have provided so far.