Vault agent does not write all messages to log file

[jcasale]

Describe the bug
When configuring the vault agent to log to a file, only some messages are written.

For example, run the agent as follows:

vault agent -config=/vault/agent.hcl -log-file=/vault/agent.log -log-level=trace

The entries with messages that begin with parenthesis are not sent to the file, only the ones with context or source names. For example, the first two lines below are written to the logfile, but not the last two lines.

2023-06-08T19:09:18.846-0600 [INFO]  agent.sink.file: token written: path=/vault/sink
2023-06-08T19:09:18.867-0600 [INFO]  agent.auth.handler: renewed auth token
2023-06-08T19:09:19.214-0600 [INFO] (runner) rendered "/vault/tmpl" => "/vault/cred"
2023-06-08T19:09:19.214-0600 [INFO] (runner) executing command "..."

To Reproduce
Steps to reproduce the behavior:

1. Run vault agent -config=/vault/agent.hcl -log-file=/vault/agent.log
2. Examine the console and log file.
3. Note the missing entries in the log file.

Expected behavior
All messages written to the console are also written to the log file.

Environment:

• Vault Server Version (retrieve with vault status): v1.13.2
• Vault CLI Version (retrieve with vault version): v1.13.2
• Server Operating System/Architecture: Windows Server 2022

[maxb]

I got involved in this when it was posted in discuss.hashicorp.com... looking into it, the root cause is that the consul-template code uses a completely different logging setup to Vault (The Go stdlib log package, instead of HashiCorp's go-hclog).

Another bug caused by this, is that if you request the agent to emit JSON logging (-log-format json) then the log lines printed from within the consul-template code are not JSON either - you end up with a fairly disasterous mixture of JSON and traditional logging:

{"@level":"info","@message":"starting template server","@module":"agent.template.server","@timestamp":"2023-06-09T22:41:40.720071+01:00"}
2023-06-09T22:41:40.720+0100 [INFO] (runner) creating new runner (dry: false, once: false)
{"@level":"info","@message":"starting auth handler","@module":"agent.auth.handler","@timestamp":"2023-06-09T22:41:40.720081+01:00"}
{"@level":"info","@message":"authenticating","@module":"agent.auth.handler","@timestamp":"2023-06-09T22:41:40.720188+01:00"}
{"@level":"info","@message":"starting sink server","@module":"agent.sink.server","@timestamp":"2023-06-09T22:41:40.720087+01:00"}
2023-06-09T22:41:40.720+0100 [INFO] (runner) creating watcher
{"@level":"info","@message":"authentication successful, sending token to sinks","@module":"agent.auth.handler","@timestamp":"2023-06-09T22:41:40.727871+01:00"}

A thorough fix to this issue would require replacing the logging system in consul-template with go-hclog too.

[VioletHynes]

Hey folks! Thanks for raising this and providing such good detail, both. As maxb points out, the issue with the logs that you're missing are specifically the ones from the consul-template dependency, the dependency that manages Agent's template subsystem at a low-level, so the logs affected are those.

I can't give an estimate for a fix, but I wanted to update this to say that I just raised an issue internally for this and it's something I'll try and encourage prioritizing. We'll update this issue when we fix it!