Data in Race in github.com/juju/testing/cleanup

[Aaron Bentley]

There is a data race in TestLogOutput.

As seen here:
http://reports.vapour.ws/releases/issue/57b5cada749a567eabd11a4b

Starting with revision build 4268 (5c126b0) we have seen it consistently, not intermittently.

Full log:
==================
WARNING: DATA RACE
Write by goroutine 34:
  reflect.Value.Set()
      /usr/lib/go-1.6/src/reflect/value.go:1338 +0x10b
  github.com/juju/testing.PatchValue()
      /home/ubuntu/juju-core_2.0-beta16/src/github.com/juju/testing/patch.go:46 +0x2a3
  github.com/juju/testing.(*CleanupSuite).PatchValue()
      /home/ubuntu/juju-core_2.0-beta16/src/github.com/juju/testing/cleanup.go:125 +0x50
  github.com/juju/juju/cmd/juju/commands.(*DebugLogSuite).TestLogOutput()
      /home/ubuntu/juju-core_2.0-beta16/src/github.com/juju/juju/cmd/juju/commands/debuglog_test.go:131 +0x3d8
  runtime.call32()
      /usr/lib/go-1.6/src/runtime/asm_amd64.s:472 +0x3d
  reflect.Value.Call()
      /usr/lib/go-1.6/src/reflect/value.go:303 +0xcd
  gopkg.in/check%2ev1.(*suiteRunner).forkTest.func1()
      /home/ubuntu/juju-core_2.0-beta16/src/gopkg.in/check.v1/check.go:772 +0x5d1
  gopkg.in/check%2ev1.(*suiteRunner).forkCall.func1()
      /home/ubuntu/juju-core_2.0-beta16/src/gopkg.in/check.v1/check.go:666 +0x80

Previous read by goroutine 28:
  time.Now()
      /usr/lib/go-1.6/src/time/time.go:783 +0x6e
  time.sendTime()
      /usr/lib/go-1.6/src/time/sleep.go:101 +0x60

Goroutine 34 (running) created at:
  gopkg.in/check%2ev1.(*suiteRunner).forkCall()
      /home/ubuntu/juju-core_2.0-beta16/src/gopkg.in/check.v1/check.go:667 +0x48b
  gopkg.in/check%2ev1.(*suiteRunner).forkTest()
      /home/ubuntu/juju-core_2.0-beta16/src/gopkg.in/check.v1/check.go:804 +0x126
  gopkg.in/check%2ev1.(*suiteRunner).runTest()
      /home/ubuntu/juju-core_2.0-beta16/src/gopkg.in/check.v1/check.go:809 +0x38
  gopkg.in/check%2ev1.(*suiteRunner).run()
      /home/ubuntu/juju-core_2.0-beta16/src/gopkg.in/check.v1/check.go:615 +0x481
  gopkg.in/check%2ev1.Run()
      /home/ubuntu/juju-core_2.0-beta16/src/gopkg.in/check.v1/run.go:92 +0x50
  gopkg.in/check%2ev1.RunAll()
      /home/ubuntu/juju-core_2.0-beta16/src/gopkg.in/check.v1/run.go:84 +0x138
  gopkg.in/check%2ev1.TestingT()
      /home/ubuntu/juju-core_2.0-beta16/src/gopkg.in/check.v1/run.go:72 +0x4af
  github.com/juju/testing.MgoTestPackage()
      /home/ubuntu/juju-core_2.0-beta16/src/github.com/juju/testing/mgo.go:420 +0x177
  github.com/juju/juju/testing.MgoTestPackage()
      /home/ubuntu/juju-core_2.0-beta16/src/github.com/juju/juju/testing/mgo.go:15 +0x4a
  github.com/juju/juju/cmd/juju/commands.TestPackage()
      /home/ubuntu/juju-core_2.0-beta16/src/github.com/juju/juju/cmd/juju/commands/package_test.go:21 +0x2e
  testing.tRunner()
      /usr/lib/go-1.6/src/testing/testing.go:473 +0xdc

Goroutine 28 (running) created at:
  runtime.addtimerLocked()
      /usr/lib/go-1.6/src/runtime/time.go:116 +0x1a6
  testing.startAlarm()
      /usr/lib/go-1.6/src/testing/testing.go:726 +0x93
  testing.(*M).Run()
      /usr/lib/go-1.6/src/testing/testing.go:513 +0x7c
  main.main()
      github.com/juju/juju/cmd/juju/commands/_test/_testmain.go:56 +0x210
==================
OK: 190 passed
PASS
Found 1 data race(s)

[Tim Penhey (thumper)]

https://github.com/juju/juju/pull/6089

[Alexis Bruemmer (alexis-bruemmer)]

Is this test still failing in CI with the fix from comment #1 from thumper?

[Aaron Bentley (abentley)]

On 2016-08-29 10:08 AM, Alexis Bruemmer wrote:
> Is this test still failing in CI with the fix from comment #1 from
> thumper?

Yes. There have been two failures today already, which you can see from
the Issue:
http://reports.vapour.ws/releases/issue/57b5cada749a567eabd11a4b

[Aaron Bentley (abentley)]

AFAICT, the fix has not actually landed in master yet.

[Aaron Bentley (abentley)]

It appears to have been a temporary problem on the lander end:
http://juju-ci.vapour.ws:8080/job/github-merge-juju/8921/console

The landing script was not at the expected location, so it could not update the pull request.

+ set +e
++ /var/lib/jenkins/juju-ci-tools/check_blockers.py -c /var/lib/jenkins/cloud-city/juju-qa-bot-lp-oauth.txt check master 6089
+ blockers_reason='Does not match ['\''fixes-1616584'\'', '\''fixes-1611514'\'', '\''fixes-1475212'\'']'
+ EXIT_STATUS=1
+ set -e
+ echo Does not match '['\''fixes-1616584'\'',' ''\''fixes-1611514'\'',' ''\''fixes-1475212'\'']'
Does not match ['fixes-1616584', 'fixes-1611514', 'fixes-1475212']
+ [[ 1 != 0 ]]
+ echo 'Build rejected, reporting on proposal'
Build rejected, reporting on proposal
+ /var/lib/jenkins-github-lander/bin/lander-merge-result --ini /var/lib/jenkins-github-lander/juju.ini '--failure=Does not match ['\''fixes-1616584'\'', '\''fixes-1611514'\'', '\''fixes-1475212'\'']' --pr=6089 --job-name=github-merge-juju --build-number=8921
/tmp/hudson3752569120501167549.sh: line 29: /var/lib/jenkins-github-lander/bin/lander-merge-result: No such file or directory
Build step 'Execute shell' marked build as failure
Archiving artifacts
[description-setter] Could not determine description.
Finished: FAILURE

[Aaron Bentley (abentley)]

I re-ran the merge job and it succeeded, producing 9b7d533