Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

html/template: Execute is not concurrent safe #51344

Closed
bep opened this issue Feb 24, 2022 · 11 comments
Closed

html/template: Execute is not concurrent safe #51344

bep opened this issue Feb 24, 2022 · 11 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.

Comments

@bep
Copy link
Contributor

bep commented Feb 24, 2022

Note that I suspect this is the same issue as I reported long time ago in #30286.

What version of Go are you using (go version)?

go version go1.17.7 darwin/arm64

But I have also experienced this with most earlier Go versions.

Does this issue reproduce with the latest release?

Yes.

What operating system and processor architecture are you using (go env)?

go env Output
GO111MODULE=""
GOARCH="arm64"
GOBIN=""
GOCACHE="/Users/bep/Library/Caches/go-build"
GOENV="/Users/bep/Library/Application Support/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="arm64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/bep/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/bep/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_arm64"
GOVCS=""
GOVERSION="go1.17.7"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/bep/dev/go/bep/temp/go.mod"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/_g/j3j21hts4fn7__h04w2x8gb40000gn/T/go-build2758236989=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

Run the following program with the -race flag:

package main

import (
	"html/template"
	"io/ioutil"
	"log"
	"sync"
	"sync/atomic"
	"time"
)

type Data struct {
	counter uint32
}

func (d *Data) Incr() uint32 {
	atomic.AddUint32(&d.counter, 1)
	return atomic.LoadUint32(&d.counter)
}

func main() {
	templ, err := template.New("master").Parse(`
{{ .Incr }}
{{ . }}
`)
	if err != nil {
		log.Fatal(err)
	}

	var wg sync.WaitGroup

	data := &Data{}

	for i := 0; i < 10; i++ {
		wg.Add(1)
		go func() {
			defer wg.Done()

			for i := 0; i < 10; i++ {
				if err := templ.Execute(ioutil.Discard, data); err != nil {
					log.Fatal(err)
				}
				time.Sleep(23 * time.Millisecond)
			}
		}()
	}

	wg.Wait()
	log.Println("Done ...")
}

What did you expect to see?

Done ...

What did you see instead?

==================
WARNING: DATA RACE
Write at 0x00c00011601c by goroutine 13:
  ??()
      -:0 +0x104f344c8
  main.(*Data).Incr()
      /Users/bep/dev/go/bep/temp/main.go:17 +0x3c
  runtime.call16()
      /usr/local/go/src/runtime/asm_arm64.s:414 +0x70
  reflect.Value.Call()
      /usr/local/go/src/reflect/value.go:339 +0x98
  text/template.safeCall()
      /usr/local/go/src/text/template/funcs.go:368 +0x94
  text/template.(*state).evalCall()
      /usr/local/go/src/text/template/exec.go:724 +0x848
  text/template.(*state).evalField()
      /usr/local/go/src/text/template/exec.go:608 +0x9b4
  text/template.(*state).evalFieldChain()
      /usr/local/go/src/text/template/exec.go:569 +0x1f8
  text/template.(*state).evalFieldNode()
      /usr/local/go/src/text/template/exec.go:533 +0x114
  text/template.(*state).evalCommand()
      /usr/local/go/src/text/template/exec.go:461 +0x588
  text/template.(*state).evalPipeline()
      /usr/local/go/src/text/template/exec.go:435 +0x1b0
  text/template.(*state).walk()
      /usr/local/go/src/text/template/exec.go:254 +0x318
  text/template.(*state).walk()
      /usr/local/go/src/text/template/exec.go:263 +0x5cc
  text/template.(*Template).execute()
      /usr/local/go/src/text/template/exec.go:217 +0x464
  text/template.(*Template).Execute()
      /usr/local/go/src/text/template/exec.go:200 +0xac
  html/template.(*Template).Execute()
      /usr/local/go/src/html/template/template.go:124 +0x6c
  main.main.func1()
      /Users/bep/dev/go/bep/temp/main.go:40 +0xe0

Previous read at 0x00c00011601e by goroutine 8:
  reflect.typedmemmove()
      /usr/local/go/src/runtime/mbarrier.go:178 +0x0
  reflect.packEface()
      /usr/local/go/src/reflect/value.go:123 +0xa0
  reflect.valueInterface()
      /usr/local/go/src/reflect/value.go:1394 +0x1a4
  reflect.Value.Interface()
      /usr/local/go/src/reflect/value.go:1364 +0x33c
  html/template.indirectToStringerOrError()
      /usr/local/go/src/html/template/content.go:146 +0x340
  html/template.stringify()
      /usr/local/go/src/html/template/content.go:181 +0x550
  html/template.htmlEscaper()
      /usr/local/go/src/html/template/html.go:43 +0x40
  runtime.call64()
      /usr/local/go/src/runtime/asm_arm64.s:416 +0x70
  reflect.Value.Call()
      /usr/local/go/src/reflect/value.go:339 +0x98
  text/template.safeCall()
      /usr/local/go/src/text/template/funcs.go:368 +0x94
  text/template.(*state).evalCall()
      /usr/local/go/src/text/template/exec.go:724 +0x848
  text/template.(*state).evalFunction()
      /usr/local/go/src/text/template/exec.go:579 +0x1d4
  text/template.(*state).evalCommand()
      /usr/local/go/src/text/template/exec.go:466 +0x12c
  text/template.(*state).evalPipeline()
      /usr/local/go/src/text/template/exec.go:435 +0x1b0
  text/template.(*state).walk()
      /usr/local/go/src/text/template/exec.go:254 +0x318
  text/template.(*state).walk()
      /usr/local/go/src/text/template/exec.go:263 +0x5cc
  text/template.(*Template).execute()
      /usr/local/go/src/text/template/exec.go:217 +0x464
  text/template.(*Template).Execute()
      /usr/local/go/src/text/template/exec.go:200 +0xac
  html/template.(*Template).Execute()
      /usr/local/go/src/html/template/template.go:124 +0x6c
  main.main.func1()
      /Users/bep/dev/go/bep/temp/main.go:40 +0xe0

Goroutine 13 (running) created at:
  main.main()
      /Users/bep/dev/go/bep/temp/main.go:36 +0x17c

Goroutine 8 (running) created at:
  main.main()
      /Users/bep/dev/go/bep/temp/main.go:36 +0x17c
==================
2022/02/24 08:40:33 Done ...
@mengzhuo mengzhuo added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Feb 24, 2022
@mengzhuo
Copy link
Contributor

A much more easier testcase:

type Data struct {
	counter uint32
}

func (d *Data) Incr() uint32 {
	atomic.AddUint32(&d.counter, 1)
	return atomic.LoadUint32(&d.counter)
}

func main() {
	templ, err := template.New("master").Parse(`
{{ .Incr }}
{{ . }}
`)
	if err != nil {
		log.Fatal(err)
	}
	data := &Data{}
        go func() {
	        if err := templ.Execute(ioutil.Discard, data); err != nil {
			        log.Fatal(err)
	        }
        }()
	if err := templ.Execute(ioutil.Discard, data); err != nil {
			log.Fatal(err)
	}
}

I think the doc should changed into

A template is not concurrent safe to execute.

CC @robpike @mvdan

@mengzhuo mengzhuo changed the title html/template: data race in indirect html/template: Execute is not concurrent safe Feb 24, 2022
@bep
Copy link
Contributor Author

bep commented Feb 24, 2022

Just to be clear: This is the current documentation of Execute:

https://github.com/golang/go/blob/master/src/html/template/template.go#L118

// A template may be executed safely in parallel, although if parallel
// executions share a Writer the output may be interleaved.

@mengzhuo
Copy link
Contributor

mengzhuo commented Feb 24, 2022

The Execute function walk through the data by reflecting fields, for objects that share pointer WILL inevitable be data race .
Putting a mutex in the template for Execute will solve this issue, unfortunately this will cause a performance regression on objects which not share any pointer.

@seankhliao
Copy link
Member

This may be working as intended:
While you protect writes to *Data.counter by sync/atomic, the reads from template {{ . }} aren't so there's a race.

@bep
Copy link
Contributor Author

bep commented Feb 24, 2022

A template is not concurrent safe to execute.

@mengzhuo I get a mild heart attack just by reading suggestions like the above. html/template.Execute has existed since Go 1.1/1.0 and, a bold statement, is most likely the single method in Go's stdlib that has seen most parallel execution and variation under the race detector. With that I think my original issue title would be more descriptive.

While you protect writes to *Data.counter by sync/atomic, the reads from template {{ . }} aren't so there's a race.

@seankhliao So, the example given above is obviously simplified and synthetic. The panic comes from tests that fails like 1/100 in a CI environment that I have not managed to pinpoint exactly, but the stack trace is similar.

This is the object:

type Data struct {
	counter uint32
}

The reads you talk about comes from html/template.indirectToStringerOrError. It should certainly be both possible and the expected thing to create a string representation of *Data without a data race related to the unexported field counter.

@seankhliao
Copy link
Member

seankhliao commented Feb 24, 2022

What you're doing is essentially this, just via the template package.

package main

import (
	"fmt"
	"io"
	"sync"
	"sync/atomic"
)

type Data struct {
	counter uint32
}

func (d *Data) Incr() uint32 {
	atomic.AddUint32(&d.counter, 1)
	return atomic.LoadUint32(&d.counter)
}

func main() {
	d := &Data{}
	var wg sync.WaitGroup
	for i := 0; i < 100; i++ {
		wg.Add(1)
		go func() {
			defer wg.Done()
			d.Incr()
			fmt.Fprintln(io.Discard, d)
		}()
	}
	wg.Wait()
}

I don't think it's expected or reasonable for library functions to magically synchronize your code. The fact that it's unexported doesn't matter, you've asked for it to be read without synchronization.

@bep
Copy link
Contributor Author

bep commented Feb 24, 2022

What you're doing is essentially this, just via the template package.

I would say that fmt.Fprintln's behaviour is also surprising and buggy, but I would argue that this is similar to:

package main

import (
	"fmt"
	"io"
	"sync"
	"sync/atomic"
)

type Data struct {
	name    string
	counter uint32
}

func (d *Data) String() string {
	return d.name
}

type Incrementer interface {
	Incr() uint32
}

func (d *Data) Incr() uint32 {
	atomic.AddUint32(&d.counter, 1)
	return atomic.LoadUint32(&d.counter)
}

func main() {
	var d Incrementer = &Data{}
	var wg sync.WaitGroup
	for i := 0; i < 100; i++ {
		wg.Add(1)
		go func() {
			defer wg.Done()
			d.Incr()
			if stringer, ok := d.(fmt.Stringer); ok {
				fmt.Fprintln(io.Discard, stringer.String())
			}
		}()
	}
	wg.Wait()
}

Which is does not fail. Note that I'm not suggesting the above as a fix, just as an illustration.

I don't think it's expected or reasonable for library functions to magically synchronize your code. T

A library function's role is to make life easier, and this is especially important in situations where the user lack other synchronization primitives (Go templates) and also a different security setup (dynamic web templates, possibly user provided).

But this is not a big thing for me as long as you're not changing the docs to "A template is not concurrent safe to execute".

@bep
Copy link
Contributor Author

bep commented Feb 24, 2022

The Execute function walk through the data by reflecting fields, for objects that share pointer WILL inevitable be data race .

@mengzhuo This race is about an un-exported field; you're talking about reflection as something magical, but you could easily argue that the reflect package should be adjusted to skip these fields as they're not relevant for this task (printing the struct).

@icholy
Copy link

icholy commented Feb 24, 2022

@bep The fmt package prints unexported fields by default. It's too late to change that now:

package main

import "fmt"

type Data struct {
	counter uint32
}

func main() {
	fmt.Println(Data{123}) // {123}
}

https://go.dev/play/p/HP0mvJiCaWJ

@ianlancetaylor
Copy link
Contributor

Like others, I'm not seeing a bug. I don't understand who this could possibly not be a race condition. No matter what, it has to fetch the value of data.counter in order to print it. Whether counter is exported or not is not relevant here. What is the argument that there isn't a race condition here?

The race is easy enough to avoid with code like

package main

import (
	"fmt"
	"html/template"
	"io"
	"log"
	"sync"
	"sync/atomic"
	"time"
)

type Data struct {
	counter uint32
}

func (d *Data) Incr() uint32 {
	atomic.AddUint32(&d.counter, 1)
	return atomic.LoadUint32(&d.counter)
}

func (d *Data) String() string {
	return fmt.Sprintf("{%d}", atomic.LoadUint32(&d.counter))
}

func main() {
	templ, err := template.New("master").Parse(`
{{ .Incr }}
{{ .String }}
`)
	if err != nil {
		log.Fatal(err)
	}

	var wg sync.WaitGroup

	data := &Data{}

	for i := 0; i < 10; i++ {
		wg.Add(1)
		go func() {
			defer wg.Done()

			for i := 0; i < 10; i++ {
				if err := templ.Execute(io.Discard, data); err != nil {
					log.Fatal(err)
				}
				time.Sleep(23 * time.Millisecond)
			}
		}()
	}

	wg.Wait()
	log.Println("Done ...")
}

@ianlancetaylor ianlancetaylor added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Feb 25, 2022
@gopherbot
Copy link

Timed out in state WaitingForInfo. Closing.

(I am just a bot, though. Please speak up if this is a mistake or you have the requested information.)

@golang golang locked and limited conversation to collaborators Mar 25, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Projects
None yet
Development

No branches or pull requests

6 participants