race in StatusHistoryTest

Bug #1735112 reported by John A Meinel on 2017-11-29
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
juju
High
John A Meinel
2.3
High
John A Meinel

Bug Description

As seen here (though incorrectly targeted):
http://qa.jujucharms.com/releases/6015/job/run-unit-tests-race/attempt/3507#highlight

I was able to reproduce it locally, just by doing
cd cmd/juju/status
go test --race --check.v
^- unfortunately some of the earlier tests take 90s to complete, so this is a bit expensive (wall clock time is 222s for the whole suite, and a huge amount of time to build.)
Note that I also tried:
go test --race --check.v --check.f StatusHistorySuite

and that does *not* appear to trigger the failure.

==================
WARNING: DATA RACE
Write at 0x00000317e500 by goroutine 35:
  reflect.Value.Set()
      /snap/go/1016/src/reflect/value.go:1361 +0x106
  github.com/juju/testing.PatchValue()
      /home/jameinel/dev/go/src/github.com/juju/testing/patch.go:46 +0x195
  github.com/juju/testing.(*CleanupSuite).PatchValue()
      /home/jameinel/dev/go/src/github.com/juju/testing/cleanup.go:125 +0x5a
  github.com/juju/juju/cmd/juju/status_test.(*StatusHistorySuite).SetUpTest()
      /home/jameinel/dev/go/src/github.com/juju/juju/cmd/juju/status/history_test.go:34 +0x1b1
  runtime.call32()
      /snap/go/1016/src/runtime/asm_amd64.s:509 +0x3a
  reflect.Value.Call()
      /snap/go/1016/src/reflect/value.go:302 +0xc0
  gopkg.in/check%2ev1.(*suiteRunner).runFixture.func1()
      /home/jameinel/dev/go/src/gopkg.in/check.v1/check.go:721 +0x184
  gopkg.in/check%2ev1.(*suiteRunner).forkCall.func1()
      /home/jameinel/dev/go/src/gopkg.in/check.v1/check.go:666 +0x89

Previous read at 0x00000317e500 by goroutine 36:
  time.Now()
      /snap/go/1016/src/time/time.go:1049 +0xd3
  time.sendTime()
      /snap/go/1016/src/time/sleep.go:139 +0x44

Goroutine 35 (running) created at:
  gopkg.in/check%2ev1.(*suiteRunner).forkCall()
      /home/jameinel/dev/go/src/gopkg.in/check.v1/check.go:663 +0x430
  gopkg.in/check%2ev1.(*suiteRunner).runFunc()
      /home/jameinel/dev/go/src/gopkg.in/check.v1/check.go:673 +0x7e
  gopkg.in/check%2ev1.(*suiteRunner).runFixture()
      /home/jameinel/dev/go/src/gopkg.in/check.v1/check.go:717 +0x7e
  gopkg.in/check%2ev1.(*suiteRunner).runFixtureWithPanic()
      /home/jameinel/dev/go/src/gopkg.in/check.v1/check.go:735 +0xaa
  gopkg.in/check%2ev1.(*suiteRunner).forkTest.func1()
      /home/jameinel/dev/go/src/gopkg.in/check.v1/check.go:760 +0x217
  gopkg.in/check%2ev1.(*suiteRunner).forkCall.func1()
      /home/jameinel/dev/go/src/gopkg.in/check.v1/check.go:666 +0x89

Goroutine 36 (running) created at:
  runtime.addtimerLocked()
      /snap/go/1016/src/runtime/time.go:122 +0xec
  context.WithDeadline()
      /snap/go/1016/src/context/context.go:401 +0x56c
  net.(*Dialer).DialContext()
      /snap/go/1016/src/net/dial.go:348 +0xe59
  net.(*Dialer).Dial()
      /snap/go/1016/src/net/dial.go:320 +0xa1
  net.DialTimeout()
      /snap/go/1016/src/net/dial.go:306 +0xb6
  gopkg.in/mgo%2ev2.resolveAddr.func1()
      /home/jameinel/dev/go/src/gopkg.in/mgo.v2/cluster.go:434 +0x72
==================

John A Meinel (jameinel) on 2017-11-29
Changed in juju:
status: Triaged → In Progress
John A Meinel (jameinel) wrote :

It does seem to be the transition between test suites, I can trigger it a bit faster with:
gt --race --check.f "StatusHistory|TestSummaryStatusWithUnresolvableDns"

John A Meinel (jameinel) wrote :

This looks to have been introduced by Tim's recent test suite around "juju show-status-log".
We are patching "time.Local" to force the test suite to give times in UTC time, but it appears to be racing with something else.
Previous read at 0x00000317e500 by goroutine 36:
  time.Now()
      /snap/go/1016/src/time/time.go:1049 +0xd3
  time.sendTime()
      /snap/go/1016/src/time/sleep.go:139 +0x44

is racing with:
  github.com/juju/testing.(*CleanupSuite).PatchValue()
      /home/jameinel/dev/go/src/github.com/juju/testing/cleanup.go:125 +0x5a
  github.com/juju/juju/cmd/juju/status_test.(*StatusHistorySuite).SetUpTest()
      /home/jameinel/dev/go/src/github.com/juju/juju/cmd/juju/status/history_test.go:34 +0x1b1

Probably the goroutine that is monitoring the time to see if it needs to kill the test suite because we went over time.
We probably can't fix that race, so we should see if we can avoid patching Local.

John A Meinel (jameinel) on 2017-11-29
Changed in juju:
milestone: 2.3.0 → 2.4-beta1
John A Meinel (jameinel) on 2018-01-09
Changed in juju:
status: In Progress → Fix Committed
Changed in juju:
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers