Philipp H was going through some log files generated by their CI job to try and measure how long certain steps in the process took. He took the obvious path of writing code to read the logfiles, parse out the timestamps, and then take the difference between them.
Everything worked fine, until for certain steps, a negative timestamp was reported:
> -1 day, 23:59:59.713529 section cleanup_file_variables
On one hand, having CI jobs finish before they were started was incredibly convenient, and certainly would make their integration much faster. Plus, they could probably get some funding to find the exotic matter which allowed the existence of the wormhole that clearly allowed this inversion of causality.
On the other hand, this was probably a bug.
Here's a snippet from the logfile:
> 2025-08-18T14:49:40.748000Z 00O+section_start:1755528580:cleanup_file_variables
> 2025-08-18T14:49:40.754100Z 00O+Cleaning up project directory and file based variables
> 2025-08-18T14:49:40.461529Z 00O section_end:1755528580:cleanup_file_variables
The format is a timestamp with nanoseconds, followed by a stream identifier (STDOUT vs. STDERR) followed by the actual message.
If you look at the nanoseconds, you might spot something odd: the third timestamp occurs before the previous ones. The obvious conclusion one could draw is that this is a concurrency issue, and the log entries are getting printed out of order. Philipp's naive solution won't work, and he'll need to sort the timestamps before doing the calculation.
But that conclusion is as obvious as it is wrong. Look more closely at those trailing zeroes. They seem a little odd, don't they? Something off?
Here's the Go code which generates the timestamps:
t := now()
// time.RFC3339 doesn't add nanosecond precision, and time.RFC3339Nano doesn't
// use a fixed length of precision. Whilst we could use a custom format, this
// is slower, as Go as built-in optimizations for RFC3339. So here we use the
// non-nano version, and then add nanoseconds to a fixed length. Fixed length
// is important because it makes the logs easier for both a human and machine
// to read.
t.AppendFormat(l.bufStream[:0], time.RFC3339)
// remove the 'Z'
l.bufStream = l.bufStream[:l.timeLen-fracs-additionalBytes]
l.bufStream[len(l.bufStream)-1] = '.' // replace 'Z' for '.'
// ensure nanoseconds doesn't exceed our fracs precision
nanos := t.Nanosecond() / int(math.Pow10(9-fracs))
// add nanoseconds and append leading zeros
leadingZeros := len(l.bufStream)
l.bufStream = strconv.AppendInt(l.bufStream, int64(nanos), 10)
leadingZeros = fracs - (len(l.bufStream) - leadingZeros)
for i := 0; i < leadingZeros; i++ {
l.bufStream = append(l.bufStream, '0')
}
// add 'Z' back
l.bufStream = append(l.bufStream, 'Z')
// expand back to full header size
l.bufStream = l.bufStream[:l.timeLen+4]
This appends the timestamp to the stream, then replaces the timezone indicator (Z) with a .. In calculates the number of nanoseconds, then the number of required leading zeros to get the fixed length. Then it appends the nanoseconds, followed by the leading zeroes, making them trailing zeroes. Whoops.
Now, this Go code doesn't come from some in-house job, but from a major vendor of CI/CD tooling, which is what makes this tiny little bug a WTF. But hey, it's very well commented.
Philipp writes:
We're talking about a modern language like Go here and that really make we wonder, if they do not have a built-in function to format integers to strings with left-padding...
While I'm not a Go expert, I can actually answer this question: Go has made the explicit choice to keep the standard library as small as possible, to the point where loads of things you think should be there aren't. Whether that extends to formatting functions, I'm not certain, but it results of a conscious design choice.
Setting aside whether or not one agrees with this design choice, there's an argument to be had over it. It's not, on its face, automatically wrong.
[Advertisement]
Utilize BuildMaster to release your software with confidence, at the pace your business demands. Download today!
This post originally appeared on The Daily WTF.