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

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,13 @@ 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.initLog()
+	return nil
+}

agent/dockerclient/dockerapi/types.go

@@ -153,3 +153,15 @@ func (event *DockerContainerChangeEvent) String() string {
 
 	return res
 }
+
+// String returns a short human readable string of the container change event
+func (event *DockerContainerChangeEvent) ShortString() string {
+	res := fmt.Sprintf("event type: %s, event container status: %s, docker ID: %s",
+		event.Type.String(), event.Status.String(), event.DockerID)
+
+	if event.ExitCode != nil {
+		res += fmt.Sprintf(", ExitCode: %d", aws.IntValue(event.ExitCode))
+	}
+
+	return res
+}

agent/engine/docker_task_engine.go

@@ -1392,7 +1392,7 @@ func (engine *DockerTaskEngine) applyContainerState(task *apitask.Task, containe
 	}
 	metadata := transitionFunction(task, container)
 	if metadata.Error != nil {
-		seelog.Infof("Task engine [%s]: error transitioning container [%s] to [%s]: %v",
+		seelog.Errorf("Task engine [%s]: error transitioning container [%s] to [%s]: %v",
 			task.Arn, container.Name, nextState.String(), metadata.Error)
 	} else {
 		seelog.Debugf("Task engine [%s]: transitioned container [%s] to [%s]",

agent/logger/log.go

@@ -16,6 +16,7 @@ package logger
 import (
 	"fmt"
 	"os"
+	"sort"
 	"strconv"
 	"strings"
 	"sync"
@@ -53,24 +54,32 @@ var Config *logConfig
 
 func logfmtFormatter(params string) seelog.FormatterFunc {
 	return func(message string, level seelog.LogLevel, context seelog.LogContextInterface) interface{} {
-		return fmt.Sprintf(`level=%s time=%s msg=%q module=%s
-`, level.String(), context.CallTime().UTC().Format(time.RFC3339), message, context.FileName())
+		cc, ok := context.CustomContext().(map[string]string)
+		var customContext string
+		if ok && len(cc) > 0 {
+			var sortedContext []string
+			for k, v := range cc {
+				sortedContext = append(sortedContext, k+"="+v)
+			}
+			sort.Strings(sortedContext)
+			customContext = " " + strings.Join(sortedContext, " ")
+		}
+		return fmt.Sprintf(`level=%s time=%s msg=%q module=%s%s
+`, level.String(), context.CallTime().UTC().Format(time.RFC3339), message, context.FileName(), customContext)
 	}
 }
 
 func jsonFormatter(params string) seelog.FormatterFunc {
 	return func(message string, level seelog.LogLevel, context seelog.LogContextInterface) interface{} {
-		return fmt.Sprintf(`{"level": %q, "time": %q, "msg": %q, "module": %q}
-`, level.String(), context.CallTime().UTC().Format(time.RFC3339), message, context.FileName())
-	}
-}
-
-func reloadConfig() {
-	logger, err := seelog.LoggerFromConfigAsString(seelogConfig())
-	if err == nil {
-		seelog.ReplaceLogger(logger)
-	} else {
-		seelog.Error(err)
+		cc, ok := context.CustomContext().(map[string]string)
+		var customContext string
+		if ok && len(cc) > 0 {
+			for k, v := range cc {
+				customContext += fmt.Sprintf(", %q: %q", k, v)
+			}
+		}
+		return fmt.Sprintf(`{"level": %q, "time": %q, "msg": %q, "module": %q%s}
+`, level.String(), context.CallTime().UTC().Format(time.RFC3339), message, context.FileName(), customContext)
 	}
 }
 
@@ -117,7 +126,7 @@ func SetLevel(logLevel string) {
 		Config.lock.Lock()
 		defer Config.lock.Unlock()
 		Config.level = parsedLevel
-		reloadConfig()
+		reloadMainConfig()
 	}
 }
 
@@ -129,6 +138,24 @@ func GetLevel() string {
 	return Config.level
 }
 
+func InitLogger() seelog.LoggerInterface {
+	logger, err := seelog.LoggerFromConfigAsString(seelogConfig())
+	if err != nil {
+		seelog.Errorf("Error creating seelog logger: %s", err)
+		return seelog.Default
+	}
+	return logger
+}
+
+func reloadMainConfig() {
+	logger, err := seelog.LoggerFromConfigAsString(seelogConfig())
+	if err == nil {
+		seelog.ReplaceLogger(logger)
+	} else {
+		seelog.Error(err)
+	}
+}
+
 func init() {
 	Config = &logConfig{
 		logfile:       os.Getenv(LOGFILE_ENV_VAR),
@@ -139,7 +166,9 @@ func init() {
 		MaxRollCount:  DEFAULT_MAX_ROLL_COUNT,
 	}
 
-	SetLevel(os.Getenv(LOGLEVEL_ENV_VAR))
+	if level := os.Getenv(LOGLEVEL_ENV_VAR); level != "" {
+		SetLevel(level)
+	}
 	if RolloverType := os.Getenv(LOG_ROLLOVER_TYPE_ENV_VAR); RolloverType != "" {
 		Config.RolloverType = RolloverType
 	}
@@ -169,7 +198,6 @@ func init() {
 	if err := seelog.RegisterCustomFormatter("EcsAgentJson", jsonFormatter); err != nil {
 		seelog.Error(err)
 	}
-
 	registerPlatformLogger()
-	reloadConfig()
+	seelog.ReplaceLogger(InitLogger())
 }

agent/logger/log_test.go

@@ -32,12 +32,53 @@ func TestLogfmtFormat(t *testing.T) {
 `, s)
 }
 
+func TestLogfmtFormat_context(t *testing.T) {
+	logfmt := logfmtFormatter("")
+	out := logfmt("This is my log message", seelog.InfoLvl, &LogContextMock{
+		context: map[string]string{
+			"myID":  "12345",
+			"myARN": "arn:12345:/abc",
+		},
+	})
+	s, ok := out.(string)
+	require.True(t, ok)
+	require.Equal(t, `level=info time=2018-10-01T01:02:03Z msg="This is my log message" module=mytestmodule.go myARN=arn:12345:/abc myID=12345
+`, s)
+}
+
 func TestJSONFormat(t *testing.T) {
 	jsonF := jsonFormatter("")
 	out := jsonF("This is my log message", seelog.InfoLvl, &LogContextMock{})
 	s, ok := out.(string)
 	require.True(t, ok)
-	require.JSONEq(t, `{"level": "info", "time": "2018-10-01T01:02:03Z", "msg": "This is my log message", "module": "mytestmodule.go"}`, s)
+	require.JSONEq(t, `
+		{
+			"level": "info",
+			"time": "2018-10-01T01:02:03Z",
+			"msg": "This is my log message",
+			"module": "mytestmodule.go"
+		}`, s)
+}
+
+func TestJSONFormat_context(t *testing.T) {
+	jsonF := jsonFormatter("")
+	out := jsonF("This is my log message", seelog.InfoLvl, &LogContextMock{
+		context: map[string]string{
+			"myID":  "12345",
+			"myARN": "arn:12345:/abc",
+		},
+	})
+	s, ok := out.(string)
+	require.True(t, ok)
+	require.JSONEq(t, `
+	{
+		"level": "info",
+		"time": "2018-10-01T01:02:03Z",
+		"msg": "This is my log message",
+		"module": "mytestmodule.go",
+		"myARN":"arn:12345:/abc",
+		"myID":"12345"
+	}`, s)
 }
 
 func TestLogfmtFormat_debug(t *testing.T) {
@@ -54,7 +95,13 @@ func TestJSONFormat_debug(t *testing.T) {
 	out := jsonF("This is my log message", seelog.DebugLvl, &LogContextMock{})
 	s, ok := out.(string)
 	require.True(t, ok)
-	require.JSONEq(t, `{"level": "debug", "time": "2018-10-01T01:02:03Z", "msg": "This is my log message", "module": "mytestmodule.go"}`, s)
+	require.JSONEq(t, `
+		{
+			"level": "debug",
+			"time": "2018-10-01T01:02:03Z",
+			"msg": "This is my log message",
+			"module": "mytestmodule.go"
+		}`, s)
 }
 
 func TestSeelogConfig_Default(t *testing.T) {
@@ -201,7 +248,9 @@ func TestSeelogConfig_JSONOutput(t *testing.T) {
 </seelog>`, c)
 }
 
-type LogContextMock struct{}
+type LogContextMock struct {
+	context map[string]string
+}
 
 // Caller's function name.
 func (l *LogContextMock) Func() string {
@@ -242,5 +291,5 @@ func (l *LogContextMock) CallTime() time.Time {
 
 // Custom context that can be set by calling logger.SetContext
 func (l *LogContextMock) CustomContext() interface{} {
-	return map[string]string{}
+	return l.context
 }

agent/taskresource/cgroup/cgroup.go

@@ -23,6 +23,7 @@ import (
 	"time"
 
 	"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/taskresource"
 	control "github.com/aws/amazon-ecs-agent/agent/taskresource/cgroup/control"
 	resourcestatus "github.com/aws/amazon-ecs-agent/agent/taskresource/status"
@@ -64,6 +65,8 @@ type CgroupResource struct {
 	statusToTransitions map[resourcestatus.ResourceStatus]func() error
 	// lock is used for fields that are accessed and updated concurrently
 	lock sync.RWMutex
+	// log is a custom logger with extra context specific to the cgroup struct
+	log seelog.LoggerInterface
 }
 
 // NewCgroupResource is used to return an object that implements the Resource interface
@@ -82,9 +85,22 @@ func NewCgroupResource(taskARN string,
 		resourceSpec:    resourceSpec,
 	}
 	c.initializeResourceStatusToTransitionFunction()
+	c.initLog()
 	return c
 }
 
+func (cgroup *CgroupResource) initLog() {
+	if cgroup.log == nil {
+		cgroup.log = logger.InitLogger()
+		cgroup.log.SetContext(map[string]string{
+			"taskARN":         cgroup.taskARN,
+			"cgroupRoot":      cgroup.cgroupRoot,
+			"cgroupMountPath": cgroup.cgroupMountPath,
+			"resourceName":    resourceName,
+		})
+	}
+}
+
 // GetTerminalReason returns an error string to propagate up through to task
 // state change messages
 func (cgroup *CgroupResource) GetTerminalReason() string {
@@ -159,8 +175,7 @@ func (cgroup *CgroupResource) NextKnownState() resourcestatus.ResourceStatus {
 func (cgroup *CgroupResource) ApplyTransition(nextState resourcestatus.ResourceStatus) error {
 	transitionFunc, ok := cgroup.statusToTransitions[nextState]
 	if !ok {
-		seelog.Errorf("Cgroup Resource [%s]: unsupported desired state transition [%s]: %s",
-			cgroup.taskARN, cgroup.GetName(), cgroup.StatusString(nextState))
+		cgroup.log.Errorf("unsupported desired state transition %s", cgroup.StatusString(nextState))
 		return errors.Errorf("resource [%s]: transition to %s impossible", cgroup.GetName(),
 			cgroup.StatusString(nextState))
 	}
@@ -244,18 +259,18 @@ func (cgroup *CgroupResource) GetCreatedAt() time.Time {
 func (cgroup *CgroupResource) Create() error {
 	err := cgroup.setupTaskCgroup()
 	if err != nil {
-		seelog.Criticalf("Cgroup resource [%s]: unable to setup cgroup root: %v", cgroup.taskARN, err)
+		cgroup.log.Errorf("unable to setup cgroup root: %v", err)
 		return err
 	}
 	return nil
 }
 
 func (cgroup *CgroupResource) setupTaskCgroup() error {
 	cgroupRoot := cgroup.cgroupRoot
-	seelog.Debugf("Cgroup resource [%s]: setting up cgroup at: %s", cgroup.taskARN, cgroupRoot)
+	cgroup.log.Info("setting up cgroup")
 
 	if cgroup.control.Exists(cgroupRoot) {
-		seelog.Debugf("Cgroup resource [%s]: cgroup at %s already exists, skipping creation", cgroup.taskARN, cgroupRoot)
+		cgroup.log.Infof("cgroup at root already exists, skipping creation")
 		return nil
 	}
 
@@ -285,7 +300,7 @@ func (cgroup *CgroupResource) Cleanup() error {
 	// Explicitly handle cgroup deleted error
 	if err != nil {
 		if err == cgroups.ErrCgroupDeleted {
-			seelog.Warnf("Cgroup at %s has already been removed: %v", cgroup.cgroupRoot, err)
+			cgroup.log.Warnf("Cgroup at root has already been removed: %v", err)
 			return nil
 		}
 		return errors.Wrapf(err, "resource: cleanup cgroup: unable to remove cgroup at %s", cgroup.cgroupRoot)
@@ -343,6 +358,7 @@ func (cgroup *CgroupResource) UnmarshalJSON(b []byte) error {
 	if temp.KnownStatus != nil {
 		cgroup.SetKnownStatus(resourcestatus.ResourceStatus(*temp.KnownStatus))
 	}
+	cgroup.initLog()
 	return nil
 }