A saga do /net/bin

Uma das coisas mais divertidas da vida de um administrador de sistemas é resolver um problema difícil. É ainda mais legal quando o problema é antigo e você já tentou resolvê-lo várias vezes sem sucesso. Daí, quando você consegue finalmente vencê-lo, a satisfação é enorme.

Hoje tive um desses momentos memoráveis. Tanto assim que ao invés de simplesmente mandar um email para meus colegas de trabalho resolvi relatar a solução aqui e só mandar o link pra eles. Assim eles vão poder ter razão quando disserem que o Gustavo está "se achando". :-)

Pois bem. O mistério que nos estava deixando encucados há alguns meses eram as mensagens freqüentes que apareciam no /var/log/messages de vários servidores Linux:

May 13 16:05:02 noname automount[7655]: lookup(program): lookup for bin failed
May 13 16:05:02 noname automount[7655]: failed to mount /net/bin

Essas mensagens apareciam uma ou duas vezes por minuto, durante o dia todo, e indicavam que um ou mais processos estavam periodicamente tentando acessar o diretório /net/bin que não existe. Como o /net é a base de um mapa indireto do automounter, as falhas eram reportadas por ele via syslog.

O problema que não conseguíamos resolver era como identificar os processos que estavam acessando o diretório inexistente para podermos corrigi-los. Os logs do automounter não davam nenhuma pista útil, de modo que precisávamos de uma abordagem criativa.

O fato de os logs terem uma freqüência regular sugeria que os processos causadores pudessem estar sendo ativados via crontab. Só que essas máquinas são servidoras e têm dezenas de usuários com crontabs definidos. Os logs do /var/log/cron indicavam que grande parte dos crontabs iniciava comandos a cada minuto, de modo que não dava pra investigar um ou outro script especificamente.

Tentei pegar o culpado rastreando as chamadas de sistema do daemon crond e procurando por referências ao diretório /net/bin.

# strace -f -e trace=file -o/tmp/crond.strace -p `pidof crond`

Infelizmente, não encontrei nada, o que parecia um forte indício de que não se tratava mesmo de um processo de cron, mas eu não fiquei convencido.

Eu já tinha lido alguma coisa a respeito de ferramentas para monitorar o acesso a arquivos no Linux. Com o Google foi fácil encontrar o venerável dnotify e seu colega mais novo inotify. O dnotify permite monitorar o acesso aos arquivos de um diretório e o inotify é bem mais flexível. Só que o inotify não é suportado pela versão do kernel do servidor e eu desisti de instalar o dnotify pois provavelmente o tipo de acesso que os processos estavam fazendo não seria detectável mesmo por ele.

Uma idéia que parecia promissora era procurar por processos que tivessem o diretório /net/bin presente na sua variável de ambiente PATH. Podia ser que estes processos estivessem acessando o /net/bin como resultado do processo de busca de algum comando no PATH. Felizmente, ter a idéia foi mais difícil que implementá-la:

for e in /proc/[0-9]*/environ
do echo -n "$e: "; tr '\0' '\012' <$e | grep PATH
done | grep /net/bin

Procurar nos quase 3.000 processos do servidor demorou alguns segundos mas não devolveu resultado algum. Ou o acesso não era por causa do PATH ou os processos tinham vida curta e eu não consegui acertar em nenhum deles com esse tiro.

A próxima idéia foi importante, pois me fez descobrir algumas pistas e abriu as portas para a idéia seguinte. Se os logs eram gerados porque o /net/bin não existia, talvez eu pudesse ver o resultado do acesso se eu o criasse. Exportei um diretório vazio de outra máquina e configurei o automounter para montá-lo como /net/bin na servidora. Não demorou pra eu ver que ele tinha sido montado e que as mensagens de erro pararam. Já era um avanço.

A vantagem é que agora qualquer acesso ao /net/bin deixaria um rastro de pacotes NFS na rede. Trabalho para um analisador de pacotes como o ethereal. Alguns minutos de captura e eu já tinha uma coleção razoável de pacotes NFS pra investigar. Consegui descobrir duas coisas. A primeira, promissora, foi que havia várias tentativas de acesso ao arquivo /net/bin/gawk. A segunda, ruim, foi que estes acessos eram feitos por vários usuários diferentes. Eu podia identificá-los, pois suas credenciais estavam registradas nos campos RPC dos pacotes NFS.

Daí eu pensei: se eles estão procurando o /net/bin/gawk eu vou criar um que me avise quando for invocado. Criei um script chamado gawk no diretório montado como /net/bin. O script iria registrar várias informações sobre seu chamador num arquivo e dormir por 10 minutos, de modo que eu poderia identificá-lo mais facilmente. Preparei a armadilha e fiquei esperando... Nada aconteceu. Por algum motivo os processos não estavam "chamando" o gawk falso que eu havia criado. Eu não conseguia entender porque é que algum processo procuraria o gawk se não era para chamá-lo.

Mas a idéia de forçar o travamento dos processos que estavam acessando o /net/bin era muito boa. Tinha que haver uma maneira de poder efetivá-la. A ficha caiu quando eu me lembrei da causa de um travamento recente no mesmo servidor: um servidor de NFS fora do ar. Agora que eu já tinha o /net/bin montado de um servidor NFS, bastava eu desativar o serviço remoto de NFS pra que os processos que quisessem acessar o diretório ficassem suspensos num estado de uninterruptible sleep. Tive um certo receio, pois esses travamentos devidos a problemas com servidores NFS costumam deixar os servidores num estado em que só é possível ressuscitá-los com um reboot. Ocorre que os processos que param pelo problema com o NFS podem causar a parada de outros processos que dependam deles e assim sucessivamente. Mas como eu podia restabelecer o serviço de NFS rapidamente deveria ser possível sair de qualquer enrascada.

Parei o NFS e fiquei analisando o número de processos que iam parando no estado "D":

# ps aux | awk '$8 ~ /D/'

Pelo que me lembro, o número de processos assim chegou perto dos 400 em poucos minutos. Joguei o resultado num arquivo e reativei o NFS. Os processos travados voltaram a rodar e eu pude analisar o arquivo com calma. O que eu vi nele não fez muito sentido a princípio. Todos os processos parados ou eram instâncias de uma shell invocando o /net/gnu/bin/gawk ou o /net/gnu/bin/awk:

/bin/bash /net/gnu/bin/gawk ...

Preciso explicar que o /net/gnu/bin é onde, historicamente, costumamos instalar as ferramentas livres do Projeto GNU nas nossas máquinas Solaris. Quando começamos a instalar servidores Linux há quase 10 anos o modelo do /net/gnu/bin não era necessário em princípio. Afinal, os sistemas Linux já vêm com todas as ferramentas do Projeto GNU instaladas nos diretórios padrão /usr/bin e /bin. Mas como o diretório /net/gnu/bin já era referenciado por uma quantidade enorme de scripts e binários antigos, pra evitar o trabalho de mexer em tudo isso alguém teve a brilhante idéia de configurar o automounter das máquinas Linux para montar o diretório local /usr/bin das máquinas como /net/gnu/bin sempre que algum processo fizesse referência explícita ao último. (Nessas horas não adianta muito ser purista. Uma solução porca e torta que "resolva o problema" é considerada boa o suficiente. Ahem.)

Tudo bem. Que o /net/gnu/bin/gawk era mesmo o /usr/bin/gawk eu sabia, mas o que é que ele tinha a ver com o inexistente /net/bin/gawk? Por que é que ao chamar o /net/gnu/bin/gawk a shell travaria se o /net/bin estivesse com o servidor NFS fora?

Isso não fazia nenhum sentido até que eu dei uma olhada de perto no dito cujo:

# ls -l /usr/bin/gawk
lrwxrwxrwx 1 root root 14 Dez 15 2005 /usr/bin/gawk -> ../../bin/gawk

Um link simbólico!?!? Pra que raios o gawk é um link simbólico? Ah... o /usr/bin/gawk está apontando para o /bin/gawk, que é onde o binário do comando está efetivamente instalado.

Cáspita! Matei a charada. Como o link simbólico é relativo, o /usr/bin/gawk aponta para o /bin/gawk mas o /net/gnu/bin/gawk acaba apontando para o /net/bin/gawk!!!

Isso explicava o fato de eu não ter encontrado nenhuma referência direta ao /net/bin com o strace: o PATH da shell tinha uma referência ao /net/gnu/bin e não ao /net/bin. O travamento ocorreu dentro do sistema operacional, na chamada ao exec, quando ele foi seguir o link simbólico.

Eu sabia que um dia eu teria uma boa razão pra dizer "bem que eu avisei" quando reclamei da gambiarra que foi o /net/gnu/bin no Linux. Agora eu tenho. :-)

Bom, a causa do problema foi descoberta. Resta agora resolvê-lo. Idealmente, os processos que estão tentando acessar o /net/gnu/bin deveriam ser reescritos para não tentarem. Mas algo me diz que a solução vai acabar sendo criar mais uma gambiarra. Que desta vez deverá ser montar o /bin local dos servidores Linux no /net/bin.