Markus’ Messaging Blog

Ein grauer Tag im Leben eines Exchange Administrators:

Du kommst ungewohnt früh und nichts Böses ahnend morgens ins Office und noch vor dem ersten Kaffee bombardiert das Monitoring System Dein Postfach derart extrem, dass Du augenblicklich wach bist. Angeblich soll sich der Exchange Store des neuen Exchange 2007 CCR Clusters auf die Seite gelegt haben.
 
Toller Witz, denke ich! Ein Blick auf den Kalender bestätigt, dass heute nicht der 1. April ist und mit einem weiteren Blick in den Windows Cluster Administrator zeigt mir ein rotes Pfeil-Symbol frech-freundlich an, dass die Ressource “First Storage Group/Mailbox Database” offline ist.

Zeit ein paar Blicke in die Windows Eventlogs zu riskieren…

System Eventlog:

Event Type:    Warning
Event Source:    Srv
Event Category:    None
Event ID:    2013
Date:        21.09.2007
Time:        03:33:48
User:        N/A
Computer:    <ClusterNodeName>
Description:
The D: disk is at or near capacity.  You may need to delete some files.

Application Eventlog:

Event Type:    Error
Event Source:    ESE
Event Category:    Logging/Recovery
Event ID:    428
Date:        21.09.2007
Time:        03:36:34
User:        N/A
Computer:    <ClusterNodeName>
Description:
MSExchangeIS (3520) First Storage Group: The database engine is rejecting update operations due to low free disk space on the log disk.

Application Eventlog:

Event Type:    Error
Event Source:    MSExchangeIS
Event Category:    General
Event ID:    9559
Date:        21.09.2007
Time:        03:36:34
User:        N/A
Computer:    <ClusterNodeName>
Description:
The log disk is full for storage group “First Storage Group”. Attempting to unmount all databases in this storage group.

Application Eventlog:
Event Type:    Information
Event Source:    MSExchangeIS Mailbox Store
Event Category:    General
Event ID:    9539
Date:        21.09.2007
Time:        03:36:36
User:        N/A
Computer:    <ClusterNodeName>
Description:
The Microsoft Exchange Information Store database “First Storage Group\Mailbox Database” was stopped.

System Eventlog:
Event Type:    Error
Event Source:    ClusSvc
Event Category:    Failover Mgr
Event ID:    1069
Date:        21.09.2007
Time:        03:36:41
User:        N/A
Computer:    <ClusterNodeName>
Description:
Cluster resource ‘First Storage Group/Mailbox Database (<ServerName>)’ in Resource Group ‘<ResourceGroupName>’ failed.

Application Eventlog:
Event Type:    Error
Event Source:    MSExchangeIS
Event Category:    General
Event ID:    1004
Date:        21.09.2007
Time:        03:36:53
User:        N/A
Computer:    <ClusterNodeName>
Description:
Unable to start the Microsoft Exchange Information Store. Disk is full.

Schauen wir uns in einer tabellarischen Übersicht die Meldungen mal genauer an und analysieren, was genau geschehen ist…

Okay. Die Exchange Datenbank ist offline, weil die D: Platte vollgelaufen ist. Auf D: liegen die Exchange Transaktionsprotokolle (DB Logfiles). Vermutlich hat eine große Menge an DB Logfiles die Platte zum Überlaufen gebracht.

Die Vermutung bestätigt sich. Wir haben über 99.000 Logfiles (fast 100GB!) auf der Platte liegen und nur noch wenige Bytes frei. Einen Moment denke ich darüber nach, ob wir den Store wieder online bekommen, wenn wir den Cluster schwenken, was natürlich nicht funktioniert, denn im Exchange 2007 CCR Cluster sorgt der “Microsoft Exchange Replication Service” dafür, dass die Logfiles zeitnah auf den passiven Knoten kopiert werden. Gut, suchen wir also weiter nach dem Übel des Problems.

Ziel ist es jetzt die Logfiles zu bereinigen um Platz auf dem Laufwerk zu schaffen und dem Store die Möglichkeit zu geben wieder online zu kommen. Jeder Exchange Administrator hat in seinem ersten Exchange Kurs gelernt, dass die DB Logfiles durch eine erfolgreiche und fehlerfreie Exchange Online Datenbanksicherung bereinigt werden. Also starten wir eine solche in der Hoffnung, dass am Ende die Logs bereinigt werden.

Im Eventlog sind im Anschluss daran folgende Einträge zu sehen…

Application Eventlog:
Event Type:    Information
Event Source:    NTBackup
Event Category:    None
Event ID:    8000
Date:        21.09.2007
Time:        8:01:18
User:        N/A
Computer:    <ClusterNodeName>
Description:
Begin Backup of ‘<ServerName>\Microsoft Information Store\First Storage Group’

     Verify:  Off
     Mode:  Replace
     Type:  Normal

Application Eventlog:
Event Type:    Information
Event Source:    NTBackup
Event Category:    None
Event ID:    8001
Date:        21.09.2007
Time:        10:12:53
User:        N/A
Computer:    <ClusterNodeName>
Description:
End Backup of ‘<ServerName>\Microsoft Information Store\First Storage Group’ ‘
The operation was successfully completed.’

     Verify:  Off
     Mode:  Replace
     Type:  Normal
Consult the backup report for more details.

Soweit alles gut. NTBACKUP meldet “The operation was successfully completed.” Das ist ja erst mal schön. Jetzt staunen wir aber nicht schlecht, als wir sehen, dass keinerlei Logs bereinigt wurden. Irgendwas scheint zu verhindern, dass trotz des erfolgreichen Backups die Logs nicht bereinigt werden können.

Um nun die Exchange Datenbank wieder online zu bekommen verschiebe ich jetzt erst einmal einige der ältesten Exchange Protokolldateien in ein Verzeichnis auf einer anderen Platte. Jetzt haben wir wieder einiges an Platz und die Cluster Ressource “Mailbox Database” lässt sich wieder starten. Damit können die Benutzer erstmal wieder arbeiten.

Aufgrund der besonderen Brisanz der Situation, haben wir die folgenden Schritte gemeinsam mit MS PSS (Microsoft Product Support Services) durchgeführt.

Einen Blick ins Filesystem der beiden Cluster Nodes brachte die Erkenntnis, dass auf dem aktiven Knoten 99583 Protokolldateien und auf dem passiven 99588 vorhanden waren… ein Zustand, den ich bis heute nicht verstehe. Normalerweise sollte die Anzahl der Logfiles auf dem aktiven Knoten etwas höher sein und auf dem passiven Knoten geringer, da Exchange die Logs vom aktiven zum passiven Knoten nachführt. Wie auch immer.
Im Ordner “Inspector” finden wir das Logfile E000003A60B.log. Das letzte replizierte Logfile ist E000003A60A.log um 3:16 Uhr morgens. Damit ist klar, dass die CCR Replikation unterbrochen ist und nicht funktioniert.

Gemeinsam mit MS PSS diskutierten wir welche Gründe es geben kann, dass eine Bereinigung der Logfiles nicht funktioniert. Die folgenden beiden TechNet-Artikel geben Infos darüber, dass Exchange DB-Logs nicht bereinigt werden, wenn es Probleme mit der CCR Replikation gibt, oder wenn eine Logfile defekt ist:

http://technet.microsoft.com/en-us/library/bb123996.aspx
 
Note:

A common task during Exchange-aware backups is the truncation of transaction log files after the backup has completed successfully. The replication feature in CCR guarantees that logs that have not been replicated are not deleted. The implication of this behavior is that running backups in a mode that deletes logs may not actually free space if replication is sufficiently far behind in its log copying.

http://technet.microsoft.com/en-us/library/bb218100.aspx
 

Explanation:

This Error event indicates one of two possible events:

• As part of replication inspection, the Microsoft® Exchange Replication (MSExchangeRepl) service cannot remove a log file that failed inspection from the inspector directory.
• As part of replication startup, the replication service cannot clean out old unrelated log files that were in the middle of being copied and inspected during a previous replication session. This error will occur if either of the following conditions is true:
  • There is an I/O exception.
  • There are incorrect file permissions when the replication service tries to delete the log file.

Replication for the given storage group goes into a failed state when the error occurs. As soon as the error is resolved, replication resumes.

Damit wäre erklärt, dass der “Exchange Replication Service” dafür gesorgt hat, dass NTBACKUP dies Logfiles nicht bereinigen konnten, da ja die CCR Replikation der Logfiles unterbrochen war.

 
Folgender Aktionsplan wurde nun durchgeführt…

1.) Exchange Management Shell (Powershell) öffnen

2.) Ausführen des Befehls “Suspend-StorageGroupCopy” (Anhalten der “CCR Replikation”) mit entsprechenden Parametern…

Suspend-StorageGroupCopy “<CMS Name>\SG Name>”

3.) Auf dem passiven CCR Knoten alle Dateien im Ordner “First Storage Group” samt Unterordner löschen

4.) Ausführen des Befehls “update-StorageGroupCopy” mit entsprechenden Parametern in der PowerShell…

Update-StorageGroupCopy “<CMS Name>\SG Name>”

Dadurch wird ein so genanntes “CCR Reseeding” eingeleitet. Dabei wird die Mailbox Datenbank auf den passiven Knoten kopiert, was je nach Größe der Datenbank eine Weile dauern kann.

>>> SCREENSHOT FEHLT NOCH <<<

5.) Ausführen des Befehls “resume-StorageGroupCopy” mit entsprechenden Parametern in der PowerShell…

Resume-StorageGroupCopy “<CMS Name>\SG Name>”

Wenn dieser Vorgang abgeschlossen ist, werden die Exchange Transkationsprotokolle kopiert, was im Hintergrund und ohne Fortschrittsanzeige geschieht.

6.) NTBACKUP starten und eine vollständige Exchange Online Datenbanksicherung durchführen…

Jetzt macht es natürlich Sinn zu prüfen, ob das Backup fehlerfrei funktioniert hat und genau das überprüfen wir als nächstes.

Im Eventlog ist folgender Einträge zu sehen…

Application Eventlog:
Event Type:    Information
Event Source:    NTBackup
Event Category:    None
Event ID:    8001
Date:        21.09.2007
Time:        14:22:53
User:        N/A
Computer:    <ClusterNodeName>
Description:
End Backup of ‘<ServerName>\Microsoft Information Store\First Storage Group’ ‘
The operation was successfully completed.’

     Verify:  Off
     Mode:  Replace
     Type:  Normal
Consult the backup report for more details.

Application Eventlog:
Event Type:    Information
Event Source:    ESE BACKUP
Event Category:    General
Event ID:    916
Date:        21.09.2007
Time:        16:32:39
User:        N/A
Computer:    <ClusterNodeName>
Description:
Information Store (3952) Deleting log files D:\exchsrvr\mdbdata\Mailbox\First Storage Group\Exxxxxxxxxx.log to D:\exchsrvr\mdbdata\Mailbox\First Storage Group\Eyyyyyyyyyy.log.

Nach gut 2 Stunden bangen und hoffen hatten wir also nun die Gewissheit, dass das Backup erfolgreich durchgelaufen ist und die Logfiles erfolgreich bereinigt wurden.

 
Mein Fazit

Ein Exchange 2007 CCR Cluster ist ein geniales und fehlertolerantes System. Gefährlich wirds, wenn die CCR Replikation aus irgendeinem Grund unterbrochen ist, da dann unter Umständen ein Exchange Onlinebackup nicht mehr die Exchage Transaktionsprotokolle bereinigen kann.
In jedem Fall ist es bei einem Exchange 2007 CCR Cluster unabdingbar eine funktionierende Überwachung samt Alarmierung zu haben. Nichts ist schöner, als wenn der Admin frühzeitig weiß, dass mit der CCR Replikation etwas nicht stimmt und dann entsprechend handeln kann.

Über den Grund, warum in so kurzer Zeit so extrem viele Exchange Logs entstanden werde ich in Kürze hier im Blog in einem separaten Posting berichten. Es lohnt sich also von Zeit zu Zeit hier mal vorbei zu schauen, oder direkt den folgenden RSS-Feed zu abonieren um über neue Beiträge informiert zu werden…

RSS-Feed von Markus’ Messaging Blog

Links zum Thema

High Availability Cmdlets
http://technet.microsoft.com/en-us/library/bb124727.aspx

Planning for Cluster Continuous Replication
http://technet.microsoft.com/en-us/library/bb123996.aspx

Managing Cluster Continuous Replication
http://technet.microsoft.com/en-us/library/aa997676.aspx

The Microsoft Exchange Replication Service was unable to clean up an unneeded log file
http://technet.microsoft.com/en-us/library/bb218100.aspx

MSXFAQ: Exchange 2007 – Cluster Continuous Replication
http://www.msxfaq.de/e2007/ccr.htm

 
Keywords:  Exchange 2007 CCR Cluster Reseeding Microsoft Exchange Replication Service