EX522020 - Auswertung

Am 1 März 2023 gab es Probleme mit Exchange Online, dass einige Anwender anscheinend nicht ihr Postfach öffnen, konnten. Es gab aber noch andere Probleme, die Microsoft aber nicht erwähnt hat.

Auslöser

In meinem Fall hat ein Kunde sich beschwert, dass ein Angebot einer externen Firma nicht bei ihm und seinen Kollegen im Postfach angekommen ist. Die Mails sind aus dem Internet über einen Spamfilter bei einem Exchange Edge Server gelandet. Der Edge Server hat diese Mails dann zum internen Mailbox-Server gesendet. Da die Mailbox aber schon in Exchange Online lag, hat der Exchange Server die TargetAddress umgeschrieben und die Mail wieder über die Edge-Server mittels "Hybrid Bereitstellung" zum Exchange Online Server senden wollen. Bis zum eigenen Edge Server ist die Mail noch gelaufen aber dann wurde sie von Exchange Online abgelehnt. Das konnten wir per Powershell auf den Edge-Server auch recht schnell ermitteln, indem wir nach dem Absender und Empfänger gesucht haben:

Get-MessageTrackingLog `
   -Source smtp `
   -Start (get-date).adddays(-1) `
   -Recipients user@msxfaq.de `
   -Sender user@example.com
   -ResultSize unlimited 

Timestamp           EventId      Source Sender           Recipients                         MessageSubject
---------           -------      ------ ------           ----------                         --------------
01.03.2023 18:35:19 RECEIVE      SMTP   user@example.com {user@msxfaq.de}                   NonDeliverdM...
01.03.2023 18:35:20 SENDEXTERNAL SMTP   user@example.com {user@msxfaq.de}                   NonDeliverdM...
01.03.2023 18:35:25 RECEIVE      SMTP   user@example.com {user@msxfaq.mail.onmicrosoft.com} NonDeliverdM...
01.03.2023 18:35:25 FAIL         SMTP   user@example.com {user@msxfaq.mail.onmicrosoft.com} NonDeliverdM...

Die sehen gut die eingehende Mail, die zum internen Server geht und nach dem Rewrite des Empfängers auf dem Weg zu Office 365 ist und mit einem SMTP FAIL endet. Die FAIL-Meldung im Detail ist:

Timestamp               : 01.03.2023 18:45:20
ClientIp                : 10.11.1.104
ClientHostname          : EDGE1
ServerIp                : 104.47.51.202
ServerHostname          : msxfaq-mail-onmicrosoft-com.mail.protection.outlook.com
SourceContext           :
ConnectorId             : Outbound to Exchange Online
Source                  : SMTP
EventId                 : FAIL
InternalMessageId       : 35154733367520
MessageId               : <xxxxxxxxxx@mail.1und1.de>
NetworkMessageId        : aaffbba6-1234-1234-6789-1122337cb9c9
Recipients              : {user@msxfaq.mail.onmicrosoft.com}
RecipientStatus         : {[{LED=550 5.4.1 Recipient address rejected: Access denied. AS(123456789)
                          [AM7EUR03FT013.eop-EUR03.prod.protection.outlook.com 2023-03-01T17:45:25.406Z 08DB1A00F586E95
                          1]};{MSG=};{FQDN=msxfaq-mail-onmicrosoft-com.mail.protection.outlook.com};{IP=104.47.51.202
                          };{LRT=01.03.2023 17:45:25}]}
TotalBytes              : 14332
RecipientCount          : 1
RelatedRecipientAddress :
Reference               : {<12345678-1234-1234-1234-112233445566@edge1.msxfaq.de>}
MessageSubject          : NonDeliverMessageTest
Sender                  : user@example.com
ReturnPath              : user@example.com
Directionality          : Incoming
TenantId                :
OriginalClientIp        :
MessageInfo             : ........
MessageLatency          :
MessageLatencyType      : None
EventData               : ........
TransportTrafficType    : Email
SchemaVersion           : 15.01.2507.017

Ein Blick auf den RecipientStatus zeigt schön dass die Gegenseite ein Exchange Online Server ist und dieser die Mail mit einem "550 5.4.1 Recipient address rejected: Access denied" ablehnt. Das ist eine permanente Ablehnung und der lokale Exchange Edge Server verwirft die Mail und erstellt einen NDR an den Absender.

Soweit so gut, oder in dem Beispiel eher so schlecht, da die erwünschte und korrekte Mail nicht in das Exchange Online Postfach zugestellt wurde. Der Absender hat natürlich einen NDR bekommen aber nicht jeder Absender kann damit auch umgehen. Vor allem war nun die Frage wie schwerwiegend das Problem ist.

Meldung zu EX522020

Passend zum Zeitfenster haben wir auch eine Meldung im Exchange Admin Center gefunden:

Das passt natürlich genau auf diese Situation. Allerdings "hilft" das nun dem Kunden nicht wirklich weiter. Er wollte schon genauer wissen, in welchem Zeitraum das Problem vorlag und wie viele Mails betroffen waren. Microsoft hat den Zeitraum von 14:11 Uhr bis 21:57 Uhr und damit ca. 7h recht umfangreich angegeben.

Messagtracking einsammeln

In diesem Fall habe ich mir nur das Messagetracking des Edge-Servers angeschaut und die Mail der letzten 5 Tage erst einmal so analysiert und da ich weitere Analysen vorhabe, speichere die die Ergebnisse gleich in einer Variablen.

$track = Get-MessageTrackingLog `
             -Source SMTP `
             -Start (get-date).adddays(-5) `
             -ResultSize unlimited

Das kann auf einem aktiven Server durchaus auch etwas dauern und auch Speicher belegen. Wenn Sie wissen, nach was sie suchen, können Sie die Ausgabe auch per Pipeline oder Parameter vorab weiter filtern. Hier wollte ich aber die volle Daten und die ca. 800.000 SMTP-Events haben 2,3 GB Ram belegt.

Messagetracking auswerten

Die folgenden Analysen können Sie natürlich auch mit Excel oder PowerBi durchführen. Wobei Excel mit der schieren Menge an Zeilen überfordert sein dürfte. PowerShell hat aber den Vorteil, dass Sie all das auch automatisieren könnten.

Ein Grund bei bei den folgenden Auswertungen mit "Group-Object" immer schön ein "-NoElement" anzuhängen.

$track |Group-Object eventid -NoElement | ft -AutoSize

 Count Name
 ----- ----
417788 RECEIVE
417534 SENDEXTERNAL
    53 DEFER
  3227 FAIL

Sie sehen hier gut dass über die letzten 5 Tage auf dem Server weniger als 1% der Mails "Fail" waren und ganz viele Mails problemlos übertragen wurden. Vielleicht sollten wir die Werte doch mal auf die verschiedenen Tage umbrechen. Dazu filtere ich erst einmal nur auf die "Fail", da ich vielleicht noch weitere Auswertungen machen möchte.

$fails = $track | where {$_.Eventid -eq "FAIL"}

Damit ich nach dem Timestamp gruppieren kann, muss ich diesen erst umformatieren.

Ausgangswert : 27.02.2023 10:16:02
Zielwert     : 2023-02-27 10:16:02Z
Kürzen auf   : 2023-02-27 10

Das geht mit "Get-Date" und "tostring("u") relativ schnell. Wer mag kann die Ausgabe auch mit "yyyyMMdd:HH" formatieren. Sie sollte nur "sortierbar" sein

$fails `
|Group-Object `
     -property @{expression={(get-date $_.timestamp).tostring("u").substring(0,13)}} `
     -NoElement `
| sort name

Count Name
----- ----
    3 2023-02-27 10
    2 2023-02-27 11
    3 2023-02-27 12
    1 2023-02-27 13
.....
    4 2023-03-01 11
   16 2023-03-01 12
   16 2023-03-01 13
    8 2023-03-01 14
   12 2023-03-01 15
  292 2023-03-01 16
  594 2023-03-01 17
  743 2023-03-01 18
  708 2023-03-01 19
  243 2023-03-01 20
   75 2023-03-01 21
    1 2023-03-01 23
    2 2023-03-02 01
....
    4 2023-03-03 13
    4 2023-03-03 14
    2 2023-03-03 15
    2 2023-03-03 16
    1 2023-03-03 17

Hier ist dann sehr gut zu sehen, dass es einen deutlichen Berg gibt. Wenn Sie die Ausgabe in Excel farbig machen, dann sehen Sie das noch deutlicher

Bei dieser Umgebung war die Störung mit ca. 4-5 Stunden kürzer als die im Statusbericht gemeldeten 7h. Dennoch hat es allein auf diesem Server ca. 2655 Mails betroffen. Die Frage ist, wie viel Prozent das zu der Zeit waren. Ich filtere aus den 800.000 Elementen über 5 Tage die fraglichen Einträge heraus. Alternative könnte ich auch mit "Get-Messagetracking" und dem Start/End-Parameter den Zeitraum eingrenzen. Denken Sie bei großen Datenmengen aber daran:

$ausfall = $track `
         | where {`
                    ($_.timestamp -gt (get-date "2023-03-01 16:00:00Z")) `
               -and ($_.timestamp -lt (get-date "2023-03-01 22:00:00Z")) `
                 }

Das Ergebnis kann ich wieder gruppieren:

$ausfall |Group-Object eventid -NoElement

Count Name
----- ----
14986 RECEIVE
14777 SENDEXTERNAL
 2363 FAIL
    1 DEFER

Der "Fehler" von Microsoft war also kein 100% Ausfall sondern auf den ersten Blick vielleicht nur 13%, wen man die Summe von SendExternal und Fail als 100% ansetzt. Aber in dem Trace sind ja nicht nur Mails an Office 365 drin. Wir sollten schon eine Unterscheidung nach Connectoren vornehmen:

$ausfall |Group-Object connectorid -NoElement | ft -AutoSize

Count Name
----- ----
14988 edge1\Default internal receive connector edge1
 4886 EdgeSync - Inbound to msxfaq via NoSpamProxy
 5859 Edgesync - Outbound MSXFAQ to to Internet via NoSpamProxy
 6394 Outbound to Exchange Online

Hier sehen wir, dass zu Office 365 nur 6394 Mails gesendet wurden, während die Mehrzahl über den Edge zum/vom  Internet oder nach intern gesendet wurden. Also schauen wir uns die Mails zum Connector "Outbound to Exchange Online" mal genauer nach der EventID an:

$ausfall | where {$_.connectorid -eq "Outbound to Exchange Online"} |Group-Object eventid -NoElement

Count Name
----- ----
 4033 SENDEXTERNAL
 2360 FAIL
    1 DEFER

Nun haben wir die "richtige" Zahl. Microsoft hat in der Zeit also mehr als 1/3 der Mails abgelehnt, die eigentlich zugestellt werden sollten.

Beifang: Wenn ich 4033+2360 addiere und durch 4h teile, komme ich auf ca. 17 Mails/Minute.

Wenn wir nun noch etwas genauer den Recipientstatus anschauen wollen, dann sehen wir immer den gleichen Fehler:

($ausfall `
   | where {$_.connectorid -eq "Outbound to Exchange Online" `
       -and $_.eventid -eq "fail" `
        }`
   ).recipientstatus.substring(0,70) `
|Group-Object -NoElement `
| ft -AutoSize

Count Name
----- ----
 2612 [{LED=550 5.4.1 Recipient address rejected: Access denied. AS(20180628

SMTP 554 5.7.105 SenderFilterAgent

Bei der Analyse der NDRs hat mich auch der "Recipientstatus" interessiert. Welche anderen Häufungen gibt es noch und daher ist eine Gruppierung nach diesem Feld ein weiteren Ansatzpunkt für eine Mustererkennung. (Ich habe allerdings die Domainnamen durch eigene Domains ersetzt):

[PS] C:\>($fails).recipientstatus.substring(0,73) |Group-Object -NoElement | ft -AutoSize

Count Name
----- ----
   77 [{LED=554 5.6.1 E-Mail rejected because of Spam-Header to unlock goto htt
  483 [{LED=554 5.7.105 SenderFilterAgent; Sender denied as sender's email addr
    1 [{LED=501 5.1.3 Bad recipient address syntax};{MSG=};{FQDN=relay-eu01.hor
    1 [{LED=504 5.5.2 <vora.nach@gmailcom>: Recipient address rejected: n
    2 [{LED=504 5.5.2 <serviceaccount@orange>: Recipient address rejected: need
 2895 [{LED=550 5.4.1 Recipient address rejected: Access denied. AS(201806281)
    1 [{LED=504 5.5.2 <virname@domain>: Recipient address rejected:
    2 [{LED=504 5.5.2 <vorname.nachname@msxfaqde>: Recipient address reje
    1 [{LED=504 5.5.2 <info@stadt-hoevelhof-de>: Recipient address rejecte
    6 [{LED=504 5.5.2 <V1@Camera>: Recipient address rejected: need fully-quali
   19 [{LED=550 5.4.1 Recipient address rejected: Access denied. AS(201806281)}
    1 [{LED=504 5.5.2 <thomas.muster@intern-netatwork-se>: Recipient address rejected: ne

Es ist gut zu sehen, dass viele Fehler beim Anwender zu suchen sind, die einfach die SMTP-Adresse nicht richtig angegeben haben und damit korrekt und sollte keinen Administrator aufscheuchen. Die 2895 "Access denied"-Fehler kennen Sie ja schon aber die 483 Fehler mit der Meldung "554 5.7.105 SenderFilterAgent" habe mich neugierig gemacht. Die habe ich mir dann doch noch mal genauer angeschaut:

$senderfilteragent=$track | where {$_.recipientStatus[0].startswith("[{LED=554 5.7.105 SenderFilterAgent")}

Die Liste der Absender bilde ich hier nicht ab aber hat in den meisten Fällen auf "Spam" oder zumindest unerwünschte Absender hingewiesen.

Genau genommen könnten Sie diese NDRs zur Funktionskontrolle der "Blocked Sender List" zu prüfen.

Hellhörig sollten Sie werden, denn die geblockten Absender eigentliche interne Absender sind, z.B. Prozesse, Benachrichtigungen etc. und warum die Empfänger diese blockieren.

Interessant ist, dass ein 504 als "permanenter Fehler" dem Absender aktiv mitteilt, dass der Empfänger diese Mail nicht erhalten will.

SMTP 550 ignorieren?

Der EX522020 war ein bekannter Ausfall aber nicht der erste Fall und wird auch nicht die letzte Exchange Online Störung sein. Die Frage stellt sich, wie Sie damit zukünftig umgehen. Bei diesem Ausfall hat Microsoft den permanenten Fehler 550 ausgeliefert, der dem einliefernden Mailserver signalisiert, dass die Mail nie ankommen wird.

Es wäre schöber gewesen, wenn Microsoft bei einem Fehler oder Problem einen temporären SMTP-Fehler liefert, z.B.

421 Temporary System Problem. Try again later.

Dann hätte der lokale Edge-Server die Mail zurückgestellt und einfach später wieder gemeldet. Insofern ist es schon erstaunlich, dass der Fehler zu einem 550 durchgeschlagen hat.

Solche Fehler können aber immer wieder passieren und vielleicht ist es eine gute Idee, wenn man der Antwort der anderen Seite nicht blind vertraut, sondern bei einem 5xx-Fehler vielleicht doch die Mail erst mal zurückstellen und es nach einigen Stunden wieder versuchen. Dann wären zumindest Verluste oder manuelle Eingriffe des Absender nicht erforderlich. Allerdings würde dies auch bedeuten, dass einige Mailserver entsprechende Platz zum Zwischenspeichern brauchen.

SMTP 452 4.3.1 Insufficient system resources

Bei der Analyse des EX522020 sind mir noch die DEFER-Meldungen aufgefallen. Auch diese habe ich mir genauer angeschaut und die 57 Meldungen verteilen sich wie folgt::

$defers = $track | where {$_.Eventid -eq "DEFER"}
$defers | %{$($_.recipientstatus.substring(6,40))"} |Group-Object -noelement

Count Name
----- ----
   35 452 4.3.1 Insufficient system resources
   20 451 4.4.3 Temporary server error. Please
    2 451 4.4.28 Message failed to be replicat

Ein 4xx-Fehler sagt dem Absendersystem, dass er es später noch einmal versuchen soll, weil der Server gerade unpässlich ist. Die Meldungen von Exchange Online sind aber nicht besonders gehäuft sondern immer mal wieder vor. Es kann ja durchaus sein, dass ein Server gerade "gestresst" wurde und damit auch normale legitime Verbindungen erst einmal abgeleht werden. Der Absender versucht es einige Minuten später wieder und landen vermutlich auch auf einem anderen Server. Insofern sind diese Meldungen nicht kritisch.

Monitoring

Die Analyse des EX5222020 hat aber auch wieder gezeigt, die nützlich oder sogar erforderlich eine Überwachung der SMTP-Übertragungen ist. Sie liefern einmal Grundlagen für das Sizing der nächsten Server aber können als Frühwarnsysteme bei anstehenden Problemen sein. Auch Microsoft hat hier wohl noch Verbesserungspotential, wenn die Zunahme der 550-Meldungen ist sicher nicht unbeobachtet geblieben. Das sollten Sie aber auch bei sich umsetzen und z.B. alle 5 Minuten aus dem Messagtracking ein paar Kennzahlen zu ermitteln, z.B. die Anzahl der gesamt übertragenen Mails und der fehlerhaften Mails. Die Fehler können Sie auch noch nach dem Einzelcode aufschlüsseln und damit Veränderungen schnell erkennen:

Get-Messsagetracking `
   -Eventid "FAIL" `
   -source "SMTP" -Start (get-datei)-addminutes(-5) `
| Group-Object `
   -property @{expression={$_.Recipientstate.substring(6,70)}} `

Sie erhalten so die Fehler der letzten 5 Minuten nach dem Fehlercode und können diese Werte z.B. zu PRTG oder einer anderen Lösung weiterleiten. Wer es perfekter machen möchte, kann dies noch nach dem Connector aufschlüsseln. Wem absolute Zahlen nicht gefallen, kann die erfolgreichen Übertragungen mit erfassen und dann prozentuale Verteilungen ermitteln. Exchange stellt die Meldungen sogar selbst als Performance Counter bereit.

Die Werte sind aber über die letzte Stunde ermittelt und steigen bei einem Fehler damit verzögert an. Zudem ist keine Unterscheidung nach Connector möglich.

Wichtig ist nur, dass Sie es tun und erfassen.

Ihr Ausfall

Wenn sie diese Seite noch vor dem 31. März 2022 lesen und ihr Exchange Server per Default die Daten für 30 Tage vorhält, dann nutzen Sie doch einfach mal folgenden Code, um den Einfluss auf ihr System zu ermitteln.

Dies funktioniert nur, wenn Sie die Mail über einen eigenen Server zu Exchange Online Senden. Wenn ihr MX-Record direkt zur Cloud geht, dann können Sie diesen Report nicht ausführen.

Das Skript hilft holt die Details des 1. Mail 2023 und gruppiert die Anzahl der Fails in Stundenintervallen. Sie sollten danach 24 Zeilen mit den Fails pro Stunde sehen.

Get-MessageTrackingLog `
   -EventId fail `
   -Source smtp `
   -Start (get-date "2023-03-01 00:00:00Z")) `
   -End   (get-date "2023-03-02 00:00:00Z")) `
   -ResultSize unlimited `
| Group-Object `
   -property @{expression={(get-date $_.timestamputc).tostring("u").substring(0,13)}} `
   -NoElement `
| sort name

Wenn Sie dann noch die betroffenen Mails sehen wollen, lassen Sie das "Group-Object" einfach weg und exportieren die Daten in eine CSV-Datei, z.B:

Get-MessageTrackingLog `
   -EventId fail `
   -Source smtp `
   -Start (get-date "2023-03-01 00:00:00Z")) `
   -End   (get-date "2023-03-02 00:00:00Z")) `
   -ResultSize unlimited `
| select `
    timestamp, `
    @{label='TimestampUTC';expression={(get-date $_.timestamp).tostring(“u”)}}, `
    sender, `
    @{label='Recipient1';expression={($_.Recipients[0])}}, `
    Recipientcount, `
    messagesubject, `
    Directionality, `
    ConnectorID, `
    Serverip, `
    @{label='RecipientStatus1';expression={($_.RecipientStatus[0])}} `
| Export-Csv .\failed.csv

MS Monitoring

Microsoft sammelt natürlich auch Kennzahlen und viele Administratoren kennen vielleicht noch gar nicht das Portal im Microsoft 365 Center zu den Diensten. Schon der Bericht zu Exchange auf https://admin.microsoft.com/Adminportal/Home#/servicehealth/exchangemonitoring ist sehr aufschlussreich:

Diese detaillierte Ansicht bekommen Sie nur, wenn Sie in der Summe mehr als 5000 Office 365 E3/E5 oder Microsoft E3/E5-Lizenzen haben.

Das Bild zeigt leider nicht den Status während der Störung.


Quelle: https://admin.microsoft.com/Adminportal/Home#/servicehealth/exchangemonitoring

Die Daten können auch per Graph abgerufen werden. Sie brauchen nur einen User oder besser eine Application mit dem Recht "ServiceHealth.Read.All".

Zusammenfassung

Der Ausfall am 1. März 2023, den Microsoft als EX522020 beschrieben hat, dürfte einige Kunden erwischt haben und es wurden auch Mails nicht zugestellt. Allerdings sollte dass nicht unbemerkt geblieben sein, denn die Absender haben einen NDR bekommen. In keinem der analysierten Fällen wurde eine Mail an Exchange Online zugestellt und danach unterdrückt. Dennoch war es natürlich unschön, dass Absender auf ihre Geschäftspost eine Unzustellbarkeit bekommen haben. Nicht alle Anwender können damit um gehen aber insbesondere automatisierte Dienste ignorieren gerne solche NDRs und die Mail bleibt verschwunden. Das ist insbesondere bei M2M-Kommunikationen ein Thema und zeigt, wie wichtig gerade hier eine Behandlung von Verlusten auf dem Übertragungsweg ist. Wer schon keine NDRs überwacht, sollte dem Empfänger z.B.: über eine Sequencenummer eine Verlustanalyse erlauben. Da auch immer mehr Angebote, Flugticket, Fahrscheine, Rechnungen aber auch Einmalkennworte und andere Belege per Mail versendet werden, ist so ein Verlust natürlich extrem störend.

Dennoch kann und wird dies immer wieder passieren. Auch Zustellfahrzeuge von Paketdiensten werden überfallen oder in Unfälle verwickelt und wir kennen alle die Geschichten, dass auch Postkarten, Briefe und Gepäckstücke nicht oder verspätet ankommen.

Wir können aber unsere Überwachung verbessern, um auf zukünftige Probleme besser und schneller reagieren zu können.

Weitere Links