Timeout middleware write race #2126

aldas · 2022-03-13T14:03:27Z

Timeout middleware occasionally fails with data race in Github CI flow. I have taken code from v5 branch which has a little bit reworked logic so we are not using t.ctx.Error(err) anymore

==================
WARNING: DATA RACE
Read at 0x00c0001e8ca8 by goroutine 70:
  bytes.(*Buffer).String()
      /Users/runner/hostedtoolcache/go/1.15.15/x64/src/bytes/buffer.go:65 +0x3ca
  github.com/labstack/echo/v4/middleware.TestTimeoutWithFullEchoStack.func2()
      /Users/runner/work/echo/echo/middleware/timeout_test.go:408 +0x3b9
  testing.tRunner()
      /Users/runner/hostedtoolcache/go/1.15.15/x64/src/testing/testing.go:1123 +0x202

Previous write at 0x00c0001e8ca8 by goroutine 76:
  bytes.(*Buffer).grow()
      /Users/runner/hostedtoolcache/go/1.15.15/x64/src/bytes/buffer.go:147 +0x2d7
  bytes.(*Buffer).Write()
      /Users/runner/hostedtoolcache/go/1.15.15/x64/src/bytes/buffer.go:172 +0x184
  github.com/labstack/echo/v4/middleware.LoggerWithConfig.func2.1()
      /Users/runner/work/echo/echo/middleware/logger.go:216 +0x724
  github.com/labstack/echo/v4/middleware.echoHandlerFuncWrapper.ServeHTTP()
      /Users/runner/work/echo/echo/middleware/timeout.go:156 +0x22c
  github.com/labstack/echo/v4/middleware.(*echoHandlerFuncWrapper).ServeHTTP()
      <autogenerated>:1 +0xcc
  net/http.(*timeoutHandler).ServeHTTP.func1()
      /Users/runner/hostedtoolcache/go/1.15.15/x64/src/net/http/server.go:[32](https://github.com/labstack/echo/runs/5527738819?check_suite_focus=true#step:7:32)72 +0xb5

Goroutine 70 (running) created at:
  testing.(*T).Run()
      /Users/runner/hostedtoolcache/go/1.15.15/x64/src/testing/testing.go:1168 +0x5bb
  github.com/labstack/echo/v4/middleware.TestTimeoutWithFullEchoStack()
      /Users/runner/work/echo/echo/middleware/timeout_test.go:392 +0xa3b
  testing.tRunner()
      /Users/runner/hostedtoolcache/go/1.15.15/x64/src/testing/testing.go:1123 +0x202

Goroutine 76 (finished) created at:
  net/http.(*timeoutHandler).ServeHTTP()
      /Users/runner/hostedtoolcache/go/1.15.15/x64/src/net/http/server.go:3266 +0x38f
  github.com/labstack/echo/v4/middleware.TimeoutWithConfig.func1.1()
      /Users/runner/work/echo/echo/middleware/timeout.go:118 +0x449
  github.com/labstack/echo/v4.(*Echo).ServeHTTP()
      /Users/runner/work/echo/echo/echo.go:630 +0x1fd
  net/http.serverHandler.ServeHTTP()
      /Users/runner/hostedtoolcache/go/1.15.15/x64/src/net/http/server.go:2843 +0xca
  net/http.(*conn).serve()
      /Users/runner/hostedtoolcache/go/1.15.15/x64/src/net/http/server.go:1925 +0x84c
==================
==================
WARNING: DATA RACE
Read at 0x00c0001e8c90 by goroutine 70:
  bytes.(*Buffer).String()
      /Users/runner/hostedtoolcache/go/1.15.15/x64/src/bytes/buffer.go:65 +0x3e4
  github.com/labstack/echo/v4/middleware.TestTimeoutWithFullEchoStack.func2()
      /Users/runner/work/echo/echo/middleware/timeout_test.go:408 +0x3b9
  testing.tRunner()
      /Users/runner/hostedtoolcache/go/1.15.15/x64/src/testing/testing.go:1123 +0x202

Previous write at 0x00c0001e8c90 by goroutine 76:
  bytes.(*Buffer).grow()
      /Users/runner/hostedtoolcache/go/1.15.15/x64/src/bytes/buffer.go:144 +0x297
  bytes.(*Buffer).Write()
      /Users/runner/hostedtoolcache/go/1.15.15/x64/src/bytes/buffer.go:172 +0x184
  github.com/labstack/echo/v4/middleware.LoggerWithConfig.func2.1()
      /Users/runner/work/echo/echo/middleware/logger.go:216 +0x724
  github.com/labstack/echo/v4/middleware.echoHandlerFuncWrapper.ServeHTTP()
      /Users/runner/work/echo/echo/middleware/timeout.go:156 +0x22c
  github.com/labstack/echo/v4/middleware.(*echoHandlerFuncWrapper).ServeHTTP()
      <autogenerated>:1 +0xcc
  net/http.(*timeoutHandler).ServeHTTP.func1()
      /Users/runner/hostedtoolcache/go/1.15.15/x64/src/net/http/server.go:3272 +0xb5

Goroutine 70 (running) created at:
  testing.(*T).Run()
      /Users/runner/hostedtoolcache/go/1.15.15/x64/src/testing/testing.go:1168 +0x5bb
  github.com/labstack/echo/v4/middleware.TestTimeoutWithFullEchoStack()
      /Users/runner/work/echo/echo/middleware/timeout_test.go:392 +0xa3b
  testing.tRunner()
      /Users/runner/hostedtoolcache/go/1.15.15/x64/src/testing/testing.go:1123 +0x202

Goroutine 76 (finished) created at:
  net/http.(*timeoutHandler).ServeHTTP()
      /Users/runner/hostedtoolcache/go/1.15.15/x64/src/net/http/server.go:3266 +0x38f
  github.com/labstack/echo/v4/middleware.TimeoutWithConfig.func1.1()
      /Users/runner/work/echo/echo/middleware/timeout.go:118 +0x449
  github.com/labstack/echo/v4.(*Echo).ServeHTTP()
      /Users/runner/work/echo/echo/echo.go:630 +0x1fd
  net/http.serverHandler.ServeHTTP()
      /Users/runner/hostedtoolcache/go/1.15.15/x64/src/net/http/server.go:2843 +0xca
  net/http.(*conn).serve()
      /Users/runner/hostedtoolcache/go/1.15.15/x64/src/net/http/server.go:1925 +0x84c
==================
==================
WARNING: DATA RACE
Read at 0x00c000188000 by goroutine 70:
  runtime.slicebytetostring()
      /Users/runner/hostedtoolcache/go/1.15.15/x64/src/runtime/string.go:80 +0x0
  bytes.(*Buffer).String()
      /Users/runner/hostedtoolcache/go/1.15.15/x64/src/bytes/buffer.go:65 +0x437
  github.com/labstack/echo/v4/middleware.TestTimeoutWithFullEchoStack.func2()
      /Users/runner/work/echo/echo/middleware/timeout_test.go:408 +0x3b9
  testing.tRunner()
      /Users/runner/hostedtoolcache/go/1.15.15/x64/src/testing/testing.go:1123 +0x202

Previous write at 0x00c000188000 by goroutine 76:
  runtime.slicecopy()
      /Users/runner/hostedtoolcache/go/1.15.15/x64/src/runtime/slice.go:246 +0x0
  bytes.(*Buffer).Write()
      /Users/runner/hostedtoolcache/go/1.15.15/x64/src/bytes/buffer.go:174 +0x147
  github.com/labstack/echo/v4/middleware.LoggerWithConfig.func2.1()
      /Users/runner/work/echo/echo/middleware/logger.go:216 +0x724
  github.com/labstack/echo/v4/middleware.echoHandlerFuncWrapper.ServeHTTP()
      /Users/runner/work/echo/echo/middleware/timeout.go:156 +0x22c
  github.com/labstack/echo/v4/middleware.(*echoHandlerFuncWrapper).ServeHTTP()
      <autogenerated>:1 +0xcc
  net/http.(*timeoutHandler).ServeHTTP.func1()
      /Users/runner/hostedtoolcache/go/1.15.15/x64/src/net/http/server.go:3272 +0xb5

Goroutine 70 (running) created at:
  testing.(*T).Run()
      /Users/runner/hostedtoolcache/go/1.15.15/x64/src/testing/testing.go:1168 +0x5bb
  github.com/labstack/echo/v4/middleware.TestTimeoutWithFullEchoStack()
      /Users/runner/work/echo/echo/middleware/timeout_test.go:392 +0xa3b
  testing.tRunner()
      /Users/runner/hostedtoolcache/go/1.15.15/x64/src/testing/testing.go:1123 +0x202

Goroutine 76 (finished) created at:
  net/http.(*timeoutHandler).ServeHTTP()
      /Users/runner/hostedtoolcache/go/1.15.15/x64/src/net/http/server.go:3266 +0x38f
  github.com/labstack/echo/v4/middleware.TimeoutWithConfig.func1.1()
      /Users/runner/work/echo/echo/middleware/timeout.go:118 +0x449
  github.com/labstack/echo/v4.(*Echo).ServeHTTP()
      /Users/runner/work/echo/echo/echo.go:630 +0x1fd
  net/http.serverHandler.ServeHTTP()
      /Users/runner/hostedtoolcache/go/1.15.15/x64/src/net/http/server.go:2843 +0xca
  net/http.(*conn).serve()
      /Users/runner/hostedtoolcache/go/1.15.15/x64/src/net/http/server.go:1925 +0x84c
==================
--- FAIL: TestTimeoutWithFullEchoStack (0.12s)
    --- FAIL: TestTimeoutWithFullEchoStack/503_-_handler_timeouts,_write_response_in_timeout_middleware (0.10s)
        timeout_test.go:413: 
            	Error Trace:	timeout_test.go:413
            	Error:      	Should be false
            	Test:       	TestTimeoutWithFullEchoStack/503_-_handler_timeouts,_write_response_in_timeout_middleware
Error:         testing.go:1038: race detected during execution of test
Error:     testing.go:1038: race detected during execution of test
{"time":"2022-03-13T13:06:20.137835Z","level":"-","prefix":"echo","file":"recover.go","line":"109","message":"[PANIC RECOVER] panic!!! goroutine 494 [running]:\ngithub.com/labstack/echo/v4/middleware.RecoverWithConfig.func1.1.1(0x19e6070, 0x1000, 0x0, 0x0, 0x1ab46c0, 0xc0001d6820)\n\t/Users/runner/work/echo/echo/middleware/recover.go:89 +0xa0f\npanic(0x18f3f00, 0x1a8ff90)\n\t/Users/runner/hostedtoolcache/go/1.15.15/x64/src/runtime/panic.go:975 +0x47a\nnet/http.(*timeoutHandler).ServeHTTP(0xc0000f3e40, 0x1aa7f80, 0xc0000f3dc0, 0xc0003ff900)\n\t/Users/runner/hostedtoolcache/go/1.15.15/x64/src/net/http/server.go:3277 +0xe8b\ngithub.com/labstack/echo/v4/middleware.TimeoutWithConfig.func1.1(0x1ab46c0, 0xc0001d6820, 0xc00000000c, 0xc00018de00)\n\t/Users/runner/work/echo/echo/middleware/timeout.go:118 +0x44a\ngithub.com/labstack/echo/v4/middleware.RecoverWithConfig.func1.1(0x1ab46c0, 0xc0001d6820, 0x0, 0x0)\n\t/Users/runner/work/echo/echo/middleware/recover.go:115 +0x1ab\ngithub.com/labstack/echo/v4.(*Echo).ServeHTTP(0xc0006c2480, 0x1aa7f80, 0xc0000f3dc0, 0xc0003ff900)\n\t/Users/runner/work/echo/echo/echo.go:630 +0x1fe\ngithub.com/labstack/echo/v4/middleware.TestTimeoutRecoversPanic.func2()\n\t/Users/runner/work/echo/echo/middleware/timeout_test.go:190 +0x65\ngithub.com/stretchr/testify/assert.didPanic.func1(0xc00005bd08, 0xc00005bcd6, 0xc00005bcf8, 0xc000666ee0)\n\t/Users/runner/work/echo/pkg/mod/github.com/stretchr/testify@v1.7.0/assert/assertions.go:1018 +0x8c\ngithub.com/stretchr/testify/assert.didPanic(0xc000666ee0, 0x1a9e5a0, 0xc0002ec300, 0x2fd9ad8, 0xc0002ec300, 0xc00005bd01)\n\t/Users/runner/work/echo/pkg/mod/github.com/stretchr/testify@v1.7.0/assert/assertions.go:1020 +0x6d\ngithub.com/stretchr/testify/assert.NotPanics(0x1a9e5a0, 0xc0002ec300, 0xc000666ee0, 0x0, 0x0, 0x0, 0xc0003ff900)\n\t/Users/runner/work/echo/pkg/mod/github.com/stretchr/testify@v1.7.0/assert/assertions.go:1091 +0x85\ngithub.com/labstack/echo/v4/middleware.TestTimeoutRecoversPanic(0xc0002ec300)\n\t/Users/runner/work/echo/echo/middleware/timeout_test.go:189 +0x57b\ntesting.tRunner(0xc0002ec300, 0x19e68d0)\n\t/Users/runner/hostedtoolcache/go/1.15.15/x64/src/testing/testing.go:1123 +0x203\ncreated by testing.(*T).Run\n\t/Users/runner/hostedtoolcache/go/1.15.15/x64/src/testing/testing.go:1168 +0x5bc\n\ngoroutine 1 [chan receive]:\ntesting.tRunner.func1(0xc000082900)\n\t/Users/runner/hostedtoolcache/go/1.15.15/x64/src/testing/testing.go:1088 +0x[33](https://github.com/labstack/echo/runs/5527738819?check_suite_focus=true#step:7:33)3\ntesting.tRunner(0xc000082900, 0xc0001b1c78)\n\t/Users/runner/hostedtoolcache/go/1.15.15/x64/src/testing/testing.go:1127 +0x22b\ntesting.runTests(0xc0000b0b40, 0x1e32f60, 0x7d, 0x7d, 0xc0839988da1e9988, 0x8bb30c1c78, 0x1e378e0, 0xc0001c8190)\n\t/Users/runner/hostedtoolcache/go/1.15.15/x64/src/testing/testing.go:1437 +0x613\ntesting.(*M).Run(0xc00018c180, 0x0)\n\t/Users/runner/hostedtoolcache/go/1.15.15/x64/src/testing/testing.go:1[34](https://github.com/labstack/echo/runs/5527738819?check_suite_focus=true#step:7:34)5 +0x3b4\nmain.main()\n\t_testmain.go:407 +0x[35](https://github.com/labstack/echo/runs/5527738819?check_suite_focus=true#step:7:35)7\n\ngoroutine 215 [select]:\nnet/http.(*persistConn).writeLoop(0xc00013fe60)\n\t/Users/runner/hostedtoolcache/go/1.15.15/x64/src/net/http/transport.go:2346 +0x1d4\ncreated by net/http.(*Transport).dialConn\n\t/Users/runner/hostedtoolcache/go/1.15.15/x64/src/net/http/transport.go:1716 +0xc31\n\ngoroutine 214 [select]:\nnet/http.(*persistConn).readLoop(0xc00013fe60)\n\t/Users/runner/hostedtoolcache/go/1.15.15/x64/src/net/http/transport.go:2167 +0xf3b\ncreated by net/http.(*Transport).dialConn\n\t/Users/runner/hostedtoolcache/go/1.15.15/x64/src/net/http/transport.go:1715 +0xc0c\n\ngoroutine 495 [chan send]:\ntesting.tRunner.func1(0xc0002ec480)\n\t/Users/runner/hostedtoolcache/go/1.15.15/x64/src/testing/testing.go:1113 +0x505\ntesting.tRunner(0xc0002ec480, 0x19e68a8)\n\t/Users/runner/hostedtoolcache/go/1.15.15/x64/src/testing/testing.go:1127 +0x22b\ncreated by testing.(*T).Run\n\t/Users/runner/hostedtoolcache/go/1.15.15/x64/src/testing/testing.go:1168 +0x5bc\n\ngoroutine 496 [select]:\nnet/http.(*timeoutHandler).ServeHTTP(0xc0000f3d80, 0x1aa7f80, 0xc0000f3d00, 0xc0003ff700)\n\t/Users/runner/hostedtoolcache/go/1.15.15/x64/src/net/http/server.go:3275 +0x4bf\ngithub.com/labstack/echo/v4/middleware.TimeoutWithConfig.func1.1(0x1ab46c0, 0xc0001d66e0, 0xc000034f60, 0x1e68[39](https://github.com/labstack/echo/runs/5527738819?check_suite_focus=true#step:7:39)0)\n\t/Users/runner/work/echo/echo/middleware/timeout.go:118 +0x[44](https://github.com/labstack/echo/runs/5527738819?check_suite_focus=true#step:7:44)a\ngithub.com/labstack/echo/v4/\n"}
FAIL
coverage: [92](https://github.com/labstack/echo/runs/5527738819?check_suite_focus=true#step:7:92).1% of statements
FAIL	github.com/labstack/echo/v4/middleware	1.002s

codecov · 2022-03-13T14:04:22Z

Codecov Report

Merging #2126 (5436ee9) into master (3f5b733) will decrease coverage by 0.01%.
The diff coverage is 91.66%.

@@            Coverage Diff             @@
##           master    #2126      +/-   ##
==========================================
- Coverage   92.10%   92.09%   -0.02%     
==========================================
  Files          37       37              
  Lines        3028     3047      +19     
==========================================
+ Hits         2789     2806      +17     
- Misses        150      151       +1     
- Partials       89       90       +1

Impacted Files	Coverage Δ
middleware/timeout.go	`96.42% <91.66%> (-3.58%)`	⬇️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 3f5b733...5436ee9. Read the comment docs.

lammel

Looks good. Comments improved as well, better to read now.
Haven't run into the race though yet.

Timeout middleware write race

5436ee9

aldas requested a review from lammel March 13, 2022 18:40

lammel approved these changes Mar 16, 2022

View reviewed changes

aldas merged commit 1919cf4 into labstack:master Mar 16, 2022

aldas deleted the timeout_mw_races branch July 12, 2022 19:04

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Timeout middleware write race #2126

Timeout middleware write race #2126

aldas commented Mar 13, 2022 •

edited

Loading

codecov bot commented Mar 13, 2022

lammel left a comment

Timeout middleware write race #2126

Timeout middleware write race #2126

Conversation

aldas commented Mar 13, 2022 • edited Loading

codecov bot commented Mar 13, 2022

Codecov Report

lammel left a comment

Choose a reason for hiding this comment

aldas commented Mar 13, 2022 •

edited

Loading