Skip to content
This repository has been archived by the owner on Apr 18, 2021. It is now read-only.

Possible Race condition #39

Open
StarpTech opened this issue Aug 20, 2017 · 3 comments
Open

Possible Race condition #39

StarpTech opened this issue Aug 20, 2017 · 3 comments

Comments

@StarpTech
Copy link

StarpTech commented Aug 20, 2017 •
edited
Loading

Hi, I run into following race condition. On windows the issue happens randomly but on travis ci its reproducible see logs https://travis-ci.org/hemerajs/momos/builds/266557761

==================
WARNING: DATA RACE
Write at 0x00c420160058 by goroutine 16:
  net/http.(*response).Header()
      /home/travis/.gimme/versions/go1.8.3.linux.amd64/src/net/http/server.go:1032 +0x63
  github.com/lox/httpcache.(*responseStreamer).Header()
      <autogenerated>:97 +0x69
  net/http/httputil.(*ReverseProxy).ServeHTTP()
      /home/travis/.gimme/versions/go1.8.3.linux.amd64/src/net/http/httputil/reverseproxy.go:257 +0xc9a
  github.com/lox/httpcache.(*Handler).passUpstream.func1()
      /home/travis/gopath/src/github.com/lox/httpcache/handler.go:254 +0x8b
Previous write at 0x00c420160058 by goroutine 12:
  net/http.(*response).Header()
      /home/travis/.gimme/versions/go1.8.3.linux.amd64/src/net/http/server.go:1032 +0x63
  github.com/lox/httpcache.(*Handler).passUpstream()
      /home/travis/gopath/src/github.com/lox/httpcache/handler.go:261 +0x4e6
  github.com/lox/httpcache.(*Handler).ServeHTTP()
      /home/travis/gopath/src/github.com/lox/httpcache/handler.go:97 +0xbf9
  net/http.serverHandler.ServeHTTP()
      /home/travis/.gimme/versions/go1.8.3.linux.amd64/src/net/http/server.go:2568 +0xbc
  net/http.(*conn).serve()
      /home/travis/.gimme/versions/go1.8.3.linux.amd64/src/net/http/server.go:1825 +0x71a
Goroutine 16 (running) created at:
  github.com/lox/httpcache.(*Handler).passUpstream()
      /home/travis/gopath/src/github.com/lox/httpcache/handler.go:256 +0x36a
  github.com/lox/httpcache.(*Handler).ServeHTTP()
      /home/travis/gopath/src/github.com/lox/httpcache/handler.go:97 +0xbf9
  net/http.serverHandler.ServeHTTP()
      /home/travis/.gimme/versions/go1.8.3.linux.amd64/src/net/http/server.go:2568 +0xbc
  net/http.(*conn).serve()
      /home/travis/.gimme/versions/go1.8.3.linux.amd64/src/net/http/server.go:1825 +0x71a
Goroutine 12 (running) created at:
  net/http.(*Server).Serve()
      /home/travis/.gimme/versions/go1.8.3.linux.amd64/src/net/http/server.go:2668 +0x35f
  net/http/httptest.(*Server).goServe.func1()
      /home/travis/.gimme/versions/go1.8.3.linux.amd64/src/net/http/httptest/server.go:235 +0xa2
==================

Windows

==================
WARNING: DATA RACE
Write at 0x00c04213c138 by goroutine 8:
  net/http.(*response).Header()
      C:/Go/src/net/http/server.go:1032 +0x6a
  github.com/lox/httpcache.(*Handler).passUpstream()
      E:/go/work/src/github.com/lox/httpcache/handler.go:261 +0x4ed
  github.com/lox/httpcache.(*Handler).ServeHTTP()
      E:/go/work/src/github.com/lox/httpcache/handler.go:97 +0xc00
  net/http.serverHandler.ServeHTTP()
      C:/Go/src/net/http/server.go:2568 +0xc3
  net/http.(*conn).serve()
      C:/Go/src/net/http/server.go:1825 +0x721

Previous write at 0x00c04213c138 by goroutine 20:
  net/http.(*response).Header()
      C:/Go/src/net/http/server.go:1032 +0x6a
  github.com/lox/httpcache.(*responseStreamer).Header()
      <autogenerated>:97 +0x70
  net/http/httputil.(*ReverseProxy).ServeHTTP()
      C:/Go/src/net/http/httputil/reverseproxy.go:257 +0xca1
  github.com/lox/httpcache.(*Handler).passUpstream.func1()
      E:/go/work/src/github.com/lox/httpcache/handler.go:254 +0x92

Goroutine 8 (running) created at:
  net/http.(*Server).Serve()
      C:/Go/src/net/http/server.go:2668 +0x366
  net/http.(*Server).ListenAndServe()
      C:/Go/src/net/http/server.go:2585 +0xe7
  main.main()
      E:/go/work/src/github.com/hemerajs/momos/examples/server.go:61 +0x23d

Goroutine 20 (finished) created at:
  github.com/lox/httpcache.(*Handler).passUpstream()
      E:/go/work/src/github.com/lox/httpcache/handler.go:256 +0x371
  github.com/lox/httpcache.(*Handler).ServeHTTP()
      E:/go/work/src/github.com/lox/httpcache/handler.go:97 +0xc00
  net/http.serverHandler.ServeHTTP()
      C:/Go/src/net/http/server.go:2568 +0xc3
  net/http.(*conn).serve()
      C:/Go/src/net/http/server.go:1825 +0x721
@StarpTech
Copy link
Author

StarpTech commented Aug 20, 2017 •
edited
Loading

You don't need any code from me you can just run go test -v -race ./... to see race conditions in the httpcache package

go test -v -race ./...
=== RUN   TestSaveResource
--- PASS: TestSaveResource (0.00s)
=== RUN   TestSaveResourceWithIncorrectContentLength
--- PASS: TestSaveResourceWithIncorrectContentLength (0.00s)
=== RUN   TestParsingCacheControl
--- PASS: TestParsingCacheControl (0.00s)
=== RUN   TestKeysDiffer
--- PASS: TestKeysDiffer (0.00s)
=== RUN   TestRequestKey
--- PASS: TestRequestKey (0.00s)
=== RUN   TestVaryKey
--- PASS: TestVaryKey (0.00s)
=== RUN   TestRequestKeyWithContentLocation
--- PASS: TestRequestKeyWithContentLocation (0.00s)
=== RUN   TestRequestKeyWithIllegalContentLocation
--- PASS: TestRequestKeyWithIllegalContentLocation (0.00s)
=== RUN   TestSpecResponseCacheControl

>> GET / HTTP/1.1
>> Host: example.org

2017/08/20 19:50:38 GET http://example.org/ not in private cache
2017/08/20 19:50:38 passing request upstream
2017/08/20 19:50:38 upstream responded headers in 0s
2017/08/20 19:50:38 resource is uncacheable

<< HTTP/1.1 200 OK
<< Accept-Ranges: bytes
<< Content-Length: 6
<< Content-Type: text/plain; charset=utf-8
<< Date: Tue, 10 Nov 2009 23:00:00 GMT
<< X-Cache: SKIP

==================
WARNING: DATA RACE
Read at 0x00c04216c018 by goroutine 14:
  runtime.convT2E()
      C:/Go/src/runtime/iface.go:191 +0x0
  github.com/lox/httpcache/httplog.(*ResponseLogger).writeLog()
      E:/go/work/src/github.com/lox/httpcache/httplog/log.go:113 +0x534
  github.com/lox/httpcache/httplog.(*ResponseLogger).ServeHTTP()
      E:/go/work/src/github.com/lox/httpcache/httplog/log.go:87 +0x220
  github.com/lox/httpcache_test.(*client).do()
      E:/go/work/src/github.com/lox/httpcache/util_test.go:58 +0x1cc
  github.com/lox/httpcache_test.(*client).get()
      E:/go/work/src/github.com/lox/httpcache/util_test.go:85 +0xd1
  github.com/lox/httpcache_test.TestSpecResponseCacheControl()
      E:/go/work/src/github.com/lox/httpcache/spec_test.go:80 +0x22f
  testing.tRunner()
      C:/Go/src/testing/testing.go:657 +0x10e

Previous write at 0x00c04216c018 by goroutine 15:
  github.com/lox/httpcache/httplog.(*responseWriter).Write()
      E:/go/work/src/github.com/lox/httpcache/httplog/log.go:39 +0x11f
  github.com/lox/httpcache.(*responseStreamer).Write()
      E:/go/work/src/github.com/lox/httpcache/handler.go:558 +0xbe
  io.copyBuffer()
      C:/Go/src/io/io.go:392 +0x284
  io.Copy()
      C:/Go/src/io/io.go:360 +0x85
  io.CopyN()
      C:/Go/src/io/io.go:336 +0xcd
  net/http.serveContent()
      C:/Go/src/net/http/fs.go:268 +0x2f5
  net/http.ServeContent()
      C:/Go/src/net/http/fs.go:135 +0x119
  github.com/lox/httpcache_test.(*upstreamServer).ServeHTTP()
      E:/go/work/src/github.com/lox/httpcache/util_test.go:168 +0x6ab
  github.com/lox/httpcache.(*Handler).passUpstream.func1()
      E:/go/work/src/github.com/lox/httpcache/handler.go:254 +0x92

Goroutine 14 (running) created at:
  testing.(*T).Run()
      C:/Go/src/testing/testing.go:697 +0x54a
  testing.runTests.func1()
      C:/Go/src/testing/testing.go:882 +0xb1
  testing.tRunner()
      C:/Go/src/testing/testing.go:657 +0x10e
  testing.runTests()
      C:/Go/src/testing/testing.go:888 +0x4e7
  testing.(*M).Run()
      C:/Go/src/testing/testing.go:822 +0x1ca
  main.main()
      github.com/lox/httpcache/_test/_testmain.go:118 +0x216

Goroutine 15 (finished) created at:
  github.com/lox/httpcache.(*Handler).passUpstream()
      E:/go/work/src/github.com/lox/httpcache/handler.go:256 +0x371
  github.com/lox/httpcache.(*Handler).ServeHTTP()
      E:/go/work/src/github.com/lox/httpcache/handler.go:97 +0xc00
  github.com/lox/httpcache/httplog.(*ResponseLogger).ServeHTTP()
      E:/go/work/src/github.com/lox/httpcache/httplog/log.go:72 +0x1ba
  github.com/lox/httpcache_test.(*client).do()
      E:/go/work/src/github.com/lox/httpcache/util_test.go:58 +0x1cc
  github.com/lox/httpcache_test.(*client).get()
      E:/go/work/src/github.com/lox/httpcache/util_test.go:85 +0xd1
  github.com/lox/httpcache_test.TestSpecResponseCacheControl()
      E:/go/work/src/github.com/lox/httpcache/spec_test.go:80 +0x22f
  testing.tRunner()
      C:/Go/src/testing/testing.go:657 +0x10e
==================
2017/08/20 19:50:38 test.local "GET http://example.org/ HTTP/1.1" (OK) 6 SKIP 48.0071ms
==================
WARNING: DATA RACE
Read at 0x00c042030558 by goroutine 14:
  github.com/lox/httpcache_test.(*client).do()
      E:/go/work/src/github.com/lox/httpcache/util_test.go:79 +0x2bd
  github.com/lox/httpcache_test.(*client).get()
      E:/go/work/src/github.com/lox/httpcache/util_test.go:85 +0xd1
  github.com/lox/httpcache_test.TestSpecResponseCacheControl()
      E:/go/work/src/github.com/lox/httpcache/spec_test.go:80 +0x22f
  testing.tRunner()
      C:/Go/src/testing/testing.go:657 +0x10e

Previous write at 0x00c042030558 by goroutine 15:
  bytes.(*Buffer).grow()
      C:/Go/src/bytes/buffer.go:113 +0x369
  bytes.(*Buffer).Write()
      C:/Go/src/bytes/buffer.go:137 +0x67
  net/http/httptest.(*ResponseRecorder).Write()
      C:/Go/src/net/http/httptest/recorder.go:100 +0x107
  github.com/lox/httpcache/httplog.(*responseWriter).Write()
      E:/go/work/src/github.com/lox/httpcache/httplog/log.go:38 +0xcb
  github.com/lox/httpcache.(*responseStreamer).Write()
      E:/go/work/src/github.com/lox/httpcache/handler.go:558 +0xbe
  io.copyBuffer()
      C:/Go/src/io/io.go:392 +0x284
  io.Copy()
      C:/Go/src/io/io.go:360 +0x85
  io.CopyN()
      C:/Go/src/io/io.go:336 +0xcd
  net/http.serveContent()
      C:/Go/src/net/http/fs.go:268 +0x2f5
  net/http.ServeContent()
      C:/Go/src/net/http/fs.go:135 +0x119
  github.com/lox/httpcache_test.(*upstreamServer).ServeHTTP()
      E:/go/work/src/github.com/lox/httpcache/util_test.go:168 +0x6ab
  github.com/lox/httpcache.(*Handler).passUpstream.func1()
      E:/go/work/src/github.com/lox/httpcache/handler.go:254 +0x92

Goroutine 14 (running) created at:
  testing.(*T).Run()
      C:/Go/src/testing/testing.go:697 +0x54a
  testing.runTests.func1()
      C:/Go/src/testing/testing.go:882 +0xb1
  testing.tRunner()
      C:/Go/src/testing/testing.go:657 +0x10e
  testing.runTests()
      C:/Go/src/testing/testing.go:888 +0x4e7
  testing.(*M).Run()
      C:/Go/src/testing/testing.go:822 +0x1ca
  main.main()
      github.com/lox/httpcache/_test/_testmain.go:118 +0x216

Goroutine 15 (finished) created at:
  github.com/lox/httpcache.(*Handler).passUpstream()
      E:/go/work/src/github.com/lox/httpcache/handler.go:256 +0x371
  github.com/lox/httpcache.(*Handler).ServeHTTP()
      E:/go/work/src/github.com/lox/httpcache/handler.go:97 +0xc00
  github.com/lox/httpcache/httplog.(*ResponseLogger).ServeHTTP()
      E:/go/work/src/github.com/lox/httpcache/httplog/log.go:72 +0x1ba
  github.com/lox/httpcache_test.(*client).do()
      E:/go/work/src/github.com/lox/httpcache/util_test.go:58 +0x1cc
  github.com/lox/httpcache_test.(*client).get()
      E:/go/work/src/github.com/lox/httpcache/util_test.go:85 +0xd1
  github.com/lox/httpcache_test.TestSpecResponseCacheControl()
      E:/go/work/src/github.com/lox/httpcache/spec_test.go:80 +0x22f
  testing.tRunner()
      C:/Go/src/testing/testing.go:657 +0x10e
==================
==================
WARNING: DATA RACE
Read at 0x00c042030540 by goroutine 14:
  github.com/lox/httpcache_test.(*client).do()
      E:/go/work/src/github.com/lox/httpcache/util_test.go:79 +0x2d7
  github.com/lox/httpcache_test.(*client).get()
      E:/go/work/src/github.com/lox/httpcache/util_test.go:85 +0xd1
  github.com/lox/httpcache_test.TestSpecResponseCacheControl()
      E:/go/work/src/github.com/lox/httpcache/spec_test.go:80 +0x22f
  testing.tRunner()
      C:/Go/src/testing/testing.go:657 +0x10e

Previous write at 0x00c042030540 by goroutine 15:
  bytes.(*Buffer).grow()
      C:/Go/src/bytes/buffer.go:112 +0x32c
  bytes.(*Buffer).Write()
      C:/Go/src/bytes/buffer.go:137 +0x67
  net/http/httptest.(*ResponseRecorder).Write()
      C:/Go/src/net/http/httptest/recorder.go:100 +0x107
  github.com/lox/httpcache/httplog.(*responseWriter).Write()
      E:/go/work/src/github.com/lox/httpcache/httplog/log.go:38 +0xcb
  github.com/lox/httpcache.(*responseStreamer).Write()
      E:/go/work/src/github.com/lox/httpcache/handler.go:558 +0xbe
  io.copyBuffer()
      C:/Go/src/io/io.go:392 +0x284
  io.Copy()
      C:/Go/src/io/io.go:360 +0x85
  io.CopyN()
      C:/Go/src/io/io.go:336 +0xcd
  net/http.serveContent()
      C:/Go/src/net/http/fs.go:268 +0x2f5
  net/http.ServeContent()
      C:/Go/src/net/http/fs.go:135 +0x119
  github.com/lox/httpcache_test.(*upstreamServer).ServeHTTP()
      E:/go/work/src/github.com/lox/httpcache/util_test.go:168 +0x6ab
  github.com/lox/httpcache.(*Handler).passUpstream.func1()
      E:/go/work/src/github.com/lox/httpcache/handler.go:254 +0x92

Goroutine 14 (running) created at:
  testing.(*T).Run()
      C:/Go/src/testing/testing.go:697 +0x54a
  testing.runTests.func1()
      C:/Go/src/testing/testing.go:882 +0xb1
  testing.tRunner()
      C:/Go/src/testing/testing.go:657 +0x10e
  testing.runTests()
      C:/Go/src/testing/testing.go:888 +0x4e7
  testing.(*M).Run()
      C:/Go/src/testing/testing.go:822 +0x1ca
  main.main()
      github.com/lox/httpcache/_test/_testmain.go:118 +0x216

Goroutine 15 (finished) created at:
  github.com/lox/httpcache.(*Handler).passUpstream()
      E:/go/work/src/github.com/lox/httpcache/handler.go:256 +0x371
  github.com/lox/httpcache.(*Handler).ServeHTTP()
      E:/go/work/src/github.com/lox/httpcache/handler.go:97 +0xc00
  github.com/lox/httpcache/httplog.(*ResponseLogger).ServeHTTP()
      E:/go/work/src/github.com/lox/httpcache/httplog/log.go:72 +0x1ba
  github.com/lox/httpcache_test.(*client).do()
      E:/go/work/src/github.com/lox/httpcache/util_test.go:58 +0x1cc
  github.com/lox/httpcache_test.(*client).get()
      E:/go/work/src/github.com/lox/httpcache/util_test.go:85 +0xd1
  github.com/lox/httpcache_test.TestSpecResponseCacheControl()
      E:/go/work/src/github.com/lox/httpcache/spec_test.go:80 +0x22f
  testing.tRunner()
      C:/Go/src/testing/testing.go:657 +0x10e
==================

@StarpTech
Copy link
Author

StarpTech commented Aug 20, 2017 •
edited
Loading

It seems that the issue sit here https://github.com/lox/httpcache/blob/master/handler.go#L218

@StarpTech
Copy link
Author

Easy reproducible with go test -v -race -run "^TestSpecResponseCacheControlWithAuthorizationHeaders|TestSpecMultipleCacheControlHeaders$"

@StarpTech StarpTech mentioned this issue Aug 27, 2017
Open
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@StarpTech