Skip to content

Commit b64e8bd

Browse files
sparrcsparrc
committed
Structured logging for docker image manager
1 parent f2919b8 commit b64e8bd

File tree

5 files changed

+98
-43
lines changed

5 files changed

+98
-43
lines changed

‎agent/api/container/container.go

+15
Original file line numberDiff line numberDiff line change
@@ -26,6 +26,7 @@ import (
2626
apierrors "github.com/aws/amazon-ecs-agent/agent/api/errors"
2727
resourcestatus "github.com/aws/amazon-ecs-agent/agent/taskresource/status"
2828
"github.com/aws/amazon-ecs-agent/ecs-agent/credentials"
29+
"github.com/aws/amazon-ecs-agent/ecs-agent/logger"
2930

3031
"github.com/aws/aws-sdk-go/aws"
3132
"github.com/cihub/seelog"
@@ -509,6 +510,20 @@ func (c *Container) String() string {
509510
return ret
510511
}
511512

513+
func (c *Container) Fields() logger.Fields {
514+
exitCode := "nil"
515+
if c.GetKnownExitCode() != nil {
516+
exitCode = strconv.Itoa(*c.GetKnownExitCode())
517+
}
518+
return logger.Fields{
519+
"containerName": c.Name,
520+
"containerImage": c.Image,
521+
"containerKnownStatus": c.GetKnownStatus().String(),
522+
"containerDesiredStatus": c.GetDesiredStatus().String(),
523+
"containerExitCode": exitCode,
524+
}
525+
}
526+
512527
// GetSteadyStateStatus returns the steady state status for the container. If
513528
// Container.steadyState is not initialized, the default steady state status
514529
// defined by `defaultContainerSteadyStateStatus` is returned. In awsvpc, the 'pause'

‎agent/engine/docker_image_manager.go

+55-37
Original file line numberDiff line numberDiff line change
@@ -33,7 +33,6 @@ import (
3333
"github.com/aws/amazon-ecs-agent/agent/dockerclient/dockerapi"
3434
"github.com/aws/amazon-ecs-agent/agent/engine/dockerstate"
3535
"github.com/aws/amazon-ecs-agent/agent/engine/image"
36-
"github.com/cihub/seelog"
3736
)
3837

3938
const (
@@ -152,7 +151,9 @@ func (imageManager *dockerImageManager) RecordContainerReference(container *apic
152151
// Inspect image for obtaining Container's Image ID
153152
imageInspected, err := imageManager.client.InspectImage(container.Image)
154153
if err != nil {
155-
seelog.Errorf("Error inspecting image %v: %v", container.Image, err)
154+
fields := container.Fields()
155+
fields["err"] = err
156+
logger.Error("Error inspecting image", fields)
156157
return err
157158
}
158159
container.ImageID = imageInspected.ID
@@ -177,7 +178,7 @@ func (imageManager *dockerImageManager) fetchRepoDigest(imageInspected *types.Im
177178
resultRepoDigest = repoDigestSplitList[1]
178179
return resultRepoDigest
179180
} else {
180-
seelog.Warnf("ImageRepoDigest doesn't have the right format: %v", imageRepoDigest)
181+
logger.Warn(fmt.Sprintf("ImageRepoDigest doesn't have the right format: %v", imageRepoDigest), container.Fields())
181182
return ""
182183
}
183184
}
@@ -272,7 +273,7 @@ func (imageManager *dockerImageManager) removeImageState(imageStateToBeRemoved *
272273
for i, imageState := range imageManager.imageStates {
273274
if imageState.Image.ImageID == imageStateToBeRemoved.Image.ImageID {
274275
// Image State found; hence remove it
275-
seelog.Infof("Removing Image State: [%s] from Image Manager", imageState.String())
276+
logger.Debug("Image Manager: removing image state", imageState.Fields())
276277
imageManager.imageStates = append(imageManager.imageStates[:i], imageManager.imageStates[i+1:]...)
277278
imageManager.removeImageStateData(imageState.Image.ImageID)
278279
return
@@ -282,14 +283,14 @@ func (imageManager *dockerImageManager) removeImageState(imageStateToBeRemoved *
282283

283284
func (imageManager *dockerImageManager) getCandidateImagesForDeletion() []*image.ImageState {
284285
if len(imageManager.imageStatesConsideredForDeletion) < 1 {
285-
seelog.Debugf("Image Manager: Empty state!")
286+
logger.Debug("Image Manager: Empty state!")
286287
// no image states present in image manager
287288
return nil
288289
}
289290
var imagesForDeletion []*image.ImageState
290291
for _, imageState := range imageManager.imageStatesConsideredForDeletion {
291292
if imageManager.isImageOldEnough(imageState) && imageState.HasNoAssociatedContainers() {
292-
seelog.Infof("Candidate image for deletion: [%s]", imageState.String())
293+
logger.Debug("Candidate image for deletion", imageState.Fields())
293294
imagesForDeletion = append(imagesForDeletion, imageState)
294295
}
295296
}
@@ -346,7 +347,7 @@ func (imageManager *dockerImageManager) StartImageCleanupProcess(ctx context.Con
346347
// If the image pull behavior is prefer cached, don't clean up the image,
347348
// because the cached image is needed.
348349
if imageManager.imagePullBehavior == config.ImagePullPreferCachedBehavior {
349-
seelog.Info("Pull behavior is set to always use cache. Disabling cleanup")
350+
logger.Info("Pull behavior is set to always use cache. Disabling cleanup")
350351
return
351352
}
352353
// passing the cleanup interval as argument which would help during testing
@@ -367,10 +368,10 @@ func (imageManager *dockerImageManager) performPeriodicImageCleanup(ctx context.
367368
}
368369

369370
func (imageManager *dockerImageManager) removeUnusedImages(ctx context.Context) {
370-
seelog.Debug("Attempting to obtain ImagePullDeleteLock for removing images")
371+
logger.Debug("Attempting to obtain ImagePullDeleteLock for removing images")
371372
ImagePullDeleteLock.Lock()
372-
seelog.Debug("Obtained ImagePullDeleteLock for removing images")
373-
defer seelog.Debug("Released ImagePullDeleteLock after removing images")
373+
logger.Debug("Obtained ImagePullDeleteLock for removing images")
374+
defer logger.Debug("Released ImagePullDeleteLock after removing images")
374375
defer ImagePullDeleteLock.Unlock()
375376

376377
imageManager.updateLock.Lock()
@@ -383,7 +384,9 @@ func (imageManager *dockerImageManager) removeUnusedImages(ctx context.Context)
383384
err := imageManager.removeLeastRecentlyUsedImage(ctx)
384385
numECSImagesDeleted = i
385386
if err != nil {
386-
seelog.Infof("End of eligible images for deletion: %v; Still have %d image states being managed", err, len(imageManager.getAllImageStates()))
387+
logger.Info("End of eligible images for deletion", logger.Fields{
388+
"managedImagesRemaining": len(imageManager.getAllImageStates()),
389+
})
387390
break
388391
}
389392
}
@@ -399,20 +402,20 @@ func (imageManager *dockerImageManager) removeUnusedImages(ctx context.Context)
399402
func (imageManager *dockerImageManager) removeNonECSContainers(ctx context.Context) {
400403
nonECSContainersIDs, err := imageManager.getNonECSContainerIDs(ctx)
401404
if err != nil {
402-
seelog.Errorf("Error getting non-ECS container IDs: %v", err)
405+
logger.Error(fmt.Sprintf("Error getting non-ECS container IDs: %v", err))
403406
}
404407
var nonECSContainerRemoveAvailableIDs []string
405408
for _, id := range nonECSContainersIDs {
406409
response, icErr := imageManager.client.InspectContainer(ctx, id, dockerclient.InspectContainerTimeout)
407410
if icErr != nil {
408-
seelog.Errorf("Error inspecting non-ECS container id: %s - %v", id, icErr)
411+
logger.Error(fmt.Sprintf("Error inspecting non-ECS container id: %s - %v", id, icErr))
409412
continue
410413
}
411414

412-
seelog.Debugf("Inspecting Non-ECS Container ID [%s] for removal, Finished [%s] Status [%s]", id, response.State.FinishedAt, response.State.Status)
415+
logger.Debug(fmt.Sprintf("Inspecting Non-ECS Container ID [%s] for removal, Finished [%s] Status [%s]", id, response.State.FinishedAt, response.State.Status))
413416
finishedTime, err := time.Parse(time.RFC3339Nano, response.State.FinishedAt)
414417
if err != nil {
415-
seelog.Errorf("Error parsing time string for container. id: %s, time: %s err: %s", id, response.State.FinishedAt, err)
418+
logger.Error(fmt.Sprintf("Error parsing time string for container. id: %s, time: %s err: %s", id, response.State.FinishedAt, err))
416419
continue
417420
}
418421

@@ -428,13 +431,17 @@ func (imageManager *dockerImageManager) removeNonECSContainers(ctx context.Conte
428431
if numNonECSContainerDeleted == imageManager.numNonECSContainersToDelete {
429432
break
430433
}
431-
seelog.Debugf("Removing non-ECS Container ID %s", id)
434+
logger.Debug("Removing non-ECS container", logger.Fields{
435+
"runtimeID": id,
436+
})
432437
err := imageManager.client.RemoveContainer(ctx, id, dockerclient.RemoveContainerTimeout)
433438
if err == nil {
434-
seelog.Infof("Removed Container ID: %s", id)
439+
logger.Info("Removed non-ECS container", logger.Fields{
440+
"runtimeID": id,
441+
})
435442
numNonECSContainerDeleted++
436443
} else {
437-
seelog.Errorf("Error Removing Container ID %s - %s", id, err)
444+
logger.Error(fmt.Sprintf("Error Removing Container ID %s - %s", id, err))
438445
continue
439446
}
440447
}
@@ -480,24 +487,29 @@ func (imageManager *dockerImageManager) removeNonECSImages(ctx context.Context,
480487
if !imageManager.nonECSImageOldEnough(image) {
481488
continue
482489
}
490+
fields := logger.Fields{
491+
"imageID": image.ImageID,
492+
"imageSizeBytes": image.Size,
493+
"repoTags": image.RepoTags,
494+
}
483495
if len(image.RepoTags) > 1 {
484-
seelog.Debugf("Non-ECS image has more than one tag Image: %s (Tags: %s)", image.ImageID, image.RepoTags)
496+
logger.Debug("Non-ECS image has more than one tag", fields)
485497
for _, tag := range image.RepoTags {
486498
err := imageManager.client.RemoveImage(ctx, tag, dockerclient.RemoveImageTimeout)
487499
if err != nil {
488-
seelog.Errorf("Error removing RepoTag (ImageID: %s, Tag: %s) %v", image.ImageID, tag, err)
500+
logger.Error("Error removing non-ECS RepoTag", fields, logger.Fields{"err": err})
489501
} else {
490-
seelog.Infof("Image Tag Removed: %s (ImageID: %s)", tag, image.ImageID)
502+
logger.Info("Non-ECS image tag removed", fields, logger.Fields{"imageTag": tag})
491503
numImagesAlreadyDeleted++
492504
}
493505
}
494506
} else {
495-
seelog.Debugf("Removing non-ECS Image: %s (Tags: %s)", image.ImageID, image.RepoTags)
507+
logger.Debug("Removing non-ECS image", fields)
496508
err := imageManager.client.RemoveImage(ctx, image.ImageID, dockerclient.RemoveImageTimeout)
497509
if err != nil {
498-
seelog.Errorf("Error removing Image %s (Tags: %s) - %v", image.ImageID, image.RepoTags, err)
510+
logger.Error("Error removing non-ECS image", fields, logger.Fields{"err": err})
499511
} else {
500-
seelog.Infof("Image removed: %s (Tags: %s)", image.ImageID, image.RepoTags)
512+
logger.Info("Non-ECS image removed", fields)
501513
numImagesAlreadyDeleted++
502514
}
503515
}
@@ -512,13 +524,14 @@ func (imageManager *dockerImageManager) getNonECSImages(ctx context.Context) []I
512524
for _, imageID := range r.ImageIDs {
513525
resp, err := imageManager.client.InspectImage(imageID)
514526
if err != nil {
515-
seelog.Errorf("Error inspecting non-ECS image: (ImageID: %s), %s", imageID, err)
527+
logger.Error("Error inspecting non-ECS image", logger.Fields{"imageID": imageID, "err": err})
516528
continue
517529
}
518530
createTime := time.Time{}
519531
createTime, err = time.Parse(time.RFC3339, resp.Created)
520532
if err != nil {
521-
seelog.Warnf("Error parse the inspected non-ECS image created time (ImageID: %s), %v", imageID, err)
533+
logger.Warn("Error parsing the inspected non-ECS image created time.",
534+
logger.Fields{"imageID": imageID, "err": err})
522535
}
523536
allImages = append(allImages,
524537
ImageWithSizeID{
@@ -588,13 +601,13 @@ func exclude(allList []string, exclusionList []string) []string {
588601

589602
func (imageManager *dockerImageManager) imagesConsiderForDeletion(allImageStates []*image.ImageState) map[string]*image.ImageState {
590603
var imagesConsiderForDeletionMap = make(map[string]*image.ImageState)
591-
seelog.Info("Begin building map of eligible unused images for deletion")
604+
logger.Debug("Begin building map of eligible unused images for deletion")
592605
for _, imageState := range allImageStates {
593606
if imageManager.isExcludedFromCleanup(imageState) {
594607
//imageState that we want to keep
595-
seelog.Debugf("Image excluded from deletion: [%s]", imageState.String())
608+
logger.Debug("Image excluded from deletion", imageState.Fields())
596609
} else {
597-
seelog.Debugf("Image going to be considered for deletion: [%s]", imageState.String())
610+
logger.Debug("Image going to be considered for deletion", imageState.Fields())
598611
imagesConsiderForDeletionMap[imageState.Image.ImageID] = imageState
599612
}
600613
}
@@ -617,17 +630,18 @@ func (imageManager *dockerImageManager) removeLeastRecentlyUsedImage(ctx context
617630
if leastRecentlyUsedImage == nil {
618631
return fmt.Errorf("No more eligible images for deletion")
619632
}
633+
logger.Info("Image ready for deletion", leastRecentlyUsedImage.Fields())
620634
imageManager.removeImage(ctx, leastRecentlyUsedImage)
621635
return nil
622636
}
623637

624638
func (imageManager *dockerImageManager) getUnusedImageForDeletion() *image.ImageState {
625639
candidateImageStatesForDeletion := imageManager.getCandidateImagesForDeletion()
626640
if len(candidateImageStatesForDeletion) < 1 {
627-
seelog.Infof("No eligible images for deletion for this cleanup cycle")
641+
logger.Debug("No eligible images for deletion for this cleanup cycle")
628642
return nil
629643
}
630-
seelog.Infof("Found %d eligible images for deletion", len(candidateImageStatesForDeletion))
644+
logger.Debug(fmt.Sprintf("Found %d eligible images for deletion", len(candidateImageStatesForDeletion)))
631645
return imageManager.getLeastRecentlyUsedImage(candidateImageStatesForDeletion)
632646
}
633647

@@ -648,24 +662,28 @@ func (imageManager *dockerImageManager) removeImage(ctx context.Context, leastRe
648662

649663
func (imageManager *dockerImageManager) deleteImage(ctx context.Context, imageID string, imageState *image.ImageState) {
650664
if imageID == "" {
651-
seelog.Errorf("Image ID to be deleted is null")
665+
var fields logger.Fields
666+
if imageState != nil {
667+
fields = imageState.Fields()
668+
}
669+
logger.Error("Image ID to be deleted is null", fields)
652670
return
653671
}
654-
seelog.Infof("Removing Image: %s", imageID)
672+
logger.Debug(fmt.Sprintf("Removing Image: %s", imageID), imageState.Fields())
655673
err := imageManager.client.RemoveImage(ctx, imageID, dockerclient.RemoveImageTimeout)
656674
if err != nil {
657675
if strings.Contains(strings.ToLower(err.Error()), imageNotFoundForDeletionError) {
658-
seelog.Errorf("Image already removed from the instance: %v", err)
676+
logger.Error(fmt.Sprintf("Image already removed from the instance: %v", imageID), imageState.Fields())
659677
} else {
660-
seelog.Errorf("Error removing Image %v - %v", imageID, err)
678+
logger.Error(fmt.Sprintf("Error removing Image %v", imageID), imageState.Fields(), logger.Fields{"err": err})
661679
delete(imageManager.imageStatesConsideredForDeletion, imageState.Image.ImageID)
662680
return
663681
}
664682
}
665-
seelog.Infof("Image removed: %v", imageID)
683+
logger.Info(fmt.Sprintf("Image removed: %v", imageID), imageState.Fields())
666684
imageState.RemoveImageName(imageID)
667685
if len(imageState.Image.Names) == 0 {
668-
seelog.Infof("Cleaning up all tracking information for image %s as it has zero references", imageID)
686+
logger.Info(fmt.Sprintf("Cleaning up all tracking information for image %s as it has zero references", imageID), imageState.Fields())
669687
delete(imageManager.imageStatesConsideredForDeletion, imageState.Image.ImageID)
670688
imageManager.removeImageState(imageState)
671689
imageManager.state.RemoveImageState(imageState)

‎agent/engine/docker_task_engine.go

+2-3
Original file line numberDiff line numberDiff line change
@@ -2090,9 +2090,8 @@ func (engine *DockerTaskEngine) stopDockerContainer(dockerID, containerName stri
20902090
}
20912091

20922092
func (engine *DockerTaskEngine) removeContainer(task *apitask.Task, container *apicontainer.Container) error {
2093-
logger.Info("Removing container", logger.Fields{
2094-
field.TaskID: task.GetID(),
2095-
field.Container: container.Name,
2093+
logger.Info("Removing container", container.Fields(), logger.Fields{
2094+
field.TaskID: task.GetID(),
20962095
})
20972096
dockerID, err := engine.getDockerID(task, container)
20982097
if err != nil {

‎agent/engine/image/types.go

+23-1
Original file line numberDiff line numberDiff line change
@@ -188,5 +188,27 @@ func (imageState *ImageState) String() string {
188188
image = imageState.Image.String()
189189
}
190190
return fmt.Sprintf("Image: [%s] referenced by %d containers; PulledAt: %s; LastUsedAt: %s; PullSucceeded: %t",
191-
image, len(imageState.Containers), imageState.PulledAt.String(), imageState.LastUsedAt.String(), imageState.PullSucceeded)
191+
image, len(imageState.Containers), imageState.PulledAt.UTC().Format(time.RFC3339),
192+
imageState.LastUsedAt.UTC().Format(time.RFC3339), imageState.PullSucceeded)
193+
}
194+
195+
func (imageState *ImageState) Fields() logger.Fields {
196+
imageID := ""
197+
names := []string{}
198+
size := int64(-1)
199+
if imageState.Image != nil {
200+
imageID = imageState.Image.ImageID
201+
names = imageState.Image.Names
202+
size = imageState.Image.Size
203+
}
204+
205+
return logger.Fields{
206+
"imageID": imageID,
207+
"imageNames": names,
208+
"imageSizeBytes": size,
209+
"referencedBy": len(imageState.Containers),
210+
"imagePulledAt": imageState.PulledAt.UTC().Format(time.RFC3339),
211+
"imageLastUsedAt": imageState.LastUsedAt.UTC().Format(time.RFC3339),
212+
"imagePullSucceeded": imageState.PullSucceeded,
213+
}
192214
}

‎agent/stats/container.go

+3-2
Original file line numberDiff line numberDiff line change
@@ -24,6 +24,7 @@ import (
2424
"github.com/aws/amazon-ecs-agent/agent/dockerclient/dockerapi"
2525
"github.com/aws/amazon-ecs-agent/agent/stats/resolver"
2626
"github.com/aws/amazon-ecs-agent/agent/utils/retry"
27+
"github.com/aws/amazon-ecs-agent/ecs-agent/logger"
2728
"github.com/cihub/seelog"
2829
)
2930

@@ -74,7 +75,7 @@ func (container *StatsContainer) collect() {
7475
err := container.processStatsStream()
7576
select {
7677
case <-container.ctx.Done():
77-
seelog.Infof("Container [%s]: Stopping stats collection", dockerID)
78+
logger.Info("Stopping container stats collection", logger.Fields{"runtimeID": dockerID})
7879
return
7980
default:
8081
if err != nil {
@@ -97,7 +98,7 @@ func (container *StatsContainer) collect() {
9798
container.StopStatsCollection()
9899
return
99100
} else if terminal {
100-
seelog.Infof("Container [%s]: container is terminal, stopping stats collection", dockerID)
101+
logger.Info("Container is terminal, stopping stats collection", logger.Fields{"runtimeID": dockerID})
101102
container.StopStatsCollection()
102103
return
103104
}

0 commit comments

Comments
 (0)