Exchange 2010 DAG backup, logs not truncating

[smckelvey]

or at least only occasionally, with no way that's apparent to me to replicate for testing purposes. Occasionally they do or have truncated, but I can't find any rhyme or reason. We are just moving our 2007 environment to 2010, so we only have a handful of mailboxes in the 2010 environment. Which is why I'm trying to get all this problem resolved so that we can begin moving people over to 2010.

Right now for example, 1 of the databases has logs going back to the 2/13 at 9:01AM, even though I've run a successfull full backup many times.

Our configuration is as follows:

• We are NOT using Instant Recovery or GRT.
• Backups are successful with status of 0 (I'm doing "Full" backups for the purpose of testing log truncation)
• I've tried backing up both the Active and Passive nodes, and it doesn't seem to make a difference.
• In Exchange, Copy length and Queue length are 0
• I read stuff about a bug w/ the Indexing Service on Exchange: I stopped the Indexing Service on all of the DAG nodes. No change.
• We have a MAPI network and Replication network b/t the nodes. I turned off the Firewall on the Replication Network. No change.
• I've tried dismounting and remounting the database. And I ran ESEUTIL /MH and confirmed that it was clean.
• The Exchange logs indicate the backups were successful I always see the following two events: one which says they can't truncate (225), but the next says it will once replayed (9827)   

1. 2/14/2012 12:34:44 PM    MSExchangeIS    9827    Exchange VSS Writer
2. 2/14/2012 12:34:44 PM    ESE    225    ShadowCopy

• The other Event that is odd to me, but maybe it's just the way they read, are the MSExchangeRepl Event 4114. They indicate that the the logs are replicating and replaying, and that the backups are occuring, EXCEPT on the Active node, which doesn't indicate an accurate "Latest Full Backup" time; refer to the following.

Database redundancy health check passed.
Database copy: DAG4
Redundancy count: 3

Errors:


================
 Summary Status
================


Name                 Status RealCopyQueu InspectorQue  ReplayQueue      CIState
                                       e           ue                          
----                 ------ ------------ ------------  -----------      -------
DAG4\WTP-EX-M       Healthy            0            0            0      Healthy
B3                                                                             
DAG4\WTP-EX-M       Mounted            0            0            0      Healthy
B2                                                                             
DAG4\WTP-EX-M       Healthy            0            0            0      Healthy
B1


===============
 Full Status
===============



Identity                         : DAG4\WTP-EX-MB3
Name                             : DAG4\WTP-EX-MB3
DatabaseName                     : DAG4
Status                           : Healthy
MailboxServer                    : WTP-EX-MB3
ActiveDatabaseCopy               : wtp-ex-mb2
ActivationSuspended              : False
ActionInitiator                  : Administrator
ErrorMessage                     :
ErrorEventId                     :
ExtendedErrorInfo                :
SuspendComment                   :
SinglePageRestore                : 0
ContentIndexState                : Healthy
ContentIndexErrorMessage         :
CopyQueueLength                  : 0
ReplayQueueLength                : 0
LatestAvailableLogTime           : 2/15/2012 9:29:08 AM
LastCopyNotificationedLogTime    : 2/15/2012 9:29:08 AM
LastCopiedLogTime                : 2/15/2012 9:17:22 AM
LastInspectedLogTime             : 2/15/2012 9:17:22 AM
LastReplayedLogTime              : 2/15/2012 9:17:22 AM
LastLogGenerated                 : 944
LastLogCopyNotified              : 944
LastLogCopied                    : 944
LastLogInspected                 : 944
LastLogReplayed                  : 944
LogsReplayedSinceInstanceStart   : 13
LogsCopiedSinceInstanceStart     : 12
LatestFullBackupTime             : 2/14/2012 9:46:03 PM
LatestIncrementalBackupTime      : 2/15/2012 3:04:23 AM
LatestDifferentialBackupTime     :
LatestCopyBackupTime             :
SnapshotBackup                   : True
SnapshotLatestFullBackup         : True
SnapshotLatestIncrementalBackup  : True
SnapshotLatestDifferentialBackup :
SnapshotLatestCopyBackup         :
LogReplayQueueIncreasing         : False
LogCopyQueueIncreasing           : False
OutstandingDumpsterRequests      : {}
OutgoingConnections              :
IncomingLogCopyingNetwork        :
SeedingNetwork                   :
ActiveCopy                       : False

Identity                         : DAG4\WTP-EX-MB2
Name                             : DAG4\WTP-EX-MB2
DatabaseName                     : DAG4
Status                           : Mounted
MailboxServer                    : WTP-EX-MB2
ActiveDatabaseCopy               : wtp-ex-mb2
ActivationSuspended              : False
ActionInitiator                  : Service
ErrorMessage                     :
ErrorEventId                     :
ExtendedErrorInfo                :
SuspendComment                   :
SinglePageRestore                : 0
ContentIndexState                : Healthy
ContentIndexErrorMessage         :
CopyQueueLength                  : 0
ReplayQueueLength                : 0
LatestAvailableLogTime           :
LastCopyNotificationedLogTime    :
LastCopiedLogTime                :
LastInspectedLogTime             :
LastReplayedLogTime              :
LastLogGenerated                 : 0
LastLogCopyNotified              : 0
LastLogCopied                    : 0
LastLogInspected                 : 0
LastLogReplayed                  : 0
LogsReplayedSinceInstanceStart   : 0
LogsCopiedSinceInstanceStart     : 0
LatestFullBackupTime             :
LatestIncrementalBackupTime      :
LatestDifferentialBackupTime     :
LatestCopyBackupTime             :
SnapshotBackup                   :
SnapshotLatestFullBackup         :
SnapshotLatestIncrementalBackup  :
SnapshotLatestDifferentialBackup :
SnapshotLatestCopyBackup         :
LogReplayQueueIncreasing         : False
LogCopyQueueIncreasing           : False
OutstandingDumpsterRequests      : {}
OutgoingConnections              :
IncomingLogCopyingNetwork        :
SeedingNetwork                   :
ActiveCopy                       : True

Identity                         : DAG4\WTP-EX-MB1
Name                             : DAG4\WTP-EX-MB1
DatabaseName                     : DAG4
Status                           : Healthy
MailboxServer                    : WTP-EX-MB1
ActiveDatabaseCopy               : wtp-ex-mb2
ActivationSuspended              : False
ActionInitiator                  : Administrator
ErrorMessage                     :
ErrorEventId                     :
ExtendedErrorInfo                :
SuspendComment                   :
SinglePageRestore                : 0
ContentIndexState                : Healthy
ContentIndexErrorMessage         :
CopyQueueLength                  : 0
ReplayQueueLength                : 0
LatestAvailableLogTime           : 2/15/2012 9:29:08 AM
LastCopyNotificationedLogTime    : 2/15/2012 9:29:08 AM
LastCopiedLogTime                : 2/15/2012 9:17:22 AM
LastInspectedLogTime             : 2/15/2012 9:17:22 AM
LastReplayedLogTime              : 2/15/2012 9:17:22 AM
LastLogGenerated                 : 944
LastLogCopyNotified              : 944
LastLogCopied                    : 944
LastLogInspected                 : 944
LastLogReplayed                  : 944
LogsReplayedSinceInstanceStart   : 13
LogsCopiedSinceInstanceStart     : 12
LatestFullBackupTime             : 2/14/2012 9:46:03 PM
LatestIncrementalBackupTime      : 2/15/2012 3:04:23 AM
LatestDifferentialBackupTime     :
LatestCopyBackupTime             :
SnapshotBackup                   : True
SnapshotLatestFullBackup         : True
SnapshotLatestIncrementalBackup  : True
SnapshotLatestDifferentialBackup :
SnapshotLatestCopyBackup         :
LogReplayQueueIncreasing         : False
LogCopyQueueIncreasing           : False
OutstandingDumpsterRequests      : {}
OutgoingConnections              :
IncomingLogCopyingNetwork        :
SeedingNetwork                   :
ActiveCopy                       : False

 

[Mark_Solutions]

Thanks for the detailed description - but could I ask a couple more questions please:

1. What NBU version and patch level are you Master and Media Servers (include any EEBs applied

2. same question for the mailbox and CAS servers

Thanks

[smckelvey]

Netbackup is 7.1, Build 20110203, across the board. Master and media Servers are Windows server 2003. All are physical.

Exchange is 2010, Version: 14.02.0247.005, running on Windows Server 2008 R2 Enterprise x64 bit. All Physical servers.

[Mark_Solutions]

All actually looks good then,

I would suggest trying this with four policies, one for each database.

Doing it that way you will be able to see if a specific database is the issue to at least pin things down.

By having them in seperate policies as each completes successfully it will allow just the logs for that database to be truncated whereas in a single policy it will prevent all logs being truncated if any one fails.

Do bear in mind that after the truncate command has been passed to Exchange it can still be some hours before it actually truncates the logs

Try this and then lets see if we can tie down the issue

[smckelvey]

I am using one policy per Database.

[Marianne]

Important point in Mark's last post: the truncate command is passed to Exchange...

What happens is that NBU merely notifies Exchange that the backup was successful (status 0).
It is then up to Exchange to truncate the logs. NBU has no control or involvement in that process. This means that nothing will be logged in NBU logs. Not sure if Exchange will log truncate actions in Application log?

Extract from NBU for Exchange manual:

Exchange truncates all committed transaction logs after NetBackup notifies it that
the backup succeeded. In replicated environments, the truncation is scheduled and does
not occur immediately.

[smckelvey]

Unfortunately there's no concrete conclusion to the following thread,

https://www-secure.symantec.com/connect/forums/exchange-2010-sp1-and-nbu-70-logs-not-truncating

But, I'm pretty sure that what he is referring to is what we were mistaking for the logs not truncating.

Marianne, I was aware of all of that stuff (actually, mostly thanks to your other posts on this forum), but needed to cover all bases in case I was missing something on the Netbackup side.

Anyways, based on some research, the "checkpoint" matter seems to essentially keep a miniumum amount of logs. Because we are just moving to Exchange 2010 and had only moved a couple of mailboxes to begin testing, we weren't generating enough logs to determine whether truncation was happening after each backup. This helps explain our intermittent and seemingly inexplicable results. It wasn't so much about scheduling  or copy length etc.When it did truncate, it was pretty much right after a successful backup. And the logs seem to state pretty clearly when they will truncated, but they don't seem to indicate that they have truncated, or why they didn't.

After moving more users over to 2010 (generating more logs), it appears to me that logs are truncating just fine, regardless of whether we use the passive or active node to backup. If anything changes, I'll update this thread. Otherwise hopefully this helps someone down the road.

[smckelvey · Accepted solution]

Although the following thread was never concluded concretely in my opinion, I think this he/she describes what we were mistaking as a problem:

https://www-secure.symantec.com/connect/forums/exchange-2010-sp1-and-nbu-70-logs-not-truncating

After some more reading, the "Checkpoint" appears to essentially be a minimum number of logs that Exchange will retain. Since our 2010 environment was brand new and we'd only moved a couple of users to it, we weren't generating enough logs to reliably test truncation after each backup. This also explains the seemingly intermittent and odd numbers of truncated logs that we were seeing.

So, after moving some more users into the 2010 environment (which generated more logs), it appears to be working as described by the Checkpoint literature. Also, it appears to be working regardless of whether we backedup from the passive or active nodes. I'll update this thread if anything changes.