AlreadyExists error cause repeated provisioning a volume

[orainxiong]

For some unknown reasons in our circumstance, external-provisioner probably provision an already existing Volume(the name of a Volume is the unique key to decide whether it exists). Base on the current logic, that means it causes repeated provisioning a volume for the given PVC. To be worse, there is no external API I can use to delete the volume manually.

In a very simplified view, the functionality of provisionClaimOperation is responsible for provisioning a volume and could be broken down into the following steps :

• Obtains a given PVC mapping to specific storage class;
• Calls against CSI-Driver to provision a Volume;
• Create a PV to save the volume;

Based on the CSI RPC specifications, the current default behavior is that CSI-Driver explicitly raises an AlreadyExists error if the volume already exists. As a result, provisionClaimOperation have to repeated provision the volume unless the already existing volume be deleted manually.

volume, err := ctrl.provisioner.Provision(options)
	if err != nil {
		if ierr, ok := err.(*IgnoredError); ok {
			// Provision ignored, do nothing and hope another provisioner will provision it.
			glog.Infof("provision of claim %q ignored: %v", claimToClaimKey(claim), ierr)
			return nil
		}
		strerr := fmt.Sprintf("Failed to provision volume with StorageClass %q: %v", claimClass, err)
		glog.Errorf("Failed to provision volume for claim %q with StorageClass %q: %v", claimToClaimKey(claim), claimClass, err)
		ctrl.eventRecorder.Event(claim, v1.EventTypeWarning, "ProvisioningFailed", strerr)
		return err
	}

I plan to take some time to figure out why more than one provisioning for the same PVC happens.
For now, IMO probably we can think of AlreadyExists error as an ignored error to improve code robustness.

	opts := wait.Backoff{Duration: backoffDuration, Factor: backoffFactor, Steps: backoffSteps}
	err = wait.ExponentialBackoff(opts, func() (bool, error) {
		ctx, cancel := context.WithTimeout(context.Background(), p.timeout)
		defer cancel()
		rep, err = p.csiClient.CreateVolume(ctx, &req)
		if err == nil {
			// CreateVolume has finished successfully
			return true, nil
		}

		if status, ok := status.FromError(err); ok {
			if status.Code() == codes.DeadlineExceeded {
				// CreateVolume timed out, give it another chance to complete
				glog.Warningf("CreateVolume timeout: %s has expired, operation will be retried", p.timeout.String())
				return false, nil
			}
		}
		// CreateVolume failed , no reason to retry, bailing from ExponentialBackoff
		return false, err
	})

        // think of `AlreadyExists` error as an ignored error
	if status, ok := status.FromError(err); ok {
		if status.Code() == codes.AlreadyExists {
			// CreateVolume timed out, give it another chance to complete
			return nil, &controller.IgnoredError{Reason: "Volume already exists"}
		}
	}

[orainxiong]

@vladimirvivien

Looking forward to your comments.

[msau42]

In the CSI drivers I've seen, we return success when the volume already exists, not error

[msau42]

Also from the CSI spec:

This operation MUST be idempotent. If a volume corresponding to the specified volume name already exists, is accessible from accessibility_requirements, and is compatible with the specified capacity_range, volume_capabilities and parameters in the CreateVolumeRequest, the Plugin MUST reply 0 OK with the corresponding CreateVolumeResponse

[orainxiong]

@msau42 Many Thanks.

I have modified the implementation of createVolume logic by returning success to make it idempotence, but I hit another serious problem.

After code refactors, provisionClaimOperation subsequently creates a PV object in order to save the Volume. Because the corresponding PV already exists as well, the function of PersistentVolumes().Create() will raise the similar AlreadyExists Error as CSI-Driver does.

	for i := 0; i < ctrl.createProvisionedPVRetryCount; i++ {
		glog.V(4).Infof("provisionClaimOperation [%s]: trying to save volume %s", claimToClaimKey(claim), volume.Name)
		if _, err = ctrl.client.CoreV1().PersistentVolumes().Create(volume); err == nil {
			// Save succeeded.
			glog.Infof("volume %q for claim %q saved", volume.Name, claimToClaimKey(claim))
			break
		}
		// Save failed, try again after a while.
		glog.Infof("failed to save volume %q for claim %q: %v", volume.Name, claimToClaimKey(claim), err)
		time.Sleep(ctrl.createProvisionedPVInterval)
	}

After the several attempts fail, the default behavior will clean Volume by deleting it.

		for i := 0; i < ctrl.createProvisionedPVRetryCount; i++ {
			if err = ctrl.provisioner.Delete(volume); err == nil {
				// Delete succeeded
				glog.V(4).Infof("provisionClaimOperation [%s]: cleaning volume %s succeeded", claimToClaimKey(claim), volume.Name)
				break
			}
			// Delete failed, try again after a while.
			glog.Infof("failed to delete volume %q: %v", volume.Name, err)
			time.Sleep(ctrl.createProvisionedPVInterval)
		}

For more code details

As a result, Volume has been deleted, while both PVC and PV still exists. In case the Volume is in use, it will cause unpredictable IO error.

IMO, probably We are supposed to distinguish the AlreadyExists with the other errors.

[msau42]

Can you clarify the sequence of events you are seeing? The PV object should only be created after Provision() successfully returns. And once PV object is successfully created, then you should not see the Provision() being called again

[wongma7]

Yes, we should be checking for AlreadyExists in the PV.Create part of the code like upstream https://github.com/kubernetes/kubernetes/blob/master/pkg/controller/volume/persistentvolume/pv_controller.go#L1502 However the issue will be extremely rare due to the safeguard here at the start of Provision https://github.com/kubernetes-incubator/external-storage/blob/master/lib/controller/controller.go#L949 and the impossibility (I would hope) of 2 controllers racing to Provision the same thing at the same time

As for a CSI driver returning AlreadyExists, if it's following the spec then AlreadyExists is an error where the volume already exists but is incompatible.

"Indicates that a volume corresponding to the specified volume name already exists but is incompatible with the specified capacity_range, volume_capabilities or parameters."

A volume that already exists and is compatible should return nil error as msau42 said.

[orainxiong]

I am not sure I fully understand this problem, but I think it probably is an cache related issue rather than the racing issue of multiple controllers.

The following code (for more details) is responsible for ensuring whether the corresponding PV already exists or not, if exists the Provision()should not be called again.

	_, exists, err := ctrl.volumes.GetByKey(fmt.Sprintf("%s/%s", namespace, pvName))

In order to avoid API throttling, the latest version external-provisioner is refactored to use local cache rather than directly touching API Server. For more details, please visit: #68

Once there are more than one provisionClaimOperation being called for a given PVC in a very short time(0.1 ~ 0.5 second), the second one probably can't find the corresponding PV object from the local cache after the first one successfully returns. The printed log shows more details:

// The first one started
I0813 17:57:58.956265       1 controller.go:1099] scheduleOperation[provision-default/archive-yt-test1-0[5bc11503-9edf-11e8-923d-faa1f8c84900]]
I0813 17:57:58.956292       1 controller.go:749] provisionClaimOperation [default/archive-yt-test1-0] started, class: "csi-qcfs"

// The first one successfully returned
I0813 17:58:00.617709       1 controller.go:831] provisionClaimOperation [default/archive-yt-test1-0]: trying to save volume pvc-5bc115039edf11e8
I0813 17:58:00.684158       1 controller.go:834] volume "pvc-5bc115039edf11e8" for claim "default/archive-yt-test1-0" saved
I0813 17:58:00.684180       1 controller.go:870] volume "pvc-5bc115039edf11e8" provisioned for claim "default/archive-yt-test1-0"

// The second one came along in about 0.3 second after the PV object is successfully created
I0813 17:58:00.931261       1 controller.go:1099] scheduleOperation[provision-default/archive-yt-test1-0[5bc11503-9edf-11e8-923d-faa1f8c84900]]
I0813 17:58:00.931360       1 controller.go:749] provisionClaimOperation [default/archive-yt-test1-0] started, class: "csi-qcfs"

I think it is a cache out-of-sync related issue. IMO, there are probably 2 options to fix the problem :

• Directly call against API Server in this place to fetch the exact status of the corresponding PV object;
• provisionClaimOperation supports idempotence as CSI driver does;

[wongma7]

What version of the controller exactly did that happen in? Two provision claim operations happening on the same claim object within 2 seconds shouldn’t be possible.

[wongma7]

By version I mean git commit hash btw. I think scheduleoperation is goroutinemap thing

[orainxiong]

Base on release 0.2.0, I just refactor code to use informer cache.

The specified Volume is successfully created and subsequently deleted in a very short time.

I think the second Provision() comes because of the resyncing of cache.

[orainxiong]

I think we could reproduce it when all conditions are met at the same time:

• The first Provision() successfully returns because of the adding event of PVC ;
• The second Provision() comes in a very short time because of the updating event of PVC;
• The second Provision() use the local cache of PV object to check whether it exists or not, but the local cache of PV object is not the most up-to-date at that time;

Poor performance (CPU, Memory, Network) could increase the probability of that happening.

[msau42]

The way that the PV controller avoids this issue is that it updates it's in-memory cache first, and then sends the API update.

[wongma7]

@orainxiong okay I understand the issue now. Recall my comments here: kubernetes-retired/external-storage#837 (comment) . I said I'm okay with the change with the assumption that informer cache would reflect the new PV immediately, which is probably wrong. I also said something about switching from goroutinemap to work queues in the 3rd comment there but I'm not sure what I meant. If you can replicate this easily, I would try again with the latest lib version instead of v0.2.0 since it has work queues and the informer changes already, maybe we will figure out what I meant :)

Directly call against API Server in this place to fetch the exact status of the corresponding PV object;

I would prefer this, i.e. we just change it back to how it was

provisionClaimOperation supports idempotence as CSI driver does;

it does; like i said, the CSI driver returning AlreadyExists is an error. it should return nil.

IMO we should do both. If you tally up the API calls it’s at most 2kube+1backend

[wongma7]

Sorry, made a mistake in last comment, provisionclaimopetation Isn’t idempotent since we need to make it check for pv AlreadyExists (different from csi alreadyexists... confusing)

[orainxiong]

@wongma7 You are right. Indeed, I don' t understand your definitive meaning until I recall your comments. : - )

IMO I think probably we should move on refactoring, so I'm gonna mirror PV controller current logic, updates it's in-memory cache as @msau42 proposed, to guarantee cache up-to-date.

I will break this work down into the following steps:

• Upgrade to the latest external-storage v5.0.0, and check which is compatible with external-provisioner
• Move on code refactor by mirroring PV controller current logic
• Do endurance test , like repeatedly provisioning/deleting 100 Volume at once in a day, and that sort of thing

If it works, I will create PR to repo external-storage.

Please let me know, if I ignore something important.

[wongma7]

I don't want to maintain an internal cache just to solve this and we cannot modify the SharedInformer's cache. My understanding ist hat PV controller needs internal cache not only to avoid Provisioning twice but to avoid conflicts with syncClaim & syncVolume, it is complicated. I would prefer we bring back the single API call in Provision. Consider that the pv controller still does the API call https://github.com/kubernetes/kubernetes/blob/master/pkg/controller/volume/persistentvolume/pv_controller.go#L1404 even though its internal cache should be up to date and trustable. https://github.com/kubernetes/kubernetes/blob/master/pkg/controller/volume/persistentvolume/pv_controller.go#L1510

[orainxiong]

Anyway, I think we missed an important detail.

In fact, external-storage use getProvisionedVolumeNameForClaim() to obtain deterministic PV name(like pvc-9278f458-a053-11e8-9af0-5254003d0a20) to check whether PV exists or not, and external-provisioner use makeVolumeName() to generate PV name(like pvc-9278f458a05311e8) to finally create a PV, they are independent and different. That means, we actually don't know the correct PV name of a given unbound PVC. Obviously, whatever touching API Server or updating local cache both of them can found nothing even if the PV object already exists.

As the image shows the difference:

There are the main two steps to ensure the operation of provisioning performs correctly:

• GoRoutineMap is responsible for guaranteeing there is no more than one Provision() in flight for a given PVC;
• Touching API Server to avoid Provision() an already existing PV;

We had expected both of them works well. Indeed, the step 2 is always invalid, and GoRoutineMap basically plays the only role to guarantee all the operations correct. Without the E2E endurance test, it is very hard to notice it. However, after fixing step 2, it hits the out-of-sync related issue again, and we can easily reproduce it by repeatedly creating/deleting a bunch of PVC at once. So, it is a complicated issue which involves many factors.

Sorry for my half-solution and mistakes, I intend to create patch to fix all the issues based on v5.0.0, which mainly involves the following changes:

• Make both of makeVolumeName() and getProvisionedVolumeNameForClaim() the same. We could start by simply duplicating codes, and later we should discuss how to make external-storage aware makeVolumeName(), maybe we could introduce a new parameter being exposed to external-provisioner;
• Back to call out to API Server instead of using local cache;

[wongma7]

@orainxiong OK, thanks again for thorough analysis.

Make both of makeVolumeName() and getProvisionedVolumeNameForClaim() the same. We could start by simply duplicating codes, and later we should discuss how to make external-storage aware makeVolumeName(), maybe we could introduce a new parameter being exposed to external-provisioner;

There have been requests in the past to make getProvisionedVolumeNameForClaim() configurable / exposing some interface to let provisioners determine the name. I will work on this, exposing it. As long as it returns a unique name that can be derived from the PVC there should be no problem. edit: there was a PR kubernetes-retired/external-storage#612 but needs work. I'll pick it up