The attempt to merge lp:~mfoord/juju-core/jenv-warning into lp:juju-core failed. Below is the output from the failed tests. ok launchpad.net/juju-core 0.018s ok launchpad.net/juju-core/agent 0.964s ok launchpad.net/juju-core/agent/tools 0.196s ---------------------------------------------------------------------- FAIL: bzr_test.go:26: BzrSuite.SetUpTest bzr_test.go:28: c.Assert(s.b.Init(), gc.IsNil) ... value *errors.errorString = &errors.errorString{s:"error running \"bzr init\": exec: \"bzr\": executable file not found in $PATH"} ("error running \"bzr init\": exec: \"bzr\": executable file not found in $PATH") ---------------------------------------------------------------------- PANIC: bzr_test.go:128: BzrSuite.TestCheckClean ... Panic: Fixture has panicked (see related PANIC) OOPS: 0 passed, 1 FAILED, 8 MISSED --- FAIL: Test (0.00 seconds) FAIL FAIL launchpad.net/juju-core/bzr 0.012s ok launchpad.net/juju-core/cert 2.684s ok launchpad.net/juju-core/charm 0.371s ? 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.025s ok launchpad.net/juju-core/cloudinit/sshinit 0.952s ok launchpad.net/juju-core/cmd 0.164s ok launchpad.net/juju-core/cmd/charm-admin 0.750s ? launchpad.net/juju-core/cmd/charmd [no test files] ? launchpad.net/juju-core/cmd/charmload [no test files] ---------------------------------------------------------------------- FAIL: bootstrap_test.go:320: BootstrapSuite.TestBootstrapJenvWarning [LOG] 60.02503 DEBUG juju.environs.tools no architecture specified when finding tools, looking for any [LOG] 60.02503 DEBUG juju.environs.tools no series specified when finding tools, looking for any [LOG] 60.02507 DEBUG juju.environs.simplestreams fetchData failed for "file:///tmp/gocheck-4751997750760398084/21/tools/streams/v1/index.sjson": stat /tmp/gocheck-4751997750760398084/21/tools/streams/v1/index.sjson: no such file or directory [LOG] 60.02510 DEBUG juju.environs.simplestreams cannot load index "file:///tmp/gocheck-4751997750760398084/21/tools/streams/v1/index.sjson": invalid URL "file:///tmp/gocheck-4751997750760398084/21/tools/streams/v1/index.sjson" not found [LOG] 60.02512 DEBUG juju.environs.simplestreams fetchData failed for "file:///tmp/gocheck-4751997750760398084/21/tools/streams/v1/index.json": stat /tmp/gocheck-4751997750760398084/21/tools/streams/v1/index.json: no such file or directory [LOG] 60.02515 DEBUG juju.environs.simplestreams cannot load index "file:///tmp/gocheck-4751997750760398084/21/tools/streams/v1/index.json": invalid URL "file:///tmp/gocheck-4751997750760398084/21/tools/streams/v1/index.json" not found [LOG] 60.02575 INFO juju.environs.tools Writing tools/streams/v1/index.json [LOG] 60.02592 INFO juju.environs.tools Writing tools/streams/v1/com.ubuntu.juju:released:tools.json [LOG] 60.02616 INFO juju.provider.dummy reset environment [LOG] 60.02827 INFO juju Reset successfully reset admin password [LOG] 60.02879 DEBUG juju.environs.configstore Making /tmp/gocheck-4751997750760398084/22/.juju/environments clearing private storage removing files: [] [LOG] 60.14035 DEBUG juju.environs ConfigForName found bootstrap config map[string]interface {}{"bootstrap-timeout":600, "logging-config":"=WARNING;juju=DEBUG;unit=DEBUG", "ca-cert":"-----BEGIN CERTIFICATE-----\nMIIB2DCCAYSgAwIBAgIBADALBgkqhkiG9w0BAQUwRTENMAsGA1UEChMEanVqdTE0\nMDIGA1UEAwwranVqdS1nZW5lcmF0ZWQgQ0EgZm9yIGVudmlyb25tZW50ICJwZWNr\naGFtIjAeFw0xNDAzMDYxNzM5NDFaFw0yNDAzMDYxNzQ0NDFaMEUxDTALBgNVBAoT\nBGp1anUxNDAyBgNVBAMMK2p1anUtZ2VuZXJhdGVkIENBIGZvciBlbnZpcm9ubWVu\ndCAicGVja2hhbSIwWjALBgkqhkiG9w0BAQEDSwAwSAJBAJt7+f2iok1/gP2j3Y2B\nVbKiLHJRgHucjEjZJRzIQ7teB0s3ZEmXwM/Di2oKCiktAtWYvXxW4EhcOVgiWi+7\njsUCAwEAAaNjMGEwDgYDVR0PAQH/BAQDAgCkMA8GA1UdEwEB/wQFMAMBAf8wHQYD\nVR0OBBYEFEy/heai7KbvS4yxRKX8owvtT4Q2MB8GA1UdIwQYMBaAFEy/heai7Kbv\nS4yxRKX8owvtT4Q2MAsGCSqGSIb3DQEBBQNBAEloaHJGMFNeQ6GsrkwLOHZ9pLeh\n4egU/0OHvWb0uKDt6BvlsAMA2UNT2JXoOdsz8zPWPIJPnW8X8sHcaB+7n7o=\n-----END CERTIFICATE-----\n", "firewall-mode":"instance", "image-stream":"", "name":"peckham", "ssl-hostname-verification":true, "state-server":false, "syslog-port":6514, "api-port":17070, "authorized-keys":"i-am-a-key", "broken":"", "default-series":"raring", "image-metadata-url":"", "secret":"pork", "state-port":37017, "tools-metadata-url":"", "tools-url":"", "admin-secret":"arble", "bootstrap-addresses-delay":10, "bootstrap-retry-delay":5, "ca-private-key":"-----BEGIN RSA PRIVATE KEY-----\nMIIBPAIBAAJBAJt7+f2iok1/gP2j3Y2BVbKiLHJRgHucjEjZJRzIQ7teB0s3ZEmX\nwM/Di2oKCiktAtWYvXxW4EhcOVgiWi+7jsUCAwEAAQJBAJPfmAVSPJwKDKqtwxNG\nkzN+K1laDCED5SOPaU1zZX921WfGuWP3yt8DPzGVR3vPbZddCDmF+KXsyUfrATu1\ngG0CIQDGkEeEwBgRzrNFFLOEZbgrQAehwaRPEVksvEm73YuGawIhAMh1p9ThTXLa\nvhimNSFh20M9aixj237C8Zaqo6aghquPAiAC4yw3EPgIokHXGlL19Oi1sEusHX2/\nLJhoXyCPW8xgmwIhAJiC0zamV2tLuxc71O5Z6hzFK/Mr4gIWRQHRP4L1XKBHAiEA\npytlKofxhHbbhKXw0doPJpwyAARzQy+7TiLbIO3dUjI=\n-----END RSA PRIVATE KEY-----\n", "charm-store-auth":"", "development":false, "state-id":"33", "type":"dummy"} [LOG] 60.15392 DEBUG juju.environs.configstore Making /tmp/gocheck-4751997750760398084/22/.juju/environments [LOG] 60.15395 INFO juju.environs environment info already exists; using New not Prepare [LOG] 60.19411 WARNING juju.cmd.juju ignoring environments.yaml: using bootstrap config in file "/tmp/gocheck-4751997750760398084/22/.juju/environments/peckham.jenv" [LOG] 60.19480 DEBUG juju.environs ConfigForName found bootstrap config map[string]interface {}{"ca-cert":"-----BEGIN CERTIFICATE-----\nMIIB2DCCAYSgAwIBAgIBADALBgkqhkiG9w0BAQUwRTENMAsGA1UEChMEanVqdTE0\nMDIGA1UEAwwranVqdS1nZW5lcmF0ZWQgQ0EgZm9yIGVudmlyb25tZW50ICJwZWNr\naGFtIjAeFw0xNDAzMDYxNzM5NDFaFw0yNDAzMDYxNzQ0NDFaMEUxDTALBgNVBAoT\nBGp1anUxNDAyBgNVBAMMK2p1anUtZ2VuZXJhdGVkIENBIGZvciBlbnZpcm9ubWVu\ndCAicGVja2hhbSIwWjALBgkqhkiG9w0BAQEDSwAwSAJBAJt7+f2iok1/gP2j3Y2B\nVbKiLHJRgHucjEjZJRzIQ7teB0s3ZEmXwM/Di2oKCiktAtWYvXxW4EhcOVgiWi+7\njsUCAwEAAaNjMGEwDgYDVR0PAQH/BAQDAgCkMA8GA1UdEwEB/wQFMAMBAf8wHQYD\nVR0OBBYEFEy/heai7KbvS4yxRKX8owvtT4Q2MB8GA1UdIwQYMBaAFEy/heai7Kbv\nS4yxRKX8owvtT4Q2MAsGCSqGSIb3DQEBBQNBAEloaHJGMFNeQ6GsrkwLOHZ9pLeh\n4egU/0OHvWb0uKDt6BvlsAMA2UNT2JXoOdsz8zPWPIJPnW8X8sHcaB+7n7o=\n-----END CERTIFICATE-----\n", "ca-private-key":"-----BEGIN RSA PRIVATE KEY-----\nMIIBPAIBAAJBAJt7+f2iok1/gP2j3Y2BVbKiLHJRgHucjEjZJRzIQ7teB0s3ZEmX\nwM/Di2oKCiktAtWYvXxW4EhcOVgiWi+7jsUCAwEAAQJBAJPfmAVSPJwKDKqtwxNG\nkzN+K1laDCED5SOPaU1zZX921WfGuWP3yt8DPzGVR3vPbZddCDmF+KXsyUfrATu1\ngG0CIQDGkEeEwBgRzrNFFLOEZbgrQAehwaRPEVksvEm73YuGawIhAMh1p9ThTXLa\nvhimNSFh20M9aixj237C8Zaqo6aghquPAiAC4yw3EPgIokHXGlL19Oi1sEusHX2/\nLJhoXyCPW8xgmwIhAJiC0zamV2tLuxc71O5Z6hzFK/Mr4gIWRQHRP4L1XKBHAiEA\npytlKofxhHbbhKXw0doPJpwyAARzQy+7TiLbIO3dUjI=\n-----END RSA PRIVATE KEY-----\n", "charm-store-auth":"", "firewall-mode":"instance", "secret":"pork", "admin-secret":"arble", "bootstrap-retry-delay":5, "development":false, "logging-config":"=WARNING;juju=DEBUG;unit=DEBUG", "syslog-port":6514, "tools-metadata-url":"", "api-port":17070, "bootstrap-addresses-delay":10, "broken":"", "state-id":"33", "state-server":false, "tools-url":"", "type":"dummy", "authorized-keys":"i-am-a-key", "bootstrap-timeout":600, "default-series":"raring", "image-metadata-url":"", "image-stream":"", "name":"peckham", "ssl-hostname-verification":true, "state-port":37017} [LOG] 60.20714 DEBUG juju.environs.configstore Making /tmp/gocheck-4751997750760398084/22/.juju/environments [LOG] 60.20718 INFO juju.environs environment info already exists; using New not Prepare [LOG] 60.24476 INFO juju.environs.bootstrap bootstrapping environment "peckham" [LOG] 60.24478 DEBUG juju.environs.bootstrap looking for bootstrap tools: series="raring", arch=, version= [LOG] 60.24480 INFO juju.environs.tools reading tools with major.minor version 1.17 [LOG] 60.24480 INFO juju.environs.tools filtering tools by series: raring [LOG] 60.24482 DEBUG juju.environs.tools no architecture specified when finding tools, looking for any [LOG] 60.24485 DEBUG juju.environs.simplestreams fetchData failed for "tools/streams/v1/index.sjson": file "tools/streams/v1/index.sjson" not found not found [LOG] 60.24486 DEBUG juju.environs.simplestreams cannot load index "streams/v1/index.sjson": invalid URL "tools/streams/v1/index.sjson" not found [LOG] 60.24488 DEBUG juju.environs.simplestreams fetchData failed for "tools/streams/v1/index.json": file "tools/streams/v1/index.json" not found not found [LOG] 60.24490 DEBUG juju.environs.simplestreams cannot load index "streams/v1/index.json": invalid URL "tools/streams/v1/index.json" not found [LOG] 60.24500 DEBUG juju.environs.simplestreams fetchData failed for "file:///tmp/gocheck-4751997750760398084/21/tools/streams/v1/index.sjson": cannot find URL "file:///tmp/gocheck-4751997750760398084/21/tools/streams/v1/index.sjson" not found [LOG] 60.24502 DEBUG juju.environs.simplestreams cannot load index "file:///tmp/gocheck-4751997750760398084/21/tools/streams/v1/index.sjson": invalid URL "file:///tmp/gocheck-4751997750760398084/21/tools/streams/v1/index.sjson" not found [LOG] 60.24522 DEBUG juju.environs.simplestreams fetchData failed for "file:///tmp/gocheck-4751997750760398084/21/tools/streams/v1/mirrors.json": cannot find URL "file:///tmp/gocheck-4751997750760398084/21/tools/streams/v1/mirrors.json" not found [LOG] 60.24524 DEBUG juju.environs.simplestreams no mirror index file found [LOG] 60.24525 DEBUG juju.environs.simplestreams no mirror information available for { }: mirror data for "com.ubuntu.juju:released:tools" not found [LOG] 60.24526 DEBUG juju.environs.simplestreams read metadata index at "file:///tmp/gocheck-4751997750760398084/21/tools/streams/v1/index.json" [LOG] 60.24531 DEBUG juju.environs.simplestreams candidate matches for products ["com.ubuntu.juju:13.04:amd64" "com.ubuntu.juju:13.04:i386" "com.ubuntu.juju:13.04:arm" "com.ubuntu.juju:13.04:arm64"] are [{Thu, 06 Mar 2014 17:44:41 +0000 products:1.0 content-download [] streams/v1/com.ubuntu.juju:released:tools.json [com.ubuntu.juju:12.04:amd64 com.ubuntu.juju:12.04:i386 com.ubuntu.juju:12.10:amd64 com.ubuntu.juju:12.10:i386 com.ubuntu.juju:13.04:amd64]}] [LOG] 60.24532 DEBUG juju.environs.simplestreams finding products at path "streams/v1/com.ubuntu.juju:released:tools.json" [LOG] 60.24624 DEBUG juju.environs.simplestreams metadata: &{map[com.ubuntu.juju:12.04:amd64:{ 1.0.0 amd64 map[20140306:0xc201884e40]} com.ubuntu.juju:12.04:i386:{ 1.9.0 i386 map[20140306:0xc201884f60]} com.ubuntu.juju:12.10:amd64:{ 1.9.0 amd64 map[20140306:0xc2018a30c0]} com.ubuntu.juju:12.10:i386:{ 1.2.0 i386 map[20140306:0xc2018a31e0]} com.ubuntu.juju:13.04:amd64:{ 1.0.0 amd64 map[20140306:0xc2018a3300]}] map[] Thu, 06 Mar 2014 17:44:41 +0000 products:1.0 com.ubuntu.juju:released:tools} [LOG] 60.24628 DEBUG juju.environs.simplestreams index has no matching records [LOG] 60.24629 WARNING juju.environs.bootstrap no tools available, attempting to retrieve from /tmp/gocheck-4751997750760398084/21 [LOG] 60.24631 INFO juju.environs.sync using sync tools source: file:///tmp/gocheck-4751997750760398084/21/tools [LOG] 60.24632 INFO juju.environs.sync listing available tools [LOG] 60.24632 DEBUG juju.environs.tools no architecture specified when finding tools, looking for any [LOG] 60.24633 DEBUG juju.environs.tools no series specified when finding tools, looking for any [LOG] 60.24637 DEBUG juju.environs.simplestreams fetchData failed for "file:///tmp/gocheck-4751997750760398084/21/tools/streams/v1/index.sjson": cannot find URL "file:///tmp/gocheck-4751997750760398084/21/tools/streams/v1/index.sjson" not found [LOG] 60.24639 DEBUG juju.environs.simplestreams cannot load index "file:///tmp/gocheck-4751997750760398084/21/tools/streams/v1/index.sjson": invalid URL "file:///tmp/gocheck-4751997750760398084/21/tools/streams/v1/index.sjson" not found [LOG] 60.24653 DEBUG juju.environs.simplestreams fetchData failed for "file:///tmp/gocheck-4751997750760398084/21/tools/streams/v1/mirrors.json": cannot find URL "file:///tmp/gocheck-4751997750760398084/21/tools/streams/v1/mirrors.json" not found [LOG] 60.24654 DEBUG juju.environs.simplestreams no mirror index file found [LOG] 60.24656 DEBUG juju.environs.simplestreams no mirror information available for { }: mirror data for "com.ubuntu.juju:released:tools" not found [LOG] 60.24657 DEBUG juju.environs.simplestreams read metadata index at "file:///tmp/gocheck-4751997750760398084/21/tools/streams/v1/index.json" [LOG] 60.24664 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.04:arm64" "com.ubuntu.juju:12.10:amd64" "com.ubuntu.juju:12.10:i386" "com.ubuntu.juju:12.10:arm" "com.ubuntu.juju:12.10:arm64" "com.ubuntu.juju:13.04:amd64" "com.ubuntu.juju:13.04:i386" "com.ubuntu.juju:13.04:arm" "com.ubuntu.juju:13.04:arm64" "com.ubuntu.juju:13.10:amd64" "com.ubuntu.juju:13.10:i386" "com.ubuntu.juju:13.10:arm" "com.ubuntu.juju:13.10:arm64" "com.ubuntu.juju:14.04:amd64" "com.ubuntu.juju:14.04:i386" "com.ubuntu.juju:14.04:arm" "com.ubuntu.juju:14.04:arm64"] are [{Thu, 06 Mar 2014 17:44:41 +0000 products:1.0 content-download [] streams/v1/com.ubuntu.juju:released:tools.json [com.ubuntu.juju:12.04:amd64 com.ubuntu.juju:12.04:i386 com.ubuntu.juju:12.10:amd64 com.ubuntu.juju:12.10:i386 com.ubuntu.juju:13.04:amd64]}] [LOG] 60.24666 DEBUG juju.environs.simplestreams finding products at path "streams/v1/com.ubuntu.juju:released:tools.json" [LOG] 60.24756 DEBUG juju.environs.simplestreams metadata: &{map[com.ubuntu.juju:12.04:amd64:{ 1.0.0 amd64 map[20140306:0xc2018a6b40]} com.ubuntu.juju:12.04:i386:{ 1.9.0 i386 map[20140306:0xc2018a6c60]} com.ubuntu.juju:12.10:amd64:{ 1.9.0 amd64 map[20140306:0xc2018a6d80]} com.ubuntu.juju:12.10:i386:{ 1.2.0 i386 map[20140306:0xc2018a6f00]} com.ubuntu.juju:13.04:amd64:{ 1.0.0 amd64 map[20140306:0xc2018be060]}] map[] Thu, 06 Mar 2014 17:44:41 +0000 products:1.0 com.ubuntu.juju:released:tools} [LOG] 60.24766 DEBUG juju.environs.simplestreams index has no matching records [LOG] 60.24767 WARNING juju.environs.bootstrap no tools found, so attempting to build and upload new tools [LOG] 60.24768 DEBUG juju.environs.sync Uploading tools for [raring precise] [LOG] 60.24778 DEBUG juju.environs.tools looking for: /tmp/go-build377082666/launchpad.net/juju-core/cmd/juju/_test/juju.test [LOG] 60.24779 DEBUG juju.environs.tools checking: /tmp/go-build377082666/launchpad.net/juju-core/cmd/juju/_test/jujud [LOG] 60.24780 INFO juju.environs.tools couldn't find existing jujud [LOG] 60.24781 DEBUG juju.environs.tools copy existing failed: stat /tmp/go-build377082666/launchpad.net/juju-core/cmd/juju/_test/jujud: no such file or directory [LOG] 60.24782 INFO juju.environs.tools building jujud [LOG] 64.77585 DEBUG juju.environs.tools forcing version to 1.17.5.1 [LOG] 64.99864 DEBUG juju.environs.tools adding entry: &tar.Header{Name:"FORCE-VERSION", Mode:436, Uid:0, Gid:0, Size:8, ModTime:time.Time{sec:63529724685, nsec:897896999, loc:(*time.Location)(0x1698360)}, Typeflag:0x30, Linkname:"", Uname:"ubuntu", Gname:"ubuntu", Devmajor:0, Devminor:0, AccessTime:time.Time{sec:63529724685, nsec:897896999, loc:(*time.Location)(0x1698360)}, ChangeTime:time.Time{sec:63529724685, nsec:897896999, loc:(*time.Location)(0x1698360)}} [LOG] 64.99957 DEBUG juju.environs.tools adding entry: &tar.Header{Name:"jujud", Mode:509, Uid:0, Gid:0, Size:17294336, ModTime:time.Time{sec:63529724685, nsec:889896999, loc:(*time.Location)(0x1698360)}, Typeflag:0x30, Linkname:"", Uname:"ubuntu", Gname:"ubuntu", Devmajor:0, Devminor:0, AccessTime:time.Time{sec:63529724685, nsec:889896999, loc:(*time.Location)(0x1698360)}, ChangeTime:time.Time{sec:63529724685, nsec:889896999, loc:(*time.Location)(0x1698360)}} [LOG] 68.06472 INFO juju.environs.sync built tools 1.17.5.1-precise-amd64 (3734kB) [LOG] 68.06484 DEBUG juju.environs.sync generating tarballs for [raring precise] [LOG] 68.07315 DEBUG juju.environs.sync generating tools metadata [LOG] 68.07318 DEBUG juju.environs.tools no architecture specified when finding tools, looking for any [LOG] 68.07319 DEBUG juju.environs.tools no series specified when finding tools, looking for any [LOG] 68.07324 DEBUG juju.environs.simplestreams fetchData failed for "file:///tmp/587746733/tools/streams/v1/index.sjson": stat /tmp/587746733/tools/streams/v1/index.sjson: no such file or directory [LOG] 68.07326 DEBUG juju.environs.simplestreams cannot load index "file:///tmp/587746733/tools/streams/v1/index.sjson": invalid URL "file:///tmp/587746733/tools/streams/v1/index.sjson" not found [LOG] 68.07328 DEBUG juju.environs.simplestreams fetchData failed for "file:///tmp/587746733/tools/streams/v1/index.json": stat /tmp/587746733/tools/streams/v1/index.json: no such file or directory [LOG] 68.07329 DEBUG juju.environs.simplestreams cannot load index "file:///tmp/587746733/tools/streams/v1/index.json": invalid URL "file:///tmp/587746733/tools/streams/v1/index.json" not found [LOG] 68.07358 INFO juju.environs.tools Writing tools/streams/v1/index.json [LOG] 68.07377 INFO juju.environs.tools Writing tools/streams/v1/com.ubuntu.juju:released:tools.json [LOG] 68.07387 DEBUG juju.environs.sync uploading tools to cloud storage [LOG] 68.07389 INFO juju.environs.sync using sync tools source: file:///tmp/587746733/tools [LOG] 68.07389 INFO juju.environs.sync listing available tools [LOG] 68.07390 DEBUG juju.environs.tools no architecture specified when finding tools, looking for any [LOG] 68.07391 DEBUG juju.environs.tools no series specified when finding tools, looking for any [LOG] 68.07398 DEBUG juju.environs.simplestreams fetchData failed for "file:///tmp/587746733/tools/streams/v1/index.sjson": cannot find URL "file:///tmp/587746733/tools/streams/v1/index.sjson" not found [LOG] 68.07400 DEBUG juju.environs.simplestreams cannot load index "file:///tmp/587746733/tools/streams/v1/index.sjson": invalid URL "file:///tmp/587746733/tools/streams/v1/index.sjson" not found [LOG] 68.07416 DEBUG juju.environs.simplestreams fetchData failed for "file:///tmp/587746733/tools/streams/v1/mirrors.json": cannot find URL "file:///tmp/587746733/tools/streams/v1/mirrors.json" not found [LOG] 68.07418 DEBUG juju.environs.simplestreams no mirror index file found [LOG] 68.07420 DEBUG juju.environs.simplestreams no mirror information available for { }: mirror data for "com.ubuntu.juju:released:tools" not found [LOG] 68.07421 DEBUG juju.environs.simplestreams read metadata index at "file:///tmp/587746733/tools/streams/v1/index.json" [LOG] 68.07431 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.04:arm64" "com.ubuntu.juju:12.10:amd64" "com.ubuntu.juju:12.10:i386" "com.ubuntu.juju:12.10:arm" "com.ubuntu.juju:12.10:arm64" "com.ubuntu.juju:13.04:amd64" "com.ubuntu.juju:13.04:i386" "com.ubuntu.juju:13.04:arm" "com.ubuntu.juju:13.04:arm64" "com.ubuntu.juju:13.10:amd64" "com.ubuntu.juju:13.10:i386" "com.ubuntu.juju:13.10:arm" "com.ubuntu.juju:13.10:arm64" "com.ubuntu.juju:14.04:amd64" "com.ubuntu.juju:14.04:i386" "com.ubuntu.juju:14.04:arm" "com.ubuntu.juju:14.04:arm64"] are [{Thu, 06 Mar 2014 17:44:49 +0000 products:1.0 content-download [] streams/v1/com.ubuntu.juju:released:tools.json [com.ubuntu.juju:12.04:amd64 com.ubuntu.juju:13.04:amd64]}] [LOG] 68.07433 DEBUG juju.environs.simplestreams finding products at path "streams/v1/com.ubuntu.juju:released:tools.json" [LOG] 68.07467 DEBUG juju.environs.simplestreams metadata: &{map[com.ubuntu.juju:12.04:amd64:{ 1.17.5.1 amd64 map[20140306:0xc2018a62a0]} com.ubuntu.juju:13.04:amd64:{ 1.17.5.1 amd64 map[20140306:0xc2018a6480]}] map[] Thu, 06 Mar 2014 17:44:49 +0000 products:1.0 com.ubuntu.juju:released:tools} [LOG] 68.07475 INFO juju.environs.sync found 2 tools [LOG] 68.07478 DEBUG juju.environs.sync found source tool: &{1.17.5.1-precise-amd64 file:///tmp/587746733/tools/releases/juju-1.17.5.1-precise-amd64.tgz c0deb9bbfeeb57c1ae12bfd6e0799694cad281eaeef1b1e12063734d73cf9b97 3823816} [LOG] 68.07479 DEBUG juju.environs.sync found source tool: &{1.17.5.1-raring-amd64 file:///tmp/587746733/tools/releases/juju-1.17.5.1-raring-amd64.tgz c0deb9bbfeeb57c1ae12bfd6e0799694cad281eaeef1b1e12063734d73cf9b97 3823816} [LOG] 68.07480 INFO juju.environs.sync listing target tools storage [LOG] 68.07481 DEBUG juju.environs.tools reading v1.* tools [LOG] 68.07483 INFO juju.environs.sync found 0 tools in target; 2 tools to be copied [LOG] 68.07484 INFO juju.environs.sync copying 1.17.5.1-precise-amd64 from file:///tmp/587746733/tools/releases/juju-1.17.5.1-precise-amd64.tgz [LOG] 68.07485 INFO juju.environs.sync copying tools/releases/juju-1.17.5.1-precise-amd64.tgz [LOG] 68.15628 INFO juju.environs.sync downloaded tools/releases/juju-1.17.5.1-precise-amd64.tgz (3734kB), uploading [LOG] 68.15631 INFO juju.environs.sync download 3734kB, uploading [LOG] 68.16668 INFO juju.environs.sync copying 1.17.5.1-raring-amd64 from file:///tmp/587746733/tools/releases/juju-1.17.5.1-raring-amd64.tgz [LOG] 68.16670 INFO juju.environs.sync copying tools/releases/juju-1.17.5.1-raring-amd64.tgz [LOG] 68.48442 INFO juju.environs.sync downloaded tools/releases/juju-1.17.5.1-raring-amd64.tgz (3734kB), uploading [LOG] 68.48445 INFO juju.environs.sync download 3734kB, uploading [LOG] 68.48997 INFO juju.environs.sync copied 2 tools [LOG] 68.48999 INFO juju.environs.sync generating tools metadata [LOG] 68.49000 DEBUG juju.environs.tools no architecture specified when finding tools, looking for any [LOG] 68.49001 DEBUG juju.environs.tools no series specified when finding tools, looking for any [LOG] 68.49006 DEBUG juju.environs.simplestreams fetchData failed for "tools/streams/v1/index.sjson": file "tools/streams/v1/index.sjson" not found not found [LOG] 68.49007 DEBUG juju.environs.simplestreams cannot load index "streams/v1/index.sjson": invalid URL "tools/streams/v1/index.sjson" not found [LOG] 68.49009 DEBUG juju.environs.simplestreams fetchData failed for "tools/streams/v1/index.json": file "tools/streams/v1/index.json" not found not found [LOG] 68.49010 DEBUG juju.environs.simplestreams cannot load index "streams/v1/index.json": invalid URL "tools/streams/v1/index.json" not found [LOG] 68.49033 INFO juju.environs.tools Writing tools/streams/v1/index.json [LOG] 68.49035 INFO juju.environs.tools Writing tools/streams/v1/com.ubuntu.juju:released:tools.json [LOG] 68.49036 INFO juju.environs.sync tools metadata written [LOG] 68.54054 INFO juju.environs.tools reading tools with major.minor version 1.17 [LOG] 68.54056 INFO juju.environs.tools filtering tools by series: raring [LOG] 68.54058 DEBUG juju.environs.tools no architecture specified when finding tools, looking for any [LOG] 68.54062 DEBUG juju.environs.simplestreams fetchData failed for "tools/streams/v1/index.sjson": file "tools/streams/v1/index.sjson" not found not found [LOG] 68.54064 DEBUG juju.environs.simplestreams cannot load index "streams/v1/index.sjson": invalid URL "tools/streams/v1/index.sjson" not found [LOG] 68.54073 DEBUG juju.environs.simplestreams fetchData failed for "tools/streams/v1/mirrors.json": file "tools/streams/v1/mirrors.json" not found not found [LOG] 68.54074 DEBUG juju.environs.simplestreams no mirror index file found [LOG] 68.54076 DEBUG juju.environs.simplestreams no mirror information available for { }: mirror data for "com.ubuntu.juju:released:tools" not found [LOG] 68.54077 DEBUG juju.environs.simplestreams read metadata index at "http://127.0.0.1:44047/peckham/private/tools/streams/v1/index.json" [LOG] 68.54082 DEBUG juju.environs.simplestreams candidate matches for products ["com.ubuntu.juju:13.04:amd64" "com.ubuntu.juju:13.04:i386" "com.ubuntu.juju:13.04:arm" "com.ubuntu.juju:13.04:arm64"] are [{Thu, 06 Mar 2014 17:44:49 +0000 products:1.0 content-download [] streams/v1/com.ubuntu.juju:released:tools.json [com.ubuntu.juju:12.04:amd64 com.ubuntu.juju:13.04:amd64]}] [LOG] 68.54083 DEBUG juju.environs.simplestreams finding products at path "streams/v1/com.ubuntu.juju:released:tools.json" [LOG] 68.54117 DEBUG juju.environs.simplestreams metadata: &{map[com.ubuntu.juju:12.04:amd64:{ 1.17.5.1 amd64 map[20140306:0xc2011e7120]} com.ubuntu.juju:13.04:amd64:{ 1.17.5.1 amd64 map[20140306:0xc2011e7240]}] map[] Thu, 06 Mar 2014 17:44:49 +0000 products:1.0 com.ubuntu.juju:released:tools} [LOG] 68.54123 INFO juju.environs.bootstrap picked newest version: 1.17.5.1 [LOG] 68.54126 INFO juju.provider.dummy would pick tools from 1.17.5.1-raring-amd64 bootstrap_test.go:338: c.Assert(testWriter.Log, jc.LogMatches, []string{"using existing environment file: .*"}) ... obtained checkers.SimpleMessages = SimpleMessages{ WARNING ignoring environments.yaml: using bootstrap config in file "/tmp/gocheck-4751997750760398084/22/.juju/environments/peckham.jenv" WARNING no tools available, attempting to retrieve from /tmp/gocheck-4751997750760398084/21 WARNING no tools found, so attempting to build and upload new tools } ... expected checkers.SimpleMessages = SimpleMessages{ UNSPECIFIED using existing environment file: .* } [LOG] 68.55983 INFO juju Reset successfully reset admin password [LOG] 68.55991 INFO juju.provider.dummy reset environment [LOG] 68.56272 INFO juju Reset successfully reset admin password [LOG] 68.56537 INFO juju Reset successfully reset admin password ---------------------------------------------------------------------- FAIL: publish_test.go:75: PublishSuite.SetUpTest publish_test.go:88: c.Assert(err, gc.IsNil) ... value *errors.errorString = &errors.errorString{s:"error running \"bzr init\": exec: \"bzr\": executable file not found in $PATH"} ("error running \"bzr init\": exec: \"bzr\": executable file not found in $PATH") ---------------------------------------------------------------------- PANIC: publish_test.go:159: PublishSuite.TestBrokenCharm ... Panic: Fixture has panicked (see related PANIC) OOPS: 182 passed, 2 skipped, 2 FAILED, 17 MISSED --- FAIL: TestPackage (185.64 seconds) FAIL FAIL launchpad.net/juju-core/cmd/juju 185.830s ok launchpad.net/juju-core/cmd/jujud 66.165s ok launchpad.net/juju-core/cmd/plugins/juju-metadata 9.105s ? launchpad.net/juju-core/cmd/plugins/juju-restore [no test files] ok launchpad.net/juju-core/cmd/plugins/local 0.162s ? launchpad.net/juju-core/cmd/plugins/local/juju-local [no test files] ok launchpad.net/juju-core/constraints 0.023s ok launchpad.net/juju-core/container 0.029s ok launchpad.net/juju-core/container/factory 0.045s ok launchpad.net/juju-core/container/kvm 0.173s ok launchpad.net/juju-core/container/kvm/mock 0.032s ? launchpad.net/juju-core/container/kvm/testing [no test files] ok launchpad.net/juju-core/container/lxc 0.717s ? 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.221s ok launchpad.net/juju-core/environs 2.495s ok launchpad.net/juju-core/environs/bootstrap 3.509s ok launchpad.net/juju-core/environs/cloudinit 0.528s ok launchpad.net/juju-core/environs/config 2.598s ok launchpad.net/juju-core/environs/configstore 0.032s ok launchpad.net/juju-core/environs/filestorage 0.025s ok launchpad.net/juju-core/environs/httpstorage 0.697s ok launchpad.net/juju-core/environs/imagemetadata 0.502s ? launchpad.net/juju-core/environs/imagemetadata/testing [no test files] ok launchpad.net/juju-core/environs/instances 0.043s ok launchpad.net/juju-core/environs/jujutest 0.184s ok launchpad.net/juju-core/environs/manual 12.243s ok launchpad.net/juju-core/environs/simplestreams 0.282s ? launchpad.net/juju-core/environs/simplestreams/testing [no test files] ok launchpad.net/juju-core/environs/sshstorage 1.034s ok launchpad.net/juju-core/environs/storage 0.918s ok launchpad.net/juju-core/environs/sync 24.914s ok launchpad.net/juju-core/environs/testing 0.132s ok launchpad.net/juju-core/environs/tools 5.113s ? launchpad.net/juju-core/environs/tools/testing [no test files] ok launchpad.net/juju-core/errors 0.011s ok launchpad.net/juju-core/instance 0.019s ? launchpad.net/juju-core/instance/testing [no test files] ok launchpad.net/juju-core/juju 18.924s ok launchpad.net/juju-core/juju/osenv 0.014s ? launchpad.net/juju-core/juju/testing [no test files] ok launchpad.net/juju-core/log 0.015s ok launchpad.net/juju-core/log/syslog 0.017s ? launchpad.net/juju-core/log/syslog/testing [no test files] ok launchpad.net/juju-core/names 0.020s ? launchpad.net/juju-core/provider [no test files] ? launchpad.net/juju-core/provider/all [no test files] ok launchpad.net/juju-core/provider/azure 4.798s ok launchpad.net/juju-core/provider/common 5.555s ok launchpad.net/juju-core/provider/dummy 16.911s ok launchpad.net/juju-core/provider/ec2 16.709s ok launchpad.net/juju-core/provider/joyent 3.784s ok launchpad.net/juju-core/provider/local 7.200s ok launchpad.net/juju-core/provider/maas 15.229s ok launchpad.net/juju-core/provider/manual 1.186s ok launchpad.net/juju-core/provider/openstack 29.863s ok launchpad.net/juju-core/replicaset 61.788s ok launchpad.net/juju-core/rpc 0.078s ok launchpad.net/juju-core/rpc/jsoncodec 0.028s ? launchpad.net/juju-core/rpc/rpcreflect [no test files] ok launchpad.net/juju-core/schema 0.022s ok launchpad.net/juju-core/state 70.963s ok launchpad.net/juju-core/state/api 1.568s ok launchpad.net/juju-core/state/api/agent 1.610s ? launchpad.net/juju-core/state/api/base [no test files] ok launchpad.net/juju-core/state/api/charmrevisionupdater 1.274s ? 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 4.923s ok launchpad.net/juju-core/state/api/environment 1.480s ok launchpad.net/juju-core/state/api/firewaller 8.305s ok launchpad.net/juju-core/state/api/keymanager 3.397s ok launchpad.net/juju-core/state/api/keyupdater 2.033s ok launchpad.net/juju-core/state/api/logger 1.810s ok launchpad.net/juju-core/state/api/machiner 2.577s ok launchpad.net/juju-core/state/api/params 0.023s ok launchpad.net/juju-core/state/api/provisioner 7.191s ok launchpad.net/juju-core/state/api/rsyslog 1.567s ok launchpad.net/juju-core/state/api/uniter 22.065s ok launchpad.net/juju-core/state/api/upgrader 7.576s ok launchpad.net/juju-core/state/api/watcher 2.563s ok launchpad.net/juju-core/state/apiserver 8.489s ok launchpad.net/juju-core/state/apiserver/agent 2.502s ok launchpad.net/juju-core/state/apiserver/charmrevisionupdater 2.232s ? launchpad.net/juju-core/state/apiserver/charmrevisionupdater/testing [no test files] ok launchpad.net/juju-core/state/apiserver/client 35.874s ok launchpad.net/juju-core/state/apiserver/common 2.081s ? launchpad.net/juju-core/state/apiserver/common/testing [no test files] ok launchpad.net/juju-core/state/apiserver/deployer 3.773s ok launchpad.net/juju-core/state/apiserver/environment 1.434s ok launchpad.net/juju-core/state/apiserver/firewaller 4.812s ok launchpad.net/juju-core/state/apiserver/keymanager 4.228s ? launchpad.net/juju-core/state/apiserver/keymanager/testing [no test files] ok launchpad.net/juju-core/state/apiserver/keyupdater 2.550s ok launchpad.net/juju-core/state/apiserver/logger 2.967s ok launchpad.net/juju-core/state/apiserver/machine 2.451s ok launchpad.net/juju-core/state/apiserver/provisioner 9.224s ok launchpad.net/juju-core/state/apiserver/rsyslog 2.371s ? launchpad.net/juju-core/state/apiserver/testing [no test files] ok launchpad.net/juju-core/state/apiserver/uniter 15.912s ok launchpad.net/juju-core/state/apiserver/upgrader 8.981s ok launchpad.net/juju-core/state/multiwatcher 0.620s ok launchpad.net/juju-core/state/presence 6.152s ok launchpad.net/juju-core/state/statecmd 1.519s ? launchpad.net/juju-core/state/testing [no test files] ok launchpad.net/juju-core/state/watcher 4.980s ---------------------------------------------------------------------- PANIC: branch_test.go:61: StoreSuite.TestPublish [LOG] 99.27308 Resetting stats [LOG] 99.27309 Cluster 0xc200a2b460 acquired (refs=2) [LOG] 99.27310 New session 0xc200f329a0 on cluster 0xc200a2b460 [LOG] 99.27311 Session 0xc200f329a0: setting mode 0 with refresh=true (master=0x0, slave=0x0) [LOG] 99.27312 Cluster 0xc200a2b460 released (refs=1) [LOG] 99.27313 Cluster has 0 known masters and 0 known slaves. [LOG] 99.27313 Waiting for servers to synchronize... [LOG] 99.27318 Socket 0xc200a2b0e0 to localhost:50017: killed again: read tcp 127.0.0.1:50017: use of closed network connection (previously: Closed explicitly) [LOG] 99.27319 SYNC Cluster 0xc200a2b460 is starting a sync loop iteration. [LOG] 99.27319 SYNC Starting full topology synchronization... [LOG] 99.27322 Establishing new connection to 127.0.0.1:50017 (timeout=15s)... [LOG] 99.27332 Connection to 127.0.0.1:50017 established. [LOG] 99.27333 Socket 0xc200a2b700 to 127.0.0.1:50017: initialized [LOG] 99.27334 Socket 0xc200a2b700 to 127.0.0.1:50017: requesting a new nonce [LOG] 99.27337 Socket 0xc200a2b700 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:(*mgo.getNonceCmd)(0xc200a35028), skip:0, limit:-1, selector:interface {}(nil), flags:0x0, replyFunc:(mgo.replyFunc)(0x53dfd0), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.27340 Socket 0xc200a2b700 to 127.0.0.1:50017: sending 1 op(s) (58 bytes) [LOG] 99.27343 Socket 0xc200a2b700 to 127.0.0.1:50017: updated write deadline to 15s ahead (2014-03-06 17:52:15.402062166 +0000 UTC) [LOG] 99.27350 Socket 0xc200a2b700 to 127.0.0.1:50017: updated read deadline to 15s ahead (2014-03-06 17:52:15.40212416 +0000 UTC) [LOG] 99.27354 Socket 0xc200a2b700 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ping", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x53fc80), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.27357 Socket 0xc200a2b700 to 127.0.0.1:50017: sending 1 op(s) (54 bytes) [LOG] 99.27358 Socket 0xc200a2b700 to 127.0.0.1:50017: updated write deadline to 15s ahead (2014-03-06 17:52:15.402225283 +0000 UTC) [LOG] 99.27399 Socket 0xc200a2b700 to 127.0.0.1:50017: got reply (81 bytes) [LOG] 99.27408 Socket 0xc200a2b700 to 127.0.0.1:50017: received document: bson.M{"nonce":"b7111896dc5fc354", "ok":1} [LOG] 99.27411 Socket 0xc200a2b700 to 127.0.0.1:50017: nonce unmarshalled: &mgo.getNonceResult{Nonce:"b7111896dc5fc354", Err:"", Code:0} [LOG] 99.27413 Socket 0xc200a2b700 to 127.0.0.1:50017: updated read deadline to 15s ahead (2014-03-06 17:52:15.402769899 +0000 UTC) [LOG] 99.27414 Socket 0xc200a2b700 to 127.0.0.1:50017: got reply (53 bytes) [LOG] 99.27417 Socket 0xc200a2b700 to 127.0.0.1:50017: received document: bson.M{"ok":1} [LOG] 99.27419 Ping for 127.0.0.1:50017 is 0 ms [LOG] 99.27420 SYNC Processing 127.0.0.1:50017... [LOG] 99.27421 Cluster 0xc200a2b460 acquired (refs=3) [LOG] 99.27421 New session 0xc200f32b00 on cluster 0xc200a2b460 [LOG] 99.27422 Session 0xc200f32b00: setting mode 1 with refresh=true (master=0x0, slave=0x0) [LOG] 99.27426 Socket 0xc200a2b700 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ismaster", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x53fc80), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.27427 Socket 0xc200a2b700 to 127.0.0.1:50017: sending 1 op(s) (58 bytes) [LOG] 99.27429 Socket 0xc200a2b700 to 127.0.0.1:50017: updated write deadline to 5s ahead (2014-03-06 17:52:05.40293492 +0000 UTC) [LOG] 99.27436 Socket 0xc200a2b700 to 127.0.0.1:50017: updated read deadline to 5s ahead (2014-03-06 17:52:05.40299734 +0000 UTC) [LOG] 99.27451 Socket 0xc200a2b700 to 127.0.0.1:50017: got reply (131 bytes) [LOG] 99.27457 Socket 0xc200a2b700 to 127.0.0.1:50017: received document: bson.M{"ismaster":true, "maxBsonObjectSize":16777216, "maxMessageSizeBytes":48000000, "localTime":time.Time{sec:63529725120, nsec:403000000, loc:(*time.Location)(0xc72440)}, "ok":1} [LOG] 99.27462 Query 0xc200a2b7e0 document unmarshaled: &mgo.isMasterResult{IsMaster:true, Secondary:false, Primary:"", Hosts:[]string(nil), Passives:[]string(nil), Tags:bson.D(nil), Msg:""} [LOG] 99.27463 Closing session 0xc200f32b00 [LOG] 99.27463 Cluster 0xc200a2b460 released (refs=2) [LOG] 99.27466 SYNC Result of 'ismaster' from 127.0.0.1:50017: mgo.isMasterResult{IsMaster:true, Secondary:false, Primary:"", Hosts:[]string(nil), Passives:[]string(nil), Tags:bson.D(nil), Msg:""} [LOG] 99.27467 SYNC 127.0.0.1:50017 is a master. [LOG] 99.27467 SYNC 127.0.0.1:50017 knows about the following peers: []string{} [LOG] 99.27468 SYNC Adding 127.0.0.1:50017 to cluster as a master. [LOG] 99.27469 SYNC Broadcasting availability of server 127.0.0.1:50017 [LOG] 99.27470 Cluster has 1 known masters and 0 known slaves. [LOG] 99.27474 Socket 0xc200a2b700 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ping", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x53fc80), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.27476 Socket 0xc200a2b700 to 127.0.0.1:50017: sending 1 op(s) (54 bytes) [LOG] 99.27478 Socket 0xc200a2b700 to 127.0.0.1:50017: updated write deadline to 10s ahead (2014-03-06 17:52:10.403419753 +0000 UTC) [LOG] 99.27485 Socket 0xc200a2b700 to 127.0.0.1:50017: updated read deadline to 10s ahead (2014-03-06 17:52:10.403491703 +0000 UTC) [LOG] 99.27486 SYNC Synchronization was complete (got data from primary). [LOG] 99.27488 SYNC Synchronization completed: 1 master(s) and 0 slave(s) alive. [LOG] 99.27489 SYNC New dynamic seeds: []string{"127.0.0.1:50017"} [LOG] 99.27490 Cluster 0xc200a2b460 released (refs=1) [LOG] 99.27499 Socket 0xc200a2b700 to 127.0.0.1:50017: got reply (53 bytes) [LOG] 99.27504 Socket 0xc200a2b700 to 127.0.0.1:50017: received document: bson.M{"ok":1} [LOG] 99.27506 Session 0xc200f329a0: setting mode 2 with refresh=true (master=0x0, slave=0x0) [LOG] 99.27509 INFO juju store: Store opened. Connecting to: 127.0.0.1:50017 [LOG] 99.27512 Cluster 0xc200a2b8c0 acquired (refs=2) [LOG] 99.27512 New session 0xc200f32c60 on cluster 0xc200a2b8c0 [LOG] 99.27513 Session 0xc200f32c60: setting mode 0 with refresh=true (master=0x0, slave=0x0) [LOG] 99.27514 Cluster 0xc200a2b8c0 released (refs=1) [LOG] 99.27515 Cluster has 0 known masters and 0 known slaves. [LOG] 99.27516 Waiting for servers to synchronize... [LOG] 99.27516 SYNC Cluster 0xc200a2b8c0 is starting a sync loop iteration. [LOG] 99.27517 SYNC Starting full topology synchronization... [LOG] 99.27521 Establishing new connection to 127.0.0.1:50017 (timeout=15s)... [LOG] 99.27543 Connection to 127.0.0.1:50017 established. [LOG] 99.27544 Socket 0xc200a2bb60 to 127.0.0.1:50017: initialized [LOG] 99.27545 Socket 0xc200a2bb60 to 127.0.0.1:50017: requesting a new nonce [LOG] 99.27552 Socket 0xc200a2bb60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:(*mgo.getNonceCmd)(0xc200a35680), skip:0, limit:-1, selector:interface {}(nil), flags:0x0, replyFunc:(mgo.replyFunc)(0x53dfd0), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.27554 Socket 0xc200a2bb60 to 127.0.0.1:50017: sending 1 op(s) (58 bytes) [LOG] 99.27556 Socket 0xc200a2bb60 to 127.0.0.1:50017: updated write deadline to 15s ahead (2014-03-06 17:52:15.404200963 +0000 UTC) [LOG] 99.27569 Socket 0xc200a2bb60 to 127.0.0.1:50017: updated read deadline to 15s ahead (2014-03-06 17:52:15.404323876 +0000 UTC) [LOG] 99.27578 Socket 0xc200a2bb60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ping", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x53fc80), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.27580 Socket 0xc200a2bb60 to 127.0.0.1:50017: sending 1 op(s) (54 bytes) [LOG] 99.27582 Socket 0xc200a2bb60 to 127.0.0.1:50017: updated write deadline to 15s ahead (2014-03-06 17:52:15.404462695 +0000 UTC) [LOG] 99.27593 Socket 0xc200a2bb60 to 127.0.0.1:50017: got reply (81 bytes) [LOG] 99.27597 Socket 0xc200a2bb60 to 127.0.0.1:50017: received document: bson.M{"nonce":"82d1369415350647", "ok":1} [LOG] 99.27604 Socket 0xc200a2bb60 to 127.0.0.1:50017: nonce unmarshalled: &mgo.getNonceResult{Nonce:"82d1369415350647", Err:"", Code:0} [LOG] 99.27606 Socket 0xc200a2bb60 to 127.0.0.1:50017: updated read deadline to 15s ahead (2014-03-06 17:52:15.404700955 +0000 UTC) [LOG] 99.27607 Socket 0xc200a2bb60 to 127.0.0.1:50017: got reply (53 bytes) [LOG] 99.27614 Socket 0xc200a2bb60 to 127.0.0.1:50017: received document: bson.M{"ok":1} [LOG] 99.27616 Ping for 127.0.0.1:50017 is 0 ms [LOG] 99.27617 SYNC Processing 127.0.0.1:50017... [LOG] 99.27621 Cluster 0xc200a2b8c0 acquired (refs=3) [LOG] 99.27622 New session 0xc200f32dc0 on cluster 0xc200a2b8c0 [LOG] 99.27623 Session 0xc200f32dc0: setting mode 1 with refresh=true (master=0x0, slave=0x0) [LOG] 99.27637 Socket 0xc200a2bb60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ismaster", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x53fc80), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.27642 Socket 0xc200a2bb60 to 127.0.0.1:50017: sending 1 op(s) (58 bytes) [LOG] 99.27644 Socket 0xc200a2bb60 to 127.0.0.1:50017: updated write deadline to 5s ahead (2014-03-06 17:52:05.405081991 +0000 UTC) [LOG] 99.27657 Socket 0xc200a2bb60 to 127.0.0.1:50017: updated read deadline to 5s ahead (2014-03-06 17:52:05.405203433 +0000 UTC) [LOG] 99.27684 Socket 0xc200a2bb60 to 127.0.0.1:50017: got reply (131 bytes) [LOG] 99.27691 Socket 0xc200a2bb60 to 127.0.0.1:50017: received document: bson.M{"ismaster":true, "maxBsonObjectSize":16777216, "maxMessageSizeBytes":48000000, "localTime":time.Time{sec:63529725120, nsec:405000000, loc:(*time.Location)(0xc72440)}, "ok":1} [LOG] 99.27704 Query 0xc200a2bc40 document unmarshaled: &mgo.isMasterResult{IsMaster:true, Secondary:false, Primary:"", Hosts:[]string(nil), Passives:[]string(nil), Tags:bson.D(nil), Msg:""} [LOG] 99.27705 Closing session 0xc200f32dc0 [LOG] 99.27706 Cluster 0xc200a2b8c0 released (refs=2) [LOG] 99.27708 SYNC Result of 'ismaster' from 127.0.0.1:50017: mgo.isMasterResult{IsMaster:true, Secondary:false, Primary:"", Hosts:[]string(nil), Passives:[]string(nil), Tags:bson.D(nil), Msg:""} [LOG] 99.27709 SYNC 127.0.0.1:50017 is a master. [LOG] 99.27709 SYNC 127.0.0.1:50017 knows about the following peers: []string{} [LOG] 99.27710 SYNC Adding 127.0.0.1:50017 to cluster as a master. [LOG] 99.27711 SYNC Broadcasting availability of server 127.0.0.1:50017 [LOG] 99.27712 Cluster has 1 known masters and 0 known slaves. [LOG] 99.27715 Socket 0xc200a2bb60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ping", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x53fc80), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.27721 Socket 0xc200a2bb60 to 127.0.0.1:50017: sending 1 op(s) (54 bytes) [LOG] 99.27723 Socket 0xc200a2bb60 to 127.0.0.1:50017: updated write deadline to 10s ahead (2014-03-06 17:52:10.405867217 +0000 UTC) [LOG] 99.27727 Socket 0xc200a2bb60 to 127.0.0.1:50017: updated read deadline to 10s ahead (2014-03-06 17:52:10.40591291 +0000 UTC) [LOG] 99.27728 SYNC Synchronization was complete (got data from primary). [LOG] 99.27729 SYNC Synchronization completed: 1 master(s) and 0 slave(s) alive. [LOG] 99.27730 SYNC New dynamic seeds: []string{"127.0.0.1:50017"} [LOG] 99.27731 Cluster 0xc200a2b8c0 released (refs=1) [LOG] 99.27741 Socket 0xc200a2bb60 to 127.0.0.1:50017: got reply (53 bytes) [LOG] 99.27751 Socket 0xc200a2bb60 to 127.0.0.1:50017: received document: bson.M{"ok":1} [LOG] 99.27754 Session 0xc200f32c60: setting mode 2 with refresh=true (master=0x0, slave=0x0) [LOG] 99.27763 Cluster has 1 known masters and 0 known slaves. [LOG] 99.27771 Socket 0xc200a2bb60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"juju.$cmd", query:bson.D{bson.DocElem{Name:"create", Value:"stat.counters"}, bson.DocElem{Name:"autoIndexId", Value:false}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x0, replyFunc:(mgo.replyFunc)(0x53fc80), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.27773 Socket 0xc200a2bb60 to 127.0.0.1:50017: sending 1 op(s) (83 bytes) [LOG] 99.27775 Socket 0xc200a2bb60 to 127.0.0.1:50017: updated write deadline to 1m0s ahead (2014-03-06 17:53:00.406391045 +0000 UTC) [LOG] 99.27779 Socket 0xc200a2bb60 to 127.0.0.1:50017: updated read deadline to 1m0s ahead (2014-03-06 17:53:00.406434492 +0000 UTC) [LOG] 99.28237 Socket 0xc200a2bb60 to 127.0.0.1:50017: got reply (53 bytes) [LOG] 99.28240 Socket 0xc200a2bb60 to 127.0.0.1:50017: received document: bson.M{"ok":1} [LOG] 99.28242 Cluster 0xc200a2b8c0 acquired (refs=2) [LOG] 99.28243 New session 0xc200ad2000 on cluster 0xc200a2b8c0 (copy from 0xc200f32c60) [LOG] 99.28244 Session 0xc200ad2000: setting mode 2 with refresh=false (master=0xc200a2bb60, slave=0x0) [LOG] 99.28245 Socket 0xc200a2bb60 to 127.0.0.1:50017: serializing op: &mgo.insertOp{collection:"juju.system.indexes", documents:[]interface {}{(*mgo.indexSpec)(0xc203c9e060)}} [LOG] 99.28248 Socket 0xc200a2bb60 to 127.0.0.1:50017: serializing document for insertion: &mgo.indexSpec{Name:"k_1_t_1", NS:"juju.stat.counters", Key:bson.D{bson.DocElem{Name:"k", Value:1}, bson.DocElem{Name:"t", Value:1}}, Unique:true, DropDups:false, Background:false, Sparse:false, Bits:0, Min:0, Max:0, ExpireAfter:0} [LOG] 99.28251 Socket 0xc200a2bb60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"juju.$cmd", query:(*mgo.getLastError)(0xc2013847e0), skip:0, limit:-1, selector:interface {}(nil), flags:0x0, replyFunc:(mgo.replyFunc)(0x53fc10), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.28252 Socket 0xc200a2bb60 to 127.0.0.1:50017: sending 2 op(s) (184 bytes) [LOG] 99.28254 Socket 0xc200a2bb60 to 127.0.0.1:50017: updated write deadline to 1m0s ahead (2014-03-06 17:53:00.411181297 +0000 UTC) [LOG] 99.28257 Socket 0xc200a2bb60 to 127.0.0.1:50017: updated read deadline to 1m0s ahead (2014-03-06 17:53:00.4112111 +0000 UTC) [LOG] 99.28313 Socket 0xc200a2bb60 to 127.0.0.1:50017: got reply (83 bytes) [LOG] 99.28316 Socket 0xc200a2bb60 to 127.0.0.1:50017: received document: bson.M{"n":0, "connectionId":75, "err":interface {}(nil), "ok":1} [LOG] 99.28321 Result from writing query: &mgo.LastError{Err:"", Code:0, N:0, Waited:0, FSyncFiles:0, WTimeout:false, UpdatedExisting:false, UpsertedId:interface {}(nil)} [LOG] 99.28322 Closing session 0xc200ad2000 [LOG] 99.28322 Cluster 0xc200a2b8c0 released (refs=1) [LOG] 99.28323 Cluster 0xc200a2b8c0 acquired (refs=2) [LOG] 99.28323 New session 0xc200ad2420 on cluster 0xc200a2b8c0 (copy from 0xc200f32c60) [LOG] 99.28324 Session 0xc200ad2420: setting mode 2 with refresh=false (master=0xc200a2bb60, slave=0x0) [LOG] 99.28325 Socket 0xc200a2bb60 to 127.0.0.1:50017: serializing op: &mgo.insertOp{collection:"juju.system.indexes", documents:[]interface {}{(*mgo.indexSpec)(0xc203c9e420)}} [LOG] 99.28328 Socket 0xc200a2bb60 to 127.0.0.1:50017: serializing document for insertion: &mgo.indexSpec{Name:"t_1", NS:"juju.stat.tokens", Key:bson.D{bson.DocElem{Name:"t", Value:1}}, Unique:true, DropDups:false, Background:false, Sparse:false, Bits:0, Min:0, Max:0, ExpireAfter:0} [LOG] 99.28331 Socket 0xc200a2bb60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"juju.$cmd", query:(*mgo.getLastError)(0xc201384ab0), skip:0, limit:-1, selector:interface {}(nil), flags:0x0, replyFunc:(mgo.replyFunc)(0x53fc10), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.28332 Socket 0xc200a2bb60 to 127.0.0.1:50017: sending 2 op(s) (171 bytes) [LOG] 99.28334 Socket 0xc200a2bb60 to 127.0.0.1:50017: updated write deadline to 1m0s ahead (2014-03-06 17:53:00.411982198 +0000 UTC) [LOG] 99.28337 Socket 0xc200a2bb60 to 127.0.0.1:50017: updated read deadline to 1m0s ahead (2014-03-06 17:53:00.412013186 +0000 UTC) [LOG] 99.28422 Socket 0xc200a2bb60 to 127.0.0.1:50017: got reply (83 bytes) [LOG] 99.28426 Socket 0xc200a2bb60 to 127.0.0.1:50017: received document: bson.M{"n":0, "connectionId":75, "err":interface {}(nil), "ok":1} [LOG] 99.28431 Result from writing query: &mgo.LastError{Err:"", Code:0, N:0, Waited:0, FSyncFiles:0, WTimeout:false, UpdatedExisting:false, UpsertedId:interface {}(nil)} [LOG] 99.28431 Closing session 0xc200ad2420 [LOG] 99.28432 Cluster 0xc200a2b8c0 released (refs=1) [LOG] 99.28433 Cluster 0xc200a2b8c0 acquired (refs=2) [LOG] 99.28433 New session 0xc200ad2580 on cluster 0xc200a2b8c0 (copy from 0xc200f32c60) [LOG] 99.28434 Session 0xc200ad2580: setting mode 2 with refresh=false (master=0xc200a2bb60, slave=0x0) [LOG] 99.28435 Socket 0xc200a2bb60 to 127.0.0.1:50017: serializing op: &mgo.insertOp{collection:"juju.system.indexes", documents:[]interface {}{(*mgo.indexSpec)(0xc203c9e7e0)}} [LOG] 99.28437 Socket 0xc200a2bb60 to 127.0.0.1:50017: serializing document for insertion: &mgo.indexSpec{Name:"urls_1_revision_1", NS:"juju.charms", Key:bson.D{bson.DocElem{Name:"urls", Value:1}, bson.DocElem{Name:"revision", Value:1}}, Unique:true, DropDups:false, Background:false, Sparse:false, Bits:0, Min:0, Max:0, ExpireAfter:0} [LOG] 99.28440 Socket 0xc200a2bb60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"juju.$cmd", query:(*mgo.getLastError)(0xc201384d80), skip:0, limit:-1, selector:interface {}(nil), flags:0x0, replyFunc:(mgo.replyFunc)(0x53fc10), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.28441 Socket 0xc200a2bb60 to 127.0.0.1:50017: sending 2 op(s) (197 bytes) [LOG] 99.28443 Socket 0xc200a2bb60 to 127.0.0.1:50017: updated write deadline to 1m0s ahead (2014-03-06 17:53:00.413071866 +0000 UTC) [LOG] 99.28446 Socket 0xc200a2bb60 to 127.0.0.1:50017: updated read deadline to 1m0s ahead (2014-03-06 17:53:00.413103009 +0000 UTC) [LOG] 99.28530 Socket 0xc200a2bb60 to 127.0.0.1:50017: got reply (83 bytes) [LOG] 99.28534 Socket 0xc200a2bb60 to 127.0.0.1:50017: received document: bson.M{"n":0, "connectionId":75, "err":interface {}(nil), "ok":1} [LOG] 99.28539 Result from writing query: &mgo.LastError{Err:"", Code:0, N:0, Waited:0, FSyncFiles:0, WTimeout:false, UpdatedExisting:false, UpsertedId:interface {}(nil)} [LOG] 99.28540 Closing session 0xc200ad2580 [LOG] 99.28540 Cluster 0xc200a2b8c0 released (refs=1) [LOG] 99.28541 Cluster 0xc200a2b8c0 acquired (refs=2) [LOG] 99.28541 New session 0xc200ad2b00 on cluster 0xc200a2b8c0 (copy from 0xc200f32c60) [LOG] 99.28542 Session 0xc200ad2b00: setting mode 2 with refresh=false (master=0xc200a2bb60, slave=0x0) [LOG] 99.28544 Socket 0xc200a2bb60 to 127.0.0.1:50017: serializing op: &mgo.insertOp{collection:"juju.system.indexes", documents:[]interface {}{(*mgo.indexSpec)(0xc203c9ede0)}} [LOG] 99.28546 Socket 0xc200a2bb60 to 127.0.0.1:50017: serializing document for insertion: &mgo.indexSpec{Name:"urls_1_digest_1", NS:"juju.events", Key:bson.D{bson.DocElem{Name:"urls", Value:1}, bson.DocElem{Name:"digest", Value:1}}, Unique:false, DropDups:false, Background:false, Sparse:false, Bits:0, Min:0, Max:0, ExpireAfter:0} [LOG] 99.28553 Socket 0xc200a2bb60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"juju.$cmd", query:(*mgo.getLastError)(0xc200ad9060), skip:0, limit:-1, selector:interface {}(nil), flags:0x0, replyFunc:(mgo.replyFunc)(0x53fc10), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.28559 Socket 0xc200a2bb60 to 127.0.0.1:50017: sending 2 op(s) (184 bytes) [LOG] 99.28561 Socket 0xc200a2bb60 to 127.0.0.1:50017: updated write deadline to 1m0s ahead (2014-03-06 17:53:00.414248026 +0000 UTC) [LOG] 99.28565 Socket 0xc200a2bb60 to 127.0.0.1:50017: updated read deadline to 1m0s ahead (2014-03-06 17:53:00.414294429 +0000 UTC) [LOG] 99.28695 Socket 0xc200a2bb60 to 127.0.0.1:50017: got reply (83 bytes) [LOG] 99.28704 Socket 0xc200a2bb60 to 127.0.0.1:50017: received document: bson.M{"n":0, "connectionId":75, "err":interface {}(nil), "ok":1} [LOG] 99.28708 Result from writing query: &mgo.LastError{Err:"", Code:0, N:0, Waited:0, FSyncFiles:0, WTimeout:false, UpdatedExisting:false, UpsertedId:interface {}(nil)} [LOG] 99.28709 Closing session 0xc200ad2b00 [LOG] 99.28710 Cluster 0xc200a2b8c0 released (refs=1) [LOG] 99.28729 Closing session 0xc200f32c60 [LOG] 99.28730 Cluster 0xc200a2b8c0 released (refs=0) [LOG] 99.28731 Connections to 127.0.0.1:50017 closing (1 live sockets). [LOG] 99.28732 Socket 0xc200a2bb60 to 127.0.0.1:50017: closing: Closed explicitly (abend=false) [LOG] 99.28732 Closing session 0xc200f329a0 [LOG] 99.28733 Cluster 0xc200a2b460 released (refs=0) [LOG] 99.28734 Connections to 127.0.0.1:50017 closing (1 live sockets). [LOG] 99.28734 Socket 0xc200a2b700 to 127.0.0.1:50017: closing: Closed explicitly (abend=false) [LOG] 99.28739 Socket 0xc200a2bb60 to 127.0.0.1:50017: killed again: read tcp 127.0.0.1:50017: use of closed network connection (previously: Closed explicitly) [LOG] 99.28743 Socket 0xc200a2b700 to 127.0.0.1:50017: killed again: read tcp 127.0.0.1:50017: use of closed network connection (previously: Closed explicitly) ... Panic: command failed: bzr init (PC=0x414071) /usr/lib/go/src/pkg/runtime/panic.c:229 in panic branch_test.go:185 in bzrDir.run branch_test.go:191 in bzrDir.init branch_test.go:31 in StoreSuite.dummyBranch branch_test.go:62 in StoreSuite.TestPublish ---------------------------------------------------------------------- PANIC: lpad_test.go:21: StoreSuite.TestPublishCharmDistro [LOG] 99.29221 Resetting stats [LOG] 99.29222 Cluster 0xc201451460 acquired (refs=2) [LOG] 99.29223 New session 0xc20144f420 on cluster 0xc201451460 [LOG] 99.29223 Session 0xc20144f420: setting mode 0 with refresh=true (master=0x0, slave=0x0) [LOG] 99.29224 Cluster 0xc201451460 released (refs=1) [LOG] 99.29226 Cluster has 0 known masters and 0 known slaves. [LOG] 99.29227 Waiting for servers to synchronize... [LOG] 99.29231 Socket 0xc2014510e0 to localhost:50017: killed again: read tcp 127.0.0.1:50017: use of closed network connection (previously: Closed explicitly) [LOG] 99.29232 SYNC Cluster 0xc201451460 is starting a sync loop iteration. [LOG] 99.29233 SYNC Starting full topology synchronization... [LOG] 99.29235 Establishing new connection to 127.0.0.1:50017 (timeout=15s)... [LOG] 99.29245 Connection to 127.0.0.1:50017 established. [LOG] 99.29246 Socket 0xc201451700 to 127.0.0.1:50017: initialized [LOG] 99.29247 Socket 0xc201451700 to 127.0.0.1:50017: requesting a new nonce [LOG] 99.29250 Socket 0xc201451700 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:(*mgo.getNonceCmd)(0xc200d5d300), skip:0, limit:-1, selector:interface {}(nil), flags:0x0, replyFunc:(mgo.replyFunc)(0x53dfd0), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.29252 Socket 0xc201451700 to 127.0.0.1:50017: sending 1 op(s) (58 bytes) [LOG] 99.29254 Socket 0xc201451700 to 127.0.0.1:50017: updated write deadline to 15s ahead (2014-03-06 17:52:15.421176491 +0000 UTC) [LOG] 99.29259 Socket 0xc201451700 to 127.0.0.1:50017: updated read deadline to 15s ahead (2014-03-06 17:52:15.421226645 +0000 UTC) [LOG] 99.29264 Socket 0xc201451700 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ping", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x53fc80), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.29265 Socket 0xc201451700 to 127.0.0.1:50017: sending 1 op(s) (54 bytes) [LOG] 99.29267 Socket 0xc201451700 to 127.0.0.1:50017: updated write deadline to 15s ahead (2014-03-06 17:52:15.421310204 +0000 UTC) [LOG] 99.29317 Socket 0xc201451700 to 127.0.0.1:50017: got reply (81 bytes) [LOG] 99.29322 Socket 0xc201451700 to 127.0.0.1:50017: received document: bson.M{"nonce":"6ec15d9add760994", "ok":1} [LOG] 99.29327 Socket 0xc201451700 to 127.0.0.1:50017: nonce unmarshalled: &mgo.getNonceResult{Nonce:"6ec15d9add760994", Err:"", Code:0} [LOG] 99.29329 Socket 0xc201451700 to 127.0.0.1:50017: updated read deadline to 15s ahead (2014-03-06 17:52:15.421932969 +0000 UTC) [LOG] 99.29331 Socket 0xc201451700 to 127.0.0.1:50017: got reply (53 bytes) [LOG] 99.29334 Socket 0xc201451700 to 127.0.0.1:50017: received document: bson.M{"ok":1} [LOG] 99.29336 Ping for 127.0.0.1:50017 is 0 ms [LOG] 99.29337 SYNC Processing 127.0.0.1:50017... [LOG] 99.29338 Cluster 0xc201451460 acquired (refs=3) [LOG] 99.29339 New session 0xc20144f580 on cluster 0xc201451460 [LOG] 99.29339 Session 0xc20144f580: setting mode 1 with refresh=true (master=0x0, slave=0x0) [LOG] 99.29346 Socket 0xc201451700 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ismaster", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x53fc80), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.29351 Socket 0xc201451700 to 127.0.0.1:50017: sending 1 op(s) (58 bytes) [LOG] 99.29353 Socket 0xc201451700 to 127.0.0.1:50017: updated write deadline to 5s ahead (2014-03-06 17:52:05.422171214 +0000 UTC) [LOG] 99.29360 Socket 0xc201451700 to 127.0.0.1:50017: updated read deadline to 5s ahead (2014-03-06 17:52:05.422235769 +0000 UTC) [LOG] 99.29383 Socket 0xc201451700 to 127.0.0.1:50017: got reply (131 bytes) [LOG] 99.29390 Socket 0xc201451700 to 127.0.0.1:50017: received document: bson.M{"ismaster":true, "maxBsonObjectSize":16777216, "maxMessageSizeBytes":48000000, "localTime":time.Time{sec:63529725120, nsec:422000000, loc:(*time.Location)(0xc72440)}, "ok":1} [LOG] 99.29393 Query 0xc2014517e0 document unmarshaled: &mgo.isMasterResult{IsMaster:true, Secondary:false, Primary:"", Hosts:[]string(nil), Passives:[]string(nil), Tags:bson.D(nil), Msg:""} [LOG] 99.29394 Closing session 0xc20144f580 [LOG] 99.29395 Cluster 0xc201451460 released (refs=2) [LOG] 99.29397 SYNC Result of 'ismaster' from 127.0.0.1:50017: mgo.isMasterResult{IsMaster:true, Secondary:false, Primary:"", Hosts:[]string(nil), Passives:[]string(nil), Tags:bson.D(nil), Msg:""} [LOG] 99.29397 SYNC 127.0.0.1:50017 is a master. [LOG] 99.29398 SYNC 127.0.0.1:50017 knows about the following peers: []string{} [LOG] 99.29399 SYNC Adding 127.0.0.1:50017 to cluster as a master. [LOG] 99.29399 SYNC Broadcasting availability of server 127.0.0.1:50017 [LOG] 99.29400 Cluster has 1 known masters and 0 known slaves. [LOG] 99.29405 Socket 0xc201451700 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ping", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x53fc80), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.29408 Socket 0xc201451700 to 127.0.0.1:50017: sending 1 op(s) (54 bytes) [LOG] 99.29410 Socket 0xc201451700 to 127.0.0.1:50017: updated write deadline to 10s ahead (2014-03-06 17:52:10.42273605 +0000 UTC) [LOG] 99.29416 Socket 0xc201451700 to 127.0.0.1:50017: updated read deadline to 10s ahead (2014-03-06 17:52:10.42280023 +0000 UTC) [LOG] 99.29417 SYNC Synchronization was complete (got data from primary). [LOG] 99.29418 SYNC Synchronization completed: 1 master(s) and 0 slave(s) alive. [LOG] 99.29419 SYNC New dynamic seeds: []string{"127.0.0.1:50017"} [LOG] 99.29420 Cluster 0xc201451460 released (refs=1) [LOG] 99.29435 Socket 0xc201451700 to 127.0.0.1:50017: got reply (53 bytes) [LOG] 99.29439 Socket 0xc201451700 to 127.0.0.1:50017: received document: bson.M{"ok":1} [LOG] 99.29440 Session 0xc20144f420: setting mode 2 with refresh=true (master=0x0, slave=0x0) [LOG] 99.29444 INFO juju store: Store opened. Connecting to: 127.0.0.1:50017 [LOG] 99.29445 Cluster 0xc2014518c0 acquired (refs=2) [LOG] 99.29446 New session 0xc20144f6e0 on cluster 0xc2014518c0 [LOG] 99.29447 Session 0xc20144f6e0: setting mode 0 with refresh=true (master=0x0, slave=0x0) [LOG] 99.29447 Cluster 0xc2014518c0 released (refs=1) [LOG] 99.29448 Cluster has 0 known masters and 0 known slaves. [LOG] 99.29449 Waiting for servers to synchronize... [LOG] 99.29450 SYNC Cluster 0xc2014518c0 is starting a sync loop iteration. [LOG] 99.29451 SYNC Starting full topology synchronization... [LOG] 99.29454 Establishing new connection to 127.0.0.1:50017 (timeout=15s)... [LOG] 99.29477 Connection to 127.0.0.1:50017 established. [LOG] 99.29478 Socket 0xc201451b60 to 127.0.0.1:50017: initialized [LOG] 99.29479 Socket 0xc201451b60 to 127.0.0.1:50017: requesting a new nonce [LOG] 99.29487 Socket 0xc201451b60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:(*mgo.getNonceCmd)(0xc200d5d958), skip:0, limit:-1, selector:interface {}(nil), flags:0x0, replyFunc:(mgo.replyFunc)(0x53dfd0), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.29489 Socket 0xc201451b60 to 127.0.0.1:50017: sending 1 op(s) (58 bytes) [LOG] 99.29491 Socket 0xc201451b60 to 127.0.0.1:50017: updated write deadline to 15s ahead (2014-03-06 17:52:15.42354743 +0000 UTC) [LOG] 99.29507 Socket 0xc201451b60 to 127.0.0.1:50017: updated read deadline to 15s ahead (2014-03-06 17:52:15.423647231 +0000 UTC) [LOG] 99.29511 Socket 0xc201451b60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ping", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x53fc80), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.29517 Socket 0xc201451b60 to 127.0.0.1:50017: sending 1 op(s) (54 bytes) [LOG] 99.29519 Socket 0xc201451b60 to 127.0.0.1:50017: updated write deadline to 15s ahead (2014-03-06 17:52:15.423828285 +0000 UTC) [LOG] 99.29531 Socket 0xc201451b60 to 127.0.0.1:50017: got reply (81 bytes) [LOG] 99.29540 Socket 0xc201451b60 to 127.0.0.1:50017: received document: bson.M{"nonce":"5086f8656adaaf9e", "ok":1} [LOG] 99.29543 Socket 0xc201451b60 to 127.0.0.1:50017: nonce unmarshalled: &mgo.getNonceResult{Nonce:"5086f8656adaaf9e", Err:"", Code:0} [LOG] 99.29545 Socket 0xc201451b60 to 127.0.0.1:50017: updated read deadline to 15s ahead (2014-03-06 17:52:15.424086783 +0000 UTC) [LOG] 99.29550 Socket 0xc201451b60 to 127.0.0.1:50017: got reply (53 bytes) [LOG] 99.29554 Socket 0xc201451b60 to 127.0.0.1:50017: received document: bson.M{"ok":1} [LOG] 99.29559 Ping for 127.0.0.1:50017 is 0 ms [LOG] 99.29560 SYNC Processing 127.0.0.1:50017... [LOG] 99.29561 Cluster 0xc2014518c0 acquired (refs=3) [LOG] 99.29562 New session 0xc20144f840 on cluster 0xc2014518c0 [LOG] 99.29563 Session 0xc20144f840: setting mode 1 with refresh=true (master=0x0, slave=0x0) [LOG] 99.29570 Socket 0xc201451b60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ismaster", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x53fc80), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.29572 Socket 0xc201451b60 to 127.0.0.1:50017: sending 1 op(s) (58 bytes) [LOG] 99.29574 Socket 0xc201451b60 to 127.0.0.1:50017: updated write deadline to 5s ahead (2014-03-06 17:52:05.424378751 +0000 UTC) [LOG] 99.29586 Socket 0xc201451b60 to 127.0.0.1:50017: updated read deadline to 5s ahead (2014-03-06 17:52:05.42449488 +0000 UTC) [LOG] 99.29598 Socket 0xc201451b60 to 127.0.0.1:50017: got reply (131 bytes) [LOG] 99.29609 Socket 0xc201451b60 to 127.0.0.1:50017: received document: bson.M{"ismaster":true, "maxBsonObjectSize":16777216, "maxMessageSizeBytes":48000000, "localTime":time.Time{sec:63529725120, nsec:424000000, loc:(*time.Location)(0xc72440)}, "ok":1} [LOG] 99.29613 Query 0xc201451c40 document unmarshaled: &mgo.isMasterResult{IsMaster:true, Secondary:false, Primary:"", Hosts:[]string(nil), Passives:[]string(nil), Tags:bson.D(nil), Msg:""} [LOG] 99.29618 Closing session 0xc20144f840 [LOG] 99.29619 Cluster 0xc2014518c0 released (refs=2) [LOG] 99.29621 SYNC Result of 'ismaster' from 127.0.0.1:50017: mgo.isMasterResult{IsMaster:true, Secondary:false, Primary:"", Hosts:[]string(nil), Passives:[]string(nil), Tags:bson.D(nil), Msg:""} [LOG] 99.29622 SYNC 127.0.0.1:50017 is a master. [LOG] 99.29622 SYNC 127.0.0.1:50017 knows about the following peers: []string{} [LOG] 99.29627 SYNC Adding 127.0.0.1:50017 to cluster as a master. [LOG] 99.29628 SYNC Broadcasting availability of server 127.0.0.1:50017 [LOG] 99.29628 Cluster has 1 known masters and 0 known slaves. [LOG] 99.29632 Socket 0xc201451b60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ping", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x53fc80), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.29638 Socket 0xc201451b60 to 127.0.0.1:50017: sending 1 op(s) (54 bytes) [LOG] 99.29640 Socket 0xc201451b60 to 127.0.0.1:50017: updated write deadline to 10s ahead (2014-03-06 17:52:10.425040002 +0000 UTC) [LOG] 99.29652 Socket 0xc201451b60 to 127.0.0.1:50017: updated read deadline to 10s ahead (2014-03-06 17:52:10.425152884 +0000 UTC) [LOG] 99.29653 SYNC Synchronization was complete (got data from primary). [LOG] 99.29653 SYNC Synchronization completed: 1 master(s) and 0 slave(s) alive. [LOG] 99.29654 SYNC New dynamic seeds: []string{"127.0.0.1:50017"} [LOG] 99.29655 Cluster 0xc2014518c0 released (refs=1) [LOG] 99.29660 Socket 0xc201451b60 to 127.0.0.1:50017: got reply (53 bytes) [LOG] 99.29664 Socket 0xc201451b60 to 127.0.0.1:50017: received document: bson.M{"ok":1} [LOG] 99.29666 Session 0xc20144f6e0: setting mode 2 with refresh=true (master=0x0, slave=0x0) [LOG] 99.29671 Cluster has 1 known masters and 0 known slaves. [LOG] 99.29675 Socket 0xc201451b60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"juju.$cmd", query:bson.D{bson.DocElem{Name:"create", Value:"stat.counters"}, bson.DocElem{Name:"autoIndexId", Value:false}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x0, replyFunc:(mgo.replyFunc)(0x53fc80), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.29680 Socket 0xc201451b60 to 127.0.0.1:50017: sending 1 op(s) (83 bytes) [LOG] 99.29682 Socket 0xc201451b60 to 127.0.0.1:50017: updated write deadline to 1m0s ahead (2014-03-06 17:53:00.425465588 +0000 UTC) [LOG] 99.29697 Socket 0xc201451b60 to 127.0.0.1:50017: updated read deadline to 1m0s ahead (2014-03-06 17:53:00.42556856 +0000 UTC) [LOG] 99.30219 Socket 0xc201451b60 to 127.0.0.1:50017: got reply (53 bytes) [LOG] 99.30223 Socket 0xc201451b60 to 127.0.0.1:50017: received document: bson.M{"ok":1} [LOG] 99.30229 Cluster 0xc2014518c0 acquired (refs=2) [LOG] 99.30230 New session 0xc20144f9a0 on cluster 0xc2014518c0 (copy from 0xc20144f6e0) [LOG] 99.30231 Session 0xc20144f9a0: setting mode 2 with refresh=false (master=0xc201451b60, slave=0x0) [LOG] 99.30233 Socket 0xc201451b60 to 127.0.0.1:50017: serializing op: &mgo.insertOp{collection:"juju.system.indexes", documents:[]interface {}{(*mgo.indexSpec)(0xc2012db000)}} [LOG] 99.30241 Socket 0xc201451b60 to 127.0.0.1:50017: serializing document for insertion: &mgo.indexSpec{Name:"k_1_t_1", NS:"juju.stat.counters", Key:bson.D{bson.DocElem{Name:"k", Value:1}, bson.DocElem{Name:"t", Value:1}}, Unique:true, DropDups:false, Background:false, Sparse:false, Bits:0, Min:0, Max:0, ExpireAfter:0} [LOG] 99.30246 Socket 0xc201451b60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"juju.$cmd", query:(*mgo.getLastError)(0xc2014f57e0), skip:0, limit:-1, selector:interface {}(nil), flags:0x0, replyFunc:(mgo.replyFunc)(0x53fc10), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.30248 Socket 0xc201451b60 to 127.0.0.1:50017: sending 2 op(s) (184 bytes) [LOG] 99.30250 Socket 0xc201451b60 to 127.0.0.1:50017: updated write deadline to 1m0s ahead (2014-03-06 17:53:00.431139424 +0000 UTC) [LOG] 99.30254 Socket 0xc201451b60 to 127.0.0.1:50017: updated read deadline to 1m0s ahead (2014-03-06 17:53:00.431185199 +0000 UTC) [LOG] 99.30331 Socket 0xc201451b60 to 127.0.0.1:50017: got reply (83 bytes) [LOG] 99.30338 Socket 0xc201451b60 to 127.0.0.1:50017: received document: bson.M{"n":0, "connectionId":78, "err":interface {}(nil), "ok":1} [LOG] 99.30343 Result from writing query: &mgo.LastError{Err:"", Code:0, N:0, Waited:0, FSyncFiles:0, WTimeout:false, UpdatedExisting:false, UpsertedId:interface {}(nil)} [LOG] 99.30344 Closing session 0xc20144f9a0 [LOG] 99.30344 Cluster 0xc2014518c0 released (refs=1) [LOG] 99.30345 Cluster 0xc2014518c0 acquired (refs=2) [LOG] 99.30346 New session 0xc20144fdc0 on cluster 0xc2014518c0 (copy from 0xc20144f6e0) [LOG] 99.30347 Session 0xc20144fdc0: setting mode 2 with refresh=false (master=0xc201451b60, slave=0x0) [LOG] 99.30353 Socket 0xc201451b60 to 127.0.0.1:50017: serializing op: &mgo.insertOp{collection:"juju.system.indexes", documents:[]interface {}{(*mgo.indexSpec)(0xc2012db420)}} [LOG] 99.30356 Socket 0xc201451b60 to 127.0.0.1:50017: serializing document for insertion: &mgo.indexSpec{Name:"t_1", NS:"juju.stat.tokens", Key:bson.D{bson.DocElem{Name:"t", Value:1}}, Unique:true, DropDups:false, Background:false, Sparse:false, Bits:0, Min:0, Max:0, ExpireAfter:0} [LOG] 99.30361 Socket 0xc201451b60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"juju.$cmd", query:(*mgo.getLastError)(0xc2014f5ab0), skip:0, limit:-1, selector:interface {}(nil), flags:0x0, replyFunc:(mgo.replyFunc)(0x53fc10), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.30368 Socket 0xc201451b60 to 127.0.0.1:50017: sending 2 op(s) (171 bytes) [LOG] 99.30373 Socket 0xc201451b60 to 127.0.0.1:50017: updated write deadline to 1m0s ahead (2014-03-06 17:53:00.432337124 +0000 UTC) [LOG] 99.30381 Socket 0xc201451b60 to 127.0.0.1:50017: updated read deadline to 1m0s ahead (2014-03-06 17:53:00.432419798 +0000 UTC) [LOG] 99.30489 Socket 0xc201451b60 to 127.0.0.1:50017: got reply (83 bytes) [LOG] 99.30497 Socket 0xc201451b60 to 127.0.0.1:50017: received document: bson.M{"n":0, "connectionId":78, "err":interface {}(nil), "ok":1} [LOG] 99.30502 Result from writing query: &mgo.LastError{Err:"", Code:0, N:0, Waited:0, FSyncFiles:0, WTimeout:false, UpdatedExisting:false, UpsertedId:interface {}(nil)} [LOG] 99.30503 Closing session 0xc20144fdc0 [LOG] 99.30504 Cluster 0xc2014518c0 released (refs=1) [LOG] 99.30505 Cluster 0xc2014518c0 acquired (refs=2) [LOG] 99.30509 New session 0xc20107b000 on cluster 0xc2014518c0 (copy from 0xc20144f6e0) [LOG] 99.30510 Session 0xc20107b000: setting mode 2 with refresh=false (master=0xc201451b60, slave=0x0) [LOG] 99.30512 Socket 0xc201451b60 to 127.0.0.1:50017: serializing op: &mgo.insertOp{collection:"juju.system.indexes", documents:[]interface {}{(*mgo.indexSpec)(0xc2012db7e0)}} [LOG] 99.30515 Socket 0xc201451b60 to 127.0.0.1:50017: serializing document for insertion: &mgo.indexSpec{Name:"urls_1_revision_1", NS:"juju.charms", Key:bson.D{bson.DocElem{Name:"urls", Value:1}, bson.DocElem{Name:"revision", Value:1}}, Unique:true, DropDups:false, Background:false, Sparse:false, Bits:0, Min:0, Max:0, ExpireAfter:0} [LOG] 99.30524 Socket 0xc201451b60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"juju.$cmd", query:(*mgo.getLastError)(0xc2014f5d80), skip:0, limit:-1, selector:interface {}(nil), flags:0x0, replyFunc:(mgo.replyFunc)(0x53fc10), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.30526 Socket 0xc201451b60 to 127.0.0.1:50017: sending 2 op(s) (197 bytes) [LOG] 99.30528 Socket 0xc201451b60 to 127.0.0.1:50017: updated write deadline to 1m0s ahead (2014-03-06 17:53:00.433914776 +0000 UTC) [LOG] 99.30532 Socket 0xc201451b60 to 127.0.0.1:50017: updated read deadline to 1m0s ahead (2014-03-06 17:53:00.433959889 +0000 UTC) [LOG] 99.30643 Socket 0xc201451b60 to 127.0.0.1:50017: got reply (83 bytes) [LOG] 99.30658 Socket 0xc201451b60 to 127.0.0.1:50017: received document: bson.M{"n":0, "connectionId":78, "err":interface {}(nil), "ok":1} [LOG] 99.30663 Result from writing query: &mgo.LastError{Err:"", Code:0, N:0, Waited:0, FSyncFiles:0, WTimeout:false, UpdatedExisting:false, UpsertedId:interface {}(nil)} [LOG] 99.30664 Closing session 0xc20107b000 [LOG] 99.30664 Cluster 0xc2014518c0 released (refs=1) [LOG] 99.30666 Cluster 0xc2014518c0 acquired (refs=2) [LOG] 99.30667 New session 0xc20107b580 on cluster 0xc2014518c0 (copy from 0xc20144f6e0) [LOG] 99.30667 Session 0xc20107b580: setting mode 2 with refresh=false (master=0xc201451b60, slave=0x0) [LOG] 99.30669 Socket 0xc201451b60 to 127.0.0.1:50017: serializing op: &mgo.insertOp{collection:"juju.system.indexes", documents:[]interface {}{(*mgo.indexSpec)(0xc2012dbcc0)}} [LOG] 99.30672 Socket 0xc201451b60 to 127.0.0.1:50017: serializing document for insertion: &mgo.indexSpec{Name:"urls_1_digest_1", NS:"juju.events", Key:bson.D{bson.DocElem{Name:"urls", Value:1}, bson.DocElem{Name:"digest", Value:1}}, Unique:false, DropDups:false, Background:false, Sparse:false, Bits:0, Min:0, Max:0, ExpireAfter:0} [LOG] 99.30677 Socket 0xc201451b60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"juju.$cmd", query:(*mgo.getLastError)(0xc201082060), skip:0, limit:-1, selector:interface {}(nil), flags:0x0, replyFunc:(mgo.replyFunc)(0x53fc10), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.30692 Socket 0xc201451b60 to 127.0.0.1:50017: sending 2 op(s) (184 bytes) [LOG] 99.30695 Socket 0xc201451b60 to 127.0.0.1:50017: updated write deadline to 1m0s ahead (2014-03-06 17:53:00.435583119 +0000 UTC) [LOG] 99.30699 Socket 0xc201451b60 to 127.0.0.1:50017: updated read deadline to 1m0s ahead (2014-03-06 17:53:00.435629973 +0000 UTC) [LOG] 99.30805 Socket 0xc201451b60 to 127.0.0.1:50017: got reply (83 bytes) [LOG] 99.30817 Socket 0xc201451b60 to 127.0.0.1:50017: received document: bson.M{"n":0, "connectionId":78, "err":interface {}(nil), "ok":1} [LOG] 99.30821 Result from writing query: &mgo.LastError{Err:"", Code:0, N:0, Waited:0, FSyncFiles:0, WTimeout:false, UpdatedExisting:false, UpsertedId:interface {}(nil)} [LOG] 99.30822 Closing session 0xc20107b580 [LOG] 99.30823 Cluster 0xc2014518c0 released (refs=1) [LOG] 99.30852 Closing session 0xc20144f6e0 [LOG] 99.30853 Cluster 0xc2014518c0 released (refs=0) [LOG] 99.30853 Connections to 127.0.0.1:50017 closing (1 live sockets). [LOG] 99.30854 Socket 0xc201451b60 to 127.0.0.1:50017: closing: Closed explicitly (abend=false) [LOG] 99.30855 Closing session 0xc20144f420 [LOG] 99.30856 Cluster 0xc201451460 released (refs=0) [LOG] 99.30856 Connections to 127.0.0.1:50017 closing (1 live sockets). [LOG] 99.30857 Socket 0xc201451700 to 127.0.0.1:50017: closing: Closed explicitly (abend=false) [LOG] 99.30862 Socket 0xc201451b60 to 127.0.0.1:50017: killed again: read tcp 127.0.0.1:50017: use of closed network connection (previously: Closed explicitly) [LOG] 99.30865 Socket 0xc201451700 to 127.0.0.1:50017: killed again: read tcp 127.0.0.1:50017: use of closed network connection (previously: Closed explicitly) ... Panic: command failed: bzr init (PC=0x414071) /usr/lib/go/src/pkg/runtime/panic.c:229 in panic branch_test.go:185 in bzrDir.run branch_test.go:191 in bzrDir.init branch_test.go:31 in StoreSuite.dummyBranch lpad_test.go:22 in StoreSuite.TestPublishCharmDistro ---------------------------------------------------------------------- PANIC: branch_test.go:132: StoreSuite.TestPublishErrorFromBzr [LOG] 99.31339 Resetting stats [LOG] 99.31340 Cluster 0xc2006b9460 acquired (refs=2) [LOG] 99.31341 New session 0xc20107bc60 on cluster 0xc2006b9460 [LOG] 99.31342 Session 0xc20107bc60: setting mode 0 with refresh=true (master=0x0, slave=0x0) [LOG] 99.31343 Cluster 0xc2006b9460 released (refs=1) [LOG] 99.31344 Cluster has 0 known masters and 0 known slaves. [LOG] 99.31344 Waiting for servers to synchronize... [LOG] 99.31356 Socket 0xc2006b90e0 to localhost:50017: killed again: read tcp 127.0.0.1:50017: use of closed network connection (previously: Closed explicitly) [LOG] 99.31361 SYNC Cluster 0xc2006b9460 is starting a sync loop iteration. [LOG] 99.31361 SYNC Starting full topology synchronization... [LOG] 99.31364 Establishing new connection to 127.0.0.1:50017 (timeout=15s)... [LOG] 99.31382 Connection to 127.0.0.1:50017 established. [LOG] 99.31384 Socket 0xc2006b9700 to 127.0.0.1:50017: initialized [LOG] 99.31384 Socket 0xc2006b9700 to 127.0.0.1:50017: requesting a new nonce [LOG] 99.31388 Socket 0xc2006b9700 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:(*mgo.getNonceCmd)(0xc200e7c5d8), skip:0, limit:-1, selector:interface {}(nil), flags:0x0, replyFunc:(mgo.replyFunc)(0x53dfd0), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.31390 Socket 0xc2006b9700 to 127.0.0.1:50017: sending 1 op(s) (58 bytes) [LOG] 99.31392 Socket 0xc2006b9700 to 127.0.0.1:50017: updated write deadline to 15s ahead (2014-03-06 17:52:15.442561931 +0000 UTC) [LOG] 99.31399 Socket 0xc2006b9700 to 127.0.0.1:50017: updated read deadline to 15s ahead (2014-03-06 17:52:15.442629766 +0000 UTC) [LOG] 99.31404 Socket 0xc2006b9700 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ping", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x53fc80), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.31406 Socket 0xc2006b9700 to 127.0.0.1:50017: sending 1 op(s) (54 bytes) [LOG] 99.31407 Socket 0xc2006b9700 to 127.0.0.1:50017: updated write deadline to 15s ahead (2014-03-06 17:52:15.442716668 +0000 UTC) [LOG] 99.31412 Socket 0xc2006b9700 to 127.0.0.1:50017: got reply (81 bytes) [LOG] 99.31416 Socket 0xc2006b9700 to 127.0.0.1:50017: received document: bson.M{"nonce":"7cb06090d3482a6d", "ok":1} [LOG] 99.31419 Socket 0xc2006b9700 to 127.0.0.1:50017: nonce unmarshalled: &mgo.getNonceResult{Nonce:"7cb06090d3482a6d", Err:"", Code:0} [LOG] 99.31421 Socket 0xc2006b9700 to 127.0.0.1:50017: updated read deadline to 15s ahead (2014-03-06 17:52:15.442849241 +0000 UTC) [LOG] 99.31422 Socket 0xc2006b9700 to 127.0.0.1:50017: got reply (53 bytes) [LOG] 99.31425 Socket 0xc2006b9700 to 127.0.0.1:50017: received document: bson.M{"ok":1} [LOG] 99.31426 Ping for 127.0.0.1:50017 is 0 ms [LOG] 99.31431 SYNC Processing 127.0.0.1:50017... [LOG] 99.31432 Cluster 0xc2006b9460 acquired (refs=3) [LOG] 99.31432 New session 0xc20107bdc0 on cluster 0xc2006b9460 [LOG] 99.31433 Session 0xc20107bdc0: setting mode 1 with refresh=true (master=0x0, slave=0x0) [LOG] 99.31437 Socket 0xc2006b9700 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ismaster", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x53fc80), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.31447 Socket 0xc2006b9700 to 127.0.0.1:50017: sending 1 op(s) (58 bytes) [LOG] 99.31449 Socket 0xc2006b9700 to 127.0.0.1:50017: updated write deadline to 5s ahead (2014-03-06 17:52:05.443130953 +0000 UTC) [LOG] 99.31455 Socket 0xc2006b9700 to 127.0.0.1:50017: updated read deadline to 5s ahead (2014-03-06 17:52:05.443192098 +0000 UTC) [LOG] 99.31492 Socket 0xc2006b9700 to 127.0.0.1:50017: got reply (131 bytes) [LOG] 99.31503 Socket 0xc2006b9700 to 127.0.0.1:50017: received document: bson.M{"ismaster":true, "maxBsonObjectSize":16777216, "maxMessageSizeBytes":48000000, "localTime":time.Time{sec:63529725120, nsec:443000000, loc:(*time.Location)(0xc72440)}, "ok":1} [LOG] 99.31511 Query 0xc2006b97e0 document unmarshaled: &mgo.isMasterResult{IsMaster:true, Secondary:false, Primary:"", Hosts:[]string(nil), Passives:[]string(nil), Tags:bson.D(nil), Msg:""} [LOG] 99.31512 Closing session 0xc20107bdc0 [LOG] 99.31512 Cluster 0xc2006b9460 released (refs=2) [LOG] 99.31514 SYNC Result of 'ismaster' from 127.0.0.1:50017: mgo.isMasterResult{IsMaster:true, Secondary:false, Primary:"", Hosts:[]string(nil), Passives:[]string(nil), Tags:bson.D(nil), Msg:""} [LOG] 99.31515 SYNC 127.0.0.1:50017 is a master. [LOG] 99.31516 SYNC 127.0.0.1:50017 knows about the following peers: []string{} [LOG] 99.31517 SYNC Adding 127.0.0.1:50017 to cluster as a master. [LOG] 99.31517 SYNC Broadcasting availability of server 127.0.0.1:50017 [LOG] 99.31518 Cluster has 1 known masters and 0 known slaves. [LOG] 99.31526 Socket 0xc2006b9700 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ping", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x53fc80), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.31527 Socket 0xc2006b9700 to 127.0.0.1:50017: sending 1 op(s) (54 bytes) [LOG] 99.31530 Socket 0xc2006b9700 to 127.0.0.1:50017: updated write deadline to 10s ahead (2014-03-06 17:52:10.443934437 +0000 UTC) [LOG] 99.31536 Socket 0xc2006b9700 to 127.0.0.1:50017: updated read deadline to 10s ahead (2014-03-06 17:52:10.44399873 +0000 UTC) [LOG] 99.31537 SYNC Synchronization was complete (got data from primary). [LOG] 99.31538 SYNC Synchronization completed: 1 master(s) and 0 slave(s) alive. [LOG] 99.31539 SYNC New dynamic seeds: []string{"127.0.0.1:50017"} [LOG] 99.31540 Cluster 0xc2006b9460 released (refs=1) [LOG] 99.31551 Socket 0xc2006b9700 to 127.0.0.1:50017: got reply (53 bytes) [LOG] 99.31555 Socket 0xc2006b9700 to 127.0.0.1:50017: received document: bson.M{"ok":1} [LOG] 99.31557 Session 0xc20107bc60: setting mode 2 with refresh=true (master=0x0, slave=0x0) [LOG] 99.31573 INFO juju store: Store opened. Connecting to: 127.0.0.1:50017 [LOG] 99.31574 Cluster 0xc2006b98c0 acquired (refs=2) [LOG] 99.31578 New session 0xc203bf1000 on cluster 0xc2006b98c0 [LOG] 99.31579 Session 0xc203bf1000: setting mode 0 with refresh=true (master=0x0, slave=0x0) [LOG] 99.31581 Cluster 0xc2006b98c0 released (refs=1) [LOG] 99.31582 Cluster has 0 known masters and 0 known slaves. [LOG] 99.31582 Waiting for servers to synchronize... [LOG] 99.31583 SYNC Cluster 0xc2006b98c0 is starting a sync loop iteration. [LOG] 99.31587 SYNC Starting full topology synchronization... [LOG] 99.31590 Establishing new connection to 127.0.0.1:50017 (timeout=15s)... [LOG] 99.31609 Connection to 127.0.0.1:50017 established. [LOG] 99.31610 Socket 0xc2006b9b60 to 127.0.0.1:50017: initialized [LOG] 99.31611 Socket 0xc2006b9b60 to 127.0.0.1:50017: requesting a new nonce [LOG] 99.31614 Socket 0xc2006b9b60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:(*mgo.getNonceCmd)(0xc200e7cc30), skip:0, limit:-1, selector:interface {}(nil), flags:0x0, replyFunc:(mgo.replyFunc)(0x53dfd0), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.31616 Socket 0xc2006b9b60 to 127.0.0.1:50017: sending 1 op(s) (58 bytes) [LOG] 99.31618 Socket 0xc2006b9b60 to 127.0.0.1:50017: updated write deadline to 15s ahead (2014-03-06 17:52:15.444820169 +0000 UTC) [LOG] 99.31624 Socket 0xc2006b9b60 to 127.0.0.1:50017: updated read deadline to 15s ahead (2014-03-06 17:52:15.444881018 +0000 UTC) [LOG] 99.31629 Socket 0xc2006b9b60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ping", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x53fc80), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.31630 Socket 0xc2006b9b60 to 127.0.0.1:50017: sending 1 op(s) (54 bytes) [LOG] 99.31632 Socket 0xc2006b9b60 to 127.0.0.1:50017: updated write deadline to 15s ahead (2014-03-06 17:52:15.444961681 +0000 UTC) [LOG] 99.31639 Socket 0xc2006b9b60 to 127.0.0.1:50017: got reply (81 bytes) [LOG] 99.31643 Socket 0xc2006b9b60 to 127.0.0.1:50017: received document: bson.M{"nonce":"916e55a903e65930", "ok":1} [LOG] 99.31645 Socket 0xc2006b9b60 to 127.0.0.1:50017: nonce unmarshalled: &mgo.getNonceResult{Nonce:"916e55a903e65930", Err:"", Code:0} [LOG] 99.31648 Socket 0xc2006b9b60 to 127.0.0.1:50017: updated read deadline to 15s ahead (2014-03-06 17:52:15.445115548 +0000 UTC) [LOG] 99.31649 Socket 0xc2006b9b60 to 127.0.0.1:50017: got reply (53 bytes) [LOG] 99.31651 Socket 0xc2006b9b60 to 127.0.0.1:50017: received document: bson.M{"ok":1} [LOG] 99.31653 Ping for 127.0.0.1:50017 is 0 ms [LOG] 99.31657 SYNC Processing 127.0.0.1:50017... [LOG] 99.31658 Cluster 0xc2006b98c0 acquired (refs=3) [LOG] 99.31659 New session 0xc203bf1160 on cluster 0xc2006b98c0 [LOG] 99.31659 Session 0xc203bf1160: setting mode 1 with refresh=true (master=0x0, slave=0x0) [LOG] 99.31667 Socket 0xc2006b9b60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ismaster", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x53fc80), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.31672 Socket 0xc2006b9b60 to 127.0.0.1:50017: sending 1 op(s) (58 bytes) [LOG] 99.31673 Socket 0xc2006b9b60 to 127.0.0.1:50017: updated write deadline to 5s ahead (2014-03-06 17:52:05.445376042 +0000 UTC) [LOG] 99.31680 Socket 0xc2006b9b60 to 127.0.0.1:50017: updated read deadline to 5s ahead (2014-03-06 17:52:05.445435739 +0000 UTC) [LOG] 99.31696 Socket 0xc2006b9b60 to 127.0.0.1:50017: got reply (131 bytes) [LOG] 99.31702 Socket 0xc2006b9b60 to 127.0.0.1:50017: received document: bson.M{"ismaster":true, "maxBsonObjectSize":16777216, "maxMessageSizeBytes":48000000, "localTime":time.Time{sec:63529725120, nsec:445000000, loc:(*time.Location)(0xc72440)}, "ok":1} [LOG] 99.31710 Query 0xc2006b9c40 document unmarshaled: &mgo.isMasterResult{IsMaster:true, Secondary:false, Primary:"", Hosts:[]string(nil), Passives:[]string(nil), Tags:bson.D(nil), Msg:""} [LOG] 99.31711 Closing session 0xc203bf1160 [LOG] 99.31712 Cluster 0xc2006b98c0 released (refs=2) [LOG] 99.31714 SYNC Result of 'ismaster' from 127.0.0.1:50017: mgo.isMasterResult{IsMaster:true, Secondary:false, Primary:"", Hosts:[]string(nil), Passives:[]string(nil), Tags:bson.D(nil), Msg:""} [LOG] 99.31715 SYNC 127.0.0.1:50017 is a master. [LOG] 99.31716 SYNC 127.0.0.1:50017 knows about the following peers: []string{} [LOG] 99.31717 SYNC Adding 127.0.0.1:50017 to cluster as a master. [LOG] 99.31717 SYNC Broadcasting availability of server 127.0.0.1:50017 [LOG] 99.31718 Cluster has 1 known masters and 0 known slaves. [LOG] 99.31725 Socket 0xc2006b9b60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ping", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x53fc80), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.31727 Socket 0xc2006b9b60 to 127.0.0.1:50017: sending 1 op(s) (54 bytes) [LOG] 99.31729 Socket 0xc2006b9b60 to 127.0.0.1:50017: updated write deadline to 10s ahead (2014-03-06 17:52:10.445926 +0000 UTC) [LOG] 99.31735 Socket 0xc2006b9b60 to 127.0.0.1:50017: updated read deadline to 10s ahead (2014-03-06 17:52:10.445988112 +0000 UTC) [LOG] 99.31736 SYNC Synchronization was complete (got data from primary). [LOG] 99.31737 SYNC Synchronization completed: 1 master(s) and 0 slave(s) alive. [LOG] 99.31738 SYNC New dynamic seeds: []string{"127.0.0.1:50017"} [LOG] 99.31738 Cluster 0xc2006b98c0 released (refs=1) [LOG] 99.31746 Socket 0xc2006b9b60 to 127.0.0.1:50017: got reply (53 bytes) [LOG] 99.31753 Socket 0xc2006b9b60 to 127.0.0.1:50017: received document: bson.M{"ok":1} [LOG] 99.31755 Session 0xc203bf1000: setting mode 2 with refresh=true (master=0x0, slave=0x0) [LOG] 99.31756 Cluster has 1 known masters and 0 known slaves. [LOG] 99.31759 Socket 0xc2006b9b60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"juju.$cmd", query:bson.D{bson.DocElem{Name:"create", Value:"stat.counters"}, bson.DocElem{Name:"autoIndexId", Value:false}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x0, replyFunc:(mgo.replyFunc)(0x53fc80), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.31760 Socket 0xc2006b9b60 to 127.0.0.1:50017: sending 1 op(s) (83 bytes) [LOG] 99.31765 Socket 0xc2006b9b60 to 127.0.0.1:50017: updated write deadline to 1m0s ahead (2014-03-06 17:53:00.446257055 +0000 UTC) [LOG] 99.31769 Socket 0xc2006b9b60 to 127.0.0.1:50017: updated read deadline to 1m0s ahead (2014-03-06 17:53:00.44633485 +0000 UTC) [LOG] 99.32222 Socket 0xc2006b9b60 to 127.0.0.1:50017: got reply (53 bytes) [LOG] 99.32227 Socket 0xc2006b9b60 to 127.0.0.1:50017: received document: bson.M{"ok":1} [LOG] 99.32231 Cluster 0xc2006b98c0 acquired (refs=2) [LOG] 99.32234 New session 0xc203bf12c0 on cluster 0xc2006b98c0 (copy from 0xc203bf1000) [LOG] 99.32235 Session 0xc203bf12c0: setting mode 2 with refresh=false (master=0xc2006b9b60, slave=0x0) [LOG] 99.32236 Socket 0xc2006b9b60 to 127.0.0.1:50017: serializing op: &mgo.insertOp{collection:"juju.system.indexes", documents:[]interface {}{(*mgo.indexSpec)(0xc201279d80)}} [LOG] 99.32238 Socket 0xc2006b9b60 to 127.0.0.1:50017: serializing document for insertion: &mgo.indexSpec{Name:"k_1_t_1", NS:"juju.stat.counters", Key:bson.D{bson.DocElem{Name:"k", Value:1}, bson.DocElem{Name:"t", Value:1}}, Unique:true, DropDups:false, Background:false, Sparse:false, Bits:0, Min:0, Max:0, ExpireAfter:0} [LOG] 99.32241 Socket 0xc2006b9b60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"juju.$cmd", query:(*mgo.getLastError)(0xc203bf3990), skip:0, limit:-1, selector:interface {}(nil), flags:0x0, replyFunc:(mgo.replyFunc)(0x53fc10), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.32242 Socket 0xc2006b9b60 to 127.0.0.1:50017: sending 2 op(s) (184 bytes) [LOG] 99.32244 Socket 0xc2006b9b60 to 127.0.0.1:50017: updated write deadline to 1m0s ahead (2014-03-06 17:53:00.451081843 +0000 UTC) [LOG] 99.32248 Socket 0xc2006b9b60 to 127.0.0.1:50017: updated read deadline to 1m0s ahead (2014-03-06 17:53:00.451125305 +0000 UTC) [LOG] 99.32345 Socket 0xc2006b9b60 to 127.0.0.1:50017: got reply (83 bytes) [LOG] 99.32357 Socket 0xc2006b9b60 to 127.0.0.1:50017: received document: bson.M{"n":0, "connectionId":81, "err":interface {}(nil), "ok":1} [LOG] 99.32362 Result from writing query: &mgo.LastError{Err:"", Code:0, N:0, Waited:0, FSyncFiles:0, WTimeout:false, UpdatedExisting:false, UpsertedId:interface {}(nil)} [LOG] 99.32363 Closing session 0xc203bf12c0 [LOG] 99.32365 Cluster 0xc2006b98c0 released (refs=1) [LOG] 99.32366 Cluster 0xc2006b98c0 acquired (refs=2) [LOG] 99.32367 New session 0xc203bf16e0 on cluster 0xc2006b98c0 (copy from 0xc203bf1000) [LOG] 99.32367 Session 0xc203bf16e0: setting mode 2 with refresh=false (master=0xc2006b9b60, slave=0x0) [LOG] 99.32370 Socket 0xc2006b9b60 to 127.0.0.1:50017: serializing op: &mgo.insertOp{collection:"juju.system.indexes", documents:[]interface {}{(*mgo.indexSpec)(0xc20125b060)}} [LOG] 99.32374 Socket 0xc2006b9b60 to 127.0.0.1:50017: serializing document for insertion: &mgo.indexSpec{Name:"t_1", NS:"juju.stat.tokens", Key:bson.D{bson.DocElem{Name:"t", Value:1}}, Unique:true, DropDups:false, Background:false, Sparse:false, Bits:0, Min:0, Max:0, ExpireAfter:0} [LOG] 99.32380 Socket 0xc2006b9b60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"juju.$cmd", query:(*mgo.getLastError)(0xc203bf3c60), skip:0, limit:-1, selector:interface {}(nil), flags:0x0, replyFunc:(mgo.replyFunc)(0x53fc10), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.32382 Socket 0xc2006b9b60 to 127.0.0.1:50017: sending 2 op(s) (171 bytes) [LOG] 99.32384 Socket 0xc2006b9b60 to 127.0.0.1:50017: updated write deadline to 1m0s ahead (2014-03-06 17:53:00.452475392 +0000 UTC) [LOG] 99.32388 Socket 0xc2006b9b60 to 127.0.0.1:50017: updated read deadline to 1m0s ahead (2014-03-06 17:53:00.452520535 +0000 UTC) [LOG] 99.32522 Socket 0xc2006b9b60 to 127.0.0.1:50017: got reply (83 bytes) [LOG] 99.32530 Socket 0xc2006b9b60 to 127.0.0.1:50017: received document: bson.M{"n":0, "connectionId":81, "err":interface {}(nil), "ok":1} [LOG] 99.32535 Result from writing query: &mgo.LastError{Err:"", Code:0, N:0, Waited:0, FSyncFiles:0, WTimeout:false, UpdatedExisting:false, UpsertedId:interface {}(nil)} [LOG] 99.32536 Closing session 0xc203bf16e0 [LOG] 99.32537 Cluster 0xc2006b98c0 released (refs=1) [LOG] 99.32545 Cluster 0xc2006b98c0 acquired (refs=2) [LOG] 99.32546 New session 0xc203bf1840 on cluster 0xc2006b98c0 (copy from 0xc203bf1000) [LOG] 99.32547 Session 0xc203bf1840: setting mode 2 with refresh=false (master=0xc2006b9b60, slave=0x0) [LOG] 99.32551 Socket 0xc2006b9b60 to 127.0.0.1:50017: serializing op: &mgo.insertOp{collection:"juju.system.indexes", documents:[]interface {}{(*mgo.indexSpec)(0xc20125b420)}} [LOG] 99.32554 Socket 0xc2006b9b60 to 127.0.0.1:50017: serializing document for insertion: &mgo.indexSpec{Name:"urls_1_revision_1", NS:"juju.charms", Key:bson.D{bson.DocElem{Name:"urls", Value:1}, bson.DocElem{Name:"revision", Value:1}}, Unique:true, DropDups:false, Background:false, Sparse:false, Bits:0, Min:0, Max:0, ExpireAfter:0} [LOG] 99.32558 Socket 0xc2006b9b60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"juju.$cmd", query:(*mgo.getLastError)(0xc203bf3f30), skip:0, limit:-1, selector:interface {}(nil), flags:0x0, replyFunc:(mgo.replyFunc)(0x53fc10), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.32561 Socket 0xc2006b9b60 to 127.0.0.1:50017: sending 2 op(s) (197 bytes) [LOG] 99.32563 Socket 0xc2006b9b60 to 127.0.0.1:50017: updated write deadline to 1m0s ahead (2014-03-06 17:53:00.454268762 +0000 UTC) [LOG] 99.32567 Socket 0xc2006b9b60 to 127.0.0.1:50017: updated read deadline to 1m0s ahead (2014-03-06 17:53:00.454313572 +0000 UTC) [LOG] 99.32702 Socket 0xc2006b9b60 to 127.0.0.1:50017: got reply (83 bytes) [LOG] 99.32710 Socket 0xc2006b9b60 to 127.0.0.1:50017: received document: bson.M{"n":0, "connectionId":81, "err":interface {}(nil), "ok":1} [LOG] 99.32714 Result from writing query: &mgo.LastError{Err:"", Code:0, N:0, Waited:0, FSyncFiles:0, WTimeout:false, UpdatedExisting:false, UpsertedId:interface {}(nil)} [LOG] 99.32723 Closing session 0xc203bf1840 [LOG] 99.32724 Cluster 0xc2006b98c0 released (refs=1) [LOG] 99.32725 Cluster 0xc2006b98c0 acquired (refs=2) [LOG] 99.32726 New session 0xc203bf1dc0 on cluster 0xc2006b98c0 (copy from 0xc203bf1000) [LOG] 99.32727 Session 0xc203bf1dc0: setting mode 2 with refresh=false (master=0xc2006b9b60, slave=0x0) [LOG] 99.32729 Socket 0xc2006b9b60 to 127.0.0.1:50017: serializing op: &mgo.insertOp{collection:"juju.system.indexes", documents:[]interface {}{(*mgo.indexSpec)(0xc20125b960)}} [LOG] 99.32732 Socket 0xc2006b9b60 to 127.0.0.1:50017: serializing document for insertion: &mgo.indexSpec{Name:"urls_1_digest_1", NS:"juju.events", Key:bson.D{bson.DocElem{Name:"urls", Value:1}, bson.DocElem{Name:"digest", Value:1}}, Unique:false, DropDups:false, Background:false, Sparse:false, Bits:0, Min:0, Max:0, ExpireAfter:0} [LOG] 99.32737 Socket 0xc2006b9b60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"juju.$cmd", query:(*mgo.getLastError)(0xc200b33210), skip:0, limit:-1, selector:interface {}(nil), flags:0x0, replyFunc:(mgo.replyFunc)(0x53fc10), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.32743 Socket 0xc2006b9b60 to 127.0.0.1:50017: sending 2 op(s) (184 bytes) [LOG] 99.32745 Socket 0xc2006b9b60 to 127.0.0.1:50017: updated write deadline to 1m0s ahead (2014-03-06 17:53:00.456087547 +0000 UTC) [LOG] 99.32750 Socket 0xc2006b9b60 to 127.0.0.1:50017: updated read deadline to 1m0s ahead (2014-03-06 17:53:00.456137188 +0000 UTC) [LOG] 99.32882 Socket 0xc2006b9b60 to 127.0.0.1:50017: got reply (83 bytes) [LOG] 99.32890 Socket 0xc2006b9b60 to 127.0.0.1:50017: received document: bson.M{"n":0, "connectionId":81, "err":interface {}(nil), "ok":1} [LOG] 99.32895 Result from writing query: &mgo.LastError{Err:"", Code:0, N:0, Waited:0, FSyncFiles:0, WTimeout:false, UpdatedExisting:false, UpsertedId:interface {}(nil)} [LOG] 99.32896 Closing session 0xc203bf1dc0 [LOG] 99.32896 Cluster 0xc2006b98c0 released (refs=1) [LOG] 99.32910 Closing session 0xc203bf1000 [LOG] 99.32910 Cluster 0xc2006b98c0 released (refs=0) [LOG] 99.32911 Connections to 127.0.0.1:50017 closing (1 live sockets). [LOG] 99.32912 Socket 0xc2006b9b60 to 127.0.0.1:50017: closing: Closed explicitly (abend=false) [LOG] 99.32913 Closing session 0xc20107bc60 [LOG] 99.32913 Cluster 0xc2006b9460 released (refs=0) [LOG] 99.32914 Connections to 127.0.0.1:50017 closing (1 live sockets). [LOG] 99.32915 Socket 0xc2006b9700 to 127.0.0.1:50017: closing: Closed explicitly (abend=false) [LOG] 99.32920 Socket 0xc2006b9b60 to 127.0.0.1:50017: killed again: read tcp 127.0.0.1:50017: use of closed network connection (previously: Closed explicitly) [LOG] 99.32923 Socket 0xc2006b9700 to 127.0.0.1:50017: killed again: read tcp 127.0.0.1:50017: use of closed network connection (previously: Closed explicitly) ... Panic: command failed: bzr init (PC=0x414071) /usr/lib/go/src/pkg/runtime/panic.c:229 in panic branch_test.go:185 in bzrDir.run branch_test.go:191 in bzrDir.init branch_test.go:31 in StoreSuite.dummyBranch branch_test.go:133 in StoreSuite.TestPublishErrorFromBzr ---------------------------------------------------------------------- PANIC: branch_test.go:147: StoreSuite.TestPublishErrorInCharm [LOG] 99.33264 Resetting stats [LOG] 99.33266 Cluster 0xc2010d9460 acquired (refs=2) [LOG] 99.33267 New session 0xc200b35580 on cluster 0xc2010d9460 [LOG] 99.33268 Session 0xc200b35580: setting mode 0 with refresh=true (master=0x0, slave=0x0) [LOG] 99.33268 Cluster 0xc2010d9460 released (refs=1) [LOG] 99.33269 Cluster has 0 known masters and 0 known slaves. [LOG] 99.33269 Waiting for servers to synchronize... [LOG] 99.33272 Socket 0xc2010d90e0 to localhost:50017: killed again: read tcp 127.0.0.1:50017: use of closed network connection (previously: Closed explicitly) [LOG] 99.33273 SYNC Cluster 0xc2010d9460 is starting a sync loop iteration. [LOG] 99.33273 SYNC Starting full topology synchronization... [LOG] 99.33275 Establishing new connection to 127.0.0.1:50017 (timeout=15s)... [LOG] 99.33288 Connection to 127.0.0.1:50017 established. [LOG] 99.33290 Socket 0xc2010d9700 to 127.0.0.1:50017: initialized [LOG] 99.33290 Socket 0xc2010d9700 to 127.0.0.1:50017: requesting a new nonce [LOG] 99.33293 Socket 0xc2010d9700 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:(*mgo.getNonceCmd)(0xc2010dc8b0), skip:0, limit:-1, selector:interface {}(nil), flags:0x0, replyFunc:(mgo.replyFunc)(0x53dfd0), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.33298 Socket 0xc2010d9700 to 127.0.0.1:50017: sending 1 op(s) (58 bytes) [LOG] 99.33299 Socket 0xc2010d9700 to 127.0.0.1:50017: updated write deadline to 15s ahead (2014-03-06 17:52:15.461635222 +0000 UTC) [LOG] 99.33302 Socket 0xc2010d9700 to 127.0.0.1:50017: updated read deadline to 15s ahead (2014-03-06 17:52:15.461669034 +0000 UTC) [LOG] 99.33310 Socket 0xc2010d9700 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ping", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x53fc80), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.33316 Socket 0xc2010d9700 to 127.0.0.1:50017: sending 1 op(s) (54 bytes) [LOG] 99.33318 Socket 0xc2010d9700 to 127.0.0.1:50017: updated write deadline to 15s ahead (2014-03-06 17:52:15.461819723 +0000 UTC) [LOG] 99.33346 Socket 0xc2010d9700 to 127.0.0.1:50017: got reply (81 bytes) [LOG] 99.33358 Socket 0xc2010d9700 to 127.0.0.1:50017: received document: bson.M{"nonce":"a3007ed35122108e", "ok":1} [LOG] 99.33360 Socket 0xc2010d9700 to 127.0.0.1:50017: nonce unmarshalled: &mgo.getNonceResult{Nonce:"a3007ed35122108e", Err:"", Code:0} [LOG] 99.33361 Socket 0xc2010d9700 to 127.0.0.1:50017: updated read deadline to 15s ahead (2014-03-06 17:52:15.46225397 +0000 UTC) [LOG] 99.33362 Socket 0xc2010d9700 to 127.0.0.1:50017: got reply (53 bytes) [LOG] 99.33363 Socket 0xc2010d9700 to 127.0.0.1:50017: received document: bson.M{"ok":1} [LOG] 99.33365 Ping for 127.0.0.1:50017 is 0 ms [LOG] 99.33368 SYNC Processing 127.0.0.1:50017... [LOG] 99.33369 Cluster 0xc2010d9460 acquired (refs=3) [LOG] 99.33369 New session 0xc200b356e0 on cluster 0xc2010d9460 [LOG] 99.33372 Session 0xc200b356e0: setting mode 1 with refresh=true (master=0x0, slave=0x0) [LOG] 99.33380 Socket 0xc2010d9700 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ismaster", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x53fc80), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.33381 Socket 0xc2010d9700 to 127.0.0.1:50017: sending 1 op(s) (58 bytes) [LOG] 99.33382 Socket 0xc2010d9700 to 127.0.0.1:50017: updated write deadline to 5s ahead (2014-03-06 17:52:05.462465641 +0000 UTC) [LOG] 99.33387 Socket 0xc2010d9700 to 127.0.0.1:50017: updated read deadline to 5s ahead (2014-03-06 17:52:05.462511306 +0000 UTC) [LOG] 99.33397 Socket 0xc2010d9700 to 127.0.0.1:50017: got reply (131 bytes) [LOG] 99.33407 Socket 0xc2010d9700 to 127.0.0.1:50017: received document: bson.M{"ismaster":true, "maxBsonObjectSize":16777216, "maxMessageSizeBytes":48000000, "localTime":time.Time{sec:63529725120, nsec:462000000, loc:(*time.Location)(0xc72440)}, "ok":1} [LOG] 99.33410 Query 0xc2010d97e0 document unmarshaled: &mgo.isMasterResult{IsMaster:true, Secondary:false, Primary:"", Hosts:[]string(nil), Passives:[]string(nil), Tags:bson.D(nil), Msg:""} [LOG] 99.33411 Closing session 0xc200b356e0 [LOG] 99.33411 Cluster 0xc2010d9460 released (refs=2) [LOG] 99.33412 SYNC Result of 'ismaster' from 127.0.0.1:50017: mgo.isMasterResult{IsMaster:true, Secondary:false, Primary:"", Hosts:[]string(nil), Passives:[]string(nil), Tags:bson.D(nil), Msg:""} [LOG] 99.33416 SYNC 127.0.0.1:50017 is a master. [LOG] 99.33417 SYNC 127.0.0.1:50017 knows about the following peers: []string{} [LOG] 99.33418 SYNC Adding 127.0.0.1:50017 to cluster as a master. [LOG] 99.33418 SYNC Broadcasting availability of server 127.0.0.1:50017 [LOG] 99.33418 Cluster has 1 known masters and 0 known slaves. [LOG] 99.33424 Socket 0xc2010d9700 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ping", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x53fc80), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.33425 Socket 0xc2010d9700 to 127.0.0.1:50017: sending 1 op(s) (54 bytes) [LOG] 99.33427 Socket 0xc2010d9700 to 127.0.0.1:50017: updated write deadline to 10s ahead (2014-03-06 17:52:10.462912412 +0000 UTC) [LOG] 99.33430 Socket 0xc2010d9700 to 127.0.0.1:50017: updated read deadline to 10s ahead (2014-03-06 17:52:10.462943272 +0000 UTC) [LOG] 99.33430 SYNC Synchronization was complete (got data from primary). [LOG] 99.33431 SYNC Synchronization completed: 1 master(s) and 0 slave(s) alive. [LOG] 99.33432 SYNC New dynamic seeds: []string{"127.0.0.1:50017"} [LOG] 99.33432 Cluster 0xc2010d9460 released (refs=1) [LOG] 99.33440 Socket 0xc2010d9700 to 127.0.0.1:50017: got reply (53 bytes) [LOG] 99.33442 Socket 0xc2010d9700 to 127.0.0.1:50017: received document: bson.M{"ok":1} [LOG] 99.33444 Session 0xc200b35580: setting mode 2 with refresh=true (master=0x0, slave=0x0) [LOG] 99.33446 INFO juju store: Store opened. Connecting to: 127.0.0.1:50017 [LOG] 99.33447 Cluster 0xc2010d98c0 acquired (refs=2) [LOG] 99.33447 New session 0xc200b359a0 on cluster 0xc2010d98c0 [LOG] 99.33448 Session 0xc200b359a0: setting mode 0 with refresh=true (master=0x0, slave=0x0) [LOG] 99.33448 Cluster 0xc2010d98c0 released (refs=1) [LOG] 99.33449 Cluster has 0 known masters and 0 known slaves. [LOG] 99.33449 Waiting for servers to synchronize... [LOG] 99.33450 SYNC Cluster 0xc2010d98c0 is starting a sync loop iteration. [LOG] 99.33450 SYNC Starting full topology synchronization... [LOG] 99.33455 Establishing new connection to 127.0.0.1:50017 (timeout=15s)... [LOG] 99.33461 Connection to 127.0.0.1:50017 established. [LOG] 99.33462 Socket 0xc2010d9b60 to 127.0.0.1:50017: initialized [LOG] 99.33463 Socket 0xc2010d9b60 to 127.0.0.1:50017: requesting a new nonce [LOG] 99.33465 Socket 0xc2010d9b60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:(*mgo.getNonceCmd)(0xc2010dcf08), skip:0, limit:-1, selector:interface {}(nil), flags:0x0, replyFunc:(mgo.replyFunc)(0x53dfd0), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.33466 Socket 0xc2010d9b60 to 127.0.0.1:50017: sending 1 op(s) (58 bytes) [LOG] 99.33467 Socket 0xc2010d9b60 to 127.0.0.1:50017: updated write deadline to 15s ahead (2014-03-06 17:52:15.46331736 +0000 UTC) [LOG] 99.33471 Socket 0xc2010d9b60 to 127.0.0.1:50017: updated read deadline to 15s ahead (2014-03-06 17:52:15.463350347 +0000 UTC) [LOG] 99.33476 Socket 0xc2010d9b60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ping", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x53fc80), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.33480 Socket 0xc2010d9b60 to 127.0.0.1:50017: sending 1 op(s) (54 bytes) [LOG] 99.33482 Socket 0xc2010d9b60 to 127.0.0.1:50017: updated write deadline to 15s ahead (2014-03-06 17:52:15.463461497 +0000 UTC) [LOG] 99.33512 Socket 0xc2010d9b60 to 127.0.0.1:50017: got reply (81 bytes) [LOG] 99.33517 Socket 0xc2010d9b60 to 127.0.0.1:50017: received document: bson.M{"nonce":"d87f59cf9dada89e", "ok":1} [LOG] 99.33520 Socket 0xc2010d9b60 to 127.0.0.1:50017: nonce unmarshalled: &mgo.getNonceResult{Nonce:"d87f59cf9dada89e", Err:"", Code:0} [LOG] 99.33521 Socket 0xc2010d9b60 to 127.0.0.1:50017: updated read deadline to 15s ahead (2014-03-06 17:52:15.463858581 +0000 UTC) [LOG] 99.33522 Socket 0xc2010d9b60 to 127.0.0.1:50017: got reply (53 bytes) [LOG] 99.33524 Socket 0xc2010d9b60 to 127.0.0.1:50017: received document: bson.M{"ok":1} [LOG] 99.33525 Ping for 127.0.0.1:50017 is 0 ms [LOG] 99.33528 SYNC Processing 127.0.0.1:50017... [LOG] 99.33529 Cluster 0xc2010d98c0 acquired (refs=3) [LOG] 99.33529 New session 0xc200b35b00 on cluster 0xc2010d98c0 [LOG] 99.33530 Session 0xc200b35b00: setting mode 1 with refresh=true (master=0x0, slave=0x0) [LOG] 99.33532 Socket 0xc2010d9b60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ismaster", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x53fc80), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.33536 Socket 0xc2010d9b60 to 127.0.0.1:50017: sending 1 op(s) (58 bytes) [LOG] 99.33537 Socket 0xc2010d9b60 to 127.0.0.1:50017: updated write deadline to 5s ahead (2014-03-06 17:52:05.464016334 +0000 UTC) [LOG] 99.33541 Socket 0xc2010d9b60 to 127.0.0.1:50017: updated read deadline to 5s ahead (2014-03-06 17:52:05.464059351 +0000 UTC) [LOG] 99.33545 Socket 0xc2010d9b60 to 127.0.0.1:50017: got reply (131 bytes) [LOG] 99.33550 Socket 0xc2010d9b60 to 127.0.0.1:50017: received document: bson.M{"ismaster":true, "maxBsonObjectSize":16777216, "maxMessageSizeBytes":48000000, "localTime":time.Time{sec:63529725120, nsec:464000000, loc:(*time.Location)(0xc72440)}, "ok":1} [LOG] 99.33552 Query 0xc2010d9c40 document unmarshaled: &mgo.isMasterResult{IsMaster:true, Secondary:false, Primary:"", Hosts:[]string(nil), Passives:[]string(nil), Tags:bson.D(nil), Msg:""} [LOG] 99.33553 Closing session 0xc200b35b00 [LOG] 99.33554 Cluster 0xc2010d98c0 released (refs=2) [LOG] 99.33555 SYNC Result of 'ismaster' from 127.0.0.1:50017: mgo.isMasterResult{IsMaster:true, Secondary:false, Primary:"", Hosts:[]string(nil), Passives:[]string(nil), Tags:bson.D(nil), Msg:""} [LOG] 99.33555 SYNC 127.0.0.1:50017 is a master. [LOG] 99.33556 SYNC 127.0.0.1:50017 knows about the following peers: []string{} [LOG] 99.33556 SYNC Adding 127.0.0.1:50017 to cluster as a master. [LOG] 99.33557 SYNC Broadcasting availability of server 127.0.0.1:50017 [LOG] 99.33560 Cluster has 1 known masters and 0 known slaves. [LOG] 99.33562 Socket 0xc2010d9b60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ping", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x53fc80), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.33563 Socket 0xc2010d9b60 to 127.0.0.1:50017: sending 1 op(s) (54 bytes) [LOG] 99.33564 Socket 0xc2010d9b60 to 127.0.0.1:50017: updated write deadline to 10s ahead (2014-03-06 17:52:10.464290124 +0000 UTC) [LOG] 99.33569 Socket 0xc2010d9b60 to 127.0.0.1:50017: updated read deadline to 10s ahead (2014-03-06 17:52:10.464333703 +0000 UTC) [LOG] 99.33570 SYNC Synchronization was complete (got data from primary). [LOG] 99.33570 SYNC Synchronization completed: 1 master(s) and 0 slave(s) alive. [LOG] 99.33571 SYNC New dynamic seeds: []string{"127.0.0.1:50017"} [LOG] 99.33571 Cluster 0xc2010d98c0 released (refs=1) [LOG] 99.33572 Socket 0xc2010d9b60 to 127.0.0.1:50017: got reply (53 bytes) [LOG] 99.33574 Socket 0xc2010d9b60 to 127.0.0.1:50017: received document: bson.M{"ok":1} [LOG] 99.33575 Session 0xc200b359a0: setting mode 2 with refresh=true (master=0x0, slave=0x0) [LOG] 99.33576 Cluster has 1 known masters and 0 known slaves. [LOG] 99.33579 Socket 0xc2010d9b60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"juju.$cmd", query:bson.D{bson.DocElem{Name:"create", Value:"stat.counters"}, bson.DocElem{Name:"autoIndexId", Value:false}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x0, replyFunc:(mgo.replyFunc)(0x53fc80), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.33584 Socket 0xc2010d9b60 to 127.0.0.1:50017: sending 1 op(s) (83 bytes) [LOG] 99.33592 Socket 0xc2010d9b60 to 127.0.0.1:50017: updated write deadline to 1m0s ahead (2014-03-06 17:53:00.464496269 +0000 UTC) [LOG] 99.33596 Socket 0xc2010d9b60 to 127.0.0.1:50017: updated read deadline to 1m0s ahead (2014-03-06 17:53:00.464606319 +0000 UTC) [LOG] 99.34079 Socket 0xc2010d9b60 to 127.0.0.1:50017: got reply (53 bytes) [LOG] 99.34083 Socket 0xc2010d9b60 to 127.0.0.1:50017: received document: bson.M{"ok":1} [LOG] 99.34085 Cluster 0xc2010d98c0 acquired (refs=2) [LOG] 99.34086 New session 0xc200b35c60 on cluster 0xc2010d98c0 (copy from 0xc200b359a0) [LOG] 99.34086 Session 0xc200b35c60: setting mode 2 with refresh=false (master=0xc2010d9b60, slave=0x0) [LOG] 99.34096 Socket 0xc2010d9b60 to 127.0.0.1:50017: serializing op: &mgo.insertOp{collection:"juju.system.indexes", documents:[]interface {}{(*mgo.indexSpec)(0xc201208a20)}} [LOG] 99.34099 Socket 0xc2010d9b60 to 127.0.0.1:50017: serializing document for insertion: &mgo.indexSpec{Name:"k_1_t_1", NS:"juju.stat.counters", Key:bson.D{bson.DocElem{Name:"k", Value:1}, bson.DocElem{Name:"t", Value:1}}, Unique:true, DropDups:false, Background:false, Sparse:false, Bits:0, Min:0, Max:0, ExpireAfter:0} [LOG] 99.34107 Socket 0xc2010d9b60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"juju.$cmd", query:(*mgo.getLastError)(0xc20143d960), skip:0, limit:-1, selector:interface {}(nil), flags:0x0, replyFunc:(mgo.replyFunc)(0x53fc10), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.34109 Socket 0xc2010d9b60 to 127.0.0.1:50017: sending 2 op(s) (184 bytes) [LOG] 99.34110 Socket 0xc2010d9b60 to 127.0.0.1:50017: updated write deadline to 1m0s ahead (2014-03-06 17:53:00.469744738 +0000 UTC) [LOG] 99.34128 Socket 0xc2010d9b60 to 127.0.0.1:50017: updated read deadline to 1m0s ahead (2014-03-06 17:53:00.469920178 +0000 UTC) [LOG] 99.34201 Socket 0xc2010d9b60 to 127.0.0.1:50017: got reply (83 bytes) [LOG] 99.34208 Socket 0xc2010d9b60 to 127.0.0.1:50017: received document: bson.M{"n":0, "connectionId":84, "err":interface {}(nil), "ok":1} [LOG] 99.34215 Result from writing query: &mgo.LastError{Err:"", Code:0, N:0, Waited:0, FSyncFiles:0, WTimeout:false, UpdatedExisting:false, UpsertedId:interface {}(nil)} [LOG] 99.34216 Closing session 0xc200b35c60 [LOG] 99.34216 Cluster 0xc2010d98c0 released (refs=1) [LOG] 99.34218 Cluster 0xc2010d98c0 acquired (refs=2) [LOG] 99.34219 New session 0xc204384160 on cluster 0xc2010d98c0 (copy from 0xc200b359a0) [LOG] 99.34221 Session 0xc204384160: setting mode 2 with refresh=false (master=0xc2010d9b60, slave=0x0) [LOG] 99.34224 Socket 0xc2010d9b60 to 127.0.0.1:50017: serializing op: &mgo.insertOp{collection:"juju.system.indexes", documents:[]interface {}{(*mgo.indexSpec)(0xc201208de0)}} [LOG] 99.34227 Socket 0xc2010d9b60 to 127.0.0.1:50017: serializing document for insertion: &mgo.indexSpec{Name:"t_1", NS:"juju.stat.tokens", Key:bson.D{bson.DocElem{Name:"t", Value:1}}, Unique:true, DropDups:false, Background:false, Sparse:false, Bits:0, Min:0, Max:0, ExpireAfter:0} [LOG] 99.34234 Socket 0xc2010d9b60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"juju.$cmd", query:(*mgo.getLastError)(0xc20143dc30), skip:0, limit:-1, selector:interface {}(nil), flags:0x0, replyFunc:(mgo.replyFunc)(0x53fc10), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.34242 Socket 0xc2010d9b60 to 127.0.0.1:50017: sending 2 op(s) (171 bytes) [LOG] 99.34245 Socket 0xc2010d9b60 to 127.0.0.1:50017: updated write deadline to 1m0s ahead (2014-03-06 17:53:00.471081151 +0000 UTC) [LOG] 99.34251 Socket 0xc2010d9b60 to 127.0.0.1:50017: updated read deadline to 1m0s ahead (2014-03-06 17:53:00.471142176 +0000 UTC) [LOG] 99.34375 Socket 0xc2010d9b60 to 127.0.0.1:50017: got reply (83 bytes) [LOG] 99.34389 Socket 0xc2010d9b60 to 127.0.0.1:50017: received document: bson.M{"n":0, "connectionId":84, "err":interface {}(nil), "ok":1} [LOG] 99.34395 Result from writing query: &mgo.LastError{Err:"", Code:0, N:0, Waited:0, FSyncFiles:0, WTimeout:false, UpdatedExisting:false, UpsertedId:interface {}(nil)} [LOG] 99.34397 Closing session 0xc204384160 [LOG] 99.34398 Cluster 0xc2010d98c0 released (refs=1) [LOG] 99.34399 Cluster 0xc2010d98c0 acquired (refs=2) [LOG] 99.34400 New session 0xc2043842c0 on cluster 0xc2010d98c0 (copy from 0xc200b359a0) [LOG] 99.34401 Session 0xc2043842c0: setting mode 2 with refresh=false (master=0xc2010d9b60, slave=0x0) [LOG] 99.34410 Socket 0xc2010d9b60 to 127.0.0.1:50017: serializing op: &mgo.insertOp{collection:"juju.system.indexes", documents:[]interface {}{(*mgo.indexSpec)(0xc2011ee0c0)}} [LOG] 99.34414 Socket 0xc2010d9b60 to 127.0.0.1:50017: serializing document for insertion: &mgo.indexSpec{Name:"urls_1_revision_1", NS:"juju.charms", Key:bson.D{bson.DocElem{Name:"urls", Value:1}, bson.DocElem{Name:"revision", Value:1}}, Unique:true, DropDups:false, Background:false, Sparse:false, Bits:0, Min:0, Max:0, ExpireAfter:0} [LOG] 99.34420 Socket 0xc2010d9b60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"juju.$cmd", query:(*mgo.getLastError)(0xc20143df00), skip:0, limit:-1, selector:interface {}(nil), flags:0x0, replyFunc:(mgo.replyFunc)(0x53fc10), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.34423 Socket 0xc2010d9b60 to 127.0.0.1:50017: sending 2 op(s) (197 bytes) [LOG] 99.34432 Socket 0xc2010d9b60 to 127.0.0.1:50017: updated write deadline to 1m0s ahead (2014-03-06 17:53:00.472891861 +0000 UTC) [LOG] 99.34438 Socket 0xc2010d9b60 to 127.0.0.1:50017: updated read deadline to 1m0s ahead (2014-03-06 17:53:00.473016131 +0000 UTC) [LOG] 99.34572 Socket 0xc2010d9b60 to 127.0.0.1:50017: got reply (83 bytes) [LOG] 99.34585 Socket 0xc2010d9b60 to 127.0.0.1:50017: received document: bson.M{"n":0, "connectionId":84, "err":interface {}(nil), "ok":1} [LOG] 99.34591 Result from writing query: &mgo.LastError{Err:"", Code:0, N:0, Waited:0, FSyncFiles:0, WTimeout:false, UpdatedExisting:false, UpsertedId:interface {}(nil)} [LOG] 99.34593 Closing session 0xc2043842c0 [LOG] 99.34594 Cluster 0xc2010d98c0 released (refs=1) [LOG] 99.34601 Cluster 0xc2010d98c0 acquired (refs=2) [LOG] 99.34603 New session 0xc204384840 on cluster 0xc2010d98c0 (copy from 0xc200b359a0) [LOG] 99.34604 Session 0xc204384840: setting mode 2 with refresh=false (master=0xc2010d9b60, slave=0x0) [LOG] 99.34608 Socket 0xc2010d9b60 to 127.0.0.1:50017: serializing op: &mgo.insertOp{collection:"juju.system.indexes", documents:[]interface {}{(*mgo.indexSpec)(0xc2011ee480)}} [LOG] 99.34611 Socket 0xc2010d9b60 to 127.0.0.1:50017: serializing document for insertion: &mgo.indexSpec{Name:"urls_1_digest_1", NS:"juju.events", Key:bson.D{bson.DocElem{Name:"urls", Value:1}, bson.DocElem{Name:"digest", Value:1}}, Unique:false, DropDups:false, Background:false, Sparse:false, Bits:0, Min:0, Max:0, ExpireAfter:0} [LOG] 99.34617 Socket 0xc2010d9b60 to 127.0.0.1:50017: serializing op: &mgo.queryOp{collection:"juju.$cmd", query:(*mgo.getLastError)(0xc2043891e0), skip:0, limit:-1, selector:interface {}(nil), flags:0x0, replyFunc:(mgo.replyFunc)(0x53fc10), options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil)}, hasOptions:false, serverTags:[]bson.D(nil)} [LOG] 99.34629 Socket 0xc2010d9b60 to 127.0.0.1:50017: sending 2 op(s) (184 bytes) [LOG] 99.34632 Socket 0xc2010d9b60 to 127.0.0.1:50017: updated write deadline to 1m0s ahead (2014-03-06 17:53:00.474957839 +0000 UTC) [LOG] 99.34637 Socket 0xc2010d9b60 to 127.0.0.1:50017: updated read deadline to 1m0s ahead (2014-03-06 17:53:00.475007883 +0000 UTC) [LOG] 99.34765 Socket 0xc2010d9b60 to 127.0.0.1:50017: got reply (83 bytes) [LOG] 99.34772 Socket 0xc2010d9b60 to 127.0.0.1:50017: received document: bson.M{"n":0, "connectionId":84, "err":interface {}(nil), "ok":1} [LOG] 99.34778 Result from writing query: &mgo.LastError{Err:"", Code:0, N:0, Waited:0, FSyncFiles:0, WTimeout:false, UpdatedExisting:false, UpsertedId:interface {}(nil)} [LOG] 99.34779 Closing session 0xc204384840 [LOG] 99.34780 Cluster 0xc2010d98c0 released (refs=1) [LOG] 99.34806 Closing session 0xc200b359a0 [LOG] 99.34807 Cluster 0xc2010d98c0 released (refs=0) [LOG] 99.34808 Connections to 127.0.0.1:50017 closing (1 live sockets). [LOG] 99.34810 Socket 0xc2010d9b60 to 127.0.0.1:50017: closing: Closed explicitly (abend=false) [LOG] 99.34811 Closing session 0xc200b35580 [LOG] 99.34812 Cluster 0xc2010d9460 released (refs=0) [LOG] 99.34812 Connections to 127.0.0.1:50017 closing (1 live sockets). [LOG] 99.34813 Socket 0xc2010d9700 to 127.0.0.1:50017: closing: Closed explicitly (abend=false) [LOG] 99.34819 Socket 0xc2010d9b60 to 127.0.0.1:50017: killed again: read tcp 127.0.0.1:50017: use of closed network connection (previously: Closed explicitly) [LOG] 99.34830 Socket 0xc2010d9700 to 127.0.0.1:50017: killed again: read tcp 127.0.0.1:50017: use of closed network connection (previously: Closed explicitly) ... Panic: command failed: bzr init (PC=0x414071) /usr/lib/go/src/pkg/runtime/panic.c:229 in panic branch_test.go:185 in bzrDir.run branch_test.go:191 in bzrDir.init branch_test.go:31 in StoreSuite.dummyBranch branch_test.go:148 in StoreSuite.TestPublishErrorInCharm OOPS: 31 passed, 4 PANICKED --- FAIL: Test (11.62 seconds) FAIL FAIL launchpad.net/juju-core/store 11.822s ok launchpad.net/juju-core/testing 1.275s ok launchpad.net/juju-core/testing/checkers 0.020s ok launchpad.net/juju-core/testing/testbase 0.015s ok launchpad.net/juju-core/thirdparty/pbkdf2 0.116s ok launchpad.net/juju-core/tools 0.015s ok launchpad.net/juju-core/upgrades 6.230s ok launchpad.net/juju-core/upstart 1.044s ok launchpad.net/juju-core/utils 1.904s ok launchpad.net/juju-core/utils/exec 0.026s ok launchpad.net/juju-core/utils/fslock 0.857s ok launchpad.net/juju-core/utils/parallel 0.879s ok launchpad.net/juju-core/utils/set 0.019s ok launchpad.net/juju-core/utils/ssh 20.985s ? launchpad.net/juju-core/utils/ssh/testing [no test files] ok launchpad.net/juju-core/utils/tailer 0.931s ok launchpad.net/juju-core/utils/voyeur 0.013s ok launchpad.net/juju-core/utils/zip 0.091s ok launchpad.net/juju-core/version 0.087s ok launchpad.net/juju-core/worker 6.357s ok launchpad.net/juju-core/worker/authenticationworker 2.586s ok launchpad.net/juju-core/worker/charmrevisionworker 1.719s ok launchpad.net/juju-core/worker/cleaner 1.100s ok launchpad.net/juju-core/worker/deployer 3.006s ok launchpad.net/juju-core/worker/firewaller 9.967s ok launchpad.net/juju-core/worker/instancepoller 1.859s ok launchpad.net/juju-core/worker/localstorage 0.036s ok launchpad.net/juju-core/worker/logger 1.313s ok launchpad.net/juju-core/worker/machineenvironmentworker 7.079s ok launchpad.net/juju-core/worker/machiner 2.415s ok launchpad.net/juju-core/worker/minunitsworker 1.158s ok launchpad.net/juju-core/worker/peergrouper 0.988s ok launchpad.net/juju-core/worker/provisioner 36.786s ok launchpad.net/juju-core/worker/resumer 1.328s ok launchpad.net/juju-core/worker/rsyslog 3.325s ok launchpad.net/juju-core/worker/terminationworker 0.047s ok launchpad.net/juju-core/worker/uniter 132.789s ok launchpad.net/juju-core/worker/uniter/charm 2.247s ok launchpad.net/juju-core/worker/uniter/debug 0.067s ok launchpad.net/juju-core/worker/uniter/hook 0.016s ok launchpad.net/juju-core/worker/uniter/jujuc 0.412s ok launchpad.net/juju-core/worker/uniter/relation 1.348s ok launchpad.net/juju-core/worker/upgrader 2.880s warning: building out-of-date packages: 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.