SMTP Protocol log en Exchange 2007

  • Article

Por Daniel Seveso

 

El "SMTP protocol log" es de suma utilidad para el seguimiento de problemas de trasporte de mensajes. El mismo registra la conversación a nivel del protocolo smtp, respuestas y errores generados por los participantes de esta conversación.

En Exchange 2000 y 2003, podemos aumentar el nivel de diagnóstico del servicio MSExchangeTransport en la categoría SMTP Protocol a nivel de debug, obteniendo así un registro de la actividad de SMTP en forma de eventos en el Application log.

 

Esto se logra configurando el valor 7 en el siguiente clave de registry:

HKLM\System\CurrentControlSet\Services\MSExchangeTransport\Diagnostics
Type: REG_DWORD
Value name: 6 SMTP Protocol
Value: 7

 

Luego de configurada esta opción, cuando recibimos un mensaje a través de SMTP, el application log muestra eventos informativos 7006 indicando que tipo de comandos estan siendo procesados y cual es la respuesta del servidor a cada comando. Este es un ejemplo del mensaje de conexión luego del ehlo recibido por el server.

Event Type: Information
Event Source: MSExchangeTransport
Event Category: SMTP Protocol
Event ID: 7006
Date: 5/1/2008
Time: 6:15:18 PM
User: N/A
Computer: NETE2K3FE
Description:
This is an SMTP protocol log for virtual server ID 1, connection #1. The client at "192.168.131.160" sent a "ehlo" command, and the SMTP server responded with "250-NetE2K3FE.dseveso.net Hello [192.168.131.160] 250-TURN 250-SIZE 250-ETRN 250-PIPELINING 250-DSN 250-ENHANCEDSTATUSCODES 250-8bitmime 250-BINARYMIME 250-CHUNKING 250-VRFY 250-TLS 250-STARTTLS 250-X-EXPS GSSAPI NTLM LOGIN 250-X-EXPS=LOGIN 250-AUTH GSSAPI NTLM LOGIN 250-AUTH=LOGIN 250-X-LINK2STATE 250-XEXCH50 250 OK ". The full command sent was "ehlo NetDC1.dseveso.net". This is an informational event and does not indicate an error.

 

Adicionalmente a estos eventos, disponemos también la opción de generar un archivo de log (protocol log), configurandolo dentro de las opciones del SMTP Virtual Server marcando la opción "Enable Logging"

image

Con "Properties..." puedes definir cuales son los campos a registrar. Desde el más básico:

#Fields: time c-ip cs-method cs-uri-stem sc-status
23:15:18 192.168.131.160 EHLO - 250
23:15:18 192.168.131.160 MAIL - 250
23:15:18 192.168.131.160 RCPT - 250
23:15:18 192.168.131.160 RCPT - 250
23:15:18 192.168.131.160 RCPT - 250
23:15:19 192.168.131.160 BDAT - 250
23:15:19 192.168.131.160 QUIT - 240

 

Hasta el más completo conjunto de campos.

#Fields: date time c-ip cs-username s-sitename s-computername s-ip s-port cs-method cs-uri-stem cs-uri-query sc-status sc-win32-status sc-bytes cs-bytes time-taken cs-version cs-host cs(User-Agent) cs(Cookie) cs(Referer)
2008-05-01 23:29:34 192.168.131.160 NetDC1.dseveso.net SMTPSVC1 NETE2K3FE 192.168.131.163 0 EHLO - +NetDC1.dseveso.net 250 0 339 23 0 SMTP - - - -
2008-05-01 23:29:34 192.168.131.160 NetDC1.dseveso.net SMTPSVC1 NETE2K3FE 192.168.131.163 0 MAIL - +FROM:<user@test.com> 250 0 38 25 0 SMTP - - - -
2008-05-01 23:29:34 192.168.131.160 NetDC1.dseveso.net SMTPSVC1 NETE2K3FE 192.168.131.163 0 RCPT - +TO:<test1@dseveso.net> 250 0 30 27 0 SMTP - - - -
2008-05-01 23:29:34 192.168.131.160 NetDC1.dseveso.net SMTPSVC1 NETE2K3FE 192.168.131.163 0 RCPT - +TO:<test2@dseveso.net> 250 0 30 27 0 SMTP - - - -
2008-05-01 23:29:34 192.168.131.160 NetDC1.dseveso.net SMTPSVC1 NETE2K3FE 192.168.131.163 0 RCPT - +TO:<test3@dseveso.net> 250 0 30 27 0 SMTP - - - -
2008-05-01 23:29:34 192.168.131.160 NetDC1.dseveso.net SMTPSVC1 NETE2K3FE 192.168.131.163 0 BDAT - +<91E79368A3574A6983259092E1BE3BFC@dseveso.net> 250 0 84 1015 311 SMTP - - - -
2008-05-01 23:29:34 192.168.131.160 NetDC1.dseveso.net SMTPSVC1 NETE2K3FE 192.168.131.163 0 QUIT - NetDC1.dseveso.net 240 471 70 4 0 SMTP - - - -

 

Cambios en Exchange 2007

En Exchange 2007 la funcionalidad de registrar eventos de SMTP en el Aplication Log no está disponible. Sin embargo, la información que nos provee el Protocol Log de Exchange 2007 supera en calidad y cantidad la ofrecida por ambos logs en Exchange 2000/2003. El Protocol Log en Exchange 2007 incluye información de sesión, conector asociado, número de secuencia de eventos para cada sesión smtp, y una serie de caracteres especiales indicando la dirección del evento. Este es un ejemplo de la entrega del mismo mensaje de arriba pero en un Exchange 2007.

#Fields: date-time,connector-id,session-id,sequence-number,local-endpoint,remote-endpoint,event,data,context
2008-05-01T23:42:35.126Z,NETE12-1\Default NETE12-1,08CA79F858031A16,0,192.168.131.162:25,192.168.131.163:1366,+,,
2008-05-01T23:42:35.206Z,NETE12-1\Default NETE12-1,08CA79F858031A16,1,192.168.131.162:25,192.168.131.163:1366,*,None,Set Session Permissions
2008-05-01T23:42:35.206Z,NETE12-1\Default NETE12-1,08CA79F858031A16,2,192.168.131.162:25,192.168.131.163:1366,>,"220 NetE12-1.dseveso.net Microsoft ESMTP MAIL Service ready at Thu, 1 May 2008 18:42:34 -0500",
2008-05-01T23:42:35.206Z,NETE12-1\Default NETE12-1,08CA79F858031A16,3,192.168.131.162:25,192.168.131.163:1366,<,EHLO NetE2K3FE.dseveso.net,
2008-05-01T23:42:35.206Z,NETE12-1\Default NETE12-1,08CA79F858031A16,4,192.168.131.162:25,192.168.131.163:1366,>,250-NetE12-1.dseveso.net Hello [192.168.131.163],
2008-05-01T23:42:35.206Z,NETE12-1\Default NETE12-1,08CA79F858031A16,5,192.168.131.162:25,192.168.131.163:1366,>,250-SIZE,
2008-05-01T23:42:35.206Z,NETE12-1\Default NETE12-1,08CA79F858031A16,6,192.168.131.162:25,192.168.131.163:1366,>,250-PIPELINING,
2008-05-01T23:42:35.206Z,NETE12-1\Default NETE12-1,08CA79F858031A16,7,192.168.131.162:25,192.168.131.163:1366,>,250-DSN,
2008-05-01T23:42:35.206Z,NETE12-1\Default NETE12-1,08CA79F858031A16,8,192.168.131.162:25,192.168.131.163:1366,>,250-ENHANCEDSTATUSCODES,
2008-05-01T23:42:35.206Z,NETE12-1\Default NETE12-1,08CA79F858031A16,9,192.168.131.162:25,192.168.131.163:1366,>,250-STARTTLS,
2008-05-01T23:42:35.206Z,NETE12-1\Default NETE12-1,08CA79F858031A16,10,192.168.131.162:25,192.168.131.163:1366,>,250-X-ANONYMOUSTLS,
2008-05-01T23:42:35.206Z,NETE12-1\Default NETE12-1,08CA79F858031A16,11,192.168.131.162:25,192.168.131.163:1366,>,250-AUTH NTLM,
2008-05-01T23:42:35.206Z,NETE12-1\Default NETE12-1,08CA79F858031A16,12,192.168.131.162:25,192.168.131.163:1366,>,250-X-EXPS GSSAPI NTLM,
2008-05-01T23:42:35.206Z,NETE12-1\Default NETE12-1,08CA79F858031A16,13,192.168.131.162:25,192.168.131.163:1366,>,250-8BITMIME,
2008-05-01T23:42:35.206Z,NETE12-1\Default NETE12-1,08CA79F858031A16,14,192.168.131.162:25,192.168.131.163:1366,>,250-BINARYMIME,
2008-05-01T23:42:35.206Z,NETE12-1\Default NETE12-1,08CA79F858031A16,15,192.168.131.162:25,192.168.131.163:1366,>,250-CHUNKING,
2008-05-01T23:42:35.206Z,NETE12-1\Default NETE12-1,08CA79F858031A16,16,192.168.131.162:25,192.168.131.163:1366,>,250-XEXCH50,
2008-05-01T23:42:35.206Z,NETE12-1\Default NETE12-1,08CA79F858031A16,17,192.168.131.162:25,192.168.131.163:1366,>,250 XRDST,
2008-05-01T23:42:35.216Z,NETE12-1\Default NETE12-1,08CA79F858031A16,18,192.168.131.162:25,192.168.131.163:1366,<,X-EXPS GSSAPI,
2008-05-01T23:42:35.216Z,NETE12-1\Default NETE12-1,08CA79F858031A16,19,192.168.131.162:25,192.168.131.163:1366,>,334 <authentication response>,
2008-05-01T23:42:35.226Z,NETE12-1\Default NETE12-1,08CA79F858031A16,20,192.168.131.162:25,192.168.131.163:1366,>,334 <authentication response>,
2008-05-01T23:42:35.226Z,NETE12-1\Default NETE12-1,08CA79F858031A16,21,192.168.131.162:25,192.168.131.163:1366,*,SMTPSubmit SMTPSubmitForMLS SMTPAcceptAnyRecipient SMTPAcceptAuthenticationFlag SMTPAcceptAnySender SMTPAcceptAuthoritativeDomainSender BypassAntiSpam BypassMessageSizeLimit SMTPSendEXCH50 SMTPAcceptEXCH50 AcceptRoutingHeaders SendRoutingHeaders SendForestHeaders SendOrganizationHeaders SendAs,Set Session Permissions
2008-05-01T23:42:35.226Z,NETE12-1\Default NETE12-1,08CA79F858031A16,22,192.168.131.162:25,192.168.131.163:1366,*,DSEVESONET\NETE2K3FE$,authenticated
2008-05-01T23:42:35.226Z,NETE12-1\Default NETE12-1,08CA79F858031A16,23,192.168.131.162:25,192.168.131.163:1366,>,235 2.7.0 Authentication successful,
2008-05-01T23:42:35.226Z,NETE12-1\Default NETE12-1,08CA79F858031A16,24,192.168.131.162:25,192.168.131.163:1366,<,MAIL FROM:<user@test.com> AUTH=<>,
2008-05-01T23:42:35.226Z,NETE12-1\Default NETE12-1,08CA79F858031A16,25,192.168.131.162:25,192.168.131.163:1366,*,08CA79F858031A16;2008-05-01T23:42:35.126Z;1,receiving message
2008-05-01T23:42:35.226Z,NETE12-1\Default NETE12-1,08CA79F858031A16,26,192.168.131.162:25,192.168.131.163:1366,>,250 2.1.0 Sender OK,
2008-05-01T23:42:35.236Z,NETE12-1\Default NETE12-1,08CA79F858031A16,27,192.168.131.162:25,192.168.131.163:1366,<,RCPT TO:<test1@dseveso.net>,
2008-05-01T23:42:35.236Z,NETE12-1\Default NETE12-1,08CA79F858031A16,28,192.168.131.162:25,192.168.131.163:1366,>,250 2.1.5 Recipient OK,
2008-05-01T23:42:35.236Z,NETE12-1\Default NETE12-1,08CA79F858031A16,29,192.168.131.162:25,192.168.131.163:1366,<,RCPT TO:<Test2@dseveso.net>,
2008-05-01T23:42:35.236Z,NETE12-1\Default NETE12-1,08CA79F858031A16,30,192.168.131.162:25,192.168.131.163:1366,>,250 2.1.5 Recipient OK,
2008-05-01T23:42:35.236Z,NETE12-1\Default NETE12-1,08CA79F858031A16,31,192.168.131.162:25,192.168.131.163:1366,<,XEXCH50 1080 3,
2008-05-01T23:42:35.236Z,NETE12-1\Default NETE12-1,08CA79F858031A16,32,192.168.131.162:25,192.168.131.163:1366,>,354 Send binary data,
2008-05-01T23:42:35.236Z,NETE12-1\Default NETE12-1,08CA79F858031A16,33,192.168.131.162:25,192.168.131.163:1366,>,250 2.0.0 XEXCH50 OK,
2008-05-01T23:42:35.236Z,NETE12-1\Default NETE12-1,08CA79F858031A16,34,192.168.131.162:25,192.168.131.163:1366,<,BDAT 1154 LAST,
2008-05-01T23:42:35.587Z,NETE12-1\Default NETE12-1,08CA79F858031A16,35,192.168.131.162:25,192.168.131.163:1366,>,250 2.6.0 <1E05BED233AB42D4AB2689A7385E0437@dseveso.net> Queued mail for delivery,
2008-05-01T23:42:35.597Z,NETE12-1\Default NETE12-1,08CA79F858031A16,36,192.168.131.162:25,192.168.131.163:1366,<,QUIT,
2008-05-01T23:42:35.597Z,NETE12-1\Default NETE12-1,08CA79F858031A16,37,192.168.131.162:25,192.168.131.163:1366,>,221 2.0.0 Service closing transmission channel,
2008-05-01T23:42:35.597Z,NETE12-1\Default NETE12-1,08CA79F858031A16,38,192.168.131.162:25,192.168.131.163:1366,-,,Local

 

El campo "event" determina el tipo de evento en la conversación, y su simbología indica lo siguiente:

+ Connect
- Disconnect
> Send
< Receive
* Information

 

El campo "session-id" y "sequence-number" nos permite filtrar los eventos del protocol log por una determinada conversación smtp y ordenar los eventos tal como son recibidos por el servidor. Esto es útil a la hora de individualizar las conversaciones simultáneas de SMTP que se mantienen con múltiples servidores.

Debido a la gran cantidad de información que se registra en este log, el mismo se encuentra deshabilitado en forma estándar. Tienes que habilitarlo y configurarlo desde el shell.

A diferencia del resto de los logs de transporte que se habilitan y configuran en el objeto TransportServer, el protocol log se habilita para cada Receive Connector o SendConnector en forma independiente y se configura a nivel general en el TransportServer. Solo el send connector que representa el servicio de smtp usado internamente entre servidores de Exchange, se habilita a nivel del TransportServer.

 

Para habilitar el protocol log en mi receive connector NETE12-1\Default NETE12-1, el comando es el siguiente:

[PS] C:\>Set-ReceiveConnector "NETE12-1\Default NETE12-1" -ProtocolLoggingLevel:Verbose

siendo NETE12-1\Default NETE12-1 la identidad del ReceiveConnector.

 

Para habilitar el protocol log en el send connector interno, el comando sería el sigiuente:

[PS] C:\>Set-TransportServer NETE12-1 -IntraOrgConnectorProtocolLoggingLevel:Verbose

siendo NETE12-1 el TransportServer (servidor con rol de HUB)

 

Los archivos de log se guardan en forma estándar en

<Directorio de instalación de Exchange>\TransportRoles\Logs\ProtocolLog\

 

Las opciones por omisión del protocol log para todas sus instancias, son las siguientes y pueden ser cambiadas usando el comando Set-TransportServer con la opción correspondiente:

ReceiveProtocolLogMaxAge : 30.00:00:00 (30 días)
ReceiveProtocolLogMaxDirectorySize : 250MB
ReceiveProtocolLogMaxFileSize : 10MB
ReceiveProtocolLogPath : C:\Program Files\Microsoft\Exchange Server\TransportRoles\Logs\ProtocolLog\SmtpReceive

SendProtocolLogMaxAge : 30.00:00:00
SendProtocolLogMaxDirectorySize : 250MB
SendProtocolLogMaxFileSize : 10MB
SendProtocolLogPath : C:\Program Files\Microsoft\Exchange Server\TransportRoles\Logs\ProtocolLog\SmtpSend

Puedes obtener información completa de como administrar el protocol log en Exchange 2007 visitando el siguiente sitio de Technet