BES Logs ... What's in them? Part 7 of 20 (MAGT log)

Welcome to Part 7 of the 20 part series looking at the BES logs. (Part 6)

Welcome to the most overwhelming log of all ... the BlackBerry Messaging Agent (MAGT) log.

Much like the SYNC log splits off data into other logs (such as CBCK), the DISP log splits off MAGT data. In fact, you'll notice no such service in the Windows Control Panel for Messaging Agents ... but if you stop the BlackBerry Dispatcher Service you'll see any BlackBerryAgent.exe processed stop. Unlike the SYNC service which doesn't spawn additional processes only logs, the DISP service creates a separate BlackBerryAgent.exe process for each Messaging Agent loaded.

By default you'll only see one BlackBerry Messaging Agent, but as you add additional users from different Exchange (Remember, most if not all of my references will be Microsoft Exchange focused) servers the server will spawn up to 5 separate messaging agents (by default). Also, if you go over 500 users on a BES from a single Exchange server it'll spawn another Messaging Agent.

What's this all mean? It means you may have multiple logs to go through, and life just got a little bit harder. A users Messaging Agent log data will be stored in the Agent log that is accessing their mailbox. You can find out which Agent a user is currently on by launching the BlackBerry Manager and adding the field Mailbox Agent ID to the list of displayed values. The number will correspond to the MAGT_## log file.

Trying to parse through the MAGT log can be daunting; especially given its size ... but here again is where Windows Grep is your friend. It'll find everything for a specific email address (user) in 5 seconds instead of trying to parse through it manually

So ... onto the log! One useful thing I find in the log is the line (which you'll see repeated through out the file):

[40442] (06/01 08:16:44):{0x190C} User settings: email=testuser1@port3101.org, routing=S9999999, service=TESTBES1, device=
, calendar=1, MDS=1,userOTAFM=47, incradle=0, SMIME=0, dir=testuser1, server=EXCHANGE01

In addition to providing information about the server / routing information, you also see that a user has Wireless Calendar Enabled, MDS Connection Service Enabled, is not cradled, is not enabled for S/MIME, and has a userOTAFM of 47. UserOTAFM is a users wireless message reconciliation state.

The wireless message reconciliation state can be determined using the table below:
<table style="border: 2px solid black; margin-left: 12px; border-collapse: collapse;"> <tbody> <tr> <td style="border: 2px solid black; background: rgb(220, 220, 220) none repeat scroll 0% 0%; font-weight: bold; -moz-background-clip: border; -moz-background-origin: padding; -moz-background-inline-policy: continuous; vertical-align: top; font-style: normal; text-align: center;"> userOTAFM Entry</td> <td style="border: 2px solid black; background: rgb(220, 220, 220) none repeat scroll 0% 0%; font-weight: bold; -moz-background-clip: border; -moz-background-origin: padding; -moz-background-inline-policy: continuous; vertical-align: top; font-style: normal; text-align: center;"> State Description</td> </tr> <tr> <td style="border: 2px solid black;"> 47

</td> <td style="border: 2px solid black;"> A BlackBerry device user’s account has enabled wireless message reconciliation on the BlackBerry device with the following states turned on: status, delete, move, and purge.

</td> </tr> <tr> <td style="border: 2px solid black;"> 63

</td> <td style="border: 2px solid black;"> Wireless message reconciliation is enabled and the following states are turned on: status, delete, move, purge, and enabled.

</td> </tr> <tr> <td style="border: 2px solid black;"> 32

</td> <td style="border: 2px solid black;"> Wireless message reconciliation has been disabled on the device, or through an IT Policy.

</td> </tr> </tbody> </table>

The decimal value of the userOTAFM entry is obtained by adding the hexadecimal values of each applicable state. For example:

OTAFM_STATUS (0x01) + OTAFM_DELETES (0x02) + OTAFM_WIRELESS_FILING (0x04) + OTAFM_PURGE (0x08) + OTAFM_DEVICE_INIT (0x20) = 0x2F (hexadecimal value)
0x2F = 47 (decimal value)

The following table lists some feature states, corresponding hexadecimal values, and additional details:
<table style="border: 2px solid black; margin-left: 12px; border-collapse: collapse;"><tbody><tr> <td class="Header" style="border: 2px solid black; background: rgb(220, 220, 220) none repeat scroll 0% 0%; font-weight: bold; -moz-background-clip: border; -moz-background-origin: padding; -moz-background-inline-policy: continuous; vertical-align: top; font-style: normal; text-align: center;"> Feature Description</td> <td class="Header" style="border: 2px solid black; background: rgb(220, 220, 220) none repeat scroll 0% 0%; font-weight: bold; -moz-background-clip: border; -moz-background-origin: padding; -moz-background-inline-policy: continuous; vertical-align: top; font-style: normal; text-align: center;"> Hexadecimal Details</td> </tr> <tr> <td style="border: 2px solid black; vertical-align: top;"> OTAFM_STATUS

</td> <td style="border: 2px solid black; vertical-align: top;">

• 0x01
• Feature bit that implies read, reply to, and forward.

</td> </tr> <tr> <td style="border: 2px solid black; vertical-align: top;"> OTAFM_DELETES



</td> <td style="border: 2px solid black; vertical-align: top;">

• 0x02
• Feature bit

</td> </tr> <tr> <td style="border: 2px solid black; vertical-align: top;"> OTAFM_WIRELESS_FILING



</td> <td style="border: 2px solid black; vertical-align: top;">

• 0x04
• Feature bit

</td> </tr> <tr> <td style="border: 2px solid black; vertical-align: top;"> OTAFM_PURGE



</td> <td style="border: 2px solid black; vertical-align: top;">

• 0x08
• Feature bit

</td> </tr> <tr> <td style="border: 2px solid black; vertical-align: top;"> OTAFM_USER_ENABLED

</td> <td style="border: 2px solid black; vertical-align: top;">

• 0x10
• This is only used in conjunction with the OTAFM_USER_CONFIG flag. Wireless email reconciliation was enabled on the device.

</td> </tr> <tr> <td style="border: 2px solid black; vertical-align: top;"> OTAFM_DEVICE_INIT



</td> <td style="border: 2px solid black; vertical-align: top;">

• 0x20
• This is only used in conjunction with the OTAFM_USER_CONFIG flag.

</td> </tr> <tr> <td style="border: 2px solid black; vertical-align: top;"> OTAFM_USER_CONFIG

</td> <td style="border: 2px solid black; vertical-align: top;"> The value of this state is cumulative. BlackBerry Desktop Software uses this feature and the OTAFM_DEVICE_INIT flag to determine if wireless message reconciliation is enabled on the device, and to display the appropriate interface. This feature enables the interface and functionality appropriate to the OTAFM_SERVER_SUPPORT bitmask. This is cleared by the BlackBerry Desktop Software and the BlackBerry Enterprise Server administrator, if BlackBerry devices are switched.
BlackBerry Enterprise Server uses this and the OTAFM_DEVICE_INIT flag to determine if wireless message reconciliation functions should be processed (for example, polling).

</td> </tr> <tr> <td style="border: 2px solid black; vertical-align: top;"> OTAFM_SERVER_SUPPORT

</td> <td style="border: 2px solid black; vertical-align: top;">

• 0x0f or 0
• The value of this state depends on whether or not the registry entry OTAFMSupport has a value of 0 or 1.

</td></tr></tbody></table>

While this data may not be particularly useful everyday for doing analysis, it gives you some insight into what information is recorded in the logs, and that while some of it may be excessive, there is some value you can grab from the logs.

Here's some more:

[40559] (06/01 10:26:59.921):{0xB74} {testuser1@port3101.org} Batching Delete for RefId=-1234785636, status=1, TransactionID=-902665788
[40559] (06/01 10:26:59.921):{0xB74} {testuser1@port3101.org} Batching Delete for RefId=-813740944, status=1, TransactionID=-902665788
[30289] (06/01 10:26:59.921):{0xB74} {testuser1@port3101.org} 2 OTAFM commands sent in batch for TransactionId=-902665788, Tag=3281758, size=52
[40279] (06/01 10:26:59.921):{0xB74} {testuser1@port3101.org} SubmitToRelaySendQ, Tag=3281758
[30201] (06/01 10:27:04.671):{0xD00} {testuser1@port3101.org} OTAFM batch has been DELIVERED to device, Tag=3281758
[40536] (06/01 10:27:04.671):{0xD00} {testuser1@port3101.org} Updating messages in OTAFM batch, TransactionID=-902665788

[40373] (06/01 10:27:49.906):{0xA48} {testuser1@port3101.org} Queuing notification of modified appointment (external). EntryId=13897840 (delay processing 2 seconds)
[40465] (06/01 10:27:49.906):{0xFE4} {testuser1@port3101.org} Get source key for this MAPI object, EntryId=13897840
[40267] (06/01 10:27:51.312):{0xD00} {testuser1@port3101.org} Starting calendar rescan
[30019] (06/01 10:27:51.328):{0xD00} {testuser1@port3101.org} MAPIMailbox:: DoICS ICS Synch Successful
[40701] (06/01 10:27:51.328):{0xD00} {testuser1@port3101.org} Calendar rescan completed

The above lines show a few things you'll see in the MAGT log.

In the first group of lines, the first two lines are the BES processing delete requests from Exchange. The third line is the package of data being sent. The fourth line is the data leaving the BES. The fifth is the confirmation that the device received the delete command for the two messages, and the sixth is the BES updating itself.

In the second group the agent has picked up a change in a calendar appointment from the handheld and needs to update Exchange. In the second line it is looking for the item in the mailbox. In the third line simultaneously it is starting a rescan of the calendar for any changes. The fourth line BES has completed the calendar sync, and the fifth line it is reporting the calendar rescan as done ... not too bad, it did the rescan of the calendar in 16 thousandths of a second.

Here's another one you might see (and this is a real useless one):

[30000] (06/01 14:02:13.190):{0x7E0} [Alarm::ActivateAlarm] Queuing alarm: <n a=""> | BlackBerry Messaging Agent TESTBES1 Agent 1 (Application Event Log on TESTBES1) | 06/01/2009 14:02:11 (6FFF9F4E) -> {testuser1@port3101.org} GetContactPicture - No picture synced, filename is not ContactPicture.jpg</n>

Check out: KB15201 - GetContactPicture - No picture synced, filename is not ContactPicture.jpg for that one.

Last but certainly not least:

[10277] (06/01 14:21:05.722):{0x28F0} BlackBerry Messaging Agent BLACKBERRY Agent 1 failed to start. Error code 5305

You'll see this error show up in the ALRT log too, but seeing it in the MAGT log and looking at the surrounding log entries may help point to the problem. KB01018 - Service failed to start, generating error 5305 will lead you to a solution on this one ... always note the error code if provided. It may be a BES one such as 5305 or a MAPI error 0x80040111 (Logon failed) ... but just make note of it when you're looking to find an answer. Even if you can't find it someone out there has probably seen it!

If you've got any questions about other specific entries in the MAGT log feel free to post a question / comment in response to this post, or in the forum.

Tomorrow in Part 8 we'll dive into the log that everyone seems to always ask about, but for some reason has no idea how to process ... the BlackBerry Mobile Data Service (MDAT) log.