Add log message for task CNI setup, and other log mods

.github/workflows/windows.yml

@@ -40,4 +40,4 @@ jobs:
           gcc --version
           $env:ZZZ_SKIP_WINDOWS_SERVER_VERSION_CHECK_NOT_SUPPORTED_IN_PRODUCTION = 'true'
           $packages=go list .\... | Where-Object {$_ -NotMatch 'vendor'}
-          go test -v -tags unit -timeout=40s $packages
+          go test -v -tags unit -timeout=120s $packages

Makefile

@@ -145,15 +145,15 @@ ifneq (${BUILD_PLATFORM},aarch64)
 endif
 
 test:
-	cd agent && GO111MODULE=on ${GOTEST} ${VERBOSE} -tags unit -mod vendor -coverprofile ../cover.out -timeout=60s ./... && cd ..
+	cd agent && GO111MODULE=on ${GOTEST} ${VERBOSE} -tags unit -mod vendor -coverprofile ../cover.out -timeout=120s ./... && cd ..
 	go tool cover -func cover.out > coverprofile.out
 
 test-init:
 	go test -count=1 -short -v -coverprofile cover.out ./ecs-init/...
 	go tool cover -func cover.out > coverprofile-init.out
 
 test-silent:
-	cd agent && GO111MODULE=on ${GOTEST} -tags unit -mod vendor -coverprofile ../cover.out -timeout=60s ./... && cd ..
+	cd agent && GO111MODULE=on ${GOTEST} -tags unit -mod vendor -coverprofile ../cover.out -timeout=120s ./... && cd ..
 	go tool cover -func cover.out > coverprofile.out
 
 .PHONY: analyze-cover-profile
@@ -254,7 +254,7 @@ dockerfree-cni-plugins:
 release-agent-internal: dockerfree-certs dockerfree-cni-plugins static
 	./scripts/build-agent-image
 
-# Default Agent target to build. Pulls cni plugins, builds agent image and save it to disk 
+# Default Agent target to build. Pulls cni plugins, builds agent image and save it to disk
 release-agent: get-cni-sources
 	$(MAKE) release-agent-internal
 
@@ -350,7 +350,7 @@ install-golang:
 .get-deps-stamp:
 	go install github.com/golang/mock/mockgen@v1.6.0
 	go install golang.org/x/tools/cmd/goimports@v0.2.0
-	GO111MODULE=on go install github.com/fzipp/gocyclo/cmd/gocyclo@v0.3.1
+	GO111MODULE=on go install github.com/fzipp/gocyclo/cmd/gocyclo@v0.6.0
 	GO111MODULE=on go install honnef.co/go/tools/cmd/staticcheck@v0.3.2
 	touch .get-deps-stamp
 
@@ -359,7 +359,7 @@ get-deps: .get-deps-stamp
 get-deps-init:
 	go install github.com/golang/mock/mockgen@v1.6.0
 	go install golang.org/x/tools/cmd/goimports@v0.2.0
-	GO111MODULE=on go install github.com/fzipp/gocyclo/cmd/gocyclo@v0.3.1
+	GO111MODULE=on go install github.com/fzipp/gocyclo/cmd/gocyclo@v0.6.0
 	GO111MODULE=on go install honnef.co/go/tools/cmd/staticcheck@v0.3.2
 
 amazon-linux-sources.tgz:

agent/acs/handler/payload_handler_test.go

@@ -217,7 +217,6 @@ func TestHandlePayloadMessageSaveDataError(t *testing.T) {
 		ResourcesMapUnsafe:  make(map[string][]taskresource.TaskResource),
 		NetworkMode:         apitask.BridgeNetworkMode,
 	}
-	expectedTask.GetID() // to set the task setIdOnce (sync.Once) property
 
 	assert.Equal(t, expectedTask, addedTask, "added task is not expected")
 }
@@ -279,7 +278,6 @@ func TestHandlePayloadMessageAckedWhenTaskAdded(t *testing.T) {
 		ResourcesMapUnsafe: make(map[string][]taskresource.TaskResource),
 		NetworkMode:        apitask.BridgeNetworkMode,
 	}
-	expectedTask.GetID() // to set the task setIdOnce (sync.Once) property
 	assert.Equal(t, expectedTask, addedTask, "received task is not expected")
 }
 
@@ -458,7 +456,6 @@ func TestPayloadBufferHandler(t *testing.T) {
 		ResourcesMapUnsafe: make(map[string][]taskresource.TaskResource),
 		NetworkMode:        apitask.BridgeNetworkMode,
 	}
-	expectedTask.GetID() // to set the task setIdOnce (sync.Once) property
 	assert.Equal(t, expectedTask, addedTask, "received task is not expected")
 }
 
@@ -693,7 +690,6 @@ func validateTaskAndCredentials(taskCredentialsAck, expectedCredentialsAckForTas
 		NetworkMode:        apitask.BridgeNetworkMode,
 	}
 	expectedTask.SetCredentialsID(expectedTaskCredentials.CredentialsID)
-	expectedTask.GetID() // to set the task setIdOnce (sync.Once) property
 
 	if !reflect.DeepEqual(addedTask, expectedTask) {
 		return fmt.Errorf("Mismatch between expected and added tasks, expected: %v, added: %v", expectedTask, addedTask)

agent/api/statechange.go

@@ -149,14 +149,14 @@ func NewContainerStateChangeEvent(task *apitask.Task, cont *apicontainer.Contain
 	}
 	contKnownStatus := cont.GetKnownStatus()
 	if !contKnownStatus.ShouldReportToBackend(cont.GetSteadyStateStatus()) {
-		return event, errors.Errorf(
+		return event, ErrShouldNotSendEvent{fmt.Sprintf(
 			"create container state change event api: status not recognized by ECS: %v",
-			contKnownStatus)
+			contKnownStatus)}
 	}
 	if cont.GetSentStatus() >= contKnownStatus {
-		return event, errors.Errorf(
+		return event, ErrShouldNotSendEvent{fmt.Sprintf(
 			"create container state change event api: status [%s] already sent for container %s, task %s",
-			contKnownStatus.String(), cont.Name, task.Arn)
+			contKnownStatus.String(), cont.Name, task.Arn)}
 	}
 	if reason == "" && cont.ApplyingError != nil {
 		reason = cont.ApplyingError.Error()

agent/api/task/task.go

@@ -508,10 +508,6 @@ func (task *Task) initNetworkMode(acsTaskNetworkMode *string) {
 			field.NetworkMode: aws.StringValue(acsTaskNetworkMode),
 		})
 	}
-	logger.Info("Task network mode initialized", logger.Fields{
-		field.TaskID:      task.GetID(),
-		field.NetworkMode: task.NetworkMode,
-	})
 }
 
 func (task *Task) initServiceConnectResources() error {

agent/api/task/task_test.go

@@ -1864,7 +1864,6 @@ func TestTaskFromACS(t *testing.T) {
 		Memory:              512,
 		ResourcesMapUnsafe:  make(map[string][]taskresource.TaskResource),
 	}
-	expectedTask.GetID() // to set the task setIdOnce (sync.Once) property
 
 	seqNum := int64(42)
 	task, err := TaskFromACS(&taskFromAcs, &ecsacs.PayloadMessage{SeqNum: &seqNum})

agent/engine/docker_task_engine.go

@@ -1752,6 +1752,15 @@ func (engine *DockerTaskEngine) provisionContainerResourcesAwsvpc(task *apitask.
 		}
 	}
 
+	logger.Info("Setting up CNI config for task", logger.Fields{
+		field.TaskID:        task.GetID(),
+		"cniContainerID":    cniConfig.ContainerID,
+		"cniPluginPath":     cniConfig.PluginsPath,
+		"cniID":             cniConfig.ID,
+		"cniBridgeName":     cniConfig.BridgeName,
+		"cniContainerNetNs": cniConfig.ContainerNetNS,
+	})
+
 	// Invoke the libcni to config the network namespace for the container
 	result, err := engine.cniClient.SetupNS(engine.ctx, cniConfig, cniSetupTimeout)
 	if err != nil {

agent/sighandlers/termination_handler.go

@@ -87,11 +87,11 @@ func FinalSave(state dockerstate.TaskEngineState, dataClient data.Client, taskEn
 	disableErr := <-engineDisabled
 
 	stateSaved := make(chan error)
-	saveTimer := time.AfterFunc(finalSaveTimeout, func() {
-		stateSaved <- errors.New("final save: timed out trying to save to disk")
-	})
 	go func() {
 		seelog.Debug("Saving state before shutting down")
+		saveTimer := time.AfterFunc(finalSaveTimeout, func() {
+			stateSaved <- errors.New("final save: timed out trying to save to disk")
+		})
 		saveStateAll(state, dataClient)
 		saveTimer.Stop()
 		stateSaved <- nil

agent/stats/container.go

@@ -39,6 +39,7 @@ func newStatsContainer(dockerID string, client dockerapi.DockerClient, resolver
 			DockerID:    dockerID,
 			Name:        dockerContainer.Container.Name,
 			NetworkMode: dockerContainer.Container.GetNetworkMode(),
+			StartedAt:   dockerContainer.Container.GetStartedAt(),
 		},
 		ctx:      ctx,
 		cancel:   cancel,

agent/stats/engine.go

@@ -707,6 +707,8 @@ func newDockerContainerMetadataResolver(taskEngine ecsengine.TaskEngine) (*Docke
 }
 
 // taskContainerMetricsUnsafe gets all container metrics for a task arn.
+//
+//gocyclo:ignore
 func (engine *DockerStatsEngine) taskContainerMetricsUnsafe(taskArn string) ([]*ecstcs.ContainerMetric, error) {
 	containerMap, taskExists := engine.tasksToContainers[taskArn]
 	if !taskExists {
@@ -723,10 +725,20 @@ func (engine *DockerStatsEngine) taskContainerMetricsUnsafe(taskArn string) ([]*
 		if engine.stopTrackingContainerUnsafe(container, taskArn) {
 			continue
 		}
+		// age is used to determine if we should or should not expect missing metrics.
+		// this is because recently-started containers would normally not have their metrics
+		// queue filled yet.
+		age := time.Since(container.containerMetadata.StartedAt)
+		// gracePeriod is the time that containers are allowed to have missing metrics
+		// without throwing/logging errors.
+		gracePeriod := time.Second * 30
 
 		// CPU and Memory are both critical, so skip the container if either of these fail.
 		cpuStatsSet, err := container.statsQueue.GetCPUStatsSet()
 		if err != nil {
+			if age < gracePeriod {
+				continue
+			}
 			logger.Error("Error collecting cloudwatch metrics for container", logger.Fields{
 				field.Container: dockerID,
 				field.Error:     err,
@@ -735,6 +747,9 @@ func (engine *DockerStatsEngine) taskContainerMetricsUnsafe(taskArn string) ([]*
 		}
 		memoryStatsSet, err := container.statsQueue.GetMemoryStatsSet()
 		if err != nil {
+			if age < gracePeriod {
+				continue
+			}
 			logger.Error("Error collecting cloudwatch metrics for container", logger.Fields{
 				field.Container: dockerID,
 				field.Error:     err,
@@ -749,7 +764,7 @@ func (engine *DockerStatsEngine) taskContainerMetricsUnsafe(taskArn string) ([]*
 		}
 
 		storageStatsSet, err := container.statsQueue.GetStorageStatsSet()
-		if err != nil {
+		if err != nil && age > gracePeriod {
 			logger.Warn("Error getting storage stats for container", logger.Fields{
 				field.Container: dockerID,
 				field.Error:     err,
@@ -777,7 +792,7 @@ func (engine *DockerStatsEngine) taskContainerMetricsUnsafe(taskArn string) ([]*
 						seelog.Debug("Skip adding network stats for pause container in Service Connect enabled task")
 					} else {
 						networkStatsSet, err := container.statsQueue.GetNetworkStatsSet()
-						if err != nil {
+						if err != nil && age > gracePeriod {
 							// we log the error and still continue to publish cpu, memory stats
 							logger.Warn("Error getting network stats for container", logger.Fields{
 								field.Container: dockerID,
@@ -795,7 +810,7 @@ func (engine *DockerStatsEngine) taskContainerMetricsUnsafe(taskArn string) ([]*
 					// do not add network stats for pause container
 					if dockerContainer.Container.Type != apicontainer.ContainerCNIPause {
 						networkStats, err := taskStatsMap.StatsQueue.GetNetworkStatsSet()
-						if err != nil {
+						if err != nil && age > gracePeriod {
 							logger.Warn("Error getting network stats for container", logger.Fields{
 								field.TaskARN:   taskArn,
 								field.Container: dockerContainer.DockerID,

agent/stats/queue.go

@@ -169,62 +169,72 @@ func (queue *Queue) GetMemoryStatsSet() (*ecstcs.CWStatsSet, error) {
 func (queue *Queue) GetStorageStatsSet() (*ecstcs.StorageStatsSet, error) {
 	storageStatsSet := &ecstcs.StorageStatsSet{}
 	var err error
+	var errStr string
 	storageStatsSet.ReadSizeBytes, err = queue.getULongStatsSet(getStorageReadBytes)
 	if err != nil {
-		seelog.Warnf("Error getting storage read size bytes: %v", err)
+		errStr += fmt.Sprintf("error getting storage read size bytes: %v - ", err)
 	}
 	storageStatsSet.WriteSizeBytes, err = queue.getULongStatsSet(getStorageWriteBytes)
 	if err != nil {
-		seelog.Warnf("Error getting storage write size bytes: %v", err)
+		errStr += fmt.Sprintf("error getting storage write size bytes: %v - ", err)
 	}
-	return storageStatsSet, err
+	var errOut error
+	if len(errStr) > 0 {
+		errOut = fmt.Errorf(errStr)
+	}
+	return storageStatsSet, errOut
 }
 
 // GetNetworkStatsSet gets the stats set for network metrics.
 func (queue *Queue) GetNetworkStatsSet() (*ecstcs.NetworkStatsSet, error) {
 	networkStatsSet := &ecstcs.NetworkStatsSet{}
 	var err error
+	var errStr string
 	networkStatsSet.RxBytes, err = queue.getULongStatsSet(getNetworkRxBytes)
 	if err != nil {
-		seelog.Warnf("Error getting network rx bytes: %v", err)
+		errStr += fmt.Sprintf("error getting network rx bytes: %v - ", err)
 	}
 	networkStatsSet.RxDropped, err = queue.getULongStatsSet(getNetworkRxDropped)
 	if err != nil {
-		seelog.Warnf("Error getting network rx dropped: %v", err)
+		errStr += fmt.Sprintf("error getting network rx dropped: %v - ", err)
 	}
 	networkStatsSet.RxErrors, err = queue.getULongStatsSet(getNetworkRxErrors)
 	if err != nil {
-		seelog.Warnf("Error getting network rx errors: %v", err)
+		errStr += fmt.Sprintf("error getting network rx errors: %v - ", err)
 	}
 	networkStatsSet.RxPackets, err = queue.getULongStatsSet(getNetworkRxPackets)
 	if err != nil {
-		seelog.Warnf("Error getting network rx packets: %v", err)
+		errStr += fmt.Sprintf("error getting network rx packets: %v - ", err)
 	}
 	networkStatsSet.TxBytes, err = queue.getULongStatsSet(getNetworkTxBytes)
 	if err != nil {
-		seelog.Warnf("Error getting network tx bytes: %v", err)
+		errStr += fmt.Sprintf("error getting network tx bytes: %v - ", err)
 	}
 	networkStatsSet.TxDropped, err = queue.getULongStatsSet(getNetworkTxDropped)
 	if err != nil {
-		seelog.Warnf("Error getting network tx dropped: %v", err)
+		errStr += fmt.Sprintf("error getting network tx dropped: %v - ", err)
 	}
 	networkStatsSet.TxErrors, err = queue.getULongStatsSet(getNetworkTxErrors)
 	if err != nil {
-		seelog.Warnf("Error getting network tx errors: %v", err)
+		errStr += fmt.Sprintf("error getting network tx errors: %v - ", err)
 	}
 	networkStatsSet.TxPackets, err = queue.getULongStatsSet(getNetworkTxPackets)
 	if err != nil {
-		seelog.Warnf("Error getting network tx packets: %v", err)
+		errStr += fmt.Sprintf("error getting network tx packets: %v - ", err)
 	}
 	networkStatsSet.RxBytesPerSecond, err = queue.getUDoubleCWStatsSet(getNetworkRxPacketsPerSecond)
 	if err != nil {
-		seelog.Warnf("Error getting network rx bytes per second: %v", err)
+		errStr += fmt.Sprintf("error getting network rx bytes per second: %v - ", err)
 	}
 	networkStatsSet.TxBytesPerSecond, err = queue.getUDoubleCWStatsSet(getNetworkTxPacketsPerSecond)
 	if err != nil {
-		seelog.Warnf("Error getting network tx bytes per second: %v", err)
+		errStr += fmt.Sprintf("error getting network tx bytes per second: %v - ", err)
+	}
+	var errOut error
+	if len(errStr) > 0 {
+		errOut = fmt.Errorf(errStr)
 	}
-	return networkStatsSet, err
+	return networkStatsSet, errOut
 }
 
 func getNetworkRxBytes(s *UsageStats) uint64 {

agent/stats/task.go

@@ -57,22 +57,14 @@ func (taskStat *StatsTask) collect() {
 	backoff := retry.NewExponentialBackoff(time.Second*1, time.Second*10, 0.5, 2)
 
 	for {
-		err := taskStat.processStatsStream()
+		statStreamErr := taskStat.processStatsStream()
 		select {
 		case <-taskStat.Ctx.Done():
 			logger.Debug("Stopping stats collection for taskStat", logger.Fields{
 				field.TaskID: taskId,
 			})
 			return
 		default:
-			if err != nil {
-				d := backoff.Duration()
-				time.Sleep(d)
-				logger.Debug("Error querying stats for task", logger.Fields{
-					field.TaskID: taskId,
-					field.Error:  err,
-				})
-			}
 			// We were disconnected from the stats stream.
 			// Check if the task is terminal. If it is, stop collecting metrics.
 			terminal, err := taskStat.terminal()
@@ -83,11 +75,22 @@ func (taskStat *StatsTask) collect() {
 					field.Error:  err,
 				})
 				taskStat.StopStatsCollection()
+				continue
 			} else if terminal {
-				logger.Warn("Task is terminal, stopping stats collection", logger.Fields{
+				logger.Info("Task is terminal, stopping stats collection", logger.Fields{
 					field.TaskID: taskId,
 				})
 				taskStat.StopStatsCollection()
+				continue
+			}
+			// task stats were not stopped for terminal task, backoff before trying to reconnect
+			if statStreamErr != nil {
+				d := backoff.Duration()
+				time.Sleep(d)
+				logger.Debug("Error querying stats for task", logger.Fields{
+					field.TaskID: taskId,
+					field.Error:  err,
+				})
 			}
 		}
 	}

agent/stats/types.go

@@ -62,9 +62,10 @@ type UsageStats struct {
 
 // ContainerMetadata contains meta-data information for a container.
 type ContainerMetadata struct {
-	DockerID    string `json:"-"`
-	Name        string `json:"-"`
-	NetworkMode string `json:"-"`
+	DockerID    string    `json:"-"`
+	Name        string    `json:"-"`
+	NetworkMode string    `json:"-"`
+	StartedAt   time.Time `json:"-"`
 }
 
 // TaskMetadata contains meta-data information for a task.

scripts/run-unit-tests.ps1

@@ -16,7 +16,7 @@ $cwd = (pwd).Path
 try {
     cd $cwd
     $packages=go list .\agent\... | Where-Object {$_ -NotMatch 'vendor'}
-    go test -v -tags unit -timeout=40s $packages
+    go test -v -tags unit -timeout=120s $packages
     $testsExitCode = $LastExitCode
 } finally {
     cd "$cwd"