Event ID 2216 - no archiving for one out of two Exchange servers

[Masmit_999]

We've got EV 8.0 SP4 with Exchange 2007 SP3 rollup9.

There is a single EV server.

There are 2x Exchange servers.

Everything is working fine for the second Exchange server but no automatic archiving appears to have been successful since the 3rd June (our policies are 4 days or 7 days).

We've been using EV since 2007 and it's been working fine for the last couple of years until this has started happening.

The only error we see is: "Event ID: 2216 Message dispenser will suspend processing for 10 minutes due to a recoverable error"

The MSMQ queues had approx 5,000 items in the A7 and A5 queues which have been purged.

The MAPI account is working fine and has not been moved but we've created a new account and changed over to use that.

If I restart the task it processes approx 5-10 items in the A2 queue which is around the 60-75 item mark.

A dstrace doesn't show much up, I've copied the log just before and after the 2216 error below:

Families,OU=NCC,DC=nottinghamcity,DC=gov,DC=uk] - Processing security descriptor: List only Associated Mbx Account (not including inherited accounts)
5935 20:13:02.937  [4860] (ArchiveTask) <7280> EV:H :AgentMessageDispenser::ActivateObject() |Exiting routine at point A |
5936 20:13:02.937  [4860] (ArchiveTask) <9348> EV:M EX2KMBXPERM::GMUL[CN=Sarah Pikett,OU=Children and Families General Users,OU=Children and Families,OU=NCC,DC=nottinghamcity,DC=gov,DC=uk] - Adding user account [S-1-5-21-3388933763-2387696048-3050347461-26028]
5937 20:13:02.953  [4860] (ArchiveTask) <656> EV:M :AgentMessageDispenser::ProcessNextMessage() |Read new message or a message that is within its retry limit (). |About to process the message body |
5938 20:13:02.953  [4860] (ArchiveTask) <5504> EV:M :AgentMessageDispenser::ProcessNextMessage() |Retrieved a message successfully from the queue |
5939 20:13:02.953  [4860] (ArchiveTask) <7280> EV:M :AgentMessageDispenser::ProcessNextMessage() |ActivateObject has returned failure |
5940 20:13:02.953  [4860] (ArchiveTask) <656> EV:H :AgentMessageDispenser::ActivateObject() |Entering routine |
5941 20:13:02.953  [4860] (ArchiveTask) <9348> EV:M CSynchHelper::SFP(Inbox) - Successfully opened object of type MAPI_MAILUSER
5942 20:13:02.953  [4860] (ArchiveTask) <7280> EV:M AgentMessageDispenser::ProcessNextMessage - AGENTS_E_DISPABORTITEM, agent will sleep and abort the the current MSMQ Transation
5943 20:13:02.953  [4860] (ArchiveTask) <5504> EV:M :AgentMessageDispenser::ProcessNextMessage() |Read new message or a message that is within its retry limit (). |About to process the message body |
5944 20:13:02.953  [4860] (ArchiveTask) <656> EV:L :AgentMessageDispenser::ActivateObject() |Called server side object, with arguments: |m_pIArchiveAction->ArchiveMarkedItems(ExchangeServer = "RESEXEVS1",| MailboxDn = "/o=nottingham city/ou=exchange administrative group (fydibohf23spdlt)/cn=recipients/cn=hjones",| FolderPath = " ",| PathSeparator = "AAAAAAAAIPMFHCHNPABJMIEOJDFLBLNGPNOIEBJNABAAPDINKPKAOLJCJIEGKELPDADKFMBABDANAAACDFEGIMNJAAAA",| TimeStamp = "2013-06-19T15:20:05",| RetentionCategoryId = "",| AuthToken = "S-1-1-0 *****",| RetryCount = "0") |
5945 20:13:02.953  [4860] (ArchiveTask) <5504> EV:H :AgentMessageDispenser::ActivateObject() |Entering routine |
5946 20:13:02.953  [4860] (ArchiveTask) <5504> EV:M :AgentMessageDispenser::ActivateObject() |Message type indicator = MsgID_ArchiveItemV35. |Will fall through to be handled by the case for MsgID_ArchiveItemV35Imp |
5947 20:13:02.953  [4860] (ArchiveTask) <5504> EV:M :AgentMessageDispenser::ActivateObject() |Message type indicator = MsgID_ArchiveItemV35Imp. |Will fall through to be handled by the case for MsgID_ArchiveItemV35ImpImp |
5948 20:13:02.953  [4860] (ArchiveTask) <5504> EV:M :AgentMessageDispenser::ActivateObject() |Message type indicator = MsgID_ArchiveItemImp |
5949 20:13:02.953  [4860] (ArchiveTask) <5504> EV:M (BlacklistedDLs) 'BlacklistedDLs' registry key not found. No DLs will be blacklisted.
5950 20:13:02.953  [4860] (ArchiveTask) <5504> EV:H :AgentMessageDispenser::ActivateObject() |Exiting routine at point A |
5951 20:13:02.953  [4860] (ArchiveTask) <5504> EV:M :AgentMessageDispenser::ProcessNextMessage() |ActivateObject has returned failure |
5952 20:13:02.953  [4860] (ArchiveTask) <5504> EV:M AgentMessageDispenser::ProcessNextMessage - AGENTS_E_DISPSLEEPNOREPOST, agent will sleep without reposting the current message
5953 20:13:02.953  [4860] (ArchiveTask) <656> EV:L CArchivingAgent::ArchiveMarkedItems() (Entry) |
5954 20:13:02.953  [4860] (ArchiveTask) <656> EV:M CAA::AMI() - Another thread is currently processing mailbox /o=nottingham city/ou=exchange administrative group (fydibohf23spdlt)/cn=recipients/cn=hjones, this request will be put to the back of the queue
5955 20:13:02.953  [4860] (ArchiveTask) <656> EV:L CArchivingAgent::ArchiveMarkedItems() (Exit) |Success  [0] |
5956 20:13:02.953  [4860] (ArchiveTask) <656> EV:H :AgentMessageDispenser::ActivateObject() |Exiting routine at point A |
5957 20:13:02.953  [4860] (ArchiveTask) <656> EV:M :AgentMessageDispenser::ProcessNextMessage() |ActivateObject has returned failure |
5958 20:13:02.953  [4860] (ArchiveTask) <656> EV:M AgentMessageDispenser::ProcessNextMessage - AGENTS_E_DISPABORTITEM, agent will sleep and abort the the current MSMQ Transation
5959 20:13:02.953  [4860] (ArchiveTask) <9348> EV:M IsCDOEXMInstalled returning TRUE
5960 20:13:02.953  [4860] (ArchiveTask) <9348> EV:M EX2KMBXPERM::GMUL[(null)] - Getting security descriptor
5961 20:13:02.953  [4860] (ArchiveTask) <9348> EV:M EX2KMBXPERM::GMSD[(null)] - Get the Active Directory Distinguished name for this mailbox
5962 20:13:02.953  [4860] (ArchiveTask) <9348> EV:M MBXPERM::gimu[(null)] - Opened IMailUser, copying to output parameter
5963 20:13:02.953  [4860] (ArchiveTask) <9348> EV:M MBXPERM::gimu[/o=Nottingham City/ou=Exchange Administrative Group (FYDIBOHF23SPDLT)/cn=Recipients/cn=louise.mulcock] - Initialised mailbox dn
5964 20:13:02.953  [4860] (ArchiveTask) <9348> EV:M EX2KMBXPERM::getaddn[/o=Nottingham City/ou=Exchange Administrative Group (FYDIBOHF23SPDLT)/cn=Recipients/cn=louise.mulcock] - Looking up user in Active Directory
5965 20:13:02.953  [4860] (ArchiveTask) <9348> EV:M SanitizeUserName() - Sanitized username '/o=Nottingham City/ou=Exchange Administrative Group (FYDIBOHF23SPDLT)/cn=Recipients/cn=louise.mulcock' to '/o=Nottingham City/ou=Exchange Administrative Group \28FYDIBOHF23SPDLT\29/cn=Recipients/cn=louise.mulcock'
5966 20:13:02.953  [4860] (ArchiveTask) <9348> EV:M FindUser() - Using searchbase GC://resadw2k31.nottinghamcity.gov.uk
5967 20:13:02.953  [4860] (ArchiveTask) <9348> EV:M FindUser() - Search filter: (&(objectCategory=user)(legacyExchangeDN=/o=Nottingham City/ou=Exchange Administrative Group \28FYDIBOHF23SPDLT\29/cn=Recipients/cn=louise.mulcock))
5968 20:13:02.953  [4860] (ArchiveTask) <9348> EV:M FindUser() - [homeMDB] = CN=Childrens Services Mailbox Database,CN=Childrens Services Storage Group,CN=InformationStore,CN=RESEXEVS1,CN=Servers,CN=Exchange Administrative Group (FYDIBOHF23SPDLT),CN=Administrative Groups,CN=Nottingham City,CN=Microsoft Exchange,CN=Services,CN=Configuration,DC=nottinghamcity,DC=gov,DC=uk
5969 20:13:02.953  [4860] (ArchiveTask) <9348> EV:M FindUser() - [distinguishedName] = CN=louise mulcock,OU=Children and Families General Users,OU=Children and Families,OU=NCC,DC=nottinghamcity,DC=gov,DC=uk
5970 20:13:02.953  [4860] (ArchiveTask) <9348> EV:M EX2KMBXPERM::GMSD[/o=Nottingham City/ou=Exchange Administrative Group (FYDIBOHF23SPDLT)/cn=Recipients/cn=louise.mulcock] - Reading security descriptor from Active Directory
5971 20:13:02.953  [4860] (ArchiveTask) <9348> EV:M EX2KMBXPERM::RSDFAD[/o=Nottingham City/ou=Exchange Administrative Group (FYDIBOHF23SPDLT)/cn=Recipients/cn=louise.mulcock] - Bind to object: GC://resadw2k31.nottinghamcity.gov.uk/CN=louise mulcock,OU=Children and Families General Users,OU=Children and Families,OU=NCC,DC=nottinghamcity,DC=gov,DC=uk
5972 20:13:02.953  [4860] (ArchiveTask) <9348> EV:M EX2KMBXPERM::RSDFAD[/o=Nottingham City/ou=Exchange Administrative Group (FYDIBOHF23SPDLT)/cn=Recipients/cn=louise.mulcock] - Reading msExchMailboxSecurityDescriptor
5973 20:13:02.953  [4860] (ArchiveTask) <9348> EV:M EX2KMBXPERM::RSDFAD[/o=Nottingham City/ou=Exchange Administrative Group (FYDIBOHF23SPDLT)/cn=Recipients/cn=louise.mulcock] - Checking objectClass
5974 20:13:02.953  [4860] (ArchiveTask) <9348> EV:M EX2KMBXPERM::RSDFAD[/o=Nottingham City/ou=Exchange Administrative Group (FYDIBOHF23SPDLT)/cn=Recipients/cn=louise.mulcock] - Allocating new object Sid
5975 20:13:02.953  [4860] (ArchiveTask) <9348> EV:M EX2KMBXPERM::RSDFAD[/o=Nottingham City/ou=Exchange Administrative Group (FYDIBOHF23SPDLT)/cn=Recipients/cn=louise.mulcock] - Allocate/Copy security descriptor
5976 20:13:02.953  [4860] (ArchiveTask) <9348> EV:M EX2KMBXPERM::USDWOS[CN=louise mulcock,OU=Children and Families General Users,OU=Children and Families,OU=NCC,DC=nottinghamcity,DC=gov,DC=uk] - Entering Routine
5977 20:13:02.953  [4860] (ArchiveTask) <9348> EV:M EX2KMBXPERM::USDWOS[CN=louise mulcock,OU=Children and Families General Users,OU=Children and Families,OU=NCC,DC=nottinghamcity,DC=gov,DC=uk] - Copying Security Descriptor to remove instances of NT_AUTHORITY\SELF: ACE Count = 24
5978 20:13:02.953  [4860] (ArchiveTask) <9348> EV:M EX2KMBXPERM::USDWOS[CN=louise mulcock,OU=Children and Families General Users,OU=Children and Families,OU=NCC,DC=nottinghamcity,DC=gov,DC=uk] - Omitting SELF entry from Security Descriptor copy
5979 20:13:02.953  [4860] (ArchiveTask) <9348> EV:M EX2KMBXPERM::USDWOS[CN=louise mulcock,OU=Children and Families General Users,OU=Children and Families,OU=NCC,DC=nottinghamcity,DC=gov,DC=uk] - Adding objectSid [S-1-5-21-3388933763-2387696048-3050347461-30202]
5980 20:13:02.953  [4860] (ArchiveTask) <9348> EV:M EX2KMBXPERM::USDWOS[CN=louise mulcock,OU=Children and Families General Users,OU=Children and Families,OU=NCC,DC=nottinghamcity,DC=gov,DC=uk] - Saving updated Security Descriptor
5981 20:13:02.953  [4860] (ArchiveTask) <9348> EV:M EX2KMBXPERM::GMUL[CN=louise mulcock,OU=Children and Families General Users,OU=Children and Families,OU=NCC,DC=nottinghamcity,DC=gov,DC=uk] - Processing security descriptor: List only Associated Mbx Account (not including inherited accounts)
5982 20:13:02.953  [4860] (ArchiveTask) <9348> EV:M EX2KMBXPERM::GMUL[CN=louise mulcock,OU=Children and Families General Users,OU=Children and Families,OU=NCC,DC=nottinghamcity,DC=gov,DC=uk] - Adding user account [S-1-5-21-3388933763-2387696048-3050347461-30202]
5983 20:13:02.953  [4860] (ArchiveTask) <9348> EV:M CSynchHelper::SFP(Inbox) - Successfully opened object of type MAPI_MAILUSER
5984 20:13:02.968  [4860] (ArchiveTask) <7096> EV:M AgentMessageDispenser: 1 of 5 Agent threads is pausing|
5985 20:13:02.968  [4860] (ArchiveTask) <7096> EV:M AgentMessageDispenser::LogPauseReason - First Dispenser Thread to Sleep
5986 20:13:02.968  [4860] (ArchiveTask) <5504> EV:M AgentMessageDispenser: 2 of 5 Agent threads is pausing|
5987 20:13:02.968  [4860] (ArchiveTask) <7280> EV:M AgentMessageDispenser: 3 of 5 Agent threads is pausing|
5988 20:13:02.968  [4860] (ArchiveTask) <656> EV:M AgentMessageDispenser: 4 of 5 Agent threads is pausing|
5989 20:13:02.968  [4860] (ArchiveTask) <7096> EV~W Event ID: 2216 Message dispenser will suspend processing for 10 minutes due to a recoverable error |Task: Exchange Mailbox Archiving Task for RESEXEVS1 |
5990 20:13:02.968  [4860] (ArchiveTask) <9348> EV:M IsCDOEXMInstalled returning TRUE
5991 20:13:02.968  [4860] (ArchiveTask) <9348> EV:M EX2KMBXPERM::GMUL[(null)] - Getting security descriptor
5992 20:13:02.968  [4860] (ArchiveTask) <9348> EV:M EX2KMBXPERM::GMSD[(null)] - Get the Active Directory Distinguished name for this mailbox
5993 20:13:02.968  [4860] (ArchiveTask) <9348> EV:M MBXPERM::gimu[(null)] - Opened IMailUser, copying to output parameter
5994 20:13:02.968  [4860] (ArchiveTask) <9348> EV:M MBXPERM::gimu[/o=nottingham city/ou=exchange administrative group (fydibohf23spdlt)/cn=recipients/cn=heather.ingham] - Initialised mailbox dn
5995 20:13:02.968  [4860] (ArchiveTask) <9348> EV:M EX2KMBXPERM::getaddn[/o=nottingham city/ou=exchange administrative group (fydibohf23spdlt)/cn=recipients/cn=heather.ingham] - Looking up user in Active Directory
5996 20:13:02.968  [4860] (ArchiveTask) <9348> EV:M SanitizeUserName() - Sanitized username '/o=nottingham city/ou=exchange administrative group (fydibohf23spdlt)/cn=recipients/cn=heather.ingham' to '/o=nottingham city/ou=exchange administrative group \28fydibohf23spdlt\29/cn=recipients/cn=heather.ingham'
5997 20:13:02.968  [4860] (ArchiveTask) <9348> EV:M FindUser() - Using searchbase GC://resadw2k31.nottinghamcity.gov.uk
5998 20:13:02.968  [4860] (ArchiveTask) <9348> EV:M FindUser() - Search filter: (&(objectCategory=user)(legacyExchangeDN=/o=nottingham city/ou=exchange administrative group \28fydibohf23spdlt\29/cn=recipients/cn=heather.ingham))
5999 20:13:02.968  [4860] (ArchiveTask) <9348> EV:M FindUser() - [homeMDB] = CN=Childrens Services Mailbox Database,CN=Childrens Services Storage Group,CN=InformationStore,CN=RESEXEVS1,CN=Servers,CN=Exchange Administrative Group (FYDIBOHF23SPDLT),CN=Administrative Groups,CN=Nottingham City,CN=Microsoft Exchange,CN=Services,CN=Configuration,DC=nottinghamcity,DC=gov,DC=uk
6000 20:13:02.968  [4860] (ArchiveTask) <9348> EV:M FindUser() - [distinguishedName] = CN=Heather Ingham,OU=Children and Families General Users,OU=Children and Families,OU=NCC,DC=nottinghamcity,DC=gov,DC=uk
6001 20:13:02.968  [4860] (ArchiveTask) <9348> EV:M EX2KMBXPERM::GMSD[/o=nottingham city/ou=exchange administrative group (fydibohf23spdlt)/cn=recipients/cn=heather.ingham] - Reading security descriptor from Active Directory
6002 20:13:02.968  [4860] (ArchiveTask) <9348> EV:M EX2KMBXPERM::RSDFAD[/o=nottingham city/ou=exchange administrative group (fydibohf23spdlt)/cn=recipients/cn=heather.ingham] - Bind to object: GC://resadw2k31.nottinghamcity.gov.uk/CN=Heather Ingham,OU=Children and Families General Users,OU=Children and Families,OU=NCC,DC=nottinghamcity,DC=gov,DC=uk
6003 20:13:02.968  [4860] (ArchiveTask) <9348> EV:M EX2KMBXPERM::RSDFAD[/o=nottingham city/ou=exchange administrative group (fydibohf23spdlt)/cn=recipients/cn=heather.ingham] - Reading msExchMailboxSecurityDescriptor
6004 20:13:02.968  [4860] (ArchiveTask) <9348> EV:M EX2KMBXPERM::RSDFAD[/o=nottingham city/ou=exchange administrative group (fydibohf23spdlt)/cn=recipients/cn=heather.ingham] - Checking objectClass
6005 20:13:02.968  [4860] (ArchiveTask) <9348> EV:M EX2KMBXPERM::RSDFAD[/o=nottingham city/ou=exchange administrative group (fydibohf23spdlt)/cn=recipients/cn=heather.ingham] - Allocating new object Sid
6006 20:13:02.968  [4860] (ArchiveTask) <9348> EV:M EX2KMBXPERM::RSDFAD[/o=nottingham city/ou=exchange administrative group (fydibohf23spdlt)/cn=recipients/cn=heather.ingham] - Allocate/Copy security descriptor
6007 20:13:02.968  [4860] (ArchiveTask) <9348> EV:M EX2KMBXPERM::USDWOS[CN=Heather Ingham,OU=Children and Families General Users,OU=Children and Families,OU=NCC,DC=nottinghamcity,DC=gov,DC=uk] - Entering Routine
6008 20:13:02.968  [4860] (ArchiveTask) <9348> EV:M EX2KMBXPERM::USDWOS[CN=Heather Ingham,OU=Children and Families General Users,OU=Children and Families,OU=NCC,DC=nottinghamcity,DC=gov,DC=uk] - Copying Security Descriptor to remove instances of NT_AUTHORITY\SELF: ACE Count = 25
6009 20:13:02.968  [4860] (ArchiveTask) <9348> EV:M EX2KMBXPERM::USDWOS[CN=Heather Ingham,OU=Children and Families General Users,OU=Children and Families,OU=NCC,DC=nottinghamcity,DC=gov,DC=uk] - Omitting SELF entry from Security Descriptor copy
6010 20:13:02.968  [4860] (ArchiveTask) <9348> EV:M EX2KMBXPERM::USDWOS[CN=Heather Ingham,OU=Children and Families General Users,OU=Children and Families,OU=NCC,DC=nottinghamcity,DC=gov,DC=uk] - Adding objectSid [S-1-5-21-3388933763-2387696048-3050347461-37442]
6011 20:13:02.968  [4860] (ArchiveTask) <9348> EV:M EX2KMBXPERM::USDWOS[CN=Heather Ingham,OU=Children and Families General Users,OU=Children and Families,OU=NCC,DC=nottinghamcity,DC=gov,DC=uk] - Saving updated Security Descriptor

Any suggestions on what to try that will resolve this?

Mark

[Arjun_Shelke]

Do you see any item in A4 queue? The MAPI account you referring I assume its EV System mailbox. As you changed it to new, did you grant Vault service account "Send as" permissions on it? Its more related to System mailbox or mailbox in migration phase.