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

Question

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

Can you explain what more you need to know? The errors show precisely where you have concurrent reads and writes for the first data race, and concurrent writes in the second. Please include the code in question as well. — JimB, Feb 24 '19 at 15:04
Just got thrown off by the trace. @mkopriva helped out with deciphering the trace. Will try it out and should be all set. I suppose you could say that I haven't ever dealt with a race before so I had some trouble understanding what it meant. But I understand now. — nitimalh, Feb 24 '19 at 15:26

mkopriva · Accepted Answer · 2019-02-24T15:10:43.697

4

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.

edited Feb 24 '19 at 15:10

answered Feb 24 '19 at 15:05

mkopriva

35,176
4
57
71

1

Thanks that no helps. I guess I just got thrown off by the long trace that I didn't understand what to look for. I will add a RWMutex to the task struct and use it in the methods. – nitimalh Feb 24 '19 at 15:25
4

Go idiom: Don't communicate by sharing data. Share data by communicating. (translation: use channels, not mutexes) – Jarri Abidi Sep 24 '20 at 02:46

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

1 Answers1