Vault charm errors during update-status after "rpc error: code = DeadlineExceeded desc = context deadline exceeded"

[Michael Skalka]

As seen in this test run: https://solutions.qa.canonical.com/testruns/testRun/2917658f-9a7f-436d-a84b-bd3e313d32d1
Crashdump here: https://oil-jenkins.canonical.com/artifacts/2917658f-9a7f-436d-a84b-bd3e313d32d1/generated/generated/lmacmr/juju-crashdump-openstack-2020-11-13-17.20.35.tar.gz

While setting up LMA on an already stable cluster the vault unit errors out on the "update-status" hook when the vault service is unavailable:

var/log/juju/unit-vault-2.log:
...
2020-11-13 17:03:17 WARNING update-status Traceback (most recent call last):
2020-11-13 17:03:17 WARNING update-status File "/var/lib/juju/agents/unit-vault-2/charm/hooks/update-status", line 22, in <module>
2020-11-13 17:03:17 WARNING update-status main()
2020-11-13 17:03:17 WARNING update-status File "/var/lib/juju/agents/unit-vault-2/.venv/lib/python3.6/site-packages/charms/reactive/__init__.py", line 84, in main
2020-11-13 17:03:17 WARNING update-status hookenv._run_atexit()
2020-11-13 17:03:17 WARNING update-status File "/var/lib/juju/agents/unit-vault-2/.venv/lib/python3.6/site-packages/charmhelpers/core/hookenv.py", line 1343, in _run_atexit
2020-11-13 17:03:17 WARNING update-status callback(*args, **kwargs)
2020-11-13 17:03:17 WARNING update-status File "/var/lib/juju/agents/unit-vault-2/charm/reactive/vault_handlers.py", line 706, in _assess_status
2020-11-13 17:03:17 WARNING update-status if not client_approle_authorized():
2020-11-13 17:03:17 WARNING update-status File "/var/lib/juju/agents/unit-vault-2/charm/reactive/vault_handlers.py", line 727, in client_approle_authorized
2020-11-13 17:03:17 WARNING update-status vault.get_local_client()
2020-11-13 17:03:17 WARNING update-status File "/var/lib/juju/agents/unit-vault-2/.venv/lib/python3.6/site-packages/tenacity/__init__.py", line 329, in wrapped_f
2020-11-13 17:03:17 WARNING update-status return self.call(f, *args, **kw)
2020-11-13 17:03:17 WARNING update-status File "/var/lib/juju/agents/unit-vault-2/.venv/lib/python3.6/site-packages/tenacity/__init__.py", line 409, in call
2020-11-13 17:03:17 WARNING update-status do = self.iter(retry_state=retry_state)
2020-11-13 17:03:17 WARNING update-status File "/var/lib/juju/agents/unit-vault-2/.venv/lib/python3.6/site-packages/tenacity/__init__.py", line 356, in iter
2020-11-13 17:03:17 WARNING update-status return fut.result()
2020-11-13 17:03:17 WARNING update-status File "/usr/lib/python3.6/concurrent/futures/_base.py", line 425, in result
2020-11-13 17:03:17 WARNING update-status return self.__get_result()
2020-11-13 17:03:17 WARNING update-status File "/usr/lib/python3.6/concurrent/futures/_base.py", line 384, in __get_result
2020-11-13 17:03:17 WARNING update-status raise self._exception
2020-11-13 17:03:17 WARNING update-status File "/var/lib/juju/agents/unit-vault-2/.venv/lib/python3.6/site-packages/tenacity/__init__.py", line 412, in call
2020-11-13 17:03:17 WARNING update-status result = fn(*args, **kwargs)
2020-11-13 17:03:17 WARNING update-status File "/var/lib/juju/agents/unit-vault-2/charm/lib/charm/vault.py", line 254, in get_local_client
2020-11-13 17:03:17 WARNING update-status client.auth_approle(app_role_id)
2020-11-13 17:03:17 WARNING update-status File "/var/lib/juju/agents/unit-vault-2/.venv/lib/python3.6/site-packages/hvac/v1/__init__.py", line 2072, in auth_approle
2020-11-13 17:03:17 WARNING update-status return self.auth('/v1/auth/{0}/login'.format(mount_point), json=params, use_token=use_token)
2020-11-13 17:03:17 WARNING update-status File "/var/lib/juju/agents/unit-vault-2/.venv/lib/python3.6/site-packages/hvac/v1/__init__.py", line 1729, in auth
2020-11-13 17:03:17 WARNING update-status **kwargs
2020-11-13 17:03:17 WARNING update-status File "/var/lib/juju/agents/unit-vault-2/.venv/lib/python3.6/site-packages/hvac/adapters.py", line 159, in auth
2020-11-13 17:03:17 WARNING update-status response = self.post(url, **kwargs).json()
2020-11-13 17:03:17 WARNING update-status File "/var/lib/juju/agents/unit-vault-2/.venv/lib/python3.6/site-packages/hvac/adapters.py", line 103, in post
2020-11-13 17:03:17 WARNING update-status return self.request('post', url, **kwargs)
2020-11-13 17:03:17 WARNING update-status File "/var/lib/juju/agents/unit-vault-2/.venv/lib/python3.6/site-packages/hvac/adapters.py", line 219, in request
2020-11-13 17:03:17 WARNING update-status allow_redirects=False, **_kwargs)
2020-11-13 17:03:17 WARNING update-status File "/var/lib/juju/agents/unit-vault-2/.venv/lib/python3.6/site-packages/requests/sessions.py", line 530, in request
2020-11-13 17:03:17 WARNING update-status resp = self.send(prep, **send_kwargs)
2020-11-13 17:03:17 WARNING update-status File "/var/lib/juju/agents/unit-vault-2/.venv/lib/python3.6/site-packages/requests/sessions.py", line 643, in send
2020-11-13 17:03:17 WARNING update-status r = adapter.send(request, **kwargs)
2020-11-13 17:03:17 WARNING update-status File "/var/lib/juju/agents/unit-vault-2/.venv/lib/python3.6/site-packages/requests/adapters.py", line 529, in send
2020-11-13 17:03:17 WARNING update-status raise ReadTimeout(e, request=request)
2020-11-13 17:03:17 WARNING update-status requests.exceptions.ReadTimeout: HTTPConnectionPool(host='127.0.0.1', port=8220): Read timed out. (read timeout=30)
...

var/log/syslog:

Nov 13 17:02:47 vault-3 vault[28885]: {"level":"warn","ts":"2020-11-13T17:02:47.772Z","caller":"clientv3/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"endpoint://client-88a1
3883-06d6-4799-b073-05d81eec41c0/192.168.33.184:2379","attempt":0,"error":"rpc error: code = DeadlineExceeded desc = context deadline exceeded"}
Nov 13 17:02:57 vault-3 vault[28885]: {"level":"warn","ts":"2020-11-13T17:02:57.773Z","caller":"clientv3/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"endpoint://client-88a1
3883-06d6-4799-b073-05d81eec41c0/192.168.33.184:2379","attempt":0,"error":"rpc error: code = DeadlineExceeded desc = context deadline exceeded"}
Nov 13 17:03:10 vault-3 vault[28885]: {"level":"warn","ts":"2020-11-13T17:03:10.276Z","caller":"clientv3/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"endpoint://client-88a1
3883-06d6-4799-b073-05d81eec41c0/192.168.33.184:2379","attempt":0,"error":"rpc error: code = DeadlineExceeded desc = context deadline exceeded"}
Nov 13 17:03:22 vault-3 vault[28885]: {"level":"warn","ts":"2020-11-13T17:03:22.778Z","caller":"clientv3/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"endpoint://client-88a1
3883-06d6-4799-b073-05d81eec41c0/192.168.33.184:2379","attempt":0,"error":"rpc error: code = DeadlineExceeded desc = context deadline exceeded"}
Nov 13 17:03:35 vault-3 vault[28885]: {"level":"warn","ts":"2020-11-13T17:03:35.279Z","caller":"clientv3/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"endpoint://client-88a1
3883-06d6-4799-b073-05d81eec41c0/192.168.33.184:2379","attempt":0,"error":"rpc error: code = DeadlineExceeded desc = context deadline exceeded"}

It is not clear if the service goes down or it's an issue with stale connections. The syslog errors repeat multiple times after this, indicating that the service is unhealthy, however neither juju nor syslog give any more information on what is going on.

[Alexander Balderson (asbalderson)]

we've seen this during the certificates-relation-changed hook as well:

Traceback (most recent call last):
  File "/var/lib/juju/agents/unit-vault-2/.venv/lib/python3.8/site-packages/charms/reactive/__init__.py", line 74, in main
    bus.dispatch(restricted=restricted_mode)
  File "/var/lib/juju/agents/unit-vault-2/.venv/lib/python3.8/site-packages/charms/reactive/bus.py", line 390, in dispatch
    _invoke(other_handlers)
  File "/var/lib/juju/agents/unit-vault-2/.venv/lib/python3.8/site-packages/charms/reactive/bus.py", line 359, in _invoke
    handler.invoke()
  File "/var/lib/juju/agents/unit-vault-2/.venv/lib/python3.8/site-packages/charms/reactive/bus.py", line 181, in invoke
    self._action(*args)
  File "/var/lib/juju/agents/unit-vault-2/charm/reactive/vault_handlers.py", line 861, in publish_ca_info
    chain = vault_pki.get_chain()
  File "/var/lib/juju/agents/unit-vault-2/charm/lib/charm/vault_pki.py", line 80, in get_chain
    return client.read('{}/cert/ca_chain'.format(name))['data']['certificate']
  File "/var/lib/juju/agents/unit-vault-2/.venv/lib/python3.8/site-packages/hvac/v1/__init__.py", line 157, in read
    return self._adapter.get('/v1/{0}'.format(path), wrap_ttl=wrap_ttl).json()
  File "/var/lib/juju/agents/unit-vault-2/.venv/lib/python3.8/site-packages/hvac/adapters.py", line 90, in get
    return self.request('get', url, **kwargs)
  File "/var/lib/juju/agents/unit-vault-2/.venv/lib/python3.8/site-packages/hvac/adapters.py", line 233, in request
    utils.raise_for_error(response.status_code, text, errors=errors)
  File "/var/lib/juju/agents/unit-vault-2/.venv/lib/python3.8/site-packages/hvac/utils.py", line 39, in raise_for_error
    raise exceptions.InternalServerError(message, errors=errors)
hvac.exceptions.InternalServerError: context deadline exceeded

coming from vault2 in this crashdump:
https://oil-jenkins.canonical.com/artifacts/e9741061-8c3b-42ef-95a9-c8fdd425245b/generated/generated/kubernetes/juju-crashdump-kubernetes-2021-05-02-01.11.52.tar.gz

[Bas de Bruijne (basdbruijne)]

This is still a relevant issue, though the traceback has changed slightly:

==========
Traceback (most recent call last):
  File "/var/lib/juju/agents/unit-vault-1/.venv/lib/python3.8/site-packages/charms/reactive/__init__.py", line 74, in main
    bus.dispatch(restricted=restricted_mode)
  File "/var/lib/juju/agents/unit-vault-1/.venv/lib/python3.8/site-packages/charms/reactive/bus.py", line 390, in dispatch
    _invoke(other_handlers)
  File "/var/lib/juju/agents/unit-vault-1/.venv/lib/python3.8/site-packages/charms/reactive/bus.py", line 359, in _invoke
    handler.invoke()
  File "/var/lib/juju/agents/unit-vault-1/.venv/lib/python3.8/site-packages/charms/reactive/bus.py", line 181, in invoke
    self._action(*args)
  File "/var/lib/juju/agents/unit-vault-1/charm/reactive/vault_handlers.py", line 1100, in tune_pki_backend_config_changed
    vault_pki.update_roles(max_ttl=max_ttl)
  File "/var/lib/juju/agents/unit-vault-1/charm/lib/charm/vault_pki.py", line 339, in update_roles
    write_roles(client, **local)
  File "/var/lib/juju/agents/unit-vault-1/charm/lib/charm/vault_pki.py", line 314, in write_roles
    client.write(
  File "/var/lib/juju/agents/unit-vault-1/.venv/lib/python3.8/site-packages/hvac/v1/__init__.py", line 189, in write
    response = self._adapter.post('/v1/{0}'.format(path), json=kwargs, wrap_ttl=wrap_ttl)
  File "/var/lib/juju/agents/unit-vault-1/.venv/lib/python3.8/site-packages/hvac/adapters.py", line 103, in post
    return self.request('post', url, **kwargs)
  File "/var/lib/juju/agents/unit-vault-1/.venv/lib/python3.8/site-packages/hvac/adapters.py", line 233, in request
    utils.raise_for_error(response.status_code, text, errors=errors)
  File "/var/lib/juju/agents/unit-vault-1/.venv/lib/python3.8/site-packages/hvac/utils.py", line 39, in raise_for_error
    raise exceptions.InternalServerError(message, errors=errors)
hvac.exceptions.InternalServerError: context deadline exceeded
==========