How to test Go function containing log.Fatal()

Question

Say, I had the following code that prints some log messages. How would I go about testing that the correct messages have been logged? As log.Fatal calls os.Exit(1) the tests fail.

package main

import (
    "log"
)

func hello() {
    log.Print("Hello!")
}

func goodbye() {
    log.Fatal("Goodbye!")
}

func init() {
    log.SetFlags(0)
}

func main() {
    hello()
    goodbye()
}

Here are the hypothetical tests:

package main

import (
    "bytes"
    "log"
    "testing"
)


func TestHello(t *testing.T) {
    var buf bytes.Buffer
    log.SetOutput(&buf)

    hello()

    wantMsg := "Hello!\n"
    msg := buf.String()
    if msg != wantMsg {
        t.Errorf("%#v, wanted %#v", msg, wantMsg)
    }
}

func TestGoodby(t *testing.T) {
    var buf bytes.Buffer
    log.SetOutput(&buf)

    goodbye()

    wantMsg := "Goodbye!\n"
    msg := buf.String()
    if msg != wantMsg {
        t.Errorf("%#v, wanted %#v", msg, wantMsg)
    }
}

Armilda

Answer 1

This is similar to "How to test os.Exit() scenarios in Go": you need to implement your own logger, which by default redirect to log.xxx(), but gives you the opportunity, when testing, to replace a function like log.Fatalf() with your own (which does not call os.Exit(1))

I did the same for testing os.Exit() calls in exit/exit.go:

exiter = New(func(int) {})
exiter.Exit(3)
So(exiter.Status(), ShouldEqual, 3)

(here, my "exit" function is an empty one which does nothing)

Dextrosinistral

Answer 2

While it's possible to test code that contains log.Fatal, it is not recommended. In particular you cannot test that code in a way that is supported by the -cover flag on go test.

Instead it is recommended that you change your code to return an error instead of calling log.Fatal. In a sequential function you can add an additional return value, and in a goroutine you can pass an error on a channel of type chan error (or some struct type containing a field of type error).

Once that change is made your code will be much easier to read, much easier to test, and it will be more portable (now you can use it in a server program in addition to command line tools).

If you have log.Println calls I also recommend passing a custom logger as a field on a receiver. That way you can log to the custom logger, which you can set to stderr or stdout for a server, and a noop logger for tests (so you don't get a bunch of unnecessary output in your tests). The log package supports custom loggers, so there's no need to write your own or import a third party package for this.

Conative

Answer 3

If you're using logrus, there's now an option to define your exit function from v1.3.0 introduced in this commit. So your test may look something like:

func Test_X(t *testing.T) {
    cases := []struct{
        param string
        expectFatal bool
    }{
        {
            param: "valid",
            expectFatal: false,
        },
        {
            param: "invalid",
            expectFatal: true,
        },
    }

    defer func() { log.StandardLogger().ExitFunc = nil }()
    var fatal bool
    log.StandardLogger().ExitFunc = func(int){ fatal = true }

    for _, c := range cases {
        fatal = false
        X(c.param)
        assert.Equal(t, c.expectFatal, fatal)
    }
}

Paphlagonia

Answer 4

I have using the following code to test my function. In xxx.go:

var logFatalf = log.Fatalf

if err != nil {
    logFatalf("failed to init launcher, err:%v", err)
}

And in xxx_test.go:

// TestFatal is used to do tests which are supposed to be fatal
func TestFatal(t *testing.T) {
    origLogFatalf := logFatalf

    // After this test, replace the original fatal function
    defer func() { logFatalf = origLogFatalf } ()

    errors := []string{}
    logFatalf = func(format string, args ...interface{}) {
        if len(args) > 0 {
            errors = append(errors, fmt.Sprintf(format, args))
        } else {
            errors = append(errors, format)
        }
    }
    if len(errors) != 1 {
        t.Errorf("excepted one error, actual %v", len(errors))
    }
}

Koster

Neat approach. The only catch with this is that you might encounter different errors in between calling logFatalf and when you check for "len(errors) != 1" as your code may now be in an invalid state after logFatalf but continues to run instead of aborting. – Stephen

Answer 5

I'd use the supremely handy bouk/monkey package (here along with stretchr/testify).

func TestGoodby(t *testing.T) {
  wantMsg := "Goodbye!"

  fakeLogFatal := func(msg ...interface{}) {
    assert.Equal(t, wantMsg, msg[0])
    panic("log.Fatal called")
  }
  patch := monkey.Patch(log.Fatal, fakeLogFatal)
  defer patch.Unpatch()
  assert.PanicsWithValue(t, "log.Fatal called", goodbye, "log.Fatal was not called")
}

I advise reading the caveats to using bouk/monkey before going this route.

Lippi

Answer 6

There used to be an answer here that I referred to, looks like it got deleted. It was the only one I've seen where you could have passing tests without modifying dependencies or otherwise touching the code that should Fatal.

I agree with other answers that this is usually an inappropriate test. Usually you should rewrite the code under test to return an error, test the error is returned as expected, and Fatal at a higher level scope after observing the non-nil error.

To OP's question of testing that the that the correct messages have been logged, you would inspect inner process's cmd.Stdout.

https://play.golang.org/p/J8aiO9_NoYS

func TestFooFatals(t *testing.T) {
    fmt.Println("TestFooFatals")
    outer := os.Getenv("FATAL_TESTING") == ""
    if outer {
        fmt.Println("Outer process: Spawning inner `go test` process, looking for failure from fatal")
        cmd := exec.Command(os.Args[0], "-test.run=TestFooFatals")
        cmd.Env = append(os.Environ(), "FATAL_TESTING=1")
        // cmd.Stdout, cmd.Stderr = os.Stdout, os.Stderr
        err := cmd.Run()
        fmt.Printf("Outer process: Inner process returned %v\n", err)
        if e, ok := err.(*exec.ExitError); ok && !e.Success() {
            // fmt.Println("Success: inner process returned 1, passing test")
            return
        }
        t.Fatalf("Failure: inner function returned %v, want exit status 1", err)
    } else {
        // We're in the spawned process.
        // Do something that should fatal so this test fails.
        foo()
    }
}

// should fatal every time
func foo() {
    log.Printf("oh my goodness, i see %q\n", os.Getenv("FATAL_TESTING"))
    // log.Fatal("oh my gosh")
}

Shieh

Hey Plato, the answer you're referring to was my first answer. I removed it because I think it was encouraging people to be clever and also because somebody pointed out that it breaks the -cover flag, which is a fair point. Sorry I broke your reference. btw Andrew's slide is here and it contains all the relevant info: talks.golang.org/2014/testing.slide#23 – Conative

Answer 7

I've combined answers from different sources to produce this:

import (
    "bufio"
    "bytes"
    "errors"
    "fmt"
    "io/ioutil"
    "log"
    "os"
    "os/exec"
    "os/user"
    "strings"
    "testing"

    "bou.ke/monkey"
    "github.com/stretchr/testify/assert"
    "github.com/stretchr/testify/mock"
    "github.com/stretchr/testify/require"
)


func TestCommandThatErrors(t *testing.T) {
    fakeExit := func(int) {
        panic("os.Exit called")
    }
    patch := monkey.Patch(os.Exit, fakeExit)
    defer patch.Unpatch()

    var buf bytes.Buffer
    log.SetOutput(&buf)

    for _, tc := range []struct {
        cliArgs       []string
        expectedError string
    }{
        {
            cliArgs:       []string{"dev", "api", "--dockerless"},
            expectedError: "Some services don't have dockerless variants implemented yet.",
        },
    } {
        t.Run(strings.Join(tc.cliArgs, " "), func(t *testing.T) {
            harness := createTestApp()
            for _, cmd := range commands {
                cmd(harness.app)
            }

            assert.Panics(t, func() { harness.app.run(tc.cliArgs) })
            assert.Contains(t, buf.String(), tc.expectedError)
            buf.Reset()
        })
    }
}

Works great :)

Lavalava

Answer 8

You cannot and you should not. This "you must 'test' each and every line"-attitude is strange, especially for terminal conditions and that's what log.Fatal is for. (Or just test it from the outside.)

Linis

"Cannot" is a bit strong; but I'll agree with "should not". If you want to test a failure condition of a (non-main) block of code then don't use log.Fatal for that code but return an error instead (i.e. if failure is an option have an API that represents that). In the vast majority of cases log.Fatal should be only be used in main, or init functions (or possibly some things meant to be called only directly from them). – Infinitude

in a complicated distributed system there are scenarios where my code cannot perform its task, for example a database went down or configuration is missing. i prefer to Fatal here, first to avoid executing with indeterminate program state and second to ensure i get a monitoring alert – Shieh

Agree halfway, it is not really necessary to have 100% code coverage, here the question at hand is more about how to go about unit testing when you have log.fatal in your code. – Lurk