CODEWITHSUNDEEP
gotestingrace-conditiongoroutinedata-race
nitimalh
nitimalh

Reputation: 961

Cannot understand go test -race : RACE: DATA WARNING stack trace

I ran into a DATA RACE warning while testing my project, and was wondering if anyone would be kind enough to help me decipher the problem. I have never attempted testing go routines in the past and am finding it hard to wrap my head around data races.

I have provided a link in the description to the open issue, with the trace in the issue description.

I would really appreciate some help, just from the aspect of learning to debug similar issues and writing better tests for go routines in the future.

https://github.com/nitishm/vegeta-server/issues/52

A snippet of the trace is provided below as well

=== RUN   Test_dispatcher_Cancel_Error_completed
INFO[0000] creating new dispatcher                       component=dispatcher
INFO[0000] starting dispatcher                           component=dispatcher
INFO[0000] dispatching new attack                        ID=d63a79ac-6f51-486e-845d-077c8c76168a Status=scheduled component=dispatcher
==================
WARNING: DATA RACE
Read at 0x00c0000f8d68 by goroutine 8:
  vegeta-server/internal/dispatcher.(*task).Complete()
      /Users/nitishm/vegeta-server/internal/dispatcher/task.go:116 +0x61
  vegeta-server/internal/dispatcher.run()
      /Users/nitishm/vegeta-server/internal/dispatcher/task.go:213 +0x17a

Previous write at 0x00c0000f8d68 by goroutine 7:
  vegeta-server/internal/dispatcher.(*task).Run()
      /Users/nitishm/vegeta-server/internal/dispatcher/task.go:107 +0x12a
  vegeta-server/internal/dispatcher.(*dispatcher).Run()
      /Users/nitishm/vegeta-server/internal/dispatcher/dispatcher.go:109 +0xb5f

Goroutine 8 (running) created at:
  vegeta-server/internal/dispatcher.(*task).Run()
      /Users/nitishm/vegeta-server/internal/dispatcher/task.go:105 +0x11c
  vegeta-server/internal/dispatcher.(*dispatcher).Run()
      /Users/nitishm/vegeta-server/internal/dispatcher/dispatcher.go:109 +0xb5f

Goroutine 7 (running) created at:
  vegeta-server/internal/dispatcher.Test_dispatcher_Cancel_Error_completed()
      /Users/nitishm/vegeta-server/internal/dispatcher/dispatcher_test.go:249 +0x545
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:827 +0x162
==================
==================
WARNING: DATA RACE
Write at 0x00c0000f8d98 by goroutine 8:
  vegeta-server/internal/dispatcher.(*task).SendUpdate()
      /Users/nitishm/vegeta-server/internal/dispatcher/task.go:164 +0x70
  vegeta-server/internal/dispatcher.(*task).Complete()
      /Users/nitishm/vegeta-server/internal/dispatcher/task.go:128 +0x20e
  vegeta-server/internal/dispatcher.run()
      /Users/nitishm/vegeta-server/internal/dispatcher/task.go:213 +0x17a

Previous write at 0x00c0000f8d98 by goroutine 7:
  vegeta-server/internal/dispatcher.(*task).SendUpdate()
      /Users/nitishm/vegeta-server/internal/dispatcher/task.go:164 +0x70
  vegeta-server/internal/dispatcher.(*task).Run()
      /Users/nitishm/vegeta-server/internal/dispatcher/task.go:109 +0x15d
  vegeta-server/internal/dispatcher.(*dispatcher).Run()
      /Users/nitishm/vegeta-server/internal/dispatcher/dispatcher.go:109 +0xb5f

Goroutine 8 (running) created at:
  vegeta-server/internal/dispatcher.(*task).Run()
      /Users/nitishm/vegeta-server/internal/dispatcher/task.go:105 +0x11c
  vegeta-server/internal/dispatcher.(*dispatcher).Run()
      /Users/nitishm/vegeta-server/internal/dispatcher/dispatcher.go:109 +0xb5f

Goroutine 7 (running) created at:
  vegeta-server/internal/dispatcher.Test_dispatcher_Cancel_Error_completed()
      /Users/nitishm/vegeta-server/internal/dispatcher/dispatcher_test.go:249 +0x545
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:827 +0x162
==================
INFO[0002] canceling attack                              ID=d63a79ac-6f51-486e-845d-077c8c76168a ToCancel=true component=dispatcher
ERRO[0002] failed to cancel task                         ID=d63a79ac-6f51-486e-845d-077c8c76168a ToCancel=true component=dispatcher error="cannot cancel task d63a79ac-6f51-486e-845d-077c8c76168a with status completed"
WARN[0002] gracefully shutting down the dispatcher       component=dispatcher
--- FAIL: Test_dispatcher_Cancel_Error_completed (2.01s)
    testing.go:771: race detected during execution of test

Upvotes: 11

Views: 14535

Answers (1)

mkopriva
mkopriva

Reputation: 38243

As far as I can understand it:

Read at 0x00c0000f8d68 by goroutine 8: and Previous write at 0x00c0000f8d68 by goroutine 7

means that both goroutines 8 and 7 are reading from and writing to the same location. If you look at the lines pointed to by the error:

goroutine 8 on 116:

if t.status != models.AttackResponseStatusRunning {

goroutine 7 on 107:

t.status = models.AttackResponseStatusRunning

You can see that the goroutines are accessing the task's state without any synchronization and that, as you already know, can cause a race condition.

So if your program allows access to a single task by multiple goroutines you need to ensure that no data race occurs by using a mutex lock for example.

Upvotes: 8

Related Questions