Capture zap logger output when I can't alter the way logger created

Question

I need to write unit tests for Zap logger, to check it's output. There're a plenty tutorials in the internet how to capture zap log output but they suppose that I can create logger with custom X, Y, Z... In my case I receive logger object that I can't change anything in a way it initiated, and it prints logs to stdout. How can I still check output of this logger?

Some code for reference:

I create logger by following code. Once again, it's a wrapper and I need to test its behavior, so I can't change it.

logger, err := NewCustomLogger(context.Background(), zapcore.DebugLevel, "unit tests")
if err != nil {
    assert.Fail(s.T(), "couldn't initialize logger")
    return
}

I can't change NewCustomLogger and it returns *zap.Logger, is there any workaround that I can use?

P.S. I tried to use this answer and catch stdout, but it didn't work for me:

In Go, how do I capture stdout of a function into a string?

old := os.Stdout // keep backup of the real stdout
    r, w, _ := os.Pipe()
    os.Stdout = w

    logger.Warn("This log will be intercepted")

    outC := make(chan string)
    // copy the output in a separate goroutine so printing can't block indefinitely
    go func() {
        var buf bytes.Buffer
        io.Copy(&buf, r)
        outC <- buf.String()
    }()

    // back to normal state
    w.Close()
    os.Stdout = old // restoring the real stdout
    out := <-outC

    // reading our temp stdout
    fmt.Println("previous output:")
    fmt.Print(out)

fmt.Print(out) prints empty string string.

P.P.S.

I tried this answer too and it partially worked: How to properly capture zap logger output in unit tests

logger, err := NewLogger(context.Background(), zapcore.DebugLevel, "unit tests")
    if err != nil {
        assert.Fail(s.T(), "couldn't initialize logger")
        return
    }

    observed, logs := observer.New(zapcore.InfoLevel)
    observedLogger := zap.New(zapcore.NewTee(logger.Core(), observed))

    observedLogger.Warn("This log will be intercepted by the custom core")

    entry := logs.All()[0]

    fmt.Print(entry)

But it doesn't print InitialFields: https://pkg.go.dev/go.uber.org/zap#Config.InitialFields

see foo_env field:

{"level":"warn","ts":1710415413.844058,"msg":"This log will be intercepted by the custom core","foo_env":"test_env_foo"}
{{warn 2024-03-14 13:23:33.844058 +0200 IST m=+0.003122709  This log will be intercepted by the custom core undefined } []}

UPDATE:

The logger created in this way, but as I say I can't change this implementation:

func NewLogger(level zapcore.Level, serviceName string) (*zap.Logger, error) {
    productionCfg := zap.NewProductionConfig()
    productionCfg.Level = zap.NewAtomicLevelAt(level)
    productionCfg.InitialFields = map[string]interface{}{
        "INITIAL_FIELD":"INITIAL_FIELD_VALUE",  //example, initial fields populated from env variables
    }

    logger, err := productionCfg.Build(zap.AddStacktrace(zap.ErrorLevel))
    if err != nil {
        return nil, errors.Wrap(err, "failed to build logger")
    }

    logger = logger.Named(serviceName)

    return logger, nil
}

Answer 1

You can route stderr output to a temp file and then read the content of the temp file to get the log output and match it against the expected output.

Example:

func TestNewLogger(t *testing.T) {
    // create a temporary file to redirect stderr
    file, err := os.CreateTemp(".", "temp")
    assert.NoError(t, err)
    defer os.Remove(file.Name())
    os.Stderr = file

    // init the logger as normal
    logger, err := NewLogger(zapcore.DebugLevel, "test")
    assert.NoError(t, err)
    logger.Info("test")

    // read the file content for testing
    logOut, err := os.ReadFile(file.Name())
    assert.NoError(t, err)

    assert.Regexp(t, `{"level":"info","ts":.*,"logger":"test","caller":".*","msg":"test","INITIAL_FIELD":"INITIAL_FIELD_VALUE"}`, string(logOut))
}

Answer 2

If this happens on a POSIX system with the dup2(2) system call you can perform direct surgery on the file descriptor underlying the stdout —like this:

package main

import (
    "bufio"
    "fmt"
    "os"
    "syscall"

    "go.uber.org/zap"
)

func mustMakeStdoutLogger() *zap.Logger {
    conf := zap.NewProductionConfig()
    conf.OutputPaths = []string{"stdout"}

    logger, err := conf.Build()
    if err != nil {
        panic(err)
    }

    return logger
}

func mustGetSyscallConn(f *os.File) syscall.RawConn {
    rc, err := f.SyscallConn()
    if err != nil {
        panic(err)
    }

    return rc
}

func main() {
    logger := mustMakeStdoutLogger()
    defer logger.Sync()

    pr, pw, err := os.Pipe()
    if err != nil {
        panic(err)
    }
    defer pw.Close()

    var pwFD uintptr
    err = mustGetSyscallConn(pw).Control(func(fd uintptr) {
        pwFD = fd
    })
    if err != nil {
        panic(err)
    }

    var dupErr error
    err = mustGetSyscallConn(os.Stdout).Control(func(fd uintptr) {
        dupErr = syscall.Dup2(int(pwFD), int(fd))
    })
    if err != nil {
        panic(err)
    }
    if dupErr != nil {
        panic(dupErr)
    }

    errCh := make(chan error)
    go func() {
        scanner := bufio.NewScanner(pr)
        defer func() {
            errCh <- scanner.Err()
        }()

        for scanner.Scan() {
            fmt.Fprintln(os.Stderr, "!!!", scanner.Text(), "!!!")
        }
    }()

    _, err = fmt.Println("a plain message to stdout")
    if err != nil {
        panic(err)
    }

    logger.Info("a test message")
    logger.Sync()

    err = pr.Close()
    if err != nil {
        panic(err)
    }

    err = <-errCh
    fmt.Fprintf(os.Stderr, "%#v\n", err)
}

What happens here is as following:

1. A kernel-provided pipe(2) is created.
2. The file descriptor of its write end is saved.
3. The standard output's file descriptor is atomically replaced with that one using the dup(2) system call.
4. Everything written to stdout now goes into the pipe, so we can read that from its read end; this is done in a goroutine (for testing purposes).

Note that in order to make the goroutine quit, we close the write end of the pipe, so the goroutine actually quits with an error. Unfortunately, the error appears to be useless (in my version of Go at least)—in the sense it cannot be sensibly asserted for its type of value; maybe you could match its error string.

---

Note that

r, w, _ := os.Pipe()
os.Stdout = w

did not work because os.Stdout is a mere package-level variable with no magic attached to it. Supposedly, when a logger instance was being constructed, its initialization code has read the then-current value of os.Stdout and saved it somewhere, so when you later rewrote that variable with a new value, that did nothing to the already created logger.

Answer 3

Probably not the answer you want but it seems this functionality is not supported by zap according to this Github Issue:

https://github.com/uber-go/zap/issues/859

To quote prashantv:

This is expected because of how zap works:

Cores encode fields as they are added
WrapCore cannot go back, as the previous fields are not stored unencoded

As a result the initial fields cannot be unencoded.

Just to take a step back, I would review again why checking the initial fields is important for your tests. In theory your unit test should check the functionality of your unit. Initial Fields coming through the logger shouldn't matter, as it shouldn't affect your unit.