pongo2 icon indicating copy to clipboard operation
pongo2 copied to clipboard

Data race in `pongo2.FromFile()` method

Open adonespitogo opened this issue 2 years ago • 5 comments

System:

go version go1.19.4 darwin/arm64

Problem:

pongo2.FromFile() method is having a data race when put under wrk stress test. The commands I used for stress test is:

wrk -t4 -c400 -d5s http://localhost:3001/

Setup:

The setup is just a single view with data:

main.go:

package main

import (
        "fmt"
        "github.com/flosch/pongo2/v6"
        "log"
        "net/http"
)

func main() {
        http.HandleFunc("/", func(w http.ResponseWriter, _ *http.Request) {
                data := pongo2.Context{
                        "status": "Hello World",
                }

                tmpl, err := pongo2.FromFile("index.html")
                if err != nil {
                        panic(err)
                }

                res, err := tmpl.Execute(data)
                if err != nil {
                        panic(err)
                }
                fmt.Fprint(w, res)
        })

        log.Println("Server listening on port 3001")
        http.ListenAndServe(":3001", nil)
}

index.html:

<h1>{{ status }}</h1>

Result: Data Race

WARNING: DATA RACE
Write at 0x00c0001a27b0 by goroutine 16:
  github.com/flosch/pongo2/v6.(*TemplateSet).FromFile()
      /Users/adonesp/.gvm/pkgsets/go1.19.4/global/pkg/mod/github.com/flosch/pongo2/[email protected]/template_sets.go:212 +0x38
  github.com/flosch/pongo2/v6.(*TemplateSet).FromFile-fm()
      <autogenerated>:1 +0x44
  main.main.func1()
      /Users/adonesp/Projects/go-practice/pongo-error/main.go:16 +0xf8
  net/http.HandlerFunc.ServeHTTP()
      /Users/adonesp/.gvm/gos/go1.19.4/src/net/http/server.go:2109 +0x48
  net/http.(*ServeMux).ServeHTTP()
      /Users/adonesp/.gvm/gos/go1.19.4/src/net/http/server.go:2487 +0x9c
  net/http.serverHandler.ServeHTTP()
      /Users/adonesp/.gvm/gos/go1.19.4/src/net/http/server.go:2947 +0x4f4
  net/http.(*conn).serve()
      /Users/adonesp/.gvm/gos/go1.19.4/src/net/http/server.go:1991 +0x8d4
  net/http.(*Server).Serve.func3()
      /Users/adonesp/.gvm/gos/go1.19.4/src/net/http/server.go:3102 +0x4c

Previous write at 0x00c0001a27b0 by goroutine 15:
  github.com/flosch/pongo2/v6.(*TemplateSet).FromFile()
      /Users/adonesp/.gvm/pkgsets/go1.19.4/global/pkg/mod/github.com/flosch/pongo2/[email protected]/template_sets.go:212 +0x38
  github.com/flosch/pongo2/v6.(*TemplateSet).FromFile-fm()
      <autogenerated>:1 +0x44
  main.main.func1()
      /Users/adonesp/Projects/go-practice/pongo-error/main.go:16 +0xf8
  net/http.HandlerFunc.ServeHTTP()
      /Users/adonesp/.gvm/gos/go1.19.4/src/net/http/server.go:2109 +0x48
  net/http.(*ServeMux).ServeHTTP()
      /Users/adonesp/.gvm/gos/go1.19.4/src/net/http/server.go:2487 +0x9c
  net/http.serverHandler.ServeHTTP()
      /Users/adonesp/.gvm/gos/go1.19.4/src/net/http/server.go:2947 +0x4f4
  net/http.(*conn).serve()
      /Users/adonesp/.gvm/gos/go1.19.4/src/net/http/server.go:1991 +0x8d4
  net/http.(*Server).Serve.func3()
      /Users/adonesp/.gvm/gos/go1.19.4/src/net/http/server.go:3102 +0x4c

Goroutine 16 (running) created at:
  net/http.(*Server).Serve()
      /Users/adonesp/.gvm/gos/go1.19.4/src/net/http/server.go:3102 +0x628
  net/http.(*Server).ListenAndServe()
      /Users/adonesp/.gvm/gos/go1.19.4/src/net/http/server.go:2999 +0xa4
  net/http.ListenAndServe()
      /Users/adonesp/.gvm/gos/go1.19.4/src/net/http/server.go:3255 +0x158
  main.main()
      /Users/adonesp/Projects/go-practice/pongo-error/main.go:29 +0x88

Goroutine 15 (running) created at:
  net/http.(*Server).Serve()
      /Users/adonesp/.gvm/gos/go1.19.4/src/net/http/server.go:3102 +0x628
  net/http.(*Server).ListenAndServe()
      /Users/adonesp/.gvm/gos/go1.19.4/src/net/http/server.go:2999 +0xa4
  net/http.ListenAndServe()
      /Users/adonesp/.gvm/gos/go1.19.4/src/net/http/server.go:3255 +0x158
  main.main()
      /Users/adonesp/Projects/go-practice/pongo-error/main.go:29 +0x88```

adonespitogo avatar Jan 06 '23 13:01 adonespitogo

This might be related to #163

adonespitogo avatar Jan 06 '23 13:01 adonespitogo

My temporary solution is to use sync.Mutex in the method where pongo2.FromFile() is called:

var renderMu sync.Mutex
func RenderView() {
    renderMu.Lock()
    defer renderMu.Unlock()
    
    tmpl, err := pongo2.FromFile("index.html")
    // .... rest of the code
}

adonespitogo avatar Jan 06 '23 13:01 adonespitogo

Thanks for reporting, will have a look when time allows.

flosch avatar Jan 06 '23 14:01 flosch

If it's about the line

	set.firstTemplateCreated = true

Then it's harmless, it's just unprotected access on a basically integer value, which on x86/x64 will "just" result in different CPUs seeing a different cached value until they are synced (which is usually unpredictable).

The easiest fix would be to either convert firstTemplateCreated to int32 and use StoreInt32 or LoadInt32 from sync/atomic, or convert it to the Bool type from the same module.

See e.g. https://pkg.go.dev/sync/atomic#Bool

ivoras avatar Apr 11 '23 22:04 ivoras

I can confirm the issue is fixed by changing set.firstTemplateCreated to an atomic boolean type.

adonespitogo avatar Jul 27 '23 12:07 adonespitogo