Debugando Squid lento.


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.

 

fonte: http://www.eriberto.pro.br

 

Lomadee, uma nova espécie na web. A maior plataforma de afiliados da América Latina.

, , , , , , , , , , , ,

Comentários

  1. Marina disse:

    Entendi tudinho.