Mich begrüßte heute früh eine Mitteilung der Mailinglistensoftware von gnu.org, dass es Zustellprobleme bei E-Mail gäbe und man mich aus den Listen werfen würde. Die Fehlermeldung besagt, dass die Diffie-Hellmann-Schlüssel zu klein seien. Stattdessen ist es umgekehrt. Oder doch nicht?

Der Schreck

Messages to you from the xxx mailing list seem to
have been bouncing. I've attached a copy of the first bounce
message I received.

If this message bounces too, I will send you a probe. If the probe bounces,
I will remove your address from the xxx mailing list,
without further notice.
... --- ...
Hi. This is the qmail-send program at sourceware.org.
I'm afraid I wasn't able to deliver your message to the following addresses.
This is a permanent error; I've given up. Sorry it didn't work out.

<lutz@...>:
TLS connect failed:
  error:14082174:SSL routines:SSL3_CHECK_CERT_AND_ALGORITHM:
  dh key too small; connected to 217.17.192.66.
I'm not going to try again; this message has been in the queue too long.

Sollte ich die Maschine vergessen habe? Sollten da noch kurze DH-Schlüssel rumliegen?

Ungläubiges Staunen

Also schaue ich mal nach (und zwar auf beiden MXen) nach. Aber natürlich würde ich kaum Schlüssellängen verwenden, die auch andere benutzen.

[217.17.192.66]# dhparam -in /etc/sendmail/dhparams.pem -text | head -1
Diffie-Hellman-Parameters: (1139 bit)

[217.17.192.67]# dhparam -in /etc/sendmail/dhparams.pem -text | head -1
Diffie-Hellman-Parameters: (1123 bit)

Auf der 66, dem sekundären MX, ist der Schlüssel größer als auf dem primären MX (der 67). Und qmail sagt, dieser Schlüssel sei zu klein? Eine Prüfung ergibt, dass die Einlieferung auf dem primären MX problemlos klappt.

Dec  1 11:51:33 excalibur sm-mta[31817]: uB1ApSQ1031817:
 from=<xxx@yyy.gnu.org>, size=5506, class=-60, nrcpts=1,
 msgid=<zzz>, proto=ESMTP, daemon=MTA,
 relay=server1.sourceware.org [209.132.180.131]

Analoge Zeilen auf dem sekundären MX fehlen, stattdessen findet sich dort (passend zu der Beschwerde der Mailinglistensoftware)

Nov 30 13:02:07 avalon sm-mta[2695]: uAUC243i002695:
 server1.sourceware.org [209.132.180.131] did not issue MAIL/EXPN/VRFY/ETRN during connection to MTA

Ganz offensichtlich kommt das absendende Programm qmail nicht mit diesem Server klar.

Die eigne Nase

Intensives Suchen überzeugt mich, dass ich mit dem Problem allein bin. Es ist also sehr wahrscheinlich, dass der Fehler bei mir liegt.

Ein Test gegen den Server mit openssl s_client zeigt, dass tatsächlich ein zu kurzer DH-Key offeriert wird. WTF?

Die Konfiguration des Sendmail hat ganz klar die Konfigurationszeile auskommentiert, in der die Parameter zugewiesen werden. Der Sendmail hat sich selbst einen 512bit Key gebaut. Und der ist tatsächlich zu klein!

Also Konfig korrekt vorgenommen und ...

... siehe da, es geht!

Nebenan beschäftigt man sich mit der Laufzeit von Programmen anhand des Spieles Subtract a Square. Da ich aus einem anderen Projekt heraus in eine ähnliche Situation geriet, möchte ich diese Vorlage hier nutzen. Es geht darum, eine effiziente Methode zu finden, eine größere Menge an Werten systematisch nach verschiedenen Kriterien zu durchsuchen.

Aufgabestellung

Beim Spiel geht es darum, abwechselnd von einer vorgegebenen, positiven Zahl eine Quadratzahl abzuziehen, ohne ins Minus zu rutschen. Wer die letzte positive Zahl abziehen kann, hat gewonnen. Das Spiel endet offensichtlich mit dem Wert 0.

Für derartige Nimm-Spiele gibt es eine allgemeine Gewinnstrategie: Man zieht so, dass der Gegner nicht gewinnen kann.

Dazu tabellarisiert man alle Spiele mit kleineren Startzahlen und schaut, ob man dieses kleinere Spiel gewinnen könnte. Kann man das nicht, hat man eine Verliererposition. Mit der Kenntnis aller kleineren Spielausgänge muss man nur den ersten Spielzug betrachten.

Prozedurale Lösung

Zum Verständnis hier eine prozedurale Lösung des Problems:

with Ada.Text_IO;
with Ada.Command_Line;

procedure SubtractSquare is

   function Winners(i : Natural) return Boolean is
      type bitfield is array(0 .. i) of Boolean;
      pragma Pack(bitfield);
      win : bitfield := (0 => False, others => True);
   begin
      for pos in win'Range loop
         for offset in 1 .. pos loop
            declare
               square : Natural := offset*offset;
            begin
               exit when square > pos;
               if win(pos - square) then
                  win(pos) := False;
                  exit;
               end if;
            end;
         end loop;
      end loop;
      return win(i);
   end;

   package Cmd renames Ada.Command_Line;
   package BIO is new Ada.Text_IO.Enumeration_IO(Boolean);

   pos : Positive := Positive'Value(Cmd.Argument(1));
begin
   BIO.Put(Winners(pos));
end SubtractSquare;

Dieses Programm erzeugt ein (kompaktes) Bitfeld und setzt die Werte von kleinen zu großen Positionen. Der letzte Wert ist dann das gewünschte Ergebnis. Die gewünschte Position wird dem ersten Argument der Kommandozeile entnommen.

$ gnatmake -O2 subtractsquare.adb 
ada -c -O2 subtractsquare.adb
gnatbind -x subtractsquare.ali
gnatlink subtractsquare.ali -O2
$ ./subtractsquare 9
FALSE

Soweit so einfach.

Die Laufzeit ist maximal quadratisch (wegen der Doppelschleife), es besteht aber Hoffnung nur knapp über linear zu landen, weil die zweite Schleife vorzeitig abgebrochen wird.

Funktionale Lösung

Die direkte Übernahme dieses Ansatzes in eine funktionale Programmiersprache wie Haskell ist trivial:

import System.Environment

squares = [ i*i | i <- [ 1 .. ] ]

winners :: [Bool]
winners = False : [ and [ not $ winners !! (i-x)
                        | x <- takeWhile (<= i) squares
                        ]
                  | i <- [1 .. ]
                  ]

main = do [c] <- getArgs
          count <- readIO c
          print (winners !! count)

Man baut sich also eine unendliche Liste der möglichen Offsets (Quadrate). Mit der bastelt man die unendliche Liste der Gewinnerwerte zusammen, indem man beim Aufbau auf die Liste selbst zurückgreift. Das funktioniert, weil man nur auf Werte zugreift, die schon berechnet werden konnten.

Von der Liste gibt man das entsprechende Element zurück.

Unglücklicherweise ist das ziemlich langsam, denn die Doppelschleife ist eigentlich eine Dreifachschleife. Die Datenstruktur "[]" ist eine einfach verkettete Liste, die der "!!"-Operator immer von Anfang an durchlaufen muss.

Und genau das Problem habe ich in einem anderen Kontext auch. Also muss da eine Lösung her.

Effizientere Implementierung

Um die ständigen Rücksprünge zu vermeiden, kann man die Tatsache ausnutzen, dass man eigentlich mit mehreren Indizes (um Quadrate versetzt) linear durch die Liste durchläuft.

winners :: [Bool]
winners = False : worker 1 squares []
 where
  worker i so@(s:sn) rs
    | s == i    = worker' i sn (winners:rs)
    | otherwise = worker' i so          rs
  worker' i ss rs = and (map (not . head) rs)
                  : worker (i+1) ss (map tail rs)

Die Implementierung besteht also darin, mitzuzählen und jedes mal, wenn man eine Quadratzahl erreicht hat, einen weiteren Runner über das bisherige Feld aufzunehmen. Das macht die Teilfunktion worker.

Die eigentliche Wertermittlung erfolgt in der Teilfunktion worker', die von allen Runnern das erste Element auswertet und mit den Resten in die nächste Iteration läuft.

Ein direkter Vergleich der Laufzeiten zeigt einen durchschlagenden Erfolg:

subsquare-value-runtime

Seltsame Spitzen

Ungewöhnlich sind die Spitzen der violetten Kurve in diesem Graphen. Wo kommen die her? Fehlmessungen?

Also lass ich weitere Werte berechnen und sehe, dass die Spitzen bleiben. (Den Teil mit dem count ignoriere man mal vorerst.)

subsquare-stream-valuesum

Nun gut, es mag an der Schrittweite liegen, denn ich nehme nur alle 1000 Werte einen Messpunkt. Also mal in Einzelschritten in ein solches Intervall hinein hüpfen:

subsquare-stream-detail

Auch hier zeigt die violette Kurve ein extrem zackiges Bild. Warum?

Weil Haskell faul ist. Lazy evaluation ist eine Eigenschaft von Haskell, nur dann einen Wert auszurechnen, wenn der auch gebraucht wird.

In diesem Fall lautet die Aufgabe, einen bestimmten Wert in einer Liste auszugeben. Dazu geht Haskell die Listenkonstruktion durch und stellt fest, dass in jeder Iteration ein neues Element erzeugt wird. (In worker')

Um den konkreten Wert dann doch zu ermitteln, geht Haskell die Berechnung an und beginnt mit dem letzten hinzugefügten Runner. Der steht aber am Anfang der Liste und mit etwas Glück erwischt er gleich einen Abbruchwert. Damit kann Haskell das Ergebnis ausgeben und ist fertig.

Nur, wenn das Spiel wirklich eine komplexere Situation zu bewerten hat, muss Haskell deutlich mehr berechnen.

Um ihn zu zwingen, alle Werte zu ermitteln lasse ich die Anzahl der Gewinnzahlen bis zu der angefragten Position zu ermitteln.

--          print $ winners !! count
          print . length . filter id . take count $ winners

Eine alternative Formulierung wäre:

          print $ length [ x | x <- take count winners , x ]

Das Ergebnis ist verblüffend. Es ist genau die grüne count-Kurve in den oben stehenden Diagrammen.

Immer, wenn ein neuer Gewinnwert dazu kommt (oder in kleinen Schritten erreichbar wäre), steigt die Rechenzeit deutlich an. Das ist an der überlagerten blauen Stufenkurve zu sehen.

Als Gegentest kann man die Konstruktion "(winners:xs)" in worker durch "(xs ++ [winners])" ersetzen und zuerst den Wert des direkten Vorgängers benutzen. Das stellt ebenfalls sicher, dass alle Werte ermittelt werden. Die Laufzeiten liegen dann in vergleichbaren Größenordnungen wie beim count-Fall.

Warum dauert die Abarbeitung in Einzelfällen aber deutlich länger als im count-Fall? Er hat doch eigentlich weniger zu berechnen?

Die von Haskell zurückgelegten Teilberechnungen sind eine teuere Angelegenheit, sie anzulegen und später auszurechnen kostet deutlich mehr Zeit (und Speicher) als direkt zur Rechnung zu schreiten.

Nochmal!

Mit diesen Erkenntnissen vergleiche ich jetzt nochmal die beiden Algorithmen: Backreferenz per "!!"-Operator und mehrere Stream-Runner. Allerdings berechne ich diesmal die Anzahl der Gewinnzahlen.

subsquare-sum-runtime

Auch hier ist der Vergleich ähnlich: Die Runner gewinnen deutlich.

Evtl. hat ja die count-Berechnung auch das andere Verfahren massiv verlangsamt? Also beide Laufzeiten im direkten Vergleich:

subsquare-backref-valuesum

Die Backreferenz-Methode benötigt auch dann viel Zeit, wenn sie gar nicht alle Werte berechnen muss. Die Berechnung aller Werte dauert aber konstant länger. Beide Laufzeiten sind aber vergleichbar.

Zum Abschluss noch der direkte Vergleich der Methoden in der logarithmischen Darstellung:

subsquare-sum-runtime-log

Die Backreferenz-Methode ist klar polynomial (vermutlich O(n3)) während die Stream-Methode noch exponentiell aussieht (was sie aber nicht ist).

Fazit

Man achte bei der Programmierung stets darauf, ob der Algorithmus zum Programmumgebung passt.

Ist das nicht der Fall, verschlechtern sich die Ergebnisse erheblich. Dann muss entweder der Algorithmus (Streams statt Backreferenzen) oder die Umgebung (Data.Array statt Listen) angepasst werden.

Will man die Vorteile der Programmumgebung (Lazy Evaluation) erhalten, muss man die gewohnten algorithmischen Bahnen verlassen.

Als Belohnung winkt eine überdurchschnittliche Performance.

Shell-Scripte, die größere Datenmengen umher schubsen, können schon mal ganz schön lange laufen. Ein typischer Fall sind Backup-Scripte, die in einer Schleife zwischen Erstellen und Übertragen eines Archivs hin und her pendeln. Natürlich will man nicht alles voll parallel fahren, sondern hübsch nacheinander. Allerdings sollte Datentransfer und Archiverstellung schon parallel ablaufen. Das ist aber etwas trickreich.

Schwache Parallelität

Was man eigentlich will, sind zwei Scripte. Das eine generiert die Archive und das andere überträgt die auf ein entferntes System. Die Scripte sollen sich nicht gegenseitig behindern, d.h. eine noch laufende Übertragung darf nicht die Erzeugung des nächsten Archivs verzögern und umgekehrt.

Selbstverständlich dürfen nur die Archive übertragen werden, die auch fertig sind. Man braucht also eine Liste von fertig gestellten Archiven, die aus dem einen Script heraus fallen und vom zweiten Script übertragen werden.

Das klingt nach einer Pipe? Aber natürlich! Das ist eine Pipe!

(
  tar czf xxx.tgz ~xxx && echo xxx.tgz
  ...
) | while read a; do
  upload "$a"
done

Ganz klassisch. Leider aber nicht benutzbar, denn die Backupscripte existieren bereits.

#! /bin/bash

echo "Übertrage Test1"
echo "X1"
echo "Übertrage Test2"
echo "X2"
echo "Übertrage Test3"
echo "X3"
echo "Übertrage Test4"

Insbesondere sollen es nicht mehr Scripte werden, die per Helperscripte zusammen geklebt werden müssen.

Der Crux mit dem Standard

Diese Scripte benutzen bereits Standardeingabe, -ausgabe und -error. Diese Filedeskriptoren werden nicht nur von dem betreffenden Script, sondern auch von den aufgerufenen externen Programmen (wie tar) benutzt. Es ist also nicht möglich, den Zweck von STDOUT neu zu definieren.

Eine Lösung besteht darin, die Pipe auf einem anderen Filedeskriptor laufen zu lassen. Das ist aber nicht ganz so einfach.

Anstatt die eigentliche Aktion auszuführen, wird der zu übertragende Dateinamen auf einen anderen Filedeskriptor drei geschrieben. Dieser wird dann als STDOUT für die Pipe kopiert.

Was aber tun mit dem aktuellen STDOUT? Würde man ihn lassen, würde diese Ausgabe ebenfalls Übertragungen anstoßen. Definitiv ungewollt. Also retten wir den Filedeskriptor eins (STDOUT) temporär auf den Deskriptor vier.

#! /bin/bash

{ {
  echo "Test1" >&3
  echo "X1"
  echo "Test2" >&3
  echo "X2"
  sleep .1
  echo "Test3" >&3
  echo "X3"
  echo "Test4" >&3
  echo "Main done"
} 3>&1 1>&4 | {
  while read a; do
    echo "Übertrage >$a<"
    sleep 1
  done
  echo "Sub done"
} } 4>&1
echo "All done"

Und zum Schluss fügen wir den temporären Filedeskriptor vier wieder STDOUT (eins) hinzu. Das Ergebnis kann sich sehen lassen:

X1
X2
Übertrage >Test1<
X3
Main done
Übertrage >Test2<
Übertrage >Test3<
Übertrage >Test4<
Sub done
All done

Minimalinvasive Eingriffe

Die Methode der Pipe erzwingt einen riesigen Block, der aus dem bisherigen Skript besteht. Solche riesigen Blöcke sind anfällig für subtile Fehler und lassen sich sehr schwer pflegen. Schließlich sollen die Änderungen möglichst wenig Zeilen betreffen und das Ergebnis weiterhin patchbar bleiben. Eine Klammerung, die im Editor eine andere Einrückung erzwingt, scheidet damit aus.

Aber was dann?

Coprozesse sind der Kern dessen, was die Shell mit sich selbst veranstaltet, wenn sie eine Pipe generieren muss. Also kann man diese auch direkt verwenden.

Ein Coprozess ist ein fork der Shell an der Aufrufstelle, wobei der Kindprozess nur noch den Teil der Coroutine ausführt. Sein STDIN und STDOUT sind zwei Pipes, deren Enden dem Mutterprozess in die Hand gedrückt werden.

$ coproc my { read a; echo "Test $a"; };
[1] 12548
$ jobs
[1]+  Running                 coproc my { read a; echo "Test $a"; } &
$ set | grep my
my=([0]="63" [1]="60")
my_PID=12548 

Von der Muttershell aus müssen nun diese Filedeskriptoren gelesen und geschrieben werden:

$ cat - <&63
^Z
[2]+  Stopped(SIGTSTP)        cat - 0<&63
$ bg
[2] cat - 0<&63 &
$ echo Hallo >&60
Test Hallo
[1]-  Done                    coproc my { read a; echo "Test $a"; }
[2]+  Done                    cat - 0<&63 

Das Prinzip sollte damit klar sein. Natürlich muss man die Nummern der Deskriptoren aus der Umgebungsvariable auslesen, denn die sind variabel.

Um sich keinen useless use of cat einzuhandeln, sollte man aber den Filedeskriptor direkt auf STDOUT umbiegen.

Gießt man das alles zusammen, bekommt man:

#! /bin/bash

{ coproc my {
  while read a; do
    echo "Übertrage >$a<"
    sleep 1
  done
  echo "Sub done"
} >&3; } 3>&1

echo "Test1" >&${my[1]}
echo "X1"
echo "Test2" >&${my[1]}
echo "X2"
sleep .1
echo "Test3" >&${my[1]}
echo "X3"
echo "Test4" >&${my[1]}
echo "Main done"

wait
echo "All done"

Und das Ergebnis lautet:

X1
X2
Übertrage >Test1<
X3
Main done
Übertrage >Test2<
Übertrage >Test3<
Übertrage >Test4<
[ ... ewiges Warten ...]

Irgendwie bekommt der Kindprozess nicht mit, dass die Arbeit erledigt ist.

Man müsste die Pipe noch schließen, damit der Kindprozess sich beenden kann. (Oder halt ein Inband-Signalwort übertragen.)

Das Schließen des Filedeskriptors ist schwieriger als erwartet, weil die Variablensyntax anders ist. Das Prozessing von Variablensubstitution und Redirect der Filedescriptoren intereferiert auf unerwartete Weise.

exec {my[1]}>&-

Zusammen gefasst kommt dann folgende Strukturänderung heraus:

#! /bin/bash

# Initialisierung der Variablen, Konfiguration
...
# Einschub der Helperfunktion für die Hintergrundübertragung
{ coproc uploadhelper {
  while read a; do
    upload "$a"
  done
} >&3; } 3>&1

# Normales Hauptprogramm
...
echo "$FILE" >>${uploadhelper[1]}   # ersetzt die Zeile: upload "$FILE"
...
# Ende des Hauptprogrammes, Warten auf das Ende der Uploads
exec {uploadhelper[1]}>&-
wait

# Nacharbeiten des Hauptprogrammes
....
# EOF 

Tut.

Ich hab' mich lange davor gescheut, auf eine eingebaute CA zu wechseln. Die typischen Gründe waren meine seltsamen Hostnamen, die ich benutze. Also brauch' ich meist eine ganze Latte an zusätzlichen Namen oder gar ein Wildcard. Das ist teuer. Letsencrypt bietet das inzwischen zwar an, ist aber wegen der kurzen Laufzeiten umständlich, denn ich will kein fremdgesteuertes Binärblob über meine Daten bestimmen lassen. Aber auch dafür gibt es inzwischen eine Lösung.

My server is my castle

Fremdsoftware, die ich nicht selbst kompilieren und halbwegs verstehen kann, mag ich nicht auf meiner Kiste laufen haben. Python und ähnlicher neumodischer Schnickschnack kommt mir nicht auf die Platte. Also fällt der Letsencrypt Client aus.

Man kann das ACME Protokoll natürlich von Hand nacharbeiten, aber das ist aufwendig. Und da es schon jemand gemacht hatte, war es auch keine besondere Herausforderung. Meine ersten Letsencrypt Zertifikate habe ich manuell über gethttpsforfree erzeugt. Da kann ich den Code lesen und außerhalb des Servers die Zertifikate erstellen.

Nur skaliert das leider nicht besonders gut. Der Aufwand der Zertifikatserneuerung kommt häufiger als notwendig (gefühlt) und es kostet zu viel Zeit während die Uhr tickt. Das ist kein Zustand, den ich lange durchhalten möchte.

Aufmerksam wurde ich aber als Letsencrypt gegen ein Bash-Skript vorging, weil es die Markenrechte(!) verletzen würde. Der Autor benannte das Script um und brachte seinen Unwillen ob dieses unfreundlichen Aktes zum Ausdruck. Allein aus Solidarität hab ich mir das Script angeschaut.

In den Tiefen der Shell

Dehydrated ist ein klar strukturiertes, verständliches Script, dass sich einem beherzten set -x nicht entgegen setzt. Auf den ersten Blick ein sympathisches Stück Software.

Unglücklicherweise läuft es nicht.

Die Fehler sind vielfältig und reichen von Inkompatibilitäten der Letsencrypt-Webseite mit meinem curl bis hin zu schlichten Programmabbrüchen.

+ Requesting challenge for lutz.donnerhacke.de...
sed: -e expression #1, char 42: unterminated `s' command 

Die verursachende Zeile sieht etwas overquoted aus:

challenges="$(printf '%s\n' "${response}" | sed -n 's/.*\("challenges":[^\[]*\[[^]]*]\).*/\1/p')"

Beim besten Willen bekomme ich den sed-Ausdruck zum Laufen. Irgendwas ist mit den eckigen Klammern mächtig durcheinander geraten.

Also versuche ich mal zu verstehen, was der Ausdruck will und wie man ihn anders schreiben kann.

  • Es wird alles vor dem Text "challenges": weggeschnitten.
  • Dann werden alle Zeichen bis zur öffnenden eckigen Klammer mitgenommen.
  • Und schließlich alle Zeichen bis zur nächsten schließenden eckigen Klammer.
  • Der Rest wird verworfen.
  • Gab es überhaupt einen Treffer, wird der zurück gegeben.

Anders gesagt:

... | sed -n '/"challenges":/{;s/.*\("challenges":\)/\1/;s/].*/]/;p;}')"

Wenn also der Text da steht, werden drei Aktionen ausgeführt:

  • Der Text vor dem Marker wird entfernt.
  • Der Text hinter der ersten schließenden eckigen Klammer wird entfernt.
  • Der Text wird ausgegeben.

Das ist praktisch gesehen die gleiche Aktion, diesmal aber in funktionierend.

Nach einigen Tests insbesondere hinsichtlich TLSA und Schlüsselwechsel, und natürlich mit abweichenden Schlüssellängen, kann es live gehen.

Es gibt so Tage, an denen man die Wände hoch gehen möchte. Beispielweise der, an dem ein Exchange-Server beim Kunden aus heiterem Himmel massiv Spam-Mails versendete. Variierende Absender alerts@XXXbank.de und Ziele in aller Welt. Dabei hat man schon Probleme, wenn der Kunde mal im Outlook oder Webmailer seine private Adresse als Absender verwenden will. Was war also passiert?

Daten sammeln

Zuerst einmal ist festzustellen, ob überhaupt gespammt wurde. Schließlich kann es ja sein, dass die auslösende Beschwerde eine Fehlinterpretation darstellt. In dem konkreten Fall sagen die relevanten Received-Zeilen zwar ganz koscher aus, aber man weiß ja nie.

Also zuerst mal ins Logverzeichnis des Mailserver, also der Komponente, die die E-Mails tatsächlich entgegen nimmt und dann verschickt.

C:\> cd C:\Program Files\Microsoft\Exchange Server\V15\TransportRoles\Logs\Hub\ProtocolLog\SmtpReceive

Dort finden sich Dateien der Form RECVyyyymmdd-ss.LOG. In denen steht, wie die Mailserver zu seinen E-Mails gekommen ist. Findet sich dort nichts auffälliges, schaut man nebenan im SmtpSend Folder nach, ob überhaupt vom Exchange gesendet wurde.

In diesem Fall stehen aber Einträge im Empfangsprotokoll:

...,[exchange-ip]:465,[exchange-ip]:38115,...
<,EHLO exch.local,
*,None,Set Session Permissions
>,250-exch.local Hello [2a01:...],
>,250-PIPELINING,
>,250-DSN,
>,250-ENHANCEDSTATUSCODES,
>,250-AUTH GSSAPI NTLM LOGIN,
>,250-X-EXPS EXCHANGEAUTH GSSAPI NTLM,
>,250-X-EXCHANGEAUTH SHA256,
>,250-8BITMIME,
>,250-BINARYMIME,
>,250-CHUNKING,
>,250-XEXCH50,
>,250-XRDST,
>,250-XSHADOWREQUEST,
>,250-XPROXY,
>,250-XPROXYFROM,
>,250-X-MESSAGECONTEXT ADRC-2.1.0.0 EPROP-1.2.0.0,
>,250-XSYSPROBE,
>,250 XORIGFROM,
<,X-EXPS EXCHANGEAUTH,
*,NT AUTHORITY\SYSTEM,authenticated
>,235 <authentication response>,
<,XPROXY SID=08D3C19C6F595AB4 IP=80.a.b.c PORT=51066 DOMAIN=xxx CAPABILITIES=0 SECID=Uy0xLTUtMjEtMDEyMzQ1Njc4OS0wMTIzNDU2Nzg5LTAxMjM0NTY3ODktMTIzNA+3D+3D,
*,SMTPSubmit SMTPSubmitForMLS SMTPAcceptAnyRecipient SMTPAcceptAuthenticationFlag SMTPAcceptAnySender SMTPAcceptAuthoritativeDomainSender BypassAntiSpam BypassMessageSizeLimit SMTPSendEXCH50 SMTPAcceptEXCH50 AcceptRoutingHeaders AcceptForestHeaders AcceptOrganizationHeaders SendRoutingHeaders SendForestHeaders SendOrganizationHeaders SendAs SMTPSendXShadow SMTPAcceptXShadow SMTPAcceptXProxyFrom SMTPAcceptXSessionParams SMTPAcceptXMessageContextADRecipientCache SMTPAcceptXMessageContextExtendedProperties SMTPAcceptXMessageContextFastIndex SMTPAcceptXAttr SMTPAcceptXSysProbe,Set Session Permissions
>,250 XProxy accepted and authenticated,
<,MAIL FROM:<alerts@1k8JzXXXbank.com>,
<,RCPT TO:<dest@ination.net>,
>,250 2.1.0 Sender OK,
>,250 2.1.5 Recipient OK,
<,BDAT 8192,
*,,receiving message with InternetMessageId <random@ination.net>
>,"250 2.6.0 CHUNK received OK, 8192 octets",
<,BDAT 8192,
>,"250 2.6.0 CHUNK received OK, 8192 octets",
<,BDAT 8192,
>,"250 2.6.0 CHUNK received OK, 8192 octets",
<,BDAT 5082 LAST,
>,"250 2.6.0 <random@ination.net> [InternalId=7013681596317, Hostname=exch.local] Queued mail for delivery",

Der überraschende Punkt ist, dass es tatsächlich ein Mailversand von einer fremden Adresse an eine fremde Adresse gibt. Und dafür hat sich der Client die Berechtigungen SMTPAcceptAnyRecipient, SMTPAcceptAnySender, BypassAntiSpam, BypassMessageSizeLimit gegeben.

Richtig heftig ist aber, dass die Mail von der lokalen Maschine kommt und dort mit Systemrechten authentisiert ist. Ganz offenbar versteckt sich da irgendwo im XPROXY eine nachträgliche Authenisierung, die die angegeben Rechte frei schaltet.

Verursacher finden

Schaut man sich die vielen XPROXY Zeilen an, variiert alles, bis auf die IP und SECID.

Die IP ist ganz offensichtlich die originäre Quelle der Einlieferung. Wie auch immer die Mail durch Outlook Web Access, POP, IMAP oder Submission Ports durchgelaufen ist, externe IP und externer Port sind bekannt. Das ist viel wert!

Die SECID dagegen schaut sehr nach BASE64 aus. Also mal dekodieren.

$ echo Uy0xLTUtMjEtMDEyMzQ1Njc4OS0wMTIzNDU2Nzg5LTAxMjM0NTY3ODktMTIzNA== | base64 -d
S-1-5-21-0123456789-0123456789-0123456789-1234

Oh, eine Security-ID von Windows. Das könnte ein Hinweis auf den realen Nutzer sein. Mal schauen:

PS C:\> $objSID = New-Object System.Security.Principal.SecurityIdentifier ("S-1-5-21-0123456789-0123456789-0123456789-1234")
PS C:\> $objUser = $objSID.Translate( [System.Security.Principal.NTAccount])
PS C:\> $objUser.value
KUNDE\backup

Huch? Ein gültiger Nutzername aus dem AD? Gleich mal beim Kunden anrufen.

Es stellt sich heraus, dass bei dem Namen das Passwort sehr leicht zu erraten war. Viel zu leicht. Angelegt hatte den Nutzer der Kunde selbst, um damit USB-Backup-Platten im Netz einbinden zu können. Und damit jeder damit arbeiten kann, hatte der Nutzer auch viel zu viele Rechte.

Der Nutzer wurde deaktiviert und sämtliche Passworte sind zu ändern. Es gibt auch verpflichtende Passwort-Richtlinien, die nun auch als Admin nicht mehr zu umgehen sind.

Aufräumen

Nachdem die Ursache des Spamversands gefunden, bleibt nun noch das Wegräumen der Spammails, die noch nicht versendet wurden. Erst dann kann die Blockade des Mailversands aufgehoben werden.

Erstmal die Mails raus suchen:

[PS] C:\>Get-Message -Filter {FromAddress -like "alerts@*"}

Identity         FromAddress             Status           Queue            Subject
--------         -----------             ------           -----            -------
exch\50755\69... alerts@QIsnlXXXXbank... Active           exch\50755       Important Account In...
exch\155681\7... alerts@HyThUXXXXbank... Active           exch\155681      Important Account In...
...

Und dann weg löschen:

[PS] C:\>Remove-Message -Filter {FromAddress -like "alerts@*"} -WithNDR $false

Bestätigung
Möchten Sie diese Aktion wirklich ausführen?
Die Nachrichten, die dem Filter 'FromAddress -like "alerts@*"' entsprechen, werden entfernt.
[J] Ja  [A] Ja, alle  [N] Nein  [K] Nein, keine  [?] Hilfe (Standard ist "J"):

Das ganze Spiel wiederholt sich solange, bis die Mailwarteschlange nur noch legitime E-Mails enthält.

Und dann kann man den Exchange wieder in die Freiheit entlassen.

Prävention

Im Nachgang sollte man überlegen, ob man solche Situationen nicht schneller erkennen kann.

Kann man: Symptomatisch für hohes Mailaufkommen ist die Anzahl der in einem kurzen Intervall versendeten E-Mails. Und genau dafür gibt es einen Leistungsindikator. Den trägt man mit einem sinnvollen Grenzwert im SystemCenter ein und bekommt einen Alarm, wenn der Grenzwert gerissen wird.

Gestern lief ein MySQL-Exploit durch meine Kommunikationskanäle durch. CVE-2016-6662 spricht von einer remote ausnutzbaren Lücke, die Code mit root-Rechten auf der Maschine ausführen kann. Betroffen sind alle Versionen von MySQL. Das ist ein GAU. Ein Super-GAU wäre es, wenn noch die Authentisierung wegfallen würde. Bei einer Überprüfung zeigten sich drei Gründe, warum mich das trotzdem nicht betrifft.

Funktionsweise

CVE-2016-6662 ist schnell erklärt.

Ein lokaler Benutzer legt eine shared Library mit dem gewünschten Schadcode im Dateisystem an einer Stelle ab, wo er Zugriff hat. I.d.R. wird das das /tmp-Verzeichnis oder sein Home-Verzeichnis sein.

Als nächstes meldet sich der Nutzer beim MySQL-Server an und lenkt die Ausgabe eines Logfiles auf den wohl bekannten Dateinamen einer Config-Datei des MySQL-Servers um. In dieses Logfile (also die Ini-Datei) schreibt er rein, dass die soeben abgelegte shared Library geladen werden soll. Alle Schreibzugriffe des MySQL-Servers erfolgen unter den Rechten des Daemon, nicht unter den Rechten des angemeldeten Nutzers. Der MySQL-Login muss nicht mal als Nutzer im Betriebssystem existieren.

Beim Restart des MySQL-Servers sorgt das mysqld_safe Startscript dafür, dass die Library mit root-Rechten geladen wird, bevor der Server die Rechte abgibt. Damit wird dann der vom Nutzer stammende Code unter root-Rechten ausgeführt.

Produktionseinsatz

Unser Setup ist produktiv, d.h. für Experimente durch die Nutzer besteht wenig Spielraum. Unser Setup stammt nicht aus einer Distribution, sondern ist im Laufe der Zeit organisch gewachsen. In diesem Fall ist das ein Vorteil.

Gegen das Ablegen von Dateien kann man nichts tun, denn genau das ist eine der Aufgaben, die der Server für den Nutzer erfüllen soll. In dem Fall z.B. ein Webhosting. Nehmen wir also an, der Nutzer hat den Schadcode auf dem Server abgelegt.

Das Überschreiben vorhandener INI-Dateien ist dem MySQL-Server nicht möglich, da bei uns diese Dateien dem administrierenden Nutzer root gehören. Damit scheidet das Überschreiben als Angriffsvektor schon mal aus.

Natürlich könnte der Angriff darüber erfolgen, dass eine andere INI-Datei erzeugt wird, die der Server beim Start parsen wird. Da gibt es einige Plätze, die in einen typischen MySQL-Server einkompiliert werden. Die Frage ist also, ob es klappen würde. Probieren wir das mal aus:

mysql> SELECT 'malicious config entry' INTO OUTFILE '/var/lib/mysql/my.cnf';
ERROR 1045 (28000): Access denied for user 'test'@'localhost' (using password: YES)

Ohja. Der MySQL-Nutzer hat gar nicht die Rechte für diesen Angriff! Aber es gab da ja noch andere Ideen:

mysql> set global general_log_file='/var/lib/mysql/my.cnf';
ERROR 1227 (42000): Access denied; you need (at least one of) the SUPER privilege(s) for this operation

Schon wieder nichts?! Einen hab ich noch:

mysql> CREATE DEFINER=`root`@`localhost` TRIGGER appendToConf
     > AFTER INSERT ON `active_table` FOR EACH ROW begin end;
ERROR 1227 (42000): Access denied; you need (at least one of) the SUPER privilege(s) for this operation

Für einen typischen shared-Hosting Kunden haben sich damit die Möglichkeiten des Angriffs erschöpft.

Aber nehmen wir mal an, es gäbe trotzdem eine Chance, eine INI-Datei zu beeinflussen. Dann würde bei uns nicht das Startscript mysqld_safe zum Zuge kommen, sondern ein eigenes Startscript, dass zuerst die Rechte wechselt und dann den MySQL-Server aufruft. Damit ist ausgeschlossen, dass der Schadcode mit Root-Rechten laufen könnte.

Fazit

Ende gut, alles gut? Nein, diese Art von Angriff zeigt, wie wichtig es ist, zwischen administrativen Aufgaben und Produktionsaufgaben zu unterscheiden. Das Problem wird erst dann relevant, wenn z.B. durch eine Distribution die Bequemlichkeit für den Anwender im Vordergrund steht. Oder wenn man den meist gelesenen Blog-Posts folgt und das Rechtesystem außer Kraft setzt.

Es kommt der Tag, da muss man aufräumen. Und das war nun bei IPTV der Fall. Einige tausend noch Karteileichen sollten nicht mehr versorgt werden. Die Idee dazu ist ganz einfach, nur noch authentisierte Clients bekommen eine IP. Ohne IP kein IGMP, ohne IGMP kein Multicast und ohne Multicast kein Fernsehen. Aber das hat fatale Nebenwirkungen.

Ausgangslage

Es sind knapp 12000 Nutzer im IPTV-Netz eingebucht, bekommen also eine IP Adresse. Die Verteilung der Sender erfolgt dezentral über Multicast-Replikation. Damit sind die Datenleitungen bis runter zum DSLAM nur minimal belastet. Das funktioniert sehr gut.

Die Liste der Kunden, die IPTV vertragsmäßig nutzen dürfen, liegt mittlerweile vor und kann auch von der Hotline/Vertrieb aktualisiert werden. Ein Abgleich der Datenbestände mit der Produktivumgebung erfolgt automatisch. Soweit so einfach.

Die Kunden bekommen aktuelle aus einem großen Pool privater IPs eine DHCP-Lease. Eine Authentisierung erfolgt nicht, weil das der bisherige gewünschte Operationsmodus ist.

Umsetzung

Zur Änderung des Operationsmodus sind einige Vorüberlegungen notwendig:

  • Es dürfen nicht alle Kunden mit einmal gesperrt werden, sondern nur ein Teil, damit die Hotline auf evtl. Fehlsperrungen reagieren kann.
  • Authentisierte und nicht authentisierte Kunden sollten technisch unterscheidbar bleiben, damit der Netzbetrieb Kenntnis von der Vertragslage hat.
  • Der Abgleich der Datenbanken zwischen Vertrieb und Produktion darf nicht angefasst werden, in den Datenbanken des Produktivsystem darf kein Kunde virtuell zugeteilte MAC-Adressen haben, die dem Vertriebssystem fremd sind. Andernfalls ist die Hotline nicht zur Störungsdiagnose und -behebung in der Lage und alle diese Fälle eskalieren in den Netzbetrieb.

Als Lösung werden zwei Pools eingerichtet:

  • ein großer Pool für die authentisierten Kunden und
  • ein kleinerer Pool für die nicht authentisierten Kunden.

Der unauthentisierte Pool kann dann schrittweise verkleinert werden, um für immer mehr Kunden den Zugang zu sperren. Bei Bedarf kann er auch schlagartig wieder vergrößert werden. Dies gestattet die Anzahl der ausgesperrten Kunden rein im operativen Betrieb einzustellen, die Datenbanken bleiben davon unberührt.

Da sich beide Pools hinsichtlich der verwendeten Adressbereiche unterscheiden ist die Diagnose, ob eine fehlende Authentisierung vorliegt auch der Hotline direkt möglich. Diese kann bei Bedarf die Daten auslesen und direkt zur Freischaltung verwenden.

Soweit der Plan.

Überraschungen

Ich müsste nicht darüber schreiben, wenn es so einfach gegangen wäre. Also zuerst einmal die Wirkung der Umschaltung.

poolusage-dhcp.iptv-limit

Nach einem Testlauf kurz vor Mitternacht (bei dem sich herausstellte, dass die Auswertung der Authentisierung gar nicht aktiviert wurde), erfolgte dann wie geplant die Umschaltung und die erste Limitierung der Kunden auf ca. 5000 unauthentisierte Teilnehmer.

Wie leicht zu sehen, hat das dann nach Ablauf der Lease-Zeiten auch funktioniert. Sobald der Pool voll war, sank die Anzahl der IPTV-Teilnehmer ab, bis alle authentisierten plus die glücklichen 5000 Pool-Teilnehmer. In Summe um die 6000 Kunden.

Auch zu sehen ist aber auch, dass diese Reglung wieder aufgehoben wurde. Und das kam so:

In bestimmten Gegenden fiel am nächsten Morgen regelmäßig der komplette Anschluss aus. Einige Switche stellte kurzzeitig, aber effektiv, die Arbeit ein. Zwar erholten sie sich wieder, jedoch blieb ein konstanter Betrieb aus. Stattdessen wiederholte sich der Ausfall in kurzen aber unregelmäßigen Abständen.

Es stellte sich heraus, dass diese Switche mit Bursts von Broadcasts nicht klar kamen, wenn in diesen Burst zu viele unbekannte Quell-MAC-Adressen auftauchten. Offenbar geraten diese Geräte dann an Limits hinsichtlich der Verwaltung von MAC-Adressen. Diese Bursts kommen aus dem DHCP:

poolrate-dhcp.iptv-limit

Als Notlösung wurde erst einmal wieder für alle der Zugang freigegeben. Damit hören die Bursts auf und das System funktioniert wieder.

Diese Bursts bestehen aus den DHCPDISOVER Anfragen der CPEs, für die keine Adressen mehr zur Verfügung stehen. Und die fragen eben alle paar Sekunden per Broadcast rum, ob irgendjemand evtl. doch eine IP für sie übrig hat.

Broadcast heißt aber auch, dass die Anfragen auch die hintersten Winkel des Netzes erreichen, insbesondere diese empfindlichen Switche. Im Normalbetrieb haben diese Switche kein Problem, aber so war's doch etwas zu heftig.

Die Lösung besteht nun darin, die betreffenden Segmente in getrennte Broadcast-Domains zu verfrachten und die Multicast-Streams in alle diese VLANs einzuspeisen. Aber dazu später mal mehr.

Greift ein Kunde mit POP3 auf ein (Unix)-Postfach zu, kommt es vor, dass bestimmte E-Mails immer und immer wieder reinkommen. Auch dann, wenn die E-Mail nicht so häufig angekommen ist. Zuerst hatte ich eine besondere Header-Zeile der E-Mail in Verdacht, aber es ist ganz anders.

Hunderte von E-Mails

Der Kunde verzweifelt, weil er mit dem Löschen der E-Mails gar nicht mehr nach kommt. Immer, wenn er ins Postfach schaut, sind wieder E-Mails da.

2016-07-08-143453_477x186_scrot

Über's Wochenende können tausende E-Mails auflaufen. Aber wo kommen die her?

Ein Blick ins betreffende Postfach auf Serverseite zeigt diese E-Mail nur ein paar Mal. Im Log steht ebenfalls nichts von einer Mailflut. Also kann es eigentlich gar nicht zu dem beobachteten Effekt kommen.

POP3 Defizite

Das Problem tritt nur auf, wenn das Outlook per POP3 die E-Mails abruft.

Dann aber kommen pro Abruf einige E-Mails hinzu. Und zwar genau eine Mail weniger als im Postfach liegen. Anders gesagt: Liegen im Postfach vier Exemplare der gleichen E-Mail, so fügt Outlook beim Abrufen drei Versionen hinzu.

Ganz offensichtlich hat Outlook Probleme mit der Erkennung von Dubletten. Genau genommen gibt es zwei Probleme, eins davon ist die Verarbeitung identischer Nachrichten.

Wenn man bei POP3 die Nachrichten auf dem Server belässt, holt Outlook sie jedes Mal komplett ab und prüft, ob es die Nachricht schon hat. Ist das der Fall, sortiert Outlook die Nachricht nicht ins Postfach ein.

Offenbar vergisst Outlook aber sofort, dass es die betreffende Nachricht hat. Eine wahrscheinliche Erklärung dafür ist eine Performanceoptimierung: Wenn die Nachricht angekommen ist, braucht man nicht mehr gegen die Nachricht testen und die Tests laufen schneller ab.

Kommt dann eine Nachricht mehrfach rein, werden die späteren Versionen alle als neue Nachrichten einsortiert.

Die offenkundige Lösung dieses Problems besteht darin, die Nachrichten auf dem Server unterschiedlich zu machen.

#### Duplicates
:0 whc: msgid.lock
| formail -D 8192 msgid.cache

:0 fha
| formail -R Message-ID: Old-Message-ID: -a Message-ID:

Wer mag, kann natürlich auch die Duplikate als Spam aussortieren. Das ist nur dann keine gute Idee, wenn Sammelpostfächer und nachfolgende Aufsplittungen im Spiel sind.

Überraschenderweise ist Outlook selbst Quelle von doppelten Message-IDs. Wird eine Nachricht weitergeleitet, eine Empfangsbetätigung verschickt o.ä., benutzt Outlook die Message-ID der Ursprungsnachricht weiter. Sortiert man diese Mails dann aus, stört man erheblich die Bürokommunikation.

Eine andere Quelle sind Anrufbeantworter und Scanner, die ihre Message-IDs gern in der Form <laufende-nummer@gerätename> erzeugen. Und nach jedem Einschalten wieder mit eins zu zählen beginnen ...

Andere Ursachen

Andere E-Mails werden von Outlook ebenfalls schon früh verarbeitet. So werden Kalenderobjekte oder Empfangsbestätigungen direkt bei der Annahme verarbeitet. Auch benutzerdefinierte Regeln werden schon während der Abholung ausgeführt.

In all diesen Fällen ist es wahrscheinlich, dass der Algorithmus zur Dubletten-Erkennung durcheinander gerät. Solche E-Mails werden dann bei jedem Abholen erneut behandelt und ggf. als neu einsortiert.

Als saubere Lösung bleibt nur, Outlook so zu konfigurieren, dass es die Nachrichten nach dem Abholen vom Server löscht. Damit sind alle Probleme mit einem Mal verschwunden. Oder man lässt Outlook nur noch mit einem Exchange reden.

Quo usque tandem abutere, Mozilla, patientia nostra? Überaschenende Einblicke in das Zertifikatshandling von Firefox und Thunderbird. Einige wichtige abgelaufene Zertifikate werden defaultmäßig als in der Ausnahmeliste geführt. Und natürlich noch einiges mehr.

Überraschung

Mein Kollege schaute gerade etwas konsterniert, als er im ThunderBird einem Zertifikatsproblem nach jagte.

FireFox Advanced Options

Der Klick auf View Certificates und dann auf den Reiter Servers offenbart Erschreckendes:

FireFox freigeschaltete Zertifikate

Was zur Hölle?!

Was sollen diese Freischaltungen für abgelaufene Zertifikate? Was soll die Zertifikate für mögliche Schadcode-Server?

Usability-Problem

Zumindest die Suche nach dem ominösen MD5 Collisions Inc. Zertifikat bringt eine Erklärung: Allen diesen Zertifikaten wurde das Vertrauen entzogen.

Das Problem damit ist, dass man diese Eigenschaft nicht sofort sieht. Da in der Liste auf die individuellen Freischaltungen landen, die man selbst genehmigt hat, ist es nicht so leicht, den Überblick zu behalten. Denn schließlich dient die Liste ja ganz anderen Zwecken:

  • Mozilla stellt eine Liste von Zertifikatsausnahmen bereit, damit der Nutzer lokale Abweichungen der globalen Policy vornehmen kann.
  • Der Nutzer trägt in die Liste Zertifikate ein, denen er vertraut.
  • Mozilla behält sich vor, die Liste der Zertifikatsausnahmen auch selbst zu pflegen.
  • Bisher hat Mozilla zum Schutz der Nutzer dort Zertifikate eingetragen, denen nicht vertraut werden soll.
  • Es ist der Liste nicht anzusehen, ob vertraut oder nicht vertraut wird.

Damit bleibt dem Nutzer nichts anderes übrig, als regelmäßig alle Einträge in der Liste anzuklicken, um die Vertrauenseinstellungen zu überprüfen. Das ist inakzeptabel.

Vor einigen Tagen verloren nach einem Failover auf die Hot-Standby-Maschine ein Großteil dort aktiven Kunden ihre Kommunikationsmöglichkeit. Grund waren divergierende MySQL-Datenbanken, die eigentlich per Replikation in einem synchronen Zustand gehalten werden. Derartige Fehlerzustände werden überwacht und ggf. alarmiert. Aber genau das Monitoring hat versagt.

Was geschehen ist

Eine Appliance für einen klassischen Cloud-Dienst, steht als Hochverfügbarkeitslösung mit zwei Knoten da, von denen der eine den anderen in Sekundenbruchteilen übernehmen kann. Alle laufenden Sessions der Kunden werden dabei übernommen, so dass der Kunde nichts vom Umschalten mit bekommt.

Das hat jahrelang bestens geklappt. Nur eben diesmal nicht. Die Lösung des Problems war einfach: Zurückschalten und Beginn der Fehleranalyse.

Es stellte sich heraus, dass die MySQL-Datenbank auf dem Standby-System schon seit Tagen nicht mehr synchron lief. Sie verweigerte ab einem bestimmten Kommando (Löschen einer Tabelle) das Replay des Replikationslogs. Grund war, dass die Tabelle selbst schon nicht vorhanden war und deswegen nicht gelöscht werden konnte. Die Tabelle selbst war nur ein Überbleibsel eines Tests, also nicht wirklich relevant. Warum sie auf dem zweiten System schon gefehlt hat, ist nicht ganz nachvollziehbar. Vermutlich hat sich irgendwann der Replikations-Filter geändert, so dass die Tabelle erst später Bestandteil der Replikation wurde.

Fakt ist, dass die Replikation nicht mehr lief. Beim Failover traten dann die abstrusesten Effekte auf.

Warum es nicht auffiel

Wesentlich interessanter ist die Frage, warum die fehlerhafte Synchronisation nicht aufgefallen ist. Schließlich gibt es ein Monitoring auf Synchronisations-Diskrepanzen an die ein Alarm angeschlossen ist. Eigentlich hätte es also schon Tage vorher mächtig klingeln sollen.

Das Monitoring lieferte aber immer nur einen Wert von "0" für die Anzahl der Synchronisationsabweichungen. Warum?

Ein Blick in den Quellcode des Monitorings (ein collectd-Plugin) zeigt:

        if ($MK_REPLICATE_CHECK_TABLES && $MK_REPLICATE_CHECK_HOSTS) {
                my $now = time();
                my $fake;
                if ($MK_REPLICATE_CHECK_INTERVAL && $mk_last_run && defined($mk_last_result)) {
                        if ($now - $mk_last_run < $MK_REPLICATE_CHECK_INTERVAL) {
                                $fake = $mk_last_result;
                        }
                }

                if (!defined($fake)) {
                        my @tables = split(/[\s,;]+/, $MK_REPLICATE_CHECK_TABLES);

                        my @fails = do_replication_check(\@tables);
                        my @rechecks = do_replication_check(\@fails, '--wait=60');

                        $fake = scalar(@rechecks);
                        $mk_last_run = $now;
                        $mk_last_result = $fake;
                }

                defined($fake) and plugin_dispatch_values({
                        type => 'mysql_replication_discrepancies',
                        plugin => "XXX",
                        values => [ $fake ],
                        host => $ME,
                });
        } 

Collectd ruft eine read-Funktion regelmäßig auf, um dem Plugin die Möglichkeit zu geben, Daten zu sammeln. Hat das Plugin die Daten ermittelt, schickt es diese mit plugin_dispatch_values an den collectd zurück, der den Messwert an die verschiedenen write-Funktionen der Ausgabe-Plugins übermittelt. Letzteres ist u.a. der RRD-Writer.

In diesem Fall fällt auf, dass das Plugin nur alle $MK_REPLICATE_CHECK_INTERVAL Sekunden überhaupt eine Messung macht. In der Zwischenzeit liefert es den letzten Messwert immer wieder aus.

Weiterhin auffällig ist, dass der Messwert selbst die Anzahl der Tabellen enthält, die nicht synchron sind. Dazu übergibt er die zu überwachenden Tabellen der eigentlichen Messfunktion und diese liefert ihm die Liste der Tabellen, die nicht synchron sind.

In einer zweiten Runde werden – mit einer Wartezeit von bis zu einer Minute – die Tabellen angeschaut, die sich verändert haben. I.d.R. also die Tabellen, die häufigen Änderungen unterliegen. Diese werden nach einem deutlich aufwendigeren Verfahren auf Synchronität untersucht. Es ist offenbar sinnvoll, die statischen Tabellen in einer schnellen ersten Runde schon auszusortieren.

Was dann immer noch nicht synchron ist, bleibt übrig und erhöht den Rückgabewert um eins.

Dieser Teil der Funktion schaut auf den ersten Blick ganz normal aus.

Wie funktioniert aber nun die Messung?

Die eigentliche Messfunktion ist folgende:

        sub do_replication_check {
                my ($tables, $add_args) = @_;

                $add_args or $add_args = '';

                my %results;
                for my $t (@$tables) {
                        my $arg = ($t =~ /\./) ? "--tables=$t" : "--databases=$t";
                        my $out = `mk-table-checksum --algorithm=ACCUM $arg $add_args --tab $MK_REPLICATE_CHECK_HOSTS 2>&1`;
                        my @out = split(/[\n\r]+/, $out);
                        my @headers = split(/\t/, $out[0]);
                        for my $i (1 .. $#out) {
                                $out[$i] or next;
                                my @c = split(/\t/, $out[$i]);
                                scalar(@c) == scalar(@headers) or next;
                                my $h = { map {$headers[$_], $c[$_]} (0 .. $#headers) };
                                $results{$h->{DATABASE} . '.' . $h->{TABLE}}->{$h->{HOST}} = $h;
                        }
                }

                my @fails;
                for my $k (values(%results)) {
                        ref($k) eq 'HASH' or next;
                        my @r = values(%$k);
                        @r > 1 or next;
                        my $h = $r[0]->{CHECKSUM};
                        for my $j (1 .. $#r) {
                                my $i = $r[$j];
                                $h eq $i->{CHECKSUM} and next;
                                push(@fails, $i->{DATABASE} . '.' . $i->{TABLE});
                                last;
                        }
                }

                return @fails;
        }

Man kann sicher über den Stil der Perl-Programmierung lästern, aber das ist nicht das Thema. Interessanter ist die Frage, was der Code tut.

Er lässt sich vom Programm mt-table-checksum die Liste der Prüfsummen über die einzelnen Tabellen geben. Diese parst er und vergleicht anschließend, ob die Prüfsummen pro gefundener Tabelle auf beiden Systemen überein stimmt.

Hat er unterschiedliche Prüfsummen für die Tabellen gefunden, so wird die Tabelle als unsynchronisiert zurück gemeldet.

Was kann daran schon schief gehen?

Ich schaue mir die Ausgabe des Programms mal direkt an:

# mt-table-checksum ...
-bash: mt-table-checksum: command not found

WTF?!

Der Programmcode ignoriert die erste Zeile (die mit der Fehlermeldung) und liest dann die Liste der Tabellen mit ihren Prüfsummen ein (die ist leer). Anschließend vergleicht er, ob er für die gefundenen Tabellen (also keine) Unterschiede bei den Prüfsummen feststellen kann (was nicht möglich ist). Also kommt er zum Schluss, dass keine Unterschiede vorliegen.

Keine Unterschiede zwischen den beiden MySQL-Instanzen heißt also, nach Logik des darüber liegenden Monitorings, dass die Synchronisation in Ordnung ist.

Was wirklich schief gelaufen ist

Der eigentliche Fehler der Messfunktion besteht darin, dass sie keine Validitätsprüfung der Ausgabe gemacht hat.

Sie bekommt eine Liste von Tabellen und hat dann zumindest zu prüfen, ob diese Tabellen überhaupt Prüfsummen geliefert haben! Würde das geprüft, wäre das Fehlen des externen Programms instantan aufgefallen.

Man kann natürlich auch argumentieren, dass der Errorcode des Programmaufrufs zu prüfen gewesen wäre. Oder die Existenz des Programms selbst. Oder, oder ... Am Ende läuft es darauf hinaus, dass die erwartete Ausgabe vorliegt. Schließlich gibt es ja auch noch viele andere Möglichkeiten, warum das externe Programm seinen Job nicht erledigen konnte.

Es wäre nun leicht, diesen Test hinzu zufügen. Allerdings ist das eine fremde Appliance und da geht der Weg über den Hersteller-Support.

Was wir tun können, ist das fehlende Programm nachzuinstallieren. Es ist im Rahmen eines Updates verschwunden, als die Datenbank dieses Programm durch das wesentlich flexiblere und robustere pt-table-checksum ersetzt hat. Ja, das ist schon eine ganze Weile her.

Überraschende Nicht-Lösung

Nachdem nun das betreffende Programm mk-table-checksum installiert war (wobei der Alarm an sprang) und manuell die Datenbank wieder in Sync gebracht wurde (so dass der Alarm verstummte), schien alles soweit in Butter.

Allerdings zeigte sich in der darauf folgenden Nacht, dass da noch ein anderer Fehler drin steckt.

Über einige Stunden schwankte der Messwert, den collectd einsammelte, zwischen 0.1666, 0.25, 0.3333 und 0.5. Alle paar Minuten ergab sich ein anderer Wert.

Zur Erinnerung: Der Messwert ist die Anzahl der unsynchronisierten Tabellen!

Erst die Dokumentation von collectd brachte die Lösung: Wenn mehrere Messwerte in einem sehr kurzen Zeitfenster eingehen, werden sie von collectd gemittelt und dieser Mittelwert wird an die write-Funktionen übermittelt. Die Messwerte sind klare Brüche: Einer von zwei, drei, vier, ... Messungen hatte eine Eins, der Rest Null geliefert.

Wie können aber viele Messwerte in so kurzer Zeit eingehen?

Zur Erinnerung: collectd ruft die read-Funktion regelmäßig auf. Also auch dann, wenn die schon aufgerufene Funktion sich noch nicht beendet hat!

Es liefen also zwei oder mehr Prüfungen parallel. Und vermutlich war zu dem Zeitpunkt die Datenbank mächtig belastet. Es hat alles gedauert, auch die Tests. Als die Last nachließ, wurden alle Prüfungen zusammen fertig.

Logischerweise hinkt eine schwer belastete Datenbank auch in der Replikation hinterher. Es ist also nur natürlich, wenn einer der Messungen dieses feststellt.

Also Ticket Nummer zwei beim Hersteller: Verhindern der Doppelausführung.