Solved

Blackberry emails are suddenly delayed - using BES 4.1 on Exchange 2003

Posted on 2008-10-03
6
3,555 Views
Last Modified: 2013-12-01
I'm running SBS2003 w/ Exchange 2003 Standard.  We have 1 user with a Blackberry running on Blackberry Enterprise Server 4.1 and the flow of mail from the BES to the BB has always been instant.  Recently, there is about a 10 to 15 minute delay between the Outlook Delivery and the BB delivery, and I cannot seem to figure out why.  I'm not quite sure how to troubleshoot the problem to figure out if the delay is between Exchange and BES, BES and the carrier network, or anywhere inbetween.  I did download the BES Resource Kit, but I'm not quite sure where to begin as far as what logging levels to enable in BES, what actual log files to analyze, etc...  The only change that has been made to the server (The Exchange Server and the BES are on the same machine) is that we upgraded our version of Backup Exec to Symantec Backup Exec 12, which seemed to correlate to the same time frame that this delayed BES delivery began happening.  The BES database is on a seperate machine on the network, and uses an MSDE 2000 instance.  I've verified that the BES is communicating fine w/ the BES database as well as the SRP "network node" out on the Blackberry internet network.

Help guys!!!
0
Comment
Question by:zagnutttt4
[X]
Welcome to Experts Exchange

Add your voice to the tech community where 5M+ people just like you are talking about what matters.

  • Help others & share knowledge
  • Earn cash & points
  • Learn & ask questions
  • 3
  • 3
6 Comments
 
LVL 11

Expert Comment

by:ALogvin
ID: 22637069
OK, first things first, we need to see if the e-mails are being delivered via Rescan or via notification.

On the BES, make sure you Messaging Agent logging level is turned up to 4. Next, wait a few minutes, then open up your MAGT log for today. I would recommend a program called "TextPad".

Once opened, do a search: for the term "Queuing new mail through".

You will see one of two items:

[40423] (10/02 00:01:12.152):{0xC10} {User@domain.com} Queuing new mail through notification (external, busy). EntryId=1360840
[40266] (10/02 10:49:07.218):{0x1CC4} {User@domain.com} Queuing new mail through rescan. EntryId=1425767

What you need to see is if the "Rescan" is happening EVERY time, or just a few times an hour. My guess is it is EVERY time... which means your BES is not recieving the alerts from Exchange that it has a new e-mail.

In my environment, this typically happens when Exchange fails over or is rebooted, and BES is not. The fix is typically rebooting the BES.
0
 

Author Comment

by:zagnutttt4
ID: 22637731
Hi There!!

Thank you for your prompt response.  I turned my logging level for the Mailbox/Messaging Agent up to level 4 and sent out a bunch of test messages to myself.  I opened up my log file after a bit to analyze it.  It does appear that most of the messages are being queued through actual notification, but for some reason, they are still being delayed.  I notice quite a bit in the log that it says "message pending" or "Total Msgs Pending". Here's a snippet of the logfile from some recent transactions:
----------------------------------------------------------------------------------------------------------------------
[40279] (10/03 14:45:39.002):{0x1AC8} {cmyers@woodhavenassociation.com} SubmitToRelaySendQ, Tag=21926
[40000] (10/03 14:45:39.002):{0x1C48} [BIPP] Send data, Tag=21926
[30066] (10/03 14:45:39.002):{0x1AC8} Total Msgs Pending 5
[45009] (10/03 14:45:46.330):{0x27DC} More cache hit rate: 0.0%, requests: 0, adds: 4, size: 0.0/10.0 Mb
[45014] (10/03 14:45:46.330):{0x27DC} ExtMore cache hit rate: 0.0%, requests: 0, adds: 0, size: 0/20000
[40000] (10/03 14:45:49.955):{0x1C48} [BIPP] Ping 216 sent
[40000] (10/03 14:45:49.955):{0x2710} [BIPP] PingResponse 216 received
[40000] (10/03 14:46:12.096):{0x2710} [BIPP] Received datagram, Tag=2622
[40913] (10/03 14:46:12.096):{0x1AC8} {cmyers@woodhavenassociation.com} Device 400DB778 state: in coverage
[40000] (10/03 14:46:14.737):{0x2710} [BIPP] Received status DELIVERED, Tag=21922
[30097] (10/03 14:46:14.737):{0x1AC8} {cmyers@woodhavenassociation.com} Message has been delivered to device, Tag=21922, EntryId=9510
[30066] (10/03 14:46:14.752):{0x1AC8} Total Msgs Pending 4
[30247] (10/03 14:46:15.455):{0x2534} Server stats - Msgs: Forwarded 19297, Sent 361, Pending 5, Expired 0, Filtered 76
[40000] (10/03 14:46:17.924):{0x2710} [BIPP] Received status DELIVERED, Tag=21923
[30097] (10/03 14:46:17.924):{0x1AC8} {cmyers@woodhavenassociation.com} Message has been delivered to device, Tag=21923, EntryId=9511
[30066] (10/03 14:46:17.924):{0x1AC8} Total Msgs Pending 3
[40000] (10/03 14:46:19.377):{0x2710} [BIPP] Received status DELIVERED, Tag=21924
[30097] (10/03 14:46:19.377):{0x1AC8} {cmyers@woodhavenassociation.com} Message has been delivered to device, Tag=21924, EntryId=9512
[30066] (10/03 14:46:19.377):{0x1AC8} Total Msgs Pending 2
[40000] (10/03 14:46:20.627):{0x2710} [BIPP] Received status DELIVERED, Tag=21925
[30097] (10/03 14:46:20.627):{0x1AC8} {cmyers@woodhavenassociation.com} Message has been delivered to device, Tag=21925, EntryId=9513
[30066] (10/03 14:46:20.627):{0x1AC8} Total Msgs Pending 1
[40000] (10/03 14:46:29.112):{0x2710} [BIPP] Received status DELIVERED, Tag=21926
[30201] (10/03 14:46:29.112):{0x1AC8} {cmyers@woodhavenassociation.com} OTAFM batch has been DELIVERED to device, Tag=21926
[40536] (10/03 14:46:29.112):{0x1AC8} {cmyers@woodhavenassociation.com} Updating messages in OTAFM batch, TransactionID=-924430725
[30066] (10/03 14:46:29.112):{0x1AC8} Total Msgs Pending 0
[30247] (10/03 14:47:15.455):{0x2534} Server stats - Msgs: Forwarded 19301, Sent 361, Pending 0, Expired 0, Filtered 76
[40000] (10/03 14:47:29.127):{0x1C48} [BIPP] Ping 217 sent
[40000] (10/03 14:47:29.127):{0x2710} [BIPP] PingResponse 217 received
[40267] (10/03 14:47:36.205):{0x1AC8} {cmyers@woodhavenassociation.com} Starting calendar rescan
[40701] (10/03 14:47:36.205):{0x1AC8} {cmyers@woodhavenassociation.com} Calendar rescan completed
[40690] (10/03 14:47:54.002):{0x1AC8} {cmyers@woodhavenassociation.com} Starting message status rescan
[40570] (10/03 14:47:54.034):{0x1AC8} {cmyers@woodhavenassociation.com} FindAndQueueNewMessageStatusUpdates - Queuing new Message Status Update detected for RefId=-1291383553
[40691] (10/03 14:47:54.034):{0x1AC8} {cmyers@woodhavenassociation.com} Message status rescan completed
[40000] (10/03 14:48:29.127):{0x1C48} [BIPP] Ping 218 sent
[40000] (10/03 14:48:29.127):{0x2710} [BIPP] PingResponse 218 received
[30262] (10/03 14:48:54.049):{0x1AC8} {cmyers@woodhavenassociation.com} Preparing OTAFM Batch
[40560] (10/03 14:48:54.049):{0x1AC8} {cmyers@woodhavenassociation.com} Batching Message Status Update for RefId=-1291383553, status=1, TransactionID=-924430724
[30289] (10/03 14:48:54.049):{0x1AC8} {cmyers@woodhavenassociation.com} 1 OTAFM commands sent in batch for TransactionId=-924430724, Tag=21927, size=46
[40279] (10/03 14:48:54.049):{0x1AC8} {cmyers@woodhavenassociation.com} SubmitToRelaySendQ, Tag=21927
[40000] (10/03 14:48:54.049):{0x1C48} [BIPP] Send data, Tag=21927
[30066] (10/03 14:48:54.049):{0x1AC8} Total Msgs Pending 1
[40423] (10/03 14:48:54.987):{0x23C4} {cmyers@woodhavenassociation.com} Queuing new mail through notification (external, busy). EntryId=9516
[40724] (10/03 14:48:54.987):{0x1AC8} {cmyers@woodhavenassociation.com} Get record key for this MAPI object, EntryId=9516
[40435] (10/03 14:48:54.987):{0x1AC8} {cmyers@woodhavenassociation.com} Queuing new mail through notification. EntryId=9516. Msgs Pending 1
[30085] (10/03 14:48:54.987):{0x1AC8} {cmyers@woodhavenassociation.com} New mail has arrived, EntryId=9516
[40287] (10/03 14:48:55.002):{0x1AC8} {cmyers@woodhavenassociation.com} Queuing message, RefId=-1370575639, EntryId=9516, Posted=10/03 14:48:53, Delivered=10/03 14:48:54
[30066] (10/03 14:48:55.002):{0x1AC8} Total Msgs Pending 2
[30081] (10/03 14:48:55.002):{0x1AC8} {cmyers@woodhavenassociation.com} Sending message to device, size=488, EntryId=9516, RefId=-1370575639, TransactionId=-924430723, Tag=21928
[40279] (10/03 14:48:55.002):{0x1AC8} {cmyers@woodhavenassociation.com} SubmitToRelaySendQ, Tag=21928
[40000] (10/03 14:48:55.002):{0x1C48} [BIPP] Send data, Tag=21928
[40423] (10/03 14:49:02.987):{0x23C4} {cmyers@woodhavenassociation.com} Queuing new mail through notification (external). EntryId=9517
[40724] (10/03 14:49:02.987):{0x1AC8} {cmyers@woodhavenassociation.com} Get record key for this MAPI object, EntryId=9517
[40435] (10/03 14:49:02.987):{0x1AC8} {cmyers@woodhavenassociation.com} Queuing new mail through notification. EntryId=9517. Msgs Pending 2
[30085] (10/03 14:49:02.987):{0x1AC8} {cmyers@woodhavenassociation.com} New mail has arrived, EntryId=9517
[40287] (10/03 14:49:03.002):{0x1AC8} {cmyers@woodhavenassociation.com} Queuing message, RefId=-1383774320, EntryId=9517, Posted=10/03 14:49:02, Delivered=10/03 14:49:02
[30066] (10/03 14:49:03.002):{0x1AC8} Total Msgs Pending 3
[30081] (10/03 14:49:03.002):{0x1AC8} {cmyers@woodhavenassociation.com} Sending message to device, size=488, EntryId=9517, RefId=-1383774320, TransactionId=-924430722, Tag=21929
[40279] (10/03 14:49:03.002):{0x1AC8} {cmyers@woodhavenassociation.com} SubmitToRelaySendQ, Tag=21929
[40000] (10/03 14:49:03.002):{0x1C48} [BIPP] Send data, Tag=21929
[40423] (10/03 14:49:13.987):{0x23C4} {cmyers@woodhavenassociation.com} Queuing new mail through notification (external). EntryId=9518
[40724] (10/03 14:49:13.987):{0x1AC8} {cmyers@woodhavenassociation.com} Get record key for this MAPI object, EntryId=9518
[40435] (10/03 14:49:13.987):{0x1AC8} {cmyers@woodhavenassociation.com} Queuing new mail through notification. EntryId=9518. Msgs Pending 3
[30085] (10/03 14:49:13.987):{0x1AC8} {cmyers@woodhavenassociation.com} New mail has arrived, EntryId=9518
[40287] (10/03 14:49:14.002):{0x1AC8} {cmyers@woodhavenassociation.com} Queuing message, RefId=-1396973001, EntryId=9518, Posted=10/03 14:49:12, Delivered=10/03 14:49:13
[30066] (10/03 14:49:14.002):{0x1AC8} Total Msgs Pending 4
[30081] (10/03 14:49:14.018):{0x1AC8} {cmyers@woodhavenassociation.com} Sending message to device, size=488, EntryId=9518, RefId=-1396973001, TransactionId=-924430721, Tag=21930
[40279] (10/03 14:49:14.018):{0x1AC8} {cmyers@woodhavenassociation.com} SubmitToRelaySendQ, Tag=21930
[40000] (10/03 14:49:14.018):{0x1C48} [BIPP] Send data, Tag=21930
[30247] (10/03 14:49:15.455):{0x2534} Server stats - Msgs: Forwarded 19301, Sent 361, Pending 2, Expired 0, Filtered 76
[40000] (10/03 14:49:29.127):{0x1C48} [BIPP] Ping 219 sent
[40000] (10/03 14:49:29.127):{0x2710} [BIPP] PingResponse 219 received
[40423] (10/03 14:49:31.987):{0x23C4} {cmyers@woodhavenassociation.com} Queuing new mail through notification (external). EntryId=9519
[40435] (10/03 14:49:31.987):{0x1AC8} {cmyers@woodhavenassociation.com} Queuing new mail through notification. EntryId=9519. Msgs Pending 4
[40423] (10/03 14:49:31.987):{0x23C4} {cmyers@woodhavenassociation.com} Queuing new mail through notification (external). EntryId=9520
[40423] (10/03 14:49:31.987):{0x23C4} {cmyers@woodhavenassociation.com} Queuing new mail through notification (external). EntryId=9521
[30233] (10/03 14:49:31.987):{0x1AC8} {cmyers@woodhavenassociation.com} New message was found in SentItems, EntryId=9519
[40287] (10/03 14:49:32.002):{0x1AC8} {cmyers@woodhavenassociation.com} Queuing message, RefId=-1410171682, EntryId=9519, Posted=10/03 14:48:53, Delivered=10/03 14:48:00
[30066] (10/03 14:49:32.002):{0x1AC8} Total Msgs Pending 5
[40435] (10/03 14:49:32.002):{0x1AC8} {cmyers@woodhavenassociation.com} Queuing new mail through notification. EntryId=9520. Msgs Pending 5
[40435] (10/03 14:49:32.002):{0x1AC8} {cmyers@woodhavenassociation.com} Queuing new mail through notification. EntryId=9521. Msgs Pending 5
[40671] (10/03 14:49:32.002):{0x1AC8} {cmyers@woodhavenassociation.com} Not sending message body (311 bytes), RefId=-1410171682, EntryId=9519
[30081] (10/03 14:49:32.002):{0x1AC8} {cmyers@woodhavenassociation.com} Sending message to device, size=179, EntryId=9519, RefId=-1410171682, TransactionId=-924430720, Tag=21931
[40279] (10/03 14:49:32.002):{0x1AC8} {cmyers@woodhavenassociation.com} SubmitToRelaySendQ, Tag=21931
[40000] (10/03 14:49:32.002):{0x1C48} [BIPP] Send data, Tag=21931
[30233] (10/03 14:49:32.002):{0x1AC8} {cmyers@woodhavenassociation.com} New message was found in SentItems, EntryId=9520
[40287] (10/03 14:49:32.034):{0x1AC8} {cmyers@woodhavenassociation.com} Queuing message, RefId=-1423370363, EntryId=9520, Posted=10/03 14:49:02, Delivered=10/03 14:49:00
[30066] (10/03 14:49:32.034):{0x1AC8} Total Msgs Pending 6
[30233] (10/03 14:49:32.034):{0x1AC8} {cmyers@woodhavenassociation.com} New message was found in SentItems, EntryId=9521
[40287] (10/03 14:49:32.049):{0x1AC8} {cmyers@woodhavenassociation.com} Queuing message, RefId=-1436569044, EntryId=9521, Posted=10/03 14:49:12, Delivered=10/03 14:49:00
[30066] (10/03 14:49:32.049):{0x1AC8} Total Msgs Pending 7
[30247] (10/03 14:50:15.455):{0x2534} Server stats - Msgs: Forwarded 19301, Sent 361, Pending 7, Expired 0, Filtered 76
[40000] (10/03 14:50:29.143):{0x1C48} [BIPP] Ping 220 sent
[40000] (10/03 14:50:29.143):{0x2710} [BIPP] PingResponse 220 received
[40000] (10/03 14:51:29.159):{0x1C48} [BIPP] Ping 221 sent
[40000] (10/03 14:51:29.159):{0x2710} [BIPP] PingResponse 221 received
[40688] (10/03 14:51:55.705):{0x1AC8} {cmyers@woodhavenassociation.com} Starting message deleted rescan
[40689] (10/03 14:51:55.705):{0x1AC8} {cmyers@woodhavenassociation.com} Message deleted rescan completed
[40000] (10/03 14:52:29.174):{0x1C48} [BIPP] Ping 222 sent
[40000] (10/03 14:52:29.174):{0x2710} [BIPP] PingResponse 222 received
[40442] (10/03 14:52:30.955):{0x1AC8} User settings: email=cmyers@woodhavenassociation.com, routing=S16146687, service=WSBS2003, device=400DB778, calendar=1, MDS=1, userOTAFM=63, incradle=0, SMIME=0, sentItems=1, dir=cmyers, server=WSBS2003
[40000] (10/03 14:53:29.190):{0x1C48} [BIPP] Ping 223 sent
[40000] (10/03 14:53:29.190):{0x2710} [BIPP] PingResponse 223 received
[40702] (10/03 14:53:40.705):{0x1AC8} {cmyers@woodhavenassociation.com} Starting message rescan
[40175] (10/03 14:53:40.705):{0x1AC8} {cmyers@woodhavenassociation.com} MAPIMailbox::GetNewMessages found 3 message(s) in Inbox
[40677] (10/03 14:53:40.705):{0x1AC8} {cmyers@woodhavenassociation.com} MAPIMailbox::GetNewMessages found 3 message(s) in SentItems
[40703] (10/03 14:53:40.705):{0x1AC8} {cmyers@woodhavenassociation.com} Message rescan completed
[40000] (10/03 14:54:29.205):{0x1C48} [BIPP] Ping 224 sent
[40000] (10/03 14:54:29.205):{0x2710} [BIPP] PingResponse 224 received
[40423] (10/03 14:54:42.987):{0x23C4} {cmyers@woodhavenassociation.com} Queuing new mail through notification (external). EntryId=9528
[40724] (10/03 14:54:42.987):{0x1AC8} {cmyers@woodhavenassociation.com} Get record key for this MAPI object, EntryId=9528
[40435] (10/03 14:54:42.987):{0x1AC8} {cmyers@woodhavenassociation.com} Queuing new mail through notification. EntryId=9528. Msgs Pending 7
[30085] (10/03 14:54:42.987):{0x1AC8} {cmyers@woodhavenassociation.com} New mail has arrived, EntryId=9528
[40287] (10/03 14:54:43.002):{0x1AC8} {cmyers@woodhavenassociation.com} Queuing message, RefId=-1449767725, EntryId=9528, Posted=10/03 14:54:41, Delivered=10/03 14:54:42
[30066] (10/03 14:54:43.002):{0x1AC8} Total Msgs Pending 8
[30181] (10/03 14:54:45.455):{0x254} Performing system health check (BlackBerry Mailbox Agent 200 - BESX Version 4.1.4.13)
[40360] (10/03 14:54:45.455):{0x254} [BIPPa] Health: QSize=0, intMap=5
[40748] (10/03 14:54:46.034):{0x27DC} License total: 1
[40890] (10/03 14:54:46.034):{0x27DC} GlobalRescan stats: messaging=25% (6/24), calendar=81% (9/11), pim=66% (6/9)
-------------------------------------------------------------------------------------------------------------------------------------------

Any ideas on what my next diagnostic step should be?
0
 
LVL 11

Accepted Solution

by:
ALogvin earned 500 total points
ID: 22637856
It is good that they are being delivered via notification. At this point, i would focus on the device. It appears that the server is recognizing the e-mails nice and quick, however they are pending on the BlackBerry network, as the device doesnt appear to be "listening".

Have you rebooted your device? I'm wondering if this might be a network issue in your area too.
0
Does Powershell have you tied up in knots?

Managing Active Directory does not always have to be complicated.  If you are spending more time trying instead of doing, then it's time to look at something else. For nearly 20 years, AD admins around the world have used one tool for day-to-day AD management: Hyena. Discover why

 

Author Comment

by:zagnutttt4
ID: 22637953
I'm also wondering if it's the device itself.  This is an older Blackberry 7520 and we are using it on the Nextel Network.  There does not appear to be any difference in delivery times when we are on different towers, however, I'm assuming that it 'could' be specific to a specific chunk of Sprint/Nextel's network and/or the actual phone itself.  

So from the looks of the log file I included, it shows the the actual messages are being seen quickly and correctly by the actual Blackberry Enterprise Server, however at that point they are being delayed on the actual Nextel and/or Blackberry network?  I've been successful in attempts to quickly ping, traceroute, etc..  to the Network Node (the SRP node).  

Would you recommend wiping and/or re-activating the device on the BES?
0
 
LVL 11

Expert Comment

by:ALogvin
ID: 22637991
It is never a bad idea to wipe/reactivate the device. I would recommend that. Back up the device first, and feel free to restore everything except "Service Books".

Also... devices are pretty cheap. Get a Curve, they are great! ;)
0
 

Author Comment

by:zagnutttt4
ID: 22640772
ALogvin;

I thank you for helping me with this scenario.  The assumption that the problem may lye with the device was correct.  Wiping and re-activating the device did not solve the problem, however I tried an older BB on the same email account and it'w working fine.  Looks like the device in question was (as you stated) not "listening" correctly for the messages being pushed out over the Blackberry network.  I am awarding the points at this time.  

Thanks again for all of your help!!

Chris Myers
0

Featured Post

Efficient way to get backups off site to Azure

This user guide provides instructions on how to deploy and configure both a StoneFly Scale Out NAS Enterprise Cloud Drive virtual machine and Veeam Cloud Connect in the Microsoft Azure Cloud.

Question has a verified solution.

If you are experiencing a similar issue, please ask a related question

Read this checklist to learn more about the 15 things you should never include in an email signature.
This article will help to fix the below errors for MS Exchange Server 2013 I. Certificate error "name on the security certificate is invalid or does not match the name of the site" II. Out of Office not working III. Make Internal URLs and Externa…
The basic steps you have just learned will be implemented in this video. The basic steps are shown to configure an Exchange DAG in a live working Exchange Server Environment and manage the same (Exchange Server 2010 Software is used in a Windows Ser…
This video shows how to quickly and easily add an email signature for all users on Exchange 2016. The resulting signature is applied on a server level by Exchange Online. The email signature template has been downloaded from: www.mail-signatures…

695 members asked questions and received personalized solutions in the past 7 days.

Join the community of 500,000 technology professionals and ask your questions.

Join & Ask a Question