sigs.k8s.io/azuredisk-csi-driver PR #180 chewong-pull-azuredisk-csi-driver-e2e-multi-az #1191852367847362560
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 306 lines ... I1105 23:29:36.592] pod/tiller-deploy-54c96cb5df-wlzbj condition met I1105 23:29:36.594] helm version I1105 23:29:36.643] Client: &version.Version{SemVer:"v2.11.0", GitCommit:"2e55dbe1fdb5fdb96b75ff144a339489417b146b", GitTreeState:"clean"} I1105 23:29:37.669] Server: &version.Version{SemVer:"v2.11.0", GitCommit:"2e55dbe1fdb5fdb96b75ff144a339489417b146b", GitTreeState:"clean"} I1105 23:29:37.671] # Only build and push the image if it does not exist in the registry I1105 23:29:37.672] docker pull k8sprowinternal.azurecr.io/azuredisk-csi:e2e-9f289d4c7792de742a1ded20837778e2acb91093 || make azuredisk-container push I1105 23:29:37.881] Error response from daemon: manifest for k8sprowinternal.azurecr.io/azuredisk-csi:e2e-9f289d4c7792de742a1ded20837778e2acb91093 not found: manifest unknown: manifest unknown I1105 23:29:37.886] make[2]: Entering directory '/go/src/sigs.k8s.io/azuredisk-csi-driver' I1105 23:29:37.892] if [ ! -d ./vendor ]; then dep ensure -vendor-only; fi I1105 23:29:37.893] CGO_ENABLED=0 GOOS=linux go build -a -ldflags "-X sigs.k8s.io/azuredisk-csi-driver/pkg/azuredisk.driverVersion=e2e-9f289d4c7792de742a1ded20837778e2acb91093 -X sigs.k8s.io/azuredisk-csi-driver/pkg/azuredisk.gitCommit=9f289d4c7792de742a1ded20837778e2acb91093 -X sigs.k8s.io/azuredisk-csi-driver/pkg/azuredisk.buildDate=2019-11-05T23:29:37Z -X sigs.k8s.io/azuredisk-csi-driver/pkg/azuredisk.DriverName=disk.csi.azure.com -X sigs.k8s.io/azuredisk-csi-driver/pkg/azuredisk.topologyKey=topology.disk.csi.azure.com/zone -extldflags "-static"" -o _output/azurediskplugin ./pkg/azurediskplugin I1105 23:30:13.197] docker build --no-cache -t k8sprowinternal.azurecr.io/azuredisk-csi:e2e-9f289d4c7792de742a1ded20837778e2acb91093 -f ./pkg/azurediskplugin/Dockerfile . I1105 23:30:15.229] Sending build context to Docker daemon 214.4MB I1105 23:30:15.259] Step 1/6 : FROM aksrepos.azurecr.io/fundamental/base-ubuntu:v0.0.5 ... skipping 351 lines ... I1105 23:36:44.824] Nov 5 23:36:44.824: INFO: PersistentVolumeClaim pvc-4v87q found but phase is Pending instead of Bound. I1105 23:36:46.911] Nov 5 23:36:46.911: INFO: PersistentVolumeClaim pvc-4v87q found but phase is Pending instead of Bound. I1105 23:36:48.993] Nov 5 23:36:48.993: INFO: PersistentVolumeClaim pvc-4v87q found but phase is Pending instead of Bound. I1105 23:36:51.070] Nov 5 23:36:51.070: INFO: PersistentVolumeClaim pvc-4v87q found but phase is Pending instead of Bound. I1105 23:36:53.149] Nov 5 23:36:53.149: INFO: PersistentVolumeClaim pvc-4v87q found but phase is Pending instead of Bound. I1105 23:36:55.227] Nov 5 23:36:55.227: INFO: PersistentVolumeClaim pvc-4v87q found but phase is Pending instead of Bound. I1105 23:36:57.228] Nov 5 23:36:57.227: INFO: Unexpected error occurred: PersistentVolumeClaims [pvc-4v87q] not all in phase Bound within 5m0s I1105 23:36:57.228] [AfterEach] [single-az] I1105 23:36:57.228] /go/src/sigs.k8s.io/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1105 23:36:57.228] STEP: Collecting events from namespace "azuredisk-6016". I1105 23:36:57.305] STEP: Found 3 events. I1105 23:36:57.305] Nov 5 23:36:57.305: INFO: At 2019-11-05 23:31:55 +0000 UTC - event for pvc-4v87q: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "disk.csi.azure.com" or manually created by system administrator I1105 23:36:57.306] Nov 5 23:36:57.305: INFO: At 2019-11-05 23:31:55 +0000 UTC - event for pvc-4v87q: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-k2p5m_71d5eefc-0024-11ea-a712-66d7d8b096eb } Provisioning: External provisioner is provisioning volume for claim "azuredisk-6016/pvc-4v87q" I1105 23:36:57.306] Nov 5 23:36:57.305: INFO: At 2019-11-05 23:32:05 +0000 UTC - event for pvc-4v87q: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-k2p5m_71d5eefc-0024-11ea-a712-66d7d8b096eb } ProvisioningFailed: failed to provision volume with StorageClass "azuredisk-6016-disk.csi.azure.com-dynamic-sc-t8bq6": rpc error: code = DeadlineExceeded desc = context deadline exceeded I1105 23:36:57.382] Nov 5 23:36:57.382: INFO: POD NODE PHASE GRACE CONDITIONS I1105 23:36:57.382] Nov 5 23:36:57.382: INFO: I1105 23:36:57.611] Nov 5 23:36:57.611: INFO: I1105 23:36:57.611] Logging node info for node k8s-agentpool-73731178-vmss000000 I1105 23:36:57.691] Nov 5 23:36:57.688: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:k8s-agentpool-73731178-vmss000000,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/k8s-agentpool-73731178-vmss000000,UID:e9bc0b16-6756-4155-b49c-e223c0ba9499,ResourceVersion:2698,Generation:0,CreationTimestamp:2019-11-05 23:27:32 +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-07e0acb7-0020-11ea-802a-02428e4d9973,kubernetes.azure.com/role: agent,kubernetes.io/arch: amd64,kubernetes.io/hostname: k8s-agentpool-73731178-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-73731178-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-07e0acb7-0020-11ea-802a-02428e4d9973/providers/Microsoft.Compute/virtualMachineScaleSets/k8s-agentpool-73731178-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-05 23:28:18 +0000 UTC 2019-11-05 23:28:18 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2019-11-05 23:36:33 +0000 UTC 2019-11-05 23:27:30 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2019-11-05 23:36:33 +0000 UTC 2019-11-05 23:27:30 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2019-11-05 23:36:33 +0000 UTC 2019-11-05 23:27:30 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2019-11-05 23:36:33 +0000 UTC 2019-11-05 23:27:48 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.248.0.4} {Hostname k8s-agentpool-73731178-vmss000000}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:956ad861ae4a42099801f8e840b4e502,SystemUUID:439CF4B9-2B9F-B74E-9ED7-7379FD8BD0DF,BootID:bd3476e5-4fd4-4437-9b56-54fbe38a3a49,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,},} I1105 23:36:57.692] Nov 5 23:36:57.689: INFO: ... skipping 175 lines ... I1105 23:37:18.521] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:33 I1105 23:37:18.521] [single-az] I1105 23:37:18.522] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:36 I1105 23:37:18.522] should create a raw block volume on demand [It] I1105 23:37:18.522] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:101 I1105 23:37:18.522] I1105 23:37:18.522] Unexpected error: I1105 23:37:18.522] <*errors.errorString | 0xc000238480>: { I1105 23:37:18.522] s: "PersistentVolumeClaims [pvc-4v87q] not all in phase Bound within 5m0s", I1105 23:37:18.523] } I1105 23:37:18.523] PersistentVolumeClaims [pvc-4v87q] not all in phase Bound within 5m0s I1105 23:37:18.523] occurred I1105 23:37:18.524] ... skipping 161 lines ... I1105 23:42:08.286] Nov 5 23:42:08.286: INFO: PersistentVolumeClaim pvc-n72lg found but phase is Pending instead of Bound. I1105 23:42:10.370] Nov 5 23:42:10.370: INFO: PersistentVolumeClaim pvc-n72lg found but phase is Pending instead of Bound. I1105 23:42:12.454] Nov 5 23:42:12.454: INFO: PersistentVolumeClaim pvc-n72lg found but phase is Pending instead of Bound. I1105 23:42:14.539] Nov 5 23:42:14.538: INFO: PersistentVolumeClaim pvc-n72lg found but phase is Pending instead of Bound. I1105 23:42:16.624] Nov 5 23:42:16.624: INFO: PersistentVolumeClaim pvc-n72lg found but phase is Pending instead of Bound. I1105 23:42:18.708] Nov 5 23:42:18.708: INFO: PersistentVolumeClaim pvc-n72lg found but phase is Pending instead of Bound. I1105 23:42:20.709] Nov 5 23:42:20.708: INFO: Unexpected error occurred: PersistentVolumeClaims [pvc-n72lg] not all in phase Bound within 5m0s I1105 23:42:20.709] [AfterEach] [single-az] I1105 23:42:20.710] /go/src/sigs.k8s.io/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1105 23:42:20.710] STEP: Collecting events from namespace "azuredisk-8925". I1105 23:42:20.793] STEP: Found 3 events. I1105 23:42:20.794] Nov 5 23:42:20.793: INFO: At 2019-11-05 23:37:19 +0000 UTC - event for pvc-n72lg: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "disk.csi.azure.com" or manually created by system administrator I1105 23:42:20.794] Nov 5 23:42:20.793: INFO: At 2019-11-05 23:37:19 +0000 UTC - event for pvc-n72lg: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-k2p5m_71d5eefc-0024-11ea-a712-66d7d8b096eb } Provisioning: External provisioner is provisioning volume for claim "azuredisk-8925/pvc-n72lg" I1105 23:42:20.794] Nov 5 23:42:20.793: INFO: At 2019-11-05 23:37:29 +0000 UTC - event for pvc-n72lg: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-k2p5m_71d5eefc-0024-11ea-a712-66d7d8b096eb } ProvisioningFailed: failed to provision volume with StorageClass "azuredisk-8925-disk.csi.azure.com-dynamic-sc-28z88": rpc error: code = DeadlineExceeded desc = context deadline exceeded I1105 23:42:20.877] Nov 5 23:42:20.877: INFO: POD NODE PHASE GRACE CONDITIONS I1105 23:42:20.877] Nov 5 23:42:20.877: INFO: I1105 23:42:21.126] Nov 5 23:42:21.126: INFO: I1105 23:42:21.126] Logging node info for node k8s-agentpool-73731178-vmss000000 I1105 23:42:21.213] Nov 5 23:42:21.210: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:k8s-agentpool-73731178-vmss000000,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/k8s-agentpool-73731178-vmss000000,UID:e9bc0b16-6756-4155-b49c-e223c0ba9499,ResourceVersion:3600,Generation:0,CreationTimestamp:2019-11-05 23:27:32 +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-07e0acb7-0020-11ea-802a-02428e4d9973,kubernetes.azure.com/role: agent,kubernetes.io/arch: amd64,kubernetes.io/hostname: k8s-agentpool-73731178-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-73731178-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-07e0acb7-0020-11ea-802a-02428e4d9973/providers/Microsoft.Compute/virtualMachineScaleSets/k8s-agentpool-73731178-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-05 23:28:18 +0000 UTC 2019-11-05 23:28:18 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2019-11-05 23:41:34 +0000 UTC 2019-11-05 23:27:30 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2019-11-05 23:41:34 +0000 UTC 2019-11-05 23:27:30 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2019-11-05 23:41:34 +0000 UTC 2019-11-05 23:27:30 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2019-11-05 23:41:34 +0000 UTC 2019-11-05 23:27:48 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.248.0.4} {Hostname k8s-agentpool-73731178-vmss000000}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:956ad861ae4a42099801f8e840b4e502,SystemUUID:439CF4B9-2B9F-B74E-9ED7-7379FD8BD0DF,BootID:bd3476e5-4fd4-4437-9b56-54fbe38a3a49,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,},} I1105 23:42:21.214] Nov 5 23:42:21.211: INFO: ... skipping 175 lines ... I1105 23:42:42.415] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:33 I1105 23:42:42.416] [single-az] I1105 23:42:42.416] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:36 I1105 23:42:42.416] should create multiple PV objects, bind to PVCs and attach all to different pods on the same node [It] I1105 23:42:42.416] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:151 I1105 23:42:42.416] I1105 23:42:42.416] Unexpected error: I1105 23:42:42.416] <*errors.errorString | 0xc000dbc950>: { I1105 23:42:42.417] s: "PersistentVolumeClaims [pvc-n72lg] not all in phase Bound within 5m0s", I1105 23:42:42.417] } I1105 23:42:42.417] PersistentVolumeClaims [pvc-n72lg] not all in phase Bound within 5m0s I1105 23:42:42.417] occurred I1105 23:42:42.417] ... skipping 160 lines ... I1105 23:47:30.950] Nov 5 23:47:30.950: INFO: PersistentVolumeClaim pvc-25lxh found but phase is Pending instead of Bound. I1105 23:47:33.027] Nov 5 23:47:33.027: INFO: PersistentVolumeClaim pvc-25lxh found but phase is Pending instead of Bound. I1105 23:47:35.104] Nov 5 23:47:35.104: INFO: PersistentVolumeClaim pvc-25lxh found but phase is Pending instead of Bound. I1105 23:47:37.181] Nov 5 23:47:37.181: INFO: PersistentVolumeClaim pvc-25lxh found but phase is Pending instead of Bound. I1105 23:47:39.258] Nov 5 23:47:39.257: INFO: PersistentVolumeClaim pvc-25lxh found but phase is Pending instead of Bound. I1105 23:47:41.335] Nov 5 23:47:41.334: INFO: PersistentVolumeClaim pvc-25lxh found but phase is Pending instead of Bound. I1105 23:47:43.335] Nov 5 23:47:43.335: INFO: Unexpected error occurred: PersistentVolumeClaims [pvc-25lxh] not all in phase Bound within 5m0s I1105 23:47:43.335] [AfterEach] [single-az] I1105 23:47:43.336] /go/src/sigs.k8s.io/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1105 23:47:43.336] STEP: Collecting events from namespace "azuredisk-2836". I1105 23:47:43.413] STEP: Found 3 events. I1105 23:47:43.413] Nov 5 23:47:43.413: INFO: At 2019-11-05 23:42:43 +0000 UTC - event for pvc-25lxh: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "disk.csi.azure.com" or manually created by system administrator I1105 23:47:43.413] Nov 5 23:47:43.413: INFO: At 2019-11-05 23:42:43 +0000 UTC - event for pvc-25lxh: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-k2p5m_71d5eefc-0024-11ea-a712-66d7d8b096eb } Provisioning: External provisioner is provisioning volume for claim "azuredisk-2836/pvc-25lxh" I1105 23:47:43.414] Nov 5 23:47:43.413: INFO: At 2019-11-05 23:42:53 +0000 UTC - event for pvc-25lxh: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-k2p5m_71d5eefc-0024-11ea-a712-66d7d8b096eb } ProvisioningFailed: failed to provision volume with StorageClass "azuredisk-2836-disk.csi.azure.com-dynamic-sc-6rtz6": rpc error: code = DeadlineExceeded desc = context deadline exceeded I1105 23:47:43.489] Nov 5 23:47:43.489: INFO: POD NODE PHASE GRACE CONDITIONS I1105 23:47:43.490] Nov 5 23:47:43.489: INFO: I1105 23:47:43.717] Nov 5 23:47:43.717: INFO: I1105 23:47:43.717] Logging node info for node k8s-agentpool-73731178-vmss000000 I1105 23:47:43.796] Nov 5 23:47:43.793: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:k8s-agentpool-73731178-vmss000000,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/k8s-agentpool-73731178-vmss000000,UID:e9bc0b16-6756-4155-b49c-e223c0ba9499,ResourceVersion:4671,Generation:0,CreationTimestamp:2019-11-05 23:27:32 +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-07e0acb7-0020-11ea-802a-02428e4d9973,kubernetes.azure.com/role: agent,kubernetes.io/arch: amd64,kubernetes.io/hostname: k8s-agentpool-73731178-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-73731178-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-07e0acb7-0020-11ea-802a-02428e4d9973/providers/Microsoft.Compute/virtualMachineScaleSets/k8s-agentpool-73731178-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-05 23:28:18 +0000 UTC 2019-11-05 23:28:18 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2019-11-05 23:47:35 +0000 UTC 2019-11-05 23:27:30 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2019-11-05 23:47:35 +0000 UTC 2019-11-05 23:27:30 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2019-11-05 23:47:35 +0000 UTC 2019-11-05 23:27:30 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2019-11-05 23:47:35 +0000 UTC 2019-11-05 23:27:48 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.248.0.4} {Hostname k8s-agentpool-73731178-vmss000000}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:956ad861ae4a42099801f8e840b4e502,SystemUUID:439CF4B9-2B9F-B74E-9ED7-7379FD8BD0DF,BootID:bd3476e5-4fd4-4437-9b56-54fbe38a3a49,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,},} I1105 23:47:43.796] Nov 5 23:47:43.793: INFO: ... skipping 175 lines ... I1105 23:48:04.410] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:33 I1105 23:48:04.410] [single-az] I1105 23:48:04.410] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:36 I1105 23:48:04.410] should create a volume on demand and mount it as readOnly in a pod [It] I1105 23:48:04.410] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:126 I1105 23:48:04.410] I1105 23:48:04.411] Unexpected error: I1105 23:48:04.411] <*errors.errorString | 0xc00016b4b0>: { I1105 23:48:04.411] s: "PersistentVolumeClaims [pvc-25lxh] not all in phase Bound within 5m0s", I1105 23:48:04.411] } I1105 23:48:04.411] PersistentVolumeClaims [pvc-25lxh] not all in phase Bound within 5m0s I1105 23:48:04.411] occurred I1105 23:48:04.411] ... skipping 258 lines ... I1105 23:58:01.287] Nov 5 23:58:01.287: INFO: PersistentVolumeClaim pvc-7xh4b found but phase is Pending instead of Bound. I1105 23:58:03.364] Nov 5 23:58:03.364: INFO: PersistentVolumeClaim pvc-7xh4b found but phase is Pending instead of Bound. I1105 23:58:05.441] Nov 5 23:58:05.441: INFO: PersistentVolumeClaim pvc-7xh4b found but phase is Pending instead of Bound. I1105 23:58:07.518] Nov 5 23:58:07.518: INFO: PersistentVolumeClaim pvc-7xh4b found but phase is Pending instead of Bound. I1105 23:58:09.600] Nov 5 23:58:09.600: INFO: PersistentVolumeClaim pvc-7xh4b found but phase is Pending instead of Bound. I1105 23:58:11.677] Nov 5 23:58:11.677: INFO: PersistentVolumeClaim pvc-7xh4b found but phase is Pending instead of Bound. I1105 23:58:13.677] Nov 5 23:58:13.677: INFO: Unexpected error occurred: PersistentVolumeClaims [pvc-7xh4b] not all in phase Bound within 5m0s I1105 23:58:13.678] [AfterEach] [single-az] I1105 23:58:13.678] /go/src/sigs.k8s.io/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1105 23:58:13.679] STEP: Collecting events from namespace "azuredisk-180". I1105 23:58:13.755] STEP: Found 3 events. I1105 23:58:13.755] Nov 5 23:58:13.755: INFO: At 2019-11-05 23:53:12 +0000 UTC - event for pvc-7xh4b: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "disk.csi.azure.com" or manually created by system administrator I1105 23:58:13.756] Nov 5 23:58:13.755: INFO: At 2019-11-05 23:53:12 +0000 UTC - event for pvc-7xh4b: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-k2p5m_71d5eefc-0024-11ea-a712-66d7d8b096eb } Provisioning: External provisioner is provisioning volume for claim "azuredisk-180/pvc-7xh4b" I1105 23:58:13.756] Nov 5 23:58:13.755: INFO: At 2019-11-05 23:53:22 +0000 UTC - event for pvc-7xh4b: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-k2p5m_71d5eefc-0024-11ea-a712-66d7d8b096eb } ProvisioningFailed: failed to provision volume with StorageClass "azuredisk-180-disk.csi.azure.com-dynamic-sc-zqqs6": rpc error: code = DeadlineExceeded desc = context deadline exceeded I1105 23:58:13.831] Nov 5 23:58:13.831: INFO: POD NODE PHASE GRACE CONDITIONS I1105 23:58:13.832] Nov 5 23:58:13.831: INFO: I1105 23:58:14.060] Nov 5 23:58:14.060: INFO: I1105 23:58:14.060] Logging node info for node k8s-agentpool-73731178-vmss000000 I1105 23:58:14.140] Nov 5 23:58:14.136: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:k8s-agentpool-73731178-vmss000000,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/k8s-agentpool-73731178-vmss000000,UID:e9bc0b16-6756-4155-b49c-e223c0ba9499,ResourceVersion:6530,Generation:0,CreationTimestamp:2019-11-05 23:27:32 +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-07e0acb7-0020-11ea-802a-02428e4d9973,kubernetes.azure.com/role: agent,kubernetes.io/arch: amd64,kubernetes.io/hostname: k8s-agentpool-73731178-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-73731178-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-07e0acb7-0020-11ea-802a-02428e4d9973/providers/Microsoft.Compute/virtualMachineScaleSets/k8s-agentpool-73731178-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-05 23:28:18 +0000 UTC 2019-11-05 23:28:18 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2019-11-05 23:57:26 +0000 UTC 2019-11-05 23:27:30 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2019-11-05 23:57:26 +0000 UTC 2019-11-05 23:27:30 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2019-11-05 23:57:26 +0000 UTC 2019-11-05 23:27:30 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2019-11-05 23:57:26 +0000 UTC 2019-11-05 23:27:48 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.248.0.4} {Hostname k8s-agentpool-73731178-vmss000000}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:956ad861ae4a42099801f8e840b4e502,SystemUUID:439CF4B9-2B9F-B74E-9ED7-7379FD8BD0DF,BootID:bd3476e5-4fd4-4437-9b56-54fbe38a3a49,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:[],VolumesAttached:[],Config:nil,},} I1105 23:58:14.140] Nov 5 23:58:14.137: INFO: ... skipping 175 lines ... I1105 23:58:34.729] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:33 I1105 23:58:34.729] [single-az] I1105 23:58:34.729] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:36 I1105 23:58:34.729] [env] should retain PV with reclaimPolicy "Retain" [It] I1105 23:58:34.729] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:240 I1105 23:58:34.729] I1105 23:58:34.730] Unexpected error: I1105 23:58:34.730] <*errors.errorString | 0xc000b62770>: { I1105 23:58:34.730] s: "PersistentVolumeClaims [pvc-7xh4b] not all in phase Bound within 5m0s", I1105 23:58:34.730] } I1105 23:58:34.730] PersistentVolumeClaims [pvc-7xh4b] not all in phase Bound within 5m0s I1105 23:58:34.730] occurred I1105 23:58:34.731] ... skipping 161 lines ... I1106 00:03:24.754] Nov 6 00:03:24.754: INFO: PersistentVolumeClaim pvc-ssrnz found but phase is Pending instead of Bound. I1106 00:03:26.839] Nov 6 00:03:26.838: INFO: PersistentVolumeClaim pvc-ssrnz found but phase is Pending instead of Bound. I1106 00:03:28.924] Nov 6 00:03:28.924: INFO: PersistentVolumeClaim pvc-ssrnz found but phase is Pending instead of Bound. I1106 00:03:31.009] Nov 6 00:03:31.008: INFO: PersistentVolumeClaim pvc-ssrnz found but phase is Pending instead of Bound. I1106 00:03:33.094] Nov 6 00:03:33.094: INFO: PersistentVolumeClaim pvc-ssrnz found but phase is Pending instead of Bound. I1106 00:03:35.179] Nov 6 00:03:35.179: INFO: PersistentVolumeClaim pvc-ssrnz found but phase is Pending instead of Bound. I1106 00:03:37.179] Nov 6 00:03:37.179: INFO: Unexpected error occurred: PersistentVolumeClaims [pvc-ssrnz] not all in phase Bound within 5m0s I1106 00:03:37.180] [AfterEach] [single-az] I1106 00:03:37.180] /go/src/sigs.k8s.io/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1106 00:03:37.180] STEP: Collecting events from namespace "azuredisk-8464". I1106 00:03:37.266] STEP: Found 3 events. I1106 00:03:37.266] Nov 6 00:03:37.266: INFO: At 2019-11-05 23:58:35 +0000 UTC - event for pvc-ssrnz: {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 00:03:37.266] Nov 6 00:03:37.266: INFO: At 2019-11-05 23:58:35 +0000 UTC - event for pvc-ssrnz: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-k2p5m_71d5eefc-0024-11ea-a712-66d7d8b096eb } Provisioning: External provisioner is provisioning volume for claim "azuredisk-8464/pvc-ssrnz" I1106 00:03:37.267] Nov 6 00:03:37.266: INFO: At 2019-11-05 23:58:45 +0000 UTC - event for pvc-ssrnz: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-k2p5m_71d5eefc-0024-11ea-a712-66d7d8b096eb } ProvisioningFailed: failed to provision volume with StorageClass "azuredisk-8464-disk.csi.azure.com-dynamic-sc-6pxn6": rpc error: code = DeadlineExceeded desc = context deadline exceeded I1106 00:03:37.351] Nov 6 00:03:37.351: INFO: POD NODE PHASE GRACE CONDITIONS I1106 00:03:37.351] Nov 6 00:03:37.351: INFO: I1106 00:03:37.601] Nov 6 00:03:37.601: INFO: I1106 00:03:37.602] Logging node info for node k8s-agentpool-73731178-vmss000000 I1106 00:03:37.689] Nov 6 00:03:37.686: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:k8s-agentpool-73731178-vmss000000,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/k8s-agentpool-73731178-vmss000000,UID:e9bc0b16-6756-4155-b49c-e223c0ba9499,ResourceVersion:7601,Generation:0,CreationTimestamp:2019-11-05 23:27:32 +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-07e0acb7-0020-11ea-802a-02428e4d9973,kubernetes.azure.com/role: agent,kubernetes.io/arch: amd64,kubernetes.io/hostname: k8s-agentpool-73731178-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-73731178-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-07e0acb7-0020-11ea-802a-02428e4d9973/providers/Microsoft.Compute/virtualMachineScaleSets/k8s-agentpool-73731178-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-05 23:28:18 +0000 UTC 2019-11-05 23:28:18 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2019-11-06 00:03:27 +0000 UTC 2019-11-05 23:27:30 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2019-11-06 00:03:27 +0000 UTC 2019-11-05 23:27:30 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2019-11-06 00:03:27 +0000 UTC 2019-11-05 23:27:30 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2019-11-06 00:03:27 +0000 UTC 2019-11-05 23:27:48 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.248.0.4} {Hostname k8s-agentpool-73731178-vmss000000}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:956ad861ae4a42099801f8e840b4e502,SystemUUID:439CF4B9-2B9F-B74E-9ED7-7379FD8BD0DF,BootID:bd3476e5-4fd4-4437-9b56-54fbe38a3a49,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:[],VolumesAttached:[],Config:nil,},} I1106 00:03:37.689] Nov 6 00:03:37.686: INFO: ... skipping 175 lines ... I1106 00:03:58.911] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:33 I1106 00:03:58.912] [single-az] I1106 00:03:58.912] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:36 I1106 00:03:58.912] should delete PV with reclaimPolicy "Delete" [It] I1106 00:03:58.912] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:221 I1106 00:03:58.912] I1106 00:03:58.912] Unexpected error: I1106 00:03:58.912] <*errors.errorString | 0xc000997520>: { I1106 00:03:58.913] s: "PersistentVolumeClaims [pvc-ssrnz] not all in phase Bound within 5m0s", I1106 00:03:58.913] } I1106 00:03:58.913] PersistentVolumeClaims [pvc-ssrnz] not all in phase Bound within 5m0s I1106 00:03:58.913] occurred I1106 00:03:58.913] ... skipping 15 lines ... I1106 00:03:59.528] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:101 I1106 00:03:59.528] STEP: setting up the StorageClass I1106 00:03:59.528] STEP: creating a StorageClass I1106 00:03:59.619] STEP: setting up the PVC and PV I1106 00:03:59.620] STEP: creating a PVC I1106 00:03:59.711] STEP: deploying the pod I1106 00:03:59.800] STEP: checking that the pods command exits with no error I1106 00:03:59.800] Nov 6 00:03:59.800: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-zjlj6" in namespace "azuredisk-7509" to be "success or failure" I1106 00:03:59.884] Nov 6 00:03:59.884: INFO: Pod "azuredisk-volume-tester-zjlj6": Phase="Pending", Reason="", readiness=false. Elapsed: 84.314234ms I1106 00:04:01.969] Nov 6 00:04:01.969: INFO: Pod "azuredisk-volume-tester-zjlj6": Phase="Pending", Reason="", readiness=false. Elapsed: 2.169266617s I1106 00:04:04.059] Nov 6 00:04:04.058: INFO: Pod "azuredisk-volume-tester-zjlj6": Phase="Pending", Reason="", readiness=false. Elapsed: 4.258826136s I1106 00:04:06.144] Nov 6 00:04:06.143: INFO: Pod "azuredisk-volume-tester-zjlj6": Phase="Pending", Reason="", readiness=false. Elapsed: 6.343813821s I1106 00:04:08.237] Nov 6 00:04:08.236: INFO: Pod "azuredisk-volume-tester-zjlj6": Phase="Pending", Reason="", readiness=false. Elapsed: 8.436821367s ... skipping 310 lines ... I1106 00:18:25.666] Nov 6 00:18:25.666: INFO: PersistentVolumeClaim pvc-cwqdw found but phase is Pending instead of Bound. I1106 00:18:27.752] Nov 6 00:18:27.751: INFO: PersistentVolumeClaim pvc-cwqdw found but phase is Pending instead of Bound. I1106 00:18:29.836] Nov 6 00:18:29.835: INFO: PersistentVolumeClaim pvc-cwqdw found but phase is Pending instead of Bound. I1106 00:18:31.920] Nov 6 00:18:31.919: INFO: PersistentVolumeClaim pvc-cwqdw found but phase is Pending instead of Bound. I1106 00:18:34.004] Nov 6 00:18:34.003: INFO: PersistentVolumeClaim pvc-cwqdw found but phase is Pending instead of Bound. I1106 00:18:36.087] Nov 6 00:18:36.087: INFO: PersistentVolumeClaim pvc-cwqdw found but phase is Pending instead of Bound. I1106 00:18:38.088] Nov 6 00:18:38.087: INFO: Unexpected error occurred: PersistentVolumeClaims [pvc-cwqdw] not all in phase Bound within 5m0s I1106 00:18:38.088] [AfterEach] [multi-az] I1106 00:18:38.090] /go/src/sigs.k8s.io/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1106 00:18:38.090] STEP: Collecting events from namespace "azuredisk-5196". I1106 00:18:38.172] STEP: Found 3 events. I1106 00:18:38.173] Nov 6 00:18:38.172: INFO: At 2019-11-06 00:13:37 +0000 UTC - event for pvc-cwqdw: {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 00:18:38.173] Nov 6 00:18:38.172: INFO: At 2019-11-06 00:13:37 +0000 UTC - event for pvc-cwqdw: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-k2p5m_71d5eefc-0024-11ea-a712-66d7d8b096eb } Provisioning: External provisioner is provisioning volume for claim "azuredisk-5196/pvc-cwqdw" I1106 00:18:38.173] Nov 6 00:18:38.172: INFO: At 2019-11-06 00:13:47 +0000 UTC - event for pvc-cwqdw: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-k2p5m_71d5eefc-0024-11ea-a712-66d7d8b096eb } ProvisioningFailed: failed to provision volume with StorageClass "azuredisk-5196-disk.csi.azure.com-dynamic-sc-ksmsx": rpc error: code = DeadlineExceeded desc = context deadline exceeded I1106 00:18:38.256] Nov 6 00:18:38.256: INFO: POD NODE PHASE GRACE CONDITIONS I1106 00:18:38.256] Nov 6 00:18:38.256: INFO: I1106 00:18:38.505] Nov 6 00:18:38.505: INFO: I1106 00:18:38.506] Logging node info for node k8s-agentpool-73731178-vmss000000 I1106 00:18:38.593] Nov 6 00:18:38.589: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:k8s-agentpool-73731178-vmss000000,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/k8s-agentpool-73731178-vmss000000,UID:e9bc0b16-6756-4155-b49c-e223c0ba9499,ResourceVersion:10212,Generation:0,CreationTimestamp:2019-11-05 23:27:32 +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-07e0acb7-0020-11ea-802a-02428e4d9973,kubernetes.azure.com/role: agent,kubernetes.io/arch: amd64,kubernetes.io/hostname: k8s-agentpool-73731178-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-73731178-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-07e0acb7-0020-11ea-802a-02428e4d9973/providers/Microsoft.Compute/virtualMachineScaleSets/k8s-agentpool-73731178-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-05 23:28:18 +0000 UTC 2019-11-05 23:28:18 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2019-11-06 00:18:09 +0000 UTC 2019-11-05 23:27:30 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2019-11-06 00:18:09 +0000 UTC 2019-11-05 23:27:30 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2019-11-06 00:18:09 +0000 UTC 2019-11-05 23:27:30 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2019-11-06 00:18:09 +0000 UTC 2019-11-05 23:27:48 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.248.0.4} {Hostname k8s-agentpool-73731178-vmss000000}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:956ad861ae4a42099801f8e840b4e502,SystemUUID:439CF4B9-2B9F-B74E-9ED7-7379FD8BD0DF,BootID:bd3476e5-4fd4-4437-9b56-54fbe38a3a49,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-07e0acb7-0020-11ea-802a-02428e4d9973/providers/Microsoft.Compute/disks/pvc-4f5bb48a-bfb9-4847-9099-b2d2110a7312],VolumesAttached:[],Config:nil,},} I1106 00:18:38.593] Nov 6 00:18:38.590: INFO: ... skipping 175 lines ... I1106 00:18:59.848] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:33 I1106 00:18:59.848] [multi-az] I1106 00:18:59.849] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:40 I1106 00:18:59.849] should delete PV with reclaimPolicy "Delete" [It] I1106 00:18:59.849] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:221 I1106 00:18:59.849] I1106 00:18:59.849] Unexpected error: I1106 00:18:59.850] <*errors.errorString | 0xc000830880>: { I1106 00:18:59.850] s: "PersistentVolumeClaims [pvc-cwqdw] not all in phase Bound within 5m0s", I1106 00:18:59.850] } I1106 00:18:59.850] PersistentVolumeClaims [pvc-cwqdw] not all in phase Bound within 5m0s I1106 00:18:59.850] occurred I1106 00:18:59.850] ... skipping 23 lines ... I1106 00:19:02.397] Nov 6 00:19:02.396: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-bkpbm] to have phase Bound I1106 00:19:02.480] Nov 6 00:19:02.480: INFO: PersistentVolumeClaim pvc-bkpbm found and phase=Bound (83.843535ms) I1106 00:19:02.481] STEP: checking the PVC I1106 00:19:02.564] STEP: validating provisioned PV I1106 00:19:02.648] STEP: checking the PV I1106 00:19:02.649] STEP: deploying the pod I1106 00:19:02.737] STEP: checking that the pods command exits with an error I1106 00:19:02.737] Nov 6 00:19:02.737: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-5nd5c" in namespace "azuredisk-7323" to be "Error status code" I1106 00:19:02.821] Nov 6 00:19:02.820: INFO: Pod "azuredisk-volume-tester-5nd5c": Phase="Pending", Reason="", readiness=false. Elapsed: 83.546433ms I1106 00:19:04.905] Nov 6 00:19:04.904: INFO: Pod "azuredisk-volume-tester-5nd5c": Phase="Pending", Reason="", readiness=false. Elapsed: 2.167577331s I1106 00:19:06.989] Nov 6 00:19:06.989: INFO: Pod "azuredisk-volume-tester-5nd5c": Phase="Pending", Reason="", readiness=false. Elapsed: 4.252218942s I1106 00:19:09.075] Nov 6 00:19:09.075: INFO: Pod "azuredisk-volume-tester-5nd5c": Phase="Pending", Reason="", readiness=false. Elapsed: 6.337990157s I1106 00:19:11.167] Nov 6 00:19:11.167: INFO: Pod "azuredisk-volume-tester-5nd5c": Phase="Pending", Reason="", readiness=false. Elapsed: 8.430224619s I1106 00:19:13.255] Nov 6 00:19:13.254: INFO: Pod "azuredisk-volume-tester-5nd5c": Phase="Pending", Reason="", readiness=false. Elapsed: 10.517664534s ... skipping 421 lines ... I1106 00:33:52.250] Nov 6 00:33:52.250: INFO: Pod "azuredisk-volume-tester-5nd5c": Phase="Pending", Reason="", readiness=false. Elapsed: 14m49.512730654s I1106 00:33:54.335] Nov 6 00:33:54.334: INFO: Pod "azuredisk-volume-tester-5nd5c": Phase="Pending", Reason="", readiness=false. Elapsed: 14m51.597638192s I1106 00:33:56.419] Nov 6 00:33:56.419: INFO: Pod "azuredisk-volume-tester-5nd5c": Phase="Pending", Reason="", readiness=false. Elapsed: 14m53.682135725s I1106 00:33:58.510] Nov 6 00:33:58.510: INFO: Pod "azuredisk-volume-tester-5nd5c": Phase="Pending", Reason="", readiness=false. Elapsed: 14m55.772971808s I1106 00:34:00.595] Nov 6 00:34:00.595: INFO: Pod "azuredisk-volume-tester-5nd5c": Phase="Pending", Reason="", readiness=false. Elapsed: 14m57.858037043s I1106 00:34:02.680] Nov 6 00:34:02.680: INFO: Pod "azuredisk-volume-tester-5nd5c": Phase="Pending", Reason="", readiness=false. Elapsed: 14m59.943104078s I1106 00:34:04.684] Nov 6 00:34:04.683: INFO: Unexpected error occurred: Gave up after waiting 15m0s for pod "azuredisk-volume-tester-5nd5c" to be "Error status code" I1106 00:34:04.684] Nov 6 00:34:04.683: INFO: deleting Pod "azuredisk-7323"/"azuredisk-volume-tester-5nd5c" I1106 00:34:04.776] Nov 6 00:34:04.773: INFO: Error getting logs for pod azuredisk-volume-tester-5nd5c: the server rejected our request for an unknown reason (get pods azuredisk-volume-tester-5nd5c) I1106 00:34:04.777] STEP: Deleting pod azuredisk-volume-tester-5nd5c in namespace azuredisk-7323 I1106 00:34:04.871] STEP: deleting PV "azuredisk-7323-disk.csi.azure.com-preprovsioned-pv-tj6l5" I1106 00:34:04.923] Nov 6 00:34:04.871: INFO: Deleting PersistentVolume "azuredisk-7323-disk.csi.azure.com-preprovsioned-pv-tj6l5" I1106 00:34:04.964] STEP: waiting for claim's PV "azuredisk-7323-disk.csi.azure.com-preprovsioned-pv-tj6l5" to be deleted I1106 00:34:04.964] Nov 6 00:34:04.962: INFO: Waiting up to 10m0s for PersistentVolume azuredisk-7323-disk.csi.azure.com-preprovsioned-pv-tj6l5 to get deleted I1106 00:34:05.046] Nov 6 00:34:05.046: INFO: PersistentVolume azuredisk-7323-disk.csi.azure.com-preprovsioned-pv-tj6l5 found and phase=Bound (84.197763ms) ... skipping 112 lines ... I1106 00:43:39.529] Nov 6 00:43:39.528: INFO: PersistentVolume azuredisk-7323-disk.csi.azure.com-preprovsioned-pv-tj6l5 found and phase=Bound (9m34.566482714s) I1106 00:43:44.613] Nov 6 00:43:44.612: INFO: PersistentVolume azuredisk-7323-disk.csi.azure.com-preprovsioned-pv-tj6l5 found and phase=Bound (9m39.650608007s) I1106 00:43:49.697] Nov 6 00:43:49.697: INFO: PersistentVolume azuredisk-7323-disk.csi.azure.com-preprovsioned-pv-tj6l5 found and phase=Bound (9m44.735306003s) I1106 00:43:54.782] Nov 6 00:43:54.781: INFO: PersistentVolume azuredisk-7323-disk.csi.azure.com-preprovsioned-pv-tj6l5 found and phase=Bound (9m49.819629593s) I1106 00:43:59.866] Nov 6 00:43:59.866: INFO: PersistentVolume azuredisk-7323-disk.csi.azure.com-preprovsioned-pv-tj6l5 found and phase=Bound (9m54.904000182s) I1106 00:44:04.958] Nov 6 00:44:04.954: INFO: PersistentVolume azuredisk-7323-disk.csi.azure.com-preprovsioned-pv-tj6l5 found and phase=Bound (9m59.991890195s) I1106 00:44:09.962] Nov 6 00:44:09.958: INFO: Unexpected error occurred: PersistentVolume azuredisk-7323-disk.csi.azure.com-preprovsioned-pv-tj6l5 still exists within 10m0s I1106 00:44:09.962] [AfterEach] [azuredisk-csi-e2e] [single-az] Pre-Provisioned I1106 00:44:09.962] /go/src/sigs.k8s.io/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1106 00:44:09.962] STEP: Collecting events from namespace "azuredisk-7323". I1106 00:44:10.044] STEP: Found 4 events. I1106 00:44:10.045] Nov 6 00:44:10.043: INFO: At 2019-11-06 00:19:02 +0000 UTC - event for azuredisk-volume-tester-5nd5c: {default-scheduler } Scheduled: Successfully assigned azuredisk-7323/azuredisk-volume-tester-5nd5c to k8s-agentpool-73731178-vmss000001 I1106 00:44:10.045] Nov 6 00:44:10.043: INFO: At 2019-11-06 00:19:03 +0000 UTC - event for azuredisk-volume-tester-5nd5c: {attachdetach-controller } FailedAttachVolume: AttachVolume.Attach failed for volume "azuredisk-7323-disk.csi.azure.com-preprovsioned-pv-tj6l5" : rpc error: code = Unknown desc = Attach volume "/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/kubetest-07e0acb7-0020-11ea-802a-02428e4d9973/providers/Microsoft.Compute/disks/pre-provisioned-readOnly" to instance "k8s-agentpool-73731178-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-07e0acb7-0020-11ea-802a-02428e4d9973/providers/Microsoft.Compute/disks/pre-provisioned-readOnly cannot be attached to the VM because it is not in zone '2'." I1106 00:44:10.046] Nov 6 00:44:10.043: INFO: At 2019-11-06 00:21:05 +0000 UTC - event for azuredisk-volume-tester-5nd5c: {kubelet k8s-agentpool-73731178-vmss000001} FailedMount: Unable to mount volumes for pod "azuredisk-volume-tester-5nd5c_azuredisk-7323(93a93c37-6e37-479e-9d1b-9eeed106bb91)": timeout expired waiting for volumes to attach or mount for pod "azuredisk-7323"/"azuredisk-volume-tester-5nd5c". list of unmounted volumes=[test-volume-1]. list of unattached volumes=[test-volume-1 default-token-m7bpj] I1106 00:44:10.047] Nov 6 00:44:10.043: INFO: At 2019-11-06 00:34:40 +0000 UTC - event for azuredisk-volume-tester-5nd5c: {kubelet k8s-agentpool-73731178-vmss000001} FailedMount: Unable to mount volumes for pod "azuredisk-volume-tester-5nd5c_azuredisk-7323(93a93c37-6e37-479e-9d1b-9eeed106bb91)": timeout expired waiting for volumes to attach or mount for pod "azuredisk-7323"/"azuredisk-volume-tester-5nd5c". list of unmounted volumes=[test-volume-1 default-token-m7bpj]. list of unattached volumes=[test-volume-1 default-token-m7bpj] I1106 00:44:10.130] Nov 6 00:44:10.129: INFO: POD NODE PHASE GRACE CONDITIONS I1106 00:44:10.130] Nov 6 00:44:10.129: INFO: I1106 00:44:10.380] Nov 6 00:44:10.380: INFO: I1106 00:44:10.380] Logging node info for node k8s-agentpool-73731178-vmss000000 ... skipping 177 lines ... I1106 00:44:52.520] • Failure [1550.077 seconds] I1106 00:44:52.520] [azuredisk-csi-e2e] [single-az] Pre-Provisioned I1106 00:44:52.520] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/pre_provisioning.go:36 I1106 00:44:52.520] [env] should use a pre-provisioned volume and mount it as readOnly in a pod [It] I1106 00:44:52.520] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/pre_provisioning.go:66 I1106 00:44:52.520] I1106 00:44:52.520] Unexpected error: I1106 00:44:52.521] <*errors.errorString | 0xc0002036f0>: { I1106 00:44:52.521] s: "Gave up after waiting 15m0s for pod \"azuredisk-volume-tester-5nd5c\" to be \"Error status code\"", I1106 00:44:52.521] } I1106 00:44:52.521] Gave up after waiting 15m0s for pod "azuredisk-volume-tester-5nd5c" to be "Error status code" I1106 00:44:52.521] occurred I1106 00:44:52.521] I1106 00:44:52.522] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:553 I1106 00:44:52.522] ------------------------------ I1106 00:44:52.522] [azuredisk-csi-e2e] Dynamic Provisioning [multi-az] I1106 00:44:52.522] should create a deployment object, write and read to it, delete the pod and write and read to it again ... skipping 164 lines ... I1106 00:49:42.974] Nov 6 00:49:42.973: 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:63708597890, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708597890, 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:63708597890, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708597890, loc:(*time.Location)(0x34d4fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-prv9t-8479847459\" is progressing."}}, CollisionCount:(*int32)(nil)} I1106 00:49:44.982] Nov 6 00:49:44.978: 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:63708597890, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708597890, 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:63708597890, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708597890, loc:(*time.Location)(0x34d4fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-prv9t-8479847459\" is progressing."}}, CollisionCount:(*int32)(nil)} I1106 00:49:46.973] Nov 6 00:49:46.973: 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:63708597890, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708597890, 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:63708597890, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708597890, loc:(*time.Location)(0x34d4fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-prv9t-8479847459\" is progressing."}}, CollisionCount:(*int32)(nil)} I1106 00:49:48.973] Nov 6 00:49:48.972: 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:63708597890, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708597890, 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:63708597890, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708597890, loc:(*time.Location)(0x34d4fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-prv9t-8479847459\" is progressing."}}, CollisionCount:(*int32)(nil)} I1106 00:49:50.972] Nov 6 00:49:50.971: 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:63708597890, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708597890, 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:63708597890, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708597890, loc:(*time.Location)(0x34d4fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-prv9t-8479847459\" is progressing."}}, CollisionCount:(*int32)(nil)} I1106 00:49:51.057] Nov 6 00:49:51.056: 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:63708597890, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708597890, 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:63708597890, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708597890, loc:(*time.Location)(0x34d4fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-prv9t-8479847459\" is progressing."}}, CollisionCount:(*int32)(nil)} I1106 00:49:51.057] Nov 6 00:49:51.056: INFO: Unexpected error occurred: error waiting for deployment "azuredisk-volume-tester-prv9t" 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:63708597890, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708597890, 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:63708597890, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708597890, loc:(*time.Location)(0x34d4fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-prv9t-8479847459\" is progressing."}}, CollisionCount:(*int32)(nil)} I1106 00:49:51.058] Nov 6 00:49:51.056: INFO: deleting Deployment "azuredisk-2929"/"azuredisk-volume-tester-prv9t" I1106 00:49:51.058] Nov 6 00:49:51.056: INFO: Error getting logs for pod : resource name may not be empty I1106 00:49:51.236] STEP: validating provisioned PV I1106 00:49:51.236] Nov 6 00:49:51.234: INFO: Unexpected error occurred: resource name may not be empty I1106 00:49:51.237] Nov 6 00:49:51.235: INFO: deleting StorageClass azuredisk-2929-disk.csi.azure.com-dynamic-sc-hdx22 I1106 00:49:51.334] [AfterEach] [multi-az] I1106 00:49:51.334] /go/src/sigs.k8s.io/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1106 00:49:51.334] STEP: Collecting events from namespace "azuredisk-2929". I1106 00:49:51.414] STEP: Found 6 events. I1106 00:49:51.415] Nov 6 00:49:51.412: INFO: At 2019-11-06 00:44:50 +0000 UTC - event for azuredisk-volume-tester-prv9t: {deployment-controller } ScalingReplicaSet: Scaled up replica set azuredisk-volume-tester-prv9t-8479847459 to 1 I1106 00:49:51.415] Nov 6 00:49:51.412: INFO: At 2019-11-06 00:44:50 +0000 UTC - event for azuredisk-volume-tester-prv9t-8479847459: {replicaset-controller } SuccessfulCreate: Created pod: azuredisk-volume-tester-prv9t-8479847459-z69p9 I1106 00:49:51.416] Nov 6 00:49:51.412: INFO: At 2019-11-06 00:44:50 +0000 UTC - event for pvc-d8vrf: {persistentvolume-controller } WaitForFirstConsumer: waiting for first consumer to be created before binding I1106 00:49:51.416] Nov 6 00:49:51.412: INFO: At 2019-11-06 00:44:50 +0000 UTC - event for pvc-d8vrf: {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 00:49:51.417] Nov 6 00:49:51.413: INFO: At 2019-11-06 00:44:50 +0000 UTC - event for pvc-d8vrf: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-k2p5m_71d5eefc-0024-11ea-a712-66d7d8b096eb } Provisioning: External provisioner is provisioning volume for claim "azuredisk-2929/pvc-d8vrf" I1106 00:49:51.417] Nov 6 00:49:51.413: INFO: At 2019-11-06 00:45:00 +0000 UTC - event for pvc-d8vrf: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-k2p5m_71d5eefc-0024-11ea-a712-66d7d8b096eb } ProvisioningFailed: failed to provision volume with StorageClass "azuredisk-2929-disk.csi.azure.com-dynamic-sc-hdx22": rpc error: code = DeadlineExceeded desc = context deadline exceeded I1106 00:49:51.500] Nov 6 00:49:51.500: INFO: POD NODE PHASE GRACE CONDITIONS I1106 00:49:51.501] Nov 6 00:49:51.500: INFO: azuredisk-volume-tester-prv9t-8479847459-z69p9 Pending [] I1106 00:49:51.501] Nov 6 00:49:51.500: INFO: I1106 00:49:51.758] Nov 6 00:49:51.758: INFO: I1106 00:49:51.758] Logging node info for node k8s-agentpool-73731178-vmss000000 I1106 00:49:51.845] Nov 6 00:49:51.842: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:k8s-agentpool-73731178-vmss000000,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/k8s-agentpool-73731178-vmss000000,UID:e9bc0b16-6756-4155-b49c-e223c0ba9499,ResourceVersion:15611,Generation:0,CreationTimestamp:2019-11-05 23:27:32 +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-07e0acb7-0020-11ea-802a-02428e4d9973,kubernetes.azure.com/role: agent,kubernetes.io/arch: amd64,kubernetes.io/hostname: k8s-agentpool-73731178-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-73731178-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-07e0acb7-0020-11ea-802a-02428e4d9973/providers/Microsoft.Compute/virtualMachineScaleSets/k8s-agentpool-73731178-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-05 23:28:18 +0000 UTC 2019-11-05 23:28:18 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2019-11-06 00:49:14 +0000 UTC 2019-11-05 23:27:30 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2019-11-06 00:49:14 +0000 UTC 2019-11-05 23:27:30 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2019-11-06 00:49:14 +0000 UTC 2019-11-05 23:27:30 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2019-11-06 00:49:14 +0000 UTC 2019-11-05 23:27:48 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.248.0.4} {Hostname k8s-agentpool-73731178-vmss000000}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:956ad861ae4a42099801f8e840b4e502,SystemUUID:439CF4B9-2B9F-B74E-9ED7-7379FD8BD0DF,BootID:bd3476e5-4fd4-4437-9b56-54fbe38a3a49,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-07e0acb7-0020-11ea-802a-02428e4d9973/providers/Microsoft.Compute/disks/pvc-4f5bb48a-bfb9-4847-9099-b2d2110a7312],VolumesAttached:[],Config:nil,},} ... skipping 176 lines ... I1106 00:50:13.175] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:33 I1106 00:50:13.175] [multi-az] I1106 00:50:13.176] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:40 I1106 00:50:13.176] should create a deployment object, write and read to it, delete the pod and write and read to it again [It] I1106 00:50:13.176] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:193 I1106 00:50:13.176] I1106 00:50:13.176] Unexpected error: I1106 00:50:13.176] <*errors.errorString | 0xc000985ce0>: { I1106 00:50:13.177] s: "error waiting for deployment \"azuredisk-volume-tester-prv9t\" 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:63708597890, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708597890, 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:63708597890, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708597890, loc:(*time.Location)(0x34d4fc0)}}, Reason:\"ReplicaSetUpdated\", Message:\"ReplicaSet \\\"azuredisk-volume-tester-prv9t-8479847459\\\" is progressing.\"}}, CollisionCount:(*int32)(nil)}", I1106 00:50:13.177] } I1106 00:50:13.178] error waiting for deployment "azuredisk-volume-tester-prv9t" 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:63708597890, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708597890, 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:63708597890, loc:(*time.Location)(0x34d4fc0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63708597890, loc:(*time.Location)(0x34d4fc0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"azuredisk-volume-tester-prv9t-8479847459\" is progressing."}}, CollisionCount:(*int32)(nil)} I1106 00:50:13.178] occurred I1106 00:50:13.178] I1106 00:50:13.178] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:434 I1106 00:50:13.178] ------------------------------ I1106 00:50:13.179] [azuredisk-csi-e2e] Dynamic Provisioning [single-az] I1106 00:50:13.179] should create a volume on demand ... skipping 156 lines ... I1106 00:55:01.956] Nov 6 00:55:01.956: INFO: PersistentVolumeClaim pvc-6snqm found but phase is Pending instead of Bound. I1106 00:55:04.043] Nov 6 00:55:04.043: INFO: PersistentVolumeClaim pvc-6snqm found but phase is Pending instead of Bound. I1106 00:55:06.128] Nov 6 00:55:06.128: INFO: PersistentVolumeClaim pvc-6snqm found but phase is Pending instead of Bound. I1106 00:55:08.213] Nov 6 00:55:08.213: INFO: PersistentVolumeClaim pvc-6snqm found but phase is Pending instead of Bound. I1106 00:55:10.298] Nov 6 00:55:10.297: INFO: PersistentVolumeClaim pvc-6snqm found but phase is Pending instead of Bound. I1106 00:55:12.382] Nov 6 00:55:12.382: INFO: PersistentVolumeClaim pvc-6snqm found but phase is Pending instead of Bound. I1106 00:55:14.382] Nov 6 00:55:14.382: INFO: Unexpected error occurred: PersistentVolumeClaims [pvc-6snqm] not all in phase Bound within 5m0s I1106 00:55:14.383] [AfterEach] [single-az] I1106 00:55:14.383] /go/src/sigs.k8s.io/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1106 00:55:14.383] STEP: Collecting events from namespace "azuredisk-8969". I1106 00:55:14.470] STEP: Found 3 events. I1106 00:55:14.470] Nov 6 00:55:14.470: INFO: At 2019-11-06 00:50:13 +0000 UTC - event for pvc-6snqm: {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 00:55:14.470] Nov 6 00:55:14.470: INFO: At 2019-11-06 00:50:13 +0000 UTC - event for pvc-6snqm: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-k2p5m_71d5eefc-0024-11ea-a712-66d7d8b096eb } Provisioning: External provisioner is provisioning volume for claim "azuredisk-8969/pvc-6snqm" I1106 00:55:14.471] Nov 6 00:55:14.470: INFO: At 2019-11-06 00:50:23 +0000 UTC - event for pvc-6snqm: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-k2p5m_71d5eefc-0024-11ea-a712-66d7d8b096eb } ProvisioningFailed: failed to provision volume with StorageClass "azuredisk-8969-disk.csi.azure.com-dynamic-sc-4d6c6": rpc error: code = DeadlineExceeded desc = context deadline exceeded I1106 00:55:14.555] Nov 6 00:55:14.555: INFO: POD NODE PHASE GRACE CONDITIONS I1106 00:55:14.555] Nov 6 00:55:14.555: INFO: I1106 00:55:14.809] Nov 6 00:55:14.808: INFO: I1106 00:55:14.809] Logging node info for node k8s-agentpool-73731178-vmss000000 I1106 00:55:14.895] Nov 6 00:55:14.892: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:k8s-agentpool-73731178-vmss000000,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/k8s-agentpool-73731178-vmss000000,UID:e9bc0b16-6756-4155-b49c-e223c0ba9499,ResourceVersion:16522,Generation:0,CreationTimestamp:2019-11-05 23:27:32 +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-07e0acb7-0020-11ea-802a-02428e4d9973,kubernetes.azure.com/role: agent,kubernetes.io/arch: amd64,kubernetes.io/hostname: k8s-agentpool-73731178-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-73731178-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-07e0acb7-0020-11ea-802a-02428e4d9973/providers/Microsoft.Compute/virtualMachineScaleSets/k8s-agentpool-73731178-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-05 23:28:18 +0000 UTC 2019-11-05 23:28:18 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2019-11-06 00:54:15 +0000 UTC 2019-11-05 23:27:30 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2019-11-06 00:54:15 +0000 UTC 2019-11-05 23:27:30 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2019-11-06 00:54:15 +0000 UTC 2019-11-05 23:27:30 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2019-11-06 00:54:15 +0000 UTC 2019-11-05 23:27:48 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.248.0.4} {Hostname k8s-agentpool-73731178-vmss000000}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:956ad861ae4a42099801f8e840b4e502,SystemUUID:439CF4B9-2B9F-B74E-9ED7-7379FD8BD0DF,BootID:bd3476e5-4fd4-4437-9b56-54fbe38a3a49,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-07e0acb7-0020-11ea-802a-02428e4d9973/providers/Microsoft.Compute/disks/pvc-4f5bb48a-bfb9-4847-9099-b2d2110a7312],VolumesAttached:[],Config:nil,},} I1106 00:55:14.896] Nov 6 00:55:14.893: INFO: ... skipping 175 lines ... I1106 00:55:36.088] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:33 I1106 00:55:36.088] [single-az] I1106 00:55:36.088] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:36 I1106 00:55:36.089] should create a volume on demand [It] I1106 00:55:36.089] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:78 I1106 00:55:36.089] I1106 00:55:36.089] Unexpected error: I1106 00:55:36.089] <*errors.errorString | 0xc00094fc10>: { I1106 00:55:36.089] s: "PersistentVolumeClaims [pvc-6snqm] not all in phase Bound within 5m0s", I1106 00:55:36.089] } I1106 00:55:36.090] PersistentVolumeClaims [pvc-6snqm] not all in phase Bound within 5m0s I1106 00:55:36.090] occurred I1106 00:55:36.090] ... skipping 15 lines ... I1106 00:55:36.698] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:78 I1106 00:55:36.698] STEP: setting up the StorageClass I1106 00:55:36.699] STEP: creating a StorageClass I1106 00:55:36.792] STEP: setting up the PVC and PV I1106 00:55:36.792] STEP: creating a PVC I1106 00:55:36.885] STEP: deploying the pod I1106 00:55:36.983] STEP: checking that the pods command exits with no error I1106 00:55:36.983] Nov 6 00:55:36.983: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-ksl4f" in namespace "azuredisk-1499" to be "success or failure" I1106 00:55:37.067] Nov 6 00:55:37.067: INFO: Pod "azuredisk-volume-tester-ksl4f": Phase="Pending", Reason="", readiness=false. Elapsed: 84.165753ms I1106 00:55:39.152] Nov 6 00:55:39.152: INFO: Pod "azuredisk-volume-tester-ksl4f": Phase="Pending", Reason="", readiness=false. Elapsed: 2.16922832s I1106 00:55:41.238] Nov 6 00:55:41.238: INFO: Pod "azuredisk-volume-tester-ksl4f": Phase="Pending", Reason="", readiness=false. Elapsed: 4.255086794s I1106 00:55:43.322] Nov 6 00:55:43.322: INFO: Pod "azuredisk-volume-tester-ksl4f": Phase="Pending", Reason="", readiness=false. Elapsed: 6.339293154s I1106 00:55:45.407] Nov 6 00:55:45.407: INFO: Pod "azuredisk-volume-tester-ksl4f": Phase="Pending", Reason="", readiness=false. Elapsed: 8.423823917s ... skipping 420 lines ... I1106 01:10:26.013] Nov 6 01:10:26.013: INFO: Pod "azuredisk-volume-tester-ksl4f": Phase="Pending", Reason="", readiness=false. Elapsed: 14m49.030108127s I1106 01:10:28.098] Nov 6 01:10:28.098: INFO: Pod "azuredisk-volume-tester-ksl4f": Phase="Pending", Reason="", readiness=false. Elapsed: 14m51.115210576s I1106 01:10:30.183] Nov 6 01:10:30.183: INFO: Pod "azuredisk-volume-tester-ksl4f": Phase="Pending", Reason="", readiness=false. Elapsed: 14m53.200025022s I1106 01:10:32.268] Nov 6 01:10:32.268: INFO: Pod "azuredisk-volume-tester-ksl4f": Phase="Pending", Reason="", readiness=false. Elapsed: 14m55.285195272s I1106 01:10:34.355] Nov 6 01:10:34.355: INFO: Pod "azuredisk-volume-tester-ksl4f": Phase="Pending", Reason="", readiness=false. Elapsed: 14m57.372016834s I1106 01:10:36.439] Nov 6 01:10:36.439: INFO: Pod "azuredisk-volume-tester-ksl4f": Phase="Pending", Reason="", readiness=false. Elapsed: 14m59.456475277s I1106 01:10:38.440] Nov 6 01:10:38.439: INFO: Unexpected error occurred: Gave up after waiting 15m0s for pod "azuredisk-volume-tester-ksl4f" to be "success or failure" I1106 01:10:38.440] Nov 6 01:10:38.440: INFO: deleting Pod "azuredisk-1499"/"azuredisk-volume-tester-ksl4f" I1106 01:10:38.525] Nov 6 01:10:38.525: INFO: Pod azuredisk-volume-tester-ksl4f has the following logs: I1106 01:10:38.525] STEP: Deleting pod azuredisk-volume-tester-ksl4f in namespace azuredisk-1499 I1106 01:10:38.712] STEP: validating provisioned PV I1106 01:10:38.713] Nov 6 01:10:38.712: INFO: Unexpected error occurred: resource name may not be empty I1106 01:10:38.713] Nov 6 01:10:38.712: INFO: deleting StorageClass azuredisk-1499-disk.csi.azure.com-dynamic-sc-mc826 I1106 01:10:38.806] [AfterEach] [multi-az] I1106 01:10:38.806] /go/src/sigs.k8s.io/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1106 01:10:38.806] STEP: Collecting events from namespace "azuredisk-1499". I1106 01:10:38.890] STEP: Found 6 events. I1106 01:10:38.890] Nov 6 01:10:38.890: INFO: At 2019-11-06 00:55:36 +0000 UTC - event for pvc-h4dl8: {persistentvolume-controller } WaitForFirstConsumer: waiting for first consumer to be created before binding I1106 01:10:38.891] Nov 6 01:10:38.890: INFO: At 2019-11-06 00:55:36 +0000 UTC - event for pvc-h4dl8: {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:10:38.891] Nov 6 01:10:38.890: INFO: At 2019-11-06 00:55:36 +0000 UTC - event for pvc-h4dl8: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-k2p5m_71d5eefc-0024-11ea-a712-66d7d8b096eb } Provisioning: External provisioner is provisioning volume for claim "azuredisk-1499/pvc-h4dl8" I1106 01:10:38.891] Nov 6 01:10:38.890: INFO: At 2019-11-06 00:55:46 +0000 UTC - event for pvc-h4dl8: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-k2p5m_71d5eefc-0024-11ea-a712-66d7d8b096eb } ProvisioningFailed: failed to provision volume with StorageClass "azuredisk-1499-disk.csi.azure.com-dynamic-sc-mc826": rpc error: code = DeadlineExceeded desc = context deadline exceeded I1106 01:10:38.891] Nov 6 01:10:38.890: INFO: At 2019-11-06 01:05:36 +0000 UTC - event for azuredisk-volume-tester-ksl4f: {default-scheduler } FailedScheduling: timed out waiting for the condition I1106 01:10:38.891] Nov 6 01:10:38.890: INFO: At 2019-11-06 01:10:38 +0000 UTC - event for azuredisk-volume-tester-ksl4f: {default-scheduler } FailedScheduling: skip schedule deleting pod: azuredisk-1499/azuredisk-volume-tester-ksl4f I1106 01:10:38.975] Nov 6 01:10:38.974: INFO: POD NODE PHASE GRACE CONDITIONS I1106 01:10:38.975] Nov 6 01:10:38.974: INFO: I1106 01:10:39.225] Nov 6 01:10:39.225: INFO: I1106 01:10:39.226] Logging node info for node k8s-agentpool-73731178-vmss000000 ... skipping 177 lines ... I1106 01:11:00.539] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:33 I1106 01:11:00.540] [multi-az] I1106 01:11:00.540] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:40 I1106 01:11:00.540] should create a volume on demand [It] I1106 01:11:00.540] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:78 I1106 01:11:00.540] I1106 01:11:00.540] Unexpected error: I1106 01:11:00.540] <*errors.errorString | 0xc000eaa9d0>: { I1106 01:11:00.541] s: "Gave up after waiting 15m0s for pod \"azuredisk-volume-tester-ksl4f\" to be \"success or failure\"", I1106 01:11:00.541] } I1106 01:11:00.541] Gave up after waiting 15m0s for pod "azuredisk-volume-tester-ksl4f" to be "success or failure" I1106 01:11:00.541] occurred I1106 01:11:00.541] ... skipping 161 lines ... I1106 01:15:50.494] Nov 6 01:15:50.493: INFO: PersistentVolumeClaim pvc-vgrmd found but phase is Pending instead of Bound. I1106 01:15:52.578] Nov 6 01:15:52.578: INFO: PersistentVolumeClaim pvc-vgrmd found but phase is Pending instead of Bound. I1106 01:15:54.662] Nov 6 01:15:54.662: INFO: PersistentVolumeClaim pvc-vgrmd found but phase is Pending instead of Bound. I1106 01:15:56.747] Nov 6 01:15:56.746: INFO: PersistentVolumeClaim pvc-vgrmd found but phase is Pending instead of Bound. I1106 01:15:58.830] Nov 6 01:15:58.830: INFO: PersistentVolumeClaim pvc-vgrmd found but phase is Pending instead of Bound. I1106 01:16:00.914] Nov 6 01:16:00.914: INFO: PersistentVolumeClaim pvc-vgrmd found but phase is Pending instead of Bound. I1106 01:16:02.915] Nov 6 01:16:02.914: INFO: Unexpected error occurred: PersistentVolumeClaims [pvc-vgrmd] not all in phase Bound within 5m0s I1106 01:16:02.915] [AfterEach] [single-az] I1106 01:16:02.915] /go/src/sigs.k8s.io/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1106 01:16:02.915] STEP: Collecting events from namespace "azuredisk-7154". I1106 01:16:02.999] STEP: Found 3 events. I1106 01:16:03.000] Nov 6 01:16:02.999: INFO: At 2019-11-06 01:11:01 +0000 UTC - event for pvc-vgrmd: {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:16:03.000] Nov 6 01:16:02.999: INFO: At 2019-11-06 01:11:01 +0000 UTC - event for pvc-vgrmd: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-k2p5m_71d5eefc-0024-11ea-a712-66d7d8b096eb } Provisioning: External provisioner is provisioning volume for claim "azuredisk-7154/pvc-vgrmd" I1106 01:16:03.000] Nov 6 01:16:02.999: INFO: At 2019-11-06 01:11:11 +0000 UTC - event for pvc-vgrmd: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-k2p5m_71d5eefc-0024-11ea-a712-66d7d8b096eb } ProvisioningFailed: failed to provision volume with StorageClass "azuredisk-7154-disk.csi.azure.com-dynamic-sc-9hbzj": rpc error: code = DeadlineExceeded desc = context deadline exceeded I1106 01:16:03.083] Nov 6 01:16:03.083: INFO: POD NODE PHASE GRACE CONDITIONS I1106 01:16:03.084] Nov 6 01:16:03.083: INFO: I1106 01:16:03.336] Nov 6 01:16:03.336: INFO: I1106 01:16:03.337] Logging node info for node k8s-agentpool-73731178-vmss000000 I1106 01:16:03.423] Nov 6 01:16:03.420: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:k8s-agentpool-73731178-vmss000000,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/k8s-agentpool-73731178-vmss000000,UID:e9bc0b16-6756-4155-b49c-e223c0ba9499,ResourceVersion:20203,Generation:0,CreationTimestamp:2019-11-05 23:27:32 +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-07e0acb7-0020-11ea-802a-02428e4d9973,kubernetes.azure.com/role: agent,kubernetes.io/arch: amd64,kubernetes.io/hostname: k8s-agentpool-73731178-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-73731178-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-07e0acb7-0020-11ea-802a-02428e4d9973/providers/Microsoft.Compute/virtualMachineScaleSets/k8s-agentpool-73731178-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-05 23:28:18 +0000 UTC 2019-11-05 23:28:18 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2019-11-06 01:15:18 +0000 UTC 2019-11-05 23:27:30 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2019-11-06 01:15:18 +0000 UTC 2019-11-05 23:27:30 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2019-11-06 01:15:18 +0000 UTC 2019-11-05 23:27:30 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2019-11-06 01:15:18 +0000 UTC 2019-11-05 23:27:48 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.248.0.4} {Hostname k8s-agentpool-73731178-vmss000000}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:956ad861ae4a42099801f8e840b4e502,SystemUUID:439CF4B9-2B9F-B74E-9ED7-7379FD8BD0DF,BootID:bd3476e5-4fd4-4437-9b56-54fbe38a3a49,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-07e0acb7-0020-11ea-802a-02428e4d9973/providers/Microsoft.Compute/disks/pvc-4f5bb48a-bfb9-4847-9099-b2d2110a7312],VolumesAttached:[],Config:nil,},} I1106 01:16:03.424] Nov 6 01:16:03.420: INFO: ... skipping 175 lines ... I1106 01:16:24.583] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:33 I1106 01:16:24.583] [single-az] I1106 01:16:24.583] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:36 I1106 01:16:24.583] should create a deployment object, write and read to it, delete the pod and write and read to it again [It] I1106 01:16:24.583] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:193 I1106 01:16:24.584] I1106 01:16:24.584] Unexpected error: I1106 01:16:24.584] <*errors.errorString | 0xc000996db0>: { I1106 01:16:24.584] s: "PersistentVolumeClaims [pvc-vgrmd] not all in phase Bound within 5m0s", I1106 01:16:24.584] } I1106 01:16:24.584] PersistentVolumeClaims [pvc-vgrmd] not all in phase Bound within 5m0s I1106 01:16:24.584] occurred I1106 01:16:24.584] ... skipping 214 lines ... I1106 01:16:49.666] [azuredisk-csi-e2e] [single-az] Pre-Provisioned I1106 01:16:49.666] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/pre_provisioning.go:36 I1106 01:16:49.666] [env] should use a pre-provisioned volume and retain PV with reclaimPolicy "Retain" [It] I1106 01:16:49.667] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/pre_provisioning.go:100 I1106 01:16:49.667] I1106 01:16:49.667] Test Panicked I1106 01:16:49.667] runtime error: invalid memory address or nil pointer dereference I1106 01:16:49.667] /usr/local/go/src/runtime/panic.go:82 I1106 01:16:49.667] I1106 01:16:49.667] Full Stack Trace I1106 01:16:49.667] /usr/local/go/src/runtime/panic.go:522 +0x1b5 I1106 01:16:49.668] sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites.(*TestPersistentVolumeClaim).Cleanup(0xc000bfc8a0) I1106 01:16:49.668] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:313 +0x3b ... skipping 170 lines ... I1106 01:21:38.287] Nov 6 01:21:38.287: INFO: PersistentVolumeClaim pvc-l88cs found but phase is Pending instead of Bound. I1106 01:21:40.372] Nov 6 01:21:40.372: INFO: PersistentVolumeClaim pvc-l88cs found but phase is Pending instead of Bound. I1106 01:21:42.456] Nov 6 01:21:42.456: INFO: PersistentVolumeClaim pvc-l88cs found but phase is Pending instead of Bound. I1106 01:21:44.542] Nov 6 01:21:44.542: INFO: PersistentVolumeClaim pvc-l88cs found but phase is Pending instead of Bound. I1106 01:21:46.627] Nov 6 01:21:46.627: INFO: PersistentVolumeClaim pvc-l88cs found but phase is Pending instead of Bound. I1106 01:21:48.711] Nov 6 01:21:48.711: INFO: PersistentVolumeClaim pvc-l88cs found but phase is Pending instead of Bound. I1106 01:21:50.712] Nov 6 01:21:50.711: INFO: Unexpected error occurred: PersistentVolumeClaims [pvc-l88cs] not all in phase Bound within 5m0s I1106 01:21:50.712] [AfterEach] [multi-az] I1106 01:21:50.712] /go/src/sigs.k8s.io/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1106 01:21:50.712] STEP: Collecting events from namespace "azuredisk-5705". I1106 01:21:50.796] STEP: Found 3 events. I1106 01:21:50.796] Nov 6 01:21:50.796: INFO: At 2019-11-06 01:16:50 +0000 UTC - event for pvc-l88cs: {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:50.797] Nov 6 01:21:50.796: INFO: At 2019-11-06 01:16:50 +0000 UTC - event for pvc-l88cs: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-k2p5m_71d5eefc-0024-11ea-a712-66d7d8b096eb } Provisioning: External provisioner is provisioning volume for claim "azuredisk-5705/pvc-l88cs" I1106 01:21:50.797] Nov 6 01:21:50.796: INFO: At 2019-11-06 01:17:00 +0000 UTC - event for pvc-l88cs: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-k2p5m_71d5eefc-0024-11ea-a712-66d7d8b096eb } ProvisioningFailed: failed to provision volume with StorageClass "azuredisk-5705-disk.csi.azure.com-dynamic-sc-4gwx7": rpc error: code = DeadlineExceeded desc = context deadline exceeded I1106 01:21:50.880] Nov 6 01:21:50.880: INFO: POD NODE PHASE GRACE CONDITIONS I1106 01:21:50.881] Nov 6 01:21:50.880: INFO: I1106 01:21:51.130] Nov 6 01:21:51.130: INFO: I1106 01:21:51.130] Logging node info for node k8s-agentpool-73731178-vmss000000 I1106 01:21:51.217] Nov 6 01:21:51.214: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:k8s-agentpool-73731178-vmss000000,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/k8s-agentpool-73731178-vmss000000,UID:e9bc0b16-6756-4155-b49c-e223c0ba9499,ResourceVersion:21294,Generation:0,CreationTimestamp:2019-11-05 23:27:32 +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-07e0acb7-0020-11ea-802a-02428e4d9973,kubernetes.azure.com/role: agent,kubernetes.io/arch: amd64,kubernetes.io/hostname: k8s-agentpool-73731178-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-73731178-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-07e0acb7-0020-11ea-802a-02428e4d9973/providers/Microsoft.Compute/virtualMachineScaleSets/k8s-agentpool-73731178-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-05 23:28:18 +0000 UTC 2019-11-05 23:28:18 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2019-11-06 01:21:19 +0000 UTC 2019-11-05 23:27:30 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2019-11-06 01:21:19 +0000 UTC 2019-11-05 23:27:30 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2019-11-06 01:21:19 +0000 UTC 2019-11-05 23:27:30 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2019-11-06 01:21:19 +0000 UTC 2019-11-05 23:27:48 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.248.0.4} {Hostname k8s-agentpool-73731178-vmss000000}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:956ad861ae4a42099801f8e840b4e502,SystemUUID:439CF4B9-2B9F-B74E-9ED7-7379FD8BD0DF,BootID:bd3476e5-4fd4-4437-9b56-54fbe38a3a49,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-07e0acb7-0020-11ea-802a-02428e4d9973/providers/Microsoft.Compute/disks/pvc-4f5bb48a-bfb9-4847-9099-b2d2110a7312],VolumesAttached:[],Config:nil,},} I1106 01:21:51.218] Nov 6 01:21:51.214: INFO: ... skipping 175 lines ... I1106 01:22:12.413] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:33 I1106 01:22:12.413] [multi-az] I1106 01:22:12.414] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:40 I1106 01:22:12.414] [env] should retain PV with reclaimPolicy "Retain" [It] I1106 01:22:12.414] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:240 I1106 01:22:12.414] I1106 01:22:12.414] Unexpected error: I1106 01:22:12.414] <*errors.errorString | 0xc000bc16f0>: { I1106 01:22:12.414] s: "PersistentVolumeClaims [pvc-l88cs] not all in phase Bound within 5m0s", I1106 01:22:12.415] } I1106 01:22:12.415] PersistentVolumeClaims [pvc-l88cs] not all in phase Bound within 5m0s I1106 01:22:12.415] occurred I1106 01:22:12.415] ... skipping 15 lines ... I1106 01:22:13.026] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:126 I1106 01:22:13.026] STEP: setting up the StorageClass I1106 01:22:13.026] STEP: creating a StorageClass I1106 01:22:13.110] STEP: setting up the PVC and PV I1106 01:22:13.110] STEP: creating a PVC I1106 01:22:13.196] STEP: deploying the pod I1106 01:22:13.275] STEP: checking that the pods command exits with an error I1106 01:22:13.275] Nov 6 01:22:13.275: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-qtf4g" in namespace "azuredisk-4885" to be "Error status code" I1106 01:22:13.349] Nov 6 01:22:13.349: INFO: Pod "azuredisk-volume-tester-qtf4g": Phase="Pending", Reason="", readiness=false. Elapsed: 74.598678ms I1106 01:22:15.425] Nov 6 01:22:15.425: INFO: Pod "azuredisk-volume-tester-qtf4g": Phase="Pending", Reason="", readiness=false. Elapsed: 2.150439252s I1106 01:22:17.501] Nov 6 01:22:17.500: INFO: Pod "azuredisk-volume-tester-qtf4g": Phase="Pending", Reason="", readiness=false. Elapsed: 4.225749022s I1106 01:22:19.576] Nov 6 01:22:19.575: INFO: Pod "azuredisk-volume-tester-qtf4g": Phase="Pending", Reason="", readiness=false. Elapsed: 6.300689489s I1106 01:22:21.652] Nov 6 01:22:21.652: INFO: Pod "azuredisk-volume-tester-qtf4g": Phase="Pending", Reason="", readiness=false. Elapsed: 8.376959366s I1106 01:22:23.727] Nov 6 01:22:23.727: INFO: Pod "azuredisk-volume-tester-qtf4g": Phase="Pending", Reason="", readiness=false. Elapsed: 10.452272736s ... skipping 420 lines ... I1106 01:37:01.017] Nov 6 01:37:01.017: INFO: Pod "azuredisk-volume-tester-qtf4g": Phase="Pending", Reason="", readiness=false. Elapsed: 14m47.741874432s I1106 01:37:03.101] Nov 6 01:37:03.101: INFO: Pod "azuredisk-volume-tester-qtf4g": Phase="Pending", Reason="", readiness=false. Elapsed: 14m49.826104358s I1106 01:37:05.185] Nov 6 01:37:05.185: INFO: Pod "azuredisk-volume-tester-qtf4g": Phase="Pending", Reason="", readiness=false. Elapsed: 14m51.910127886s I1106 01:37:07.270] Nov 6 01:37:07.269: INFO: Pod "azuredisk-volume-tester-qtf4g": Phase="Pending", Reason="", readiness=false. Elapsed: 14m53.994532818s I1106 01:37:09.353] Nov 6 01:37:09.353: INFO: Pod "azuredisk-volume-tester-qtf4g": Phase="Pending", Reason="", readiness=false. Elapsed: 14m56.07848115s I1106 01:37:11.444] Nov 6 01:37:11.444: INFO: Pod "azuredisk-volume-tester-qtf4g": Phase="Pending", Reason="", readiness=false. Elapsed: 14m58.169403835s I1106 01:37:13.445] Nov 6 01:37:13.444: INFO: Unexpected error occurred: Gave up after waiting 15m0s for pod "azuredisk-volume-tester-qtf4g" to be "Error status code" I1106 01:37:13.445] Nov 6 01:37:13.445: INFO: deleting Pod "azuredisk-4885"/"azuredisk-volume-tester-qtf4g" I1106 01:37:13.529] Nov 6 01:37:13.528: INFO: Pod azuredisk-volume-tester-qtf4g has the following logs: I1106 01:37:13.529] STEP: Deleting pod azuredisk-volume-tester-qtf4g in namespace azuredisk-4885 I1106 01:37:13.714] STEP: validating provisioned PV I1106 01:37:13.714] Nov 6 01:37:13.714: INFO: Unexpected error occurred: resource name may not be empty I1106 01:37:13.715] Nov 6 01:37:13.714: INFO: deleting StorageClass azuredisk-4885-disk.csi.azure.com-dynamic-sc-n7b82 I1106 01:37:13.813] [AfterEach] [multi-az] I1106 01:37:13.814] /go/src/sigs.k8s.io/azuredisk-csi-driver/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:151 I1106 01:37:13.814] STEP: Collecting events from namespace "azuredisk-4885". I1106 01:37:13.897] STEP: Found 6 events. I1106 01:37:13.897] Nov 6 01:37:13.897: INFO: At 2019-11-06 01:22:13 +0000 UTC - event for pvc-zcktj: {persistentvolume-controller } WaitForFirstConsumer: waiting for first consumer to be created before binding I1106 01:37:13.897] Nov 6 01:37:13.897: INFO: At 2019-11-06 01:22:13 +0000 UTC - event for pvc-zcktj: {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:37:13.898] Nov 6 01:37:13.897: INFO: At 2019-11-06 01:22:13 +0000 UTC - event for pvc-zcktj: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-k2p5m_71d5eefc-0024-11ea-a712-66d7d8b096eb } Provisioning: External provisioner is provisioning volume for claim "azuredisk-4885/pvc-zcktj" I1106 01:37:13.898] Nov 6 01:37:13.897: INFO: At 2019-11-06 01:22:23 +0000 UTC - event for pvc-zcktj: {disk.csi.azure.com_csi-azuredisk-controller-59bf945f54-k2p5m_71d5eefc-0024-11ea-a712-66d7d8b096eb } ProvisioningFailed: failed to provision volume with StorageClass "azuredisk-4885-disk.csi.azure.com-dynamic-sc-n7b82": rpc error: code = DeadlineExceeded desc = context deadline exceeded I1106 01:37:13.898] Nov 6 01:37:13.897: INFO: At 2019-11-06 01:32:13 +0000 UTC - event for azuredisk-volume-tester-qtf4g: {default-scheduler } FailedScheduling: timed out waiting for the condition I1106 01:37:13.898] Nov 6 01:37:13.897: INFO: At 2019-11-06 01:37:13 +0000 UTC - event for azuredisk-volume-tester-qtf4g: {default-scheduler } FailedScheduling: skip schedule deleting pod: azuredisk-4885/azuredisk-volume-tester-qtf4g I1106 01:37:13.981] Nov 6 01:37:13.981: INFO: POD NODE PHASE GRACE CONDITIONS I1106 01:37:13.981] Nov 6 01:37:13.981: INFO: I1106 01:37:14.230] Nov 6 01:37:14.230: INFO: I1106 01:37:14.231] Logging node info for node k8s-agentpool-73731178-vmss000000 ... skipping 177 lines ... I1106 01:37:35.493] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:33 I1106 01:37:35.493] [multi-az] I1106 01:37:35.493] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:40 I1106 01:37:35.494] should create a volume on demand and mount it as readOnly in a pod [It] I1106 01:37:35.494] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:126 I1106 01:37:35.494] I1106 01:37:35.494] Unexpected error: I1106 01:37:35.494] <*errors.errorString | 0xc000bc01c0>: { I1106 01:37:35.494] s: "Gave up after waiting 15m0s for pod \"azuredisk-volume-tester-qtf4g\" to be \"Error status code\"", I1106 01:37:35.494] } I1106 01:37:35.495] Gave up after waiting 15m0s for pod "azuredisk-volume-tester-qtf4g" to be "Error status code" I1106 01:37:35.495] occurred I1106 01:37:35.495] I1106 01:37:35.495] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:553 I1106 01:37:35.495] ------------------------------ I1106 01:37:35.495] 2019/11/06 01:37:35 Uninstalling Azure Disk CSI Driver... I1106 01:37:35.495] make[1]: Entering directory '/go/src/sigs.k8s.io/azuredisk-csi-driver' ... skipping 2 lines ... I1106 01:37:43.579] make[1]: Leaving directory '/go/src/sigs.k8s.io/azuredisk-csi-driver' I1106 01:37:43.580] 2019/11/06 01:37:43 Azure Disk CSI Driver uninstalled I1106 01:37:43.582] I1106 01:37:43.582] I1106 01:37:43.582] Summarizing 14 Failures: I1106 01:37:43.582] I1106 01:37:43.582] [Fail] [azuredisk-csi-e2e] Dynamic Provisioning [single-az] [It] should create a raw block volume on demand I1106 01:37:43.583] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:278 I1106 01:37:43.583] I1106 01:37:43.583] [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 01:37:43.583] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:278 I1106 01:37:43.583] I1106 01:37:43.583] [Fail] [azuredisk-csi-e2e] Dynamic Provisioning [single-az] [It] should create a volume on demand and mount it as readOnly in a pod I1106 01:37:43.584] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:278 I1106 01:37:43.584] I1106 01:37:43.584] [Fail] [azuredisk-csi-e2e] Dynamic Provisioning [single-az] [It] [env] should retain PV with reclaimPolicy "Retain" I1106 01:37:43.584] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:278 I1106 01:37:43.584] I1106 01:37:43.584] [Fail] [azuredisk-csi-e2e] Dynamic Provisioning [single-az] [It] should delete PV with reclaimPolicy "Delete" I1106 01:37:43.584] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:278 I1106 01:37:43.585] I1106 01:37:43.585] [Fail] [azuredisk-csi-e2e] Dynamic Provisioning [multi-az] [It] should delete PV with reclaimPolicy "Delete" I1106 01:37:43.585] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:278 I1106 01:37:43.585] I1106 01:37:43.585] [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 01:37:43.585] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:553 I1106 01:37:43.586] I1106 01:37:43.586] [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 01:37:43.586] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:434 I1106 01:37:43.586] I1106 01:37:43.586] [Fail] [azuredisk-csi-e2e] Dynamic Provisioning [single-az] [It] should create a volume on demand I1106 01:37:43.587] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:278 I1106 01:37:43.587] I1106 01:37:43.587] [Fail] [azuredisk-csi-e2e] Dynamic Provisioning [multi-az] [It] should create a volume on demand I1106 01:37:43.587] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:529 I1106 01:37:43.587] I1106 01:37:43.587] [Fail] [azuredisk-csi-e2e] Dynamic Provisioning [single-az] [It] should create a deployment object, write and read to it, delete the pod and write and read to it again I1106 01:37:43.587] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:278 I1106 01:37:43.588] I1106 01:37:43.588] [Panic!] [azuredisk-csi-e2e] [single-az] Pre-Provisioned [It] [env] should use a pre-provisioned volume and retain PV with reclaimPolicy "Retain" I1106 01:37:43.588] /usr/local/go/src/runtime/panic.go:82 I1106 01:37:43.588] I1106 01:37:43.588] [Fail] [azuredisk-csi-e2e] Dynamic Provisioning [multi-az] [It] [env] should retain PV with reclaimPolicy "Retain" I1106 01:37:43.588] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:278 I1106 01:37:43.588] I1106 01:37:43.589] [Fail] [azuredisk-csi-e2e] Dynamic Provisioning [multi-az] [It] should create a volume on demand and mount it as readOnly in a pod I1106 01:37:43.589] /go/src/sigs.k8s.io/azuredisk-csi-driver/test/e2e/testsuites/testsuites.go:553 I1106 01:37:43.589] I1106 01:37:43.589] Ran 16 of 16 Specs in 7692.234 seconds I1106 01:37:43.589] FAIL! -- 2 Passed | 14 Failed | 0 Pending | 0 Skipped I1106 01:37:43.589] --- FAIL: TestE2E (7692.23s) I1106 01:37:43.589] FAIL I1106 01:37:43.589] FAIL sigs.k8s.io/azuredisk-csi-driver/test/e2e 7692.286s W1106 01:37:43.727] make: *** [Makefile:59: e2e-test] Error 1 W1106 01:37:43.728] 2019/11/06 01:37:43 process.go:155: Step 'make e2e-test' finished in 2h9m0.874450582s W1106 01:37:43.728] 2019/11/06 01:37:43 azure.go:912: Skippng DumpClusterLogs due to CCM not being enabled. W1106 01:37:43.728] 2019/11/06 01:37:43 azure.go:906: Deleting resource group: kubetest-07e0acb7-0020-11ea-802a-02428e4d9973. W1106 01:47:54.399] 2019/11/06 01:47:54 process.go:96: Saved XML output to /workspace/_artifacts/junit_runner.xml. W1106 01:47:54.400] 2019/11/06 01:47:54 process.go:153: Running: bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}" W1106 01:47:55.055] 2019/11/06 01:47:55 process.go:155: Step 'bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}"' finished in 656.011948ms W1106 01:47:55.056] 2019/11/06 01:47:55 main.go:319: Something went wrong: encountered 1 errors: [error during make e2e-test: exit status 2] W1106 01:47:55.057] Traceback (most recent call last): W1106 01:47:55.058] File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 778, in <module> W1106 01:47:55.058] main(parse_args()) W1106 01:47:55.058] File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 626, in main W1106 01:47:55.058] mode.start(runner_args) W1106 01:47:55.058] File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 262, in start W1106 01:47:55.059] check_env(env, self.command, *args) W1106 01:47:55.059] File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 111, in check_env W1106 01:47:55.059] subprocess.check_call(cmd, env=env) W1106 01:47:55.059] File "/usr/lib/python2.7/subprocess.py", line 190, in check_call W1106 01:47:55.059] raise CalledProcessError(retcode, cmd) W1106 01:47:55.060] 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 01:47:55.065] Command failed I1106 01:47:55.065] process 682 exited with code 1 after 167.7m E1106 01:47:55.065] FAIL: chewong-pull-azuredisk-csi-driver-e2e-multi-az I1106 01:47:55.065] Call: gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json W1106 01:47:55.901] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com] I1106 01:47:55.935] process 19779 exited with code 0 after 0.0m I1106 01:47:55.935] Call: gcloud config get-value account I1106 01:47:56.204] process 19791 exited with code 0 after 0.0m I1106 01:47:56.204] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com I1106 01:47:56.204] Upload result and artifacts... I1106 01:47:56.204] 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/1191852367847362560 I1106 01:47:56.205] Call: gsutil ls gs://kubernetes-upstream/pr-logs/pull/sigs.k8s.io_azuredisk-csi-driver/180/chewong-pull-azuredisk-csi-driver-e2e-multi-az/1191852367847362560/artifacts W1106 01:47:57.366] CommandException: One or more URLs matched no objects. E1106 01:47:57.441] Command failed I1106 01:47:57.441] process 19803 exited with code 1 after 0.0m W1106 01:47:57.441] Remote dir gs://kubernetes-upstream/pr-logs/pull/sigs.k8s.io_azuredisk-csi-driver/180/chewong-pull-azuredisk-csi-driver-e2e-multi-az/1191852367847362560/artifacts not exist yet I1106 01:47:57.441] 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/1191852367847362560/artifacts I1106 01:47:58.862] process 19947 exited with code 0 after 0.0m I1106 01:47:58.863] Call: git rev-parse HEAD I1106 01:47:58.866] process 20476 exited with code 0 after 0.0m ... skipping 21 lines ...