logger output missing timestamp values

[calvn]

Consul Template version

Vault agent version 1.7.0, importing consul-template version 0.25.2

Configuration

N/A

Command

See debug output of command + logs

Debug output

               Log Level: info
                 Version: Vault v1.4.0

2021-05-26T22:46:07.569-0700 [INFO]  sink.file: creating file sink
2021-05-26T22:46:07.570-0700 [INFO]  sink.file: file sink configured: path=/tmp/agent_test/.vault-token mode=-rw-r-----
2021-05-26T22:46:07.570-0700 [INFO]  sink.server: starting sink server
2021-05-26T22:46:07.570-0700 [INFO]  auth.handler: starting auth handler
2021-05-26T22:46:07.570-0700 [INFO]  template.server: starting template server
2021-05-26T22:46:07.570-0700 [INFO]  auth.handler: authenticating
2021/05/27 05:46:07.571269 [INFO] (runner) creating new runner (dry: false, once: false)
2021/05/27 05:46:07.572112 [INFO] (runner) creating watcher
2021-05-26T22:46:07.683-0700 [INFO]  auth.handler: authentication successful, sending token to sinks
2021-05-26T22:46:07.683-0700 [INFO]  template.server: template server received new token
2021-05-26T22:46:07.683-0700 [INFO]  auth.handler: starting renewal process
2021/05/27 05:46:07.683871 [INFO] (runner) stopping
2021/05/27 05:46:07.683927 [INFO] (runner) creating new runner (dry: false, once: false)
2021/05/27 05:46:07.684056 [INFO] (runner) creating watcher
2021-05-26T22:46:07.684-0700 [INFO]  sink.file: token written: path=/tmp/agent_test/.vault-token
2021/05/27 05:46:07.684242 [INFO] (runner) starting
2021-05-26T22:46:07.688-0700 [INFO]  auth.handler: renewed auth token
2021/05/27 05:46:07.693380 [WARN] (view) vault.read(kv/b): no secret exists at kv/b (retry attempt 1 after "250ms")
2021/05/27 05:46:07.953052 [WARN] (view) vault.read(kv/b): no secret exists at kv/b (retry attempt 2 after "500ms")
2021/05/27 05:46:08.463408 [WARN] (view) vault.read(kv/b): no secret exists at kv/b (retry attempt 3 after "1s")
2021/05/27 05:46:09.470984 [WARN] (view) vault.read(kv/b): no secret exists at kv/b (retry attempt 4 after "2s")
2021/05/27 05:46:11.480051 [WARN] (view) vault.read(kv/b): no secret exists at kv/b (retry attempt 5 after "4s")
2021/05/27 05:46:15.485882 [WARN] (view) vault.read(kv/b): no secret exists at kv/b (retry attempt 6 after "8s")
2021/05/27 05:46:23.496498 [WARN] (view) vault.read(kv/b): no secret exists at kv/b (retry attempt 7 after "16s")
2021/05/27 05:46:39.504152 [WARN] (view) vault.read(kv/b): no secret exists at kv/b (retry attempt 8 after "32s")
2021/05/27 05:47:11.512512 [WARN] (view) vault.read(kv/b): no secret exists at kv/b (retry attempt 9 after "1m0s")
2021/05/27 05:48:11.519200 [WARN] (view) vault.read(kv/b): no secret exists at kv/b (retry attempt 10 after "1m0s")
2021/05/27 05:49:11.524638 [WARN] (view) vault.read(kv/b): no secret exists at kv/b (retry attempt 11 after "1m0s")
2021/05/27 05:50:11.533526 [WARN] (view) vault.read(kv/b): no secret exists at kv/b (retry attempt 12 after "1m0s")
2021/05/27 05:51:11.541864 [ERR] (view) vault.read(kv/b): no secret exists at kv/b (exceeded maximum retries)
2021/05/27 05:51:11.541882 [ERR] (runner) watcher reported error: vault.read(kv/b): no secret exists at kv/b
2021-05-26T22:51:11.541-0700 [ERROR] template.server: template server error: error="vault.read(kv/b): no secret exists at kv/b"
2021-05-26T22:51:11.541-0700 [INFO]  template.server: template server stopped
^C==> Vault agent shutdown triggered

1.7.0

==> Vault agent configuration:

                     Cgo: disabled
               Log Level: info
                 Version: Vault v1.7.0
             Version Sha: 4e222b85c40a810b74400ee3c54449479e32bb9f

2021-05-26T22:39:49.086-0700 [INFO]  sink.file: creating file sink
2021-05-26T22:39:49.086-0700 [INFO]  sink.file: file sink configured: path=/tmp/agent_test/.vault-token mode=-rw-r-----
2021-05-26T22:39:49.087-0700 [INFO]  sink.server: starting sink server
2021-05-26T22:39:49.087-0700 [INFO]  auth.handler: starting auth handler
2021-05-26T22:39:49.087-0700 [INFO]  auth.handler: authenticating
2021-05-26T22:39:49.087-0700 [INFO]  template.server: starting template server
[INFO] (runner) creating new runner (dry: false, once: false)
[INFO] (runner) creating watcher
2021-05-26T22:39:49.202-0700 [INFO]  auth.handler: authentication successful, sending token to sinks
2021-05-26T22:39:49.202-0700 [INFO]  auth.handler: starting renewal process
2021-05-26T22:39:49.202-0700 [INFO]  template.server: template server received new token
[INFO] (runner) stopping
[INFO] (runner) creating new runner (dry: false, once: false)
[INFO] (runner) creating watcher
[INFO] (runner) starting
2021-05-26T22:39:49.203-0700 [INFO]  sink.file: token written: path=/tmp/agent_test/.vault-token
2021-05-26T22:39:49.204-0700 [INFO]  auth.handler: renewed auth token
[WARN] (view) vault.read(kv/b.v1): no secret exists at kv/b (retry attempt 1 after "250ms")
[WARN] (view) vault.read(kv/b.v1): no secret exists at kv/b (retry attempt 2 after "500ms")
[ERR] (view) vault.read(kv/b.v1): no secret exists at kv/b (exceeded maximum retries)
[ERR] (runner) watcher reported error: vault.read(kv/b.v1): no secret exists at kv/b
[INFO] (runner) stopping
2021-05-26T22:39:49.969-0700 [INFO]  template.server: template server stopped
2021-05-26T22:39:49.969-0700 [INFO]  auth.handler: shutdown triggered, stopping lifetime watcher
2021-05-26T22:39:49.969-0700 [INFO]  sink.server: sink server stopped
2021-05-26T22:39:49.969-0700 [INFO]  sinks finished, exiting
2021-05-26T22:39:49.969-0700 [INFO]  auth.handler: auth handler stopped
2021-05-26T22:39:49.969-0700 [ERROR] runtime error encountered: error="template server: vault.read(kv/b.v1): no secret exists at kv/b"

Expected behavior

Logs by the consul-template library should have timestamp formatted output

Actual behavior

Timestamps are entirely missing after upgrading to v0.25.2.

I suspect that it may be because

consul-template/logging/logging.go

Line 75 in 980d053

log.SetOutput(logOutput)

is always overwriting the log output set earlier in

consul-template/logging/logging.go

Line 46 in 980d053

log.SetOutput(new(logWriter))

Steps to reproduce

1. Import consul-template library
2. Render secrets and output it logs
3. Observe difference in log output

References

Are there any other GitHub issues (open or closed) that should
be linked here? For example:

• Writer to log date / time in conistent format like in other places. #1412
• fix extra log output #1454

[eikenb]

Thanks for the ticket @calvn.

It looks like I failed to catch these issues when reviewing a related PR a while back. It tried to add a custom date output without properly taking into account the rest of the logging setup (filtering, etc).

I'm going to re-visit this area and fix it. It mainly needs better testing to catch these things.