BlackBerry Enterprise Server Log, BB device and Outlook Communication, Part III

Part IIIa – Email status change as a result of change from Outlook (read, unread etc.)

Continued from my previous posts, this is the third part of my 5 part series about BlackBerry log. In this post, we will examine the status change from within two locations, Outlook and BB device. Status change is nothing uncommon, any user action that modify the ’state’ of a mailbox item will trigger an update to the mailbox and BB device. For an example when an email is marked as ‘read’ or ‘unread’, changing the time or date of a meeting item. So how does BES know? What part of BES keeps track of this changes? BES performs what we call ’scan’ to keep itself and the device up-to-date. It constantly polls the state of the mailbox by performing rescan and there are many types of scanning such as address book scan, tasks scan, calendar scan, memos scan, message moved scan, and the one we will be examining is message status rescan. Message Status rescan is happening averagely at 18-30 minutes interval. From my observation, it’s random but most of them are in between that range. If there is changes in the status, the scan will then happen between 7-9 minutes. To give you an idea, here are the time BES did the status rescan:

• 13:22
• 13:41
• 14:11
• 14:32
• 14:50
• 15:16
• 15:33
• 15:46
• 15:55
• 16:11
• 16:19
• 16:46
• 17:08

In summary, when there is an activity (user actions), the rescan will occur seemingly in shorter intervals. However, it will take about 18-30 minutes between rescans when there is no activity in Outlook. It looks like BES has ability to ’sense’ that and forces itself to perform rescan in shorter time period. Every status rescan will come in two phases:

1. Start to scan

2. Batch, prepare and update the device (exactly one minute later)

The following log shows when I change the email from ‘unread’ to ‘read’.

=== SERVERNAME_MAGT_01_20090123_0001.txt ===
[40000] (01/23 16:16:49.587):{0×1B04} [BIPP] Received datagram, Tag=280166
[40700] (01/23 16:16:49.587):{0×1F20} {cat@cheelam.com} Receiving packet from device, size=49, TransactionId=573264609, Tag=280166, content type=CMIME, cmd=0×3
[40698] (01/23 16:16:49.587):{0×1F20} {cat@cheelam.com} Receiving OTAFM request from device, Tag=280166, TransactionId=573264609
[40572] (01/23 16:16:49.587):{0×1F20} {cat@cheelam.com} Receiving MESSAGE_STATUS_UPDATE request from device, Tag=280166, TransactionId=573264609, RefId=-1934095857, MsgStatus=0
[40262] (01/23 16:16:49.587):{0×1F20} {cat@cheelam.com} StateDb – Found RefId=-1934095857
[40699] (01/23 16:16:49.650):{0×1F20} {cat@cheelam.com} OTAFM request from device processed
[40279] (01/23 16:16:49.650):{0×1F20} {cat@cheelam.com} SubmitToRelaySendQ, Tag=280166
[40000] (01/23 16:16:49.650):{0×1B08} [BIPP] Send status DATA_ACCEPTED, Tag=280166

Click to enlarge

Part IIIb – Email status change as a result of change from BB device (read, unread etc.)

Unlike status change from Outlook, it does not depend on scanning from BES thus there is only one phase to update the mailbox instead of two. The reason is BES is receiving the command from the device and pass the action (read/unread) to the corresponding mailbox. It is then the Exchange responsibility to update the Outlook. Similar to above but this time the change is initated from the device. I “Mark Unopened”. Immediately the action is captured in BES and status is updated within the mailbox which subsequently reflected in my Outlook as ‘unread’. This happens in about less than 10 sec. MESSAGE_STATUS_UPDATE indicates that the device is asking BES to perform such action. This is very different from Outlook initiated actions where status scan required.

=== SERVERNAME_MAGT_01_20090123_0001.txt ===
[40000] (01/23 16:16:49.587):{0×1B04} [BIPP] Received datagram, Tag=280166
[40700] (01/23 16:16:49.587):{0×1F20} {cat@cheelam.com} Receiving packet from device, size=49, TransactionId=573264609, Tag=280166, content type=CMIME, cmd=0×3
[40698] (01/23 16:16:49.587):{0×1F20} {cat@cheelam.com} Receiving OTAFM request from device, Tag=280166, TransactionId=573264609
[40572] (01/23 16:16:49.587):{0×1F20} {cat@cheelam.com} Receiving MESSAGE_STATUS_UPDATE request from device, Tag=280166, TransactionId=573264609, RefId=-1934095857, MsgStatus=0
[40262] (01/23 16:16:49.587):{0×1F20} {cat@cheelam.com} StateDb – Found RefId=-1934095857
[40699] (01/23 16:16:49.650):{0×1F20} {cat@cheelam.com} OTAFM request from device processed
[40279] (01/23 16:16:49.650):{0×1F20} {cat@cheelam.com} SubmitToRelaySendQ, Tag=280166
[40000] (01/23 16:16:49.650):{0×1B08} [BIPP] Send status DATA_ACCEPTED, Tag=280166

Click to enlarge

I then open the email effectively change the status from ‘unread’ to ‘read’. This action is also immediately captured in BES.

=== SERVERNAME_MAGT_01_20090123_0001.txt ===
[40000] (01/23 16:18:10.433):{0×1B04} [BIPP] Received datagram, Tag=280167
[40700] (01/23 16:18:10.433):{0×1B48} {cat@cheelam.com} Receiving packet from device, size=49, TransactionId=573264610, Tag=280167, content type=CMIME, cmd=0×3
[40698] (01/23 16:18:10.433):{0×1B48} {cat@cheelam.com} Receiving OTAFM request from device, Tag=280167, TransactionId=573264610
[40572] (01/23 16:18:10.433):{0×1B48} {cat@cheelam.com} Receiving MESSAGE_STATUS_UPDATE request from device, Tag=280167, TransactionId=573264610, RefId=-1934095857, MsgStatus=1
[40262] (01/23 16:18:10.433):{0×1B48} {cat@cheelam.com} StateDb – Found RefId=-1934095857
[40699] (01/23 16:18:10.480):{0×1B48} {cat@cheelam.com} OTAFM request from device processed
[40279] (01/23 16:18:10.480):{0×1B48} {cat@cheelam.com} SubmitToRelaySendQ, Tag=280167
[40000] (01/23 16:18:10.480):{0×1B08} [BIPP] Send status DATA_ACCEPTED, Tag=280167

Click to enlarge