httpcache
httpcache copied to clipboard
lox
Possible Race condition
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
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
==================
It seems that the issue sit here https://github.com/lox/httpcache/blob/master/handler.go#L218
Easy reproducible with go test -v -race -run "^TestSpecResponseCacheControlWithAuthorizationHeaders|TestSpecMultipleCacheControlHeaders$"