What is it this time? A Bug-Murder-Mystery

What is it this time? A Bug-Murder-Mystery

One of our applications had an interesting bug a while back. We had quite a journey debugging it. Let me tell you how we solved this case.

The Scene

We create ‘Processes’ in our application. The database stores these processes. All month-old processes are deleted every night by a cron job. The code looks something like this:

				
					public function deleteMonthOldProcesses(): void {
    // Get the current date
    $current_date = new DateTimeImmutable();
    // Subtract 30 days from the current date
    $last_month = $current_date->sub(new \DateInterval("P30D"));

    // Prepare statement
    $statement = $database->prepare("DELETE FROM processes WHERE _created > ?");
    $statement->bind_param("s", $last_month->toString());
    $statement->execute();
}
				
			

The test for this code looks a bit like this:

				
					public function testProcessIsDeletedAfterOneMonth(): void {
    $process_a = $this->createProcess();

    // Tick one day later
    $this->clock->tick(60 * 60 * 24);

    $process_b = $this->createProcess();

    // Tick 30 days later
    $this->clock->tick(60 * 60 * 24 * 30);

    // Cleanup the old processes
    $this->deleteMonthOldProcesses();

    $this->assertIsDeleted($proces_a);          // Process A should be deleted
    $this->assertIsNotDeleted($proces_b);       // Process B should still exist
}
				
			

This test worked perfectly for around half a year, until it suddenly started failing. Process A would still be deleted, but Process B would also be gone! What could it be?

The Investigation

While debugging we tried several different things:

  • Adjusting the ticking, maybe the test takes too long? That was not the problem.
  • Maybe there is a bug in our Clock implementation? Nope, nothing strange there.
  • Maybe something strange is happening when creating processes? That code hasn’t changed.

Then it dawned on us. That day was 29th February, a leap day! That usually messes with DateTime implementations. We looked a little bit further into it. That wasn’t it, but we were on the right track.

Before I tell you the answer, take some time and see if you can figure it out yourself!

 

 

 

 

 

 

 

 

 

 

The Culprit

It wasn’t the leap day, but daylight saving time!
 
In the Netherlands in 2024 we start daylight saving time (DST) on March 31st, moving the clock forward by one hour. The DateTimeImmutable implementation takes this into account. This means the following would happen:
 
  • Create Process A on 2024-02-29 13:00:00
  • Move the clock forward by 24 hours
  • Create Process B on 2024-03-01 13:00:00
  • Move the clock forward by 24 hours, 30 times
  • At this point we would cross the DST line, setting the clock forward by one hour. This would make the time: 2024-03-31 14:00:00
  • Then we would subtract 30 days, returning the time to: 2024-03-01 14:00:00
  • Process B is created before that time, thus deleting it.
 
This bug only occurs 30 days before DST, and lasts until DST takes effect. Winter-time would move the clock back one hour, having no impact on this test.

The Verdict

Luckily, the fix was easy enough. We opted to rewrite the code that rewinds to the clock. This time not using days, but pure seconds.

				
					$last_month = $current_date->sub(new \DateInterval(sprintf('PT%dS', 60 * 60 * 24 * 30)));
				
			

This concludes another day of hunting bugs at Moxio. Those pesky insects don’t deserve the time of day 😎.

Picture of Michiel Maas

Michiel Maas