Gestern habe ich viel zu lange darauf verwendet, einen kniffligen Bug zu suchen. Am Ende stellte es sich heraus, dass ich es geschafft hatte, einen Bug zu produzieren, der genau einmal im Jahr zuschlägt: Am Tag nach der Zeitumstellung auf Sommerzeit!

Was hatte ich gemacht? Ganz vereinfacht sah der PHP-Code so aus:

$exampleDay = ( new \DateTime() )->modify( '- 1 day' )->setTime( 0, 0 );
$timestamp1 = ( clone $exampleDay )->modify( '+ 2 hours' );
$timestamp2 = ( clone $exampleDay )->modify( '+ 3 hours' );

Es ging darum, Testdaten für eine komplexe Statistikberechnung zu erzeugen. Die Testdaten waren der Einfachheit halber immer relativ zum aktuellen Datum angegeben. Die Datumswerte wanderten in die Datenbank und am Ende wurde geprüft, ob die Statistik die gewünschte Anzahl Datensätze gezählt hatte. Tief in der Statistik-Definition wurde auf diesen Werten ein „COUNT( DISTINCT … )“ ausgeführt in SQL. Letzte Woche geschrieben, lief durch, committet und gut.

Montag morgen war dann die E-Mail im Postfach, dass die Statistikfunktion in dem Test einen zu kleinen Wert geliefert hat. „Failed asserting that 2 matches expected 3.“ Ein paar Dinge waren seitdem committet worden, aber nichts was auch nur in die Nähe dieser Codestelle gelangte. Und noch besser: Der Test ging auch lokal schief, und das selbst mit dem Code-Stand von letzter Woche, mit dem er da noch durchgelaufen war.

An dieser Stelle bin ich jetzt zugleich ein bisschen stolz auf mich und ärgere mich ziemlich: Mein Bauchgefül hat mir nämlich sehr schnell gesagt, dass die einzig andere Änderung die Zeitumstellung Sonntag Nacht gewesen war. Aber weil das ja relativ absurd wäre habe ich doch noch lange an anderen Stellen herumgesucht und herumprobiert. Letztlich lag es aber genau daran.

Wer es ausprobieren möchte, der Code zum Initialisieren der willkürlich gewählten Testdaten noch mal mit dem festen Datum von Sonntag:

$exampleDay = \DateTime::createFromFormat( 'Y-m-d H:i:s', '2021-03-28 00:00:00' );
$timestamp1 = ( clone $exampleDay )->modify( '+ 2 hours' );
$timestamp2 = ( clone $exampleDay )->modify( '+ 3 hours' );
echo "ts1 = {$timestamp1->format( 'Y-m-d H:i:s' )}\n";
echo "ts2 = {$timestamp2->format( 'Y-m-d H:i:s' )}\n";
echo "ts1 == ts2 -> " . ( $timestamp1 == $timestamp2 ) . "\n";
echo "ts1 === ts2 -> " . ( $timestamp1 === $timestamp2 ) . "\n";
echo "ts1->getTimestamp() === ts2->getTimestamp() -> " . ( $timestamp1->getTimestamp() === $timestamp2->getTimestamp() ) . "\n";

Und das Ergebnis:

ts1 = 2021-03-28 03:00:00
ts2 = 2021-03-28 03:00:00
ts1 == ts2 -> 1
ts1 === ts2 ->
ts1->getTimestamp() === ts2->getTimestamp() -> 1

Der erste Teil ist hier eigentlich klar: An diesem Tag gibt es kein 2:00 Uhr, da ja genau zu diesem Zeitpunkt die Uhr auf 3:00 Uhr vorgestellt wird. Der Zeitpunkt heißt also offiziell „3:00″ und entsprechend gibt PHP dann den Timestamp auch aus. Auf den ersten Blick unverständlich ist dann aber der zweite Teil: Wenn von Mitternacht aus 3 Stunden vergehen, ist es ja an diesem Tag eben nicht 3 Uhr sondern 4 Uhr. Hier schlägt dann wohl die Art zu, wie PHP das umrechnet: Ich vermute, dass PHP aus meinen Modify-Angaben einen Zeit-String wie „2021-03-28 03:00:00″ baut und dann schaut, ob es den gibt oder ob man etwas ändern müsste. So in etwa als wenn man „2021-02-30″ reinreichen würde und PHP dann merkt, dass es den Tag nicht gibt und daraus „2021-03-02″ macht. Und da es 3:00 ja gibt, bleibt das dann halt so, auch wenn es aus modify-Sicht Quatsch ist.

Genau genommen ist das also nicht mein Bug, sondern ein Bug in PHP. Ich habe es unter PHP 7.4.16 ausgeführt. Für die Zeitumstellung im Herbst gibt es im PHP-Trac eine umfangreichere Liste an offenen Bugs, und auch sonst sind da diverse teils seit Jahren bekannte Bugs in der DateTime-Library gelistet. Der Code ist wohl komplex und müsste eigentlich neugeschrieben werden. Es scheint auf jeden Fall von der eingestellten Zeitzone abzuhängen und nur aufzutreten, wenn man eine Zeitzone wie „Europe/Berlin“ eingestellt hat. Es klappt in UTC. Dazu einfach vor dem Beispielcode von oben das hier ausführen:

date_default_timezone_set( 'UTC' );

Und schon:

ts1 = 2021-03-28 02:00:00 UTC
ts2 = 2021-03-28 03:00:00 UTC
ts1 == ts2 ->
ts1 === ts2 ->
ts1->getTimestamp() === ts2->getTimestamp() ->

Das macht Sinn, denn in UTC gibt es ja keine Sommerzeit-Umstellung. In diesem Bug-Eintrag verrät der Autor etwas über die Interna der DateTime-Klasse:

But what happens is that PHP converts it first to UTC time, which ends up comparing 2016-12-31 23:00 to 2017-09-30 22:00 – and then the algorithm gets even more confused and messes up.

Etwas ähnliches wird hier ja wohl auch passieren:

• Mitternacht wird intern zu 23:00 UTC umgerechnet. Dann werden 2 Stunden addiert, das ergibt 1:00 Uhr UTC. Das wird umgerechnet zu 2:00 MEZ, und dann muss ja noch die Zeitumstellung angewandt werden. Also wird 3:00 MESZ draus.
• Mitternacht wird intern zu 23:00 UTC umgerechnet. Dann werden 3 Stunden addiert, das ergibt 2:00 Uhr UTC. Das wird umgerechnet zu 3:00 MESZ. Hier geht nun irgendwas mit der Zeitzonen-Änderung schief, denn in MESZ wäre es ja eigentlich 4:00 Uhr.

Ohne in den PHP-Quellcode zu schauen kann ich das gerade nicht genauer erklären. Das Problem tritt jedenfalls nur auf, wenn man genau die Stunde der Zeitumstellung trifft. Die Minuten sind dabei egal.

Für meinen Test sind die Uhrzeiten jedenfalls völlig egal. Um also nicht nächstes Jahr um diese Zeit wieder einen fehlgeschlagenen Test zu haben, setze ich die Uhrzeit nun einfach auf 12 und 13 Uhr und dann ist gut.