juju bootstrap failed - cannot dial mongo to initiate replicaset: no reachable servers

I just ran into this myself, although looking at the logs you've submitted the symptoms are different.

I notice you're using 1.23. If at all possible please use a 1.24 release instead. There are some serious problems with the 1.23 release. Also, replicaset initialisation was greatly improved for 1.24.

Menno, this was recreated with 1.24.2:

Attempt 1 to download tools from https://streams.canonical.com/juju/tools/releases/juju-1.24.2-trusty-amd64.tgz...
tools from https://streams.canonical.com/juju/tools/releases/juju-1.24.2-trusty-amd64.tgz downloaded: HTTP 200; time 2.183s; size 16630409 bytes; speed 7617205.000 bytes/s Tools downloaded successfully.
94d3a1f785acfd6e259d0f1dd2d08f5549732299ed1336ee0fb71598740795ae /var/lib/juju/tools/1.24.2-trusty-amd64/tools.tar.gz
2015-07-23 18:45:12 INFO juju.cmd supercommand.go:37 running jujud [1.24.2-trusty-amd64 gc]
2015-07-23 18:45:12 INFO juju.network network.go:194 setting prefer-ipv6 to false
2015-07-23 18:45:14 INFO juju.agent identity.go:22 writing system identity file
2015-07-23 18:45:14 INFO juju.mongo mongo.go:173 Ensuring mongo server is running; data directory /var/lib/juju; port 37017
2015-07-23 18:45:14 INFO juju.mongo mongo.go:348 installing juju-mongodb
2015-07-23 18:45:14 INFO juju.utils.packaging.manager utils.go:57 Running: apt-get --option=Dpkg::Options::=--force-confold --option=Dpkg::options::=--force-unsafe-io --assume-yes --quiet install juju-mongodb
2015-07-23 18:45:28 INFO juju.mongo open.go:125 dialled mongo successfully on address "127.0.0.1:37017"
2015-07-23 18:45:28 INFO juju.replicaset replicaset.go:78 Initiating replicaset with config replicaset.Config{Name:"juju", Version:1, Members:[]replicaset.Member{replicaset.Member{Id:1, Address:"hayward-53.oil: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)}}}
2015-07-23 18:45:33 INFO juju.mongo open.go:125 dialled mongo successfully on address "127.0.0.1:37017"
2015-07-23 18:45:48 INFO juju.mongo open.go:125 dialled mongo successfully on address "127.0.0.1:37017"
2015-07-23 18:45:49 INFO juju.mongo open.go:125 dialled mongo successfully on address "127.0.0.1:37017"
2015-07-23 18:45:53 INFO juju.mongo open.go:125 dialled mongo successfully on address "127.0.0.1:37017"
2015-07-23 18:45:56 INFO juju.mongo open.go:125 dialled mongo successfully on address "127.0.0.1:37017"
2015-07-23 18:46:05 INFO juju.mongo open.go:125 dialled mongo successfully on address "127.0.0.1:37017"
2015-07-23 18:46:10 WARNING juju.replicaset replicaset.go:98 Initiate: fetching replication status failed: cannot get replica set status: Closed explicitly
2015-07-23 18:46:11 INFO juju.mongo open.go:125 dialled mongo successfully on address "127.0.0.1:37017"
2015-07-23 18:46:14 INFO juju.worker.peergrouper initiate.go:70 replica set initiated
2015-07-23 18:46:14 INFO juju.worker.peergrouper initiate.go:78 finished MaybeInitiateMongoServer
2015-07-23 18:46:14 INFO juju.cmd.jujud bootstrap.go:187 started mongo
2015-07-23 18:46:14 INFO juju.mongo open.go:125 dialled mongo successfully on address "127.0.0.1:37017"
2015-07-23 18:46:17 INFO juju.state open.go:47 opening state, mongo addresses: ["127.0.0.1:37017"]; entity <nil>
2015-07-23 18:46:17 INFO juju.mongo open.go:125 dialled mongo successfully on address "127.0.0.1:37017"
2015-07-23 18:46:17 INFO juju.mongo open.go:125 dialled mongo successfully on addre...

@lmic: can you explain how the above output was obtained? It looks like a mix of "juju bootstrap --debug" output mixed in with cloud-init output and machine agent logs.

It's also curious that there's logs for jujud starting up twice. The first time Juju is able to connect to mongo fine, the second time it can't which is why MaybeInitiateMongoServer failed. Do you know why there's 2 jujud startups in this output?

Is the problem occurring consistently for you? If not, how many time have you seen it?

My best guess so far is that Juju is choosing the wrong address to connect to mongod with during bootstrap. I'm going to add some logging to 1.24 and 1.25 to help diagnose this. I can provide a pre-release build with this if you'd like to try it out before the releases are out.

After looking at this some more I found that Juju does already log address of the mongod when checking and initialising the replicaset but those logs are at DEBUG and the end of the output you provided appears to be INFO after the second "starting jujud" where the failure occurs. It would be very useful to have the DEBUG level output here if possible.

It would also be useful to have the contents of /var/log/syslog when the failure occurs so I can see what mongod is reporting.

I have not used linux much. But I am stuck at the same error mentioned in this thread. My juju version is -

1.24.3-vivid-amd64

And below is the output that I am getting when I do "juju bootstrap". How do I go about debugging this issue. I have seen the troubleshooting videos for juju and also the documentation but I am not finding a solution to the error below -

vagrant@vagrant-ubuntu-vivid-64:~$ juju bootstrap

Bootstrapping environment "local"
Starting new instance for initial state server
Building tools to upload (1.24.3.1-vivid-amd64)

Bootstrapping environment "local"
Starting new instance for initial state server
Building tools to upload (1.24.3.1-vivid-amd64)

Installing Juju agent on bootstrap instance
Logging to /home/vagrant/.juju/local/cloud-init-output.log on remote host
Installing package: curl
Installing package: cpu-checker
Installing package: bridge-utils
Installing package: rsyslog-gnutls
Installing package: cloud-utils
Installing package: cloud-image-utils
Installing package: tmux
Bootstrapping Juju machine agent
Reading package lists...
Building dependency tree...
Reading state information...
curl is already the newest version.
0 upgraded, 0 newly installed, 0 to remove and 24 not upgraded.
Reading package lists...
Building dependency tree...
Reading state information...
cpu-checker is already the newest version.
cpu-checker set to manually installed.
0 upgraded, 0 newly installed, 0 to remove and 24 not upgraded.
Reading package lists...
Building dependency tree...
Reading state information...
bridge-utils is already the newest version.
bridge-utils set to manually installed.
0 upgraded, 0 newly installed, 0 to remove and 24 not upgraded.
Reading package lists...
Building dependency tree...
Reading state information...
rsyslog-gnutls is already the newest version.
rsyslog-gnutls set to manually installed.
0 upgraded, 0 newly installed, 0 to remove and 24 not upgraded.
Reading package lists...
Building dependency tree...
Reading state information...
The following NEW packages will be installed:
  cloud-utils
0 upgraded, 1 newly installed, 0 to remove and 24 not upgraded.
Need to get 1,568 B of archives.
After this operation, 31.7 kB of additional disk space will be used.
Get:1 http://archive.ubuntu.com/ubuntu/ vivid/main cloud-utils all 0.27-0ubuntu15 [1,568 B]
Fetched 1,568 B in 5s (296 B/s)
Selecting previously unselected package cloud-utils.
(Reading database ... 66876 files and directories currently installed.)
Preparing to unpack .../cloud-utils_0.27-0ubuntu15_all.deb ...
Unpacking cloud-utils (0.27-0ubuntu15) ...
Setting up cloud-utils (0.27-0ubuntu15) ...
Reading package lists...
Building dependency tree...
Reading state information...
cloud-image-utils is already the newest version.
cloud-image-utils set to manually installed.
0 upgraded, 0 newly installed, 0 to remove and 24 not upgraded.
Reading package lists...
Building dependency tree...
Reading state information...
tmux is already the newest version.
0 upgraded, 0 newly installed, 0 to remove and 24 not upgraded.
945f7daba6d7d7f7d441d6536d513a61b6ccaf92d858bbc86a0038c9b97bd01d /home/vagrant/.juju/local/tools/1.24.3.1-vivid-amd64/tools.tar.gz
2015-07-29 21:...

@sirisha: sorry that you're experiencing this problem. I'm unable to reproduce the issue but a few others have seen it too.

Does it happen consistently for you?

Can you please run "juju bootstrap --debug"? That *should* give me the information I need to figure out what's going wrong.

I am affected by this issue as well. The below lines are the tail end of "juju bootstrap --debug" while the full the detail is attached.

2015-08-06 21:29:18 DEBUG juju.mongo open.go:117 connection failed, will retry: dial tcp 127.0.0.1:37017: connection refused
2015-08-06 21:29:18 DEBUG juju.mongo open.go:117 connection failed, will retry: dial tcp 127.0.0.1:37017: connection refused
2015-08-06 21:29:19 INFO juju.worker.peergrouper initiate.go:77 finished MaybeInitiateMongoServer
2015-08-06 21:29:19 ERROR juju.cmd supercommand.go:430 cannot initiate replica set: cannot dial mongo to initiate replicaset: no reachable servers
2015-08-06 21:29:19 ERROR juju.cmd supercommand.go:430 failed to bootstrap environment: exit status 1

The problem seems to be that systemd is not able to start mongod

I just hit this on 1.24.3 on trusty:

Attempt 1 to download tools from https://streams.canonical.com/juju/tools/releases/juju-1.24.3-trusty-amd64.tgz...
tools from https://streams.canonical.com/juju/tools/releases/juju-1.24.3-trusty-amd64.tgz downloaded: HTTP 200; time 3.569s; size 16686360 bytes; speed 4675045.000 bytes/s Tools downloaded successfully.
a07f31a56a32224207b2d64de13c49101eaf3e5131b4f0b78fba1ef43aeda8d1 /var/lib/juju/tools/1.24.3-trusty-amd64/tools.tar.gz
2015-08-07 07:53:02 INFO juju.cmd supercommand.go:37 running jujud [1.24.3-trusty-amd64 gc]
2015-08-07 07:53:02 INFO juju.network network.go:194 setting prefer-ipv6 to false
2015-08-07 07:53:02 INFO juju.provider.openstack provider.go:243 opening environment "devel3"
2015-08-07 07:53:03 INFO juju.agent identity.go:22 writing system identity file
2015-08-07 07:53:03 INFO juju.mongo mongo.go:173 Ensuring mongo server is running; data directory /var/lib/juju; port 37017
2015-08-07 07:53:03 INFO juju.mongo mongo.go:348 installing juju-mongodb
2015-08-07 07:53:03 INFO juju.utils.packaging.manager utils.go:57 Running: apt-get --option=Dpkg::Options::=--force-confold --option=Dpkg::options::=--force-unsafe-io --assume-yes --quiet install juju-mongodb
2015-08-07 07:58:07 INFO juju.worker.peergrouper initiate.go:78 finished MaybeInitiateMongoServer
2015-08-07 07:58:07 ERROR juju.cmd supercommand.go:430 cannot initiate replica set: cannot dial mongo to initiate replicaset: no reachable servers
ERROR failed to bootstrap environment: subprocess encountered error code 1

Can anyone who's experiencing this issue please attach the contents of /var/log/syslog for the period of the bootstrap? That will tell us if mongod is having problems and if it's even trying to start.

The attached is my syslog contents after running a fresh "juju bootstrap"

@olutayo: The syslog output indicates that the mongodb shared secret file is missing (possibily a race). This gives me enough to work with. Thank you!

Although I don't quite understand how the mongod shared-secret file can be missing even though the mongod init system config is there, I have made a change so that mongod related config files are always written out before trying to start mongod.

The fix for 1.24 is here: https://github.com/juju/juju/pull/3027

Fix for master here: https://github.com/juju/juju/pull/3030

How can this fix be applied to cure the defect in an already but affected installation

@olutayo: Given that this is a bootstrap issue, there is of course no existing Juju deployments to upgrade.

The fix will be in the next release of 1.24 and also in 1.25.0. If you are using the Juju stable PPA you'll see the update once the new version is released.

Additionally, if you urgently need a custom Juju build with this fix I can provide it for you. Let me know.

@smits: Thanks for the support offer. The next release has no date yet, though I am just exploring juju after a nice experience with lxd.

I am recreating this bug with 1.25.0

....
Reading state information...
tmux is already the newest version.
0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded.
Attempt 1 to download tools from https://streams.canonical.com/juju/tools/releases/juju-1.25.0-trusty-amd64.tgz...
tools from https://streams.canonical.com/juju/tools/releases/juju-1.25.0-trusty-amd64.tgz downloaded: HTTP 200; time 4.093s; size 18672448 bytes; speed 4561922.000 bytes/s Tools downloaded successfully.
0419fcde2d571a00eddd0b2fb9e35f5102a9fd81cbecd4a2d0b648da7740eab3 /var/lib/juju/tools/1.25.0-trusty-amd64/tools.tar.gz
2016-01-19 14:36:45 INFO juju.cmd supercommand.go:37 running jujud [1.25.0-trusty-amd64 gc]
2016-01-19 14:36:45 INFO juju.network network.go:242 setting prefer-ipv6 to false
2016-01-19 14:36:45 INFO juju.agent identity.go:22 writing system identity file
2016-01-19 14:36:45 INFO juju.mongo mongo.go:175 Ensuring mongo server is running; data directory /var/lib/juju; port 37017
2016-01-19 14:36:45 INFO juju.mongo mongo.go:339 installing juju-mongodb
2016-01-19 14:36:45 INFO juju.utils.packaging.manager utils.go:57 Running: apt-get --option=Dpkg::Options::=--force-confold --option=Dpkg::options::=--force-unsafe-io --assume-yes --quiet install juju-mongodb
2016-01-19 14:44:33 INFO juju.worker.peergrouper initiate.go:78 finished MaybeInitiateMongoServer
2016-01-19 14:44:33 ERROR juju.cmd supercommand.go:429 cannot initiate replica set: cannot dial mongo to initiate replicaset: no reachable servers
ERROR failed to bootstrap environment: subprocess encountered error code 1

Hey Larry, can you open a new bug and attach /var/log/syslog?