Vault 0.10.0 is flooding Consul backend with GET /v1/kv/vault/sys/token/parent/xxxxxxx/?keys=&separator=%2F requests (3K RPS) #4462

burdandrei · 2018-04-26T10:14:53Z

Environment:

Vault Version:
Vault v0.10.0 ('5dd7f25f5c4b541f2da62d70075b6f82771a650d')
Operating System/Architecture:

# cat /etc/lsb-release 
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=16.04
DISTRIB_CODENAME=xenial
DISTRIB_DESCRIPTION="Ubuntu 16.04.4 LTS"

Vault Config File:

# cat /etc/vault.d/server.hcl 
backend "consul" {
  address = "127.0.0.1:8500"
  path = "vault"
  token = "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxx"
}

listener "tcp" {
 address = "0.0.0.0:8200"
 tls_cert_file = "/etc/ssl/private/xxxxx.combined.crt"
 tls_key_file = "/etc/ssl/private/xxxxxx.key"
}

Expected Behavior:
Not flood the backend

Actual Behavior:
Vault is sending thousands of requests to backend causing both vault and consul to have very high CPU

consul monitor with debug level output:

2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/1a8ae3xxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (37.763µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/1af47fxxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (28.368µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/1b8abdxxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (41.889µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/1c1d1exxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (32.827µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/1d10cfxxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (26.997µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/1d178exxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (38.659µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/1dd805xxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (42.961µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/1ecbf7xxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (41.245µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/201182xxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (43.963µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/23cb25xxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (62.26µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/23e29dxxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (60.271µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/23ea12xxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (34.86µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/25145fxxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (32.21µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/25d5bexxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (44.667µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/26128bxxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (33.14µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/284dc5xxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (32.819µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/29551axxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (33.316µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/2a5c7dxxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (43.663µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/2aca69xxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (36.481µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/2ad77dxxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (38.065µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/2b2c17xxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (35.969µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/2c032dxxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (55.004µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/2e638dxxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (51.249µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/31b10bxxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (45.898µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/321bf9xxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (34.412µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/33f218xxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (34.276µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/352810xxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (36.187µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/371addxxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (35.249µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/373848xxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (43.203µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/37fc4bxxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (37.36µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/3817a3xxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (38.125µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/38fe22xxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (34.843µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/39c910xxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (35.969µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/3a5d42xxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (32.385µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/3adf2cxxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (35.231µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/3b4840xxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (33.102µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/3bedbbxxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (48.471µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/3cbfd7xxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (32.316µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/3cd1f5xxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (32.667µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/3d9136xxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (33.068µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/3da299xxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (37.835µs) from=127.0.0.1:59111
2018/04/26 10:04:53 [DEBUG] http: Request GET /v1/kv/vault/sys/token/parent/3e1e44xxxxxxxxyyyyyyyzzzzzzzzz/?keys=&separator=%2F (36.032µs) from=127.0.0.1:59111

Steps to Reproduce:
update to 0.10.0

The text was updated successfully, but these errors were encountered:

jefferai · 2018-04-26T12:10:25Z

I think this is due to a previous error fixed by 0.10 in #4193. Can you try running auth/token/tidy on 0.10?

burdandrei · 2018-04-26T12:29:49Z

@jefferai could you please elaborate what I should do?

jefferai · 2018-04-26T14:21:01Z

Yep, run this: https://www.vaultproject.io/api/auth/token/index.html#tidy-tokens

From a Vault CLI you could do vault write -f auth/token/tidy. Be aware that this may also cause a good amount of I/O as it examines state and tries to clean things up.

burdandrei · 2018-04-26T18:46:22Z

Thanks! Next working day for me is Sunday, so I'll do it then.

jefferai · 2018-04-26T20:37:47Z

Question for you: do you issue a lot of child tokens (and potentially have them then issue a lot of child tokens)? We think what's happening is that you have one parent token with a huge subtree underneath it of tokens that then need to be revoked because of the parent token being revoked. We found a place where we're not being super efficient at revocation time, which can halve the number of GET requests that are made (see #4465) but it will only make things better...the root cause is still the question, and it seems like you just have a huge token hierarchy that is being revoked.

burdandrei · 2018-04-26T20:40:43Z

Sure I do!
I got nomad server, who is issuing all the tokens for thousands of allocations.
Means every time I flip Nomad server, Vault needs to revoke all the tokens and leases that were issued by this server. Right?

jefferai · 2018-04-26T21:41:07Z

If those are not orphan tokens, you are correct. We recommend issuing orphan tokens for this exact reason. So likely all of these requests are because of Vault chewing through all of the revocations. If you want to build from source you can try pulling in #4465 which will remove the need for some requests and help a bit.

burdandrei · 2018-04-26T21:44:41Z

Thanks, I'll check how to make nomad issue orphaned tokens for jobs

jefferai · 2018-04-26T21:46:47Z

See https://www.nomadproject.io/docs/vault-integration/index.html for a detailed guide.

burdandrei · 2018-04-29T11:50:00Z

I ran the command you provided @jefferai, but unfortunately, I think there is a bug, cause Vault/Consul is on high CPU for more than 48 hours already.
After I ran consul monitor --log-level=debug > log and then sorted unique the file, I can see that vault is trying to reach the same keys in Consul over and over again:

$ cat xx | sort | uniq  -c
    130 /v1/kv/vault/sys/token/parent/0046c3fc52fc23fd78180199d51063ed25836c77/?keys=&separator=%2F
    130 /v1/kv/vault/sys/token/parent/0119884cf93442dd8006479c563a0365868574f5/?keys=&separator=%2F
    130 /v1/kv/vault/sys/token/parent/01392e2b2b2b58b83f3cf21b3c09265a4369bca0/?keys=&separator=%2F
    130 /v1/kv/vault/sys/token/parent/0353e5ced1a12872a674000892d88842b2768bbb/?keys=&separator=%2F
    130 /v1/kv/vault/sys/token/parent/048721c90ebf037378b1d8b6e04b651a56d59d62/?keys=&separator=%2F
    130 /v1/kv/vault/sys/token/parent/059c1945a65f6f10a2cbbfee73f1c4c79f259e6c/?keys=&separator=%2F
    130 /v1/kv/vault/sys/token/parent/05b1dff4a7748c0f0def4dc182f2b890b0347b76/?keys=&separator=%2F
    130 /v1/kv/vault/sys/token/parent/05b3336a0f88634c8ab383ed63c34f6f0fa0d92d/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/0632bdce6040b42fd4fcba73e30f7043ac36cc28/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/06f230565997be444740da97c019947f414c648d/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/09693b0cd776b9e15f1a816d1e1b808053611ca2/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/09b7725805c149cc920df3efbe39e9d8fc14161d/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/09b77634223b9a677acd16e8ff541a2630602458/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/0a43c5178ab26b35ccb669b53883dd5195177580/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/0b0ee8a8a64aa4b8166236fbe8147078e5f5623a/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/0b2c0a9c4cec8b334e4023e7d5b4fc9fb78662d8/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/0bd4a41488cae756b40dba6d9bc0e618bd164133/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/0cf3ef2beddeb5c4149fd7c331293f9a8dc34be9/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/0f8715e6a6f52f523e68442598cfaff8a4c55131/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/0ff9d841e68c9a7152ac7d67847562a84a562a5b/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/1146f91f7ede834940f8322ef2510681d13dabe9/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/121800c9e3e6802167e5ac8acf744fd0e4e49789/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/12cf4f3e7a09f4e6f372f89c1a47b42067cbb779/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/1584b57dc210a1a2f5291ffe104446f0ce8895a4/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/15e77cb8e524a6c7131e0a719b8b16a359f59b5b/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/16236db3c204c97e1e5b15be35812bf3cc580af3/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/18774a6ef833f8bbf914f05ad56efe04892b2a57/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/1a8ae3e6dc9895ef7719a946d5299ee1df087d97/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/1af47fdc77742f163887f3d39b995fd2f510790e/?keys=&separator=%2F
    130 /v1/kv/vault/sys/token/parent/1b82d2f6c843b5d23f0b84d032a47f5eb0e72df8/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/1b8abdae9009a5fe0bab7f034e62526c909da949/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/1c1d1e566933757a224723c4d1b455a58bc6b274/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/1d10cf7e5d697e7e6b4c1a2957b57d9e9fba05ab/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/1d178e1e5dad39a6b56b24d9747ff4df9b17e268/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/1dd80502ccc0b495f1da0aa51e32af07a1ef1120/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/1ecbf7f11f245cc4f8c24a29f59a326fd8295e7e/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/201182aa3d340a903eb2dcbc9e2d6ce018e2f670/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/23cb252ff0ac5722e5e581c50e7a50022b7283a7/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/23e29dc4d4b45b1541b344d947d0b2a4ce350e05/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/23ea121097507058766e95ece245d1c4793df6ba/?keys=&separator=%2F
    129 /v1/kv/vault/sys/token/parent/25145fd67a2b17113325d52d78a18ab7db5c55e7/?keys=&separator=%2F

any hints?

jefferai · 2018-04-29T12:09:20Z

I think it's likely the same issue as #4143, can you subscribe to that one?

burdandrei · 2018-04-29T18:58:05Z

looks like the same. I think it's better to close it as duplicate

jefferai · 2018-04-29T20:09:21Z

Will do.

Duplicate of #4143

jefferai mentioned this issue Apr 26, 2018

Strange token with negative TTL blocking Vault shutdown #4143

Closed

jefferai added this to the 0.10.2 milestone Apr 26, 2018

jefferai closed this as completed Apr 29, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Vault 0.10.0 is flooding Consul backend with GET /v1/kv/vault/sys/token/parent/xxxxxxx/?keys=&separator=%2F requests (3K RPS) #4462

Vault 0.10.0 is flooding Consul backend with GET /v1/kv/vault/sys/token/parent/xxxxxxx/?keys=&separator=%2F requests (3K RPS) #4462

burdandrei commented Apr 26, 2018

jefferai commented Apr 26, 2018 •

edited

Loading

burdandrei commented Apr 26, 2018

jefferai commented Apr 26, 2018

burdandrei commented Apr 26, 2018

jefferai commented Apr 26, 2018

burdandrei commented Apr 26, 2018

jefferai commented Apr 26, 2018

burdandrei commented Apr 26, 2018

jefferai commented Apr 26, 2018

burdandrei commented Apr 29, 2018

jefferai commented Apr 29, 2018

burdandrei commented Apr 29, 2018

jefferai commented Apr 29, 2018

Vault 0.10.0 is flooding Consul backend with GET /v1/kv/vault/sys/token/parent/xxxxxxx/?keys=&separator=%2F requests (3K RPS) #4462

Vault 0.10.0 is flooding Consul backend with GET /v1/kv/vault/sys/token/parent/xxxxxxx/?keys=&separator=%2F requests (3K RPS) #4462

Comments

burdandrei commented Apr 26, 2018

jefferai commented Apr 26, 2018 • edited Loading

burdandrei commented Apr 26, 2018

jefferai commented Apr 26, 2018

burdandrei commented Apr 26, 2018

jefferai commented Apr 26, 2018

burdandrei commented Apr 26, 2018

jefferai commented Apr 26, 2018

burdandrei commented Apr 26, 2018

jefferai commented Apr 26, 2018

burdandrei commented Apr 29, 2018

jefferai commented Apr 29, 2018

burdandrei commented Apr 29, 2018

jefferai commented Apr 29, 2018

jefferai commented Apr 26, 2018 •

edited

Loading