sigs.k8s.io/azuredisk-csi-driver PR #180 chewong-pull-azuredisk-csi-driver-e2e-multi-az #1191875772084654080
Recent runs || View in Spyglass
Recent runs || View in Spyglass
error during make e2e-test: exit status 2
from junit_runner.xml
Filter through log files
Build
Check APIReachability
Deferred TearDown
DumpClusterLogs
IsUp
TearDown
TearDown Previous
Timeout
Up
kubectl version
list nodes
test setup
... skipping 427 lines ... I1106 01:06:14.360] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:126 I1106 01:06:14.360] STEP: setting up the StorageClass I1106 01:06:14.360] STEP: creating a StorageClass I1106 01:06:14.441] STEP: setting up the PVC and PV I1106 01:06:14.441] STEP: creating a PVC I1106 01:06:14.520] STEP: deploying the pod I1106 01:06:14.599] STEP: checking that the pods command exits with an error I1106 01:06:14.599] Nov 6 01:06:14.599: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-xtwv8" in namespace "azuredisk-6675" to be "Error status code" I1106 01:06:14.673] Nov 6 01:06:14.673: INFO: Pod "azuredisk-volume-tester-xtwv8": Phase="Pending", Reason="", readiness=false. Elapsed: 73.949172ms I1106 01:06:16.749] Nov 6 01:06:16.748: INFO: Pod "azuredisk-volume-tester-xtwv8": Phase="Pending", Reason="", readiness=false. Elapsed: 2.149681351s I1106 01:06:18.822] Nov 6 01:06:18.821: INFO: Pod "azuredisk-volume-tester-xtwv8": Phase="Pending", Reason="", readiness=false. Elapsed: 4.222743009s I1106 01:06:20.895] Nov 6 01:06:20.895: INFO: Pod "azuredisk-volume-tester-xtwv8": Phase="Pending", Reason="", readiness=false. Elapsed: 6.296462872s I1106 01:06:22.970] Nov 6 01:06:22.969: INFO: Pod "azuredisk-volume-tester-xtwv8": Phase="Pending", Reason="", readiness=false. Elapsed: 8.370564938s I1106 01:06:25.075] Nov 6 01:06:25.074: INFO: Pod "azuredisk-volume-tester-xtwv8": Phase="Pending", Reason="", readiness=false. Elapsed: 10.475731845s ... skipping 422 lines ... I1106 01:21:04.190] Nov 6 01:21:04.190: INFO: Pod "azuredisk-volume-tester-xtwv8": Phase="Pending", Reason="", readiness=false. Elapsed: 14m49.590910749s I1106 01:21:06.270] Nov 6 01:21:06.270: INFO: Pod "azuredisk-volume-tester-xtwv8": Phase="Pending", Reason="", readiness=false. Elapsed: 14m51.671109157s I1106 01:21:08.350] Nov 6 01:21:08.350: INFO: Pod "azuredisk-volume-tester-xtwv8": Phase="Pending", Reason="", readiness=false. Elapsed: 14m53.751056762s I1106 01:21:10.430] Nov 6 01:21:10.430: INFO: Pod "azuredisk-volume-tester-xtwv8": Phase="Pending", Reason="", readiness=false. Elapsed: 14m55.831028969s I1106 01:21:12.510] Nov 6 01:21:12.510: INFO: Pod "azuredisk-volume-tester-xtwv8": Phase="Pending", Reason="", readiness=false. Elapsed: 14m57.910837774s I1106 01:21:14.590] Nov 6 01:21:14.589: INFO: Pod "azuredisk-volume-tester-xtwv8": Phase="Pending", Reason="", readiness=false. Elapsed: 14m59.990646078s I1106 01:21:16.590] Nov 6 01:21:16.590: INFO: Unexpected error occurred: Gave up after waiting 15m0s for pod "azuredisk-volume-tester-xtwv8" to be "Error status code" I1106 01:21:16.590] Nov 6 01:21:16.590: INFO: deleting Pod "azuredisk-6675"/"azuredisk-volume-tester-xtwv8" I1106 01:21:16.670] Nov 6 01:21:16.669: INFO: Pod azuredisk-volume-tester-xtwv8 has the following logs: I1106 01:21:16.670] STEP: Deleting pod azuredisk-volume-tester-xtwv8 in namespace azuredisk-6675 I1106 01:21:16.846] STEP: validating provisioned PV I1106 01:21:16.847] Nov 6 01:21:16.846: INFO: Unexpected error occurred: resource name may not be empty I1106 01:21:16.847] Nov 6 01:21:16.846: INFO: deleting StorageClass azuredisk-6675-disk.csi.azure.com-dynamic-sc-g2b9d I1106 01:21:16.937] [AfterEach] [multi-az] I1106 01:21:16.938] /go/src/sigs.k8s.io/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1106 01:21:16.938] STEP: Collecting events from namespace "azuredisk-6675". I1106 01:21:17.017] STEP: Found 7 events. I1106 01:21:17.017] Nov 6 01:21:17.017: INFO: At 2019-11-06 01:06:14 +0000 UTC - event for pvc-jthsq: {persistentvolume-controller } WaitForFirstConsumer: waiting for first consumer to be created before binding I1106 01:21:17.017] Nov 6 01:21:17.017: INFO: At 2019-11-06 01:06:14 +0000 UTC - event for pvc-jthsq: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "disk.csi.azure.com" or manually created by system administrator I1106 01:21:17.018] Nov 6 01:21:17.017: INFO: At 2019-11-06 01:06:14 +0000 UTC - event for pvc-jthsq: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-bpnmm_9f10eebb-0031-11ea-937c-fe0323241632 } Provisioning: External provisioner is provisioning volume for claim "azuredisk-6675/pvc-jthsq" I1106 01:21:17.018] Nov 6 01:21:17.017: INFO: At 2019-11-06 01:06:24 +0000 UTC - event for pvc-jthsq: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-bpnmm_9f10eebb-0031-11ea-937c-fe0323241632 } ProvisioningFailed: failed to provision volume with StorageClass "azuredisk-6675-disk.csi.azure.com-dynamic-sc-g2b9d": rpc error: code = DeadlineExceeded desc = context deadline exceeded I1106 01:21:17.018] Nov 6 01:21:17.017: INFO: At 2019-11-06 01:16:14 +0000 UTC - event for azuredisk-volume-tester-xtwv8: {default-scheduler } FailedScheduling: timed out waiting for the condition I1106 01:21:17.018] Nov 6 01:21:17.017: INFO: At 2019-11-06 01:16:16 +0000 UTC - event for azuredisk-volume-tester-xtwv8: {default-scheduler } FailedScheduling: AssumePod failed: pod af9a4408-5351-44ad-aed2-1978dd125f97 is in the cache, so can't be assumed I1106 01:21:17.019] Nov 6 01:21:17.017: INFO: At 2019-11-06 01:21:16 +0000 UTC - event for azuredisk-volume-tester-xtwv8: {default-scheduler } FailedScheduling: skip schedule deleting pod: azuredisk-6675/azuredisk-volume-tester-xtwv8 I1106 01:21:17.100] Nov 6 01:21:17.100: INFO: POD NODE PHASE GRACE CONDITIONS I1106 01:21:17.100] Nov 6 01:21:17.100: INFO: I1106 01:21:17.336] Nov 6 01:21:17.336: INFO: I1106 01:21:17.336] Logging node info for node k8s-agentpool-54406713-vmss000000 I1106 01:21:17.419] Nov 6 01:21:17.415: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:k8s-agentpool-54406713-vmss000000,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/k8s-agentpool-54406713-vmss000000,UID:f11c401a-3543-4cfb-af66-e320a19275bf,ResourceVersion:4293,Generation:0,CreationTimestamp:2019-11-06 01:02:48 +0000 UTC,DeletionTimestamp:<nil>,DeletionGracePeriodSeconds:nil,Labels:map[string]string{agentpool: agentpool,beta.kubernetes.io/arch: amd64,beta.kubernetes.io/instance-type: Standard_D4s_v3,beta.kubernetes.io/os: linux,failure-domain.beta.kubernetes.io/region: eastus2,failure-domain.beta.kubernetes.io/zone: eastus2-1,kubernetes.azure.com/cluster: kubetest-03920ff3-002d-11ea-be9c-02423fe68cb4,kubernetes.azure.com/role: agent,kubernetes.io/arch: amd64,kubernetes.io/hostname: k8s-agentpool-54406713-vmss000000,kubernetes.io/os: linux,kubernetes.io/role: agent,node-role.kubernetes.io/agent: ,storageprofile: managed,storagetier: Premium_LRS,topology.disk.csi.azure.com/zone: eastus2-1,},Annotations:map[string]string{csi.volume.kubernetes.io/nodeid: {"disk.csi.azure.com":"k8s-agentpool-54406713-vmss000000"},node.alpha.kubernetes.io/ttl: 0,volumes.kubernetes.io/controller-managed-attach-detach: true,},OwnerReferences:[],Finalizers:[],ClusterName:,Initializers:nil,ManagedFields:[],},Spec:NodeSpec{PodCIDR:10.244.0.0/24,DoNotUse_ExternalID:,ProviderID:azure:///subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/kubetest-03920ff3-002d-11ea-be9c-02423fe68cb4/providers/Microsoft.Compute/virtualMachineScaleSets/k8s-agentpool-54406713-vmss/virtualMachines/0,Unschedulable:false,Taints:[],ConfigSource:nil,},Status:NodeStatus{Capacity:ResourceList{attachable-volumes-csi-disk.csi.azure.com: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{31036776448 0} {<nil>} BinarySI},hugepages-1Gi: {{0 0} {<nil>} 0 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{16797044736 0} {<nil>} 16403364Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Allocatable:ResourceList{attachable-volumes-csi-disk.csi.azure.com: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{27933098757 0} {<nil>} 27933098757 DecimalSI},hugepages-1Gi: {{0 0} {<nil>} 0 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{16010612736 0} {<nil>} 15635364Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Phase:,Conditions:[{NetworkUnavailable False 2019-11-06 01:03:21 +0000 UTC 2019-11-06 01:03:21 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2019-11-06 01:21:11 +0000 UTC 2019-11-06 01:02:32 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2019-11-06 01:21:11 +0000 UTC 2019-11-06 01:02:32 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2019-11-06 01:21:11 +0000 UTC 2019-11-06 01:02:32 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2019-11-06 01:21:11 +0000 UTC 2019-11-06 01:03:06 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.248.0.4} {Hostname k8s-agentpool-54406713-vmss000000}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:314d4f6d838542d1b91629162863d266,SystemUUID:28F72AD9-C8ED-1C40-AC90-621A4747BF6F,BootID:73555e39-2e46-4dd8-a077-48bc5b4d8032,KernelVersion:4.15.0-1061-azure,OSImage:Ubuntu 16.04.6 LTS,ContainerRuntimeVersion:docker://3.0.6,KubeletVersion:v1.15.0,KubeProxyVersion:v1.15.0,OperatingSystem:linux,Architecture:amd64,},Images:[{[gcrio.azureedge.net/google_containers/hyperkube-amd64@sha256:7f66ed6bd11edd309dad15db1dc906f89035cc9d9ae705c65c98264c775b9a8f gcrio.azureedge.net/google_containers/hyperkube-amd64:v1.15.0] 593352254} {[k8sprowinternal.azurecr.io/azuredisk-csi@sha256:209b5e3501b93135a3e5715553aeb99d41dc7fab732b42161d48b00e40772a93 k8sprowinternal.azurecr.io/azuredisk-csi:e2e-9f289d4c7792de742a1ded20837778e2acb91093] 286926836} {[k8s.gcr.io/kubernetes-dashboard-amd64@sha256:0ae6b69432e78069c5ce2bcde0fe409c5c4d6f0f4d9cd50a17974fea38898747 k8s.gcr.io/kubernetes-dashboard-amd64:v1.10.1] 121711221} {[k8s.gcr.io/ip-masq-agent-amd64@sha256:269e0fb9d53fd37f7a135d6a55ea265a67279ba218aa148323f015cf70167340 k8s.gcr.io/ip-masq-agent-amd64:v2.3.0] 50144412} {[k8s.gcr.io/metrics-server-amd64@sha256:49a9f12f7067d11f42c803dbe61ed2c1299959ad85cb315b25ff7eef8e6b8892 k8s.gcr.io/metrics-server-amd64:v0.2.1] 42541759} {[mcr.microsoft.com/k8s/flexvolume/keyvault-flexvolume@sha256:4fd30d43947d4a54fc89ead7985beecfd3c9b2a93a0655a373b1608ab90bd5af mcr.microsoft.com/k8s/flexvolume/keyvault-flexvolume:v0.0.7] 22909487} {[quay.io/k8scsi/livenessprobe@sha256:8c9c8a0f330acc2e558ae6624309447d02522e76aa35af23fa19b88abf4381cb quay.io/k8scsi/livenessprobe:v1.0.2] 17415381} {[quay.io/k8scsi/csi-node-driver-registrar@sha256:13daf82fb99e951a4bff8ae5fc7c17c3a8fe7130be6400990d8f6076c32d4599 quay.io/k8scsi/csi-node-driver-registrar:v1.1.0] 15815995} {[mcr.microsoft.com/k8s/flexvolume/blobfuse-flexvolume@sha256:23d8c6033f02a1ecad05127ebdc931bb871264228661bc122704b0974e4d9fdd mcr.microsoft.com/k8s/flexvolume/blobfuse-flexvolume:1.0.8] 1159025} {[k8s.gcr.io/pause-amd64@sha256:59eec8837a4d942cc19a52b8c09ea75121acc38114a2c68b98983ce9356b8610 k8s.gcr.io/pause-amd64:3.1] 742472}],VolumesInUse:[],VolumesAttached:[],Config:nil,},} ... skipping 176 lines ... I1106 01:21:30.507] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:33 I1106 01:21:30.508] [multi-az] I1106 01:21:30.508] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:40 I1106 01:21:30.508] should create a volume on demand and mount it as readOnly in a pod [It] I1106 01:21:30.508] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:126 I1106 01:21:30.508] I1106 01:21:30.508] Unexpected error: I1106 01:21:30.508] <*errors.errorString | 0xc0004cbc70>: { I1106 01:21:30.509] s: "Gave up after waiting 15m0s for pod \"azuredisk-volume-tester-xtwv8\" to be \"Error status code\"", I1106 01:21:30.509] } I1106 01:21:30.509] Gave up after waiting 15m0s for pod "azuredisk-volume-tester-xtwv8" to be "Error status code" I1106 01:21:30.509] occurred I1106 01:21:30.509] I1106 01:21:30.509] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:553 I1106 01:21:30.509] ------------------------------ I1106 01:21:30.509] [azuredisk-csi-e2e] Dynamic Provisioning [multi-az] I1106 01:21:30.509] should create a deployment object, write and read to it, delete the pod and write and read to it again ... skipping 164 lines ... I1106 01:26:23.509] Nov 6 01:26:23.508: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-ljtkr-78678ccbd6\" is progressing."}}, CollisionCount:(*int32)(nil)} I1106 01:26:25.509] Nov 6 01:26:25.508: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-ljtkr-78678ccbd6\" is progressing."}}, CollisionCount:(*int32)(nil)} I1106 01:26:27.508] Nov 6 01:26:27.508: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-ljtkr-78678ccbd6\" is progressing."}}, CollisionCount:(*int32)(nil)} I1106 01:26:29.509] Nov 6 01:26:29.508: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-ljtkr-78678ccbd6\" is progressing."}}, CollisionCount:(*int32)(nil)} I1106 01:26:31.509] Nov 6 01:26:31.508: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-ljtkr-78678ccbd6\" is progressing."}}, CollisionCount:(*int32)(nil)} I1106 01:26:31.589] Nov 6 01:26:31.588: INFO: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-ljtkr-78678ccbd6\" is progressing."}}, CollisionCount:(*int32)(nil)} I1106 01:26:31.590] Nov 6 01:26:31.588: INFO: Unexpected error occurred: error waiting for deployment "azuredisk-volume-tester-ljtkr" status to match expectation: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-ljtkr-78678ccbd6\" is progressing."}}, CollisionCount:(*int32)(nil)} I1106 01:26:31.590] Nov 6 01:26:31.588: INFO: deleting Deployment "azuredisk-6617"/"azuredisk-volume-tester-ljtkr" I1106 01:26:31.590] Nov 6 01:26:31.588: INFO: Error getting logs for pod : resource name may not be empty I1106 01:26:31.760] STEP: validating provisioned PV I1106 01:26:31.760] Nov 6 01:26:31.760: INFO: Unexpected error occurred: resource name may not be empty I1106 01:26:31.760] Nov 6 01:26:31.760: INFO: deleting StorageClass azuredisk-6617-disk.csi.azure.com-dynamic-sc-wq2dx I1106 01:26:31.848] [AfterEach] [multi-az] I1106 01:26:31.848] /go/src/sigs.k8s.io/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1106 01:26:31.848] STEP: Collecting events from namespace "azuredisk-6617". I1106 01:26:31.928] STEP: Found 6 events. I1106 01:26:31.928] Nov 6 01:26:31.927: INFO: At 2019-11-06 01:21:31 +0000 UTC - event for azuredisk-volume-tester-ljtkr: {deployment-controller } ScalingReplicaSet: Scaled up replica set azuredisk-volume-tester-ljtkr-78678ccbd6 to 1 I1106 01:26:31.928] Nov 6 01:26:31.927: INFO: At 2019-11-06 01:21:31 +0000 UTC - event for azuredisk-volume-tester-ljtkr-78678ccbd6: {replicaset-controller } SuccessfulCreate: Created pod: azuredisk-volume-tester-ljtkr-78678ccbd6-lnw4m I1106 01:26:31.928] Nov 6 01:26:31.927: INFO: At 2019-11-06 01:21:31 +0000 UTC - event for pvc-cgp2r: {persistentvolume-controller } WaitForFirstConsumer: waiting for first consumer to be created before binding I1106 01:26:31.929] Nov 6 01:26:31.927: INFO: At 2019-11-06 01:21:31 +0000 UTC - event for pvc-cgp2r: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "disk.csi.azure.com" or manually created by system administrator I1106 01:26:31.929] Nov 6 01:26:31.927: INFO: At 2019-11-06 01:21:31 +0000 UTC - event for pvc-cgp2r: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-bpnmm_9f10eebb-0031-11ea-937c-fe0323241632 } Provisioning: External provisioner is provisioning volume for claim "azuredisk-6617/pvc-cgp2r" I1106 01:26:31.929] Nov 6 01:26:31.927: INFO: At 2019-11-06 01:21:41 +0000 UTC - event for pvc-cgp2r: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-bpnmm_9f10eebb-0031-11ea-937c-fe0323241632 } ProvisioningFailed: failed to provision volume with StorageClass "azuredisk-6617-disk.csi.azure.com-dynamic-sc-wq2dx": rpc error: code = DeadlineExceeded desc = context deadline exceeded I1106 01:26:32.007] Nov 6 01:26:32.007: INFO: POD NODE PHASE GRACE CONDITIONS I1106 01:26:32.007] Nov 6 01:26:32.007: INFO: azuredisk-volume-tester-ljtkr-78678ccbd6-lnw4m Pending [] I1106 01:26:32.007] Nov 6 01:26:32.007: INFO: I1106 01:26:32.242] Nov 6 01:26:32.241: INFO: I1106 01:26:32.242] Logging node info for node k8s-agentpool-54406713-vmss000000 I1106 01:26:32.325] Nov 6 01:26:32.321: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:k8s-agentpool-54406713-vmss000000,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/k8s-agentpool-54406713-vmss000000,UID:f11c401a-3543-4cfb-af66-e320a19275bf,ResourceVersion:5215,Generation:0,CreationTimestamp:2019-11-06 01:02:48 +0000 UTC,DeletionTimestamp:<nil>,DeletionGracePeriodSeconds:nil,Labels:map[string]string{agentpool: agentpool,beta.kubernetes.io/arch: amd64,beta.kubernetes.io/instance-type: Standard_D4s_v3,beta.kubernetes.io/os: linux,failure-domain.beta.kubernetes.io/region: eastus2,failure-domain.beta.kubernetes.io/zone: eastus2-1,kubernetes.azure.com/cluster: kubetest-03920ff3-002d-11ea-be9c-02423fe68cb4,kubernetes.azure.com/role: agent,kubernetes.io/arch: amd64,kubernetes.io/hostname: k8s-agentpool-54406713-vmss000000,kubernetes.io/os: linux,kubernetes.io/role: agent,node-role.kubernetes.io/agent: ,storageprofile: managed,storagetier: Premium_LRS,topology.disk.csi.azure.com/zone: eastus2-1,},Annotations:map[string]string{csi.volume.kubernetes.io/nodeid: {"disk.csi.azure.com":"k8s-agentpool-54406713-vmss000000"},node.alpha.kubernetes.io/ttl: 0,volumes.kubernetes.io/controller-managed-attach-detach: true,},OwnerReferences:[],Finalizers:[],ClusterName:,Initializers:nil,ManagedFields:[],},Spec:NodeSpec{PodCIDR:10.244.0.0/24,DoNotUse_ExternalID:,ProviderID:azure:///subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/kubetest-03920ff3-002d-11ea-be9c-02423fe68cb4/providers/Microsoft.Compute/virtualMachineScaleSets/k8s-agentpool-54406713-vmss/virtualMachines/0,Unschedulable:false,Taints:[],ConfigSource:nil,},Status:NodeStatus{Capacity:ResourceList{attachable-volumes-csi-disk.csi.azure.com: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{31036776448 0} {<nil>} BinarySI},hugepages-1Gi: {{0 0} {<nil>} 0 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{16797044736 0} {<nil>} 16403364Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Allocatable:ResourceList{attachable-volumes-csi-disk.csi.azure.com: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{27933098757 0} {<nil>} 27933098757 DecimalSI},hugepages-1Gi: {{0 0} {<nil>} 0 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{16010612736 0} {<nil>} 15635364Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Phase:,Conditions:[{NetworkUnavailable False 2019-11-06 01:03:21 +0000 UTC 2019-11-06 01:03:21 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2019-11-06 01:26:12 +0000 UTC 2019-11-06 01:02:32 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2019-11-06 01:26:12 +0000 UTC 2019-11-06 01:02:32 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2019-11-06 01:26:12 +0000 UTC 2019-11-06 01:02:32 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2019-11-06 01:26:12 +0000 UTC 2019-11-06 01:03:06 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.248.0.4} {Hostname k8s-agentpool-54406713-vmss000000}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:314d4f6d838542d1b91629162863d266,SystemUUID:28F72AD9-C8ED-1C40-AC90-621A4747BF6F,BootID:73555e39-2e46-4dd8-a077-48bc5b4d8032,KernelVersion:4.15.0-1061-azure,OSImage:Ubuntu 16.04.6 LTS,ContainerRuntimeVersion:docker://3.0.6,KubeletVersion:v1.15.0,KubeProxyVersion:v1.15.0,OperatingSystem:linux,Architecture:amd64,},Images:[{[gcrio.azureedge.net/google_containers/hyperkube-amd64@sha256:7f66ed6bd11edd309dad15db1dc906f89035cc9d9ae705c65c98264c775b9a8f gcrio.azureedge.net/google_containers/hyperkube-amd64:v1.15.0] 593352254} {[k8sprowinternal.azurecr.io/azuredisk-csi@sha256:209b5e3501b93135a3e5715553aeb99d41dc7fab732b42161d48b00e40772a93 k8sprowinternal.azurecr.io/azuredisk-csi:e2e-9f289d4c7792de742a1ded20837778e2acb91093] 286926836} {[k8s.gcr.io/kubernetes-dashboard-amd64@sha256:0ae6b69432e78069c5ce2bcde0fe409c5c4d6f0f4d9cd50a17974fea38898747 k8s.gcr.io/kubernetes-dashboard-amd64:v1.10.1] 121711221} {[k8s.gcr.io/ip-masq-agent-amd64@sha256:269e0fb9d53fd37f7a135d6a55ea265a67279ba218aa148323f015cf70167340 k8s.gcr.io/ip-masq-agent-amd64:v2.3.0] 50144412} {[k8s.gcr.io/metrics-server-amd64@sha256:49a9f12f7067d11f42c803dbe61ed2c1299959ad85cb315b25ff7eef8e6b8892 k8s.gcr.io/metrics-server-amd64:v0.2.1] 42541759} {[mcr.microsoft.com/k8s/flexvolume/keyvault-flexvolume@sha256:4fd30d43947d4a54fc89ead7985beecfd3c9b2a93a0655a373b1608ab90bd5af mcr.microsoft.com/k8s/flexvolume/keyvault-flexvolume:v0.0.7] 22909487} {[quay.io/k8scsi/livenessprobe@sha256:8c9c8a0f330acc2e558ae6624309447d02522e76aa35af23fa19b88abf4381cb quay.io/k8scsi/livenessprobe:v1.0.2] 17415381} {[quay.io/k8scsi/csi-node-driver-registrar@sha256:13daf82fb99e951a4bff8ae5fc7c17c3a8fe7130be6400990d8f6076c32d4599 quay.io/k8scsi/csi-node-driver-registrar:v1.1.0] 15815995} {[mcr.microsoft.com/k8s/flexvolume/blobfuse-flexvolume@sha256:23d8c6033f02a1ecad05127ebdc931bb871264228661bc122704b0974e4d9fdd mcr.microsoft.com/k8s/flexvolume/blobfuse-flexvolume:1.0.8] 1159025} {[k8s.gcr.io/pause-amd64@sha256:59eec8837a4d942cc19a52b8c09ea75121acc38114a2c68b98983ce9356b8610 k8s.gcr.io/pause-amd64:3.1] 742472}],VolumesInUse:[],VolumesAttached:[],Config:nil,},} ... skipping 176 lines ... I1106 01:26:53.278] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:33 I1106 01:26:53.278] [multi-az] I1106 01:26:53.278] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:40 I1106 01:26:53.279] should create a deployment object, write and read to it, delete the pod and write and read to it again [It] I1106 01:26:53.279] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:193 I1106 01:26:53.279] I1106 01:26:53.279] Unexpected error: I1106 01:26:53.279] <*errors.errorString | 0xc00095dbc0>: { I1106 01:26:53.280] s: "error waiting for deployment \"azuredisk-volume-tester-ljtkr\" status to match expectation: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:\"Available\", Status:\"False\", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, Reason:\"MinimumReplicasUnavailable\", Message:\"Deployment does not have minimum availability.\"}, v1.DeploymentCondition{Type:\"Progressing\", Status:\"True\", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, Reason:\"ReplicaSetUpdated\", Message:\"ReplicaSet \\\"azuredisk-volume-tester-ljtkr-78678ccbd6\\\" is progressing.\"}}, CollisionCount:(*int32)(nil)}", I1106 01:26:53.280] } I1106 01:26:53.280] error waiting for deployment "azuredisk-volume-tester-ljtkr" status to match expectation: deployment status: v1.DeploymentStatus{ObservedGeneration:1, Replicas:1, UpdatedReplicas:1, ReadyReplicas:0, AvailableReplicas:0, UnavailableReplicas:1, Conditions:[]v1.DeploymentCondition{v1.DeploymentCondition{Type:"Available", Status:"False", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708600091, loc:(*time.Location)(0x34d4fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-ljtkr-78678ccbd6\" is progressing."}}, CollisionCount:(*int32)(nil)} I1106 01:26:53.281] occurred I1106 01:26:53.281] I1106 01:26:53.281] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:434 I1106 01:26:53.281] ------------------------------ I1106 01:26:53.281] [azuredisk-csi-e2e] Dynamic Provisioning [multi-az] I1106 01:26:53.281] should create a volume on demand ... skipping 11 lines ... I1106 01:26:53.867] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:78 I1106 01:26:53.867] STEP: setting up the StorageClass I1106 01:26:53.867] STEP: creating a StorageClass I1106 01:26:53.949] STEP: setting up the PVC and PV I1106 01:26:53.949] STEP: creating a PVC I1106 01:26:54.035] STEP: deploying the pod I1106 01:26:54.128] STEP: checking that the pods command exits with no error I1106 01:26:54.128] Nov 6 01:26:54.128: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-rk9ww" in namespace "azuredisk-938" to be "success or failure" I1106 01:26:54.207] Nov 6 01:26:54.207: INFO: Pod "azuredisk-volume-tester-rk9ww": Phase="Pending", Reason="", readiness=false. Elapsed: 79.116013ms I1106 01:26:56.287] Nov 6 01:26:56.287: INFO: Pod "azuredisk-volume-tester-rk9ww": Phase="Pending", Reason="", readiness=false. Elapsed: 2.158907617s I1106 01:26:58.368] Nov 6 01:26:58.368: INFO: Pod "azuredisk-volume-tester-rk9ww": Phase="Pending", Reason="", readiness=false. Elapsed: 4.239486027s I1106 01:27:00.447] Nov 6 01:27:00.447: INFO: Pod "azuredisk-volume-tester-rk9ww": Phase="Pending", Reason="", readiness=false. Elapsed: 6.319168331s I1106 01:27:02.527] Nov 6 01:27:02.527: INFO: Pod "azuredisk-volume-tester-rk9ww": Phase="Pending", Reason="", readiness=false. Elapsed: 8.399136636s ... skipping 422 lines ... I1106 01:41:42.049] Nov 6 01:41:42.049: INFO: Pod "azuredisk-volume-tester-rk9ww": Phase="Pending", Reason="", readiness=false. Elapsed: 14m47.920570683s I1106 01:41:44.129] Nov 6 01:41:44.128: INFO: Pod "azuredisk-volume-tester-rk9ww": Phase="Pending", Reason="", readiness=false. Elapsed: 14m50.000388608s I1106 01:41:46.209] Nov 6 01:41:46.209: INFO: Pod "azuredisk-volume-tester-rk9ww": Phase="Pending", Reason="", readiness=false. Elapsed: 14m52.080536536s I1106 01:41:48.289] Nov 6 01:41:48.289: INFO: Pod "azuredisk-volume-tester-rk9ww": Phase="Pending", Reason="", readiness=false. Elapsed: 14m54.161123469s I1106 01:41:50.370] Nov 6 01:41:50.370: INFO: Pod "azuredisk-volume-tester-rk9ww": Phase="Pending", Reason="", readiness=false. Elapsed: 14m56.241587502s I1106 01:41:52.450] Nov 6 01:41:52.450: INFO: Pod "azuredisk-volume-tester-rk9ww": Phase="Pending", Reason="", readiness=false. Elapsed: 14m58.321795334s I1106 01:41:54.450] Nov 6 01:41:54.450: INFO: Unexpected error occurred: Gave up after waiting 15m0s for pod "azuredisk-volume-tester-rk9ww" to be "success or failure" I1106 01:41:54.451] Nov 6 01:41:54.450: INFO: deleting Pod "azuredisk-938"/"azuredisk-volume-tester-rk9ww" I1106 01:41:54.530] Nov 6 01:41:54.530: INFO: Pod azuredisk-volume-tester-rk9ww has the following logs: I1106 01:41:54.530] STEP: Deleting pod azuredisk-volume-tester-rk9ww in namespace azuredisk-938 I1106 01:41:54.754] STEP: validating provisioned PV I1106 01:41:54.754] Nov 6 01:41:54.754: INFO: Unexpected error occurred: resource name may not be empty I1106 01:41:54.754] Nov 6 01:41:54.754: INFO: deleting StorageClass azuredisk-938-disk.csi.azure.com-dynamic-sc-5ffzn I1106 01:41:54.843] [AfterEach] [multi-az] I1106 01:41:54.844] /go/src/sigs.k8s.io/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1106 01:41:54.844] STEP: Collecting events from namespace "azuredisk-938". I1106 01:41:54.923] STEP: Found 7 events. I1106 01:41:54.923] Nov 6 01:41:54.923: INFO: At 2019-11-06 01:26:53 +0000 UTC - event for pvc-c8jq4: {persistentvolume-controller } WaitForFirstConsumer: waiting for first consumer to be created before binding I1106 01:41:54.923] Nov 6 01:41:54.923: INFO: At 2019-11-06 01:26:54 +0000 UTC - event for pvc-c8jq4: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "disk.csi.azure.com" or manually created by system administrator I1106 01:41:54.923] Nov 6 01:41:54.923: INFO: At 2019-11-06 01:26:54 +0000 UTC - event for pvc-c8jq4: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-bpnmm_9f10eebb-0031-11ea-937c-fe0323241632 } Provisioning: External provisioner is provisioning volume for claim "azuredisk-938/pvc-c8jq4" I1106 01:41:54.924] Nov 6 01:41:54.923: INFO: At 2019-11-06 01:27:04 +0000 UTC - event for pvc-c8jq4: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-bpnmm_9f10eebb-0031-11ea-937c-fe0323241632 } ProvisioningFailed: failed to provision volume with StorageClass "azuredisk-938-disk.csi.azure.com-dynamic-sc-5ffzn": rpc error: code = DeadlineExceeded desc = context deadline exceeded I1106 01:41:54.924] Nov 6 01:41:54.923: INFO: At 2019-11-06 01:36:54 +0000 UTC - event for azuredisk-volume-tester-rk9ww: {default-scheduler } FailedScheduling: timed out waiting for the condition I1106 01:41:54.924] Nov 6 01:41:54.923: INFO: At 2019-11-06 01:36:55 +0000 UTC - event for azuredisk-volume-tester-rk9ww: {default-scheduler } FailedScheduling: AssumePod failed: pod 1a7ec637-0e61-4970-acec-f35bb3ca5107 is in the cache, so can't be assumed I1106 01:41:54.924] Nov 6 01:41:54.923: INFO: At 2019-11-06 01:41:54 +0000 UTC - event for azuredisk-volume-tester-rk9ww: {default-scheduler } FailedScheduling: skip schedule deleting pod: azuredisk-938/azuredisk-volume-tester-rk9ww I1106 01:41:55.002] Nov 6 01:41:55.001: INFO: POD NODE PHASE GRACE CONDITIONS I1106 01:41:55.002] Nov 6 01:41:55.001: INFO: I1106 01:41:55.237] Nov 6 01:41:55.237: INFO: I1106 01:41:55.238] Logging node info for node k8s-agentpool-54406713-vmss000000 I1106 01:41:55.320] Nov 6 01:41:55.316: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:k8s-agentpool-54406713-vmss000000,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/k8s-agentpool-54406713-vmss000000,UID:f11c401a-3543-4cfb-af66-e320a19275bf,ResourceVersion:7834,Generation:0,CreationTimestamp:2019-11-06 01:02:48 +0000 UTC,DeletionTimestamp:<nil>,DeletionGracePeriodSeconds:nil,Labels:map[string]string{agentpool: agentpool,beta.kubernetes.io/arch: amd64,beta.kubernetes.io/instance-type: Standard_D4s_v3,beta.kubernetes.io/os: linux,failure-domain.beta.kubernetes.io/region: eastus2,failure-domain.beta.kubernetes.io/zone: eastus2-1,kubernetes.azure.com/cluster: kubetest-03920ff3-002d-11ea-be9c-02423fe68cb4,kubernetes.azure.com/role: agent,kubernetes.io/arch: amd64,kubernetes.io/hostname: k8s-agentpool-54406713-vmss000000,kubernetes.io/os: linux,kubernetes.io/role: agent,node-role.kubernetes.io/agent: ,storageprofile: managed,storagetier: Premium_LRS,topology.disk.csi.azure.com/zone: eastus2-1,},Annotations:map[string]string{csi.volume.kubernetes.io/nodeid: {"disk.csi.azure.com":"k8s-agentpool-54406713-vmss000000"},node.alpha.kubernetes.io/ttl: 0,volumes.kubernetes.io/controller-managed-attach-detach: true,},OwnerReferences:[],Finalizers:[],ClusterName:,Initializers:nil,ManagedFields:[],},Spec:NodeSpec{PodCIDR:10.244.0.0/24,DoNotUse_ExternalID:,ProviderID:azure:///subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/kubetest-03920ff3-002d-11ea-be9c-02423fe68cb4/providers/Microsoft.Compute/virtualMachineScaleSets/k8s-agentpool-54406713-vmss/virtualMachines/0,Unschedulable:false,Taints:[],ConfigSource:nil,},Status:NodeStatus{Capacity:ResourceList{attachable-volumes-csi-disk.csi.azure.com: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{31036776448 0} {<nil>} BinarySI},hugepages-1Gi: {{0 0} {<nil>} 0 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{16797044736 0} {<nil>} 16403364Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Allocatable:ResourceList{attachable-volumes-csi-disk.csi.azure.com: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{27933098757 0} {<nil>} 27933098757 DecimalSI},hugepages-1Gi: {{0 0} {<nil>} 0 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{16010612736 0} {<nil>} 15635364Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Phase:,Conditions:[{NetworkUnavailable False 2019-11-06 01:03:21 +0000 UTC 2019-11-06 01:03:21 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2019-11-06 01:41:14 +0000 UTC 2019-11-06 01:02:32 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2019-11-06 01:41:14 +0000 UTC 2019-11-06 01:02:32 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2019-11-06 01:41:14 +0000 UTC 2019-11-06 01:02:32 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2019-11-06 01:41:14 +0000 UTC 2019-11-06 01:03:06 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.248.0.4} {Hostname k8s-agentpool-54406713-vmss000000}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:314d4f6d838542d1b91629162863d266,SystemUUID:28F72AD9-C8ED-1C40-AC90-621A4747BF6F,BootID:73555e39-2e46-4dd8-a077-48bc5b4d8032,KernelVersion:4.15.0-1061-azure,OSImage:Ubuntu 16.04.6 LTS,ContainerRuntimeVersion:docker://3.0.6,KubeletVersion:v1.15.0,KubeProxyVersion:v1.15.0,OperatingSystem:linux,Architecture:amd64,},Images:[{[gcrio.azureedge.net/google_containers/hyperkube-amd64@sha256:7f66ed6bd11edd309dad15db1dc906f89035cc9d9ae705c65c98264c775b9a8f gcrio.azureedge.net/google_containers/hyperkube-amd64:v1.15.0] 593352254} {[k8sprowinternal.azurecr.io/azuredisk-csi@sha256:209b5e3501b93135a3e5715553aeb99d41dc7fab732b42161d48b00e40772a93 k8sprowinternal.azurecr.io/azuredisk-csi:e2e-9f289d4c7792de742a1ded20837778e2acb91093] 286926836} {[k8s.gcr.io/kubernetes-dashboard-amd64@sha256:0ae6b69432e78069c5ce2bcde0fe409c5c4d6f0f4d9cd50a17974fea38898747 k8s.gcr.io/kubernetes-dashboard-amd64:v1.10.1] 121711221} {[k8s.gcr.io/ip-masq-agent-amd64@sha256:269e0fb9d53fd37f7a135d6a55ea265a67279ba218aa148323f015cf70167340 k8s.gcr.io/ip-masq-agent-amd64:v2.3.0] 50144412} {[k8s.gcr.io/metrics-server-amd64@sha256:49a9f12f7067d11f42c803dbe61ed2c1299959ad85cb315b25ff7eef8e6b8892 k8s.gcr.io/metrics-server-amd64:v0.2.1] 42541759} {[mcr.microsoft.com/k8s/flexvolume/keyvault-flexvolume@sha256:4fd30d43947d4a54fc89ead7985beecfd3c9b2a93a0655a373b1608ab90bd5af mcr.microsoft.com/k8s/flexvolume/keyvault-flexvolume:v0.0.7] 22909487} {[quay.io/k8scsi/livenessprobe@sha256:8c9c8a0f330acc2e558ae6624309447d02522e76aa35af23fa19b88abf4381cb quay.io/k8scsi/livenessprobe:v1.0.2] 17415381} {[quay.io/k8scsi/csi-node-driver-registrar@sha256:13daf82fb99e951a4bff8ae5fc7c17c3a8fe7130be6400990d8f6076c32d4599 quay.io/k8scsi/csi-node-driver-registrar:v1.1.0] 15815995} {[mcr.microsoft.com/k8s/flexvolume/blobfuse-flexvolume@sha256:23d8c6033f02a1ecad05127ebdc931bb871264228661bc122704b0974e4d9fdd mcr.microsoft.com/k8s/flexvolume/blobfuse-flexvolume:1.0.8] 1159025} {[k8s.gcr.io/pause-amd64@sha256:59eec8837a4d942cc19a52b8c09ea75121acc38114a2c68b98983ce9356b8610 k8s.gcr.io/pause-amd64:3.1] 742472}],VolumesInUse:[],VolumesAttached:[],Config:nil,},} ... skipping 176 lines ... I1106 01:42:16.169] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:33 I1106 01:42:16.169] [multi-az] I1106 01:42:16.169] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:40 I1106 01:42:16.169] should create a volume on demand [It] I1106 01:42:16.169] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:78 I1106 01:42:16.169] I1106 01:42:16.170] Unexpected error: I1106 01:42:16.170] <*errors.errorString | 0xc00077bd30>: { I1106 01:42:16.170] s: "Gave up after waiting 15m0s for pod \"azuredisk-volume-tester-rk9ww\" to be \"success or failure\"", I1106 01:42:16.170] } I1106 01:42:16.170] Gave up after waiting 15m0s for pod "azuredisk-volume-tester-rk9ww" to be "success or failure" I1106 01:42:16.170] occurred I1106 01:42:16.170] ... skipping 161 lines ... I1106 01:47:06.262] Nov 6 01:47:06.262: INFO: PersistentVolumeClaim pvc-6dmtr found but phase is Pending instead of Bound. I1106 01:47:08.342] Nov 6 01:47:08.342: INFO: PersistentVolumeClaim pvc-6dmtr found but phase is Pending instead of Bound. I1106 01:47:10.423] Nov 6 01:47:10.422: INFO: PersistentVolumeClaim pvc-6dmtr found but phase is Pending instead of Bound. I1106 01:47:12.502] Nov 6 01:47:12.502: INFO: PersistentVolumeClaim pvc-6dmtr found but phase is Pending instead of Bound. I1106 01:47:14.585] Nov 6 01:47:14.585: INFO: PersistentVolumeClaim pvc-6dmtr found but phase is Pending instead of Bound. I1106 01:47:16.665] Nov 6 01:47:16.665: INFO: PersistentVolumeClaim pvc-6dmtr found but phase is Pending instead of Bound. I1106 01:47:18.665] Nov 6 01:47:18.665: INFO: Unexpected error occurred: PersistentVolumeClaims [pvc-6dmtr] not all in phase Bound within 5m0s I1106 01:47:18.666] [AfterEach] [single-az] I1106 01:47:18.666] /go/src/sigs.k8s.io/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1106 01:47:18.666] STEP: Collecting events from namespace "azuredisk-9110". I1106 01:47:18.745] STEP: Found 3 events. I1106 01:47:18.746] Nov 6 01:47:18.745: INFO: At 2019-11-06 01:42:16 +0000 UTC - event for pvc-6dmtr: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "disk.csi.azure.com" or manually created by system administrator I1106 01:47:18.746] Nov 6 01:47:18.745: INFO: At 2019-11-06 01:42:16 +0000 UTC - event for pvc-6dmtr: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-bpnmm_9f10eebb-0031-11ea-937c-fe0323241632 } Provisioning: External provisioner is provisioning volume for claim "azuredisk-9110/pvc-6dmtr" I1106 01:47:18.746] Nov 6 01:47:18.745: INFO: At 2019-11-06 01:42:26 +0000 UTC - event for pvc-6dmtr: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-bpnmm_9f10eebb-0031-11ea-937c-fe0323241632 } ProvisioningFailed: failed to provision volume with StorageClass "azuredisk-9110-disk.csi.azure.com-dynamic-sc-pjxwm": rpc error: code = DeadlineExceeded desc = context deadline exceeded I1106 01:47:18.827] Nov 6 01:47:18.827: INFO: POD NODE PHASE GRACE CONDITIONS I1106 01:47:18.828] Nov 6 01:47:18.827: INFO: I1106 01:47:19.067] Nov 6 01:47:19.067: INFO: I1106 01:47:19.068] Logging node info for node k8s-agentpool-54406713-vmss000000 I1106 01:47:19.150] Nov 6 01:47:19.147: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:k8s-agentpool-54406713-vmss000000,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/k8s-agentpool-54406713-vmss000000,UID:f11c401a-3543-4cfb-af66-e320a19275bf,ResourceVersion:8915,Generation:0,CreationTimestamp:2019-11-06 01:02:48 +0000 UTC,DeletionTimestamp:<nil>,DeletionGracePeriodSeconds:nil,Labels:map[string]string{agentpool: agentpool,beta.kubernetes.io/arch: amd64,beta.kubernetes.io/instance-type: Standard_D4s_v3,beta.kubernetes.io/os: linux,failure-domain.beta.kubernetes.io/region: eastus2,failure-domain.beta.kubernetes.io/zone: eastus2-1,kubernetes.azure.com/cluster: kubetest-03920ff3-002d-11ea-be9c-02423fe68cb4,kubernetes.azure.com/role: agent,kubernetes.io/arch: amd64,kubernetes.io/hostname: k8s-agentpool-54406713-vmss000000,kubernetes.io/os: linux,kubernetes.io/role: agent,node-role.kubernetes.io/agent: ,storageprofile: managed,storagetier: Premium_LRS,topology.disk.csi.azure.com/zone: eastus2-1,},Annotations:map[string]string{csi.volume.kubernetes.io/nodeid: {"disk.csi.azure.com":"k8s-agentpool-54406713-vmss000000"},node.alpha.kubernetes.io/ttl: 0,volumes.kubernetes.io/controller-managed-attach-detach: true,},OwnerReferences:[],Finalizers:[],ClusterName:,Initializers:nil,ManagedFields:[],},Spec:NodeSpec{PodCIDR:10.244.0.0/24,DoNotUse_ExternalID:,ProviderID:azure:///subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/kubetest-03920ff3-002d-11ea-be9c-02423fe68cb4/providers/Microsoft.Compute/virtualMachineScaleSets/k8s-agentpool-54406713-vmss/virtualMachines/0,Unschedulable:false,Taints:[],ConfigSource:nil,},Status:NodeStatus{Capacity:ResourceList{attachable-volumes-csi-disk.csi.azure.com: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{31036776448 0} {<nil>} BinarySI},hugepages-1Gi: {{0 0} {<nil>} 0 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{16797044736 0} {<nil>} 16403364Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Allocatable:ResourceList{attachable-volumes-csi-disk.csi.azure.com: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{27933098757 0} {<nil>} 27933098757 DecimalSI},hugepages-1Gi: {{0 0} {<nil>} 0 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{16010612736 0} {<nil>} 15635364Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Phase:,Conditions:[{NetworkUnavailable False 2019-11-06 01:03:21 +0000 UTC 2019-11-06 01:03:21 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2019-11-06 01:47:15 +0000 UTC 2019-11-06 01:02:32 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2019-11-06 01:47:15 +0000 UTC 2019-11-06 01:02:32 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2019-11-06 01:47:15 +0000 UTC 2019-11-06 01:02:32 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2019-11-06 01:47:15 +0000 UTC 2019-11-06 01:03:06 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.248.0.4} {Hostname k8s-agentpool-54406713-vmss000000}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:314d4f6d838542d1b91629162863d266,SystemUUID:28F72AD9-C8ED-1C40-AC90-621A4747BF6F,BootID:73555e39-2e46-4dd8-a077-48bc5b4d8032,KernelVersion:4.15.0-1061-azure,OSImage:Ubuntu 16.04.6 LTS,ContainerRuntimeVersion:docker://3.0.6,KubeletVersion:v1.15.0,KubeProxyVersion:v1.15.0,OperatingSystem:linux,Architecture:amd64,},Images:[{[gcrio.azureedge.net/google_containers/hyperkube-amd64@sha256:7f66ed6bd11edd309dad15db1dc906f89035cc9d9ae705c65c98264c775b9a8f gcrio.azureedge.net/google_containers/hyperkube-amd64:v1.15.0] 593352254} {[k8sprowinternal.azurecr.io/azuredisk-csi@sha256:209b5e3501b93135a3e5715553aeb99d41dc7fab732b42161d48b00e40772a93 k8sprowinternal.azurecr.io/azuredisk-csi:e2e-9f289d4c7792de742a1ded20837778e2acb91093] 286926836} {[k8s.gcr.io/kubernetes-dashboard-amd64@sha256:0ae6b69432e78069c5ce2bcde0fe409c5c4d6f0f4d9cd50a17974fea38898747 k8s.gcr.io/kubernetes-dashboard-amd64:v1.10.1] 121711221} {[k8s.gcr.io/ip-masq-agent-amd64@sha256:269e0fb9d53fd37f7a135d6a55ea265a67279ba218aa148323f015cf70167340 k8s.gcr.io/ip-masq-agent-amd64:v2.3.0] 50144412} {[k8s.gcr.io/metrics-server-amd64@sha256:49a9f12f7067d11f42c803dbe61ed2c1299959ad85cb315b25ff7eef8e6b8892 k8s.gcr.io/metrics-server-amd64:v0.2.1] 42541759} {[mcr.microsoft.com/k8s/flexvolume/keyvault-flexvolume@sha256:4fd30d43947d4a54fc89ead7985beecfd3c9b2a93a0655a373b1608ab90bd5af mcr.microsoft.com/k8s/flexvolume/keyvault-flexvolume:v0.0.7] 22909487} {[quay.io/k8scsi/livenessprobe@sha256:8c9c8a0f330acc2e558ae6624309447d02522e76aa35af23fa19b88abf4381cb quay.io/k8scsi/livenessprobe:v1.0.2] 17415381} {[quay.io/k8scsi/csi-node-driver-registrar@sha256:13daf82fb99e951a4bff8ae5fc7c17c3a8fe7130be6400990d8f6076c32d4599 quay.io/k8scsi/csi-node-driver-registrar:v1.1.0] 15815995} {[mcr.microsoft.com/k8s/flexvolume/blobfuse-flexvolume@sha256:23d8c6033f02a1ecad05127ebdc931bb871264228661bc122704b0974e4d9fdd mcr.microsoft.com/k8s/flexvolume/blobfuse-flexvolume:1.0.8] 1159025} {[k8s.gcr.io/pause-amd64@sha256:59eec8837a4d942cc19a52b8c09ea75121acc38114a2c68b98983ce9356b8610 k8s.gcr.io/pause-amd64:3.1] 742472}],VolumesInUse:[],VolumesAttached:[],Config:nil,},} I1106 01:47:19.150] Nov 6 01:47:19.147: INFO: ... skipping 175 lines ... I1106 01:47:39.947] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:33 I1106 01:47:39.947] [single-az] I1106 01:47:39.947] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:36 I1106 01:47:39.947] should create multiple PV objects, bind to PVCs and attach all to different pods on the same node [It] I1106 01:47:39.947] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:151 I1106 01:47:39.947] I1106 01:47:39.948] Unexpected error: I1106 01:47:39.948] <*errors.errorString | 0xc000f91150>: { I1106 01:47:39.948] s: "PersistentVolumeClaims [pvc-6dmtr] not all in phase Bound within 5m0s", I1106 01:47:39.948] } I1106 01:47:39.948] PersistentVolumeClaims [pvc-6dmtr] not all in phase Bound within 5m0s I1106 01:47:39.948] occurred I1106 01:47:39.948] ... skipping 145 lines ... I1106 01:54:43.132] Nov 6 01:54:43.132: INFO: PersistentVolumeClaim pvc-pgz6n found but phase is Pending instead of Bound. I1106 01:54:45.207] Nov 6 01:54:45.207: INFO: PersistentVolumeClaim pvc-pgz6n found and phase=Bound (56.108442848s) I1106 01:54:45.207] STEP: checking the PVC I1106 01:54:45.283] STEP: validating provisioned PV I1106 01:54:45.357] STEP: checking the PV I1106 01:54:45.357] STEP: deploying the pod I1106 01:54:45.444] STEP: checking that the pods command exits with no error I1106 01:54:45.444] Nov 6 01:54:45.444: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-df864" in namespace "azuredisk-2296" to be "success or failure" I1106 01:54:45.518] Nov 6 01:54:45.518: INFO: Pod "azuredisk-volume-tester-df864": Phase="Pending", Reason="", readiness=false. Elapsed: 73.828859ms I1106 01:54:47.593] Nov 6 01:54:47.593: INFO: Pod "azuredisk-volume-tester-df864": Phase="Pending", Reason="", readiness=false. Elapsed: 2.149055695s I1106 01:54:49.672] Nov 6 01:54:49.672: INFO: Pod "azuredisk-volume-tester-df864": Phase="Pending", Reason="", readiness=false. Elapsed: 4.22807066s I1106 01:54:51.748] Nov 6 01:54:51.748: INFO: Pod "azuredisk-volume-tester-df864": Phase="Pending", Reason="", readiness=false. Elapsed: 6.3037245s I1106 01:54:53.823] Nov 6 01:54:53.822: INFO: Pod "azuredisk-volume-tester-df864": Phase="Pending", Reason="", readiness=false. Elapsed: 8.378624134s ... skipping 360 lines ... I1106 02:04:49.154] [azuredisk-csi-e2e] [single-az] Pre-Provisioned I1106 02:04:49.154] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/pre_provisioning.go:36 I1106 02:04:49.154] [env] should use a pre-provisioned volume and retain PV with reclaimPolicy "Retain" [It] I1106 02:04:49.155] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/pre_provisioning.go:100 I1106 02:04:49.155] I1106 02:04:49.155] Test Panicked I1106 02:04:49.155] runtime error: invalid memory address or nil pointer dereference I1106 02:04:49.155] /usr/local/go/src/runtime/panic.go:82 I1106 02:04:49.155] I1106 02:04:49.156] Full Stack Trace I1106 02:04:49.156] /usr/local/go/src/runtime/panic.go:522 +0x1b5 I1106 02:04:49.156] sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites.(*TestPersistentVolumeClaim).Cleanup(0xc000cca3c0) I1106 02:04:49.156] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:313 +0x3b ... skipping 171 lines ... I1106 02:09:38.933] Nov 6 02:09:38.933: INFO: PersistentVolumeClaim pvc-hd7gv found but phase is Pending instead of Bound. I1106 02:09:41.007] Nov 6 02:09:41.007: INFO: PersistentVolumeClaim pvc-hd7gv found but phase is Pending instead of Bound. I1106 02:09:43.082] Nov 6 02:09:43.082: INFO: PersistentVolumeClaim pvc-hd7gv found but phase is Pending instead of Bound. I1106 02:09:45.157] Nov 6 02:09:45.157: INFO: PersistentVolumeClaim pvc-hd7gv found but phase is Pending instead of Bound. I1106 02:09:47.232] Nov 6 02:09:47.231: INFO: PersistentVolumeClaim pvc-hd7gv found but phase is Pending instead of Bound. I1106 02:09:49.306] Nov 6 02:09:49.306: INFO: PersistentVolumeClaim pvc-hd7gv found but phase is Pending instead of Bound. I1106 02:09:51.307] Nov 6 02:09:51.306: INFO: Unexpected error occurred: PersistentVolumeClaims [pvc-hd7gv] not all in phase Bound within 5m0s I1106 02:09:51.307] [AfterEach] [single-az] I1106 02:09:51.307] /go/src/sigs.k8s.io/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1106 02:09:51.307] STEP: Collecting events from namespace "azuredisk-9868". I1106 02:09:51.381] STEP: Found 3 events. I1106 02:09:51.382] Nov 6 02:09:51.381: INFO: At 2019-11-06 02:04:49 +0000 UTC - event for pvc-hd7gv: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "disk.csi.azure.com" or manually created by system administrator I1106 02:09:51.382] Nov 6 02:09:51.381: INFO: At 2019-11-06 02:04:49 +0000 UTC - event for pvc-hd7gv: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-bpnmm_9f10eebb-0031-11ea-937c-fe0323241632 } Provisioning: External provisioner is provisioning volume for claim "azuredisk-9868/pvc-hd7gv" I1106 02:09:51.382] Nov 6 02:09:51.381: INFO: At 2019-11-06 02:04:59 +0000 UTC - event for pvc-hd7gv: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-bpnmm_9f10eebb-0031-11ea-937c-fe0323241632 } ProvisioningFailed: failed to provision volume with StorageClass "azuredisk-9868-disk.csi.azure.com-dynamic-sc-2vgcz": rpc error: code = DeadlineExceeded desc = context deadline exceeded I1106 02:09:51.455] Nov 6 02:09:51.455: INFO: POD NODE PHASE GRACE CONDITIONS I1106 02:09:51.456] Nov 6 02:09:51.455: INFO: I1106 02:09:51.675] Nov 6 02:09:51.675: INFO: I1106 02:09:51.675] Logging node info for node k8s-agentpool-54406713-vmss000000 I1106 02:09:51.753] Nov 6 02:09:51.749: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:k8s-agentpool-54406713-vmss000000,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/k8s-agentpool-54406713-vmss000000,UID:f11c401a-3543-4cfb-af66-e320a19275bf,ResourceVersion:13044,Generation:0,CreationTimestamp:2019-11-06 01:02:48 +0000 UTC,DeletionTimestamp:<nil>,DeletionGracePeriodSeconds:nil,Labels:map[string]string{agentpool: agentpool,beta.kubernetes.io/arch: amd64,beta.kubernetes.io/instance-type: Standard_D4s_v3,beta.kubernetes.io/os: linux,failure-domain.beta.kubernetes.io/region: eastus2,failure-domain.beta.kubernetes.io/zone: eastus2-1,kubernetes.azure.com/cluster: kubetest-03920ff3-002d-11ea-be9c-02423fe68cb4,kubernetes.azure.com/role: agent,kubernetes.io/arch: amd64,kubernetes.io/hostname: k8s-agentpool-54406713-vmss000000,kubernetes.io/os: linux,kubernetes.io/role: agent,node-role.kubernetes.io/agent: ,storageprofile: managed,storagetier: Premium_LRS,topology.disk.csi.azure.com/zone: eastus2-1,},Annotations:map[string]string{csi.volume.kubernetes.io/nodeid: {"disk.csi.azure.com":"k8s-agentpool-54406713-vmss000000"},node.alpha.kubernetes.io/ttl: 0,volumes.kubernetes.io/controller-managed-attach-detach: true,},OwnerReferences:[],Finalizers:[],ClusterName:,Initializers:nil,ManagedFields:[],},Spec:NodeSpec{PodCIDR:10.244.0.0/24,DoNotUse_ExternalID:,ProviderID:azure:///subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/kubetest-03920ff3-002d-11ea-be9c-02423fe68cb4/providers/Microsoft.Compute/virtualMachineScaleSets/k8s-agentpool-54406713-vmss/virtualMachines/0,Unschedulable:false,Taints:[],ConfigSource:nil,},Status:NodeStatus{Capacity:ResourceList{attachable-volumes-csi-disk.csi.azure.com: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{31036776448 0} {<nil>} BinarySI},hugepages-1Gi: {{0 0} {<nil>} 0 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{16797044736 0} {<nil>} 16403364Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Allocatable:ResourceList{attachable-volumes-csi-disk.csi.azure.com: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{27933098757 0} {<nil>} 27933098757 DecimalSI},hugepages-1Gi: {{0 0} {<nil>} 0 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{16010612736 0} {<nil>} 15635364Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Phase:,Conditions:[{NetworkUnavailable False 2019-11-06 01:03:21 +0000 UTC 2019-11-06 01:03:21 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2019-11-06 02:09:49 +0000 UTC 2019-11-06 01:02:32 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2019-11-06 02:09:49 +0000 UTC 2019-11-06 01:02:32 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2019-11-06 02:09:49 +0000 UTC 2019-11-06 01:02:32 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2019-11-06 02:09:49 +0000 UTC 2019-11-06 01:03:06 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.248.0.4} {Hostname k8s-agentpool-54406713-vmss000000}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:314d4f6d838542d1b91629162863d266,SystemUUID:28F72AD9-C8ED-1C40-AC90-621A4747BF6F,BootID:73555e39-2e46-4dd8-a077-48bc5b4d8032,KernelVersion:4.15.0-1061-azure,OSImage:Ubuntu 16.04.6 LTS,ContainerRuntimeVersion:docker://3.0.6,KubeletVersion:v1.15.0,KubeProxyVersion:v1.15.0,OperatingSystem:linux,Architecture:amd64,},Images:[{[gcrio.azureedge.net/google_containers/hyperkube-amd64@sha256:7f66ed6bd11edd309dad15db1dc906f89035cc9d9ae705c65c98264c775b9a8f gcrio.azureedge.net/google_containers/hyperkube-amd64:v1.15.0] 593352254} {[k8sprowinternal.azurecr.io/azuredisk-csi@sha256:209b5e3501b93135a3e5715553aeb99d41dc7fab732b42161d48b00e40772a93 k8sprowinternal.azurecr.io/azuredisk-csi:e2e-9f289d4c7792de742a1ded20837778e2acb91093] 286926836} {[k8s.gcr.io/kubernetes-dashboard-amd64@sha256:0ae6b69432e78069c5ce2bcde0fe409c5c4d6f0f4d9cd50a17974fea38898747 k8s.gcr.io/kubernetes-dashboard-amd64:v1.10.1] 121711221} {[k8s.gcr.io/ip-masq-agent-amd64@sha256:269e0fb9d53fd37f7a135d6a55ea265a67279ba218aa148323f015cf70167340 k8s.gcr.io/ip-masq-agent-amd64:v2.3.0] 50144412} {[k8s.gcr.io/metrics-server-amd64@sha256:49a9f12f7067d11f42c803dbe61ed2c1299959ad85cb315b25ff7eef8e6b8892 k8s.gcr.io/metrics-server-amd64:v0.2.1] 42541759} {[mcr.microsoft.com/k8s/flexvolume/keyvault-flexvolume@sha256:4fd30d43947d4a54fc89ead7985beecfd3c9b2a93a0655a373b1608ab90bd5af mcr.microsoft.com/k8s/flexvolume/keyvault-flexvolume:v0.0.7] 22909487} {[quay.io/k8scsi/livenessprobe@sha256:8c9c8a0f330acc2e558ae6624309447d02522e76aa35af23fa19b88abf4381cb quay.io/k8scsi/livenessprobe:v1.0.2] 17415381} {[quay.io/k8scsi/csi-node-driver-registrar@sha256:13daf82fb99e951a4bff8ae5fc7c17c3a8fe7130be6400990d8f6076c32d4599 quay.io/k8scsi/csi-node-driver-registrar:v1.1.0] 15815995} {[mcr.microsoft.com/k8s/flexvolume/blobfuse-flexvolume@sha256:23d8c6033f02a1ecad05127ebdc931bb871264228661bc122704b0974e4d9fdd mcr.microsoft.com/k8s/flexvolume/blobfuse-flexvolume:1.0.8] 1159025} {[busybox@sha256:8ccbac733d19c0dd4d70b4f0c1e12245b5fa3ad24758a11035ee505c629c0796 busybox:1.29] 1154361} {[k8s.gcr.io/pause-amd64@sha256:59eec8837a4d942cc19a52b8c09ea75121acc38114a2c68b98983ce9356b8610 k8s.gcr.io/pause-amd64:3.1] 742472}],VolumesInUse:[kubernetes.io/csi/disk.csi.azure.com^/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/kubetest-03920ff3-002d-11ea-be9c-02423fe68cb4/providers/Microsoft.Compute/disks/pvc-87d218a7-da86-4695-851c-449e48182a17],VolumesAttached:[],Config:nil,},} I1106 02:09:51.753] Nov 6 02:09:51.750: INFO: ... skipping 175 lines ... I1106 02:10:12.158] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:33 I1106 02:10:12.158] [single-az] I1106 02:10:12.158] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:36 I1106 02:10:12.158] should create a volume on demand and mount it as readOnly in a pod [It] I1106 02:10:12.158] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:126 I1106 02:10:12.159] I1106 02:10:12.159] Unexpected error: I1106 02:10:12.159] <*errors.errorString | 0xc000bbac60>: { I1106 02:10:12.159] s: "PersistentVolumeClaims [pvc-hd7gv] not all in phase Bound within 5m0s", I1106 02:10:12.159] } I1106 02:10:12.159] PersistentVolumeClaims [pvc-hd7gv] not all in phase Bound within 5m0s I1106 02:10:12.159] occurred I1106 02:10:12.160] ... skipping 161 lines ... I1106 02:15:01.786] Nov 6 02:15:01.786: INFO: PersistentVolumeClaim pvc-ztk9k found but phase is Pending instead of Bound. I1106 02:15:03.866] Nov 6 02:15:03.866: INFO: PersistentVolumeClaim pvc-ztk9k found but phase is Pending instead of Bound. I1106 02:15:05.946] Nov 6 02:15:05.946: INFO: PersistentVolumeClaim pvc-ztk9k found but phase is Pending instead of Bound. I1106 02:15:08.027] Nov 6 02:15:08.026: INFO: PersistentVolumeClaim pvc-ztk9k found but phase is Pending instead of Bound. I1106 02:15:10.106] Nov 6 02:15:10.106: INFO: PersistentVolumeClaim pvc-ztk9k found but phase is Pending instead of Bound. I1106 02:15:12.186] Nov 6 02:15:12.185: INFO: PersistentVolumeClaim pvc-ztk9k found but phase is Pending instead of Bound. I1106 02:15:14.186] Nov 6 02:15:14.186: INFO: Unexpected error occurred: PersistentVolumeClaims [pvc-ztk9k] not all in phase Bound within 5m0s I1106 02:15:14.186] [AfterEach] [single-az] I1106 02:15:14.186] /go/src/sigs.k8s.io/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1106 02:15:14.187] STEP: Collecting events from namespace "azuredisk-9202". I1106 02:15:14.266] STEP: Found 3 events. I1106 02:15:14.266] Nov 6 02:15:14.266: INFO: At 2019-11-06 02:10:12 +0000 UTC - event for pvc-ztk9k: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "disk.csi.azure.com" or manually created by system administrator I1106 02:15:14.267] Nov 6 02:15:14.266: INFO: At 2019-11-06 02:10:12 +0000 UTC - event for pvc-ztk9k: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-bpnmm_9f10eebb-0031-11ea-937c-fe0323241632 } Provisioning: External provisioner is provisioning volume for claim "azuredisk-9202/pvc-ztk9k" I1106 02:15:14.267] Nov 6 02:15:14.266: INFO: At 2019-11-06 02:10:22 +0000 UTC - event for pvc-ztk9k: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-bpnmm_9f10eebb-0031-11ea-937c-fe0323241632 } ProvisioningFailed: failed to provision volume with StorageClass "azuredisk-9202-disk.csi.azure.com-dynamic-sc-sxvqw": rpc error: code = DeadlineExceeded desc = context deadline exceeded I1106 02:15:14.355] Nov 6 02:15:14.355: INFO: POD NODE PHASE GRACE CONDITIONS I1106 02:15:14.355] Nov 6 02:15:14.355: INFO: I1106 02:15:14.594] Nov 6 02:15:14.594: INFO: I1106 02:15:14.594] Logging node info for node k8s-agentpool-54406713-vmss000000 I1106 02:15:14.676] Nov 6 02:15:14.673: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:k8s-agentpool-54406713-vmss000000,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/k8s-agentpool-54406713-vmss000000,UID:f11c401a-3543-4cfb-af66-e320a19275bf,ResourceVersion:13943,Generation:0,CreationTimestamp:2019-11-06 01:02:48 +0000 UTC,DeletionTimestamp:<nil>,DeletionGracePeriodSeconds:nil,Labels:map[string]string{agentpool: agentpool,beta.kubernetes.io/arch: amd64,beta.kubernetes.io/instance-type: Standard_D4s_v3,beta.kubernetes.io/os: linux,failure-domain.beta.kubernetes.io/region: eastus2,failure-domain.beta.kubernetes.io/zone: eastus2-1,kubernetes.azure.com/cluster: kubetest-03920ff3-002d-11ea-be9c-02423fe68cb4,kubernetes.azure.com/role: agent,kubernetes.io/arch: amd64,kubernetes.io/hostname: k8s-agentpool-54406713-vmss000000,kubernetes.io/os: linux,kubernetes.io/role: agent,node-role.kubernetes.io/agent: ,storageprofile: managed,storagetier: Premium_LRS,topology.disk.csi.azure.com/zone: eastus2-1,},Annotations:map[string]string{csi.volume.kubernetes.io/nodeid: {"disk.csi.azure.com":"k8s-agentpool-54406713-vmss000000"},node.alpha.kubernetes.io/ttl: 0,volumes.kubernetes.io/controller-managed-attach-detach: true,},OwnerReferences:[],Finalizers:[],ClusterName:,Initializers:nil,ManagedFields:[],},Spec:NodeSpec{PodCIDR:10.244.0.0/24,DoNotUse_ExternalID:,ProviderID:azure:///subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/kubetest-03920ff3-002d-11ea-be9c-02423fe68cb4/providers/Microsoft.Compute/virtualMachineScaleSets/k8s-agentpool-54406713-vmss/virtualMachines/0,Unschedulable:false,Taints:[],ConfigSource:nil,},Status:NodeStatus{Capacity:ResourceList{attachable-volumes-csi-disk.csi.azure.com: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{31036776448 0} {<nil>} BinarySI},hugepages-1Gi: {{0 0} {<nil>} 0 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{16797044736 0} {<nil>} 16403364Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Allocatable:ResourceList{attachable-volumes-csi-disk.csi.azure.com: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{27933098757 0} {<nil>} 27933098757 DecimalSI},hugepages-1Gi: {{0 0} {<nil>} 0 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{16010612736 0} {<nil>} 15635364Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Phase:,Conditions:[{NetworkUnavailable False 2019-11-06 01:03:21 +0000 UTC 2019-11-06 01:03:21 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2019-11-06 02:14:50 +0000 UTC 2019-11-06 01:02:32 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2019-11-06 02:14:50 +0000 UTC 2019-11-06 01:02:32 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2019-11-06 02:14:50 +0000 UTC 2019-11-06 01:02:32 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2019-11-06 02:14:50 +0000 UTC 2019-11-06 01:03:06 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.248.0.4} {Hostname k8s-agentpool-54406713-vmss000000}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:314d4f6d838542d1b91629162863d266,SystemUUID:28F72AD9-C8ED-1C40-AC90-621A4747BF6F,BootID:73555e39-2e46-4dd8-a077-48bc5b4d8032,KernelVersion:4.15.0-1061-azure,OSImage:Ubuntu 16.04.6 LTS,ContainerRuntimeVersion:docker://3.0.6,KubeletVersion:v1.15.0,KubeProxyVersion:v1.15.0,OperatingSystem:linux,Architecture:amd64,},Images:[{[gcrio.azureedge.net/google_containers/hyperkube-amd64@sha256:7f66ed6bd11edd309dad15db1dc906f89035cc9d9ae705c65c98264c775b9a8f gcrio.azureedge.net/google_containers/hyperkube-amd64:v1.15.0] 593352254} {[k8sprowinternal.azurecr.io/azuredisk-csi@sha256:209b5e3501b93135a3e5715553aeb99d41dc7fab732b42161d48b00e40772a93 k8sprowinternal.azurecr.io/azuredisk-csi:e2e-9f289d4c7792de742a1ded20837778e2acb91093] 286926836} {[k8s.gcr.io/kubernetes-dashboard-amd64@sha256:0ae6b69432e78069c5ce2bcde0fe409c5c4d6f0f4d9cd50a17974fea38898747 k8s.gcr.io/kubernetes-dashboard-amd64:v1.10.1] 121711221} {[k8s.gcr.io/ip-masq-agent-amd64@sha256:269e0fb9d53fd37f7a135d6a55ea265a67279ba218aa148323f015cf70167340 k8s.gcr.io/ip-masq-agent-amd64:v2.3.0] 50144412} {[k8s.gcr.io/metrics-server-amd64@sha256:49a9f12f7067d11f42c803dbe61ed2c1299959ad85cb315b25ff7eef8e6b8892 k8s.gcr.io/metrics-server-amd64:v0.2.1] 42541759} {[mcr.microsoft.com/k8s/flexvolume/keyvault-flexvolume@sha256:4fd30d43947d4a54fc89ead7985beecfd3c9b2a93a0655a373b1608ab90bd5af mcr.microsoft.com/k8s/flexvolume/keyvault-flexvolume:v0.0.7] 22909487} {[quay.io/k8scsi/livenessprobe@sha256:8c9c8a0f330acc2e558ae6624309447d02522e76aa35af23fa19b88abf4381cb quay.io/k8scsi/livenessprobe:v1.0.2] 17415381} {[quay.io/k8scsi/csi-node-driver-registrar@sha256:13daf82fb99e951a4bff8ae5fc7c17c3a8fe7130be6400990d8f6076c32d4599 quay.io/k8scsi/csi-node-driver-registrar:v1.1.0] 15815995} {[mcr.microsoft.com/k8s/flexvolume/blobfuse-flexvolume@sha256:23d8c6033f02a1ecad05127ebdc931bb871264228661bc122704b0974e4d9fdd mcr.microsoft.com/k8s/flexvolume/blobfuse-flexvolume:1.0.8] 1159025} {[busybox@sha256:8ccbac733d19c0dd4d70b4f0c1e12245b5fa3ad24758a11035ee505c629c0796 busybox:1.29] 1154361} {[k8s.gcr.io/pause-amd64@sha256:59eec8837a4d942cc19a52b8c09ea75121acc38114a2c68b98983ce9356b8610 k8s.gcr.io/pause-amd64:3.1] 742472}],VolumesInUse:[kubernetes.io/csi/disk.csi.azure.com^/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/kubetest-03920ff3-002d-11ea-be9c-02423fe68cb4/providers/Microsoft.Compute/disks/pvc-87d218a7-da86-4695-851c-449e48182a17],VolumesAttached:[],Config:nil,},} I1106 02:15:14.676] Nov 6 02:15:14.673: INFO: ... skipping 175 lines ... I1106 02:15:35.468] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:33 I1106 02:15:35.468] [single-az] I1106 02:15:35.468] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:36 I1106 02:15:35.468] should delete PV with reclaimPolicy "Delete" [It] I1106 02:15:35.468] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:221 I1106 02:15:35.468] I1106 02:15:35.468] Unexpected error: I1106 02:15:35.469] <*errors.errorString | 0xc000915680>: { I1106 02:15:35.469] s: "PersistentVolumeClaims [pvc-ztk9k] not all in phase Bound within 5m0s", I1106 02:15:35.469] } I1106 02:15:35.469] PersistentVolumeClaims [pvc-ztk9k] not all in phase Bound within 5m0s I1106 02:15:35.469] occurred I1106 02:15:35.469] ... skipping 120 lines ... I1106 02:18:44.430] Nov 6 02:18:44.429: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-424mg] to have phase Bound I1106 02:18:44.502] Nov 6 02:18:44.502: INFO: PersistentVolumeClaim pvc-424mg found and phase=Bound (72.662067ms) I1106 02:18:44.502] STEP: checking the PVC I1106 02:18:44.575] STEP: validating provisioned PV I1106 02:18:44.651] STEP: checking the PV I1106 02:18:44.652] STEP: deploying the pod I1106 02:18:44.729] STEP: checking that the pods command exits with an error I1106 02:18:44.730] Nov 6 02:18:44.729: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-mfjcf" in namespace "azuredisk-6246" to be "Error status code" I1106 02:18:44.807] Nov 6 02:18:44.807: INFO: Pod "azuredisk-volume-tester-mfjcf": Phase="Pending", Reason="", readiness=false. Elapsed: 78.110009ms I1106 02:18:46.881] Nov 6 02:18:46.881: INFO: Pod "azuredisk-volume-tester-mfjcf": Phase="Pending", Reason="", readiness=false. Elapsed: 2.151629773s I1106 02:18:48.959] Nov 6 02:18:48.959: INFO: Pod "azuredisk-volume-tester-mfjcf": Phase="Pending", Reason="", readiness=false. Elapsed: 4.230149276s I1106 02:18:51.038] Nov 6 02:18:51.038: INFO: Pod "azuredisk-volume-tester-mfjcf": Phase="Pending", Reason="", readiness=false. Elapsed: 6.308535676s I1106 02:18:53.113] Nov 6 02:18:53.112: INFO: Pod "azuredisk-volume-tester-mfjcf": Phase="Pending", Reason="", readiness=false. Elapsed: 8.383382149s I1106 02:18:55.187] Nov 6 02:18:55.186: INFO: Pod "azuredisk-volume-tester-mfjcf": Phase="Pending", Reason="", readiness=false. Elapsed: 10.457317713s ... skipping 421 lines ... I1106 02:33:33.150] Nov 6 02:33:33.150: INFO: Pod "azuredisk-volume-tester-mfjcf": Phase="Pending", Reason="", readiness=false. Elapsed: 14m48.42080171s I1106 02:33:35.230] Nov 6 02:33:35.230: INFO: Pod "azuredisk-volume-tester-mfjcf": Phase="Pending", Reason="", readiness=false. Elapsed: 14m50.500644565s I1106 02:33:37.318] Nov 6 02:33:37.318: INFO: Pod "azuredisk-volume-tester-mfjcf": Phase="Pending", Reason="", readiness=false. Elapsed: 14m52.588751684s I1106 02:33:39.398] Nov 6 02:33:39.398: INFO: Pod "azuredisk-volume-tester-mfjcf": Phase="Pending", Reason="", readiness=false. Elapsed: 14m54.66867174s I1106 02:33:41.478] Nov 6 02:33:41.478: INFO: Pod "azuredisk-volume-tester-mfjcf": Phase="Pending", Reason="", readiness=false. Elapsed: 14m56.748845697s I1106 02:33:43.558] Nov 6 02:33:43.557: INFO: Pod "azuredisk-volume-tester-mfjcf": Phase="Pending", Reason="", readiness=false. Elapsed: 14m58.82837845s I1106 02:33:45.558] Nov 6 02:33:45.558: INFO: Unexpected error occurred: Gave up after waiting 15m0s for pod "azuredisk-volume-tester-mfjcf" to be "Error status code" I1106 02:33:45.558] Nov 6 02:33:45.558: INFO: deleting Pod "azuredisk-6246"/"azuredisk-volume-tester-mfjcf" I1106 02:33:45.644] Nov 6 02:33:45.644: INFO: Error getting logs for pod azuredisk-volume-tester-mfjcf: the server rejected our request for an unknown reason (get pods azuredisk-volume-tester-mfjcf) I1106 02:33:45.644] STEP: Deleting pod azuredisk-volume-tester-mfjcf in namespace azuredisk-6246 I1106 02:33:45.735] STEP: deleting PV "azuredisk-6246-disk.csi.azure.com-preprovsioned-pv-th8dq" I1106 02:33:45.735] Nov 6 02:33:45.735: INFO: Deleting PersistentVolume "azuredisk-6246-disk.csi.azure.com-preprovsioned-pv-th8dq" I1106 02:33:45.825] STEP: waiting for claim's PV "azuredisk-6246-disk.csi.azure.com-preprovsioned-pv-th8dq" to be deleted I1106 02:33:45.825] Nov 6 02:33:45.824: INFO: Waiting up to 10m0s for PersistentVolume azuredisk-6246-disk.csi.azure.com-preprovsioned-pv-th8dq to get deleted I1106 02:33:45.904] Nov 6 02:33:45.903: INFO: PersistentVolume azuredisk-6246-disk.csi.azure.com-preprovsioned-pv-th8dq found and phase=Bound (79.01481ms) ... skipping 112 lines ... I1106 02:43:20.037] Nov 6 02:43:20.036: INFO: PersistentVolume azuredisk-6246-disk.csi.azure.com-preprovsioned-pv-th8dq found and phase=Bound (9m34.211942476s) I1106 02:43:25.118] Nov 6 02:43:25.118: INFO: PersistentVolume azuredisk-6246-disk.csi.azure.com-preprovsioned-pv-th8dq found and phase=Bound (9m39.293434526s) I1106 02:43:30.198] Nov 6 02:43:30.198: INFO: PersistentVolume azuredisk-6246-disk.csi.azure.com-preprovsioned-pv-th8dq found and phase=Bound (9m44.373215545s) I1106 02:43:35.277] Nov 6 02:43:35.277: INFO: PersistentVolume azuredisk-6246-disk.csi.azure.com-preprovsioned-pv-th8dq found and phase=Bound (9m49.45232014s) I1106 02:43:40.357] Nov 6 02:43:40.356: INFO: PersistentVolume azuredisk-6246-disk.csi.azure.com-preprovsioned-pv-th8dq found and phase=Bound (9m54.531994923s) I1106 02:43:45.436] Nov 6 02:43:45.436: INFO: PersistentVolume azuredisk-6246-disk.csi.azure.com-preprovsioned-pv-th8dq found and phase=Bound (9m59.611347387s) I1106 02:43:50.436] Nov 6 02:43:50.436: INFO: Unexpected error occurred: PersistentVolume azuredisk-6246-disk.csi.azure.com-preprovsioned-pv-th8dq still exists within 10m0s I1106 02:43:50.437] [AfterEach] [azuredisk-csi-e2e] [single-az] Pre-Provisioned I1106 02:43:50.437] /go/src/sigs.k8s.io/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1106 02:43:50.437] STEP: Collecting events from namespace "azuredisk-6246". I1106 02:43:50.516] STEP: Found 4 events. I1106 02:43:50.517] Nov 6 02:43:50.516: INFO: At 2019-11-06 02:18:44 +0000 UTC - event for azuredisk-volume-tester-mfjcf: {default-scheduler } Scheduled: Successfully assigned azuredisk-6246/azuredisk-volume-tester-mfjcf to k8s-agentpool-54406713-vmss000001 I1106 02:43:50.517] Nov 6 02:43:50.516: INFO: At 2019-11-06 02:18:45 +0000 UTC - event for azuredisk-volume-tester-mfjcf: {attachdetach-controller } FailedAttachVolume: AttachVolume.Attach failed for volume "azuredisk-6246-disk.csi.azure.com-preprovsioned-pv-th8dq" : rpc error: code = Unknown desc = Attach volume "/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/kubetest-03920ff3-002d-11ea-be9c-02423fe68cb4/providers/Microsoft.Compute/disks/pre-provisioned-readOnly" to instance "k8s-agentpool-54406713-vmss000001" failed with compute.VirtualMachineScaleSetVMsClient#Update: Failure sending request: StatusCode=400 -- Original Error: Code="BadRequest" Message="Disk /subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/kubetest-03920ff3-002d-11ea-be9c-02423fe68cb4/providers/Microsoft.Compute/disks/pre-provisioned-readOnly cannot be attached to the VM because it is not in zone '2'." I1106 02:43:50.518] Nov 6 02:43:50.516: INFO: At 2019-11-06 02:20:47 +0000 UTC - event for azuredisk-volume-tester-mfjcf: {kubelet k8s-agentpool-54406713-vmss000001} FailedMount: Unable to mount volumes for pod "azuredisk-volume-tester-mfjcf_azuredisk-6246(fa08ec9d-8bf0-4e07-be1d-00d174bdcc95)": timeout expired waiting for volumes to attach or mount for pod "azuredisk-6246"/"azuredisk-volume-tester-mfjcf". list of unmounted volumes=[test-volume-1]. list of unattached volumes=[test-volume-1 default-token-hn925] I1106 02:43:50.518] Nov 6 02:43:50.516: INFO: At 2019-11-06 02:34:19 +0000 UTC - event for azuredisk-volume-tester-mfjcf: {kubelet k8s-agentpool-54406713-vmss000001} FailedMount: Unable to mount volumes for pod "azuredisk-volume-tester-mfjcf_azuredisk-6246(fa08ec9d-8bf0-4e07-be1d-00d174bdcc95)": timeout expired waiting for volumes to attach or mount for pod "azuredisk-6246"/"azuredisk-volume-tester-mfjcf". list of unmounted volumes=[test-volume-1 default-token-hn925]. list of unattached volumes=[test-volume-1 default-token-hn925] I1106 02:43:50.596] Nov 6 02:43:50.596: INFO: POD NODE PHASE GRACE CONDITIONS I1106 02:43:50.596] Nov 6 02:43:50.596: INFO: I1106 02:43:50.831] Nov 6 02:43:50.831: INFO: I1106 02:43:50.831] Logging node info for node k8s-agentpool-54406713-vmss000000 ... skipping 177 lines ... I1106 02:44:17.570] • Failure [1545.951 seconds] I1106 02:44:17.571] [azuredisk-csi-e2e] [single-az] Pre-Provisioned I1106 02:44:17.571] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/pre_provisioning.go:36 I1106 02:44:17.571] [env] should use a pre-provisioned volume and mount it as readOnly in a pod [It] I1106 02:44:17.571] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/pre_provisioning.go:66 I1106 02:44:17.571] I1106 02:44:17.571] Unexpected error: I1106 02:44:17.571] <*errors.errorString | 0xc00077abe0>: { I1106 02:44:17.571] s: "Gave up after waiting 15m0s for pod \"azuredisk-volume-tester-mfjcf\" to be \"Error status code\"", I1106 02:44:17.571] } I1106 02:44:17.572] Gave up after waiting 15m0s for pod "azuredisk-volume-tester-mfjcf" to be "Error status code" I1106 02:44:17.572] occurred I1106 02:44:17.572] I1106 02:44:17.572] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:553 I1106 02:44:17.572] ------------------------------ I1106 02:44:17.572] [azuredisk-csi-e2e] Dynamic Provisioning [multi-az] I1106 02:44:17.572] should create a raw block volume on demand ... skipping 11 lines ... I1106 02:44:18.160] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:101 I1106 02:44:18.160] STEP: setting up the StorageClass I1106 02:44:18.160] STEP: creating a StorageClass I1106 02:44:18.242] STEP: setting up the PVC and PV I1106 02:44:18.242] STEP: creating a PVC I1106 02:44:18.328] STEP: deploying the pod I1106 02:44:18.417] STEP: checking that the pods command exits with no error I1106 02:44:18.418] Nov 6 02:44:18.417: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-qxbbz" in namespace "azuredisk-4328" to be "success or failure" I1106 02:44:18.497] Nov 6 02:44:18.497: INFO: Pod "azuredisk-volume-tester-qxbbz": Phase="Pending", Reason="", readiness=false. Elapsed: 79.316949ms I1106 02:44:20.577] Nov 6 02:44:20.576: INFO: Pod "azuredisk-volume-tester-qxbbz": Phase="Pending", Reason="", readiness=false. Elapsed: 2.15908476s I1106 02:44:22.657] Nov 6 02:44:22.657: INFO: Pod "azuredisk-volume-tester-qxbbz": Phase="Pending", Reason="", readiness=false. Elapsed: 4.239901177s I1106 02:44:24.737] Nov 6 02:44:24.737: INFO: Pod "azuredisk-volume-tester-qxbbz": Phase="Pending", Reason="", readiness=false. Elapsed: 6.319483081s I1106 02:44:26.817] Nov 6 02:44:26.817: INFO: Pod "azuredisk-volume-tester-qxbbz": Phase="Pending", Reason="", readiness=false. Elapsed: 8.399540186s ... skipping 422 lines ... I1106 02:59:06.363] Nov 6 02:59:06.363: INFO: Pod "azuredisk-volume-tester-qxbbz": Phase="Pending", Reason="", readiness=false. Elapsed: 14m47.945705096s I1106 02:59:08.437] Nov 6 02:59:08.437: INFO: Pod "azuredisk-volume-tester-qxbbz": Phase="Pending", Reason="", readiness=false. Elapsed: 14m50.019363122s I1106 02:59:10.511] Nov 6 02:59:10.510: INFO: Pod "azuredisk-volume-tester-qxbbz": Phase="Pending", Reason="", readiness=false. Elapsed: 14m52.09326045s I1106 02:59:12.591] Nov 6 02:59:12.590: INFO: Pod "azuredisk-volume-tester-qxbbz": Phase="Pending", Reason="", readiness=false. Elapsed: 14m54.173210325s I1106 02:59:14.671] Nov 6 02:59:14.671: INFO: Pod "azuredisk-volume-tester-qxbbz": Phase="Pending", Reason="", readiness=false. Elapsed: 14m56.253679603s I1106 02:59:16.751] Nov 6 02:59:16.751: INFO: Pod "azuredisk-volume-tester-qxbbz": Phase="Pending", Reason="", readiness=false. Elapsed: 14m58.333525876s I1106 02:59:18.751] Nov 6 02:59:18.751: INFO: Unexpected error occurred: Gave up after waiting 15m0s for pod "azuredisk-volume-tester-qxbbz" to be "success or failure" I1106 02:59:18.752] Nov 6 02:59:18.751: INFO: deleting Pod "azuredisk-4328"/"azuredisk-volume-tester-qxbbz" I1106 02:59:18.831] Nov 6 02:59:18.831: INFO: Pod azuredisk-volume-tester-qxbbz has the following logs: I1106 02:59:18.831] STEP: Deleting pod azuredisk-volume-tester-qxbbz in namespace azuredisk-4328 I1106 02:59:19.054] STEP: validating provisioned PV I1106 02:59:19.055] Nov 6 02:59:19.054: INFO: Unexpected error occurred: resource name may not be empty I1106 02:59:19.055] Nov 6 02:59:19.055: INFO: deleting StorageClass azuredisk-4328-disk.csi.azure.com-dynamic-sc-mlk5n I1106 02:59:19.151] [AfterEach] [multi-az] I1106 02:59:19.152] /go/src/sigs.k8s.io/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1106 02:59:19.152] STEP: Collecting events from namespace "azuredisk-4328". I1106 02:59:19.231] STEP: Found 6 events. I1106 02:59:19.231] Nov 6 02:59:19.230: INFO: At 2019-11-06 02:44:18 +0000 UTC - event for pvc-pl8l8: {persistentvolume-controller } WaitForFirstConsumer: waiting for first consumer to be created before binding I1106 02:59:19.231] Nov 6 02:59:19.230: INFO: At 2019-11-06 02:44:18 +0000 UTC - event for pvc-pl8l8: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "disk.csi.azure.com" or manually created by system administrator I1106 02:59:19.231] Nov 6 02:59:19.230: INFO: At 2019-11-06 02:44:18 +0000 UTC - event for pvc-pl8l8: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-bpnmm_9f10eebb-0031-11ea-937c-fe0323241632 } Provisioning: External provisioner is provisioning volume for claim "azuredisk-4328/pvc-pl8l8" I1106 02:59:19.232] Nov 6 02:59:19.230: INFO: At 2019-11-06 02:44:28 +0000 UTC - event for pvc-pl8l8: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-bpnmm_9f10eebb-0031-11ea-937c-fe0323241632 } ProvisioningFailed: failed to provision volume with StorageClass "azuredisk-4328-disk.csi.azure.com-dynamic-sc-mlk5n": rpc error: code = DeadlineExceeded desc = context deadline exceeded I1106 02:59:19.232] Nov 6 02:59:19.230: INFO: At 2019-11-06 02:54:18 +0000 UTC - event for azuredisk-volume-tester-qxbbz: {default-scheduler } FailedScheduling: timed out waiting for the condition I1106 02:59:19.232] Nov 6 02:59:19.230: INFO: At 2019-11-06 02:59:18 +0000 UTC - event for azuredisk-volume-tester-qxbbz: {default-scheduler } FailedScheduling: skip schedule deleting pod: azuredisk-4328/azuredisk-volume-tester-qxbbz I1106 02:59:19.310] Nov 6 02:59:19.310: INFO: POD NODE PHASE GRACE CONDITIONS I1106 02:59:19.310] Nov 6 02:59:19.310: INFO: I1106 02:59:19.545] Nov 6 02:59:19.545: INFO: I1106 02:59:19.545] Logging node info for node k8s-agentpool-54406713-vmss000000 ... skipping 177 lines ... I1106 02:59:40.476] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:33 I1106 02:59:40.476] [multi-az] I1106 02:59:40.477] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:40 I1106 02:59:40.477] should create a raw block volume on demand [It] I1106 02:59:40.477] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:101 I1106 02:59:40.477] I1106 02:59:40.477] Unexpected error: I1106 02:59:40.478] <*errors.errorString | 0xc000bbaa60>: { I1106 02:59:40.478] s: "Gave up after waiting 15m0s for pod \"azuredisk-volume-tester-qxbbz\" to be \"success or failure\"", I1106 02:59:40.478] } I1106 02:59:40.478] Gave up after waiting 15m0s for pod "azuredisk-volume-tester-qxbbz" to be "success or failure" I1106 02:59:40.478] occurred I1106 02:59:40.478] ... skipping 161 lines ... I1106 03:04:30.315] Nov 6 03:04:30.315: INFO: PersistentVolumeClaim pvc-lztpn found but phase is Pending instead of Bound. I1106 03:04:32.389] Nov 6 03:04:32.389: INFO: PersistentVolumeClaim pvc-lztpn found but phase is Pending instead of Bound. I1106 03:04:34.463] Nov 6 03:04:34.462: INFO: PersistentVolumeClaim pvc-lztpn found but phase is Pending instead of Bound. I1106 03:04:36.536] Nov 6 03:04:36.536: INFO: PersistentVolumeClaim pvc-lztpn found but phase is Pending instead of Bound. I1106 03:04:38.640] Nov 6 03:04:38.640: INFO: PersistentVolumeClaim pvc-lztpn found but phase is Pending instead of Bound. I1106 03:04:40.714] Nov 6 03:04:40.714: INFO: PersistentVolumeClaim pvc-lztpn found but phase is Pending instead of Bound. I1106 03:04:42.715] Nov 6 03:04:42.714: INFO: Unexpected error occurred: PersistentVolumeClaims [pvc-lztpn] not all in phase Bound within 5m0s I1106 03:04:42.715] [AfterEach] [multi-az] I1106 03:04:42.715] /go/src/sigs.k8s.io/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1106 03:04:42.715] STEP: Collecting events from namespace "azuredisk-2578". I1106 03:04:42.789] STEP: Found 3 events. I1106 03:04:42.789] Nov 6 03:04:42.789: INFO: At 2019-11-06 02:59:41 +0000 UTC - event for pvc-lztpn: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "disk.csi.azure.com" or manually created by system administrator I1106 03:04:42.789] Nov 6 03:04:42.789: INFO: At 2019-11-06 02:59:41 +0000 UTC - event for pvc-lztpn: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-bpnmm_9f10eebb-0031-11ea-937c-fe0323241632 } Provisioning: External provisioner is provisioning volume for claim "azuredisk-2578/pvc-lztpn" I1106 03:04:42.790] Nov 6 03:04:42.789: INFO: At 2019-11-06 02:59:51 +0000 UTC - event for pvc-lztpn: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-bpnmm_9f10eebb-0031-11ea-937c-fe0323241632 } ProvisioningFailed: failed to provision volume with StorageClass "azuredisk-2578-disk.csi.azure.com-dynamic-sc-6r65b": rpc error: code = DeadlineExceeded desc = context deadline exceeded I1106 03:04:42.866] Nov 6 03:04:42.866: INFO: POD NODE PHASE GRACE CONDITIONS I1106 03:04:42.866] Nov 6 03:04:42.866: INFO: I1106 03:04:43.085] Nov 6 03:04:43.085: INFO: I1106 03:04:43.086] Logging node info for node k8s-agentpool-54406713-vmss000000 I1106 03:04:43.162] Nov 6 03:04:43.159: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:k8s-agentpool-54406713-vmss000000,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/k8s-agentpool-54406713-vmss000000,UID:f11c401a-3543-4cfb-af66-e320a19275bf,ResourceVersion:22520,Generation:0,CreationTimestamp:2019-11-06 01:02:48 +0000 UTC,DeletionTimestamp:<nil>,DeletionGracePeriodSeconds:nil,Labels:map[string]string{agentpool: agentpool,beta.kubernetes.io/arch: amd64,beta.kubernetes.io/instance-type: Standard_D4s_v3,beta.kubernetes.io/os: linux,failure-domain.beta.kubernetes.io/region: eastus2,failure-domain.beta.kubernetes.io/zone: eastus2-1,kubernetes.azure.com/cluster: kubetest-03920ff3-002d-11ea-be9c-02423fe68cb4,kubernetes.azure.com/role: agent,kubernetes.io/arch: amd64,kubernetes.io/hostname: k8s-agentpool-54406713-vmss000000,kubernetes.io/os: linux,kubernetes.io/role: agent,node-role.kubernetes.io/agent: ,storageprofile: managed,storagetier: Premium_LRS,topology.disk.csi.azure.com/zone: eastus2-1,},Annotations:map[string]string{csi.volume.kubernetes.io/nodeid: {"disk.csi.azure.com":"k8s-agentpool-54406713-vmss000000"},node.alpha.kubernetes.io/ttl: 0,volumes.kubernetes.io/controller-managed-attach-detach: true,},OwnerReferences:[],Finalizers:[],ClusterName:,Initializers:nil,ManagedFields:[],},Spec:NodeSpec{PodCIDR:10.244.0.0/24,DoNotUse_ExternalID:,ProviderID:azure:///subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/kubetest-03920ff3-002d-11ea-be9c-02423fe68cb4/providers/Microsoft.Compute/virtualMachineScaleSets/k8s-agentpool-54406713-vmss/virtualMachines/0,Unschedulable:false,Taints:[],ConfigSource:nil,},Status:NodeStatus{Capacity:ResourceList{attachable-volumes-csi-disk.csi.azure.com: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{31036776448 0} {<nil>} BinarySI},hugepages-1Gi: {{0 0} {<nil>} 0 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{16797044736 0} {<nil>} 16403364Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Allocatable:ResourceList{attachable-volumes-csi-disk.csi.azure.com: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{27933098757 0} {<nil>} 27933098757 DecimalSI},hugepages-1Gi: {{0 0} {<nil>} 0 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{16010612736 0} {<nil>} 15635364Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Phase:,Conditions:[{NetworkUnavailable False 2019-11-06 01:03:21 +0000 UTC 2019-11-06 01:03:21 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2019-11-06 03:03:48 +0000 UTC 2019-11-06 01:02:32 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2019-11-06 03:03:48 +0000 UTC 2019-11-06 01:02:32 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2019-11-06 03:03:48 +0000 UTC 2019-11-06 01:02:32 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2019-11-06 03:03:48 +0000 UTC 2019-11-06 01:03:06 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.248.0.4} {Hostname k8s-agentpool-54406713-vmss000000}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:314d4f6d838542d1b91629162863d266,SystemUUID:28F72AD9-C8ED-1C40-AC90-621A4747BF6F,BootID:73555e39-2e46-4dd8-a077-48bc5b4d8032,KernelVersion:4.15.0-1061-azure,OSImage:Ubuntu 16.04.6 LTS,ContainerRuntimeVersion:docker://3.0.6,KubeletVersion:v1.15.0,KubeProxyVersion:v1.15.0,OperatingSystem:linux,Architecture:amd64,},Images:[{[gcrio.azureedge.net/google_containers/hyperkube-amd64@sha256:7f66ed6bd11edd309dad15db1dc906f89035cc9d9ae705c65c98264c775b9a8f gcrio.azureedge.net/google_containers/hyperkube-amd64:v1.15.0] 593352254} {[k8sprowinternal.azurecr.io/azuredisk-csi@sha256:209b5e3501b93135a3e5715553aeb99d41dc7fab732b42161d48b00e40772a93 k8sprowinternal.azurecr.io/azuredisk-csi:e2e-9f289d4c7792de742a1ded20837778e2acb91093] 286926836} {[k8s.gcr.io/kubernetes-dashboard-amd64@sha256:0ae6b69432e78069c5ce2bcde0fe409c5c4d6f0f4d9cd50a17974fea38898747 k8s.gcr.io/kubernetes-dashboard-amd64:v1.10.1] 121711221} {[k8s.gcr.io/ip-masq-agent-amd64@sha256:269e0fb9d53fd37f7a135d6a55ea265a67279ba218aa148323f015cf70167340 k8s.gcr.io/ip-masq-agent-amd64:v2.3.0] 50144412} {[k8s.gcr.io/metrics-server-amd64@sha256:49a9f12f7067d11f42c803dbe61ed2c1299959ad85cb315b25ff7eef8e6b8892 k8s.gcr.io/metrics-server-amd64:v0.2.1] 42541759} {[mcr.microsoft.com/k8s/flexvolume/keyvault-flexvolume@sha256:4fd30d43947d4a54fc89ead7985beecfd3c9b2a93a0655a373b1608ab90bd5af mcr.microsoft.com/k8s/flexvolume/keyvault-flexvolume:v0.0.7] 22909487} {[quay.io/k8scsi/livenessprobe@sha256:8c9c8a0f330acc2e558ae6624309447d02522e76aa35af23fa19b88abf4381cb quay.io/k8scsi/livenessprobe:v1.0.2] 17415381} {[quay.io/k8scsi/csi-node-driver-registrar@sha256:13daf82fb99e951a4bff8ae5fc7c17c3a8fe7130be6400990d8f6076c32d4599 quay.io/k8scsi/csi-node-driver-registrar:v1.1.0] 15815995} {[mcr.microsoft.com/k8s/flexvolume/blobfuse-flexvolume@sha256:23d8c6033f02a1ecad05127ebdc931bb871264228661bc122704b0974e4d9fdd mcr.microsoft.com/k8s/flexvolume/blobfuse-flexvolume:1.0.8] 1159025} {[busybox@sha256:8ccbac733d19c0dd4d70b4f0c1e12245b5fa3ad24758a11035ee505c629c0796 busybox:1.29] 1154361} {[k8s.gcr.io/pause-amd64@sha256:59eec8837a4d942cc19a52b8c09ea75121acc38114a2c68b98983ce9356b8610 k8s.gcr.io/pause-amd64:3.1] 742472}],VolumesInUse:[kubernetes.io/csi/disk.csi.azure.com^/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/kubetest-03920ff3-002d-11ea-be9c-02423fe68cb4/providers/Microsoft.Compute/disks/pvc-87d218a7-da86-4695-851c-449e48182a17],VolumesAttached:[],Config:nil,},} I1106 03:04:43.163] Nov 6 03:04:43.159: INFO: ... skipping 175 lines ... I1106 03:05:03.552] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:33 I1106 03:05:03.552] [multi-az] I1106 03:05:03.552] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:40 I1106 03:05:03.552] should delete PV with reclaimPolicy "Delete" [It] I1106 03:05:03.553] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:221 I1106 03:05:03.553] I1106 03:05:03.553] Unexpected error: I1106 03:05:03.553] <*errors.errorString | 0xc0006f3920>: { I1106 03:05:03.553] s: "PersistentVolumeClaims [pvc-lztpn] not all in phase Bound within 5m0s", I1106 03:05:03.553] } I1106 03:05:03.553] PersistentVolumeClaims [pvc-lztpn] not all in phase Bound within 5m0s I1106 03:05:03.554] occurred I1106 03:05:03.554] ... skipping 161 lines ... I1106 03:09:53.446] Nov 6 03:09:53.446: INFO: PersistentVolumeClaim pvc-zn6cs found but phase is Pending instead of Bound. I1106 03:09:55.526] Nov 6 03:09:55.526: INFO: PersistentVolumeClaim pvc-zn6cs found but phase is Pending instead of Bound. I1106 03:09:57.611] Nov 6 03:09:57.610: INFO: PersistentVolumeClaim pvc-zn6cs found but phase is Pending instead of Bound. I1106 03:09:59.691] Nov 6 03:09:59.691: INFO: PersistentVolumeClaim pvc-zn6cs found but phase is Pending instead of Bound. I1106 03:10:01.770] Nov 6 03:10:01.770: INFO: PersistentVolumeClaim pvc-zn6cs found but phase is Pending instead of Bound. I1106 03:10:03.850] Nov 6 03:10:03.850: INFO: PersistentVolumeClaim pvc-zn6cs found but phase is Pending instead of Bound. I1106 03:10:05.850] Nov 6 03:10:05.850: INFO: Unexpected error occurred: PersistentVolumeClaims [pvc-zn6cs] not all in phase Bound within 5m0s I1106 03:10:05.850] [AfterEach] [single-az] I1106 03:10:05.851] /go/src/sigs.k8s.io/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1106 03:10:05.851] STEP: Collecting events from namespace "azuredisk-2558". I1106 03:10:05.930] STEP: Found 3 events. I1106 03:10:05.931] Nov 6 03:10:05.930: INFO: At 2019-11-06 03:05:04 +0000 UTC - event for pvc-zn6cs: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "disk.csi.azure.com" or manually created by system administrator I1106 03:10:05.931] Nov 6 03:10:05.930: INFO: At 2019-11-06 03:05:04 +0000 UTC - event for pvc-zn6cs: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-bpnmm_9f10eebb-0031-11ea-937c-fe0323241632 } Provisioning: External provisioner is provisioning volume for claim "azuredisk-2558/pvc-zn6cs" I1106 03:10:05.931] Nov 6 03:10:05.930: INFO: At 2019-11-06 03:05:14 +0000 UTC - event for pvc-zn6cs: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-bpnmm_9f10eebb-0031-11ea-937c-fe0323241632 } ProvisioningFailed: failed to provision volume with StorageClass "azuredisk-2558-disk.csi.azure.com-dynamic-sc-g8g9s": rpc error: code = DeadlineExceeded desc = context deadline exceeded I1106 03:10:06.012] Nov 6 03:10:06.012: INFO: POD NODE PHASE GRACE CONDITIONS I1106 03:10:06.012] Nov 6 03:10:06.012: INFO: I1106 03:10:06.258] Nov 6 03:10:06.258: INFO: I1106 03:10:06.258] Logging node info for node k8s-agentpool-54406713-vmss000000 I1106 03:10:06.340] Nov 6 03:10:06.337: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:k8s-agentpool-54406713-vmss000000,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/k8s-agentpool-54406713-vmss000000,UID:f11c401a-3543-4cfb-af66-e320a19275bf,ResourceVersion:23591,Generation:0,CreationTimestamp:2019-11-06 01:02:48 +0000 UTC,DeletionTimestamp:<nil>,DeletionGracePeriodSeconds:nil,Labels:map[string]string{agentpool: agentpool,beta.kubernetes.io/arch: amd64,beta.kubernetes.io/instance-type: Standard_D4s_v3,beta.kubernetes.io/os: linux,failure-domain.beta.kubernetes.io/region: eastus2,failure-domain.beta.kubernetes.io/zone: eastus2-1,kubernetes.azure.com/cluster: kubetest-03920ff3-002d-11ea-be9c-02423fe68cb4,kubernetes.azure.com/role: agent,kubernetes.io/arch: amd64,kubernetes.io/hostname: k8s-agentpool-54406713-vmss000000,kubernetes.io/os: linux,kubernetes.io/role: agent,node-role.kubernetes.io/agent: ,storageprofile: managed,storagetier: Premium_LRS,topology.disk.csi.azure.com/zone: eastus2-1,},Annotations:map[string]string{csi.volume.kubernetes.io/nodeid: {"disk.csi.azure.com":"k8s-agentpool-54406713-vmss000000"},node.alpha.kubernetes.io/ttl: 0,volumes.kubernetes.io/controller-managed-attach-detach: true,},OwnerReferences:[],Finalizers:[],ClusterName:,Initializers:nil,ManagedFields:[],},Spec:NodeSpec{PodCIDR:10.244.0.0/24,DoNotUse_ExternalID:,ProviderID:azure:///subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/kubetest-03920ff3-002d-11ea-be9c-02423fe68cb4/providers/Microsoft.Compute/virtualMachineScaleSets/k8s-agentpool-54406713-vmss/virtualMachines/0,Unschedulable:false,Taints:[],ConfigSource:nil,},Status:NodeStatus{Capacity:ResourceList{attachable-volumes-csi-disk.csi.azure.com: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{31036776448 0} {<nil>} BinarySI},hugepages-1Gi: {{0 0} {<nil>} 0 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{16797044736 0} {<nil>} 16403364Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Allocatable:ResourceList{attachable-volumes-csi-disk.csi.azure.com: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{27933098757 0} {<nil>} 27933098757 DecimalSI},hugepages-1Gi: {{0 0} {<nil>} 0 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{16010612736 0} {<nil>} 15635364Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Phase:,Conditions:[{NetworkUnavailable False 2019-11-06 01:03:21 +0000 UTC 2019-11-06 01:03:21 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2019-11-06 03:09:49 +0000 UTC 2019-11-06 01:02:32 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2019-11-06 03:09:49 +0000 UTC 2019-11-06 01:02:32 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2019-11-06 03:09:49 +0000 UTC 2019-11-06 01:02:32 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2019-11-06 03:09:49 +0000 UTC 2019-11-06 01:03:06 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.248.0.4} {Hostname k8s-agentpool-54406713-vmss000000}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:314d4f6d838542d1b91629162863d266,SystemUUID:28F72AD9-C8ED-1C40-AC90-621A4747BF6F,BootID:73555e39-2e46-4dd8-a077-48bc5b4d8032,KernelVersion:4.15.0-1061-azure,OSImage:Ubuntu 16.04.6 LTS,ContainerRuntimeVersion:docker://3.0.6,KubeletVersion:v1.15.0,KubeProxyVersion:v1.15.0,OperatingSystem:linux,Architecture:amd64,},Images:[{[gcrio.azureedge.net/google_containers/hyperkube-amd64@sha256:7f66ed6bd11edd309dad15db1dc906f89035cc9d9ae705c65c98264c775b9a8f gcrio.azureedge.net/google_containers/hyperkube-amd64:v1.15.0] 593352254} {[k8sprowinternal.azurecr.io/azuredisk-csi@sha256:209b5e3501b93135a3e5715553aeb99d41dc7fab732b42161d48b00e40772a93 k8sprowinternal.azurecr.io/azuredisk-csi:e2e-9f289d4c7792de742a1ded20837778e2acb91093] 286926836} {[k8s.gcr.io/kubernetes-dashboard-amd64@sha256:0ae6b69432e78069c5ce2bcde0fe409c5c4d6f0f4d9cd50a17974fea38898747 k8s.gcr.io/kubernetes-dashboard-amd64:v1.10.1] 121711221} {[k8s.gcr.io/ip-masq-agent-amd64@sha256:269e0fb9d53fd37f7a135d6a55ea265a67279ba218aa148323f015cf70167340 k8s.gcr.io/ip-masq-agent-amd64:v2.3.0] 50144412} {[k8s.gcr.io/metrics-server-amd64@sha256:49a9f12f7067d11f42c803dbe61ed2c1299959ad85cb315b25ff7eef8e6b8892 k8s.gcr.io/metrics-server-amd64:v0.2.1] 42541759} {[mcr.microsoft.com/k8s/flexvolume/keyvault-flexvolume@sha256:4fd30d43947d4a54fc89ead7985beecfd3c9b2a93a0655a373b1608ab90bd5af mcr.microsoft.com/k8s/flexvolume/keyvault-flexvolume:v0.0.7] 22909487} {[quay.io/k8scsi/livenessprobe@sha256:8c9c8a0f330acc2e558ae6624309447d02522e76aa35af23fa19b88abf4381cb quay.io/k8scsi/livenessprobe:v1.0.2] 17415381} {[quay.io/k8scsi/csi-node-driver-registrar@sha256:13daf82fb99e951a4bff8ae5fc7c17c3a8fe7130be6400990d8f6076c32d4599 quay.io/k8scsi/csi-node-driver-registrar:v1.1.0] 15815995} {[mcr.microsoft.com/k8s/flexvolume/blobfuse-flexvolume@sha256:23d8c6033f02a1ecad05127ebdc931bb871264228661bc122704b0974e4d9fdd mcr.microsoft.com/k8s/flexvolume/blobfuse-flexvolume:1.0.8] 1159025} {[busybox@sha256:8ccbac733d19c0dd4d70b4f0c1e12245b5fa3ad24758a11035ee505c629c0796 busybox:1.29] 1154361} {[k8s.gcr.io/pause-amd64@sha256:59eec8837a4d942cc19a52b8c09ea75121acc38114a2c68b98983ce9356b8610 k8s.gcr.io/pause-amd64:3.1] 742472}],VolumesInUse:[kubernetes.io/csi/disk.csi.azure.com^/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/kubetest-03920ff3-002d-11ea-be9c-02423fe68cb4/providers/Microsoft.Compute/disks/pvc-87d218a7-da86-4695-851c-449e48182a17],VolumesAttached:[],Config:nil,},} I1106 03:10:06.340] Nov 6 03:10:06.337: INFO: ... skipping 175 lines ... I1106 03:10:27.146] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:33 I1106 03:10:27.146] [single-az] I1106 03:10:27.146] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:36 I1106 03:10:27.146] [env] should retain PV with reclaimPolicy "Retain" [It] I1106 03:10:27.147] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:240 I1106 03:10:27.147] I1106 03:10:27.147] Unexpected error: I1106 03:10:27.147] <*errors.errorString | 0xc00092a420>: { I1106 03:10:27.147] s: "PersistentVolumeClaims [pvc-zn6cs] not all in phase Bound within 5m0s", I1106 03:10:27.147] } I1106 03:10:27.147] PersistentVolumeClaims [pvc-zn6cs] not all in phase Bound within 5m0s I1106 03:10:27.147] occurred I1106 03:10:27.148] ... skipping 233 lines ... I1106 03:16:17.897] Nov 6 03:16:17.897: INFO: PersistentVolumeClaim pvc-zgd5g found but phase is Pending instead of Bound. I1106 03:16:19.971] Nov 6 03:16:19.971: INFO: PersistentVolumeClaim pvc-zgd5g found but phase is Pending instead of Bound. I1106 03:16:22.045] Nov 6 03:16:22.045: INFO: PersistentVolumeClaim pvc-zgd5g found but phase is Pending instead of Bound. I1106 03:16:24.119] Nov 6 03:16:24.118: INFO: PersistentVolumeClaim pvc-zgd5g found but phase is Pending instead of Bound. I1106 03:16:26.193] Nov 6 03:16:26.193: INFO: PersistentVolumeClaim pvc-zgd5g found but phase is Pending instead of Bound. I1106 03:16:28.268] Nov 6 03:16:28.268: INFO: PersistentVolumeClaim pvc-zgd5g found but phase is Pending instead of Bound. I1106 03:16:30.268] Nov 6 03:16:30.268: INFO: Unexpected error occurred: PersistentVolumeClaims [pvc-zgd5g] not all in phase Bound within 5m0s I1106 03:16:30.269] [AfterEach] [single-az] I1106 03:16:30.269] /go/src/sigs.k8s.io/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1106 03:16:30.269] STEP: Collecting events from namespace "azuredisk-325". I1106 03:16:30.342] STEP: Found 3 events. I1106 03:16:30.343] Nov 6 03:16:30.342: INFO: At 2019-11-06 03:11:28 +0000 UTC - event for pvc-zgd5g: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "disk.csi.azure.com" or manually created by system administrator I1106 03:16:30.343] Nov 6 03:16:30.342: INFO: At 2019-11-06 03:11:28 +0000 UTC - event for pvc-zgd5g: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-bpnmm_9f10eebb-0031-11ea-937c-fe0323241632 } Provisioning: External provisioner is provisioning volume for claim "azuredisk-325/pvc-zgd5g" I1106 03:16:30.343] Nov 6 03:16:30.342: INFO: At 2019-11-06 03:11:38 +0000 UTC - event for pvc-zgd5g: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-bpnmm_9f10eebb-0031-11ea-937c-fe0323241632 } ProvisioningFailed: failed to provision volume with StorageClass "azuredisk-325-disk.csi.azure.com-dynamic-sc-8b7ql": rpc error: code = DeadlineExceeded desc = context deadline exceeded I1106 03:16:30.415] Nov 6 03:16:30.415: INFO: POD NODE PHASE GRACE CONDITIONS I1106 03:16:30.415] Nov 6 03:16:30.415: INFO: I1106 03:16:30.638] Nov 6 03:16:30.638: INFO: I1106 03:16:30.639] Logging node info for node k8s-agentpool-54406713-vmss000000 I1106 03:16:30.715] Nov 6 03:16:30.711: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:k8s-agentpool-54406713-vmss000000,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/k8s-agentpool-54406713-vmss000000,UID:f11c401a-3543-4cfb-af66-e320a19275bf,ResourceVersion:24697,Generation:0,CreationTimestamp:2019-11-06 01:02:48 +0000 UTC,DeletionTimestamp:<nil>,DeletionGracePeriodSeconds:nil,Labels:map[string]string{agentpool: agentpool,beta.kubernetes.io/arch: amd64,beta.kubernetes.io/instance-type: Standard_D4s_v3,beta.kubernetes.io/os: linux,failure-domain.beta.kubernetes.io/region: eastus2,failure-domain.beta.kubernetes.io/zone: eastus2-1,kubernetes.azure.com/cluster: kubetest-03920ff3-002d-11ea-be9c-02423fe68cb4,kubernetes.azure.com/role: agent,kubernetes.io/arch: amd64,kubernetes.io/hostname: k8s-agentpool-54406713-vmss000000,kubernetes.io/os: linux,kubernetes.io/role: agent,node-role.kubernetes.io/agent: ,storageprofile: managed,storagetier: Premium_LRS,topology.disk.csi.azure.com/zone: eastus2-1,},Annotations:map[string]string{csi.volume.kubernetes.io/nodeid: {"disk.csi.azure.com":"k8s-agentpool-54406713-vmss000000"},node.alpha.kubernetes.io/ttl: 0,volumes.kubernetes.io/controller-managed-attach-detach: true,},OwnerReferences:[],Finalizers:[],ClusterName:,Initializers:nil,ManagedFields:[],},Spec:NodeSpec{PodCIDR:10.244.0.0/24,DoNotUse_ExternalID:,ProviderID:azure:///subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/kubetest-03920ff3-002d-11ea-be9c-02423fe68cb4/providers/Microsoft.Compute/virtualMachineScaleSets/k8s-agentpool-54406713-vmss/virtualMachines/0,Unschedulable:false,Taints:[],ConfigSource:nil,},Status:NodeStatus{Capacity:ResourceList{attachable-volumes-csi-disk.csi.azure.com: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{31036776448 0} {<nil>} BinarySI},hugepages-1Gi: {{0 0} {<nil>} 0 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{16797044736 0} {<nil>} 16403364Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Allocatable:ResourceList{attachable-volumes-csi-disk.csi.azure.com: {{8 0} {<nil>} 8 DecimalSI},cpu: {{4 0} {<nil>} 4 DecimalSI},ephemeral-storage: {{27933098757 0} {<nil>} 27933098757 DecimalSI},hugepages-1Gi: {{0 0} {<nil>} 0 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{16010612736 0} {<nil>} 15635364Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Phase:,Conditions:[{NetworkUnavailable False 2019-11-06 01:03:21 +0000 UTC 2019-11-06 01:03:21 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2019-11-06 03:15:50 +0000 UTC 2019-11-06 01:02:32 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2019-11-06 03:15:50 +0000 UTC 2019-11-06 01:02:32 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2019-11-06 03:15:50 +0000 UTC 2019-11-06 01:02:32 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2019-11-06 03:15:50 +0000 UTC 2019-11-06 01:03:06 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.248.0.4} {Hostname k8s-agentpool-54406713-vmss000000}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:314d4f6d838542d1b91629162863d266,SystemUUID:28F72AD9-C8ED-1C40-AC90-621A4747BF6F,BootID:73555e39-2e46-4dd8-a077-48bc5b4d8032,KernelVersion:4.15.0-1061-azure,OSImage:Ubuntu 16.04.6 LTS,ContainerRuntimeVersion:docker://3.0.6,KubeletVersion:v1.15.0,KubeProxyVersion:v1.15.0,OperatingSystem:linux,Architecture:amd64,},Images:[{[gcrio.azureedge.net/google_containers/hyperkube-amd64@sha256:7f66ed6bd11edd309dad15db1dc906f89035cc9d9ae705c65c98264c775b9a8f gcrio.azureedge.net/google_containers/hyperkube-amd64:v1.15.0] 593352254} {[k8sprowinternal.azurecr.io/azuredisk-csi@sha256:209b5e3501b93135a3e5715553aeb99d41dc7fab732b42161d48b00e40772a93 k8sprowinternal.azurecr.io/azuredisk-csi:e2e-9f289d4c7792de742a1ded20837778e2acb91093] 286926836} {[k8s.gcr.io/kubernetes-dashboard-amd64@sha256:0ae6b69432e78069c5ce2bcde0fe409c5c4d6f0f4d9cd50a17974fea38898747 k8s.gcr.io/kubernetes-dashboard-amd64:v1.10.1] 121711221} {[k8s.gcr.io/ip-masq-agent-amd64@sha256:269e0fb9d53fd37f7a135d6a55ea265a67279ba218aa148323f015cf70167340 k8s.gcr.io/ip-masq-agent-amd64:v2.3.0] 50144412} {[k8s.gcr.io/metrics-server-amd64@sha256:49a9f12f7067d11f42c803dbe61ed2c1299959ad85cb315b25ff7eef8e6b8892 k8s.gcr.io/metrics-server-amd64:v0.2.1] 42541759} {[mcr.microsoft.com/k8s/flexvolume/keyvault-flexvolume@sha256:4fd30d43947d4a54fc89ead7985beecfd3c9b2a93a0655a373b1608ab90bd5af mcr.microsoft.com/k8s/flexvolume/keyvault-flexvolume:v0.0.7] 22909487} {[quay.io/k8scsi/livenessprobe@sha256:8c9c8a0f330acc2e558ae6624309447d02522e76aa35af23fa19b88abf4381cb quay.io/k8scsi/livenessprobe:v1.0.2] 17415381} {[quay.io/k8scsi/csi-node-driver-registrar@sha256:13daf82fb99e951a4bff8ae5fc7c17c3a8fe7130be6400990d8f6076c32d4599 quay.io/k8scsi/csi-node-driver-registrar:v1.1.0] 15815995} {[mcr.microsoft.com/k8s/flexvolume/blobfuse-flexvolume@sha256:23d8c6033f02a1ecad05127ebdc931bb871264228661bc122704b0974e4d9fdd mcr.microsoft.com/k8s/flexvolume/blobfuse-flexvolume:1.0.8] 1159025} {[busybox@sha256:8ccbac733d19c0dd4d70b4f0c1e12245b5fa3ad24758a11035ee505c629c0796 busybox:1.29] 1154361} {[k8s.gcr.io/pause-amd64@sha256:59eec8837a4d942cc19a52b8c09ea75121acc38114a2c68b98983ce9356b8610 k8s.gcr.io/pause-amd64:3.1] 742472}],VolumesInUse:[kubernetes.io/csi/disk.csi.azure.com^/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/kubetest-03920ff3-002d-11ea-be9c-02423fe68cb4/providers/Microsoft.Compute/disks/pvc-87d218a7-da86-4695-851c-449e48182a17],VolumesAttached:[],Config:nil,},} I1106 03:16:30.715] Nov 6 03:16:30.712: INFO: ... skipping 175 lines ... I1106 03:16:51.112] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:33 I1106 03:16:51.112] [single-az] I1106 03:16:51.112] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:36 I1106 03:16:51.112] should create a volume on demand [It] I1106 03:16:51.112] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:78 I1106 03:16:51.113] I1106 03:16:51.113] Unexpected error: I1106 03:16:51.113] <*errors.errorString | 0xc0007560a0>: { I1106 03:16:51.113] s: "PersistentVolumeClaims [pvc-zgd5g] not all in phase Bound within 5m0s", I1106 03:16:51.113] } I1106 03:16:51.113] PersistentVolumeClaims [pvc-zgd5g] not all in phase Bound within 5m0s I1106 03:16:51.114] occurred I1106 03:16:51.114] ... skipping 6 lines ... I1106 03:16:58.650] make[1]: Leaving directory '/go/src/sigs.k8s.io/azuredisk-csi-driver' I1106 03:16:58.650] 2019/11/06 03:16:58 Azure Disk CSI Driver uninstalled I1106 03:16:58.650] I1106 03:16:58.651] I1106 03:16:58.651] Summarizing 12 Failures: I1106 03:16:58.651] I1106 03:16:58.651] [Fail] [azuredisk-csi-e2e] Dynamic Provisioning [multi-az] [It] should create a volume on demand and mount it as readOnly in a pod I1106 03:16:58.651] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:553 I1106 03:16:58.651] I1106 03:16:58.651] [Fail] [azuredisk-csi-e2e] Dynamic Provisioning [multi-az] [It] should create a deployment object, write and read to it, delete the pod and write and read to it again I1106 03:16:58.652] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:434 I1106 03:16:58.652] I1106 03:16:58.652] [Fail] [azuredisk-csi-e2e] Dynamic Provisioning [multi-az] [It] should create a volume on demand I1106 03:16:58.652] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:529 I1106 03:16:58.652] I1106 03:16:58.652] [Fail] [azuredisk-csi-e2e] Dynamic Provisioning [single-az] [It] should create multiple PV objects, bind to PVCs and attach all to different pods on the same node I1106 03:16:58.652] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:278 I1106 03:16:58.652] I1106 03:16:58.652] [Panic!] [azuredisk-csi-e2e] [single-az] Pre-Provisioned [It] [env] should use a pre-provisioned volume and retain PV with reclaimPolicy "Retain" I1106 03:16:58.653] /usr/local/go/src/runtime/panic.go:82 I1106 03:16:58.653] I1106 03:16:58.653] [Fail] [azuredisk-csi-e2e] Dynamic Provisioning [single-az] [It] should create a volume on demand and mount it as readOnly in a pod I1106 03:16:58.653] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:278 I1106 03:16:58.653] I1106 03:16:58.653] [Fail] [azuredisk-csi-e2e] Dynamic Provisioning [single-az] [It] should delete PV with reclaimPolicy "Delete" I1106 03:16:58.653] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:278 I1106 03:16:58.653] I1106 03:16:58.653] [Fail] [azuredisk-csi-e2e] [single-az] Pre-Provisioned [It] [env] should use a pre-provisioned volume and mount it as readOnly in a pod I1106 03:16:58.654] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:553 I1106 03:16:58.654] I1106 03:16:58.654] [Fail] [azuredisk-csi-e2e] Dynamic Provisioning [multi-az] [It] should create a raw block volume on demand I1106 03:16:58.654] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:529 I1106 03:16:58.654] I1106 03:16:58.654] [Fail] [azuredisk-csi-e2e] Dynamic Provisioning [multi-az] [It] should delete PV with reclaimPolicy "Delete" I1106 03:16:58.655] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:278 I1106 03:16:58.655] I1106 03:16:58.655] [Fail] [azuredisk-csi-e2e] Dynamic Provisioning [single-az] [It] [env] should retain PV with reclaimPolicy "Retain" I1106 03:16:58.655] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:278 I1106 03:16:58.655] I1106 03:16:58.655] [Fail] [azuredisk-csi-e2e] Dynamic Provisioning [single-az] [It] should create a volume on demand I1106 03:16:58.655] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:278 I1106 03:16:58.656] I1106 03:16:58.656] Ran 16 of 16 Specs in 7924.898 seconds I1106 03:16:58.656] FAIL! -- 4 Passed | 12 Failed | 0 Pending | 0 Skipped I1106 03:16:58.656] --- FAIL: TestE2E (7924.90s) I1106 03:16:58.656] FAIL I1106 03:16:58.656] FAIL sigs.k8s.io/azuredisk-csi-driver/test/e2e 7924.949s W1106 03:16:58.914] make: *** [Makefile:59: e2e-test] Error 1 W1106 03:16:58.914] 2019/11/06 03:16:58 process.go:155: Step 'make e2e-test' finished in 2h12m55.199131829s W1106 03:16:58.914] 2019/11/06 03:16:58 azure.go:912: Skippng DumpClusterLogs due to CCM not being enabled. W1106 03:16:58.914] 2019/11/06 03:16:58 azure.go:906: Deleting resource group: kubetest-03920ff3-002d-11ea-be9c-02423fe68cb4. W1106 03:27:09.103] 2019/11/06 03:27:09 process.go:96: Saved XML output to /workspace/_artifacts/junit_runner.xml. W1106 03:27:09.103] 2019/11/06 03:27:09 process.go:153: Running: bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}" W1106 03:27:09.755] 2019/11/06 03:27:09 process.go:155: Step 'bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}"' finished in 651.288681ms W1106 03:27:09.755] 2019/11/06 03:27:09 main.go:319: Something went wrong: encountered 1 errors: [error during make e2e-test: exit status 2] W1106 03:27:09.757] Traceback (most recent call last): W1106 03:27:09.757] File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 778, in <module> W1106 03:27:09.758] main(parse_args()) W1106 03:27:09.758] File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 626, in main W1106 03:27:09.758] mode.start(runner_args) W1106 03:27:09.758] File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 262, in start W1106 03:27:09.758] check_env(env, self.command, *args) W1106 03:27:09.758] File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 111, in check_env W1106 03:27:09.758] subprocess.check_call(cmd, env=env) W1106 03:27:09.759] File "/usr/lib/python2.7/subprocess.py", line 190, in check_call W1106 03:27:09.759] raise CalledProcessError(retcode, cmd) W1106 03:27:09.759] subprocess.CalledProcessError: Command '('kubetest', '--dump=/workspace/_artifacts', '--gcp-service-account=/etc/service-account/service-account.json', '--build=bazel', '--up', '--down', '--test', '--deployment=acsengine', '--provider=skeleton', '--cluster=bootstrap-e2e', '--gcp-network=bootstrap-e2e', '--ginkgo-parallel=1', '--acsengine-agentpoolcount=2', '--acsengine-admin-username=azureuser', '--acsengine-creds=/etc/azure-cred/credentials', '--acsengine-orchestratorRelease=1.16', '--acsengine-mastervmsize=Standard_DS2_v2', '--acsengine-agentvmsize=Standard_D4s_v3', '--acsengine-location=eastus2', '--acsengine-public-key=/etc/azure-ssh/azure-ssh-pub', '--acsengine-template-url=https://raw.githubusercontent.com/kubernetes-sigs/cloud-provider-azure/da4b9f5e9696ab00a5b1ac08606218f9f352d324/tests/k8s-azure/manifest/linux-vmss-multi-zones.json', '--acsengine-download-url=https://github.com/Azure/aks-engine/releases/download/v0.39.1/aks-engine-v0.39.1-linux-amd64.tar.gz', '--test-azure-disk-csi-driver=True', '--test_args=--ginkgo.focus="\\[multi\\-az\\]"', '--timeout=420m')' returned non-zero exit status 1 E1106 03:27:09.764] Command failed I1106 03:27:09.764] process 684 exited with code 1 after 174.0m E1106 03:27:09.765] FAIL: chewong-pull-azuredisk-csi-driver-e2e-multi-az I1106 03:27:09.765] Call: gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json W1106 03:27:10.357] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com] I1106 03:27:10.392] process 14189 exited with code 0 after 0.0m I1106 03:27:10.392] Call: gcloud config get-value account I1106 03:27:10.650] process 14201 exited with code 0 after 0.0m I1106 03:27:10.650] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com I1106 03:27:10.650] Upload result and artifacts... I1106 03:27:10.651] Gubernator results at https://gubernator.k8s.io/build/kubernetes-upstream/pr-logs/pull/sigs.k8s.io_azuredisk-csi-driver/180/chewong-pull-azuredisk-csi-driver-e2e-multi-az/1191875772084654080 I1106 03:27:10.651] Call: gsutil ls gs://kubernetes-upstream/pr-logs/pull/sigs.k8s.io_azuredisk-csi-driver/180/chewong-pull-azuredisk-csi-driver-e2e-multi-az/1191875772084654080/artifacts W1106 03:27:11.618] CommandException: One or more URLs matched no objects. E1106 03:27:11.696] Command failed I1106 03:27:11.696] process 14213 exited with code 1 after 0.0m W1106 03:27:11.696] Remote dir gs://kubernetes-upstream/pr-logs/pull/sigs.k8s.io_azuredisk-csi-driver/180/chewong-pull-azuredisk-csi-driver-e2e-multi-az/1191875772084654080/artifacts not exist yet I1106 03:27:11.697] Call: gsutil -m -q -o GSUtil:use_magicfile=True cp -r -c -z log,txt,xml /workspace/_artifacts gs://kubernetes-upstream/pr-logs/pull/sigs.k8s.io_azuredisk-csi-driver/180/chewong-pull-azuredisk-csi-driver-e2e-multi-az/1191875772084654080/artifacts I1106 03:27:13.202] process 14357 exited with code 0 after 0.0m I1106 03:27:13.203] Call: git rev-parse HEAD I1106 03:27:13.206] process 14886 exited with code 0 after 0.0m ... skipping 21 lines ...