search

lox / httpcache

An RFC7234 compliant golang http.Handler for caching HTTP responses
MIT License
264 stars 28 forks source link

Possible Race condition #39

Open StarpTech opened 7 years ago

StarpTech commented 7 years ago

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 commented 7 years ago

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 commented 7 years ago

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

StarpTech commented 7 years ago

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