etcd3gw.exceptions.ConnectionFailedError: Service Unavailable in c-vol

[Matt Riedemann]

Seen here:

http://logs.openstack.org/99/471899/25/check/gate-tempest-dsvm-py35-ubuntu-xenial/6edbd19/logs/screen-c-vol.txt.gz?level=TRACE#_Jul_18_22_29_28_601899

Jul 18 22:29:28.601899 ubuntu-xenial-infracloud-vanilla-9918756 cinder-volume[25564]: ERROR oslo_messaging.rpc.server [None req-f9efaaa9-b153-40ee-9a42-0ee9610d773e tempest-AttachVolumeShelveTestJSON-225529070 None] Exception during message handling: tooz.coordination.ToozConnectionError: Service Unavailable
Jul 18 22:29:28.602062 ubuntu-xenial-infracloud-vanilla-9918756 cinder-volume[25564]: ERROR oslo_messaging.rpc.server Traceback (most recent call last):
Jul 18 22:29:28.602224 ubuntu-xenial-infracloud-vanilla-9918756 cinder-volume[25564]: ERROR oslo_messaging.rpc.server File "/usr/local/lib/python3.5/dist-packages/tooz/drivers/etcd3gw.py", line 37, in wrapper
Jul 18 22:29:28.602831 ubuntu-xenial-infracloud-vanilla-9918756 cinder-volume[25564]: ERROR oslo_messaging.rpc.server return func(*args, **kwargs)
Jul 18 22:29:28.602983 ubuntu-xenial-infracloud-vanilla-9918756 cinder-volume[25564]: ERROR oslo_messaging.rpc.server File "/usr/local/lib/python3.5/dist-packages/tooz/drivers/etcd3gw.py", line 111, in acquire
Jul 18 22:29:28.603136 ubuntu-xenial-infracloud-vanilla-9918756 cinder-volume[25564]: ERROR oslo_messaging.rpc.server return _acquire()
Jul 18 22:29:28.603288 ubuntu-xenial-infracloud-vanilla-9918756 cinder-volume[25564]: ERROR oslo_messaging.rpc.server File "/usr/local/lib/python3.5/dist-packages/tenacity/__init__.py", line 170, in wrapped_f
Jul 18 22:29:28.603478 ubuntu-xenial-infracloud-vanilla-9918756 cinder-volume[25564]: ERROR oslo_messaging.rpc.server return self.call(f, *args, **kw)
Jul 18 22:29:28.603635 ubuntu-xenial-infracloud-vanilla-9918756 cinder-volume[25564]: ERROR oslo_messaging.rpc.server File "/usr/local/lib/python3.5/dist-packages/tenacity/__init__.py", line 247, in call
Jul 18 22:29:28.603828 ubuntu-xenial-infracloud-vanilla-9918756 cinder-volume[25564]: ERROR oslo_messaging.rpc.server start_time=start_time)
Jul 18 22:29:28.603975 ubuntu-xenial-infracloud-vanilla-9918756 cinder-volume[25564]: ERROR oslo_messaging.rpc.server File "/usr/local/lib/python3.5/dist-packages/tenacity/__init__.py", line 202, in iter
Jul 18 22:29:28.604167 ubuntu-xenial-infracloud-vanilla-9918756 cinder-volume[25564]: ERROR oslo_messaging.rpc.server return fut.result()
Jul 18 22:29:28.604344 ubuntu-xenial-infracloud-vanilla-9918756 cinder-volume[25564]: ERROR oslo_messaging.rpc.server File "/usr/lib/python3.5/concurrent/futures/_base.py", line 398, in result
Jul 18 22:29:28.604521 ubuntu-xenial-infracloud-vanilla-9918756 cinder-volume[25564]: ERROR oslo_messaging.rpc.server return self.__get_result()
Jul 18 22:29:28.608773 ubuntu-xenial-infracloud-vanilla-9918756 cinder-volume[25564]: ERROR oslo_messaging.rpc.server File "/usr/lib/python3.5/concurrent/futures/_base.py", line 357, in __get_result
Jul 18 22:29:28.608986 ubuntu-xenial-infracloud-vanilla-9918756 cinder-volume[25564]: ERROR oslo_messaging.rpc.server raise self._exception
Jul 18 22:29:28.609178 ubuntu-xenial-infracloud-vanilla-9918756 cinder-volume[25564]: ERROR oslo_messaging.rpc.server File "/usr/local/lib/python3.5/dist-packages/tenacity/__init__.py", line 250, in call
Jul 18 22:29:28.609342 ubuntu-xenial-infracloud-vanilla-9918756 cinder-volume[25564]: ERROR oslo_messaging.rpc.server result = fn(*args, **kwargs)
Jul 18 22:29:28.609509 ubuntu-xenial-infracloud-vanilla-9918756 cinder-volume[25564]: ERROR oslo_messaging.rpc.server File "/usr/local/lib/python3.5/dist-packages/tooz/drivers/etcd3gw.py", line 101, in _acquire
Jul 18 22:29:28.609694 ubuntu-xenial-infracloud-vanilla-9918756 cinder-volume[25564]: ERROR oslo_messaging.rpc.server result = self._coord.client.transaction(txn)
Jul 18 22:29:28.609896 ubuntu-xenial-infracloud-vanilla-9918756 cinder-volume[25564]: ERROR oslo_messaging.rpc.server File "/usr/local/lib/python3.5/dist-packages/etcd3gw/client.py", line 294, in transaction
Jul 18 22:29:28.610079 ubuntu-xenial-infracloud-vanilla-9918756 cinder-volume[25564]: ERROR oslo_messaging.rpc.server data=json.dumps(txn))
Jul 18 22:29:28.610269 ubuntu-xenial-infracloud-vanilla-9918756 cinder-volume[25564]: ERROR oslo_messaging.rpc.server File "/usr/local/lib/python3.5/dist-packages/etcd3gw/client.py", line 80, in post
Jul 18 22:29:28.610689 ubuntu-xenial-infracloud-vanilla-9918756 cinder-volume[25564]: ERROR oslo_messaging.rpc.server raise _EXCEPTIONS_BY_CODE[resp.status_code](resp.reason)
Jul 18 22:29:28.610848 ubuntu-xenial-infracloud-vanilla-9918756 cinder-volume[25564]: ERROR oslo_messaging.rpc.server etcd3gw.exceptions.ConnectionFailedError: Service Unavailable

Looks like we can randomly loose the connection to etcd3 via tooz.

http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22etcd3gw.exceptions.ConnectionFailedError%3A%20Service%20Unavailable%5C%22%20AND%20tags%3A%5C%22screen-c-vol.txt%5C%22&from=7d

[Julien Danjou (jdanjou)]

I guess this is due to:

Jul 18 22:29:28.603914 ubuntu-xenial-infracloud-vanilla-9918756 etcd[2359]: sync duration of 8.333605774s, expected less than 1s

http://logs.openstack.org/99/471899/25/check/gate-tempest-dsvm-py35-ubuntu-xenial/6edbd19/logs/screen-etcd.txt.gz

[Ben Nemec (bnemec)]

According to logstash this is still happening, although not very often.