Exchange Server 2007 Process Tracking Log Tool
As a Microsoft Exchange Server 2007 administrator, you can experience situations that may require parsing, monitoring, and analyzing Message Tracking logs. These situations include the following scenarios:
Growth of a transaction log or of a database
A server experiencing many unsolicited commercial e-mail messages (also known as spam)
A looping message
Transport queue backup
Poor server performance
In such scenarios, you may have to review and analyze the Exchange Message Tracking logs. The following factors or combination of factors can make it difficult or impossible to analyze the message tracking logs manually:
Many fields
A large amount of data in message tracking logs
Large message tracking log files
Additionally, if you have to review message tracking log files from multiple servers, the task becomes even more complex.
Process Tracking Log tool simplifies reviewing message tracking logs by automating the parsing and analysis of Message tracking logs, and then generating an .xls or .txt output file for reporting. This tool provides useful data about monitoring, administration, and troubleshooting. This tool also provides important data about end-to-end delivery latency distribution for all Messages Delivered, Server Latency Distribution for all Messages Processed, and Server Latency Distribution for all Individual Deliveries.
Important
The Process Tracking Log tool script was developed by Todd Luttinen, Principal Program Manager at Microsoft. However, this tool is not an official Microsoft tool. Therefore, we recommend that you review the script before you run this tool in a production environment.
To obtain the tool
To download the Process Tracking Log tool (Processtrackinglog.vbs), see the Exchange Server Team Blog article Processtrackinglog.vbs script
Running the tool
USAGE:
To run this tool, use the following script:
cscript ProcessTrackingLog.vbs <LogFilePath> <NumFiles> <hub|edge|all> [ <mm/dd/yyyy> | today | yesterday ]
Note
This syntax assumes that the "HUB" or "GWY" exists in the directory path. If neither of these entries is displayed in the directory path, specify "all" in the command-line.
EXAMPLES:
The following command-line examples provide usage scenarios for the Process Tracking Log tool.
To parse one file
cscript ProcessTrackingLog.vbs "D:\Program Files\Microsoft\Exchange Server\TransportRoles\Logs\MessageTracking\MSGTRK20070804-1.LOG" 1 all
To parse one file in a single directory
cscript \data\scripts\ProcessTrackingLog.vbs "D:\Program Files\Microsoft\Exchange Server\TransportRoles\Logs\MessageTracking" 1 all
To parse all files in a single directory
cscript \data\scripts\ProcessTrackingLog.vbs "D:\Program Files\Microsoft\Exchange Server\TransportRoles\Logs\MessageTracking" 0 all
To parse all files in all subdirectories in a single directory
cscript \data\scripts\ProcessTrackingLog.vbs "D:\Program Files\Microsoft\Exchange Server\TransportRoles\Logs\MessageTracking" 0 all
To parse three files in each subdirectory
cscript \data\scripts\ProcessTrackingLog.vbs "D:\Program Files\Microsoft\Exchange Server\TransportRoles\Logs\MessageTracking" 3 all
To parse all files that were logged yesterday, in each subdirectory
cscript \data\scripts\ProcessTrackingLog.vbs "D:\Program Files\Microsoft\Exchange Server\TransportRoles\Logs\MessageTracking" 0 all yesterday
To parse all files that were logged on 10/29/2007, in each subdirectory
cscript \data\scripts\ProcessTrackingLog.vbs "D:\Program Files\Microsoft\Exchange Server\TransportRoles\Logs\MessageTracking" 0 all 10/29/2007
The results from the Process Tracking Log tool are stored in the c:\temp\msgtrack\output directory. If you install the Winzip command-line tools in the default path on drive C, the Process Tracking Log tool automatically archives the results in a compressed (.zip) file.
Output files
The following sections describe each output file that the Process Tracking Log tool generates, together with interpretations of example data.
MTDsnFailureResults.csv
The MTDsnFailureResults.csv file includes details of all failure reasons.
Note
Not all delivery failures result in the generation of a non-delivery report.
The file includes fields such as Timestamp, ServerName, Reason for failure, ReturnPath, and Recipients. The MTDsnFailureResults.csv includes NDR reason codes and recipients together with other information. If you are troubleshooting a particular NDR code or specific recipient issues, you can use the filtering features in Microsoft Office Excel to obtain statistical data about a particular server or organization. To do this in Excel, click Filter on the Data menu. This data may give you information that is relevant to the delivery issue.
For example, you may be troubleshooting a "550 5.2.2 STOREDRV.Deliver: mailbox full" NDR reason code. During your investigation, you may want to know how many users on a server actually have their mailboxes full.
Note
The MTSummaryResults.txt file includes a section that summarizes NDR reason codes by the "Unique FAIL Recipient Status codes" and "FAIL Event Sources" fields.
MTDuplicateDeliveryResults.csv
The MTDuplicateDeliveryResults.csv file is useful to help troubleshoot duplicate mail delivery issues that occur on a particular server or across an organization.
MTNextHopResults.csv
The MTNextHopResults.csv file includes a count of messages together with the average message size for each next hop server through SMTP and the StoreDriver component. The file includes statistics that are based on the following fields:
ClientName,Source
Server
MsgCount,AvgMsgBytes
MsgCountServerSLAMet
PercentServerSLAMet
MsgCountDeliverSLAMet
PercentDeliverSLAMet
This file is one of the three most important files for data analysis purposes. You can use pivot tables that are based on this file to analyze the destination of server traffic. Also, you can group multiple servers into a pivot table that is based on the MTNextHopResults.csv file to obtain an overall traffic analysis. It is best to analyze the data based on the following three fields:
StoreDriver
IntraOrg SMTP
External SMTP delivery
MTExpandResults.csv
The MTExpandResults.csv file includes the distribution group SMTP address, the number of recipients per distribution group expansion operation, and the number of distribution group expansions performed.
In the example results that are displayed in the following table, the MTExpandResults.csv file shows that the DL100@contoso.com distribution group has a recipient count of 49,426. The distribution group was expanded 21 times, and has an average expansion latency of 3,045 seconds (50.75 minutes). This amount of latency could cause server performance issues. You can use this output file to help troubleshoot server performance issues that you may experience.
| Number | SMTP | Recipient Count | Expansion Count | Avg Expansion Latency |
|---|---|---|---|---|
95 |
DL1@contoso.com |
116 |
1 |
14 |
96 |
DL1199@contoso.com |
228 |
2 |
24 |
97 |
DLTest@contoso.com |
3,341 |
1 |
190 |
90 |
DL100@contoso.com |
49,426 |
21 |
3,045 |
91 |
DL9999@contoso.com |
374 |
1 |
59 |
92 |
DL1010@contoso.com |
458 |
1 |
65 |
146 |
DL99110@contoso.com |
3,346 |
1 |
179 |
Note
Average expansion latency is calculated in seconds.
To obtain a graphical view of the data, use Microsoft Excel to plot this data in a chart.
MTLogStatistics.csv
The MTLogStatistics.csv file includes many statistics for each log file that is processed. The file contains the following fields:
LogFilePath
ServerName
iLogFileEventCount
Events/MsgId
LogDateTimeStart
LogDateTimeEnd
LogDuration(Min)
iAvgStoreDriverReceiveRatePerMin
iAvgSmtpReceiveRatePerMin
iAvgStoreDriverDeliverRatePerMin
iAvgSmtpSendRatePerMin
iAvgDsnFailRatePerMin
iAvgFailRatePerMin
iServerLatencyTotalCount
iPercentServerLatencySLAMet
iPercentServerLatencyRecipientsCounted
iDeliveryLatencyTotalCount
iPercentDeliveryLatencySLAMet
You can use these values to verify the percentage of messages that are counted in latency SLA measurements.
Note
Message tracking does not include events that indicate the final disposition of every handled message. Instead, most message tracking events are related to delivery status notification suppression. This occurs when messages are sent to distribution groups that have DSN suppression enabled.
The "percent SLA met" numbers are the most significant because they indicate the percentage of messages that are below the server default of 30 seconds and the delivery default of 90 seconds. These values are default levels that you can modify to obtain the appropriate percentiles.
The server latency and delivery latency SLA goals are defined as variables in the script. The default values are 30 seconds and 90 seconds respectively. Server latency represents the delay from when the message is submitted to transport to when the message is delivered or relayed. For the server latency calculation, each set of recipient deliveries is counted separately. Delivery latency represents the end-to-end latency based on the difference between the organization's submission time and the final delivery event time stamp.
Note
The final disposition of a message could be the transfer of a bifurcated copy of the message to recipients. Therefore, final disposition does not always represent a message delivery or message relay.
Note
The "org submission time" is defined as the message entry time into the message transport at the header firewall (the first transport server in the forest).
For example, the combination of iAvgStoreDriverReceiveRatePerMin and iAvgSmtpReceiveRatePerMin in the MTLogStatistics.csv file indicates the average rate at which the transport component receives messages.
Note
This calculation is valid only if there are no message submissions through the Pickup or Replay directories.
The combination of iAvgStoreDriverDeliverRatePerMin and iAvgSmtpSendRatePerMin specifies the average delivery rate for the transport component. This rate assumes that there are no deliveries to the Drop directory.
The comparison of these two combinations may give you an indication of whether the transport component is effectively processing messages or whether the transport or one of its dependent components is a performance bottleneck. To determine this status, you may have to examine other factors that can affect the results. For example, you may have to adjust the calculation to take the iAvgDsnFailRatePerMin value into consideration.
MTDeliveryLatencyExceptions.csv
The MTDeliveryLatencyExceptions.csv file includes the MinDeliveryLatency and MaxDeliveryLatency fields. These fields contain latency measurements, in seconds. The fields are used to measure deliveries that have occurred for a particular message. These measurements are valid if only one message delivery is made. You can use this information to help determine whether a single next hop in the message delivery process was the cause of latency for a subset of recipients.
MTMbxFullRecipResults.csv
The MTMbxFullRecipResults.csv file contains the results of "mailbox full" events. This file includes the SMTP addresses and NDR counts for full mailboxes.
The following table shows some example output from this file. In this output, the full mailbox for User2 has caused 4,283 NDRs.
| Mailbox | DsnFailureCount |
|---|---|
278 |
|
4283 |
|
58 |
|
19 |
|
24 |
|
19 |
You can use this information to notify users to delete messages from their mailboxes. This reduces server overhead.
MTReceiveResults.csv
The MTReceiveResults.csv file includes the number of messages together with the average message size for each host that submits messages by using SMTP or by using the StoreDriver component. The .csv file includes the following fields:
ServerName
Client IP
MsgCount
This file helps display the StoreDriver receive results for the Hub role. The following table contains example output from the MTReceiveResults.csv file. The output indicates that IP address 192.168.0.190 has submitted a very high number of messages (349,230) to the server that is named GCS1E2K7.
| ServerName | Source | Client | MsgCount | AvgBytes |
|---|---|---|---|---|
GCS1E2K7 |
SMTP(GCS1E2K7\ Default Receive) |
192.168.0.190 |
349230 |
294987 |
GCS1E2K7 |
SMTP(GCS1E2K7\ Default Receive) |
10.10.0.110 |
1429 |
82019 |
GCS1E2K7 |
SMTP(GCS1E2K7\ Default Receive) |
10/10/0/120 |
389 |
69041 |
GCS1E2K7 |
STOREDRIVER |
GCS4E2K7.contoso.com |
209 |
926738 |
GCS1E2K7 |
STOREDRIVER |
GCS3E2K7.contoso.com |
147 |
5737 |
GCS1E2K7 |
STOREDRIVER |
GCS2E2K7.contoso.com |
408 |
17774 |
GCS1E2K7 |
PICKUP |
1 |
774 |
This kind of message count requires additional investigation. It could indicate a spam issue. For example, a server may have a receive connector that is configured incorrectly so that the volume of spam increases.
MTTopRecipientResults.csv
The MTTopRecipientResults.csv file includes the SMTP addresses, mailbox server name, and messages that are received for the top recipients. Top recipients are those who receive more than the average number of messages. The following table contains example output from the MTTopRecipientResults.csv file. In this output, User1245@contoso.com stands out.
| Server name | SMTP address | Message count |
|---|---|---|
GCS1E2K7 |
User1099@contoso.com |
1950 |
GCS1E2K7 |
User1245@contoso.com |
211738 |
GCS1E2K7 |
User2398@contoso.com |
2124 |
GCS1E2K7 |
User3276@contoso.com |
4784 |
GCS1E2K7 |
User7612@contoso.com |
1861 |
You can use the charting feature in a spreadsheet program such as Excel to obtain a graphical view of the top message recipients.
MTTopSendersbyDeliverResults.csv
The MTTopSendersbyDeliverResults.csv file includes the SMTP addresses together with the number of sent messages for the top message senders. Top senders are those who send more than the average number of messages. This includes messages from senders who are outside the organization. The following table contains example output from the MTTopSendersbyDeliverResults.csv file. In this output, User1176@contoso.com stands out.
| Sender | Message count |
|---|---|
6074 |
|
112240 |
|
6571 |
|
3245 |
|
5732 |
MTTopSendersbySubmitResults.csv
The MTTopSendersbySubmitResults.csv file includes the SMTP addresses, mailbox server name, and messages that are sent for top senders. Top senders are users who send more messages than average. This file only includes messages that are submitted from mailboxes by using the StoreDriver (not SMTP). The following table contains example output from the MTTopSendersbySubmitResults.csv file. In this output, User2389@contoso.com stands out.
| Mailbox server | Sender | Message count |
|---|---|---|
GCS2E2K7 |
867 |
|
GCS2E2K7 |
654 |
|
GCS2E2K7 |
727 |
|
GCS2E2K7 |
3532 |
|
GCS2E2K7 |
9984 |
MTEventTimeDistribution.csv
The MTEventTimeDistribution.csv file displays Event distributions based on an hourly count. This file helps provide a means to graph events over time. This may help determine which source is submitting messages, and the message destination. The following table contains example output from this file.
| Server | Event | Source | Month | Day | Hour | Count |
|---|---|---|---|---|---|---|
GCS1E2K7 |
RECEIVE |
SMTP(SERVER01\Default SERVER01) |
8 |
2 |
0 |
5198 |
GCS1E2K7 |
DELIVER |
STOREDRIVER |
8 |
2 |
0 |
3868 |
GCS1E2K7 |
RECEIVE |
STOREDRIVER |
8 |
2 |
0 |
341 |
GCS1E2K7 |
DSN |
DSN(Delivery) |
8 |
2 |
0 |
47 |
GCS1E2K7 |
SEND |
SMTP(Intra-Organization SMTP Send Connector) |
8 |
2 |
0 |
2169 |
GCS1E2K7 |
DSN |
DSN(Failure) |
8 |
2 |
0 |
93 |
GCS1E2K7 |
FAIL |
STOREDRIVER |
8 |
2 |
0 |
93 |
GCS1E2K7 |
BADMAIL |
DSN |
8 |
2 |
0 |
87 |
GCS1E2K7 |
FAIL |
ROUTING |
8 |
2 |
0 |
87 |
GCS1E2K7 |
TRANSFER |
ROUTING(Resolver) |
8 |
2 |
0 |
55 |
GCS1E2K7 |
TRANSFER |
ROUTING(Content Conversion) |
8 |
2 |
0 |
66 |
GCS1E2K7 |
REDIRECT |
ROUTING |
8 |
2 |
0 |
1 |
GCS1E2K7 |
EXPAND |
ROUTING |
8 |
2 |
0 |
6 |
GCS1E2K7 |
FAIL |
AGENT(FSE Routing Agent) |
8 |
2 |
0 |
2 |
RECEIVE |
AGENT() |
8 |
2 |
0 |
2 |
|
GCS1E2K7 |
DEFER |
AGENT(Transport Rule Agent) |
8 |
2 |
0 |
2 |
GCS1E2K7 |
DELIVER |
STOREDRIVER |
8 |
2 |
1 |
4748 |
GCS1E2K7 |
RECEIVE |
SMTP(SERVER01\Default SERVER01) |
8 |
2 |
1 |
6492 |
GCS1E2K7 |
RECEIVE |
STOREDRIVER |
8 |
2 |
1 |
389 |
GCS1E2K7 |
DSN |
DSN(Delivery) |
8 |
2 |
1 |
35 |
GCS1E2K7 |
SEND |
SMTP(Intra-Organization SMTP Send Connector) |
8 |
2 |
1 |
2809 |
GCS1E2K7 |
TRANSFER |
ROUTING(Resolver) |
8 |
2 |
1 |
152 |
GCS1E2K7 |
TRANSFER |
ROUTING(Content Conversion) |
8 |
2 |
1 |
65 |
MTMessageSizeDistribution.csv
The MTMessageSizeDistribution.csv file shows the distribution of messages based on message size. The distribution is broken down according to the number of messages, a percentage of the total messages, and the percentage of messages that are smaller than the current message size. This may help determine the spectrum of message size distribution in an organization. The following table contains example output from this file.
| Size range | Message count | Percentage of total | Percent under current size |
|---|---|---|---|
0-1 KB |
63 |
0.02% |
0.02% |
1-2 KB |
11846 |
4.66% |
4.68% |
2-4 KB |
45172 |
17.76% |
22.44% |
4-8 KB |
47072 |
18.50% |
40.94% |
8-16 KB |
39641 |
15.58% |
56.53% |
16-32 KB |
28810 |
11.33% |
67.85% |
32-64 KB |
20251 |
7.96% |
75.81% |
64-128 KB |
20252 |
7.96% |
83.77% |
128-256 KB |
13228 |
5.20% |
88.97% |
256-512 KB |
9022 |
3.55% |
92.52% |
512-1024 KB |
7460 |
2.93% |
95.45% |
1024-2048 KB |
5243 |
2.06% |
97.51% |
2048-4096 KB |
3925 |
1.54% |
99.05% |
4096-8192 KB |
2399 |
0.94% |
100% |
8192-16384 KB |
5 |
0% |
100% |
16384-32768 KB |
0 |
0% |
100% |
32768-65536 KB |
0 |
0% |
100% |
MTRecipientNotFoundResults.csv
The MTRecipientNotFoundResults.csv file contains statistics about recipients who could not be located in the global address list (GAL) or Active Directory directory service. The following table contains example output from this file. In this output, the high count for User1001 may indicate that this user is no longer associated with the organization.
| Recipient not found | Count |
|---|---|
User1001@contoso.com |
2149 |
User2167@contoso.com |
19 |
User3267@contoso.com |
6 |
User1282@contoso.com |
6 |
User1491@contoso.com |
8 |
MTDomainExpiredResults.csv
The MTDomainExpiredResults.csv contains entries that may be helpful to troubleshoot DSN failures. For example, these entries may help you troubleshoot if a DSN failure occurs because of a misspelling, or if a destination server is unavailable for more than two days (the default expiration time-out). The following table contains example output from this file.
| Domain | Recipient failures | Message failures | Original expiry | Last expiry | MTBF (hours) |
|---|---|---|---|---|---|
Hotmail.com |
6 |
6 |
1/9/2008 19:06 |
1/11/2008 20:20 |
8 |
contoso.com |
7 |
7 |
1/9/2008 3:47 |
1/12/2008 8:13 |
11 |
fourthcoffee.com |
4 |
4 |
1/9/2008 19:15 |
1/10/2008 15:51 |
5 |
msn.com |
23 |
23 |
1/9/2008 20:40 |
1/11/2008 17:10 |
2 |
MTMessageSizeExceptions.csv
The MTMessageSizeExceptions.csv output file is generated only if there is a tracking log event for a message whose size exceeds the value for iMaxMessageSizeThresholdKB. The default threshold is 64MB. If there is no such tracking log event, the file is not generated.
MTRunTimeLog.log
The MTRunTimeLog.log file is the log file for the Process Tracking Log tool. This file contains the run-time log for the Processtrackinglog.vbs script.
MTMailSubmissionDistribution.csv
The MTMailSubmissionDistribution.csv file contains the distribution of submissions by MessageClass and ClientType. This includes the ability to parse the SUBMIT event SourceContext field to determine the distribution of submissions by ClientType and by MessageClass. This file relies on the Mailbox role tracking logs.
You can use this file to help determine the distribution of client types when you analyze the Mailbox role tracking log.
MTSummaryResults.txt
The MTSummaryResults.txt file includes summary statistics for all the log files that are processed. This file contains many items. Some more significant items are as follows:
Total Events processed
Total Message Id's Processed
Total Messages received
Total Messages sent
Total Messages delivered
Total Messages delivered (duplicate)
Total Resolve
Total Transfer
Total Expand
Total Fail
Total Fail with NDR
Total Fail (valid Return Path)
Total Fail (Recipient)
Avg Fail Events/Min
Max Fail Events/Min
Max DSN(Fail) Events/Min
Total DSN Generated
Total DSN Badmail
Total DSN
Total DSN Delivered from CORP
Total Null Reverse Path Delivered
Total Null Reverse Path Delivered from Internal
Total Null Reverse Path Delivered from External
Total Defer
Total Poison
Total SMTP Receive
Total StoreDriver Receive
Total SMTP Send
Total StoreDriver Deliver
Total Expand
End-To-End Delivery Latency Distribution for all Messages Delivered
Server Latency Distribution for all Messages Processed
Server Latency Distribution for all Individual Deliveries
Unique Encapsulated Addresses
Unique DSN Source Context
Unique Defer Source Context
Unique StoreDriver Sender Domains
Transfer Source Context
FAIL Event Sources
Unique FAIL Recipient Status codes
The following example is an excerpt from an MTSummaryResults.txt file. This example illustrates some of the information that is collected.
Total Events processed: 671316 (Avg Events/Log: 26852.64) Total Message Id's Processed: 291378 (Avg Events/MsgId: 2.30393509461936, Max: 3.03358797138353, Min: 1.41262468992453) Total Messages received: 254389 (Avg Msg Size: 184 KB) Total Messages sent: 95301 Total Messages delivered: 256995 Total Messages delivered (duplicate): 0 (0 recipients) Total Resolve: 45 Total Transfer: 32610 (46.9% exceeded 30 sec before transfer, average 599 sec latency before transfer) Total Expand: 5179 Total Fail: 10229 (0% *.contoso.com senders, 99.6% external senders) Total Fail with NDR: 5759 Total Fail (valid Return Path): 5802 (0% *.contoso.com senders, 100% external senders) Total Fail (Recipient): 11203 Avg Fail Events/Min: 7.1 Max Fail Events/Min: 280.3 Max DSN(Fail) Events/Min: 146.5 Total DSN Generated: 7240 Total DSN Badmail: 4352 Total DSN: 11592 (Percent DSN Badmail: 37.5%) Total DSN Delivered from CORP: 0 Total DSN Delivered from CORP/EXCHANGE/NWTRADERS: 0 Total Null Reverse Path Delivered: 8604 Total Null Reverse Path Delivered from Internal: 3 (0%) Total Null Reverse Path Delivered from External: 8601 (100%) Total Defer: 42 Total Poison: 0 Total Split Errors: 22120 |