Freigeben über

SMTP: Analisi del Protocol Logging in Exchange 2003

  • Artikel

L'SMTP virtual server ha un suo protocol logging che offre anche la possibilità di farci analizzare qualche informazione utile sul nostro sistema Exchange. Spesso ci si dimentica di ciò, relegando tale attività al Diagnostic logging di Exchange nel caso si debba analizzare qualche problematica o, al Message tracking, quando si voglia verificare il percorso di un messaggio all'interno dell'infrastruttura.

Parlando di Exchange 2003 spesso ci troviamo ad aver bisogno di analizzare il pattern di traffico SMTP per capire cosa sta succedendo durante il rallentamento del flusso del traffico mail su un server specifico, e spesso il logging non risulta essere attivato oppure risulta essere attivato ad un livello troppo basso per poter estrapolare informazioni utili.

Detto questo, ciò non è un problema fintanto che non si presenti la necessità di fare un analisi temporale di una problematica. L'incremento del livello di logging è un operazione semplice e veloce, ma la mancanza di dati anteriori al presentarsi del problema rende impossibile analizzare il potenziale momento zero in cui l'anomalia si è presentata.

Queste informazione possono essere utili, nel momento in cui si hanno i dati di più sistemi da aggregare (event log di più sistemi, protocol log di vari server, router e firewall log) per fare il punto della situazione su una problematica in corso.

Abilitazione del protocol log

La configurazione del protocol logging si esegue dalla console di Exchange seguendo il percorso:

Organizzazione -> Servers -> Protocols -> Smtp -> Proprietà del virtual server SMTP -> Enable logging

Come tipologia di logging, io preferisco il formato w3c in quanto è facilmente manipolabile sia con Excel, sia con LogParser

I log sono salvati in: C:\Windows\System32\logfiles\SMTPSVCxxx

Come configurazione per la gestione dei file, preferisco il logging giornaliero per 2 motivi:

  • I file non sono mai troppo grossi da rallentare le operazioni di manipolazioni come nel caso del log settimanale o mensile.
  • Il logging orario genera troppi file che devono poi essere uniti.

I campi da includere nel logging sono i seguenti:

date; time; c-ip; cs-username; s-sitename; s-computername; s-ip; s-port; cs-method; cs-uri-query; sc-status; sc-bytes; cs-bytes; time-taken.

Interpretazione del log file

Per interpretare correttamente i campi tenete presente i suffissi del nome dei campi:

  • c- : Client 
  • s- : Server 
  • cs- : comunicazione dal Client al server
  • sc- : comunicazione dal Server al client

Date e Time ci indicano il momento in cui stato loggato l'evento, considerate che l'orario è sempre in GMT (Greenwich Meridian Time)

c-ip: Indirizzo ip del client.

cs-username: Nome macchina con cui il client si presenta al server.

s-sitename: Qui troverete il nome del virtual server smtp da cui parte la chiamata.Il nome è lo stesso della cartella in cui è salvato il log. es:SMTPSVC1

s-computername: Nome del server (qui è possibile trovare l'indirizzo ip della macchina remota)

s-ip: Server ip addres (quello associato al virtual server smtp).

s-port: Porta tcp utilizzata

cs-method: Generalmente il verbo smtp inviato dal client, es: ehlo, mail, data, quit etc.

cs-uri-query: Parametro del comando smtp, es: from:utente@dominio.dom nel caso di un verbo mail from

sc-status: codice di ritorno che il server genera a fronte del comando inviato, es. 250 (ok)

sc-bytes: numero di bytes inviati dal server al client

cs-bytes: numero di bytes inviati dal client al server

time-taken: durata della comunicazione in millisecondi

Durante l'analisi di un log SMTP, generalmente viene analizzato un sottoinsieme di verbi, nel complesso si guarda lo stato della sessione nella sua integrità. Vi riporto il sotto insieme più utilizzato durante l'analisi con la descrizione del verbo.
Per la lista completa dei verbi SMTP, fare riferimento a: SMTP Protocol Extensions

HELO e EHLO

Helo indica l'inizio di una sessione SMTP base, mentre ehlo indica che sono supportati i verbi avanzati SMTP.

MAIL

Identifica l'identità del mittente. Lo troverete come: MAIL FROM.

RCPT

Indica la lista dei destinataria cui è diretta la mail. Nella forma RCPT TO.

DATA

Indica l'inizio del trasferimento dati del contenuto della mail.

BDAT, CHUNKING

Comando alternativo a DATA, usato in sessioni EHLO.

Con il verbo CHUNKING il server indica che è utilizzabile il verbo BDAT e quindi è possibile suddividere il messaggio in pezzetti.

Il vantaggio del comando BDAT è che che per ogni chunk inviato, il server remoto ne notifica la dimensione. Questo permette al server locale di non controllare continuamente i dati ricevuti per ricercare la fine del messaggio, ma in questo caso si limita a fare un conteggio dei byte ricevuti: questo migliora le performance del server in ricezione.

QUIT

Indica la fine della sessione SMTP.

RSET

Resetta il buffer della sessione SMTP.

Sessione SMTP

Di seguito riporto un esempio di sessione SMTP tra Front-end e Back-end in cui il front-end passa una mail al back-end con Ehlo

#Fields: date time c-ip cs-username s-sitename s-computername s-ip s-port cs-method cs-uri-query sc-status sc-bytes cs-bytes time-taken
2008-09-23 13:38:54 172.16.10.15 OutboundConnectionResponse SMTPSVC1 FRONTEND - 25 - 220+back.monkey.island+Microsoft+ESMTP+MAIL+Service,+Version:+6.0.3790.3959+ready+at++Tue,+23+Sep+2008+15:38:54++0200+ 0 125 0 15
2008-09-23 13:38:54 172.16.10.15 OutboundConnectionCommand SMTPSVC1 FRONTEND - 25 EHLO frontend.monkey.island.int 0 4 0 15
2008-09-23 13:38:54 172.16.10.15 OutboundConnectionResponse SMTPSVC1 FRONTEND - 25 - 250-back.monkey.island+Hello+[172.16.10.17] 0 50 0 15
2008-09-23 13:38:54 172.16.10.15 OutboundConnectionResponse SMTPSVC1 FRONTEND - 25 - 334+GSSAPI+supported 0 20 0 31
2008-09-23 13:38:54 172.16.10.15 OutboundConnectionResponse SMTPSVC1 FRONTEND - 25 - 334+[CUT] 0 224 0 47
2008-09-23 13:38:54 172.16.10.15 OutboundConnectionResponse SMTPSVC1 FRONTEND - 25 - 235+2.7.0+Authentication+successful. 0 36 0 47
2008-09-23 13:38:54 172.16.10.15 OutboundConnectionCommand SMTPSVC1 FRONTEND - 25 X-LINK2STATE LAST+CHUNK={0000006a}+MULTI+(5)+({00000051}+DIGEST_QUERY+05996d955a6b194d96b4bdc96a3edb91+59f38b59d328aeb71e6e0cd01c35e32b++)++ 0 12 0 47
2008-09-23 13:38:54 172.16.10.15 OutboundConnectionResponse SMTPSVC1 FRONTEND - 25 - 200+LAST+CHUNK={00000029}+MULTI+(5)+({00000010}+DONE_RESPONSE++)++ 0 66 0 47
2008-09-23 13:38:54 172.16.10.15 OutboundConnectionCommand SMTPSVC1 FRONTEND - 25 MAIL FROM:<elaine@booty.island>+AUTH=<> 0 4 0 47
2008-09-23 13:38:54 172.16.10.15 OutboundConnectionResponse SMTPSVC1 FRONTEND - 25 - 250+2.1.0+elaine@booty.island....Sender+OK 0 41 0 47
2008-09-23 13:38:54 172.16.10.15 OutboundConnectionCommand SMTPSVC1 FRONTEND - 25 RCPT TO:<GUYBRUSH@MONKEY.ISLAND> 0 4 0 47
2008-09-23 13:38:54 172.16.10.15 OutboundConnectionResponse SMTPSVC1 FRONTEND - 25 - 250+2.1.5+GUYBRUSH@MONKEY.ISLAND+ 0 46 0 47
2008-09-23 13:38:54 172.16.10.15 OutboundConnectionCommand SMTPSVC1 FRONTEND - 25 XEXCH50 1092+2 0 7 0 47
2008-09-23 13:38:54 172.16.10.15 OutboundConnectionResponse SMTPSVC1 FRONTEND - 25 - 354+Send+binary+data 0 20 0 47
2008-09-23 13:38:54 172.16.10.15 OutboundConnectionResponse SMTPSVC1 FRONTEND - 25 - 250+XEXCH50+OK 0 14 0 62
2008-09-23 13:38:54 172.16.10.15 OutboundConnectionCommand SMTPSVC1 FRONTEND - 25 BDAT 21089+LAST 0 4 0 62
2008-09-23 13:38:54 172.16.10.15 OutboundConnectionResponse SMTPSVC1 FRONTEND - 25 - 250+2.6.0++<1e7932b22686$25501dfb$0c18149e@bxzenisl>+Queued+mail+for+delivery 0 77 0 62
2008-09-23 13:38:54 172.16.10.15 OutboundConnectionCommand SMTPSVC1 FRONTEND - 25 RSET - 0 4 0 93
2008-09-23 13:38:54 172.16.10.15 OutboundConnectionResponse SMTPSVC1 FRONTEND - 25 - 250+2.0.0+Resetting 0 19 0 93
2008-09-23 13:38:58 172.16.10.15 OutboundConnectionCommand SMTPSVC1 FRONTEND - 25 QUIT - 0 4 0 2937
2008-09-23 13:38:58 172.16.10.15 OutboundConnectionResponse SMTPSVC1 FRONTEND - 25 - 221+2.0.0+back.monkey.island+Service+closing+transmission+channel 0 72 0 2937

Da notare le ultime 4 righe, in particolare la sequenza RSET -> 250 resetting -> QUIT -> 221 closing trasmission channel.

In questo caso ho tagliato il log riportato per motivi di lunghezza. Il front-end aveva più email da consegnare al back-end e quindi ha proceduto a fare il reset del canale dopo il quint'ultimo comando(queued mail for delivery), e ha ricominciato la sequenza di comandi da “Mail from” per il successivo messaggio in coda.

Log Parsing

Un tool molto comodo per fare un parsing dei log SMTP è il LogParser, scaricabile gratuitamente.

LogParser è un processore intelligente di log che supporta una sintassi query SQL per l'interrogazione di vari formati di file e permette l'export del risultato della query in vari formati, testuali e grafici.

Alcuni si chiederanno come mai utilizziamo LogParser quando abbiamo a disposizione strumenti come Excel, che permettono una manipolazione grafica del file?
La risposta è tutto sommato semplice: è possibile creare script! Potete creare script Batch, Vbs o Powershell che, a titolo di esempio, vi crei dei reports durante la notte e li pubblichi su un sito intranet o li invii tramite email.

Vediamo qualche elaborazione che può esserci utile:

  1. Top 10 client che hanno "occupato" il server per più tempo (aka: somma dei tempi della sessione)
    logparser -i:w3c "select Top 10 c-ip as ClientIp,div(div(sum(to_real(time-taken)),1000),60) as TotalMinutes,div(sum(to_real(cs-bytes)),1024) as ClientSentKb,div(sum(to_real(sc-bytes)),1024) as ServerSentKb from example.log where ((cs-method not like 'quit') and (cs-method <> NULL)) group by ClientIp order by TotalMinutes desc" -q:on -o:datagrid

  2. Top 10 client che hanno trasferito più dati (sempre somma totale dei byte di tutte le sessioni):
    logparser -i:w3c "select Top 10 c-ip as ClientIp,div(div(sum(to_real(time-taken)),1000),60) as TotalMinutes,div(sum(cs-bytes),1024) as ClientSentKb,div(sum(sc-bytes),1024) as ServerSentKb from example.log where ((cs-method not like 'quit') and (cs-method <> NULL)) group by ClientIp order by ClientSentKb desc" -q:on -o:datagrid

  3. Top 10 command che hanno impiegato più tempo:
    logparser -i:w3c "select Top 10 c-ip as ClientIp,cs-username as ClientName,cs-method as Verb,cs-uri-query as Command,div(to_real(time-taken),1000) as CommandSeconds,div(to_real(cs-bytes),1024) as ClientSentKb,div(to_real(sc-bytes),1024) as ServerSentKb from monkey.log where ((verb not like 'quit') and (verb <> NULL)) order by CommandSeconds desc" -q:on -o:datagrid

  4. Top 10 command che hanno trasferito più dati:
    logparser -i:w3c "select Top 10 c-ip as ClientIp,cs-username as ClientName,cs-method as Verb,cs-uri-query as Command,div(to_real(time-taken),1000) as CommandSeconds,div(to_real(cs-bytes),1024) as ClientSentKb,div(to_real(sc-bytes),1024) as ServerSentKb from example.log where ((verb not like 'quit') and (verb <> NULL)) order by ClientSentKb desc" -q:on -o:datagrid

  5. Tutte le sessioni di un client:
    logparser -i:w3c "select * from example.log where c-ip like '172.16.10.15'" -q:on -o:datagrid

  6. Comandi che hanno ricevuto una risposta negativa temporanea (es. timeout):
    logparser -i:w3c "select * from example.log where((sc-status > 400) and (sc-status < 500))" -q:on -o:datagrid

  7. Comandi che hanno ricevuto un errore:
    logparser -i:w3c "select * from example.log where (sc-status > 500)" -q:on -o:datagrid

  8. Indicativamente quanti byte sono transitati in SMTP:
    logparser -i:w3c "select sum(cs-bytes) as ClientSentKb, sum(sc-bytes) as ServerSentKb from example.log where ((cs-method not like 'quit') and (cs-method <> NULL))" -q:on -o:datagrid

  9. Logparser bonus NeuroView Star:

    Provate a sostituire nei comandi precedenti l'ultimo parametro:
    -o:datagrid

    con
    -o:neuroview -looprows 100

L'analisi di un log SMTP può fornire qualche informazione utile anche riguardo allo stato del nostro sistema Exchange, oltre a fornirci una visione dettagliata di quello che sta accadendo a basso livello.

Possiamo per esempio verificare se una sessione SMTP ha dei problemi di performance magari dovuti all'infrastruttura di rete, ad esempio link VPN o DSL, molto usati nelle grosse infrastrutture dove la topologia dell'infrastruttura Exchange è composta da svariati siti e routing group: quindi routing group connector e SMTP connector.

Per fare un esempio verificando il trasferimento di una mail da un sito all'altro, potremmo renderci conto di essere di fronte ad una situazione del genere:

 cs-bytes: 10240; time-taken:35000

Dipendentemente dalla tipologia di link di rete che abbiamo a disposizione, 35 secondi per inviare 10kb potrebbero essere accettabili, ma nella maggior parte dei casi, sarebbe indicativo di un problema lato network piuttosto che un problema di processi Exchange. Anche se la prima impressione dovuta alle code SMTP in crescita, avrebbe potuto far pensare il contrario.

Francesco Poli
Senior Support Engineer
Microsoft Enterprise Exchange Support