Wir haben ein Problem beobachtet, bei denen unsere Dags nicht zur spezifizierten Zeit, sondern konsistent zu einer scheinbar zufälligen Zeit ausgeführt wurden.
Erwartetes Verhalten:
Wir haben eine Jobkette bestehend aus drei Dags, die täglich eingeplant sind auch hintereinander laufen sollten. Dazu haben wir jeweil ein start_date definiert mit den Werten 22.11.2021 11:30 (12:30 / 13:30).
Beobachtung:
Die Airflow Dags laufen zur gleichen zeit, obwohl sie ganz klar 1 Stunde voneinander eingeplant wurden. Zudem laufen sie zu einer scheinbar willkürlichen Zeit, die nicht durch eine Zeitverschiebung durch unterschiedliche Zeitzonen erklärbar ist.
Hintergrundinformationen:
Um dieses Mysterium zu lösen, sind insbesondere folgende 2 Fakten über den Airflow Scheduler wichtig zu wissen, die sich insbesondere auf den start_date Parameter beziehen.
- wenn das start_date in der Vergangenheit liegt und ein schedule_interval festgelegt wurde, wird Airflow versuchen, für jeden verpassten Interval das entsprechende Dag auszuführen, sobald es aktiviert wurde
- “Note that Airflow simply looks at the latest
execution_dateand adds theschedule_intervalto determine the nextexecution_date” – von der offiziellen Dokumentation. Wenn es kein execution_date gibt (weil das Dag zum ersten mal gestartet wurde) wird es zur angegebenen start_date ausgeführt - zusätzlich ist es nützlich zu wissen, dass start_date nur der Startzeitpunkt des schedule_intervals ist, zu dem das Dag ausgeführt werden soll. Angenommen das start_date ist auf 22.11.2021 13:00 gesetzt, schedule_interval ist @daily und es ist jetzt gerade 23.11.2021 08:00 Uhr. Airflow wird überprüfen, ob das Dag innerhalb des Intervals 22.11.2021 13:00 – 23.11.2021 13:00 bereits gelaufen ist, bemerkt, dass wir uns jetzt innerhalb des Intervalls befinden und führt den Dag aus.
Was also passiert ist, ist folgendes:
- Wir haben die Dags deployt und das start_date zu einem Zeitpunkt in der Vergangenheit gesetzt.
- Wir aktivieren die entsprechenden Dags. Es ist ungefähr 12:02.
- Airflow erkennt, dass die Dags schon längst überfällig sind und beginnt, die Ausführung nachzuholen
- nun kalkuliert Airflow die nächste Ausführungszeit (execution_date), indem es die aktuelle Zeit (12:02) nimmt und dazu einen Tag addiert, sodass die zuvor spezifizierten Zeiten 11:30/12:30/13:30 nicht mehr berücksichtigt werden
Und das wars. Wir haben diesen Sachverhalt auch tatsächlich nur einige Minuten bevor wir auf den Blogeintrag Apache Airflow Gotchas gestoßen sind nachvollzogen. In diesem wird unter anderem auch die Berechnung der execution_date erwähnt und implizit auf unser Problem hingedeutet.
Learnings
- als Best Practice sollte man in Betracht ziehen, tatsächliche ein Dag als Jobkette zu erstellen, die die Ausführung und Beziehungen der anderen Dags steuert
- Wenn ein neues dag Deployt wird, sollte darauf geachtet werden, dass das start_date entsprechend in der Zukunft liegt, damit die Ausführung auch zu dem erwartetem Zeitpunkt geschieht.
Private Anekdote
Ein Grund, weshalb wir doch so verwirrt waren, war, dass wir zwei Instanzen mit demselben Problem besaßen. Eine davon hat alle Dags um 12 gestartet, die andere hat alle Dags gegen 3 Uhr früh gestartet. Dies erschien uns vollkommen willkürlich und wild vom Scheduler gewählt und wir hatten am anfang noch auf einen Bug spekuliert. Nachdem wir das Verhalten letzendlich verstanden haben, blieb noch die große Frage Wer oder Wie ein Deployment und Aktivierung der Dags um 3 Uhr Nachts geschehen konnte. Stellt sich heraus, derjenige der an einem Mittwoch Miternacht die Dags auf das Dev System deployt hat – war ich selbst…
