From b8bc2e70681144c4502739802def66b4eb1105fe Mon Sep 17 00:00:00 2001 From: Mahmood Ali Date: Wed, 20 Oct 2021 14:27:47 -0400 Subject: [PATCH 1/3] logging: Pipe all logs through hclog This commit addresses two usability issues with our logging. First, log the failure error when the agent fails to start. Previously, the agent startup failure error would be emitted to the command UI but not logged. So it doesn't get emitted to syslog or `log_file` if they are set, and it makes debugging much harder. Also, logging the error again before exit makes the error more visible: previously, the operator needed to scroll to the top to find the error. On a sample failure, the output will look like: ``` ==> WARNING: Bootstrap mode enabled! Potentially unsafe operation. ==> Loaded configuration from sample-configs/config-bad ==> Starting Nomad agent... ==> Error starting agent: setting up server node ID failed: mkdir /path-without-permission: read-only file system 2021-10-20T14:38:51.179-0400 [WARN] agent.plugin_loader: skipping external plugins since plugin_dir doesn't exist: plugin_dir=/path-without-permission/plugins 2021-10-20T14:38:51.181-0400 [DEBUG] agent.plugin_loader.docker: using client connection initialized from environment: plugin_dir=/path-without-permission/plugins 2021-10-20T14:38:51.181-0400 [DEBUG] agent.plugin_loader.docker: using client connection initialized from environment: plugin_dir=/path-without-permission/plugins 2021-10-20T14:38:51.181-0400 [INFO] agent: detected plugin: name=java type=driver plugin_version=0.1.0 2021-10-20T14:38:51.181-0400 [INFO] agent: detected plugin: name=docker type=driver plugin_version=0.1.0 2021-10-20T14:38:51.181-0400 [INFO] agent: detected plugin: name=mock_driver type=driver plugin_version=0.1.0 2021-10-20T14:38:51.181-0400 [INFO] agent: detected plugin: name=raw_exec type=driver plugin_version=0.1.0 2021-10-20T14:38:51.181-0400 [INFO] agent: detected plugin: name=exec type=driver plugin_version=0.1.0 2021-10-20T14:38:51.181-0400 [INFO] agent: detected plugin: name=qemu type=driver plugin_version=0.1.0 2021-10-20T14:38:51.181-0400 [ERROR] agent: error starting agent: error="setting up server node ID failed: mkdir /path-without-permission: read-only file system" ``` This change adds the final `ERROR` message. It's easy to miss the `==> Error starting agent` above. Also, ensure that all logs emitted by the golang standard logger (e.g. `log.Printf`), are routed through hclog. Some dependencies still use `log.Printf` and we'd like their output to be timestampped and jsonified as appropriate. --- command/agent/command.go | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/command/agent/command.go b/command/agent/command.go index f803d880b45b..48f3463f6c8d 100644 --- a/command/agent/command.go +++ b/command/agent/command.go @@ -492,6 +492,8 @@ func (c *Command) setupAgent(config *Config, logger hclog.InterceptLogger, logOu c.Ui.Output("Starting Nomad agent...") agent, err := NewAgent(config, logger, logOutput, inmem) if err != nil { + // log the error as well, so it appears at the end + logger.Error("error starting agent", "error", err) c.Ui.Error(fmt.Sprintf("Error starting agent: %s", err)) return err } @@ -673,6 +675,14 @@ func (c *Command) Run(args []string) int { c.Ui = &logging.HcLogUI{Log: logger} } + // route standard logger to hc-log, so stray log.Printf get tagged with + // timestamps and potentially jsonified + log.SetOutput(logger.StandardWriter(&hclog.StandardLoggerOptions{ + InferLevels: true, + })) + log.SetPrefix("") + log.SetFlags(0) + // Log config files if len(config.Files) > 0 { c.Ui.Output(fmt.Sprintf("Loaded configuration from %s", strings.Join(config.Files, ", "))) From fb1047ba4710c36aee5c90c46c90343ca0079f7a Mon Sep 17 00:00:00 2001 From: Mahmood Ali Date: Wed, 20 Oct 2021 14:54:31 -0400 Subject: [PATCH 2/3] remove code that PR 11291 already handled --- command/agent/command.go | 8 -------- 1 file changed, 8 deletions(-) diff --git a/command/agent/command.go b/command/agent/command.go index 48f3463f6c8d..558e63ee120e 100644 --- a/command/agent/command.go +++ b/command/agent/command.go @@ -675,14 +675,6 @@ func (c *Command) Run(args []string) int { c.Ui = &logging.HcLogUI{Log: logger} } - // route standard logger to hc-log, so stray log.Printf get tagged with - // timestamps and potentially jsonified - log.SetOutput(logger.StandardWriter(&hclog.StandardLoggerOptions{ - InferLevels: true, - })) - log.SetPrefix("") - log.SetFlags(0) - // Log config files if len(config.Files) > 0 { c.Ui.Output(fmt.Sprintf("Loaded configuration from %s", strings.Join(config.Files, ", "))) From 20746bc772dfcc0265e0591a1de84a9a03420635 Mon Sep 17 00:00:00 2001 From: Mahmood Ali Date: Wed, 27 Oct 2021 08:40:33 -0700 Subject: [PATCH 3/3] changelog --- .changelog/11353.txt | 3 +++ 1 file changed, 3 insertions(+) create mode 100644 .changelog/11353.txt diff --git a/.changelog/11353.txt b/.changelog/11353.txt new file mode 100644 index 000000000000..b519e599d49e --- /dev/null +++ b/.changelog/11353.txt @@ -0,0 +1,3 @@ +```release-note:improvement +agent: Log the cause of failure if agent failed to start +```