Inconsistent date format in Vault Agent debug logs #9816

mikegreen · 2020-08-25T00:22:44Z

Describe the bug

Vault agent log output is inconsistent in the date format when running in debug.
Some are YYYY/MM/DD, while others are YYYY-MM-DD
And that correlates to some being in server time (ie, the ones with timezone T) and some zulu.

2020/08/25 00:08:53.746776 [DEBUG] (runner) watching 1 dependencies
2020-08-24T18:09:03.919-0600 [INFO]  auth.handler: renewed auth token
2020/08/25 00:09:14.578845 [DEBUG] Found certificate and set lease duration to 605 seconds

2020-08-24T18:15:29.620-0600 [INFO]  auth.handler: starting renewal process
2020/08/25 00:15:29.620538 [INFO] (runner) stopping
2020/08/25 00:15:29.620562 [DEBUG] (runner) stopping watcher

To Reproduce
Run Vault in agent mode, ie

$ vault agent -config=agent-demo.hcl -log-level=DEBUG

Expected behavior
Log format to be consistent, can be slash or dash delimited, but not mixed.

Environment:

Vault Server Version (retrieve with vault status): Vault v1.5.0
Vault CLI Version (retrieve with vault version): Vault v1.4.2+prem
Server Operating System/Architecture: Darwin CLI, Ubuntu 18.x server

The text was updated successfully, but these errors were encountered:

aphorise · 2020-08-25T20:06:32Z

I'm thinking if this could be ISO formating set local to VM?

@mikegreen - can you provide locale details:

grep -v '#' /etc/locale.gen && printf '___\n' && locale -a && printf '___\n' && locale ;

mikegreen · 2020-08-25T20:17:43Z

Darwin doesn't seem to have /etc/locale.gen ?

$ locale
LANG="en_US.UTF-8"
LC_COLLATE="en_US.UTF-8"
LC_CTYPE="en_US.UTF-8"
LC_MESSAGES="en_US.UTF-8"
LC_MONETARY="en_US.UTF-8"
LC_NUMERIC="en_US.UTF-8"
LC_TIME="en_US.UTF-8"
LC_ALL=

aphorise · 2020-08-25T20:47:36Z

@mikegreen - can you try setting and running again to see if it impacts anything:

export LANGUAGE=en_US.UTF-8 ;
export LANG=en_US.UTF-8 ;
export LC_ALL=en_US.UTF-8 ;
locale-gen en_US.UTF-8 && dpkg-reconfigure locales ;
# // check again you should have: /etc/locale.gen

Otherwise I think it might actually be related to consul-template.

aphorise · 2020-08-25T21:28:32Z

Like this part specifically with the logger maybe

aphorise · 2020-08-25T21:43:28Z

@mikegreen - please also output: locale -k LC_TIME - I think it may actually be related:

uname -a
  # Linux hsm1-vault1 4.19.0-9-amd64 #1 SMP Debian 4.19.118-2 (2020-04-29) x86_64 GNU/Linux

locale -k LC_TIME
  # ...
  # date_fmt="%a %d %b %Y %r %Z"

# // in the case of my MacOs for example:
locale -k LC_TIME
  # ...
  # t_fmt_ampm="%I:%M:%S %p"
  # era=""
  # era_d_fmt=""
  # era_t_fmt=""
  # era_d_t_fmt=""
  # alt_digits=""
  # d_t_fmt="%a %b %e %X %Y"
  # d_fmt="%m/%d/%Y"
  # t_fmt="%H:%M:%S"

mikegreen · 2020-08-25T23:09:07Z

$ locale-gen en_US.UTF-8 && dpkg-reconfigure locales ;
-bash: locale-gen: command not found

Darwin MacBook-Pro.localdomain 19.6.0 Darwin Kernel Version 19.6.0: Thu Jun 18 20:49:00 PDT 2020; root:xnu-6153.141.1~1/RELEASE_X86_64 x86_64

$ locale -k LC_TIME
ab_day="Sun";"Mon";"Tue";"Wed";"Thu";"Fri";"Sat"
abday="Sun";"Mon";"Tue";"Wed";"Thu";"Fri";"Sat"
day="Sunday";"Monday";"Tuesday";"Wednesday";"Thursday";"Friday";"Saturday"
abmon="Jan";"Feb";"Mar";"Apr";"May";"Jun";"Jul";"Aug";"Sep";"Oct";"Nov";"Dec"
mon="January";"February";"March";"April";"May";"June";"July";"August";"September";"October";"November";"December"
am_pm="AM";"PM"
t_fmt_ampm="%I:%M:%S %p"
era=""
era_d_fmt=""
era_t_fmt=""
era_d_t_fmt=""
alt_digits=""
d_t_fmt="%a %b %e %X %Y"
d_fmt="%m/%d/%Y"
t_fmt="%H:%M:%S"

aphorise · 2020-08-26T09:32:35Z

Thanks for the input. For clarity the LC... settings do not seem to be related and I've observed the same condition you've shown in both Darwin & Debian. I'm rather confident its related to: consul-template. I can strive to take a look in the coming week (after 3rd of August) if no earlier attention is given to it.

My observations (UTC / 2 hour difference from other log entries)

==> Vault agent configuration:

           Api Address 1: http://127.0.0.1:8200
                     Cgo: disabled
               Log Level: trace
                 Version: Vault v1.5.0
             Version Sha: de37ed221f39704129c02f7a8981c1ac0cf432b4+CHANGES

2020-08-26T11:21:22.457+0200 [INFO]  sink.file: creating file sink
2020-08-26T11:21:22.457+0200 [TRACE] sink.file: enter write_token: path=vault-token-via-agent
2020-08-26T11:21:22.457+0200 [TRACE] sink.file: exit write_token: path=vault-token-via-agent
2020-08-26T11:21:22.457+0200 [INFO]  sink.file: file sink configured: path=vault-token-via-agent mode=-rw-r-----
2020-08-26T11:21:22.459+0200 [DEBUG] cache: auto-auth token is allowed to be used; configuring inmem sink
2020-08-26T11:21:22.459+0200 [INFO]  sink.server: starting sink server
2020-08-26T11:21:22.459+0200 [INFO]  auth.handler: starting auth handler
2020-08-26T11:21:22.459+0200 [INFO]  auth.handler: authenticating
2020-08-26T11:21:22.459+0200 [TRACE] auth.aws: beginning authentication
2020-08-26T11:21:22.459+0200 [INFO]  template.server: starting template server

2020/08/26 09:21:22.460160 [INFO] (runner) creating new runner (dry: false, once: false)
2020/08/26 09:21:22.460938 [DEBUG] (runner) final config: {"..."}
2020/08/26 09:21:22.461309 [INFO] (runner) creating watcher

2020-08-26T11:21:23.368+0200 [INFO]  sink.server: sink server stopped

2020/08/26 09:21:23.368481 [INFO] (runner) stopping
2020/08/26 09:21:23.368496 [DEBUG] (runner) stopping watcher
2020/08/26 09:21:23.368503 [DEBUG] (watcher) stopping all views

2020-08-26T11:21:23.368+0200 [INFO]  auth.handler: auth handler stopped
2020-08-26T11:21:23.368+0200 [INFO]  template.server: template server stopped
2020-08-26T11:21:23.368+0200 [TRACE] auth.aws: shutdown triggered, stopping aws auth handler

calvn · 2020-09-01T17:43:24Z

I've observed this as well, and it comes from the fact that the template server outputs logs in a format that is different to the rest of the agent's logs. We pass in the same writer to the template server, but it instantiates its own logger and thus adheres to its own logging format. I'll mark this as an enhancement for Agent, thanks for the report!

aphorise · 2020-09-02T22:20:55Z

I've created the following PR on Consul-Template which seems to fix the issue (not sure I broke anything else)

==> Vault agent configuration:

           Api Address 1: http://127.0.0.1:8300
                     Cgo: disabled
               Log Level: trace
                 Version: Vault v1.5.0
             Version Sha: 8bb35c207ee7e1c2dd77a47edb7e553aaf237f5e

2020-09-03T00:08:27.384+0200 [INFO]  sink.file: creating file sink
2020-09-03T00:08:27.384+0200 [TRACE] sink.file: enter write_token: path=vault-token-via-agent
2020-09-03T00:08:27.384+0200 [TRACE] sink.file: exit write_token: path=vault-token-via-agent
2020-09-03T00:08:27.384+0200 [INFO]  sink.file: file sink configured: path=vault-token-via-agent mode=-rw-r-----
2020-09-03T00:08:27.385+0200 [DEBUG] cache: auto-auth token is allowed to be used; configuring inmem sink
2020-09-03T00:08:27.385+0200 [INFO]  sink.server: starting sink server
2020-09-03T00:08:27.385+0200 [INFO]  auth.handler: starting auth handler
2020-09-03T00:08:27.385+0200 [INFO]  template.server: starting template server
2020-09-03T00:08:27.385+0200 [INFO]  auth.handler: authenticating
2020-09-03T00:08:27.385+0200 [TRACE] auth.aws: beginning authentication
2020-09-03T00:08:27.385+0200 [INFO] (runner) creating new runner (dry: false, once: false)
2020-09-03T00:08:27.386+0200 [DEBUG] (runner) final config: { ……… }
2020-09-03T00:08:27.386+0200 [INFO] (runner) creating watcher
2020-09-03T00:08:27.386+0200 [ERROR] template.server: template server failed to create: error="failed to read template: open customer.tmpl: no such file or directory"
2020-09-03T00:08:27.386+0200 [INFO]  template.server: template server stopped
2020-09-03T00:08:27.387+0200 [ERROR] auth.handler: error authenticating: error="Error making API request.

URL: PUT http://127.0.0.1:8200/v1/auth/aws/login
Code: 403. Errors:

* 1 error occurred:
	* permission denied

" backoff=2.538875047
^C==> Vault agent shutdown triggered
2020-09-03T00:08:27.948+0200 [INFO]  sink.server: sink server stopped
2020-09-03T00:08:27.948+0200 [TRACE] auth.aws: shutdown triggered, stopping aws auth handler
2020-09-03T00:08:27.948+0200 [INFO]  auth.handler: auth handler stopped

vishalnayak · 2020-10-26T18:54:43Z

@calvn @mikegreen @aphorise Based on the last comment on this issue, can this be considered fixed? If yes, we can close the issue.

aphorise · 2020-11-16T19:36:55Z

@vishalnayak - I'm not sure if the latest 1.6.0 build of Vault is with the updated version that included the merged hashicorp/consul-template#1412. It needs checking. The output looks the same atm and issue is not yet resolved.

mladlow · 2020-12-12T00:29:42Z

We are currently using consul-template 0.25.1, and the change will be released in 0.25.2. The consul-template folks are planning a release at which point we'll be able to update our dependency.

I'll keep bumping the milestone on this so I can keep checking for new releases.

mladlow · 2021-02-22T16:54:39Z

Consul-template has released 0.25.2, and we'll be using it in 1.7.

calvn added agent enhancement labels Sep 1, 2020

calvn added this to the 1.6 milestone Sep 1, 2020

aphorise mentioned this issue Sep 2, 2020

Writer to log date / time in conistent format like in other places. hashicorp/consul-template#1412

Merged

mladlow modified the milestones: 1.6, 1.6.1 Oct 30, 2020

mladlow modified the milestones: 1.6.1, 1.6.2 Dec 12, 2020

mladlow modified the milestones: 1.6.2, 1.6.3 Jan 15, 2021

mladlow modified the milestones: 1.6.3, 1.7 Feb 22, 2021

pbernal removed this from the 1.7 milestone Apr 14, 2021

calvn mentioned this issue Jun 11, 2021

dep: update consul-template to v0.26.0 #11830

Closed

calvn added this to the 1.8-rc1 milestone Jun 11, 2021

calvn mentioned this issue Jun 11, 2021

dep: update consul-template to v0.26.0 #11838

Merged

calvn closed this as completed in #11838 Jun 11, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Inconsistent date format in Vault Agent debug logs #9816

Inconsistent date format in Vault Agent debug logs #9816

mikegreen commented Aug 25, 2020 •

edited

Loading

aphorise commented Aug 25, 2020

mikegreen commented Aug 25, 2020

aphorise commented Aug 25, 2020

aphorise commented Aug 25, 2020

aphorise commented Aug 25, 2020

mikegreen commented Aug 25, 2020 •

edited

Loading

aphorise commented Aug 26, 2020

calvn commented Sep 1, 2020

aphorise commented Sep 2, 2020 •

edited

Loading

vishalnayak commented Oct 26, 2020

aphorise commented Nov 16, 2020

mladlow commented Dec 12, 2020 •

edited

Loading

mladlow commented Feb 22, 2021

Inconsistent date format in Vault Agent debug logs #9816

Inconsistent date format in Vault Agent debug logs #9816

Comments

mikegreen commented Aug 25, 2020 • edited Loading

aphorise commented Aug 25, 2020

mikegreen commented Aug 25, 2020

aphorise commented Aug 25, 2020

aphorise commented Aug 25, 2020

aphorise commented Aug 25, 2020

mikegreen commented Aug 25, 2020 • edited Loading

aphorise commented Aug 26, 2020

calvn commented Sep 1, 2020

aphorise commented Sep 2, 2020 • edited Loading

vishalnayak commented Oct 26, 2020

aphorise commented Nov 16, 2020

mladlow commented Dec 12, 2020 • edited Loading

mladlow commented Feb 22, 2021

mikegreen commented Aug 25, 2020 •

edited

Loading

mikegreen commented Aug 25, 2020 •

edited

Loading

aphorise commented Sep 2, 2020 •

edited

Loading

mladlow commented Dec 12, 2020 •

edited

Loading