Advanced Exchange 2007 Transport Logs Troubleshooting using Log Parser - Part 2

[The_Exchange_Team]

This is a second in my series of posts that deal with using Log Parser tool to analyze your Exchange 2007 transport logs. For the first post, please go here. I have written this blog post in a way that I walk you through building more and more complex Log Parser queries, which I hope will help you with learning how to build your own queries. Log Parser (also referred to as LP in this blog post) can take advantage of Office Web Components to draw charts of your mail flow information. To download the Office Web Components, please go here: http://www.microsoft.com/downloads/details.aspx?FamilyID=7287252C-402E-4F72-97A5-E0FD290D4B76&displa... When installed, you can use the integration of LP and Office Web Components. For example, typing: logparser -h -o:CHART will give you a chart output. Here are different options for chart types you can use: LineMarkers, LineStacked, LineStackedMarkers, LineStacked100,   LineStacked100Markers, Line3D, LineOverlapped3D, LineStacked3D, LineStacked1003D, SmoothLine, SmoothLineStacked100, BarClustered, BarStacked, BarStacked100, Bar3D, BarClustered3D, BarStacked3D, BarStacked1003D, ColumnClustered, ColumnStacked, ColumnStacked100, Column3D, ColumnClustered3D, ColumnStacked3D, ColumnStacked1003D, Pie, PieExploded, PieStacked, Pie3D, PieExploded3D, ScatterMarkers, ScatterSmoothLine, ScatterSmoothLine, AreaStacked3D, StockHLC,  PolarMarkers,  PolarSmoothLineMarkers [default value=Line] Identifying top senders to your system Using the integration with Office Web Components in LP you can extract the top 10 senders to your system: logparser "select top 10 REVERSEDNS(EXTRACT_PREFIX(remote-endpoint,0,':')) as RemoteSendingHost, count(*) as Hits into topsender.gif from RECV20070608-1.LOG group by RemoteSendingHost order by Hits DESC" -i:CSV -nSkipLines:4  -o:CHART  -chartType:PieExploded3D -chartTitle:"Top 10 senders" So far so good, but I can hear you say: "This is great but this is going to take forever on my productions logs so how do I optimize this?" One option is to filter by using the event field when it is equal to '+'. The '+' in the event field identifies a new connection so it will just happen once per SMTP connection. That being said this can still take some time especially if a lot of spammers are trying to hit the servers. The sample bellow extracts top inbound connection filtered where event equals to '+' (as the plus sign means a new inbound connection): logparser "select top 10 REVERSEDNS(EXTRACT_PREFIX(remote-endpoint,0,':')) as RemoteSendingHost, count(*) as Hits into topsender.gif from RECV*.LOG where event='+' group by RemoteSendingHost order by Hits DESC" -i:CSV -nSkipLines:4  -o:CHART  -chartType:PieExploded3D -chartTitle:"TOP 10 senders" Next step is to be able to narrow on a specific time frame in your Exchange 2007 logs. The table bellow provides the LP conversion expressions to use in order to manipulate the different date and time formats:

Extracting	Log Parser expression	Format
Date	EXTRACT_PREFIX([#Fields: date-time],0,'T')	YYYY-MM-DD
Time	EXTRACT_PREFIX(TO_STRING(EXTRACT_SUFFIX([#Fields: date-time],0,'T')),0,'.')	HH:MM:SS
Date & time	TO_TIMESTAMP ( EXTRACT_PREFIX(TO_STRING([#Fields: date-time]),0,'.') , 'yyyy-mm-ddThh:mm:ss')	TO_TIMESTAMP (Log Parser time stamp type)

So returning all rows after '2007-10-10 21:46:23' from a log file would look like this: logparser "select * from RECV.LOG where TO_TIMESTAMP ( EXTRACT_PREFIX(TO_STRING([#Fields: date-time]),0,'.') , 'yyyy-mm-ddThh:mm:ss') > TO_TIMESTAMP ('2007-10-10 21:46:23','yyyy-mm-dd hh:mm:ss')" -i:CSV -nSkipLines:4 -o:DATAGRID Returning all rows between 2007-05-13 21:00:00 and '2007-05-13 21:15:00' from an Exchange 2007 SMTP log file would look like this: logparser "select TO_TIMESTAMP ( EXTRACT_PREFIX(TO_STRING([#Fields: date-time]),0,'.'), 'yyyy-mm-ddThh:mm:ss') as DateTime, EXTRACT_PREFIX(remote-endpoint,0,':') as RemoteSending, data, context, case TO_INT( SUBSTR(DATA,0,3)) when NULL then 0 else TO_INT(SUBSTR(DATA,0,3)) end as RemoteHostReturnCode from SEND*.log where RemoteHostReturnCode > 500 and context <> 'Certificate thumbprint' and context <> 'sending message'" -i:CSV -nSkipLines:4 -o:DATAGRID Identifying times of highest traffic Now you might want to know in what time of the day your system has most connections and traffic. This is also interesting in order to identify when potential spam attacks have occurred. In order to draw a radar graph of global total SMTP inbound simultaneous connections per hours: logparser "SELECT QUANTIZE(TO_TIMESTAMP (EXTRACT_PREFIX(TO_STRING(EXTRACT_SUFFIX([#Fields: date-time],0,'T')),0,'.'), 'hh:mm:ss'),3600) AS Hour, COUNT(*) AS Hits INTO radar_traffic.gif from RECV*.log where event='+' GROUP BY Hour ORDER BY Hour ASC" -i:CSV -nSkipLines:4 -o:CHART -charttype:RadarLineFilled -charttitle:" Global total SMTP inbound simultaneous connections per hours" Identifying top senders Now let's say we want to identify our top senders. Top senders are usually referred to as senders that are sending the most messages. So let's first build a query to output senders by where we at least started to "receive a message": logparser "select top 10 remote-endpoint, count(*) as Hits into topsender-messages.gif from RECV*.LOG where context='receiving message' group by remote-endpoint order by Hits DESC" -i:CSV -nSkipLines:4  -o:CHART  -chartType:PieExploded3D -chartTitle:"TOP 10 senders of messages" But this doesn't mean that all messages where 'accepted' because in one SMTP connection multiple SMTP messages can be sent but some can be accepted and other rejected. If you dig into the Exchange logs you will find that the "signature" of an accepted message is as follows: Data field starts with the following string: "250 2.6.0 <" and ends with the following string "Queued mail for delivery". Sample query to dump all inbound queued mail for delivery: logparser "select * from RECV*.log where (data like '%250 2.6.0 <%') and (data like '%Queued mail for delivery%')" -i:CSV -nSkipLines:4  -o:DATAGRID Now we can group by top senders of messages, note we are removing the port number because indeed a same host can connect multiple times in a day but using different remote source ports. Of course you can REVERSEDNS to identify (or at least getting started to identify) that is hiding behind the IPs: logparser "select EXTRACT_PREFIX(remote-endpoint,0,':') as remote-host, count(*) as hits from RECV*.log where (data like '%250 2.6.0 <%') and (data like '%Queued mail for delivery%') group by remote-host order by hits DESC" -i:CSV -nSkipLines:4  -o:DATAGRID Identifying top email rejecting IP sources Identifying top servers that you most reject mail from is helpful to help saving bandwidth. If a server is sending mail that is very often rejected, that is very likely to help you identify potential spammers. Once these IP sources have been identified, they can be blocked at firewall level and will help against consuming bandwidth by unsolicited email. A manual check should be performed to make sure that the sending server is indeed a real offender. Sample exchange log of unsolicited mail blocked by exchange that can be found in the data field:

550 5.7.1 Message rejected due to content restrictions

Identifying top rejected senders would look like this: logparser "select EXTRACT_PREFIX(remote-endpoint,0,':') as Remote-host, count (*) as hits from RECV*.log where data like '%rejected%' group by Remote-host order by hits desc" -i:CSV -nSkipLines:4  -o:DATAGRID As you can see in the example above the same sender 10.0.0.x as multiple outbound hosts that seem to be on the same C class... A wider interesting search would be to look at 550 return codes: logparser "select * from RECV*.log  where data like '%550 %'" -i:CSV -nSkipLines:4  -o:DATAGRID As you can see from results of that, 550's are also valid for relay attempts. So the following query will help you identify both mail rejection and senders trying to relay through your mail system: logparser "select EXTRACT_PREFIX(remote-endpoint,0,':') as Remote-host, count (*) as hits from RECV*.log where data like '%550 %' group by Remote-host order by hits desc" -i:CSV -nSkipLines:4  -o:DATAGRID Note if you don't see any "Unable to relay" attempts in your logs it is very likely that:

- You have a smarthost upfront blocking beforehand and may relay attempts.

Or

- That your server is indeed relaying mail.

There are other 500's types of status codes such as 504, 535 and so on. The most effective query I have found is to catch all numeric numbers above 500. The LP query would look like this: logparser "select *  from RECV*.log where TO_INT( SUBSTR(DATA,0,3)) > 500 and event = '>'" -i:CSV -nSkipLines:4  -o:DATAGRID Then, the ultimate group by query would be: logparser "select EXTRACT_PREFIX(remote-endpoint,0,':') as Remote-host, count (*) as hits from RECV*.log where TO_INT( SUBSTR(DATA,0,3)) > 500 and event = '>' group by Remote-host order by hits desc" -i:CSV -nSkipLines:4  -o:DATAGRID You can use the REVERSEDNS function on top of that. If you see IP address returned instead of a FQDN, it is even more likely that these hosts are really offenders because they didn't provide a reverse PTR record. But again - doing a reversedns function on huge logs would be slow. The best approach I have come up with to work around that is in two phases: 1. As shown above, identify the list of suspicious senders with the query and dump the output to a temporary log file such as the following: logparser "select EXTRACT_PREFIX(remote-endpoint,0,':') as Remote-host, count (*) as hits into SuspiciousSenders.xml  from RECV*.log where TO_INT( SUBSTR(DATA,0,3)) > 500 and event = '>' group by Remote-host order by hits desc" -i:CSV -nSkipLines:4  -o:XML 2. You can then load the XML generated file as below and apply the REVERSEDNS only on the "hotspot" (top senders): logparser "select REVERSEDNS(Remote-host), hits from  SuspiciousSenders.xml" -i:XML -o:DATAGRID You can then select the top 10 and first investigate those: logparser "select top 10 REVERSEDNS(Remote-host), hits from  SuspiciousSenders.xml" -i:XML -o:DATAGRID Identifying outbound email issues As we have mentioned previously, outbound SMTP log is located in: ProtocolLog\SmtpSend. If we want to identify outbound status codes we first need to parse the data field to identify if the remote host has accepted our messages and as the Data field is a string we also need to convert it to an "int" (intger) type: logparser "select case TO_INT( SUBSTR(DATA,0,3)) when NULL then 0 else TO_INT( SUBSTR(DATA,0,3)) end as RemoteHostReturnCode from SEND*.log " -i:CSV -nSkipLines:4 -o:DATAGRID We are filtering status codes above 400 as we want to have both deferred and rejected emails. For rejected emails only you can filter at 500. So getting detailed information of outbound issues would look like this: logparser "select EXTRACT_PREFIX(remote-endpoint,0,':') as Remote-host, data, context, case TO_INT( SUBSTR(DATA,0,3)) when NULL then 0 else TO_INT( SUBSTR(DATA,0,3)) end as RemoteHostReturnCode from SEND*.log where RemoteHostReturnCode > 400" -i:CSV -nSkipLines:4 -o:DATAGRID That being said, the above might get some false positives so a better query looks like this: logparser "select TO_TIMESTAMP ( EXTRACT_PREFIX(TO_STRING([#Fields: date-time]),0,'.'), 'yyyy-mm-ddThh:mm:ss') as DateTime, EXTRACT_PREFIX(remote-endpoint,0,':') as Remote-host, data, context, case TO_INT( SUBSTR(DATA,0,3)) when NULL then 0 else TO_INT(SUBSTR(DATA,0,3)) end as RemoteHostReturnCode from SEND*.log where RemoteHostReturnCode > 400 and context <> 'Certificate thumbprint' and context <> 'sending message'" -i:CSV -nSkipLines:4 -o:DATAGRID Now again you can use the two step approach as mentioned above to dump the results into an .XML log file: logparser "select EXTRACT_PREFIX(remote-endpoint,0,':') as Remote-host, count(*) as hits into SendingIssues.xml from SEND*.log where TO_INT( SUBSTR(DATA,0,3)) > 400 and context <> 'Certificate thumbprint' and context <> 'sending message' group by Remote-host order by hits desc" -i:CSV -nSkipLines:4 -o:XML And then group by and "reversedns" on it: logparser "select REVERSEDNS(Remote-host), hits from  SendingIssues.xml" -i:XML -o:DATAGRID Based on the above queries, the following one will build a table of top rejection errors by type and number of hits: logparser "select case TO_INT( SUBSTR(DATA,0,3)) when NULL then 0 else TO_INT( SUBSTR(DATA,0,3)) end as RemoteHostReturnCode, data, count (*) as hits from SEND*.log where RemoteHostReturnCode > 400 and context <> 'Certificate thumbprint' and context <> 'sending message' group by RemoteHostReturnCode, data order by hits desc" -i:CSV -nSkipLines:4 -o:DATAGRID

RemoteHostReturnCode	Data	Hits
554	554- (RTR:DU)  http://postmaster.contoso.com/errors/yyy.html	1595
550	550 Desole votre serveur de messagerie etant identifie comme generateur de messages non sollicites. Votre message ne peut etre delivre. Veuillez contacter votre administrateur systeme.	653
451	451 Message temporarily deferred - [160]	563
421	421 Message from (mail.contoso.com) temporarily deferred - 4.16.50. Please refer to http://mail.contoso.com/defer.html	498
550	550 DY-001 Mail rejected by this domain for policy reasons.	223
550	550-5.7.1 [mail.contoso.com] The IP you're using to send email is not authorized	206
550	550-5.7.1 To send email directly to our servers please use..	198
550	550 5.7.1 Service unavailable; Client host [mail.contoso.com] blocked	187
554	554 TRANSACTION FAILED	108
554	554-: (RTR:GE) http:// postmaster.contoso.com/errors/yyy.html	78
550	550 Mail rejected. Contact your ISP to determine which authorized SMTP relay servers to send your mail through (or) request a static and dedicated IP before attempting to send mail.	76
502	502 Error: command not implemented	1
550	550 5.7.1 Rejected: mail.contoso.com listed as spam source	1

Content agent filtering log Content Agent Filtering files are very similar in format and structure to SMTP inbound protocol log files so same tricks apply. They can be parsed by LP using the same base line as above. They really help understanding mail rejection reasons. Table of fields:

Field	Most useful (in our examples)
Timestamp	x
SessionId
LocalEndpoint
RemoteEndpoint	x
EnteredOrgFromIP	x
MessageId
P1FromAddress	x
P2FromAddresses	x
Recipient	x
NumRecipients	x
Agent
Event
Action
SmtpResponse	x
Reason	x
ReasonData	x

Similar to examples mentioned earlier, the baseline Log Parser query for AGENT logs will look like this: logparser "select * from AGENT*.log " -i:CSV -nSkipLines:4  -o:DATAGRID In order to get all types of rejection reasons I have came up with the bellow query: logparser "select case TO_INT(ReasonData) when NULL then 10 else ReasonData end as ReasonData2, count(*) as hits into agentreasonspread.gif from AGENT*.log group by ReasonData2 order by hits desc" -i:CSV -nSkipLines:4  -o:CHART  -chartType:PieExploded3D -chartTitle:"Agent reason spread" -e 200

- 0 is accepted content

- Everything else is rejected content

This gives a great idea of the amount of rejected mail by a server. Message tracking log This log is self explanatory and is the best place to look at when one is trying to understand what goes in and out of the system, especially when multiple routing connectors are available. It also keeps tracks of all message subjects that go through the server.  So when message routing or history is in question, this is the place to go to. Again same LP base line query applies: logparser "select * from AGENT*.log " -i:CSV -nSkipLines:4  -o:DATAGRID

Field	Most useful (in our examples)
date-time	x
client-ip	x
client-hostname
server-ip	x
server-hostname
source-context	x
connector-id
source	x
event-id
internal-message-id
message-id
recipient-address	x
recipient-status
total-bytes	x
recipient-count
related-recipient-address
reference
message-subject	x
sender-address
return-path	x
message-info

As you can see, this log provides valuable information around message bytes. For example - a same message-id can generate several raws (at different steps) and generate different total-bytes size at each step. As we explained above it is also useful to understand mail flow between hosts. The following query will help you identify the top used connectors, this is data is extremely interesting when dealing with complex topologies: logparser "select connector-id, count (*) as Hits from MSGT*.log group by connector-id order by hits desc" -i:CSV -nSkipLines:4 I hope this document has provided you some hints on how LP can help you in parsing new Exchange 2007 transport logs! Additional reading How to Configure Protocol Logging on Exchange 2007: http://technet.microsoft.com/en-us/library/c81cac9c-b990-492a-b899-5be8d08a6068.aspx The Office Web Components (for Log Parser) can be downloaded at: http://www.microsoft.com/downloads/details.aspx?FamilyId=7287252C-402E-4F72-97A5-E0FD290D4B76&displa... Log Parser: http://www.microsoft.com/downloads/details.aspx?FamilyID=890cd06b-abf8-4c25-91b2-f8d975cf8c07&displa... I would like to thank Jeffrey A. Johnson and Nino Bilic for their help in writing, testing and reviewing this! - Julien Clauzel

[#2]

A hell of a log parser post, nice work! :) Hey the Technet Flash Newsletter today claimed SP1 (non-beta, the real deal) is being released 11/30 for download. Any truth to this?

[#3]

Tomorrow SP1, party on.. Wheeeeuww.

[#4]

Agreed - I would have expected some sort of annoucement re: SP1 here on the blog. I've made this my start page on IE just to get the good news ASAP, only to see it first mentioned on a TechNet mailing last night. Ah, the mysterious ways of the corporate machine.

[#5]

Well guys - since nobody else has put it here yet, I'll announce that SP1 has been RTM'ed!!

I'm downloading it right now at:

http://www.microsoft.com/downloads/details.aspx?FamilyId=44C66AD6-F185-4A1D-A9AB-473C1188954C&displa...

Good luck!

[#6]

ITS THERE !!!

http://www.microsoft.com/downloads/details.aspx?FamilyId=44C66AD6-F185-4A1D-A9AB-473C1188954C&displa...

[#7]

Been working with E2003 for few years and got used to it. Now I feel like we are getting back to DOS days, or UNIX, if you like. I understand that Log Parser and Powershell are nice tools, but is there a GUI-based alternative by any chance? I just feel sick when I see those multiple line queries...