We at Selfnet use Best Practical's open-source ticketing system Request
Tracker (RT) to handle emails sent to support@selfnet.de. For some
reason, I happen to be one of the admins of our RT instance. One day, people
using the RT complained that that its web interface has become
unresponsive. Logging into the RT server, I noticed that the RT server
processes was running at 100% CPU load. Attaching strace to it
showed no activity, meaning that it's
spinning CPU cycles one something internal not interacting with the OS. Doing what every lazy admin
does, I restarted the RT service hoping that this was a single event
caused by cosmic rays or some other glitch.
As you might have already guessed, that wasn't the case and the RT
locked up again. Time for some deeper investigation. So I created a
core dump of the RT processes and inspected it with gdb to figure out
what RT was getting stuck at:
$ gdb perl core.7780
(gdb) bt
#0 0x000055b414603727 in S_regcppush (my_perl=my_perl@entry=0x55b416538010, rex=rex@entry=0x55b41f71d300, parenfloor=<optimized out>, maxopenparen=<optimized out>) at regexec.c:328
#1 0x000055b414609e0a in S_regmatch (prog=<optimized out>, startpos=<optimized out>, reginfo=<optimized out>, my_perl=0x55b41f8acc58) at regexec.c:7361
#2 S_regtry (my_perl=my_perl@entry=0x55b416538010, reginfo=reginfo@entry=0x7ffe4a279360, startposp=startposp@entry=0x7ffe4a279350) at regexec.c:3628
#3 0x000055b4146152b8 in Perl_regexec_flags (my_perl=0x55b416538010, rx=0x55b41f6c5bc0,
stringarg=0x55b41f88a77a "\"... \"[REDACTED].\" <[REDACTED]@[REDACTED].com.br>, \"[REDACTED]\" <[REDACTED]@[REDACTED].com.br>, [REDACTED] <[REDACTED]@gmail.com>, \"[REDACTED] I"..., strend=0x55b41f88c69f "",
strbeg=0x55b41f88a77a "\"... \"[REDACTED].\" <[REDACTED]@[REDACTED].com.br>, \"[REDACTED]\" <[REDACTED]@[REDACTED].com.br>, [REDACTED] <[REDACTED]@gmail.com>, \"[REDACTED] I"..., minend=<optimized out>, sv=0x55b4193b5d80, data=0x0, flags=1) at regexec.c:3158
#4 0x000055b4145a2453 in Perl_pp_subst (my_perl=0x55b416538010) at pp_hot.c:2980
#5 0x000055b41459c7a6 in Perl_runops_standard (my_perl=0x55b416538010) at run.c:41
#6 0x000055b414522775 in S_run_body (oldscope=<optimized out>, my_perl=<optimized out>) at perl.c:2483
#7 perl_run (my_perl=0x55b416538010) at perl.c:2411
#8 0x000055b4144fb9fd in main (argc=<optimized out>, argv=<optimized out>, env=<optimized out>) at perlmain.c:116
Seems like RT is busy parsing Email addresses using regular
expressions, nothing out of the ordinary given that RT is written in
Perl. To figure out how exactly RT got there, we'll need to know which
file and which line is currently being executed. A bit of googling
brought up this answer on stackoverflow, explaining how to access the Perl interpreter's internal state.
With this in mind we can get to what we want to know.
(gdb) p my_perl->Icurcop->cop_file
$2 = 0x55b4193baf00 "/usr/share/perl5/Email/Address/List.pm"
(gdb) p my_perl->Icurcop->cop_line
$3 = 310
Looking into that file, we now know for sure, that RT is busy parsing
email addresses using some kind of complex regex.
if ( $line =~ s/^($CRE{'mailbox'})($RE{cfws}*)(?=,|;|$)//o
|| ($line =~ s/^($CRE{'obs-mailbox'})($RE{cfws}*)(?=,|;|$)//o and $obsolete = 1)
Since I don't know Perl and have absolutely no intention of learning
it, I was more or less lost at this point. To at least make our RT
instance usable again, I asked the admin of our mail server if there
was an email stuck in the queue that contained the email address from
the stack trace. After confirming that this was the case and the email
was just spam they deleted the email from the queue gave me a copy for
further examination.
I could have stopped here since our RT was now
back in service, but I wasn't exactly happy with a spam mail bringing
down our ticket system. Knowing that Email::Address::List is used to
extract email addresses from incoming mails, I hacked a simple Perl
script that parses the offending email using Email::Address::List. As
to be expected, this script didn't finish in timely manner. Some random
editing and checking if parsing still takes excessively long yielded
this concise test case:
use strict;
use Email::Address::List;
my $header = <<'END';
"AAAA" <a@a.com.br>, "...
"A A A A A A A." <a@a.com.br>, "A A A A A" <aa@a.com.br>,
END
my @list = Email::Address::List->parse($header);
foreach my $e ( @list ) {
if ($e->{'type'} eq 'mailbox') {
print "an address: ", $e->{'value'}->format ,"\n";
}
else {
print $e->{'type'}, "\n"
}
}
Running this script with Email::Address::List < 0.06 takes 3 seconds,
much too long given the size of the input. Doing some small edits,
such removing "... from the first line brings parsing speed back to
instant. I sent that test case to Alex Vandiver since his name was next
to copy of the Email::Address::List module on CPAN. He was able to reproduce
this issue and coordinated a new release of that module:
metacpan.org/release/BPS/Email-Address-List-0.06
Changes for version 0.06 - 2019-01-02
Changes to address CVE-2018-18898 which could allow DDoS-type attacks. Thanks to Lukas Kramer for reporting the issue and Alex Vandiver for contributing fixes.
Fix pathological backtracking for unkown regex
Fix pathological backtracking in obs-phrase(i.e. obs-display-name)
Fix pathological backtracking in cfws, quoted strings
And that is the story on how being curious can lead to greater good.
Random notes:
In the process of writing that blog post I needed to recreate the gdb
output from when the issue occurred. I still had the coredump around,
but Perl has been upgraded, so I couldn't just run $ gdb perl
core.7780 to examine the core dump. After extracting the proper
version of Perl including matching debug symbols, I wasn't able to
convince gdb to use the extracted debug symbols. Luckily, there's
eu-unstrip from elfutils that - as the name implies - does the
inverse of strip, thus combining a stripped executable and debug
symbols into a an executable with debug symbols that's usable by gdb.
Wie einige im August vielleicht gemerkt haben, hat es von Montag Nacht (14. August 2017) bis Mittwoch Abend einige technische Probleme bei uns gegeben. Diese haben dazu geführt, dass das Selfnet-WLAN nicht mehr funktioniert hat. Doch was war die Ursache dafür?
Alles fängt damit an, dass einige virtuelle Maschinen nicht mehr normal funktionieren. Schnell ist klar, dass dies kein Problem der jeweiligen virtuellen Maschinen, sondern unseres Storage-Clusters ist.
Unser Storage-Cluster basiert auf Ceph und stellt allen virtuellen Maschinen die Festplatten und damit etwa 100 TiB Speicherplatz bereit. Es besteht aus 3 Knoten (Nodes): Ein großer Klotz in Vaihingen (storage-1), ein weiterer großer Klotz in der Heilmannstraße (storage-2) und ein kleinerer nochmals in Vaihingen (storage-3). In der Theorie sollte der Cluster auch noch weiterhin funktionieren, wenn ein Knoten ausfällt.
Die erste Diagnose war, dass der Link (Verbindung) von storage-2 zum Core-Router dort wackelig ist. Deshalb entscheidet man sich dazu storage-2 komplett abzuschalten. Die Hoffnung: Das Ceph sammelt sich dann und verteilt die Inhalte neu, damit wieder hinreichende Redundanz sichergestellt ist. Das tritt jedoch entgegen unserer Annahme nicht ein.
Virtuelle Maschinen, welche viel Disk-IO (also Lese- und Schreiboperationen) verursachen (z.B. Mail, DHCP wegen logging oder Radius), stellten daher sofort ihren Dienst ein. Auf wundersame Weise überleben die IRC und Jabber/XMPP Server die Zeit ohne funktionierende Festplatten.
Erste Versuche den Link (Glasfaser und Optik) zwischen storage-2 und heilmann-core zu reparieren, scheiterten an einem SFP (Optik), auf dessen Schachtel Intel draufstand aber wohl doch nicht Intel drin war und deshalb die Netzwerkkarte den SFP nicht akzeptiert.
Um das Netz für unsere Mitglieder wieder halbwegs verfügbar zu machen, wird dann in den Morgenstunden des Dienstags (etwa zwischen 5 und 6 Uhr) auf kvm-dev (Virtualisierungsserver) die virtuelle Maschine 'notfall-1' mit lokaler Festplatte erzeugt und dort mit Ansible (schick, wa?) ein resolver und DHCP-Server installiert. Glücklicherweise hat einer von uns noch von der DHCP-Migration vor einer Woche die von den Update-Skripten erzeugte DHCP-Konfiguration im /tmp Ordner liegen. Sonst wäre das deutlich schwerer gewesen...
Auch nachdem erfolgreich in storage-2 und den heilmann-core neue SFPs und neue Patchkabel eingebaut wurden, will sich das Ceph immer noch nicht wieder zusammenbauen. Mal geht es aufwärts mit der Anzahl an 'guten' Objekten, um dann wieder zu sinken. So läuft das dann bis Mittwoch Abend. Im tcpdump zwischen den Storage-Kisten fallen uns recht viele ACKs auf, aber mit iperf laufen dennoch 10GBit/ über den Link...
Einem unserer aktiven Mitglieder fällt dann im IRC Chat auf, dass
ich hab grad die vermutung, dass der link zwischen heilmann-core-2 und -1 hin ist
ich hatte gerade jede menge loss dazwischen und testweise das routing umgebogen, dass der weg zu storage-2 nicht über den link geht
Daraufhin fängt sich Ceph wieder. Im weiteren Verlauf der Dinge stellt sich dann heraus, dass nicht der link zwischen den beiden Core-Routern in der Stadt wackelig ist, sondern die Strecke vom vaih-core-1 zum heilmann-core-2 wackelig ist. Auch das Tauschen und Putzen aller Glasfasern und SFPs ändert daran nichts.
Mit dem Routing über den kade-core hat sich das Ceph dann auch im nu zusammen gebaut, aber manche virtuelle Maschinen wollen gar nicht booten. Andere virtuelle Maschinen kommen nicht über die Initramdisk hinaus. Alles ganz komisch.
Also haben wir eine der Festplatten (der virtuellen Maschinen) mit rbd map als Blockdevice auf einem der kvm-hosts (Virtualisierungsserver) gemapped und mit cat /dev/rbd0 | xxd einen Dump (Speicherauszug) erstellt. Feststellung: Nach ein paar Megabyte bleibt die Operation hängen und will sich weder durch ^C noch mit kill -9 beenden lassen. Vermutlich findet bei rbd map die Kommunikation mit den storage-nodes im Kernel statt und der syscall bleibt hängen. Das ist zum Debuggen natürlich gar nicht schön.
Deshalb haben wir mit rbd import die Platte auf stdout (Standardausgabe) geschrieben und festgestellt, dass auch dies nach ein paar MB hängen bleibt, sich aber im Gegensatz zu der Methode davor mit ^C abbrechen lässt. Ein wenig Debuggen mit strace zeigt, dass sich rbd mit einem OSD (so heißen bei Ceph die Daemons (Dienste), die an den Platten im Storage dranhängen) auf Port 6914 verbinden wollte, aber ein "connection refused zurück kam". netstat bestätigt, dass da tatsächlich ein OSD auf dem Port lauscht. Es stellt sich heraus, dass in der Firewall auf allen Storage-Knoten nur Ports 6700-6900 offen waren, Ceph aber die Ports 6800-7300 benützt. Interessanterweise steht in den Release notes von Ceph nichts von der Portänderung sondern nur in den verschiedenen Versionen der Dokumentation.
Nachdem das repariert war, wollen auch alle virtuellen Maschinen wieder hochfahren. Ein stichprobenartiges fsck (Dateisystemüberprüfung) fand nirgendwo Fehler.
Woran lag's also?
Ursächlich war die kaputte Glasfaserstrecke zwischen Vaihngen und der Innenstadt. Dies hat zu Paketverlusten geführt aber der Link war noch da und deshalb sah das Routing keinen Grund, die betroffene Strecke nicht zu nehmen. Dem Ceph kann man hier nichts vorwerfen, Zitat:
und halb-kaputtes "Kabel" fickt am Ende jedes System
Das zweite Problem war, dass sich das Ceph nach Abschalten von einem der drei Knoten nicht wieder zu einem funktionierendem Zustand zurückkehren konnte. Weshalb wissen wir noch nicht. Die Firewallregeln von oben kann man ausschließen, da alle anderen OSDs auf nicht gesperrten Ports liefen.
Das dritte Problem war, dass die Firewall auf den storage-nodes falsch konfiguriert war. Weshalb das davor nicht aufgefallen ist wissen wir nicht genau. Wir vermuten, dass die OSD's bis jetzt immer zufällig auf den 'freigeschalteten Ports' liefen und das mit der neuen Version von Ceph sich der Bereich der Portnummern geändert/erweitert hat.
Was wollen wir noch verbessern?
Wir vermuten, dass durch die OSD-Crashes wegen kaputtem Netz einige Objekte nur auf storage-2 ge-ack-t waren, der restliche cluster hat diese dann nach dessen abschalten nicht gefunden und I/O blockiert. Deshalb konnten storage-1 und storage-3 sich nach abscahlten von storage-2 nicht mehr syncen.
Um das in Zukunft zu verhindern überlegen wir uns gerade wie wir unser Routing (OSPF) verbessern können. Folgende Möglichkeiten werden im Moment diskutiert um bei defekten Verbindungen die Routen möglichst schnell über andere Verbindungen laufen zu lassen:
-
BFD (Bidirectional Forwarding Detection): Hierbei werden zwischen zwei Routern viele Pakete hin und hergeschickt. Sollten einige Pakete nicht oder nicht intakt ankommen wird der Link automatisch deaktiviert. Die Folge: OSPF baut die Routen neu und der Pakete nehmen einen anderen Weg.
-
OSPF Metriken: Der defekte Link (Glasfaserstrecke) ist die (geographisch) längste die wir im Moment haben. Es bietet sich hier an die Metriken aller Links im Wohnheimnetzwerk über ihre Entfernung voneinander in Kilometern zu setzen.
-
Carrier-Delay: Wenn ein Link instabil ist und häufig an/aus geht (flappt) müssen alle OSPF Teilnehmer (Router) ihren "Shortest Path Baum" neu bauen. Carrier-Delay sorgt dafür, dass ein Link erst dann verwendet wird wenn dieser eine gewisse Zeit stabil läuft.
-
Dampening: Immer wenn ein Link down geht, bekommt dieser Link einen Malus (Penalty). Sollte diese über einen Schwellenwert steigen wird der Link deaktiviert. In bestimmten Zeitabständen wird der Penalty Wert halbiert.
The last time, I analyzed the the hardware and figured out where the
firmware is stored. So let's dump it. The datasheet
tells us, that the flash IC has an SPI interface. Now we need something
that adapts SPI to a more common interface like preferably USB. There
are several devices to to this:
- Use some microcontroller and write firmware for it that reads the
SPI flash and dumps its contents via UART/USB. Downside: have to
write code for microcontroller, hard to debug
- Bus Pirate already
supports SPI flashes. Unfortunately, Selfnet doesn't have one.
- FTDI also makes USB to SPI converters besides USB to UART. I didn't
have one at hand either, but I've had existing code for using
certain FTDI bridges as USB - SPI converts.
So I purchased the FT2232H Mini Module
and built an adapter to connect the SPI flash to it.
The FT2232H contains a so called MPSSE (Multi-Protocol Synchronous
Serial Engine) to do SPI. Side note: FTDI claims that the MPSSE also
supports I²C, but since the FT2232H doesn't have open-drain outputs
and has some glitching issues, it's really painful to implement. Since
my existing code was developed on Windows™, it used the proprietary
FTD2XX driver. After some fiddling, I got ftd2xx to work on python 3. Sorry, libftdi people :(
Implementing the protocol used by the SPI flash was rather
straightforward since its datasheet is available. One particular nice
aspect of the protocol is that you can read an arbitrary amount of data
after sending the start address. So I hacked an IPython notebook to
dump the flash. Magically, it worked the first time, therefore I didn't
bother to clean it up to make it publishable.
That's inside the romdump:
$ binwalk romdump
DECIMAL HEXADECIMAL DESCRIPTION
--------------------------------------------------------------------------------
94976 0x17300 U-Boot version string, "U-Boot 1.1.3 (Dec 4 2013 - 08:55:41)"
131584 0x20200 LZMA compressed data, properties: 0x5D, dictionary size: 8388608 bytes, uncompressed size: 3515396 bytes
1441792 0x160000 Squashfs filesystem, little endian, version 4.0, compression:lzma (non-standard type definition), size: 5051300 bytes, 627 inodes, blocksize: 131072 bytes, created: Fri Jun 20 05:19:24 2014
8126480 0x7C0010 XML document, version: "1.0"
In the next post, we'll dig into the romdump.