I see the following output when running live tests against provider/ec2.
What seems to be happening is that tools.StorageName
is returning a different name than is actually used when uploading.
Looking at the code, there is a global variable changed by SetToolPrefix, which
is called when uploading. This:
a) is thread-unsafe, because it's not guarded with a mutex
b) is thread-unsafe even if it *was* guarded with a mutex, because the variable actually
relates to one particular storage only.
c) violates assumptions in various parts of the code that tools.StorageName
returns the name that will be used.
0:03.118 START: live_test.go:81: LiveTests.SetUpSuite
0:03.131 [LOG] 36.85478 INFO juju.provider.ec2 opening environment "sample-62123cf38ff4318e"
0:03.149 [LOG] 36.85478 INFO juju environs/testing: uploading FAKE tools 1.15.0-raring-amd64
0:04.352 [LOG] 36.85478 INFO juju environs/testing: uploading FAKE tools 1.15.0-precise-amd64
0:04.904 PASS: live_test.go:81: LiveTests.SetUpSuite 1.786s
0:04.904
0:04.904 START: live_test.go:1: LiveTests.TestBootstrapWithDefaultSeries
0:04.904 START: live_test.go:109: LiveTests.SetUpTest
0:04.904 PASS: live_test.go:109: LiveTests.SetUpTest 0.000s
0:04.904
0:04.937 [LOG] 36.85478 INFO juju.provider.ec2 opening environment "sample-62123cf38ff4318e"
0:04.985 [LOG] 36.85478 INFO juju environs/testing: uploading FAKE tools 1.15.0-raring-amd64
0:04.985 [LOG] 36.85478 INFO juju environs/testing: uploading FAKE tools 1.15.0-precise-amd64
0:05.004 [LOG] 36.85478 DEBUG juju.environs.sync Uploading tools for []
0:05.005 [LOG] 36.85478 DEBUG juju.environs.tools looking for: /tmp/go-build049762941/launchpad.net/juju-core/provider/ec2/_test/ec2.test
0:05.005 [LOG] 36.85478 DEBUG juju.environs.tools checking: /tmp/go-build049762941/launchpad.net/juju-core/provider/ec2/_test/jujud
0:05.005 [LOG] 36.85478 INFO juju.environs.tools couldn't find existing jujud
0:05.005 [LOG] 36.85478 DEBUG juju.environs.tools copy existing failed: stat /tmp/go-build049762941/launchpad.net/juju-core/provider/ec2/_test/jujud: no such file or directory
0:05.005 [LOG] 36.85478 INFO juju.environs.tools building jujud
0:08.946 [LOG] 36.85478 DEBUG juju.environs.tools forcing version to 1.15.0
0:08.954 [LOG] 36.85478 DEBUG juju.environs.tools adding entry: &tar.Header{Name:"FORCE-VERSION", Mode:436, Uid:0, Gid:0, Size:6, ModTime:time.Time{sec:63515637330, nsec:0x23dc73e2, loc:(*time.Location)(0x14192a0)}, Typeflag:0x30, Linkname:"", Uname:"ubuntu", Gname:"ubuntu", Devmajor:0, Devminor:0, AccessTime:time.Time{sec:63515637330, nsec:0x23dc73e2, loc:(*time.Location)(0x14192a0)}, ChangeTime:time.Time{sec:63515637330, nsec:0x23dc73e2, loc:(*time.Location)(0x14192a0)}}
0:08.963 [LOG] 36.85478 DEBUG juju.environs.tools adding entry: &tar.Header{Name:"jujud", Mode:509, Uid:0, Gid:0, Size:19500136, ModTime:time.Time{sec:63515637330, nsec:0x2085f5e0, loc:(*time.Location)(0x14192a0)}, Typeflag:0x30, Linkname:"", Uname:"ubuntu", Gname:"ubuntu", Devmajor:0, Devminor:0, AccessTime:time.Time{sec:63515637330, nsec:0x2085f5e0, loc:(*time.Location)(0x14192a0)}, ChangeTime:time.Time{sec:63515637330, nsec:0x2085f5e0, loc:(*time.Location)(0x14192a0)}}
0:11.468 [LOG] 36.85478 INFO juju.environs.sync built 1.15.0-raring-amd64 (4244kB)
0:11.472 [LOG] 36.85478 INFO juju.environs.sync listing available tools
0:11.472 [LOG] 36.85478 DEBUG juju.environs.tools reading v1.* tools
0:11.472 [LOG] 36.85478 DEBUG juju.environs.tools reading v1.* tools
0:11.472 [LOG] 36.85478 DEBUG juju.environs.tools found 1.15.0-raring-amd64
0:11.472 [LOG] 36.85478 INFO juju.environs.sync found 1 tools
0:11.472 [LOG] 36.85478 DEBUG juju.environs.sync found source tool: &{1.15.0-raring-amd64 file:///tmp/193788623/tools/releases/juju-1.15.0-raring-amd64.tgz 0}
0:11.472 [LOG] 36.85478 INFO juju.environs.sync listing target bucket
0:11.472 [LOG] 36.85478 DEBUG juju.environs.tools reading v1.* tools
0:11.472 [LOG] 36.85478 DEBUG juju.environs.tools reading v1.* tools
0:11.472 [LOG] 36.85478 INFO juju.environs.sync found 0 tools in target; 1 tools to be copied
0:11.472 [LOG] 36.85478 INFO juju.environs.sync copying 1.15.0-raring-amd64 from file:///tmp/193788623/tools/releases/juju-1.15.0-raring-amd64.tgz
0:11.472 [LOG] 36.85478 INFO juju.environs.sync copying tools/releases/juju-1.15.0-raring-amd64.tgz
0:11.490 [LOG] 36.85478 INFO juju.environs.sync downloaded tools/releases/juju-1.15.0-raring-amd64.tgz (4244kB), uploading
0:11.490 [LOG] 36.85478 INFO juju.environs.sync download 4244kB, uploading
0:11.548 [LOG] 36.85478 INFO juju.environs.sync copied 1 tools
0:11.548 [LOG] 36.85478 INFO juju.environs.sync generating tools metadata
0:11.548 [LOG] 36.85478 DEBUG juju.environs.tools no architecture specified when finding tools, looking for any
0:11.548 [LOG] 36.85478 DEBUG juju.environs.tools no series specified when finding tools, looking for any
0:11.548 [LOG] 36.85478 DEBUG juju.environs.simplestreams cannot load index "http://127.0.0.1:45765/dummy storage/private/tools/streams/v1/index.sjson": invalid URL "http://127.0.0.1:45765/dummy storage/private/tools/streams/v1/index.sjson" not found
0:11.548 [LOG] 36.85478 DEBUG juju.environs.simplestreams cannot load index "http://127.0.0.1:45765/dummy storage/private/tools/streams/v1/index.json": invalid URL "http://127.0.0.1:45765/dummy storage/private/tools/streams/v1/index.json" not found
0:11.549 [LOG] 36.85478 INFO juju.environs.tools Writing tools/streams/v1/index.json
0:11.549 [LOG] 36.85478 INFO juju.environs.tools Writing tools/streams/v1/com.ubuntu.juju:released:tools.json
0:11.549 [LOG] 36.85478 INFO juju.environs.sync tools metadata written
0:11.551 /home/rog/src/go/src/launchpad.net/juju-core/environs/jujutest/livetests.go:899:
0:11.555 c.Assert(err, gc.IsNil)
0:11.555 ... value errors.notFoundError = errors.notFoundError{errorWrapper:(*errors.errorWrapper)(0xc21048f920)} ("file \"tools/juju-1.15.0-raring-amd64.tgz\" not found not found")
There's a long story associated with this. The short answer is that this is pretty old code and there's a need for 2 possible tools prefixes because simplestreams uses a different location to where the tools used to go. Both still need to be supported for backwards compatibility. As soon as the tools repository is set up, the legacy code can be deleted, so it is only short term. The repository ticket was raised over a month ago so the code has had to stay around longer than anticipated.
The production code which uses the tools prefix is single threaded so there are no issues there. And it is only used in the case that simplestreams tools lookup fails or someone tries to sync tools where the tools are located in a deprecated directory.
The SetToolsPrefix method has been there a while and I think it may have been introduced specifically for live tests so as not to overwrite the real tools in ec2. This is just a guess as I didn't write it originally. But if tests are run across multiple processes, then it could cause issues.