search

hashicorp / vault

A tool for secrets management, encryption as a service, and privileged access management
https://www.vaultproject.io/
Other
30.59k stars 4.14k forks source link

Disable kv-v2 store fails with "list failed at path" #12228

Open anxstj opened 2 years ago

anxstj commented 2 years ago

Describe the bug

Vault fails to disable a secret engine. The path is blocked and can not be used to mount a new engine or even create new credentials.

$ vault secrets disable my/secret
Error disabling secrets engine at my/secret/: Delete "https://vault.example.com/v1/sys/mounts/my/secret": unexpected EOF
# journalctl -u vault -f
[ERROR] core: failed to clear view for path being unmounted: error="list failed at path "76f7645a-821f-cc82-d1af-8464221bb674/versions/b5a/": Get "https://127.0.0.1:8501/v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b5a/?keys=&separator=%2F": context canceled" path=my/secret/
[ERROR] secrets.system.system_dad665bb: unmount failed: path=my/secret/ error="list failed at path "76f7645a-821f-cc82-d1af-8464221bb674/versions/b5a/": Get "https://127.0.0.1:8501/v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b5a/?keys=&separator=%2F": context canceled"

It seems that the part after versions (here b5a) changes with every try to disable the store.

Disabling the store via web UI and trying to list the secret stores results in the following message:

Attempted to handle event `pushedData` on <secret-engine:my/secret> while in state root.deleted.inFlight.

After some time the secret stores are listed again and the store my/secret is still present, but empty. Creating a new secret will result in the error message: no handler for routemy/secret/data/test-secret`.

To Reproduce

I don't know (yet)

Expected behavior

The secret store should be disabled. Or there should be an option to force the deletion of a store.

Environment:

Vault server configuration file(s):

storage "consul" {
  address = "127.0.0.1:8501"
  scheme = "https"
  tls_ca_file = "/etc/vault.d/consul.ca.pem"
  tls_cert_file = "/etc/vault.d/consul_cert.pem"
  tls_key_file = "/etc/vault.d/consul_privkey.pem"
  path = "vault/"
  service = "vault"
  token = "..."
}

listener "tcp" {
  address = "0.0.0.0:8200"
  cluster_address = "0.0.0.0:8201"
  tls_cert_file = "/etc/vault.d/vault_cert.pem"
  tls_key_file  = "/etc/vault.d/vault_privkey.pem"
  telemetry {
    unauthenticated_metrics_access = true
  }
  proxy_protocol_behavior = "allow_authorized"
  proxy_protocol_authorized_addrs = "10.61.35.192,10.61.35.191"
}

api_addr = "https://vault.example.com"
cluster_addr = "https://10.61.35.192:8201"
ui = true
log_level = "info"

default_lease_ttl = "25h"
max_lease_ttl = "768h"

Additional context Add any other context about the problem here.

ncabatoff commented 2 years ago

Hi @anxstj,

It's not letting you mount something on the old path because it hasn't been able to clean up the old data yet. Can you try increasing the client timeout, e.g.

VAULT_CLIENT_TIMEOUT=3600s vault secrets disable my/secret
anxstj commented 2 years ago

Hi @ncabatoff,

thank you for your suggestion. Unfortunately, it doesn't work.

$ time VAULT_CLIENT_TIMEOUT=3600s vault secrets disable my/secret
Error disabling secrets engine at my/secret/: Delete "https://vault.example.com/v1/sys/mounts/my/secret": unexpected EOF

real    0m30,431s
user    0m0,155s
sys     0m0,058s

And Vault still logs the ERROR message mentioned above.

ncabatoff commented 2 years ago

Can you increase log_level to trace and see what's in the logs when you try to unmount?

anxstj commented 2 years ago

It's the same.

vault[60848]: 2021-08-02T16:39:04.778Z [ERROR] core: failed to clear view for path being unmounted: error="list failed at path "76f7645a-821f-cc82-d1af-8464221bb674/versions/c41/": Get "https://127.0.0.1:8501/v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/c41/?keys=&separator=%2F": context canceled" path=my/secret/
vault[60848]: 2021-08-02T16:39:04.779Z [ERROR] secrets.system.system_dad665bb: unmount failed: path=my/secret/ error="list failed at path "76f7645a-821f-cc82-d1af-8464221bb674/versions/c41/": Get "https://127.0.0.1:8501/v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/c41/?keys=&separator=%2F": context canceled"

(trace is active. Some [TRACE] auth.approle.auth_approle_478b2c1b.tidy lines were logged, too. But not on a second run, so they were unrelated.)

ncabatoff commented 2 years ago

I'm a bit confused by the 30s duration. It feels like there's a timeout being hit somewhere, but we've already eliminated the client timeout. There's a max request duration, both global and per-listener, but you posted your config and didn't touch those. I can't think offhand of any other means by which requests get timed out.

If you retry, does it always take 30s?

Also, I agree the tidy lines are irrelevant, but is there anything else preceding the error in the logs that might give any hints? How about in the Consul logs at the same point in time?

anxstj commented 2 years ago

Yes, it's always 30s.

The vault log is empty, except for these two error lines (repeated here to match the consul log output):

vault[60848]: 2021-08-02T17:26:48.525Z [ERROR] core: failed to clear view for path being unmounted: error="list failed at path "76f7645a-821f-cc82-d1af-8464221bb674/versions/b3d/": Get "https://127.0.0.1:8501/v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b3d/?keys=&separator=%2F": context canceled" path=my/secret/
vault[60848]: 2021-08-02T17:26:48.525Z [ERROR] secrets.system.system_dad665bb: unmount failed: path=my/secret/ error="list failed at path "76f7645a-821f-cc82-d1af-8464221bb674/versions/b3d/": Get "https://127.0.0.1:8501/v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b3d/?keys=&separator=%2F": context canceled"

I increased the Consul log also to trace level and this was logged:

consul[64225]:     2021/08/02 17:26:18 [DEBUG] http: Request PUT /v1/kv/vault/core/mounts (41.450393ms) from=127.0.0.1:43232
consul[64225]: http: Request PUT /v1/kv/vault/core/mounts (41.450393ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:18 [DEBUG] http: Request GET /v1/kv/vault/sys/expire/id/my/secret/?keys=&separator=%2F (21.880437ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/sys/expire/id/my/secret/?keys=&separator=%2F (21.880437ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:18 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/?keys=&separator=%2F (89.63415ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/?keys=&separator=%2F (89.63415ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:19 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/?keys=&separator=%2F (78.205695ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/?keys=&separator=%2F (78.205695ms) from=127.0.0.1:43232
...
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b71/?keys=&separator=%2F (22.415903ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:47 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b70/?keys=&separator=%2F (22.863676ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b70/?keys=&separator=%2F (22.863676ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:47 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b6f/?keys=&separator=%2F (23.392751ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b6f/?keys=&separator=%2F (23.392751ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:47 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b6e/?keys=&separator=%2F (23.372082ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b6e/?keys=&separator=%2F (23.372082ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:47 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b6d/?keys=&separator=%2F (22.519052ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b6d/?keys=&separator=%2F (22.519052ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:47 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b6c/?keys=&separator=%2F (22.551567ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b6c/?keys=&separator=%2F (22.551567ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:47 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b6b/?keys=&separator=%2F (22.493262ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b6b/?keys=&separator=%2F (22.493262ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:47 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b6a/?keys=&separator=%2F (36.5868ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b6a/?keys=&separator=%2F (36.5868ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:47 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b69/?keys=&separator=%2F (22.726204ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b69/?keys=&separator=%2F (22.726204ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:47 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b68/?keys=&separator=%2F (23.340354ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b68/?keys=&separator=%2F (23.340354ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:47 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b67/?keys=&separator=%2F (22.356355ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b67/?keys=&separator=%2F (22.356355ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:47 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b66/?keys=&separator=%2F (22.334276ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b66/?keys=&separator=%2F (22.334276ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:47 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b65/?keys=&separator=%2F (22.333859ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b65/?keys=&separator=%2F (22.333859ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:47 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b64/?keys=&separator=%2F (22.097441ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b64/?keys=&separator=%2F (22.097441ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:47 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b63/?keys=&separator=%2F (22.113477ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b63/?keys=&separator=%2F (22.113477ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:47 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b62/?keys=&separator=%2F (22.401425ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b62/?keys=&separator=%2F (22.401425ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:47 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b61/?keys=&separator=%2F (22.099971ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b61/?keys=&separator=%2F (22.099971ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:47 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b60/?keys=&separator=%2F (22.280024ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b60/?keys=&separator=%2F (22.280024ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:47 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b5f/?keys=&separator=%2F (22.460992ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b5f/?keys=&separator=%2F (22.460992ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:47 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b5e/?keys=&separator=%2F (22.424549ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b5e/?keys=&separator=%2F (22.424549ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:47 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b5d/?keys=&separator=%2F (22.294534ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b5d/?keys=&separator=%2F (22.294534ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:47 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b5c/?keys=&separator=%2F (22.362118ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b5c/?keys=&separator=%2F (22.362118ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:47 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b5b/?keys=&separator=%2F (22.196448ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b5b/?keys=&separator=%2F (22.196448ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:47 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b5a/?keys=&separator=%2F (22.339119ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b5a/?keys=&separator=%2F (22.339119ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:47 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b59/?keys=&separator=%2F (22.516296ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b59/?keys=&separator=%2F (22.516296ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:47 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b58/?keys=&separator=%2F (22.333042ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b58/?keys=&separator=%2F (22.333042ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:47 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b57/?keys=&separator=%2F (22.318204ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b57/?keys=&separator=%2F (22.318204ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:47 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b56/?keys=&separator=%2F (22.503882ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b56/?keys=&separator=%2F (22.503882ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:47 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b55/?keys=&separator=%2F (22.627274ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b55/?keys=&separator=%2F (22.627274ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:47 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b54/?keys=&separator=%2F (22.255823ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b54/?keys=&separator=%2F (22.255823ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:47 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b53/?keys=&separator=%2F (22.60835ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b53/?keys=&separator=%2F (22.60835ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:48 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b52/?keys=&separator=%2F (22.253494ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b52/?keys=&separator=%2F (22.253494ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:48 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b51/?keys=&separator=%2F (22.392074ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b51/?keys=&separator=%2F (22.392074ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:48 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b50/?keys=&separator=%2F (22.452219ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b50/?keys=&separator=%2F (22.452219ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:48 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b4f/?keys=&separator=%2F (22.630215ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b4f/?keys=&separator=%2F (22.630215ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:48 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b4e/?keys=&separator=%2F (22.514242ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b4e/?keys=&separator=%2F (22.514242ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:48 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b4d/?keys=&separator=%2F (22.277551ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b4d/?keys=&separator=%2F (22.277551ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:48 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b4c/?keys=&separator=%2F (22.341572ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b4c/?keys=&separator=%2F (22.341572ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:48 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b4b/?keys=&separator=%2F (22.35797ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b4b/?keys=&separator=%2F (22.35797ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:48 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b4a/?keys=&separator=%2F (22.378175ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b4a/?keys=&separator=%2F (22.378175ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:48 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b49/?keys=&separator=%2F (22.589079ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b49/?keys=&separator=%2F (22.589079ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:48 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b48/?keys=&separator=%2F (22.255833ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b48/?keys=&separator=%2F (22.255833ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:48 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b47/?keys=&separator=%2F (22.441137ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b47/?keys=&separator=%2F (22.441137ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:48 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b46/?keys=&separator=%2F (22.603531ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b46/?keys=&separator=%2F (22.603531ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:48 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b45/?keys=&separator=%2F (24.59822ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b45/?keys=&separator=%2F (24.59822ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:48 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b44/?keys=&separator=%2F (22.614185ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b44/?keys=&separator=%2F (22.614185ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:48 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b43/?keys=&separator=%2F (22.811088ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b43/?keys=&separator=%2F (22.811088ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:48 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b42/?keys=&separator=%2F (22.45612ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b42/?keys=&separator=%2F (22.45612ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:48 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b41/?keys=&separator=%2F (22.597072ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b41/?keys=&separator=%2F (22.597072ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:48 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b40/?keys=&separator=%2F (43.573971ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b40/?keys=&separator=%2F (43.573971ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:48 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b3f/?keys=&separator=%2F (22.475438ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b3f/?keys=&separator=%2F (22.475438ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:48 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b3e/?keys=&separator=%2F (22.672865ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b3e/?keys=&separator=%2F (22.672865ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:48 [DEBUG] http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b3d/?keys=&separator=%2F (22.203733ms) from=127.0.0.1:43232
consul[64225]: http: Request GET /v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/b3d/?keys=&separator=%2F (22.203733ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:49 [DEBUG] http: Request PUT /v1/session/renew/707e9f5d-308d-bf21-58b2-78c0009aff6e (22.505888ms) from=127.0.0.1:43232
consul[64225]: http: Request PUT /v1/session/renew/707e9f5d-308d-bf21-58b2-78c0009aff6e (22.505888ms) from=127.0.0.1:43232
consul[64225]:     2021/08/02 17:26:49 [DEBUG] agent: Check "vault::443:vault-sealed-check" status is now passing
consul[64225]: agent: Check "vault::443:vault-sealed-check" status is now passing
consul[64225]:     2021/08/02 17:26:49 [DEBUG] agent: Service "vault::443" in sync
consul[64225]:     2021/08/02 17:26:49 [DEBUG] agent: Check "vault::443:vault-sealed-check" in sync
consul[64225]:     2021/08/02 17:26:49 [DEBUG] agent: Node info in sync
consul[64225]:     2021/08/02 17:26:49 [DEBUG] http: Request PUT /v1/agent/check/pass/vault::443:vault-sealed-check?note=Vault+Unsealed (687.256µs) from=127.0.0.1:43252
consul[64225]: agent: Service "vault::443" in sync
consul[64225]: agent: Check "vault::443:vault-sealed-check" in sync
consul[64225]: agent: Node info in sync
consul[64225]: http: Request PUT /v1/agent/check/pass/vault::443:vault-sealed-check?note=Vault+Unsealed (687.256µs) from=127.0.0.1:43252

consul[64225]:     2021/08/02 17:26:52 [DEBUG] http: Request PUT /v1/kv/vault/sys/counters/requests/2021/08 (44.584318ms) from=127.0.0.1:43232
consul[64225]: http: Request PUT /v1/kv/vault/sys/counters/requests/2021/08 (44.584318ms) from=127.0.0.1:43232

consul[64225]:     2021/08/02 17:26:54 [DEBUG] agent: Check "vault::443:vault-sealed-check" status is now passing
consul[64225]:     2021/08/02 17:26:54 [DEBUG] agent: Service "vault::443" in sync
consul[64225]:     2021/08/02 17:26:54 [DEBUG] agent: Check "vault::443:vault-sealed-check" in sync
consul[64225]:     2021/08/02 17:26:54 [DEBUG] agent: Node info in sync
consul[64225]:     2021/08/02 17:26:54 [DEBUG] http: Request PUT /v1/agent/check/pass/vault::443:vault-sealed-check?note=Vault+Unsealed (593.373µs) from=127.0.0.1:43252
consul[64225]: agent: Check "vault::443:vault-sealed-check" status is now passing
consul[64225]: agent: Service "vault::443" in sync
consul[64225]: agent: Check "vault::443:vault-sealed-check" in sync
consul[64225]: agent: Node info in sync
consul[64225]: http: Request PUT /v1/agent/check/pass/vault::443:vault-sealed-check?note=Vault+Unsealed (593.373µs) from=127.0.0.1:43252
anxstj commented 2 years ago

The 30s timeout was caused by a load balancer (haproxy) in front of Vault. Increasing the client/server timeout to 300s results now in the following error:

$ time VAULT_CLIENT_TIMEOUT=3600s vault secrets disable my/secret
Error disabling secrets engine at my/secret/: Error making API request.

URL: DELETE https://vault.example.com/v1/sys/mounts/my/secret
Code: 400. Errors:

* list failed at path "76f7645a-821f-cc82-d1af-8464221bb674/versions/426/": Get "https://127.0.0.1:8501/v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/versions/426/?keys=&separator=%2F": context canceled

real    1m31,050s
user    0m0,214s
sys     0m0,148s

Vault is still reporting the same error as mentioned above.

ncabatoff commented 2 years ago

Ok, so now it looks like you're hitting the max request duration server-side timeout, which defaults to 90s. Can you try increasing that?

anxstj commented 2 years ago

Thanks, that did the trick. I increased the default_max_request_duration to 3600s.

time VAULT_CLIENT_TIMEOUT=3600s vault secrets disable my/secret
Error disabling secrets engine at my/secret/: context deadline exceeded

real    60m0,622s
user    0m0,942s
sys     0m0,678
vault[43759]: 2021-08-03T12:43:01.389Z [INFO]  secrets.kv.kv_bef5e39d: collecting keys to upgrade
vault[43759]: 2021-08-03T12:59:35.794Z [INFO]  secrets.kv.kv_bef5e39d: done collecting keys: num_keys=78511
vault[43759]: 2021-08-03T12:59:35.794Z [DEBUG] secrets.kv.kv_bef5e39d: upgrading keys: progress=0/78511
vault[43759]: 2021-08-03T12:59:35.794Z [DEBUG] secrets.kv.kv_bef5e39d: upgrading keys: progress=500/78511
...
vault[43759]: 2021-08-03T12:59:35.801Z [INFO]  secrets.kv.kv_bef5e39d: upgrading keys finished
vault[43759]: 2021-08-03T13:00:03.959Z [DEBUG] core.secrets.deletion: clearing view: namespace=root path=my/secret/ total_keys=78511
vault[43759]: 2021-08-03T13:00:37.652Z [TRACE] core.secrets.deletion: view deletion progress: namespace=root path=my/secret/ percent=1 keys_deleted=786
...
vault[43759]: 2021-08-03T13:43:27.823Z [TRACE] core.secrets.deletion: view deletion progress: namespace=root path=my/secret/ percent=75 keys_deleted=58884
vault[43759]: 2021-08-03T13:43:41.094Z [ERROR] core: failed to clear view for path being unmounted: error="Delete "https://127.0.0.1:8501/v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/metadata/p0CS6AIpT3uUqlsBijMdg3O1zEcLaBtzikP3aNAAJih1yW6bYGwF48mAZ0bRCBXfnWZ/8RGQGs4pfPrGimakx39uHasH9F4bS19L59CcqdOZLNhRALN89kqD3ZotDPXZuVElnTvROu2XAgujYS/8RH8uAEf3yePNGerfwbYQW2rMAeIPlWF9A6Akak37eiQUJPJYW2N61N6iZLzFfdnxcioHCJCGL026h/18yeoDhel8ZoIQv9AWAav2tRDYrFcbu3nsmpBU8NINBDdRPRsrwroXgXs/5kKUFZT8AJOuO3kvIdgID3WzBjXmKi4uoD50MbUCjbSBvG2MzIxYgWW7QbxN2l": context canceled" path=my/secret/
vault[43759]: 2021-08-03T13:43:41.094Z [ERROR] secrets.system.system_dad665bb: unmount failed: path=my/secret/ error="Delete "https://127.0.0.1:8501/v1/kv/vault/logical/42cf8daf-6e1f-3ff9-a74e-f9c62e30479a/76f7645a-821f-cc82-d1af-8464221bb674/metadata/p0CS6AIpT3uUqlsBijMdg3O1zEcLaBtzikP3aNAAJih1yW6bYGwF48mAZ0bRCBXfnWZ/8RGQGs4pfPrGimakx39uHasH9F4bS19L59CcqdOZLNhRALN89kqD3ZotDPXZuVElnTvROu2XAgujYS/8RH8uAEf3yePNGerfwbYQW2rMAeIPlWF9A6Akak37eiQUJPJYW2N61N6iZLzFfdnxcioHCJCGL026h/18yeoDhel8ZoIQv9AWAav2tRDYrFcbu3nsmpBU8NINBDdRPRsrwroXgXs/5kKUFZT8AJOuO3kvIdgID3WzBjXmKi4uoD50MbUCjbSBvG2MzIxYgWW7QbxN2l": context canceled"

The timeout was reached again, but the second try finished the deletion:

$ time VAULT_CLIENT_TIMEOUT=3600s vault secrets disable my/secret
Success! Disabled the secrets engine (if it existed) at: my/secret/

real    20m42,062s
user    0m0,563s
sys     0m0,276s
vault[43759]: 2021-08-03T13:53:57.788Z [DEBUG] core.secrets.deletion: clearing view: namespace=root path=my/secret/ total_keys=19363
vault[43759]: 2021-08-03T13:54:05.252Z [TRACE] core.secrets.deletion: view deletion progress: namespace=root path=my/secret/ percent=1 keys_deleted=194
...
vault[43759]: 2021-08-03T14:07:14.550Z [TRACE] core.secrets.deletion: view deletion progress: namespace=root path=my/secret/ percent=99 keys_deleted=19170
vault[43759]: 2021-08-03T14:07:22.220Z [DEBUG] core.secrets.deletion: view cleared: namespace=root path=my/secret/
vault[43759]: 2021-08-03T14:07:22.263Z [INFO]  core: successfully unmounted: path=my/secret/ namespace=""
anxstj commented 2 years ago

This was quite hard to debug. I missed the information that a timeout was reached and the delete process was therefore canceled. The ERROR message wasn't of much help, either. From a user perspective, an improved error message would be helpful.

The whole operation took around 80 minutes for approx. 80,000 keys (~1000/min). Which is much more than the default max request duration of 1,5 minutes (1500 keys). Are we using an unusual large store or are the defaults extra sensitive?

anxstj commented 2 years ago

And another problem is that the store will be unusable if the deletion aborts. In that case, all credentials are gone, the store seems to be empty but the keys are still present in the database (consul). For the user, it's not visible that there is a pending deletion.

ncabatoff commented 2 years ago

Agreed on both counts. I'm going to leave this issue open to address those usability issues. Thanks @anxstj!

aphorise commented 1 year ago

@ncabatoff are there improvements still pending here or were some related changes already made in later 1.8.x+ versions?

Hey @anxstj have you how relevant is this request still and have you rested this in any of the latest (1.11.3) versions?

anxstj commented 1 year ago

@aphorise the issue was left open for two problems: 1) There's no error message that mentions that the deletion was canceled due to a timeout. 2) The half-disabled store is still visible, but empty. And there's no error message that indicates that a deletion process was aborted.

From my point of view, both issues are still not solved.

I retested with Vault 1.11.4, but with filesystem as storage backend. I mounted a kvv2 engine and created approx 68000 key/value pairs in it. Then I disabled the whole engine. That process took approx. 36 seconds which was much faster than before (but this was tested with one node and local filesystem; the original issue used a remote consul backend as storage, so not comparable). I had to set default_max_request_duration = "20s" to trigger the error condition.

I executed:

time VAULT_CLIENT_TIMEOUT=3600s vault secrets disable my/secret
Error disabling secrets engine at my/secret/: Error making API request.

URL: DELETE https://127.0.0.1:8200/v1/sys/mounts/my/secret
Code: 400. Errors:

* context canceled

Then I executed:

vault kv put my/secret/test test=test
Error writing data to my/secret/data/test: Error making API request.

URL: PUT https://127.0.0.1:8200/v1/my/secret/data/test
Code: 404. Errors:

* no handler for route "my/secret/data/test". route entry is tainted

Vault logged:

[ERROR] core: failed to clear view for path being unmounted: error="context canceled" path=my/secret/
[ERROR] secrets.system.system_47ace526: unmount failed: path=my/secret/ error="context canceled"
ddimasik commented 1 month ago

I've got the same issue with vault-benchmark, but with disabling auth approle, here is output

2024-06-14T16:19:28.659+0300 [INFO]  vault-benchmark: cleaning up targets
2024-06-14T16:19:28.659+0300 [DEBUG] vault-benchmark: cleaning up: target=approle_logins
2024-06-14T16:19:28.660+0300 [DEBUG] vault-benchmark: cleaning up: target=static_secret_writes
2024-06-14T16:20:28.662+0300 [ERROR] vault-benchmark: error cleaning up: target=approle_logins error="error cleaning up mount: context deadline exceeded"
2024-06-14T16:20:28.662+0300 [INFO]  vault-benchmark: benchmark complete
Target: https://vault.lamoda.tech
op                    count  rate       throughput  mean          95th%         99th%         successRatio
approle_logins        1413   47.091727  46.937733   114.737998ms  237.520192ms  333.84169ms   100.00%
static_secret_writes  1466   48.946184  48.746715   94.461562ms   168.07251ms   246.810527ms  100.00%

here is error in Vault log 2024-06-14T13:21:28.004Z [ERROR] secrets.system.system_58ad97cd: disable auth mount failed: path=646d79ca-a850-3d30-38bd-ea94e447746d/ error="list failed at path \"\": context canceled" 2024-06-14T13:21:28.004Z [ERROR] core: failed to clear view for path being unmounted: error="list failed at path \"\": context canceled" path=auth/646d79ca-a850-3d30-38bd-ea94e447746d/

meanwhile if I try to disable it via CLI it mostly wokrs:

vault auth disable 646d79ca-a850-3d30-38bd-ea94e447746d     
Success! Disabled the auth method (if it existed) at: 646d79ca-a850-3d30-38bd-ea94e447746d/

But even via CLI one time I got 504 error from Vault

It's not timeout issue, I set 300s timeout on load-balancer and max_request_duration = "300s" on Vault itself 

vault status
Key                     Value
---                     -----
Seal Type               shamir
Initialized             true
Sealed                  false
Total Shares            1
Threshold               1
Version                 1.16.2
Build Date              2024-04-22T16:25:54Z
Storage Type            raft
Cluster Name            vault-cluster-eb1d5857
Cluster ID              ebb01d5e-93aa-d8b9-5cdb-afaffd6288dd
HA Enabled              true
HA Cluster              https://10.199.6.31:8201
HA Mode                 active
Active Since            2024-06-10T21:45:04.978431004Z
Raft Committed Index    252472
Raft Applied Index      252472

Any ideas?