Fix non-JSON log messages when using -log-format JSON

[peteski22]

The intention of this PR is that log entries generated by the consul-template library used by Vault Agent will now be in a format consistent with the supplied configuration.

Fixes: #21109

Steps to manually test:

1. Build Vault from PR/branch (make dev)
2. Run Vault in dev mode:

vault server -dev -dev-root-token-id="root"

3. Open another terminal window and set environment variables from $HOME directory (cd $HOME)

export VAULT_ADDR='http://127.0.0.1:8200'
export VAULT_TOKEN='root'

4. Create sample data file in $HOME directory

tee data.json -<<EOF
{
   "organization": "ACME Inc.",
   "customer_id": "ABXX2398YZPIE7391",
   "region": "US-West",
   "zip_code": "94105",
   "type": "premium",
   "contact_email": "james@acme.com",
   "status": "active"
}
EOF

5. Write sample data to Vault:

vault kv put secret/customers/acme @data.json

6. Create Agent template

tee template.ctmpl -<<EOF
{{- with secret "secret/customers/acme"}}{"secret": "other",
{{- if .Data.data.region}}"region":"{{ .Data.data.region}}",{{- end }}
{{- if .Data.data.contact_email }}"contact_email":"{{ .Data.data.contact_email }}"{{- end }}}
{{- end }}
EOF

7. Create Agent configuration

tee agent-config.hcl -<<EOF
pid_file = "./pidfile"

vault {
   address = "http://127.0.0.1:8200"
   tls_skip_verify = true
}

auto_auth {
   method {
      type = "token_file"
      config = {
         token_file_path = "$HOME/.vault-token"
      }
   }
   sink "file" {
      config = {
            path = "$HOME/vault-token-via-agent"
      }
   }
}

template_config {
  exit_on_retry_failure = false
  static_secret_render_interval = 10
}

template {
  source      = "$HOME/template.ctmpl"
  destination = "$HOME/template-render.txt"
}
EOF

8. Start Agent:

vault agent -config=agent-config.hcl -log-file="$HOME/agent.log" -log-format=json -log-level=trace`

9. Check the logs (after 10, 20, 30s), they will be named with a timestamp suffix. e.g.

The output should be entirely JSON, so you can pipe it through jq.

cat agent-1701091968647204000.log | jq

Example content:

{
  "@level": "info",
  "@message": "(runner) rendered \"/Users/juan/template.ctmpl\" => \"/Users/juantemplate-render.txt\"",
  "@module": "agent",
  "@timestamp": "2023-11-27T17:06:20.653631Z"
}
{
  "@level": "debug",
  "@message": "(runner) diffing and updating dependencies",
  "@module": "agent",
  "@timestamp": "2023-11-27T17:06:20.653649Z"
}
{
  "@level": "debug",
  "@message": "(runner) vault.read(secret/customers/acme) is still needed",
  "@module": "agent",
  "@timestamp": "2023-11-27T17:06:20.653655Z"
}
{
  "@level": "debug",
  "@message": "(runner) watching 1 dependencies",
  "@module": "agent",
  "@timestamp": "2023-11-27T17:06:20.653665Z"
}
{
  "@level": "debug",
  "@message": "(runner) all templates rendered",
  "@module": "agent",
  "@timestamp": "2023-11-27T17:06:20.653671Z"
}

10. For completeness, check the rendered template

cat template-render.txt | jq

Example content:

{
  "secret": "other",
  "region": "US-West",
  "contact_email": "james@acme.com"
}

[github-actions]

CI Results:
All Go tests succeeded! ✅

[VioletHynes]

I know this is a draft, but one idea I had for a test for this feature is that we could use the -log-file option for Agent and render a template, then check stdout. Before, as I understand it, with this bug, stdout would be non-empty (since it didn't respect that config either), but after this change, it should be empty (and the log file should be full). There might be a less E2E-y way to test this, but I thought I'd offer that as an option if you were struggling to think of something!

[peteski22]

Nobody likes the extra line.

[raskchanky]

[hghaf099]

Since the error is of type multierror.Error, you may want to use errs.ErrorOrNil() on the return.

[peteski22]

Thanks @hghaf099, do you mean like this?

if errs.ErrorOrNil() != nil {
		return nil, errs.ErrorOrNil()

[hghaf099]

Ah, my bad. It seems that we only need to return if the error is non-nil. Then what you already had is sufficient. Sorry for the confusion.

[peteski22]

this is the actual bug fix.

[raskchanky]

The description on this PR is so good.

[peteski22]

I know this is a draft, but one idea I had for a test for this feature is that we could use the -log-file option for Agent and render a template, then check stdout. Before, as I understand it, with this bug, stdout would be non-empty (since it didn't respect that config either), but after this change, it should be empty (and the log file should be full). There might be a less E2E-y way to test this, but I thought I'd offer that as an option if you were struggling to think of something!

Thanks @VioletHynes, I'm not sure if that would work as the stdout/stderr is still used if file is enabled, you just end up writing to both. 🤔

[github-actions]

Build Results:
All builds succeeded! ✅

[VioletHynes]

Looks good! I'd like to see a test before I approve, especially as this is dependent on consul-template, I worry maybe we'll take a new version of that and this functionality would break.

I mentioned the option of checking stdout in a test, but if it still has all of the output in tests even if it goes to a file, we could check that it has logs from consul-template, e.g. check the log-file for

 "@message": "(runner) rendered "file-name"

There may be a smarter way to test this too, but that approach should be hopefully easy enough, and should test both aspects of the PR (log format and log file).

[kubawi]

LGTM