Task state change logging refactor

Author: sparrc

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",
+			c.Container.GetSentStatus().String(), c.Container.GetRuntimeID())
 	}
 	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,29 @@ 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,
+		"taskKnownSentStatus":    change.Task.GetSentStatus().String(),
+		"taskPullStartedAt":      change.Task.GetPullStartedAt().UTC().Format(time.RFC3339),
+		"taskPullStoppedAt":      change.Task.GetPullStoppedAt().UTC().Format(time.RFC3339),
+		"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())

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)
 	}
 }

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()
 	}
 }
 

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())