Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1677362

Summary: Timeout mounting volume with huge number of files
Product: OpenShift Container Platform Reporter: Sergio G. <sgarciam>
Component: StorageAssignee: Bradley Childs <bchilds>
Status: CLOSED DUPLICATE QA Contact: Liang Xia <lxia>
Severity: high Docs Contact:
Priority: unspecified    
Version: 3.7.0CC: aos-bugs, aos-storage-staff, jsafrane
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2019-02-19 09:24:31 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Sergio G. 2019-02-14 15:59:49 UTC 
Description of problem:
Customer running a pod with an Azure disk as persistent volume (500GB) with a lot of files (1345497) doesn't start and a timeout error is seen in the logs.

Version-Release number of selected component (if applicable):
3.7.52


How reproducible:
Always


Meaninful events:
33s        9m          5         core-conv-history-1829247960-q7ss2                  Pod                                                                   Warning   FailedMount              kubelet, aazp002-wrk-02   Unable to mount volumes for pod "core-conv-history-1829247960-q7ss2_prod(807b4938-1a60-11e9-ac29-0017fa10afe9)": timeout expired waiting for volumes to attach/mount for pod "prod"/"core-conv-history-1829247960-q7ss2". list of unattached/unmounted volumes=[pvol-claim]


Meaningful log in node:
Jan 24 09:34:01 aazp002-wrk-02 atomic-openshift-node[2273]: I0124 09:34:01.214873    2273 round_trippers.go:405] GET https://masters.aazp002.prod.azure.appagile:8443/api/v1/namespaces/prod/persistentvolumeclaims/claim-conv-hist-data2 200 OK in 24 milliseconds
Jan 24 09:34:01 aazp002-wrk-02 atomic-openshift-node[2273]: I0124 09:34:01.225890    2273 round_trippers.go:405] GET https://masters.example.local:8443/api/v1/persistentvolumes/pvc-5de49905-1e5d-11e9-ac29-0017fa10afe9 200 OK in 10 milliseconds
Jan 24 09:34:01 aazp002-wrk-02 atomic-openshift-node[2273]: I0124 09:34:01.226121    2273 config.go:293] Setting pods for source api
Jan 24 09:34:01 aazp002-wrk-02 atomic-openshift-node[2273]: I0124 09:34:01.226492    2273 networkpolicy.go:444] Watch MODIFIED event for Pod "prod/core-conv-history-1916662478-xtt2s"
Jan 24 09:34:01 aazp002-wrk-02 atomic-openshift-node[2273]: I0124 09:34:01.226509    2273 networkpolicy.go:451] PodIP is not set for pod "prod/core-conv-history-1916662478-xtt2s"; ignoring
Jan 24 09:34:01 aazp002-wrk-02 atomic-openshift-node[2273]: I0124 09:34:01.227241    2273 kubelet.go:1890] SyncLoop (RECONCILE, "api"): "core-conv-history-1916662478-xtt2s_prod(ccafd4a2-1fb2-11e9-ac29-0017fa10afe9)"
Jan 24 09:34:01 aazp002-wrk-02 atomic-openshift-node[2273]: I0124 09:34:01.227413    2273 round_trippers.go:405] PUT https://masters.example.local:8443/api/v1/namespaces/prod/pods/core-conv-history-1916662478-xtt2s/status 200 OK in 13 milliseconds
Jan 24 09:34:01 aazp002-wrk-02 atomic-openshift-node[2273]: I0124 09:34:01.227494    2273 status_manager.go:483] Status for pod "core-conv-history-1916662478-xtt2s_prod(ccafd4a2-1fb2-11e9-ac29-0017fa10afe9)" updated successfully: (1, {Phase:Pending Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2019-01-24 09:34:01 +0100 CET Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2019-01-24 09:34:01 +0100 CET Reason:ContainersNotReady Message:containers with unready status: [core-conv-history]} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2019-01-24 09:34:01 +0100 CET Reason: Message:}] Message: Reason: HostIP:192.168.2.66 PodIP: StartTime:2019-01-24 09:34:01 +0100 CET InitContainerStatuses:[] ContainerStatuses:[{Name:core-conv-history State:{Waiting:&ContainerStateWaiting{Reason:ContainerCreating,Message:,} Running:nil Terminated:nil} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:docker-registry.default.svc:5000/prod/conversation-history:0.0.32-snapshot_bab32c84_325782 ImageID: ContainerID:}] QOSClass:Burstable})
Jan 24 09:34:01 aazp002-wrk-02 atomic-openshift-node[2273]: I0124 09:34:01.264455    2273 worker.go:163] Probe target container not found: core-conv-history-1916662478-xtt2s_prod(ccafd4a2-1fb2-11e9-ac29-0017fa10afe9) - core-conv-history
Jan 24 09:34:01 aazp002-wrk-02 atomic-openshift-node[2273]: I0124 09:34:01.291255    2273 reconciler.go:212] operationExecutor.VerifyControllerAttachedVolume started for volume "pvc-5de49905-1e5d-11e9-ac29-0017fa10afe9" (UniqueName: "kubernetes.io/azure-disk//subscriptions/fa31b85f-7a01-4548-9262-2e60f224eefa/resourceGroups/aazp002-rg-nodes/providers/Microsoft.Compute/disks/kubernetes-dynamic-pvc-5de49905-1e5d-11e9-ac29-0017fa10afe9") pod "core-conv-history-1916662478-xtt2s" (UID: "ccafd4a2-1fb2-11e9-ac29-0017fa10afe9")
Jan 24 09:34:01 aazp002-wrk-02 atomic-openshift-node[2273]: I0124 09:34:01.291305    2273 reconciler.go:212] operationExecutor.VerifyControllerAttachedVolume started for volume "default-token-v28rh" (UniqueName: "kubernetes.io/secret/ccafd4a2-1fb2-11e9-ac29-0017fa10afe9-default-token-v28rh") pod "core-conv-history-1916662478-xtt2s" (UID: "ccafd4a2-1fb2-11e9-ac29-0017fa10afe9")
Jan 24 09:34:01 aazp002-wrk-02 atomic-openshift-node[2273]: I0124 09:34:01.291345    2273 reconciler.go:257] operationExecutor.MountVolume started for volume "conversation-history-config-volume" (UniqueName: "kubernetes.io/configmap/ccafd4a2-1fb2-11e9-ac29-0017fa10afe9-conversation-history-config-volume") pod "core-conv-history-1916662478-xtt2s" (UID: "ccafd4a2-1fb2-11e9-ac29-0017fa10afe9")
Jan 24 09:34:01 aazp002-wrk-02 atomic-openshift-node[2273]: E0124 09:34:01.291434    2273 nestedpendingoperations.go:264] Operation for "\"kubernetes.io/azure-disk//subscriptions/fa31b85f-7a01-4548-9262-2e60f224eefa/resourceGroups/aazp002-rg-nodes/providers/Microsoft.Compute/disks/kubernetes-dynamic-pvc-5de49905-1e5d-11e9-ac29-0017fa10afe9\"" failed. No retries permitted until 2019-01-24 09:34:01.79137696 +0100 CET (durationBeforeRetry 500ms). Error: Volume has not been added to the list of VolumesInUse in the node's volume status for volume "pvc-5de49905-1e5d-11e9-ac29-0017fa10afe9" (UniqueName: "kubernetes.io/azure-disk//subscriptions/fa31b85f-7a01-4548-9262-2e60f224eefa/resourceGroups/aazp002-rg-nodes/providers/Microsoft.Compute/disks/kubernetes-dynamic-pvc-5de49905-1e5d-11e9-ac29-0017fa10afe9") pod "core-conv-history-1916662478-xtt2s" (UID: "ccafd4a2-1fb2-11e9-ac29-0017fa10afe9")


Additional info:
 - the volume is attached successfully according to Azure console, we checked during the tests and detached manually before retries
 - if the number of files is reduced the pod eventually starts after 22 mins
 - if the number of files is reduced even more (approx 1/3) it starts after 8 mins
Comment 3 Jan Safranek 2019-02-19 09:24:31 UTC 
This looks like a dup of https://bugzilla.redhat.com/show_bug.cgi?id=1459106

Kubelet does chown+chmod of all files on a volume and it may take lot of time.

*** This bug has been marked as a duplicate of bug 1459106 ***