Skip to content

Commit

Permalink
More structured logging for Task object
Browse files Browse the repository at this point in the history
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"
```
  • Loading branch information
sparrc committed May 5, 2023
1 parent a15af5b commit 28763cd
Show file tree
Hide file tree
Showing 2 changed files with 20 additions and 14 deletions.
29 changes: 18 additions & 11 deletions agent/api/task/task.go
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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)
Expand All @@ -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())
}
}
}
Expand Down Expand Up @@ -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 {
Expand Down
5 changes: 2 additions & 3 deletions agent/eventhandler/task_handler.go
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down

0 comments on commit 28763cd

Please sign in to comment.