How to check a log/output in go test?

Question

I have this function that logs the error in some cases:

func readByte(/*...*/){
    // ...
    if err != nil {
        fmt.Println("ERROR")
        log.Print("Couldn't read first byte")
        return
    }
    // ...
}

Now, in the test file, I want to check the output error from this function:

    c.Assert(OUTPUT, check.Matches, "teste")

How can I access the log? I tried to put a buffer but it didn't work. What is the right way to catch this log without change my readByte function code?

the buffer is empty. the OUTPUT returns "". I check if the log is writing and it's ok but my buffer is always empty. — Vivi
– Vivi, Commented May 22, 2017 at 18:45
So show how you're writing to the buffer. There's no reason that you shouldn't be able to write to a buffer and check it later. — Mr_Pink
– Mr_Pink, Commented May 22, 2017 at 18:59

peterSO · Accepted Answer · 2017-05-22 20:51:58Z

65

For example,

readbyte_test.go:

package main

import (
    "bytes"
    "fmt"
    "io"
    "log"
    "os"
    "testing"
)

func readByte( /*...*/ ) {
    // ...
    err := io.EOF // force an error
    if err != nil {
        fmt.Println("ERROR")
        log.Print("Couldn't read first byte")
        return
    }
    // ...
}

func TestReadByte(t *testing.T) {
    var buf bytes.Buffer
    log.SetOutput(&buf)
    defer func() {
        log.SetOutput(os.Stderr)
    }()
    readByte()
    t.Log(buf.String())
}

Output:

$ go test -v readbyte_test.go 
=== RUN   TestReadByte
ERROR
--- PASS: TestReadByte (0.00s)
    readbyte_test.go:30: 2017/05/22 16:41:00 Couldn't read first byte
PASS
ok      command-line-arguments  0.004s
$

edited May 22, 2017 at 20:51

answered May 22, 2017 at 20:45

peterSO

168k32 gold badges303 silver badges293 bronze badges

Sign up to request clarification or add additional context in comments.

2 Comments

Ian Over a year ago

I'm just trying to improve my understanding of unit testing best practices. In this example, would it not be best to also assert, after the call to readByte that the contents of buf is as expected (or at least non-empty)?

Mitar Over a year ago

I prefer to use t.Cleanup instead of defer in testing.

ddrake12 · Accepted Answer · 2021-08-16 18:40:02Z

Answer for Concurrent Tests

If your test is running concurrently (for example, when testing an http Server or Client), you may encounter a race between writing to the buffer and reading from it. Instead of the buffer, we can redirect output to an os.Pipe and use a bufio.Scanner to block until output has been written by using the Scan() method.

Here is an example of creating an os.Pipe and setting the stdlib log package to use the pipe. Note my use of the testify/assert package here:

func mockLogger(t *testing.T) (*bufio.Scanner, *os.File, *os.File) {
    reader, writer, err := os.Pipe()
    if err != nil {
        assert.Fail(t, "couldn't get os Pipe: %v", err)
    }
    log.SetOutput(writer)

    return bufio.NewScanner(reader), reader, writer
}

The *os.File objects are returned so they can be properly closed with a deferred function. Here I'm just printing to stdout since if there was some strange error on close I personally wouldn't want to fail the test. However, this could easily be another call to t.Errorf or similar if you wanted:

func resetLogger(reader *os.File, writer *os.File) {
    err := reader.Close()
    if err != nil {
        fmt.Println("error closing reader was ", err)
    }
    if err = writer.Close(); err != nil {
        fmt.Println("error closing writer was ", err)
    }
    log.SetOutput(os.Stderr)
}

And then in your test you would have this pattern:

scanner, reader, writer := mockLogger(t) // turn this off when debugging or developing as you will miss output!
defer resetLogger(reader, writer)

// other setup as needed, getting some value for thing below

go concurrentAction() 

scanner.Scan() // blocks until a new line is written to the pipe 

got := scanner.Text() // the last line written to the scanner
msg := fmt.Sprintf("your log message with thing %v you care about", thing) 
assert.Contains(t, got, msg)

And finally, the concurrentAction() function is calling a log function (or method if using a log.logger, the package actually behaves the same way with log.SetOutput() call above either way) like:

// doing something, getting value for thing 
log.Printf("your log message with the thing %v you care about", thing)

Collectives™ on Stack Overflow

How to check a log/output in go test?

2 Answers 2

2 Comments

Answer for Concurrent Tests

Comments

Your Answer

Linked

Hot Network Questions

Collectives™ on Stack Overflow

2 Answers 2

2 Comments

Answer for Concurrent Tests

Comments

Your Answer

Sign up or log in

Post as a guest

Linked

Related