Aus dem Rechenzentrum

An sich ist auch das Übertragen größerer Dateien per SMTP kein Problem mit qmail, solange die Mail vom Umfang her unter dem in control/databytes angegeben Limit bleibt. Abbrüche aufgrund von Timeouts nimmt qmail-smtpd nur dann vor, wenn es 20 Minuten lang überhaupt keine Daten mehr vom Client bekommt (einstellbar in control/timeoutsmtpd). Solange Daten übertragen werden, werden die auch verarbeitet – auch wenn’s Stunden dauert.

Nun beklagte sich ein „Kundeskunde“, der nur eine 64-kbit/s-Leitung sein eigen nennt, darüber, dass beim Versenden größerer Dateien die Verbindung immer nach einigen Minuten abbrechen würde, ohne eine Fehlermeldung des Servers. Thunderbird sagt dann:

The message could not be sent because the connection to SMTP server $HOSTNAME was lost in the middle of the transaction.

Wir konnten uns zunächst keinen Reim darauf machen. Selbst wenn qmail-smtpd die Verbindung wegen eines Timeouts dichtmachen würde, dann doch zumindest mit einer entsprechenden Meldung (wobei fraglich wäre, ob diese den Client dann noch erreicht). Also doch ein Netzproblem?

Im Logfile von qmail-smtpd fand sich nur das hier:

2010-03-24 14:42:49.222521500 6412 > [EOF]
2010-03-24 14:42:49.222721500 tcpserver: end 6412 status 14

Die erste Zeile resultiert daraus, dass wir ein recordio haben mitlaufen lassen, um dem Problem auf die Spur zu kommen. Schnell war analysiert, dass derartige Abbrüche immer nach exakt 8 Minuten verzeichnet werden. Passt also auch nicht zur qmail-smtpd-Konfiguration. Mein Kollege Andreas schlug vor, die Sourcen der beteiligten Programme mal ganz stumpf nach „480“ (Sekunden = 8 Minuten) zu durchsuchen. Im gesamten qmail-Source fand sich wie erwartet nichts. Auch nicht im Source von ucspi-tcp. Aber dann, ein Treffer in greylite.c:

/* timeout in seconds for one read/write operation (seconds) */
#define TIMEOUT                     40
/* big timeout after which exiting (seconds) */
#define BIG_TIMEOUT                 480

Kurz darauf wird dann ein Alarm-Handler auf diesen Timeout gesetzt, der an sighand verzweigt:

    signal(SIGALRM, sighand);
    signal(SIGPIPE, sighand);
    alarm(BIG_TIMEOUT);
    [...]
void sighand(int sig) {
    switch (sig) {
        case SIGALRM:
            logmsg(LOG_WARNING, "Big timeout reached from '%s'!", client_metainfo.address);
            break;
        case SIGPIPE:
            logmsg(LOG_INFO, "Client '%s' closed connection prematurely.", client_metainfo.address);
            break;
    }
    exit(100);
}

Also: Nach 8 Minuten kappt greylite die Verbindung, egal was gerade ist oder ob gerade noch eine Mail überträgt. Hm, das ist ja mal ’ne tolle Wurst. Wir haben aus der 480 mal eine 1800 gemacht, neu kompiliert, und der Kunde bestätigt: Jetzt gibt’s kein Problem mehr.

Fraglich bleibt, wieso wir keine „Big timeout reached“-Meldung im Logfile vorgefunden haben. Manchmal gibt’s die nämlich durchaus. Aber manchmal stirbt das greylite auch kommentarlos weg – aber eben unzweifelhaft nach jenen 8 Minuten.

Im Rahmen unserer Arbeiten mit qmail-tauglichen Greylisting-Implementierungen sind wir auf greylite gestoßen, das zu einem der am einfachsten zu installierenden und zu benutzenden Tools gehört. Es unterstützt MySQL als Backend, was insbesondere deshalb für uns wichtig ist, weil wir mehrere Filterserver einsetzen, die sich eine Greylisting-Datenbank teilen sollen.

Auch wenn alles von Anfang an prima klappte, eins haute nicht hin: Das automatische Aufräumen von veralteten Einträgen. Zwar war in der Dokumentation nichts davon erwähnt; aus dem Sourcecode ging aber klar hervor, dass ein derartiges Aufräumen durchaus eingebaut ist.

Mit LOG_DEBUG als Log-Level war schließlich das Problem schnell identifiziert:

2010-01-18 19:51:39.804329500 greylite: Cleaning up stale verified entries.
2010-01-18 19:51:39.804348500 greylite: Query: DELETE FROM verified WHERE NOW() - ts > interval '480 hours'
2010-01-18 19:51:39.805073500 greylite: Query failed: You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near '' at line 1

Für die Tabelle pending galt übertragen das gleiche. Das Problem ist also, dass der Autor hier eine Syntax verwendet, die von MySQL nicht unterstützt wird: INTERVAL kann dort nur zusammen mit DATE_ADD/DATE_SUB oder direkter Addition oder Subtraktion mit einem Datum verwendet. „Alleinstehend“ auf einer Seite eines Vergleichs kann es nicht genutzt werden. Damit nicht genug heißt die entsprechende Einheit in MySQL nicht etwa HOURS, sondern immer HOUR im Singular, auch wenn eine Formulierung wie INTERVAL 480 HOUR sicherlich sprachlich zweifelhaft ist. Und schließlich ist HOUR ein Schlüsselwort, das nicht gequotet werden darf. Mit anderen Worten: So kann’s überhaupt nicht gehen.

Ich habe daraufhin die beiden betreffenden SQL-Statements in der db-mysql.c schnell umgeschrieben und getestet. Der Einfachheit halber habe ich das Ergebnis als Patch bereitgestellt (greylite-3.0pre2-db-mysql.patch). Den Autor von greylite habe ich informiert; mit etwas Glück ist der Patch bei der nächsten Version nicht mehr nötig.