kubernetes-sigs/azuredisk-csi-driver PR #166 pull-azuredisk-csi-driver-e2e #1179515703451979776
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 361 lines ... I1002 22:29:55.096] pod/tiller-deploy-54c96cb5df-4d9v9 condition met I1002 22:29:55.099] helm version I1002 22:29:55.153] Client: &version.Version{SemVer:"v2.11.0", GitCommit:"2e55dbe1fdb5fdb96b75ff144a339489417b146b", GitTreeState:"clean"} I1002 22:29:56.606] Server: &version.Version{SemVer:"v2.11.0", GitCommit:"2e55dbe1fdb5fdb96b75ff144a339489417b146b", GitTreeState:"clean"} I1002 22:29:56.608] # Only build and push the image if it does not exist in the registry I1002 22:29:56.609] docker pull k8sprowinternal.azurecr.io/azuredisk-csi:e2e-0f439f89acfd5bbdb1c6bb5ea27451b0f804821a || make azuredisk-container push I1002 22:29:56.836] Error response from daemon: manifest for k8sprowinternal.azurecr.io/azuredisk-csi:e2e-0f439f89acfd5bbdb1c6bb5ea27451b0f804821a not found I1002 22:29:56.841] make[2]: Entering directory '/go/src/github.com/kubernetes-sigs/azuredisk-csi-driver' I1002 22:29:56.846] if [ ! -d ./vendor ]; then dep ensure -vendor-only; fi I1002 22:29:56.848] CGO_ENABLED=0 GOOS=linux go build -a -ldflags "-X github.com/kubernetes-sigs/azuredisk-csi-driver/pkg/azuredisk.driverVersion=e2e-0f439f89acfd5bbdb1c6bb5ea27451b0f804821a -X github.com/kubernetes-sigs/azuredisk-csi-driver/pkg/azuredisk.gitCommit=0f439f89acfd5bbdb1c6bb5ea27451b0f804821a -X github.com/kubernetes-sigs/azuredisk-csi-driver/pkg/azuredisk.buildDate=2019-10-02T22:29:56Z -X github.com/kubernetes-sigs/azuredisk-csi-driver/pkg/azuredisk.DriverName=disk.csi.azure.com -X github.com/kubernetes-sigs/azuredisk-csi-driver/pkg/azuredisk.topologyKey=topology.disk.csi.azure.com/zone -extldflags "-static"" -o _output/azurediskplugin ./pkg/azurediskplugin I1002 22:30:30.295] docker build --no-cache -t k8sprowinternal.azurecr.io/azuredisk-csi:e2e-0f439f89acfd5bbdb1c6bb5ea27451b0f804821a -f ./pkg/azurediskplugin/Dockerfile . I1002 22:30:31.914] Sending build context to Docker daemon 187.1MB I1002 22:30:31.945] Step 1/6 : FROM debian:9 ... skipping 256 lines ... I1002 22:32:16.226] Oct 2 22:32:16.226: INFO: PersistentVolumeClaim pvc-2j9d4 found but phase is Pending instead of Bound. I1002 22:32:18.294] Oct 2 22:32:18.294: INFO: PersistentVolumeClaim pvc-2j9d4 found and phase=Bound (12.478520537s) I1002 22:32:18.294] STEP: checking the PVC I1002 22:32:18.361] STEP: validating provisioned PV I1002 22:32:18.429] STEP: checking the PV I1002 22:32:18.429] STEP: deploying the pod I1002 22:32:18.498] STEP: checking that the pods command exits with no error I1002 22:32:18.498] Oct 2 22:32:18.497: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-8z5rj" in namespace "azuredisk-7880" to be "success or failure" I1002 22:32:18.565] Oct 2 22:32:18.565: INFO: Pod "azuredisk-volume-tester-8z5rj": Phase="Pending", Reason="", readiness=false. Elapsed: 67.531748ms I1002 22:32:20.634] Oct 2 22:32:20.633: INFO: Pod "azuredisk-volume-tester-8z5rj": Phase="Pending", Reason="", readiness=false. Elapsed: 2.135960295s I1002 22:32:22.702] Oct 2 22:32:22.702: INFO: Pod "azuredisk-volume-tester-8z5rj": Phase="Pending", Reason="", readiness=false. Elapsed: 4.204590952s I1002 22:32:24.771] Oct 2 22:32:24.770: INFO: Pod "azuredisk-volume-tester-8z5rj": Phase="Pending", Reason="", readiness=false. Elapsed: 6.272957216s I1002 22:32:26.839] Oct 2 22:32:26.839: INFO: Pod "azuredisk-volume-tester-8z5rj": Phase="Pending", Reason="", readiness=false. Elapsed: 8.34143049s ... skipping 424 lines ... I1002 22:47:07.503] Oct 2 22:47:07.503: INFO: Pod "azuredisk-volume-tester-8z5rj": Phase="Pending", Reason="", readiness=false. Elapsed: 14m49.005479766s I1002 22:47:09.573] Oct 2 22:47:09.573: INFO: Pod "azuredisk-volume-tester-8z5rj": Phase="Pending", Reason="", readiness=false. Elapsed: 14m51.075596726s I1002 22:47:11.643] Oct 2 22:47:11.643: INFO: Pod "azuredisk-volume-tester-8z5rj": Phase="Pending", Reason="", readiness=false. Elapsed: 14m53.145465185s I1002 22:47:13.713] Oct 2 22:47:13.713: INFO: Pod "azuredisk-volume-tester-8z5rj": Phase="Pending", Reason="", readiness=false. Elapsed: 14m55.215114545s I1002 22:47:15.783] Oct 2 22:47:15.783: INFO: Pod "azuredisk-volume-tester-8z5rj": Phase="Pending", Reason="", readiness=false. Elapsed: 14m57.285413011s I1002 22:47:17.854] Oct 2 22:47:17.854: INFO: Pod "azuredisk-volume-tester-8z5rj": Phase="Pending", Reason="", readiness=false. Elapsed: 14m59.356105282s I1002 22:47:19.854] Oct 2 22:47:19.854: INFO: Unexpected error occurred: Gave up after waiting 15m0s for pod "azuredisk-volume-tester-8z5rj" to be "success or failure" I1002 22:47:19.854] Oct 2 22:47:19.854: INFO: deleting Pod "azuredisk-7880"/"azuredisk-volume-tester-8z5rj" I1002 22:47:19.954] Oct 2 22:47:19.954: INFO: Error getting logs for pod azuredisk-volume-tester-8z5rj: the server rejected our request for an unknown reason (get pods azuredisk-volume-tester-8z5rj) I1002 22:47:19.955] STEP: Deleting pod azuredisk-volume-tester-8z5rj in namespace azuredisk-7880 I1002 22:47:20.025] Oct 2 22:47:20.024: INFO: deleting PVC "azuredisk-7880"/"pvc-2j9d4" I1002 22:47:20.025] Oct 2 22:47:20.024: INFO: Deleting PersistentVolumeClaim "pvc-2j9d4" I1002 22:47:20.095] STEP: waiting for claim's PV "pvc-c5fb70eb-2363-460a-9cb5-ab694c8623ea" to be deleted I1002 22:47:20.096] Oct 2 22:47:20.095: INFO: Waiting up to 10m0s for PersistentVolume pvc-c5fb70eb-2363-460a-9cb5-ab694c8623ea to get deleted I1002 22:47:20.165] Oct 2 22:47:20.164: INFO: PersistentVolume pvc-c5fb70eb-2363-460a-9cb5-ab694c8623ea found and phase=Bound (69.188021ms) ... skipping 14 lines ... I1002 22:48:05.936] STEP: Collecting events from namespace "azuredisk-7880". I1002 22:48:06.005] STEP: Found 8 events. I1002 22:48:06.005] Oct 2 22:48:06.005: INFO: At 2019-10-02 22:32:05 +0000 UTC - event for pvc-2j9d4: {disk.csi.azure.com_csi-azuredisk-controller-657c68b968-nkkzl_746f70d3-e564-11e9-b2fb-76f21099fb6f } Provisioning: External provisioner is provisioning volume for claim "azuredisk-7880/pvc-2j9d4" I1002 22:48:06.006] Oct 2 22:48:06.005: INFO: At 2019-10-02 22:32:05 +0000 UTC - event for pvc-2j9d4: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "disk.csi.azure.com" or manually created by system administrator I1002 22:48:06.006] Oct 2 22:48:06.005: INFO: At 2019-10-02 22:32:16 +0000 UTC - event for pvc-2j9d4: {disk.csi.azure.com_csi-azuredisk-controller-657c68b968-nkkzl_746f70d3-e564-11e9-b2fb-76f21099fb6f } ProvisioningSucceeded: Successfully provisioned volume pvc-c5fb70eb-2363-460a-9cb5-ab694c8623ea I1002 22:48:06.006] Oct 2 22:48:06.005: INFO: At 2019-10-02 22:32:18 +0000 UTC - event for azuredisk-volume-tester-8z5rj: {default-scheduler } Scheduled: Successfully assigned azuredisk-7880/azuredisk-volume-tester-8z5rj to k8s-agentpool1-39643736-0 I1002 22:48:06.006] Oct 2 22:48:06.005: INFO: At 2019-10-02 22:32:33 +0000 UTC - event for azuredisk-volume-tester-8z5rj: {attachdetach-controller } FailedAttachVolume: AttachVolume.Attach failed for volume "pvc-c5fb70eb-2363-460a-9cb5-ab694c8623ea" : attachment timeout for volume /subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/kubetest-c3e42932-e55f-11e9-9f99-0242f3679761/providers/Microsoft.Compute/disks/pvc-c5fb70eb-2363-460a-9cb5-ab694c8623ea I1002 22:48:06.007] Oct 2 22:48:06.005: INFO: At 2019-10-02 22:32:48 +0000 UTC - event for azuredisk-volume-tester-8z5rj: {attachdetach-controller } FailedAttachVolume: AttachVolume.Attach failed for volume "pvc-c5fb70eb-2363-460a-9cb5-ab694c8623ea" : rpc error: code = Unknown desc = Attach volume "/subscriptions/940f88ce-a64b-4e73-a258-9931349b9789/resourceGroups/kubetest-c3e42932-e55f-11e9-9f99-0242f3679761/providers/Microsoft.Compute/disks/pvc-c5fb70eb-2363-460a-9cb5-ab694c8623ea" to instance "k8s-agentpool1-39643736-0" failed with failed to get azure instance id for node "k8s-agentpool1-39643736-0" (Get http://169.254.169.254/metadata/instance?api-version=2019-03-11&format=json: dial tcp 169.254.169.254:80: i/o timeout) I1002 22:48:06.007] Oct 2 22:48:06.005: INFO: At 2019-10-02 22:34:21 +0000 UTC - event for azuredisk-volume-tester-8z5rj: {kubelet k8s-agentpool1-39643736-0} FailedMount: Unable to mount volumes for pod "azuredisk-volume-tester-8z5rj_azuredisk-7880(c0a372e1-81bf-4880-af53-7e54cc3e75c1)": timeout expired waiting for volumes to attach or mount for pod "azuredisk-7880"/"azuredisk-volume-tester-8z5rj". list of unmounted volumes=[test-volume-1]. list of unattached volumes=[test-volume-1 default-token-8jvcx] I1002 22:48:06.008] Oct 2 22:48:06.005: INFO: At 2019-10-02 22:48:01 +0000 UTC - event for azuredisk-volume-tester-8z5rj: {kubelet k8s-agentpool1-39643736-0} FailedMount: Unable to mount volumes for pod "azuredisk-volume-tester-8z5rj_azuredisk-7880(c0a372e1-81bf-4880-af53-7e54cc3e75c1)": timeout expired waiting for volumes to attach or mount for pod "azuredisk-7880"/"azuredisk-volume-tester-8z5rj". list of unmounted volumes=[test-volume-1 default-token-8jvcx]. list of unattached volumes=[test-volume-1 default-token-8jvcx] I1002 22:48:06.075] Oct 2 22:48:06.074: INFO: POD NODE PHASE GRACE CONDITIONS I1002 22:48:06.075] Oct 2 22:48:06.074: INFO: I1002 22:48:06.214] Oct 2 22:48:06.214: INFO: I1002 22:48:06.214] Logging node info for node k8s-agentpool1-39643736-0 ... skipping 83 lines ... I1002 22:48:16.573] • Failure [972.160 seconds] I1002 22:48:16.573] Dynamic Provisioning I1002 22:48:16.573] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:30 I1002 22:48:16.573] should create a volume on demand [It] I1002 22:48:16.573] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e/dynamic_provisioning.go:45 I1002 22:48:16.574] I1002 22:48:16.574] Unexpected error: I1002 22:48:16.574] <*errors.errorString | 0xc000866660>: { I1002 22:48:16.574] s: "Gave up after waiting 15m0s for pod \"azuredisk-volume-tester-8z5rj\" to be \"success or failure\"", I1002 22:48:16.574] } I1002 22:48:16.574] Gave up after waiting 15m0s for pod "azuredisk-volume-tester-8z5rj" to be "success or failure" I1002 22:48:16.574] occurred I1002 22:48:16.574] ... skipping 23 lines ... I1002 22:48:19.143] Oct 2 22:48:19.142: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-hzf58] to have phase Bound I1002 22:48:19.211] Oct 2 22:48:19.211: INFO: PersistentVolumeClaim pvc-hzf58 found and phase=Bound (68.89972ms) I1002 22:48:19.212] STEP: checking the PVC I1002 22:48:19.280] STEP: validating provisioned PV I1002 22:48:19.349] STEP: checking the PV I1002 22:48:19.349] STEP: deploying the pod I1002 22:48:19.419] STEP: checking that the pods command exits with an error I1002 22:48:19.419] Oct 2 22:48:19.419: INFO: Waiting up to 15m0s for pod "azuredisk-volume-tester-pl24g" in namespace "azuredisk-8543" to be "Error status code" I1002 22:48:19.489] Oct 2 22:48:19.488: INFO: Pod "azuredisk-volume-tester-pl24g": Phase="Pending", Reason="", readiness=false. Elapsed: 69.425523ms I1002 22:48:21.562] Oct 2 22:48:21.561: INFO: Pod "azuredisk-volume-tester-pl24g": Phase="Pending", Reason="", readiness=false. Elapsed: 2.142553257s I1002 22:48:23.632] Oct 2 22:48:23.632: INFO: Pod "azuredisk-volume-tester-pl24g": Phase="Pending", Reason="", readiness=false. Elapsed: 4.212571768s I1002 22:48:25.702] Oct 2 22:48:25.702: INFO: Pod "azuredisk-volume-tester-pl24g": Phase="Pending", Reason="", readiness=false. Elapsed: 6.28259108s I1002 22:48:27.772] Oct 2 22:48:27.771: INFO: Pod "azuredisk-volume-tester-pl24g": Phase="Pending", Reason="", readiness=false. Elapsed: 8.352487093s I1002 22:48:29.843] Oct 2 22:48:29.842: INFO: Pod "azuredisk-volume-tester-pl24g": Phase="Pending", Reason="", readiness=false. Elapsed: 10.423559416s ... skipping 486 lines ... I1002 22:59:44.862] github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/golang.org/x/net/http2.(*clientConnReadLoop).run(0xc000289fb8, 0x1e2e320, 0xc000136fb8) I1002 22:59:44.862] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/golang.org/x/net/http2/transport.go:1686 +0x8d I1002 22:59:44.862] github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/golang.org/x/net/http2.(*ClientConn).readLoop(0xc0008b8300) I1002 22:59:44.862] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/golang.org/x/net/http2/transport.go:1614 +0x76 I1002 22:59:44.863] created by github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/golang.org/x/net/http2.(*Transport).newClientConn I1002 22:59:44.863] /go/src/github.com/kubernetes-sigs/azuredisk-csi-driver/vendor/golang.org/x/net/http2/transport.go:673 +0x637 I1002 22:59:44.863] FAIL github.com/kubernetes-sigs/azuredisk-csi-driver/test/e2e 1800.054s I1002 22:59:45.022] Makefile:59: recipe for target 'e2e-test' failed W1002 22:59:45.122] make: *** [e2e-test] Error 1 W1002 22:59:45.122] 2019/10/02 22:59:45 process.go:155: Step 'make e2e-test' finished in 30m48.796996589s W1002 22:59:45.123] 2019/10/02 22:59:45 azure.go:901: Deleting resource group: kubetest-c3e42932-e55f-11e9-9f99-0242f3679761. W1002 23:10:40.138] 2019/10/02 23:10:40 process.go:96: Saved XML output to /workspace/_artifacts/junit_runner.xml. W1002 23:10:40.139] 2019/10/02 23:10:40 process.go:153: Running: bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}" W1002 23:10:40.814] 2019/10/02 23:10:40 process.go:155: Step 'bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}"' finished in 675.875351ms W1002 23:10:40.815] 2019/10/02 23:10:40 main.go:319: Something went wrong: encountered 1 errors: [error during make e2e-test: exit status 2] W1002 23:10:40.816] Traceback (most recent call last): W1002 23:10:40.817] File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 778, in <module> W1002 23:10:40.817] main(parse_args()) W1002 23:10:40.817] File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 626, in main W1002 23:10:40.818] mode.start(runner_args) W1002 23:10:40.818] File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 262, in start W1002 23:10:40.818] check_env(env, self.command, *args) W1002 23:10:40.818] File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 111, in check_env W1002 23:10:40.818] subprocess.check_call(cmd, env=env) W1002 23:10:40.819] File "/usr/lib/python2.7/subprocess.py", line 186, in check_call W1002 23:10:40.819] raise CalledProcessError(retcode, cmd) W1002 23:10:40.819] 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/cloud-provider-azure/master/tests/k8s-azure/manifest/linux.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')' returned non-zero exit status 1 E1002 23:10:40.824] Command failed I1002 23:10:40.825] process 689 exited with code 1 after 72.2m E1002 23:10:40.825] FAIL: pull-azuredisk-csi-driver-e2e I1002 23:10:40.825] Call: gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json W1002 23:10:41.620] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com] I1002 23:10:41.653] process 27900 exited with code 0 after 0.0m I1002 23:10:41.653] Call: gcloud config get-value account I1002 23:10:41.902] process 27912 exited with code 0 after 0.0m I1002 23:10:41.902] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com I1002 23:10:41.902] Upload result and artifacts... I1002 23:10:41.902] Gubernator results at https://gubernator.k8s.io/build/kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azuredisk-csi-driver/166/pull-azuredisk-csi-driver-e2e/1179515703451979776 I1002 23:10:41.902] Call: gsutil ls gs://kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azuredisk-csi-driver/166/pull-azuredisk-csi-driver-e2e/1179515703451979776/artifacts W1002 23:10:43.301] CommandException: One or more URLs matched no objects. E1002 23:10:43.377] Command failed I1002 23:10:43.378] process 27924 exited with code 1 after 0.0m W1002 23:10:43.378] Remote dir gs://kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azuredisk-csi-driver/166/pull-azuredisk-csi-driver-e2e/1179515703451979776/artifacts not exist yet I1002 23:10:43.378] Call: gsutil -m -q -o GSUtil:use_magicfile=True cp -r -c -z log,txt,xml /workspace/_artifacts gs://kubernetes-upstream/pr-logs/pull/kubernetes-sigs_azuredisk-csi-driver/166/pull-azuredisk-csi-driver-e2e/1179515703451979776/artifacts I1002 23:10:45.020] process 28066 exited with code 0 after 0.0m I1002 23:10:45.021] Call: git rev-parse HEAD I1002 23:10:45.024] process 28593 exited with code 0 after 0.0m ... skipping 21 lines ...