talking to mongo can fail with "TCP i/o timeout"

[John A Meinel]

While doing scale testing, I ended up getting:

ERROR cannot add unit 53/100 to service "ubuntu": cannot add unit to service "ubuntu": write tcp 127.0.0.1:37017: i/o timeout
ERROR cannot add unit 53/100 to service "ubuntu": cannot add unit to service "ubuntu": write tcp 127.0.0.1:37017: i/o timeout
ERROR cannot add unit 53/100 to service "ubuntu": cannot add unit to service "ubuntu": write tcp 127.0.0.1:37017: i/o timeout
ERROR cannot add unit 52/100 to service "ubuntu": cannot add unit to service "ubuntu": write tcp 127.0.0.1:37017: i/o timeout
ERROR cannot add unit 52/100 to service "ubuntu": cannot add unit to service "ubuntu": write tcp 127.0.0.1:37017: i/o timeout
ERROR cannot add unit 53/100 to service "ubuntu": cannot add unit to service "ubuntu": write tcp 127.0.0.1:37017: i/o timeout
ERROR cannot add unit 52/100 to service "ubuntu": cannot add unit to service "ubuntu": write tcp 127.0.0.1:37017: i/o timeout
ERROR cannot add unit 52/100 to service "ubuntu": cannot add unit to service "ubuntu": write tcp 127.0.0.1:37017: i/o timeout
ERROR cannot add unit 53/100 to service "ubuntu": cannot add unit to service "ubuntu": write tcp 127.0.0.1:37017: i/o timeout
ERROR cannot assign unit "ubuntu/8589" to machine 14: write tcp 127.0.0.1:37017: i/o timeout
ERROR cannot add unit 50/100 to service "ubuntu": cannot add unit to service "ubuntu": write tcp 127.0.0.1:37017: i/o timeout
ERROR cannot add unit 52/100 to service "ubuntu": cannot add unit to service "ubuntu": write tcp 127.0.0.1:37017: i/o timeout
ERROR cannot add unit 53/100 to service "ubuntu": cannot add unit to service "ubuntu": write tcp 127.0.0.1:37017: i/o timeout
ERROR cannot add unit 53/100 to service "ubuntu": cannot add unit to service "ubuntu": write tcp 127.0.0.1:37017: i/o timeout
ERROR cannot add unit 55/100 to service "ubuntu": cannot add unit to service "ubuntu": write tcp 127.0.0.1:37017: i/o timeout
ERROR cannot add unit 55/100 to service "ubuntu": cannot add unit to service "ubuntu": write tcp 127.0.0.1:37017: i/o timeout

It appears that if you overload Mongo enough that it can't respond to your requests as fast as you are making them, you end up failing because of i/o timeout, rather than getting a nicer error.

This might be considered a bug in 'mgo' that it doesn't notice that Mongo is in overload and tell you to back off. At the least, it feels like juju needs to be able to gracefully recover from this state.

[Adam Stokes (adam-stokes)]

We've actually seen this exact problem with deploying 4 charms on trusty using juju-core 1.18.x

The charms deployed were:

nova-cloud-controller
glance
keystone
mysql

All in local provider with lxc containers for each

[Adam Collard (adam-collard)]

We hit this problem with deploying 64 nodes. Restarting the state server worked around it.

[Chris J Arges (arges)]

Me too:

2014-05-08 18:51:49 INFO install Traceback (most recent call last):
2014-05-08 18:51:49 INFO install File "/var/lib/juju/agents/unit-glance-0/charm/hooks/install", line 385, in <module>
2014-05-08 18:51:49 INFO install hooks.execute(sys.argv)
2014-05-08 18:51:49 INFO install File "/var/lib/juju/agents/unit-glance-0/charm/hooks/charmhelpers/core/hookenv.py", line 381, in execute
2014-05-08 18:51:49 INFO install self._hooks[hook_name]()
2014-05-08 18:51:49 INFO install File "/var/lib/juju/agents/unit-glance-0/charm/hooks/install", line 71, in install_hook
2014-05-08 18:51:49 INFO install src = config('openstack-origin')
2014-05-08 18:51:49 INFO install File "/var/lib/juju/agents/unit-glance-0/charm/hooks/charmhelpers/core/hookenv.py", line 44, in wrapper
2014-05-08 18:51:49 INFO install res = func(*args, **kwargs)
2014-05-08 18:51:49 INFO install File "/var/lib/juju/agents/unit-glance-0/charm/hooks/charmhelpers/core/hookenv.py", line 166, in config
2014-05-08 18:51:49 INFO install return json.loads(subprocess.check_output(config_cmd_line))
2014-05-08 18:51:49 INFO install File "/usr/lib/python2.7/subprocess.py", line 573, in check_output
2014-05-08 18:51:49 INFO install raise CalledProcessError(retcode, cmd, output=output)
2014-05-08 18:51:49 INFO install subprocess.CalledProcessError: Command '['config-get', 'openstack-origin', '--format=json']' returned non-zero exit status 1
2014-05-08 18:51:49 ERROR juju.worker.uniter uniter.go:486 hook failed: exit status 1
2014-05-08 18:51:49 ERROR juju runner.go:209 worker: fatal "uniter": watcher iteration error: read tcp 127.0.0.1:37017: i/o timeout
2014-05-08 18:51:49 ERROR juju runner.go:220 worker: exited "api": watcher iteration error: read tcp 127.0.0.1:37017: i/o timeout
2014-05-08 18:53:03 ERROR juju watcher.go:66 state/api: error trying to stop watcher connection is shut down
2014-05-08 18:53:03 ERROR juju watcher.go:66 state/api: error trying to stop watcher connection is shut down
2014-05-08 18:53:03 ERROR juju watcher.go:66 state/api: error trying to stop watcher connection is shut down
2014-05-08 18:53:03 ERROR juju watcher.go:66 state/api: error trying to stop watcher connection is shut down
2014-05-08 18:53:03 ERROR juju watcher.go:66 state/api: error trying to stop watcher connection is shut down
2014-05-08 18:53:03 ERROR juju watcher.go:66 state/api: error trying to stop watcher connection is shut down
2014-05-08 18:53:03 ERROR juju watcher.go:66 state/api: error trying to stop watcher connection is shut down
2014-05-08 18:53:03 ERROR juju watcher.go:66 state/api: error trying to stop watcher connection is shut down
2014-05-08 18:53:03 ERROR juju.worker.uniter.filter filter.go:116 watcher iteration error: read tcp 127.0.0.1:37017: i/o timeout
2014-05-08 18:53:03 ERROR juju runner.go:209 worker: fatal "upgrader": watcher iteration error: read tcp 127.0.0.1:37017: i/o timeout
2014-05-08 18:53:03 ERROR juju runner.go:209 worker: fatal "logger": watcher iteration error: read tcp 127.0.0.1:37017: i/o timeout
2014-05-08 18:53:03 ERROR juju runner.go:209 worker: fatal "uniter": watcher iteration error: read tcp 127.0.0.1:37017: i/o timeout
2014-05-0...

[Kapil Thangavelu (hazmat)]

we've seen this quite a bit.. also found some panics in the jujud on state server, bouncing machine-0 jujud resolved.

[Nate Finch (natefinch)]

This is happening with small numbers of units (Adam Stokes' case above was just 1 unit each of 4 services) and apparently requires a server restart to resolve the situation. Increased importance to High because it seems this is much more likely than previously thought.

[Kapil Thangavelu (hazmat)]

also to note this was seen on systems with almost minor load and just 2 machines.

[Nate Finch (natefinch)]

I hit this recently just by doing bootstrap and then ensure availability. no services deployed at all.

[Christian Reis (kiko)]

This is happening to us at the Async deployment as well, with a 10-container installation. Nothing very interesting in the mongo log.

[Adam Stokes (adam-stokes)]

Hi,

Why is this only targetted for 1.19.x when the problem is seen in the stable release of 1.18.x? Can we get this scheduled for inclusion in the stable release series?

Thanks
Adam

[Mike McCracken (mikemc)]

Here's a unit log for another instance of this issue in deploying glance inside an lxc on a host in a maas cluster:

http://paste.ubuntu.com/7589184/

Here's the corresponding juju status :
http://paste.ubuntu.com/7589198/

I've experienced this same error more than half the times that I've tried to deploy this environment.

[Alex Chiang (achiang)]

Here is my contribution to this bug.

/var/log/juju/all-machines.log: http://pastebin.ubuntu.com/7691311/

This occurs with:

- a bootstrap node
- a single mongodb unit
- my own service/unit that I am developing.

(deployed on an openstack instance)

ssh to the bootstrap node and issuing:

$ sudo service jujud-machine-0 restart
jujud-machine-0 stop/waiting
jujud-machine-0 start/running, process 6442

Seems to recover, and allow `juju status` to work again.

[Michael Foord (mfoord)]

This looks like several different bugs, or more specifically the same issue surfacing in several different places. We believe that the underlying cause is due to juju holding onto a single session to mongo - so if this connection dies everything is irredeemably broken. The best fix is to open a new session whenever we need it, and use the underlying socket pooling provided by the mgo driver. Unfortunately our watcher architecture (and the state itself) all hold onto an indirect reference to this session via mgo collections. So it needs a bit of "unpicking" to resolve.

This (short) email thread is a useful reference on the topic: https://groups.google.com/forum/#!topic/mgo-users/iZeiKgonGDU