hook failed: "vault-kv-relation-changed" when deploying master with vault

[Seyeong Kim]

Hello

I faced issue when deploying k8s with vault.
This symptom was not happened regularly but intermittently.

I've analyzed this but no clue where is the exact point this is happening.

actually generated token seems to be not proper.

Could you please advice me to analyze this or fix this?

#######################################################
error msg in kubernetes-master
#######################################################

2019-09-16 05:53:18 DEBUG vault-kv-relation-changed /var/lib/juju/agents/unit-kubernetes-master-0/.venv/lib/python3.6/site-packages/charmhelpers/contrib/openstack/vaultlocker.py:127: DeprecationWarning: Call to deprecated function '_post'. This method will be removed in version '0.8.0' Please use the 'post' method on the 'hvac.adapters' class moving forward. 2019-09-16 05:53:18 DEBUG vault-kv-relation-changed response = client._post('/v1/sys/wrapping/unwrap') 2019-09-16 05:53:18 DEBUG vault-kv-relation-changed Traceback (most recent call last): 2019-09-16 05:53:18 DEBUG vault-kv-relation-changed File "/var/lib/juju/agents/unit-kubernetes-master-0/charm/hooks/vault-kv-relation-changed", line 22, in <module> 2019-09-16 05:53:18 DEBUG vault-kv-relation-changed main() 2019-09-16 05:53:18 DEBUG vault-kv-relation-changed File "/var/lib/juju/agents/unit-kubernetes-master-0/.venv/lib/python3.6/site-packages/charms/reactive/__init__.py", line 73, in main 2019-09-16 05:53:18 DEBUG vault-kv-relation-changed bus.dispatch(restricted=restricted_mode) 2019-09-16 05:53:18 DEBUG vault-kv-relation-changed File "/var/lib/juju/agents/unit-kubernetes-master-0/.venv/lib/python3.6/site-packages/charms/reactive/bus.py", line 390, in dispatch 2019-09-16 05:53:18 DEBUG vault-kv-relation-changed _invoke(other_handlers) 2019-09-16 05:53:18 DEBUG vault-kv-relation-changed File "/var/lib/juju/agents/unit-kubernetes-master-0/.venv/lib/python3.6/site-packages/charms/reactive/bus.py", line 359, in _invoke 2019-09-16 05:53:18 DEBUG vault-kv-relation-changed handler.invoke() 2019-09-16 05:53:18 DEBUG vault-kv-relation-changed File "/var/lib/juju/agents/unit-kubernetes-master-0/.venv/lib/python3.6/site-packages/charms/reactive/bus.py", line 181, in invoke 2019-09-16 05:53:18 DEBUG vault-kv-relation-changed self._action(*args) 2019-09-16 05:53:18 DEBUG vault-kv-relation-changed File "/var/lib/juju/agents/unit-kubernetes-master-0/charm/reactive/vault_kv.py", line 22, in set_ready 2019-09-16 05:53:18 DEBUG vault-kv-relation-changed vault_kv.get_vault_config() 2019-09-16 05:53:18 DEBUG vault-kv-relation-changed File "lib/charms/layer/vault_kv.py", line 212, in get_vault_config 2019-09-16 05:53:18 DEBUG vault-kv-relation-changed 'secret_id': _get_secret_id(vault), 2019-09-16 05:53:18 DEBUG vault-kv-relation-changed File "lib/charms/layer/vault_kv.py", line 228, in _get_secret_id 2019-09-16 05:53:18 DEBUG vault-kv-relation-changed secret_id = retrieve_secret_id(vault_url, token) 2019-09-16 05:53:18 DEBUG vault-kv-relation-changed File "/var/lib/juju/agents/unit-kubernetes-master-0/.venv/lib/python3.6/site-packages/charmhelpers/contrib/openstack/vaultlocker.py", line 127, in retrieve_secret_id 2019-09-16 05:53:18 DEBUG vault-kv-relation-changed response = client._post('/v1/sys/wrapping/unwrap') 2019-09-16 05:53:18 DEBUG vault-kv-relation-changed File "/var/lib/juju/agents/unit-kubernetes-master-0/.venv/lib/python3.6/site-packages/hvac/utils.py", line 170, in new_func 2019-09-16 05:53:18 DEBUG vault-kv-relation-changed return method(*args, **kwargs) 2019-09-16 05:53:18 DEBUG vault-kv-relation-changed File "/var/lib/juju/agents/unit-kubernetes-master-0/.venv/lib/python3.6/site-packages/hvac/v1/__init__.py", line 2525, in _post 2019-09-16 05:53:18 DEBUG vault-kv-relation-changed return self._adapter.post(*args, **kwargs) 2019-09-16 05:53:18 DEBUG vault-kv-relation-changed File "/var/lib/juju/agents/unit-kubernetes-master-0/.venv/lib/python3.6/site-packages/hvac/adapters.py", line 103, in post 2019-09-16 05:53:18 DEBUG vault-kv-relation-changed return self.request('post', url, **kwargs) 2019-09-16 05:53:18 DEBUG vault-kv-relation-changed File "/var/lib/juju/agents/unit-kubernetes-master-0/.venv/lib/python3.6/site-packages/hvac/adapters.py", line 272, in request 2019-09-16 05:53:18 DEBUG vault-kv-relation-changed utils.raise_for_error(response.status_code, text, errors=errors) 2019-09-16 05:53:18 DEBUG vault-kv-relation-changed File "/var/lib/juju/agents/unit-kubernetes-master-0/.venv/lib/python3.6/site-packages/hvac/utils.py", line 30, in raise_for_error 2019-09-16 05:53:18 DEBUG vault-kv-relation-changed raise exceptions.InvalidRequest(message, errors=errors) 2019-09-16 05:53:18 DEBUG vault-kv-relation-changed hvac.exceptions.InvalidRequest: wrapping token is not valid or does not exist

#######################################################
Some analysis
#######################################################

juju run --unit kubernetes-master/0 -- "relation-get -r vault-kv:19 - vault/0" egress-subnets: 10.0.0.23/32 ingress-address: 10.0.0.23 kubernetes-master/0_role_id: '"72a89a04-6aea-db8d-2102-48694e0dde68"' kubernetes-master/0_token: '"s.wtHvWWnEDdjvWNuIgyflHQz4"' private-address: 10.0.0.23 vault_url: '"http://10.0.0.254:8200"'

vault token lookup s.wtHvWWnEDdjvWNuIgyflHQz4 Error looking up token: Error making API request. URL: POST http://10.0.0.23:8200/v1/auth/token/lookup Code: 403. Errors: * bad token

[Cory Johns (johnsca)]

The token in the relation data is a one-shot token which is used to request a secret ID from Vault which is then saved and used for future requests. This is failing on the retrieve_secret_id call; the most likely reason why this would fail is if it was called more than once, possibly due to a previous hook error.

Can you check the logs and confirm whether this failure was the first error in the logs? Also, can you see if the secret_id already has a value:

juju run --unit kubernetes-master/0 -- chlp unitdata get layer.vault-kv.secret_id

[Seyeong Kim (seyeongkim)]

@johnsca

It was the only error I could see before.
In my test env secret_id was None. but I think my test env was contaminated with several tests.

In order to confirm this, I'll collect more information and I'll attach it.

[Cory Johns (johnsca)]

Another possibility that comes to mind would be that the unit token was regenerated on the Vault side for some reason but then also didn't make it over the relation in time before k8s-master saw and tried to use the old, now invalid value.

You could check for this by seeing if there were multiple instances of "Invoking reactive handler: .*configure_secrets_backend" in the Vault charm log.

[Cory Johns (johnsca)]

I haven't been able to replicate this in my testing.

[Francesco De Simone (fdesi)]

Hi, I run into the same problem. I can provide a crashdump

[Adam Dyess (addyess)]

From the above crashdumps debug_log
https://paste.ubuntu.com/p/Xf2rtPrTNQ/

[Bas de Bruijne (basdbruijne)]

In testrun https://solutions.qa.canonical.com/testruns/testRun/05df0cb7-50b6-4afe-b25a-dc95a2029c3d, we also see this error but with different errors in the logs:

https://paste.ubuntu.com/p/CXw3BbRqHC/

Crashdumps:
https://oil-jenkins.canonical.com/artifacts/05df0cb7-50b6-4afe-b25a-dc95a2029c3d/index.html

[Konstantinos Kaskavelis (kaskavel)]

SQA team still sees this error:

unit-kubernetes-control-plane-1: 18:41:23 DEBUG unit.kubernetes-control-plane/1.juju-log vault-kv:50: vault-kv.log: Logging VaultAppKV in to http://172.31.32.44:8200
unit-kubernetes-control-plane-1: 18:41:23 WARNING unit.kubernetes-control-plane/1.vault-kv-relation-changed /var/lib/juju/agents/unit-kubernetes-control-plane-1/charm/lib/charms/layer/vault_kv.py:60: DeprecationWarning: Call to deprecated function 'auth_approle'. This method will be removed in version '0.12.0' Please use the 'login' method on the 'hvac.api.auth_methods.approle' class moving forward.
unit-kubernetes-control-plane-1: 18:41:23 WARNING unit.kubernetes-control-plane/1.vault-kv-relation-changed client.auth_approle(self._config["role_id"], self._config["secret_id"])
unit-kubernetes-control-plane-1: 18:41:23 WARNING unit.kubernetes-control-plane/1.vault-kv-relation-changed Traceback (most recent call last):
unit-kubernetes-control-plane-1: 18:41:23 WARNING unit.kubernetes-control-plane/1.vault-kv-relation-changed File "/var/lib/juju/agents/unit-kubernetes-control-plane-1/charm/hooks/vault-kv-relation-changed", line 22, in <module>
unit-kubernetes-control-plane-1: 18:41:23 WARNING unit.kubernetes-control-plane/1.vault-kv-relation-changed main()
unit-kubernetes-control-plane-1: 18:41:23 WARNING unit.kubernetes-control-plane/1.vault-kv-relation-changed File "/var/lib/juju/agents/unit-kubernetes-control-plane-1/.venv/lib/python3.10/site-packages/charms/reactive/__init__.py", line 84, in main
unit-kubernetes-control-plane-1: 18:41:23 WARNING unit.kubernetes-control-plane/1.vault-kv-relation-changed hookenv._run_atexit()
unit-kubernetes-control-plane-1: 18:41:23 WARNING unit.kubernetes-control-plane/1.vault-kv-relation-changed File "/var/lib/juju/agents/unit-kubernetes-control-plane-1/.venv/lib/python3.10/site-packages/charmhelpers/core/hookenv.py", line 1357, in _run_atexit
unit-kubernetes-control-plane-1: 18:41:23 WARNING unit.kubernetes-control-plane/1.vault-kv-relation-changed callback(*args, **kwargs)
unit-kubernetes-control-plane-1: 18:41:23 WARNING unit.kubernetes-control-plane/1.vault-kv-relation-changed File "/var/lib/juju/agents/unit-kubernetes-control-plane-1/charm/reactive/vault_kv.py", line 55, in update_app_kv_hashes
unit-kubernetes-control-plane-1: 18:41:23 WARNING unit.kubernetes-control-plane/1.vault-kv-relation-changed app_kv = vault_kv.VaultAppKV()
unit-kubernetes-control-plane-1: 18:41:23 WARNING unit.kubernetes-control-plane/1.vault-kv-relation-changed File "/var/lib/juju/agents/unit-kubernetes-control-plane-1/charm/lib/charms/layer/vault_kv.py", line 33, in __call__
unit-kubernetes-control-plane-1: 18:41:23 WARNING unit.kubernetes-control-plane/1.vault-kv-relation-changed cls._singleton_instance = super().__call__(*args, **kwargs)
unit-kubernetes-control-plane-1: 18:41:23 WARNING unit.kubernetes-control-plane/1.vault-kv-relation-changed File "/var/lib/juju/agents/unit-kubernetes-control-plane-1/charm/lib/charms/layer/vault_kv.py", line 132, in __init__
unit-kubernetes-control-plane-1: 18:41:23 WARNING unit.kubernetes-control-plane/1.vault-kv-relation-changed super().__init__()
unit-ku...