Dead Packets

16/01/2015

Troubleshooting One Arm NAT

Filed under: fortinet,troubleshooting — drak @ 3:24 PM

Esse post é dedicado aos colegas “retardados” que me trouxeram o caso.

Situação: Servidores da rede interna devem chegar a uma rede remota usando um NAT específico, isso seria trivial se o tráfego para a rede remota não fosse roteado pela mesma interface que chega o tráfego de origem, ou seja, o pacote deve entrar e sair pela mesma interface (caminho não ótimo, já que o servidor da rede local poderia enviar o pacote diretamente para o gateway usado pelo firewall para a rede remota, porém nesse caso isso não é possível já que não ocorreria o NAT nesse fluxo).

Topologia para facilitar a visualização:

topo-one-arm-nat

Agora vamos ao que interessa, primeiro criamos uma regra liberando o tráfego da port2 para a port2, com os IPs de origem e destino adequados, após criar a regra e definir o NAT com IP Pool testamos com ping e não temos resposta, logo vamos ao debug sniffer:

FG01 # diag sniffer packet any 'host 192.168.10.63'
interfaces=[any]
filters=[host 192.168.10.63]
3.423153 192.168.10.63 -> 172.16.0.160: icmp: echo request
3.423189 192.168.10.63 -> 172.16.0.160: icmp: echo request
3.423266 192.168.10.7 -> 192.168.10.63: icmp: type-#5
4.427205 192.168.10.63 -> 172.16.0.160: icmp: echo request
4.427239 192.168.10.63 -> 172.16.0.160: icmp: echo request
4.427309 192.168.10.7 -> 192.168.10.63: icmp: type-#5
...
9.984483 192.168.10.63.54077 -> 172.16.0.160.443: syn 2201610154 
9.984565 192.168.10.63.54077 -> 172.16.0.160.443: syn 2201610154 
9.984623 192.168.10.7 -> 192.168.10.63: icmp: type-#5

Na captura acima fiz dois testes, o primeiro com ping (icmp echo request) e o segundo com um telnet na porta 443 (https).

Note o pacote “estranho” icmp type 5, como alguns de vocês podem imaginar deve estar ocorrendo um ICMP redirect pois o FW está enviando o pacote para um gw na mesma rede que o host de origem.

Confirmando o que significa icmp type 5 a partir da fonte: RFC792

The gateway sends a redirect message to a host in the following
situation. A gateway, G1, receives an internet datagram from a
host on a network to which the gateway is attached. The gateway,
G1, checks its routing table and obtains the address of the next
gateway, G2, on the route to the datagram's internet destination
network, X. If G2 and the host identified by the internet source
address of the datagram are on the same network, a redirect
message is sent to the host. The redirect message advises the
host to send its traffic for network X directly to gateway G2 as
this is a shorter path to the destination. The gateway forwards
the original datagram's data to its internet destination.

Ok, a descrição acima bate com o esperado. Agora como resolver isso ?

Pesquisando no CLI Guide (http://docs.fortinet.com/d/fortigate-fortios-5.2-cli-reference) alguma coisa relacionada a ‘redirect’ achei o seguinte na página 484:

“Under some conditions, it is undesirable to have enable traffic routed back on the same interface. In that case, set allow-traffic-redirect to disable.”

Ou seja, exatamente a situação enfrentada, tráfego entra e sai pela mesma interface, vamos habilitar o comando:

config system global
    set allow-traffic-redirect disable
end

Testamos:

FG01 # diag sniffer packet any 'port 443'
interfaces=[any]
filters=[port 443]
6.316107 192.168.10.63.47071 -> 172.16.0.160.443: syn 3467548287 
6.316225 192.168.10.51.47071 -> 172.16.0.160.443: syn 3467548287 
6.317751 172.16.0.160.443 -> 192.168.10.51.47071: syn 2754869133 ack 3467548288 
6.317767 172.16.0.160.443 -> 192.168.10.63.47071: syn 2754869133 ack 3467548288 
6.317994 192.168.10.63.47071 -> 172.16.0.160.443: ack 2754869134 
6.318009 192.168.10.51.47071 -> 172.16.0.160.443: ack 2754869134 
6.318276 192.168.10.63.47071 -> 172.16.0.160.443: fin 3467548288 ack 2754869134 
6.318308 192.168.10.51.47071 -> 172.16.0.160.443: fin 3467548288 ack 2754869134 
6.319294 172.16.0.160.443 -> 192.168.10.51.47071: fin 2754869134 ack 3467548289 
6.319306 172.16.0.160.443 -> 192.168.10.63.47071: fin 2754869134 ack 3467548289 
6.319517 192.168.10.63.47071 -> 172.16.0.160.443: ack 2754869135 
6.319526 192.168.10.51.47071 -> 172.16.0.160.443: ack 2754869135 

E observando o comportamento no diag debug flow:

2014-12-09 13:16:31 id=20085 trace_id=101 func=print_pkt_detail line=4373 msg="vd-root received a packet(proto=6, 192.168.10.63:58746->172.16.0.160:443) from port2. flag [S], seq 29096599, ack 0, win 14600"
2014-12-09 13:16:31 id=20085 trace_id=101 func=init_ip_session_common line=4522 msg="allocate a new session-0000027b"
2014-12-09 13:16:31 id=20085 trace_id=101 func=vf_ip4_route_input line=1596 msg="find a route: flags=01000000 gw-192.168.10.211 via port2"
2014-12-09 13:16:31 id=20085 trace_id=101 func=fw_forward_handler line=670 msg="Allowed by Policy-2: SNAT"
2014-12-09 13:16:31 id=20085 trace_id=101 func=__ip_session_run_tuple line=2520 msg="SNAT 192.168.10.63->192.168.10.51:58746"
2014-12-09 13:16:31 id=20085 trace_id=102 func=print_pkt_detail line=4373 msg="vd-root received a packet(proto=6, 192.168.10.63:58746->172.16.0.160:443) from port2. flag [.], seq 29096600, ack 612563040, win 7300"
2014-12-09 13:16:31 id=20085 trace_id=102 func=resolve_ip_tuple_fast line=4432 msg="Find an existing session, id-0000027b, original direction"
2014-12-09 13:16:31 id=20085 trace_id=102 func=__ip_session_run_tuple line=2520 msg="SNAT 192.168.10.63->192.168.10.51:58746"
2014-12-09 13:16:31 id=20085 trace_id=103 func=print_pkt_detail line=4373 msg="vd-root received a packet(proto=6, 192.168.10.63:58746->172.16.0.160:443) from port2. flag [F.], seq 29096600, ack 612563040, win 7300"
2014-12-09 13:16:31 id=20085 trace_id=103 func=resolve_ip_tuple_fast line=4432 msg="Find an existing session, id-0000027b, original direction"
2014-12-09 13:16:31 id=20085 trace_id=103 func=__ip_session_run_tuple line=2520 msg="SNAT 192.168.10.63->192.168.10.51:58746"
2014-12-09 13:16:31 id=20085 trace_id=104 func=print_pkt_detail line=4373 msg="vd-root received a packet(proto=6, 192.168.10.63:58746->172.16.0.160:443) from port2. flag [.], seq 29096601, ack 612563041, win 7300"
2014-12-09 13:16:31 id=20085 trace_id=104 func=resolve_ip_tuple_fast line=4432 msg="Find an existing session, id-0000027b, original direction"
2014-12-09 13:16:31 id=20085 trace_id=104 func=__ip_session_run_tuple line=2520 msg="SNAT 192.168.10.63->192.168.10.51:58746"

Removi o comando ‘allow-traffic-redirect’ no debug flow abaixo, para comparar como seria o output dessa análise quando o problema ocorre:

2014-12-09 13:19:51 id=20085 trace_id=105 func=print_pkt_detail line=4373 msg="vd-root received a packet(proto=6, 192.168.10.63:44447->172.16.0.160:443) from port2. flag [S], seq 3913655818, ack 0, win 14600"
2014-12-09 13:19:51 id=20085 trace_id=105 func=init_ip_session_common line=4522 msg="allocate a new session-000002d0"
2014-12-09 13:19:51 id=20085 trace_id=105 func=vf_ip4_route_input line=1596 msg="find a route: flags=01000000 gw-192.168.10.211 via port2"
2014-12-09 13:19:54 id=20085 trace_id=106 func=print_pkt_detail line=4373 msg="vd-root received a packet(proto=6, 192.168.10.63:44447->172.16.0.160:443) from port2. flag [S], seq 3913655818, ack 0, win 14600"
2014-12-09 13:19:54 id=20085 trace_id=106 func=init_ip_session_common line=4522 msg="allocate a new session-000002d3"
2014-12-09 13:19:54 id=20085 trace_id=106 func=vf_ip4_route_input line=1596 msg="find a route: flags=01000000 gw-192.168.10.211 via port2"

Lembrando apenas que esse tipo de topologia não é usual e obviamente não é a melhor prática, porém as vezes não temos como mudar a topologia do ambiente e temos que fazer funcionar de “qualquer jeito”. Caso resolvido!

Referências
FortiOS 5.2.0 CLI Reference
RFC 792 – ICMP

Anúncios

11/07/2012

TCP RST enviado pelo firewall

Filed under: cisco,troubleshooting — drak @ 7:00 PM

Caso: Capture no Cisco ASA (caixa grande, 5550) indicava intermitência na comunicação de certos tráfegos, ora estabelecia conexão ora a mesma recebia um TCP Reset. Foi inicialmente verificado as métricas de performance do equipamento: CPU e memória normais, tráfego na interface também normal.

Foi verificado o detalhe do tráfego ponto a ponto, originava de um determinado host da rede interna, chegava no firewall e era enviada para um VIP (Load Balancer F5 BigIP). Foi montada um tcpdump no BigIP para determinar qual dos servidores da farm estava enviando o TCP Reset e qual não foi a surpresa quando na captura do BigIP não foi encontrado nenhum pacote RST sendo enviado.

Tráfego passando normalmente

Tráfego sendo rejeitado com TCP RST

Surgiu a questão, porque o firewall estava enviando os resets (já que não havia outros elementos que poderiam fazer isso na topologia) ?

Foi feito nova revisão do firewall, verificou-se a configuração da ACL, existência de service policy (não havia) e outros parâmetros de segurança que poderiam limitar conexões como threath-detection, nada relevante foi encontrado.

Foi passado a informação de que uma nova aplicação relacionada ao SAP havia entrado em produção há pouco tempo, o que poderia ter causado algum impacto de performance no firewall, porém parâmetros como CPU e memória já haviam sido analisados e não estavam nem perto de 100%, foi quando analisando o número de conexões estabelecidas (sh conn count) notamos que o número era estranhamente “redondo”, 650001. Imediatamente suspeitamos que o número máximo de sessões do equipamento havia sido atingido, ao validar o número de sessões simultâneas que o equipamento suporta no datasheet do fabricante finalmente validamos a suspeita, entendendo que o comportamento observado ocorria justamente por esse limite ter sido alcançado.

Comunicamos ao time da aplicação o problema encontrado, fizemos uma análise de sessões (inserir link) para determinar os IPs mais ofensivos (do ponto de vista de número de sessões criadas) e passamos essa informação a eles, durante essa análise notamos que o maior tráfego era de servidores de backup fazendo consultas DNS, descobrimos que as máquinas de backup estavam rodando o software Data Protector que em sua configuração padrão realiza uma consulta no DNS reverso do IP do servidor que está sendo feito o backup, o motivo do número excessivo de sessões foi que a zona de DNS reversa não estava configurada e portanto o Data Protector ficava continuamente tentando efetuar essa consulta ao DNS, que nunca era resolvida com sucesso, causando um efeito similar a o de uma ataque DoS e estourando o número de sessões utilizadas no firewall.

Referências
Cisco ASA 5500 Series Adaptive Security Appliances

02/11/2011

Troubleshooting de lentidão com firewall, MPLS e HP-UX

Filed under: checkpoint,troubleshooting — drak @ 9:20 PM

Enfrentava um problema de lentidão em um sistema web acessado por uma empresa parceira que chegava no meu cliente por uma MPLS contratada de um ISP.

Testes de ping mostravam entre 25% a 75% de perda de pacotes, a operadora já havia tentado corrigir a situação aplicando QoS no roteador de WAN mais próximo do cliente porém não surtiu efeito. No meio do caminho havia um Check Point R71.30 splat com conhecido problema de alto processamento (CPU constantemente entre 75% e 85%).

Inicialmente queria estabelecer um baseline desse sistema web que era afetado pela lentidão. Fui informado que outra empresa parceira tambem acessava esse mesmo sistema e que seu desempenho era medido por agentes que mostravam um tempo médio de resposta de 2s.

Com essa informação confrontei com o tempo a partir da parceira problemática. Eles obteram essa informação com o HttpWatch, ferramenta que provê gratuitamenta esse tipo de métrica, podemos ver um exemplo de medição para o site yahoo.com abaixo.

O tempo foi em média 30s, portanto muito maior, comparativamente, com a velocidade esperada do sistema.

O próximo passo seria um traceroute a partir da parceira afetada até o web server, não conseguimos progredir com essa abordagem pois o firewall no parceiro não possuia liberação para isso.

Mudamos a abordagem e fizemos um traceroute a partir do roteador da wan que estava na frente deste firewall (da parceira), o gateway do firewall para a rede MPLS. A partir desse ponto obtivemos o caminho até o web server, cada asterisco é um IP que mapeamos usando o traceroute.

|LAN PARCEIRA| – |FW PARC| – |ROUTER WAN PARC| – *|ROUTER1| – *|ROUTER2| – *|ROUTER WAN CUST| – *|FW CLIENTE| – *|WEB SERVER|

Com um traceroute no sentido contrário, feito a partir do firewall (pois o web server estava diretamente conectado) cruzamos as duas informações e montamos a topologia completa do ambiente afetado pelo problema:

|LAN PARCEIRA| – |FW PARC| – |ROUTER WAN PARC|* – *|ROUTER1|* – *|ROUTER2|* – *|ROUTER WAN CUST|* – *|FW CLIENTE| – *|WEB SERVER|

Com o ambiente mapeado começamos os testes. Ping a partir do equipamento ROUTER WAN PARC para o WEB SERVER indicava perdas de até 75%!

Próximo hop mesmo teste, e assim por diante, vejam os resultados.

ROUTER WAN PARC, WEB SERVER: 75%
ROUTER1, WEB SERVER: 75%
ROUTER2, WEB SERVER: 75%
ROUTER WAN CUST, WEB SERVER: 0%
FW CLIENTE: 0%

Com os resultados desses testes, imaginei que havíamos descoberto que o problema estava entre o segmento ROUTER WAN PARC e a interface mais próxima dele do ROUTER WAN CUST, porém ao fazer testes iniciando do ROUTER2 também tinhamos uma quantidade alta de perda, a príncipio eliminando a possibilidade de ser algo no segmento anteriormente suspeito.

Ao analisar o resultado das falhas de ping do ROUTER2 notamos algo estranho, ele não simplemente perdia os pacotes por time-out mas sim por algum outro motivo, vejam a imagem:

Pesquisando um pouco descobrimos que a mensagem icmp !Q era enviada quando o servidor estava com seu buffer estava cheio e não conseguia lidar com todos os pings enviados para ele, essa mensagem solicita ao host que está enviando os pacotes que o mesmo diminuia a velocidade de envio.

Outra informação importante é que, embora no firewall ele não definisse os pacotes como perdidos também estávamos recebendo pacotes de ICMP source-quench, segue um exemplo dos logs que víamos no firewall.

FIREWALL[admin]# ping -s 1400 XXX.XXX.XXX.177
PING XXX.XXX.XXX.177 (XXX.XXX.XXX.177): 1400 data bytes
1408 bytes from XXX.XXX.XXX.177: icmp_seq=0 ttl=255 time=2.025 ms
1408 bytes from XXX.XXX.XXX.177: icmp_seq=1 ttl=255 time=0.343 ms
1408 bytes from XXX.XXX.XXX.177: icmp_seq=2 ttl=255 time=0.336 ms
1408 bytes from XXX.XXX.XXX.177: icmp_seq=3 ttl=255 time=3.196 ms
...
1408 bytes from XXX.XXX.XXX.177: icmp_seq=50 ttl=255 time=0.334 ms
1408 bytes from XXX.XXX.XXX.177: icmp_seq=51 ttl=255 time=0.312 ms
1408 bytes from XXX.XXX.XXX.177: icmp_seq=52 ttl=255 time=0.672 ms
1408 bytes from XXX.XXX.XXX.177: icmp_seq=53 ttl=255 time=1.046 ms
1408 bytes from XXX.XXX.XXX.177: icmp_seq=54 ttl=255 time=0.344 ms
92 bytes from XXX.XXX.XXX.177: Source Quench
Vr HL TOS Len ID Flg off TTL Pro cks Src Dst
4 5 00 0594 00e4 0 0000 40 01 f861 XXX.XXX.XXX.10 XXX.XXX.XXX.177

1408 bytes from XXX.XXX.XXX.177: icmp_seq=55 ttl=255 time=0.456 ms
92 bytes from XXX.XXX.XXX.177: Source Quench
Vr HL TOS Len ID Flg off TTL Pro cks Src Dst
4 5 00 0594 010c 0 0000 40 01 f839 XXX.XXX.XXX.10 XXX.XXX.XXX.177

1408 bytes from XXX.XXX.XXX.177: icmp_seq=56 ttl=255 time=0.362 ms
92 bytes from XXX.XXX.XXX.177: Source Quench
Vr HL TOS Len ID Flg off TTL Pro cks Src Dst
4 5 00 0594 0132 0 0000 40 01 f813 XXX.XXX.XXX.10 XXX.XXX.XXX.177

1408 bytes from XXX.XXX.XXX.177: icmp_seq=57 ttl=255 time=0.276 ms
92 bytes from XXX.XXX.XXX.177: Source Quench
Vr HL TOS Len ID Flg off TTL Pro cks Src Dst
4 5 00 0594 0154 0 0000 40 01 f7f1 XXX.XXX.XXX.10 XXX.XXX.XXX.177

1408 bytes from XXX.XXX.XXX.177: icmp_seq=58 ttl=255 time=0.314 ms
92 bytes from XXX.XXX.XXX.177: Source Quench
Vr HL TOS Len ID Flg off TTL Pro cks Src Dst
4 5 00 0594 0178 0 0000 40 01 f7cd XXX.XXX.XXX.10 XXX.XXX.XXX.177

1408 bytes from XXX.XXX.XXX.177: icmp_seq=59 ttl=255 time=0.286 ms
92 bytes from XXX.XXX.XXX.177: Source Quench
Vr HL TOS Len ID Flg off TTL Pro cks Src Dst
4 5 00 0594 01a1 0 0000 40 01 f7a4 XXX.XXX.XXX.10 XXX.XXX.XXX.177

1408 bytes from XXX.XXX.XXX.177: icmp_seq=60 ttl=255 time=2.355 ms
92 bytes from XXX.XXX.XXX.177: Source Quench
Vr HL TOS Len ID Flg off TTL Pro cks Src Dst
4 5 00 0594 01c8 0 0000 40 01 f77d XXX.XXX.XXX.10 XXX.XXX.XXX.177

1408 bytes from XXX.XXX.XXX.177: icmp_seq=61 ttl=255 time=0.333 ms
92 bytes from XXX.XXX.XXX.177: Source Quench
Vr HL TOS Len ID Flg off TTL Pro cks Src Dst
4 5 00 0594 01ee 0 0000 40 01 f757 XXX.XXX.XXX.10 XXX.XXX.XXX.177

1408 bytes from XXX.XXX.XXX.177: icmp_seq=62 ttl=255 time=0.592 ms
92 bytes from XXX.XXX.XXX.177: Source Quench
Vr HL TOS Len ID Flg off TTL Pro cks Src Dst
4 5 00 0594 020f 0 0000 40 01 f736 XXX.XXX.XXX.10 XXX.XXX.XXX.177

Para forçar esse log a aparecer de maneira mais constante, usamos a opção de ping “flood” (ping host -f), ao fazer isso constatamos que o comportamento do servidor era o mesmo tanto para o router quanto para o firewall, que estava diretamente conectado.

Após verificação da saúde do servidor (CPU, memória, velocidade da placa de rede, erros na interface) começamos a investigar outros motivos para que essa mensagem possa ser enviada que não envolvam o servidor não estar “aguentando” a taxa de pings enviados. O servidor em questão era um HP-UX e isso nos trouxe alguns artigos interessantes.

Descobrimos que havia uma certa proteção interna nos servidores HP-UX e que havia um meio de desativar essa proteção, dada a natureza do nosso teste (envio de repetidos pings a partir de um router, que tem uma taxa de envio bem alta, certamente isso estava atrapalhando os testes. Após desabilitar a proteção seguindo o conselho de um dos blogs (Set “Source quench” to 0 as “ndd -set /dev/ip ip_send_souce_quench 0” and include this parameter inside “nddconf” file.) refizemos os testes, com os seguintes resultados:

ROUTER WAN PARC, WEB SERVER: 25%
ROUTER1, WEB SERVER: 25%
ROUTER2, WEB SERVER: 0%
ROUTER WAN CUST, WEB SERVER: 0%
FW CLIENTE: 0%

Agora sim, uma vez removido o fator “source-quench” que estava mascarando os resultados conseguimos isolar em que trecho da rede estava o real problema de lentidão. O ISP investigou o problema e informou que o problema estava com uma política de QoS nesse trecho, uma vez removida a política as perdas pararam e o acesso Web voltou ao patamar esperado (cerca de 2s).

Referências
Understanding the Ping and Traceroute Commands
HttpWatch
ICMP Source Quench
HP-UX ping source quench

04/03/2011

Troubleshooting de conexão RPC

Filed under: troubleshooting — drak @ 8:49 AM

Um problema de comunicação que não passa por um firewall é mais difícil de ser analisado pois você não tem prontamente um jeito de realizar o dump dos pacotes, seria necessário espelhar a porta do switch e capturar em outra porta, o que geralmente não é tão simples dependendo do ambiente que você está (datacenter, portas livres, etc).

Nesse caso temos que analisar o caso confiando nos testes entre as pontas. Um caso interessante que eu peguei foi o seguinte: Os clients Outlook da uma determinada localidade não conseguiam conectar no servidor de Exchange, acessível por uma rede MPLS a partir desta localidade, não haviam firewalls nesse caminho.

Os testes começaram com conectividade básica, ping de um lado para outro funcionavam normalmente, foi solicitado o tracert do cliente até o servidor, o que não agregou nada relevante, seguimos para teste de conexão na TCP/135 (conforme indicado pelo KB da Microsoft na seção “Communication between Exchange Client computers and Exchange Server computers”) e o teste de conexão também teve sucesso, a conexão fechava normalmente.

A equipe de Messaging procedeu para testes com o utilitário PortQry que testa a conexão RPC de maneira completa, ou seja, após abrir a conexão na porta TCP/135 também realiza a chamada ao serviço portmapper que lista todos os programas que se registraram no serviço RPC remoto. Durante este teste era possível ver que embora a conexão fosse estabelecida, como esperado, ocorria um erro, veja o log:

Querying target system called:
srv_exchange
Attempting to resolve name to IP address...
Name resolved to 192.168.10.20
querying...
TCP port 135 (epmap service): LISTENING
Using ephemeral source port
Querying Endpoint Mapper Database...
Server's response:
RPC query failed (6bf).
Querying target system called:
srv_exchange
Attempting to resolve name to IP address...
Name resolved to 192.168.10.20
querying...
TCP port 11020 (unknown service): LISTENING
TCP port 11021 (unknown service): NOT LISTENING
TCP port 6001 (unknown service): LISTENING

Com essa nova informação procuramos levantar se no ambiente havia algum dispositivo que pudesse influenciar na aplicação mas não na conectividade, um exemplo disso seria um IPS na rede, antivírus da estação de trabalho ou no servidor ou algum firewall desconhecido no caminho, depois de eliminadas estas possibilidades iríamos começar a analisar o pacote em cada ponto por onde ele passava, para isso foi re-verificado o tracert do desktop para o servidor Exchange e outro no sentido contrário, com o resultado desses tracerts notou-se que o número de hops era diferente, após revisão desta informação constatamos que os pacotes do cliente para o servidor estavam indo pelo link principal, porém a volta estava pelo link backup, devido a este comportamento assimétrico estava ocorrendo o problema com a aplicação RPC.

Como não havia nenhum dispositivo statefull no caminho existia conectividade, porém quando a aplicação efetivamente entrava no tráfego a mesma não se comportava como deveria. Após a correção das tabelas de roteamento o problema foi resolvido.

Referências
TCP ports and Microsoft Exchange: In-depth discussion
Analyzing Exchange RPC traffic over TCP/IP
How to Use Portqry to Troubleshoot Active Directory Connectivity Issues

16/05/2010

Parser para log de sessões do ScreenOS

Filed under: ScreenOs,troubleshooting — drak @ 2:04 PM

Uma parte do meu trabalho é atuar no tratamento de incidentes e, para dispositivos como firewalls, a análise de sessões geralmente dá uma ótima idéia do que está ocorrendo no momento do problema. Em firewalls Netscreen o comando “get session” realiza o dump da tabela de sessões do firewall, um trecho desse tipo de log pode ser visto abaixo:

id 407322/s**,vsys 0,flag 00000040/4000/0003,policy 70,time 1, dip 0 module 03773,1Bot
 if 45(nspflag 800805):172.18.6.11/6->10.253.22.4/47959,1,00093d1447ad,sess token 21,vlan 30,tun 0,vsd 0,route 103774,1Bot
 if 9(nspflag 800804):172.18.6.11/6<-10.253.22.4/47959,1,001882fb38b2,sess token 25,vlan 11,tun 0,vsd 0,route 523775,1Bot

id 47596/s**,vsys 0,flag 14000000/0000/0001,policy 50,time 22, dip 0 module 0
 if 5(nspflag 4801):192.168.1.150/51218->97.125.239.85/47804,17,000000000000,sess token 3,vlan 0,tun 0,vsd 0,route 0
 if 0(nspflag 4800):200.200.200.16/51218<-97.125.239.85/47804,17,000000000000,sess token 4,vlan 0,tun 0,vsd 0,route 0

Como vocês podem imaginar a informação acima não é facilmente interpretada se temos algumas centenas ou milhares de sessões estabelecidas, para resolver este problema temos algumas alternativas, uma delas é gravar a saída do comando e realizar o upload do arquivo para a ferramente online da Juniper conhecida como Firewall Session Analyzer (necessário login), outra opção é realizar alguns malabarismos com um script na saída padrão do comando para tornar estes dados utilizáveis numa análise via CLI do Linux.

Abaixo segue o primeiro programa que irá ajudar na tarefa de analisar a saída do comando “get session” pela CLI, eu porcamente escrevi este programa (tenho zero de experiência em Perl) me baseando nos parsers utilizados no projeto Afterglow.

nse2csv.pl

#!/usr/bin/perl
use strict vars;

my $output=$ARGV[0] || "full";
my $DEBUG=0;
our ($sip,$sport,$dip,$dport);

while (<STDIN>) {
        chomp;
        my $input = $_;
        if ($input =~ /(.*):(\d+\.\d+\.\d+\.\d+)\/?(\d*)->(\d+\.\d+\.\d+\.\d+)\/?(\d*)/) {
                $input = "$1|$2|$3|$4|$5";
        } else {
                $DEBUG && print STDERR "ERROR: $input\n";
                next;
        }

        my @fields = split ('\|',$input);

        $sip = $fields[1];
        $sport = $fields[2];
        $dip = $fields[3];
        $dport = $fields[4];

        if ($output eq "full") {
                print "$sip,$dip,$dport\n";
        } else {
                my @tokens = split / /,$output;
                print ${shift(@tokens)};
                for my $token (@tokens) {
                        if (!defined($$token)) {
                                $DEBUG && print STDERR "$token is not a known field\n";
                                #exit;
                        } else {
                                print ','.$$token;
                        }
                }
                print "\n";
        }
}

Este programinha em perl deve ser utilizado com a seguinte sintaxe:

cat ARQUIVO_LOG_SESSOES.log > nse2cvs.pl

Como saída teremos, nesta ordem: SOURCE IP, DESTINATION IP, DESTINATION PORT.

Futuramente irei postar a segunda parte deste artigo, com outro script que efetua a análise dos dados gerados com o nse2csv.pl

Referências
Afterglow – Parsers
Learning Perl

25/01/2010

Troubleshooting ScreenOS 6.2 – SQL ALG

Filed under: ScreenOs,troubleshooting — drak @ 4:53 PM

Novas versões sempre podem trazer surpresas quanto ao comportamento de velhas funcionalidades ou adição de novas, uma característica interessante presente no ScreenOS 6.2 (mas que foi introduzida antes, não sei exatamente quando) é o ALG, ou Application Layer Gateway.

Esta funcionalidade é responsável por controlar o comportamento global do firewall para certos protocolos (FTP, SQL, PPTP, etc), como abertura de portas efêmeras (acima de 1024) para a sessão de dados. Porém como nem todos os desenvolvedores seguem as regras da RFC adequada ao protocolo ou até mesmo por bugs do ScreenOS esta funcionalidade às vezes precisa ser desativada.

Agora, o caso: um cliente teve seu firewall atualizado de 5.4r8 para 6.2r4 e inicialmente reclamou de lentidão na rede, após análise de perda de pacotes, confirmação das velocidades das portas no FW x switch e traceroutes indicando o caminho do tráfego, tudo indicou que o ambiente estava normal.

Dias depois o cliente volta a reclamar, porém dessa vez ele informa que, através de um túnel SSH ele conseguiu fazer com que a aplicação, que faz uma requisição ao BD Oracle, funcionasse normalmente, de posse dessas informações inicio um debug no firewall, segue abaixo trecho da captura.

ssgFW(M)-> set ffilter src-ip 10.0.2.2 dst-ip 172.16.4.14
ssgFW(M)-> clear db
ssgFW(M)-> debug flow basic
ssgFW(M)-> get db str

**** jump to packet:10.0.2.2->172.16.4.14
 flow_decap_vector IPv4 process
 flow packet already have session.
 flow session id 47490
 flow_main_body_vector in ifp ethernet0/0 out ifp ethernet0/1
 flow vector index 0x3ab, vector addr 0x518d8e4, orig vector 0x518d8e4
 vsd 0 is active
 av/uf/voip checking.
 post addr xlation: 10.0.2.2->172.16.4.14.
 update policy out counter info.
 packet send out to 0015c5ebed63 through ethernet0/1
 **** pak processing end.
after ALG, drop temp packet(550c924).
 **** pak processing end.
****** 10166.0: <DMZ/ethernet0/1> packet received [1500]******
 ipid = 39074(98a2), @1d544914
 packet passed sanity check.
 flow_decap_vector IPv4 process
 ethernet0/1:172.16.4.14/1521->10.0.2.2/2171,6<Root>
 existing session found. sess token 13
 flow got session.
 flow session id 47490
 flow_main_body_vector in ifp ethernet0/1 out ifp N/A
 flow vector index 0x3ab, vector addr 0x518d8e4, orig vector 0x518d8e4
 vsd 0 is active
 av/uf/voip checking.
 asp vector processing state: 2
ASP inject packet from ethernet0/0

Estou acostumado a realizar o debug (que mostra o processamento do pacote pelo firewall) e percebi que havia algo estranho. A mensagem “after ALG, drop temp packet(550c924).” não era comum em outras capturas e por isso resolvi investigar um pouco mais.

Ativei o log (tanto no fim quanto no início da sessão) na regra de acesso e solicitei novo teste, percebi que havia um timeout 2s após a primeira conexão, além disso quando a requisição estava encapsulada em SSH a aplicação funcionava, por estes motivos desconfiei do tempo de timeout do protocolo (SQL*Net V2, TCP/1521) e o alterei, sem sucesso.

Encontrei algumas informações no KB da Juniper relacionada à funcionalidade ALG, experimentei desativar o ALG desse protocolo, utilizei o seguinte comando:

ssgFW(M)-> unset alg sql enable

Solicitei novo teste, com a seguinte captura:

****** 11049.0: <Trust/ethernet0/0> packet received [52]******
 ipid = 61246(ef3e), @1d51f114
 packet passed sanity check.
 flow_decap_vector IPv4 process
 ethernet0/0:10.0.2.2/2226->172.16.4.14/1521,6<Root>
 no session found
 flow_first_sanity_check: in <ethernet0/0>, out <N/A>
 chose interface ethernet0/0 as incoming nat if.
 flow_first_routing: in <ethernet0/0>, out <N/A>
 search route to (ethernet0/0, 10.0.2.2->172.16.4.14) in vr trust-vr for vsd-0/flag-0/ifp-null
 [ Dest] 3.route 172.16.4.14->172.16.4.14, to ethernet0/1
 routed (x_dst_ip 172.16.4.14) from ethernet0/0 (ethernet0/0 in 0) to ethernet0/1
 policy search from zone 2-> zone 3
 policy_flow_search  policy search nat_crt from zone 2-> zone 3
 RPC Mapping Table search returned 0 matched service(s) for (vsys Root, ip 172.16.4.14, port 1521, proto 6)
 No SW RPC rule match, search HW rule
swrs_search_ip: policy matched id/idx/action = 150/0/0x9
 Permitted by policy 150
 No src xlate   choose interface ethernet0/1 as outgoing phy if
 check nsrp pak fwd: in_tun=0xffffffff, VSD 0 for out ifp ethernet0/1
 vsd 0 is active
 no loop on ifp ethernet0/1.
 session application type 64, name SQLNETV2, nas_id 0, timeout 131070sec
ALG vector is not attached
 service lookup identified service 0.
 flow_first_final_check: in <ethernet0/0>, out <ethernet0/1>
 existing vector list 123-815f334.
 Session (id:46885) created for first pak 123
 flow_first_install_session======>
 route to 172.16.4.14
 arp entry found for 172.16.4.14
 ifp2 ethernet0/1, out_ifp ethernet0/1, flag 00800800, tunnel ffffffff, rc 1
 outgoing wing prepared, ready
 handle cleartext reverse route
 search route to (ethernet0/1, 172.16.4.14->10.0.2.2) in vr trust-vr for vsd-0/flag-3000/ifp-ethernet0/0
 [ Dest] 10.route 10.0.2.2->192.168.8.2, to ethernet0/0
 route to 192.168.8.2
 arp entry found for 192.168.8.2
 ifp2 ethernet0/0, out_ifp ethernet0/0, flag 00800801, tunnel ffffffff, rc 1
 flow got session.
 flow session id 46885
 flow_main_body_vector in ifp ethernet0/0 out ifp ethernet0/1
 flow vector index 0x123, vector addr 0x815f334, orig vector 0x815f334
 vsd 0 is active
 tcp seq check.
 Got syn, 10.0.2.2(2226)->172.16.4.14(1521), nspflag 0x801801, 0x800800
 post addr xlation: 10.0.2.2->172.16.4.14.
 packet send out to 0015c5ebed63 through ethernet0/1
****** 11049.0: <DMZ/ethernet0/1> packet received [52]******
 ipid = 0(0000), @1d58a914
 packet passed sanity check.
 flow_decap_vector IPv4 process
 ethernet0/1:172.16.4.14/1521->10.0.2.2/2226,6<Root>
 existing session found. sess token 13
 flow got session.
 flow session id 46885
 flow_main_body_vector in ifp ethernet0/1 out ifp N/A
 flow vector index 0x123, vector addr 0x815f334, orig vector 0x815f334
 vsd 0 is active
 tcp seq check.
 Got syn_ack, 172.16.4.14(1521)->10.0.2.2(2226), nspflag 0x801800, 0x801801
 post addr xlation: 172.16.4.14->10.0.2.2.
 packet send out to 0003a0284406 through ethernet0/0

Percebi que o output havia mudado e estava parecido com o que eu estou acostumado, notei também o detalhe “ALG vector is not attached”.

Após o teste o cliente reportou que a aplicação estava normal, problema solucionado.

Referências
What is an ALG (Application Layer Gateway)?

What happens when I turn off a ALG (Application Layer Gateway)

Blog no WordPress.com.