The attempt to merge lp:~gz/juju-core/openstack_network_config_1241674 into lp:juju-core failed. Below is the output from the failed tests.

ok  	launchpad.net/juju-core/agent	1.372s
ok  	launchpad.net/juju-core/agent/tools	0.281s
ok  	launchpad.net/juju-core/bzr	8.517s
ok  	launchpad.net/juju-core/cert	3.220s
ok  	launchpad.net/juju-core/charm	0.685s
?   	launchpad.net/juju-core/charm/hooks	[no test files]
?   	launchpad.net/juju-core/charm/testing	[no test files]
ok  	launchpad.net/juju-core/cloudinit	0.034s
ok  	launchpad.net/juju-core/cloudinit/sshinit	1.075s
ok  	launchpad.net/juju-core/cmd	0.276s
ok  	launchpad.net/juju-core/cmd/charm-admin	0.869s
?   	launchpad.net/juju-core/cmd/charmd	[no test files]
?   	launchpad.net/juju-core/cmd/charmload	[no test files]
ok  	launchpad.net/juju-core/cmd/juju	259.043s

----------------------------------------------------------------------
FAIL: machine_test.go:278: MachineSuite.TestManageEnviron

[LOG] 83.93422 DEBUG juju.environs.configstore Making /tmp/gocheck-2202916659517317514/50/home/ubuntu/.juju/environments
[LOG] 84.05088 DEBUG juju.environs.tools reading v1.* tools
[LOG] 84.05098 INFO juju environs/testing: uploading FAKE tools 1.17.1-precise-amd64
[LOG] 84.05221 DEBUG juju.environs.tools no architecture specified when finding tools, looking for any
[LOG] 84.05222 DEBUG juju.environs.tools no series specified when finding tools, looking for any
[LOG] 84.05233 DEBUG juju.environs.simplestreams fetchData failed for "http://127.0.0.1:53656/dummyenv/private/tools/streams/v1/index.sjson": file "tools/streams/v1/index.sjson" not found not found
[LOG] 84.05236 DEBUG juju.environs.simplestreams cannot load index "http://127.0.0.1:53656/dummyenv/private/tools/streams/v1/index.sjson": invalid URL "http://127.0.0.1:53656/dummyenv/private/tools/streams/v1/index.sjson" not found
[LOG] 84.05240 DEBUG juju.environs.simplestreams fetchData failed for "http://127.0.0.1:53656/dummyenv/private/tools/streams/v1/index.json": file "tools/streams/v1/index.json" not found not found
[LOG] 84.05242 DEBUG juju.environs.simplestreams cannot load index "http://127.0.0.1:53656/dummyenv/private/tools/streams/v1/index.json": invalid URL "http://127.0.0.1:53656/dummyenv/private/tools/streams/v1/index.json" not found
[LOG] 84.05287 INFO juju.environs.tools Writing tools/streams/v1/index.json
[LOG] 84.05294 INFO juju.environs.tools Writing tools/streams/v1/com.ubuntu.juju:released:tools.json
[LOG] 84.05313 INFO juju.environs.bootstrap bootstrapping environment "dummyenv"
[LOG] 84.05321 DEBUG juju.environs.bootstrap looking for bootstrap tools: series="precise", arch=<nil>, version=1.17.1
[LOG] 84.05324 INFO juju.environs.tools reading tools with major.minor version 1.17
[LOG] 84.05328 INFO juju.environs.tools filtering tools by version: 1.17.1
[LOG] 84.05328 INFO juju.environs.tools filtering tools by series: precise
[LOG] 84.05331 DEBUG juju.environs.tools no architecture specified when finding tools, looking for any
[LOG] 84.05333 DEBUG juju.environs.simplestreams fetchData failed for "http://127.0.0.1:53656/dummyenv/private/tools/streams/v1/index.sjson": file "tools/streams/v1/index.sjson" not found not found
[LOG] 84.05335 DEBUG juju.environs.simplestreams cannot load index "http://127.0.0.1:53656/dummyenv/private/tools/streams/v1/index.sjson": invalid URL "http://127.0.0.1:53656/dummyenv/private/tools/streams/v1/index.sjson" not found
[LOG] 84.05351 DEBUG juju.environs.simplestreams fetchData failed for "http://127.0.0.1:53656/dummyenv/private/tools/streams/v1/mirrors.json": file "tools/streams/v1/mirrors.json" not found not found
[LOG] 84.05356 DEBUG juju.environs.simplestreams no mirror index file found
[LOG] 84.05361 DEBUG juju.environs.simplestreams no mirror information available for { }: mirror data for "com.ubuntu.juju:released:tools" not found
[LOG] 84.05362 DEBUG juju.environs.simplestreams read metadata index at "http://127.0.0.1:53656/dummyenv/private/tools/streams/v1/index.json"
[LOG] 84.05372 DEBUG juju.environs.simplestreams candidate matches for products ["com.ubuntu.juju:12.04:amd64" "com.ubuntu.juju:12.04:i386" "com.ubuntu.juju:12.04:arm"] are [{Fri, 24 Jan 2014 20:46:45 +0000 products:1.0 content-download  [] streams/v1/com.ubuntu.juju:released:tools.json [com.ubuntu.juju:12.04:amd64]}]
[LOG] 84.05372 DEBUG juju.environs.simplestreams finding products at path "streams/v1/com.ubuntu.juju:released:tools.json"
[LOG] 84.05395 DEBUG juju.environs.simplestreams metadata: &{map[com.ubuntu.juju:12.04:amd64:{ 1.17.1 amd64   map[20140124:0xc200a00360]}] map[] Fri, 24 Jan 2014 20:46:45 +0000 products:1.0 com.ubuntu.juju:released:tools}
[LOG] 84.05404 INFO juju.environs.bootstrap picked newest version: 1.17.1
[LOG] 84.05407 INFO juju.provider.dummy would pick tools from 1.17.1-precise-amd64
[LOG] 84.05456 INFO juju.state opening state; mongo addresses: ["localhost:42494"]; entity ""
[LOG] 84.06040 INFO juju.state connection established
[LOG] 84.11901 INFO juju.state initializing environment
[LOG] 84.14045 INFO juju.state.apiserver listening on "127.0.0.1:42159"
[LOG] 84.15812 INFO juju.state opening state; mongo addresses: ["localhost:42494"]; entity ""
[LOG] 84.17135 INFO juju.state connection established
[LOG] 84.17362 INFO juju juju: authorization error while connecting to state server; retrying
[LOG] 84.17368 INFO juju.state opening state; mongo addresses: ["localhost:42494"]; entity ""
[LOG] 84.17806 INFO juju.state connection established
[LOG] 84.22987 INFO juju state/api: dialing "wss://127.0.0.1:42159/"
[LOG] 84.23293 INFO juju.state.apiserver [E] API connection from 127.0.0.1:47472
[LOG] 84.23304 INFO juju state/api: connection established
[LOG] 84.23323 DEBUG juju.state.apiserver <- [E] <unknown> {"RequestId":1,"Type":"Admin","Request":"Login","Params":{"AuthTag":"user-admin","Password":"dummy-secret","Nonce":""}}
[LOG] 84.23359 DEBUG juju.state.apiserver -> [E] user-admin 363.819us {"RequestId":1,"Response":{}} Admin[""].Login
[LOG] 84.23405 DEBUG juju.environs.tools reading v1.* tools
[LOG] 84.23410 DEBUG juju.environs.tools found 1.17.1-precise-amd64
[LOG] 84.23413 INFO juju environs/testing: uploading FAKE tools 1.17.1-quantal-amd64
[LOG] 84.25542 DEBUG juju.environs.tools no architecture specified when finding tools, looking for any
[LOG] 84.25547 DEBUG juju.environs.tools no series specified when finding tools, looking for any
[LOG] 84.25557 DEBUG juju.environs.simplestreams fetchData failed for "http://127.0.0.1:53656/dummyenv/private/tools/streams/v1/index.sjson": file "tools/streams/v1/index.sjson" not found not found
[LOG] 84.25560 DEBUG juju.environs.simplestreams cannot load index "http://127.0.0.1:53656/dummyenv/private/tools/streams/v1/index.sjson": invalid URL "http://127.0.0.1:53656/dummyenv/private/tools/streams/v1/index.sjson" not found
[LOG] 84.25581 DEBUG juju.environs.simplestreams fetchData failed for "http://127.0.0.1:53656/dummyenv/private/tools/streams/v1/mirrors.json": file "tools/streams/v1/mirrors.json" not found not found
[LOG] 84.25584 DEBUG juju.environs.simplestreams no mirror index file found
[LOG] 84.25589 DEBUG juju.environs.simplestreams no mirror information available for { }: mirror data for "com.ubuntu.juju:released:tools" not found
[LOG] 84.25591 DEBUG juju.environs.simplestreams read metadata index at "http://127.0.0.1:53656/dummyenv/private/tools/streams/v1/index.json"
[LOG] 84.25604 DEBUG juju.environs.simplestreams candidate matches for products ["com.ubuntu.juju:12.04:amd64" "com.ubuntu.juju:12.04:i386" "com.ubuntu.juju:12.04:arm" "com.ubuntu.juju:12.10:amd64" "com.ubuntu.juju:12.10:i386" "com.ubuntu.juju:12.10:arm" "com.ubuntu.juju:13.04:amd64" "com.ubuntu.juju:13.04:i386" "com.ubuntu.juju:13.04:arm" "com.ubuntu.juju:13.10:amd64" "com.ubuntu.juju:13.10:i386" "com.ubuntu.juju:13.10:arm" "com.ubuntu.juju:14.04:amd64" "com.ubuntu.juju:14.04:i386" "com.ubuntu.juju:14.04:arm"] are [{Fri, 24 Jan 2014 20:46:45 +0000 products:1.0 content-download  [] streams/v1/com.ubuntu.juju:released:tools.json [com.ubuntu.juju:12.04:amd64]}]
[LOG] 84.25610 DEBUG juju.environs.simplestreams finding products at path "streams/v1/com.ubuntu.juju:released:tools.json"
[LOG] 84.25648 DEBUG juju.environs.simplestreams metadata: &{map[com.ubuntu.juju:12.04:amd64:{ 1.17.1 amd64   map[20140124:0xc2004d6c00]}] map[] Fri, 24 Jan 2014 20:46:45 +0000 products:1.0 com.ubuntu.juju:released:tools}
[LOG] 84.25693 INFO juju.environs.tools Writing tools/streams/v1/index.json
[LOG] 84.25733 INFO juju.environs.tools Writing tools/streams/v1/com.ubuntu.juju:released:tools.json
[LOG] 84.30758 INFO juju environs/testing: uploading FAKE tools 1.17.1-precise-amd64
[LOG] 84.31748 INFO juju.cmd.jujud machine agent machine-0 start
[LOG] 84.31755 DEBUG juju.agent Reading agent config, format: format 1.16
[LOG] 84.31896 INFO juju.cmd.jujud Starting StateWorker for machine-0
[LOG] 84.31900 INFO juju worker: start "state"
[LOG] 84.31905 INFO juju.state opening state; mongo addresses: ["localhost:42494"]; entity "machine-0"
[LOG] 84.31941 INFO juju worker: start "api"
[LOG] 84.31966 INFO juju state/api: dialing "wss://localhost:50228/"
[LOG] 84.32032 INFO juju worker: start "termination"
[LOG] 84.32041 ERROR juju state/api: websocket.Dial wss://localhost:50228/: dial tcp 127.0.0.1:50228: connection refused
[LOG] 84.32043 ERROR juju worker: exited "api": websocket.Dial wss://localhost:50228/: dial tcp 127.0.0.1:50228: connection refused
[LOG] 84.32044 INFO juju worker: restarting "api" in 50ms
[LOG] 84.32682 INFO juju writing charm to storage [1418 bytes]
[LOG] 84.32689 INFO juju adding charm to state
[LOG] 84.33818 INFO juju.state connection established
[LOG] 84.34469 INFO juju worker: start "instancepoller"
[LOG] 84.34485 INFO juju worker: start "apiserver"
[LOG] 84.34514 INFO juju.state.apiserver listening on "[::]:50228"
[LOG] 84.36722 INFO juju worker: start "cleaner"
[LOG] 84.36767 INFO juju worker: start "resumer"
[LOG] 84.36790 INFO juju worker: start "minunitsworker"
[LOG] 84.36993 INFO juju.worker.instanceupdater instance poller received inital environment configuration
[LOG] 84.37125 WARNING juju.worker.instanceupdater cannot get instance info for instance "ardbeg-0": no instances found
[LOG] 84.38430 INFO juju worker: start "api"
[LOG] 84.38468 INFO juju state/api: dialing "wss://localhost:50228/"
[LOG] 84.41501 INFO juju.state.apiserver [F] API connection from 127.0.0.1:42181
[LOG] 84.41557 INFO juju state/api: connection established
[LOG] 84.41576 DEBUG juju.state.apiserver <- [F] <unknown> {"RequestId":1,"Type":"Admin","Request":"Login","Params":{"AuthTag":"machine-0","Password":"machine-password-1234567890","Nonce":"user-admin:bootstrap"}}
[LOG] 84.41986 DEBUG juju.state.apiserver -> [F] machine-0 4.033089ms {"RequestId":1,"Response":{}} Admin[""].Login
[LOG] 84.42037 DEBUG juju.agent writing configuration file
[LOG] 84.42144 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":2,"Type":"Agent","Request":"GetEntities","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 84.42189 DEBUG juju.state.apiserver -> [F] machine-0 454.982us {"RequestId":2,"Response":{"Entities":[{"Life":"alive","Jobs":["JobManageEnviron"],"ContainerType":"","Error":null}]}} Agent[""].GetEntities
[LOG] 84.42211 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":4,"Type":"Agent","Request":"SetPasswords","Params":{"Changes":[{"Tag":"machine-0","Password":"yxD8dRdjr2CbFZdQsrszOp2+"}]}}
[LOG] 84.42310 INFO juju setting mongo password for "machine-0"
[LOG] 84.43642 INFO juju setting password for "machine-0"
[LOG] 84.43650 DEBUG juju.state.apiserver -> [F] machine-0 14.368916ms {"RequestId":4,"Response":{"Results":[{"Error":null}]}} Agent[""].SetPasswords
[LOG] 84.43675 INFO juju worker: start "machiner"
[LOG] 84.43690 INFO juju worker: start "upgrader"
[LOG] 84.43693 INFO juju worker: start "logger"
[LOG] 84.43706 DEBUG juju.worker.logger initial log config: "<root>=WARNING;juju=DEBUG;unit=DEBUG"
[LOG] 84.43723 DEBUG juju.worker.logger logger setup
[LOG] 84.43739 WARNING juju.cmd.jujud determining kvm support: exec: "kvm-ok": executable file not found in $PATH
no kvm containers possible
[LOG] 84.43747 INFO juju worker: start "authenticationworker"
[LOG] 84.43766 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":5,"Type":"Machiner","Request":"Life","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 84.43782 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":6,"Type":"Upgrader","Request":"SetTools","Params":{"AgentTools":[{"Tag":"machine-0","Tools":{"Version":"1.17.1-precise-amd64"}}]}}
[LOG] 84.43791 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":7,"Type":"Logger","Request":"LoggingConfig","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 84.43800 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":8,"Type":"Provisioner","Request":"Life","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 84.43808 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":9,"Type":"KeyUpdater","Request":"AuthorisedKeys","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 84.44028 DEBUG juju.state.apiserver -> [F] machine-0 2.574699ms {"RequestId":5,"Response":{"Results":[{"Life":"alive","Error":null}]}} Machiner[""].Life
[LOG] 84.44232 DEBUG juju.state.apiserver -> [F] machine-0 4.358726ms {"RequestId":7,"Response":{"Results":[{"Error":null,"Result":"\u003croot\u003e=WARNING;juju=DEBUG;unit=DEBUG"}]}} Logger[""].LoggingConfig
[LOG] 84.44269 DEBUG juju.state.apiserver -> [F] machine-0 4.667868ms {"RequestId":8,"Response":{"Results":[{"Life":"alive","Error":null}]}} Provisioner[""].Life
[LOG] 84.44439 INFO juju.worker.machiner setting addresses for machine-0 to ["10.55.32.52" "fe80::f816:3eff:fef7:1c4e"]
[LOG] 84.44471 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":10,"Type":"Machiner","Request":"SetMachineAddresses","Params":{"MachineAddresses":[{"Tag":"machine-0","Addresses":[{"Value":"10.55.32.52","Type":"ipv4","NetworkName":"","NetworkScope":""},{"Value":"fe80::f816:3eff:fef7:1c4e","Type":"ipv6","NetworkName":"","NetworkScope":""}]}]}}
[LOG] 84.44477 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":11,"Type":"Logger","Request":"WatchLoggingConfig","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 84.44484 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":12,"Type":"Provisioner","Request":"SetSupportedContainers","Params":{"Params":[{"MachineTag":"machine-0","ContainerTypes":["lxc"]}]}}
[LOG] 84.45512 DEBUG juju.state.apiserver -> [F] machine-0 16.740528ms {"RequestId":9,"Response":{"Results":[{"Error":null,"Result":["my-keys"]}]}} KeyUpdater[""].AuthorisedKeys
[LOG] 84.45617 DEBUG juju.utils.ssh reading authorised keys file /tmp/gocheck-2202916659517317514/56/.ssh/authorized_keys
[LOG] 84.45627 WARNING juju.utils.ssh invalid Juju ssh key my-keys: malformed line: "my-keys"
[LOG] 84.45631 DEBUG juju.utils.ssh reading authorised keys file /tmp/gocheck-2202916659517317514/56/.ssh/authorized_keys
[LOG] 84.45636 ERROR juju.worker.authenticationworker adding current Juju keys to ssh authorised keys: generating key fingerprint: malformed line: "my-keys"
[LOG] 84.45667 ERROR juju worker: exited "authenticationworker": adding current Juju keys to ssh authorised keys: generating key fingerprint: malformed line: "my-keys"
[LOG] 84.45671 INFO juju worker: restarting "authenticationworker" in 50ms
[LOG] 84.45892 DEBUG juju.state.apiserver -> [F] machine-0 13.974357ms {"RequestId":11,"Response":{"Results":[{"NotifyWatcherId":"2","Error":null}]}} Logger[""].WatchLoggingConfig
[LOG] 84.46076 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":14,"Type":"Logger","Request":"LoggingConfig","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 84.46088 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":15,"Type":"NotifyWatcher","Id":"2","Request":"Next","Params":{}}
[LOG] 84.46526 DEBUG juju.state.apiserver -> [F] machine-0 4.48048ms {"RequestId":14,"Response":{"Results":[{"Error":null,"Result":"\u003croot\u003e=WARNING;juju=DEBUG;unit=DEBUG"}]}} Logger[""].LoggingConfig
[LOG] 84.46941 DEBUG juju.state.apiserver -> [F] machine-0 31.625151ms {"RequestId":6,"Response":{"Results":[{"Error":null}]}} Upgrader[""].SetTools
[LOG] 84.47013 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":16,"Type":"Upgrader","Request":"WatchAPIVersion","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 84.47125 DEBUG juju.state.apiserver -> [F] machine-0 1.130558ms {"RequestId":16,"Response":{"Results":[{"NotifyWatcherId":"3","Error":null}]}} Upgrader[""].WatchAPIVersion
[LOG] 84.47171 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":17,"Type":"Upgrader","Request":"DesiredVersion","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 84.47184 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":18,"Type":"NotifyWatcher","Id":"3","Request":"Next","Params":{}}
[LOG] 84.47716 DEBUG juju.state.apiserver -> [F] machine-0 5.175685ms {"RequestId":17,"Response":{"Results":[{"Version":"1.17.1","Error":null}]}} Upgrader[""].DesiredVersion
[LOG] 84.48091 INFO juju.worker.upgrader desired tool version: 1.17.1
[LOG] 84.48242 DEBUG juju.state.apiserver -> [F] machine-0 37.726939ms {"RequestId":10,"Response":{"Results":[{"Error":null}]}} Machiner[""].SetMachineAddresses
[LOG] 84.48280 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":19,"Type":"Machiner","Request":"SetStatus","Params":{"Entities":[{"Tag":"machine-0","Status":"started","Info":"","Data":null}]}}
discarding unknown event dummy.OpPutFile{Env:"dummyenv", FileName:"local_3a_quantal_2f_dummy-1"}
[LOG] 84.48907 DEBUG juju.state.apiserver -> [F] machine-0 44.170212ms {"RequestId":12,"Response":{"Results":[{"Error":null}]}} Provisioner[""].SetSupportedContainers
[LOG] 84.48985 INFO juju worker: start "0-container-watcher"
[LOG] 84.48989 INFO juju worker: start "environ-provisioner"
[LOG] 84.49028 INFO juju worker: start "firewaller"
[LOG] 84.49040 INFO juju worker: start "charm-revision-updater"
[LOG] 84.49064 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":20,"Type":"Provisioner","Request":"WatchContainers","Params":{"Params":[{"MachineTag":"machine-0","ContainerType":""}]}}
[LOG] 84.49075 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":21,"Type":"Provisioner","Request":"WatchForEnvironConfigChanges","Params":{}}
[LOG] 84.49084 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":22,"Type":"Firewaller","Request":"WatchForEnvironConfigChanges","Params":{}}
[LOG] 84.49093 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":23,"Type":"CharmRevisionUpdater","Request":"UpdateLatestRevisions","Params":{}}
[LOG] 84.49299 DEBUG juju.state.apiserver -> [F] machine-0 2.254142ms {"RequestId":21,"Response":{"NotifyWatcherId":"4","Error":null}} Provisioner[""].WatchForEnvironConfigChanges
[LOG] 84.49309 DEBUG juju.state.apiserver -> [F] machine-0 2.265951ms {"RequestId":22,"Response":{"NotifyWatcherId":"5","Error":null}} Firewaller[""].WatchForEnvironConfigChanges
[LOG] 84.49635 INFO juju.state.apiserver.charmrevisionupdater retrieving revision information for 0 charms
[LOG] 84.49691 DEBUG juju.state.apiserver -> [F] machine-0 6.223151ms {"RequestId":20,"Response":{"Results":[{"StringsWatcherId":"6","Changes":[],"Error":null}]}} Provisioner[""].WatchContainers
[LOG] 84.49848 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":24,"Type":"Firewaller","Request":"WatchEnvironMachines","Params":{}}
[LOG] 84.49859 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":25,"Type":"Provisioner","Request":"EnvironConfig","Params":{}}
[LOG] 84.49878 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":26,"Type":"NotifyWatcher","Id":"4","Request":"Next","Params":{}}
[LOG] 84.49887 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":27,"Type":"NotifyWatcher","Id":"5","Request":"Next","Params":{}}
[LOG] 84.49986 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":28,"Type":"StringsWatcher","Id":"6","Request":"Next","Params":{}}
[LOG] 84.50208 DEBUG juju.state.apiserver -> [F] machine-0 3.208881ms {"RequestId":25,"Response":{"Error":null,"Config":{"admin-secret":"","agent-version":"1.17.1","api-port":4321,"authorized-keys":"my-keys","broken":"","ca-cert":"-----BEGIN CERTIFICATE-----\nMIIB4jCCAY6gAwIBAgIBADALBgkqhkiG9w0BAQUwSjENMAsGA1UEChMEanVqdTE5\nMDcGA1UEAwwwanVqdS1nZW5lcmF0ZWQgQ0EgZm9yIGVudmlyb25tZW50ICJqdWp1\nIHRlc3RpbmciMB4XDTE0MDEyNDIwNDEyN1oXDTI0MDEyNDIwNDYyN1owSjENMAsG\nA1UEChMEanVqdTE5MDcGA1UEAwwwanVqdS1nZW5lcmF0ZWQgQ0EgZm9yIGVudmly\nb25tZW50ICJqdWp1IHRlc3RpbmciMFowCwYJKoZIhvcNAQEBA0sAMEgCQQC4qR/z\nJQo4xS84XV07iQYbycC27iWdPNgFXv9ouoTu9Y5FV2bPuE0uDx3n/AKQAz+eqVNv\nXI6WrJSA7IKSd7rPAgMBAAGjYzBhMA4GA1UdDwEB/wQEAwIApDAPBgNVHRMBAf8E\nBTADAQH/MB0GA1UdDgQWBBSu0Kjlvf3RVUeFNukqfwUog21FjDAfBgNVHSMEGDAW\ngBSu0Kjlvf3RVUeFNukqfwUog21FjDALBgkqhkiG9w0BAQUDQQBd6CyFSHIhM9er\nvA9qSb8P9yjqMzXnqRxI1ETljgXzNTLLMuZYf3Tj93lLdZm7zZDgrdlqoD5JiRD0\nONmStaWi\n-----END CERTIFICATE-----\n","ca-private-key":"","charm-store-auth":"","default-series":"precise","development":false,"firewall-mode":"instance","image-metadata-url":"","logging-config":"\u003croot\u003e=WARNING;juju=DEBUG;unit=DEBUG","name":"dummyenv","secret":"pork","ssl-hostname-verification":true,"state-id":"8","state-port":1234,"state-server":true,"syslog-port":2345,"tools-metadata-url":"","tools-url":"","type":"dummy"}}} Provisioner[""].EnvironConfig
[LOG] 84.50764 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":29,"Type":"Provisioner","Request":"StateAddresses","Params":{}}
[LOG] 84.50786 INFO juju worker: start "authenticationworker"
[LOG] 84.50807 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":30,"Type":"KeyUpdater","Request":"AuthorisedKeys","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 84.50839 DEBUG juju.state.apiserver -> [F] machine-0 9.938505ms {"RequestId":24,"Response":{"StringsWatcherId":"7","Changes":["1","0"],"Error":null}} Firewaller[""].WatchEnvironMachines
[LOG] 84.51044 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":31,"Type":"Firewaller","Request":"EnvironConfig","Params":{}}
[LOG] 84.51055 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":32,"Type":"StringsWatcher","Id":"7","Request":"Next","Params":{}}
[LOG] 84.51312 DEBUG juju.state.apiserver -> [F] machine-0 5.494413ms {"RequestId":29,"Response":{"Error":null,"Result":["0.1.2.3:1234"]}} Provisioner[""].StateAddresses
[LOG] 84.51359 DEBUG juju.state.apiserver -> [F] machine-0 5.496771ms {"RequestId":30,"Response":{"Results":[{"Error":null,"Result":["my-keys"]}]}} KeyUpdater[""].AuthorisedKeys
[LOG] 84.51536 DEBUG juju.state.apiserver -> [F] machine-0 4.636056ms {"RequestId":31,"Response":{"Error":null,"Config":{"admin-secret":"","agent-version":"1.17.1","api-port":4321,"authorized-keys":"my-keys","broken":"","ca-cert":"-----BEGIN CERTIFICATE-----\nMIIB4jCCAY6gAwIBAgIBADALBgkqhkiG9w0BAQUwSjENMAsGA1UEChMEanVqdTE5\nMDcGA1UEAwwwanVqdS1nZW5lcmF0ZWQgQ0EgZm9yIGVudmlyb25tZW50ICJqdWp1\nIHRlc3RpbmciMB4XDTE0MDEyNDIwNDEyN1oXDTI0MDEyNDIwNDYyN1owSjENMAsG\nA1UEChMEanVqdTE5MDcGA1UEAwwwanVqdS1nZW5lcmF0ZWQgQ0EgZm9yIGVudmly\nb25tZW50ICJqdWp1IHRlc3RpbmciMFowCwYJKoZIhvcNAQEBA0sAMEgCQQC4qR/z\nJQo4xS84XV07iQYbycC27iWdPNgFXv9ouoTu9Y5FV2bPuE0uDx3n/AKQAz+eqVNv\nXI6WrJSA7IKSd7rPAgMBAAGjYzBhMA4GA1UdDwEB/wQEAwIApDAPBgNVHRMBAf8E\nBTADAQH/MB0GA1UdDgQWBBSu0Kjlvf3RVUeFNukqfwUog21FjDAfBgNVHSMEGDAW\ngBSu0Kjlvf3RVUeFNukqfwUog21FjDALBgkqhkiG9w0BAQUDQQBd6CyFSHIhM9er\nvA9qSb8P9yjqMzXnqRxI1ETljgXzNTLLMuZYf3Tj93lLdZm7zZDgrdlqoD5JiRD0\nONmStaWi\n-----END CERTIFICATE-----\n","ca-private-key":"","charm-store-auth":"","default-series":"precise","development":false,"firewall-mode":"instance","image-metadata-url":"","logging-config":"\u003croot\u003e=WARNING;juju=DEBUG;unit=DEBUG","name":"dummyenv","secret":"pork","ssl-hostname-verification":true,"state-id":"8","state-port":1234,"state-server":true,"syslog-port":2345,"tools-metadata-url":"","tools-url":"","type":"dummy"}}} Firewaller[""].EnvironConfig
[LOG] 84.51659 DEBUG juju.utils.ssh reading authorised keys file /tmp/gocheck-2202916659517317514/56/.ssh/authorized_keys
[LOG] 84.51664 WARNING juju.utils.ssh invalid Juju ssh key my-keys: malformed line: "my-keys"
[LOG] 84.51668 DEBUG juju.utils.ssh reading authorised keys file /tmp/gocheck-2202916659517317514/56/.ssh/authorized_keys
[LOG] 84.51671 ERROR juju.worker.authenticationworker adding current Juju keys to ssh authorised keys: generating key fingerprint: malformed line: "my-keys"
[LOG] 84.51854 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":33,"Type":"Provisioner","Request":"APIAddresses","Params":{}}
[LOG] 84.51861 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":34,"Type":"Firewaller","Request":"Life","Params":{"Entities":[{"Tag":"machine-1"}]}}
[LOG] 84.51954 DEBUG juju.state.apiserver -> [F] machine-0 36.755434ms {"RequestId":19,"Response":{"Results":[{"Error":null}]}} Machiner[""].SetStatus
[LOG] 84.51987 DEBUG juju.state.apiserver -> [F] machine-0 1.259849ms {"RequestId":34,"Response":{"Results":[{"Life":"alive","Error":null}]}} Firewaller[""].Life
[LOG] 84.52017 ERROR juju worker: exited "authenticationworker": adding current Juju keys to ssh authorised keys: generating key fingerprint: malformed line: "my-keys"
[LOG] 84.52019 INFO juju.worker.machiner "machine-0" started
[LOG] 84.52033 INFO juju worker: restarting "authenticationworker" in 50ms
[LOG] 84.52089 DEBUG juju.state.apiserver -> [F] machine-0 2.353709ms {"RequestId":33,"Response":{"Error":null,"Result":["0.1.2.3:4321"]}} Provisioner[""].APIAddresses
[LOG] 84.52109 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":36,"Type":"Machiner","Request":"Watch","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 84.52116 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":37,"Type":"Firewaller","Request":"Life","Params":{"Entities":[{"Tag":"machine-1"}]}}
[LOG] 84.52129 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":38,"Type":"Provisioner","Request":"CACert","Params":{}}
[LOG] 84.52176 DEBUG juju.state.apiserver -> [F] machine-0 421.35us {"RequestId":38,"Response":{"Result":"LS0tLS1CRUdJTiBDRVJUSUZJQ0FURS0tLS0tCk1JSUI0akNDQVk2Z0F3SUJBZ0lCQURBTEJna3Foa2lHOXcwQkFRVXdTakVOTUFzR0ExVUVDaE1FYW5WcWRURTUKTURjR0ExVUVBd3d3YW5WcWRTMW5aVzVsY21GMFpXUWdRMEVnWm05eUlHVnVkbWx5YjI1dFpXNTBJQ0pxZFdwMQpJSFJsYzNScGJtY2lNQjRYRFRFME1ERXlOREl3TkRFeU4xb1hEVEkwTURFeU5ESXdORFl5TjFvd1NqRU5NQXNHCkExVUVDaE1FYW5WcWRURTVNRGNHQTFVRUF3d3dhblZxZFMxblpXNWxjbUYwWldRZ1EwRWdabTl5SUdWdWRtbHkKYjI1dFpXNTBJQ0pxZFdwMUlIUmxjM1JwYm1jaU1Gb3dDd1lKS29aSWh2Y05BUUVCQTBzQU1FZ0NRUUM0cVIvegpKUW80eFM4NFhWMDdpUVlieWNDMjdpV2RQTmdGWHY5b3VvVHU5WTVGVjJiUHVFMHVEeDNuL0FLUUF6K2VxVk52ClhJNldySlNBN0lLU2Q3clBBZ01CQUFHall6QmhNQTRHQTFVZER3RUIvd1FFQXdJQXBEQVBCZ05WSFJNQkFmOEUKQlRBREFRSC9NQjBHQTFVZERnUVdCQlN1MEtqbHZmM1JWVWVGTnVrcWZ3VW9nMjFGakRBZkJnTlZIU01FR0RBVwpnQlN1MEtqbHZmM1JWVWVGTnVrcWZ3VW9nMjFGakRBTEJna3Foa2lHOXcwQkFRVURRUUJkNkN5RlNISWhNOWVyCnZBOXFTYjhQOXlqcU16WG5xUnhJMUVUbGpnWHpOVExMTXVaWWYzVGo5M2xMZFptN3paRGdyZGxxb0Q1SmlSRDAKT05tU3RhV2kKLS0tLS1FTkQgQ0VSVElGSUNBVEUtLS0tLQo="}} Provisioner[""].CACert
[LOG] 84.52207 DEBUG juju.state.apiserver -> [F] machine-0 31.132867ms {"RequestId":23,"Response":{"Error":null}} CharmRevisionUpdater[""].UpdateLatestRevisions
[LOG] 84.52258 DEBUG juju.state.apiserver -> [F] machine-0 1.421461ms {"RequestId":37,"Response":{"Results":[{"Life":"alive","Error":null}]}} Firewaller[""].Life
[LOG] 84.52328 DEBUG juju.state.apiserver -> [F] machine-0 2.177731ms {"RequestId":36,"Response":{"Results":[{"NotifyWatcherId":"8","Error":null}]}} Machiner[""].Watch
[LOG] 84.52347 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":39,"Type":"Provisioner","Request":"WatchEnvironMachines","Params":{}}
[LOG] 84.52408 DEBUG juju.state.apiserver -> [F] machine-0 600.804us {"RequestId":39,"Response":{"StringsWatcherId":"9","Changes":["1","0"],"Error":null}} Provisioner[""].WatchEnvironMachines
[LOG] 84.52420 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":40,"Type":"Firewaller","Request":"WatchUnits","Params":{"Entities":[{"Tag":"machine-1"}]}}
[LOG] 84.52426 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":41,"Type":"Machiner","Request":"Life","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 84.52434 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":42,"Type":"NotifyWatcher","Id":"8","Request":"Next","Params":{}}
[LOG] 84.52498 DEBUG juju.state.apiserver -> [F] machine-0 701.45us {"RequestId":41,"Response":{"Results":[{"Life":"alive","Error":null}]}} Machiner[""].Life
[LOG] 84.52542 INFO juju.provisioner Starting up provisioner task machine-0
[LOG] 84.52565 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":43,"Type":"Provisioner","Request":"Life","Params":{"Entities":[{"Tag":"machine-1"}]}}
[LOG] 84.52573 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":44,"Type":"StringsWatcher","Id":"9","Request":"Next","Params":{}}
[LOG] 84.52621 DEBUG juju.state.apiserver -> [F] machine-0 554.622us {"RequestId":43,"Response":{"Results":[{"Life":"alive","Error":null}]}} Provisioner[""].Life
[LOG] 84.52664 DEBUG juju.state.apiserver -> [F] machine-0 2.437789ms {"RequestId":40,"Response":{"Results":[{"StringsWatcherId":"10","Changes":["test-service/0"],"Error":null}]}} Firewaller[""].WatchUnits
[LOG] 84.52676 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":45,"Type":"Provisioner","Request":"Life","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 84.52710 DEBUG juju.state.apiserver -> [F] machine-0 338.272us {"RequestId":45,"Response":{"Results":[{"Life":"alive","Error":null}]}} Provisioner[""].Life
[LOG] 84.52767 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":46,"Type":"Provisioner","Request":"InstanceId","Params":{"Entities":[{"Tag":"machine-1"}]}}
[LOG] 84.52776 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":47,"Type":"Firewaller","Request":"Life","Params":{"Entities":[{"Tag":"unit-test-service-0"}]}}
[LOG] 84.52786 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":48,"Type":"StringsWatcher","Id":"10","Request":"Next","Params":{}}
[LOG] 84.52852 DEBUG juju.state.apiserver -> [F] machine-0 753.445us {"RequestId":47,"Response":{"Results":[{"Life":"alive","Error":null}]}} Firewaller[""].Life
[LOG] 84.52870 DEBUG juju.state.apiserver -> [F] machine-0 1.042329ms {"RequestId":46,"Response":{"Results":[{"Error":{"Message":"machine 1 is not provisioned","Code":"not provisioned"},"Result":""}]}} Provisioner[""].InstanceId
[LOG] 84.52892 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":49,"Type":"Firewaller","Request":"GetAssignedMachine","Params":{"Entities":[{"Tag":"unit-test-service-0"}]}}
[LOG] 84.52898 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":50,"Type":"Provisioner","Request":"Status","Params":{"Entities":[{"Tag":"machine-1"}]}}
[LOG] 84.52948 DEBUG juju.state.apiserver -> [F] machine-0 551.643us {"RequestId":49,"Response":{"Results":[{"Error":null,"Result":"machine-1"}]}} Firewaller[""].GetAssignedMachine
[LOG] 84.52985 DEBUG juju.state.apiserver -> [F] machine-0 816.065us {"RequestId":50,"Response":{"Results":[{"Error":null,"Status":"pending","Info":""}]}} Provisioner[""].Status
[LOG] 84.53008 INFO juju.provisioner found machine "1" pending provisioning
[LOG] 84.53020 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":51,"Type":"Firewaller","Request":"Life","Params":{"Entities":[{"Tag":"service-test-service"}]}}
[LOG] 84.53027 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":52,"Type":"Provisioner","Request":"InstanceId","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 84.53074 DEBUG juju.state.apiserver -> [F] machine-0 555.53us {"RequestId":51,"Response":{"Results":[{"Life":"alive","Error":null}]}} Firewaller[""].Life
[LOG] 84.53090 DEBUG juju.state.apiserver -> [F] machine-0 630.157us {"RequestId":52,"Response":{"Results":[{"Error":null,"Result":"ardbeg-0"}]}} Provisioner[""].InstanceId
[LOG] 84.53111 INFO juju.provisioner machine 0 already started as instance "ardbeg-0"
[LOG] 84.53122 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":53,"Type":"Firewaller","Request":"OpenedPorts","Params":{"Entities":[{"Tag":"unit-test-service-0"}]}}
[LOG] 84.53128 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":54,"Type":"Provisioner","Request":"InstanceId","Params":{"Entities":[{"Tag":"machine-1"}]}}
[LOG] 84.53173 DEBUG juju.state.apiserver -> [F] machine-0 494.259us {"RequestId":53,"Response":{"Results":[{"Error":null,"Ports":[]}]}} Firewaller[""].OpenedPorts
[LOG] 84.53209 DEBUG juju.state.apiserver -> [F] machine-0 797.818us {"RequestId":54,"Response":{"Results":[{"Error":{"Message":"machine 1 is not provisioned","Code":"not provisioned"},"Result":""}]}} Provisioner[""].InstanceId
[LOG] 84.53239 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":55,"Type":"Firewaller","Request":"GetExposed","Params":{"Entities":[{"Tag":"service-test-service"}]}}
[LOG] 84.53245 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":56,"Type":"Provisioner","Request":"InstanceId","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 84.53293 DEBUG juju.state.apiserver -> [F] machine-0 500.183us {"RequestId":55,"Response":{"Results":[{"Error":null,"Result":true}]}} Firewaller[""].GetExposed
[LOG] 84.53311 DEBUG juju.state.apiserver -> [F] machine-0 653.962us {"RequestId":56,"Response":{"Results":[{"Error":null,"Result":"ardbeg-0"}]}} Provisioner[""].InstanceId
[LOG] 84.53331 DEBUG juju worker/firewaller: started watching unit test-service/0
[LOG] 84.53334 DEBUG juju worker/firewaller: started watching "machine-1"
[LOG] 84.53360 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":57,"Type":"Firewaller","Request":"Life","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 84.53369 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":58,"Type":"Provisioner","Request":"Constraints","Params":{"Entities":[{"Tag":"machine-1"}]}}
[LOG] 84.53377 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":59,"Type":"Firewaller","Request":"Watch","Params":{"Entities":[{"Tag":"service-test-service"}]}}
[LOG] 84.53385 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":60,"Type":"Firewaller","Request":"Watch","Params":{"Entities":[{"Tag":"unit-test-service-0"}]}}
[LOG] 84.53480 DEBUG juju.state.apiserver -> [F] machine-0 1.185628ms {"RequestId":57,"Response":{"Results":[{"Life":"alive","Error":null}]}} Firewaller[""].Life
[LOG] 84.53553 DEBUG juju.state.apiserver -> [F] machine-0 1.771301ms {"RequestId":58,"Response":{"Results":[{"Error":null,"Constraints":{}}]}} Provisioner[""].Constraints
[LOG] 84.53564 DEBUG juju.state.apiserver -> [F] machine-0 1.875796ms {"RequestId":59,"Response":{"Results":[{"NotifyWatcherId":"11","Error":null}]}} Firewaller[""].Watch
[LOG] 84.53570 DEBUG juju.state.apiserver -> [F] machine-0 1.860134ms {"RequestId":60,"Response":{"Results":[{"NotifyWatcherId":"12","Error":null}]}} Firewaller[""].Watch
[LOG] 84.53640 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":61,"Type":"Firewaller","Request":"Life","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 84.53649 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":62,"Type":"Provisioner","Request":"Series","Params":{"Entities":[{"Tag":"machine-1"}]}}
[LOG] 84.53657 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":63,"Type":"Firewaller","Request":"Life","Params":{"Entities":[{"Tag":"service-test-service"}]}}
[LOG] 84.53664 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":64,"Type":"Firewaller","Request":"Life","Params":{"Entities":[{"Tag":"unit-test-service-0"}]}}
[LOG] 84.53672 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":65,"Type":"NotifyWatcher","Id":"11","Request":"Next","Params":{}}
[LOG] 84.53679 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":66,"Type":"NotifyWatcher","Id":"12","Request":"Next","Params":{}}
[LOG] 84.53773 DEBUG juju.state.apiserver -> [F] machine-0 1.328785ms {"RequestId":61,"Response":{"Results":[{"Life":"alive","Error":null}]}} Firewaller[""].Life
[LOG] 84.53784 DEBUG juju.state.apiserver -> [F] machine-0 1.361126ms {"RequestId":62,"Response":{"Results":[{"Error":null,"Result":"quantal"}]}} Provisioner[""].Series
[LOG] 84.53795 DEBUG juju.state.apiserver -> [F] machine-0 1.392327ms {"RequestId":63,"Response":{"Results":[{"Life":"alive","Error":null}]}} Firewaller[""].Life
[LOG] 84.53805 DEBUG juju.state.apiserver -> [F] machine-0 1.419787ms {"RequestId":64,"Response":{"Results":[{"Life":"alive","Error":null}]}} Firewaller[""].Life
[LOG] 84.53834 INFO juju.environs.tools reading tools with major.minor version 1.17
[LOG] 84.53835 INFO juju.environs.tools filtering tools by version: 1.17.1
[LOG] 84.53836 INFO juju.environs.tools filtering tools by series: quantal
[LOG] 84.53839 DEBUG juju.environs.tools no architecture specified when finding tools, looking for any
[LOG] 84.53846 DEBUG juju.environs.simplestreams fetchData failed for "http://127.0.0.1:53656/dummyenv/private/tools/streams/v1/index.sjson": file "tools/streams/v1/index.sjson" not found not found
[LOG] 84.53848 DEBUG juju.environs.simplestreams cannot load index "http://127.0.0.1:53656/dummyenv/private/tools/streams/v1/index.sjson": invalid URL "http://127.0.0.1:53656/dummyenv/private/tools/streams/v1/index.sjson" not found
[LOG] 84.53858 DEBUG juju.environs.simplestreams fetchData failed for "http://127.0.0.1:53656/dummyenv/private/tools/streams/v1/mirrors.json": file "tools/streams/v1/mirrors.json" not found not found
[LOG] 84.53860 DEBUG juju.environs.simplestreams no mirror index file found
[LOG] 84.53863 DEBUG juju.environs.simplestreams no mirror information available for { }: mirror data for "com.ubuntu.juju:released:tools" not found
[LOG] 84.53865 DEBUG juju.environs.simplestreams read metadata index at "http://127.0.0.1:53656/dummyenv/private/tools/streams/v1/index.json"
[LOG] 84.53870 DEBUG juju.environs.simplestreams candidate matches for products ["com.ubuntu.juju:12.10:amd64" "com.ubuntu.juju:12.10:i386" "com.ubuntu.juju:12.10:arm"] are [{Fri, 24 Jan 2014 20:46:45 +0000 products:1.0 content-download  [] streams/v1/com.ubuntu.juju:released:tools.json [com.ubuntu.juju:12.04:amd64 com.ubuntu.juju:12.10:amd64]}]
[LOG] 84.53872 DEBUG juju.environs.simplestreams finding products at path "streams/v1/com.ubuntu.juju:released:tools.json"
[LOG] 84.53904 DEBUG juju.environs.simplestreams metadata: &{map[com.ubuntu.juju:12.04:amd64:{ 1.17.1 amd64   map[20140124:0xc200b6cba0]} com.ubuntu.juju:12.10:amd64:{ 1.17.1 amd64   map[20140124:0xc200b6ccc0]}] map[] Fri, 24 Jan 2014 20:46:45 +0000 products:1.0 com.ubuntu.juju:released:tools}
[LOG] 84.53932 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":67,"Type":"Firewaller","Request":"WatchUnits","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 84.53939 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":68,"Type":"Provisioner","Request":"SetPasswords","Params":{"Changes":[{"Tag":"machine-1","Password":"9awlgM2iCteW5avVhg6Jgv7F"}]}}
[LOG] 84.53944 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":69,"Type":"Firewaller","Request":"GetExposed","Params":{"Entities":[{"Tag":"service-test-service"}]}}
[LOG] 84.53950 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":70,"Type":"Firewaller","Request":"OpenedPorts","Params":{"Entities":[{"Tag":"unit-test-service-0"}]}}
[LOG] 84.54077 DEBUG juju.state.apiserver -> [F] machine-0 1.305502ms {"RequestId":69,"Response":{"Results":[{"Error":null,"Result":true}]}} Firewaller[""].GetExposed
[LOG] 84.54088 DEBUG juju.state.apiserver -> [F] machine-0 1.383782ms {"RequestId":70,"Response":{"Results":[{"Error":null,"Ports":[]}]}} Firewaller[""].OpenedPorts
[LOG] 84.54224 DEBUG juju.state.apiserver -> [F] machine-0 2.896002ms {"RequestId":67,"Response":{"Results":[{"StringsWatcherId":"13","Changes":null,"Error":null}]}} Firewaller[""].WatchUnits
[LOG] 84.54239 DEBUG juju worker/firewaller: started watching "machine-0"
[LOG] 84.54318 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":71,"Type":"Firewaller","Request":"Life","Params":{"Entities":[{"Tag":"machine-1"}]}}
[LOG] 84.54324 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":72,"Type":"StringsWatcher","Id":"13","Request":"Next","Params":{}}
[LOG] 84.54387 DEBUG juju.state.apiserver -> [F] machine-0 665.951us {"RequestId":71,"Response":{"Results":[{"Life":"alive","Error":null}]}} Firewaller[""].Life
[LOG] 84.54476 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":73,"Type":"Firewaller","Request":"InstanceId","Params":{"Entities":[{"Tag":"machine-1"}]}}
[LOG] 84.54563 DEBUG juju.state.apiserver -> [F] machine-0 861.512us {"RequestId":73,"Response":{"Results":[{"Error":{"Message":"machine 1 is not provisioned","Code":"not provisioned"},"Result":""}]}} Firewaller[""].InstanceId
[LOG] 84.54583 INFO juju setting password for "machine-1"
[LOG] 84.54590 DEBUG juju.state.apiserver -> [F] machine-0 6.514156ms {"RequestId":68,"Response":{"Results":[{"Error":null}]}} Provisioner[""].SetPasswords
[LOG] 84.54602 INFO juju.provider.dummy dummy startinstance, machine 1
[LOG] 84.54605 INFO juju.provider.dummy would pick tools from 1.17.1-quantal-amd64
waiting for unit "test-service/0" to be provisioned
[LOG] 84.54644 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":74,"Type":"NotifyWatcher","Id":"5","Request":"Stop","Params":{}}
[LOG] 84.54656 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":75,"Type":"Provisioner","Request":"SetProvisioned","Params":{"Machines":[{"Tag":"machine-1","InstanceId":"dummyenv-0","Nonce":"machine-0:9b66d73b-d730-4af7-840e-bd306d0db90c","Characteristics":{"Arch":"amd64","Mem":1024,"RootDisk":8192,"CpuCores":1,"CpuPower":null,"Tags":null}}]}}
[LOG] 84.54680 DEBUG juju.state.apiserver -> [F] machine-0 47.916406ms {"RequestId":27,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":{}} NotifyWatcher["5"].Next
[LOG] 84.54686 DEBUG juju.state.apiserver -> [F] machine-0 442.132us {"RequestId":74,"Response":{}} NotifyWatcher["5"].Stop
[LOG] 84.54786 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":76,"Type":"StringsWatcher","Id":"7","Request":"Stop","Params":{}}
[LOG] 84.54816 DEBUG juju.state.apiserver -> [F] machine-0 37.60875ms {"RequestId":32,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":{}} StringsWatcher["7"].Next
[LOG] 84.54822 DEBUG juju.state.apiserver -> [F] machine-0 373.974us {"RequestId":76,"Response":{}} StringsWatcher["7"].Stop
[LOG] 84.54897 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":77,"Type":"NotifyWatcher","Id":"12","Request":"Stop","Params":{}}
[LOG] 84.54925 DEBUG juju.state.apiserver -> [F] machine-0 12.453249ms {"RequestId":66,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":{}} NotifyWatcher["12"].Next
[LOG] 84.54931 DEBUG juju.state.apiserver -> [F] machine-0 363.493us {"RequestId":77,"Response":{}} NotifyWatcher["12"].Stop
[LOG] 84.55003 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":78,"Type":"NotifyWatcher","Id":"11","Request":"Stop","Params":{}}
[LOG] 84.55010 DEBUG juju.state.apiserver -> [F] machine-0 13.387177ms {"RequestId":65,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":{}} NotifyWatcher["11"].Next
[LOG] 84.55016 DEBUG juju.state.apiserver -> [F] machine-0 150.285us {"RequestId":78,"Response":{}} NotifyWatcher["11"].Stop
[LOG] 84.55113 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":79,"Type":"StringsWatcher","Id":"10","Request":"Stop","Params":{}}
[LOG] 84.55121 DEBUG juju.state.apiserver -> [F] machine-0 23.38235ms {"RequestId":48,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":{}} StringsWatcher["10"].Next
[LOG] 84.55127 DEBUG juju.state.apiserver -> [F] machine-0 161.553us {"RequestId":79,"Response":{}} StringsWatcher["10"].Stop
[LOG] 84.55246 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":80,"Type":"StringsWatcher","Id":"13","Request":"Stop","Params":{}}
[LOG] 84.55253 DEBUG juju.state.apiserver -> [F] machine-0 9.291085ms {"RequestId":72,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":{}} StringsWatcher["13"].Next
[LOG] 84.55259 DEBUG juju.state.apiserver -> [F] machine-0 190.847us {"RequestId":80,"Response":{}} StringsWatcher["13"].Stop
[LOG] 84.55272 ERROR juju worker: fatal "firewaller": machine 1 is not provisioned
[LOG] 84.55275 DEBUG juju worker: killing "machiner"
[LOG] 84.55277 DEBUG juju worker: killing "upgrader"
[LOG] 84.55278 DEBUG juju worker: killing "logger"
[LOG] 84.55279 DEBUG juju worker: killing "authenticationworker"
[LOG] 84.55280 DEBUG juju worker: killing "0-container-watcher"
[LOG] 84.55281 DEBUG juju worker: killing "environ-provisioner"
[LOG] 84.55282 DEBUG juju worker: killing "charm-revision-updater"
[LOG] 84.55381 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":81,"Type":"NotifyWatcher","Id":"8","Request":"Stop","Params":{}}
[LOG] 84.55387 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":82,"Type":"NotifyWatcher","Id":"3","Request":"Stop","Params":{}}
[LOG] 84.55392 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":83,"Type":"NotifyWatcher","Id":"2","Request":"Stop","Params":{}}
[LOG] 84.55398 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":84,"Type":"StringsWatcher","Id":"6","Request":"Stop","Params":{}}
[LOG] 84.55410 DEBUG juju.state.apiserver -> [F] machine-0 29.758474ms {"RequestId":42,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":{}} NotifyWatcher["8"].Next
[LOG] 84.55416 DEBUG juju.state.apiserver -> [F] machine-0 367.329us {"RequestId":81,"Response":{}} NotifyWatcher["8"].Stop
[LOG] 84.55421 DEBUG juju.state.apiserver -> [F] machine-0 82.401082ms {"RequestId":18,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":{}} NotifyWatcher["3"].Next
[LOG] 84.55425 DEBUG juju.state.apiserver -> [F] machine-0 390.218us {"RequestId":82,"Response":{}} NotifyWatcher["3"].Stop
[LOG] 84.55430 DEBUG juju.state.apiserver -> [F] machine-0 93.444775ms {"RequestId":15,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":{}} NotifyWatcher["2"].Next
[LOG] 84.55435 DEBUG juju.state.apiserver -> [F] machine-0 433.919us {"RequestId":83,"Response":{}} NotifyWatcher["2"].Stop
[LOG] 84.55440 DEBUG juju.state.apiserver -> [F] machine-0 54.577868ms {"RequestId":28,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":{}} StringsWatcher["6"].Next
[LOG] 84.55444 DEBUG juju.state.apiserver -> [F] machine-0 460.793us {"RequestId":84,"Response":{}} StringsWatcher["6"].Stop
[LOG] 84.55579 DEBUG juju.state.apiserver -> [F] machine-0 9.266039ms {"RequestId":75,"Response":{"Results":[{"Error":null}]}} Provisioner[""].SetProvisioned
[LOG] 84.55599 INFO juju.provisioner started machine 1 as instance dummyenv-0 with hardware "arch=amd64 cpu-cores=1 mem=1024M root-disk=8192M"
[LOG] 84.55601 INFO juju.provisioner Shutting down provisioner task machine-0
[LOG] 84.55613 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":85,"Type":"StringsWatcher","Id":"9","Request":"Stop","Params":{}}
[LOG] 84.55619 DEBUG juju.state.apiserver -> [F] machine-0 30.46943ms {"RequestId":44,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":{}} StringsWatcher["9"].Next
[LOG] 84.55624 DEBUG juju.state.apiserver -> [F] machine-0 121.868us {"RequestId":85,"Response":{}} StringsWatcher["9"].Stop
[LOG] 84.55641 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":86,"Type":"NotifyWatcher","Id":"4","Request":"Stop","Params":{}}
[LOG] 84.55647 DEBUG juju.state.apiserver -> [F] machine-0 57.701757ms {"RequestId":26,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":{}} NotifyWatcher["4"].Next
[LOG] 84.55652 DEBUG juju.state.apiserver -> [F] machine-0 109.351us {"RequestId":86,"Response":{}} NotifyWatcher["4"].Stop
[LOG] 84.57062 INFO juju worker: start "authenticationworker"
[LOG] 84.57092 DEBUG juju worker: killing "authenticationworker"
[LOG] 84.57116 DEBUG juju.state.apiserver <- [F] machine-0 {"RequestId":87,"Type":"KeyUpdater","Request":"AuthorisedKeys","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 84.57470 DEBUG juju.state.apiserver -> [F] machine-0 3.478688ms {"RequestId":87,"Response":{"Results":[{"Error":null,"Result":["my-keys"]}]}} KeyUpdater[""].AuthorisedKeys
[LOG] 84.57602 DEBUG juju.utils.ssh reading authorised keys file /tmp/gocheck-2202916659517317514/56/.ssh/authorized_keys
[LOG] 84.57619 WARNING juju.utils.ssh invalid Juju ssh key my-keys: malformed line: "my-keys"
[LOG] 84.57631 DEBUG juju.utils.ssh reading authorised keys file /tmp/gocheck-2202916659517317514/56/.ssh/authorized_keys
[LOG] 84.57641 ERROR juju.worker.authenticationworker adding current Juju keys to ssh authorised keys: generating key fingerprint: malformed line: "my-keys"
[LOG] 84.57723 ERROR juju worker: exited "authenticationworker": adding current Juju keys to ssh authorised keys: generating key fingerprint: malformed line: "my-keys"
[LOG] 84.57755 ERROR juju worker: fatal "api": machine 1 is not provisioned
[LOG] 84.57758 DEBUG juju worker: killing "state"
[LOG] 84.57760 DEBUG juju worker: killing runner 0xc201453b40
[LOG] 84.57767 DEBUG juju worker: killing "termination"
[LOG] 84.57770 INFO juju worker: runner is dying
[LOG] 84.57776 DEBUG juju worker: killing "instancepoller"
[LOG] 84.57778 DEBUG juju worker: killing "apiserver"
[LOG] 84.57781 DEBUG juju worker: killing "cleaner"
[LOG] 84.57787 DEBUG juju worker: killing "resumer"
[LOG] 84.57789 DEBUG juju worker: killing "minunitsworker"
[LOG] 84.58145 INFO juju.state.apiserver [F] API connection terminated after 166.404368ms
unit provisioned with instance dummyenv-0
machine_test.go:316:
    c.Check(opRecvTimeout(c, s.State, op, dummy.OpOpenPorts{}), gc.NotNil)
machine_test.go:633:
    c.Fatalf("time out wating for operation")
... Error: time out wating for operation

[LOG] 4.52700 DEBUG juju worker: killing runner 0xc200dc0c00
[LOG] 4.52839 INFO juju.provider.dummy reset environment
[LOG] 4.52856 INFO juju.state.apiserver [E] API connection terminated after 20.295639148s
[LOG] 4.55726 INFO juju Reset successfully reset admin password
[LOG] 4.57663 INFO juju Reset successfully reset admin password
[LOG] 4.58098 INFO juju Reset successfully reset admin password

----------------------------------------------------------------------
FAIL: machine_test.go:329: MachineSuite.TestManageEnvironRunsInstancePoller

[LOG] 5.43215 DEBUG juju.environs.configstore Making /tmp/gocheck-2202916659517317514/64/home/ubuntu/.juju/environments
[LOG] 5.53376 DEBUG juju.environs.tools reading v1.* tools
[LOG] 5.53382 INFO juju environs/testing: uploading FAKE tools 1.17.1-precise-amd64
[LOG] 5.53481 DEBUG juju.environs.tools no architecture specified when finding tools, looking for any
[LOG] 5.53482 DEBUG juju.environs.tools no series specified when finding tools, looking for any
[LOG] 5.53489 DEBUG juju.environs.simplestreams fetchData failed for "http://127.0.0.1:35935/dummyenv/private/tools/streams/v1/index.sjson": file "tools/streams/v1/index.sjson" not found not found
[LOG] 5.53491 DEBUG juju.environs.simplestreams cannot load index "http://127.0.0.1:35935/dummyenv/private/tools/streams/v1/index.sjson": invalid URL "http://127.0.0.1:35935/dummyenv/private/tools/streams/v1/index.sjson" not found
[LOG] 5.53496 DEBUG juju.environs.simplestreams fetchData failed for "http://127.0.0.1:35935/dummyenv/private/tools/streams/v1/index.json": file "tools/streams/v1/index.json" not found not found
[LOG] 5.53498 DEBUG juju.environs.simplestreams cannot load index "http://127.0.0.1:35935/dummyenv/private/tools/streams/v1/index.json": invalid URL "http://127.0.0.1:35935/dummyenv/private/tools/streams/v1/index.json" not found
[LOG] 5.53531 INFO juju.environs.tools Writing tools/streams/v1/index.json
[LOG] 5.53542 INFO juju.environs.tools Writing tools/streams/v1/com.ubuntu.juju:released:tools.json
[LOG] 5.53559 INFO juju.environs.bootstrap bootstrapping environment "dummyenv"
[LOG] 5.53562 DEBUG juju.environs.bootstrap looking for bootstrap tools: series="precise", arch=<nil>, version=1.17.1
[LOG] 5.53564 INFO juju.environs.tools reading tools with major.minor version 1.17
[LOG] 5.53565 INFO juju.environs.tools filtering tools by version: 1.17.1
[LOG] 5.53566 INFO juju.environs.tools filtering tools by series: precise
[LOG] 5.53569 DEBUG juju.environs.tools no architecture specified when finding tools, looking for any
[LOG] 5.53573 DEBUG juju.environs.simplestreams fetchData failed for "http://127.0.0.1:35935/dummyenv/private/tools/streams/v1/index.sjson": file "tools/streams/v1/index.sjson" not found not found
[LOG] 5.53575 DEBUG juju.environs.simplestreams cannot load index "http://127.0.0.1:35935/dummyenv/private/tools/streams/v1/index.sjson": invalid URL "http://127.0.0.1:35935/dummyenv/private/tools/streams/v1/index.sjson" not found
[LOG] 5.53588 DEBUG juju.environs.simplestreams fetchData failed for "http://127.0.0.1:35935/dummyenv/private/tools/streams/v1/mirrors.json": file "tools/streams/v1/mirrors.json" not found not found
[LOG] 5.53590 DEBUG juju.environs.simplestreams no mirror index file found
[LOG] 5.53596 DEBUG juju.environs.simplestreams no mirror information available for { }: mirror data for "com.ubuntu.juju:released:tools" not found
[LOG] 5.53597 DEBUG juju.environs.simplestreams read metadata index at "http://127.0.0.1:35935/dummyenv/private/tools/streams/v1/index.json"
[LOG] 5.53603 DEBUG juju.environs.simplestreams candidate matches for products ["com.ubuntu.juju:12.04:amd64" "com.ubuntu.juju:12.04:i386" "com.ubuntu.juju:12.04:arm"] are [{Fri, 24 Jan 2014 20:47:06 +0000 products:1.0 content-download  [] streams/v1/com.ubuntu.juju:released:tools.json [com.ubuntu.juju:12.04:amd64]}]
[LOG] 5.53604 DEBUG juju.environs.simplestreams finding products at path "streams/v1/com.ubuntu.juju:released:tools.json"
[LOG] 5.53625 DEBUG juju.environs.simplestreams metadata: &{map[com.ubuntu.juju:12.04:amd64:{ 1.17.1 amd64   map[20140124:0xc200a6e5a0]}] map[] Fri, 24 Jan 2014 20:47:06 +0000 products:1.0 com.ubuntu.juju:released:tools}
[LOG] 5.53632 INFO juju.environs.bootstrap picked newest version: 1.17.1
[LOG] 5.53634 INFO juju.provider.dummy would pick tools from 1.17.1-precise-amd64
[LOG] 5.53679 INFO juju.state opening state; mongo addresses: ["localhost:42494"]; entity ""
[LOG] 5.53998 INFO juju.state connection established
[LOG] 5.59871 INFO juju.state initializing environment
[LOG] 5.62168 INFO juju.state.apiserver listening on "127.0.0.1:44358"
[LOG] 5.63956 INFO juju.state opening state; mongo addresses: ["localhost:42494"]; entity ""
[LOG] 5.64261 INFO juju.state connection established
[LOG] 5.65741 INFO juju juju: authorization error while connecting to state server; retrying
[LOG] 5.65756 INFO juju.state opening state; mongo addresses: ["localhost:42494"]; entity ""
[LOG] 5.66709 INFO juju.state connection established
[LOG] 5.71210 INFO juju state/api: dialing "wss://127.0.0.1:44358/"
[LOG] 5.71514 INFO juju.state.apiserver [12] API connection from 127.0.0.1:59548
[LOG] 5.71532 INFO juju state/api: connection established
[LOG] 5.71551 DEBUG juju.state.apiserver <- [12] <unknown> {"RequestId":1,"Type":"Admin","Request":"Login","Params":{"AuthTag":"user-admin","Password":"dummy-secret","Nonce":""}}
[LOG] 5.71598 DEBUG juju.state.apiserver -> [12] user-admin 466.18us {"RequestId":1,"Response":{}} Admin[""].Login
[LOG] 5.71657 DEBUG juju.environs.tools reading v1.* tools
[LOG] 5.71663 DEBUG juju.environs.tools found 1.17.1-precise-amd64
[LOG] 5.71666 INFO juju environs/testing: uploading FAKE tools 1.17.1-quantal-amd64
[LOG] 5.72857 DEBUG juju.environs.tools no architecture specified when finding tools, looking for any
[LOG] 5.72860 DEBUG juju.environs.tools no series specified when finding tools, looking for any
[LOG] 5.72869 DEBUG juju.environs.simplestreams fetchData failed for "http://127.0.0.1:35935/dummyenv/private/tools/streams/v1/index.sjson": file "tools/streams/v1/index.sjson" not found not found
[LOG] 5.72873 DEBUG juju.environs.simplestreams cannot load index "http://127.0.0.1:35935/dummyenv/private/tools/streams/v1/index.sjson": invalid URL "http://127.0.0.1:35935/dummyenv/private/tools/streams/v1/index.sjson" not found
[LOG] 5.72890 DEBUG juju.environs.simplestreams fetchData failed for "http://127.0.0.1:35935/dummyenv/private/tools/streams/v1/mirrors.json": file "tools/streams/v1/mirrors.json" not found not found
[LOG] 5.72892 DEBUG juju.environs.simplestreams no mirror index file found
[LOG] 5.72894 DEBUG juju.environs.simplestreams no mirror information available for { }: mirror data for "com.ubuntu.juju:released:tools" not found
[LOG] 5.72896 DEBUG juju.environs.simplestreams read metadata index at "http://127.0.0.1:35935/dummyenv/private/tools/streams/v1/index.json"
[LOG] 5.72909 DEBUG juju.environs.simplestreams candidate matches for products ["com.ubuntu.juju:12.04:amd64" "com.ubuntu.juju:12.04:i386" "com.ubuntu.juju:12.04:arm" "com.ubuntu.juju:12.10:amd64" "com.ubuntu.juju:12.10:i386" "com.ubuntu.juju:12.10:arm" "com.ubuntu.juju:13.04:amd64" "com.ubuntu.juju:13.04:i386" "com.ubuntu.juju:13.04:arm" "com.ubuntu.juju:13.10:amd64" "com.ubuntu.juju:13.10:i386" "com.ubuntu.juju:13.10:arm" "com.ubuntu.juju:14.04:amd64" "com.ubuntu.juju:14.04:i386" "com.ubuntu.juju:14.04:arm"] are [{Fri, 24 Jan 2014 20:47:06 +0000 products:1.0 content-download  [] streams/v1/com.ubuntu.juju:released:tools.json [com.ubuntu.juju:12.04:amd64]}]
[LOG] 5.72912 DEBUG juju.environs.simplestreams finding products at path "streams/v1/com.ubuntu.juju:released:tools.json"
[LOG] 5.72943 DEBUG juju.environs.simplestreams metadata: &{map[com.ubuntu.juju:12.04:amd64:{ 1.17.1 amd64   map[20140124:0xc2002a7c60]}] map[] Fri, 24 Jan 2014 20:47:06 +0000 products:1.0 com.ubuntu.juju:released:tools}
[LOG] 5.72993 INFO juju.environs.tools Writing tools/streams/v1/index.json
[LOG] 5.73028 INFO juju.environs.tools Writing tools/streams/v1/com.ubuntu.juju:released:tools.json
[LOG] 5.77519 INFO juju environs/testing: uploading FAKE tools 1.17.1-precise-amd64
[LOG] 5.78678 INFO juju.cmd.jujud machine agent machine-0 start
[LOG] 5.78701 DEBUG juju.agent Reading agent config, format: format 1.16
[LOG] 5.78797 INFO juju.cmd.jujud Starting StateWorker for machine-0
[LOG] 5.78801 INFO juju worker: start "state"
[LOG] 5.78807 INFO juju.state opening state; mongo addresses: ["localhost:42494"]; entity "machine-0"
[LOG] 5.78846 INFO juju worker: start "api"
[LOG] 5.78870 INFO juju state/api: dialing "wss://localhost:35540/"
[LOG] 5.78947 INFO juju worker: start "termination"
[LOG] 5.80411 ERROR juju state/api: websocket.Dial wss://localhost:35540/: dial tcp 127.0.0.1:35540: connection refused
[LOG] 5.81251 INFO juju writing charm to storage [1418 bytes]
[LOG] 5.81260 INFO juju adding charm to state
[LOG] 5.81396 ERROR juju worker: exited "api": websocket.Dial wss://localhost:35540/: dial tcp 127.0.0.1:35540: connection refused
[LOG] 5.81401 INFO juju worker: restarting "api" in 50ms
[LOG] 5.81562 INFO juju.state connection established
[LOG] 5.82015 INFO juju worker: start "instancepoller"
[LOG] 5.82019 INFO juju worker: start "apiserver"
[LOG] 5.82030 INFO juju.state.apiserver listening on "[::]:35540"
[LOG] 5.84235 INFO juju worker: start "cleaner"
[LOG] 5.84287 INFO juju worker: start "resumer"
[LOG] 5.84308 INFO juju worker: start "minunitsworker"
[LOG] 5.84606 INFO juju.worker.instanceupdater instance poller received inital environment configuration
[LOG] 5.84702 WARNING juju.worker.instanceupdater cannot get instance info for instance "ardbeg-0": no instances found
[LOG] 5.87118 INFO juju worker: start "api"
[LOG] 5.87241 INFO juju state/api: dialing "wss://localhost:35540/"
[LOG] 5.87618 INFO juju.state.apiserver [13] API connection from 127.0.0.1:49293
[LOG] 5.87647 INFO juju state/api: connection established
[LOG] 5.87666 DEBUG juju.state.apiserver <- [13] <unknown> {"RequestId":1,"Type":"Admin","Request":"Login","Params":{"AuthTag":"machine-0","Password":"machine-password-1234567890","Nonce":"user-admin:bootstrap"}}
[LOG] 5.88058 DEBUG juju.state.apiserver -> [13] machine-0 3.917004ms {"RequestId":1,"Response":{}} Admin[""].Login
[LOG] 5.88073 DEBUG juju.agent writing configuration file
[LOG] 5.88259 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":2,"Type":"Agent","Request":"GetEntities","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 5.88307 DEBUG juju.state.apiserver -> [13] machine-0 491.636us {"RequestId":2,"Response":{"Entities":[{"Life":"alive","Jobs":["JobManageEnviron"],"ContainerType":"","Error":null}]}} Agent[""].GetEntities
[LOG] 5.88379 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":4,"Type":"Agent","Request":"SetPasswords","Params":{"Changes":[{"Tag":"machine-0","Password":"dye+WgZK7ckbqycY0On9U0Q/"}]}}
[LOG] 5.88542 INFO juju setting mongo password for "machine-0"
[LOG] 5.88953 INFO juju setting password for "machine-0"
[LOG] 5.88959 DEBUG juju.state.apiserver -> [13] machine-0 5.800326ms {"RequestId":4,"Response":{"Results":[{"Error":null}]}} Agent[""].SetPasswords
[LOG] 5.88977 INFO juju worker: start "machiner"
[LOG] 5.88985 INFO juju worker: start "upgrader"
[LOG] 5.88987 INFO juju worker: start "logger"
[LOG] 5.88997 DEBUG juju.worker.logger initial log config: "<root>=WARNING;juju=DEBUG;unit=DEBUG"
[LOG] 5.89006 DEBUG juju.worker.logger logger setup
[LOG] 5.89017 WARNING juju.cmd.jujud determining kvm support: exec: "kvm-ok": executable file not found in $PATH
no kvm containers possible
[LOG] 5.89022 INFO juju worker: start "authenticationworker"
[LOG] 5.89082 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":5,"Type":"Machiner","Request":"Life","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 5.89095 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":6,"Type":"Upgrader","Request":"SetTools","Params":{"AgentTools":[{"Tag":"machine-0","Tools":{"Version":"1.17.1-precise-amd64"}}]}}
[LOG] 5.89101 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":7,"Type":"Logger","Request":"LoggingConfig","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 5.89107 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":8,"Type":"Provisioner","Request":"Life","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 5.89113 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":9,"Type":"KeyUpdater","Request":"AuthorisedKeys","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 5.89206 DEBUG juju.state.apiserver -> [13] machine-0 1.248767ms {"RequestId":5,"Response":{"Results":[{"Life":"alive","Error":null}]}} Machiner[""].Life
[LOG] 5.89292 DEBUG juju.state.apiserver -> [13] machine-0 1.89446ms {"RequestId":7,"Response":{"Results":[{"Error":null,"Result":"\u003croot\u003e=WARNING;juju=DEBUG;unit=DEBUG"}]}} Logger[""].LoggingConfig
[LOG] 5.89304 DEBUG juju.state.apiserver -> [13] machine-0 1.978998ms {"RequestId":8,"Response":{"Results":[{"Life":"alive","Error":null}]}} Provisioner[""].Life
[LOG] 5.89510 DEBUG juju.state.apiserver -> [13] machine-0 3.944061ms {"RequestId":9,"Response":{"Results":[{"Error":null,"Result":["my-keys"]}]}} KeyUpdater[""].AuthorisedKeys
[LOG] 5.89537 INFO juju.worker.machiner setting addresses for machine-0 to ["10.55.32.52" "fe80::f816:3eff:fef7:1c4e"]
[LOG] 5.89568 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":10,"Type":"Machiner","Request":"SetMachineAddresses","Params":{"MachineAddresses":[{"Tag":"machine-0","Addresses":[{"Value":"10.55.32.52","Type":"ipv4","NetworkName":"","NetworkScope":""},{"Value":"fe80::f816:3eff:fef7:1c4e","Type":"ipv6","NetworkName":"","NetworkScope":""}]}]}}
[LOG] 5.89584 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":11,"Type":"Logger","Request":"WatchLoggingConfig","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 5.89592 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":12,"Type":"Provisioner","Request":"SetSupportedContainers","Params":{"Params":[{"MachineTag":"machine-0","ContainerTypes":["lxc"]}]}}
[LOG] 5.89686 DEBUG juju.utils.ssh reading authorised keys file /tmp/gocheck-2202916659517317514/70/.ssh/authorized_keys
[LOG] 5.89693 WARNING juju.utils.ssh invalid Juju ssh key my-keys: malformed line: "my-keys"
[LOG] 5.89697 DEBUG juju.utils.ssh reading authorised keys file /tmp/gocheck-2202916659517317514/70/.ssh/authorized_keys
[LOG] 5.89699 ERROR juju.worker.authenticationworker adding current Juju keys to ssh authorised keys: generating key fingerprint: malformed line: "my-keys"
[LOG] 5.89839 DEBUG juju.state.apiserver -> [13] machine-0 2.613135ms {"RequestId":11,"Response":{"Results":[{"NotifyWatcherId":"2","Error":null}]}} Logger[""].WatchLoggingConfig
[LOG] 5.89877 ERROR juju worker: exited "authenticationworker": adding current Juju keys to ssh authorised keys: generating key fingerprint: malformed line: "my-keys"
[LOG] 5.90017 INFO juju worker: restarting "authenticationworker" in 50ms
[LOG] 5.90048 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":14,"Type":"Logger","Request":"LoggingConfig","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 5.90054 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":15,"Type":"NotifyWatcher","Id":"2","Request":"Next","Params":{}}
[LOG] 5.90239 DEBUG juju.state.apiserver -> [13] machine-0 1.907432ms {"RequestId":14,"Response":{"Results":[{"Error":null,"Result":"\u003croot\u003e=WARNING;juju=DEBUG;unit=DEBUG"}]}} Logger[""].LoggingConfig
[LOG] 5.90544 DEBUG juju.state.apiserver -> [13] machine-0 14.529033ms {"RequestId":6,"Response":{"Results":[{"Error":null}]}} Upgrader[""].SetTools
[LOG] 5.90589 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":16,"Type":"Upgrader","Request":"WatchAPIVersion","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 5.90661 DEBUG juju.state.apiserver -> [13] machine-0 754.105us {"RequestId":16,"Response":{"Results":[{"NotifyWatcherId":"3","Error":null}]}} Upgrader[""].WatchAPIVersion
[LOG] 5.90694 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":17,"Type":"Upgrader","Request":"DesiredVersion","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 5.90699 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":18,"Type":"NotifyWatcher","Id":"3","Request":"Next","Params":{}}
[LOG] 5.90821 DEBUG juju.state.apiserver -> [13] machine-0 1.258688ms {"RequestId":17,"Response":{"Results":[{"Version":"1.17.1","Error":null}]}} Upgrader[""].DesiredVersion
[LOG] 5.90953 INFO juju.worker.upgrader desired tool version: 1.17.1
[LOG] 5.91266 DEBUG juju.state.apiserver -> [13] machine-0 16.988685ms {"RequestId":10,"Response":{"Results":[{"Error":null}]}} Machiner[""].SetMachineAddresses
[LOG] 5.91400 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":19,"Type":"Machiner","Request":"SetStatus","Params":{"Entities":[{"Tag":"machine-0","Status":"started","Info":"","Data":null}]}}
[LOG] 5.92050 DEBUG juju.state.apiserver -> [13] machine-0 24.542898ms {"RequestId":12,"Response":{"Results":[{"Error":null}]}} Provisioner[""].SetSupportedContainers
[LOG] 5.92184 INFO juju worker: start "0-container-watcher"
[LOG] 5.92186 INFO juju worker: start "environ-provisioner"
[LOG] 5.92201 INFO juju worker: start "firewaller"
[LOG] 5.92207 INFO juju worker: start "charm-revision-updater"
[LOG] 5.92221 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":20,"Type":"Provisioner","Request":"WatchContainers","Params":{"Params":[{"MachineTag":"machine-0","ContainerType":""}]}}
[LOG] 5.92228 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":21,"Type":"Provisioner","Request":"WatchForEnvironConfigChanges","Params":{}}
[LOG] 5.92236 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":22,"Type":"Firewaller","Request":"WatchForEnvironConfigChanges","Params":{}}
[LOG] 5.92241 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":23,"Type":"CharmRevisionUpdater","Request":"UpdateLatestRevisions","Params":{}}
[LOG] 5.92418 DEBUG juju.state.apiserver -> [13] machine-0 1.888421ms {"RequestId":21,"Response":{"NotifyWatcherId":"4","Error":null}} Provisioner[""].WatchForEnvironConfigChanges
[LOG] 5.92457 DEBUG juju.state.apiserver -> [13] machine-0 2.19255ms {"RequestId":22,"Response":{"NotifyWatcherId":"5","Error":null}} Firewaller[""].WatchForEnvironConfigChanges
[LOG] 5.92543 INFO juju.state.apiserver.charmrevisionupdater retrieving revision information for 0 charms
[LOG] 5.92771 DEBUG juju.state.apiserver -> [13] machine-0 5.484579ms {"RequestId":20,"Response":{"Results":[{"StringsWatcherId":"6","Changes":[],"Error":null}]}} Provisioner[""].WatchContainers
[LOG] 5.92806 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":24,"Type":"Firewaller","Request":"WatchEnvironMachines","Params":{}}
[LOG] 5.92811 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":25,"Type":"Provisioner","Request":"EnvironConfig","Params":{}}
[LOG] 5.92816 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":26,"Type":"NotifyWatcher","Id":"4","Request":"Next","Params":{}}
[LOG] 5.92821 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":27,"Type":"NotifyWatcher","Id":"5","Request":"Next","Params":{}}
[LOG] 5.92827 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":28,"Type":"StringsWatcher","Id":"6","Request":"Next","Params":{}}
[LOG] 5.93107 DEBUG juju.state.apiserver -> [13] machine-0 2.855169ms {"RequestId":25,"Response":{"Error":null,"Config":{"admin-secret":"","agent-version":"1.17.1","api-port":4321,"authorized-keys":"my-keys","broken":"","ca-cert":"-----BEGIN CERTIFICATE-----\nMIIB4jCCAY6gAwIBAgIBADALBgkqhkiG9w0BAQUwSjENMAsGA1UEChMEanVqdTE5\nMDcGA1UEAwwwanVqdS1nZW5lcmF0ZWQgQ0EgZm9yIGVudmlyb25tZW50ICJqdWp1\nIHRlc3RpbmciMB4XDTE0MDEyNDIwNDEyN1oXDTI0MDEyNDIwNDYyN1owSjENMAsG\nA1UEChMEanVqdTE5MDcGA1UEAwwwanVqdS1nZW5lcmF0ZWQgQ0EgZm9yIGVudmly\nb25tZW50ICJqdWp1IHRlc3RpbmciMFowCwYJKoZIhvcNAQEBA0sAMEgCQQC4qR/z\nJQo4xS84XV07iQYbycC27iWdPNgFXv9ouoTu9Y5FV2bPuE0uDx3n/AKQAz+eqVNv\nXI6WrJSA7IKSd7rPAgMBAAGjYzBhMA4GA1UdDwEB/wQEAwIApDAPBgNVHRMBAf8E\nBTADAQH/MB0GA1UdDgQWBBSu0Kjlvf3RVUeFNukqfwUog21FjDAfBgNVHSMEGDAW\ngBSu0Kjlvf3RVUeFNukqfwUog21FjDALBgkqhkiG9w0BAQUDQQBd6CyFSHIhM9er\nvA9qSb8P9yjqMzXnqRxI1ETljgXzNTLLMuZYf3Tj93lLdZm7zZDgrdlqoD5JiRD0\nONmStaWi\n-----END CERTIFICATE-----\n","ca-private-key":"","charm-store-auth":"","default-series":"precise","development":false,"firewall-mode":"instance","image-metadata-url":"","logging-config":"\u003croot\u003e=WARNING;juju=DEBUG;unit=DEBUG","name":"dummyenv","secret":"pork","ssl-hostname-verification":true,"state-id":"10","state-port":1234,"state-server":true,"syslog-port":2345,"tools-metadata-url":"","tools-url":"","type":"dummy"}}} Provisioner[""].EnvironConfig
[LOG] 5.93127 DEBUG juju.state.apiserver -> [13] machine-0 3.198771ms {"RequestId":24,"Response":{"StringsWatcherId":"7","Changes":["1","0"],"Error":null}} Firewaller[""].WatchEnvironMachines
waiting for unit "test-service/0" to be provisioned
[LOG] 5.93364 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":29,"Type":"Provisioner","Request":"StateAddresses","Params":{}}
[LOG] 5.93370 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":30,"Type":"Firewaller","Request":"EnvironConfig","Params":{}}
[LOG] 5.93377 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":31,"Type":"StringsWatcher","Id":"7","Request":"Next","Params":{}}
[LOG] 5.93793 DEBUG juju.state.apiserver -> [13] machine-0 4.121244ms {"RequestId":30,"Response":{"Error":null,"Config":{"admin-secret":"","agent-version":"1.17.1","api-port":4321,"authorized-keys":"my-keys","broken":"","ca-cert":"-----BEGIN CERTIFICATE-----\nMIIB4jCCAY6gAwIBAgIBADALBgkqhkiG9w0BAQUwSjENMAsGA1UEChMEanVqdTE5\nMDcGA1UEAwwwanVqdS1nZW5lcmF0ZWQgQ0EgZm9yIGVudmlyb25tZW50ICJqdWp1\nIHRlc3RpbmciMB4XDTE0MDEyNDIwNDEyN1oXDTI0MDEyNDIwNDYyN1owSjENMAsG\nA1UEChMEanVqdTE5MDcGA1UEAwwwanVqdS1nZW5lcmF0ZWQgQ0EgZm9yIGVudmly\nb25tZW50ICJqdWp1IHRlc3RpbmciMFowCwYJKoZIhvcNAQEBA0sAMEgCQQC4qR/z\nJQo4xS84XV07iQYbycC27iWdPNgFXv9ouoTu9Y5FV2bPuE0uDx3n/AKQAz+eqVNv\nXI6WrJSA7IKSd7rPAgMBAAGjYzBhMA4GA1UdDwEB/wQEAwIApDAPBgNVHRMBAf8E\nBTADAQH/MB0GA1UdDgQWBBSu0Kjlvf3RVUeFNukqfwUog21FjDAfBgNVHSMEGDAW\ngBSu0Kjlvf3RVUeFNukqfwUog21FjDALBgkqhkiG9w0BAQUDQQBd6CyFSHIhM9er\nvA9qSb8P9yjqMzXnqRxI1ETljgXzNTLLMuZYf3Tj93lLdZm7zZDgrdlqoD5JiRD0\nONmStaWi\n-----END CERTIFICATE-----\n","ca-private-key":"","charm-store-auth":"","default-series":"precise","development":false,"firewall-mode":"instance","image-metadata-url":"","logging-config":"\u003croot\u003e=WARNING;juju=DEBUG;unit=DEBUG","name":"dummyenv","secret":"pork","ssl-hostname-verification":true,"state-id":"10","state-port":1234,"state-server":true,"syslog-port":2345,"tools-metadata-url":"","tools-url":"","type":"dummy"}}} Firewaller[""].EnvironConfig
[LOG] 5.94048 DEBUG juju.state.apiserver -> [13] machine-0 6.840143ms {"RequestId":29,"Response":{"Error":null,"Result":["0.1.2.3:1234"]}} Provisioner[""].StateAddresses
[LOG] 5.94080 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":32,"Type":"Firewaller","Request":"Life","Params":{"Entities":[{"Tag":"machine-1"}]}}
[LOG] 5.94086 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":33,"Type":"Provisioner","Request":"APIAddresses","Params":{}}
[LOG] 5.94094 DEBUG juju.state.apiserver -> [13] machine-0 26.973952ms {"RequestId":19,"Response":{"Results":[{"Error":null}]}} Machiner[""].SetStatus
[LOG] 5.94197 DEBUG juju.state.apiserver -> [13] machine-0 1.232331ms {"RequestId":32,"Response":{"Results":[{"Life":"alive","Error":null}]}} Firewaller[""].Life
[LOG] 5.94224 INFO juju.worker.machiner "machine-0" started
[LOG] 5.94252 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":34,"Type":"Machiner","Request":"Watch","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 5.94328 DEBUG juju.state.apiserver -> [13] machine-0 2.403013ms {"RequestId":33,"Response":{"Error":null,"Result":["0.1.2.3:4321"]}} Provisioner[""].APIAddresses
[LOG] 5.94393 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":35,"Type":"Firewaller","Request":"Life","Params":{"Entities":[{"Tag":"machine-1"}]}}
[LOG] 5.94434 DEBUG juju.state.apiserver -> [13] machine-0 417.094us {"RequestId":35,"Response":{"Results":[{"Life":"alive","Error":null}]}} Firewaller[""].Life
[LOG] 5.94441 DEBUG juju.state.apiserver -> [13] machine-0 1.910557ms {"RequestId":34,"Response":{"Results":[{"NotifyWatcherId":"8","Error":null}]}} Machiner[""].Watch
[LOG] 5.94469 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":36,"Type":"Provisioner","Request":"CACert","Params":{}}
[LOG] 5.94475 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":37,"Type":"Firewaller","Request":"WatchUnits","Params":{"Entities":[{"Tag":"machine-1"}]}}
[LOG] 5.94481 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":38,"Type":"Machiner","Request":"Life","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 5.94486 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":39,"Type":"NotifyWatcher","Id":"8","Request":"Next","Params":{}}
[LOG] 5.94493 DEBUG juju.state.apiserver -> [13] machine-0 224.516us {"RequestId":36,"Response":{"Result":"LS0tLS1CRUdJTiBDRVJUSUZJQ0FURS0tLS0tCk1JSUI0akNDQVk2Z0F3SUJBZ0lCQURBTEJna3Foa2lHOXcwQkFRVXdTakVOTUFzR0ExVUVDaE1FYW5WcWRURTUKTURjR0ExVUVBd3d3YW5WcWRTMW5aVzVsY21GMFpXUWdRMEVnWm05eUlHVnVkbWx5YjI1dFpXNTBJQ0pxZFdwMQpJSFJsYzNScGJtY2lNQjRYRFRFME1ERXlOREl3TkRFeU4xb1hEVEkwTURFeU5ESXdORFl5TjFvd1NqRU5NQXNHCkExVUVDaE1FYW5WcWRURTVNRGNHQTFVRUF3d3dhblZxZFMxblpXNWxjbUYwWldRZ1EwRWdabTl5SUdWdWRtbHkKYjI1dFpXNTBJQ0pxZFdwMUlIUmxjM1JwYm1jaU1Gb3dDd1lKS29aSWh2Y05BUUVCQTBzQU1FZ0NRUUM0cVIvegpKUW80eFM4NFhWMDdpUVlieWNDMjdpV2RQTmdGWHY5b3VvVHU5WTVGVjJiUHVFMHVEeDNuL0FLUUF6K2VxVk52ClhJNldySlNBN0lLU2Q3clBBZ01CQUFHall6QmhNQTRHQTFVZER3RUIvd1FFQXdJQXBEQVBCZ05WSFJNQkFmOEUKQlRBREFRSC9NQjBHQTFVZERnUVdCQlN1MEtqbHZmM1JWVWVGTnVrcWZ3VW9nMjFGakRBZkJnTlZIU01FR0RBVwpnQlN1MEtqbHZmM1JWVWVGTnVrcWZ3VW9nMjFGakRBTEJna3Foa2lHOXcwQkFRVURRUUJkNkN5RlNISWhNOWVyCnZBOXFTYjhQOXlqcU16WG5xUnhJMUVUbGpnWHpOVExMTXVaWWYzVGo5M2xMZFptN3paRGdyZGxxb0Q1SmlSRDAKT05tU3RhV2kKLS0tLS1FTkQgQ0VSVElGSUNBVEUtLS0tLQo="}} Provisioner[""].CACert
[LOG] 5.94558 DEBUG juju.state.apiserver -> [13] machine-0 753.099us {"RequestId":38,"Response":{"Results":[{"Life":"alive","Error":null}]}} Machiner[""].Life
[LOG] 5.94622 DEBUG juju.state.apiserver -> [13] machine-0 23.795911ms {"RequestId":23,"Response":{"Error":null}} CharmRevisionUpdater[""].UpdateLatestRevisions
[LOG] 5.94632 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":40,"Type":"Provisioner","Request":"WatchEnvironMachines","Params":{}}
[LOG] 5.94703 DEBUG juju.state.apiserver -> [13] machine-0 688.425us {"RequestId":40,"Response":{"StringsWatcherId":"9","Changes":["1","0"],"Error":null}} Provisioner[""].WatchEnvironMachines
[LOG] 5.94716 INFO juju.provisioner Starting up provisioner task machine-0
[LOG] 5.94754 DEBUG juju.state.apiserver -> [13] machine-0 2.787718ms {"RequestId":37,"Response":{"Results":[{"StringsWatcherId":"10","Changes":["test-service/0"],"Error":null}]}} Firewaller[""].WatchUnits
[LOG] 5.94766 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":41,"Type":"Provisioner","Request":"Life","Params":{"Entities":[{"Tag":"machine-1"}]}}
[LOG] 5.94771 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":42,"Type":"StringsWatcher","Id":"9","Request":"Next","Params":{}}
[LOG] 5.94807 DEBUG juju.state.apiserver -> [13] machine-0 392.809us {"RequestId":41,"Response":{"Results":[{"Life":"alive","Error":null}]}} Provisioner[""].Life
[LOG] 5.94843 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":43,"Type":"Provisioner","Request":"Life","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 5.94849 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":44,"Type":"Firewaller","Request":"Life","Params":{"Entities":[{"Tag":"unit-test-service-0"}]}}
[LOG] 5.94855 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":45,"Type":"StringsWatcher","Id":"10","Request":"Next","Params":{}}
[LOG] 5.94907 DEBUG juju.state.apiserver -> [13] machine-0 629.961us {"RequestId":43,"Response":{"Results":[{"Life":"alive","Error":null}]}} Provisioner[""].Life
[LOG] 5.94921 DEBUG juju.state.apiserver -> [13] machine-0 683.071us {"RequestId":44,"Response":{"Results":[{"Life":"alive","Error":null}]}} Firewaller[""].Life
[LOG] 5.94948 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":46,"Type":"Provisioner","Request":"InstanceId","Params":{"Entities":[{"Tag":"machine-1"}]}}
[LOG] 5.94954 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":47,"Type":"Firewaller","Request":"GetAssignedMachine","Params":{"Entities":[{"Tag":"unit-test-service-0"}]}}
[LOG] 5.95015 DEBUG juju.state.apiserver -> [13] machine-0 578.561us {"RequestId":47,"Response":{"Results":[{"Error":null,"Result":"machine-1"}]}} Firewaller[""].GetAssignedMachine
[LOG] 5.95043 DEBUG juju.state.apiserver -> [13] machine-0 956.404us {"RequestId":46,"Response":{"Results":[{"Error":{"Message":"machine 1 is not provisioned","Code":"not provisioned"},"Result":""}]}} Provisioner[""].InstanceId
[LOG] 5.95049 INFO juju worker: start "authenticationworker"
[LOG] 5.95071 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":48,"Type":"Firewaller","Request":"Life","Params":{"Entities":[{"Tag":"service-test-service"}]}}
[LOG] 5.95077 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":49,"Type":"KeyUpdater","Request":"AuthorisedKeys","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 5.95085 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":50,"Type":"Provisioner","Request":"Status","Params":{"Entities":[{"Tag":"machine-1"}]}}
[LOG] 5.95157 DEBUG juju.state.apiserver -> [13] machine-0 852.903us {"RequestId":48,"Response":{"Results":[{"Life":"alive","Error":null}]}} Firewaller[""].Life
[LOG] 5.95246 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":51,"Type":"Firewaller","Request":"OpenedPorts","Params":{"Entities":[{"Tag":"unit-test-service-0"}]}}
[LOG] 5.95296 DEBUG juju.state.apiserver -> [13] machine-0 2.178061ms {"RequestId":49,"Response":{"Results":[{"Error":null,"Result":["my-keys"]}]}} KeyUpdater[""].AuthorisedKeys
[LOG] 5.95308 DEBUG juju.state.apiserver -> [13] machine-0 2.227372ms {"RequestId":50,"Response":{"Results":[{"Error":null,"Status":"pending","Info":""}]}} Provisioner[""].Status
[LOG] 5.95321 DEBUG juju.state.apiserver -> [13] machine-0 733.419us {"RequestId":51,"Response":{"Results":[{"Error":null,"Ports":[]}]}} Firewaller[""].OpenedPorts
[LOG] 5.95345 DEBUG juju.utils.ssh reading authorised keys file /tmp/gocheck-2202916659517317514/70/.ssh/authorized_keys
[LOG] 5.95350 WARNING juju.utils.ssh invalid Juju ssh key my-keys: malformed line: "my-keys"
[LOG] 5.95353 DEBUG juju.utils.ssh reading authorised keys file /tmp/gocheck-2202916659517317514/70/.ssh/authorized_keys
[LOG] 5.95356 ERROR juju.worker.authenticationworker adding current Juju keys to ssh authorised keys: generating key fingerprint: malformed line: "my-keys"
[LOG] 5.95359 INFO juju.provisioner found machine "1" pending provisioning
[LOG] 5.95379 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":52,"Type":"Provisioner","Request":"InstanceId","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 5.95386 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":53,"Type":"Firewaller","Request":"GetExposed","Params":{"Entities":[{"Tag":"service-test-service"}]}}
[LOG] 5.95412 ERROR juju worker: exited "authenticationworker": adding current Juju keys to ssh authorised keys: generating key fingerprint: malformed line: "my-keys"
[LOG] 5.95414 INFO juju worker: restarting "authenticationworker" in 50ms
[LOG] 5.95466 DEBUG juju.state.apiserver -> [13] machine-0 832.609us {"RequestId":52,"Response":{"Results":[{"Error":null,"Result":"ardbeg-0"}]}} Provisioner[""].InstanceId
[LOG] 5.95480 DEBUG juju.state.apiserver -> [13] machine-0 948.153us {"RequestId":53,"Response":{"Results":[{"Error":null,"Result":false}]}} Firewaller[""].GetExposed
[LOG] 5.95502 INFO juju.provisioner machine 0 already started as instance "ardbeg-0"
[LOG] 5.95513 DEBUG juju worker/firewaller: started watching unit test-service/0
[LOG] 5.95515 DEBUG juju worker/firewaller: started watching "machine-1"
[LOG] 5.95540 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":55,"Type":"Provisioner","Request":"InstanceId","Params":{"Entities":[{"Tag":"machine-1"}]}}
[LOG] 5.95549 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":56,"Type":"Firewaller","Request":"Life","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 5.95557 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":57,"Type":"Firewaller","Request":"Watch","Params":{"Entities":[{"Tag":"service-test-service"}]}}
[LOG] 5.95569 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":58,"Type":"Firewaller","Request":"Watch","Params":{"Entities":[{"Tag":"unit-test-service-0"}]}}
[LOG] 5.95709 DEBUG juju.state.apiserver -> [13] machine-0 1.566679ms {"RequestId":56,"Response":{"Results":[{"Life":"alive","Error":null}]}} Firewaller[""].Life
[LOG] 5.95778 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":59,"Type":"Firewaller","Request":"Life","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 5.95835 DEBUG juju.state.apiserver -> [13] machine-0 2.911481ms {"RequestId":55,"Response":{"Results":[{"Error":{"Message":"machine 1 is not provisioned","Code":"not provisioned"},"Result":""}]}} Provisioner[""].InstanceId
[LOG] 5.95852 DEBUG juju.state.apiserver -> [13] machine-0 2.930785ms {"RequestId":57,"Response":{"Results":[{"NotifyWatcherId":"11","Error":null}]}} Firewaller[""].Watch
[LOG] 5.95862 DEBUG juju.state.apiserver -> [13] machine-0 2.903358ms {"RequestId":58,"Response":{"Results":[{"NotifyWatcherId":"12","Error":null}]}} Firewaller[""].Watch
[LOG] 5.95907 DEBUG juju.state.apiserver -> [13] machine-0 1.279975ms {"RequestId":59,"Response":{"Results":[{"Life":"alive","Error":null}]}} Firewaller[""].Life
[LOG] 5.95965 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":60,"Type":"Provisioner","Request":"InstanceId","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 5.95975 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":61,"Type":"Firewaller","Request":"Life","Params":{"Entities":[{"Tag":"service-test-service"}]}}
[LOG] 5.95989 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":62,"Type":"Firewaller","Request":"Life","Params":{"Entities":[{"Tag":"unit-test-service-0"}]}}
[LOG] 5.95996 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":63,"Type":"NotifyWatcher","Id":"11","Request":"Next","Params":{}}
[LOG] 5.96001 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":64,"Type":"NotifyWatcher","Id":"12","Request":"Next","Params":{}}
[LOG] 5.96112 DEBUG juju.state.apiserver -> [13] machine-0 1.463466ms {"RequestId":60,"Response":{"Results":[{"Error":null,"Result":"ardbeg-0"}]}} Provisioner[""].InstanceId
[LOG] 5.96134 DEBUG juju.state.apiserver -> [13] machine-0 1.590449ms {"RequestId":61,"Response":{"Results":[{"Life":"alive","Error":null}]}} Firewaller[""].Life
[LOG] 5.96149 DEBUG juju.state.apiserver -> [13] machine-0 1.660909ms {"RequestId":62,"Response":{"Results":[{"Life":"alive","Error":null}]}} Firewaller[""].Life
[LOG] 5.96165 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":65,"Type":"Firewaller","Request":"WatchUnits","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 5.96240 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":66,"Type":"Provisioner","Request":"Constraints","Params":{"Entities":[{"Tag":"machine-1"}]}}
[LOG] 5.96321 DEBUG juju.state.apiserver -> [13] machine-0 804.053us {"RequestId":66,"Response":{"Results":[{"Error":null,"Constraints":{}}]}} Provisioner[""].Constraints
[LOG] 5.96338 DEBUG juju.state.apiserver -> [13] machine-0 1.757659ms {"RequestId":65,"Response":{"Results":[{"StringsWatcherId":"13","Changes":null,"Error":null}]}} Firewaller[""].WatchUnits
[LOG] 5.96354 DEBUG juju worker/firewaller: started watching "machine-0"
[LOG] 5.96428 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":67,"Type":"Firewaller","Request":"GetExposed","Params":{"Entities":[{"Tag":"service-test-service"}]}}
[LOG] 5.96437 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":68,"Type":"Firewaller","Request":"OpenedPorts","Params":{"Entities":[{"Tag":"unit-test-service-0"}]}}
[LOG] 5.96445 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":69,"Type":"Provisioner","Request":"Series","Params":{"Entities":[{"Tag":"machine-1"}]}}
[LOG] 5.96453 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":70,"Type":"Firewaller","Request":"Life","Params":{"Entities":[{"Tag":"machine-1"}]}}
[LOG] 5.96461 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":71,"Type":"StringsWatcher","Id":"13","Request":"Next","Params":{}}
[LOG] 5.96570 DEBUG juju.state.apiserver -> [13] machine-0 1.414972ms {"RequestId":67,"Response":{"Results":[{"Error":null,"Result":false}]}} Firewaller[""].GetExposed
[LOG] 5.96586 DEBUG juju.state.apiserver -> [13] machine-0 1.500521ms {"RequestId":68,"Response":{"Results":[{"Error":null,"Ports":[]}]}} Firewaller[""].OpenedPorts
[LOG] 5.96601 DEBUG juju.state.apiserver -> [13] machine-0 1.537732ms {"RequestId":69,"Response":{"Results":[{"Error":null,"Result":"quantal"}]}} Provisioner[""].Series
[LOG] 5.96613 DEBUG juju.state.apiserver -> [13] machine-0 1.599674ms {"RequestId":70,"Response":{"Results":[{"Life":"alive","Error":null}]}} Firewaller[""].Life
[LOG] 5.96649 INFO juju.environs.tools reading tools with major.minor version 1.17
[LOG] 5.96653 INFO juju.environs.tools filtering tools by version: 1.17.1
[LOG] 5.96654 INFO juju.environs.tools filtering tools by series: quantal
[LOG] 5.96657 DEBUG juju.environs.tools no architecture specified when finding tools, looking for any
[LOG] 5.96667 DEBUG juju.environs.simplestreams fetchData failed for "http://127.0.0.1:35935/dummyenv/private/tools/streams/v1/index.sjson": file "tools/streams/v1/index.sjson" not found not found
[LOG] 5.96671 DEBUG juju.environs.simplestreams cannot load index "http://127.0.0.1:35935/dummyenv/private/tools/streams/v1/index.sjson": invalid URL "http://127.0.0.1:35935/dummyenv/private/tools/streams/v1/index.sjson" not found
[LOG] 5.96686 DEBUG juju.environs.simplestreams fetchData failed for "http://127.0.0.1:35935/dummyenv/private/tools/streams/v1/mirrors.json": file "tools/streams/v1/mirrors.json" not found not found
[LOG] 5.96690 DEBUG juju.environs.simplestreams no mirror index file found
[LOG] 5.96693 DEBUG juju.environs.simplestreams no mirror information available for { }: mirror data for "com.ubuntu.juju:released:tools" not found
[LOG] 5.96694 DEBUG juju.environs.simplestreams read metadata index at "http://127.0.0.1:35935/dummyenv/private/tools/streams/v1/index.json"
[LOG] 5.96702 DEBUG juju.environs.simplestreams candidate matches for products ["com.ubuntu.juju:12.10:amd64" "com.ubuntu.juju:12.10:i386" "com.ubuntu.juju:12.10:arm"] are [{Fri, 24 Jan 2014 20:47:06 +0000 products:1.0 content-download  [] streams/v1/com.ubuntu.juju:released:tools.json [com.ubuntu.juju:12.04:amd64 com.ubuntu.juju:12.10:amd64]}]
[LOG] 5.96714 DEBUG juju.environs.simplestreams finding products at path "streams/v1/com.ubuntu.juju:released:tools.json"
[LOG] 5.96759 DEBUG juju.environs.simplestreams metadata: &{map[com.ubuntu.juju:12.04:amd64:{ 1.17.1 amd64   map[20140124:0xc2006238a0]} com.ubuntu.juju:12.10:amd64:{ 1.17.1 amd64   map[20140124:0xc2006239c0]}] map[] Fri, 24 Jan 2014 20:47:06 +0000 products:1.0 com.ubuntu.juju:released:tools}
[LOG] 5.96803 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":72,"Type":"Provisioner","Request":"SetPasswords","Params":{"Changes":[{"Tag":"machine-1","Password":"MIu+SZXvuS8+P7EZ99aZaw+P"}]}}
[LOG] 5.96817 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":73,"Type":"Firewaller","Request":"InstanceId","Params":{"Entities":[{"Tag":"machine-1"}]}}
[LOG] 5.96996 DEBUG juju.state.apiserver -> [13] machine-0 1.737156ms {"RequestId":73,"Response":{"Results":[{"Error":{"Message":"machine 1 is not provisioned","Code":"not provisioned"},"Result":""}]}} Firewaller[""].InstanceId
[LOG] 5.97166 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":74,"Type":"NotifyWatcher","Id":"5","Request":"Stop","Params":{}}
[LOG] 5.97236 DEBUG juju.state.apiserver -> [13] machine-0 44.100279ms {"RequestId":27,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":{}} NotifyWatcher["5"].Next
[LOG] 5.97246 DEBUG juju.state.apiserver -> [13] machine-0 853.036us {"RequestId":74,"Response":{}} NotifyWatcher["5"].Stop
[LOG] 5.97373 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":75,"Type":"StringsWatcher","Id":"7","Request":"Stop","Params":{}}
[LOG] 5.97417 DEBUG juju.state.apiserver -> [13] machine-0 40.352652ms {"RequestId":31,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":{}} StringsWatcher["7"].Next
[LOG] 5.97426 DEBUG juju.state.apiserver -> [13] machine-0 559.679us {"RequestId":75,"Response":{}} StringsWatcher["7"].Stop
[LOG] 5.97494 INFO juju setting password for "machine-1"
[LOG] 5.97498 DEBUG juju.state.apiserver -> [13] machine-0 6.995969ms {"RequestId":72,"Response":{"Results":[{"Error":null}]}} Provisioner[""].SetPasswords
[LOG] 5.97512 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":76,"Type":"NotifyWatcher","Id":"12","Request":"Stop","Params":{}}
[LOG] 5.97522 DEBUG juju.state.apiserver -> [13] machine-0 15.200785ms {"RequestId":64,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":{}} NotifyWatcher["12"].Next
[LOG] 5.97532 DEBUG juju.state.apiserver -> [13] machine-0 209.185us {"RequestId":76,"Response":{}} NotifyWatcher["12"].Stop
[LOG] 5.97557 INFO juju.provider.dummy dummy startinstance, machine 1
[LOG] 5.97561 INFO juju.provider.dummy would pick tools from 1.17.1-quantal-amd64
[LOG] 5.97598 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":77,"Type":"Provisioner","Request":"SetProvisioned","Params":{"Machines":[{"Tag":"machine-1","InstanceId":"dummyenv-0","Nonce":"machine-0:35b20ea4-f610-4fca-85e4-817d5c2e9195","Characteristics":{"Arch":"amd64","Mem":1024,"RootDisk":8192,"CpuCores":1,"CpuPower":null,"Tags":null}}]}}
[LOG] 5.97604 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":78,"Type":"NotifyWatcher","Id":"11","Request":"Stop","Params":{}}
[LOG] 5.97636 DEBUG juju.state.apiserver -> [13] machine-0 16.397501ms {"RequestId":63,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":{}} NotifyWatcher["11"].Next
[LOG] 5.97642 DEBUG juju.state.apiserver -> [13] machine-0 378.742us {"RequestId":78,"Response":{}} NotifyWatcher["11"].Stop
[LOG] 5.97734 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":79,"Type":"StringsWatcher","Id":"10","Request":"Stop","Params":{}}
[LOG] 5.97741 DEBUG juju.state.apiserver -> [13] machine-0 28.861448ms {"RequestId":45,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":{}} StringsWatcher["10"].Next
[LOG] 5.97750 DEBUG juju.state.apiserver -> [13] machine-0 175.121us {"RequestId":79,"Response":{}} StringsWatcher["10"].Stop
[LOG] 5.97804 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":80,"Type":"StringsWatcher","Id":"13","Request":"Stop","Params":{}}
[LOG] 5.97811 DEBUG juju.state.apiserver -> [13] machine-0 13.501364ms {"RequestId":71,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":{}} StringsWatcher["13"].Next
[LOG] 5.97816 DEBUG juju.state.apiserver -> [13] machine-0 133.157us {"RequestId":80,"Response":{}} StringsWatcher["13"].Stop
[LOG] 5.97869 ERROR juju worker: fatal "firewaller": machine 1 is not provisioned
[LOG] 5.97871 DEBUG juju worker: killing "machiner"
[LOG] 5.97872 DEBUG juju worker: killing "upgrader"
[LOG] 5.97873 DEBUG juju worker: killing "logger"
[LOG] 5.97874 DEBUG juju worker: killing "authenticationworker"
[LOG] 5.97875 DEBUG juju worker: killing "0-container-watcher"
[LOG] 5.97876 DEBUG juju worker: killing "environ-provisioner"
[LOG] 5.97877 DEBUG juju worker: killing "charm-revision-updater"
[LOG] 5.97978 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":81,"Type":"NotifyWatcher","Id":"8","Request":"Stop","Params":{}}
[LOG] 5.97987 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":82,"Type":"NotifyWatcher","Id":"3","Request":"Stop","Params":{}}
[LOG] 5.97992 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":83,"Type":"NotifyWatcher","Id":"2","Request":"Stop","Params":{}}
[LOG] 5.97996 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":84,"Type":"StringsWatcher","Id":"6","Request":"Stop","Params":{}}
[LOG] 5.98008 DEBUG juju.state.apiserver -> [13] machine-0 35.213038ms {"RequestId":39,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":{}} NotifyWatcher["8"].Next
[LOG] 5.98013 DEBUG juju.state.apiserver -> [13] machine-0 379.515us {"RequestId":81,"Response":{}} NotifyWatcher["8"].Stop
[LOG] 5.98019 DEBUG juju.state.apiserver -> [13] machine-0 73.199267ms {"RequestId":18,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":{}} NotifyWatcher["3"].Next
[LOG] 5.98024 DEBUG juju.state.apiserver -> [13] machine-0 374.818us {"RequestId":82,"Response":{}} NotifyWatcher["3"].Stop
[LOG] 5.98028 DEBUG juju.state.apiserver -> [13] machine-0 79.746504ms {"RequestId":15,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":{}} NotifyWatcher["2"].Next
[LOG] 5.98033 DEBUG juju.state.apiserver -> [13] machine-0 409.677us {"RequestId":83,"Response":{}} NotifyWatcher["2"].Stop
[LOG] 5.98037 DEBUG juju.state.apiserver -> [13] machine-0 52.101584ms {"RequestId":28,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":{}} StringsWatcher["6"].Next
[LOG] 5.98042 DEBUG juju.state.apiserver -> [13] machine-0 452.842us {"RequestId":84,"Response":{}} StringsWatcher["6"].Stop
[LOG] 5.98356 DEBUG juju.state.apiserver -> [13] machine-0 7.624061ms {"RequestId":77,"Response":{"Results":[{"Error":null}]}} Provisioner[""].SetProvisioned
[LOG] 5.98374 INFO juju.provisioner started machine 1 as instance dummyenv-0 with hardware "arch=amd64 cpu-cores=1 mem=1024M root-disk=8192M"
[LOG] 5.98375 INFO juju.provisioner Shutting down provisioner task machine-0
[LOG] 5.98392 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":85,"Type":"StringsWatcher","Id":"9","Request":"Stop","Params":{}}
[LOG] 5.98400 DEBUG juju.state.apiserver -> [13] machine-0 36.286923ms {"RequestId":42,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":{}} StringsWatcher["9"].Next
[LOG] 5.98405 DEBUG juju.state.apiserver -> [13] machine-0 143.533us {"RequestId":85,"Response":{}} StringsWatcher["9"].Stop
[LOG] 5.98425 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":86,"Type":"NotifyWatcher","Id":"4","Request":"Stop","Params":{}}
[LOG] 5.98430 DEBUG juju.state.apiserver -> [13] machine-0 56.136874ms {"RequestId":26,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":{}} NotifyWatcher["4"].Next
[LOG] 5.98436 DEBUG juju.state.apiserver -> [13] machine-0 120.499us {"RequestId":86,"Response":{}} NotifyWatcher["4"].Stop
[LOG] 6.00455 INFO juju worker: start "authenticationworker"
[LOG] 6.00497 DEBUG juju worker: killing "authenticationworker"
[LOG] 6.00538 DEBUG juju.state.apiserver <- [13] machine-0 {"RequestId":87,"Type":"KeyUpdater","Request":"AuthorisedKeys","Params":{"Entities":[{"Tag":"machine-0"}]}}
[LOG] 6.01173 DEBUG juju.state.apiserver -> [13] machine-0 6.209389ms {"RequestId":87,"Response":{"Results":[{"Error":null,"Result":["my-keys"]}]}} KeyUpdater[""].AuthorisedKeys
[LOG] 6.01295 DEBUG juju.utils.ssh reading authorised keys file /tmp/gocheck-2202916659517317514/70/.ssh/authorized_keys
[LOG] 6.01318 WARNING juju.utils.ssh invalid Juju ssh key my-keys: malformed line: "my-keys"
[LOG] 6.01349 DEBUG juju.utils.ssh reading authorised keys file /tmp/gocheck-2202916659517317514/70/.ssh/authorized_keys
[LOG] 6.01362 ERROR juju.worker.authenticationworker adding current Juju keys to ssh authorised keys: generating key fingerprint: malformed line: "my-keys"
[LOG] 6.01484 ERROR juju worker: exited "authenticationworker": adding current Juju keys to ssh authorised keys: generating key fingerprint: malformed line: "my-keys"
[LOG] 6.01535 ERROR juju worker: fatal "api": machine 1 is not provisioned
[LOG] 6.01542 DEBUG juju worker: killing "state"
[LOG] 6.01548 DEBUG juju worker: killing runner 0xc200e08c00
[LOG] 6.01557 DEBUG juju worker: killing "termination"
[LOG] 6.01562 INFO juju worker: runner is dying
[LOG] 6.01570 DEBUG juju worker: killing "instancepoller"
[LOG] 6.01573 DEBUG juju worker: killing "apiserver"
[LOG] 6.01585 DEBUG juju worker: killing "cleaner"
[LOG] 6.01595 DEBUG juju worker: killing "resumer"
[LOG] 6.01603 DEBUG juju worker: killing "minunitsworker"
[LOG] 6.02001 INFO juju.state.apiserver [13] API connection terminated after 143.834127ms
machine_test.go:342:
    c.Check(a.Run(nil), gc.IsNil)
... value *params.Error = &params.Error{"not provisioned", "machine 1 is not provisioned"} ("machine 1 is not provisioned")

unit provisioned with instance dummyenv-0
final machine addresses: []instance.Address(nil)
machine_test.go:361:
    c.Fatalf("timed out waiting for machine to get address")
... Error: timed out waiting for machine to get address

[LOG] 20.66378 DEBUG juju worker: killing runner 0xc200dc0a20
[LOG] 20.66632 INFO juju.provider.dummy reset environment
[LOG] 20.66671 INFO juju.state.apiserver [12] API connection terminated after 14.951551231s
[LOG] 20.67640 INFO juju Reset successfully reset admin password
[LOG] 20.69089 INFO juju Reset successfully reset admin password
[LOG] 20.69705 INFO juju Reset successfully reset admin password
[jujuc whatever]
[remote]
[/path/to/remote]
[remote --help]
[unknown]
[remote --error borken]
[remote --unknown]
[remote unwanted]
OOPS: 51 passed, 3 skipped, 2 FAILED
--- FAIL: TestPackage (77.37 seconds)
FAIL
FAIL	launchpad.net/juju-core/cmd/jujud	77.656s
ok  	launchpad.net/juju-core/cmd/plugins/juju-metadata	10.645s
?   	launchpad.net/juju-core/cmd/plugins/juju-restore	[no test files]
ok  	launchpad.net/juju-core/constraints	0.030s
ok  	launchpad.net/juju-core/container	0.038s
ok  	launchpad.net/juju-core/container/factory	0.069s
ok  	launchpad.net/juju-core/container/kvm	0.382s
ok  	launchpad.net/juju-core/container/kvm/mock	0.063s
?   	launchpad.net/juju-core/container/kvm/testing	[no test files]
ok  	launchpad.net/juju-core/container/lxc	0.348s
?   	launchpad.net/juju-core/container/lxc/mock	[no test files]
?   	launchpad.net/juju-core/container/lxc/testing	[no test files]
?   	launchpad.net/juju-core/container/testing	[no test files]
ok  	launchpad.net/juju-core/downloader	5.267s
ok  	launchpad.net/juju-core/environs	3.215s
ok  	launchpad.net/juju-core/environs/bootstrap	4.709s
ok  	launchpad.net/juju-core/environs/cloudinit	0.646s
ok  	launchpad.net/juju-core/environs/config	2.629s
ok  	launchpad.net/juju-core/environs/configstore	0.083s
ok  	launchpad.net/juju-core/environs/filestorage	0.033s
ok  	launchpad.net/juju-core/environs/httpstorage	1.276s
ok  	launchpad.net/juju-core/environs/imagemetadata	0.884s
?   	launchpad.net/juju-core/environs/imagemetadata/testing	[no test files]
ok  	launchpad.net/juju-core/environs/instances	0.072s
ok  	launchpad.net/juju-core/environs/jujutest	0.255s
ok  	launchpad.net/juju-core/environs/manual	11.517s
ok  	launchpad.net/juju-core/environs/simplestreams	0.397s
?   	launchpad.net/juju-core/environs/simplestreams/testing	[no test files]
ok  	launchpad.net/juju-core/environs/sshstorage	2.210s
ok  	launchpad.net/juju-core/environs/storage	1.353s
ok  	launchpad.net/juju-core/environs/sync	36.774s
ok  	launchpad.net/juju-core/environs/testing	0.208s
ok  	launchpad.net/juju-core/environs/tools	7.426s
?   	launchpad.net/juju-core/environs/tools/testing	[no test files]
ok  	launchpad.net/juju-core/errors	0.023s
ok  	launchpad.net/juju-core/instance	0.026s
?   	launchpad.net/juju-core/instance/testing	[no test files]
ok  	launchpad.net/juju-core/juju	29.121s
ok  	launchpad.net/juju-core/juju/osenv	0.020s
?   	launchpad.net/juju-core/juju/testing	[no test files]
ok  	launchpad.net/juju-core/log	0.026s
ok  	launchpad.net/juju-core/log/syslog	0.024s
ok  	launchpad.net/juju-core/names	0.027s
?   	launchpad.net/juju-core/provider	[no test files]
?   	launchpad.net/juju-core/provider/all	[no test files]
ok  	launchpad.net/juju-core/provider/azure	6.796s
ok  	launchpad.net/juju-core/provider/common	8.085s
ok  	launchpad.net/juju-core/provider/dummy	25.760s
ok  	launchpad.net/juju-core/provider/ec2	17.622s
ok  	launchpad.net/juju-core/provider/joyent	5.301s
ok  	launchpad.net/juju-core/provider/local	5.172s
ok  	launchpad.net/juju-core/provider/maas	20.565s
ok  	launchpad.net/juju-core/provider/null	1.256s
ok  	launchpad.net/juju-core/provider/openstack	34.897s
ok  	launchpad.net/juju-core/replicaset	48.079s
ok  	launchpad.net/juju-core/rpc	0.099s
ok  	launchpad.net/juju-core/rpc/jsoncodec	0.045s
?   	launchpad.net/juju-core/rpc/rpcreflect	[no test files]
ok  	launchpad.net/juju-core/schema	0.038s
ok  	launchpad.net/juju-core/state	103.825s
ok  	launchpad.net/juju-core/state/api	2.228s
ok  	launchpad.net/juju-core/state/api/agent	2.014s
?   	launchpad.net/juju-core/state/api/base	[no test files]
ok  	launchpad.net/juju-core/state/api/charmrevisionupdater	1.730s
?   	launchpad.net/juju-core/state/api/common	[no test files]
?   	launchpad.net/juju-core/state/api/common/testing	[no test files]
ok  	launchpad.net/juju-core/state/api/deployer	6.904s
ok  	launchpad.net/juju-core/state/api/firewaller	12.972s
ok  	launchpad.net/juju-core/state/api/keymanager	3.721s
ok  	launchpad.net/juju-core/state/api/keyupdater	2.957s
ok  	launchpad.net/juju-core/state/api/logger	2.649s
ok  	launchpad.net/juju-core/state/api/machiner	4.014s
ok  	launchpad.net/juju-core/state/api/params	0.040s
ok  	launchpad.net/juju-core/state/api/provisioner	10.844s
ok  	launchpad.net/juju-core/state/api/uniter	30.629s
ok  	launchpad.net/juju-core/state/api/upgrader	4.199s
ok  	launchpad.net/juju-core/state/api/watcher	3.652s
ok  	launchpad.net/juju-core/state/apiserver	8.680s
ok  	launchpad.net/juju-core/state/apiserver/agent	3.308s
ok  	launchpad.net/juju-core/state/apiserver/charmrevisionupdater	2.641s
?   	launchpad.net/juju-core/state/apiserver/charmrevisionupdater/testing	[no test files]
ok  	launchpad.net/juju-core/state/apiserver/client	46.127s
ok  	launchpad.net/juju-core/state/apiserver/common	2.121s
?   	launchpad.net/juju-core/state/apiserver/common/testing	[no test files]
ok  	launchpad.net/juju-core/state/apiserver/deployer	4.853s
ok  	launchpad.net/juju-core/state/apiserver/firewaller	6.281s
ok  	launchpad.net/juju-core/state/apiserver/keymanager	4.343s
?   	launchpad.net/juju-core/state/apiserver/keymanager/testing	[no test files]
ok  	launchpad.net/juju-core/state/apiserver/keyupdater	3.763s
ok  	launchpad.net/juju-core/state/apiserver/logger	4.409s
ok  	launchpad.net/juju-core/state/apiserver/machine	3.412s
ok  	launchpad.net/juju-core/state/apiserver/provisioner	13.169s
?   	launchpad.net/juju-core/state/apiserver/testing	[no test files]
ok  	launchpad.net/juju-core/state/apiserver/uniter	22.723s
ok  	launchpad.net/juju-core/state/apiserver/upgrader	6.703s
ok  	launchpad.net/juju-core/state/multiwatcher	0.763s
ok  	launchpad.net/juju-core/state/presence	6.808s
ok  	launchpad.net/juju-core/state/statecmd	2.045s
?   	launchpad.net/juju-core/state/testing	[no test files]
ok  	launchpad.net/juju-core/state/watcher	7.895s
ok  	launchpad.net/juju-core/store	26.483s
ok  	launchpad.net/juju-core/testing	1.394s
ok  	launchpad.net/juju-core/testing/checkers	0.035s
ok  	launchpad.net/juju-core/testing/testbase	0.020s
ok  	launchpad.net/juju-core/thirdparty/pbkdf2	0.136s
ok  	launchpad.net/juju-core/tools	0.045s
ok  	launchpad.net/juju-core/upstart	1.218s
ok  	launchpad.net/juju-core/utils	2.458s
ok  	launchpad.net/juju-core/utils/exec	0.041s
ok  	launchpad.net/juju-core/utils/fslock	0.943s
ok  	launchpad.net/juju-core/utils/parallel	0.993s
ok  	launchpad.net/juju-core/utils/set	0.017s
ok  	launchpad.net/juju-core/utils/ssh	25.659s
?   	launchpad.net/juju-core/utils/ssh/testing	[no test files]
ok  	launchpad.net/juju-core/utils/tailer	1.007s
ok  	launchpad.net/juju-core/version	0.106s
ok  	launchpad.net/juju-core/worker	6.744s
ok  	launchpad.net/juju-core/worker/authenticationworker	3.388s
ok  	launchpad.net/juju-core/worker/charmrevisionworker	2.451s
ok  	launchpad.net/juju-core/worker/cleaner	1.369s
ok  	launchpad.net/juju-core/worker/deployer	4.089s
ok  	launchpad.net/juju-core/worker/firewaller	14.518s
ok  	launchpad.net/juju-core/worker/instancepoller	2.747s
ok  	launchpad.net/juju-core/worker/localstorage	0.055s
ok  	launchpad.net/juju-core/worker/logger	1.536s
ok  	launchpad.net/juju-core/worker/machiner	3.668s
ok  	launchpad.net/juju-core/worker/minunitsworker	1.416s
ok  	launchpad.net/juju-core/worker/provisioner	45.483s
ok  	launchpad.net/juju-core/worker/resumer	1.674s
ok  	launchpad.net/juju-core/worker/terminationworker	0.068s
ok  	launchpad.net/juju-core/worker/uniter	196.133s
ok  	launchpad.net/juju-core/worker/uniter/charm	5.459s
ok  	launchpad.net/juju-core/worker/uniter/debug	0.188s
ok  	launchpad.net/juju-core/worker/uniter/hook	0.016s
ok  	launchpad.net/juju-core/worker/uniter/jujuc	0.482s
ok  	launchpad.net/juju-core/worker/uniter/relation	2.015s
ok  	launchpad.net/juju-core/worker/upgrader	5.971s

warning: building out-of-date packages:
	launchpad.net/lpad
	launchpad.net/goamz/ec2/ec2test
	launchpad.net/goamz/s3/s3test
	launchpad.net/goose/testservices/hook
	launchpad.net/goose/testservices/identityservice
	launchpad.net/goose/testservices
	launchpad.net/goose/testservices/novaservice
	launchpad.net/goose/testservices/swiftservice
	launchpad.net/goose/testservices/openstackservice
installing these packages with 'go test -i ./...' will speed future tests.