Juni 2019, der Monat, als es begann.
replicator: Panic: data stack: Out of memory when allocating 4294967336 bytes
Erste Reaktion: Verdammt, mein Mailserver stirbt, wenn Mails ankommen!
Zweite Reaktion: Brauche ich mehr RAM? --> nein!
Im folgenden eine etwas vereinfachte Darstellung meine Handlungen auf diesen Fehler, welche sich über mehrere Monate erstreckten.
2-Knoten Mailserver Cluster mit Exim4 und Dovecot in einer Master-Master Konfiguration.
Dovecot Version und Konfiguration sind auf beiden Nodes prinzipiell gleich.
Verbindung der Knoten per wireguard VPN Tunnel.
Netzwerkgeschwindigkeit zwischen den Knoten: ca. 1 Gigabit
Dovecot Replication funktioniert solange, bis eine neue Mail ankommt.
Danach Panic und Backtrace!
Neustart des Replicator Prozesses.
Sync funktioniert! (kurz)
Hier die komplette Fehlermeldung aus /var/log/dovecot.log
Oct 19 10:16:10 replicator: Panic: data stack: Out of memory when allocating 4294967336 bytes
Oct 19 10:16:10 replicator: Error: Raw backtrace: /usr/lib/dovecot/libdovecot.so.0(+0xe5c31) [0x7f75d78abc31] -> /usr/lib/dovecot/libdovecot.so.0(+0xe5cd1) [0x7f75d78abcd1] -> /usr/lib/dovecot/libdovecot.so.0(i_fatal+0) [0x7f75d7803103] -> /usr/lib/dovecot/libdovecot.so.0(t_pop_last_unsafe+0) [0x7f75d78a7a90] -> /usr/lib/dovecot/libdovecot.so.0(+0xe1ebb) [0x7f75d78a7ebb] -> /usr/lib/dovecot/libdovecot.so.0(+0x109b28) [0x7f75d78cfb28] -> /usr/lib/dovecot/libdovecot.so.0(+0xdd951) [0x7f75d78a3951] -> /usr/lib/dovecot/libdovecot.so.0(buffer_write+0xac) [0x7f75d78a3c9c] -> dovecot/replicator(replicator_queue_push+0x16e) [0x55614c8147ee] -> dovecot/replicator(+0x4deb) [0x55614c813deb] -> dovecot/replicator(+0x431e) [0x55614c81331e] -> dovecot/replicator(+0x4536) [0x55614c813536] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_call_io+0x75) [0x7f75d78c5845] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0x11b) [0x7f75d78c725b] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0x59) [0x7f75d78c5959] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_run+0x38) [0x7f75d78c5b68] -> /usr/lib/dovecot/libdovecot.so.0(master_service_run+0x13) [0x7f75d7832fe3] -> dovecot/replicator(main+0x1b7) [0x55614c812537] -> /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xe7) [0x7f75d73f6b97] -> dovecot/replicator(_start+0x2a) [0x55614c8125ea]
Oct 19 10:16:11 replicator: Fatal: master: service(replicator): child 8009 killed with signal 6 (core dumped)
Beim Lesen von "Panic: data stack: Out of memory when allocating 4294967336 bytes", war mein Gedanke: Wieso braucht der 4 GB Arbeitsspeicher?
Meine Mailbox war ca. 1.2GB groß und enthielt zu diesem Zeitpunkt ca. 15000 Nachrichten.
Die Größe der ankommenden Nachricht spielte keine Rolle, der Replicator lief in den Fehler, ist gestorben und wurde neu gestartet.
Bei jeder ankommenden Mail. Doof, bei einem Mailserver.
Immerhin wurden die Mails nach dem Replicator Neustart auf den jeweils anderen Knoten synchronisiert.
Zudem tauchte Anfangs auf dem jeweils anderen Knoten folgende Fehlermeldung zur gleichen Zeit auf:
Oct 19 10:16:12 dsync-local(user@example.com)<eRBgAkzGql3ACgAAbI4cUw>: Error: dsync(192.168.2.2:2727): I/O has stalled, no activity for 600 seconds (version not received)
Oct 19 10:16:12 dsync-local(user@example.com)<eRBgAkzGql3ACgAAbI4cUw>: Error: Timeout during state=master_recv_handshake
Vielleicht ein IO Problem mit dem Netzwerk oder den (leider sehr langsamen) Festplatten?
Durch zuweisen von mehr RAM und SWAP konnte ich eine relativ sichere Aussage darüber treffen, dass die Ursache des Problems nicht zu wenig Arbeitsspeicher ist.
Dovecot Downgrade von 2.3.8 zu 2.3.7
Dovecot Downgrade von 2.3.7 zu 2.2.33
Dovecot Upgrade auf die aktuellste Version von 2.3.9
Der Fehler ist leider in jeder dieser Versionen aufgetreten. Ein Wechsel der Versionen war somit nicht die Ursache für den Fehler.
Es blieben noch 3 Möglichkeiten, die den Betrieb von Dovecot zum Negativen beeinflusst haben könnten. Doch keine davon hatte auch nur annähernd etwas mit der Fehlermeldung zu tun.
Finde die Nadel im Heu-Haufen!
Da die Konten über wireguard verbunden sind und sich meine Netzwerk-Künste in Grenzen halten, galt für mich die Möglichkeit, dass vielleicht etwas mit der Netzwerkverbindung nicht stimmt.
iperf hier, iperf dort ... ein wenig netstat ... nein, es kann nicht am Netzwerk liegen! Das läuft und ist stabil.
Nach dem Aufbau des Kontakts mit "Dovecotianern" in deren IRC Channel (#dovecot im Freenode Netzwerk), wurde mir empfohlen Core Dumps zu aktivieren, um herauszufinden, welches Problem bei dem Prozess der dovecot Replikation auftrat.
Falls mein Vorgehen für irgendjemanden von Interesse sein sollte, möchte ich diesem meine (leider sehr dürftig ausgefallenen) Notizen nicht vorenthalten:
apt install dovecot-dbg
mkdir /var/core
chmod 0777 /var/core
sysctl kernel.core_pattern=/var/core/core.%e.%p
> reproduce the problem
gdb /usr/local/libexec/dovecot/replicator /usr/local/var/run/dovecot/core
bt full
Eine entsprechende Informationsseite dazu gibt es unter: https://www.dovecot.org/bugreport-mail
#VielAufwand->KeinErgebnis!
Arbeitsthese: Es muss ein IO Problem sein! Wie kann ich das testen?
Wenige Tage später wurde der zweite Mailserver Knoten auf eine neue virtuelle Maschine mit SSD Storage migriert. (War sowieso mal an der Zeit.)
Ergebnis: Es liegt nicht an der (bei mir) sehr langsamen Platten IO!! Das Problem tritt weiterhin auf.
Was bleibt, ist die dovecot Konfiguration.
Im Nachhinein betrachtet hätte ich diesen Versuch auch etwas früher anstellen können, wo er doch letztlich zum Erfolg geführt hat. Wer jedoch die verteilten Konfigurationen von dovecot kennt, kann sicher nachvollziehen, dass es kein wirklicher Spaß ist, sich mit diesen intensiv auseinander zu setzen.
Somit zog ich es vor, zuerst nur einen Teil zu prüfen und musste feststellen, dass der Teil zur Replikation, anhand der offiziellen Dokumentation, bereits "optimiert" war.
Da sich, wie zu erwarten, kein Erfolg einsetzte, blieb nicht anderes, als die komplette Konfiguration ein mal neu, sauber und ordentlich zu schreiben und alle Parameter zu entfernen, welche ich nicht nachvollziehen konnte.
Mein Fleiß wurde belohnt, Fehler gefunden!
Auszug der offiziellen Dokumentation: (https://wiki.dovecot.org/Replication)
> Normally all replication is asynchronous. You can also optionally configure new mail saving to be synchronous, with a timeout to avoid waiting too long. This can be configured with:
plugin {
# When saving a new mail via IMAP or delivering a mail via LDA/LMTP,
# wait for the mail to be synced to the remote site. If it doesn't finish
# in 2 seconds, return success anyway.
replication_sync_timeout = 2s
}
Letztendlich lief aller Aufwand auf einen Parameter hinaus: replication_sync_timeout = 2s
Entfernen dessen aus der Konfiguration hat das Problem gelöst!