Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

vault.service: Reload operation timed out. Killing reload process. #15436

Closed
localhorst-org opened this issue May 16, 2022 · 1 comment
Closed

vault.service: Reload operation timed out. Killing reload process. #15436

localhorst-org opened this issue May 16, 2022 · 1 comment
Labels
bug Used to indicate a potential bug

Comments

@localhorst-org
Copy link

I came across from here https://www.vaultproject.io/docs/audit/file -> Log File Rotation (SIGHUP)

:~$ cat /etc/logrotate.d/vault
[...]
        postrotate
                if invoke-rc.d vault status > /dev/null 2>&1; then \
                    invoke-rc.d vault reload > /dev/null 2>&1; \
                fi;
        endscript
[...]

The next morning i saw

:~# systemctl status vault.service
● vault.service - "HashiCorp Vault - A tool for managing secrets"
     Loaded: loaded (/lib/systemd/system/vault.service; enabled; vendor preset: enabled)
     Active: reloading (reload) since Fri 2022-05-13 11:55:25 CEST; 2 days ago
       Docs: https://www.vaultproject.io/docs/
    Process: 2208345 ExecReload=/bin/kill --signal HUP $MAINPID (code=exited, status=0/SUCCESS)
   Main PID: 919 (vault)
      Tasks: 8 (limit: 2273)
     Memory: 155.5M
     CGroup: /system.slice/vault.service
             └─919 /usr/bin/vault server -config=/etc/vault.d/vault.hcl

May 16 11:22:47 u-ciss-auth01 systemd[1]: vault.service: Reload operation timed out. Killing reload process.
May 16 11:24:17 u-ciss-auth01 systemd[1]: vault.service: Reload operation timed out. Killing reload process.
May 16 11:25:47 u-ciss-auth01 systemd[1]: vault.service: Reload operation timed out. Killing reload process.
May 16 11:27:17 u-ciss-auth01 systemd[1]: vault.service: Reload operation timed out. Killing reload process.
May 16 11:28:47 u-ciss-auth01 systemd[1]: vault.service: Reload operation timed out. Killing reload process.
May 16 11:30:18 u-ciss-auth01 systemd[1]: vault.service: Reload operation timed out. Killing reload process.
May 16 11:31:48 u-ciss-auth01 systemd[1]: vault.service: Reload operation timed out. Killing reload process.

For furhter investigation i create a new VM from scratch. Do nothing more like this...

:~# vim /etc/apt/sources.list.d/hashicorp.list
deb [arch=amd64 signed-by=/usr/share/keyrings/hashicorp-archive-keyring.gpg] https://apt.releases.hashicorp.com focal main

:~# curl -fsSL https://apt.releases.hashicorp.com/gpg | gpg --dearmor -o /usr/share/keyrings/hashicorp-archive-keyring.gpg

:~# apt-get update
:~# apt-get install vault

:~# vim /etc/vault.d/vault.hcl
[...]
log_level = "Debug"

:~# systemctl enable vault

:~# systemctl restart vault.service

:~# vault operator init -tls-skip-verify -address=https://localhost:8200 -key-shares=1 -key-threshold=1
Unseal Key 1: QDE3nm6xOPbwgTr8OingDdYk/TtVih5qxBEvBohbWaE=
Initial Root Token: hvs.MFLjmzNVxqa1YC6EAFmMk5W0

:~# vault operator unseal -tls-skip-verify -address=https://localhost:8200

:~# pidof vault
3062

:~# systemctl status vault
● vault.service - "HashiCorp Vault - A tool for managing secrets"
     Loaded: loaded (/lib/systemd/system/vault.service; enabled; vendor preset: enabled)
     Active: active (running) since Mon 2022-05-16 11:30:28 UTC; 1min 31s ago
       Docs: https://www.vaultproject.io/docs/
   Main PID: 3062 (vault)
      Tasks: 7 (limit: 4612)
     Memory: 66.5M
     CGroup: /system.slice/vault.service
             └─3062 /usr/bin/vault server -config=/etc/vault.d/vault.hcl

Mai 16 11:31:34 devubu2004 vault[3062]: 2022-05-16T11:31:34.809Z [INFO]  identity: groups restored
Mai 16 11:31:34 devubu2004 vault[3062]: 2022-05-16T11:31:34.809Z [DEBUG] identity: identity loading OIDC clients
Mai 16 11:31:34 devubu2004 vault[3062]: 2022-05-16T11:31:34.810Z [DEBUG] core: request forwarding setup function
Mai 16 11:31:34 devubu2004 vault[3062]: 2022-05-16T11:31:34.810Z [DEBUG] core: clearing forwarding clients
Mai 16 11:31:34 devubu2004 vault[3062]: 2022-05-16T11:31:34.810Z [DEBUG] core: done clearing forwarding clients
Mai 16 11:31:34 devubu2004 vault[3062]: 2022-05-16T11:31:34.810Z [DEBUG] core: request forwarding not setup
Mai 16 11:31:34 devubu2004 vault[3062]: 2022-05-16T11:31:34.810Z [DEBUG] core: leaving request forwarding setup function
Mai 16 11:31:34 devubu2004 vault[3062]: 2022-05-16T11:31:34.811Z [INFO]  core: post-unseal setup complete
Mai 16 11:31:34 devubu2004 vault[3062]: 2022-05-16T11:31:34.811Z [INFO]  core: vault is unsealed
Mai 16 11:31:34 devubu2004 vault[3062]: 2022-05-16T11:31:34.812Z [INFO]  core: usage gauge collection is disabled

Try a Reload but this command "hang"

:~# systemctl reload vault.service

And look in the logs

:~# journalctl -f -n 50
[...]
Mai 16 11:33:35 devubu2004 systemd[1]: Reloading "HashiCorp Vault - A tool for managing secrets".
Mai 16 11:33:35 devubu2004 vault[3062]: ==> Vault reload triggered
Mai 16 11:33:35 devubu2004 vault[3062]: 2022-05-16T11:33:35.721Z [DEBUG] sent systemd notification: notification=RELOADING=1
Mai 16 11:33:35 devubu2004 vault[3062]: 2022-05-16T11:33:35.721Z [DEBUG] core: set config: sanitized config="{\"api_addr\":\"\",\"cache_size\":0,\"cluster_addr\":\"\",\"cluster_cipher_suites\":\"\",\"cluster_name\":\"\",\"default_lease_ttl\":0,\"default_max_request_duration\":0,\"disable_cache\":false,\"disable_clustering\":false,\"disable_indexing\":false,\"disable_mlock\":false,\"disable_performance_standby\":false,\"disable_printable_check\":false,\"disable_sealwrap\":false,\"disable_sentinel_trace\":false,\"enable_response_header_hostname\":false,\"enable_response_header_raft_node_id\":false,\"enable_ui\":true,\"listeners\":[{\"config\":{\"address\":\"0.0.0.0:8200\",\"tls_cert_file\":\"/opt/vault/tls/tls.crt\",\"tls_key_file\":\"/opt/vault/tls/tls.key\"},\"type\":\"tcp\"}],\"log_format\":\"\",\"log_level\":\"Debug\",\"log_requests_level\":\"\",\"max_lease_ttl\":0,\"pid_file\":\"\",\"plugin_directory\":\"\",\"raw_storage_endpoint\":false,\"storage\":{\"cluster_addr\":\"\",\"disable_clustering\":false,\"redirect_addr\":\"\",\"type\":\"file\"}}"
[...]
Mai 16 11:35:05 devubu2004 systemd[1]: vault.service: Reload operation timed out. Killing reload process.
Mai 16 11:36:36 devubu2004 systemd[1]: vault.service: Reload operation timed out. Killing reload process.
Mai 16 11:38:06 devubu2004 systemd[1]: vault.service: Reload operation timed out. Killing reload process.

:~# ps fax shows

:~# ps fax
[...]
root        2445  0.0  0.2  13788  8888 ?        Ss   11:28   0:00  \_ sshd: vagrant [priv]
vagrant     2523  0.1  0.1  13924  6196 ?        S    11:28   0:00  |   \_ sshd: vagrant@pts/0
vagrant     2524  0.0  0.1   8276  5216 pts/0    Ss   11:28   0:00  |       \_ -bash
root        2533  0.0  0.1   9256  4588 pts/0    S    11:29   0:00  |           \_ sudo su -
root        2535  0.0  0.1   8396  4368 pts/0    S    11:29   0:00  |               \_ su -
root        2536  0.0  0.1   8568  5688 pts/0    S    11:29   0:00  |                   \_ -bash
root        3258  0.0  0.0   9276  3700 pts/0    S+   11:33   0:00  |                       \_ systemctl reload vault.service
root        3259  0.0  0.1  16208  5764 pts/0    S+   11:33   0:00  |                           \_ /bin/systemd-tty-ask-password-agent --watch
[...]
vault       3062  2.1  5.0 845884 205000 ?       SLsl 11:30   0:04 /usr/bin/vault server -config=/etc/vault.d/vault.hcl

:~# systemctl status vault
● vault.service - "HashiCorp Vault - A tool for managing secrets"
     Loaded: loaded (/lib/systemd/system/vault.service; enabled; vendor preset: enabled)
     Active: reloading (reload) since Mon 2022-05-16 11:30:28 UTC; 8min ago
       Docs: https://www.vaultproject.io/docs/
    Process: 3260 ExecReload=/bin/kill --signal HUP $MAINPID (code=exited, status=0/SUCCESS)
   Main PID: 3062 (vault)
      Tasks: 7 (limit: 4612)
     Memory: 66.8M
     CGroup: /system.slice/vault.service
             └─3062 /usr/bin/vault server -config=/etc/vault.d/vault.hcl

Mai 16 11:31:34 devubu2004 vault[3062]: 2022-05-16T11:31:34.811Z [INFO]  core: post-unseal setup complete
Mai 16 11:31:34 devubu2004 vault[3062]: 2022-05-16T11:31:34.811Z [INFO]  core: vault is unsealed
Mai 16 11:31:34 devubu2004 vault[3062]: 2022-05-16T11:31:34.812Z [INFO]  core: usage gauge collection is disabled
Mai 16 11:33:35 devubu2004 systemd[1]: Reloading "HashiCorp Vault - A tool for managing secrets".
Mai 16 11:33:35 devubu2004 vault[3062]: ==> Vault reload triggered
Mai 16 11:33:35 devubu2004 vault[3062]: 2022-05-16T11:33:35.721Z [DEBUG] sent systemd notification: notification=RELOADING=1
Mai 16 11:33:35 devubu2004 vault[3062]: 2022-05-16T11:33:35.721Z [DEBUG] core: set config: sanitized config="{\"api_addr\":\"\",\"cache_size\":0,\"cluster_addr\":\"\",\"cluster_c>
Mai 16 11:35:05 devubu2004 systemd[1]: vault.service: Reload operation timed out. Killing reload process.
Mai 16 11:36:36 devubu2004 systemd[1]: vault.service: Reload operation timed out. Killing reload process.
Mai 16 11:38:06 devubu2004 systemd[1]: vault.service: Reload operation timed out. Killing reload process.

Restart and try with the kill command. The kill command hang not and ps fax shows nothing unexpected.

:~# /bin/kill --signal SIGHUP $(pidof vault)

But "timed out" appeared in the logs.

:~# journalctl -f -n 50
[...]
Mai 16 11:40:47 devubu2004 vault[3414]: ==> Vault reload triggered
Mai 16 11:40:47 devubu2004 vault[3414]: 2022-05-16T11:40:47.946Z [DEBUG] sent systemd notification: notification=RELOADING=1
Mai 16 11:40:47 devubu2004 vault[3414]: 2022-05-16T11:40:47.947Z [DEBUG] core: set config: sanitized config="{\"api_addr\":\"\",\"cache_size\":0,\"cluster_addr\":\"\",\"cluster_cipher_suites\":\"\",\"cluster_name\":\"\",\"default_lease_ttl\":0,\"default_max_request_duration\":0,\"disable_cache\":false,\"disable_clustering\":false,\"disable_indexing\":false,\"disable_mlock\":false,\"disable_performance_standby\":false,\"disable_printable_check\":false,\"disable_sealwrap\":false,\"disable_sentinel_trace\":false,\"enable_response_header_hostname\":false,\"enable_response_header_raft_node_id\":false,\"enable_ui\":true,\"listeners\":[{\"config\":{\"address\":\"0.0.0.0:8200\",\"tls_cert_file\":\"/opt/vault/tls/tls.crt\",\"tls_key_file\":\"/opt/vault/tls/tls.key\"},\"type\":\"tcp\"}],\"log_format\":\"\",\"log_level\":\"Debug\",\"log_requests_level\":\"\",\"max_lease_ttl\":0,\"pid_file\":\"\",\"plugin_directory\":\"\",\"raw_storage_endpoint\":false,\"storage\":{\"cluster_addr\":\"\",\"disable_clustering\":false,\"redirect_addr\":\"\",\"type\":\"file\"}}"
[...]
Mai 16 11:42:18 devubu2004 systemd[1]: vault.service: Reload operation timed out. Killing reload process.
Mai 16 11:43:48 devubu2004 systemd[1]: vault.service: Reload operation timed out. Killing reload process.
Mai 16 11:45:18 devubu2004 systemd[1]: vault.service: Reload operation timed out. Killing reload process.

:~# systemctl status vault
● vault.service - "HashiCorp Vault - A tool for managing secrets"
     Loaded: loaded (/lib/systemd/system/vault.service; enabled; vendor preset: enabled)
     Active: reloading (reload) since Mon 2022-05-16 11:39:34 UTC; 5min ago
       Docs: https://www.vaultproject.io/docs/
   Main PID: 3414 (vault)
      Tasks: 7 (limit: 4612)
     Memory: 58.2M
     CGroup: /system.slice/vault.service
             └─3414 /usr/bin/vault server -config=/etc/vault.d/vault.hcl

Mai 16 11:39:55 devubu2004 vault[3414]: 2022-05-16T11:39:55.273Z [DEBUG] core: leaving request forwarding setup function
Mai 16 11:39:55 devubu2004 vault[3414]: 2022-05-16T11:39:55.274Z [INFO]  core: post-unseal setup complete
Mai 16 11:39:55 devubu2004 vault[3414]: 2022-05-16T11:39:55.274Z [INFO]  core: vault is unsealed
Mai 16 11:39:55 devubu2004 vault[3414]: 2022-05-16T11:39:55.277Z [INFO]  core: usage gauge collection is disabled
Mai 16 11:40:47 devubu2004 vault[3414]: ==> Vault reload triggered
Mai 16 11:40:47 devubu2004 vault[3414]: 2022-05-16T11:40:47.946Z [DEBUG] sent systemd notification: notification=RELOADING=1
Mai 16 11:40:47 devubu2004 vault[3414]: 2022-05-16T11:40:47.947Z [DEBUG] core: set config: sanitized config="{\"api_addr\":\"\",\"cache_size\":0,\"cluster_addr\":\"\",\"cluster_c>
Mai 16 11:42:18 devubu2004 systemd[1]: vault.service: Reload operation timed out. Killing reload process.
Mai 16 11:43:48 devubu2004 systemd[1]: vault.service: Reload operation timed out. Killing reload process.
Mai 16 11:45:18 devubu2004 systemd[1]: vault.service: Reload operation timed out. Killing reload process.

Is this the expected behavior from reload vault?

Regards Horst
@hsimon-hashicorp hsimon-hashicorp added the bug Used to indicate a potential bug label May 18, 2022
@hsimon-hashicorp
Copy link
Contributor

This appears to be a duplicate of #15221, which was resolved in #15041, so I'm going to go ahead and close this issue now. Please be on the lookout for this to be included in an upcoming release! :)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Used to indicate a potential bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@localhorst-org @hsimon-hashicorp