[burschi]

Hello everybody,

The following issue occurred within this week, I also had confirmations from other people that this happened.

Mail system is a fully patched Exchange 2007, the mailbox is accessed by Outlook 2007 via RPC over SSL. The system worked perfectly, first with an attached BES 4.1.6 MR7 and afterwards with BES 5.0 MR2 until the afternoon of Aug 2nd.
In the afternoon a user received several emails which some were deleted unread and some were opened and deleted afterwards.
Within a time frame of 2h all of the messages appeared twice in the deleted items, one message unread and one message read. Both had the same message ID but a different size.

This was reproducible within the upper mentioned time frame, without any change on the BES or messaging system it disappeared later.

[burschi]

Happened again this morning - I opened the Microsoft MSDN Flash 18/2009 with embedded content in the message, only in Outlook. This is the log during the period it occurred...

40000] (09/07 08:30:51.717):{0x11C4} [BIPP] Ping 1946 sent
[40000] (09/07 08:30:51.718):{0x1378} [BIPP] Ping Response 1946 received
[40000] (09/07 08:31:51.672):{0x11C4} [BIPP] Ping 1947 sent
[40000] (09/07 08:31:51.673):{0x1378} [BIPP] Ping Response 1947 received
[40442] (09/07 08:32:11.942):{0x1414} User settings: email=user@example.com, routing=S11348049, service=BlackBerryhost2, device=25XXXXXB, calendar=1, MDS=1, userOTAFM=63, incradle=0, SMIME=0, sentItems=1, dir=firstname.lastname, server=SBS2008 (session : 0x021e1090)
[40000] (09/07 08:32:51.639):{0x11C4} [BIPP] Ping 1948 sent
[40000] (09/07 08:32:51.640):{0x1378} [BIPP] Ping Response 1948 received
[40000] (09/07 08:33:51.614):{0x11C4} [BIPP] Ping 1949 sent
[40000] (09/07 08:33:51.615):{0x1378} [BIPP] Ping Response 1949 received
[40853] (09/07 08:33:59.815):{0x1414} {user@example.com} Starting Tasks rescan
[40891] (09/07 08:33:59.820):{0x1414} {user@example.com} No changes detected, rescan complete (type=Tasks)
[40423] (09/07 08:33:59.820):{0x13C8} {user@example.com} Queuing new mail through notification (external, busy). EntryId=3866
[40724] (09/07 08:33:59.821):{0x1414} {user@example.com} Get record key for this MAPI object, EntryId=3866
[40435] (09/07 08:33:59.824):{0x1414} {user@example.com} Queuing new mail through notification. EntryId=3866. Msgs Pending 0
[30085] (09/07 08:33:59.857):{0x1414} {user@example.com} New mail has arrived, EntryId=3866
[40287] (09/07 08:33:59.900):{0x1414} {user@example.com} Queuing message, RefId=-896814358, EntryId=3866, Posted=09/07 08:33:29, Delivered=09/07 08:33:42
[30066] (09/07 08:33:59.900):{0x1414} Total Msgs Pending 1
[40000] (09/07 08:34:00.367):{0x14E4} RpcGetSubject is called. [CH=25695760, MH=25241792]
[40000] (09/07 08:34:00.368):{0x14E4} RpcGetFirstAttachment is called. [CH=25695760, MH=25241792]
[40954] (09/07 08:34:00.377):{0x1414} HTML email requires 7073 bytes for 1500 bytes of plain text
[40669] (09/07 08:34:00.377):{0x1414} {user@example.com} Sending 7073 bytes of message body 64000 bytes, RefId=-896814358, EntryId=3866
[40391] (09/07 08:34:00.378):{0x1414} {user@example.com} RefId=-896814358 references 4 image(s) (in 7073 bytes of body) 0 from MB, 0 from cache, 0 failed. 0 images (0 bytes) pushed, 0 images (0 bytes) cached
[30081] (09/07 08:34:00.423):{0x1414} {user@example.com} Sending message to device, size=2292, EntryId=3866, RefId=-896814358, TransactionId=-895303389, Tag=2149
[40279] (09/07 08:34:00.423):{0x1414} {user@example.com} SubmitToRelaySendQ, Tag=2149
[40000] (09/07 08:34:00.424):{0x11C4} [BIPP] Send data, Tag=2149
[40000] (09/07 08:34:03.758):{0x1378} [BIPP] Received status DELIVERED, Tag=2149
[30097] (09/07 08:34:03.758):{0x1414} {user@example.com} Message has been delivered to device, Tag=2149, EntryId=3866
[30066] (09/07 08:34:03.808):{0x1414} Total Msgs Pending 0
[30247] (09/07 08:34:23.049):{0xFD4} Server stats - Msgs: Forwarded 331, Sent 21, Pending 0, Expired 0, Filtered 0, Forwarded/Min 0, Sent/Min 0
[40579] (09/07 08:34:52.181):{0x1348} CDO helper 0185D368 closing after 300 seconds of idle state
[40577] (09/07 08:34:53.088):{0x1348} CDO helper 0185D368 stopped
[40690] (09/07 08:34:59.873):{0x1414} {user@example.com} Starting message status rescan
[40691] (09/07 08:34:59.881):{0x1414} {user@example.com} Message status rescan completed
[40000] (09/07 08:35:02.905):{0x1378} [BIPP] Ping 72 received
[40000] (09/07 08:35:02.905):{0x11C4} [BIPP] Send Ping Response 72
[40856] (09/07 08:35:27.769):{0x1414} {user@example.com} Starting Memos rescan
[40891] (09/07 08:35:27.773):{0x1414} {user@example.com} No changes detected, rescan complete (type=Memos)
[40000] (09/07 08:36:02.879):{0x11C4} [BIPP] Ping 1950 sent
[40000] (09/07 08:36:02.880):{0x1378} [BIPP] Ping Response 1950 received
[30181] (09/07 08:36:52.966):{0x11B0} Performing system health check (BlackBerry Mailbox Agent 1 - BESX Version 5.0.0.127)
[30509] (09/07 08:36:52.966):{0x11B0} Current health score, Health=0x000000000200150F, Mask=0x000000000200150F
[40360] (09/07 08:36:52.967):{0x11B0} [BIPPa] Health: QSize=0, intMap=0
[45009] (09/07 08:36:54.218):{0x10CC} More cache hit rate: 75.0%, requests: 4, adds: 18, size: 0.0/30.0 Mb
[45014] (09/07 08:36:54.218):{0x10CC} ExtMore cache hit rate: 0.0%, requests: 0, adds: 0, size: 0/20000
[45079] (09/07 08:36:54.219):{0x10CC} Attachment cache hit rate: 0.0%, requests: 0, adds: 0, size: 0.0/30.0 Mb
[40212] (09/07 08:36:54.219):{0x10CC} Address cache hit rate: 25.0%, requests: 4, adds: 3, size: 1
[40328] (09/07 08:36:54.219):{0x10CC} Failed cache hit rate: 0.0%, requests: 6, adds: 0, size: 2
[40000] (09/07 08:37:02.859):{0x11C4} [BIPP] Ping 1951 sent
[40000] (09/07 08:37:02.860):{0x1378} [BIPP] Ping Response 1951 received
[40702] (09/07 08:37:04.359):{0x1414} {user@example.com} Starting message rescan
[40703] (09/07 08:37:04.382):{0x1414} {user@example.com} Message rescan completed
[40000] (09/07 08:38:02.856):{0x11C4} [BIPP] Ping 1952 sent
[40000] (09/07 08:38:02.857):{0x1378} [BIPP] Ping Response 1952 received
[40000] (09/07 08:39:02.845):{0x11C4} [BIPP] Ping 1953 sent
[40000] (09/07 08:39:02.846):{0x1378} [BIPP] Ping Response 1953 received
[40000] (09/07 08:39:51.491):{0x1414} CDO helper 0185D368 is not in memory
[40000] (09/07 08:39:51.491):{0x1414} Starting new CDO helper 0185D368
[40574] (09/07 08:39:51.681):{0x1348} CDO helper 0185D368 started, PID 3860
[20000] (09/07 08:39:52.285):{0x1348} {firstname.lastname}-CDOCalendar::ProcessWindowsTimezoneInfo- No Index value present
[20000] (09/07 08:39:52.285):{0x1348} {firstname.lastname}-CDOCalendar::ProcessWindowsTimezoneInfo- No Index value present
[20000] (09/07 08:39:52.285):{0x1348} {firstname.lastname}-CDOCalendar::ProcessWindowsTimezoneInfo- No Index value present
[30315] (09/07 08:39:52.297):{0x1414} {user@example.com} Sending data to PIM Connector, size=328
[40279] (09/07 08:39:52.298):{0x1414} {user@example.com} SubmitToRelaySendQ, Tag=2150
[40000] (09/07 08:39:52.298):{0x11C4} [BIPP] Send data, Tag=2150
[40793] (09/07 08:39:52.298):{0x1414} {user@example.com} GetConfig request sent to the PIM Connector. Target=GetConfig
[40000] (09/07 08:39:52.306):{0x1378} [BIPP] Received status DELIVERED, Tag=2150
[30384] (09/07 08:39:52.307):{0x1414} {user@example.com} Packet has been delivered to PIM Connector, Tag=2150
[40000] (09/07 08:39:52.321):{0x1378} [BIPP] Received datagram, Tag=2891
[30418] (09/07 08:39:52.333):{0x1414} {user@example.com} Updated PIM config
[40799] (09/07 08:39:52.333):{0x1414} {user@example.com} Processed request from PIM Connector: cmd=0x5, Tag=2891
[40279] (09/07 08:39:52.333):{0x1414} {user@example.com} SubmitToRelaySendQ, Tag=2891
[40000] (09/07 08:39:52.334):{0x11C4} [BIPP] Send status DATA_ACCEPTED, Tag=2891
[40692] (09/07 08:40:48.452):{0x1414} {user@example.com} Starting message moved rescan
[40719] (09/07 08:40:48.459):{0x1414} {user@example.com} GetFolderIDFromList No folder ID in list for EntryID
[40599] (09/07 08:40:48.459):{0x1414} {user@example.com} GetNewMovedMessages - Could not find folder entry id in folder list for RefId=-1496520056
[40719] (09/07 08:40:48.459):{0x1414} {user@example.com} GetFolderIDFromList No folder ID in list for EntryID
[40599] (09/07 08:40:48.459):{0x1414} {user@example.com} GetNewMovedMessages - Could not find folder entry id in folder list for RefId=-1172845678
[40719] (09/07 08:40:48.459):{0x1414} {user@example.com} GetFolderIDFromList No folder ID in list for EntryID
[40599] (09/07 08:40:48.459):{0x1414} {user@example.com} GetNewMovedMessages - Could not find folder entry id in folder list for RefId=-1828293312
[40719] (09/07 08:40:48.459):{0x1414} {user@example.com} GetFolderIDFromList No folder ID in list for EntryID
[40599] (09/07 08:40:48.459):{0x1414} {user@example.com} GetNewMovedMessages - Could not find folder entry id in folder list for RefId=-496588497
[40719] (09/07 08:40:48.459):{0x1414} {user@example.com} GetFolderIDFromList No folder ID in list for EntryID
[40599] (09/07 08:40:48.460):{0x1414} {user@example.com} GetNewMovedMessages - Could not find folder entry id in folder list for RefId=-1804036460
[40719] (09/07 08:40:48.460):{0x1414} {user@example.com} GetFolderIDFromList No folder ID in list for EntryID
[40599] (09/07 08:40:48.460):{0x1414} {user@example.com} GetNewMovedMessages - Could not find folder entry id in folder list for RefId=-1244280245
[40719] (09/07 08:40:48.460):{0x1414} {user@example.com} GetFolderIDFromList No folder ID in list for EntryID
[40599] (09/07 08:40:48.460):{0x1414} {user@example.com} GetNewMovedMessages - Could not find folder entry id in folder list for RefId=-1003950259
[40693] (09/07 08:40:48.460):{0x1414} {user@example.com} Message moved rescan completed
[40000] (09/07 08:40:52.300):{0x11C4} [BIPP] Ping 1954 sent
[40000] (09/07 08:40:52.301):{0x1378} [BIPP] Ping Response 1954 received
[40690] (09/07 08:41:48.454):{0x1414} {user@example.com} Starting message status rescan
[40570] (09/07 08:41:48.472):{0x1414} {user@example.com} FindAndQueueNewMessageStatusUpdates - New Status Update detected, queuing OTAFM MESSAGE_STATUS_UPDATE command for RefId=-896814358
[40691] (09/07 08:41:48.472):{0x1414} {user@example.com} Message status rescan completed
[40000] (09/07 08:41:52.300):{0x11C4} [BIPP] Ping 1955 sent
[40000] (09/07 08:41:52.301):{0x1378} [BIPP] Ping Response 1955 received
[30262] (09/07 08:42:48.461):{0x1414} {user@example.com} Preparing OTAFM Batch
[40560] (09/07 08:42:48.461):{0x1414} {user@example.com} Batching OTAFM MESSAGE_STATUS_UPDATE command for RefId=-896814358, status=1, TransactionID=-895303387
[30289] (09/07 08:42:48.462):{0x1414} {user@example.com} 1 OTAFM commands sent in batch for TransactionId=-895303387, Tag=2151, size=47
[40279] (09/07 08:42:48.462):{0x1414} {user@example.com} SubmitToRelaySendQ, Tag=2151
[30066] (09/07 08:42:48.463):{0x1414} Total Msgs Pending 1
[40000] (09/07 08:42:48.463):{0x11C4} [BIPP] Send data, Tag=2151
[40000] (09/07 08:42:51.201):{0x1378} [BIPP] Received status DELIVERED, Tag=2151
[30201] (09/07 08:42:51.202):{0x1414} {user@example.com} OTAFM batch has been DELIVERED to device, Tag=2151
[40536] (09/07 08:42:51.202):{0x1414} {user@example.com} Updating messages in OTAFM batch, TransactionID=-895303387
[30066] (09/07 08:42:51.238):{0x1414} Total Msgs Pending 0
[40267] (09/07 08:43:37.384):{0x1414} {user@example.com} Starting calendar rescan
[40373] (09/07 08:43:37.524):{0x1414} {user@example.com} Queuing notification of modified appointment. EntryId=3869 (delay processing 2 seconds)
[30019] (09/07 08:43:37.524):{0x1414} {user@example.com} MAPIMailbox::DoICS ICS Synch Successful
[40701] (09/07 08:43:37.525):{0x1414} {user@example.com} Calendar rescan completed
[40000] (09/07 08:43:51.206):{0x11C4} [BIPP] Ping 1956 sent
[40000] (09/07 08:43:51.207):{0x1378} [BIPP] Ping Response 1956 received
[40000] (09/07 08:44:51.216):{0x11C4} [BIPP] Ping 1957 sent
[40000] (09/07 08:44:51.217):{0x1378} [BIPP] Ping Response 1957 received
[40579] (09/07 08:44:53.229):{0x1348} CDO helper 0185D368 closing after 300 seconds of idle state
[40577] (09/07 08:44:53.733):{0x1348} CDO helper 0185D368 stopped
[40000] (09/07 08:45:07.933):{0x1378} [BIPP] Received datagram, Tag=2892
[40000] (09/07 08:45:07.952):{0x1414} {user@example.com} Processed MULTI_STATS from Dispatcher, Tag=2892
[40000] (09/07 08:45:52.807):{0x1378} [BIPP] Ping 73 received
[40000] (09/07 08:45:52.808):{0x11C4} [BIPP] Send Ping Response 73