The master log contains these warnings:

Got RequestLimitExceeded error on AWS request (ec2::DescribeInstances)

Meaning we hit the AWS API call quota...

(In reply to Tomas Smetana from comment #2)
> The master log contains these warnings:
> 
> Got RequestLimitExceeded error on AWS request (ec2::DescribeInstances)
> 
> Meaning we hit the AWS API call quota...

From a user's point of view, what is the impact to the cluster?

I'll try to reproduce the problem to see whether this is simply a case of overloaded system and why exactly the volumes were not detached: i.e. if OpenShift tried to detach them but could not because of API quota or if the API call storm triggered some bug to show.

Did you try to wait "long enough"? Detacher tries periodically to detach the volume and deleter tries to delete it periodically too. It should cure itself in few minutes. Or dozens of minutes...

Oh, I see, waited for 1 hour. That should be enough. Sorry for the noise.

(In reply to Jan Safranek from comment #6)
> Oh, I see, waited for 1 hour. That should be enough. Sorry for the noise.

Yes I did. Actually, even more.

I repeated several times on step 2 and 3.
It lasted over 3 hours.
Even the latest created PV were deleted, the first lefeover was still there.

I've tried to reproduce this several times but failed (cleanup of the PVs took quite long -- ~20 minutes -- but eventually they were all detached in the end). I also failed to get the "RequestLimitExceeded" warning so I guess those two are related.

If anybody ever happens to encounter something similar: could you please also capture the controllers log? It might reveal more...

I am in a training this week.
Will try to reproduce this again early next week with controllers log.

@Tomas, thanks for the reply.

Good to know that we have a potential cause for this bz.

Let me know if anything need to be done from my side.

What I think is going on here (I'll try to describe so someone can correct me in case I missed something):

Once the volume is unmounted controller starts detaching the volume:
 -> OperationExecutor.DetachVolume()
    -> OperationGenerator.GenerateDetachVolumeFunc()
       (gets the AWS plugin, calls NewDetacher() to obtain AWS detacher)
       -> detacher.Detach() // this is the AWS plugin detacher
          -> aws.Volumes.DetachDisk() // calling cloudprovider
             -> Cloud.checkIfAttachedToNode()
                -> awsDisk.describeVolume()
                   (fails with RequestLimitExceeded on ec2::DescribeVolumes and
                    thigs start breaking here)

The checkIfAttachedToNode() method returns three values: disk information obtained by the describeVolume, whehter the disk is attached to the specified node and eventual error. In the case the describeVolume call returns error it does this:

if err != nil {
        describeError := fmt.Errorf("Error describing volume %s with %v", diskName, err)
        glog.Warning(describeError)
        awsDiskInfo.volumeState = "unknown"
        return awsDiskInfo, false, describeError
}

So, it sets the diskInfo.volumeState to "unknown" but leaves the rest of diskInfo empty, and tells the caller the volume is not attached to the node... The caller (AWS cloudprovider's DetachDisk) finds out there is no instance information in the diskInfo and the volume is not attached to any instance so it just returns immediately with no error.

This looks like a successful detach in the AWS plugin hence the "DetachVolume.Detach succeeded". The volume is marked as detached in the controller's ActualStateOfWorld (will never try to detach it again) and the PV controler starts deleting it. This fails since the volume is still attached to the instance: DetachDisk silently returned without instructing AWS to really detach the volume.

The PV controller calls AWS cloudprovider's DeleteDisk which again tries to call describeInstance and hits the quota from time to time. Nevertheless it also checks whether the volume can be deleted and of course finds out it can't... The PV controller's logic seems to be safe since it would re-try when hitting the API quota for describeVolume. We need to make sure the volume gets really detached though.

I forgot to add: I think this should be enough to fix the problem:

--- a/vendor/k8s.io/kubernetes/pkg/cloudprovider/providers/aws/aws.go
+++ b/vendor/k8s.io/kubernetes/pkg/cloudprovider/providers/aws/aws.go
@@ -2022,7 +2022,7 @@ func (c *Cloud) AttachDisk(diskName KubernetesVolumeID, nodeName types.NodeName,
 // DetachDisk implements Volumes.DetachDisk
 func (c *Cloud) DetachDisk(diskName KubernetesVolumeID, nodeName types.NodeName) (string, error) {
        diskInfo, attached, err := c.checkIfAttachedToNode(diskName, nodeName)
-       if diskInfo == nil {
+       if err != nil {
                return "", err
        }

I have the problem reproduced by faking describeVolume failures. The fix will be probably slightly more complicated than the one in comment #15 since as Hemant pointed out: I should check for error 404 in which case it is safe to assume the pod is detached and not try again.

Upstream PR:
https://github.com/kubernetes/kubernetes/pull/59569

Note: I have used the one-line patch in the end anyway... The cloudprovider re-formats the awsError so parsing out the code outside of the describeVolume method is not possible and also it is being called from several places so changing its behaviour is much more dangerous. The proposed change is aiming at this very specific issue.

@Tomas, Thanks for the PR.

The PR gives more chances to k8s to detach volumes, right?

(In reply to Hongkai Liu from comment #18)

> The PR gives more chances to k8s to detach volumes, right?

Yes. In case the describeVolumes fail (hit the API call quota limit in our case)  the DetachDisk method will propagate the error so the attach/detach controller will not mark the volume as detached and will try to detach it again.

I suppose this was actually quite a common issue on more loaded clusters and we may have solved one of the AWS mysterious problem. We'll see.

The next step would be to create a more "sophisticated" (and complex) fix that would differentiate among the errors and be robust even in weird situations, like someone manually managed to delete volume while the detach was in progress. It's very unlikely to happen but can't be ruled out... However the fix would touch more parts, will take more time and might bring regressions.

https://github.com/openshift/origin/pull/18544

Cool. Thanks for the reply. @Tomas.

Tested with atomic-openshift.x86_64         3.9.7-1.git.0.e1a30c3.el7

root@ip-172-31-14-145: ~/go/src/github.com/openshift/ose # git tag --contains 15c1c88b6bef9a437fed960822f203f0620b9074
...
v3.9.7-1
...

root@ip-172-31-14-145: ~/go/src/github.com/openshift/ose # git rev-list -n 1  v3.9.7-1
e1a30c3f321a9c6809f53bd4467d6442e92522c4


I can no longer see any PV left there. Tried about 10 times of creating/deleting. All PVs got cleaned up in my test.

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2018:1816