Skip to content

Timeout middleware write race#2126

Merged
aldas merged 1 commit intolabstack:masterfrom
aldas:timeout_mw_races
Mar 16, 2022
Merged

Timeout middleware write race#2126
aldas merged 1 commit intolabstack:masterfrom
aldas:timeout_mw_races

Conversation

@aldas
Copy link
Contributor

@aldas aldas commented Mar 13, 2022 •
edited
Loading

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
Copy link

codecov bot commented Mar 13, 2022

Codecov Report

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

Impacted file tree graph

@@            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.

@aldas aldas requested a review from lammel March 13, 2022 18:40
lammel
lammel approved these changes Mar 16, 2022
View reviewed changes
Copy link
Contributor

@lammel lammel left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

@aldas aldas merged commit 1919cf4 into labstack:master Mar 16, 2022
@aldas aldas deleted the timeout_mw_races branch July 12, 2022 19:04
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@lammel lammel lammel approved these changes

Assignees

No one assigned

Labels

None yet

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

2 participants

@aldas @lammel