From d9ac957c01d9ec9a94e2faacdc212549b3243aa5 Mon Sep 17 00:00:00 2001 From: Michael Schurter Date: Fri, 20 Jan 2023 11:21:31 -0800 Subject: [PATCH 1/3] client: log task events at INFO level Fixes #15840 Example INFO level client logs with this enabled: ``` [INFO] client: node registration complete [INFO] client.alloc_runner.task_runner: Task event: alloc_id=b3dab5a9-91fd-da9a-ae89-ef7f1eceaf51 task=sleepy type=Received msg="Task received by client" failed=false [INFO] client.alloc_runner.task_runner: Task event: alloc_id=b3dab5a9-91fd-da9a-ae89-ef7f1eceaf51 task=sleepy type="Task Setup" msg="Building Task Directory" failed=false [WARN] client.alloc_runner.task_runner.task_hook.logmon: plugin configured with a nil SecureConfig: alloc_id=b3dab5a9-91fd-da9a-ae89-ef7f1eceaf51 task=sleepy [INFO] client.alloc_runner.task_runner.task_hook.logmon.nomad: opening fifo: alloc_id=b3dab5a9-91fd-da9a-ae89-ef7f1eceaf51 task=sleepy path=/tmp/NomadClient2414238708/b3dab5a9-91fd-da9a-ae89-ef7f1eceaf51/alloc/logs/.sleepy.stdout.fifo @module=logmon timestamp=2023-01-20T11:19:34.275-0800 [INFO] client.alloc_runner.task_runner.task_hook.logmon.nomad: opening fifo: alloc_id=b3dab5a9-91fd-da9a-ae89-ef7f1eceaf51 task=sleepy @module=logmon path=/tmp/NomadClient2414238708/b3dab5a9-91fd-da9a-ae89-ef7f1eceaf51/alloc/logs/.sleepy.stderr.fifo timestamp=2023-01-20T11:19:34.275-0800 [INFO] client.driver_mgr.raw_exec: starting task: driver=raw_exec driver_cfg="{Command:/bin/bash Args:[-c sleep 1000]}" [WARN] client.driver_mgr.raw_exec.executor: plugin configured with a nil SecureConfig: alloc_id=b3dab5a9-91fd-da9a-ae89-ef7f1eceaf51 driver=raw_exec task_name=sleepy [INFO] client.alloc_runner.task_runner: Task event: alloc_id=b3dab5a9-91fd-da9a-ae89-ef7f1eceaf51 task=sleepy type=Started msg="Task started by client" failed=false [INFO] client.alloc_runner.task_runner: Task event: alloc_id=b3dab5a9-91fd-da9a-ae89-ef7f1eceaf51 task=sleepy type=Killing msg="Sent interrupt. Waiting 5s before force killing" failed=false [INFO] client.driver_mgr.raw_exec.executor: plugin process exited: alloc_id=b3dab5a9-91fd-da9a-ae89-ef7f1eceaf51 driver=raw_exec task_name=sleepy path=/home/schmichael/go/bin/nomad pid=27668 [INFO] client.alloc_runner.task_runner: Task event: alloc_id=b3dab5a9-91fd-da9a-ae89-ef7f1eceaf51 task=sleepy type=Terminated msg="Exit Code: 130, Signal: 2" failed=false [INFO] client.alloc_runner.task_runner: Task event: alloc_id=b3dab5a9-91fd-da9a-ae89-ef7f1eceaf51 task=sleepy type=Killed msg="Task successfully killed" failed=false [INFO] client.alloc_runner.task_runner.task_hook.logmon: plugin process exited: alloc_id=b3dab5a9-91fd-da9a-ae89-ef7f1eceaf51 task=sleepy path=/home/schmichael/go/bin/nomad pid=27653 [INFO] client.gc: marking allocation for GC: alloc_id=b3dab5a9-91fd-da9a-ae89-ef7f1eceaf51 ``` So task events will approximately *double* the number of per-task log lines, but I think they add a lot of value. --- client/allocrunner/taskrunner/task_runner.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/client/allocrunner/taskrunner/task_runner.go b/client/allocrunner/taskrunner/task_runner.go index 6f2291e12a0..e8107f19b4f 100644 --- a/client/allocrunner/taskrunner/task_runner.go +++ b/client/allocrunner/taskrunner/task_runner.go @@ -1256,8 +1256,6 @@ func (tr *TaskRunner) UpdateState(state string, event *structs.TaskEvent) { tr.logger.Trace("setting task state", "state", state) if event != nil { - tr.logger.Trace("appending task event", "state", state, "event", event.Type) - // Append the event tr.appendEvent(event) } @@ -1370,6 +1368,8 @@ func (tr *TaskRunner) appendEvent(event *structs.TaskEvent) error { tr.state.LastRestart = time.Unix(0, event.Time) } + tr.logger.Info("Task event", "type", event.Type, "msg", event.DisplayMessage, "failed", event.FailsTask) + // Append event to slice appendTaskEvent(tr.state, event, tr.maxEvents) From a7c7858454c65eee601577f053aa79ffad311b17 Mon Sep 17 00:00:00 2001 From: Michael Schurter Date: Fri, 20 Jan 2023 11:26:59 -0800 Subject: [PATCH 2/3] client: drop logmon 'opening' from debug->info Cannot imagine why users care and removes 2 log lines per task invocation. ``` [INFO] client: node registration complete [INFO] client.alloc_runner.task_runner: Task event: alloc_id=1cafb2dc-302e-2c92-7845-f56618bc8648 task=sleepy type=Received msg="Task received by client" failed=false [INFO] client.alloc_runner.task_runner: Task event: alloc_id=1cafb2dc-302e-2c92-7845-f56618bc8648 task=sleepy type="Task Setup" msg="Building Task Directory" failed=false <<< 2 "opening fifo" lines elided here >>> [WARN] client.alloc_runner.task_runner.task_hook.logmon: plugin configured with a nil SecureConfig: alloc_id=1cafb2dc-302e-2c92-7845-f56618bc8648 task=sleepy [INFO] client.driver_mgr.raw_exec: starting task: driver=raw_exec driver_cfg="{Command:/bin/bash Args:[-c sleep 1000]}" [WARN] client.driver_mgr.raw_exec.executor: plugin configured with a nil SecureConfig: alloc_id=1cafb2dc-302e-2c92-7845-f56618bc8648 driver=raw_exec task_name=sleepy [INFO] client.alloc_runner.task_runner: Task event: alloc_id=1cafb2dc-302e-2c92-7845-f56618bc8648 task=sleepy type=Started msg="Task started by client" failed=false ``` --- client/logmon/logmon.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/client/logmon/logmon.go b/client/logmon/logmon.go index ca01f5ebb56..36bdd931747 100644 --- a/client/logmon/logmon.go +++ b/client/logmon/logmon.go @@ -195,7 +195,7 @@ func (l *logRotatorWrapper) isRunning() bool { // newLogRotatorWrapper takes a rotator and returns a wrapper that has the // processOutWriter to attach to the stdout or stderr of a process. func newLogRotatorWrapper(path string, logger hclog.Logger, rotator io.WriteCloser) (*logRotatorWrapper, error) { - logger.Info("opening fifo", "path", path) + logger.Debug("opening fifo", "path", path) var openFn func() (io.ReadCloser, error) var err error From 1f8f8812b35dadfd492fc9a208b1573022ed4008 Mon Sep 17 00:00:00 2001 From: Michael Schurter Date: Fri, 20 Jan 2023 11:42:00 -0800 Subject: [PATCH 3/3] docs: add changelog for #15842 --- .changelog/15842.txt | 3 +++ 1 file changed, 3 insertions(+) create mode 100644 .changelog/15842.txt diff --git a/.changelog/15842.txt b/.changelog/15842.txt new file mode 100644 index 00000000000..78a64ce1820 --- /dev/null +++ b/.changelog/15842.txt @@ -0,0 +1,3 @@ +```release-note:improvement +client: Log task events at INFO log level +```