Why is there a data race in this Go program?

Question

I'm trying to store log messages in a buffer to access them only when I get an error. A bit like in Smarter log handling, the case for opportunistic logging. In this example I fetch the logs from the buffer each 5 seconds but I get a data race when I run it with go run -race code.go.

I'm using channels to communicate but I'm doing something wrong, obviously.

package main

import (
    "bytes"
    "fmt"
    "io/ioutil"
    "log"
    "time"
)

type LogRequest struct {
    Buffer chan []byte
}

type LogBuffer struct {
    LogInputChan chan []byte
    LogRequests  chan LogRequest
}

func (f LogBuffer) Write(b []byte) (n int, err error) {
    f.LogInputChan <- b
    return len(b), nil
}

func main() {
    var logBuffer LogBuffer
    logBuffer.LogInputChan = make(chan []byte, 100)
    logBuffer.LogRequests = make(chan LogRequest, 100)

    log.SetOutput(logBuffer)

    // store the log messages in a buffer until we ask for it
    go func() {
        buf := new(bytes.Buffer)

        for {
            select {
            // receive log messages
            case logMessage := <-logBuffer.LogInputChan:
                buf.Write(logMessage) // <- data race
            case logRequest := <-logBuffer.LogRequests:
                c, errReadAll := ioutil.ReadAll(buf)
                if errReadAll != nil {
                    panic(errReadAll)
                }
                logRequest.Buffer <- c
            }
        }
    }()

    // log a test message every 1 second
    go func() {
        for i := 0; i < 30; i++ {
            log.Printf("test: %d", i) // <- data race
            time.Sleep(1 * time.Second)
        }
    }()

    // print the log every 5 seconds
    go func() {
        for {
            time.Sleep(5 * time.Second)

            var logRequest LogRequest
            logRequest.Buffer = make(chan []byte, 1)
            logBuffer.LogRequests <- logRequest

            buffer := <-logRequest.Buffer

            fmt.Printf("**** LOG *****\n%s**** END *****\n\n", buffer)
        }
    }()

    time.Sleep(45 * time.Second)
}

Answer 1

The log package uses an internal buffer to build-up log messages for output (the buf field in log/Logger). It composes the header, appends the data provided by the caller, then passes this buffer to your Write method for output.

In order to reduce allocations, the log package recycles this buffer for each log message. It's not stated in the documentation, but the implicit assumption is that your Write method only uses the provided []byte data for the duration of the Write call. This assumption is OK for most outputs, e.g. a file or STDOUT.

To avoid a data race, you need to make an explicit copy of the incoming data before returning from the Write function:

func (f LogBuffer) Write(b []byte) (n int, err error) {
    z := make([]byte, len(b))
    copy(z, b)
    f.LogInputChan <- z
    return len(b), nil
}