BES Logs ... What's in them? Part 19 of 20 (MessageFlow.exe BRK Tool)

Welcome to Part 19 of the 20 part series looking at the BES logs (Part 17) ... the BRK Tool MessageFlow.exe. In my opinion this is the mother of all BRK tools.

Officially touted as BlackBerry Message Flow Reporting Tool, MessageFlow.exe does exactly what its name insinuates ... tracks the flow of messages from the messaging and collaboration server through the BlackBerry Enterprise Server to the BlackBerry device. Requiring the BlackBerry Messaging Agent (MAGT), BlackBerry Dispatcher (DISP), and BlackBerry Router (ROUT) log files this tool means business.

MessageFlow tracks every email message handled by the BES; it is truly an awesome tool ... In addition to two basic functions:

• Calculating the total time (in minutes) between the messaging server receiving the message and the BlackBerry Enterprise Server completing the processing; is a negative value when the BlackBerry device sends a message
• Time it takes the BlackBerry Enterprise Server to process a message and deliver it to the BlackBerry device

... here are some other data points MessageFlow provides:

• Time when the messaging server posts the message to the mailstore
• Time when the messaging server indicates that the message is delivered
• Time when the BlackBerry Enterprise Server first recognizes the message
• Time when the BlackBerry Messaging Agent sends the message to the BlackBerry Dispatcher
• Time when the BlackBerry Dispatcher receives the message
• Time when the BlackBerry Router receives the message
• Time when the BlackBerry Router sends the message
• Time when the BlackBerry Dispatcher receives the delivery notification message
• Status of whether the BlackBerry Messaging Agent receives the delivery notification message
• Time of the message delivery
• Number of times the BlackBerry Enterprise Server attempts to send the message
• How the BlackBerry Enterprise Server discovers the message (through UDP Notify or Mailbox Rescan) ... I'll go over this more as it is my favorite.
  

Syntax

Are you seeing a pattern yet? Platform identification and users ... yup, in my example below I'm using an Exchange log (even though this is only supported with Exchange) wanting to get a report for all users. The output for this log tends to be the longest ... 18 seconds for 64MB of log, 114 users, and 8694 messages.



Result

Below is the output for just testuser1@port3101.org. Had I ran the command MessageFlow.exe -p E -u testuser1@port3101.org this would have been all of the output in the file; so I simply filtered out the user data for this example. Since this tool gathers data from 3 different logs, the time stamps displayed will obviously come from these three logs ... each entry having bits and pieces. The data I've included below is filtered out a bit; I've left some of the key columns and made sure the one I want to point out is indeed still there ... the Discovery column.



Raw Data from MAGT Log

Here is how it all correlates with a snip from the MAGT log ... specifically row 6 of the above data at 09:36 (DISP Del column) and the EntryId column:
____________________

[30097] (06/25 09:36:05.437):{0x1478} {testuser1@port3101.org} Message has been delivered to device, Tag=3280849, EntryId=13858313
____________________

Note the Total Time and the Discovery colums for this specific row ... 26.08 and Rescan ... that's right, this message was delivered to the handheld due to mailbox rescan.

Message delivery to a handheld can be done either by UDP Notify or Mailbox Rescan. UDP Notify is when the BES retrieves the message from the mailbox as a result of a notification from the Exchange server that there is something for it to fetch. The key with this is that it is UDP ... the delivery of the "Hey come get this message" isn't guaranteed. For this reason BES rescans the mailbox (every 15-30 minutes) for changes and processes them ... BlackBerry smartphone users will see this as message clumping or message batching.

The biggest false positive to this problem where the BES isn't processing UDP notifications is when a user is Out of Coverage and then comes back in to coverage. She'll see several messages all with the same timestamp on her messages screen and will wonder why her mail isn't flowing in as they're delivered to her mailbox. Using the OutOfCoverage tool together with the MessageFlow tool would help you identify exactly what happened in that scenario.

So what would actually cause the messages to not be delivered by UDP notify? Usually it has to do with a performance bottleneck on the Exchange server ... and in most cases it has to do with a disk i/o bottleneck (Exchange 2003 the most)

I'll leave performance bottlenecks to its own post ... coming shortly.

If you've got any questions about the MessageFlow BRK Tool feel free to post a question / comment in response to this post, or in the forum.

Tomorrow in the final part to this series we'll get through a summary of the parts we've done.

If you've got any feedback or ideas for what you'd like to see more on please drop me a line.

Thanks!