Archiving corrupt items from mailboxes causes 7031 error on Exchange server, then restarts Exchange's RPC Client Access service.

Problem

As either scheduled archiving or manual archiving of user mailboxes proceeds; the archiving task may encounter an item with an unidentified form of corruption   Enterprise Vault's request to copy this item causes Exchange 2013's text converter to throw an error like this one in the RPC Client Access (RCA) logs on the Exchange server like this one, along with a 7031 event in the system log

Error Message

2015-10-23T02:57:46.460Z,642,13,/o=DomainName/ou=Exchange Administrative Group (FYDIBOHEXAMPLE)/cn=Recipients/cn=exeadmin,,ArchiveTask.EXE,12.0.6672.5000,Classic,,,,ncacn_http,Client=MSExchangeRPC,,,,fault,00:00:00.3910000,,"Watson: [IndexOutOfRangeException] Index was outside the bounds of the array.   at M.E.D.TextConverters.Internal.Format.FormatStore.TextStore.AddText(TextRunType runType, Char[] textBuffer, Int32 offset, Int32 count)     at M.E.D.TextConverters.Internal.Format.FormatStore.AddText(Char[] textBuffer, Int32 offset, Int32 count)     at M.E.D.TextConverters.Internal.Html.HtmlFormatConverter.OutputNonspace(TokenRun run)     at M.E.D.TextConverters.Internal.Html.HtmlFormatConverter.ProcessText()     at M.E.D.TextConverters.Internal.Html.HtmlFormatConverterWithEncapsulation.Process(HtmlTokenId tokenId)     at M.E.D.TextConverters.ConverterStream.Read(Byte[] buffer, Int32 offset, Int32 count)     at M.E.D.TextConverters.Internal.RtfCompressed.RtfCompressCommon.ReadMoreData()     at M.E.D.TextConverters.Internal.RtfCompressed.RtfCompressConverter.Run()     at M.E.D.TextConverters.ConverterStream.Read(Byte[] buffer, Int32 offset, Int32 count)     at M.E.D.S.BodyReadStream.<>c__DisplayClassb.<Read>b__a()     at M.E.D.S.ConvertUtils.<>c__DisplayClass1`1.<CallCtsWithReturnValue>b__0()     at M.E.D.S.ConvertUtils.CallCts(Trace tracer, String methodName, LocalizedString exceptionString, CtsCall ctsCall)     at M.E.D.S.ConvertUtils.CallCtsWithReturnValue[T](Trace tracer, String methodName, LocalizedString exceptionString, CtsCallWithReturnValue`1 ctsCall)     at M.E.D.S.BodyReadStream.Read(Byte[] buffer, Int32 offset, Int32 count)     at M.E.D.S.Util.StreamHandler.CopyStreamData(Stream readS",,,admin@domainname.com,

Viewing the line just above that one in the same thread should identify whose mailbox was being archived at that time, simply look for the nearest previous line that included the phrase "archivetask.exe." 

This causes Exchange's Client Access service to restart (which also throws a 4999 event in the application log on Exchange), effectively logging all users out of Outlook and/or prompting them for credentials.  It also prevents the archiving run from continuing until the EV admin manually restarts the task.


 

Cause

Microsoft has identified this as an issue with corrupt items, and claims that this effects all 3rd party archiving solutions, since the problem stems with Exchange's Text Converter's inability to copy that corrupt item when EV requests it.


To identify a problem item:

• Use the RPC Client Access (RCA) logs on the Exchange server target to identify whose mailbox is affected.  Find the error line with the word "watson" in it, and then find the closest previous line that mentions "archivetask.exe."  This should identify the user with the affected mailbox.
• Initiate a dtrace of archive task, making sure only the task for that user is running, and do a manual "run now" archiving sweep of the mailbox.
• Use the newly updated RCA logs to find the exact time that the "watson" error occurs again.
• Match that time in the dtrace, and find the closest previous group of lines in it matching these:

4688444 09:58:59.922 [13940] (ArchiveTask) <16064> EV:M CMAPISaveset::SaveSharableMessage - failed to insert into the saveset, trying a complex saveset. [0x80040115]4688485 09:59:00.984 [13940] (ArchiveTask) <14292> EV:L {CAgentScheduleHelper::IsScheduleBlockedOut:#73} running continuous schedule for this 24hrs [False]4688486 09:59:02.554 [13940] (ArchiveTask) <16064> EV:H {CMAPISaveset::CopySharableProps} (Exit) Status: [<0x80040115>]4688487 09:59:02.555 [13940] (ArchiveTask) <16064> EV:H {CMAPISaveset::SaveSharableMessage} (Exit) Status: [<0x80040115>]4688488 09:59:02.555 [13940] (ArchiveTask) <16064> EV:L {CMAPISaveset::__Insert} (Exit) Status: [Exception]4688489 09:59:02.555 [13940] (ArchiveTask) <16064> EV:L {CMAPISaveset::_Insert} (Exit) Status: [Exception]4688490 09:59:02.555 [13940] (ArchiveTask) <16064> EV:L {CMAPISaveset::_Insert} (Exit) Status: [Exception]4688491 09:59:02.555 [13940] (ArchiveTask) <16064> EV:H {CMAPISaveset2::_InsertBestBody:#219} _com_error exception: [<0x80040115>]4688492 09:59:02.556 [13940] (ArchiveTask) <16064> EV:H {CMAPISaveset2::_InsertBestBody} (Exit) Status: [<0x80040115>]4688493 09:59:02.556 [13940] (ArchiveTask) <16064> EV:H {CArchivingAgent::PI_BuildSaveset:#16750} Converting Error [0x80040115] to ARCHIVING_E_COPYTOFAILED4688494 09:59:02.556 [13940] (ArchiveTask) <16064> EV:H {CArchivingAgent::PI_BuildSaveset} HRXEX fn trace : Error [0xc00408fb], [.\ArchivingAgent.cpp, lines {16673,16680,16687,16691,16695,16697,16708,16713,16735,16751}, built May 15 12:00:42 2015].4688495 09:59:02.556 [13940] (ArchiveTask) <16064> EV:L {CArchivingAgent::PI_BuildSaveset:#17126} exiting function

• Upon finding that snippet, find the previous closest line that contains this phrase, which identifies the message being processed:

EV:H :CArchivingAgent::WriteWorkItemsToQueue() |Calling MakeItemPendingAndQueueMsg() |Mailbox (distinguished name is included here, and message title)

• This would only remedy the issue if no other items were corrupt in this manner.  It is entirely possible that more messages may cause the same problem, introducing a very laborious testing process.

 

Solution

This issue has been addressed as a part of Microsoft Exchange 2013 CU 14: https://support.microsoft.com/en-us/kb/3061079.