juju-core

intermittent test failure in BootstrapSuite

Bug #1199698 reported by Frank Mueller
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
juju-core
Fix Released
Low
Unassigned

Bug Description

The BootstrapSuite in cmd/juju fails intermittently. In these cases the number of found tools (line 108) and the test of the found tools (line 113) are failing. The test cases are number 9 and 10, so error details may vary. But the failing checks are the same.

Revision history for this message
Frank Mueller (themue) wrote :

Test case 8 shows the same failure.

John A Meinel (jameinel)
Changed in juju-core:
status: New → In Progress
Revision history for this message
Frank Mueller (themue) wrote :

test 8: --upload-tools only uploads each file once
[LOG] 25.54083 INFO juju environs/dummy: reset environment
[LOG] 25.54751 INFO juju environs/testing: uploading FAKE tools 1.11.2-raring-amd64
[LOG] 25.54754 INFO juju environs/testing: uploading FAKE tools 1.11.2-precise-amd64
clearing private storage
removing files: []
clearing public storage
removing files: [tools/juju-1.11.2-precise-amd64.tgz tools/juju-1.11.2-raring-amd64.tgz]
[LOG] 25.62582 INFO juju environs/testing: uploading FAKE tools 1.2.3.1-precise-hostarch
[LOG] 25.62589 INFO juju environs/testing: uploading FAKE tools 1.2.3.1-defaultseries-hostarch
[LOG] 25.62591 INFO juju environs: reading tools with major version 1
[LOG] 25.62592 DEBUG juju environs/tools: reading v1.* tools
[LOG] 25.62595 DEBUG juju environs/tools: found 1.2.3.1-precise-hostarch
found: 1.2.3.1-precise-hostarch
bootstrap_test.go:63:
    test.run(c)
bootstrap_test.go:108:
    c.Check(urls, HasLen, len(test.uploads))
... obtained map[version.Binary]string = map[version.Binary]string{version.Binary{Number:version.Number{Major:1, Minor:2, Patch:3, Build:1}, Series:"precise", Arch:"hostarch"}:"http://127.0.0.1:45061/peckham/private/tools/juju-1.2.3.1-precise-hostarch.tgz"}
... n int = 2

seeking: 1.2.3.1-defaultseries-hostarch
bootstrap_test.go:63:
    test.run(c)
bootstrap_test.go:113:
    c.Check(found, Equals, true)
... obtained bool = false
... expected bool = true

seeking: 1.2.3.1-precise-hostarch
[LOG] 25.66831 INFO juju environs: reading tools with major version 1
[LOG] 25.66832 DEBUG juju environs/tools: reading v1.* tools
[LOG] 25.66835 DEBUG juju environs/tools: found 1.2.3.1-defaultseries-hostarch
[LOG] 25.66837 DEBUG juju environs/tools: found 1.2.3.1-precise-hostarch
[LOG] 25.66839 INFO juju environs: filtering tools by series: defaultseries
[LOG] 25.66840 INFO juju environs: filtering tools by version: 1.2.3.1
[LOG] 25.66842 INFO juju environs/dummy: would pick tools from 1.2.3.1-defaultseries-hostarch

Revision history for this message
Frank Mueller (themue) wrote :

test 10: --upload-tools always bumps build number
[LOG] 72.92618 INFO juju environs/dummy: reset environment
[LOG] 72.93230 INFO juju environs/testing: uploading FAKE tools 1.11.2-raring-amd64
[LOG] 72.93236 INFO juju environs/testing: uploading FAKE tools 1.11.2-precise-amd64
clearing private storage
removing files: []
clearing public storage
removing files: [tools/juju-1.11.2-precise-amd64.tgz tools/juju-1.11.2-raring-amd64.tgz]
[LOG] 73.00359 INFO juju environs/testing: uploading FAKE tools 1.2.3.5-defaultseries-hostarch
[LOG] 73.00366 INFO juju environs/testing: uploading FAKE tools 1.2.3.5-precise-hostarch
[LOG] 73.00369 INFO juju environs: reading tools with major version 1
[LOG] 73.00370 DEBUG juju environs/tools: reading v1.* tools
[LOG] 73.00373 DEBUG juju environs/tools: found 1.2.3.5-defaultseries-hostarch
found: 1.2.3.5-defaultseries-hostarch
bootstrap_test.go:63:
    test.run(c)
bootstrap_test.go:108:
    c.Check(urls, HasLen, len(test.uploads))
... obtained map[version.Binary]string = map[version.Binary]string{version.Binary{Number:version.Number{Major:1, Minor:2, Patch:3, Build:5}, Series:"defaultseries", Arch:"hostarch"}:"http://127.0.0.1:48515/peckham/private/tools/juju-1.2.3.5-defaultseries-hostarch.tgz"}
... n int = 2

seeking: 1.2.3.5-defaultseries-hostarch
seeking: 1.2.3.5-precise-hostarch
bootstrap_test.go:63:
    test.run(c)
bootstrap_test.go:113:
    c.Check(found, Equals, true)
... obtained bool = false
... expected bool = true

[LOG] 73.04228 INFO juju environs: reading tools with major version 1
[LOG] 73.04230 DEBUG juju environs/tools: reading v1.* tools
[LOG] 73.04232 DEBUG juju environs/tools: found 1.2.3.5-defaultseries-hostarch
[LOG] 73.04235 DEBUG juju environs/tools: found 1.2.3.5-precise-hostarch
[LOG] 73.04237 INFO juju environs: filtering tools by series: defaultseries
[LOG] 73.04238 INFO juju environs: filtering tools by version: 1.2.3.5
[LOG] 73.04240 INFO juju environs/dummy: would pick tools from 1.2.3.5-defaultseries-hostarch

Dimiter Naydenov (dimitern)
tags: added: intermittent-failure
Revision history for this message
Frank Mueller (themue) wrote :

Test behavior seems to be influenced by GOMAXPROCS. My standard setting is 4, here it shows the intermittent failures. After setting it to 1 there's no more failure.

Revision history for this message
Frank Mueller (themue) wrote :
Download full text (3.7 KiB)

==================
WARNING: DATA RACE
Read by goroutine 22:
  labix.org/v2/mgo.(*mongoSocket).kill()
      /home/fmueller/GoPkg/src/labix.org/v2/mgo/socket.go:204 +0x4df
  labix.org/v2/mgo.(*mongoSocket).Close()
      /home/fmueller/GoPkg/src/labix.org/v2/mgo/socket.go:191 +0xa5
  labix.org/v2/mgo.(*mongoServer).Close()
      /home/fmueller/GoPkg/src/labix.org/v2/mgo/server.go:167 +0x294
  labix.org/v2/mgo.(*mongoCluster).Release()
      /home/fmueller/GoPkg/src/labix.org/v2/mgo/cluster.go:91 +0x25e
  labix.org/v2/mgo.(*mongoCluster).syncServersLoop()
      /home/fmueller/GoPkg/src/labix.org/v2/mgo/cluster.go:314 +0x2b4
  gosched0()
      /opt/go/src/pkg/runtime/proc.c:1218 +0x9f

Previous write by goroutine 27:
  labix.org/v2/mgo.ResetStats()
      /home/fmueller/GoPkg/src/labix.org/v2/mgo/stats.go:59 +0x1c6
  launchpad.net/juju-core/testing.(*MgoSuite).SetUpTest()
      /home/fmueller/Code/src/launchpad.net/juju-core/testing/mgo.go:192 +0x29
  launchpad.net/juju-core/cmd/juju.(*BootstrapSuite).SetUpTest()
      /home/fmueller/Code/src/launchpad.net/juju-core/cmd/juju/bootstrap_test.go:34 +0x59
  launchpad.net/juju-core/cmd/juju.(*BootstrapSuite).SetUpTest()
      /home/fmueller/Code/src/launchpad.net/juju-core/cmd/juju/bootstrap_test.go:34 +0x24
  reflect.Value.Call()
      /opt/go/src/pkg/reflect/value.go:345 +0xa8
  launchpad.net/gocheck.func·005()
      /home/fmueller/GoPkg/src/launchpad.net/gocheck/gocheck.go:683 +0x1cc
  launchpad.net/gocheck.func·004()
      /home/fmueller/GoPkg/src/launchpad.net/gocheck/gocheck.go:628 +0xf1
  gosched0()
      /opt/go/src/pkg/runtime/proc.c:1218 +0x9f

Goroutine 22 (running) created at:
  labix.org/v2/mgo.newCluster()
      /home/fmueller/GoPkg/src/labix.org/v2/mgo/cluster.go:68 +0x395
  labix.org/v2/mgo.DialWithInfo()
      /home/fmueller/GoPkg/src/labix.org/v2/mgo/session.go:265 +0x25a
  launchpad.net/juju-core/testing.MgoDial()
      /home/fmueller/Code/src/launchpad.net/juju-core/testing/mgo.go:184 +0x52b
  launchpad.net/juju-core/testing.MgoReset()
      /home/fmueller/Code/src/launchpad.net/juju-core/testing/mgo.go:198 +0x37
  launchpad.net/juju-core/environs/dummy.Reset()
      /home/fmueller/Code/src/launchpad.net/juju-core/environs/dummy/environs.go:193 +0x1db
  launchpad.net/juju-core/cmd/juju.(*BootstrapSuite).TearDownTest()
      /home/fmueller/Code/src/launchpad.net/juju-core/cmd/juju/bootstrap_test.go:45 +0x5e
  launchpad.net/juju-core/cmd/juju.(*BootstrapSuite).TearDownTest()
      /home/fmueller/Code/src/launchpad.net/juju-core/cmd/juju/bootstrap_test.go:45 +0x24
  reflect.Value.Call()
      /opt/go/src/pkg/reflect/value.go:345 +0xa8
  launchpad.net/gocheck.func·005()
      /home/fmueller/GoPkg/src/launchpad.net/gocheck/gocheck.go:683 +0x1cc
  launchpad.net/gocheck.func·004()
      /home/fmueller/GoPkg/src/launchpad.net/gocheck/gocheck.go:628 +0xf1
  gosched0()
      /opt/go/src/pkg/runtime/proc.c:1218 +0x9f

Goroutine 27 (running) created at:
  launchpad.net/gocheck.(*suiteRunner).forkCall()
      /home/fmueller/GoPkg/src/launchpad.net/gocheck/gocheck.go:629 +0x561
  launchpad.net/gocheck.(*suiteRunner).runFunc()
      /home/fmueller/GoPkg/src/launchpad.net/gocheck/gocheck.go:635 +0x5...

Read more...

Revision history for this message
Frank Mueller (themue) wrote :

Ouch, while test B is calling SetUp() the TearDown() of test A calls dummy.Reset() where MgoSuite.MgoReset() is called. Here the databases are dropped.

Revision history for this message
Frank Mueller (themue) wrote :

test 6: constraints
[LOG] 90.44894 INFO juju environs/dummy: reset environment
[LOG] 90.45148 INFO juju environs/testing: uploading FAKE tools 1.11.3-raring-amd64
[LOG] 90.45150 INFO juju environs/testing: uploading FAKE tools 1.11.3-precise-amd64
clearing private storage
removing files: []
clearing public storage
removing files: [tools/juju-1.11.3-precise-amd64.tgz tools/juju-1.11.3-raring-amd64.tgz]
[LOG] 90.45154 INFO juju environs/testing: uploading FAKE tools 1.11.3-defaultseries-amd64
[LOG] 90.50127 INFO juju environs: reading tools with major version 1
[LOG] 90.50129 DEBUG juju environs/tools: reading v1.* tools
[LOG] 90.50131 DEBUG juju environs/tools: found 1.11.3-defaultseries-amd64
[LOG] 90.50133 INFO juju environs: filtering tools by series: defaultseries
[LOG] 90.50134 INFO juju environs: picked newest version: 1.11.3
[LOG] 90.52241 INFO juju environs/dummy: would pick tools from 1.11.3-defaultseries-amd64
... Panic: interface conversion: interface is nil, not dummy.OpPutFile (PC=0x41E485)

/opt/go/src/pkg/runtime/traceback_x86.c:211
  in callers
/opt/go/src/pkg/runtime/runtime.c:275
  in Caller
/home/fmueller/GoPkg/src/launchpad.net/gocheck/gocheck.go:307
  in C.logPanic
/home/fmueller/GoPkg/src/launchpad.net/gocheck/gocheck.go:654
  in suiteRunner.callDone
/opt/go/src/pkg/runtime/panic.c:229
  in panic
/opt/go/src/pkg/runtime/iface.c:310
  in assertE2Tret
/opt/go/src/pkg/runtime/iface.c:298
  in assertE2T
bootstrap_test.go:125
  in bootstrapTest.run
bootstrap_test.go:63
  in BootstrapSuite.TestTest
OOPS: 155 passed, 1 PANICKED
--- FAIL: TestPackage-2 (53.70 seconds)
FAIL
exit status 1
FAIL launchpad.net/juju-core/cmd/juju 53.872s

Revision history for this message
Frank Mueller (themue) wrote :

Yep, bootstrap_test.go fails when GOMAXPROCS > 1. There are two possible flags:

-p n controls that only n parallel builds do run
- parallel n controls parallel running tests, but only those which call t.Parallel() to signal that they can run in parallel

The usage of both flags shows no difference in the error situation described above, only GOMAXPROCS=1 helps.

Revision history for this message
Frank Mueller (themue) wrote :

Problem still exists but is no real problem to anyone (dummy provider for testing). So lowering the priority.

Changed in juju-core:
importance: High → Low
status: In Progress → Triaged
Curtis Hovey (sinzui)
tags: added: test-failure
Curtis Hovey (sinzui)
Changed in juju-core:
assignee: Frank Mueller (themue) → nobody
Curtis Hovey (sinzui)
Changed in juju-core:
status: Triaged → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.