• Facebook
  • RSS Feed
  • Instagram
  • LinkedIn
  • Twitter
Aug 102011
 

I just finished working on a rather interesting Exchange 2007 Journaling issue.  The issue that some mails, spread out over several years, and even very recently have ended up in the Failed To Copy folder in the Journal Mailbox.

We tried all different “weird stuff” like Outlook versions, trying a new journal mailbox, looking at MAPI properties over and over again, moving one or more of the items out to PST and back, but eventually we hit – by accident – on the real problem.  The difficulty was that we were just getting “different” DTRACE of the journal task when we tried to process the messages internally (and they worked fine internally, of course).

Internally we were seeing :

25513   02:30:09.017     [9340]  (JournalTask)    <8464> EV:M    :CArchivingAgent::IsEligibleForArchive() |Entering routine  |

25514   02:30:09.017     [9340]  (JournalTask)    <8464> EV:L     {GetCalculatedModifiedDate:#1285} Calculated date (dd/mm/yyyy): [28/10/2010 00:13.37] [PR_MESSAGE_DELIVERY_TIME]

25515   02:30:09.017     [9340]  (JournalTask)    <8464> EV:L     :CArchivingAgent::IsEligibleForArchive(/O=EV TRAINING/OU=EXCHANGE ADMINISTRATIVE GROUP (FYDIBOHF23SPDLT)/CN=RECIPIENTS/CN=EXK7JUSER) |The message titled: SomeMessageTitle is eligible for archive  |

25516   02:30:09.017     [9340]  (JournalTask)    <8464> EV:M    CJournalPart::MakeJournalPartMsg – Considering Message [SomeMessageTitle]

25517   02:30:09.017     [9340]  (JournalTask)    <8464> EV:M    CJournalPart::MakeJournalPartMsg – Is a E2007 Journal Message? [True]

25518   02:30:09.017     [9340]  (JournalTask)    <8464> EV:M    CJournalPart::MakeJournalPartMsg – Opening The Message

25519   02:30:09.017     [9340]  (JournalTask)    <8464> EV:M    CJournalPart::ReadUniqueIdentifier – Message-Id: a4840d7347440d42849b49faaaa8d8975cac95@something.xyz.com

25520   02:30:09.017     [9340]  (JournalTask)    <8464> EV:M    CJournalPart::MakeJournalPartMsg – Message Class Changed to [IPM.Note.EnterpriseVault.PendingArchive.Part]

25521   02:30:09.017     [9340]  (JournalTask)    <8464> EV:H    :CArchivingAgent::IsEligibleForArchive() |Exiting routine |

Our customer was not getting this at all, they were getting :

2519    12:59:15.822     [11988]    (JournalTask)    <9704>    EV:H    :CArchivingAgent::IsEligibleForArchive() |Entering routine  |
2520    12:59:15.822     [11988]    (JournalTask)    <9704>    EV:M    GetCalculatedModifiedDate – calculated date – 27/10/2010 23:20.51 (PR_MESSAGE_DELIVERY_TIME)
2521    12:59:15.822     [11988]    (JournalTask)    <9704>    EV:L    :CArchivingAgent::IsEligibleForArchive(/O=GLOBAL EXCHANGE ORGANISATION/OU=EXCHANGE ADMINISTRATIVE GROUP (FYDIBOHF23SPDLT)/CN=RECIPIENTS/CN=EXK7JUSER) |The message titled: SomethingHere is eligible for archive  |
2522    12:59:15.822     [11988]    (JournalTask)    <9704>    EV:H    :CArchivingAgent::IsEligibleForArchive() |Exiting routine |

Which then led to :

(JournalTask)	<816>	EV:M
	CExchangeShortcutAccessor::MirrorChangeToRelatedItems - eAction: 
[MAKE_PENDING]
(JournalTask)	<816>	EV:M	HRXEX fn 
trace :|Source     : .ExchangeShortcutAccessor.cpp 
(CExchangeShortcutAccessor::MirrorChangeToRelatedItems) [lines 
{7040,7093,7206}] built Oct  6 11:22:27 2010|Description: Call error 0x80040107

There was eventually a small revelation … I spotted in the Support repro and in the Customer repro that the DTRACE showed :-

JournalDelay = 0

In the registry section at the bottom of the DTRACE.

What this means is that the journal task is taking a different route through the code, and means that it won’t wait to find associated journal parts of the same message.  So, it’ll work and the item will be journal archived if at the precise moment that the journal task touches the messages, the related / part messages are also in the mailbox – but if they’re not, which happens from time to time, then it’ll end up going through this problem.

The default JournalDelay value is 5 (minutes) meaning that the task will make the items part pending, then 5 minutes will actually process them (checking once per minute as normal, and making any extra “stray”/”delayed” parts pending too). 

This is all nicely documented by Support now in :

http://www.symantec.com/business/support/index?page=content&id=TECH166823

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)