Vault can't handle properly AWS RDS postgresql multi-az failover

[zenathar]

Environment:

• Vault Version: 1.1.2
• Operating System/Architecture: centos-release-7-2.1511.el7.centos.2.10.x86_64

Vault Config File:

backend "consul" {
  address = "127.0.0.1:8500"
  path = "vault"
}

listener "tcp" {
  address = "x.x.x.x:8200"
  tls_disable = 1
}

ha_backend "consul" {
  api_addr = "http:/[[vault_dns_name]]:8200"
  cluster_addr = "http://[[vault_dns_name]]:8201"
}

cluster_name = "xxx"
ui = false

Startup Log Output:

May 28 11:26:35 [censored] systemd[1]: Started Vault.
May 28 11:26:35 [censored] systemd[1]: Starting Vault...
May 28 11:26:35 [censored] vault[2140]: ==> Vault server configuration:
May 28 11:26:35 [censored] vault[2140]: HA Storage: consul
May 28 11:26:35 [censored] vault[2140]: Api Address: http://[censored]:8200
May 28 11:26:35 [censored] vault[2140]: Cgo: disabled
May 28 11:26:35 [censored] vault[2140]: Cluster Address: https://[censored]:8201
May 28 11:26:35 [censored] vault[2140]: Listener 1: tcp (addr: "[censored]:8200", cluster address: "[censored]:8201", max_request_duration: "1m30s", max
_request_size: "33554432", tls: "disabled")
May 28 11:26:35 [censored] vault[2140]: Log Level: info
May 28 11:26:35 [censored] vault[2140]: Mlock: supported: true, enabled: true
May 28 11:26:35 [censored] vault[2140]: Storage: consul
May 28 11:26:35 [censored] vault[2140]: Version: Vault v1.1.2
May 28 11:26:35 [censored] vault[2140]: Version Sha: 0082501623c0b704b87b1fbc84c2d725994bac54
May 28 11:26:35 [censored] vault[2140]: ==> Vault server started! Log data will stream in below:
May 28 11:26:35 [censored] vault[2140]: 2019-05-28T11:26:35.921Z [WARN]  storage.consul: appending trailing forward slash to path
May 28 11:26:35 [censored] vault[2140]: 2019-05-28T11:26:35.923Z [WARN]  no `api_addr` value specified in config or in VAULT_API_ADDR; falling back to d
etection if possible, but this value should be manually set
May 28 11:27:05 [censored] vault[2140]: 2019-05-28T11:27:05.819Z [INFO]  core: vault is unsealed
May 28 11:27:05 [censored] vault[2140]: 2019-05-28T11:27:05.821Z [INFO]  core.cluster-listener: starting listener: listener_address=[censored]:8201
May 28 11:27:05 [censored] vault[2140]: 2019-05-28T11:27:05.821Z [INFO]  core.cluster-listener: serving cluster requests: cluster_listen_address=[censored]:8201
May 28 11:27:05 [censored] vault[2140]: 2019-05-28T11:27:05.821Z [INFO]  core: entering standby mode
May 28 11:27:05 [censored] vault[2140]: 2019-05-28T11:27:05.844Z [INFO]  core: acquired lock, enabling active operation
May 28 11:27:05 [censored] vault[2140]: 2019-05-28T11:27:05.890Z [INFO]  core: post-unseal setup starting
May 28 11:27:05 [censored] vault[2140]: 2019-05-28T11:27:05.892Z [INFO]  core: loaded wrapping token key
May 28 11:27:05 [censored] vault[2140]: 2019-05-28T11:27:05.892Z [INFO]  core: successfully setup plugin catalog: plugin-directory=
May 28 11:27:05 [censored] vault[2140]: 2019-05-28T11:27:05.896Z [INFO]  core: successfully mounted backend: type=kv path=secret/
May 28 11:27:05 [censored] vault[2140]: 2019-05-28T11:27:05.896Z [INFO]  core: successfully mounted backend: type=system path=sys/
May 28 11:27:05 [censored] vault[2140]: 2019-05-28T11:27:05.896Z [INFO]  core: successfully mounted backend: type=identity path=identity/
May 28 11:27:05 [censored] vault[2140]: 2019-05-28T11:27:05.896Z [INFO]  core: successfully mounted backend: type=database path=database/
May 28 11:27:05 [censored] vault[2140]: 2019-05-28T11:27:05.896Z [INFO]  core: successfully mounted backend: type=cubbyhole path=cubbyhole/
May 28 11:27:05 [censored] vault[2140]: 2019-05-28T11:27:05.911Z [INFO]  core: successfully enabled credential backend: type=token path=token/
May 28 11:27:05 [censored] vault[2140]: 2019-05-28T11:27:05.911Z [INFO]  core: successfully enabled credential backend: type=approle path=approle/
May 28 11:27:05 [censored] vault[2140]: 2019-05-28T11:27:05.911Z [INFO]  core: restoring leases
May 28 11:27:05 [censored] vault[2140]: 2019-05-28T11:27:05.911Z [INFO]  rollback: starting rollback manager
May 28 11:27:05 [censored] vault[2140]: 2019-05-28T11:27:05.918Z [INFO]  identity: entities restored
May 28 11:27:05 [censored] vault[2140]: 2019-05-28T11:27:05.920Z [INFO]  identity: groups restored
May 28 11:27:05 [censored] vault[2140]: 2019-05-28T11:27:05.922Z [INFO]  core: post-unseal setup complete
May 28 11:27:06 [censored] vault[2140]: 2019-05-28T11:27:06.067Z [INFO]  expiration: lease restore complete

Expected Behavior:
After multi-az failover on postgresql on AWS RDS vault should properly generate new credentials when requested.

Actual Behavior:
After multi-az failover vault hangs maximum amount of time (90s) on generating new credentials, then times out. Credentials are properly generated in about 5-20 minutes after failover.
Additionaly, there is no traffic seen in tcpdump for both ip adresses of AWS rds postgresql - old one (before) and new one (after failover).
Issue won't occur on AWS rds mysql

Steps to Reproduce:

1. Create aws postgresql with multi-az enabled
2. Execute following statement on newly created database:

CREATE ROLE vault_root ROLE root; GRANT ALL PRIVILEGES ON ALL TABLES IN SCHEMA public TO vault_root; GRANT ALL PRIVILEGES ON ALL SEQUENCES IN SCHEMA public TO vault_root; ALTER DEFAULT PRIVILEGES IN SCHEMA public GRANT ALL ON TABLES TO vault_root; ALTER DEFAULT PRIVILEGES IN SCHEMA public GRANT ALL ON SEQUENCES TO vault_root;'"

3. Create postgresql database config as described:

/vault read database/config/db
Key                                   Value
---                                   -----
allowed_roles                         [db_rw]
connection_details                    map[max_open_connections:4 connection_url:postgresql://root:*****@[db_url]:5432/db max_connection_lifetime:5s max_idle_connections:-1]
plugin_name                           postgresql-database-plugin
root_credentials_rotate_statements    []

4. Create postgresql database role as described:

[root@aint2vault01b vault]# ./vault read database/roles/db_rw
Key                      Value
---                      -----
creation_statements      [CREATE ROLE "{{name}}" WITH LOGIN PASSWORD '{{password}}' VALID UNTIL '{{expiration}}' IN ROLE vault_root; GRANT ALL PRIVILEGES ON ALL TABLES IN SCHEMA public TO "{{name}}"; GRANT ALL PRIVILEGES ON ALL SEQUENCES IN SCHEMA public TO "{{name}}";]
db_name                 db
default_ttl              1h
max_ttl                  800000h
renew_statements         []
revocation_statements    []
rollback_statements      []

5. Reboot AWS postgresql database - - tick "Reboot With Failover?" checkbox
6. Wait about minute-two and try to read database/creds/db_rw

Important Factoids:

References:

[melkorm]

More details on on this issue.

Steps to reproduce

Using https://gist.github.com/melkorm/25ce9f0d3840d29caa3491a47129e00f we can reproduce this by running setup-server.sh then setup-db.sh with correct hostname and password for RDS, after running this commands we can watch for credentials given by vault using watch.sh.
After this we can reboot RDS with failover in AWS console and watch vault logs.

Observations:

• It looks like none of configuration parameters can't control time when connection hits driver: bad connection error,
• vault behaves correctly if it doesn't run into driver: bad connection state

driver: bad connection logs: https://gist.github.com/melkorm/d6a46b37ba2618222a89c5476d34ab06

If you look trough logs you can find this part:

2019-10-01T15:50:03.346Z [TRACE] secrets.database.database_0f754b69.postgresql-database-plugin: create user: transport=builtin status=finished err="driver: bad connection" took=5m13.5570328s
2019-10-01T15:50:03.347Z [TRACE] secrets.database.database_0f754b69.postgresql-database-plugin: create user: transport=builtin status=finished err="context canceled" took=4m11.3820182s
2019-10-01T15:50:03.349Z [TRACE] secrets.database.database_0f754b69.postgresql-database-plugin: create user: transport=builtin status=finished err="context canceled" took=3m9.3568063s
2019-10-01T15:50:03.349Z [TRACE] secrets.database.database_0f754b69.postgresql-database-plugin: create user: transport=builtin status=finished err="context canceled" took=1m5.1224078s
2019-10-01T15:50:03.351Z [TRACE] secrets.database.database_0f754b69.postgresql-database-plugin: create user: transport=builtin status=finished err="context canceled" took=2m7.2336053s
2019-10-01T15:50:04.857Z [TRACE] secrets.database.database_0f754b69.postgresql-database-plugin: create user: transport=builtin status=finished err=<nil> took=4.5787007s

which shows that vault blocks all incoming new password requests, even if DNS points to new IP and waits for driver: bad connection to happen for X amount of minutes (already hit 10 minutes and 5 minutes).

Below are the logs when vault correctly timeouts and uses new RDS instance:

2019-10-01T15:34:58.571Z [TRACE] secrets.database.database_3c1d9906.postgresql-database-plugin: create user: transport=builtin status=finished err=<nil> took=1.4509824s
2019-10-01T15:35:04.782Z [TRACE] secrets.database.database_3c1d9906.postgresql-database-plugin: create user: transport=builtin status=started
2019-10-01T15:35:06.118Z [TRACE] secrets.database.database_3c1d9906.postgresql-database-plugin: create user: transport=builtin status=finished err=<nil> took=1.3357046s
2019-10-01T15:35:08.540Z [DEBUG] rollback: attempting rollback: path=auth/token/
2019-10-01T15:35:08.540Z [DEBUG] rollback: attempting rollback: path=secret/
2019-10-01T15:35:08.540Z [DEBUG] rollback: attempting rollback: path=sys/
2019-10-01T15:35:08.540Z [DEBUG] rollback: attempting rollback: path=cubbyhole/
2019-10-01T15:35:08.540Z [DEBUG] rollback: attempting rollback: path=identity/
2019-10-01T15:35:08.540Z [DEBUG] rollback: attempting rollback: path=database/
2019-10-01T15:35:12.304Z [TRACE] secrets.database.database_3c1d9906.postgresql-database-plugin: create user: transport=builtin status=started
2019-10-01T15:35:13.715Z [TRACE] secrets.database.database_3c1d9906.postgresql-database-plugin: create user: transport=builtin status=finished err=<nil> took=1.4107558s
2019-10-01T15:35:19.990Z [TRACE] secrets.database.database_3c1d9906.postgresql-database-plugin: create user: transport=builtin status=started
2019-10-01T15:35:21.375Z [TRACE] secrets.database.database_3c1d9906.postgresql-database-plugin: create user: transport=builtin status=finished err="read tcp 172.17.0.2:34286->10.5.8.165:5432: i/o timeout" took=1.3850439s
2019-10-01T15:35:27.494Z [TRACE] secrets.database.database_3c1d9906.postgresql-database-plugin: create user: transport=builtin status=started
2019-10-01T15:35:29.499Z [TRACE] secrets.database.database_3c1d9906.postgresql-database-plugin: create user: transport=builtin status=finished err="dial tcp 10.5.8.165:5432: i/o timeout" took=2.0057219s
2019-10-01T15:35:35.631Z [TRACE] secrets.database.database_3c1d9906.postgresql-database-plugin: create user: transport=builtin status=started
2019-10-01T15:35:37.637Z [TRACE] secrets.database.database_3c1d9906.postgresql-database-plugin: create user: transport=builtin status=finished err="dial tcp 10.5.8.165:5432: i/o timeout" took=2.0058206s
2019-10-01T15:35:43.754Z [TRACE] secrets.database.database_3c1d9906.postgresql-database-plugin: create user: transport=builtin status=started
2019-10-01T15:35:45.762Z [TRACE] secrets.database.database_3c1d9906.postgresql-database-plugin: create user: transport=builtin status=finished err="dial tcp 10.5.8.165:5432: i/o timeout" took=2.0082028s
2019-10-01T15:35:52.002Z [TRACE] secrets.database.database_3c1d9906.postgresql-database-plugin: create user: transport=builtin status=started
2019-10-01T15:35:54.006Z [TRACE] secrets.database.database_3c1d9906.postgresql-database-plugin: create user: transport=builtin status=finished err="dial tcp 10.5.8.165:5432: i/o timeout" took=2.0043805s
2019-10-01T15:36:00.248Z [TRACE] secrets.database.database_3c1d9906.postgresql-database-plugin: create user: transport=builtin status=started
2019-10-01T15:36:01.794Z [TRACE] secrets.database.database_3c1d9906.postgresql-database-plugin: create user: transport=builtin status=finished err=<nil> took=1.5458048s
2019-10-01T15:36:07.932Z [TRACE] secrets.database.database_3c1d9906.postgresql-database-plugin: create user: transport=builtin status=started
2019-10-01T15:36:08.467Z [DEBUG] rollback: attempting rollback: path=secret/
2019-10-01T15:36:08.468Z [DEBUG] rollback: attempting rollback: path=identity/
2019-10-01T15:36:08.468Z [DEBUG] rollback: attempting rollback: path=cubbyhole/
2019-10-01T15:36:08.468Z [DEBUG] rollback: attempting rollback: path=sys/
2019-10-01T15:36:08.468Z [DEBUG] rollback: attempting rollback: path=database/
2019-10-01T15:36:08.469Z [DEBUG] rollback: attempting rollback: path=auth/token/
2019-10-01T15:36:09.247Z [TRACE] secrets.database.database_3c1d9906.postgresql-database-plugin: create user: transport=builtin status=finished err=<nil> took=1.3147729s
2019-10-01T15:36:15.433Z [TRACE] secrets.database.database_3c1d9906.postgresql-database-plugin: create user: transport=builtin status=started
2019-10-01T15:36:16.892Z [TRACE] secrets.database.database_3c1d9906.postgresql-database-plugin: create user: transport=builtin status=finished err=<nil> took=1.4587123s
2019-10-01T15:36:23.059Z [TRACE] secrets.database.database_3c1d9906.postgresql-database-plugin: create user: transport=builtin status=started
2019-10-01T15:36:24.367Z [TRACE] secrets.database.database_3c1d9906.postgresql-database-plugin: create user: transport=builtin status=finished err=<nil> took=1.308189s
2019-10-01T15:36:30.502Z [TRACE] secrets.database.database_3c1d9906.postgresql-database-plugin: create user: transport=builtin status=started

I've tested it with v1.0.1 and v1.2.3 vault versions.

I will dig more into this issue and try to rebuild vault with more debug points to find exactly where timeout is not respected but it would be also nice to get more information from the team so perhaps we can resolve this faster :) Perhaps issue is in https://github.com/lib/pq or in https://github.com/golang/go itself.

PS. Also found that GO https://golang.org/src/database/sql/sql.go#L777 handles driver.ErrBadConn differently that any other error.

[tj13]

Any update about this issue

[bandesz]

lib/pq does not handle query timeouts correctly and it can hang for a long time during an AZ failover. Here is the related issue: lib/pq#450.

[melkorm]

@bandesz thanks for the link to related issue ! I've discovered this myself and wanted to create similar issue but it's great that it exists already, although after some research it looks like Vault doesn't provide credentials concurrently which causes that application is not able to recover from this error and vault is in broken state - can't serve credentials for this db.

Vault could handle it and accept new requests for credentials while old connection is broken by just allowing for new requests as connection pool can handle it, currently it's not possible, please see https://groups.google.com/forum/?utm_medium=email&utm_source=footer#!msg/vault-tool/GXK3EMW7GGM/ii5DMAFODwAJ

lib/pq#450 this issue is already 3 years old and I guess there are two issues, one related to vault and other to lib/pq.

[michelvocks]

Hi @zenathar & @melkorm!

#5731 has been merged recently which looks like a solution for this issue.
I will close this issue for now but please let me know if the issue is still present.

Cheers,
Michel

[bandesz]

@michelvocks that seems to be an unrelated issue, can you please link the correct one?

[michelvocks]

@bandesz Sorry. It was #5731.

[melkorm]

@bandesz @michelvocks Hey, can we actually reopen this as it was a mistake ?

[michelvocks]

Hi @melkorm!

Yes. Sorry for the inconvenience!

Cheers,
Michel