Forum Discussion

mustufa's avatar
mustufa
Level 3
14 years ago

EV Server Journal Task does not archive journal mailbox...

We have implemented a new Enterprise Vault 9.0.1 server based on Exchange Server 2007. Journaling mailbox was activated 2 weeks ago and all mails were collected since. When we activated journal archiving on system, 80% of total journal mailbox were archived but some mails were left on Exchange journal mailbox. I have enabled journaling trace and found out the messages below (message titles are masked by me):

 

37005 15:55:28.889 [6544] (JournalTask) <5400> EV:H :CArchivingAgent::IsEligibleForArchive() |Entering routine  |
37006 15:55:28.889 [6544] (JournalTask) <5400> EV:M GetCalculatedModifiedDate - calculated date - 14/1/2011 10:21.6 (PR_MESSAGE_DELIVERY_TIME)
37007 15:55:28.889 [6544] (JournalTask) <5400> EV:L :CArchivingAgent::IsEligibleForArchive(/O=FIRST ORGANIZATION/OU=EXCHANGE ADMINISTRATIVE GROUP (XXXXXXX)/CN=RECIPIENTS/CN=XXXXX) |The message titled: XXXXXXXXXXXX is eligible for archive  |
37008 15:55:28.889 [6544] (JournalTask) <5400> EV:H :CArchivingAgent::IsEligibleForArchive() |Exiting routine |
37009 15:55:28.889 [6544] (JournalTask) <5400> EV:L CArchivingAgent::QueueEligibleItem - Eligible Item Strategy [Age]
37010 15:55:28.889 [6544] (JournalTask) <5400> EV:L CPrioritizedItemTable::GetQualifyingPosition(Age) - Item didn't qualify to enter the list
37011 15:55:28.889 [6544] (JournalTask) <5400> EV:H :CArchivingAgent::IsEligibleForArchive() |Entering routine  |
37012 15:55:28.889 [6544] (JournalTask) <5400> EV:M GetCalculatedModifiedDate - calculated date - 14/1/2011 10:21.6 (PR_MESSAGE_DELIVERY_TIME)
37013 15:55:28.889 [6544] (JournalTask) <5400> EV:L :CArchivingAgent::IsEligibleForArchive(/O=FIRST ORGANIZATION/OU=EXCHANGE ADMINISTRATIVE GROUP (XXXXXXX)/CN=RECIPIENTS/CN=XXXXX) |The message titled: XXXXXXXXXXXX is eligible for archive  | is eligible for archive  |
37014 15:55:28.889 [6544] (JournalTask) <5400> EV:H :CArchivingAgent::IsEligibleForArchive() |Exiting routine |
37015 15:55:28.889 [6544] (JournalTask) <5400> EV:L CArchivingAgent::QueueEligibleItem - Eligible Item Strategy [Age]
37016 15:55:28.889 [6544] (JournalTask) <5400> EV:L CPrioritizedItemTable::GetQualifyingPosition(Age) - Item didn't qualify to enter the list
37017 15:55:28.889 [6544] (JournalTask) <5400> EV:H :CArchivingAgent::IsEligibleForArchive() |Entering routine  |
37018 15:55:28.889 [6544] (JournalTask) <5400> EV:M GetCalculatedModifiedDate - calculated date - 14/1/2011 10:21.7 (PR_MESSAGE_DELIVERY_TIME)
37019 15:55:28.889 [6544] (JournalTask) <5400> EV:L :CArchivingAgent::IsEligibleForArchive(/O=FIRST ORGANIZATION/OU=EXCHANGE ADMINISTRATIVE GROUP (XXXXXXX)/CN=RECIPIENTS/CN=XXXXX) |The message titled: XXXXXXXXXXXX is eligible for archive  | is eligible for archive  |
37020 15:55:28.889 [6544] (JournalTask) <5400> EV:H :CArchivingAgent::IsEligibleForArchive() |Exiting routine |
37021 15:55:28.889 [6544] (JournalTask) <5400> EV:L CArchivingAgent::QueueEligibleItem - Eligible Item Strategy [Age]
37022 15:55:28.889 [6544] (JournalTask) <5400> EV:L CPrioritizedItemTable::GetQualifyingPosition(Age) - Item didn't qualify to enter the list
37023 15:55:28.889 [6544] (JournalTask) <5400> EV:H :CArchivingAgent::IsEligibleForArchive() |Entering routine  |
37024 15:55:28.904 [6544] (JournalTask) <5400> EV:M GetCalculatedModifiedDate - calculated date - 14/1/2011 10:21.8 (PR_MESSAGE_DELIVERY_TIME)
37025 15:55:28.904 [6544] (JournalTask) <5400> EV:L :CArchivingAgent::IsEligibleForArchive(/O=FIRST ORGANIZATION/OU=EXCHANGE ADMINISTRATIVE GROUP (XXXXXXX)/CN=RECIPIENTS/CN=XXXXX) |The message titled: XXXXXXXXXXXX is eligible for archive  | is eligible for archive  |
37026 15:55:28.904 [6544] (JournalTask) <5400> EV:H :CArchivingAgent::IsEligibleForArchive() |Exiting routine |
37027 15:55:28.904 [6544] (JournalTask) <5400> EV:L CArchivingAgent::QueueEligibleItem - Eligible Item Strategy [Age]
37028 15:55:28.904 [6544] (JournalTask) <5400> EV:L CPrioritizedItemTable::GetQualifyingPosition(Age) - Item didn't qualify to enter the list
37029 15:55:28.904 [6544] (JournalTask) <5400> EV:H :CArchivingAgent::IsEligibleForArchive() |Entering routine  |
37030 15:55:28.904 [6544] (JournalTask) <5400> EV:M GetCalculatedModifiedDate - calculated date - 14/1/2011 10:21.8 (PR_MESSAGE_DELIVERY_TIME)
37031 15:55:28.904 [6544] (JournalTask) <5400> EV:L :CArchivingAgent::IsEligibleForArchive(/O=FIRST ORGANIZATION/OU=EXCHANGE ADMINISTRATIVE GROUP (XXXXXXX)/CN=RECIPIENTS/CN=XXXXX) |The message titled: XXXXXXXXXXXX is eligible for archive  | is eligible for archive  |
37032 15:55:28.904 [6544] (JournalTask) <5400> EV:H :CArchivingAgent::IsEligibleForArchive() |Exiting routine |
37033 15:55:28.904 [6544] (JournalTask) <5400> EV:L CArchivingAgent::QueueEligibleItem - Eligible Item Strategy [Age]
37034 15:55:28.904 [6544] (JournalTask) <5400> EV:L CPrioritizedItemTable::GetQualifyingPosition(Age) - Item didn't qualify to enter the list
37035 15:55:28.904 [6544] (JournalTask) <5400> EV:H :CArchivingAgent::IsEligibleForArchive() |Entering routine  |
37036 15:55:28.904 [6544] (JournalTask) <5400> EV:M GetCalculatedModifiedDate - calculated date - 14/1/2011 10:21.8 (PR_MESSAGE_DELIVERY_TIME)
37037 15:55:28.904 [6544] (JournalTask) <5400> EV:L :CArchivingAgent::IsEligibleForArchive(/O=FIRST ORGANIZATION/OU=EXCHANGE ADMINISTRATIVE GROUP (XXXXXXX)/CN=RECIPIENTS/CN=XXXXX) |The message titled: XXXXXXXXXXXX is eligible for archive  | is eligible for archive  |
37038 15:55:28.904 [6544] (JournalTask) <5400> EV:H :CArchivingAgent::IsEligibleForArchive() |Exiting routine |
37039 15:55:28.904 [6544] (JournalTask) <5400> EV:L CArchivingAgent::QueueEligibleItem - Eligible Item Strategy [Age]
 
This mailbox items should have been immediately archived but the messages say mails didn't qualify to enter the archiving list. I've googled but found nothing. Does anyone know about the situation?
  • I'm guessing it's getting stuck in Phase 1.  Here's what I'd consider:

    1. Create a new mailbox in Exchange and change your journal rules(or DB settings).  Create a new journal task on your EV server to process this new mailbox.

    2. In the VAC for the Journal tasks make sure the number of messages per pass has been increased to 10,000.

    This now gives a static journal mailbox (no new mail arriving) that you can focus on.  In the Dtrace for the task if you see trace containing the text "MakeJournalPartMsg" the task is in Phase 1 converting items from IPM.Note to .Part.

    In Phase 2 you should see trace such as GroupExchangeJournalParts and ProcessMessageGroup.  These trace statements should identify if messages/groups are ready for archiving.

    It should be obvious when messages are being archived.

    Sorry I've no access to my systems today otherwise I'd provide some example trace.

    Thanks

    Karl

7 Replies

  • I believe what is happening is it makes a table of 1000 items a time to journal and groups them in to ranges of dates... so what might be happening is the first message it comes across has some funky date (Spam?) that is something like 1976 or what not and its trying to find messages inside the journal mailbox that match similar dates, then archives it

    How long has this been heappening?

  • Hmm.. Messages dropping into journaling mailbox were not spam messages so far, and the ones we see in it now are not spam either. This is a purely new implementation and you can see the message dates as:

    GetCalculatedModifiedDate - calculated date - 14/1/2011 10:21.8 (PR_MESSAGE_DELIVERY_TIME)

    messages above. These are the real message dates that we can see through OWA. EV has archived 432.000 items in ~12 hours, but haven't archived remaining 130.000 messages in 6 hours. Contents of journal mailbox is still growing up through 150.000 and EV seems to be archiving selectively.

    Any opinions?

  • It's hard to tell from the trace snippet but my guess is journaling is marking items as parts ready for processing later.  This is fairly labor intensive and single threaded.  Excuse my bloated description below but using this hopefully you can identify what the task is up to.

    --

    Processing of Exchange 2007 journal mailboxes happens in a couple of stages.  This is because there can be multiple journal reports for a sent message (due to distribution list sizes as an example).

    Because of this EV processes Exchange 2007/2010 journal items in phases.

    Phase1:  All Exchange 2007/2010 journal items in the mailbox are modified to message class IPM.Note.EnterpriseVault.PendingArchive.Part.  With this the Message-ID from the journal report body is copied to a custom property to aid grouping of reports.

    Phase2: Will only start once Phase1 is complete.  This groups journal reports together and will then process them for archiving.  Because journal reports can arrive at different times for the same message there is a 5 minute grace period.  Therefore for an identified group of messages the oldest item must be older than 5 minutes.  When an item or group of items meet this criteria a message will be posted to the J2 for processing (at this point the message class changes from IPM.Note.EnterpriseVault.PendingArchive.Part to IPM.Note.EnterpriseVault.PendingArchive).

    It's possible to gauge the phase you are in by viewing MSMQ for the Journal Task and the Journal mailbox.  For example if there are items on the J2 queue this means the journal task is still archiving items and that you are not in Phase1 (Phase 2 may have finished or still be in progress).  If there are lots of messages on J1 these take priority over anything else (this removes the item from the journal mailbox).

    Now head to the journal mailbox and group items by message class, if the .Part count is increasing you're in Phase1.  If the .PendingArchive count is increasing you're in Phase2.  If the .PendingArchive count is decreasing you have items on the J1 queue being processed.

    Thanks

    Karl

  • Hi Karl,

    Thank you for your detailed explanations, it's good to know inner workings.

    I just arrived at the site to look at what is going on and followed your instructions. We have a MSCS failover cluster here and monitored it for J* queues but they are all empty. I defined the journaling mailbox to see which items are in inbox, and saw so many .PendingArchive.Part classified messages. After these messages, remaining ones are IPM.Note. I think JournalingTask is marking items but archiving does not function. Journaling was started 12/28/10, and I saw items from those dates in inbox. When I do a search in EV for date 12/28, I can see archived messages.

    May there be selective archiving?

    Regards,

    Mustafa

  • Now, it seems like we have a growing number of 

    IPM.Note.EnterpriseVault.PendingArchive.Part messages. Interesting that some messages are archived -for the same day- which I can see through Enterprise Vault's search webapp. On which trace can I observe what is going on internally?

  • I'm guessing it's getting stuck in Phase 1.  Here's what I'd consider:

    1. Create a new mailbox in Exchange and change your journal rules(or DB settings).  Create a new journal task on your EV server to process this new mailbox.

    2. In the VAC for the Journal tasks make sure the number of messages per pass has been increased to 10,000.

    This now gives a static journal mailbox (no new mail arriving) that you can focus on.  In the Dtrace for the task if you see trace containing the text "MakeJournalPartMsg" the task is in Phase 1 converting items from IPM.Note to .Part.

    In Phase 2 you should see trace such as GroupExchangeJournalParts and ProcessMessageGroup.  These trace statements should identify if messages/groups are ready for archiving.

    It should be obvious when messages are being archived.

    Sorry I've no access to my systems today otherwise I'd provide some example trace.

    Thanks

    Karl

  • Hi Karl,

    I followed your suggestions and prevented it being growed. We have defined another journal mailbox and observed that some messages are not still being archived. We created several trace logs, and realized that we haven't added the internal domain suffixes to EV admin account's e-mail adress list. As we have added to list, mails got archived. Now we have another problem of archiving performance but it's not a matter of this topic. 

    I'm marking your comment as solution. Thank you for your explanations.

    Regards,

    Mustafa