html/template: data race in Execute

[bep]

go version go1.14.3 darwin/amd64

Building the below program with go build -race and then running it fails:

package main

import (
	"fmt"
	"html/template"
	"io/ioutil"
	"log"
	"sync"
)

func main() {
	var wg sync.WaitGroup

	jsTempl := `
{{- define "jstempl" -}}
var foo = "bar";
{{- end -}}
<script type="application/javascript">
{{ template "jstempl" $ }}
</script>
`

	tpl := template.New("")
	_, err := tpl.New("templ.html").Parse(jsTempl)
	if err != nil {
		log.Fatal(err)
	}

	const numTemplates = 20

	for i := 0; i < numTemplates; i++ {
		_, err = tpl.New(fmt.Sprintf("main%d.html", i)).Parse(`{{ template "templ.html" . }}`)
		if err != nil {
			log.Fatal(err)
		}
	}

	for i := 1; i <= 10; i++ {
		wg.Add(1)
		go func() {
			defer wg.Done()
			for j := 0; j < numTemplates; j++ {
				templ := tpl.Lookup(fmt.Sprintf("main%d.html", j))
				if err := templ.Execute(ioutil.Discard, nil); err != nil {
					log.Fatal(err)
				}

			}
		}()
	}

	wg.Wait()
}

WARNING: DATA RACE

WARNING: DATA RACE
Write at 0x00c00011c540 by goroutine 32:
  runtime.mapassign_faststr()
      /Users/bep/dev/go/dump/go/src/runtime/map_faststr.go:202 +0x0
  text/template.(*Template).associate()
      /Users/bep/dev/go/dump/go/src/text/template/template.go:227 +0x1a8
  text/template.(*Template).AddParseTree()
      /Users/bep/dev/go/dump/go/src/text/template/template.go:133 +0x2cc
  html/template.(*escaper).commit()
      /Users/bep/dev/go/dump/go/src/html/template/escape.go:810 +0x2c5
  html/template.escapeTemplate()
      /Users/bep/dev/go/dump/go/src/html/template/escape.go:38 +0x324
  html/template.(*Template).escape()
      /Users/bep/dev/go/dump/go/src/html/template/template.go:102 +0x349
  html/template.(*Template).Execute()
      /Users/bep/dev/go/dump/go/src/html/template/template.go:119 +0x3c
  main.main.func1()
      /Users/bep/dev/go/bep/temp/main.go:46 +0x177
Previous read at 0x00c00011c540 by goroutine 28:

runtime.mapaccess1_faststr()

/Users/bep/dev/go/dump/go/src/runtime/map_faststr.go:12 +0x0

text/template.(*state).walkTemplate()

/Users/bep/dev/go/dump/go/src/text/template/exec.go:399 +0x13b

text/template.(*state).walk()

/Users/bep/dev/go/dump/go/src/text/template/exec.go:268 +0x2be

text/template.(*state).walk()

/Users/bep/dev/go/dump/go/src/text/template/exec.go:263 +0x195

text/template.(*Template).execute()

/Users/bep/dev/go/dump/go/src/text/template/exec.go:220 +0x2fb

text/template.(*Template).Execute()

/Users/bep/dev/go/dump/go/src/text/template/exec.go:203 +0xd2

html/template.(*Template).Execute()

/Users/bep/dev/go/dump/go/src/html/template/template.go:122 +0x7f

main.main.func1()

/Users/bep/dev/go/bep/temp/main.go:46 +0x177
Goroutine 32 (running) created at:

main.main()

/Users/bep/dev/go/bep/temp/main.go:42 +0x2de
Goroutine 28 (running) created at:

main.main()

/Users/bep/dev/go/bep/temp/main.go:42 +0x2de
==================

WARNING: DATA RACE

Write at 0x00c0000ac0b0 by goroutine 32:

text/template.(*Template).associate()

/Users/bep/dev/go/dump/go/src/text/template/template.go:227 +0x1bd

text/template.(*Template).AddParseTree()

/Users/bep/dev/go/dump/go/src/text/template/template.go:133 +0x2cc

html/template.(*escaper).commit()

/Users/bep/dev/go/dump/go/src/html/template/escape.go:810 +0x2c5

html/template.escapeTemplate()

/Users/bep/dev/go/dump/go/src/html/template/escape.go:38 +0x324

html/template.(*Template).escape()

/Users/bep/dev/go/dump/go/src/html/template/template.go:102 +0x349

html/template.(*Template).Execute()

/Users/bep/dev/go/dump/go/src/html/template/template.go:119 +0x3c

main.main.func1()

/Users/bep/dev/go/bep/temp/main.go:46 +0x177
Previous read at 0x00c0000ac0b0 by goroutine 28:

text/template.(*state).walkTemplate()

/Users/bep/dev/go/dump/go/src/text/template/exec.go:399 +0x14e

text/template.(*state).walk()

/Users/bep/dev/go/dump/go/src/text/template/exec.go:268 +0x2be

text/template.(*state).walk()

/Users/bep/dev/go/dump/go/src/text/template/exec.go:263 +0x195

text/template.(*state).walkTemplate()

/Users/bep/dev/go/dump/go/src/text/template/exec.go:413 +0x3cd

text/template.(*state).walk()

/Users/bep/dev/go/dump/go/src/text/template/exec.go:268 +0x2be

text/template.(*state).walk()

/Users/bep/dev/go/dump/go/src/text/template/exec.go:263 +0x195

text/template.(*Template).execute()

/Users/bep/dev/go/dump/go/src/text/template/exec.go:220 +0x2fb

text/template.(*Template).Execute()

/Users/bep/dev/go/dump/go/src/text/template/exec.go:203 +0xd2

html/template.(*Template).Execute()

/Users/bep/dev/go/dump/go/src/html/template/template.go:122 +0x7f

main.main.func1()

/Users/bep/dev/go/bep/temp/main.go:46 +0x177
Goroutine 32 (running) created at:

main.main()

/Users/bep/dev/go/bep/temp/main.go:42 +0x2de
Goroutine 28 (running) created at:

main.main()

/Users/bep/dev/go/bep/temp/main.go:42 +0x2de
Found 2 data race(s)

[davecheney]

@bep thanks for the issue. Are you able to check Go 1.13 and see if it is affected? (This will determine if this is a blocker for 1.15 or not)

/cc @dmitshur

[bep]

It also fails on go1.13.12.

[FiloSottile]

/cc @empijei

[cagedmantis]

/cc @mikesamuel

[empijei]

Some additional info:

• This does not affect "text/template"
• This also affects ExecuteTemplate so it is not just an issue with the lookup+execute calls.
• This does not happen if the templates are executed at least once before the concurrent execution. This is probably due to a lazy computation since the race happens in a escapeTemplate call, which is only executed once per template.
• My best guess is that the computation is lazy because it involves calling nested templates but I'd need to take a better look at this. The escape should be happening while holding a lock or should be executed at parse time if possible.

As a quick workaround running the templates once before they are run concurrently addresses the issue (see code below), but we need to properly fix this.

Thanks for reporting.

package main

import (
	"fmt"
	"html/template"
	"io/ioutil"
	"log"
	"sync"
)

func main() {
	var wg sync.WaitGroup

	jsTempl := `
{{- define "jstempl" -}}
var foo = "bar";
{{- end -}}
<script type="application/javascript">
{{ template "jstempl" $ }}
</script>
`

	tpl := template.New("")
	_, err := tpl.New("templ.html").Parse(jsTempl)
	if err != nil {
		log.Fatal(err)
	}

	const numTemplates = 20

	for i := 0; i < numTemplates; i++ {
		_, err = tpl.New(fmt.Sprintf("main%d.html", i)).Parse(`{{ template "templ.html" . }}`)
		if err != nil {
			log.Fatal(err)
		}
	}

        // Temporary workaround to prevent the race.
	for j := 0; j < numTemplates; j++ {
		if err := tpl.ExecuteTemplate(ioutil.Discard, fmt.Sprintf("main%d.html", j), nil); err != nil {
			log.Fatal(err)
		}
	}

	for i := 1; i <= 10; i++ {
		wg.Add(1)
		go func() {
			defer wg.Done()
			for j := 0; j < numTemplates; j++ {
				if err := tpl.ExecuteTemplate(ioutil.Discard, fmt.Sprintf("main%d.html", j), nil); err != nil {
					log.Fatal(err)
				}
			}
		}()
	}

	wg.Wait()
}

[andreasf]

This appears to be the same data race causing gohugoio/hugo#7293, where it is triggered from text/template.

Hugo have a temporary fork of text/template included in their codebase. I attempted to fix the data race in the fork: gohugoio/hugo#7507. They'd rather have it upstreamed though.

[andreasf]

I pulled the patch out of Hugo's fork of text/template and changed it a bit:

• Separate lock for tmpl instead of reusing muFunc—not sure if that's best
• Use lock everywhere tmpl is accessed

Personally, I'd prefer a single lock as it's simpler and safer. What do you think, should I file a PR?

[empijei]

Do you have a proposal to fix the race described in this bug report? If so please do send a CL my way 😄

[gopherbot]

Change https://golang.org/cl/257817 mentions this issue: text/template: add lock for Template.tmpl to fix data race