My just-used Go logging idiom and why it is in fact wrong
I've just gotten through writing a Go package and command in which I rolled my own logging. I know, I should probably master the standard log package. But it seems to be a constant that in every new language I fiddle around with I wind up rolling my own logging for whatever reason. Fortunately this time I can not only tell you about my idiom but tell you why it's wrong.
As you might guess from my entry on how nil
is sometimes not
a nil
, the fundamental model is to wrap a buffered
io.Writer
that points to the underlying logging resource (eg a
file) with a interposed implementation that adds a prefix. This is:
type sLog struct { prefix []byte wr *bufio.Writer } func (l *sLog) Write(b []byte) (n int, err error) { var buf []byte buf = append(buf, log.prefix...) buf = append(buf, b...) n, err = log.wr.Write(buf) if err == nil { err = log.wr.Flush() } return n, err }
You then set up a sLog
instance and pass it (well, a pointer to
it) to something as an io.Writer
. The thing doing the logging
calls log.Write(...)
exactly as if it was writing to a normal
file or whatever, your code sticks your prefix on, and you're done.
Extensions to things like timestamps are left as an exercise.
This is a superficially appealing approach; what could be more logical than a pipeline-based approach where we wrap an underlying Writer in something that sticks our additional information on. It feels perfectly Go-ish, with a clever use of interfaces and creating our own implementation of one. And the use of a buffered writer should help avoid the ever-popular issue of partial lines stomping over each other from multiple sources, as we flush only full lines out.
(This code is safer than it looks because wr
is not shared between
different sLog
instances; only the underlying io.Writer behind
it is. This is tricky and should be documented. A shared wr
would
leave us counting on any guarantees bufio makes about multiple
concurrent Write()
s to a shared bufio not interleaving their
output.)
The big problem here is that the semantics are not so much wrong
as misleading. My code here implicitly assumes that Write()
is
only called to write whole lines. This is how you want to (and must)
write unbuffered log lines to avoid output interleaving, but Write()
in general has more broad semantics than 'write whole lines'. A
more specifically restricted interface, such as some of the ones
exposed in the standard log package, would make it clear that
you should only be writing whole lines to the log instead of feeding
it random chunks of partial output.
(I know enough to not log partial lines, but this issue is at least tricky. An interface that only accepts a full line of output makes it obvious what you have to do to use it. And interfaces should be created to say what they mean.)
PS: even this code is not absolutely safe against concurrent writes; it's assuming that the underlying io.Writer that bufio will call when we flush the output is itself basically atomic. For absolute safety we would have to add another layer that serializes writes to that io.Writer. Today's moral is that safe logging in the face of concurrency is a pain in the rear that is best left to other people's code (provided that you can trust it).
|
|