inconshreveable/log15 — pull request #30 by inconshreveable (2014-11-03 22:11:11+00:00)
Title: fix potential log record corruption

So I discovered a pretty horrible bug in log15 the other day that could cause corruption of log records when a logger is used concurrently (or by using the Channel/Buffered handlers).

The bug is in the creation of log records:

Ctx: append(l.ctx, normalize(ctx)...),

The thing about the `append()` function is that it feels like an operation that works on an immutable argument because it returns you a new slice. And that's true, really. The slice you pass to append is not mutated.

However, the backing array of the slice *is* mutated. This can cause log record context corruption in a race like this:

goroutine1:
r := &Record{
// ...
Ctx: append(l.ctx, "foo", "bar")
}

goroutine2:
r := &Record {
// ...
Ctx: append(l.ctx, "baz", "quux")
}
goroutine1:
// r could have wrong context values "baz"/"quux" instead of "foo"/"bar"
l.h.Handle(r)

I say "could have wrong context values" because whether or not the record gets corrupted actually depends on the behavior of the Go runtime. If when we initially allocated the slice for l.ctx the runtime chose to allocate the slice with not enough extra capacity for our new context values, it will allocate a new backing array and copy all of the values to it. In this case, the bug is not triggered.

Amusingly, it seems like for small context lengths (<=32 on Darwin), the runtime never chooses to allocate extra capacity and so this bug both never triggers *and* is undetectable by the race detector. This is why the test has the magical value of 34, which was the first size I could find that would trigger the bug.

@ChrisHines please review