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

Jump to bottom

x/net/trace: race when rendering active requests #24231

Closed
dhowden opened this issue Mar 3, 2018 · 5 comments
Closed

x/net/trace: race when rendering active requests #24231

dhowden opened this issue Mar 3, 2018 · 5 comments
Labels
FrozenDueToAge help wanted
Milestone
Unreleased

Comments

@dhowden
Copy link
Contributor

dhowden commented Mar 3, 2018

Please answer these questions before submitting your issue. Thanks!

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

go1.10

Does this issue reproduce with the latest release?

Yes

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

GOARCH="amd64"
GOOS="darwin"

What did you do?

View "Active" requests in /debug/requests endpoint provided by golang.org/x/net/trace.

What did you expect to see?

No races.

What did you see instead?

==================
WARNING: DATA RACE
Write at 0x00c42015a038 by goroutine 6:
  golang.org/x/net/trace.(*trace).Finish()
      /Users/dhowden/git/go/src/golang.org/x/net/trace/trace.go:371 +0xf4
  main.main.func1()
      /Users/dhowden/git/go/src/github.com/dhowden/tracerace/main.go:18 +0x91

Previous read at 0x00c42015a038 by goroutine 11:
  golang.org/x/net/trace.(*trace).ElapsedTime()
      /Users/dhowden/git/go/src/golang.org/x/net/trace/trace.go:847 +0x40
  runtime.call32()
      /usr/local/go/src/runtime/asm_amd64.s:573 +0x3a
  reflect.Value.Call()
      /usr/local/go/src/reflect/value.go:308 +0xc0
  text/template.(*state).evalCall()
      /usr/local/go/src/text/template/exec.go:667 +0x667
  text/template.(*state).evalField()
      /usr/local/go/src/text/template/exec.go:557 +0xe4a
  text/template.(*state).evalFieldChain()
      /usr/local/go/src/text/template/exec.go:525 +0x2db
  text/template.(*state).evalVariableNode()
      /usr/local/go/src/text/template/exec.go:513 +0x260
  text/template.(*state).evalCommand()
      /usr/local/go/src/text/template/exec.go:437 +0xa21
  text/template.(*state).evalPipeline()
      /usr/local/go/src/text/template/exec.go:405 +0x1a8
  text/template.(*state).walk()
      /usr/local/go/src/text/template/exec.go:231 +0x695
  text/template.(*state).walk()
      /usr/local/go/src/text/template/exec.go:239 +0x263
  text/template.(*state).walkRange.func1()
      /usr/local/go/src/text/template/exec.go:326 +0x139
  text/template.(*state).walkRange()
      /usr/local/go/src/text/template/exec.go:335 +0x424
  text/template.(*state).walk()
      /usr/local/go/src/text/template/exec.go:242 +0x61b
  text/template.(*state).walk()
      /usr/local/go/src/text/template/exec.go:239 +0x263
  text/template.(*state).walkIfOrWith()
      /usr/local/go/src/text/template/exec.go:269 +0x1d9
  text/template.(*state).walk()
      /usr/local/go/src/text/template/exec.go:236 +0x49b
  text/template.(*state).walk()
      /usr/local/go/src/text/template/exec.go:239 +0x263
  text/template.(*state).walkTemplate()
      /usr/local/go/src/text/template/exec.go:388 +0x398
  text/template.(*state).walk()
      /usr/local/go/src/text/template/exec.go:244 +0x2ef
  text/template.(*state).walk()
      /usr/local/go/src/text/template/exec.go:239 +0x263
  text/template.(*Template).execute()
      /usr/local/go/src/text/template/exec.go:194 +0x3cf
  text/template.(*Template).Execute()
      /usr/local/go/src/text/template/exec.go:177 +0x64
  html/template.(*Template).ExecuteTemplate()
      /usr/local/go/src/html/template/template.go:137 +0xf2
  golang.org/x/net/trace.Render()
      /Users/dhowden/git/go/src/golang.org/x/net/trace/trace.go:256 +0x7e4
  golang.org/x/net/trace.Traces()
      /Users/dhowden/git/go/src/golang.org/x/net/trace/trace.go:131 +0x104
  net/http.HandlerFunc.ServeHTTP()
      /usr/local/go/src/net/http/server.go:1947 +0x51
  net/http.(*ServeMux).ServeHTTP()
      /usr/local/go/src/net/http/server.go:2337 +0x9f
  net/http.serverHandler.ServeHTTP()
      /usr/local/go/src/net/http/server.go:2694 +0xb9
  net/http.(*conn).serve()
      /usr/local/go/src/net/http/server.go:1830 +0x7dc

Goroutine 6 (running) created at:
  main.main()
      /Users/dhowden/git/go/src/github.com/dhowden/tracerace/main.go:14 +0x57

Goroutine 11 (finished) created at:
  net/http.(*Server).Serve()
      /usr/local/go/src/net/http/server.go:2795 +0x364
  net/http/httptest.(*Server).goServe.func1()
      /usr/local/go/src/net/http/httptest/server.go:280 +0xa2
==================

This Go program reproduces the issue.

package main

import (
	"fmt"
	"net/http"
	"net/http/httptest"
	"time"

	"golang.org/x/net/trace"
)

func main() {
	go func() {
		for {
			t := trace.New("family", "title")
			time.Sleep(200 * time.Millisecond)
			t.Finish()
		}
	}()

	// EITHER:
	//
	// Start the webserver and trigger by viewing "Active" requests.
	//
	// http.ListenAndServe("localhost:8888", nil)

	// OR:
	// Run the test server and trigger the race in code:
	m := http.NewServeMux()
	m.HandleFunc("/debug/requests", trace.Traces)

	s := httptest.NewServer(m)
	s.Client().Get(fmt.Sprintf("%v/debug/requests?fam=family&b=-1", s.URL))
}
@gopherbot gopherbot added this to the Unreleased milestone Mar 3, 2018
@odeke-em
Copy link
Member

odeke-em commented Mar 3, 2018

/cc @dsymonds @rakyll @bradfitz

@subbu05
Copy link

subbu05 commented Mar 4, 2018 •
edited

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

go1.10

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

GOARCH="amd64"
GOOS="darwin"
go env
GOARCH="amd64"
GOBIN="/Users/test/go/bin"
GOCACHE="/Users/test/Library/Caches/go-build"
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/test/go"
GORACE=""
GOROOT="/usr/local/Cellar/go/1.10/libexec"
GOTMPDIR=""
GOTOOLDIR="/usr/local/Cellar/go/1.10/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/76/trlnwqwj0bs5003x850kzpg00000gn/T/go-build892682696=/tmp/go-build -gno-record-gcc-switches -fno-common"

Mac OS Sierra
10.13.3

By running above program I didn't see any issue. I was able to get the stats.

screen shot 2018-03-03 at 10 04 36 pm

(url)

@dhowden
Copy link
Contributor Author

dhowden commented Mar 4, 2018

Hey @subbu05. Build the code I've posted with go build -race and then run it. The page will render fine in the browser, but you should see the WARNING: DATA RACE message in the command output.

Using the test server is probably easier, you don't need a browser for that.

@dhowden
Copy link
Contributor Author

dhowden commented Mar 4, 2018

FYI: I have a fix for this, but my solution changes the template (to avoid having to add any more sync code in the trace internals). Will try to work out how to submit and attach to the issue.

@gopherbot
Copy link

Change https://golang.org/cl/98535 mentions this issue: net/trace: fix race on Elapsed property when rendering active requests

gopherbot pushed a commit to golang/net that referenced this issue Mar 8, 2018
@dhowden @hyangah
trace: fix races on concurrent Trace method calls
d0aafc7 
This change protects fields mutated by Trace methods with a mutex.
In particular it fixes races caused by concurrent calls to IsError,
and viewing active traces in /debug/requests.

Includes changes from CL/67730.

Updates golang/go#24231

Change-Id: I07db54c2642efe0ea0e3ffeb54ec796ae51e70ef
Reviewed-on: https://go-review.googlesource.com/98535
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Hyang-Ah Hana Kim <hyangah@gmail.com>
@dhowden dhowden closed this as completed Mar 11, 2018
@golang golang locked and limited conversation to collaborators Mar 11, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge help wanted
Projects
None yet
Milestone
Unreleased
Development

No branches or pull requests
4 participants
@dhowden @odeke-em @subbu05 @gopherbot