Tem 25 horas que estou tentando descobrir por que o servidor Apache decidiu gerar falhas de segmentação e derrubar o serviço aparentemente sem motivos. Ontem, na maior tranquilidade, atualizei a minha biblioteca CPAN, rodei a rotina de sempre:
# cpan
cpan> install Bundle::CPAN
cpan> install Bundle::LWP
cpan> install DBI
cpan> install DBD::mysql
cpan> install Apache::SessionX
E por aí vai….são 20 módulos que atualizo sempre.
O que me passou desapercebido foi o upgrade do driver MySQL do 4.006 para 4.007. O próprio número de versão, lá na casa dos milésimos, indica uma versão de atualização simples, que não deveria causar maiores transtornos. Eu não poderia estar mais errado.
Logo que atualizei, reiniciei o Apache para reler as bibliotecas do Perl. Como atualizei centenas de módulos(nos Bundle::CPAN e Bundle::LWP), não desconfiei do DBD::mysql de início.
Verificava o log do httpd pai, e, desde ontem de manhã, eis o que encontrava:
[Tue May 27 06:01:16 2008] [notice] child pid 14013 exit signal Segmentation fault (11)
[Tue May 27 06:01:47 2008] [notice] child pid 13698 exit signal Segmentation fault (11)
[Tue May 27 06:02:04 2008] [notice] child pid 13678 exit signal Segmentation fault (11)
[Tue May 27 06:56:07 2008] [notice] child pid 13999 exit signal Segmentation fault (11)
[Tue May 27 06:57:28 2008] [notice] child pid 14000 exit signal Segmentation fault (11)
[Tue May 27 06:58:10 2008] [notice] child pid 14004 exit signal Segmentation fault (11)
[Tue May 27 06:59:48 2008] [notice] child pid 14008 exit signal Segmentation fault (11)
[Tue May 27 07:00:17 2008] [notice] child pid 14002 exit signal Segmentation fault (11)
Esses aí já são de hoje, à partir de 6 AM…. (Vida de programador não é mole…mais uma noite virada….)
Então comecei a luta pra encontrar a biblioteca que causava o SEGFAULT. Baixei o MySQL novo e compilei, em seguida recompilei o Apache com mod_perl 1.29 para buscar a nova versão de libmysqlclient.so.16 ao invés de .so.15, reinstalei o DBD::mysql para linkar com a nova versão, porém as falhas de segmentação continuavam. Volto tudo atrás, retorno ao MySQL 5.0.51a e reinstalo as bibliotecas. Recompilo o PHP para linkar com as .so.15 e também o DBD::mysql. Só nisso se foram 40 minutos, e a cada erro me custava quase uma hora.
Em seguida baixei o Apache 1.3.41, recompilei e nada de solucionar….
Recompilei o Apache com e sem o mod_gzip.c e nada…
Instalei o Apache com e sem o PHP 5.2.4 e nada….
Recompilei com e sem o mod_ssl e nada…
Atualizei as versões das bibliotecas linkadas ao PHP, Freetype, GD….nada…
Começou a bater o desespero….nunca tinha visto um caso desses. Cismei que era sistema de arquivos corrompido, me deu frio na barriga de pensar em atualizar a libc com apenas acesso SSH remoto….um erro e já era. Não arrisquei. Dei um reboot e torcí pra não ser problema de disco….
Coloquei um ping para monitorar quando o servidor voltasse à vida….em alguns instantes tenho o retorno:
64 bytes from ……
Maravilha…o reboot funcionou. Verifico os logs do Apache e os Segmentation Fault continuam lá….
Já eram 5 AM quando decidí começar tudo do zero, a lógica diz que se eu não errar nada no caminho então a pane é de hardware. Não deu pra consertar do modo rápido, então vamos pela força bruta!
Aumentei o nível de debug do Apache sem qualquer resultado, até que cheguei à conclusão que seria inevitável enfiar a mão na massa e ir atrás do stack trace do httpd até achar a chamada que estava acessando memória não autorizada. Lá vamos nós….
Primeiro precisamos compilar o Apache com os símbolos para debug. Só há vantagem em tirar os símbolos de binários compilados se você quiser ocultar o sistema de engenheiros reversos ou tornar o binário alguns bytes menor. No caso do Apache não estamos preocupados com isso, e hoje em dia esbanjamos discos rígidos de 1 Terabyte. Então precisamos adicionar a flag -g ao gcc e recompilar tudo….
# cd apache_1.3.41
# vi configure
Vá até as cercanias da linha 282:
:282
Antes da linha “for var in CFLAGS LDFLAGS LIBS INCLUDES DEPS; do”
Adicione
CFLAGS=-g
Rode o
# ./configure
No meu caso eu utilizo o Makefile.PL do mod_perl assim:
# cd ../mod_perl-1.29/
# perl Makefile.PL USE_APACI=1 APACHE_SRC=../apache_1.3.41/src DO_HTTPD=1 USE_APACI=1 EVERYTHING=1 APACI_ARGS=’–prefix=/usr/local/apache/ –activate-module=src/modules/php5/libphp5.a –enable-module=so –enable-module=ssl –enable-module=rewrite’
Compilar:
# make
# make install
OK, 2 minutos depois e temos um novo httpd em /usr/local/apache/bin/httpd
Agora que temos um httpd recheado de símbolos, vamos dizer ao Apache onde jogar os core dumps.
Edite o seu httpd.conf:
# vi /usr/local/apache/conf/httpd.conf
Adicione :
# 2008-05-27 problema com segmentation fault
CoreDumpDirectory /usr/local/apache/coredump/
Salve(no vi é com :wq!) e reinicie o Apache
# /usr/local/apache/bin/apachectl restart
( Veja a linha antes de CoreDumpDirectory, a deixei lá de propósito. É sempre bom comentar as alterações para, no futuro, você lembrar que nesse dia você apanhou um bocado ;). Falando sério: hoje você lembra por que editou o httpd.conf, mas daqui a 6 meses você talvez fique na dúvida de por que a diretiva de core dumps está alí. Por via das dúvidas, comente seus arquivos de configuração. Eu utilizo sempre o mesmo formato de datas aaaa-mm-dd para poder fazer buscas no futuro por anos ou meses aproximados. )
Agora aguarde o servidor cair! No meu caso foi quase instantâneo. Vou até o diretório de core dumps e não encontro qualquer arquivo core apesar das falhas repetidas do servidor…. São os efeitos da falta de sono, esquecí de permitir os core dumps aumentando o ulimit -c. Como ulimit -c 0 os core dumps ficam desligados….
# ulimit -c 10240
Damos um ulimit de 10 MBytes para tamanho máximo de arquivos core. Agora reiniciamos o Apache, e não demora encontro lá os arquivos core.nnnn. Vamos examinar o core.1035 para ver onde foi a pane:
# gdb ../bin/httpd -c core.1035
GNU gdb 6.8
Copyright (C) 2008 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type “show copying”
and “show warranty” for details.
This GDB was configured as “i686-pc-linux-gnu”…
[... um apanhado de saída, até chegar em ....]
Program terminated with signal 11, Segmentation fault.
[New process 1045]
#0 0×084b739c in Perl_av_undef ()
OK, o que será que houve em Perl_av_undef() ??? Esse tempo todo desconfiando do MySQL e o culpado era o núcleo do Perl ???!
A julgar pelo nome, Perl_av_undef() parece ser uma rotina de limpeza(undef) de arrays(AV = Array Value). Sem mais chutes pesquiso no Google e descubro que não se trata de um bug do Perl e sim de uma limitação imposta pelo sistema através do ulimit. Quando o Perl tenta limpar uma estrutura de dados complexa, arrays de arrayrefs contendo referências a objetos ou hashrefs, por exemplo, ele pode gerar uma grande quantidade de chamadas recursivas. A recursividade é uma ferramenta poderosa, mas que às vezes deve ser substituída por outras técnicas para poupar a pilha. A recursividade é quase sempre uma saída elegante, porém nem sempre a mais eficiente. A cada chamada o Perl empilha mais valores na stack, eventualmente estourando a pilha e causando uma Segmentation Fault(sinal 11). Quem derruba o programa é o próprio kernel, e isso não é um bug, é uma característica de sistemas que impedem processos de levarem a máquina toda consigo no caso de perda de controle.
Então vamos verificar o tamanho atual da pilha. Vamos aproveitar e verificar outros valores-limite para sabermos em que chão estamos pisando.
#ulimit -a
core file size (blocks, -c) unlimited
data seg size (kbytes, -d) unlimited
file size (blocks, -f) unlimited
pending signals (-i) 16253
max locked memory (kbytes, -l) 32
max memory size (kbytes, -m) unlimited
open files (-n) 1024
pipe size (512 bytes, -p) 8
POSIX message queues (bytes, -q) 819200
stack size (kbytes, -s) 10240
cpu time (seconds, -t) unlimited
max user processes (-u) 16253
virtual memory (kbytes, -v) unlimited
file locks (-x) unlimited
Temos uma pilha de 10 MBytes, o que nem sempre é suficiente. Vamos exagerar um pouco para testar nossa tese, se aumentarmos para 100 MBytes teremos a chance de ver se os core dumps deixam de acontecer.
# ulimit -s 102400
Verificamos se deu certo com:
# ulimit -s
102400
OK, temos 100 MB autorizados pro Perl fazer a festa na pilha. Vamos reiniciar o Apache e ver se funciona.
# /usr/local/apache/bin/apachectl stop
# /usr/local/apache/bin/apachectl start
Prefiro o stop e start explícitos quando estou testando, para eliminar a possibilidade de alguma memória permanecer alocada do processo anterior. Pode ser só paranóia, mas vamos adiante. Temos que aguardar alguns instantes para testar a estabilidade do novo ambiente que demos ao Apache.
OK, após 5 minutos verifico que os Segmentation Faults continuam acontecendo…só que, conforme veremos, desta vez o culpado não é mais o Perl_av_undef()
Vamos examinar um dos novos arquivo core.nnnn para tentar descobrir quem é o culpado desta vez.
# gdb /usr/local/apache/bin/httpd -c core.1047
[... cortado ...]
Program terminated with signal 11, Segmentation fault.
[New process 1047]
#0 0×00b9e46b in mysql_ping () from /usr/local/mysql//lib/mysql/libmysqlclient.so.15
Opa! mysql_ping() ….estamos voltando ao principal suspeito, desde o início o servidor caía perto de alguma chamada ao MySQL no código Perl. Vamos ver o que ocorre logo antes do mysql_ping() usando o comando where do gdb.
(gdb) where
#0 0×00b9e46b in mysql_ping () from /usr/local/mysql//lib/mysql/libmysqlclient.so.15
#1 0×004d99f2 in XS_DBD__mysql__db_ping (cv=0×94d2680) at mysql.xs:519
#2 0×001edbf4 in XS_DBI_dispatch () from /usr/lib/perl5/site_perl/5.10.0/i686-linux/auto/DBI/DBI.so
#3 0×084bfa43 in Perl_pp_entersub ()
#4 0×084be32e in Perl_runops_standard ()
#5 0×084ba15d in Perl_call_sv ()
#6 0×0043ae8f in EMBPERL2_CallStoredCV () from /usr/lib/perl5/site_perl/5.10.0/i686-linux/auto/Embperl/Embperl.so
#7 0×00453cf0 in embperl_Execute () from /usr/lib/perl5/site_perl/5.10.0/i686-linux/auto/Embperl/Embperl.so
#8 0×0045a008 in ProviderEpRun_GetContentIndex () from /usr/lib/perl5/site_perl/5.10.0/i686-linux/auto/Embperl/Embperl.so
#9 0×0045891a in Cache_GetContentIndex () from /usr/lib/perl5/site_perl/5.10.0/i686-linux/auto/Embperl/Embperl.so
#10 0×00434a63 in ProcessFile () from /usr/lib/perl5/site_perl/5.10.0/i686-linux/auto/Embperl/Embperl.so
#11 0×004355da in embperl_RunRequest () from /usr/lib/perl5/site_perl/5.10.0/i686-linux/auto/Embperl/Embperl.so
#12 0×00435b8c in embperl_ExecuteRequest () from /usr/lib/perl5/site_perl/5.10.0/i686-linux/auto/Embperl/Embperl.so
#13 0×0043233f in XS_Embperl__Req_ExecuteRequest () from /usr/lib/perl5/site_perl/5.10.0/i686-linux/auto/Embperl/Embperl.so
#14 0×084bfa43 in Perl_pp_entersub ()
#15 0×084be32e in Perl_runops_standard ()
#16 0×084ba15d in Perl_call_sv ()
#17 0×08371d3b in perl_call_handler (sv=0×96a8d20, r=0×9541c14, args=0×0) at mod_perl.c:1668
#18 0×083723f9 in perl_run_stacked_handlers (hook=0×85ef03b “PerlHandler”, r=0×9541c14, handlers=0×96a8cb0)
at mod_perl.c:1381
#19 0×08373861 in perl_handler (r=0×9541c14) at mod_perl.c:904
#20 0×08395497 in ap_invoke_handler (r=0×9541c14) at http_config.c:476
#21 0×083acd2f in process_request_internal (r=0×9541c14) at http_request.c:1299
#22 0×083ad1a0 in ap_internal_redirect (new_uri=0×951427c “/index.html”, r=0×9512ae4)
at http_request.c:1440
#23 0×00386fe4 in mod_gzip_redir1_handler () from /usr/local/apache/modules/mod_gzip.so
#24 0×00385219 in mod_gzip_handler () from /usr/local/apache/modules/mod_gzip.so
#25 0×08395497 in ap_invoke_handler (r=0×9512ae4) at http_config.c:476
#26 0×083acd2f in process_request_internal (r=0×9512ae4) at http_request.c:1299
#27 0×083acd8c in ap_process_request (r=0×9512ae4) at http_request.c:1315
#28 0×083a2ef6 in child_main (child_num_arg=12) at http_main.c:4971
#29 0×083a3227 in make_child (s=0×87be05c, slot=12, now=1211894763) at http_main.c:5150
#30 0×083a32c2 in startup_children (number_to_start=23) at http_main.c:5178
#31 0×083a3a66 in standalone_main (argc=3, argv=0xbfe95934) at http_main.c:5525
#32 0×083a434f in main (argc=3, argv=0xbfe95934) at http_main.c:5883
Lendo de baixo pra cima, o where nos dá um trace de pilha completo desde a função main() até o mysql_ping().
Sem mais demora, jogo a consulta no Google e o resultado é que mais alguém acaba de ter o mesmo problema há apenas 1 semana!
E o culpado é???? O DBD::mysql v. 4.007, que foi um dos primeiros módulos que atualizamos no servidor de produção ainda ontem! Confira o report do bug MySQL clicando aqui.
Solução: regredir para a versão 4.006. Como fazer isso se o CPAN sempre busca a última versão? É simples.
Vá até a página do DBD::mysql no endereço http://search.cpan.org/dist/DBD-mysql/.
Na caixa “Other Releases” escolha a versão anterior(4.006) e clique em Goto.
Quando a página recarregar, o link Download apontará para a versão escolhida. Baixe-a, extraia com
# tar xzvf DBD-mysql-4.006.tar.gz
# cd DBD-mysql-4.006
# perl Makefile.PL
# make
# make install
Reinicie o Apache para ler o DBD::mysql antigo
# /usr/local/apache/bin/apachectl restart
E, pelo menos até o momento, os problemas de segmentação acabaram.
Conclusões
1) Os módulos de um servidor que se propõe a ser padrão industrial tem que ser melhor testados. O bug é crasso, é primário. O módulo tenta executar um mysql_ping() e derruba o processo todo. A MySQL, recém comprada pela Sun, vai ter que efetuar um controle de qualidade mais eficiente.
2) O apache 1.3 está sendo lentamente abandonado, porém ele poderia ter um sistema de gerenciamento de erros mais “civilizado”. Ninguém tem o luxo de passar 20 horas no GNU Debugger verificando stack traces, recompilando programas gigantescos e tentando montar quebra-cabeças.
3) Não confie cegamente em updates. Efetue um update de cada vez e teste o sistema novamente. Se eu tivesse testado o sistema após o update do DBD::mysql, ao invés de atualizar o CPAN todo, eu saberia que o culpado era o DBD::mysql. Nunca tinha tido problemas com um módulo do CPAN, por isso deduzí logo se tratar de algum conflito de bibliotecas compartilhadas.
4) Aumente a pilha para processos que irão rodar durante longos períodos. Apenas 10 MB de pilha para servidores Apache, MySQL ou Oracle é muito pouco. Vimos que o DBD::mysql não era o único culpado pelos Segmentation Faults do Apache. Aumentei o ulimit da pilha para 204800 KBytes(200 Megas) para garantir.
5) Problemas entrelaçados, como a stack pequena e o bug do MySQL combinados, podem causar muita confusão. Quem imaginaria que os 2 ocorreriam ao mesmo tempo e se manifestariam da mesma forma?! As mensagens no log são idênticas, não há diferença. Se não tivesse me dado o trabalho de compilar o Apache com símbolos e estudado o stack trace no gdb, eu pensaria que os primeiros core eram problema do MySQL. Aliás, durante boa parte da resolução do problema eu achava que as bibliotecas MySQL eram as únicas culpadas.
Já faz 1 hora e 30 minutos que restabelecí o serviço e não vejo qualquer SEGFAULT registrado. Agora vem a parte difícil, explicar pra minha chefe tudo isso…..