~cg


· Impressum · Datenschutz ·

Mini-Post-Mortem fehlgeschlagene DB-Migration pixelfed.de

Fri 18 December 2020

Am Wochenende hatte ich - trotz automatischer Tests - ein fehlgeschlagenes Update von pixelfed.

Der Fehler war mir neu, daher will ich kurz aufschreiben was der Grund war.

Ausfall

Bei Updates vom pixelfed-repo baut mein Jenkins automatisch ein neues Docker-Image, pusht es nach zknt/pixelfed und deployed mit dem frischen Image ein Staging-System. Dort laufen eine Reihe (äußerst oberflächlicher) Selenium-Tests, sind diese OK wird die Image-ID aufs Produktiv-System geschoben und pixelfed.de dort aktualisiert.

Das funktioniert soweit ganz gut, bis auf letztes Wochenende, da meldete das Monitoring plötzlich einen Ausfall.

Ich schaute also kurz ins Log, fehlgeschlagene Datenbank-Migration, da ist nicht auf den ersten Blick sichtbar wo der Fehler liegt. Also erstmal Rollback auf das Vorgänger-Image, Dienst starten, läuft. Prima, weiter Wochenende.

Fehlersuche

Am Montagabend wollte ich dann nachschauen was eigentlich passiert ist.

Interessant war ja das der Fehler im Testsystem nicht aufgetreten ist, es also nicht bloß kaputte Software sein sollte.

Die Fehlermeldung war ja eindeutig:

1
2
3
4
5
6
Migrating: 2020_12_13_203138_add_uuids_to_failed_jobs_table

In Connection.php line 678:

SQLSTATE[42S21]: Column already exists: 1060 Duplicate column name 'uuid' (
SQL: alter table `failed_jobs` add `uuid` varchar(191) null after `id`)

Und die zugehörige Migration ist auch sehr übersichtlich, es wird genau nur diese eine Spalte der Tabelle failed_jobs zugefügt:

1
2
3
4
5
6
public function up()
{
    Schema::table('failed_jobs', function (Blueprint $table) {
        $table->string('uuid')->after('id')->nullable()->unique();
    });
}

In der Datenbank nachgeschaut ist die Spalte da:

1
2
3
4
5
6
MariaDB [pixelfed]> describe failed_jobs;
+------------+---------------------+------+-----+---------------------+----------------+
| Field      | Type                | Null | Key | Default             | Extra          |
+------------+---------------------+------+-----+---------------------+----------------+
| id         | bigint(20) unsigned | NO   | PRI | NULL                | auto_increment |
| uuid       | varchar(191)        | YES  |     | NULL                |                |

und anscheinend auch frisch angelegt, denn sie ist komplett leer:

1
2
MariaDB [pixelfed]> select uuid from failed_jobs WHERE uuid != NULL;
Empty set (0.118 sec)

Ich habe also zuerst die Migration händisch zurückgerollt indem ich die Spalte gelöscht habe. Später wird wichtig dass das Ewigkeiten (2:30 Minuten!) gedauert hat:

1
2
3
MariaDB [pixelfed]> ALTER TABLE failed_jobs DROP COLUMN uuid;
Query OK, 0 rows affected (2 min 25.940 sec)
Records: 0  Duplicates: 0  Warnings: 0

Vom App-Server aus die Migration erneut ausgeführt trat derselbe Fehler auf. Die Migration bricht ab, und beim nächsten Starten die bekannte Fehlermeldung: Die Spalte existiert schon. Der SQL-Treiber quittiert den Abbruch übrigens mit "Server has gone away.".

Moment, server has gone away, das heisst die Verbindung wurde unterbrochen? Und das Löschen der Spalte hat Minuten gedauert?

Die Fehlkonfiguration

Das ist es, und das ist auch der Unterschied zum Staging-System. Dort steckt die Datenbank in einem Docker-Container neben der Applikation.

Produktiv ist es ein Datenbank-Cluster, vor dem haproxy Last verteilt. Und das mit nahezu Standardwerten bei den Timeouts:

1
2
3
4
defaults
        .....
        timeout client  50000
        timeout server  50000

Der Load Balancer hat also schlicht nach 50 Sekunden dicht gemacht. Das Timeout entsprechend hoch gesetzt, und schon läuft die Migration sauber durch.

Änderungen an der Tabelle sind übrigens so lahm da Laravel offensichtlich nie daraus löscht, dort sind alle fehlgeschlagenen Worker-Jobs seit zwei Jahren gespeichert, uns jeder Like/Post/Reply in der Föderation ist ein Job...

Lessons learned