diff --git a/agent/api/container/container.go b/agent/api/container/container.go index 686fbfbaa24..98d8f701c2f 100644 --- a/agent/api/container/container.go +++ b/agent/api/container/container.go @@ -26,6 +26,8 @@ import ( apierrors "github.com/aws/amazon-ecs-agent/agent/api/errors" resourcestatus "github.com/aws/amazon-ecs-agent/agent/taskresource/status" "github.com/aws/amazon-ecs-agent/ecs-agent/credentials" + "github.com/aws/amazon-ecs-agent/ecs-agent/logger" + "github.com/aws/amazon-ecs-agent/ecs-agent/logger/field" "github.com/aws/aws-sdk-go/aws" "github.com/cihub/seelog" @@ -509,6 +511,20 @@ func (c *Container) String() string { return ret } +func (c *Container) Fields() logger.Fields { + exitCode := "nil" + if c.GetKnownExitCode() != nil { + exitCode = strconv.Itoa(*c.GetKnownExitCode()) + } + return logger.Fields{ + field.ContainerName: c.Name, + field.ContainerImage: c.Image, + "containerKnownStatus": c.GetKnownStatus().String(), + "containerDesiredStatus": c.GetDesiredStatus().String(), + field.ContainerExitCode: exitCode, + } +} + // GetSteadyStateStatus returns the steady state status for the container. If // Container.steadyState is not initialized, the default steady state status // defined by `defaultContainerSteadyStateStatus` is returned. In awsvpc, the 'pause' diff --git a/agent/engine/docker_image_manager.go b/agent/engine/docker_image_manager.go index 56f8d61e1a3..31b981f791d 100644 --- a/agent/engine/docker_image_manager.go +++ b/agent/engine/docker_image_manager.go @@ -33,7 +33,6 @@ import ( "github.com/aws/amazon-ecs-agent/agent/dockerclient/dockerapi" "github.com/aws/amazon-ecs-agent/agent/engine/dockerstate" "github.com/aws/amazon-ecs-agent/agent/engine/image" - "github.com/cihub/seelog" ) const ( @@ -152,7 +151,9 @@ func (imageManager *dockerImageManager) RecordContainerReference(container *apic // Inspect image for obtaining Container's Image ID imageInspected, err := imageManager.client.InspectImage(container.Image) if err != nil { - seelog.Errorf("Error inspecting image %v: %v", container.Image, err) + fields := container.Fields() + fields[field.Error] = err + logger.Error("Error inspecting image", fields) return err } container.ImageID = imageInspected.ID @@ -177,7 +178,7 @@ func (imageManager *dockerImageManager) fetchRepoDigest(imageInspected *types.Im resultRepoDigest = repoDigestSplitList[1] return resultRepoDigest } else { - seelog.Warnf("ImageRepoDigest doesn't have the right format: %v", imageRepoDigest) + logger.Warn(fmt.Sprintf("ImageRepoDigest doesn't have the right format: %v", imageRepoDigest), container.Fields()) return "" } } @@ -272,7 +273,7 @@ func (imageManager *dockerImageManager) removeImageState(imageStateToBeRemoved * for i, imageState := range imageManager.imageStates { if imageState.Image.ImageID == imageStateToBeRemoved.Image.ImageID { // Image State found; hence remove it - seelog.Infof("Removing Image State: [%s] from Image Manager", imageState.String()) + logger.Debug("Image Manager: removing image state", imageState.Fields()) imageManager.imageStates = append(imageManager.imageStates[:i], imageManager.imageStates[i+1:]...) imageManager.removeImageStateData(imageState.Image.ImageID) return @@ -282,14 +283,14 @@ func (imageManager *dockerImageManager) removeImageState(imageStateToBeRemoved * func (imageManager *dockerImageManager) getCandidateImagesForDeletion() []*image.ImageState { if len(imageManager.imageStatesConsideredForDeletion) < 1 { - seelog.Debugf("Image Manager: Empty state!") + logger.Debug("Image Manager: Empty state!") // no image states present in image manager return nil } var imagesForDeletion []*image.ImageState for _, imageState := range imageManager.imageStatesConsideredForDeletion { if imageManager.isImageOldEnough(imageState) && imageState.HasNoAssociatedContainers() { - seelog.Infof("Candidate image for deletion: [%s]", imageState.String()) + logger.Debug("Candidate image for deletion", imageState.Fields()) imagesForDeletion = append(imagesForDeletion, imageState) } } @@ -346,7 +347,7 @@ func (imageManager *dockerImageManager) StartImageCleanupProcess(ctx context.Con // If the image pull behavior is prefer cached, don't clean up the image, // because the cached image is needed. if imageManager.imagePullBehavior == config.ImagePullPreferCachedBehavior { - seelog.Info("Pull behavior is set to always use cache. Disabling cleanup") + logger.Info("Pull behavior is set to always use cache. Disabling cleanup") return } // passing the cleanup interval as argument which would help during testing @@ -367,10 +368,10 @@ func (imageManager *dockerImageManager) performPeriodicImageCleanup(ctx context. } func (imageManager *dockerImageManager) removeUnusedImages(ctx context.Context) { - seelog.Debug("Attempting to obtain ImagePullDeleteLock for removing images") + logger.Debug("Attempting to obtain ImagePullDeleteLock for removing images") ImagePullDeleteLock.Lock() - seelog.Debug("Obtained ImagePullDeleteLock for removing images") - defer seelog.Debug("Released ImagePullDeleteLock after removing images") + logger.Debug("Obtained ImagePullDeleteLock for removing images") + defer logger.Debug("Released ImagePullDeleteLock after removing images") defer ImagePullDeleteLock.Unlock() imageManager.updateLock.Lock() @@ -383,7 +384,9 @@ func (imageManager *dockerImageManager) removeUnusedImages(ctx context.Context) err := imageManager.removeLeastRecentlyUsedImage(ctx) numECSImagesDeleted = i if err != nil { - seelog.Infof("End of eligible images for deletion: %v; Still have %d image states being managed", err, len(imageManager.getAllImageStates())) + logger.Info("End of eligible images for deletion", logger.Fields{ + "managedImagesRemaining": len(imageManager.getAllImageStates()), + }) break } } @@ -399,20 +402,20 @@ func (imageManager *dockerImageManager) removeUnusedImages(ctx context.Context) func (imageManager *dockerImageManager) removeNonECSContainers(ctx context.Context) { nonECSContainersIDs, err := imageManager.getNonECSContainerIDs(ctx) if err != nil { - seelog.Errorf("Error getting non-ECS container IDs: %v", err) + logger.Error(fmt.Sprintf("Error getting non-ECS container IDs: %v", err)) } var nonECSContainerRemoveAvailableIDs []string for _, id := range nonECSContainersIDs { response, icErr := imageManager.client.InspectContainer(ctx, id, dockerclient.InspectContainerTimeout) if icErr != nil { - seelog.Errorf("Error inspecting non-ECS container id: %s - %v", id, icErr) + logger.Error(fmt.Sprintf("Error inspecting non-ECS container id: %s - %v", id, icErr)) continue } - seelog.Debugf("Inspecting Non-ECS Container ID [%s] for removal, Finished [%s] Status [%s]", id, response.State.FinishedAt, response.State.Status) + logger.Debug(fmt.Sprintf("Inspecting Non-ECS Container ID [%s] for removal, Finished [%s] Status [%s]", id, response.State.FinishedAt, response.State.Status)) finishedTime, err := time.Parse(time.RFC3339Nano, response.State.FinishedAt) if err != nil { - seelog.Errorf("Error parsing time string for container. id: %s, time: %s err: %s", id, response.State.FinishedAt, err) + logger.Error(fmt.Sprintf("Error parsing time string for container. id: %s, time: %s err: %s", id, response.State.FinishedAt, err)) continue } @@ -428,13 +431,17 @@ func (imageManager *dockerImageManager) removeNonECSContainers(ctx context.Conte if numNonECSContainerDeleted == imageManager.numNonECSContainersToDelete { break } - seelog.Debugf("Removing non-ECS Container ID %s", id) + logger.Debug("Removing non-ECS container", logger.Fields{ + "runtimeID": id, + }) err := imageManager.client.RemoveContainer(ctx, id, dockerclient.RemoveContainerTimeout) if err == nil { - seelog.Infof("Removed Container ID: %s", id) + logger.Info("Removed non-ECS container", logger.Fields{ + "runtimeID": id, + }) numNonECSContainerDeleted++ } else { - seelog.Errorf("Error Removing Container ID %s - %s", id, err) + logger.Error(fmt.Sprintf("Error Removing Container ID %s - %s", id, err)) continue } } @@ -480,24 +487,32 @@ func (imageManager *dockerImageManager) removeNonECSImages(ctx context.Context, if !imageManager.nonECSImageOldEnough(image) { continue } + fields := logger.Fields{ + field.ImageID: image.ImageID, + field.ImageSizeBytes: image.Size, + "repoTags": image.RepoTags, + } if len(image.RepoTags) > 1 { - seelog.Debugf("Non-ECS image has more than one tag Image: %s (Tags: %s)", image.ImageID, image.RepoTags) + logger.Debug("Non-ECS image has more than one tag", fields) for _, tag := range image.RepoTags { err := imageManager.client.RemoveImage(ctx, tag, dockerclient.RemoveImageTimeout) if err != nil { - seelog.Errorf("Error removing RepoTag (ImageID: %s, Tag: %s) %v", image.ImageID, tag, err) + logger.Error("Error removing non-ECS RepoTag", fields, logger.Fields{ + field.Error: err, + "imageTag": tag, + }) } else { - seelog.Infof("Image Tag Removed: %s (ImageID: %s)", tag, image.ImageID) + logger.Info("Non-ECS image tag removed", fields, logger.Fields{"imageTag": tag}) numImagesAlreadyDeleted++ } } } else { - seelog.Debugf("Removing non-ECS Image: %s (Tags: %s)", image.ImageID, image.RepoTags) + logger.Debug("Removing non-ECS image", fields) err := imageManager.client.RemoveImage(ctx, image.ImageID, dockerclient.RemoveImageTimeout) if err != nil { - seelog.Errorf("Error removing Image %s (Tags: %s) - %v", image.ImageID, image.RepoTags, err) + logger.Error("Error removing non-ECS image", fields, logger.Fields{field.Error: err}) } else { - seelog.Infof("Image removed: %s (Tags: %s)", image.ImageID, image.RepoTags) + logger.Info("Non-ECS image removed", fields) numImagesAlreadyDeleted++ } } @@ -512,13 +527,14 @@ func (imageManager *dockerImageManager) getNonECSImages(ctx context.Context) []I for _, imageID := range r.ImageIDs { resp, err := imageManager.client.InspectImage(imageID) if err != nil { - seelog.Errorf("Error inspecting non-ECS image: (ImageID: %s), %s", imageID, err) + logger.Error("Error inspecting non-ECS image", logger.Fields{field.ImageID: imageID, field.Error: err}) continue } createTime := time.Time{} createTime, err = time.Parse(time.RFC3339, resp.Created) if err != nil { - seelog.Warnf("Error parse the inspected non-ECS image created time (ImageID: %s), %v", imageID, err) + logger.Warn("Error parsing the inspected non-ECS image created time.", + logger.Fields{field.ImageID: imageID, field.Error: err}) } allImages = append(allImages, ImageWithSizeID{ @@ -588,13 +604,13 @@ func exclude(allList []string, exclusionList []string) []string { func (imageManager *dockerImageManager) imagesConsiderForDeletion(allImageStates []*image.ImageState) map[string]*image.ImageState { var imagesConsiderForDeletionMap = make(map[string]*image.ImageState) - seelog.Info("Begin building map of eligible unused images for deletion") + logger.Debug("Begin building map of eligible unused images for deletion") for _, imageState := range allImageStates { if imageManager.isExcludedFromCleanup(imageState) { //imageState that we want to keep - seelog.Debugf("Image excluded from deletion: [%s]", imageState.String()) + logger.Debug("Image excluded from deletion", imageState.Fields()) } else { - seelog.Debugf("Image going to be considered for deletion: [%s]", imageState.String()) + logger.Debug("Image going to be considered for deletion", imageState.Fields()) imagesConsiderForDeletionMap[imageState.Image.ImageID] = imageState } } @@ -617,6 +633,7 @@ func (imageManager *dockerImageManager) removeLeastRecentlyUsedImage(ctx context if leastRecentlyUsedImage == nil { return fmt.Errorf("No more eligible images for deletion") } + logger.Info("Image ready for deletion", leastRecentlyUsedImage.Fields()) imageManager.removeImage(ctx, leastRecentlyUsedImage) return nil } @@ -624,10 +641,10 @@ func (imageManager *dockerImageManager) removeLeastRecentlyUsedImage(ctx context func (imageManager *dockerImageManager) getUnusedImageForDeletion() *image.ImageState { candidateImageStatesForDeletion := imageManager.getCandidateImagesForDeletion() if len(candidateImageStatesForDeletion) < 1 { - seelog.Infof("No eligible images for deletion for this cleanup cycle") + logger.Debug("No eligible images for deletion for this cleanup cycle") return nil } - seelog.Infof("Found %d eligible images for deletion", len(candidateImageStatesForDeletion)) + logger.Debug(fmt.Sprintf("Found %d eligible images for deletion", len(candidateImageStatesForDeletion))) return imageManager.getLeastRecentlyUsedImage(candidateImageStatesForDeletion) } @@ -648,24 +665,28 @@ func (imageManager *dockerImageManager) removeImage(ctx context.Context, leastRe func (imageManager *dockerImageManager) deleteImage(ctx context.Context, imageID string, imageState *image.ImageState) { if imageID == "" { - seelog.Errorf("Image ID to be deleted is null") + var fields logger.Fields + if imageState != nil { + fields = imageState.Fields() + } + logger.Error("Image ID to be deleted is null", fields) return } - seelog.Infof("Removing Image: %s", imageID) + logger.Debug(fmt.Sprintf("Removing Image: %s", imageID), imageState.Fields()) err := imageManager.client.RemoveImage(ctx, imageID, dockerclient.RemoveImageTimeout) if err != nil { if strings.Contains(strings.ToLower(err.Error()), imageNotFoundForDeletionError) { - seelog.Errorf("Image already removed from the instance: %v", err) + logger.Error(fmt.Sprintf("Image already removed from the instance: %v", imageID), imageState.Fields()) } else { - seelog.Errorf("Error removing Image %v - %v", imageID, err) + logger.Error(fmt.Sprintf("Error removing Image %v", imageID), imageState.Fields(), logger.Fields{field.Error: err}) delete(imageManager.imageStatesConsideredForDeletion, imageState.Image.ImageID) return } } - seelog.Infof("Image removed: %v", imageID) + logger.Info(fmt.Sprintf("Image removed: %v", imageID), imageState.Fields()) imageState.RemoveImageName(imageID) if len(imageState.Image.Names) == 0 { - seelog.Infof("Cleaning up all tracking information for image %s as it has zero references", imageID) + logger.Info(fmt.Sprintf("Cleaning up all tracking information for image %s as it has zero references", imageID), imageState.Fields()) delete(imageManager.imageStatesConsideredForDeletion, imageState.Image.ImageID) imageManager.removeImageState(imageState) imageManager.state.RemoveImageState(imageState) diff --git a/agent/engine/docker_task_engine.go b/agent/engine/docker_task_engine.go index 82e759facbf..a9349650435 100644 --- a/agent/engine/docker_task_engine.go +++ b/agent/engine/docker_task_engine.go @@ -2090,9 +2090,8 @@ func (engine *DockerTaskEngine) stopDockerContainer(dockerID, containerName stri } func (engine *DockerTaskEngine) removeContainer(task *apitask.Task, container *apicontainer.Container) error { - logger.Info("Removing container", logger.Fields{ - field.TaskID: task.GetID(), - field.Container: container.Name, + logger.Info("Removing container", container.Fields(), logger.Fields{ + field.TaskID: task.GetID(), }) dockerID, err := engine.getDockerID(task, container) if err != nil { diff --git a/agent/engine/image/types.go b/agent/engine/image/types.go index c87d17e9f7f..46be2dd1721 100644 --- a/agent/engine/image/types.go +++ b/agent/engine/image/types.go @@ -188,5 +188,27 @@ func (imageState *ImageState) String() string { image = imageState.Image.String() } return fmt.Sprintf("Image: [%s] referenced by %d containers; PulledAt: %s; LastUsedAt: %s; PullSucceeded: %t", - image, len(imageState.Containers), imageState.PulledAt.String(), imageState.LastUsedAt.String(), imageState.PullSucceeded) + image, len(imageState.Containers), imageState.PulledAt.UTC().Format(time.RFC3339), + imageState.LastUsedAt.UTC().Format(time.RFC3339), imageState.PullSucceeded) +} + +func (imageState *ImageState) Fields() logger.Fields { + imageID := "" + names := []string{} + size := int64(-1) + if imageState.Image != nil { + imageID = imageState.Image.ImageID + names = imageState.Image.Names + size = imageState.Image.Size + } + + return logger.Fields{ + field.ImageID: imageID, + field.ImageNames: names, + field.ImageSizeBytes: size, + "referencedBy": len(imageState.Containers), + field.ImagePulledAt: imageState.PulledAt.UTC().Format(time.RFC3339), + field.ImageLastUsedAt: imageState.LastUsedAt.UTC().Format(time.RFC3339), + field.ImagePullSucceeded: imageState.PullSucceeded, + } } diff --git a/agent/stats/container.go b/agent/stats/container.go index 722df196797..e1fa6ba0653 100644 --- a/agent/stats/container.go +++ b/agent/stats/container.go @@ -24,6 +24,7 @@ import ( "github.com/aws/amazon-ecs-agent/agent/dockerclient/dockerapi" "github.com/aws/amazon-ecs-agent/agent/stats/resolver" "github.com/aws/amazon-ecs-agent/agent/utils/retry" + "github.com/aws/amazon-ecs-agent/ecs-agent/logger" "github.com/cihub/seelog" ) @@ -74,7 +75,7 @@ func (container *StatsContainer) collect() { err := container.processStatsStream() select { case <-container.ctx.Done(): - seelog.Infof("Container [%s]: Stopping stats collection", dockerID) + logger.Info("Stopping container stats collection", logger.Fields{"runtimeID": dockerID}) return default: if err != nil { @@ -97,7 +98,7 @@ func (container *StatsContainer) collect() { container.StopStatsCollection() return } else if terminal { - seelog.Infof("Container [%s]: container is terminal, stopping stats collection", dockerID) + logger.Info("Container is terminal, stopping stats collection", logger.Fields{"runtimeID": dockerID}) container.StopStatsCollection() return } diff --git a/agent/vendor/github.com/aws/amazon-ecs-agent/ecs-agent/logger/field/constants.go b/agent/vendor/github.com/aws/amazon-ecs-agent/ecs-agent/logger/field/constants.go index fbfd713ffe9..8b154e1dbec 100644 --- a/agent/vendor/github.com/aws/amazon-ecs-agent/ecs-agent/logger/field/constants.go +++ b/agent/vendor/github.com/aws/amazon-ecs-agent/ecs-agent/logger/field/constants.go @@ -14,29 +14,38 @@ package field const ( - TaskID = "task" - TaskARN = "taskARN" - Container = "container" - DockerId = "dockerId" - ManagedAgent = "managedAgent" - KnownStatus = "knownStatus" - KnownSent = "knownSent" - DesiredStatus = "desiredStatus" - SentStatus = "sentStatus" - FailedStatus = "failedStatus" - Sequence = "seqnum" - Reason = "reason" - Status = "status" - RuntimeID = "runtimeID" - Elapsed = "elapsed" - Resource = "resource" - Error = "error" - Event = "event" - Image = "image" - Volume = "volume" - Time = "time" - NetworkMode = "networkMode" - Cluster = "cluster" - ServiceName = "ServiceName" - TaskProtection = "TaskProtection" + TaskID = "task" + TaskARN = "taskARN" + Container = "container" + DockerId = "dockerId" + ManagedAgent = "managedAgent" + KnownStatus = "knownStatus" + KnownSent = "knownSent" + DesiredStatus = "desiredStatus" + SentStatus = "sentStatus" + FailedStatus = "failedStatus" + Sequence = "seqnum" + Reason = "reason" + Status = "status" + RuntimeID = "runtimeID" + Elapsed = "elapsed" + Resource = "resource" + Error = "error" + Event = "event" + Image = "image" + Volume = "volume" + Time = "time" + NetworkMode = "networkMode" + Cluster = "cluster" + ServiceName = "ServiceName" + TaskProtection = "TaskProtection" + ImageID = "imageID" + ImageNames = "imageNames" + ImageSizeBytes = "imageSizeBytes" + ImagePulledAt = "imagePulledAt" + ImageLastUsedAt = "imageLastUsedAt" + ImagePullSucceeded = "imagePullSucceeded" + ContainerName = "containerName" + ContainerImage = "containerImage" + ContainerExitCode = "containerExitCode" ) diff --git a/ecs-agent/logger/field/constants.go b/ecs-agent/logger/field/constants.go index fbfd713ffe9..8b154e1dbec 100644 --- a/ecs-agent/logger/field/constants.go +++ b/ecs-agent/logger/field/constants.go @@ -14,29 +14,38 @@ package field const ( - TaskID = "task" - TaskARN = "taskARN" - Container = "container" - DockerId = "dockerId" - ManagedAgent = "managedAgent" - KnownStatus = "knownStatus" - KnownSent = "knownSent" - DesiredStatus = "desiredStatus" - SentStatus = "sentStatus" - FailedStatus = "failedStatus" - Sequence = "seqnum" - Reason = "reason" - Status = "status" - RuntimeID = "runtimeID" - Elapsed = "elapsed" - Resource = "resource" - Error = "error" - Event = "event" - Image = "image" - Volume = "volume" - Time = "time" - NetworkMode = "networkMode" - Cluster = "cluster" - ServiceName = "ServiceName" - TaskProtection = "TaskProtection" + TaskID = "task" + TaskARN = "taskARN" + Container = "container" + DockerId = "dockerId" + ManagedAgent = "managedAgent" + KnownStatus = "knownStatus" + KnownSent = "knownSent" + DesiredStatus = "desiredStatus" + SentStatus = "sentStatus" + FailedStatus = "failedStatus" + Sequence = "seqnum" + Reason = "reason" + Status = "status" + RuntimeID = "runtimeID" + Elapsed = "elapsed" + Resource = "resource" + Error = "error" + Event = "event" + Image = "image" + Volume = "volume" + Time = "time" + NetworkMode = "networkMode" + Cluster = "cluster" + ServiceName = "ServiceName" + TaskProtection = "TaskProtection" + ImageID = "imageID" + ImageNames = "imageNames" + ImageSizeBytes = "imageSizeBytes" + ImagePulledAt = "imagePulledAt" + ImageLastUsedAt = "imageLastUsedAt" + ImagePullSucceeded = "imagePullSucceeded" + ContainerName = "containerName" + ContainerImage = "containerImage" + ContainerExitCode = "containerExitCode" )