diff --git a/agent/engine/docker_image_manager.go b/agent/engine/docker_image_manager.go index 718d5d8ab87..c6db17bd28a 100644 --- a/agent/engine/docker_image_manager.go +++ b/agent/engine/docker_image_manager.go @@ -196,7 +196,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: %v from Image Manager", imageState.Image.ImageID) + seelog.Infof("Removing Image State: [%s] from Image Manager", imageState.String()) imageManager.imageStates = append(imageManager.imageStates[:i], imageManager.imageStates[i+1:]...) return } @@ -205,13 +205,14 @@ func (imageManager *dockerImageManager) removeImageState(imageStateToBeRemoved * func (imageManager *dockerImageManager) getCandidateImagesForDeletion() []*image.ImageState { if len(imageManager.imageStatesConsideredForDeletion) < 1 { + seelog.Debugf("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: %+v", imageState) + seelog.Infof("Candidate image for deletion: [%s]", imageState.String()) imagesForDeletion = append(imagesForDeletion, imageState) } } @@ -275,7 +276,12 @@ func (imageManager *dockerImageManager) performPeriodicImageCleanup(ctx context. } func (imageManager *dockerImageManager) removeUnusedImages() { - seelog.Infof("Begin building map of eligible unused images for deletion") + seelog.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") + defer ImagePullDeleteLock.Unlock() + imageManager.updateLock.Lock() defer imageManager.updateLock.Unlock() imageManager.imageStatesConsideredForDeletion = make(map[string]*image.ImageState) @@ -285,18 +291,14 @@ func (imageManager *dockerImageManager) removeUnusedImages() { for i := 0; i < imageManager.numImagesToDelete; i++ { err := imageManager.removeLeastRecentlyUsedImage() if err != nil { - seelog.Infof("End of eligible images for deletion") + seelog.Infof("End of eligible images for deletion: %v; Still have %d image states being managed", err, len(imageManager.getAllImageStates())) break } } } func (imageManager *dockerImageManager) removeLeastRecentlyUsedImage() error { - seelog.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") - defer ImagePullDeleteLock.Unlock() + seelog.Infof("Begin building map of eligible unused images for deletion") leastRecentlyUsedImage := imageManager.getUnusedImageForDeletion() if leastRecentlyUsedImage == nil { return fmt.Errorf("No more eligible images for deletion") diff --git a/agent/engine/docker_image_manager_test.go b/agent/engine/docker_image_manager_test.go index 3500fe9845c..29c899306e5 100644 --- a/agent/engine/docker_image_manager_test.go +++ b/agent/engine/docker_image_manager_test.go @@ -34,6 +34,49 @@ import ( "golang.org/x/net/context" ) +// TestImagePullRemoveDeadlock tests if there's a deadlock when trying to +// pull an image while image clean up is in progress +func TestImagePullRemoveDeadlock(t *testing.T) { + ctrl := gomock.NewController(t) + defer ctrl.Finish() + client := NewMockDockerClient(ctrl) + + cfg := defaultTestConfig() + imageManager := NewImageManager(cfg, client, dockerstate.NewTaskEngineState()) + imageManager.SetSaver(statemanager.NewNoopStateManager()) + + sleepContainer := &api.Container{ + Name: "sleep", + Image: "busybox", + } + sleepContainerImageInspected := &docker.Image{ + ID: "sha256:qwerty", + } + + // Cause a fake delay when recording container reference so that the + // race condition between ImagePullLock and updateLock gets exercised + // If updateLock precedes ImagePullLock, it can cause a deadlock + client.EXPECT().InspectImage(sleepContainer.Image).Do(func(image string) { + time.Sleep(time.Second) + }).Return(sleepContainerImageInspected, nil) + + var wg sync.WaitGroup + wg.Add(2) + go func() { + ImagePullDeleteLock.Lock() + defer ImagePullDeleteLock.Unlock() + err := imageManager.RecordContainerReference(sleepContainer) + assert.NoError(t, err) + wg.Done() + }() + + go func() { + imageManager.(*dockerImageManager).removeUnusedImages() + wg.Done() + }() + wg.Wait() +} + func TestAddAndRemoveContainerToImageStateReferenceHappyPath(t *testing.T) { ctrl := gomock.NewController(t) defer ctrl.Finish() diff --git a/agent/engine/image/types.go b/agent/engine/image/types.go index 8a5c8a5bef0..5083e01964e 100644 --- a/agent/engine/image/types.go +++ b/agent/engine/image/types.go @@ -16,6 +16,7 @@ package image import ( "encoding/json" "fmt" + "strings" "sync" "time" @@ -29,6 +30,10 @@ type Image struct { Size int64 } +func (image *Image) String() string { + return fmt.Sprintf("ImageID: %s; Names: %s", image.ImageID, strings.Join(image.Names, ", ")) +} + // ImageState represents a docker image // and its state information such as containers associated with it type ImageState struct { @@ -114,3 +119,12 @@ func (imageState *ImageState) MarshalJSON() ([]byte, error) { LastUsedAt: imageState.LastUsedAt, }) } + +func (imageState *ImageState) String() string { + image := "" + if imageState.Image != nil { + image = imageState.Image.String() + } + return fmt.Sprintf("Image: [%s] referenced by %d containers; PulledAt: %s; LastUsedAt: %s", + image, len(imageState.Containers), imageState.PulledAt.String(), imageState.LastUsedAt.String()) +}