go-kit
Using a Windows color writer with an underlying sync writer negates the benefit of the sync writer
We stumbled upon a weird issue where two goroutines writing to the same go-kit logger would have their logs interleaved even though the logger writes to stdout through a SyncWriter.
As it happens our logger was created with term.NewColorWriter which, on Windows, is implemented in a particular fashion that annihilates the benefits of synchronization, as provided by the SyncWriter.
Namely, the writer iterates over each character and performs a single Write() for each character. When two coroutines use the same logger in that scenario, the color writer - via the SyncWriter - lock and unlocks the mutex for each character. Not is this totally uneffecient, but it also causes the characters to be interleaved as we observed.
I can totally come up with a fix for that in the next couple of days, but I'd like to make sure with you that my approach at solving that is ok to you.
Suggested solution
Basically, I'd write every character in the Windows color writer inside a bytes.Buffer first, then io.Copy that buffer to the real underlying writer. This would restore writing atomicity as well as performance.
I don't expect log lines to be memory heavy (at least, not to the extent where this two-pass write would cause a real issue) so I assume this approach is fine.
What do you think ?
Yeah, that is not a good behavior. Looking at the code I'm not sure the suggested solution will preserve the proper coloring behavior in the general case. It looks to me like—at a minimum—system calls to the windows console to change the current color mode need to be made in between writing runs of characters with the same color attributes.
If that assessment is correct, then this requirement means buffering as suggested only works correctly if color codes only appear at the beginning and ending of the data passed to Write. That condition holds for the implementation of NewColorLogger, but it is not a constraint I'd like to see put on the lower level color writer code.
We should fix this somehow, but we will have to proceed carefully.
One more thing. As a workaround for now, you can use log.NewSyncLogger to serialize each call to Log rather than synchronizing the Writer until we can work out an appropriate fix for this issue.