Busy azure-disk regularly fail to mount causing K8S Pod deployments to halt.

[dbalaouras]

I've setup Azure Container Service with Kubernetes and I use dynamic provisioning of volumes (see details below) when deploying new Pods. Quite frequently (about 10%) I get the following error which halts the deployment:

14h 1m 439 {controller-manager } Warning FailedMount Failed to attach volume "pvc-95aa8dbf-082e-11e7-af1a-000d3a2735d9" on node "k8s-agent-1da8a8df-2" with: Attach volume "clst-west-eu-dev-dynamic-pvc-95aa8dbf-082e-11e7-af1a-000d3a2735d9.vhd" to instance "k8s-agent-1DA8A8DF-2" failed with compute.VirtualMachinesClient#CreateOrUpdate: Failure responding to request: StatusCode=409 -- Original Error: autorest/azure: Service returned an error. Status=409 Code="AttachDiskWhileBeingDetached" Message="Cannot attach data disk 'clst-west-eu-dev-dynamic-pvc-f843f8fa-0663-11e7-af1a-000d3a2735d9.vhd' to VM 'k8s-agent-1DA8A8DF-2' because the disk is currently being detached. Please wait until the disk is completely detached and then try again."

The Pod deployment then halts forever, or until I delete the Pod and let the ReplicationController create a new one.

Any idea what is causing this?

Workflow

I have created the following StorageClass:

Name:		azure-disk
IsDefaultClass:	No
Annotations:	<none>
Provisioner:	kubernetes.io/azure-disk
Parameters:	location=westeu,skuName=Standard_LRS,storageAccount=<<storageaccount>>

The storageaccount does contain a Blob service named vhds.

When deploying a new Pod, I create a PVC that looks like this:

{
  "apiVersion": "v1",
  "kind": "PersistentVolumeClaim",
  "Provisioner": "kubernetes.io/azure-disk",
  "metadata": {
    "name": "test-deployment-pvc",
    "annotations": {
      "volume.beta.kubernetes.io/storage-class": "azure-disk"
    },
    "labels": {
      "org": "somelabel"
    }
  },
  "spec": {
    "accessModes": [
      "ReadWriteOnce"
    ],
    "resources": {
      "requests": {
        "storage": "1Gi"
      }
    }
  }
}

and finally use the PVC in the pods:

{
  "volumes": [
    {
      "persistentVolumeClaim": {
        "claimName": "test-deployment-pvc"
      },
      "name": "storage"
    }
  ]
}

[JackQuincy]

Sorry for the slow response time. There is a known performance issue here with the azure linux drivers. the kubernetes repo might have more expertise on this. But I do know that Kubernetes 1.6 has a speed up for attaching the disks. A work around we have asked people to use in the short term is to preformat the disks to ext4. Now how to do that in the PVC I'm not the most familiar with. @colemickens did I get this right?

[colemickens]

It's not the ext4 format being slow (which is addressed in 1.5.3+) since the PV was provisioned and in use, but rather wasn't able to detached and reattached when rescheduled.

@dbalaouras, I assume this is continuing to happen, even after 4-5 minutes? If not, as @JackQuincy indicated, the attach code has seen improvements in recent releases (1.5.3+, 1.6), and a full rewrite is coming in the future: kubernetes/kubernetes#41950

This should probably be filed as an upstream Issue on Kubernetes and diagnosed further there. @dbalaouras can you do that and link it here? It would be helpful if you can repro and include these things:

• The instanceView of the VM where the Pod was originally scheduled (where the detach is occurring) (hostA)
• The instanceView of the VM where the Pod has been rescheduled (where the attach is occurring) (hostB)
• Confirm that just deleting the Pod is sufficient to repair. In this case, does it work because the Pod lands back on (hostA) when rescheduled?

The instanceViews can be collected from https://resources.azure.com. Navigate through the hierarchy to the VM and then go to the child node "instanceView". You can also get it from the CLI: az vm get-instance-view --resource-group $RG --name $VM

[dbalaouras]

Hi @colemickens and @JackQuincy - thanks for the feedback.

Indeed, this error happens every 4-5 minutes; i.e. I see the following log:

Failed to attach volume "pvc-c209421d-12dd-11e7-af1a-000d3a2735d9" on node "k8s-agent-1da8a8df-2" with: Attach volume "clst-west-eu-dev-dynamic-pvc-c209421d-12dd-11e7-af1a-000d3a2735d9.vhd" to instance "k8s-agent-1DA8A8DF-2" failed with compute.VirtualMachinesClient#CreateOrUpdate: Failure responding to request: StatusCode=409 -- Original Error: autorest/azure: Service returned an error. Status=409 Code="AttachDiskWhileBeingDetached" Message="Cannot attach data disk 'clst-west-eu-dev-dynamic-pvc-f843f8fa-0663-11e7-af1a-000d3a2735d9.vhd' to VM 'k8s-agent-1DA8A8DF-2' because the disk is currently being detached. Please wait until the disk is completely detached and then try again."

I can also verify that the Pod is deployed successfully on a different node, right after I delete it and let the ReplicationController reschedule it.

With respect to the "VM where the Pod was originally scheduled", I don't see the Pod being re-scheduled when this error occurs. Here's the event log of a problematic Pod, 20 seconds after I launched it:

Events:
  FirstSeen	LastSeen	Count	From			SubObjectPath	Type		Reason		Message
  ---------	--------	-----	----			-------------	--------	------		-------
  20s		20s		1	{default-scheduler }			Normal		Scheduled	Successfully assigned bytecode-ghost-29-rc-tttss to k8s-agent-1da8a8df-2
  20s		3s		6	{controller-manager }			Warning		FailedMount	Failed to attach volume "pvc-2e1a5f47-131e-11e7-af1a-000d3a2735d9" on node "k8s-agent-1da8a8df-2" with: Attach volume "clst-west-eu-dev-dynamic-pvc-2e1a5f47-131e-11e7-af1a-000d3a2735d9.vhd" to instance "k8s-agent-1DA8A8DF-2" failed with compute.VirtualMachinesClient#CreateOrUpdate: Failure responding to request: StatusCode=409 -- Original Error: autorest/azure: Service returned an error. Status=409 Code="AttachDiskWhileBeingDetached" Message="Cannot attach data disk 'clst-west-eu-dev-dynamic-pvc-f843f8fa-0663-11e7-af1a-000d3a2735d9.vhd' to VM 'k8s-agent-1DA8A8DF-2' because the disk is currently being detached. Please wait until the disk is completely detached and then try again."

And the full description 10 minutes later:

Name:		bytecode-ghost-29-rc-tttss
Namespace:	default
Node:		k8s-agent-1da8a8df-2/10.240.0.10
Start Time:	Mon, 27 Mar 2017 21:50:03 +0300
Labels:		app_name=ghost
		deployment_id=bytecode-ghost-29
		org=bytecode
Status:		Pending
IP:
Controllers:	ReplicationController/bytecode-ghost-29-rc
Containers:
  bytecode-ghost-29:
    Container ID:
    Image:		ghost
    Image ID:
    Port:		2368/TCP
    Limits:
      cpu:	1
      memory:	1Gi
    Requests:
      cpu:		600m
      memory:		768Mi
    State:		Waiting
      Reason:		ContainerCreating
    Ready:		False
    Restart Count:	0
    Liveness:		http-get http://:2368/ delay=10s timeout=1s period=10s #success=1 #failure=3
    Readiness:		http-get http://:2368/ delay=0s timeout=1s period=10s #success=1 #failure=3
    Volume Mounts:
      /var/lib/ghost from ghost-files (rw)
      /var/lib/ghost/config.js from ghost-config (rw)
      /var/run/secrets/kubernetes.io/serviceaccount from default-token-8dmpk (ro)
    Environment Variables:	<none>
Conditions:
  Type		Status
  Initialized 	True
  Ready 	False
  PodScheduled 	True
Volumes:
  ghost-files:
    Type:	PersistentVolumeClaim (a reference to a PersistentVolumeClaim in the same namespace)
    ClaimName:	bytecode-ghost-29-pvc
    ReadOnly:	false
  ghost-config:
    Type:	ConfigMap (a volume populated by a ConfigMap)
    Name:	bytecode-ghost-29-cm
  default-token-8dmpk:
    Type:	Secret (a volume populated by a Secret)
    SecretName:	default-token-8dmpk
QoS Class:	Burstable
Tolerations:	<none>
Events:
  FirstSeen	LastSeen	Count	From				SubObjectPath	Type		Reason		Message
  ---------	--------	-----	----				-------------	--------	------		-------
  10m		10m		1	{default-scheduler }				Normal		Scheduled	Successfully assigned bytecode-ghost-29-rc-tttss to k8s-agent-1da8a8df-2
  8m		1m		4	{kubelet k8s-agent-1da8a8df-2}			Warning		FailedMount	Unable to mount volumes for pod "bytecode-ghost-29-rc-tttss_default(2ff0e683-131e-11e7-af1a-000d3a2735d9)": timeout expired waiting for volumes to attach/mount for pod "bytecode-ghost-29-rc-tttss"/"default". list of unattached/unmounted volumes=[ghost-files]
  8m		1m		4	{kubelet k8s-agent-1da8a8df-2}			Warning		FailedSync	Error syncing pod, skipping: timeout expired waiting for volumes to attach/mount for pod "bytecode-ghost-29-rc-tttss"/"default". list of unattached/unmounted volumes=[ghost-files]
  10m		3s		13	{controller-manager }				Warning		FailedMount	Failed to attach volume "pvc-2e1a5f47-131e-11e7-af1a-000d3a2735d9" on node "k8s-agent-1da8a8df-2" with: Attach volume "clst-west-eu-dev-dynamic-pvc-2e1a5f47-131e-11e7-af1a-000d3a2735d9.vhd" to instance "k8s-agent-1DA8A8DF-2" failed with compute.VirtualMachinesClient#CreateOrUpdate: Failure responding to request: StatusCode=409 -- Original Error: autorest/azure: Service returned an error. Status=409 Code="AttachDiskWhileBeingDetached" Message="Cannot attach data disk 'clst-west-eu-dev-dynamic-pvc-f843f8fa-0663-11e7-af1a-000d3a2735d9.vhd' to VM 'k8s-agent-1DA8A8DF-2' because the disk is currently being detached. Please wait until the disk is completely detached and then try again."

BTW, I just noticed that all failing Pods I see in my cluster having the same error, try to use the same volume: clst-west-eu-dev-dynamic-pvc-2e1a5f47-131e-11e7-af1a-000d3a2735d9.vhd.

Then I inspected the VM in the Azure Portal and saw this:

I'm also attaching an Instance View of the VM where the failing Pods were scheduled (with some data removed): k8s-agent-1DA8A8DF-2-instance-view.json.zip

At this point, I'm not quite sure if this is a k8s issue; not sure what to report to Kubernetes. Looks more like an issue w/ the AzureDisk Volume Plugin I guess?

[theobolo]

Exactly the same problem here !

[colemickens]

What version of Kubernetes are your clusters running?

[colemickens]

I need the instanceView from the machine where the disk was previously attached, otherwise I have no idea what's going on - the error message indicates that the detach never finished from the other node - I need the instanceView to know if that's true.

Also, please let me know the Kubernetes cluster version.

I'm still confused about timeline of events. Are the error messages about "DiskBlobNotFound" occurring at the exact same time as the "failed to attaches"? Is the disk actually detached from wherever it was scheduled? Please review my post above and provide all of the requested information. I can not troubleshoot this any further without it, especially since I can't repro.

This also should be filed as an Issue against Kubernetes repo.

---

Wait... are you attempting to run multiple pods with the same disk right now???

[dbalaouras]

@colemickens no, I am not attempting to run multiple pods with the same disk. I know this is not possible, plus I need a separate disk mounted to each single Pod and I am using dynamic provisioning.

For each deployment, I create a brand new (with a different name each time) PersistentVolumeClaim using a StorageClass with Provisioner kubernetes.io/azure-disk. See my first post for more details.

After a few deployments, I start seeing this error...I can't be sure in which pod (if any) the disk was originally attached to. During my initial (and quick) investigation, I could not find the disk mentioned in the error msg, mounted to any other node.

With respect to the DiskBlobNotFound error, I noticed that way after I saw the errors in the Pods. So again, can't be sure if that happened before or after the AttachDiskWhileBeingDetached error.

So let me do this maybe: I will try to reproduce in a fresh cluster and try to keep records of the disks that get created and the nodes they get mounted to. In the meanwhile, if you need me to collect any additional info or if you have any hints on what could cause this issue, please let me know.

[colemickens]

"After a few deployments" means what? You spun up a bunch more PVC and Pods and then ran into it? Or you did a rolling update, and the Pod got rescheduled?

If you're in Slack, please ping me, might be able to dig in a bit faster.

[dbalaouras]

@colemickens thx much for the help so far. Posting some updates here to keep this thread synced:

Each "deployment" in my use case includes:

• 1 ConfigMap
• 1 PVC
• 1 RC with a single POD which uses the PVC
• 1 service
• 1 Ingress

PVs usually get deleted after I uninstall the deployment (i.e. delete all above resources ^^). I did notice the following tho:

• in the Azure portal, several disks (VHDs) with the same URL were shown as mounted to a single VM. That VM was of the 2 Nodes which failed to host any Pod.
• I looked into that node and found no VHD mounted.
• after "umounting" the disks from the Portal, almost everything got back to normal.

Finally: I am trying to reproduce the issue in a new cluster that runs k8s 1.5.3 but everything seems very stable so far! I will post here any updates.

[colemickens]

Hi @dbalaouras Does this still need to be kept open? If you've not repro'd please close, otherwise give an update. Otherwise I'll go ahead and close this out again. Thanks!

[dbalaouras]

@colemickens sure, I'll close it now and re-open it only if it appears again in 1.5.3. Thanks!