{"action":"created","issue":{"url":"https://api.github.com/repos/kubernetes/kubernetes/issues/35180","repository_url":"https://api.github.com/repos/kubernetes/kubernetes","labels_url":"https://api.github.com/repos/kubernetes/kubernetes/issues/35180/labels{/name}","comments_url":"https://api.github.com/repos/kubernetes/kubernetes/issues/35180/comments","events_url":"https://api.github.com/repos/kubernetes/kubernetes/issues/35180/events","html_url":"https://github.com/kubernetes/kubernetes/issues/35180","id":184165030,"number":35180,"title":"azure disk: timing data","user":{"login":"colemickens","id":327028,"avatar_url":"https://avatars.githubusercontent.com/u/327028?v=3","gravatar_id":"","url":"https://api.github.com/users/colemickens","html_url":"https://github.com/colemickens","followers_url":"https://api.github.com/users/colemickens/followers","following_url":"https://api.github.com/users/colemickens/following{/other_user}","gists_url":"https://api.github.com/users/colemickens/gists{/gist_id}","starred_url":"https://api.github.com/users/colemickens/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/colemickens/subscriptions","organizations_url":"https://api.github.com/users/colemickens/orgs","repos_url":"https://api.github.com/users/colemickens/repos","events_url":"https://api.github.com/users/colemickens/events{/privacy}","received_events_url":"https://api.github.com/users/colemickens/received_events","type":"User","site_admin":false},"labels":[{"id":116719829,"url":"https://api.github.com/repos/kubernetes/kubernetes/labels/area/kubelet","name":"area/kubelet","color":"0052cc","default":false},{"id":173493827,"url":"https://api.github.com/repos/kubernetes/kubernetes/labels/team/cluster%20(deprecated%20-%20do%20not%20use)","name":"team/cluster (deprecated - do not use)","color":"ededed","default":false}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":16,"created_at":"2016-10-20T08:27:21Z","updated_at":"2017-01-17T10:21:56Z","closed_at":null,"body":"**Environment**:\n- **Cloud provider or hardware configuration**: Azure\n- **OS** (e.g. from /etc/os-release): Ubuntu Xenial\n- **Kernel** (e.g. `uname -a`): Whatever is in Xenial today\n- **Install tools**: Custom\n- **Others**: N/a\n\n**Azure Environment**:\n- westus2\n- Standard_D2\n\n**TL;DR**:\n- Initial pod start takes 9 minutes\n- Rescheduling the pod takes 11-12 minutes due to bugs mentioned below.\n\n**Raw logs:**\n- [`kubectl logs --namespace kube-system kube-controller-manager-k8s-master-27819504-0 | grep --text azure | grep -v load | grep -v route | gist -R`](https://gist.github.com/anonymous/7126d51c573897cd4b3fd246b8085ed2/raw)\n- [`sudo journalctl -u kubelet | grep --text azure | gist-paste -R`](https://gist.githubusercontent.com/anonymous/a7691078dffb467cf81d51291ac131ad/raw)\n## Timelines\n### Initial Pod\n#### Attachment (kube-controller-manager)\n\n```\nI1020 07:22:06.068048       1 event.go:217] Event(api.ObjectReference{Kind:\"ReplicaSet\", Namespace:\"default\", Name:\"test-azure-disk-3967202423\", UID:\"e78749bb-9695-11e6-9f69-000d3af74706\", APIVersion:\"extensions\", ResourceVersion:\"3107\", FieldPath:\"\"}): type: 'Normal' reason: 'SuccessfulCreate' Created pod: test-azure-disk-3967202423-wftda\nI1020 07:22:06.073019       1 deployment_controller.go:464] Error syncing deployment default/test-azure-disk: Operation cannot be fulfilled on deployments.extensions \"test-azure-disk\": the object has been modified; please apply your changes to the latest version and try again\nI1020 07:22:06.119824       1 deployment_controller.go:464] Error syncing deployment default/test-azure-disk: Operation cannot be fulfilled on deployments.extensions \"test-azure-disk\": the object has been modified; please apply your changes to the latest version and try again\nI1020 07:22:06.159638       1 reconciler.go:168] Started AttachVolume for volume \"kubernetes.io/azure-disk/KubeTestDisk0\" to node \"k8s-agentpool1-27819504-1\"\nI1020 07:24:06.551271       1 operation_executor.go:515] AttachVolume.Attach succeeded for volume \"kubernetes.io/azure-disk/KubeTestDisk0\" (spec.Name: \"volume-azuredisk\") from node \"k8s-agentpool1-27819504-1\".\n```\n\n**Duration (attach)**: 2 minutes. (Maybe we should poll faster than Azure says to. TODO: Figure out the default CRP polling interval for disk attach)\n#### Wait for attach (kubelet on first node)\n\n```\nOct 20 07:22:06 k8s-agentpool1-27819504-1 docker[4276]: I1020 07:22:06.121062    4562 kubelet.go:2293] SyncLoop (ADD, \"api\"): \"test-azure-disk-3967202423-wftda_default(e78c2a9a-9695-11e6-9f69-000d3af74706)\"\nOct 20 07:22:06 k8s-agentpool1-27819504-1 docker[4276]: I1020 07:22:06.241400    4562 reconciler.go:225] VerifyControllerAttachedVolume operation started for volume \"kubernetes.io/azure-disk/KubeTestDisk0\" (spec.Name: \"volume-azuredisk\") pod \"e78c2a9a-9695-11e6-9f69-000d3af74706\" (UID: \"e78c2a9a-9695-11e6-9f69-000d3af74706\")\nOct 20 07:22:06 k8s-agentpool1-27819504-1 docker[4276]: E1020 07:22:06.241774    4562 nestedpendingoperations.go:253] Operation for \"\\\"kubernetes.io/azure-disk/KubeTestDisk0\\\"\" failed. No retries permitted until 2016-10-20 07:22:06.741744995 +0000 UTC (durationBeforeRetry 500ms). Error: Volume \"kubernetes.io/azure-disk/KubeTestDisk0\" (spec.Name: \"volume-azuredisk\") pod \"e78c2a9a-9695-11e6-9f69-000d3af74706\" (UID: \"e78c2a9a-9695-11e6-9f69-000d3af74706\") has not yet been added to the list of VolumesInUse in the node's volume status.\nOct 20 07:22:06 k8s-agentpool1-27819504-1 docker[4276]: I1020 07:22:06.742336    4562 reconciler.go:225] VerifyControllerAttachedVolume operation started for volume \"kubernetes.io/azure-disk/KubeTestDisk0\" (spec.Name: \"volume-azuredisk\") pod \"e78c2a9a-9695-11e6-9f69-000d3af74706\" (UID: \"e78c2a9a-9695-11e6-9f69-000d3af74706\")\nOct 20 07:22:06 k8s-agentpool1-27819504-1 docker[4276]: E1020 07:22:06.742511    4562 nestedpendingoperations.go:253] Operation for \"\\\"kubernetes.io/azure-disk/KubeTestDisk0\\\"\" failed. No retries permitted until 2016-10-20 07:22:07.742490643 +0000 UTC (durationBeforeRetry 1s). Error: Volume \"kubernetes.io/azure-disk/KubeTestDisk0\" (spec.Name: \"volume-azuredisk\") pod \"e78c2a9a-9695-11e6-9f69-000d3af74706\" (UID: \"e78c2a9a-9695-11e6-9f69-000d3af74706\") has not yet been added to the list of VolumesInUse in the node's volume status.\nOct 20 07:22:07 k8s-agentpool1-27819504-1 docker[4276]: I1020 07:22:07.744575    4562 reconciler.go:225] VerifyControllerAttachedVolume operation started for volume \"kubernetes.io/azure-disk/KubeTestDisk0\" (spec.Name: \"volume-azuredisk\") pod \"e78c2a9a-9695-11e6-9f69-000d3af74706\" (UID: \"e78c2a9a-9695-11e6-9f69-000d3af74706\")\nOct 20 07:22:07 k8s-agentpool1-27819504-1 docker[4276]: E1020 07:22:07.744818    4562 nestedpendingoperations.go:253] Operation for \"\\\"kubernetes.io/azure-disk/KubeTestDisk0\\\"\" failed. No retries permitted until 2016-10-20 07:22:09.744789506 +0000 UTC (durationBeforeRetry 2s). Error: Volume \"kubernetes.io/azure-disk/KubeTestDisk0\" (spec.Name: \"volume-azuredisk\") pod \"e78c2a9a-9695-11e6-9f69-000d3af74706\" (UID: \"e78c2a9a-9695-11e6-9f69-000d3af74706\") has not yet been added to the list of VolumesInUse in the node's volume status.\nOct 20 07:22:09 k8s-agentpool1-27819504-1 docker[4276]: I1020 07:22:09.750383    4562 reconciler.go:225] VerifyControllerAttachedVolume operation started for volume \"kubernetes.io/azure-disk/KubeTestDisk0\" (spec.Name: \"volume-azuredisk\") pod \"e78c2a9a-9695-11e6-9f69-000d3af74706\" (UID: \"e78c2a9a-9695-11e6-9f69-000d3af74706\")\nOct 20 07:22:09 k8s-agentpool1-27819504-1 docker[4276]: E1020 07:22:09.750613    4562 nestedpendingoperations.go:253] Operation for \"\\\"kubernetes.io/azure-disk/KubeTestDisk0\\\"\" failed. No retries permitted until 2016-10-20 07:22:13.750587388 +0000 UTC (durationBeforeRetry 4s). Error: Volume \"kubernetes.io/azure-disk/KubeTestDisk0\" (spec.Name: \"volume-azuredisk\") pod \"e78c2a9a-9695-11e6-9f69-000d3af74706\" (UID: \"e78c2a9a-9695-11e6-9f69-000d3af74706\") has not yet been added to the list of VolumesInUse in the node's volume status.\nOct 20 07:22:13 k8s-agentpool1-27819504-1 docker[4276]: I1020 07:22:13.758182    4562 reconciler.go:225] VerifyControllerAttachedVolume operation started for volume \"kubernetes.io/azure-disk/KubeTestDisk0\" (spec.Name: \"volume-azuredisk\") pod \"e78c2a9a-9695-11e6-9f69-000d3af74706\" (UID: \"e78c2a9a-9695-11e6-9f69-000d3af74706\")\nOct 20 07:22:13 k8s-agentpool1-27819504-1 docker[4276]: E1020 07:22:13.761167    4562 nestedpendingoperations.go:253] Operation for \"\\\"kubernetes.io/azure-disk/KubeTestDisk0\\\"\" failed. No retries permitted until 2016-10-20 07:22:21.761148159 +0000 UTC (durationBeforeRetry 8s). Error: Volume \"kubernetes.io/azure-disk/KubeTestDisk0\" (spec.Name: \"volume-azuredisk\") pod \"e78c2a9a-9695-11e6-9f69-000d3af74706\" (UID: \"e78c2a9a-9695-11e6-9f69-000d3af74706\") is not yet attached according to node status.\nOct 20 07:22:21 k8s-agentpool1-27819504-1 docker[4276]: I1020 07:22:21.780772    4562 reconciler.go:225] VerifyControllerAttachedVolume operation started for volume \"kubernetes.io/azure-disk/KubeTestDisk0\" (spec.Name: \"volume-azuredisk\") pod \"e78c2a9a-9695-11e6-9f69-000d3af74706\" (UID: \"e78c2a9a-9695-11e6-9f69-000d3af74706\")\nOct 20 07:22:21 k8s-agentpool1-27819504-1 docker[4276]: E1020 07:22:21.783591    4562 nestedpendingoperations.go:253] Operation for \"\\\"kubernetes.io/azure-disk/KubeTestDisk0\\\"\" failed. No retries permitted until 2016-10-20 07:22:37.783560355 +0000 UTC (durationBeforeRetry 16s). Error: Volume \"kubernetes.io/azure-disk/KubeTestDisk0\" (spec.Name: \"volume-azuredisk\") pod \"e78c2a9a-9695-11e6-9f69-000d3af74706\" (UID: \"e78c2a9a-9695-11e6-9f69-000d3af74706\") is not yet attached according to node status.\nOct 20 07:22:37 k8s-agentpool1-27819504-1 docker[4276]: I1020 07:22:37.818016    4562 reconciler.go:225] VerifyControllerAttachedVolume operation started for volume \"kubernetes.io/azure-disk/KubeTestDisk0\" (spec.Name: \"volume-azuredisk\") pod \"e78c2a9a-9695-11e6-9f69-000d3af74706\" (UID: \"e78c2a9a-9695-11e6-9f69-000d3af74706\")\nOct 20 07:22:37 k8s-agentpool1-27819504-1 docker[4276]: E1020 07:22:37.826516    4562 nestedpendingoperations.go:253] Operation for \"\\\"kubernetes.io/azure-disk/KubeTestDisk0\\\"\" failed. No retries permitted until 2016-10-20 07:23:09.826496865 +0000 UTC (durationBeforeRetry 32s). Error: Volume \"kubernetes.io/azure-disk/KubeTestDisk0\" (spec.Name: \"volume-azuredisk\") pod \"e78c2a9a-9695-11e6-9f69-000d3af74706\" (UID: \"e78c2a9a-9695-11e6-9f69-000d3af74706\") is not yet attached according to node status.\nOct 20 07:23:09 k8s-agentpool1-27819504-1 docker[4276]: I1020 07:23:09.832175    4562 reconciler.go:225] VerifyControllerAttachedVolume operation started for volume \"kubernetes.io/azure-disk/KubeTestDisk0\" (spec.Name: \"volume-azuredisk\") pod \"e78c2a9a-9695-11e6-9f69-000d3af74706\" (UID: \"e78c2a9a-9695-11e6-9f69-000d3af74706\")\nOct 20 07:23:09 k8s-agentpool1-27819504-1 docker[4276]: E1020 07:23:09.835290    4562 nestedpendingoperations.go:253] Operation for \"\\\"kubernetes.io/azure-disk/KubeTestDisk0\\\"\" failed. No retries permitted until 2016-10-20 07:24:13.835271426 +0000 UTC (durationBeforeRetry 1m4s). Error: Volume \"kubernetes.io/azure-disk/KubeTestDisk0\" (spec.Name: \"volume-azuredisk\") pod \"e78c2a9a-9695-11e6-9f69-000d3af74706\" (UID: \"e78c2a9a-9695-11e6-9f69-000d3af74706\") is not yet attached according to node status.\nOct 20 07:24:06 k8s-agentpool1-27819504-1 docker[4276]: E1020 07:24:06.121963    4562 kubelet.go:1813] Unable to mount volumes for pod \"test-azure-disk-3967202423-wftda_default(e78c2a9a-9695-11e6-9f69-000d3af74706)\": timeout expired waiting for volumes to attach/mount for pod \"test-azure-disk-3967202423-wftda\"/\"default\". list of unattached/unmounted volumes=[volume-azuredisk]; skipping pod\nOct 20 07:24:06 k8s-agentpool1-27819504-1 docker[4276]: E1020 07:24:06.122189    4562 pod_workers.go:184] Error syncing pod e78c2a9a-9695-11e6-9f69-000d3af74706, skipping: timeout expired waiting for volumes to attach/mount for pod \"test-azure-disk-3967202423-wftda\"/\"default\". list of unattached/unmounted volumes=[volume-azuredisk]\nOct 20 07:24:13 k8s-agentpool1-27819504-1 docker[4276]: I1020 07:24:13.891073    4562 reconciler.go:225] VerifyControllerAttachedVolume operation started for volume \"kubernetes.io/azure-disk/KubeTestDisk0\" (spec.Name: \"volume-azuredisk\") pod \"e78c2a9a-9695-11e6-9f69-000d3af74706\" (UID: \"e78c2a9a-9695-11e6-9f69-000d3af74706\")\nOct 20 07:24:13 k8s-agentpool1-27819504-1 docker[4276]: I1020 07:24:13.893908    4562 operation_executor.go:1074] Controller successfully attached volume \"kubernetes.io/azure-disk/KubeTestDisk0\" (spec.Name: \"volume-azuredisk\") pod \"e78c2a9a-9695-11e6-9f69-000d3af74706\" (UID: \"e78c2a9a-9695-11e6-9f69-000d3af74706\") devicePath: \"0\"\n```\n\n**Duration**: \n\nWe fail to attach in a timely fashion and it times out. The log indicates it retries the VerifyControllerAttachedVolume every ~48 seconds or something... so we could be losing close to that much time potentially.\n#### Format/Mount (kubelet on first node)\n\n```\nOct 20 07:24:13 k8s-agentpool1-27819504-1 docker[4276]: I1020 07:24:13.991382    4562 operation_executor.go:707] Entering MountVolume.WaitForAttach for volume \"kubernetes.io/azure-disk/KubeTestDisk0\" (spec.Name: \"volume-azuredisk\") pod \"e78c2a9a-9695-11e6-9f69-000d3af74706\" (UID: \"e78c2a9a-9695-11e6-9f69-000d3af74706\") DevicePath: \"0\"\nOct 20 07:24:13 k8s-agentpool1-27819504-1 docker[4276]: I1020 07:24:13.991556    4562 reconciler.go:299] MountVolume operation started for volume \"kubernetes.io/azure-disk/KubeTestDisk0\" (spec.Name: \"volume-azuredisk\") to pod \"e78c2a9a-9695-11e6-9f69-000d3af74706\" (UID: \"e78c2a9a-9695-11e6-9f69-000d3af74706\").\nOct 20 07:24:15 k8s-agentpool1-27819504-1 docker[4276]: I1020 07:24:15.323181    4562 operation_executor.go:727] MountVolume.WaitForAttach succeeded for volume \"kubernetes.io/azure-disk/KubeTestDisk0\" (spec.Name: \"volume-azuredisk\") pod \"e78c2a9a-9695-11e6-9f69-000d3af74706\" (UID: \"e78c2a9a-9695-11e6-9f69-000d3af74706\").\nOct 20 07:24:15 k8s-agentpool1-27819504-1 docker[4276]: Mounting arguments: /dev/sdc /var/lib/kubelet/plugins/kubernetes.io/azure-disk/mounts/KubeTestDisk0 ext4 [defaults]\nOct 20 07:26:16 k8s-agentpool1-27819504-1 docker[4276]: E1020 07:26:16.896031    4562 kubelet.go:1813] Unable to mount volumes for pod \"test-azure-disk-3967202423-wftda_default(e78c2a9a-9695-11e6-9f69-000d3af74706)\": timeout expired waiting for volumes to attach/mount for pod \"test-azure-disk-3967202423-wftda\"/\"default\". list of unattached/unmounted volumes=[volume-azuredisk]; skipping pod\nOct 20 07:26:16 k8s-agentpool1-27819504-1 docker[4276]: E1020 07:26:16.896211    4562 pod_workers.go:184] Error syncing pod e78c2a9a-9695-11e6-9f69-000d3af74706, skipping: timeout expired waiting for volumes to attach/mount for pod \"test-azure-disk-3967202423-wftda\"/\"default\". list of unattached/unmounted volumes=[volume-azuredisk]\nOct 20 07:28:28 k8s-agentpool1-27819504-1 docker[4276]: E1020 07:28:28.896047    4562 kubelet.go:1813] Unable to mount volumes for pod \"test-azure-disk-3967202423-wftda_default(e78c2a9a-9695-11e6-9f69-000d3af74706)\": timeout expired waiting for volumes to attach/mount for pod \"test-azure-disk-3967202423-wftda\"/\"default\". list of unattached/unmounted volumes=[volume-azuredisk]; skipping pod\nOct 20 07:28:28 k8s-agentpool1-27819504-1 docker[4276]: E1020 07:28:28.896076    4562 pod_workers.go:184] Error syncing pod e78c2a9a-9695-11e6-9f69-000d3af74706, skipping: timeout expired waiting for volumes to attach/mount for pod \"test-azure-disk-3967202423-wftda\"/\"default\". list of unattached/unmounted volumes=[volume-azuredisk]\nOct 20 07:30:39 k8s-agentpool1-27819504-1 docker[4276]: E1020 07:30:39.896405    4562 kubelet.go:1813] Unable to mount volumes for pod \"test-azure-disk-3967202423-wftda_default(e78c2a9a-9695-11e6-9f69-000d3af74706)\": timeout expired waiting for volumes to attach/mount for pod \"test-azure-disk-3967202423-wftda\"/\"default\". list of unattached/unmounted volumes=[volume-azuredisk]; skipping pod\nOct 20 07:30:39 k8s-agentpool1-27819504-1 docker[4276]: E1020 07:30:39.896434    4562 pod_workers.go:184] Error syncing pod e78c2a9a-9695-11e6-9f69-000d3af74706, skipping: timeout expired waiting for volumes to attach/mount for pod \"test-azure-disk-3967202423-wftda\"/\"default\". list of unattached/unmounted volumes=[volume-azuredisk]\nOct 20 07:31:55 k8s-agentpool1-27819504-1 docker[4276]: I1020 07:31:55.105097    4562 mount_linux.go:345] Disk successfully formatted (mkfs): ext4 - /dev/sdc /var/lib/kubelet/plugins/kubernetes.io/azure-disk/mounts/KubeTestDisk0\n```\n\n**Duration**: 7 minutes 42 seconds. (ISSUE: https://github.com/kubernetes/kubernetes/issues/30752)\n### Second Pod\n#### Unmount (kubelet on first node)\n\n```\nOct 20 07:40:37 k8s-agentpool1-27819504-1 docker[4276]: I1020 07:40:37.067917    4562 reconciler.go:184] UnmountVolume operation started for volume \"kubernetes.io/azure-disk/KubeTestDisk0\" (spec.Name: \"volume-azuredisk\") from pod \"e78c2a9a-9695-11e6-9f69-000d3af74706\" (UID: \"e78c2a9a-9695-11e6-9f69-000d3af74706\").\nOct 20 07:40:37 k8s-agentpool1-27819504-1 docker[4276]: I1020 07:40:37.084268    4562 operation_executor.go:877] UnmountVolume.TearDown succeeded for volume \"kubernetes.io/azure-disk/KubeTestDisk0\" (OuterVolumeSpecName: \"volume-azuredisk\") pod \"e78c2a9a-9695-11e6-9f69-000d3af74706\" (UID: \"e78c2a9a-9695-11e6-9f69-000d3af74706\"). InnerVolumeSpecName \"volume-azuredisk\". PluginName \"kubernetes.io/azure-disk\", VolumeGidValue \"\"\nOct 20 07:40:37 k8s-agentpool1-27819504-1 docker[4276]: I1020 07:40:37.168334    4562 reconciler.go:329] UnmountDevice operation started for volume \"kubernetes.io/azure-disk/KubeTestDisk0\" (spec.Name: \"volume-azuredisk\")\nOct 20 07:40:37 k8s-agentpool1-27819504-1 docker[4276]: E1020 07:40:37.202029    4562 nestedpendingoperations.go:253] Operation for \"\\\"kubernetes.io/azure-disk/KubeTestDisk0\\\"\" failed. No retries permitted until 2016-10-20 07:40:37.702007148 +0000 UTC (durationBeforeRetry 500ms). Error: UnmountDevice.DeviceOpened failed for volume \"kubernetes.io/azure-disk/KubeTestDisk0\" (spec.Name: \"volume-azuredisk\") with: PathIsDevice failed for path \"0\": stat 0: no such file or directory\nOct 20 07:40:37 k8s-agentpool1-27819504-1 docker[4276]: I1020 07:40:37.769714    4562 reconciler.go:329] UnmountDevice operation started for volume \"kubernetes.io/azure-disk/KubeTestDisk0\" (spec.Name: \"volume-azuredisk\")\nOct 20 07:40:37 k8s-agentpool1-27819504-1 docker[4276]: W1020 07:40:37.771706    4562 mount.go:121] could not determine device for path: \"/var/lib/kubelet/plugins/kubernetes.io/azure-disk/mounts/KubeTestDisk0\"\nOct 20 07:40:37 k8s-agentpool1-27819504-1 docker[4276]: W1020 07:40:37.771786    4562 util.go:72] Warning: Unmount skipped because path does not exist: /var/lib/kubelet/plugins/kubernetes.io/azure-disk/mounts/KubeTestDisk0\nOct 20 07:40:37 k8s-agentpool1-27819504-1 docker[4276]: E1020 07:40:37.771979    4562 nestedpendingoperations.go:253] Operation for \"\\\"kubernetes.io/azure-disk/KubeTestDisk0\\\"\" failed. No retries permitted until 2016-10-20 07:40:38.771960574 +0000 UTC (durationBeforeRetry 1s). Error: UnmountDevice.DeviceOpened failed for volume \"kubernetes.io/azure-disk/KubeTestDisk0\" (spec.Name: \"volume-azuredisk\") with: PathIsDevice failed for path \"0\": stat 0: no such file or directory\nOct 20 07:40:38 k8s-agentpool1-27819504-1 docker[4276]: I1020 07:40:38.772133    4562 reconciler.go:329] UnmountDevice operation started for volume \"kubernetes.io/azure-disk/KubeTestDisk0\" (spec.Name: \"volume-azuredisk\")\nOct 20 07:40:38 k8s-agentpool1-27819504-1 docker[4276]: W1020 07:40:38.774233    4562 mount.go:121] could not determine device for path: \"/var/lib/kubelet/plugins/kubernetes.io/azure-disk/mounts/KubeTestDisk0\"\nOct 20 07:40:38 k8s-agentpool1-27819504-1 docker[4276]: W1020 07:40:38.774255    4562 util.go:72] Warning: Unmount skipped because path does not exist: /var/lib/kubelet/plugins/kubernetes.io/azure-disk/mounts/KubeTestDisk0\nOct 20 07:40:38 k8s-agentpool1-27819504-1 docker[4276]: E1020 07:40:38.774311    4562 nestedpendingoperations.go:253] Operation for \"\\\"kubernetes.io/azure-disk/KubeTestDisk0\\\"\" failed. No retries permitted until 2016-10-20 07\n```\n\n**Duration (volume)**: Doesn't matter. It just keeps failing. It looks like eventually it stops after force detach and the next SyncLoop.\n#### Detach / Attach (kube-controller-manager)\n\n```\nI1020 07:40:06.089360       1 event.go:217] Event(api.ObjectReference{Kind:\"ReplicaSet\", Namespace:\"default\", Name:\"test-azure-disk-3967202423\", UID:\"e78749bb-9695-11e6-9f69-000d3af74706\", APIVersion:\"extensions\", ResourceVersion:\"4577\", FieldPath:\"\"}): type: 'Normal' reason: 'SuccessfulCreate' Created pod: test-azure-disk-3967202423-50h2n\nI1020 07:40:06.099943       1 deployment_controller.go:464] Error syncing deployment default/test-azure-disk: Operation cannot be fulfilled on deployments.extensions \"test-azure-disk\": the object has been modified; please apply your changes to the latest version and try again\nI1020 07:40:06.225135       1 reconciler.go:168] Started AttachVolume for volume \"kubernetes.io/azure-disk/KubeTestDisk0\" to node \"k8s-agentpool2-27819504-1\"\nE1020 07:42:06.651336       1 azure_storage.go:63] azure attach failed, err: compute.VirtualMachinesClient#CreateOrUpdate: Failure sending request: StatusCode=200 -- Original Error: Long running operation terminated with status 'Failed': Code=\"AcquireDiskLeaseFailed\" Message=\"Failed to acquire lease while creating disk 'KubeTestDisk0' using blob with URI https://tymdys675hn7smstr0.blob.core.windows.net/vhds/testdisk0123456.vhd. Blob is already in use.\"\nI1020 07:42:06.651382       1 azure_storage.go:67] failed to acquire disk lease, try detach\nI1020 07:42:24.046360       1 servicecontroller.go:284] Ensuring LB for service default/test-azure-disk\nE1020 07:44:07.029595       1 nestedpendingoperations.go:253] Operation for \"\\\"kubernetes.io/azure-disk/KubeTestDisk0\\\"\" failed. No retries permitted until 2016-10-20 07:44:07.529555273 +0000 UTC (durationBeforeRetry 500ms). Error: Failed to attach volume \"volume-azuredisk\" on node \"k8s-agentpool2-27819504-1\" with: Attach volume \"KubeTestDisk0\" to instance \"k8s-agentpool2-27819504-1\" failed with compute.VirtualMachinesClient#CreateOrUpdate: Failure sending request: StatusCode=200 -- Original Error: Long running operation terminated with status 'Failed': Code=\"AcquireDiskLeaseFailed\" Message=\"Failed to acquire lease while creating disk 'KubeTestDisk0' using blob with URI https://tymdys675hn7smstr0.blob.core.windows.net/vhds/testdisk0123456.vhd. Blob is already in use.\"\nI1020 07:44:07.029739       1 event.go:217] Event(api.ObjectReference{Kind:\"Pod\", Namespace:\"default\", Name:\"test-azure-disk-3967202423-50h2n\", UID:\"6b4bc239-9698-11e6-9f69-000d3af74706\", APIVersion:\"v1\", ResourceVersion:\"5764\", FieldPath:\"\"}): type: 'Warning' reason: 'FailedMount' Failed to attach volume \"volume-azuredisk\" on node \"k8s-agentpool2-27819504-1\" with: Attach volume \"KubeTestDisk0\" to instance \"k8s-agentpool2-27819504-1\" failed with compute.VirtualMachinesClient#CreateOrUpdate: Failure sending request: StatusCode=200 -- Original Error: Long running operation terminated with status 'Failed': Code=\"AcquireDiskLeaseFailed\" Message=\"Failed to acquire lease while creating disk 'KubeTestDisk0' using blob with URI https://tymdys675hn7smstr0.blob.core.windows.net/vhds/testdisk0123456.vhd. Blob is already in use.\"\nI1020 07:44:07.564970       1 reconciler.go:168] Started AttachVolume for volume \"kubernetes.io/azure-disk/KubeTestDisk0\" to node \"k8s-agentpool2-27819504-1\"\nE1020 07:46:07.920605       1 azure_storage.go:63] azure attach failed, err: compute.VirtualMachinesClient#CreateOrUpdate: Failure sending request: StatusCode=200 -- Original Error: Long running operation terminated with status 'Failed': Code=\"AcquireDiskLeaseFailed\" Message=\"Failed to acquire lease while creating disk 'KubeTestDisk0' using blob with URI https://tymdys675hn7smstr0.blob.core.windows.net/vhds/testdisk0123456.vhd. Blob is already in use.\"\nI1020 07:46:07.920653       1 azure_storage.go:67] failed to acquire disk lease, try detach\nI1020 07:47:24.499866       1 servicecontroller.go:284] Ensuring LB for service default/test-azure-disk\nE1020 07:48:08.231842       1 nestedpendingoperations.go:253] Operation for \"\\\"kubernetes.io/azure-disk/KubeTestDisk0\\\"\" failed. No retries permitted until 2016-10-20 07:48:09.231811644 +0000 UTC (durationBeforeRetry 1s). Error: Failed to attach volume \"volume-azuredisk\" on node \"k8s-agentpool2-27819504-1\" with: Attach volume \"KubeTestDisk0\" to instance \"k8s-agentpool2-27819504-1\" failed with compute.VirtualMachinesClient#CreateOrUpdate: Failure sending request: StatusCode=200 -- Original Error: Long running operation terminated with status 'Failed': Code=\"AcquireDiskLeaseFailed\" Message=\"Failed to acquire lease while creating disk 'KubeTestDisk0' using blob with URI https://tymdys675hn7smstr0.blob.core.windows.net/vhds/testdisk0123456.vhd. Blob is already in use.\"\nI1020 07:48:08.231989       1 event.go:217] Event(api.ObjectReference{Kind:\"Pod\", Namespace:\"default\", Name:\"test-azure-disk-3967202423-50h2n\", UID:\"6b4bc239-9698-11e6-9f69-000d3af74706\", APIVersion:\"v1\", ResourceVersion:\"5764\", FieldPath:\"\"}): type: 'Warning' reason: 'FailedMount' Failed to attach volume \"volume-azuredisk\" on node \"k8s-agentpool2-27819504-1\" with: Attach volume \"KubeTestDisk0\" to instance \"k8s-agentpool2-27819504-1\" failed with compute.VirtualMachinesClient#CreateOrUpdate: Failure sending request: StatusCode=200 -- Original Error: Long running operation terminated with status 'Failed': Code=\"AcquireDiskLeaseFailed\" Message=\"Failed to acquire lease while creating disk 'KubeTestDisk0' using blob with URI https://tymdys675hn7smstr0.blob.core.windows.net/vhds/testdisk0123456.vhd. Blob is already in use.\"\nI1020 07:48:09.295882       1 reconciler.go:138] Started DetachVolume for volume \"kubernetes.io/azure-disk/KubeTestDisk0\" from node \"k8s-agentpool1-27819504-1\". This volume is not safe to detach, but maxWaitForUnmountDuration 6m0s expired, force detaching\nI1020 07:50:09.615254       1 operation_executor.go:595] DetachVolume.Detach succeeded for volume \"kubernetes.io/azure-disk/KubeTestDisk0\" (spec.Name: \"volume-azuredisk\") from node \"k8s-agentpool1-27819504-1\".\nI1020 07:50:09.651262       1 reconciler.go:168] Started AttachVolume for volume \"kubernetes.io/azure-disk/KubeTestDisk0\" to node \"k8s-agentpool2-27819504-1\"\nI1020 07:52:10.012756       1 operation_executor.go:515] AttachVolume.Attach succeeded for volume \"kubernetes.io/azure-disk/KubeTestDisk0\" (spec.Name: \"volume-azuredisk\") from node \"k8s-agentpool2-27819504-1\".\n```\n\n**Duration (new pod created -> volume detached from old node)**: 8 minutes for k8s to start timeout logic (even though timeout was only 6 minutes) + 2 minutes to detach = **10 minutes**\n\nAnd then it just loops back around to the beginning.\n## Bugs:\n- Format takes 7 minutes: [#30752 mkfs.ext4 is slow when run by kubelet](https://github.com/kubernetes/kubernetes/issues/30752)\n- Unmount failing (contributes to 10-12 minute delay when Pod moves):\n  - I filed this directly for that bug: [#35176 azure disk: always times out waiting for Unmount](https://github.com/kubernetes/kubernetes/issues/35176)\n  - mentioned here: [#31186 Address open issues from \"Azure data disk volume\" PR](https://github.com/kubernetes/kubernetes/issues/31186)\n  - I think is meant to be fixed with this PR: [#33660 rbd attach/detach refactoring](https://github.com/kubernetes/kubernetes/pull/33660)\n- Related meta issue: [#31186 Address open issues from \"Azure data disk volume\"](https://github.com/kubernetes/kubernetes/issues/31186)\n\nI don't know that there needs to be direct action on this bug but I wanted a meta bug to track it and be able to point others to.\n"},"comment":{"url":"https://api.github.com/repos/kubernetes/kubernetes/issues/comments/273090614","html_url":"https://github.com/kubernetes/kubernetes/issues/35180#issuecomment-273090614","issue_url":"https://api.github.com/repos/kubernetes/kubernetes/issues/35180","id":273090614,"user":{"login":"codablock","id":1884269,"avatar_url":"https://avatars.githubusercontent.com/u/1884269?v=3","gravatar_id":"","url":"https://api.github.com/users/codablock","html_url":"https://github.com/codablock","followers_url":"https://api.github.com/users/codablock/followers","following_url":"https://api.github.com/users/codablock/following{/other_user}","gists_url":"https://api.github.com/users/codablock/gists{/gist_id}","starred_url":"https://api.github.com/users/codablock/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/codablock/subscriptions","organizations_url":"https://api.github.com/users/codablock/orgs","repos_url":"https://api.github.com/users/codablock/repos","events_url":"https://api.github.com/users/codablock/events{/privacy}","received_events_url":"https://api.github.com/users/codablock/received_events","type":"User","site_admin":false},"created_at":"2017-01-17T10:21:56Z","updated_at":"2017-01-17T10:21:56Z","body":"First test shows an improvement from 2 minutes for attachment to 40 seconds.\r\n\r\n@ckarlsen84 Do you want to prepare a PR for this? If not, I can do this. I would only change the PollingDelay for the VirtualMachinesClient and not touch any of the other go-autorest clients. In this way the quota should not suffer too much."}}
{"actor":{"display_login":"codablock"}}