BES Logs ... What's in them? Part 11 of 20 (POLC log) - Software Configuration
Posted 07-06-2009 at 05:00 AM by hdawg
Tags application managment, bb policy service, bes log, blackberry logs, blackberry polc log, blackberry policy, blackberry policy log, blackberry server logs, polc log, policy service, software config, software deploy
Continuing on the discussion of the POLC log started yesterday ... Welcome to part 11 of this 20 part series looking at the BES logs.
As promised, here is the other major part of the POLC log ... Software Deployment / Application Push. Keep in mind, that as a part of a Software Configuration is the Application Control Policy (APC). The APC (Yes, APC and not ACP) sets permissions on a given application that is deployed and either provides or revokes that application the ability to perform certain tasks on the BlackBerry handheld ... so here we go with a snip from the POLC log pushing RSA SecurID software token software to a BlackBerry handheld:
Push is initiated from the BES (Most commonly done either via the Deploy Applications option within the BlackBerry Manager, or the default 4 hour polling interval set on the BES)
[40000] (06/01 12:14:53.484):{0x166C} {testuser1@port3101.org, PIN=FFFFFFFF, UserId=70}SCS::PollDBQueueNewRequests - Queuing POLL_FOR_MISSING_APPS request
NOTE: Between the {} I've removed testuser1@port3101.org, PIN=FFFFFFFF, UserId=70 for readability sake in the following log lines.
The BES has located the source file and has broken up the source SecurID.cod file into 3 separate 56KB parts for deployment.
[40000] (06/01 12:15:01.593):{0x1318} {}RequestHandler::PollForMissingApps: Queuing the package RSA SecurID, consisting of 1 modules in 3 parts.
[40000] (06/01 12:15:01.593):{0x1318} {}RequestHandler::PollForMissingApps: Found 3 siblings for module C:\BES\PackageCache\FILESHARE_testbes1\rsa\RSA3.02\SecurID.cod.
[40000] (06/01 12:15:01.593):{0x1318} {}RequestHandler::QueueModule: Queuing part 1 of 3, module C:\BES\PackageCache\FILESHARE_testbes1\rsa\RSA3.02\SecurID.cod of the package RSA SecurID.
[40000] (06/01 12:15:01.609):{0x1318} {}RequestHandler::QueueModule: Queuing part 2 of 3, module C:\BES\PackageCache\FILESHARE_testbes1\rsa\RSA3.02\SecurID.cod of the package RSA SecurID.
[40000] (06/01 12:15:01.625):{0x1318} {}RequestHandler::QueueModule: Queuing part 3 of 3, module C:\BES\PackageCache\FILESHARE_testbes1\rsa\RSA3.02\SecurID.cod of the package RSA SecurID.
The Application Control Policy is sent to and processed by the device. Notice, this happens BEFORE the application is pushed; ensuring that a proper policy will be in place before the application is installed.
[40000] (06/01 12:15:01.765):{0x166C} {}SCS::PollDBQueueNewRequests - Queuing SEND_APC_ITPOLICY request
[40000] (06/01 12:15:02.843):{0x1780} {}SCS::CheckDBforITPolicyChanges - Queuing SET_ITPOLICY_REQUEST request, ITPolicyId 4
[40000] (06/01 12:15:04.046):{0x166C} {}SCS::PollDBQueueNewRequests - Queuing SET_ITPOLICY_REQUEST request
[40000] (06/01 12:15:20.812):{0x11B0} {}RequestHandler:: DoWork - Processing SET_ITPOLICY_REQUEST request
[40000] (06/01 12:15:20.812):{0x16E4} {}RequestHandler:: DoWork - Processing SEND_APC_ITPOLICY request
[40000] (06/01 12:15:20.843):{0x11B0} {}RequestHandler::SendToRelay - SubmitToRelaySendQ, Tag=13913
[30000] (06/01 12:15:20.875):{0x11B0} {}RequestHandler::SendQueuedITAdminCommandToDevice Sending data to device, contentType=ITADMIN, size=638, RefId=0, TransactionId=-901092938, Tag=13914
[30000] (06/01 12:15:20.875):{0x16E4} {}RequestHandler::SendQueuedITAdminCommandToDevice Sending data to device, contentType=ITADMIN, size=638, RefId=0, TransactionId=-901092937, Tag=13915
[40000] (06/01 12:15:20.875):{0x11B0} {}RequestHandler::SendToRelay - SubmitToRelaySendQ, Tag=13914
[40000] (06/01 12:15:20.875):{0x16E4} {}RequestHandler::SendToRelay - SubmitToRelaySendQ, Tag=13915
[40000] (06/01 12:15:20.890):{0x11B0} {}RequestHandler:: DoWork - Completed Processing SET_ITPOLICY_REQUEST request
[40000] (06/01 12:15:20.890):{0x16E4} {}RequestHandler:: DoWork - Completed Processing SEND_APC_ITPOLICY request
[40000] (06/01 12:15:22.421):{0x14FC} {}RequestHandler:: DoWork - Processing DEVICE_SEND_STATUS_EVENT request
[30000] (06/01 12:15:22.421):{0x14FC} {}RequestHandler:: DoDeviceSentProcessing - Message has been delivered to device, Tag=13914
[40000] (06/01 12:15:22.421):{0x14FC} {}RequestHandler:: DoITPolicyDeviceSentProcessing - ITPolicy GME Receive Ack for the command SET_IT_POLICY_COMMAND - Processing packet, Tag=13914
[40000] (06/01 12:15:22.437):{0x14FC} {}RequestHandler:: DoWork - Completed Processing DEVICE_SEND_STATUS_EVENT request
[40000] (06/01 12:15:22.578):{0x1318} {}RequestHandler:: DoWork - Processing DEVICE_SEND_STATUS_EVENT request
[30000] (06/01 12:15:22.578):{0x1318} {}RequestHandler:: DoDeviceSentProcessing - Message has been delivered to device, Tag=13915
[40000] (06/01 12:15:22.578):{0x1318} {}RequestHandler:: DoITPolicyDeviceSentProcessing - ITPolicy GME Receive Ack for the command SEND_APC_ITPOLICY - Processing packet, Tag=13915
The First 56KB chunk of SecurID.cod is sent to the handheld.
[40000] (06/01 12:15:22.656):{0x1318} {}SCS::QueueNextSequenceforGroup - Queuing SEND_APC_APP request
[40000] (06/01 12:15:22.656):{0xA4C} {}RequestHandler:: DoWork - Processing SEND_APC_APP request
[40000] (06/01 12:15:22.656):{0x1318} {}RequestHandler:: DoWork - Completed Processing DEVICE_SEND_STATUS_EVENT request
[40000] (06/01 12:15:22.656):{0xA4C} {}RequestHandler::GetApplicationData: Loading the module at offset 45, length 81340, path "C:\BES\PackageCache\FILESHARE_testbes1\rsa\RSA3.02\SecurID.cod".
[40000] (06/01 12:15:22.687):{0xA4C} {}RequestHandler::SendToRelay - SubmitToRelaySendQ, Tag=13916
[40000] (06/01 12:15:22.703):{0xA4C} {}RequestHandler::SendToRelay - SubmitToRelaySendQ, Tag=13917
[40000] (06/01 12:15:22.703):{0xA4C} {}RequestHandler::SendApp: Sending the module C:\BES\PackageCache\FILESHARE_testbes1\rsa\RSA3.02\SecurID.cod for entry id 7277.
[40000] (06/01 12:15:22.718):{0xA4C} {}RequestHandler:: DoWork - Completed Processing SEND_APC_APP request
[40000] (06/01 12:15:27.140):{0x11B0} {}RequestHandler:: DoWork - Processing DEVICE_SEND_STATUS_EVENT request
[30000] (06/01 12:15:27.140):{0x11B0} {}RequestHandler:: DoDeviceSentProcessing - Message has been delivered to device, Tag=13916
[40000] (06/01 12:15:27.140):{0x11B0} {}RequestHandler:: DoITPolicyDeviceSentProcessing - ITPolicy GME Receive Ack for the command SEND_APC_APP - Processing packet, Tag=13916
[40000] (06/01 12:15:27.140):{0x11B0} {}RequestHandler:: DoWork - Completed Processing DEVICE_SEND_STATUS_EVENT request
[40000] (06/01 12:15:29.812):{0x16E4} {}RequestHandler:: DoWork - Processing DEVICE_SEND_STATUS_EVENT request
[30000] (06/01 12:15:29.812):{0x16E4} {}RequestHandler:: DoDeviceSentProcessing - Message has been delivered to device, Tag=13917
[40000] (06/01 12:15:29.812):{0x16E4} {}RequestHandler:: DoITPolicyDeviceSentProcessing - ITPolicy GME Receive Ack for the command SEND_APC_APP - Processing packet, Tag=13917
[40000] (06/01 12:15:29.843):{0x16E4} {}SCS::QueueNextSequenceforGroup - Queuing SEND_APC_APP request
[40000] (06/01 12:15:29.843):{0x14FC} {}RequestHandler:: DoWork - Processing SEND_APC_APP request
[40000] (06/01 12:15:29.843):{0x16E4} {}RequestHandler:: DoWork - Completed Processing DEVICE_SEND_STATUS_EVENT request
The Second 56KB chunk is sent to the handheld. Notice the offset and the similiarity of data packets being sent. Even though no new IT or APC Policy is being sent to the device at this point, you'll notice the references to SET_IT_POLICY_COMMAND and SEND_APC_APP in the log lines.
[40000] (06/01 12:15:29.859):{0x14FC} {}RequestHandler::GetApplicationData: Loading the module at offset 81428, length 74472, path "C:\BES\PackageCache\FILESHARE_testbes1\rsa\RSA3.02\SecurID.cod".
[40000] (06/01 12:15:29.890):{0x14FC} {}RequestHandler::SendToRelay - SubmitToRelaySendQ, Tag=13918
[40000] (06/01 12:15:29.906):{0x14FC} {}RequestHandler::SendToRelay - SubmitToRelaySendQ, Tag=13919
[40000] (06/01 12:15:29.906):{0x14FC} {}RequestHandler::SendApp: Sending the module C:\BES\PackageCache\FILESHARE_testbes1\rsa\RSA3.02\SecurID.cod for entry id 7278.
[40000] (06/01 12:15:29.921):{0x14FC} {}RequestHandler:: DoWork - Completed Processing SEND_APC_APP request
[40000] (06/01 12:15:31.218):{0x1318} {}RequestHandler:: DoWork - Processing NEW_MESSAGE request
[40000] (06/01 12:15:31.218):{0x1318} {}RequestHandler:: DoGMEReceiveProcessing - Receiving packet from device, size=47, TransactionId=948454968, Tag=9844762, content type=ITADMIN, cmd=0x3
[40000] (06/01 12:15:31.234):{0x1318} {}RequestHandler::HandleITADMINDataCommand - ITPolicy Success Ack for the command SET_IT_POLICY_COMMAND - Processing packet, Tag=9844762
[40000] (06/01 12:15:31.250):{0x1318} {}RequestHandler::SendToRelay - SubmitToRelaySendQ, Tag=9844762
[40000] (06/01 12:15:31.250):{0x1318} {}RequestHandler:: DoWork - Completed Processing NEW_MESSAGE request
[40000] (06/01 12:15:36.578):{0xA4C} {}RequestHandler:: DoWork - Processing DEVICE_SEND_STATUS_EVENT request
[30000] (06/01 12:15:36.578):{0xA4C} {}RequestHandler:: DoDeviceSentProcessing - Message has been delivered to device, Tag=13918
[40000] (06/01 12:15:36.578):{0xA4C} {}RequestHandler:: DoITPolicyDeviceSentProcessing - ITPolicy GME Receive Ack for the command SEND_APC_APP - Processing packet, Tag=13918
[40000] (06/01 12:15:36.578):{0xA4C} {}RequestHandler:: DoWork - Completed Processing DEVICE_SEND_STATUS_EVENT request
[40000] (06/01 12:15:36.781):{0x11B0} {}RequestHandler:: DoWork - Processing DEVICE_SEND_STATUS_EVENT request
[30000] (06/01 12:15:36.781):{0x11B0} {}RequestHandler:: DoDeviceSentProcessing - Message has been delivered to device, Tag=13919
[40000] (06/01 12:15:36.796):{0x11B0} {}RequestHandler:: DoITPolicyDeviceSentProcessing - ITPolicy GME Receive Ack for the command SEND_APC_APP - Processing packet, Tag=13919
[40000] (06/01 12:15:36.828):{0x11B0} {}SCS::QueueNextSequenceforGroup - Queuing SEND_APC_APP request
[40000] (06/01 12:15:36.828):{0x16E4} {}RequestHandler:: DoWork - Processing SEND_APC_APP request
[40000] (06/01 12:15:36.828):{0x11B0} {}RequestHandler:: DoWork - Completed Processing DEVICE_SEND_STATUS_EVENT request
The final chunk is sent to the handheld. Notice the length and how it is less than the other two chunks. It is the final bits and adds up to whatever is left.
[40000] (06/01 12:15:36.843):{0x16E4} {}RequestHandler::GetApplicationData: Loading the module at offset 155943, length 34444, path "C:\BES\PackageCache\FILESHARE_testbes1\rsa\RSA3.02\SecurID.cod".
[40000] (06/01 12:15:36.859):{0x16E4} {}RequestHandler::SendToRelay - SubmitToRelaySendQ, Tag=13920
[40000] (06/01 12:15:36.859):{0x16E4} {}RequestHandler::SendApp: Sending the module C:\BES\PackageCache\FILESHARE_testbes1\rsa\RSA3.02\SecurID.cod for entry id 7279.
[40000] (06/01 12:15:36.875):{0x16E4} {}RequestHandler:: DoWork - Completed Processing SEND_APC_APP request
[40000] (06/01 12:15:38.453):{0x14FC} {}RequestHandler:: DoWork - Processing NEW_MESSAGE request
[40000] (06/01 12:15:38.453):{0x14FC} {}RequestHandler:: DoGMEReceiveProcessing - Receiving packet from device, size=47, TransactionId=948454970, Tag=9844764, content type=ITADMIN, cmd=0x3
[40000] (06/01 12:15:38.453):{0x14FC} {}RequestHandler::HandleITADMINDataCommand - ITPolicy Success Ack for the command SET_IT_POLICY_COMMAND - Processing packet, Tag=9844764
[40000] (06/01 12:15:38.468):{0x14FC} {}RequestHandler::SendToRelay - SubmitToRelaySendQ, Tag=9844764
[40000] (06/01 12:15:38.468):{0x14FC} {}RequestHandler:: DoWork - Completed Processing NEW_MESSAGE request
[40000] (06/01 12:15:39.812):{0x1318} {}RequestHandler:: DoWork - Processing DEVICE_SEND_STATUS_EVENT request
[30000] (06/01 12:15:39.812):{0x1318} {}RequestHandler:: DoDeviceSentProcessing - Message has been delivered to device, Tag=13920
[40000] (06/01 12:15:39.812):{0x1318} {}RequestHandler:: DoITPolicyDeviceSentProcessing - ITPolicy GME Receive Ack for the command SEND_APC_APP - Processing packet, Tag=13920
[40000] (06/01 12:15:39.828):{0x1318} {}RequestHandler:: DoWork - Completed Processing DEVICE_SEND_STATUS_EVENT request
[40000] (06/01 12:15:54.093):{0xA4C} {}RequestHandler:: DoWork - Processing NEW_MESSAGE request
[40000] (06/01 12:15:54.093):{0xA4C} {}RequestHandler:: DoGMEReceiveProcessing - Receiving packet from device, size=70, TransactionId=948454972, Tag=9844768, content type=APPD, cmd=0x3
The line we all look for ... Application push Success ack
[40000] (06/01 12:15:54.093):{0xA4C} {}RequestHandler::HandleAPPDDataCommand - Application push Success ack.
[40000] (06/01 12:15:54.203):{0xA4C} {}RequestHandler::SendToRelay - SubmitToRelaySendQ, Tag=9844768
... and the closing line to the whole series (Remember, we pushed an application AND a policy.)
[40000] (06/01 12:15:54.203):{0xA4C} {}RequestHandler:: DoWork - Completed Processing NEW_MESSAGE request
____________________
Two problems with Application Push that I constantly see are:
Vendor and device.xml out of date
The POLC log will show something similar to: Device info for hardwareID 0x0D000D04 could not be found
The resolution is to:
Transaction ID already Queued
This error will occur if there were any previous application push failures for a user. The given user will not be able to receive that specific application until the status in the ITAdminQueue is cleared.
The error in the POLC log will be: RequestHandler::PollForMissingApps – Transaction Id already queued for package
The resolution is to execute the following SQL statement against your production BlackBerry Configuration Database (this will fix the problem with all users at the point in time it is executed): DELETE FROM ITAdminQueue WHERE (GroupingNumber != 0 AND GroupingNumber IN (SELECT GroupingNumber FROM ITAdminQueue WHERE (Command=128 OR Command=129) AND Status=6)) OR (GroupingNumber = 0 AND (Command=128 OR Command=129) AND Status=6)
____________________
If you've got any questions about other specific entries in the POLC log feel free to post a question / comment in response to this post, or in the forum.
Tomorrow, in Part 12, we'll tackle the BlackBerry Router (ROUT) log.
As promised, here is the other major part of the POLC log ... Software Deployment / Application Push. Keep in mind, that as a part of a Software Configuration is the Application Control Policy (APC). The APC (Yes, APC and not ACP) sets permissions on a given application that is deployed and either provides or revokes that application the ability to perform certain tasks on the BlackBerry handheld ... so here we go with a snip from the POLC log pushing RSA SecurID software token software to a BlackBerry handheld:
Push is initiated from the BES (Most commonly done either via the Deploy Applications option within the BlackBerry Manager, or the default 4 hour polling interval set on the BES)
[40000] (06/01 12:14:53.484):{0x166C} {testuser1@port3101.org, PIN=FFFFFFFF, UserId=70}SCS::PollDBQueueNewRequests - Queuing POLL_FOR_MISSING_APPS request
NOTE: Between the {} I've removed testuser1@port3101.org, PIN=FFFFFFFF, UserId=70 for readability sake in the following log lines.
The BES has located the source file and has broken up the source SecurID.cod file into 3 separate 56KB parts for deployment.
[40000] (06/01 12:15:01.593):{0x1318} {}RequestHandler::PollForMissingApps: Queuing the package RSA SecurID, consisting of 1 modules in 3 parts.
[40000] (06/01 12:15:01.593):{0x1318} {}RequestHandler::PollForMissingApps: Found 3 siblings for module C:\BES\PackageCache\FILESHARE_testbes1\rsa\RSA3.02\SecurID.cod.
[40000] (06/01 12:15:01.593):{0x1318} {}RequestHandler::QueueModule: Queuing part 1 of 3, module C:\BES\PackageCache\FILESHARE_testbes1\rsa\RSA3.02\SecurID.cod of the package RSA SecurID.
[40000] (06/01 12:15:01.609):{0x1318} {}RequestHandler::QueueModule: Queuing part 2 of 3, module C:\BES\PackageCache\FILESHARE_testbes1\rsa\RSA3.02\SecurID.cod of the package RSA SecurID.
[40000] (06/01 12:15:01.625):{0x1318} {}RequestHandler::QueueModule: Queuing part 3 of 3, module C:\BES\PackageCache\FILESHARE_testbes1\rsa\RSA3.02\SecurID.cod of the package RSA SecurID.
The Application Control Policy is sent to and processed by the device. Notice, this happens BEFORE the application is pushed; ensuring that a proper policy will be in place before the application is installed.
[40000] (06/01 12:15:01.765):{0x166C} {}SCS::PollDBQueueNewRequests - Queuing SEND_APC_ITPOLICY request
[40000] (06/01 12:15:02.843):{0x1780} {}SCS::CheckDBforITPolicyChanges - Queuing SET_ITPOLICY_REQUEST request, ITPolicyId 4
[40000] (06/01 12:15:04.046):{0x166C} {}SCS::PollDBQueueNewRequests - Queuing SET_ITPOLICY_REQUEST request
[40000] (06/01 12:15:20.812):{0x11B0} {}RequestHandler:: DoWork - Processing SET_ITPOLICY_REQUEST request
[40000] (06/01 12:15:20.812):{0x16E4} {}RequestHandler:: DoWork - Processing SEND_APC_ITPOLICY request
[40000] (06/01 12:15:20.843):{0x11B0} {}RequestHandler::SendToRelay - SubmitToRelaySendQ, Tag=13913
[30000] (06/01 12:15:20.875):{0x11B0} {}RequestHandler::SendQueuedITAdminCommandToDevice Sending data to device, contentType=ITADMIN, size=638, RefId=0, TransactionId=-901092938, Tag=13914
[30000] (06/01 12:15:20.875):{0x16E4} {}RequestHandler::SendQueuedITAdminCommandToDevice Sending data to device, contentType=ITADMIN, size=638, RefId=0, TransactionId=-901092937, Tag=13915
[40000] (06/01 12:15:20.875):{0x11B0} {}RequestHandler::SendToRelay - SubmitToRelaySendQ, Tag=13914
[40000] (06/01 12:15:20.875):{0x16E4} {}RequestHandler::SendToRelay - SubmitToRelaySendQ, Tag=13915
[40000] (06/01 12:15:20.890):{0x11B0} {}RequestHandler:: DoWork - Completed Processing SET_ITPOLICY_REQUEST request
[40000] (06/01 12:15:20.890):{0x16E4} {}RequestHandler:: DoWork - Completed Processing SEND_APC_ITPOLICY request
[40000] (06/01 12:15:22.421):{0x14FC} {}RequestHandler:: DoWork - Processing DEVICE_SEND_STATUS_EVENT request
[30000] (06/01 12:15:22.421):{0x14FC} {}RequestHandler:: DoDeviceSentProcessing - Message has been delivered to device, Tag=13914
[40000] (06/01 12:15:22.421):{0x14FC} {}RequestHandler:: DoITPolicyDeviceSentProcessing - ITPolicy GME Receive Ack for the command SET_IT_POLICY_COMMAND - Processing packet, Tag=13914
[40000] (06/01 12:15:22.437):{0x14FC} {}RequestHandler:: DoWork - Completed Processing DEVICE_SEND_STATUS_EVENT request
[40000] (06/01 12:15:22.578):{0x1318} {}RequestHandler:: DoWork - Processing DEVICE_SEND_STATUS_EVENT request
[30000] (06/01 12:15:22.578):{0x1318} {}RequestHandler:: DoDeviceSentProcessing - Message has been delivered to device, Tag=13915
[40000] (06/01 12:15:22.578):{0x1318} {}RequestHandler:: DoITPolicyDeviceSentProcessing - ITPolicy GME Receive Ack for the command SEND_APC_ITPOLICY - Processing packet, Tag=13915
The First 56KB chunk of SecurID.cod is sent to the handheld.
[40000] (06/01 12:15:22.656):{0x1318} {}SCS::QueueNextSequenceforGroup - Queuing SEND_APC_APP request
[40000] (06/01 12:15:22.656):{0xA4C} {}RequestHandler:: DoWork - Processing SEND_APC_APP request
[40000] (06/01 12:15:22.656):{0x1318} {}RequestHandler:: DoWork - Completed Processing DEVICE_SEND_STATUS_EVENT request
[40000] (06/01 12:15:22.656):{0xA4C} {}RequestHandler::GetApplicationData: Loading the module at offset 45, length 81340, path "C:\BES\PackageCache\FILESHARE_testbes1\rsa\RSA3.02\SecurID.cod".
[40000] (06/01 12:15:22.687):{0xA4C} {}RequestHandler::SendToRelay - SubmitToRelaySendQ, Tag=13916
[40000] (06/01 12:15:22.703):{0xA4C} {}RequestHandler::SendToRelay - SubmitToRelaySendQ, Tag=13917
[40000] (06/01 12:15:22.703):{0xA4C} {}RequestHandler::SendApp: Sending the module C:\BES\PackageCache\FILESHARE_testbes1\rsa\RSA3.02\SecurID.cod for entry id 7277.
[40000] (06/01 12:15:22.718):{0xA4C} {}RequestHandler:: DoWork - Completed Processing SEND_APC_APP request
[40000] (06/01 12:15:27.140):{0x11B0} {}RequestHandler:: DoWork - Processing DEVICE_SEND_STATUS_EVENT request
[30000] (06/01 12:15:27.140):{0x11B0} {}RequestHandler:: DoDeviceSentProcessing - Message has been delivered to device, Tag=13916
[40000] (06/01 12:15:27.140):{0x11B0} {}RequestHandler:: DoITPolicyDeviceSentProcessing - ITPolicy GME Receive Ack for the command SEND_APC_APP - Processing packet, Tag=13916
[40000] (06/01 12:15:27.140):{0x11B0} {}RequestHandler:: DoWork - Completed Processing DEVICE_SEND_STATUS_EVENT request
[40000] (06/01 12:15:29.812):{0x16E4} {}RequestHandler:: DoWork - Processing DEVICE_SEND_STATUS_EVENT request
[30000] (06/01 12:15:29.812):{0x16E4} {}RequestHandler:: DoDeviceSentProcessing - Message has been delivered to device, Tag=13917
[40000] (06/01 12:15:29.812):{0x16E4} {}RequestHandler:: DoITPolicyDeviceSentProcessing - ITPolicy GME Receive Ack for the command SEND_APC_APP - Processing packet, Tag=13917
[40000] (06/01 12:15:29.843):{0x16E4} {}SCS::QueueNextSequenceforGroup - Queuing SEND_APC_APP request
[40000] (06/01 12:15:29.843):{0x14FC} {}RequestHandler:: DoWork - Processing SEND_APC_APP request
[40000] (06/01 12:15:29.843):{0x16E4} {}RequestHandler:: DoWork - Completed Processing DEVICE_SEND_STATUS_EVENT request
The Second 56KB chunk is sent to the handheld. Notice the offset and the similiarity of data packets being sent. Even though no new IT or APC Policy is being sent to the device at this point, you'll notice the references to SET_IT_POLICY_COMMAND and SEND_APC_APP in the log lines.
[40000] (06/01 12:15:29.859):{0x14FC} {}RequestHandler::GetApplicationData: Loading the module at offset 81428, length 74472, path "C:\BES\PackageCache\FILESHARE_testbes1\rsa\RSA3.02\SecurID.cod".
[40000] (06/01 12:15:29.890):{0x14FC} {}RequestHandler::SendToRelay - SubmitToRelaySendQ, Tag=13918
[40000] (06/01 12:15:29.906):{0x14FC} {}RequestHandler::SendToRelay - SubmitToRelaySendQ, Tag=13919
[40000] (06/01 12:15:29.906):{0x14FC} {}RequestHandler::SendApp: Sending the module C:\BES\PackageCache\FILESHARE_testbes1\rsa\RSA3.02\SecurID.cod for entry id 7278.
[40000] (06/01 12:15:29.921):{0x14FC} {}RequestHandler:: DoWork - Completed Processing SEND_APC_APP request
[40000] (06/01 12:15:31.218):{0x1318} {}RequestHandler:: DoWork - Processing NEW_MESSAGE request
[40000] (06/01 12:15:31.218):{0x1318} {}RequestHandler:: DoGMEReceiveProcessing - Receiving packet from device, size=47, TransactionId=948454968, Tag=9844762, content type=ITADMIN, cmd=0x3
[40000] (06/01 12:15:31.234):{0x1318} {}RequestHandler::HandleITADMINDataCommand - ITPolicy Success Ack for the command SET_IT_POLICY_COMMAND - Processing packet, Tag=9844762
[40000] (06/01 12:15:31.250):{0x1318} {}RequestHandler::SendToRelay - SubmitToRelaySendQ, Tag=9844762
[40000] (06/01 12:15:31.250):{0x1318} {}RequestHandler:: DoWork - Completed Processing NEW_MESSAGE request
[40000] (06/01 12:15:36.578):{0xA4C} {}RequestHandler:: DoWork - Processing DEVICE_SEND_STATUS_EVENT request
[30000] (06/01 12:15:36.578):{0xA4C} {}RequestHandler:: DoDeviceSentProcessing - Message has been delivered to device, Tag=13918
[40000] (06/01 12:15:36.578):{0xA4C} {}RequestHandler:: DoITPolicyDeviceSentProcessing - ITPolicy GME Receive Ack for the command SEND_APC_APP - Processing packet, Tag=13918
[40000] (06/01 12:15:36.578):{0xA4C} {}RequestHandler:: DoWork - Completed Processing DEVICE_SEND_STATUS_EVENT request
[40000] (06/01 12:15:36.781):{0x11B0} {}RequestHandler:: DoWork - Processing DEVICE_SEND_STATUS_EVENT request
[30000] (06/01 12:15:36.781):{0x11B0} {}RequestHandler:: DoDeviceSentProcessing - Message has been delivered to device, Tag=13919
[40000] (06/01 12:15:36.796):{0x11B0} {}RequestHandler:: DoITPolicyDeviceSentProcessing - ITPolicy GME Receive Ack for the command SEND_APC_APP - Processing packet, Tag=13919
[40000] (06/01 12:15:36.828):{0x11B0} {}SCS::QueueNextSequenceforGroup - Queuing SEND_APC_APP request
[40000] (06/01 12:15:36.828):{0x16E4} {}RequestHandler:: DoWork - Processing SEND_APC_APP request
[40000] (06/01 12:15:36.828):{0x11B0} {}RequestHandler:: DoWork - Completed Processing DEVICE_SEND_STATUS_EVENT request
The final chunk is sent to the handheld. Notice the length and how it is less than the other two chunks. It is the final bits and adds up to whatever is left.
[40000] (06/01 12:15:36.843):{0x16E4} {}RequestHandler::GetApplicationData: Loading the module at offset 155943, length 34444, path "C:\BES\PackageCache\FILESHARE_testbes1\rsa\RSA3.02\SecurID.cod".
[40000] (06/01 12:15:36.859):{0x16E4} {}RequestHandler::SendToRelay - SubmitToRelaySendQ, Tag=13920
[40000] (06/01 12:15:36.859):{0x16E4} {}RequestHandler::SendApp: Sending the module C:\BES\PackageCache\FILESHARE_testbes1\rsa\RSA3.02\SecurID.cod for entry id 7279.
[40000] (06/01 12:15:36.875):{0x16E4} {}RequestHandler:: DoWork - Completed Processing SEND_APC_APP request
[40000] (06/01 12:15:38.453):{0x14FC} {}RequestHandler:: DoWork - Processing NEW_MESSAGE request
[40000] (06/01 12:15:38.453):{0x14FC} {}RequestHandler:: DoGMEReceiveProcessing - Receiving packet from device, size=47, TransactionId=948454970, Tag=9844764, content type=ITADMIN, cmd=0x3
[40000] (06/01 12:15:38.453):{0x14FC} {}RequestHandler::HandleITADMINDataCommand - ITPolicy Success Ack for the command SET_IT_POLICY_COMMAND - Processing packet, Tag=9844764
[40000] (06/01 12:15:38.468):{0x14FC} {}RequestHandler::SendToRelay - SubmitToRelaySendQ, Tag=9844764
[40000] (06/01 12:15:38.468):{0x14FC} {}RequestHandler:: DoWork - Completed Processing NEW_MESSAGE request
[40000] (06/01 12:15:39.812):{0x1318} {}RequestHandler:: DoWork - Processing DEVICE_SEND_STATUS_EVENT request
[30000] (06/01 12:15:39.812):{0x1318} {}RequestHandler:: DoDeviceSentProcessing - Message has been delivered to device, Tag=13920
[40000] (06/01 12:15:39.812):{0x1318} {}RequestHandler:: DoITPolicyDeviceSentProcessing - ITPolicy GME Receive Ack for the command SEND_APC_APP - Processing packet, Tag=13920
[40000] (06/01 12:15:39.828):{0x1318} {}RequestHandler:: DoWork - Completed Processing DEVICE_SEND_STATUS_EVENT request
[40000] (06/01 12:15:54.093):{0xA4C} {}RequestHandler:: DoWork - Processing NEW_MESSAGE request
[40000] (06/01 12:15:54.093):{0xA4C} {}RequestHandler:: DoGMEReceiveProcessing - Receiving packet from device, size=70, TransactionId=948454972, Tag=9844768, content type=APPD, cmd=0x3
The line we all look for ... Application push Success ack
[40000] (06/01 12:15:54.093):{0xA4C} {}RequestHandler::HandleAPPDDataCommand - Application push Success ack.
[40000] (06/01 12:15:54.203):{0xA4C} {}RequestHandler::SendToRelay - SubmitToRelaySendQ, Tag=9844768
... and the closing line to the whole series (Remember, we pushed an application AND a policy.)
[40000] (06/01 12:15:54.203):{0xA4C} {}RequestHandler:: DoWork - Completed Processing NEW_MESSAGE request
____________________
Two problems with Application Push that I constantly see are:
- Vendor and device.xml out of date
- Transaction ID already Queued
Vendor and device.xml out of date
The POLC log will show something similar to: Device info for hardwareID 0x0D000D04 could not be found
The resolution is to:
- Download the most up to date Device.xml and Vendor.xml from https://www.blackberry.com/Desktop/D...XML/Device.xml and https://www.blackberry.com/Desktop/D...XML/Vendor.xml
- Replace Device.xml and Vendor.xml in C:\Program Files\Common Files\Research In Motion\AppLoader
- Delete everything in the folder C:\Program Files\Research In Motion\BlackBerry Enterprise Server\PackageCache
- Execute loader /reindex in the C:\Program Files\Common Files\Research In Motion\AppLoader directory
Transaction ID already Queued
This error will occur if there were any previous application push failures for a user. The given user will not be able to receive that specific application until the status in the ITAdminQueue is cleared.
The error in the POLC log will be: RequestHandler::PollForMissingApps – Transaction Id already queued for package
The resolution is to execute the following SQL statement against your production BlackBerry Configuration Database (this will fix the problem with all users at the point in time it is executed): DELETE FROM ITAdminQueue WHERE (GroupingNumber != 0 AND GroupingNumber IN (SELECT GroupingNumber FROM ITAdminQueue WHERE (Command=128 OR Command=129) AND Status=6)) OR (GroupingNumber = 0 AND (Command=128 OR Command=129) AND Status=6)
____________________
If you've got any questions about other specific entries in the POLC log feel free to post a question / comment in response to this post, or in the forum.
Tomorrow, in Part 12, we'll tackle the BlackBerry Router (ROUT) log.
Total Comments 4
Comments
-
Great series hdawg.
When you assign a software config policy to an app and then push the app, it looks like it applies first the IT policy again, then app config policy, then pushes the app. Sort of redundant for the IT policy but I guess it really wants the device to be in a known IT policy state before pushing the config policy and app.
Application Control policies have always scared me because there are so many gotcha's when you work with them where pushing an app to a user will cause a restart dialog box to pop up.
I am currently also working through an issue with 5.0 where using transporter to 5.0 causes some previous 3rd party apps to not be able to launch with "ControlledAccessException", probably due to the App Control Policy for Unlisted Applications. Run into that yet?Posted 07-06-2009 at 10:53 AM by mahoward
-
Thanks
Indeed that is the case. When you set / send an Application Control Policy (APC) you're also sending the IT Policy. The APC Policy is effectively an extension of the IT Policy that only kicks in with a Software Configuration assigned to a user.
I've seen ControlledAccessException with BES 4.x ... always related to Application Control Policy settings.Posted 07-07-2009 at 12:03 AM by hdawg
-
Getting "Transaction Id already queued for package ###" message in POLC log
Hello hdawg,
Thank you for the great series.
Some time before I solved a issue on BES, by using this part 11 of POLC log.
But, this time I am having Issue "Transaction Id already queued for package ###".
I am using BES 4.1.3.
And I tried to run the query suggested by you.
DELETE FROM ITAdminQueue WHERE (GroupingNumber != 0 AND GroupingNumber IN (SELECT GroupingNumber FROM ITAdminQueue WHERE (Command=128 OR Command=129) AND Status=6)) OR (GroupingNumber = 0 AND (Command=128 OR Command=129) AND Status=6)
-- Result -- No row affected
Again, after some time when BES poll for Missing Apps. POLC log again shows
"Transaction Id already queued for package ###"
Even , I deleted all the entrys from the ITAdminQueue table , but again BES polls for missing apps, same number of rows get entered in this table.
Any idea what may be going wrong here?
Thanks and appreciate your reply,
HemantPosted 08-03-2009 at 07:15 AM by hemant
-
Issue is resolved
Don't worry hdawg.
My issue is resolved.
Issue was, the BB user had removed the SIM card from the device.
Once again, thanks for the great series.
Posted 08-03-2009 at 12:11 PM by hemant
