• Facebook
  • RSS Feed
  • Instagram
  • LinkedIn
  • Twitter
Jul 022012
 

A couple of weeks ago I was helping a colleague and friend with an odd journalling issue.  He had a journal mailbox which was being written to by Exchange, but it wasn’t being touched by Enterprise Vault.  After much poking around we finally had a look at the DTRACE.

Here is the output:

4538 20:30:36.243  [5444] (JournalTask) <1856> EV:L {CStorageArchive::GetStorageInfoData:#1225} Vault [195A83B87F5E0B740AB96BBDB2B3B03081110000vaultserver1] status: [DV_DS_AS_AVAILABLE (1)]
4539 20:30:36.243  [5444] (JournalTask) <1856> EV:L {CStorageArchive::GetStorageInfoData} (Exit) Status: [Success]
4540 20:30:36.243  [5444] (JournalTask) <1856> EV:L {CStorageArchive::GetVaultStatusEx:#793} Checked Storage information, and the throttle status for archive [195A83B87F5E0B740AB96BBDB2B3B03081110000vaultserver1] is still [DV_DS_AS_AVAILABLE (1)].
4541 20:30:36.243  [5444] (JournalTask) <1856> EV:L {CStorageArchive::GetVaultStatusEx} (Exit) Status: [Success]
4542 20:30:36.243  [5444] (JournalTask) <1856> EV:H {CArchivingAgent::PF_CheckVaultAvailability:#13966} there is something wrong with the current vault status: [0xC0041B85]
4543 20:30:36.243  [5444] (JournalTask) <1856> EV:L :CArchivingAgent::ProcessFolders() |Exiting routine |
4544 20:30:36.243  [5444] (JournalTask) <1856> EV:M ExMbxArcFolderHelper - Starting EMAF Sync
4545 20:30:36.243  [5444] (JournalTask) <1856> EV:M Updating ExMbxArcFolder records
4547 20:30:36.243  [5444] (JournalTask) <1856> EV:L CBaseDirectoryServiceWrapper::CreateDirectoryService() - Entry [m_nNumTries = 40]
4548 20:30:36.243  [5444] (JournalTask) <1856> EV:L CBaseDirectoryServiceWrapper::CreateDirectoryService() - Successfully communicated with an EV Directory Service on the local machine
4549 20:30:36.274  [5444] (JournalTask) <1856> EV:M Performing post-processing on ExMbxArcFolder Records
4551 20:30:36.274  [5444] (JournalTask) <1856> EV:L CBaseDirectoryServiceWrapper::CreateDirectoryService() - Entry [m_nNumTries = 40]
4552 20:30:36.274  [5444] (JournalTask) <1856> EV:L CBaseDirectoryServiceWrapper::CreateDirectoryService() - Successfully communicated with an EV Directory Service on the local machine
4553 20:30:36.274  [5444] (JournalTask) <1856> EV:M ExMbxArcFolderHelper - Finished EMAF Sync
4554 20:30:36.274  [5444] (JournalTask) <1856> EV:L :CArchivingAgent::ProcessUser() |Return the MAPI session to the session pool |
4555 20:30:36.274  [5444] (JournalTask) <1856> EV:H :CArchivingAgent::ProcessUser() |Exiting routine |
4556 20:30:36.274  [5444] (JournalTask) <1856> EV:H {CArchivingAgent::ProcessUserEx:#19300} It took [0.456444] seconds to process mailbox [/O=FIRST ORGANIZATION/OU=EXCHANGE ADMINISTRATIVE GROUP (FYDIBOHF23SPDLT)/CN=RECIPIENTS/CN=JOURNALINGC81].
4557 20:30:36.274  [5444] (JournalTask) <1856> EV:M {CMailboxUsage::RemoveUserFromList:#113} Removed [/O=FIRST ORGANIZATION/OU=EXCHANGE ADMINISTRATIVE GROUP (FYDIBOHF23SPDLT)/CN=RECIPIENTS/CN=JOURNALINGC81] from list of mailboxes being processed. List now contains [0] mailboxes.
4558 20:30:36.290  [5444] (JournalTask) <1856> EV:L {AgentMessageDispenser::ActivateObject:#3502} Acquiring mutex for updating message count...
4559 20:30:36.290  [5444] (JournalTask) <1856> EV:L {AgentMessageDispenser::ActivateObject:#3504} Mutex acquired.
4560 20:30:36.290  [5444] (JournalTask) <1856> EV:L {AgentMessageDispenser::ActivateObject:#3512} Using Message count value [3].
4561 20:30:36.290  [5444] (JournalTask) <1856> EV:M {AgentMessageDispenser::ActivateObject:#3808} An error that we don't specifically recognise has occurred, [0xc0041b85], so we'll just increment this messages retry count.
4562 20:30:36.290  [5444] (JournalTask) <1856> EV:L {AgentMessageDispenser::ActivateObject} (Exit) Status: [The dispenser was asked to repost the message to be retried later      (0xc00408e2)]
4563 20:30:36.290  [5444] (JournalTask) <1856> EV:M {AgentMessageDispenser::ProcessNextMessage:#1250} It took [0.467571] seconds to process the [MsgID_ArchiveMailboxEx2 (77)] MSMQ message body (ActivateObject). Processing the message [failed].
4564 20:30:36.290  [5444] (JournalTask) <1856> EV:M {AgentMessageDispenser::ProcessNextMessage:#1266} Processing MSMQ message body (ActivateObject) failed with [0xc00408e2]. The retry count will be incremented, and the message reposted to the end of the queue.
4565 20:30:36.290  [5444] (JournalTask) <1856> EV:H {AgentMessageDispenser::ProcessNextMessage:#1286} The retry count [4] for this MSMQ message has exceeded the maximum retry limit. This MSMQ message will be discarded.
4566 20:30:36.290  [5444] (JournalTask) <1856> EV:L {AgentMessageDispenser::ProcessNextMessage:#1732} Committing MSMQ transaction.

 

So it was failing, but nothing major appeared to be being output to the log.

I studied this a bit more .. and wondered what it meant :

4542 20:30:36.243  [5444] (JournalTask) <1856> EV:H {CArchivingAgent::PF_CheckVaultAvailability:#13966} there is something wrong with the current vault status: [0xC0041B85]

Turns out, when we looked, the Vault Store where the journal archive resided was in BACKUP MODE.  D’oh.

If you enjoyed this post, please consider leaving a comment or subscribing to the RSS feed to have future articles delivered to your feed reader.

 Leave a Reply

You may use these HTML tags and attributes: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <s> <strike> <strong>

(required)

(required)