Custom contextual loggers (#2319)

* Add custom context to logs

1. added ability to create custom loggers for structs and add custom
context
2. implements custom loggers for a few selected structs

* Use logger.Contextual for custom struct logs

* Fixing broke tests

* factor reusable code out of formatters

agent/acs/handler/payload_handler_test.go

@@ -16,9 +16,10 @@ package handler
 
 import (
 	"context"
+	"encoding/json"
 	"errors"
 	"fmt"
-	"reflect"
+	"runtime"
 	"sync"
 	"testing"
 
@@ -33,11 +34,11 @@ import (
 	"github.com/aws/amazon-ecs-agent/agent/eventhandler"
 	"github.com/aws/amazon-ecs-agent/agent/statemanager"
 	mock_statemanager "github.com/aws/amazon-ecs-agent/agent/statemanager/mocks"
-	"github.com/aws/amazon-ecs-agent/agent/taskresource"
 	mock_wsclient "github.com/aws/amazon-ecs-agent/agent/wsclient/mock"
 	"github.com/aws/aws-sdk-go/aws"
 	"github.com/golang/mock/gomock"
 	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
 )
 
 const (
@@ -147,13 +148,7 @@ func TestHandlePayloadMessageStateSaveError(t *testing.T) {
 	})
 	assert.Error(t, err, "Expected error while adding a task from statemanager")
 
-	// We expect task to be added to the engine even though it hasn't been saved
-	expectedTask := &apitask.Task{
-		Arn:                "t1",
-		ResourcesMapUnsafe: make(map[string][]taskresource.TaskResource),
-	}
-
-	assert.Equal(t, addedTask, expectedTask, "added task is not expected")
+	validateTask(t, addedTask, "t1")
 }
 
 // TestHandlePayloadMessageAckedWhenTaskAdded tests if the handler generates an ack
@@ -194,12 +189,7 @@ func TestHandlePayloadMessageAckedWhenTaskAdded(t *testing.T) {
 	// Verify the message id acked
 	assert.Equal(t, aws.StringValue(ackRequested.MessageId), payloadMessageId, "received message is not expected")
 
-	// Verify if task added == expected task
-	expectedTask := &apitask.Task{
-		Arn:                "t1",
-		ResourcesMapUnsafe: make(map[string][]taskresource.TaskResource),
-	}
-	assert.Equal(t, addedTask, expectedTask, "received task is not expected")
+	validateTask(t, addedTask, "t1")
 }
 
 // TestHandlePayloadMessageCredentialsAckedWhenTaskAdded tests if the handler generates
@@ -290,8 +280,7 @@ func TestHandlePayloadMessageCredentialsAckedWhenTaskAdded(t *testing.T) {
 		SessionToken:    credentialsSessionToken,
 		CredentialsID:   credentialsId,
 	}
-	err = validateTaskAndCredentials(taskCredentialsAckRequested, expectedCredentialsAck, addedTask, taskArn, expectedCredentials)
-	assert.NoError(t, err, "error validating added task or credentials ack for the same")
+	validateTaskAndCredentials(t, taskCredentialsAckRequested, expectedCredentialsAck, addedTask, taskArn, expectedCredentials, "t1")
 }
 
 // TestAddPayloadTaskAddsNonStoppedTasksAfterStoppedTasks tests if tasks with desired status
@@ -371,12 +360,7 @@ func TestPayloadBufferHandler(t *testing.T) {
 	// Verify if payloadMessageId read from the ack buffer is correct
 	assert.Equal(t, aws.StringValue(ackRequested.MessageId), payloadMessageId, "received task is not expected")
 
-	// Verify if the task added to the engine is correct
-	expectedTask := &apitask.Task{
-		Arn:                taskArn,
-		ResourcesMapUnsafe: make(map[string][]taskresource.TaskResource),
-	}
-	assert.Equal(t, addedTask, expectedTask, "received task is not expected")
+	validateTask(t, addedTask, "t1")
 }
 
 // TestPayloadBufferHandlerWithCredentials tests if the async payloadBufferHandler routine
@@ -495,8 +479,7 @@ func TestPayloadBufferHandlerWithCredentials(t *testing.T) {
 		SessionToken:    firstTaskCredentialsSessionToken,
 		CredentialsID:   firstTaskCredentialsId,
 	}
-	err := validateTaskAndCredentials(firstTaskCredentialsAckRequested, expectedCredentialsAckForFirstTask, firstAddedTask, firstTaskArn, expectedCredentialsForFirstTask)
-	assert.NoError(t, err, "error validating added task or credentials ack for the same")
+	validateTaskAndCredentials(t, firstTaskCredentialsAckRequested, expectedCredentialsAckForFirstTask, firstAddedTask, firstTaskArn, expectedCredentialsForFirstTask, "t1")
 
 	// Verify the correctness of the second task added to the engine and the
 	// credentials ack generated for it
@@ -513,8 +496,7 @@ func TestPayloadBufferHandlerWithCredentials(t *testing.T) {
 		SessionToken:    secondTaskCredentialsSessionToken,
 		CredentialsID:   secondTaskCredentialsId,
 	}
-	err = validateTaskAndCredentials(secondTaskCredentialsAckRequested, expectedCredentialsAckForSecondTask, secondAddedTask, secondTaskArn, expectedCredentialsForSecondTask)
-	assert.NoError(t, err, "error validating added task or credentials ack for the same")
+	validateTaskAndCredentials(t, secondTaskCredentialsAckRequested, expectedCredentialsAckForSecondTask, secondAddedTask, secondTaskArn, expectedCredentialsForSecondTask, "t2")
 }
 
 // TestAddPayloadTaskAddsExecutionRoles tests the payload handler will add
@@ -596,24 +578,18 @@ func TestAddPayloadTaskAddsExecutionRoles(t *testing.T) {
 // validateTaskAndCredentials compares a task and a credentials ack object
 // against expected values. It returns an error if either of the the
 // comparisons fail
-func validateTaskAndCredentials(taskCredentialsAck, expectedCredentialsAckForTask *ecsacs.IAMRoleCredentialsAckRequest,
+func validateTaskAndCredentials(
+	t *testing.T,
+	taskCredentialsAck *ecsacs.IAMRoleCredentialsAckRequest,
+	expectedCredentialsAckForTask *ecsacs.IAMRoleCredentialsAckRequest,
 	addedTask *apitask.Task,
 	expectedTaskArn string,
-	expectedTaskCredentials credentials.IAMRoleCredentials) error {
-	if !reflect.DeepEqual(taskCredentialsAck, expectedCredentialsAckForTask) {
-		return fmt.Errorf("Mismatch between expected and received credentials ack requests, expected: %s, got: %s", expectedCredentialsAckForTask.String(), taskCredentialsAck.String())
-	}
-
-	expectedTask := &apitask.Task{
-		Arn:                expectedTaskArn,
-		ResourcesMapUnsafe: make(map[string][]taskresource.TaskResource),
-	}
-	expectedTask.SetCredentialsID(expectedTaskCredentials.CredentialsID)
-
-	if !reflect.DeepEqual(addedTask, expectedTask) {
-		return fmt.Errorf("Mismatch between expected and added tasks, expected: %v, added: %v", expectedTask, addedTask)
-	}
-	return nil
+	expectedTaskCredentials credentials.IAMRoleCredentials,
+	taskName string,
+) {
+	require.Equal(t, expectedCredentialsAckForTask, taskCredentialsAck)
+	require.Equal(t, expectedTaskCredentials.CredentialsID, addedTask.GetCredentialsID())
+	validateTask(t, addedTask, taskName)
 }
 
 func TestPayloadHandlerAddedENIToTask(t *testing.T) {
@@ -949,3 +925,37 @@ func TestPayloadHandlerAddedFirelensData(t *testing.T) {
 	assert.NotNil(t, actual.Options)
 	assert.Equal(t, aws.StringValue(expected.Options["enable-ecs-log-metadata"]), actual.Options["enable-ecs-log-metadata"])
 }
+
+func validateTask(t *testing.T, addedTask *apitask.Task, expectedTaskName string) {
+	// We expect task to be added to the engine even though it hasn't been saved
+	addedTaskJSON, err := json.Marshal(addedTask)
+	require.NoError(t, err)
+	platformFields := "{}"
+	if runtime.GOOS == "windows" {
+		platformFields = `{"cpuUnbounded": false, "memoryUnbounded": false}`
+	}
+	expectedTaskJSON := fmt.Sprintf(`
+	{
+		"Arn": "%s",
+		"Family": "",
+		"Version": "",
+		"Containers": null,
+		"associations": null,
+		"resources": {},
+		"volumes": null,
+		"DesiredStatus": "NONE",
+		"KnownStatus": "NONE",
+		"KnownTime": "0001-01-01T00:00:00Z",
+		"PullStartedAt": "0001-01-01T00:00:00Z",
+		"PullStoppedAt": "0001-01-01T00:00:00Z",
+		"ExecutionStoppedAt": "0001-01-01T00:00:00Z",
+		"SentStatus": "NONE",
+		"StartSequenceNumber": 0,
+		"StopSequenceNumber": 0,
+		"executionCredentialsID": "",
+		"ENI": null,
+		"AppMesh": null,
+		"PlatformFields": %s
+	}`, expectedTaskName, platformFields)
+	require.JSONEq(t, expectedTaskJSON, string(addedTaskJSON))
+}

agent/api/container/container.go

@@ -1001,7 +1001,7 @@ func (c *Container) GetLogDriver() string {
 	hostConfig := &dockercontainer.HostConfig{}
 	err := json.Unmarshal([]byte(*c.DockerConfig.HostConfig), hostConfig)
 	if err != nil {
-		seelog.Warnf("Encountered error when trying to get log driver for container %s: %v", err)
+		seelog.Warnf("Encountered error when trying to get log driver for container %s: %v", c.String(), err)
 		return ""
 	}
 
@@ -1021,7 +1021,7 @@ func (c *Container) GetNetworkModeFromHostConfig() string {
 	// TODO return error to differentiate between error and default mode .
 	err := json.Unmarshal([]byte(*c.DockerConfig.HostConfig), hostConfig)
 	if err != nil {
-		seelog.Warnf("Encountered error when trying to get network mode for container %s: %v", err)
+		seelog.Warnf("Encountered error when trying to get network mode for container %s: %v", c.String(), err)
 		return ""
 	}
 

agent/api/task/json.go

@@ -28,3 +28,17 @@ func (t *Task) MarshalJSON() ([]byte, error) {
 
 	return json.Marshal((*jTask)(t))
 }
+
+// UnmarshalJSON wraps Go's unmarshalling logic to guarantee that the logger gets created
+func (t *Task) UnmarshalJSON(data []byte) error {
+	err := json.Unmarshal(data, (*jTask)(t))
+	if err != nil {
+		return err
+	}
+	t.log.SetContext(map[string]string{
+		"taskARN":     t.Arn,
+		"taskFamily":  t.Family,
+		"taskVersion": t.Version,
+	})
+	return nil
+}