consul-template logs have inconsistent formatting

[tgross]

A truly tiny papercut: the template runner we have produces logs that are coming up from consul-template itself, but these don't have the same date format as the logs for the rest of Nomad. So we end up with logs like the following:

    2020-12-02T16:22:30.246Z [INFO]  client.alloc_runner.task_runner.task_hook.logmon.nomad: opening fifo: alloc_id=2f8932c2-f563-5053-5059-49dcaf3fd53b task=sidecar @module=logmon path=/var/nomad/alloc/2f8932c2-f563-5053-5059-49dcaf3fd53b/alloc/logs/.sidecar.stderr.fifo timestamp=2020-12-02T16:22:30.245Z
    2020-12-02T16:22:30.248Z [DEBUG] client.alloc_runner.task_runner.task_hook.stats_hook: failed to start stats collection for task with unrecoverable error: alloc_id=2f8932c2-f563-5053-5059-49dcaf3fd53b task=redis error="container stopped"
    2020/12/02 16:22:30.249053 [INFO] (runner) creating new runner (dry: false, once: false)
    2020/12/02 16:22:30.249243 [DEBUG] (runner) final config: {"Consul":{"Address":"127.0.0.1:8500","Namespace":"","Auth":{"Enabled":false,"Username":"","Password":""},"Retry":{"Attempts":12,"Backoff":250000000,"MaxBackoff":60000000000,"Enabled":true},"SSL":{"CaCert":"","CaPath":"","Cert":"","Enabled":false,"Key":"","ServerName":"","Verify":true},"Token":"","Transport":{"DialKeepAlive":30000000000,"DialTimeout":30000000000,"DisableKeepAlives":false,"IdleConnTimeout":90000000000,"MaxIdleConns":100,"MaxIdleConnsPerHost":9,"TLSHandshakeTimeout":10000000000}},"Dedup":{"Enabled":false,"MaxStale":2000000000,"Prefix":"consul-template/dedup/","TTL":15000000000,"BlockQueryWaitTime":60000000000},"DefaultDelims":{"Left":null,"Right":null},"Exec":{"Command":"","Enabled":false,"Env":{"Denylist":[],"Custom":[],"Pristine":false,"Allowlist":[]},"KillSignal":2,"KillTimeout":30000000000,"ReloadSignal":null,"Splay":0,"Timeout":0},"KillSignal":2,"LogLevel":"WARN","MaxStale":2000000000,"PidFile":"","ReloadSignal":1,"Syslog":{"Enabled":false,"Facility":"LOCAL0","Name":""},"Templates":[{"Backup":false,"Command":"","CommandTimeout":30000000000,"Contents":"#!/bin/bash\ntrap do_trap SIGTERM SIGINT\n\ndo_trap() {\n  echo \"received signal\"\n  sleep 20\n}\n\necho \"hello\"\nsleep 600\n","CreateDestDirs":true,"Destination":"/var/nomad/alloc/2f8932c2-f563-5053-5059-49dcaf3fd53b/sidecar/local/script.sh","ErrMissingKey":false,"Exec":{"Command":"","Enabled":false,"Env":{"Denylist":[],"Custom":[],"Pristine":false,"Allowlist":[]},"KillSignal":2,"KillTimeout":30000000000,"ReloadSignal":null,"Splay":0,"Timeout":30000000000},"Perms":420,"Source":"","Wait":{"Enabled":false,"Min":0,"Max":0},"LeftDelim":"{{","RightDelim":"}}","FunctionDenylist":["plugin"],"SandboxPath":"/var/nomad/alloc/2f8932c2-f563-5053-5059-49dcaf3fd53b/sidecar"}],"Vault":{"Address":"","Enabled":false,"Namespace":"","RenewToken":false,"Retry":{"Attempts":12,"Backoff":250000000,"MaxBackoff":60000000000,"Enabled":true},"SSL":{"CaCert":"","CaPath":"","Cert":"","Enabled":true,"Key":"","
ServerName":"","Verify":true},"Transport":{"DialKeepAlive":30000000000,"DialTimeout":30000000000,"DisableKeepAlives":false,"IdleConnTimeout":90000000000,"MaxIdleConns":100,"MaxIdleConnsPerHost":9,"TLSHandshakeTimeout":10000000000},"UnwrapToken":false},"Wait":{"Enabled":false,"Min":0,"Max":0},"Once":false,"BlockQueryWaitTime":60000000000}
    2020/12/02 16:22:30.249304 [INFO] (runner) creating watcher
    2020/12/02 16:22:30.249359 [INFO] (runner) starting
    2020/12/02 16:22:30.249364 [DEBUG] (runner) running initial templates
    2020/12/02 16:22:30.249367 [DEBUG] (runner) initiating run
    2020/12/02 16:22:30.249370 [DEBUG] (runner) checking template 958a38b8b3fee8cd51690838272740cf
    2020/12/02 16:22:30.249497 [DEBUG] (runner) rendering "(dynamic)" => "/var/nomad/alloc/2f8932c2-f563-5053-5059-49dcaf3fd53b/sidecar/local/script.sh"
    2020/12/02 16:22:30.249518 [DEBUG] (runner) diffing and updating dependencies
    2020/12/02 16:22:30.249523 [DEBUG] (runner) watching 0 dependencies
    2020/12/02 16:22:30.249526 [DEBUG] (runner) all templates rendered
    2020-12-02T16:22:30.252Z [DEBUG] client.alloc_runner.task_runner.task_hook.stats_hook: failed to start stats collection for task with unrecoverable error: alloc_id=2f8932c2-f563-5053-5059-49dcaf3fd53b task=sidecar error="container stopped"
    2020-12-02T16:22:30.258Z [WARN]  client.driver_mgr.docker: RemoveImage on non-referenced counted image id: driver=docker image_id=sha256:87856cc39862cec77541d68382e4867d7ccb29a85a17221446c857ddaebca916
    2020-12-02T16:22:30.258Z [INFO]  client.alloc_runner.task_runner: restarting task: alloc_id=2f8932c2-f563-5053-5059-49dcaf3fd53b task=redis reason="Restart within policy" delay=16.511388318s

[cpesch]

We ran into this, too. Is there a solution in sight?

[tgross]

Hi @cpesch. This isn't likely to happen unless someone from the community makes it happen, which would mostly involve work to make consul-template's log output more configurable and then a bit of work to update Nomad to inject its log format there.