Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Task state change logging: use logger.Fields instead of plain strings #3674

Merged
merged 1 commit into from
May 5, 2023
Merged

Task state change logging: use logger.Fields instead of plain strings #3674

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
53 changes: 46 additions & 7 deletions agent/api/statechange.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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"

Expand Down Expand Up @@ -223,29 +224,42 @@ func NewAttachmentStateChangeEvent(eniAttachment *apieni.ENIAttachment) Attachme
}
}

func (c *ContainerStateChange) ToFields() logger.Fields {
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this function is somewhat moot since we don't send container state changes anymore, but added it just for consistency with TaskStateChange code

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
}
Expand Down Expand Up @@ -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())
Expand Down
18 changes: 9 additions & 9 deletions agent/eventhandler/task_handler.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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 {
Expand All @@ -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())
}
}

Expand Down Expand Up @@ -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
}
Expand All @@ -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)
}
}
25 changes: 8 additions & 17 deletions agent/eventhandler/task_handler_types.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,7 +15,6 @@ package eventhandler

import (
"container/list"
"fmt"
"sync"

"github.com/aws/amazon-ecs-agent/agent/logger"
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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()
}
}

Expand Down
6 changes: 3 additions & 3 deletions agent/eventhandler/task_handler_types_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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())
Expand Down Expand Up @@ -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())
Expand Down