Fix race condition when stopping before spinner fully built #3

dnmurray · 2018-06-09T14:06:32Z

We're running into a race condition that is fairly repeatable:

panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x1072502]

goroutine 1 [running]:
time.(*Ticker).Stop(0x0)
    /usr/local/go/src/time/tick.go:46 +0x22
github.com/phase2/rig/vendor/github.com/slok/gospinner.(*Spinner).Stop(0xc4200a83c0, 0x0, 0x0)
    /go/src/github.com/phase2/rig/vendor/github.com/slok/gospinner/spinner.go:197 +0xe6
github.com/phase2/rig/vendor/github.com/slok/gospinner.(*Spinner).FinishWithMessage(0xc4200a83c0, 0xc420089b60, 0xc, 0xc420086c60, 0x23, 0x3, 0xc4201336e0)
    /go/src/github.com/phase2/rig/vendor/github.com/slok/gospinner/spinner.go:240 +0x40
github.com/phase2/rig/vendor/github.com/slok/gospinner.(*Spinner).FinishWithSymbol(0xc4200a83c0, 0xc420089b60, 0xc, 0x0, 0x0)
    /go/src/github.com/phase2/rig/vendor/github.com/slok/gospinner/spinner.go:235 +0x51
github.com/phase2/rig/vendor/github.com/slok/gospinner.(*Spinner).Warn(0xc4200a83c0, 0xc420086c60, 0x23)
    /go/src/github.com/phase2/rig/vendor/github.com/slok/gospinner/spinner.go:220 +0x8a

I think moving the creation of the timer out of the goroutine will solve the problem.

phase2/rig#160

dnmurray · 2018-06-10T02:21:43Z

I'm not seeing what the failure is. master also fails (on my local env):

gospinner$ git checkout master
Switched to branch 'master'
Your branch is up to date with 'origin/master'.
gospinner$ go test -v ./
=== RUN   TestIntegrationStartNoColor
--- PASS: TestIntegrationStartNoColor (1.78s)
=== RUN   TestIntegrationStartDefault
--- FAIL: TestIntegrationStartDefault (1.78s)
	spinner_i_test.go:62: {kind:0 startMessage:This is a test color:96 want:|◐ This is a test|◓ This is a test|◑ This is a test|◒ This is a test}
		 - Wrong result, got: |◐ This is a test|◓ This is a test|◑ This is a test|◒ This is a test, want: |◐ This is a test|◓ This is a test|◑ This is a test|◒ This is a test
	spinner_i_test.go:62: {kind:5 startMessage:This is another test color:35 want:|⠋ This is another test|⠙ This is another test|⠹ This is another test|⠸ This is another test|⠼ This is another test|⠴ This is another test|⠦ This is another test|⠧ This is another test|⠇ This is another test|⠏ This is another test}
		 - Wrong result, got: |⠋ This is another test|⠙ This is another test|⠹ This is another test|⠸ This is another test|⠼ This is another test|⠴ This is another test|⠦ This is another test|⠧ This is another test|⠇ This is another test|⠏ This is another test, want: |⠋ This is another test|⠙ This is another test|⠹ This is another test|⠸ This is another test|⠼ This is another test|⠴ This is another test|⠦ This is another test|⠧ This is another test|⠇ This is another test|⠏ This is another test
	spinner_i_test.go:62: {kind:13 startMessage:Это тест color:92 want:|[    ] Это тест|[   =] Это тест|[  ==] Это тест|[ ===] Это тест|[====] Это тест|[=== ] Это тест|[==  ] Это тест|[=   ] Это тест}
		 - Wrong result, got: |[    ] Это тест|[   =] Это тест|[  ==] Это тест|[ ===] Это тест|[====] Это тест|[=== ] Это тест|[==  ] Это тест|[=   ] Это тест, want: |[    ] Это тест|[   =] Это тест|[  ==] Это тест|[ ===] Это тест|[====] Это тест|[=== ] Это тест|[==  ] Это тест|[=   ] Это тест
=== RUN   TestIntegrationStartColor
--- FAIL: TestIntegrationStartColor (1.78s)
	spinner_i_test.go:92: {kind:0 startMessage:This is a test color:96 want:|◐ This is a test|◓ This is a test|◑ This is a test|◒ This is a test}
		 - Wrong result, got: |◐ This is a test|◓ This is a test|◑ This is a test|◒ This is a test, want: |◐ This is a test|◓ This is a test|◑ This is a test|◒ This is a test
	spinner_i_test.go:92: {kind:5 startMessage:This is another test color:35 want:|⠋ This is another test|⠙ This is another test|⠹ This is another test|⠸ This is another test|⠼ This is another test|⠴ This is another test|⠦ This is another test|⠧ This is another test|⠇ This is another test|⠏ This is another test}
		 - Wrong result, got: |⠋ This is another test|⠙ This is another test|⠹ This is another test|⠸ This is another test|⠼ This is another test|⠴ This is another test|⠦ This is another test|⠧ This is another test|⠇ This is another test|⠏ This is another test, want: |⠋ This is another test|⠙ This is another test|⠹ This is another test|⠸ This is another test|⠼ This is another test|⠴ This is another test|⠦ This is another test|⠧ This is another test|⠇ This is another test|⠏ This is another test
	spinner_i_test.go:92: {kind:13 startMessage:Это тест color:92 want:|[    ] Это тест|[   =] Это тест|[  ==] Это тест|[ ===] Это тест|[====] Это тест|[=== ] Это тест|[==  ] Это тест|[=   ] Это тест}
		 - Wrong result, got: |[    ] Это тест|[   =] Это тест|[  ==] Это тест|[ ===] Это тест|[====] Это тест|[=== ] Это тест|[==  ] Это тест|[=   ] Это тест, want: |[    ] Это тест|[   =] Это тест|[  ==] Это тест|[ ===] Это тест|[====] Это тест|[=== ] Это тест|[==  ] Это тест|[=   ] Это тест
=== RUN   TestIntegrationStartWithSpeed
--- PASS: TestIntegrationStartWithSpeed (0.46s)
=== RUN   TestCorrectCreation
--- PASS: TestCorrectCreation (0.00s)
=== RUN   TestStartMultipleTimes
--- PASS: TestStartMultipleTimes (0.00s)
=== RUN   TestCreateFrames
--- PASS: TestCreateFrames (0.00s)
=== RUN   TestRender
--- PASS: TestRender (0.00s)
=== RUN   TestRenderError
--- PASS: TestRenderError (0.00s)
=== RUN   TestRenderColor
--- FAIL: TestRenderColor (0.00s)
	spinner_test.go:130: {kind:0 startMessage:This is a test color:96 WantFrames:[◐ This is a test ◓ This is a test ◑ This is a test ◒ This is a test]}
◐ This is a test, want: ◐ This is a testot:
	spinner_test.go:130: {kind:0 startMessage:This is a test color:96 WantFrames:[◐ This is a test ◓ This is a test ◑ This is a test ◒ This is a test]}
◓ This is a test, want: ◓ This is a test got:
	spinner_test.go:130: {kind:0 startMessage:This is a test color:96 WantFrames:[◐ This is a test ◓ This is a test ◑ This is a test ◒ This is a test]}
◑ This is a test, want: ◑ This is a testot:
	spinner_test.go:130: {kind:0 startMessage:This is a test color:96 WantFrames:[◐ This is a test ◓ This is a test ◑ This is a test ◒ This is a test]}
◒ This is a test, want: ◒ This is a test got:
	spinner_test.go:130: {kind:5 startMessage:This is another test color:35 WantFrames:[⠋ This is another test ⠙ This is another test ⠹ This is another test ⠸ This is another test ⠼ This is another test ⠴ This is another test ⠦ This is another test ⠧ This is another test ⠇ This is another test ⠏ This is another test]}
⠋ This is another test, want: ⠋ This is another test
	spinner_test.go:130: {kind:5 startMessage:This is another test color:35 WantFrames:[⠋ This is another test ⠙ This is another test ⠹ This is another test ⠸ This is another test ⠼ This is another test ⠴ This is another test ⠦ This is another test ⠧ This is another test ⠇ This is another test ⠏ This is another test]}
⠙ This is another test, want: ⠙ This is another test
	spinner_test.go:130: {kind:5 startMessage:This is another test color:35 WantFrames:[⠋ This is another test ⠙ This is another test ⠹ This is another test ⠸ This is another test ⠼ This is another test ⠴ This is another test ⠦ This is another test ⠧ This is another test ⠇ This is another test ⠏ This is another test]}
⠹ This is another test, want: ⠹ This is another test
	spinner_test.go:130: {kind:5 startMessage:This is another test color:35 WantFrames:[⠋ This is another test ⠙ This is another test ⠹ This is another test ⠸ This is another test ⠼ This is another test ⠴ This is another test ⠦ This is another test ⠧ This is another test ⠇ This is another test ⠏ This is another test]}
⠸ This is another test, want: ⠸ This is another test
	spinner_test.go:130: {kind:5 startMessage:This is another test color:35 WantFrames:[⠋ This is another test ⠙ This is another test ⠹ This is another test ⠸ This is another test ⠼ This is another test ⠴ This is another test ⠦ This is another test ⠧ This is another test ⠇ This is another test ⠏ This is another test]}
⠼ This is another test, want: ⠼ This is another test
	spinner_test.go:130: {kind:5 startMessage:This is another test color:35 WantFrames:[⠋ This is another test ⠙ This is another test ⠹ This is another test ⠸ This is another test ⠼ This is another test ⠴ This is another test ⠦ This is another test ⠧ This is another test ⠇ This is another test ⠏ This is another test]}
⠴ This is another test, want: ⠴ This is another test
	spinner_test.go:130: {kind:5 startMessage:This is another test color:35 WantFrames:[⠋ This is another test ⠙ This is another test ⠹ This is another test ⠸ This is another test ⠼ This is another test ⠴ This is another test ⠦ This is another test ⠧ This is another test ⠇ This is another test ⠏ This is another test]}
⠦ This is another test, want: ⠦ This is another test
	spinner_test.go:130: {kind:5 startMessage:This is another test color:35 WantFrames:[⠋ This is another test ⠙ This is another test ⠹ This is another test ⠸ This is another test ⠼ This is another test ⠴ This is another test ⠦ This is another test ⠧ This is another test ⠇ This is another test ⠏ This is another test]}
⠧ This is another test, want: ⠧ This is another test
	spinner_test.go:130: {kind:5 startMessage:This is another test color:35 WantFrames:[⠋ This is another test ⠙ This is another test ⠹ This is another test ⠸ This is another test ⠼ This is another test ⠴ This is another test ⠦ This is another test ⠧ This is another test ⠇ This is another test ⠏ This is another test]}
⠇ This is another test, want: ⠇ This is another test
	spinner_test.go:130: {kind:5 startMessage:This is another test color:35 WantFrames:[⠋ This is another test ⠙ This is another test ⠹ This is another test ⠸ This is another test ⠼ This is another test ⠴ This is another test ⠦ This is another test ⠧ This is another test ⠇ This is another test ⠏ This is another test]}
⠏ This is another test, want: ⠏ This is another test
	spinner_test.go:130: {kind:13 startMessage:Это тест color:92 WantFrames:[[    ] Это тест [   =] Это тест [  ==] Это тест [ ===] Это тест [====] Это тест [=== ] Это тест [==  ] Это тест [=   ] Это тест]}
[    ] Это тест, want: [    ] Это тест
	spinner_test.go:130: {kind:13 startMessage:Это тест color:92 WantFrames:[[    ] Это тест [   =] Это тест [  ==] Это тест [ ===] Это тест [====] Это тест [=== ] Это тест [==  ] Это тест [=   ] Это тест]}
[   =] Это тест, want: [   =] Это тест
	spinner_test.go:130: {kind:13 startMessage:Это тест color:92 WantFrames:[[    ] Это тест [   =] Это тест [  ==] Это тест [ ===] Это тест [====] Это тест [=== ] Это тест [==  ] Это тест [=   ] Это тест]}
[  ==] Это тест, want: [  ==] Это тест
	spinner_test.go:130: {kind:13 startMessage:Это тест color:92 WantFrames:[[    ] Это тест [   =] Это тест [  ==] Это тест [ ===] Это тест [====] Это тест [=== ] Это тест [==  ] Это тест [=   ] Это тест]}
[ ===] Это тест, want: [ ===] Это тест
	spinner_test.go:130: {kind:13 startMessage:Это тест color:92 WantFrames:[[    ] Это тест [   =] Это тест [  ==] Это тест [ ===] Это тест [====] Это тест [=== ] Это тест [==  ] Это тест [=   ] Это тест]}
[====] Это тест, want: [====] Это тест
	spinner_test.go:130: {kind:13 startMessage:Это тест color:92 WantFrames:[[    ] Это тест [   =] Это тест [  ==] Это тест [ ===] Это тест [====] Это тест [=== ] Это тест [==  ] Это тест [=   ] Это тест]}
[=== ] Это тест, want: [=== ] Это тест
	spinner_test.go:130: {kind:13 startMessage:Это тест color:92 WantFrames:[[    ] Это тест [   =] Это тест [  ==] Это тест [ ===] Это тест [====] Это тест [=== ] Это тест [==  ] Это тест [=   ] Это тест]}
[==  ] Это тест, want: [==  ] Это тест
	spinner_test.go:130: {kind:13 startMessage:Это тест color:92 WantFrames:[[    ] Это тест [   =] Это тест [  ==] Это тест [ ===] Это тест [====] Это тест [=== ] Это тест [==  ] Это тест [=   ] Это тест]}
[=   ] Это тест, want: [=   ] Это тест
=== RUN   TestSetMessage
--- PASS: TestSetMessage (0.00s)
=== RUN   TestStop
--- PASS: TestStop (0.01s)
=== RUN   TestStopError
--- PASS: TestStopError (0.00s)
=== RUN   TestReset
--- PASS: TestReset (0.00s)
=== RUN   TestSucceed
--- PASS: TestSucceed (0.01s)
=== RUN   TestFail
--- PASS: TestFail (0.01s)
=== RUN   TestWarn
--- PASS: TestWarn (0.01s)
=== RUN   TestFinish
--- PASS: TestFinish (0.01s)
=== RUN   TestFinishWithSymbol
--- PASS: TestFinishWithSymbol (0.01s)
=== RUN   TestFinishWithMessage
--- PASS: TestFinishWithMessage (0.01s)
FAIL
FAIL	github.com/dnmurray/gospinner	5.891s
gospinner$ go version
go version go1.10.2 darwin/amd64
gospinner$

slok · 2018-06-10T16:10:10Z

Hi @dnmurray!

It's been a long time since I released this project. Yes, you are right that ticker could create a race condition because the mutex could be closed before assigning the ticker in the goroutine and calling stop before it's assigned making a Stop on a nil ticker.

Image for a better explanation:

As you say you can or move the ticker creation outside the goroutine (now is inside the mutex) or wrap the goroutine assignations with the mutex.

I'll take a look at the tests in the following days and fix them. I will notify you when I have found the problem with the color test.

Thanks and sorry for the error :(

dnmurray · 2018-06-10T17:27:13Z

@slok Thanks for the reply, and the library!

slok · 2018-06-14T16:40:34Z

Fixed in #4 You can rebase over master and try again! :)

dnmurray · 2018-06-18T00:48:26Z

Updated, passing. Thanks for the fixes.

dnmurray · 2018-06-19T13:25:51Z

@slok Could you please cut a new release tag? We're using dep to manage dependencies in our project.

slok · 2018-06-19T18:36:13Z

Done! https://github.com/slok/gospinner/tree/v0.1.1

dnmurray mentioned this pull request Jun 9, 2018

Race condition in file sync w/ spinner phase2/rig#160

Open

Fix race condition when stopping before spinner fully built

7897291

dnmurray force-pushed the bug/stop-race-condition branch from 97aaa2e to 7897291 Compare June 17, 2018 18:47

slok merged commit c6cc8e2 into slok:master Jun 18, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix race condition when stopping before spinner fully built #3

Fix race condition when stopping before spinner fully built #3

dnmurray commented Jun 9, 2018

dnmurray commented Jun 10, 2018 •

edited

Loading

slok commented Jun 10, 2018 •

edited

Loading

dnmurray commented Jun 10, 2018

slok commented Jun 14, 2018

dnmurray commented Jun 18, 2018

dnmurray commented Jun 19, 2018

slok commented Jun 19, 2018

Fix race condition when stopping before spinner fully built #3

Fix race condition when stopping before spinner fully built #3

Conversation

dnmurray commented Jun 9, 2018

dnmurray commented Jun 10, 2018 • edited Loading

slok commented Jun 10, 2018 • edited Loading

dnmurray commented Jun 10, 2018

slok commented Jun 14, 2018

dnmurray commented Jun 18, 2018

dnmurray commented Jun 19, 2018

slok commented Jun 19, 2018

dnmurray commented Jun 10, 2018 •

edited

Loading

slok commented Jun 10, 2018 •

edited

Loading