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).