How to properly capture zap logger output in unit tests

Question

Based off the configurations for zap.NewDevelopmentConfig() and zap.NewProductionConfig(), I've assumed that zap writes logs to stderr. However, I can't seem to capture the output in unit tests.

I have the following captureOutput func:

func captureOutput(f func()) string {
    r, w, err := os.Pipe()
    if err != nil {
        panic(err)
    }

    stdout := os.Stdout
    os.Stdout = w
    defer func() {
        os.Stdout = stdout
    }()

    stderr := os.Stderr
    os.Stderr = w
    defer func() {
        os.Stderr = stderr
    }()

    f()
    w.Close()

    var buf bytes.Buffer
    io.Copy(&buf, r)

    return buf.String()
}

It fails to capture zap output but does manage to grab output from fmt.Println(...):

func TestZapCapture(t *testing.T) {
    auditor, _ := zap.NewProduction()
    output := captureOutput(func() {
        auditor.Info("hi")
    })

    assert.NotEmpty(t, output)
    //fails to captures output
}

func TestFmtCapture(t *testing.T) {
    output := captureOutput(func() {
        fmt.Println("hi")
    })

    assert.NotEmpty(t, output)
    //successfully captures output
}

I'm aware of using the zap observer for situations like this but my real use case is to test a highly modified zap logger so testing a new zap.Core would defeat the purpose. Whats the best way to capture that output?

Related (though not what you want) https://stackoverflow.com/questions/52734529/how-to-test-logging-of-a-zap-logger-built-from-custom-config — blackgreen, Dec 18 '21 at 06:34
Your answer below definitely would work but required modifying the existing core. And while similar, I decided to extract the config from my constructor function in order to leverage an in-memory zap sink instead (from the link you posted): https://stackoverflow.com/a/52737940/5042150 — vercingortix, Dec 22 '21 at 00:22
note that only the second solution requires modifying the existing core. it depends on what you want to test. Using the custom sink is also a fine option — blackgreen, Dec 22 '21 at 07:20

blackgreen · Accepted Answer · 2021-12-18T13:13:19.187

Test that messages are logged at all

Use zapcore.NewTee. In your unit tests, you instantiate a logger whose core is comprised of your own highly modified core and the observed core tee'd together. The observed core will receive the log entries, so you can assert that single fields are what you expect (level, message, fields, etc.)

func main() {
    // some arbitrary custom core logger
    mycore := zapcore.NewCore(
        zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig()),
        os.Stderr,
        zapcore.InfoLevel,
    )
    // test core
    observed, logs := observer.New(zapcore.InfoLevel)
    
    // new logger with the two cores tee'd together
    logger := zap.New(zapcore.NewTee(mycore, observed))

    logger.Error("foo")

    entry := logs.All()[0]
    fmt.Println(entry.Message == "foo")            // true
    fmt.Println(entry.Level == zapcore.ErrorLevel) // true
}

Test the final log format

In this case you want to pipe the logger output to arbitrary writers. You can achieve this with zap.CombineWriteSyncers and inject this as a dependency of your custom core.

// this would be placed in your main code
func NewCustomLogger(pipeTo io.Writer) zapcore.Core {
    return zapcore.NewCore(
        zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig()),
        zap.CombineWriteSyncers(os.Stderr, zapcore.AddSync(pipeTo)),
        zapcore.InfoLevel,
    )
}

func TestLogger(t *testing.T) {
    b := &bytes.Buffer{}
    // call the constructor from your test code with the arbitrary writer
    mycore := NewCustomLogger(b)

    logger := zap.New(mycore)
    logger.Error("foo")

    fmt.Println(b.String()) // {"level":"error","ts":1639813360.853494,"msg":"foo"}
}

How to properly capture zap logger output in unit tests

1 Answers1

Test that messages are logged at all

Test the final log format