vault debug command generates several empty lines in vault.log

[tmekaumput]

Describe the bug
When running vault debug command, then either observe the vault.log while the command is running or examine the vault.log in the archive, there are several empty lines added, noted that they were not added immediately. It also seems to grow in proportion to the runtime of the command.

To Reproduce
Steps to reproduce the behavior:

1. Run vault debug -duration=2m -interval=15s
2. Observe the vault.log in the archive

Expected behavior
The vault.log contains only log messages

Environment:

• Vault Server Version (retrieve with vault status):

root@b3c7653d03ec:/# vault status
Key                      Value
---                      -----
Recovery Seal Type       shamir
Initialized              true
Sealed                   false
Total Recovery Shares    1
Threshold                1
Version                  1.11.0+ent
Build Date               2022-06-17T22:49:59Z
Storage Type             raft
Cluster Name             vault-cluster-2b1c69d5
Cluster ID               a4d2af41-cc8e-10a4-9c83-34401c18da41
HA Enabled               true
HA Cluster               https://vault-server-0-dc1:8201
HA Mode                  active
Active Since             2022-07-06T12:45:45.641272722Z
Raft Committed Index     321
Raft Applied Index       321
Last WAL                 26

• Vault CLI Version (retrieve with vault version):

Vault v1.11.0+ent (b61eb07cb09bfd7b0cf0647a9468e94c4419ae6a), built 2022-06-17T22:49:59Z

• Server Operating System/Architecture:

Linux b3c7653d03ec 5.13.0-52-generic #59~20.04.1-Ubuntu SMP Thu Jun 16 21:21:28 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux

Vault server configuration file(s):

root@b3c7653d03ec:/# cat /vault/config/addr.hcl
api_addr = "https://vault-server-0-dc1:8200"
cluster_addr = "https://vault-server-0-dc1:8201"

root@b3c7653d03ec:/# cat /vault/config/vault.hcl
storage "raft" {
  node_id = "vault-server-0-dc1"
  path    = "/vault/data" 
  snapshot_threshold = 512
              retry_join {
              leader_api_addr = "http://vault-server-0-dc1:8202"
            }
            retry_join {
              leader_api_addr = "http://vault-server-1-dc1:8202"
            }
            retry_join {
              leader_api_addr = "http://vault-server-2-dc1:8202"
            }
}

log_requests_level = "info"

listener "tcp" {
  address = "0.0.0.0:8202"
  tls_disable = "true"
  telemetry {
    unauthenticated_metrics_access = true
  }
}

listener "tcp" {
  address = "0.0.0.0:8200"
#  tls_disable = "true"
  cluster_address = "[::]:8201"
  tls_cert_file = "/vault/config/vault-server.crt"  
  tls_key_file = "/vault/config/vault-server.key"

}

ui = "true"
log_level="debug"

telemetry {
  prometheus_retention_time = "24h"
}

Additional context

• Attached the sample archive observed, the symptom is repeatedly reproducible.

vault-debug-2022-07-06T12-47-17Z.tar.gz

• Making direct API call to sys/monitor with curl to retrieve logs and see no issue.
• Debugging into this block and see no empty log, https://github.com/hashicorp/vault/blob/v1.11.0/api/sys_monitor.go#L52-L53
• The empty lines can be filtered out by checking len(log) > 0 on this block, https://github.com/hashicorp/vault/blob/v1.11.0/command/debug.go#L1083-L1090

[heatherezell]

This was fixed by #16714, so please keep an eye out on future releases! :)