diff --git a/agent/api/statechange.go b/agent/api/statechange.go index f828b63434d..042aed8ef79 100644 --- a/agent/api/statechange.go +++ b/agent/api/statechange.go @@ -23,6 +23,7 @@ import ( apieni "github.com/aws/amazon-ecs-agent/agent/api/eni" apitask "github.com/aws/amazon-ecs-agent/agent/api/task" apitaskstatus "github.com/aws/amazon-ecs-agent/agent/api/task/status" + "github.com/aws/amazon-ecs-agent/agent/logger" "github.com/aws/amazon-ecs-agent/agent/statechange" "github.com/pkg/errors" @@ -223,29 +224,42 @@ func NewAttachmentStateChangeEvent(eniAttachment *apieni.ENIAttachment) Attachme } } +func (c *ContainerStateChange) ToFields() logger.Fields { + return logger.Fields{ + "eventType": "ContainerStateChange", + "taskArn": c.TaskArn, + "containerName": c.ContainerName, + "containerStatus": c.Status.String(), + "exitCode": strconv.Itoa(*c.ExitCode), + "reason": c.Reason, + "portBindings": c.PortBindings, + } +} + // String returns a human readable string representation of this object func (c *ContainerStateChange) String() string { - res := fmt.Sprintf("%s %s -> %s", c.TaskArn, c.ContainerName, c.Status.String()) + res := fmt.Sprintf("containerName=%s containerStatus=%s", c.ContainerName, c.Status.String()) if c.ExitCode != nil { - res += ", Exit " + strconv.Itoa(*c.ExitCode) + ", " + res += " containerExitCode=" + strconv.Itoa(*c.ExitCode) } if c.Reason != "" { - res += ", Reason " + c.Reason + res += " containerReason=" + c.Reason } if len(c.PortBindings) != 0 { - res += fmt.Sprintf(", Ports %v", c.PortBindings) + res += fmt.Sprintf(" containerPortBindings=%v", c.PortBindings) } if c.Container != nil { - res += ", Known Sent: " + c.Container.GetSentStatus().String() + res += fmt.Sprintf(" containerKnownSentStatus=%s containerRuntimeID=%s containerIsEssential=%v", + c.Container.GetSentStatus().String(), c.Container.GetRuntimeID(), c.Container.IsEssential()) } return res } // String returns a human readable string representation of ManagedAgentStateChange func (m *ManagedAgentStateChange) String() string { - res := fmt.Sprintf("%s %s %s -> %s", m.TaskArn, m.Container.Name, m.Name, m.Status.String()) + res := fmt.Sprintf("containerName=%s managedAgentName=%s managedAgentStatus=%s", m.Container.Name, m.Name, m.Status.String()) if m.Reason != "" { - res += ", Reason " + m.Reason + res += " managedAgentReason=" + m.Reason } return res } @@ -287,6 +301,31 @@ func (change *TaskStateChange) ShouldBeReported() bool { return false } +func (change *TaskStateChange) ToFields() logger.Fields { + fields := logger.Fields{ + "eventType": "TaskStateChange", + "taskArn": change.TaskARN, + "taskStatus": change.Status.String(), + "taskReason": change.Reason, + } + if change.Task != nil { + fields["taskKnownSentStatus"] = change.Task.GetSentStatus().String() + fields["taskPullStartedAt"] = change.Task.GetPullStartedAt().UTC().Format(time.RFC3339) + fields["taskPullStoppedAt"] = change.Task.GetPullStoppedAt().UTC().Format(time.RFC3339) + fields["taskExecutionStoppedAt"] = change.Task.GetExecutionStoppedAt().UTC().Format(time.RFC3339) + } + if change.Attachment != nil { + fields["eniAttachment"] = change.Attachment.String() + } + for i, containerChange := range change.Containers { + fields["containerChange-"+strconv.Itoa(i)] = containerChange.String() + } + for i, managedAgentChange := range change.ManagedAgents { + fields["managedAgentChange-"+strconv.Itoa(i)] = managedAgentChange.String() + } + return fields +} + // String returns a human readable string representation of this object func (change *TaskStateChange) String() string { res := fmt.Sprintf("%s -> %s", change.TaskARN, change.Status.String()) diff --git a/agent/eventhandler/task_handler.go b/agent/eventhandler/task_handler.go index 1c13a4d26e4..54629da2845 100644 --- a/agent/eventhandler/task_handler.go +++ b/agent/eventhandler/task_handler.go @@ -26,6 +26,7 @@ import ( "github.com/aws/amazon-ecs-agent/agent/data" "github.com/aws/amazon-ecs-agent/agent/ecs_client/model/ecs" "github.com/aws/amazon-ecs-agent/agent/engine/dockerstate" + "github.com/aws/amazon-ecs-agent/agent/logger" "github.com/aws/amazon-ecs-agent/agent/metrics" "github.com/aws/amazon-ecs-agent/agent/statechange" "github.com/aws/amazon-ecs-agent/agent/utils" @@ -310,8 +311,7 @@ func (handler *TaskHandler) getTaskEventsUnsafe(event *sendableEvent) *taskSenda taskARN: taskARN, } handler.tasksToEvents[taskARN] = taskEvents - seelog.Debugf("TaskHandler: collecting events for new task; event: %s; events: %s ", - event.toString(), taskEvents.toStringUnsafe()) + logger.Debug(fmt.Sprintf("TaskHandler: collecting events for new task; events: %s", taskEvents.toStringUnsafe()), event.toFields()) } return taskEvents @@ -366,7 +366,7 @@ func (taskEvents *taskSendableEvents) sendChange(change *sendableEvent, defer taskEvents.lock.Unlock() // Add event to the queue - seelog.Debugf("TaskHandler: Adding event: %s", change.toString()) + logger.Debug("TaskHandler: Adding event", change.toFields()) taskEvents.events.PushBack(change) if !taskEvents.sending { @@ -375,9 +375,9 @@ func (taskEvents *taskSendableEvents) sendChange(change *sendableEvent, taskEvents.sending = true go handler.submitTaskEvents(taskEvents, client, change.taskArn()) } else { - seelog.Debugf( - "TaskHandler: Not submitting change as the task is already being sent: %s", - change.toString()) + logger.Debug( + "TaskHandler: Not submitting change as the task is already being sent", + change.toFields()) } } @@ -422,12 +422,12 @@ func (taskEvents *taskSendableEvents) submitFirstEvent(handler *TaskHandler, bac } } else { // Shouldn't be sent as either a task or container change event; must have been already sent - seelog.Infof("TaskHandler: Not submitting redundant event; just removing: %s", event.toString()) + logger.Info("TaskHandler: Not submitting redundant event; just removing", event.toFields()) taskEvents.events.Remove(eventToSubmit) } if taskEvents.events.Len() == 0 { - seelog.Debug("TaskHandler: Removed the last element, no longer sending") + logger.Debug("TaskHandler: Removed the last element, no longer sending") taskEvents.sending = false return true, nil } @@ -445,7 +445,7 @@ func (taskEvents *taskSendableEvents) toStringUnsafe() string { func handleInvalidParamException(err error, events *list.List, eventToSubmit *list.Element) { if utils.IsAWSErrorCodeEqual(err, ecs.ErrCodeInvalidParameterException) { event := eventToSubmit.Value.(*sendableEvent) - seelog.Warnf("TaskHandler: Event is sent with invalid parameters; just removing: %s", event.toString()) + logger.Warn("TaskHandler: Event is sent with invalid parameters; just removing", event.toFields()) events.Remove(eventToSubmit) } } diff --git a/agent/eventhandler/task_handler_types.go b/agent/eventhandler/task_handler_types.go index 4df3eedfb3b..f749b5ab2ab 100644 --- a/agent/eventhandler/task_handler_types.go +++ b/agent/eventhandler/task_handler_types.go @@ -15,7 +15,6 @@ package eventhandler import ( "container/list" - "fmt" "sync" "github.com/aws/amazon-ecs-agent/agent/logger" @@ -152,27 +151,19 @@ func (event *sendableEvent) send( backoff retry.Backoff, taskEvents *taskSendableEvents) error { - logger.Info("Sending state change to ECS", logger.Fields{ - "eventType": eventType, - "eventData": event.toString(), - }) + fields := event.toFields() + logger.Info("Sending state change to ECS", fields) // Try submitting the change to ECS if err := sendStatusToECS(client, event); err != nil { - logger.Error("Unretriable error sending state change to ECS", logger.Fields{ - "eventType": eventType, - "eventData": event.toString(), - field.Error: err, - }) + fields[field.Error] = err + logger.Error("Unretriable error sending state change to ECS", fields) return err } // submitted; ensure we don't retry it event.setSent() // Mark event as sent setChangeSent(event, dataClient) - logger.Debug("Submitted state change to ECS", logger.Fields{ - "eventType": eventType, - "eventData": event.toString(), - }) + logger.Debug("Submitted state change to ECS", fields) taskEvents.events.Remove(eventToSubmit) backoff.Reset() return nil @@ -234,14 +225,14 @@ func setTaskAttachmentSent(event *sendableEvent, dataClient data.Client) { } } -func (event *sendableEvent) toString() string { +func (event *sendableEvent) toFields() logger.Fields { event.lock.RLock() defer event.lock.RUnlock() if event.isContainerEvent { - return "ContainerChange: [" + event.containerChange.String() + fmt.Sprintf("] sent: %t", event.containerSent) + return event.containerChange.ToFields() } else { - return "TaskChange: [" + event.taskChange.String() + fmt.Sprintf("] sent: %t", event.taskSent) + return event.taskChange.ToFields() } } diff --git a/agent/eventhandler/task_handler_types_test.go b/agent/eventhandler/task_handler_types_test.go index 4842da5d494..9666a845002 100644 --- a/agent/eventhandler/task_handler_types_test.go +++ b/agent/eventhandler/task_handler_types_test.go @@ -257,7 +257,7 @@ func TestShouldTaskEventBeSent(t *testing.T) { shouldBeSent: false, }, } { - t.Run(fmt.Sprintf("Event[%s] should be sent[%t]", tc.event.toString(), tc.shouldBeSent), func(t *testing.T) { + t.Run(fmt.Sprintf("Event[%v] should be sent[%t]", tc.event.toFields(), tc.shouldBeSent), func(t *testing.T) { assert.Equal(t, tc.shouldBeSent, tc.event.taskShouldBeSent()) assert.Equal(t, false, tc.event.containerShouldBeSent()) assert.Equal(t, false, tc.event.taskAttachmentShouldBeSent()) @@ -331,8 +331,8 @@ func TestShouldTaskAttachmentEventBeSent(t *testing.T) { taskShouldBeSent: false, }, } { - t.Run(fmt.Sprintf("Event[%s] should be sent[attachment=%t;task=%t]", - tc.event.toString(), tc.attachmentShouldBeSent, tc.taskShouldBeSent), func(t *testing.T) { + t.Run(fmt.Sprintf("Event[%v] should be sent[attachment=%t;task=%t]", + tc.event.toFields(), tc.attachmentShouldBeSent, tc.taskShouldBeSent), func(t *testing.T) { assert.Equal(t, tc.attachmentShouldBeSent, tc.event.taskAttachmentShouldBeSent()) assert.Equal(t, tc.taskShouldBeSent, tc.event.taskShouldBeSent()) assert.Equal(t, false, tc.event.containerShouldBeSent())