Comunicação de uma Aplicação ASP .Net com um Servidor FTP em NLB [Hang]
Por: Roberto Alexis Farah e Yuri Diógenes
1. Introdução
O título do artigo também poderia ser “Quando o problema de aplicação está no lado da infra-estrutura”. Sim, as vezes isso acontece embora na maioria dos incidentes que trabalhamos o problema freqüentemente está no lado da aplicação, o que é explicável dado que as aplicações mudam constantemente, as vezes bugs escapam da fase de testes, etc... As combinações para acontecer problemas são muito grandes no “lado de desenvolvimento” mais do que no “lado de infra-estrutura”.
Nesse artigo descreveremos um caso real que trabalhamos algumas semanas atrás e que foi resolvido pela ação conjunta de um engenheiro de infra-estrutura e de um engenheiro de desenvolvimento.
2. Cenário
O incidente chegou como sendo um problema de aplicação, com o seguinte cenário:
Windows 2003 SP 1
IIS 6
Aplicação ASP usando FTP.
O sintoma descrito era:
O download e upload do FTP funciona em um servidor mas não no outro de idêntica configuração. Durante a tentativa de upload ou download a aplicação fica em hang, ou seja, não responde.
Nota: Mudamos um pouco o layout do blog e agora vocês podem acessar os artigos técnicos baseados no tipo de sintoma como: Hang, Crash, Performance e Memory Leak.
3. Preparando o Ambiente para Obter Informações
Lado de Desenvolvimento:
O problema começou a ser investigado do ponto de vista de aplicação porque o sintoma descrito era manifestado na aplicação. Isso ocorre porque o Technical Router, que é o primeiro contato do cliente no incidente, direciona o chamado para o time de Messaging, Platforms ou Developer Support com base no lado onde o problema parece estar, Exchange e relacionados, Windows, Network e relacionados ou IIS/SQL Server e aplicações.
Como se tratava de um hang procurei obter 3 dumps coletados durante o sintoma e com um intervalo de tempo de um minuto aproximadamente, assim posso detectar padrões durante a depuração; um log de Performance Monitor coletado pouco antes do sintoma ocorrer e finalizado pouco depois. Como o sintoma era facilmente reprodutível sabíamos quando iniciar e parar o PerfMon.
Aliado a isso usamos os logs do IIS e Event Viewer.
4. Análise dos dados
Lado de Desenvolvimento:
O fato de sabermos que uma aplicação funciona em um servidor e não no outro que é idêntico é uma informação importante. Eu poderia iniciar comparando os servidores como primeira abordagem, entretanto, como o sintoma era de fácil reprodução optei pela depuração.
Notem que temos a informação que os servidores são idênticos não podemos assumir que de fato são, seria um erro que poderia afetar a investigação. Uma das primeiras coisas que fazemos é checar isso. Sim, porque as vezes os usuários não sabem que alguém mexeu em algum dos servidores sem o conhecimento deles e não reportou.
Voltando a investigação, os logs de FTP e IIS não revelaram nenhuma informação importante. Nesse ponto, usei o DebugDiag como sempre faço para ter uma primeira análise automatizada dos dumps. Com base nessa análise automatizada posso me focar no que é importante.
A propósito, o DebugDiag v1.1 já está disponível para download.
A análise automatizada não revelou nenhum problema. Muitas vezes os problemas são solucionados apenas interpretando o relatório do DebugDiag.
Aliado a isso também não havia nada anormal nos logs de Performance Monitor.
Próximo passo: Depurar manualmente a aplicação usando o Windbg.
Eis uma amostra do resultado da depuração manual:
- Consumo de CPU pelas threads do w3wp.exe rodando o Default Application Pool estavam normal, de acordo com o que foi visto nos logs de Perfmon.
- Página ASPX estava executando.
- Thread 14 e outras mais estavam fazendo o FTP, afinal, o dump foi coletado durante uma tentativa de download de um arquivo:
Thread 14 – Lado nativo:
ESP EIP
0x019df778 0x7c82ed54 [FRAME: NDirectMethodFrameStandalone] [DEFAULT] I
System.Net.UnsafeNclNativeMethods/OSSOCK.accept(I,SZArray UI1,ByRef I4)
0x019df78c 0x0daf2d01 [DEFAULT] [hasThis] Class System.Net.Sockets.Socket
System.Net.Sockets.Socket.Accept()
0x019df79c 0x0d6663e8 [DEFAULT] [hasThis] Void
XXXX.DataConnection.ReceiveFromSocket()
0x019df7d8 0x0d665a75 [DEFAULT] [hasThis] Boolean
XXXX.FtpConnection.DownloadFile(String,String,ValueClass StreamModes,ValueClass FileModes,I8) ß XXXX foi só para substituir o nome real.
0x019df824 0x0d664859 [DEFAULT] [hasThis] Void
XXXX.WebForm1.btn_ok_Click(Object,Class System.Web.UI.ImageClickEventArgs)
0x019df890 0x0cfa35b6 [DEFAULT] [hasThis] Void
System.Web.UI.WebControls.ImageButton.OnClick(Class
System.Web.UI.ImageClickEventArgs)
0x019df8a4 0x0cfa3396 [DEFAULT] [hasThis] Void
System.Web.UI.WebControls.ImageButton.System.Web.UI.IPostBackEventHandler.RaisePostB
ackEvent(String)
0x019df8b4 0x0cfa333b [DEFAULT] [hasThis] Void
...
...
... continua...
...
Parte da thread 14 no lado de Managed Code:
Thread 14
ESP EIP
0x019df778 0x7c82ed54 [FRAME: NDirectMethodFrameStandalone] [DEFAULT] I
System.Net.UnsafeNclNativeMethods/OSSOCK.accept(I,SZArray UI1,ByRef I4)
ESP/REG Object Name
0x019df78c 0x0daf2d01 [DEFAULT] [hasThis] Class System.Net.Sockets.Socket System.Net.Sockets.Socket.Accept() ß .NET Framework…
EDI 0x0236153c ESI 0x021f8574 EBX 0x00000012 EDX 0x00000013 ECX 0x00000000
EAX 0x00000000 EBP 0x019df7d0 ESP 0x019df78c EIP 0x0daf2d01
ESP/REG Object Name
0x19df790 0x21f83f8 XXXX.DataConnection ß Código da aplicação do cliente.
0x019df79c 0x0d6663e8 [DEFAULT] [hasThis] Void
XXXX.DataConnection.ReceiveFromSocket()
EDI 0x023602d0 ESI 0x021f83f8 EBX 0x00000012 EDX 0x00000013 ECX 0x00000000
EAX 0x00000000 EBP 0x019df7d0 ESP 0x019df79c EIP 0x0d6663e8
ESP/REG Object Name
0x19df7a0 0x21ec6b8 XXXX.FtpConnection
0x019df7d8 0x0d665a75 [DEFAULT] [hasThis] Boolean
XXXX.FtpConnection.DownloadFile(String,String,ValueClass StreamModes,ValueClass FileModes,I8) ß Download começando.
EDI 0x023602d0 ESI 0x021ec6b8 EBX 0x00000012 EDX 0x00000013 ECX 0x00000000
EAX 0x00000000 EBP 0x019df808 ESP 0x019df7d8 EIP 0x0d665a75
ESP/REG Object Name
0x19df7e0 0x21f6458 System.String AVD
0x19df7e8 0x21ec6b8 XXXX.FtpConnection
0x19df820 0x21f82dc System.String
0x019df824 0x0d664859 [DEFAULT] [hasThis] Void
XXXX.WebForm1.btn_ok_Click(Object,Class System.Web.UI.ImageClickEventArgs) ß Aqui começa a operação…
EDI 0x021f6458 ESI 0x0235edb8 EBX 0x0235ed50 EDX 0x00000013 ECX 0x00000000
EAX 0x00000000 EBP 0x019df884 ESP 0x019df824 EIP 0x0d664859
ESP/REG Object Name
0x19df830 0x21f1334 System.Web.UI.WebControls.ListItemCollection
0x19df854 0x21f66a4 XXXX.ClsWeb
0x19df858 0x21f680c System.Object[]
0x19df85c 0x21f7a24 System.String AVD_8017_200611.XLS
...
...
...
Eis os objetos na pilha:
Thread 14
ESP/REG Object Name
0x19df760 0x2361554 System.Byte[]
0x19df768 0x236153c System.Net.SocketAddress
0x19df76c 0x21f8574 System.Net.Sockets.Socket
0x19df790 0x21f83f8 XXXX.DataConnection
0x19df7a0 0x21ec6b8 XXXX.FtpConnection
0x19df7e0 0x21f6458 System.String AVD
0x19df7e8 0x21ec6b8 XXXX.FtpConnection
0x19df820 0x21f82dc System.String e:\inetpub\wwwroot\intunica\XXXX\AVD\200
0x19df830 0x21f1334 System.Web.UI.WebControls.ListItemCollection
0x19df854 0x21f66a4 XXXX.ClsWeb
0x19df858 0x21f680c System.Object[]
0x19df85c 0x21f7a24 System.String AVD_8017_200611.XLS
0x19df860 0x21f3180 System.String AVDXLS
0x19df864 0x21eb394 System.String 272
0x19df868 0x21f3b6c System.String 200611
0x19df86c 0x21ec488 ASP.XXXX_frm_Download_aspx
0x19df894 0x21ee390 System.Web.UI.WebControls.ImageButton
0x19df89c 0x21ee414 System.ComponentModel.EventHandlerList
0x19df8c0 0x21ebc88 System.Web.HttpContext
0x19df8d0 0x21ec488 ASP.XXXX_frm_Download_aspx
0x19df8d8 0x21ec488 ASP.XXXX_frm_Download_aspx
0x19df8dc 0x21f5de4 System.Collections.Specialized.NameValueCollection
0x19df91c 0x6147900 System.Globalization.CultureInfo
0x19df920 0x61478d4 System.Globalization.CultureInfo
0x19df924 0x2114e08 System.Threading.Thread
0x19df928 0x21ec488 ASP.XXXX_frm_Download_aspx
0x19df94c 0x61b471c
System.Collections.Specialized.NameObjectCollectionBase/NameObjectEntry
0x19df970 0x61478d4 System.Globalization.CultureInfo
...
...
...
Ok, download sendo iniciado... nesse ponto uma das pergunta era: Porque o download não finalizava?
Para entender melhor o que estava havendo teria que dar uma olhada no código, isso me daria uma visão melhor. Por estar lidando com código .NET não era necessário fazer nenhuma análise de código disassemblado.
Portanto, para ver o código fonte extraí os módulos do dump e usando .NET Reflector abri eles e os decompilei.
Aos interessados em depuração hardcore essas e outras técnicas são agora divulgadas nesse livro: Debugging Microsoft .NET 2.0 Applications.
Continuando a depuração, cheguei nessas linhas de código sendo executadas:
public bool DownloadFile(string RemoteFile, string LocalFile,
FtpConnection.StreamModes StreamMode, DataConnection.FileModes FileMode, long
AppendFrom)
{
this.SendCommand("TYPE " + StringType.FromChar(Convert.ToChar((int) StreamMode)));
if (!this.CreateDataSocket(LocalFile, FileMode, DataConnection.StreamDirections.Download, AppendFrom))
{
if (this.CommandCompletedEvent != null)
{
this.CommandCompletedEvent();
}
return false;
}
if (!this.passiveTransfers)
{
IPEndPoint point1 = this.dataSocket.GetLocalEndPoint;
string[] textArray1 = new string[] { "PORT ", point1.Address.ToString().Replace(".", ","), ",", ((int) Math.Round(Math.Floor(((double) point1.Port) / 256))).ToString(), ",", (point1.Port % 0x100).ToString()
};
this.SendCommand(string.Concat(textArray1));
}
if ((FileMode == DataConnection.FileModes.Append) && (AppendFrom > 0))
{
this.SendCommand("REST " + AppendFrom.ToString());
}
this.SendCommand("RETR " + RemoteFile);
if ((this.lastResponseType != 4) && (this.lastResponseType != 5))
{
try
{
this.dataSocket.ReceiveFromSocket(); ß Linha sendo executada na pilha.
}
catch (Exception exception1)
{
ProjectData.SetProjectError(exception1);
this.dataSocket.Close();
this.WaitForResponse();
if (this.CommandCompletedEvent != null)
{
this.CommandCompletedEvent();
}
bool flag1 = false;
ProjectData.ClearProjectError();
return flag1;
}
this.WaitForResponse();
}
this.dataSocket.Close();
if (this.CommandCompletedEvent != null)
{
this.CommandCompletedEvent();
}
return true;
}
Ao depurar código gerenciado muitas vezes é necessário se recorrer ao código disassemblado e registradores para se descobrir qual a linha de código sendo executada, e valores de variáveis:
[DEFAULT] [hasThis] Boolean XXXX.FtpConnection.DownloadFile(String,String,ValueClass StreamModes,ValueClass FileModes,I8) ß Da pilha.
0d665a38 e8c3f5ffff call 0d665000 (XXXX.FtpConnection.SendCommand)
0d665a3d 8b0dacbc110a mov ecx,dword ptr ds:[0A11BCACh]
0d665a43 8b55dc mov edx,dword ptr [ebp-24h]
0d665a46 e89da6336c call mscorlib_79990000+0x100e8 (799a00e8)
(System.String.Concat)
0d665a4b 8bd0 mov edx,eax
0d665a4d 8bce mov ecx,esi
0d665a4f 3909 cmp dword ptr [ecx],ecx
0d665a51 e8aaf5ffff call 0d665000 (XXXX.FtpConnection.SendCommand) ß Chamada de DownloadFile sobrecarregada com 4 parâmetros.
0d665a56 0fbf4652 movsx eax,word ptr [esi+52h]
0d665a5a 83f804 cmp eax,4 ß Esse cmp e o próximo são da próxima cláusula if. Mapeie no fonte acima.
0d665a5d 7469 je 0d665ac8
0d665a5f 83f805 cmp eax,5
0d665a62 7464 je 0d665ac8
0d665a64 8bce mov ecx,esi
0d665a66 8b01 mov eax,dword ptr [ecx]
0d665a68 ff503c call dword ptr [eax+3Ch]
0d665a6b 8bc8 mov ecx,eax
0d665a6d 3909 cmp dword ptr [ecx],ecx
0d665a6f ff15f06e310d call dword ptr ds:[0D316EF0h] ß Eis nossa linha que mapeia para XXXX.DataConnection.ReceiveFromSocket()
0d665a75 eb48 jmp 0d665abf
0d665a77 8bc8 mov ecx,eax
0d665a79 ff15d4b4680d call dword ptr ds:[0D68B4D4h]
0d665a7f 8b4de0 mov ecx,dword ptr [ebp-20h]
0d665a82 8b01 mov eax,dword ptr [ecx]
0d665a84 ff503c call dword ptr [eax+3Ch]
0d665a87 8bc8 mov ecx,eax
0d665a89 3909 cmp dword ptr [ecx],ecx
0d665a8b ff15f86e310d call dword ptr ds:[0D316EF8h]
0d665a91 8b4de0 mov ecx,dword ptr [ebp-20h]
0d665a94 3909 cmp dword ptr [ecx],ecx
0d665a96 e8ddf2ffff call 0d664d78 (XXXX.FtpConnection.WaitForResponse)
0d665a9b 8b45e0 mov eax,dword ptr [ebp-20h]
0d665a9e 83780800 cmp dword ptr [eax+8],0
0d665aa2 740e je 0d665ab2
0d665aa4 8b45e0 mov eax,dword ptr [ebp-20h]
0d665aa7 8b4808 mov ecx,dword ptr [eax+8]
0d665aaa 3909 cmp dword ptr [ecx],ecx
0d665aac ff15706a310d call dword ptr ds:[0D316A70h]
0d665ab2 ff15dcb4680d call dword ptr ds:[0D68B4DCh]
0d665ab8 e8c7c2b46b call mscorsvr!XXXX (791b1d84)
...
Continuando...
public void ReceiveFromSocket()
{
Socket socket1;
try
{
if (this.m_Passive)
{
socket1 = this.m_DataSocket;
}
else
{
socket1 = this.m_DataSocket.Accept(); ß Linha sendo executada da chamada acima.
}
}
catch (Exception exception2)
{
ProjectData.SetProjectError(exception2);
throw new SocketException();
}
try
{
int num1;
byte[] buffer1 = new byte[0x400];
do
{
num1 = socket1.Receive(buffer1);
if (num1 > 0)
{
if (this.m_DownloadToFile)
{
this.m_FileStream.Write(buffer1, 0, num1);
}
else
{
this.m_Data = this.m_Data + this.ASCII.GetString(buffer1, 0, num1);
}
this.m_TransferredBytes += num1;
if (this.DataReceivedEvent != null)
{
this.DataReceivedEvent(num1);
}
}
}
while (num1 != 0);
}
catch (IOException exception3)
{
ProjectData.SetProjectError(exception3);
IOException exception1 = exception3;
throw exception1;
}
catch (Exception exception4)
{
ProjectData.SetProjectError(exception4);
throw new SocketException();
}
finally
{
try
{
socket1.Shutdown(SocketShutdown.Both);
}
catch (Exception exception5)
{
ProjectData.SetProjectError(exception5);
ProjectData.ClearProjectError();
}
socket1.Close();
}
}
Do ponto mencionado acima temos:
public Socket Accept()
{
if (this.CleanedUp)
{
throw new ObjectDisposedException(base.GetType().FullName);
}
if (this.m_RightEndPoint == null)
{
throw new
InvalidOperationException(SR.GetString("net_sockets_mustbind"));
}
this.ValidateBlockingMode();
SocketAddress address1 = this.m_RightEndPoint.Serialize();
IntPtr ptr1 = UnsafeNclNativeMethods.OSSOCK.accept(this.m_Handle, address1.m_Buffer, out address1.m_Size); ß Eis a linha sendo executada!
if (ptr1 == SocketErrors.InvalidSocketIntPtr)
{
SocketException exception1 = new SocketException();
this.UpdateStatusAfterSocketError();
throw exception1;
}
return this.CreateAcceptSocket(ptr1,
this.m_RightEndPoint.Create(address1));
}
A chamada de Accept() faz um PInvoke para essa API:
[DllImport("ws2_32.dll", CharSet=CharSet.Ansi, SetLastError=true)]
internal static extern IntPtr accept([In] IntPtr socketHandle, [Out] byte[] socketAddress, [In, Out] ref int socketAddressSize);
Ou, em VB.NET:
Declare Function accept Lib "ws2_32.dll" ( _
ByVal socketHandle As IntPtr, _
ByRef socketAddress As sockaddr, _
ByRef addressLength As Integer) As IntPtr
Essa chamada de API retorna um valor do tipo SOCKET para o novo socket. Esse valor é o handle para o socket no qual a conexão é feita.
E porque a chamada não retorna? Porque accept pode bloquear o chamador até que a conexão seja feita. Se o socket é marcado como nonblocking e não há conexões pendentes na fila então accept retorna um erro, o que não foi o caso.
Além disso, como essa chamada está apenas aguardando a conexão isso explica o fato de não haver um loop com alto consumo de cpu.
Nesse ponto isolamos as linhas de código fonte da aplicação do cliente, do .NET Framework e da API sendo chamada.
Além disso também acessei o valor de algumas variáveis relevantes e as informações de estruturas de Socket, para entender, além do fluxo de execução, o estado da aplicação na thread fazendo as chamadas acima.
A conclusão nesse ponto foi que por alguma razão os dados não estavam chegando na comunicação interna via Socket e que a aplicação não era o problema, assim como as chamadas usando .NET Framework e mesmo as chamadas baixo nível do socket. Portanto, o problema estava em algum outro lugar...
A partir daí solicitei ajuda ao meu amigo Yuri para fazer o troubleshooting a partir do ponto que cheguei, pois ele é especialista em Network. A atuação do Yuri foi decisiva na resolução do problema! J
5. Revisando a Infra-Estrutura
Ao receber a chamada do amigo Farah para revisar a infra-estrutura desta aplicação achei um pouco estranho, pois como o Farah citou no começo do artigo é pouco comum situações em que um problema que inicialmente foi trabalhado com o foco na aplicação torna-se um problema de infra-estrutura.
Como foi visto inicialmente o cenário fazia uso do serviço de “Network Load Balance” do Windows então surgiram as primeiras perguntas para o cliente (seguindo as respostas):
- Se desligar um nó do NLB o problema ocorre?
- Resposta: Não. Só ocorre em um nó.
- Foi feito um telnet na porta 21 em ambos nós? Caso sim, existe resposta.
- Sim foi realizado e sim existe resposta.
- Foi feito um telnet para todos os IP’s (internos e externos)?
- Sim, todos respondem.
- Caso se utilize o comando ftp e o endereço de destino o “upload” funciona?
- Sim, funciona.
- Ao digitar o comando netstat –nao qual o processo que está responsável pela porta 21?
- Processo do IIS.
- O problema acontece quando um cliente acessa via rede, mas já foi feito algum teste de acesso na aplicação através do servidor local?
- Sim, foi feito e não funciona.
O problema não era do IIS, pois o serviço respondia e funcionava caso as conexões fossem realizadas via FTP (linha de comando). Como o problema também ocorre localmente, demos prioridade a fazer testes locais, assim eliminávamos uma outra camada (rede) que porventura poderia ser a causa do problema.
Durante a depuração o Farah viu que o socket na realidade obtinha um endereço IP, ou seja, não é que ele ficava esperando e não obtinha nada é que ele obtinha um endereço, mas após isso não havia resposta. O Farah então me apresentou o resultado deste socket e me mostrou o resultado do IP obtido:
SOCKET_INFORMATION @ 0ceb2df8:
State = Bound
ReferenceCount = 2
Handle = 00000794
AddressFamily = 2
SocketType = 1
Protocol = 6
LocalAddress = 0ceb2ec0
LocalAddressLength = 16
SOCKADDR @ 0ceb2ec0
sin_family = 2 (IP)
sin_port = 1559
sin_addr = 10.102.0.2
RemoteAddress = 0ceb2ed0
RemoteAddressLength = 16
SOCKADDR @ 0ceb2ed0
sin_family = 0
sin_port = 0
sin_addr = 0.0.0.0
Lembra de onde é este IP? Se não lembra, reveja a figura e vai ver que este é o IP da placa de sincronismo que está ligada em um cabo cruzado com o outro nó (que por sinal é uma topologia não recomendada – ver artigo 242248).
Com isso o problema começou a fazer sentido, ou seja, o cliente entrava na página via rede de produção, o servidor mostrava a página e ao tentar fazer o download a aplicação abre um socket em um IP que está em uso para placa de sincronismo. Como não há saída para rede de produção através do IP da placa de sincronismo então ficamos com este estado de não resposta.
Agora por qual motivo o socket estava fazendo referência a este IP?
Partindo do pressuposto que tínhamos um nó funcionando, então revisei a configuração deste nó no que diz respeito a pilha TCP/IP e configuração do NLB. Foi quando comecei a verificar o outro e incrivelmente um item básico estava errado. Tratava-se do “Binding Order” da placa de rede do servidor NLB. A placa privada (comunicação intra-rede) estava na parte superior da pilha e a placa pública (rede de produção) estava na parte inferior da pilha.
Quando à aplicação fazia a chamada para abertura do socket não era passado nenhum parâmetro de IP e na realidade o conexão era aberta para o IP vinculado a placa de rede que tinha prioridade na ordem, que neste caso erroneamente estava sendo a placa privada.
6. Conclusão
Este foi um problema que poderia ter sido inclusive evitado caso um “checklist” de configuração dos servidores NLB tivesse sido realizado, mas realmente enganos acontecem e as vezes pequenos detalhes não são revistos. Do ponto de vista de resolução de problema este foi um caso bem interessante que mostrou o quanto é importante a integração entre os times e isso é um forte do nosso time, a integração entre as diversas divisões que trabalham com conjunto para oferecer uma excelente experiência de suporte para todos os clientes.