Samstag, 23. Mai 2020
Seit 2012 bin ich glücklicher Kunde von Cyon, eines schweizerischen Hosting-Anbieters. In den letzten drei Wochen hat sich das Erlebnis etwas getrübt.
Wichtig: Die unten beschriebene Problematik hatte ich in den letzten acht Jahren nie, und schon gar nicht innerhalb von drei Wochen zwei Mal. imapfilter hat bisher auch immer reibungslos funktioniert.
Das erste Problem
Am Morgen des Samstag, 9. Mai 2020 konnte ich plötzlich nicht mehr auf meine E-Mails in der INBOX von Konto A zugreifen. Weder in Apple Mail (meinem hauptsächlichen E-Mail-Client), noch über RainLoop (Webmail), noch mit imapfilter, welches ich verwende, um E-Mails automatisiert in Unterordner zu verschieben (oder im Falle von Spam: zu löschen).
Das alle 5 Minuten laufende imapfilter, gepaart mit Healthchecks, ist übrigens auch ein optimales „Frühwarnsystem“, welches mir meldet, wenn mit dem Mailserver etwas nicht stimmt.
Das Log von RainLoop (unter RAINLOOPROOT/data/_data_/_default_/logs) zeigte den Fehler schön auf:
...
[08:55:36.698][1c50d1ff] IMAP[DATA]: > TAG3 SELECT "INBOX"\r\n
[08:55:36.960][1c50d1ff] IMAP[ERROR]: Stream Meta: Array
...
[08:55:36.961][1c50d1ff] IMAP[ERROR]: MailSo\Net\Exceptions\SocketReadException: MailSo-Net-Exceptions-SocketReadException (NetClient.php ~ 523) in %PATH%/rainloop/v/0.0.0/app/libraries/MailSo/Net/NetClient.php:523
Stack trace:
...
Und so sah das Symptom bei imapfilter aus:
...
Sat May 9 10:41:38 2020: reading data through SSL; the connection has been closed cleanly
...
Diese Meldung wurde in einer Schleife ausgegeben, und zwar bei jedem Befehl, der E-Mails filtern und — falls vorhanden — verschieben sollte.
Als ich imapfilter im Debug-Modus laufen liess …
$ imapfilter -v -l log.txt -d debug.txt recipe.imapfilter
… tauchte folgende erhellende Nachricht im Debug Log (debug.txt) auf:
IMAP (5): 107C NO [UNAVAILABLE] Maximum number of connections from user+IP exceeded (mail_max_userip_connections=75)
Weil die IMAP-INBOX nicht abrufbar war, steckten meine Scripts in Endlosschleifen fest, welche die Zahl der Verbindungen pro E-Mail-Konto und IP voll ausschöpfte. Es waren also keine Verbindungen mehr möglich.
Als erstes schaltete ich deshalb den imapfilter-Cronjob ab, um dem IMAP-Server eine Verschnaufspause zu gönnen. Dann wurde rasch klar, dass die E-Mails in der INBOX aus irgendeinem Grund nicht aufgelistet werden konnten. Ich hatte in den zwei Tagen zuvor einige Anpassungen am imapfilter-Konfiguration vorgenommen; eine Möglichkeit war, dass die Verschiebeaktionen dabei zu einer korrupten INBOX-Datei geführt haben könnten.
Obwohl das Problem an einem Wochenende auftrat, schrieb ich dem Support — wohlwissentlich, dass ich erst am Montag eine Antwort erhalten würde. Vielleicht würde ja trotzdem eine gute Seele reinschauen … leider nein, The Computer Says No.
Ich kämpfte deshalb auf eigener Faust weiter: Nach viel Pröbeln wählte ich die Holzhammer-Methode: Nach einem lokalen Backup des kaputten Dovecot-Verzeichnisses löschte ich via SSH alle Dateien im INBOX-Verzeichnis (Pfad: siehe unten), ein frischer Start, sozusagen. Seither funktioniert die INBOX wieder.
Glück im Unglück: Da ich bei Konto A versuche, Inbox Zero anzuwenden, waren nur vier E-Mails von der Löschaktion betroffen, von denen ich die von Apple Mail lokal gespeicherten .emlx an einen sicheren Ort kopieren konnte.
Das zweite Problem
Kurz nach Mitternacht in der Nacht von Donnerstag auf Freitag, 22. Mai 2020 traten gemäss imapfilter Probleme mit Konto B auf. Ich merkte dieses am späteren Freitag-Morgen, als ich mit meinen Mail-Clients nicht mehr auf meine E-Mails in der INBOX von Konto B zugreifen konnte. Dieses Mal gab es aber keine Überlastung der erlaubten Verbindungen. imapfilter meldete bei Abfragen auf die INBOX:
...
Fri May 22 14:47:16 2020: IMAP (5): 127C NO [SERVERBUG] Internal error occurred. Refer to server log for more information. [2020-05-22 14:47:16] (0.040 + 0.000 + 0.039 secs).
...
Ohne Zugriff auf die Logs konnte ich „SERVERBUG“ nicht weiter eingrenzen. Erneut schrieb ich eine E-Mail an den Support (Versand um 15:19 Uhr), und erhielt um 16:57 Uhr eine Antwort. Leider in der Form „Have you tried turning it off and on again?“. Die Hoffnung war verloren, dass mir Cyon noch vor dem Wochenende beim Debugging helfen konnte — somit sah ich ca. 56 Stunden ohne E-Mail entgegen.
Hilfreich war in der ersten Antwort des Supporters einzig der Tipp, anstelle von RainLoop doch bitte das „offizielle“ Webmail von Cyon zu verwenden: webmail.cyon.ch, welches auf RoundCube basiert. Gesagt, getan. So konnte ich dem Supporter klipp und klar belegen, dass das Problem auf der Serverseite lag. Wenn ich die INBOX anwählte, erschien am unteren Bildschirmrand ganz in rot folgende Fehlermeldung:
Serverfehler: UID SORT: Internal error occurred. Refer to server log for more information. [2020-05-22 17:59:38] (0.041 + 0.000 + 0.040 secs)
Leider gab es seither keine Antwort mehr, weshalb ich mir erneut selber helfen musste (wieso passieren diese Fehler immer auf’s Wochnenende hin?!)
Das Problem war dieses Mal etwas anderer Natur — Apple Mail und imapfilter zeigten partout keine E-Mails mehr in der INBOX an; die Unterordner konnten hingegen abgerufen werden. RoundCube hingegen zeigte die INBOX etwas erratisch manchmal an, manchmal nicht.
Die schlussendliche Lösung:
Epilog
Ohne Zugriff auf die IMAP-Logs ist mir aber weiterhin nicht möglich herauszufinden, was denn nun wirklich genau das Problem war. Und so besteht zu befürchten, dass das Problem jede Minute erneut auftreten kann.
Und nein, ich gebe nicht Cyon die Schuld: Es könnte sein, dass mein spezielles Setup mit 5-minütigen imapfilter-Verbindungen die Ursache hinter den Problemen ist. Bspw. eine Anpassung, welche tausende E-Mails verschiebt und der Mailserver noch am kopieren ist, wenn der nächste imapfilter-Prozess bereits wieder startet und gerade in Kopie befindliche E-Mails irgendwohin kopiert. Oder ein Software-Update meiner Debian-Systeme in den letzten drei Wochen.
Es könnte aber auch sein, dass der Fehler bei Cyon zu suchen ist — d.h. ein kaputter RAM-Baustein, der beim Schreiben IMAP-Ordnerdateien korrumpiert, oder das Storage-System, welches zu schreibende Daten verfälscht, oder ein Update von Dovecot, nach welchem sich die Software nicht mehr wie gewohnt verhält. Oder eine Inkompatibilität zwischen der neuen Dovecot-Version mit dem bisherigen imapfilter; oder mit dem neuen imapfilter und der bisherigen Dovecot-Version.
Cyons E-Mail-Infrastruktur
Was ich bei diesen Problemen über Cyons E-Mail-Infrastruktur gelernt habe:
- Cyon verwendet Dovecot als IMAP-Server
- Ist man per SSH auf dem Cyon-Server eingeloggt, kann man sich die (eigenen) laufenden IMAP-Server-Prozesse mit folgendem Befehl anzeigen lassen. Die Zahl der Prozesse ist meines Erachtens proportional zur Anzahl der Clients, die gerade per IMAP E-Mails abfragen (mindestens 1 Prozess, es können aber durchaus auch mehrere pro Client sein).
$ ps ax | grep -i dovecot
3662642 ? S 0:00 dovecot/imap
3662645 ? S 0:01 dovecot/imap
3662646 ? S 0:00 dovecot/imap
3662706 ? S 0:00 dovecot/imap
3663038 ? S 0:00 dovecot/imap
3664246 ? S 0:00 dovecot/imap
3674314 ? S 0:00 dovecot/imap
3674316 ? S 0:00 dovecot/imap
3674317 ? S 0:00 dovecot/imap
3674449 ? S 0:00 dovecot/imap
- Die Mail-Daten eines Benutzers liegen in einer Ordnerstruktur unter /userdata01/%CYONUSER%/mail
- Die Mail-Ordner einer E-Mailadresse %EMAILUSER%@%DOMAIN% finden sich unter /userdata01/%CYONUSER%/mail/%DOMAIN%/%EMAILUSER%/mailboxes
- In einem Mail-Ordner finden sich normalerweise folgende Dateien:
drwxr-x--x 2 user user 158 May 23 17:02 ./
drwxr-x--x 3 user user 32 May 23 16:43 ../
-rw-r----- 1 user user 15024 May 23 16:41 dovecot.index
-rw-r----- 1 user user 15024 May 23 16:41 dovecot.index.backup
-rw-r----- 1 user user 391208 May 23 17:34 dovecot.index.cache
-rw-r----- 1 user user 2144 May 23 17:02 dovecot.index.log
-rw-r----- 1 user user 32928 May 23 16:41 dovecot.index.log.2
- Löscht man die Cache-Datei dovecot.cache in einem Mailordner (kann mehrere hundert Megabytes oder sogar Gigabytes gross sein), wird diese von Dovecot nicht automatisch neu generiert. Nichts geht mehr; d.h. der Ordner wird als leer angezeigt.
- Löscht man die Index-Datei dovecot.index, wird diese von Dovecot automatisch neu generiert. Beim zweiten Problem half dies tatsächlich, dass ich wieder Zugriff auf E-Mails erhielt.
