40

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?

Martin Tournoij
  • 26,737
  • 24
  • 105
  • 146
Vivi
  • 693
  • 2
  • 11
  • 21

2 Answers2

56

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
$
peterSO
  • 158,998
  • 31
  • 281
  • 276
  • 1
    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)? – Ian Nov 29 '22 at 18:18
  • 1
    I prefer to use `t.Cleanup` instead of `defer` in testing. – Mitar Jun 20 '23 at 08:49
9

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)
ddrake12
  • 831
  • 11
  • 22