CodeSOD: Well Timed Double Checking

Last week's out of order logging reminded Adam R of a similar bug he encountered once.

The log files looked like this:

[2026-01-14 16:40:12.999802][process_name][42][DEBUG][somefilename:01234] A thing happened
[2026-01-14 16:40:12.999997][process_name][42][DEBUG][somefilename:01235] Another thing happened
[2026-01-14 16:40:12.000031][process_name][42][DEBUG][somefilename:01236] A third thing happened
[2026-01-14 16:40:13.000385][process_name][42][DEBUG][somefilename:01237] A fourth thing happened

Note the timestamp on the third log line: it's out of order. But as you can get from Adam's highly anonymized messages, it's actually in the correct order- it's the third thing that happened, and it's the third log line. So clearly, something has gone off with calculating the timestamp.

Now, if you want to ask your OS for time with microsecond precision, you can call gettimeofday, which will populate a timeval struct. That gives you seconds/microseconds since the epoch. gmtime can then be used to convert the seconds portion into something more readable. This is pretty standard stuff- how could someone screw it up?

void Logger::log(const char* message, int level, const char* filename, int line)
{
    time_t now = time();
    struct tm* now_tm = gmtime(&now);

    struct timeval now_tv;
    gettimeofday(&now_tv, NULL);

    char buffer[1024];  // I've simplified this to a fixed-size buffer for expository purposes, but the code DID handle overflow and dynamically resizing the buffer correctly
    snprintf(buffer, sizeof(buffer), "[%04d-%02d-%02d %02d:%02d:%02d.%06d][%s][%s][%s][%32s:%05d] %s\n",
        now_tm->tm_year + 1900,
        now_tm->tm_mon + 1,
        now_tm->tm_mday,
        now_tm->tm_hour,
        now_tm->tm_min,
        now_tm->tm_sec,
        now_tv->tv_usec,
        get_process_name(),
        get_thread_id(),
        log_level_string(level),
        filename,
        line,
        message);

    write_to_log_file(buffer);
}

This C++ function is reconstructed as Adam remembers it. The first four lines highlight the problem: they check the time twice. The call to time() returns the number of seconds since the epoch, which they then convert into a readable time using gmtime. Then they use gettimeofday to get the seconds/microseconds since the epoch. When they print, they use the values from time for every field but microseconds, and then use the microseconds from gettimeofday.

They check the clock twice, and shockingly, get different values each time. And when the clock ticks are near a second boundary, the microseconds can roll back over to zero, creating a situation where log entries appear to go backwards in time.

The fix was simple: just check the time once.

Adam writes:

My suspicion is that this logging function started out printing only seconds, and then someone realized "Hey, wouldn't it be useful to add microseconds to here as well?" and threw in the extra call to gettimeofday() without thinking about it hard enough.

That's a pretty solid suspicion. Adam can't confirm it, because he doesn't work there anymore, and has no access to their source control, and even if he did, the project has been through multiple source control migrations which destroyed or otherwise mangled the history, leaving the root cause as always and forever a mystery.

[Advertisement] Keep all your packages and Docker containers in one place, scan for vulnerabilities, and control who can access different feeds. ProGet installs in minutes and has a powerful free version with a lot of great features that you can upgrade when ready.Learn more.

This post originally appeared on The Daily WTF.