juju-core

juju 1.20.x slow bootstrap

Bug #1338179 reported by Adam Stokes
12
This bug affects 2 people
Affects Status Importance Assigned to Milestone
juju-core
Fix Released
High
Andrew Wilkins
juju-core 1.21-alpha1
1.20
Fix Released
High
Andrew Wilkins
juju-core 1.20.1

Bug Description

Running :
juju 1.20.0.1

Problem:
juju bootstrap sits at "Bootstrapping juju agent" indefinitely.

environments.yaml:

default: local

environments:
  local:
    type: local
    container: lxc
    lxc-use-clone: true
    admin-secret: pass

Debug:
2014-07-06 02:01:29 INFO juju.cmd supercommand.go:37 running juju [1.20.0-trusty-amd64 gc]
2014-07-06 02:01:29 WARNING juju.environs config.go:106 Config attribute "lxc-use-clone" has been renamed to "lxc-clone".
Please update your environment configuration.
2014-07-06 02:01:29 DEBUG juju.environs.configstore disk.go:69 Making /home/adam/.juju/environments
2014-07-06 02:01:30 INFO juju.provider.local environprovider.go:153 checking state port
2014-07-06 02:01:30 INFO juju.provider.local environprovider.go:153 checking API port
2014-07-06 02:01:30 INFO juju.provider.local environprovider.go:42 opening environment "local"
2014-07-06 02:01:30 DEBUG juju.provider.local environ.go:297 found "10.0.3.1" as address for "lxcbr0"
2014-07-06 02:01:30 INFO juju.environs.bootstrap synctools.go:35 checking that upload is possible
2014-07-06 02:01:30 INFO juju.cmd cmd.go:113 uploading tools for series [precise trusty]
2014-07-06 02:01:30 DEBUG juju.environs.sync sync.go:277 Building tools
2014-07-06 02:01:30 DEBUG juju.environs.tools build.go:115 looking for: juju
2014-07-06 02:01:30 DEBUG juju.environs.tools build.go:156 checking: /usr/bin/jujud
2014-07-06 02:01:30 INFO juju.environs.tools build.go:162 found existing jujud
2014-07-06 02:01:30 INFO juju.environs.tools build.go:172 target: /tmp/juju-tools193716079/jujud
2014-07-06 02:01:30 DEBUG juju.environs.tools build.go:227 forcing version to 1.20.0.1
2014-07-06 02:01:30 DEBUG juju.environs.tools build.go:39 adding entry: &tar.Header{Name:"FORCE-VERSION", Mode:436, Uid:0, Gid:0, Size:8, ModTime:time.Time{sec:63540208890, nsec:0x23c87cc2, loc:(*time.Location)(0x19f25a0)}, Typeflag:0x30, Linkname:"", Uname:"ubuntu", Gname:"ubuntu", Devmajor:0, Devminor:0, AccessTime:time.Time{sec:63540208890, nsec:0x23c87cc2, loc:(*time.Location)(0x19f25a0)}, ChangeTime:time.Time{sec:63540208890, nsec:0x23c87cc2, loc:(*time.Location)(0x19f25a0)}, Xattrs:map[string]string(nil)}
2014-07-06 02:01:30 DEBUG juju.environs.tools build.go:39 adding entry: &tar.Header{Name:"jujud", Mode:493, Uid:0, Gid:0, Size:40044616, ModTime:time.Time{sec:63540208890, nsec:0x23c87cc2, loc:(*time.Location)(0x19f25a0)}, Typeflag:0x30, Linkname:"", Uname:"ubuntu", Gname:"ubuntu", Devmajor:0, Devminor:0, AccessTime:time.Time{sec:63540208890, nsec:0x23c87cc2, loc:(*time.Location)(0x19f25a0)}, ChangeTime:time.Time{sec:63540208890, nsec:0x23c87cc2, loc:(*time.Location)(0x19f25a0)}, Xattrs:map[string]string(nil)}
2014-07-06 02:01:34 INFO juju.environs.sync sync.go:296 built tools 1.20.0.1-trusty-amd64 (7830kB)
2014-07-06 02:01:34 DEBUG juju.environs.sync sync.go:201 Uploading tools for [precise trusty]
2014-07-06 02:01:34 DEBUG juju.environs.sync sync.go:231 generating tarballs for [precise trusty]
2014-07-06 02:01:34 DEBUG juju.environs.sync sync.go:251 generating tools metadata
2014-07-06 02:01:34 DEBUG juju.environs.tools tools.go:46 no architecture specified when finding tools, looking for any
2014-07-06 02:01:34 DEBUG juju.environs.tools tools.go:57 no series specified when finding tools, looking for any
2014-07-06 02:01:34 DEBUG juju.environs.simplestreams simplestreams.go:389 fetchData failed for "file:///tmp/juju-tools600554498/tools/streams/v1/index.sjson": stat /tmp/juju-tools600554498/tools/streams/v1/index.sjson: no such file or directory
2014-07-06 02:01:34 DEBUG juju.environs.simplestreams simplestreams.go:363 cannot load index "file:///tmp/juju-tools600554498/tools/streams/v1/index.sjson": invalid URL "file:///tmp/juju-tools600554498/tools/streams/v1/index.sjson" not found
2014-07-06 02:01:34 DEBUG juju.environs.simplestreams simplestreams.go:389 fetchData failed for "file:///tmp/juju-tools600554498/tools/streams/v1/index.json": stat /tmp/juju-tools600554498/tools/streams/v1/index.json: no such file or directory
2014-07-06 02:01:34 DEBUG juju.environs.simplestreams simplestreams.go:363 cannot load index "file:///tmp/juju-tools600554498/tools/streams/v1/index.json": invalid URL "file:///tmp/juju-tools600554498/tools/streams/v1/index.json" not found
2014-07-06 02:01:34 INFO juju.environs.tools simplestreams.go:379 Writing tools/streams/v1/index.json
2014-07-06 02:01:34 INFO juju.environs.tools simplestreams.go:379 Writing tools/streams/v1/com.ubuntu.juju:released:tools.json
2014-07-06 02:01:34 DEBUG juju.environs.sync sync.go:340 uploading tools to cloud storage
2014-07-06 02:01:34 INFO juju.environs.sync sync.go:142 using sync tools source: file:///tmp/juju-tools600554498/tools
2014-07-06 02:01:34 INFO juju.environs.sync sync.go:65 listing available tools
2014-07-06 02:01:34 DEBUG juju.environs.tools tools.go:46 no architecture specified when finding tools, looking for any
2014-07-06 02:01:34 DEBUG juju.environs.tools tools.go:57 no series specified when finding tools, looking for any
2014-07-06 02:01:34 INFO juju.utils http.go:59 hostname SSL verification enabled
2014-07-06 02:01:34 DEBUG juju.environs.simplestreams simplestreams.go:389 fetchData failed for "file:///tmp/juju-tools600554498/tools/streams/v1/index.sjson": cannot find URL "file:///tmp/juju-tools600554498/tools/streams/v1/index.sjson" not found
2014-07-06 02:01:34 DEBUG juju.environs.simplestreams simplestreams.go:363 cannot load index "file:///tmp/juju-tools600554498/tools/streams/v1/index.sjson": invalid URL "file:///tmp/juju-tools600554498/tools/streams/v1/index.sjson" not found
2014-07-06 02:01:34 INFO juju.utils http.go:59 hostname SSL verification enabled
2014-07-06 02:01:34 INFO juju.utils http.go:59 hostname SSL verification enabled
2014-07-06 02:01:34 DEBUG juju.environs.simplestreams simplestreams.go:389 fetchData failed for "file:///tmp/juju-tools600554498/tools/streams/v1/mirrors.json": cannot find URL "file:///tmp/juju-tools600554498/tools/streams/v1/mirrors.json" not found
2014-07-06 02:01:34 DEBUG juju.environs.simplestreams simplestreams.go:466 no mirror index file found
2014-07-06 02:01:34 DEBUG juju.environs.simplestreams simplestreams.go:447 no mirror information available for { }: mirror data for "com.ubuntu.juju:released:tools" not found
2014-07-06 02:01:34 DEBUG juju.environs.simplestreams simplestreams.go:367 read metadata index at "file:///tmp/juju-tools600554498/tools/streams/v1/index.json"
2014-07-06 02:01:34 DEBUG juju.environs.simplestreams simplestreams.go:534 candidate matches for products ["com.ubuntu.juju:12.04:amd64" "com.ubuntu.juju:12.04:i386" "com.ubuntu.juju:12.04:armhf" "com.ubuntu.juju:12.04:arm64" "com.ubuntu.juju:12.04:ppc64" "com.ubuntu.juju:12.10:amd64" "com.ubuntu.juju:12.10:i386" "com.ubuntu.juju:12.10:armhf" "com.ubuntu.juju:12.10:arm64" "com.ubuntu.juju:12.10:ppc64" "com.ubuntu.juju:13.04:amd64" "com.ubuntu.juju:13.04:i386" "com.ubuntu.juju:13.04:armhf" "com.ubuntu.juju:13.04:arm64" "com.ubuntu.juju:13.04:ppc64" "com.ubuntu.juju:13.10:amd64" "com.ubuntu.juju:13.10:i386" "com.ubuntu.juju:13.10:armhf" "com.ubuntu.juju:13.10:arm64" "com.ubuntu.juju:13.10:ppc64" "com.ubuntu.juju:14.04:amd64" "com.ubuntu.juju:14.04:i386" "com.ubuntu.juju:14.04:armhf" "com.ubuntu.juju:14.04:arm64" "com.ubuntu.juju:14.04:ppc64" "com.ubuntu.juju:14.10:amd64" "com.ubuntu.juju:14.10:i386" "com.ubuntu.juju:14.10:armhf" "com.ubuntu.juju:14.10:arm64" "com.ubuntu.juju:14.10:ppc64"] are [{Sat, 05 Jul 2014 22:01:34 -0400 products:1.0 content-download [] streams/v1/com.ubuntu.juju:released:tools.json [com.ubuntu.juju:12.04:amd64 com.ubuntu.juju:14.04:amd64]}]
2014-07-06 02:01:34 DEBUG juju.environs.simplestreams simplestreams.go:847 finding products at path "streams/v1/com.ubuntu.juju:released:tools.json"
2014-07-06 02:01:34 INFO juju.utils http.go:59 hostname SSL verification enabled
2014-07-06 02:01:34 DEBUG juju.environs.simplestreams simplestreams.go:885 metadata: &{map[com.ubuntu.juju:12.04:amd64:{ 1.20.0.1 amd64 map[20140705:0xc21014b900]} com.ubuntu.juju:14.04:amd64:{ 1.20.0.1 amd64 map[20140705:0xc21014ba20]}] map[] Sat, 05 Jul 2014 22:01:34 -0400 products:1.0 com.ubuntu.juju:released:tools }
2014-07-06 02:01:34 INFO juju.environs.sync sync.go:86 found 2 tools
2014-07-06 02:01:34 DEBUG juju.environs.sync sync.go:93 found source tool: &{1.20.0.1-precise-amd64 file:///tmp/juju-tools600554498/tools/releases/juju-1.20.0.1-precise-amd64.tgz 261a3489ee8c03cd2ef91555d819b73648c6d14136b0bfcd121c62cfd61dcfb9 8018415}
2014-07-06 02:01:34 DEBUG juju.environs.sync sync.go:93 found source tool: &{1.20.0.1-trusty-amd64 file:///tmp/juju-tools600554498/tools/releases/juju-1.20.0.1-trusty-amd64.tgz 261a3489ee8c03cd2ef91555d819b73648c6d14136b0bfcd121c62cfd61dcfb9 8018415}
2014-07-06 02:01:34 INFO juju.environs.sync sync.go:96 listing target tools storage
2014-07-06 02:01:34 DEBUG juju.environs.tools storage.go:35 reading v1.* tools
2014-07-06 02:01:34 INFO juju.environs.sync sync.go:109 found 0 tools in target; 2 tools to be copied
2014-07-06 02:01:34 INFO juju.environs.sync sync.go:149 copying 1.20.0.1-precise-amd64 from file:///tmp/juju-tools600554498/tools/releases/juju-1.20.0.1-precise-amd64.tgz
2014-07-06 02:01:34 INFO juju.environs.sync sync.go:163 copying tools/releases/juju-1.20.0.1-precise-amd64.tgz
2014-07-06 02:01:34 INFO juju.utils http.go:59 hostname SSL verification enabled
2014-07-06 02:01:34 INFO juju.environs.sync sync.go:176 downloaded tools/releases/juju-1.20.0.1-precise-amd64.tgz (7830kB), uploading
2014-07-06 02:01:34 INFO juju.environs.sync sync.go:177 download 7830kB, uploading
2014-07-06 02:01:34 INFO juju.environs.sync sync.go:149 copying 1.20.0.1-trusty-amd64 from file:///tmp/juju-tools600554498/tools/releases/juju-1.20.0.1-trusty-amd64.tgz
2014-07-06 02:01:34 INFO juju.environs.sync sync.go:163 copying tools/releases/juju-1.20.0.1-trusty-amd64.tgz
2014-07-06 02:01:34 INFO juju.utils http.go:59 hostname SSL verification enabled
2014-07-06 02:01:34 INFO juju.environs.sync sync.go:176 downloaded tools/releases/juju-1.20.0.1-trusty-amd64.tgz (7830kB), uploading
2014-07-06 02:01:34 INFO juju.environs.sync sync.go:177 download 7830kB, uploading
2014-07-06 02:01:34 INFO juju.environs.sync sync.go:114 copied 2 tools
2014-07-06 02:01:34 INFO juju.environs.sync sync.go:116 generating tools metadata
2014-07-06 02:01:34 DEBUG juju.environs.tools tools.go:46 no architecture specified when finding tools, looking for any
2014-07-06 02:01:34 DEBUG juju.environs.tools tools.go:57 no series specified when finding tools, looking for any
2014-07-06 02:01:34 DEBUG juju.environs.simplestreams simplestreams.go:389 fetchData failed for "file:///home/adam/.juju/local/storage/tools/streams/v1/index.sjson": stat /home/adam/.juju/local/storage/tools/streams/v1/index.sjson: no such file or directory
2014-07-06 02:01:34 DEBUG juju.environs.simplestreams simplestreams.go:363 cannot load index "file:///home/adam/.juju/local/storage/tools/streams/v1/index.sjson": invalid URL "file:///home/adam/.juju/local/storage/tools/streams/v1/index.sjson" not found
2014-07-06 02:01:34 DEBUG juju.environs.simplestreams simplestreams.go:389 fetchData failed for "file:///home/adam/.juju/local/storage/tools/streams/v1/index.json": stat /home/adam/.juju/local/storage/tools/streams/v1/index.json: no such file or directory
2014-07-06 02:01:34 DEBUG juju.environs.simplestreams simplestreams.go:363 cannot load index "file:///home/adam/.juju/local/storage/tools/streams/v1/index.json": invalid URL "file:///home/adam/.juju/local/storage/tools/streams/v1/index.json" not found
2014-07-06 02:01:34 INFO juju.environs.tools simplestreams.go:379 Writing tools/streams/v1/index.json
2014-07-06 02:01:34 INFO juju.environs.tools simplestreams.go:379 Writing tools/streams/v1/com.ubuntu.juju:released:tools.json
2014-07-06 02:01:34 INFO juju.environs.sync sync.go:128 tools metadata written
2014-07-06 02:01:35 DEBUG juju.provider.local environ.go:297 found "10.0.3.1" as address for "lxcbr0"
2014-07-06 02:01:35 DEBUG juju.environs.bootstrap bootstrap.go:45 environment "local" supports service/machine networks: false
2014-07-06 02:01:35 INFO juju.environs.bootstrap bootstrap.go:46 bootstrapping environment "local"
2014-07-06 02:01:35 DEBUG juju.provider.common bootstrap.go:94 generate a system ssh key
2014-07-06 02:01:36 DEBUG juju.provider.local environ.go:297 found "10.0.3.1" as address for "lxcbr0"
2014-07-06 02:01:36 DEBUG juju.environs.bootstrap state.go:36 putting "provider-state" to bootstrap storage *filestorage.fileStorageWriter
2014-07-06 02:01:36 DEBUG juju.environs.bootstrap synctools.go:167 looking for bootstrap tools: series="trusty", arch=0xc21037ce00, version=1.20.0.1
2014-07-06 02:01:36 INFO juju.environs.tools tools.go:87 reading tools with major.minor version 1.20
2014-07-06 02:01:36 INFO juju.environs.tools tools.go:95 filtering tools by version: 1.20.0.1
2014-07-06 02:01:36 INFO juju.environs.tools tools.go:98 filtering tools by series: trusty
2014-07-06 02:01:36 INFO juju.environs.tools tools.go:101 filtering tools by architecture: amd64
2014-07-06 02:01:36 DEBUG juju.environs.simplestreams simplestreams.go:389 fetchData failed for "file:///home/adam/.juju/local/storage/tools/streams/v1/index.sjson": stat /home/adam/.juju/local/storage/tools/streams/v1/index.sjson: no such file or directory
2014-07-06 02:01:36 DEBUG juju.environs.simplestreams simplestreams.go:363 cannot load index "file:///home/adam/.juju/local/storage/tools/streams/v1/index.sjson": invalid URL "file:///home/adam/.juju/local/storage/tools/streams/v1/index.sjson" not found
2014-07-06 02:01:36 DEBUG juju.environs.simplestreams simplestreams.go:389 fetchData failed for "file:///home/adam/.juju/local/storage/tools/streams/v1/mirrors.json": stat /home/adam/.juju/local/storage/tools/streams/v1/mirrors.json: no such file or directory
2014-07-06 02:01:36 DEBUG juju.environs.simplestreams simplestreams.go:466 no mirror index file found
2014-07-06 02:01:36 DEBUG juju.environs.simplestreams simplestreams.go:447 no mirror information available for { }: mirror data for "com.ubuntu.juju:released:tools" not found
2014-07-06 02:01:36 DEBUG juju.environs.simplestreams simplestreams.go:367 read metadata index at "file:///home/adam/.juju/local/storage/tools/streams/v1/index.json"
2014-07-06 02:01:36 DEBUG juju.environs.simplestreams simplestreams.go:534 candidate matches for products ["com.ubuntu.juju:14.04:amd64"] are [{Sat, 05 Jul 2014 22:01:34 -0400 products:1.0 content-download [] streams/v1/com.ubuntu.juju:released:tools.json [com.ubuntu.juju:12.04:amd64 com.ubuntu.juju:14.04:amd64]}]
2014-07-06 02:01:36 DEBUG juju.environs.simplestreams simplestreams.go:847 finding products at path "streams/v1/com.ubuntu.juju:released:tools.json"
2014-07-06 02:01:36 DEBUG juju.environs.simplestreams simplestreams.go:885 metadata: &{map[com.ubuntu.juju:12.04:amd64:{ 1.20.0.1 amd64 map[20140705:0xc21012cde0]} com.ubuntu.juju:14.04:amd64:{ 1.20.0.1 amd64 map[20140705:0xc21012cf60]}] map[] Sat, 05 Jul 2014 22:01:34 -0400 products:1.0 com.ubuntu.juju:released:tools }
2014-07-06 02:01:36 INFO juju.environs.bootstrap bootstrap.go:58 newest version: 1.20.0.1
2014-07-06 02:01:36 INFO juju.environs.bootstrap bootstrap.go:86 picked bootstrap tools version: 1.20.0.1
Logging to /home/adam/.juju/local/cloud-init-output.log on remote host
Bootstrapping Juju machine agent

Adam Stokes (adam-stokes)
tags: added: cloud-installer local-provider
Revision history for this message
Curtis Hovey (sinzui) wrote :

1.20 bootstraps are much slower than 1.18 because mongo is setup for replication. I the develops need more information to identify the cause the the hang. Can you tail /home/adam/.juju/local/cloud-init-output.log when you see "Bootstrapping Juju machine agent" to identify what is happening?

Changed in juju-core:
status: New → Incomplete
milestone: none → 1.21-alpha1
tags: added: bootstrap
Revision history for this message
Adam Stokes (adam-stokes) wrote :
Download full text (6.0 KiB)

So it took about 4 minutes to bootstrap a local environment:

3f2a6a7c173388f08bc243a3a5538fe51f74bc4bea1f6c602d3a63bb59877017 /home/adam/.juju/local/tools/1.20.0.1-trusty-amd64/tools.tar.gz
2014-07-08 14:01:43 INFO juju.cmd supercommand.go:37 running jujud [1.20.0.1-trusty-amd64 gc]
2014-07-08 14:01:43 DEBUG juju.agent agent.go:376 read agent config, format "1.18"
2014-07-08 14:01:43 INFO juju.provider.local environprovider.go:42 opening environment "local"
2014-07-08 14:01:43 DEBUG juju.cmd.jujud bootstrap.go:163 starting mongo
2014-07-08 14:01:43 DEBUG juju.cmd.jujud bootstrap.go:188 calling ensureMongoServer
2014-07-08 14:01:43 INFO juju.mongo mongo.go:147 Ensuring mongo server is running; data directory /home/adam/.juju/local; port 37017
2014-07-08 14:01:43 INFO juju.mongo mongo.go:287 installing juju-mongodb
2014-07-08 14:01:43 INFO juju.utils.apt apt.go:128 Running: [apt-get --option=Dpkg::Options::=--force-confold --option=Dpkg::options::=--force-unsafe-io --assume-yes --quiet install juju-mongodb]
2014-07-08 14:01:45 DEBUG juju.mongo mongo.go:231 using mongod: /usr/lib/juju/bin/mongod --version: "db version v2.4.9\nTue Jul 8 10:01:45.089 git version: nogitversion\n"
2014-07-08 14:04:14 DEBUG juju.worker.peergrouper initiate.go:41 Initiating mongo replicaset; dialInfo &mgo.DialInfo{Addrs:[]string{"127.0.0.1:37017"}, Direct:false, Timeout:300000000000, FailFast:false, Database:"", Source:"", Service:"", Mechanism:"", Username:"", Password:"", DialServer:(func(*mgo.ServerAddr) (net.Conn, error))(nil), Dial:(func(net.Addr) (net.Conn, error))(0x5af220)}; memberHostport "10.0.3.1:37017"; user ""; password ""
2014-07-08 14:04:17 DEBUG juju.mongo open.go:87 connection failed, will retry: dial tcp 127.0.0.1:37017: connection refused
2014-07-08 14:04:17 DEBUG juju.mongo open.go:87 connection failed, will retry: dial tcp 127.0.0.1:37017: connection refused
2014-07-08 14:04:18 DEBUG juju.mongo open.go:87 connection failed, will retry: dial tcp 127.0.0.1:37017: connection refused
2014-07-08 14:04:18 DEBUG juju.mongo open.go:87 connection failed, will retry: dial tcp 127.0.0.1:37017: connection refused
2014-07-08 14:04:19 INFO juju.mongo open.go:95 dialled mongo successfully
2014-07-08 14:04:19 INFO juju.replicaset replicaset.go:57 Initiating replicaset with config replicaset.Config{Name:"juju", Version:1, Members:[]replicaset.Member{replicaset.Member{Id:1, Address:"10.0.3.1:37017", Arbiter:(*bool)(nil), BuildIndexes:(*bool)(nil), Hidden:(*bool)(nil), Priority:(*float64)(nil), Tags:map[string]string{"juju-machine-id":"0"}, SlaveDelay:(*time.Duration)(nil), Votes:(*int)(nil)}}}
2014-07-08 14:04:24 INFO juju.mongo open.go:95 dialled mongo successfully
2014-07-08 14:04:27 INFO juju.worker.peergrouper initiate.go:84 replica set initiated
2014-07-08 14:04:27 INFO juju.worker.peergrouper initiate.go:94 finished MaybeInitiateMongoServer
2014-07-08 14:04:27 INFO juju.cmd.jujud bootstrap.go:129 started mongo
2014-07-08 14:04:27 DEBUG juju.agent bootstrap.go:82 initializing address [127.0.0.1:37017]
2014-07-08 14:04:27 INFO juju.state open.go:48 opening state, mongo addresses: ["127.0.0.1:37017"]; entity ""
2014-07-08 14:04:27 DEBUG juju.state open.go:53 ...

Read more...

Changed in juju-core:
status: Incomplete → New
Revision history for this message
Curtis Hovey (sinzui) wrote :

If we cannot make bootstrap genuinely fast and synchronous as 1.18 had intended, then status needs to tell the truth, that bootstrap is still going on.

summary: - juju 1.20.x hangs at bootstrap
+ juju 1.20.x slow bootstrap
Changed in juju-core:
status: New → Triaged
importance: Undecided → High
tags: added: status
Revision history for this message
Nate Finch (natefinch) wrote :

I dont think this has anything to do with replicasets. This seems to be the key lines in the log:

2014-07-08 14:01:45 DEBUG juju.mongo mongo.go:231 using mongod: /usr/lib/juju/bin/mongod --version: "db version v2.4.9\nTue Jul 8 10:01:45.089 git version: nogitversion\n"
2014-07-08 14:04:14 DEBUG juju.worker.peergrouper initiate.go:41 Initiating mongo replicaset; dialInfo &mgo.DialInfo{Addrs:[]string{"127.0.0.1:37017"}, Direct:false, Timeout:300000000000, FailFast:false, Database:"", Source:"", Service:"", Mechanism:"", Username:"", Password:"", DialServer:(func(*mgo.ServerAddr) (net.Conn, error))(nil), Dial:(func(net.Addr) (net.Conn, error))(0x5af220)}; memberHostport "10.0.3.1:37017"; user ""; password ""

There's 2.5 minutes there before we even start the replicaset initiation stuff. I'm not sure exactly what's going on, and it's not impossible that it's mongo being slow, but I don't think it's a sure thing. A lot has changed in 1.20, so it bears more investigation.

Revision history for this message
Ian Booth (wallyworld) wrote :

Replicaset is enabled for local provider so that people can test and play with HA cheaply in a non-cloud environment. We believe the cause of the issue is the creation of the operational log which is required by replication. The time taken is dependent on the size and speed of the hard disk. We will change the default behaviour of local provider to make this file really small which should speed up the startup time. The files are created in /var/lib/juju/db as local.*. If these are there, they will not be overwritten. So to test the fix (when done), delete the files and try again.

Andrew Wilkins (axwalk)
Changed in juju-core:
status: Triaged → In Progress
assignee: nobody → Andrew Wilkins (axwalk)
Revision history for this message
Andrew Wilkins (axwalk) wrote :

I've got a potential fix at https://github.com/juju/juju/pull/270

Ian Booth (wallyworld)
Changed in juju-core:
status: In Progress → Fix Committed
Revision history for this message
Andrew Wilkins (axwalk) wrote :

I cannot reproduce such a slow bootstrap on my machine, however I am aware that bootstrap can take a long time if the disk is large and slow due to how Mongo allocates its op log (5% of available disk space, with a minimum of 1G and maximum of 50G). I've committed a change to trunk that limits the size of the op log to 1MB for the local provider, since it is of no value when there is only a single mongo instance.

Marking fix committed. Please reopen if the change does not resolve the issue for you.

Revision history for this message
John A Meinel (jameinel) wrote :

So the oplog isn't useless. It is also used for backup and restore.
We keep treating the local provider as "throwaway" but we have evidence that it isn't being used that way, and I think we need to be careful with changes like this.
I don't know how much fits in 1MB, but it does seem a bit small.

From the manual:
    For 64-bit Linux, Solaris, FreeBSD, and Windows systems, MongoDB allocates 5% of the available free disk space, but will always allocate at least 1 gigabyte and never more than 50 gigabytes.
    For 64-bit OS X systems, MongoDB allocates 183 megabytes of space to the oplog.
    For 32-bit systems, MongoDB allocates about 48 megabytes of space to the oplog.

I think we'd prefer at least 10MB, though it certainly depends on how much churn between synchronization you ese.

Revision history for this message
Andrew Wilkins (axwalk) wrote :

So, what I wrote wasn't entirely accurate. We tell mongo to allocate an oplog of 1MB, and yet it goes and allocates an additional 32MB anyway.

Either way I don't think it's at all important for the local provider right now. We can tweak it if it becomes important, but the immediate goal is to fix the regression.

Revision history for this message
Adam Stokes (adam-stokes) wrote :
Download full text (10.0 KiB)

Latest output from 1.20.1

tail -f ~/.juju/local/cloud-init-output.log
d4375180dcfa8bb57c6f2d81399bb4dcc473310d1b5deb73c4d2ec10673aaaf2 /home/adam/.juju/local/tools/1.20.1.1-trusty-amd64/tools.tar.gz
2014-07-10 15:39:43 INFO juju.cmd supercommand.go:37 running jujud [1.20.1.1-trusty-amd64 gc]
2014-07-10 15:39:43 DEBUG juju.agent agent.go:377 read agent config, format "1.18"
2014-07-10 15:39:43 INFO juju.provider.local environprovider.go:42 opening environment "local"
2014-07-10 15:39:43 DEBUG juju.container.kvm kvm.go:51 kvm-ok output:
INFO: /dev/kvm exists
KVM acceleration can be used

2014-07-10 15:39:43 DEBUG juju.cmd.jujud bootstrap.go:191 starting mongo
2014-07-10 15:39:43 DEBUG juju.cmd.jujud bootstrap.go:216 calling ensureMongoServer
2014-07-10 15:39:43 INFO juju.mongo mongo.go:169 Ensuring mongo server is running; data directory /home/adam/.juju/local; port 37017
2014-07-10 15:39:43 INFO juju.mongo mongo.go:317 installing juju-mongodb
2014-07-10 15:39:43 INFO juju.utils.apt apt.go:128 Running: [apt-get --option=Dpkg::Options::=--force-confold --option=Dpkg::options::=--force-unsafe-io --assume-yes --quiet install juju-mongodb]
2014-07-10 15:39:44 DEBUG juju.mongo mongo.go:260 using mongod: /usr/lib/juju/bin/mongod --version: "db version v2.4.9\nThu Jul 10 11:39:44.438 git version: nogitversion\n"
2014-07-10 15:39:44 DEBUG juju.worker.peergrouper initiate.go:41 Initiating mongo replicaset; dialInfo &mgo.DialInfo{Addrs:[]string{"127.0.0.1:37017"}, Direct:false, Timeout:300000000000, FailFast:false, Database:"", Source:"", Service:"", Mechanism:"", Username:"", Password:"", DialServer:(func(*mgo.ServerAddr) (net.Conn, error))(nil), Dial:(func(net.Addr) (net.Conn, error))(0x5bbd70)}; memberHostport "10.0.3.1:37017"; user ""; password ""
2014-07-10 15:39:44 DEBUG juju.mongo open.go:87 connection failed, will retry: dial tcp 127.0.0.1:37017: connection refused
2014-07-10 15:39:44 DEBUG juju.mongo open.go:87 connection failed, will retry: dial tcp 127.0.0.1:37017: connection refused
2014-07-10 15:39:44 INFO juju.mongo open.go:95 dialled mongo successfully
2014-07-10 15:39:44 INFO juju.replicaset replicaset.go:67 Initiating replicaset with config replicaset.Config{Name:"juju", Version:1, Members:[]replicaset.Member{replicaset.Member{Id:1, Address:"10.0.3.1:37017", Arbiter:(*bool)(nil), BuildIndexes:(*bool)(nil), Hidden:(*bool)(nil), Priority:(*float64)(nil), Tags:map[string]string{"juju-machine-id":"0"}, SlaveDelay:(*time.Duration)(nil), Votes:(*int)(nil)}}}
2014-07-10 15:39:45 WARNING juju.replicaset replicaset.go:86 Initiate: fetching replication status failed: cannot get replica set status: Received replSetInitiate - should come online shortly.
2014-07-10 15:39:45 WARNING juju.replicaset replicaset.go:86 Initiate: fetching replication status failed: cannot get replica set status: Received replSetInitiate - should come online shortly.
2014-07-10 15:39:46 WARNING juju.replicaset replicaset.go:86 Initiate: fetching replication status failed: cannot get replica set status: Received replSetInitiate - should come online shortly.
2014-07-10 15:39:46 WARNING juju.replicaset replicaset.go:86 Initiate: fetching replication status failed: cannot get...

Revision history for this message
Andrew Wilkins (axwalk) wrote :

Sweet. Thanks for verifying, Adam.

Curtis Hovey (sinzui)
Changed in juju-core:
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

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