Recovery for MS Exchange - "Cannot fill metadata" errors
Installed Acronis Recovery for MS Exchange (ARME) about a week ago. Backups succeed, but throw errors about missing folders. The error is "Cannot fill metadata of..." and "'folder' is not found in the mailbox..."
These folders were deleted shortly before ARME was installed. I can't seem to purge them and don't know where the references are coming from. This is probably more of an Exchange issue, but I thought I would post this.
All backups have these errors when one of the three 'problem' mailboxes are included. I've run 3 different types of backups, Full backup of IS/Storage Group, Full backup tasked with CDB (scheduled nightly for about 3 days), and Mailbox backups.
We're running Windows Server 2003, Exchange 2003, Outlook 2k7, and of course ARME.
Below is the log. I removed many of the errors from the log, because they were just redundant. And, user,emails and server names were changed.
---------------------------------------------------------------------------------------------------------------
<log build="179" product="Acronis Tasks Service" task="78BF7BD7-E03F-4A7E-A276-5181FB74E347" uuid="FB305E39-653C-4DA1-956D-C13C388937CB" version="1.0">
<event code="0" id="1" level="2" message="Backup information store task has been started." module="82" time="1290295084" />
<event code="0" id="2" level="2" message="Prepare backup operation." module="82" time="1290295086" />
<event code="0" id="3" level="2" message="Start executing pre-commands." module="82" time="1290295086" />
<event code="1024" id="4" level="2" message="Child process has exited with code 0" module="1" time="1290295087" />
<event code="0" id="5" level="2" message="Finish executing pre-commands." module="82" time="1290295088" />
<event code="0" id="6" level="2" message="Destination place was opened." module="82" time="1290295088" />
<event code="0" id="7" level="2" message="Create new backup archive." module="82" time="1290295088" />
<event code="0" id="8" level="2" message="Strategy name `[ExchServer.Domain.local] [IS backup] [Saturday, November 20, 2010 5:36:27 PM]` is set." module="82" time="1290295088" />
<event code="0" id="9" level="2" message="Strategy ID `78BF7BD7-E03F-4A7E-A276-5181FB74E347` is set." module="82" time="1290295088" />
<event code="0" id="10" level="2" message="Compression options applied." module="82" time="1290295088">
<field name="CompressionLevel" type="TString">
high
</field>
</event>
<event code="0" id="11" level="2" message="Protection option has been applied." module="82" time="1290295088">
<field name="ProtectionEncryptMethod" type="TLong">
0
</field>
</event>
<event code="0" id="12" level="2" message="Backup options have been successfully applied." module="82" time="1290295088" />
<event code="0" id="13" level="2" message="Setting backup sources..." module="82" time="1290295088" />
<event code="0" id="14" level="2" message="Configuring backup parameters..." module="82" time="1290295088" />
<event code="0" id="15" level="2" message="Truncate transactional logs." module="82" time="1290295088" />
<event code="0" id="16" level="2" message="Backup parameters configured." module="82" time="1290295089" />
<event code="0" id="17" level="2" message="Apply backup parameters for item. Type:InformationStore; Path:/Microsoft Exchange Server/Mailbox role. " module="82" time="1290295089" />
<event code="0" id="18" level="2" message="Backup source opened." module="82" time="1290295089" />
<event code="0" id="19" level="2" message="Add storage group item to back up: /Microsoft Exchange Server/Mailbox role/First Storage Group" module="82" time="1290295089" />
<event code="0" id="20" level="2" message="Mailbox role item is added to backup." module="82" time="1290295089" />
<event code="0" id="21" level="2" message="Backup sources were successfully added." module="82" time="1290295089" />
<event code="0" id="22" level="2" message="Attach to CDP service." module="82" time="1290295089" />
<event code="0" id="23" level="2" message="Backup operation started." module="82" time="1290295089" />
<event code="16384" id="82" level="4" line_tag="0x79DF82A9E8FC2F43" message="Cannot fill metadata of the `Folder-1` folder." module="91" time="1290296108">
<field name="$module" type="TString">
C:\Program Files\Common Files\Acronis\DatabaseBackup\Fomatik\MsExchangeBackup.dll
</field>
<event code="4098" id="83" level="4" line_tag="0x79DF82A9E8FC2F24" message="Folder '/Folder-Top/Folder-1' is not found in the mailbox 'user1'." module="91" time="1290296108" />
</event>
<event code="16384" id="84" level="4" line_tag="0x79DF82A9E8FC2F43" message="Cannot fill metadata of the `Folder-2` folder." module="91" time="1290296108">
<field name="$module" type="TString">
C:\Program Files\Common Files\Acronis\DatabaseBackup\Fomatik\MsExchangeBackup.dll
</field>
<event code="4098" id="85" level="4" line_tag="0x79DF82A9E8FC2F24" message="Folder '/Folder-Top/Folder-2' is not found in the mailbox 'user1'." module="91" time="1290296108" />
</event>
<event code="16384" id="86" level="4" line_tag="0x79DF82A9E8FC2F43" message="Cannot fill metadata of the `Folder-3` folder." module="91" time="1290296108">
<field name="$module" type="TString">
C:\Program Files\Common Files\Acronis\DatabaseBackup\Fomatik\MsExchangeBackup.dll
</field>
<event code="4098" id="87" level="4" line_tag="0x79DF82A9E8FC2F24" message="Folder '/Folder-Top/Folder-3' is not found in the mailbox 'user1'." module="91" time="1290296108" />
</event>
<event code="5963776" id="88" level="2" message="Succeeded to create full backup of storage group 'First Storage Group' (database(s): 'Mailbox Store (ExchServer)') from Microsoft Exchange Server 'ExchServer'." module="91" time="1290296108" />
<event code="5963776" id="89" level="2" message="Succeeded to create full backup of storage group 'First Storage Group' (database(s): 'Public Folder Store (ExchServer)') from Microsoft Exchange Server 'ExchServer'." module="91" time="1290296139" />
<event code="5963776" id="90" level="2" message="Succeeded to create incremental backup of storage group 'First Storage Group' from Microsoft Exchange Server 'ExchServer'." module="91" time="1290296141" />
<event code="0" id="91" level="2" message="Backup operation has been successfully completed." module="82" time="1290296142" />
<event code="917515" id="92" level="4" message="Backup task failed. Reason: Member invoke failed" module="82" time="1290296148" />
<event code="0" id="93" level="2" message="E-mail notification successfully sent." module="82" time="1290296152">
<field name="Address" type="TString">
email_1, email_2, email_3
</field>
<field name="UserName" type="TString" />
<field name="Port" type="TLong">
25
</field>
<field name="Host" type="TString" />
</event>
<event code="1002" id="94" level="4" line_tag="0x6FCAEA0AC16F3E9B" message="Execution of task failed." module="65" time="1290296153">
<field name="$module" type="TString">
C:\Program Files\Common Files\Acronis\DatabaseBackup\Fomatik\ScriptTasks.dll
</field>
<event code="79" id="95" level="4" line_tag="0xDB42F6A52324F271" message="Error on executing bytecode." module="14" time="1290296153">
<field name="$module" type="TString">
C:\Program Files\Common Files\Acronis\DatabaseBackup\Fomatik\DataWalker.dll
</field>
<event code="11" id="96" level="4" line_tag="0x298D61E7C0088CAD" message="Member invoke failed" module="14" time="1290296153">
<field name="path" type="TString">
<![CDATA[
var Place;
var BackupStrategyId;
var ArchivePassword;
var CdpItem;
var OldActive;
var trace;
var WARNING;
var DEBUG;
"Find just created slice.";
set current = choose when Empty(ArchivePassword):
Place.OpenArchive.Slices
otherwise
Place.OpenArchive(ArchivePassword).Slices
end;
set lastSlice = empty;
while current.IsValid do
set currentSlice = current.Value;
choose when currentSlice.StrategyId = BackupStrategyId :
choose when Empty (lastSlice) or currentSlice.Time > lastSlice.Time:
lastSlice(currentSlice)
end
end;
current.Next
end;
current(empty);
choose when Empty (lastSlice):
evaluate WARNING with trace, "Unable to reset archive on CDP service. Backup is not found." end;
return
end;
"Find all backuped storage groups and for each SG find last log.";
set logsColl = CreateCollection;
set groups = lastSlice.DatabaseBrowser.MsExchange.MailBoxRole.StorageGroups;
while groups.IsValid do
set logs = groups.Value.LogFiles;
set lastLog = empty;
while logs.IsValid do
lastLog(logs.Value.FileName);
logs.Next
end;
choose when not Empty(lastLog):
logsColl.Add(lastLog, groups.Value.Name)
end;
groups.Next
end;
CdpItem.>>>ResetArchive(logsColl.GetPairsEnumerator);
choose when OldActive:
CdpItem.Start
end
]]>
</field>
<field name="token" type="TIdentifier">
.ResetArchive
</field>
<field name="line" type="TULong64">
52
</field>
<field name="column" type="TULong64">
17
</field>
<event code="3" id="97" level="4" line_tag="0x9D4EAFCD2984E6EF" message="File access error." module="165" time="1290296153">
<field name="$module" type="TString">
C:\Program Files\Common Files\Acronis\DatabaseBackup\Fomatik\ARXCDPAgent.exe
</field></event></event></event></event></log>
------------------------------------------------------------------------------------------------------------
Any ideas? help?
I'd appreciate it.
Thanks,
Tom
Hello Tom!
Welcome to our Forum, we're glad to greet you here! I understand how inconvenient the issue is, and will be glad to help.
Thank you for the information provided. Unfortunately it's still not obvious what caused the problem, and in order to fix it we need to localize the cause. So this issue requires investigation. Could you please gather the diagnostic data requested here and contact support directly with the information attached. Keep in mind that should there be any procrastination with the reply, you can always specify us the case number. We will do our best to speed up the process.
Should you need anything else or have any further questions - feel free to contact us at your earliest convenience, we will be happy to help you!
Thank you!
Update:
I submitted the problem to support with all of the requested info. The response was that it looked like an Exchange issue. It probably is, though I haven't run any tests. (I wanted to run an MS backup to see if any errors were thrown, but haven't done so yet).
I closed the ticket because it may be an Exchange issue and in any case I found a workaround.
I stated above that the folders were deleted, but for 2 of the Mailboxes, mine and 1 other, the folders were moved.
For these, where the folders were moved, I found a workaround:
1. Copy the folders back to their original locations (where the errors are pointing to) 2. Delete all of them (in order from bottom up)
a. Delete email of lowest subfolders
b. Delete subfolders starting from lowest
c. Delete top folder
If the top folder is deleted, with all or even just 1 remaining subfolder, then the error is still thrown for the remaining folders. The email messages then the subfolders and then the top folder had to be deleted in order to remove the errors.
There was 1 other Mailbox with 1 folder error. Since I posted this error and before I found the workaround, another folder from a different Mailbox has shown the same error. I don't know the history of this folder yet. I will try the workaround for these (creating the folders if the users had deleted rather than moved them). I will then update this post with whether all of the errors are removed.
Also, I tried moving other folders in my Mailbox and backing it up, and no errors are thrown. So, hopefully, once these last 2 folders are resolved, the issue won't come back.
One side note: I would like more detail in the error messages, or a reference list here in the Knowledge Base. If an error hasn't been posted by a user, I don't see any reference to it when searching. Even a partial list that described/defined some of the error information would be useful. For example, does "Member", as in "Member invoke failed", refer to a user, a Mailbox, or an Acronis process/procedure?