Tag Archives: design

Context is for cancelation

In my previous post I suggested that the best way to break the compile time coupling between the logger and the loggee was passing in a logger interface when constructing each major type in your program. The suggestion has been floated several times that logging is context specific, so maybe a logger can be passed around via a context.Context. I think this suggestion is flawed (as are most uses of context.Value, but that’s another story). This post explains why.

context.Value() is goroutine thread local storage

Using context.Context to pass a logger into a function is a poor design pattern. In effect context.Context is being used as a conduit to arbitrarily extend the API of any method that takes a context.Context value. It’s like Python’s **kwargs, or whatever the name is for that Ruby pattern of always passing a hash. Using context.Context in this way avoids an API break by smuggling data in the unstructured bag of values attached to the context. It’s thread local storage in a cheap suit.

It’s not just that values are boxed into an interface{} inside context.WithValue that I object to. The far more serious concern is there is no schema to this data, so there is no way for a method that takes a context to ensure that it contains the specific key required to complete the operation. context.Value returns nil if the key is not found, which means any code doing the naïve

log := ctx.Value("logger").(log.Logger)
log.Warn("something you'll ignore later")

will blow up if the "logger" key is not present.

Sure, you can check that the assertion succeeded, but I feel pretty confident that if this pattern were to become popular then people would eschew the two arg form of type assertion and just expect that the key always returned a valid logger. This would be especially true as logging in error paths is rarely tested, so you’ll hit this when you need it the most.

In my opinion passing loggers inside context.Context would be the worst solution to the problem of decoupling loggers from implementations. We’d have gone from an explicit compile time dependency to an implicit run time dependency, one that could not be enforced by the compiler.

To quote @freeformz

Loggers should be injected into dependencies. Full stop.

It’s verbose, but it’s the only way to achieve decoupled design.

The package level logger anti pattern

This post is a spin-off from various conversations around improving (I’m trying not to say standardising, otherwise I’ll have to link to XKCD) the way logging is performed in Go projects.

Consider this familiar pattern for establishing a package level log variable.

package foo

import “mylogger”

var log = mylogger.GetLogger(“github.com/project/foo”)

What’s wrong with this pattern?

The first problem with declaring a package level log variable is the tight coupling between package foo and package mylogger. Package foo now depends directly on package mylogger at compile time.

The second problem is the tight coupling between package foo and package mylogger is transitive. Any package that consumes package foo is itself dependant on mylogger at compile time.

This leads to a third problem, Go projects composed of packages using multiple logging
libraries, or fiefdoms of projects who can only consume packages that use their particular logging library.

Avoid source level coupling

The solution to this anti pattern is to delay the binding between the type that does the logging, and the type that needs to log, until it is needed. That is, until the variable is declared.

package foo

import "github.com/pkg/log"

type T struct {
        logger log.Logger
        // other fields
}

Now, the consumer of  type T supplies a value of type log.Logger when constructing new T‘s, and the methods on T use the logger they were provided when they want to log.

Interfaces to the rescue

The eagle eyed reader will note that the previous selection removed the package level log variable, but the coupling between package foo and package log remains.

However, this can be remedied by the consumer of the logger type declaring its own interface for the behaviour it expects.

package foo

type logger interface {
        Printf(string, ...interface{})
}

type T struct {
        logger
        // other fields
}

As long as the type assigned to foo.T.logger implements foo.logger the decision for which specific type to use can be deferred until run time in the same way that io.Copy escapes any knowledge of the io.Reader and io.Writer implementations in use until it is invoked.

It’s not just logging

Logging is a cross cutting concern, but the anti patterns associated with it also apply to other common areas like metrics, telemetry, and auditing.

Get involved

The Go 1.9 development window is opening next month. If this topic is important to you, get involved.

Should methods be declared on T or *T

This post is a continuation of a suggestion I made on twitter a few days ago.

In Go, for any type T, there exists a type *T which is the result of an expression that takes the address of a variable of type T1. For example:

type T struct { a int; b bool }
var t T    // t's type is T
var p = &t // p's type is *T

These two types, T and *T are distinct, but *T is not substitutable for T2.

You can declare a method on any type that you own; that is, a type that you declare in your package3. Thus it follows that you can declare methods on both the type you declare, T, and its corresponding derived pointer type, *T. Another way to talk about this is to say methods on a type are declared to take a copy of their receiver’s value, or a pointer to their receiver’s value 4. So the question becomes, which is the most appropriate form to use?

Obviously if your method mutates its receiver, it should be declared on *T. However, if the method does not mutate its receiver, is it safe to declare it on T instead5?

It turns out that the cases where it is safe to do so are very limited. For example, it is well known that you should not copy a sync.Mutex value as that breaks the invariants of the mutex. As mutexes control access to other things, they are frequently wrapped up in a struct with the value they control:

package counter

type Val struct {
        mu  sync.Mutex
        val int
}

func (v *Val) Get() int {
        v.mu.Lock()
        defer v.mu.Unlock()
        return v.val
}

func (v *Val) Add(n int) {
        v.mu.Lock()
        defer v.mu.Unlock()
        v.val += n
}

Most Go programmers know that it is a mistake to forget to declare the Get or Add methods on the pointer receiver *Val. However any type that embeds a Val to utilise its zero value, must also only declare methods on its pointer receiver otherwise it may inadvertently copy the contents of its embedded type’s values.

type Stats struct {
        a, b, c counter.Val
}

func (s Stats) Sum() int {
        return s.a.Get() + s.b.Get() + s.c.Get() // whoops
}

A similar pitfall can occur with types that maintain slices of values, and of course there is the possibility for an unintended data race.

In short, I think that you should prefer declaring methods on *T unless you have a strong reason to do otherwise.


  1. We say T but that is just a place holder for a type that you declare.
  2. This rule is recursive, taking the address of a variable of type *T returns a result of type **T.
  3. This is why nobody can declare methods on primitive types like int.
  4. Methods in Go are just syntactic sugar for a function which passes the receiver as the first formal parameter.
  5. If the method does not mutate its receiver, does it need to be a method?

Unhelpful abstractions

Sandi Metz’s post on abstraction struck a chord with me recently. I was working with a piece of code which looked like this (in pseudo code):

func Start() {
        const filename = "..."
        createOuputFile(filename)
        go run(filename)
}

It turned out that createOutputFile was written in an obscure way which first caused me to look at it more closely. Why the code expected the file to exist before starting wasn’t immediately clear. It may have been because some other goroutine was expecting the file to exist on disk, even if nothing had been written yet (slight race smell), or more likely the necessary information was not available for the job itself to create the file with the correct permissions. This calls for a refactoring!

There is a well known UNIX utility that provides these semantics, touch(1). So, I reasoned, createOutputFile is really touch plus the ability to set file permissions, which the former was hard coded to do implicitly. This was a job for abstraction!

How would you write the signature for TouchFile? Here is what I came up with:

// TouchFile ensures path exists, or creates it using
// the supplied file mode.
func TouchFile(path string, mode os.FileMode) error

This looked pretty reasonable, and was a nice generalisation over the previous function. TouchFile makes setting the file mode on creation, the primary reason why this code existed in the first place, explicit.

However, this is precisely the train of thought that Metz warned of in her post. By generalising this function I had made its API worse.

Specifically, now every caller to this function has to pass in a mode value, even if the file exists, even if they don’t really care and are happy with a default file mode. Worse still, mode is only applied if the file is not already present. Not only had I made this function harder to use in its default use case, I’d added a footgun to the API that someone might call this function expecting it to update the mode of an existing file.

The second clue that I was heading in the wrong direction was the implementation of TouchFile itself:

func TouchFile(path string, mode os.FileMode) error {
        f, err := os.OpenFile(path, os.O_WRONLY|os.O_CREATE, mode)
        if err != nil {
                return err
        }
        return f.Close()
}

TouchFile just calls os.OpenFile passing in the right flags to get the create-if-missing semantics it wants. You still have to pass in the mode, because os.OpenFile requires a mode, so the utility of TouchFile as a wrapper is undermined by the cognitive overhead of having to remember its quirks.

Coming to my senses, I reverted my change and replaced createOutputFile with a direct call to os.OpenFile.

Whereas someone reading this code and seeing a call to TouchFile may think that the goal is to ensure the file exists, will miss the subtle point that purpose of Start was to ensure that the file exists with the right permission. By making a direct call to the os package in body of the function it becomes explicit to the next reader, who already knows the os package, that the file is being created explicitly is to set the mode.

I realised that I hadn’t made things simpler by adding this abstraction, instead I’d made them more opaque. Sometimes it’s better to be explicit than abstract.

Let’s talk about logging

This is a post inspired by a thread that Nate Finch started on the Go Forum. This post focuses on Go, but if you can see your way past that, I think the ideas presented here are widely applicable.

Why no love ?

Go’s log package doesn’t have leveled logs, you have to manually add prefixes like debug, info, warn, and error, yourself. Also, Go’s logger type doesn’t have a way to turn these various levels on or off on a per package basis. By way of comparison let’s look at a few replacements from third parties.

glog from Google provides the following levels:

  • Info
  • Warning
  • Error
  • Fatal (which terminates the program)

Looking at another library, loggo, which we developed for Juju, provides the following levels:

  • Trace
  • Debug
  • Info
  • Warning
  • Error
  • Critical

Loggo also provides the ability to adjust the verbosity of logging on a per package basis.

So here are two examples, clearly influenced by other logging libraries in other languages. In fact their linage can be traced back to syslog(3), maybe even earlier. And I think they are wrong.

I want to take a contradictory position. I think that all logging libraries are bad because the offer too many features; a bewildering array of choice that dazzles the programmer right at the point they must be thinking clearly about how to communicate with the reader from the future; the one who will be consuming their logs.

I posit that successful logging packages need far less features, and certainly fewer levels.

Let’s talk about warnings

Let’s start with the easiest one. Nobody needs a warning log level.

Nobody reads warnings, because by definition nothing went wrong. Maybe something might go wrong in the future, but that sounds like someone else’s problem.

Furthermore, if you’re using some kind of leveled logging then why would you set the level at warning ? You’d set the level at info, or error. Setting the level to warning is an admission that you’re probably logging errors at warning level.

Eliminate the warning level, it’s either an informational message, or an error condition.

Let’s talk about fatal

Fatal level is effectively logging the message, then calling os.Exit(1). In principal this means:

  • defer statements in other goroutines don’t run.
  • buffers aren’t flushed.
  • temporary files and directories aren’t removed.

In effect, log.Fatal is a less verbose than, but semantically equivalent to, panic.

It is commonly accepted that libraries should not use panic1, but if calling log.Fatal2 has the same effect, surely this should also be outlawed.

Suggestions that this cleanup problem can be solved by registering shutdown handlers with the logging system introduces tight coupling between your logging system and every place where cleanup operations happen; its also violates the separation of concerns.

Don’t log at fatal level, prefer instead to return an error to the caller. If the error bubbles all the way up to main.main then that is the right place to handle any cleanup actions before exiting.

Let’s talk about error

Error handling and logging are closely related, so on the face of it, logging at error level should be easily justifiable. I disagree.

In Go, if a function or method call returns an error value, realistically you have two options:

  • handle the error.
  • return the error to your caller. You may choose to gift wrap the error, but that is not important to this discussion.

If you choose to handle the error by logging it, by definition it’s not an error any more — you handled it. The act of logging an error handles the error, hence it is no longer appropriate to log it as an error.

Let me try to convince you with this code fragment:

err := somethingHard()
if err != nil {
        log.Error("oops, something was too hard", err)
        return err // what is this, Java ?
}

You should never be logging anything at error level because you should either handle the error, or pass it back to the caller.

To be clear, I am not saying you should not log that a condition occurred

if err := planA(); err != nil {
        log.Infof("could't open the foo file, continuing with plan b: %v", err)
        planB()
}

but in effect log.Info and log.Error have the same purpose.

I am not saying DO NOT LOG ERRORS! Instead the question is, what is the smallest possible logging API ? And when it comes to errors, I believe that an overwhelming proportion of items logged at error level are simple done that way because they are related to an error. They are in fact, just informational, hence we can remove logging at error level from our API.

What’s left ?

We’ve ruled out warnings, argued that nothing should be logged at error level, and shown that only the top level of the application should have some kind of log.Fatal behaviour. What’s left ?

I believe that there are only two things you should log:

  1. Things that developers care about when they are developing or debugging software.
  2. Things that users care about when using your software.

Obviously these are debug and info levels, respectively.

log.Info should simply write that line to the log output. There should not be an option to turn it off as the user should only be told things which are useful for them. If an error that cannot be handled occurs, it should bubble up main.main where the program terminates. The minor inconvenience of having to insert the FATAL prefix in front of the final log message, or writing directly to os.Stderr with fmt.Fprintf is not sufficient justification for a logging package growing a log.Fatal method.

log.Debug, is an entirely different matter. It is for the developer or support engineer to control. During development, debugging statements should be plentiful, without resorting to trace or debug2 (you know who you are) level. The log package should support fine grained control to enable or disable debug, and only debug, statements at the package or possibly even finer scope.

Wrapping up

If this were a twitter poll, I’d ask you to choose between

  • logging is important
  • logging is hard

But the fact is, logging is both. The solution to this problem must be to de-construct and ruthlessly pair down unnecessary distraction.

What do you think ? Is this just crazy enough to work, or just plain crazy ?


Notes

  1. Some libraries may use panic/recover as an internal control flow mechanism, but the overriding mantra is they must not let these control flow operations leak outside the package boundary.
  2. Ironically while it lacks a debug level output, the Go standard log package has both Fatal and Panic functions. In this package the number of functions that cause a program to exit abruptly outnumber those that do not.