Rotação do Log do Beanstalk Elástico Causando o Reinício do Apache

3

Já trabalhei com AWS Elastic Beanstalk - o Apache está reiniciando constantemente

Nossas instâncias do beanstalk elástico estão relatando a seguinte mensagem no error_log

[Mon Jun 26 22:01:01.878892 2017] [mpm_prefork:notice] [pid 8595] AH00173: SIGHUP received.  Attempting to restart
*** Error in (wsgi:wsgi)    ': double free or corruption (out): 0x00007f564cced560 ***

por vezes, a sequência de erros será mais parecida com esta:

[Tue Jun 27 00:01:01.215260 2017] [:error] [pid 6429] [remote XX.XXX.XX.195:29773] mod_wsgi (pid=6429): Exception occurred processing WSGI script '/opt/python/current/app/site/settings/wsgi/__init__.py'.
[Tue Jun 27 00:01:01.215320 2017] [:error] [pid 6429] [remote XX.XXX.XX.195:29773] OSError: failed to write data
[Tue Jun 27 00:01:01.222407 2017] [:error] [pid 6430] [remote XX.XXX.XX.60:53313] mod_wsgi (pid=6430): Exception occurred processing WSGI script '/opt/python/current/app/site/settings/wsgi/__init__.py'.
[Tue Jun 27 00:01:01.222460 2017] [:error] [pid 6430] [remote XX.XXX.XX.60:53313] OSError: failed to write data
[Tue Jun 27 00:01:04.554810 2017] [core:warn] [pid 8595] AH00045: child process 7614 still did not exit, sending a SIGTERM
[Tue Jun 27 00:01:04.554850 2017] [core:warn] [pid 8595] AH00045: child process 7615 still did not exit, sending a SIGTERM
[Tue Jun 27 00:01:05.555958 2017] [mpm_prefork:notice] [pid 8595] AH00173: SIGHUP received.  Attempting to restart
*** Error in (wsgi:wsgi)    ': double free or corruption (out): 0x00007f5640cae900 ***
*** Error in (wsgi:wsgi)    ': double free or corruption (out): 0x00007f78649b7970 ***

Isso vai continuar, quase a cada hora. A mensagem comum é:

[Mon Jun 26 22:01:01.878892 2017] [mpm_prefork:notice] [pid 8595] AH00173: SIGHUP received.  Attempting to restart

Eu procurei pelo bloco mpm_prefork module conf ... e não há um, então todos os padrões estão sendo usados.

Eu procurei o comando logrotation sendo executado por elastic beanstalk

/var/log/httpd/* {
size 10M
missingok
notifempty
rotate 5
sharedscripts
compress
dateext
dateformat -%s
create
postrotate
    /sbin/service httpd reload > /dev/null 2>/dev/null || true
endscript
olddir /var/log/httpd/rotated
}

Coisas bastante padronizadas. Meu entendimento de reload é uma tentativa de reinicialização ...

Eu posso acionar manualmente a mensagem de erro executando sudo apachectl -k restart , embora eu não consiga encontrar onde isso seria executado durante a rotação do log.

Temos serviços downstream que parecem estar lançando exceções no ponto em que esse servidor desconecta todas as suas conexões.

Então, minha pergunta é: o que mais poderia estar causando o SIGHUP dentro do mpm_prefork durante logrotate ? Tanto quanto eu posso dizer, isso não deve estar acontecendo fora de uma condição de erro.

Apache / 2.4.18 (Amazon) mod_wsgi / 3.5 Python / 3.4.3

    
por samazi 27.06.2017 / 08:21

1 resposta

3

Em resumo, parece que a configuração atual do logrotation do Elastic Beanstalk está quebrada, o que causa tempo de inatividade do serviço, 504 Tempo Limite do Gateway . Vamos dar uma olhada.

Reprodução

Criamos o aplicativo Python WSGI mais simples.

application.py

import time


def application(environ, start_response):
    # somewhat realistic response duration
    time.sleep(0.5)

    status = '200 OK'
    response_headers = [('Content-type', 'text/plain')]
    start_response(status, response_headers)
    return [b'Hello world!\n']

Copie para application.zip . Em seguida, crie o aplicativo e o ambiente do Elastic Beanstalk Python e faça o upload do arquivo. Certifique-se de usar um par de chaves que você possui. Deixe outras configurações padrão. Espere até que seja feito (vários minutos).

ssh na instância subjacente do EC2 (consulte o identificador de instância no log do EB). Tipo (logrotate post-action de httpd , veja abaixo):

sudo /sbin/service httpd reload

Em seguida, na sua máquina, execute:

siege -v -b -c 10 -t 10S http://your-test-eb.you-aws-region.elasticbeanstalk.com/

Enquanto executa, repita o comando reload algumas vezes.

Então espera-se que você veja algo como o seguinte:

** SIEGE 3.0.8
** Preparing 10 concurrent users for battle.
The server is now under siege...
HTTP/1.1 200   0.63 secs:      13 bytes ==> GET  /
HTTP/1.1 200   0.65 secs:      13 bytes ==> GET  /
HTTP/1.1 200   0.64 secs:      13 bytes ==> GET  /
HTTP/1.1 200   0.60 secs:      13 bytes ==> GET  /
...

Veja o que acontece quando você usa reload .

HTTP/1.1 504   0.06 secs:       0 bytes ==> GET  /
HTTP/1.1 504   0.07 secs:       0 bytes ==> GET  /
HTTP/1.1 504   0.08 secs:       0 bytes ==> GET  /
HTTP/1.1 504   0.10 secs:       0 bytes ==> GET  /
HTTP/1.1 504   0.11 secs:       0 bytes ==> GET  /
HTTP/1.1 504   0.66 secs:       0 bytes ==> GET  /
HTTP/1.1 504   0.19 secs:       0 bytes ==> GET  /
HTTP/1.1 504   0.20 secs:       0 bytes ==> GET  /
HTTP/1.1 504   0.09 secs:       0 bytes ==> GET  /

Em seguida, ele se recupera.

HTTP/1.1 200   1.25 secs:      13 bytes ==> GET  /
HTTP/1.1 200   1.24 secs:      13 bytes ==> GET  /
HTTP/1.1 200   1.26 secs:      13 bytes ==> GET  /
...

Lifting the server siege..      done.

Transactions:                 75 hits
Availability:              81.52 %
Elapsed time:               9.40 secs
Data transferred:           0.00 MB
Response time:              1.21 secs
Transaction rate:           7.98 trans/sec
Throughput:             0.00 MB/sec
Concurrency:                9.68
Successful transactions:      75
Failed transactions:          17
Longest transaction:        4.27
Shortest transaction:       0.06

Observe que o ELB não parece ter nenhum efeito sobre o problema, e o mesmo pode ser reproduzido com duas sessões SSH para o EC2 subjacente e (o Amazon AMI não possui siege ):

ab -v 4 -c 10 -t 10 http://your-test-eb.you-aws-region.elasticbeanstalk.com/

Causa

/etc/cron.hourly/cron.logrotate.elasticbeanstalk.httpd.conf

#!/bin/sh
test -x /usr/sbin/logrotate || exit 0
/usr/sbin/logrotate /etc/logrotate.elasticbeanstalk.hourly/logrotate.elasticbeanstalk.httpd.conf

/etc/logrotate.elasticbeanstalk.hourly/logrotate.elasticbeanstalk.httpd.conf

/var/log/httpd/* {
size 10M
missingok
notifempty
rotate 5
sharedscripts
compress
dateext
dateformat -%s
create
postrotate
    /sbin/service httpd reload > /dev/null 2>/dev/null || true
endscript
olddir /var/log/httpd/rotated
}

Observe postrotate . /sbin/service é apenas um wrapper do System V para scripts em /etc/init.d/ . Sua página man diz:

service runs a System V init script in as predictable environment as possible, removing most environment variables and with current working directory set to /.

Observe que reload não é o comando de manutenção padrão do Apache. É a adição a jusante da distribuição. Vamos dar uma olhada no script de inicialização, /etc/init.d/httpd . Parte relevante segue:

reload() {
        echo -n $"Reloading $prog: "
        check13 || exit 1
        killproc -p ${pidfile} $httpd -HUP
        RETVAL=$?
        echo
}

Como você pode ver, ele envia o sinal HUP para o Apache, que é interpretado como Reiniciar agora :

Sending the HUP or restart signal to the parent causes it to kill off its children like in TERM, but the parent doesn't exit. It re-reads its configuration files, and re-opens any log files. Then it spawns a new set of children and continues serving hits.

TERM explica muito bem o 504s. Mas como isso provavelmente deve ser feito é Gracioso Reiniciar , pois ele também reabre os logs, mas não termina as solicitações sendo exibidas:

The USR1 or graceful signal causes the parent process to advise the children to exit after their current request (or to exit immediately if they're not serving anything). The parent re-reads its configuration files and re-opens its log files. As each child dies off the parent replaces it with a child from the new generation of the configuration, which begins serving new requests immediately.

...

The code was written to both minimize the time in which the server is unable to serve new requests (they will be queued up by the operating system, so they're not lost in any event) and to respect your tuning parameters.

Solução alternativa

É possível usar .ebextensions para substituir /etc/logrotate.elasticbeanstalk.hourly/logrotate.elasticbeanstalk.httpd.conf . No diretório raiz create .ebextensions / 10_logs.config com o seguinte conteúdo (basicamente substitua "reload" por "graceful"):

files:
    "/etc/logrotate.elasticbeanstalk.hourly/logrotate.elasticbeanstalk.httpd.conf":
        mode: "000644"
        owner: root
        group: root
        content: |
            /var/log/httpd/* {
                size 10M
                missingok
                notifempty
                rotate 5
                sharedscripts
                compress
                dateext
                dateformat -%s
                create
                postrotate
                    /sbin/service httpd graceful > /dev/null 2>/dev/null || true
                endscript
                olddir /var/log/httpd/rotated
            }

E reimplante seu ambiente do Elastic Beanstalk. Note, no entanto, com subseqüentes sub-segundos reiniciações graciosas eu era capaz de (esporadicamente) produzir 503 Serviço Indisponível , o que, no entanto, não é o caso com rotações de log como com reinicializações graciosamente espaçadas não houve erro .

    
por 14.12.2017 / 12:56