wrap log messages with hclog

[lgfa29]

hclog provides a Writer that can be used to configure Go's log package to write logs through the application logger, but the agent configuration was not actually using the hclog writer.

This PR calls log.SetOutput with the correct input. The logOutput value that was being used before is already being set as the logger.Output value.

InferLevels doesn't always work, but at least now all messages are proper JSON strings.

Closes #11232

Sample agent config

log_json = true

client {
  enabled = true

  server_join {
    retry_join = ["provider=mdns service=nomad v6=false"]
  }
}

Before

{"@level":"debug","@message":"allocation updates","@module":"client","@timestamp":"2021-10-08T18:09:25.902441-04:00","added":0,"ignored":0,"removed":0,"updated":0}
{"@level":"debug","@message":"allocation updates applied","@module":"client","@timestamp":"2021-10-08T18:09:25.902926-04:00","added":0,"errors":0,"ignored":0,"removed":0,"updated":0}
2021/10/08 18:09:25.903199 [ERR] mdns: Failed to bind to udp6 port: listen udp6 [ff02::fb]:5353: setsockopt: can't assign requested address
{"@level":"debug","@message":"state updated","@module":"client","@timestamp":"2021-10-08T18:09:25.903585-04:00","node_status":"ready"}
{"@level":"debug","@message":"state changed, updating node and re-registering","@module":"client","@timestamp":"2021-10-08T18:09:26.907301-04:00"}

After

{"@level":"debug","@message":"discover: Using provider \"mdns\"","@module":"agent.joiner","@timestamp":"2021-10-08T18:17:29.088634-04:00"}
{"@level":"debug","@message":"state updated","@module":"client","@timestamp":"2021-10-08T18:17:29.088902-04:00","node_status":"ready"}
{"@level":"info","@message":"2021/10/08 18:17:29.089869 [ERR] mdns: Failed to bind to udp6 port: listen udp6 [ff02::fb]:5353: setsockopt: can't assign requested address","@module":"agent","@timestamp":"2021-10-08T18:17:29.089872-04:00"}
{"@level":"debug","@message":"state changed, updating node and re-registering","@module":"client","@timestamp":"2021-10-08T18:17:30.089674-04:00"}
{"@level":"info","@message":"node registration complete","@module":"client","@timestamp":"2021-10-08T18:17:30.090978-04:00"}

[jrasell]

LGTM. Is it worth updating the changelog entry to detail logging output, otherwise I find it's a little vague.

[lgfa29]

LGTM. Is it worth updating the changelog entry to detail logging output, otherwise I find it's a little vague.

Good call. I reworded the CHANGELOG entry to be more descriptive.

[schmichael]

Might be worth filing an issue with hclog about InferLevels not handling https://github.com/hashicorp/mdns/blob/master/client.go#L120 right since these are all HashiCorp libraries.

[josegonzalez]

@schmichael it should based on this, so there seems to be something fishy going on.

[schmichael]

@josegonzalez Good catch! That mdns package has not needed much attention, so it might be doing something strange by modern Go standards.

[lgfa29]

Ahh thanks @josegonzalez .

go-hclog checks the message with HasPrefixand the mdns package outputs a timestamp first:

2021/10/08 18:17:29.089869 [ERR] mdns: ...

I thought log.SetFlags(0) would disable the timestamp, but maybe it needs to be called earlier in the code? I will run some experiments.

[lgfa29]

I tried setting log.SetFlags(0) in Nomad's main.go init, which is probably the very first thing that gets loaded, but no luck. I will raise an issue with go-hclog to perhaps try to handle lines with timestamps.

[github-actions]

I'm going to lock this pull request because it has been closed for 120 days ⏳. This helps our maintainers find and focus on the active contributions.
If you have found a problem that seems related to this change, please open a new issue and complete the issue template so we can capture all the details necessary to investigate further.