Fix the deadlock caused by the ImagePullDeleteLock

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")

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()

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())
+}