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.
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 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.
Per interpretare correttamente i campi tenete presente i suffissi del nome dei campi:
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.
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.
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:
Logparser bonus NeuroView : 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