[Risolto] Shut down random e improvvisi di Apache...

Salve a tutti ragazzi,

è la prima volta dopo mesi e mesi senza problemi, che il mio webserver presenta improvvisamente il problema in oggetto.
Dallo scorso Sabato 28 Maggio, dopo aver aggiornato il sistema (dnf update) e riavviato (anche il kernel è stato aggiornato, ora siamo alla versione 4.4.9-300.fc23.x86_64), in modo almeno apparentemente random apache mi “abbandona”, diverse volte al giorno (almeno ogni 1 o 2 ore). Per fortuna ho installato e configurato monit, che ho istruito per un riavvio automatico del servizio httpd, ma è chiaro che vorrei capire e risolvere il problema.

Versione di Apache:

Server version: Apache/2.4.18 (Fedora) Server built: Jan 4 2016 08:15:18

Vi fornisco un po’ di informazioni:

  1. Ho impostato SeLinux su Permissive (setenforce 0) e fermato il firewall (systemctl stop firewalld): nulla di fatto

  2. In corrispondenza dell’ultimo crash (o meglio… shut down, sembrerebbe…), poco dopo le 6 di questa mattina:

[root@servercm master]# tail -f /var/log/httpd/error_log [Mon May 30 06:02:06.465497 2016] [core:notice] [pid 24396] AH00094: Command line: '/usr/sbin/httpd -D FOREGROUND' [Mon May 30 06:04:14.846691 2016] [mpm_prefork:notice] [pid 24396] AH00170: caught SIGWINCH, shutting down gracefully [Mon May 30 06:59:55.962673 2016] [core:notice] [pid 14584] SELinux policy enabled; httpd running as context system_u:system_r:httpd_t:s0 [Mon May 30 06:59:56.071415 2016] [alias:warn] [pid 14584] AH00671: The Alias directive in /etc/httpd/conf.d/phpMyAdmin.conf at line 8 will probably never match because it overlaps an earlier Alias. [Mon May 30 06:59:56.071433 2016] [alias:warn] [pid 14584] AH00671: The Alias directive in /etc/httpd/conf.d/phpMyAdmin.conf at line 9 will probably never match because it overlaps an earlier Alias. AH00558: httpd: Could not reliably determine the server's fully qualified domain name, using fe80::d250:99ff:fe84:cc18. Set the 'ServerName' directive globally to suppress this message [Mon May 30 06:59:57.481908 2016] [mpm_prefork:notice] [pid 14584] AH00163: Apache/2.4.18 (Fedora) OpenSSL/1.0.2h-fips PHP/5.6.21 mod_perl/2.0.9 Perl/v5.22.1 configured -- resuming normal operations [Mon May 30 06:59:57.482036 2016] [core:notice] [pid 14584] AH00094: Command line: '/usr/sbin/httpd -D FOREGROUND'

Ovviamente quel “pid 24396” cambia ogni volta, ma il resto del messaggio con AH00170: caught SIGWINCH, shutting down gracefully si ripete identico ad ogni “crash”.

  1. Spazio su disco OK:

File system Dim. Usati Dispon. Uso% Montato su devtmpfs 3,7G 0 3,7G 0% /dev tmpfs 3,7G 0 3,7G 0% /dev/shm tmpfs 3,7G 1,1M 3,7G 1% /run tmpfs 3,7G 0 3,7G 0% /sys/fs/cgroup /dev/mapper/fedora_host12--225--110--95-root 50G 15G 35G 30% / tmpfs 3,7G 88K 3,7G 1% /tmp /dev/sda2 477M 146M 302M 33% /boot /dev/sda1 200M 8,3M 192M 5% /boot/efi /dev/mapper/fedora_host12--225--110--95-home 874G 19G 855G 3% /home tmpfs 747M 0 747M 0% /run/user/0 tmpfs 747M 0 747M 0% /run/user/1001

Tutti gli altri servizi (mariadb, vsftpd, ecc…) sono ok.
Che ne pensate? Non riesco a capire cos’è che dice ad apache di “spegnersi”… Ribadisco che il tutto è iniziato dopo l’aggiornamento.
Fatemi sapere se vi occorrono altri dati.

Non è un crash, è una chiusura “normale”. C’è qualcosa che lo spegne.

Non è che raggiungi MaxRequestPerChild e riavvia il processo? Magari il tuo server viene bombardato di richieste?

Ciao frafra!

Sì è vero in realtà non è un crash… (ho modificato il titolo).

Il problema è che qualunque cosa sia, Apache poi però non si riavvia! Viene chiuso e basta e devo riavviarlo io o a mano o automaticamente tramite monit. Non succedeva fino a sabato… Quanto a MaxRequestPerChild potrei aumentarlo, ma il traffico è grossomodo lo stesso e anzi succede anche di notte quando il traffico è ridotto all’osso…

Ieri è stato 12 ore senza problemi, poi ieri sera lo ha fatto 2 volte in mezz’ora… e anche stanotte e stamattina.

Non riesco a capire cosa e perché spegne (definitivamente) apache…

Update: sto cercando di monitorare cosa succede al processo padre (root) di apache con gbd. Prima dello shutdown ottendo quanto segue:

(gdb) backtrace
#0  0x00007f13a242a883 in __select_nocancel () at ../sysdeps/unix/syscall-template.S:84
#1  0x00007f13a2b3c0c5 in apr_sleep (t=t@entry=1000000) at time/unix/time.c:246
#2  0x0000561f69623751 in ap_wait_or_timeout (status=status@entry=0x7ffc1443e9a8, exitcode=exitcode@entry=0x7ffc1443e9ac, 
    ret=ret@entry=0x7ffc1443e9b0, p=<optimized out>, s=<optimized out>) at mpm_common.c:199
#3  0x00007f1398bdd69f in prefork_run (_pconf=<optimized out>, plog=<optimized out>, s=<optimized out>) at prefork.c:1053
#4  0x0000561f69622dae in ap_run_mpm (pconf=0x561f6b686188, plog=0x561f6b6b33a8, s=0x561f6b6b1450) at mpm_common.c:94
#5  0x0000561f6961c437 in main (argc=2, argv=0x7ffc1443ec88) at main.c:777

Ecco invece cosa mi dà il backtrace di gdb una volta che apache è stato killato:

(gdb) backtrace #0 0x00007f13a242a883 in __select_nocancel () at ../sysdeps/unix/syscall-template.S:84 #1 0x00007f13a2b3c0c5 in apr_sleep (t=t@entry=1000000) at time/unix/time.c:246 #2 0x0000561f69623751 in ap_wait_or_timeout (status=0x7ffc1443e9a8, status@entry=<error reading variable: Cannot access memory at address 0x7ffc1443e990>, exitcode=exitcode@entry=0x7ffc1443e9ac, ret=0x7ffc1443e9b0, ret@entry=<error reading variable: Cannot access memory at address 0x7ffc1443e978>, p=<optimized out>, s=<optimized out>) at mpm_common.c:199 #3 0x00007f1398bdd69f in prefork_run (_pconf=<optimized out>, plog=<optimized out>, s=<optimized out>) at prefork.c:1053 #4 0x0000561f69622dae in ap_run_mpm (pconf=<error reading variable: Cannot access memory at address 0x7ffc1443ea88>, plog=<error reading variable: Cannot access memory at address 0x7ffc1443ea90>, s=<error reading variable: Cannot access memory at address 0x7ffc1443ea98>) at mpm_common.c:94 #5 0x0000561f6961c437 in main (argc=<error reading variable: Cannot access memory at address 0x7ffc1443eb0c>, argv=<error reading variable: Cannot access memory at address 0x7ffc1443eb00>) at main.c:777

Qui ci addentriamo in cose che cominciano ad essere fuori dalla mia portata, chiedo un aiuto a chi è molto più esperto di me per cercare di capire meglio cosa/come indagare e ricostruire dunque quello che succede… (il problema dello shut down si presenta anche provando gli altri mpm, sia worker che event…).

Vediamo se emerge qualcosa:

# dnf history info
# updatedb;locate rpmnew
# journalctl -u httpd -b 0
$ cat /etc/httpd/conf.modules.d/00-systemd.conf

Ciao! Ecco qua:

# dnf history info ID transazione : 77 Ora inizio : Wed Jun 1 21:07:12 2016 rpmdb iniziale : 1060:152518dedcecd75cb066f95636901e4634ed9341 Ora termine : 21:07:20 2016 (8 secondi) rpmdb finale : 1060:63f75cb6161bca0610c14f3ae0681f1974836818 Utente : <master> Codice di uscita : Completato Linea di comando : update Transazione eseguita con: Installati dnf-1.1.9-2.fc23.noarch @updates Installati rpm-4.13.0-0.rc1.13.fc23.x86_64 @updates Pacchetti modificati: Aggiornati phpMyAdmin-4.6.1-1.fc23.noarch @updates Aggiornati 4.6.2-1.fc23.noarch @updates

(ma nel frattempo in questi giorni ho fatto altri aggiornamenti, anche nella speranza di qualche fix…)

# updatedb;locate rpmnew /etc/ssh/sshd_config.rpmnew

Poi, riporto gli ultimi episodi (stamattina presto, ora sono diverse ore che non succede niente… ma non è che c’è un qualche attacco!?!)

giu 02 04:47:40 servercm systemd[1]: Started The Apache HTTP Server. giu 02 05:26:27 servercm systemd[1]: Stopping The Apache HTTP Server... giu 02 05:27:57 servercm systemd[1]: httpd.service: State 'stop-sigterm' timed out. Killing. giu 02 05:27:57 servercm systemd[1]: httpd.service: Main process exited, code=killed, status=9/KILL giu 02 05:27:57 servercm systemd[1]: Stopped The Apache HTTP Server. giu 02 05:27:57 servercm systemd[1]: httpd.service: Unit entered failed state. giu 02 05:27:57 servercm systemd[1]: httpd.service: Failed with result 'signal'. giu 02 05:29:01 servercm systemd[1]: Starting The Apache HTTP Server... giu 02 05:29:01 servercm httpd[3306]: [Thu Jun 02 05:29:01.747625 2016] [alias:warn] [pid 3306] AH00671: The Alias directive in /etc/httpd/c giu 02 05:29:01 servercm httpd[3306]: [Thu Jun 02 05:29:01.747997 2016] [alias:warn] [pid 3306] AH00671: The Alias directive in /etc/httpd/c giu 02 05:29:01 servercm httpd[3306]: AH00558: httpd: Could not reliably determine the server's fully qualified domain name, using fe80::d25 giu 02 05:29:02 servercm systemd[1]: Started The Apache HTTP Server. giu 02 06:03:48 servercm systemd[1]: Stopping The Apache HTTP Server... giu 02 06:03:54 servercm systemd[1]: Stopped The Apache HTTP Server. giu 02 06:03:57 servercm systemd[1]: Starting The Apache HTTP Server... giu 02 06:04:00 servercm httpd[7205]: [Thu Jun 02 06:04:00.784647 2016] [alias:warn] [pid 7205] AH00671: The Alias directive in /etc/httpd/c giu 02 06:04:00 servercm httpd[7205]: [Thu Jun 02 06:04:00.860033 2016] [alias:warn] [pid 7205] AH00671: The Alias directive in /etc/httpd/c giu 02 06:04:01 servercm httpd[7205]: AH00558: httpd: Could not reliably determine the server's fully qualified domain name, using fe80::d25 giu 02 06:04:08 servercm systemd[1]: Started The Apache HTTP Server. giu 02 06:16:27 servercm systemd[1]: Stopping The Apache HTTP Server... giu 02 06:17:57 servercm systemd[1]: httpd.service: State 'stop-sigterm' timed out. Killing. giu 02 06:17:57 servercm systemd[1]: httpd.service: Main process exited, code=killed, status=9/KILL giu 02 06:17:57 servercm systemd[1]: Stopped The Apache HTTP Server. giu 02 06:17:57 servercm systemd[1]: httpd.service: Unit entered failed state. giu 02 06:17:57 servercm systemd[1]: httpd.service: Failed with result 'signal'. giu 02 06:18:59 servercm systemd[1]: Starting The Apache HTTP Server... giu 02 06:19:00 servercm httpd[17491]: [Thu Jun 02 06:19:00.187554 2016] [alias:warn] [pid 17491] AH00671: The Alias directive in /etc/httpd giu 02 06:19:00 servercm httpd[17491]: [Thu Jun 02 06:19:00.187855 2016] [alias:warn] [pid 17491] AH00671: The Alias directive in /etc/httpd giu 02 06:19:00 servercm httpd[17491]: AH00558: httpd: Could not reliably determine the server's fully qualified domain name, using fe80::d2 giu 02 06:19:01 servercm systemd[1]: Started The Apache HTTP Server. giu 02 06:29:18 servercm systemd[1]: Stopping The Apache HTTP Server... giu 02 06:29:22 servercm systemd[1]: Stopped The Apache HTTP Server. giu 02 06:29:22 servercm systemd[1]: Starting The Apache HTTP Server... giu 02 06:29:23 servercm httpd[20686]: [Thu Jun 02 06:29:23.288456 2016] [alias:warn] [pid 20686] AH00671: The Alias directive in /etc/httpd giu 02 06:29:23 servercm httpd[20686]: [Thu Jun 02 06:29:23.288622 2016] [alias:warn] [pid 20686] AH00671: The Alias directive in /etc/httpd giu 02 06:29:23 servercm httpd[20686]: AH00558: httpd: Could not reliably determine the server's fully qualified domain name, using fe80::d2 giu 02 06:29:24 servercm systemd[1]: Started The Apache HTTP Server.

[code]# cat /etc/httpd/conf.modules.d/00-systemd.conf

This file configures systemd module:

LoadModule systemd_module modules/mod_systemd.so[/code]

–> Aggiornamento: dopo poco più di 10 ore ecco di nuovo:

# journalctl -u httpd -b 0 giu 02 16:44:38 servercm systemd[1]: Stopping The Apache HTTP Server... giu 02 16:46:08 servercm systemd[1]: httpd.service: State 'stop-sigterm' timed out. Killing. giu 02 16:46:08 servercm systemd[1]: httpd.service: Main process exited, code=killed, status=9/KILL giu 02 16:46:08 servercm systemd[1]: Stopped The Apache HTTP Server. giu 02 16:46:08 servercm systemd[1]: httpd.service: Unit entered failed state. giu 02 16:46:08 servercm systemd[1]: httpd.service: Failed with result 'signal'. giu 02 16:46:47 servercm systemd[1]: Starting The Apache HTTP Server... giu 02 16:46:47 servercm httpd[18318]: [Thu Jun 02 16:46:47.656251 2016] [alias:warn] [pid 18318] AH00671: The Alias directive in /etc/httpd giu 02 16:46:47 servercm httpd[18318]: [Thu Jun 02 16:46:47.656545 2016] [alias:warn] [pid 18318] AH00671: The Alias directive in /etc/httpd giu 02 16:46:47 servercm httpd[18318]: AH00558: httpd: Could not reliably determine the server's fully qualified domain name, using fe80::d2 giu 02 16:46:49 servercm systemd[1]: Started The Apache HTTP Server.

Stavolta ero al terminale e ho riavviato manualmente, anziché aspettare che agisse monit. Ma la sensazione che ho avuto (non so se è stato un caso) è che quando ho digitato “service httpd restart”, di solito basta iniziare ad esempio con ht… poi fare “tab” per fa apparire automaticamente httpd in maniera completa, mentre stavolta no, ho dovuto digitare httpd per esteso perché il tab non faceva nulla… mah… magari è stato un caso, o un problema di rete, visto che è il terminale remoto del webserver…

Update:

ho aggiornato al kernel 4.5.5-201.fc23.x86_64 (+ reboot), niente da fare.

# journalctl -u httpd -b 0 -- Logs begin at mar 2015-12-01 17:56:41 CET, end at ven 2016-06-03 08:21:31 CEST. -- giu 03 06:57:46 servercm systemd[1]: Starting The Apache HTTP Server... giu 03 06:57:50 servercm httpd[1190]: [Fri Jun 03 06:57:50.005098 2016] [alias:warn] [pid 1190] AH00671: The Alias directive in /etc/httpd/c giu 03 06:57:50 servercm httpd[1190]: [Fri Jun 03 06:57:50.005361 2016] [alias:warn] [pid 1190] AH00671: The Alias directive in /etc/httpd/c giu 03 06:57:50 servercm httpd[1190]: AH00558: httpd: Could not reliably determine the server's fully qualified domain name, using ::1. Set giu 03 06:57:52 servercm systemd[1]: Started The Apache HTTP Server. giu 03 08:19:10 servercm systemd[1]: Stopping The Apache HTTP Server... giu 03 08:20:40 servercm systemd[1]: httpd.service: State 'stop-sigterm' timed out. Killing. giu 03 08:20:40 servercm systemd[1]: httpd.service: Main process exited, code=killed, status=9/KILL giu 03 08:20:40 servercm systemd[1]: httpd.service: Unit entered failed state. giu 03 08:20:40 servercm systemd[1]: httpd.service: Failed with result 'signal'. giu 03 08:20:40 servercm systemd[1]: Starting The Apache HTTP Server... giu 03 08:20:41 servercm httpd[18500]: [Fri Jun 03 08:20:41.606225 2016] [alias:warn] [pid 18500] AH00671: The Alias directive in /etc/httpd giu 03 08:20:41 servercm httpd[18500]: [Fri Jun 03 08:20:41.606635 2016] [alias:warn] [pid 18500] AH00671: The Alias directive in /etc/httpd giu 03 08:20:41 servercm httpd[18500]: AH00558: httpd: Could not reliably determine the server's fully qualified domain name, using fe80::d2 giu 03 08:20:43 servercm systemd[1]: Started The Apache HTTP Server.

Non so più dove sbattere la testa… :gratt:

Sicuro che la tua applicazione di monitoring non lo chiuda? Tra l’altro, systemd si preoccupa già di riavviare i servizi se questi muoiono.

Hai ragione! Monit ci mette del suo! Infatti ho provato a disabilitarlo per un po’ (–> niente “crash” di apache, ricordando anche che nel frattempo ho aggiornato il kernel) e a configurarlo in modo tale da non riavviare apache, ma facendomi inviare solo degli alert e in effetti mi sta di tanto in tanto inviando dei messaggi di fallimento di apache anche se non è vero (magari perché ha fallito un check quando invece era tutto ok…)!

Resta però il fatto che tale monitoraggio l’ho cominciato dopo che il problema si è presentato… (magari fu un “caso” estemporaneo su cui mi sono allarmato troppo!?) :rolleyes:

Comunque ora continuo a provare senza che monit “agisca” e vediamo che succede…

In seguito, se necessario, sempre con monit disattivato, proverò ad usare systemd direttamente, come giustamente ricordi tu (monit potrà essere ancora utile per altri monitoraggi+alert come cpu, ram, etc…), modificando /etc/systemd/system/httpd.service aggiungendo in [Service]

Restart=always
RestartSec=3

per poi fare systemctl daemon-reload e service httpd restart.

Bene :slight_smile: