This one came to my attention this week. Customers testing our Software (Avamar 7.1) complained, Software would not Purge Exchange logs after ( Successful ) Backup.

So, first of all, no Software is Purging exchange Logs at any Time. Log Purging is handled by Exchange ( VSS-Writer ) itself.

When using VSS Framework, there are 4 Types of Backup:

  • Full
  • Incremental
  • Differential
  • Copy

where only Full and Incremental instruct the VSS Framework to initiate Purge upon Completion.

You can fin a very good description of the Backup Process in terms of VSS on MSDN : Types of backup operations for Exchange 2013

 

However, my Customer was testing Full Backups with Avamar in a Replicated environment. Circular logging was disabled.

After Sending a few mails, he was running a Backup. But no logs where purged. Why That he asked ? Must be a Avamar Bug.

 

No, it is not a Avamar Bug, it is y design. Exchange uses a so called Checkpoint Depth of 100MB. Since a Log File has 1024kb, after approx. 100 Logs, the Logs are Committed to the database and a new Sequence is created.

 

Tim McMichael  did a very good explanation on that Exchange 2010: Log Truncation and Checkpoint At Log Creation in a Database Availability Group - Tim McMichael - Site Hom…

Having that said, we do have to create at least 100 Logs before old logs can be purged ?!

before we Explain or verify some things, let´s fist have a look at the anatomy of an Exchange DAG backup from Passive Side:

 

Here is an Example vie of an Application Event log of the Passive DAG Node on wich a Backup is performed for Passive Node Backups. In our Case, the Passive Backup is taken on Node E2013N2:

 

 

The Exchange VSS Backup starts with event 960 From ESE Backup:

msexchangerepl (3528) This computer is performing a surrogate backup.  The master server is E2013N1.

In this case, e2013n1 received a Backup request and instructed the Replication Writer on E2013N2 to Prepare the Backup.

 

Now the Replication Writer Coordinates the VSS Snapshot Backup, Events 2025, 2027, 2029 and 2035:

 

The Microsoft Exchange Replication service VSS Writer (Instance 39fb75f0-7069-4a04-8ae3-55daa1f739d1) successfully prepared for a snapshot.

The Microsoft Exchange VSS Writer instance 39fb75f0-7069-4a04-8ae3-55daa1f739d1 has successfully frozen the databases.

The Microsoft Exchange VSS Writer instance 39fb75f0-7069-4a04-8ae3-55daa1f739d1 has successfully thawed the databases.

The Microsoft Exchange Replication service VSS Writer (Instance 39fb75f0-7069-4a04-8ae3-55daa1f739d1) has successfully processed the post-snapshot event.

At this point, the VSS Critical Part of the Backup his done.

Next, Backup Process starts the Consistency Check. In Memory of 2007, this is called "Storage Group Consistency Check" (RIP) :-)

We start with Event 100, the Initialization. At This Point the Snapshot Volumes are mounted ( event 100)

Instance 1: A physical consistency check has been successfully initiated. Database '\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy9\labbuildrDAG_DB1\labbuildrDAG_DB1.edb' and the transaction log files in '\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy10\labbuildrDAG_DB1\Log'  with a base name of 'E01' will be validated.

This is Followed by event 200 , which i normally monitor to get the current Log Sequence. This is similar to an eseutil /mh wich checks he database header.

Instance 1: Database headers have been successfully validated. All databases are in a dirty shutdown state. To bring these databases to a clean shutdown state, log generations 239 (0x000000ef) to 283 (0x0000011b) will be required.

 

Next on the menu is the logfile Integrity check. This is an Optional Step, and is controlled by the Backup requestor. We can set if and how to Process Log Check in our Requestors ( aka RM / AppSync or Networker NMM / Avamar )

In my Example i am using Avamar, so the Avexvss Requestor controls how to check and instructs the ESE. The check is similar to eseutil /ml

The events we look at are 102, 105 and 103:

avexvss (12948) Instance 1: Log File Integrity Check (\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy10\labbuildrDAG_DB1\Log\E01): The database engine (15.00.0995.0021) is starting a new instance (0).

 

avexvss (12948) Instance 1: Log File Integrity Check (\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy10\labbuildrDAG_DB1\Log\E01): The database engine started a new instance (0). (Time=0 seconds)

 

avexvss (12948) Instance 1: Log File Integrity Check (\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy10\labbuildrDAG_DB1\Log\E01): The database engine stopped the instance (0).

In Normal Cases where everything is fine, the Backup from the VSS Writer is considered successful.

Events are Storage group Event 300 and 400:

 

Instance 1: Transaction log files in '\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy10\labbuildrDAG_DB1\Log' with a base name of 'E01' have been successfully validated. No errors were detected.

 

Instance 1: The physical consistency check has completed successfully. All files were validated and no errors were detected.

 

The Backup Metadata is saved to an XML that get´s stored with the Backup itself and required for Exchange Restore.

(event  2021)

The Microsoft Exchange VSS Writer has successfully collected the metadata document in preparation for backup

The Backup data is transferred to the ackup Media..

The Backup the is finished with event 963.

msexchangerepl (3528) The surrogate backup procedure to E2013N1 has been successfully completed.

 

As i mentioned earlier, the Backup Software at no time is responsible for the Purging of the logs. This is completely handled By the Exchange Replication Service.  once the above tasks are done,  the Backup Information is tracked in the database. We can verify this with Exchange Powershell:

Get-MailboxDatabase -Status labbuildrdag_db1| fl *backup



Once that information is in the Database, the Exchange replication Service Sends the Purge Request.

The Purge/truncate depend´s on several tings, like checkpoint depth, replication health, lagged copy settings .

Event 2046 informs us about that outstanding request, which does not necessarily mean the are truncated immediately or in this sequence. It will be initiated after the next log generation, an the required log is copied:

The Microsoft Exchange Replication service VSS Writer instance 39fb75f0-7069-4a04-8ae3-55daa1f739d1 has successfully completed the backup of database 'labbuildrDAG_DB1'.

 

Database log truncation has been requested for this database. Log truncation will occur on the active copy after the next log generation is created. Log truncation will occur automatically on the passive copies after that log file is copied.

 

and 2114 and 2034 tell us the completion of the whole Process ( no logs might be purged at this time ! )

The replication instance for database labbuildrDAG_DB1 has started copying log files. The first log file copied was generation 285.

The Microsoft Exchange Replication service VSS Writer (Instance 39fb75f0-7069-4a04-8ae3-55daa1f739d1) has successfully

processed the backup completion event.

 

 

So, how can i test logs are Purged ? The answer is that simple: generate as much Mails you need to reach an new Checkpoint ( Checkpoint Depth is 100 ), or Shutdown the Database, that generates a new checkpoint as well.

Than run your backup an see logs get purged.

 

 

Here is a Simple test: i created a Distribution Group of 10 Users in a DAG. I Just send a log file, and do it 10 times to reach 100MB...

This will guarantee an new Checkpoint.

During that, i monitor event 200:

 

Get-EventLog -LogName Application -Source "Storage Group Consistency Check" -InstanceId 200 | fl Message



 

every single event 200 is within a full backup sequence

You can see with every backup, the logs required to recover the database get more over time

 

I also measure the amount of logfiles in the log directory

 

Get-ChildItem -Path P:\labbuildrDAG_DB1\Log\ -Filter *.log | where Name -NotMatch "tmp" | Measure-Object



 

 

I can see my logs filling up.

Once the Log sequence Changes in event 200, i can see the logs of n-1 getting deleted:

You can see in this example, there was a checkpoint between both sequences, shifting from 0EF to 110 in the Current sequence.

All n-1 log are deleted now.

 

Hopefully that helps to validate your Backup tests.

Conclusion: Do not Blame the backup Software if logs do not get Purged. Start sending emails and watch the Process !!!