How to programatically prove this code has a race condition?

I'm told this code has a race condition by design, though try as I may, I'm unable to prove it does.

func (h *handler) loggingMiddleware(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        h.Log = log.WithFields(log.Fields{
            "method":     r.Method,
            "requestURI": r.RequestURI,
        })
        next.ServeHTTP(w, r)
    })
}

I tried go build -race, then running the binary: PORT=3000 ./main & load creators like hey -n 10000 -c 200 http://localhost:3000.

Rest of the code here: https://raw.githubusercontent.com/kaihendry/context-youtube/master/5/main.go

type handler struct{ Log *log.Entry }

func New() (h *handler) { return &handler{Log: log.WithFields(log.Fields{"test": "FAIL"})} }

func (h *handler) index(w http.ResponseWriter, r *http.Request) {
    h.Log.Info("index")
    fmt.Fprintf(w, "hello")
}

func (h *handler) about(w http.ResponseWriter, r *http.Request) {
    h.Log.Info("about")
    fmt.Fprintf(w, "about")
}

func main() {
    h := New()
    app := mux.NewRouter()
    app.HandleFunc("/", h.index)
    app.HandleFunc("/about", h.about)
    app.Use(h.loggingMiddleware)
    if err := http.ListenAndServe(":"+os.Getenv("PORT"), app); err != nil {
        log.WithError(err).Fatal("error listening")
    }
}

If I can't prove it has a race condition, can I assume setting h.Log is safe?

Solution

There is a programmatic way, for which you have to do 2 things:

reproduce the racy condition
and use the -race option when launching the go tool

Best is if you write a unit test for it, so the test is also reproducible, and run / checked automatically on each build / deploy.

Ok, so how to reproduce it?

Simply write a test which launches 2 goroutines, one which calls the index handler, and one which calls the about handler, deliberately without synchronization, this is what triggers the race detector.

Use the net/http/httptest package to easily test handlers. httptest.NewServer() hands you a ready server, "armed" with the handler you pass to it.

Here's a simple test example that will trigger the race condition. Put it in a file named main_test.go, next to your main.go file:

package main

import (
    "fmt"
    "net/http"
    "net/http/httptest"
    "sync"
    "testing"

    "github.com/gorilla/mux"
)

func TestRace(t *testing.T) {
    h := New()
    app := mux.NewRouter()
    app.HandleFunc("/", h.index)
    app.HandleFunc("/about", h.about)
    app.Use(h.loggingMiddleware)

    server := httptest.NewServer(app)
    defer server.Close()

    wg := &sync.WaitGroup{}
    for _, path := range []string{"/", "/about"} {
        path := path
        wg.Add(1)
        go func() {
            defer wg.Done()
            req, err := http.NewRequest(http.MethodGet, server.URL+path, nil)
            fmt.Println(server.URL + path)
            if err != nil {
                panic(err)
            }
            res, err := http.DefaultClient.Do(req)
            if err != nil {
                panic(err)
            }
            defer res.Body.Close()
        }()
    }
    wg.Wait()
}

You have to run it with

go test -race

And an example output will be:

http://127.0.0.1:33007/
http://127.0.0.1:33007/about
==================
WARNING: DATA RACE
Write at 0x00c000098030 by goroutine 17:
  play.(*handler).loggingMiddleware.func1()
      /home/icza/tmp/gows/src/play/main.go:16 +0x1ce
  net/http.HandlerFunc.ServeHTTP()
      /usr/local/go/src/net/http/server.go:1964 +0x51
  github.com/gorilla/mux.(*Router).ServeHTTP()
      /home/icza/tmp/gows/src/github.com/gorilla/mux/mux.go:212 +0x12e
  net/http.serverHandler.ServeHTTP()
      /usr/local/go/src/net/http/server.go:2741 +0xc4
  net/http.(*conn).serve()
      /usr/local/go/src/net/http/server.go:1847 +0x80a

Previous write at 0x00c000098030 by goroutine 16:
  play.(*handler).loggingMiddleware.func1()
      /home/icza/tmp/gows/src/play/main.go:16 +0x1ce
  net/http.HandlerFunc.ServeHTTP()
      /usr/local/go/src/net/http/server.go:1964 +0x51
  github.com/gorilla/mux.(*Router).ServeHTTP()
      /home/icza/tmp/gows/src/github.com/gorilla/mux/mux.go:212 +0x12e
  net/http.serverHandler.ServeHTTP()
      /usr/local/go/src/net/http/server.go:2741 +0xc4
  net/http.(*conn).serve()
      /usr/local/go/src/net/http/server.go:1847 +0x80a

Goroutine 17 (running) created at:
  net/http.(*Server).Serve()
      /usr/local/go/src/net/http/server.go:2851 +0x4c5
  net/http/httptest.(*Server).goServe.func1()
      /usr/local/go/src/net/http/httptest/server.go:280 +0xac

Goroutine 16 (running) created at:
  net/http.(*Server).Serve()
      /usr/local/go/src/net/http/server.go:2851 +0x4c5
  net/http/httptest.(*Server).goServe.func1()
      /usr/local/go/src/net/http/httptest/server.go:280 +0xac
==================
2019/01/06 14:58:50  info index                     method=GET requestURI=/
2019/01/06 14:58:50  info about                     method=GET requestURI=/about
--- FAIL: TestRace (0.00s)
    testing.go:771: race detected during execution of test
FAIL
exit status 1
FAIL    play    0.011s

The test fails, showing that there are data races.

Notes:

The synchronization with the sync.WaitGroup is to wait for the 2 launched goroutines, it is not to synchronize access to the handler's logger (which causes the data race). This is so if you fix the data race, the test will run and end properly (waiting for the 2 launched test-goroutines to complete).