Esta semana notei que a Internet, em determinados momentos, estava muito lenta somente durante a navegação em páginas. Imediatamente dei um # tail -f /var/log/squid/access.log para ver como estava o fluxo. Notei que havia problemas, pois não era raro as coisas ficarem bem lentas. Algo considerado normal era de 5 a 30 linhas de log por segundo. De repente, o fluxo passava para 1 linha a cada 3 ou 5 segundos. Era evidente que algo estava errado.
A caçada ao problema
A próxima providência foi observar o log /var/log/squid/cache.log. Esse log é muito útil em casos de panes. Assim sendo, encontrei entradas como essas:
2011/03/01 11:33:08| WARNING! Your cache is running out of filedescriptors 2011/03/01 11:33:24| WARNING! Your cache is running out of filedescriptors 2011/03/01 11:33:40| WARNING! Your cache is running out of filedescriptors ... 2011/03/01 11:37:49| comm_open: socket failure: (24) Too many open files 2011/03/01 11:37:49| comm_open: socket failure: (24) Too many open files 2011/03/01 11:37:49| comm_open: socket failure: (24) Too many open files 2011/03/01 11:37:49| comm_open: socket failure: (24) Too many open files 2011/03/01 11:37:49| comm_open: socket failure: (24) Too many open files
A primeira atitude foi parar o Squid para extinguir conexões e liberar a memória. Ao parar o Squid, o log cache.log mostrou várias linhas similares às seguintes:
2011/03/01 11:39:56| WARNING: Closing client 172.20.11.8 connection due to lifetime timeout 2011/03/01 11:39:56| http://212.95.32.228/ 2011/03/01 11:39:56| WARNING: Closing client 172.20.11.8 connection due to lifetime timeout 2011/03/01 11:39:56| http://pornorus.info/ 2011/03/01 11:39:56| WARNING: Closing client 172.20.11.8 connection due to lifetime timeout 2011/03/01 11:39:56| http://212.95.32.228/ 2011/03/01 11:39:56| WARNING: Closing client 172.20.11.8 connection due to lifetime timeout 2011/03/01 11:39:56| http://212.95.32.228/ 2011/03/01 11:39:56| WARNING: Closing client 172.20.11.8 connection due to lifetime timeout 2011/03/01 11:39:56| http://pornorus.info/
Depois de ver tais ocorrências nos logs, coloquei novamente o Squid no ar e iniciei uma sessão tcpdump analisando os pacotes oriundos da máquina 172.20.11.8 (# tcpdump -n src host 172.20.11.8 -i any). O resultado, assustador, foi o seguinte (apenas parte dele):
13:14:43.987252 IP 172.20.11.8.57275 > 69.172.201.37.80: Flags [R.], seq 181, ack 222, win 0, length 0 13:14:44.409406 IP 172.20.11.8.57267 > 66.147.233.129.80: Flags [S], seq 1898618422, win 8192, options [mss 1460,nop,nop,sackOK], length 0 13:14:44.409410 IP 172.20.11.8.57258 > 199.59.164.43.80: Flags [S], seq 55279041, win 8192, options [mss 1460,nop,nop,sackOK], length 0 13:14:44.409421 IP 172.20.11.8.57259 > 216.67.236.203.80: Flags [S], seq 932004311, win 8192, options [mss 1460,nop,nop,sackOK], length 0 13:14:44.409452 IP 172.20.11.8.57261 > 206.188.192.114.80: Flags [S], seq 2750519905, win 8192, options [mss 1460,nop,nop,sackOK], length 0 13:14:44.409462 IP 172.20.11.8.57264 > 66.147.233.129.80: Flags [S], seq 1119544921, win 8192, options [mss 1460,nop,nop,sackOK], length 0 13:14:44.409473 IP 172.20.11.8.57266 > 206.188.192.114.80: Flags [S], seq 590383906, win 8192, options [mss 1460,nop,nop,sackOK], length 0 13:14:44.409475 IP 172.20.11.8.57262 > 97.74.233.172.80: Flags [S], seq 2639837201, win 8192, options [mss 1460,nop,nop,sackOK], length 0 13:14:44.409485 IP 172.20.11.8.57263 > 199.59.164.43.80: Flags [S], seq 2739288678, win 8192, options [mss 1460,nop,nop,sackOK], length 0 13:14:44.409495 IP 172.20.11.8.57268 > 212.95.32.228.80: Flags [S], seq 2977967308, win 8192, options [mss 1460,nop,nop,sackOK], length 0 13:14:44.440659 IP 172.20.11.8.57270 > 97.74.233.172.80: Flags [S], seq 3954006774, win 8192, options [mss 1460,nop,nop,sackOK], length 0 13:14:44.440659 IP 172.20.11.8.57269 > 212.95.32.228.80: Flags [S], seq 2623039428, win 8192, options [mss 1460,nop,nop,sackOK], length 0 13:14:44.471860 IP 172.20.11.8.57271 > 216.67.236.203.80: Flags [S], seq 3118322633, win 8192, options [mss 1460,nop,nop,sackOK], length 0 13:14:44.483034 IP 172.20.11.8.57254 > 69.172.201.37.80: Flags [R.], seq 158, ack 222, win 0, length 0 13:14:44.487431 IP 172.20.11.8.57273 > 184.154.10.250.80: Flags [S], seq 3904042156, win 8192, options [mss 1460,nop,nop,sackOK], length 0 13:14:44.518571 IP 172.20.11.8.57274 > 66.147.233.129.80: Flags [S], seq 1708211931, win 8192, options [mss 1460,nop,nop,sackOK], length 0 13:14:44.525773 IP 172.20.11.8.57285 > 216.67.236.203.80: Flags [R.], seq 132, ack 285, win 0, length 0 13:14:44.525840 IP 172.20.11.8.57293 > 212.95.32.228.80: Flags [R.], seq 185, ack 263, win 0, length 0 13:14:44.534239 IP 172.20.11.8.57750 > 206.188.192.114.80: Flags [FP.], seq 0:193, ack 1, win 64240, length 193 13:14:44.598544 IP 172.20.11.8.57755 > 66.147.233.129.80: Flags [S], seq 2940124690, win 8192, options [mss 1460,nop,nop,sackOK], length 0 13:14:44.598893 IP 172.20.11.8.57755 > 66.147.233.129.80: Flags [.], ack 1072162614, win 64240, length 0 13:14:44.599643 IP 172.20.11.8.57755 > 66.147.233.129.80: Flags [P.], seq 0:209, ack 1, win 64240, length 209 13:14:44.599676 IP 172.20.11.8.57755 > 66.147.233.129.80: Flags [F.], seq 209, ack 1, win 64240, length 0 13:14:44.643413 IP 172.20.11.8.57729 > 212.95.32.228.80: Flags [S], seq 1694411187, win 8192, options [mss 1460,nop,nop,sackOK], length 0 13:14:44.643434 IP 172.20.11.8.57731 > 69.172.201.37.80: Flags [S], seq 3071298608, win 8192, options [mss 1460,nop,nop,sackOK], length 0 13:14:44.643451 IP 172.20.11.8.57728 > 216.67.236.203.80: Flags [S], seq 3961495832, win 8192, options [mss 1460,nop,nop,sackOK], length 0 13:14:44.643712 IP 172.20.11.8.57729 > 212.95.32.228.80: Flags [.], ack 1069583567, win 64240, length 0 13:14:44.643860 IP 172.20.11.8.57731 > 69.172.201.37.80: Flags [.], ack 1068018127, win 64240, length 0 13:14:44.643875 IP 172.20.11.8.57728 > 216.67.236.203.80: Flags [.], ack 1060616693, win 64240, length 0 ...
Bem, foram cerca de 250 transações por segundo. Estava evidente que era vírus. E a quantidade de conexões em massa estava exaurindo os recursos do Squid. Então, liguei para o usuário e solicitei que retirasse o cabo de rede (eu poderia ter utilizado uma regra de iptables ao invés disso). Reiniciei o Squid para que o mesmo rompesse as conexões estabelecidas. No mesmo instante a rede voltou ao normal.
A desinfecção da máquina
O próximo passo foi ir ao usuário. Eu queria ver qual era o worm que estava destruindo a minha rede. A máquina estava com um Windows Vista. Instalei o Zone Alarm Free para ver quais programas iam tentar acessar a Internet quando eu reiniciasse o computador. Um dos primeiros foi um tal svajnager.exe, localizado em c:\windows\system32\drivers. Um lugar suspeitíssimo, uma vez que lá só há arquivos .sys. Imediatamente, realizei um boot com um pendrive contendo um Debian, montei a partição e apaguei o arquivo. Reiniciei o Windows. A máquina ficou mais rápida e a rede normal.
A prevenção contra problemas futuros
Bem, para evitar problemas futuros, criei um shell script que varre o log cache.log a cada 10 minutos (via cron), procurando por anomalias. Caso encontre alguma coisa, esse shell me avisa, via Jabber, sobre o ocorrido. Para entender como configurar isso e para ver o script, acesse este post.
Conclusão
Se você procurar na Internet pelas mensagens de erro mostradas, verá que a maioria dos posts manda aumentar a quantidade possível de arquivos abertos ou outras soluções numéricas. O problema é que isso é uma solução paliativa. Na verdade, temos que descobrir a causa do problema, ao invés de darmos um jeito de convivermos com ele. Então, neste post, vimos como descobrir tal causa.
Fim!
Boa dica!
Também uso muito o ZoneAlarm Free para descobrir esses tipos de pragas em SOs MS.
Abraço!
Estava procurando algo para resolver um problema com squid lento e me deparei com o seu blog.
Gostei da maneira que você abordou o problema, eu sempre digo visitando site de performace e apredendo, aprendir um pouco mais. E vou dar continuidade a minha apredizagem ensinando.
Até
Grato Robson!
[]s
Olá.
Eu tenho um servidor squid rodando em modo transparente. O Skype conecta e funciona normalmente porém quando tento adicionar algum contato o mesmo não conecta e exibe a mensagem de que não existe conexão com a internet. Quando tento direto sem passar pelo proxy, o mesmo funciona normalmente. Eu dei uma olhada nos pacotes com o tcpdump, verifiquei conexões abertas no momento de adicionar algum contato porém, o que obtive e adicionei para liberar no squid não resolveu. A porta 443 e 80 estão liberadas no squid. Alguma idéia ?
Eduardo: Squid é um proxy HTTP. Porque o seu Skype passa por ele???
Boa Tarde Eriberto,
Trabalho em uma escola e estou com esse problema que você descreveu na minha rede, já fiz de tudo e não consegui resolver o problema, como sou iniciante em servidores Linux (No meu caso um Debian 6) Não sei como posso resolver, li seu artigo e pode perceber que meus logs estão como os que você postou acima, mas não sei como identificar a maquina em questão que estão infectada. Em todas as maquinas eu tenho um programa chamado Deep Freeze e quando a maquina é desligada ele volta para o momento da instalação desse programa, como um ponto de restauração. Você poderia me dar uma dica de como posso resolver esse problema!?
Desde já agradeço.
Manoel, Você tem que saber os endereços MAC de todas as suas máquinas. Com isso, você poderá ver o IP no Squid (log) e identificar a máquina no DHCP (log syslog).
Tente isso.
[]s