From 28763cd20b8a53b8a55a04658f6d0e5262dedfe8 Mon Sep 17 00:00:00 2001 From: Cameron Sparr Date: Thu, 4 May 2023 16:55:03 +0000 Subject: [PATCH] More structured logging for Task object also downgrade log message 'Adding a state change event to send' to DEBUG from INFO, since this log message is redundantly logged twice whenever there is a state change, since we also log the state change when we send it to ECS, like this: ``` level=info time=2023-05-05T22:17:23Z msg="TaskHandler: Adding a state change event to send batched container/managed agent events: arn:aws:ecs:us-west-2:039193556298:task/usw2/0b670ab4398f4f138e1bad9293f563a0 -> RUNNING, Known Sent: RUNNING, PullStartedAt: 2023-05-05 22:16:44.14108352 +0000 UTC m=+435.253624196, PullStoppedAt: 2023-05-05 22:16:44.3532973 +0000 UTC m=+435.465837967, ExecutionStoppedAt: 0001-01-01 00:00:00 +0000 UTC" module=task_handler.go level=info time=2023-05-05T22:17:23Z msg="Sending state change to ECS" taskArn="arn:aws:ecs:us-west-2:039193556298:task/usw2/0b670ab4398f4f138e1bad9293f563a0" taskStatus="RUNNING" taskReason="" taskPullStartedAt="2023-05-05T22:16:44Z" eventType="TaskStateChange" taskKnownSentStatus="RUNNING" taskPullStoppedAt="2023-05-05T22:16:44Z" taskExecutionStoppedAt="0001-01-01T00:00:00Z" containerChange-0="containerName=nonessential containerStatus=STOPPED containerExitCode=0 containerKnownSentStatus=RUNNING containerRuntimeID=9bd88a86abd927421788d5aae9c4ec95b42b16e6d98a5b43940f084b60a1a91d containerIsEssential=false" ``` --- agent/api/task/task.go | 29 ++++++++++++++++++----------- agent/eventhandler/task_handler.go | 5 ++--- 2 files changed, 20 insertions(+), 14 deletions(-) diff --git a/agent/api/task/task.go b/agent/api/task/task.go index 70b634728c2..ce98a8270d8 100644 --- a/agent/api/task/task.go +++ b/agent/api/task/task.go @@ -2592,6 +2592,9 @@ func (task *Task) dockerHostBinds(container *apicontainer.Container) ([]string, // It will return a bool indicating if there was a change func (task *Task) UpdateStatus() bool { change := task.updateTaskKnownStatus() + if change != apitaskstatus.TaskStatusNone { + logger.Debug("Task known status change", task.fieldsUnsafe()) + } // DesiredStatus can change based on a new known status task.UpdateDesiredStatus() return change != apitaskstatus.TaskStatusNone @@ -2609,11 +2612,7 @@ func (task *Task) UpdateDesiredStatus() { // updateTaskDesiredStatusUnsafe determines what status the task should properly be at based on the containers' statuses // Invariant: task desired status must be stopped if any essential container is stopped func (task *Task) updateTaskDesiredStatusUnsafe() { - logger.Debug("Updating task's desired status", logger.Fields{ - field.TaskID: task.GetID(), - field.KnownStatus: task.KnownStatusUnsafe.String(), - field.DesiredStatus: task.DesiredStatusUnsafe.String(), - }) + logger.Debug("Updating task's desired status", task.fieldsUnsafe()) // A task's desired status is stopped if any essential container is stopped // Otherwise, the task's desired status is unchanged (typically running, but no need to change) @@ -2622,13 +2621,8 @@ func (task *Task) updateTaskDesiredStatusUnsafe() { break } if cont.Essential && (cont.KnownTerminal() || cont.DesiredTerminal()) { - logger.Info("Essential container stopped; updating task desired status to stopped", logger.Fields{ - field.TaskID: task.GetID(), - field.Container: cont.Name, - field.KnownStatus: task.KnownStatusUnsafe.String(), - field.DesiredStatus: apitaskstatus.TaskStopped.String(), - }) task.DesiredStatusUnsafe = apitaskstatus.TaskStopped + logger.Info("Essential container stopped; updated task desired status to stopped", task.fieldsUnsafe()) } } } @@ -2916,6 +2910,19 @@ func (task *Task) stringUnsafe() string { len(task.Containers), len(task.ENIs)) } +// fieldsUnsafe returns logger.Fields representing this object +func (task *Task) fieldsUnsafe() logger.Fields { + return logger.Fields{ + "taskFamily": task.Family, + "taskVersion": task.Version, + "taskArn": task.Arn, + "taskKnownStatus": task.KnownStatusUnsafe.String(), + "taskDesiredStatus": task.DesiredStatusUnsafe.String(), + "nContainers": len(task.Containers), + "nENIs": len(task.ENIs), + } +} + // GetID is used to retrieve the taskID from taskARN // Reference: http://docs.aws.amazon.com/general/latest/gr/aws-arns-and-namespaces.html#arn-syntax-ecs func (task *Task) GetID() string { diff --git a/agent/eventhandler/task_handler.go b/agent/eventhandler/task_handler.go index 54629da2845..be1e7ab0493 100644 --- a/agent/eventhandler/task_handler.go +++ b/agent/eventhandler/task_handler.go @@ -184,9 +184,8 @@ func (handler *TaskHandler) startDrainEventsTicker() { // the tasksToContainerStates and tasksToManagedAgentStates maps based on the // task arns of containers and managed agents that haven't been sent to ECS yet. for _, taskEvent := range handler.taskStateChangesToSend() { - seelog.Infof( - "TaskHandler: Adding a state change event to send batched container/managed agent events: %s", - taskEvent.String()) + logger.Debug("TaskHandler: Adding a state change event to send batched container/managed agent events", + taskEvent.ToFields()) // Force start the the task state change submission // workflow by calling AddStateChangeEvent method. handler.AddStateChangeEvent(taskEvent, handler.client)