W1011 02:31:25.992] ************************************************************************** bootstrap.py is deprecated! test-infra oncall does not support any job still using bootstrap.py. Please migrate your job to podutils! https://github.com/kubernetes/test-infra/blob/master/prow/pod-utilities.md ************************************************************************** I1011 02:31:25.992] Args: --job=pull-azurefile-csi-driver-e2e --service-account=/etc/service-account/service-account.json --upload=gs://kubernetes-jenkins/logs --job=pull-azurefile-csi-driver-e2e --root=/go/src --service-account=/etc/service-account/service-account.json --repo=k8s.io/kubernetes --repo=sigs.k8s.io/azurefile-csi-driver=master:bd996ff37f2d725eac026d19a820ba7afeb19293,120:c075484419b673a81ba808302593ef28209eacbf --upload=gs://kubernetes-upstream/pr-logs --scenario=kubernetes_e2e --timeout=450 -- --gce-ssh= --test=true --up=true --down=true --deployment=acsengine --build=bazel --provider=skeleton --ginkgo-parallel=1 --acsengine-agentpoolcount=2 --acsengine-admin-username=azureuser '--acsengine-creds=$AZURE_CREDENTIALS' --acsengine-orchestratorRelease=1.16 --acsengine-mastervmsize=Standard_DS2_v2 --acsengine-agentvmsize=Standard_D4s_v3 --acsengine-location=eastus2 '--acsengine-public-key=$AZURE_SSH_PUBLIC_KEY_FILE' --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-file-csi-driver=True --timeout=420m --use-logexporter I1011 02:31:25.993] Bootstrap pull-azurefile-csi-driver-e2e... I1011 02:31:25.996] Builder: 2a265871-ebcf-11e9-b3d3-b20db476995a I1011 02:31:25.996] Image: chewong/kubekins-e2e:v20191010-test I1011 02:31:25.997] Gubernator results at https://gubernator.k8s.io/build/kubernetes-upstream/pr-logs/pull/sigs.k8s.io_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/1182483760709373952 I1011 02:31:25.997] Call: gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json W1011 02:31:26.517] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com] I1011 02:31:26.552] process 215 exited with code 0 after 0.0m I1011 02:31:26.553] Call: gcloud config get-value account I1011 02:31:26.798] process 227 exited with code 0 after 0.0m I1011 02:31:26.798] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com I1011 02:31:26.798] Root: /go/src I1011 02:31:26.798] cd to /go/src I1011 02:31:26.799] Checkout: /go/src/k8s.io/kubernetes master to /go/src/k8s.io/kubernetes I1011 02:31:26.799] Call: git init k8s.io/kubernetes I1011 02:31:26.803] Initialized empty Git repository in /go/src/k8s.io/kubernetes/.git/ I1011 02:31:26.804] process 239 exited with code 0 after 0.0m I1011 02:31:26.804] Call: git config --local user.name 'K8S Bootstrap' I1011 02:31:26.806] process 240 exited with code 0 after 0.0m I1011 02:31:26.807] Call: git config --local user.email k8s_bootstrap@localhost I1011 02:31:26.809] process 241 exited with code 0 after 0.0m I1011 02:31:26.809] Call: git fetch --quiet --tags https://github.com/kubernetes/kubernetes master I1011 02:32:18.641] process 242 exited with code 0 after 0.9m I1011 02:32:18.642] Call: git checkout -B test FETCH_HEAD W1011 02:32:20.827] Switched to a new branch 'test' I1011 02:32:20.836] process 254 exited with code 0 after 0.0m I1011 02:32:20.837] Call: git show -s --format=format:%ct HEAD I1011 02:32:20.844] process 255 exited with code 0 after 0.0m I1011 02:32:20.844] Checkout: /go/src/sigs.k8s.io/azurefile-csi-driver master:bd996ff37f2d725eac026d19a820ba7afeb19293,120:c075484419b673a81ba808302593ef28209eacbf to /go/src/sigs.k8s.io/azurefile-csi-driver I1011 02:32:20.845] Call: git init sigs.k8s.io/azurefile-csi-driver I1011 02:32:20.848] Initialized empty Git repository in /go/src/sigs.k8s.io/azurefile-csi-driver/.git/ I1011 02:32:20.848] process 256 exited with code 0 after 0.0m I1011 02:32:20.848] Call: git config --local user.name 'K8S Bootstrap' I1011 02:32:20.851] process 257 exited with code 0 after 0.0m I1011 02:32:20.851] Call: git config --local user.email k8s_bootstrap@localhost I1011 02:32:20.854] process 258 exited with code 0 after 0.0m I1011 02:32:20.854] Call: git fetch --quiet --tags https://github.com/kubernetes-sigs/azurefile-csi-driver master +refs/pull/120/head:refs/pr/120 I1011 02:32:25.794] process 259 exited with code 0 after 0.1m I1011 02:32:25.794] Call: git checkout -B test bd996ff37f2d725eac026d19a820ba7afeb19293 W1011 02:32:26.240] Switched to a new branch 'test' I1011 02:32:26.242] process 271 exited with code 0 after 0.0m I1011 02:32:26.242] Call: git show -s --format=format:%ct HEAD I1011 02:32:26.245] process 272 exited with code 0 after 0.0m I1011 02:32:26.246] Call: git merge --no-ff -m 'Merge +refs/pull/120/head:refs/pr/120' c075484419b673a81ba808302593ef28209eacbf I1011 02:32:26.523] Auto-merging test/utils/credentials/credentials_test.go I1011 02:32:26.523] Auto-merging test/utils/credentials/credentials.go I1011 02:32:26.523] Removing test/e2e/run-test.sh I1011 02:32:26.523] Removing hack/template/azure.json I1011 02:32:26.524] Merge made by the 'recursive' strategy. I1011 02:32:26.527] .travis.yml | 9 --- I1011 02:32:26.527] Makefile | 63 +++++++++++------ I1011 02:32:26.527] hack/template/azure.json | 9 --- I1011 02:32:26.527] test/e2e/README.md | 24 +++++-- I1011 02:32:26.527] test/e2e/dynamic_provisioning.go | 17 ----- I1011 02:32:26.527] test/e2e/pre_provisioning.go | 23 +------ I1011 02:32:26.528] test/e2e/run-test.sh | 31 --------- I1011 02:32:26.528] test/e2e/suite_test.go | 87 ++++++++++++++++++++++++ I1011 02:32:26.528] test/integration/integration_test.go | 20 +++++- I1011 02:32:26.528] test/integration/run-test.sh | 4 +- I1011 02:32:26.528] test/integration/run-tests-all-clouds.sh | 11 ++- I1011 02:32:26.528] test/sanity/run-test.sh | 9 ++- I1011 02:32:26.528] test/sanity/run-tests-all-clouds.sh | 9 ++- I1011 02:32:26.528] test/sanity/sanity_test.go | 17 ++--- I1011 02:32:26.528] test/{ => utils}/azure/azure_helpers.go | 0 I1011 02:32:26.529] test/{ => utils}/credentials/credentials.go | 83 ++++++++++++++-------- I1011 02:32:26.529] test/{ => utils}/credentials/credentials_test.go | 54 +++++++-------- I1011 02:32:26.529] test/utils/testutil/testutil.go | 8 +++ I1011 02:32:26.529] 18 files changed, 290 insertions(+), 188 deletions(-) I1011 02:32:26.529] delete mode 100644 hack/template/azure.json I1011 02:32:26.529] delete mode 100755 test/e2e/run-test.sh I1011 02:32:26.529] rename test/{ => utils}/azure/azure_helpers.go (100%) I1011 02:32:26.529] rename test/{ => utils}/credentials/credentials.go (59%) I1011 02:32:26.530] rename test/{ => utils}/credentials/credentials_test.go (77%) I1011 02:32:26.530] create mode 100644 test/utils/testutil/testutil.go I1011 02:32:26.530] process 273 exited with code 0 after 0.0m I1011 02:32:26.530] Configure environment... I1011 02:32:26.530] Call: git show -s --format=format:%ct HEAD I1011 02:32:26.538] process 275 exited with code 0 after 0.0m I1011 02:32:26.538] Call: gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json W1011 02:32:27.265] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com] I1011 02:32:27.377] process 276 exited with code 0 after 0.0m I1011 02:32:27.377] Call: gcloud config get-value account I1011 02:32:27.615] process 288 exited with code 0 after 0.0m I1011 02:32:27.616] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com I1011 02:32:27.616] Call: bash -c ' set -o errexit set -o nounset export KUBE_ROOT=. source hack/lib/version.sh kube::version::get_version_vars echo $KUBE_GIT_VERSION ' I1011 02:32:28.171] process 300 exited with code 0 after 0.0m I1011 02:32:28.172] Start 1182483760709373952 at v1.17.0-alpha.1.326+5e0f48acf83c59... I1011 02:32:28.174] Call: gsutil -q -h Content-Type:application/json cp /tmp/gsutil_TbNemN gs://kubernetes-upstream/pr-logs/pull/sigs.k8s.io_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/1182483760709373952/started.json I1011 02:32:29.711] process 333 exited with code 0 after 0.0m I1011 02:32:29.711] Call: gsutil -q -h Content-Type:text/plain -h 'x-goog-meta-link: gs://kubernetes-upstream/pr-logs/pull/sigs.k8s.io_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/1182483760709373952' cp /tmp/gsutil_wyufBv gs://kubernetes-upstream/pr-logs/directory/pull-azurefile-csi-driver-e2e/1182483760709373952.txt I1011 02:32:31.122] process 511 exited with code 0 after 0.0m I1011 02:32:31.123] Call: /workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py --gce-ssh= --test=true --up=true --down=true --deployment=acsengine --build=bazel --provider=skeleton --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-file-csi-driver=True --timeout=420m --use-logexporter W1011 02:32:31.159] starts with local mode W1011 02:32:31.160] Environment: W1011 02:32:31.160] ARTIFACTS=/workspace/_artifacts W1011 02:32:31.160] AWS_SSH_PRIVATE_KEY_FILE=/root/.ssh/kube_aws_rsa W1011 02:32:31.160] AWS_SSH_PUBLIC_KEY_FILE=/root/.ssh/kube_aws_rsa.pub W1011 02:32:31.160] AZURE_CREDENTIALS=/etc/azure-cred/credentials W1011 02:32:31.160] AZURE_SSH_PUBLIC_KEY_FILE=/etc/azure-ssh/azure-ssh-pub W1011 02:32:31.161] AZ_STORAGE_CONTAINER_NAME=mystoragecontainer W1011 02:32:31.161] BAZEL_REMOTE_CACHE_ENABLED=false W1011 02:32:31.161] BAZEL_VERSION=0.23.2 W1011 02:32:31.161] BOOTSTRAP_MIGRATION=yes W1011 02:32:31.161] BUILD_ID=1182483760709373952 W1011 02:32:31.161] BUILD_NUMBER=1182483760709373952 W1011 02:32:31.161] CLOUDSDK_COMPONENT_MANAGER_DISABLE_UPDATE_CHECK=true W1011 02:32:31.162] CLOUDSDK_CONFIG=/go/src/k8s.io/kubernetes/.config/gcloud W1011 02:32:31.162] CLOUDSDK_CORE_DISABLE_PROMPTS=1 W1011 02:32:31.162] CLOUDSDK_EXPERIMENTAL_FAST_COMPONENT_UPDATE=false W1011 02:32:31.162] CLOUD_CONFIG=random W1011 02:32:31.162] DECK_PORT=tcp://10.0.160.83:80 W1011 02:32:31.162] DECK_PORT_80_TCP=tcp://10.0.160.83:80 W1011 02:32:31.162] DECK_PORT_80_TCP_ADDR=10.0.160.83 W1011 02:32:31.163] DECK_PORT_80_TCP_PORT=80 W1011 02:32:31.163] DECK_PORT_80_TCP_PROTO=tcp W1011 02:32:31.163] DECK_SERVICE_HOST=10.0.160.83 W1011 02:32:31.163] DECK_SERVICE_PORT=80 W1011 02:32:31.163] DOCKER_IN_DOCKER_ENABLED=true W1011 02:32:31.163] DOCKER_IN_DOCKER_IPV6_ENABLED=false W1011 02:32:31.164] GCS_ARTIFACTS_DIR=gs://kubernetes-upstream/pr-logs/pull/sigs.k8s.io_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/1182483760709373952/artifacts W1011 02:32:31.164] GOOGLE_APPLICATION_CREDENTIALS=/etc/service-account/service-account.json W1011 02:32:31.164] GOPATH=/go W1011 02:32:31.164] GO_TARBALL=go1.12.1.linux-amd64.tar.gz W1011 02:32:31.164] HOME=/workspace W1011 02:32:31.164] HOOK_PORT=tcp://10.0.144.133:8888 W1011 02:32:31.164] HOOK_PORT_8888_TCP=tcp://10.0.144.133:8888 W1011 02:32:31.164] HOOK_PORT_8888_TCP_ADDR=10.0.144.133 W1011 02:32:31.165] HOOK_PORT_8888_TCP_PORT=8888 W1011 02:32:31.165] HOOK_PORT_8888_TCP_PROTO=tcp W1011 02:32:31.165] HOOK_SERVICE_HOST=10.0.144.133 W1011 02:32:31.165] HOOK_SERVICE_PORT=8888 W1011 02:32:31.165] HOSTNAME=2a265871-ebcf-11e9-b3d3-b20db476995a W1011 02:32:31.165] IMAGE=chewong/kubekins-e2e:v20191010-test W1011 02:32:31.166] INSTANCE_PREFIX=bootstrap-e2e W1011 02:32:31.166] JENKINS_GCE_SSH_PRIVATE_KEY_FILE=/root/.ssh/google_compute_engine W1011 02:32:31.166] JENKINS_GCE_SSH_PUBLIC_KEY_FILE=/root/.ssh/google_compute_engine.pub W1011 02:32:31.166] JOB_NAME=pull-azurefile-csi-driver-e2e W1011 02:32:31.166] JOB_SPEC={"type":"presubmit","job":"pull-azurefile-csi-driver-e2e","buildid":"1182483760709373952","prowjobid":"2a265871-ebcf-11e9-b3d3-b20db476995a","refs":{"org":"Azure","repo":"kubernetes","repo_link":"https://github.com/Azure/kubernetes","base_ref":"master","base_sha":"4d6deea24179a72f36f252664937d2585598ee30","base_link":"https://github.com/Azure/kubernetes/commit/4d6deea24179a72f36f252664937d2585598ee30","pulls":[{"number":113,"author":"chewong","sha":"879465972041635fd7bc8269da49153b67e63822","link":"https://github.com/Azure/kubernetes/pull/113","commit_link":"https://github.com/Azure/kubernetes/pull/113/commits/879465972041635fd7bc8269da49153b67e63822","author_link":"https://github.com/chewong"}]}} W1011 02:32:31.167] JOB_TYPE=presubmit W1011 02:32:31.167] KUBERNETES_PORT=tcp://10.0.0.1:443 W1011 02:32:31.167] KUBERNETES_PORT_443_TCP=tcp://10.0.0.1:443 W1011 02:32:31.167] KUBERNETES_PORT_443_TCP_ADDR=10.0.0.1 W1011 02:32:31.167] KUBERNETES_PORT_443_TCP_PORT=443 W1011 02:32:31.167] KUBERNETES_PORT_443_TCP_PROTO=tcp W1011 02:32:31.167] KUBERNETES_SERVICE_HOST=10.0.0.1 W1011 02:32:31.168] KUBERNETES_SERVICE_PORT=443 W1011 02:32:31.168] KUBERNETES_SERVICE_PORT_HTTPS=443 W1011 02:32:31.168] KUBETEST_IN_DOCKER=true W1011 02:32:31.168] KUBETEST_MANUAL_DUMP=y W1011 02:32:31.168] KUBE_AWS_INSTANCE_PREFIX=bootstrap-e2e W1011 02:32:31.168] KUBE_GCE_INSTANCE_PREFIX=bootstrap-e2e W1011 02:32:31.168] KUBE_VERBOSE=0 W1011 02:32:31.169] NODE_NAME=2a265871-ebcf-11e9-b3d3-b20db476995a W1011 02:32:31.169] PATH=/go/bin:/go/bin:/usr/local/go/bin:/google-cloud-sdk/bin:/workspace:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin W1011 02:32:31.169] PROW_JOB_ID=2a265871-ebcf-11e9-b3d3-b20db476995a W1011 02:32:31.169] PULL_BASE_REF=master W1011 02:32:31.169] PULL_BASE_SHA=4d6deea24179a72f36f252664937d2585598ee30 W1011 02:32:31.169] PULL_NUMBER=113 W1011 02:32:31.169] PULL_PULL_SHA=879465972041635fd7bc8269da49153b67e63822 W1011 02:32:31.170] PULL_REFS=master:4d6deea24179a72f36f252664937d2585598ee30,113:879465972041635fd7bc8269da49153b67e63822 W1011 02:32:31.170] PWD=/workspace W1011 02:32:31.170] REGISTRY=k8sprowinternal.azurecr.io W1011 02:32:31.170] REPO_NAME=kubernetes W1011 02:32:31.170] REPO_OWNER=Azure W1011 02:32:31.170] SHLVL=2 W1011 02:32:31.170] SOURCE_DATE_EPOCH=1570759252 W1011 02:32:31.171] TERM=xterm W1011 02:32:31.171] TIDE_PORT=tcp://10.0.180.53:80 W1011 02:32:31.171] TIDE_PORT_80_TCP=tcp://10.0.180.53:80 W1011 02:32:31.171] TIDE_PORT_80_TCP_ADDR=10.0.180.53 W1011 02:32:31.171] TIDE_PORT_80_TCP_PORT=80 W1011 02:32:31.171] TIDE_PORT_80_TCP_PROTO=tcp W1011 02:32:31.171] TIDE_SERVICE_HOST=10.0.180.53 W1011 02:32:31.171] TIDE_SERVICE_PORT=80 W1011 02:32:31.172] WORKSPACE=/workspace W1011 02:32:31.172] _=./test-infra/jenkins/bootstrap.py W1011 02:32:31.172] Run: ('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-file-csi-driver=True', '--timeout=420m', '--logexporter-gcs-path=gs://kubernetes-upstream/pr-logs/pull/sigs.k8s.io_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/1182483760709373952/artifacts') W1011 02:32:31.308] 2019/10/11 02:32:31 main.go:332: Limiting testing to 7h0m0s W1011 02:32:31.309] 2019/10/11 02:32:31 azure.go:232: Reading credentials file /etc/azure-cred/credentials W1011 02:32:31.310] 2019/10/11 02:32:31 process.go:153: Running: make -C /go/src/k8s.io/kubernetes bazel-release W1011 02:32:31.388] Extracting Bazel installation... I1011 02:32:31.488] make: Entering directory '/go/src/k8s.io/kubernetes' W1011 02:32:40.086] Starting local Bazel server and connecting to it... W1011 02:32:41.786] Loading: W1011 02:32:41.790] Loading: 0 packages loaded W1011 02:32:42.792] Loading: 0 packages loaded W1011 02:32:44.381] Loading: 0 packages loaded W1011 02:32:45.793] Loading: 0 packages loaded W1011 02:32:47.776] Loading: 0 packages loaded W1011 02:32:48.793] Loading: 0 packages loaded W1011 02:32:48.794] currently loading: build/release-tars W1011 02:32:50.907] Loading: 0 packages loaded W1011 02:32:50.908] currently loading: build/release-tars W1011 02:32:51.306] Analyzing: target //build/release-tars:release-tars (1 packages loaded, 0 targets configured) W1011 02:32:52.758] Analyzing: target //build/release-tars:release-tars (195 packages loaded, 1039 targets configured) W1011 02:32:54.435] Analyzing: target //build/release-tars:release-tars (780 packages loaded, 3431 targets configured) W1011 02:32:56.355] Analyzing: target //build/release-tars:release-tars (1771 packages loaded, 9288 targets configured) W1011 02:32:58.723] Analyzing: target //build/release-tars:release-tars (2564 packages loaded, 19172 targets configured) W1011 02:33:01.488] Analyzing: target //build/release-tars:release-tars (3036 packages loaded, 27189 targets configured) W1011 02:33:04.478] Analyzing: target //build/release-tars:release-tars (3072 packages loaded, 30976 targets configured) W1011 02:33:08.537] Analyzing: target //build/release-tars:release-tars (3080 packages loaded, 34696 targets configured) W1011 02:33:26.350] INFO: Analysed target //build/release-tars:release-tars (3080 packages loaded, 42328 targets configured). W1011 02:33:26.353] Building: checking cached actions W1011 02:33:26.353] INFO: Found 1 target... W1011 02:33:26.550] [0 / 21] [-----] BazelWorkspaceStatusAction stable-status.txt W1011 02:33:33.300] [103 / 3,644] GoCompile vendor/golang.org/x/text/unicode/norm/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/golang.org/x/text/unicode/norm.a; 0s linux-sandbox ... (7 actions, 6 running) W1011 02:33:41.650] [140 / 3,644] GoCompile vendor/github.com/gophercloud/gophercloud/openstack/compute/v2/servers/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/gophercloud/gophercloud/openstack/compute/v2/servers.a; 1s linux-sandbox ... (6 actions, 5 running) W1011 02:33:50.658] [482 / 3,644] Compiling vendor/golang.org/x/sys/unix/linux_amd64_stripped/go_default_library%linux_amd64%cgo_codegen%/zsysnum_linux_mipsle.cgo2.c; 0s linux-sandbox ... (6 actions running) W1011 02:34:01.018] [682 / 3,644] GoCompile vendor/github.com/vmware/govmomi/vim25/types/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/vmware/govmomi/vim25/types.a; 1s linux-sandbox ... (7 actions, 6 running) W1011 02:34:13.190] [793 / 3,644] GoCompile vendor/github.com/vmware/govmomi/vim25/types/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/vmware/govmomi/vim25/types.a; 13s linux-sandbox ... (8 actions, 7 running) W1011 02:34:27.493] [915 / 3,644] GoCompile vendor/github.com/thecodeteam/goscaleio/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/thecodeteam/goscaleio.a; 2s linux-sandbox ... (8 actions, 7 running) W1011 02:34:44.148] [1,037 / 3,644] GoStdlib external/io_bazel_rules_go/linux_amd64_pure_stripped/stdlib%/pkg; 10s linux-sandbox ... (8 actions running) W1011 02:35:03.256] [1,095 / 3,644] GoStdlib external/io_bazel_rules_go/linux_amd64_pure_stripped/stdlib%/pkg; 29s linux-sandbox ... (8 actions, 7 running) W1011 02:35:25.850] [1,169 / 3,718] GoStdlib external/io_bazel_rules_go/linux_amd64_pure_stripped/stdlib%/pkg; 52s linux-sandbox ... (8 actions running) W1011 02:35:50.808] [1,268 / 3,743] ; 23s linux-sandbox ... (8 actions, 7 running) W1011 02:36:20.100] [1,325 / 3,743] GoCompile staging/src/k8s.io/client-go/scale/scheme/autoscalingv1/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/k8s.io/client-go/scale/scheme/autoscalingv1.a; 4s linux-sandbox ... (8 actions running) W1011 02:36:53.387] [1,653 / 3,743] GoCompile vendor/github.com/globalsign/mgo/internal/json/linux_amd64_pure_stripped/go_default_library%/k8s.io/kubernetes/vendor/github.com/globalsign/mgo/internal/json.a; 2s linux-sandbox ... (8 actions, 7 running) W1011 02:37:32.324] [1,971 / 3,743] GoCompile vendor/gonum.org/v1/gonum/graph/simple/linux_amd64_pure_stripped/go_default_library%/k8s.io/kubernetes/vendor/gonum.org/v1/gonum/graph/simple.a; 1s linux-sandbox ... (7 actions, 6 running) W1011 02:38:15.936] [2,190 / 3,743] GoCompile staging/src/k8s.io/client-go/kubernetes/typed/extensions/v1beta1/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/vendor/k8s.io/client-go/kubernetes/typed/extensions/v1beta1.a; 0s linux-sandbox ... (8 actions, 7 running) W1011 02:39:06.103] [2,486 / 3,768] GoCompile staging/src/k8s.io/api/admissionregistration/v1/linux_amd64_pure_stripped/go_default_library%/k8s.io/kubernetes/vendor/k8s.io/api/admissionregistration/v1.a; 2s linux-sandbox ... (8 actions, 7 running) W1011 02:40:04.199] [2,771 / 3,768] GoCompile pkg/registry/storage/csinode/storage/linux_amd64_pure_stripped/go_default_library%/k8s.io/kubernetes/pkg/registry/storage/csinode/storage.a; 0s linux-sandbox ... (8 actions, 7 running) W1011 02:41:11.920] [3,187 / 3,768] GoCompile cmd/kubelet/app/linux_amd64_stripped/go_default_library%/k8s.io/kubernetes/cmd/kubelet/app.a; 2s linux-sandbox ... (8 actions, 7 running) W1011 02:42:28.601] [3,403 / 3,768] GoCompile staging/src/k8s.io/client-go/informers/autoscaling/v1/linux_amd64_pure_stripped/go_default_library%/k8s.io/kubernetes/vendor/k8s.io/client-go/informers/autoscaling/v1.a; 0s linux-sandbox ... (8 actions running) W1011 02:43:57.582] [3,687 / 3,816] GoLink cmd/kubeadm/linux_amd64_pure_stripped/kubeadm; 15s linux-sandbox ... (8 actions, 7 running) W1011 02:45:39.326] [4,053 / 4,314] GoLink cmd/genyaml/genyaml; 15s linux-sandbox ... (8 actions running) W1011 02:47:36.997] [4,864 / 4,971] GoLink cmd/genman/genman; 5s linux-sandbox ... (8 actions running) W1011 02:49:52.027] [5,285 / 5,306] GoLink test/e2e_node/linux_amd64_stripped/_go_default_test-cgo; 91s linux-sandbox ... (8 actions, 7 running) W1011 02:50:46.454] Target //build/release-tars:release-tars up-to-date: W1011 02:50:46.454] bazel-bin/build/release-tars/kubernetes-client-linux-amd64.tar.gz W1011 02:50:46.454] bazel-bin/build/release-tars/kubernetes-node-linux-amd64.tar.gz W1011 02:50:46.455] bazel-bin/build/release-tars/kubernetes-server-linux-amd64.tar.gz W1011 02:50:46.455] bazel-bin/build/release-tars/kubernetes-manifests.tar.gz W1011 02:50:46.456] bazel-bin/build/release-tars/kubernetes-test-portable.tar.gz W1011 02:50:46.456] bazel-bin/build/release-tars/kubernetes-test-linux-amd64.tar.gz W1011 02:50:46.456] bazel-bin/build/release-tars/kubernetes.tar.gz W1011 02:50:46.456] bazel-bin/build/release-tars/kubernetes-src.tar.gz W1011 02:50:46.486] INFO: Elapsed time: 1095.108s, Critical Path: 370.71s W1011 02:50:46.487] INFO: 5215 processes: 5215 linux-sandbox. W1011 02:50:46.493] INFO: Build completed successfully, 5306 total actions W1011 02:50:46.495] INFO: Build completed successfully, 5306 total actions W1011 02:50:46.504] 2019/10/11 02:50:46 process.go:155: Step 'make -C /go/src/k8s.io/kubernetes bazel-release' finished in 18m15.194192379s W1011 02:50:46.504] 2019/10/11 02:50:46 util.go:277: Flushing memory. I1011 02:50:46.605] make: Leaving directory '/go/src/k8s.io/kubernetes' W1011 02:51:12.382] 2019/10/11 02:51:12 azure.go:906: Deleting resource group: kubetest-600323a9-ebcf-11e9-b889-024252e495aa. W1011 02:51:12.951] 2019/10/11 02:51:12 azure.go:787: downloading /workspace/aks644083025/kubernetes.json from https://raw.githubusercontent.com/kubernetes/cloud-provider-azure/master/tests/k8s-azure/manifest/linux.json. W1011 02:51:12.951] 2019/10/11 02:51:12 util.go:42: curl https://raw.githubusercontent.com/kubernetes/cloud-provider-azure/master/tests/k8s-azure/manifest/linux.json W1011 02:51:13.116] 2019/10/11 02:51:13 azure.go:529: downloading /workspace/aks-engine.tar.gz from https://github.com/Azure/aks-engine/releases/download/v0.39.1/aks-engine-v0.39.1-linux-amd64.tar.gz. W1011 02:51:13.116] 2019/10/11 02:51:13 util.go:42: curl https://github.com/Azure/aks-engine/releases/download/v0.39.1/aks-engine-v0.39.1-linux-amd64.tar.gz W1011 02:51:14.311] 2019/10/11 02:51:14 azure.go:556: Extracting tar file /workspace/aks-engine.tar.gz into directory /go/src/k8s.io/kubernetes . W1011 02:51:14.311] 2019/10/11 02:51:14 process.go:153: Running: tar -xzf /workspace/aks-engine.tar.gz --strip 1 W1011 02:51:14.484] 2019/10/11 02:51:14 process.go:155: Step 'tar -xzf /workspace/aks-engine.tar.gz --strip 1' finished in 172.889147ms W1011 02:51:14.484] 2019/10/11 02:51:14 process.go:153: Running: /go/src/k8s.io/kubernetes/aks-engine generate /workspace/aks644083025/kubernetes.json --output-directory /workspace/aks644083025 I1011 02:51:14.693] INFO[0000] Generating assets into /workspace/aks644083025... W1011 02:51:24.294] 2019/10/11 02:51:24 process.go:155: Step '/go/src/k8s.io/kubernetes/aks-engine generate /workspace/aks644083025/kubernetes.json --output-directory /workspace/aks644083025' finished in 9.809803661s W1011 02:51:24.297] 2019/10/11 02:51:24 azure.go:627: Setting kubeconfig env variable: kubeconfig path: /workspace/aks644083025/kubeconfig/kubeconfig.eastus2.json. W1011 02:51:24.297] 2019/10/11 02:51:24 azure.go:629: Creating resource group: kubetest-600323a9-ebcf-11e9-b889-024252e495aa. W1011 02:51:24.297] 2019/10/11 02:51:24 azure.go:631: Creating Azure resource group: kubetest-600323a9-ebcf-11e9-b889-024252e495aa for cluster deployment. W1011 02:51:26.142] 2019/10/11 02:51:26 azure.go:636: Validating deployment ARM templates. W1011 02:51:28.420] 2019/10/11 02:51:28 azure.go:642: Deploying cluster kubetest-600323a9-ebcf-11e9-b889-024252e495aa in resource group kubetest-600323a9-ebcf-11e9-b889-024252e495aa. W1011 03:05:38.008] 2019/10/11 03:05:38 process.go:153: Running: ./cluster/kubectl.sh --match-server-version=false version W1011 03:05:38.679] 2019/10/11 03:05:38 process.go:155: Step './cluster/kubectl.sh --match-server-version=false version' finished in 671.809761ms W1011 03:05:38.680] 2019/10/11 03:05:38 process.go:153: Running: ./cluster/kubectl.sh --match-server-version=false get nodes -oyaml W1011 03:05:39.928] 2019/10/11 03:05:39 process.go:155: Step './cluster/kubectl.sh --match-server-version=false get nodes -oyaml' finished in 1.247990772s W1011 03:05:39.928] 2019/10/11 03:05:39 azure.go:951: KUBE_TEST_REPO_LIST_DOWNLOAD_LOCATION not set. Using default test image repos. W1011 03:05:39.928] 2019/10/11 03:05:39 azure.go:951: KUBE_TEST_REPO_LIST_DOWNLOAD_LOCATION not set. Using default test image repos. W1011 03:05:39.929] 2019/10/11 03:05:39 process.go:153: Running: kubectl get nodes --no-headers W1011 03:05:40.502] 2019/10/11 03:05:40 process.go:155: Step 'kubectl get nodes --no-headers' finished in 573.095087ms W1011 03:05:40.502] 2019/10/11 03:05:40 e2e.go:462: Cluster nodes: W1011 03:05:40.502] k8s-agentpool1-19105011-0 NotReady 36s v1.15.0 W1011 03:05:40.502] k8s-agentpool1-19105011-1 NotReady 36s v1.15.0 W1011 03:05:40.502] k8s-master-19105011-0 NotReady 36s v1.15.0 W1011 03:05:40.503] 2019/10/11 03:05:40 process.go:153: Running: ./cluster/kubectl.sh --match-server-version=false version W1011 03:05:40.903] 2019/10/11 03:05:40 process.go:155: Step './cluster/kubectl.sh --match-server-version=false version' finished in 401.648045ms W1011 03:05:40.904] 2019/10/11 03:05:40 process.go:153: Running: make e2e-test I1011 03:05:41.004] go test -v -timeout=30m ./test/e2e "-ginkgo.noColor" W1011 03:05:41.107] go: finding github.com/golang/protobuf v1.3.0 W1011 03:05:41.108] go: finding github.com/go-openapi/swag v0.19.0 W1011 03:05:41.108] go: finding github.com/coreos/go-systemd v0.0.0-20190321100706-95778dfbb74e W1011 03:05:41.108] go: finding github.com/docker/distribution v0.0.0-20170905204447-5db89f0ca686 W1011 03:05:41.108] go: finding github.com/jonboulle/clockwork v0.1.0 W1011 03:05:41.109] go: finding github.com/PuerkitoBio/purell v1.1.1 W1011 03:05:41.109] go: finding github.com/Azure/go-autorest v11.5.1+incompatible W1011 03:05:41.109] go: finding github.com/googleapis/gnostic v0.2.0 W1011 03:05:41.280] go: finding k8s.io/legacy-cloud-providers v0.0.0-20190624091455-d8621ceb9c64 W1011 03:05:41.283] go: finding golang.org/x/net v0.0.0-20190301231341-16b79f2e4e95 W1011 03:05:41.969] go: finding github.com/coreos/etcd v3.3.12+incompatible W1011 03:05:42.023] go: finding github.com/grpc-ecosystem/go-grpc-middleware v1.0.0 W1011 03:05:42.077] go: finding k8s.io/apimachinery v0.0.0-20190313205120-d7deff9243b1 W1011 03:05:42.125] go: finding github.com/xiang90/probing v0.0.0-20190116061207-43a291ad63a2 W1011 03:05:42.136] go: finding github.com/prometheus/common v0.2.0 W1011 03:05:42.356] go: finding sigs.k8s.io/yaml v1.1.0 W1011 03:05:42.388] go: finding gopkg.in/yaml.v2 v2.2.2 W1011 03:05:42.488] go: finding go.uber.org/multierr v1.1.0 W1011 03:05:43.159] go: finding github.com/opencontainers/go-digest v1.0.0-rc1 W1011 03:05:43.202] go: finding github.com/elazarl/goproxy v0.0.0-20190410145444-c548f45dcf1d W1011 03:05:43.211] go: finding github.com/dgrijalva/jwt-go v3.2.0+incompatible W1011 03:05:43.235] go: finding github.com/matttproud/golang_protobuf_extensions v1.0.1 W1011 03:05:43.274] go: finding github.com/mailru/easyjson v0.0.0-20190312143242-1de009706dbe W1011 03:05:43.360] go: finding google.golang.org/genproto v0.0.0-20190307195333-5fe7a883aa19 W1011 03:05:43.377] go: finding github.com/golang/groupcache v0.0.0-20190129154638-5b532d6fd5ef W1011 03:05:43.387] go: finding github.com/coreos/pkg v0.0.0-20180928190104-399ea9e2e55f W1011 03:05:43.919] go: finding github.com/GoogleCloudPlatform/k8s-cloud-provider v0.0.0-20181220005116-f8e995905100 W1011 03:05:43.921] go: finding github.com/ugorji/go v1.1.4 W1011 03:05:43.972] go: finding github.com/marstr/guid v1.1.0 W1011 03:05:44.031] go: finding github.com/census-instrumentation/opencensus-proto v0.1.0 W1011 03:05:44.053] go: finding github.com/kubernetes-csi/external-snapshotter v1.0.1 W1011 03:05:44.077] go: finding github.com/pborman/uuid v0.0.0-20180906182336-adf5a7427709 W1011 03:05:44.091] go: finding github.com/docker/spdystream v0.0.0-20181023171402-6480d4af844c W1011 03:05:44.120] go: finding github.com/satori/go.uuid v1.2.0 W1011 03:05:44.367] go: finding github.com/soheilhy/cmux v0.1.4 W1011 03:05:44.884] go: finding github.com/dnaeon/go-vcr v1.0.1 W1011 03:05:44.943] go: finding github.com/sirupsen/logrus v1.2.0 W1011 03:05:44.974] go: finding sigs.k8s.io/kustomize v2.0.3+incompatible W1011 03:05:45.000] go: finding gopkg.in/warnings.v0 v0.1.1 W1011 03:05:45.034] go: finding github.com/spf13/cobra v0.0.3 W1011 03:05:45.044] go: finding github.com/tmc/grpc-websocket-proxy v0.0.0-20190109142713-0ad062ec5ee5 W1011 03:05:45.277] go: finding gopkg.in/gcfg.v1 v1.2.0 W1011 03:05:45.753] go: finding k8s.io/kube-openapi v0.0.0-20190306001800-15615b16d372 W1011 03:05:46.119] go: finding github.com/go-logfmt/logfmt v0.3.0 W1011 03:05:46.151] go: finding github.com/hashicorp/golang-lru v0.5.1 W1011 03:05:46.199] go: finding github.com/gregjones/httpcache v0.0.0-20190212212710-3befbb6ad0cc W1011 03:05:46.199] go: finding github.com/pkg/errors v0.8.1 W1011 03:05:46.251] go: finding go.uber.org/zap v1.9.1 W1011 03:05:46.426] go: finding github.com/fatih/camelcase v1.0.0 W1011 03:05:46.467] go: finding google.golang.org/api v0.1.0 W1011 03:05:46.646] go: finding github.com/spf13/afero v1.2.2 W1011 03:05:46.684] go: finding github.com/prometheus/procfs v0.0.0-20190306233201-d0f344d83b0c W1011 03:05:46.907] go: finding github.com/Azure/azure-sdk-for-go v21.4.0+incompatible W1011 03:05:46.971] go: finding golang.org/x/tools v0.0.0-20190226205152-f727befe758c W1011 03:05:46.994] go: finding golang.org/x/sync v0.0.0-20190227155943-e225da77a7e6 W1011 03:05:47.032] go: finding github.com/evanphx/json-patch v3.0.0+incompatible W1011 03:05:47.164] go: finding github.com/Azure/azure-storage-file-go v0.5.0 W1011 03:05:47.174] go: finding github.com/stretchr/objx v0.1.1 W1011 03:05:47.459] go: finding github.com/coreos/bbolt v1.3.2 W1011 03:05:47.785] go: finding github.com/prometheus/client_golang v0.9.2 W1011 03:05:47.897] go: finding github.com/onsi/gomega v1.4.3 W1011 03:05:47.963] go: finding golang.org/x/lint v0.0.0-20190227174305-5b3e6a55c961 W1011 03:05:47.994] go: finding github.com/google/uuid v1.1.1 W1011 03:05:48.196] go: finding gopkg.in/alecthomas/kingpin.v2 v2.2.6 W1011 03:05:48.348] go: finding golang.org/x/text v0.3.0 W1011 03:05:48.749] go: finding github.com/davecgh/go-spew v1.1.1 W1011 03:05:48.768] go: finding github.com/beorn7/perks v0.0.0-20180321164747-3a771d992973 W1011 03:05:48.836] go: finding github.com/Azure/azure-pipeline-go v0.2.1 W1011 03:05:49.533] go: finding golang.org/x/exp v0.0.0-20190121172915-509febef88a4 W1011 03:05:50.052] go: finding github.com/kr/pretty v0.1.0 W1011 03:05:50.056] go: finding github.com/google/btree v1.0.0 W1011 03:05:50.081] go: finding github.com/container-storage-interface/spec v1.1.0 W1011 03:05:50.113] go: finding k8s.io/cli-runtime v0.0.0-20190314001948-2899ed30580f W1011 03:05:50.151] go: finding github.com/alecthomas/template v0.0.0-20160405071501-a0175ee3bccc W1011 03:05:50.197] go: finding contrib.go.opencensus.io/exporter/ocagent v0.2.0 W1011 03:05:50.215] go: finding github.com/spf13/pflag v1.0.3 W1011 03:05:50.612] go: finding go.etcd.io/bbolt v1.3.2 W1011 03:05:50.874] go: finding github.com/rubiojr/go-vhd v0.0.0-20160810183302-0bfd3b39853c W1011 03:05:50.930] go: finding github.com/kr/text v0.1.0 W1011 03:05:50.938] go: finding golang.org/x/oauth2 v0.0.0-20190226205417-e64efc72b421 W1011 03:05:51.035] go: finding github.com/go-stack/stack v1.8.0 W1011 03:05:51.071] go: finding github.com/stretchr/testify v1.3.0 W1011 03:05:51.095] go: finding github.com/go-kit/kit v0.8.0 W1011 03:05:51.117] go: finding github.com/prometheus/client_model v0.0.0-20190129233127-fd36f4220a90 W1011 03:05:51.164] go: finding github.com/vmware/govmomi v0.20.1 W1011 03:05:51.612] go: finding k8s.io/klog v0.2.0 W1011 03:05:51.722] go: finding github.com/alecthomas/units v0.0.0-20151022065526-2efee857e7cf W1011 03:05:51.867] go: finding k8s.io/utils v0.0.0-20190221042446-c2654d5206da W1011 03:05:51.898] go: finding github.com/onsi/ginkgo v1.7.0 W1011 03:05:51.911] go: finding github.com/inconshreveable/mousetrap v1.0.0 W1011 03:05:51.951] go: finding k8s.io/kube-aggregator v0.0.0-20190401185513-77f9841f26eb W1011 03:05:52.000] go: finding github.com/go-openapi/jsonpointer v0.19.0 W1011 03:05:52.039] go: finding gopkg.in/fsnotify.v1 v1.4.7 W1011 03:05:52.050] go: finding github.com/mattn/go-ieproxy v0.0.0-20190610004146-91bb50d98149 W1011 03:05:52.446] go: finding github.com/coreos/go-semver v0.3.0 W1011 03:05:52.448] go: finding google.golang.org/appengine v1.4.0 W1011 03:05:52.455] go: finding k8s.io/client-go v11.0.0+incompatible W1011 03:05:52.703] go: finding k8s.io/cluster-bootstrap v0.0.0-20190313124217-0fa624df11e9 W1011 03:05:52.707] go: finding gopkg.in/tomb.v1 v1.0.0-20141024135613-dd632973f1e7 W1011 03:05:52.771] go: finding github.com/mwitkow/go-conntrack v0.0.0-20161129095857-cc309e4a2223 W1011 03:05:52.947] go: finding k8s.io/api v0.0.0-20190313235455-40a48860b5ab W1011 03:05:53.272] go: finding github.com/imdario/mergo v0.3.7 W1011 03:05:53.400] go: finding github.com/gorilla/websocket v1.4.0 W1011 03:05:53.407] go: finding github.com/kr/logfmt v0.0.0-20140226030751-b84e30acd515 W1011 03:05:53.588] go: finding golang.org/x/sys v0.0.0-20190308023053-584f3b12f43e W1011 03:05:53.763] go: finding github.com/gogo/protobuf v1.2.1 W1011 03:05:54.202] go: finding honnef.co/go/tools v0.0.0-20190102054323-c2f93a96b099 W1011 03:05:54.376] go: finding github.com/kr/pty v1.1.5 W1011 03:05:54.502] go: finding gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405 W1011 03:05:54.595] go: finding github.com/go-openapi/jsonreference v0.19.0 W1011 03:05:54.636] go: finding github.com/json-iterator/go v1.1.5 W1011 03:05:54.684] go: finding k8s.io/apiserver v0.0.0-20190313205120-8b27c41bdbb1 W1011 03:05:55.136] go: finding golang.org/x/crypto v0.0.0-20190228161510-8dd112bcdc25 W1011 03:05:55.138] go: finding github.com/emicklei/go-restful v2.9.3+incompatible W1011 03:05:55.203] go: finding go.opencensus.io v0.18.0 W1011 03:05:55.754] go: finding github.com/konsorten/go-windows-terminal-sequences v1.0.1 W1011 03:05:55.790] go: finding github.com/kisielk/errcheck v1.1.0 W1011 03:05:55.840] go: finding github.com/julienschmidt/httprouter v1.2.0 W1011 03:05:55.939] go: finding k8s.io/apiextensions-apiserver v0.0.0-20190315093550-53c4693659ed W1011 03:05:55.944] go: finding k8s.io/cloud-provider v0.0.0-20190308083404-05ccf96446f8 W1011 03:05:56.040] go: finding github.com/elazarl/goproxy/ext v0.0.0-20190410145444-c548f45dcf1d W1011 03:05:56.179] go: finding gopkg.in/inf.v0 v0.9.1 W1011 03:05:56.210] go: finding github.com/go-openapi/spec v0.19.0 W1011 03:05:56.560] go: finding github.com/aws/aws-sdk-go v1.16.26 W1011 03:05:56.561] go: finding github.com/fsnotify/fsnotify v1.4.7 W1011 03:05:56.568] go: finding cloud.google.com/go v0.34.0 W1011 03:05:56.623] go: finding k8s.io/csi-translation-lib v0.0.0-20190313124639-7f5cabc6aac8 W1011 03:05:56.910] go: finding github.com/rogpeppe/go-charset v0.0.0-20180617210344-2471d30d28b4 W1011 03:05:56.951] go: finding google.golang.org/grpc v1.19.0 W1011 03:05:56.963] go: finding github.com/modern-go/concurrent v0.0.0-20180306012644-bacd9c7ef1dd W1011 03:05:57.109] go: finding github.com/pelletier/go-toml v1.4.0 W1011 03:05:57.474] go: finding k8s.io/kubernetes v1.14.0 W1011 03:05:57.475] go: finding github.com/modern-go/reflect2 v0.0.0-20180701023420-4b7aa43c6742 W1011 03:05:57.658] go: finding github.com/google/go-cmp v0.2.0 W1011 03:05:57.667] go: finding github.com/grpc-ecosystem/grpc-gateway v1.5.0 W1011 03:05:57.984] go: finding go.uber.org/atomic v1.3.2 W1011 03:05:58.209] go: finding github.com/openzipkin/zipkin-go v0.1.1 W1011 03:05:58.430] go: finding github.com/google/gofuzz v0.0.0-20170612174753-24818f796faf W1011 03:05:58.473] go: finding github.com/BurntSushi/toml v0.3.1 W1011 03:05:58.492] go: finding gopkg.in/square/go-jose.v2 v2.3.0 W1011 03:05:58.574] go: finding github.com/kisielk/gotool v1.0.0 W1011 03:05:58.695] go: finding github.com/apache/thrift v0.0.0-20180902110319-2566ecd5d999 W1011 03:05:58.731] go: finding k8s.io/component-base v0.0.0-20190313120452-4727f38490bc W1011 03:05:58.798] go: finding github.com/pmezard/go-difflib v1.0.0 W1011 03:05:59.079] go: finding golang.org/x/time v0.0.0-20181108054448-85acf8d2951c W1011 03:05:59.172] go: finding github.com/peterbourgon/diskv v2.0.1+incompatible W1011 03:05:59.284] go: finding github.com/PuerkitoBio/urlesc v0.0.0-20170810143723-de5bf2ad4578 W1011 03:05:59.384] go: finding github.com/client9/misspell v0.3.4 W1011 03:05:59.539] go: finding github.com/hpcloud/tail v1.0.0 W1011 03:05:59.567] go: finding github.com/golang/mock v1.1.1 W1011 03:05:59.919] go: finding github.com/grpc-ecosystem/go-grpc-prometheus v1.2.0 W1011 03:05:59.991] go: finding github.com/ghodss/yaml v1.0.0 W1011 03:06:00.175] go: finding github.com/golang/glog v0.0.0-20160126235308-23def4e6c14b W1011 03:06:05.988] go: finding github.com/jmespath/go-jmespath v0.0.0-20180206201540-c2b33e8439af W1011 03:06:12.801] go: downloading k8s.io/api v0.0.0-20190313235455-40a48860b5ab W1011 03:06:12.801] go: downloading k8s.io/kubernetes v1.14.0 W1011 03:06:12.802] go: downloading k8s.io/client-go v11.0.0+incompatible W1011 03:06:12.802] go: downloading github.com/container-storage-interface/spec v1.1.0 W1011 03:06:12.802] go: downloading github.com/onsi/ginkgo v1.7.0 W1011 03:06:12.802] go: downloading github.com/onsi/gomega v1.4.3 W1011 03:06:12.804] go: downloading k8s.io/apimachinery v0.0.0-20190313205120-d7deff9243b1 W1011 03:06:12.806] go: downloading github.com/kubernetes-csi/external-snapshotter v1.0.1 W1011 03:06:12.810] go: downloading google.golang.org/grpc v1.19.0 W1011 03:06:12.954] go: extracting github.com/container-storage-interface/spec v1.1.0 W1011 03:06:12.965] go: downloading github.com/golang/protobuf v1.3.0 W1011 03:06:13.056] go: extracting github.com/onsi/gomega v1.4.3 W1011 03:06:13.063] go: extracting github.com/onsi/ginkgo v1.7.0 W1011 03:06:13.346] go: extracting github.com/golang/protobuf v1.3.0 W1011 03:06:13.390] go: extracting k8s.io/apimachinery v0.0.0-20190313205120-d7deff9243b1 W1011 03:06:13.398] go: extracting google.golang.org/grpc v1.19.0 W1011 03:06:13.484] go: downloading k8s.io/klog v0.2.0 W1011 03:06:13.518] go: downloading github.com/gogo/protobuf v1.2.1 W1011 03:06:13.543] go: extracting k8s.io/api v0.0.0-20190313235455-40a48860b5ab W1011 03:06:13.589] go: extracting k8s.io/klog v0.2.0 W1011 03:06:13.592] go: downloading github.com/google/gofuzz v0.0.0-20170612174753-24818f796faf W1011 03:06:13.624] go: downloading github.com/pelletier/go-toml v1.4.0 W1011 03:06:13.634] go: extracting github.com/google/gofuzz v0.0.0-20170612174753-24818f796faf W1011 03:06:13.644] go: downloading golang.org/x/net v0.0.0-20190301231341-16b79f2e4e95 W1011 03:06:13.731] go: extracting k8s.io/client-go v11.0.0+incompatible W1011 03:06:13.740] go: extracting github.com/pelletier/go-toml v1.4.0 W1011 03:06:13.756] go: downloading k8s.io/legacy-cloud-providers v0.0.0-20190624091455-d8621ceb9c64 W1011 03:06:13.913] go: downloading github.com/pborman/uuid v0.0.0-20180906182336-adf5a7427709 W1011 03:06:13.967] go: extracting github.com/pborman/uuid v0.0.0-20180906182336-adf5a7427709 W1011 03:06:13.990] go: downloading github.com/Azure/azure-sdk-for-go v21.4.0+incompatible W1011 03:06:14.019] go: extracting k8s.io/legacy-cloud-providers v0.0.0-20190624091455-d8621ceb9c64 W1011 03:06:14.399] go: extracting golang.org/x/net v0.0.0-20190301231341-16b79f2e4e95 W1011 03:06:14.514] go: downloading google.golang.org/genproto v0.0.0-20190307195333-5fe7a883aa19 W1011 03:06:15.370] go: extracting github.com/gogo/protobuf v1.2.1 W1011 03:06:15.563] go: downloading k8s.io/utils v0.0.0-20190221042446-c2654d5206da W1011 03:06:15.653] go: extracting k8s.io/utils v0.0.0-20190221042446-c2654d5206da W1011 03:06:15.680] go: downloading k8s.io/cloud-provider v0.0.0-20190308083404-05ccf96446f8 W1011 03:06:16.117] go: extracting k8s.io/cloud-provider v0.0.0-20190308083404-05ccf96446f8 W1011 03:06:16.133] go: downloading gopkg.in/inf.v0 v0.9.1 W1011 03:06:16.171] go: extracting gopkg.in/inf.v0 v0.9.1 W1011 03:06:16.176] go: downloading golang.org/x/text v0.3.0 W1011 03:06:18.094] go: extracting google.golang.org/genproto v0.0.0-20190307195333-5fe7a883aa19 W1011 03:06:18.522] go: downloading github.com/Azure/go-autorest v11.5.1+incompatible W1011 03:06:18.695] go: extracting github.com/Azure/go-autorest v11.5.1+incompatible W1011 03:06:19.789] go: extracting golang.org/x/text v0.3.0 W1011 03:06:20.085] go: downloading github.com/hpcloud/tail v1.0.0 W1011 03:06:20.148] go: extracting github.com/hpcloud/tail v1.0.0 W1011 03:06:22.438] go: extracting github.com/kubernetes-csi/external-snapshotter v1.0.1 W1011 03:06:22.449] go: downloading github.com/Azure/azure-storage-file-go v0.5.0 W1011 03:06:22.476] go: downloading github.com/hashicorp/golang-lru v0.5.1 W1011 03:06:22.518] go: extracting github.com/hashicorp/golang-lru v0.5.1 W1011 03:06:22.529] go: downloading github.com/prometheus/client_golang v0.9.2 W1011 03:06:22.546] go: extracting github.com/Azure/azure-storage-file-go v0.5.0 W1011 03:06:22.567] go: downloading sigs.k8s.io/yaml v1.1.0 W1011 03:06:22.603] go: extracting sigs.k8s.io/yaml v1.1.0 W1011 03:06:22.614] go: downloading github.com/googleapis/gnostic v0.2.0 W1011 03:06:22.643] go: extracting github.com/prometheus/client_golang v0.9.2 W1011 03:06:22.963] go: extracting github.com/googleapis/gnostic v0.2.0 W1011 03:06:23.009] go: downloading github.com/modern-go/reflect2 v0.0.0-20180701023420-4b7aa43c6742 W1011 03:06:23.051] go: extracting github.com/modern-go/reflect2 v0.0.0-20180701023420-4b7aa43c6742 W1011 03:06:23.097] go: downloading github.com/prometheus/client_model v0.0.0-20190129233127-fd36f4220a90 W1011 03:06:23.163] go: extracting github.com/prometheus/client_model v0.0.0-20190129233127-fd36f4220a90 W1011 03:06:23.170] go: downloading github.com/beorn7/perks v0.0.0-20180321164747-3a771d992973 W1011 03:06:23.201] go: extracting github.com/beorn7/perks v0.0.0-20180321164747-3a771d992973 W1011 03:06:23.205] go: downloading github.com/json-iterator/go v1.1.5 W1011 03:06:23.284] go: extracting github.com/json-iterator/go v1.1.5 W1011 03:06:23.298] go: downloading gopkg.in/yaml.v2 v2.2.2 W1011 03:06:23.358] go: extracting gopkg.in/yaml.v2 v2.2.2 W1011 03:06:23.364] go: downloading golang.org/x/sys v0.0.0-20190308023053-584f3b12f43e W1011 03:06:24.433] go: extracting golang.org/x/sys v0.0.0-20190308023053-584f3b12f43e W1011 03:06:24.527] go: downloading github.com/rubiojr/go-vhd v0.0.0-20160810183302-0bfd3b39853c W1011 03:06:24.762] go: extracting github.com/rubiojr/go-vhd v0.0.0-20160810183302-0bfd3b39853c W1011 03:06:24.779] go: downloading github.com/prometheus/procfs v0.0.0-20190306233201-d0f344d83b0c W1011 03:06:24.854] go: extracting github.com/prometheus/procfs v0.0.0-20190306233201-d0f344d83b0c W1011 03:06:24.869] go: downloading github.com/golang/groupcache v0.0.0-20190129154638-5b532d6fd5ef W1011 03:06:24.917] go: extracting github.com/golang/groupcache v0.0.0-20190129154638-5b532d6fd5ef W1011 03:06:24.923] go: downloading go.opencensus.io v0.18.0 W1011 03:06:25.081] go: extracting go.opencensus.io v0.18.0 W1011 03:06:25.111] go: downloading github.com/modern-go/concurrent v0.0.0-20180306012644-bacd9c7ef1dd W1011 03:06:25.144] go: extracting github.com/modern-go/concurrent v0.0.0-20180306012644-bacd9c7ef1dd W1011 03:06:25.146] go: downloading golang.org/x/time v0.0.0-20181108054448-85acf8d2951c W1011 03:06:25.175] go: extracting golang.org/x/time v0.0.0-20181108054448-85acf8d2951c W1011 03:06:25.183] go: downloading github.com/davecgh/go-spew v1.1.1 W1011 03:06:25.231] go: extracting github.com/Azure/azure-sdk-for-go v21.4.0+incompatible W1011 03:06:25.238] go: extracting github.com/davecgh/go-spew v1.1.1 W1011 03:06:25.243] go: downloading contrib.go.opencensus.io/exporter/ocagent v0.2.0 W1011 03:06:25.286] go: extracting contrib.go.opencensus.io/exporter/ocagent v0.2.0 W1011 03:06:25.297] go: downloading github.com/prometheus/common v0.2.0 W1011 03:06:25.412] go: extracting github.com/prometheus/common v0.2.0 W1011 03:06:25.430] go: downloading k8s.io/kube-openapi v0.0.0-20190306001800-15615b16d372 W1011 03:06:25.862] go: extracting k8s.io/kubernetes v1.14.0 W1011 03:06:26.044] go: extracting k8s.io/kube-openapi v0.0.0-20190306001800-15615b16d372 W1011 03:06:26.100] go: downloading golang.org/x/oauth2 v0.0.0-20190226205417-e64efc72b421 W1011 03:06:26.190] go: extracting golang.org/x/oauth2 v0.0.0-20190226205417-e64efc72b421 W1011 03:06:26.205] go: downloading google.golang.org/api v0.1.0 W1011 03:06:26.663] go: downloading github.com/census-instrumentation/opencensus-proto v0.1.0 W1011 03:06:26.664] go: downloading github.com/matttproud/golang_protobuf_extensions v1.0.1 W1011 03:06:26.665] go: downloading github.com/marstr/guid v1.1.0 W1011 03:06:26.665] go: downloading gopkg.in/tomb.v1 v1.0.0-20141024135613-dd632973f1e7 W1011 03:06:26.669] go: downloading golang.org/x/crypto v0.0.0-20190228161510-8dd112bcdc25 W1011 03:06:26.811] go: extracting github.com/marstr/guid v1.1.0 W1011 03:06:26.813] go: downloading github.com/Azure/azure-pipeline-go v0.2.1 W1011 03:06:26.820] go: extracting github.com/matttproud/golang_protobuf_extensions v1.0.1 W1011 03:06:26.820] go: extracting gopkg.in/tomb.v1 v1.0.0-20141024135613-dd632973f1e7 W1011 03:06:26.830] go: extracting github.com/census-instrumentation/opencensus-proto v0.1.0 W1011 03:06:26.834] go: downloading github.com/google/uuid v1.1.1 W1011 03:06:26.842] go: downloading gopkg.in/fsnotify.v1 v1.4.7 W1011 03:06:26.846] go: downloading github.com/satori/go.uuid v1.2.0 W1011 03:06:26.870] go: extracting github.com/Azure/azure-pipeline-go v0.2.1 W1011 03:06:26.882] go: downloading github.com/dgrijalva/jwt-go v3.2.0+incompatible W1011 03:06:26.901] go: extracting github.com/google/uuid v1.1.1 W1011 03:06:26.936] go: extracting github.com/satori/go.uuid v1.2.0 W1011 03:06:26.941] go: downloading github.com/mattn/go-ieproxy v0.0.0-20190610004146-91bb50d98149 W1011 03:06:26.953] go: extracting gopkg.in/fsnotify.v1 v1.4.7 W1011 03:06:27.015] go: extracting github.com/dgrijalva/jwt-go v3.2.0+incompatible W1011 03:06:27.024] go: extracting github.com/mattn/go-ieproxy v0.0.0-20190610004146-91bb50d98149 W1011 03:06:27.381] go: extracting golang.org/x/crypto v0.0.0-20190228161510-8dd112bcdc25 W1011 03:06:27.785] go: downloading k8s.io/apiserver v0.0.0-20190313205120-8b27c41bdbb1 W1011 03:06:27.786] go: downloading k8s.io/apiextensions-apiserver v0.0.0-20190315093550-53c4693659ed W1011 03:06:27.787] go: downloading github.com/spf13/pflag v1.0.3 W1011 03:06:27.788] go: downloading k8s.io/kube-aggregator v0.0.0-20190401185513-77f9841f26eb W1011 03:06:28.140] go: extracting github.com/spf13/pflag v1.0.3 W1011 03:06:28.440] go: extracting k8s.io/apiserver v0.0.0-20190313205120-8b27c41bdbb1 W1011 03:06:28.524] go: downloading gopkg.in/square/go-jose.v2 v2.3.0 W1011 03:06:28.525] go: downloading github.com/imdario/mergo v0.3.7 W1011 03:06:28.527] go: downloading k8s.io/cluster-bootstrap v0.0.0-20190313124217-0fa624df11e9 W1011 03:06:28.527] go: downloading github.com/docker/distribution v0.0.0-20170905204447-5db89f0ca686 W1011 03:06:28.530] go: downloading github.com/pkg/errors v0.8.1 W1011 03:06:28.531] go: downloading github.com/stretchr/testify v1.3.0 W1011 03:06:28.538] go: downloading k8s.io/component-base v0.0.0-20190313120452-4727f38490bc W1011 03:06:28.623] go: extracting github.com/imdario/mergo v0.3.7 W1011 03:06:28.631] go: downloading github.com/fatih/camelcase v1.0.0 W1011 03:06:28.642] go: extracting github.com/pkg/errors v0.8.1 W1011 03:06:28.645] go: downloading k8s.io/csi-translation-lib v0.0.0-20190313124639-7f5cabc6aac8 W1011 03:06:28.705] go: extracting github.com/fatih/camelcase v1.0.0 W1011 03:06:28.738] go: extracting github.com/stretchr/testify v1.3.0 W1011 03:06:28.796] go: extracting k8s.io/component-base v0.0.0-20190313120452-4727f38490bc W1011 03:06:28.803] go: extracting gopkg.in/square/go-jose.v2 v2.3.0 W1011 03:06:28.807] go: downloading github.com/docker/spdystream v0.0.0-20181023171402-6480d4af844c W1011 03:06:28.833] go: extracting k8s.io/cluster-bootstrap v0.0.0-20190313124217-0fa624df11e9 W1011 03:06:28.836] go: downloading github.com/pmezard/go-difflib v1.0.0 W1011 03:06:28.839] go: downloading k8s.io/cli-runtime v0.0.0-20190314001948-2899ed30580f W1011 03:06:28.879] go: extracting github.com/docker/spdystream v0.0.0-20181023171402-6480d4af844c W1011 03:06:28.888] go: extracting github.com/pmezard/go-difflib v1.0.0 W1011 03:06:28.928] go: extracting k8s.io/csi-translation-lib v0.0.0-20190313124639-7f5cabc6aac8 W1011 03:06:28.961] go: extracting k8s.io/cli-runtime v0.0.0-20190314001948-2899ed30580f W1011 03:06:28.978] go: downloading github.com/evanphx/json-patch v3.0.0+incompatible W1011 03:06:28.978] go: downloading github.com/gregjones/httpcache v0.0.0-20190212212710-3befbb6ad0cc W1011 03:06:28.979] go: downloading sigs.k8s.io/kustomize v2.0.3+incompatible W1011 03:06:28.980] go: downloading github.com/peterbourgon/diskv v2.0.1+incompatible W1011 03:06:28.980] go: downloading github.com/spf13/cobra v0.0.3 W1011 03:06:29.032] go: extracting github.com/evanphx/json-patch v3.0.0+incompatible W1011 03:06:29.049] go: extracting github.com/gregjones/httpcache v0.0.0-20190212212710-3befbb6ad0cc W1011 03:06:29.067] go: extracting github.com/peterbourgon/diskv v2.0.1+incompatible W1011 03:06:29.069] go: downloading github.com/google/btree v1.0.0 W1011 03:06:29.105] go: extracting github.com/google/btree v1.0.0 W1011 03:06:29.187] go: extracting github.com/spf13/cobra v0.0.3 W1011 03:06:29.222] go: extracting github.com/docker/distribution v0.0.0-20170905204447-5db89f0ca686 W1011 03:06:29.416] go: extracting k8s.io/kube-aggregator v0.0.0-20190401185513-77f9841f26eb W1011 03:06:29.441] go: downloading github.com/opencontainers/go-digest v1.0.0-rc1 W1011 03:06:29.487] go: extracting github.com/opencontainers/go-digest v1.0.0-rc1 W1011 03:06:29.575] go: extracting k8s.io/apiextensions-apiserver v0.0.0-20190315093550-53c4693659ed W1011 03:06:29.965] go: extracting sigs.k8s.io/kustomize v2.0.3+incompatible W1011 03:06:29.995] go: downloading github.com/ghodss/yaml v1.0.0 W1011 03:06:29.996] go: downloading github.com/go-openapi/spec v0.19.0 W1011 03:06:29.996] go: downloading github.com/emicklei/go-restful v2.9.3+incompatible W1011 03:06:30.049] go: extracting github.com/ghodss/yaml v1.0.0 W1011 03:06:30.099] go: extracting github.com/emicklei/go-restful v2.9.3+incompatible W1011 03:06:30.177] go: extracting github.com/go-openapi/spec v0.19.0 W1011 03:06:30.197] go: downloading github.com/go-openapi/jsonreference v0.19.0 W1011 03:06:30.197] go: downloading github.com/go-openapi/swag v0.19.0 W1011 03:06:30.197] go: downloading github.com/go-openapi/jsonpointer v0.19.0 W1011 03:06:30.247] go: extracting github.com/go-openapi/jsonreference v0.19.0 W1011 03:06:30.250] go: downloading github.com/PuerkitoBio/purell v1.1.1 W1011 03:06:30.289] go: extracting github.com/PuerkitoBio/purell v1.1.1 W1011 03:06:30.291] go: downloading github.com/PuerkitoBio/urlesc v0.0.0-20170810143723-de5bf2ad4578 W1011 03:06:30.297] go: extracting github.com/go-openapi/jsonpointer v0.19.0 W1011 03:06:30.298] go: extracting github.com/go-openapi/swag v0.19.0 W1011 03:06:30.302] go: downloading github.com/mailru/easyjson v0.0.0-20190312143242-1de009706dbe W1011 03:06:30.317] go: extracting github.com/PuerkitoBio/urlesc v0.0.0-20170810143723-de5bf2ad4578 W1011 03:06:30.374] go: extracting github.com/mailru/easyjson v0.0.0-20190312143242-1de009706dbe W1011 03:06:32.324] go: extracting google.golang.org/api v0.1.0 W1011 03:06:32.824] go: downloading golang.org/x/sync v0.0.0-20190227155943-e225da77a7e6 W1011 03:06:32.957] go: extracting golang.org/x/sync v0.0.0-20190227155943-e225da77a7e6 I1011 03:07:23.585] Oct 11 03:07:23.584: INFO: The --provider flag is not set. Continuing as if --provider=skeleton had been used. I1011 03:07:23.585] === RUN TestE2E I1011 03:07:23.585] Running Suite: AzureFile CSI Driver End-to-End Tests I1011 03:07:23.585] ==================================================== I1011 03:07:23.586] Random Seed: 1570763243 - Will randomize all specs I1011 03:07:23.586] Will run 8 of 8 specs I1011 03:07:23.586] I1011 03:07:23.586] 2019/10/11 03:07:23 Running in Prow, converting AZURE_CREDENTIALS to AZURE_CREDENTIAL_FILE I1011 03:07:23.586] 2019/10/11 03:07:23 Reading credentials file /etc/azure-cred/credentials I1011 03:07:25.625] 2019/10/11 03:07:25 Attempting docker login with Azure service principal I1011 03:07:27.011] 2019/10/11 03:07:27 docker login is successful I1011 03:07:27.011] 2019/10/11 03:07:27 Installing Azure File CSI Driver... I1011 03:07:27.013] make[1]: Entering directory '/go/src/sigs.k8s.io/azurefile-csi-driver' I1011 03:07:27.013] # Use v2.11.0 helm to match tiller's version in clusters made by aks-engine I1011 03:07:27.014] curl https://raw.githubusercontent.com/helm/helm/master/scripts/get | DESIRED_VERSION=v2.11.0 bash I1011 03:07:27.268] % Total % Received % Xferd Average Speed Time Time Time Current I1011 03:07:27.269] Dload Upload Total Spent Left Speed I1011 03:07:27.471] 0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0 100 7034 100 7034 0 0 34731 0 --:--:-- --:--:-- --:--:-- 34821 I1011 03:07:27.486] Downloading https://get.helm.sh/helm-v2.11.0-linux-amd64.tar.gz I1011 03:07:28.903] Preparing to install helm and tiller into /usr/local/bin I1011 03:07:28.933] helm installed into /usr/local/bin/helm I1011 03:07:28.959] tiller installed into /usr/local/bin/tiller I1011 03:07:28.961] Run 'helm init' to configure helm. I1011 03:07:28.977] # Make sure tiller is ready I1011 03:07:28.977] kubectl wait pod -l name=tiller --namespace kube-system --for condition=ready I1011 03:07:30.084] pod/tiller-deploy-54c96cb5df-ls57l condition met I1011 03:07:30.087] helm version I1011 03:07:30.143] Client: &version.Version{SemVer:"v2.11.0", GitCommit:"2e55dbe1fdb5fdb96b75ff144a339489417b146b", GitTreeState:"clean"} I1011 03:07:33.079] Server: &version.Version{SemVer:"v2.11.0", GitCommit:"2e55dbe1fdb5fdb96b75ff144a339489417b146b", GitTreeState:"clean"} I1011 03:07:33.080] # Only build and push the image if it does not exist in the registry I1011 03:07:33.081] docker pull k8sprowinternal.azurecr.io/azurefile-csi:e2e-78fd0851bcc9d9407385c5678d72c3b7e73d2222 || make azurefile-container push I1011 03:07:33.252] Error response from daemon: manifest for k8sprowinternal.azurecr.io/azurefile-csi:e2e-78fd0851bcc9d9407385c5678d72c3b7e73d2222 not found I1011 03:07:33.257] make[2]: Entering directory '/go/src/sigs.k8s.io/azurefile-csi-driver' I1011 03:07:33.257] CGO_ENABLED=0 GOOS=linux go build -a -ldflags "-X github.com/kubernetes-sigs/azurefile-csi-driver/pkg/azurefile.driverVersion=e2e-78fd0851bcc9d9407385c5678d72c3b7e73d2222 -X github.com/kubernetes-sigs/azurefile-csi-driver/pkg/azurefile.gitCommit=78fd0851bcc9d9407385c5678d72c3b7e73d2222 -X github.com/kubernetes-sigs/azurefile-csi-driver/pkg/azurefile.buildDate=2019-10-11T03:05:40Z -s -w -extldflags '-static'" -o _output/azurefileplugin ./pkg/azurefileplugin I1011 03:08:04.597] docker build --no-cache -t k8sprowinternal.azurecr.io/azurefile-csi:e2e-78fd0851bcc9d9407385c5678d72c3b7e73d2222 -f ./pkg/azurefileplugin/Dockerfile . I1011 03:08:06.737] Sending build context to Docker daemon 155.7MB I1011 03:08:06.778] Step 1/6 : FROM debian:9 I1011 03:08:07.747] 9: Pulling from library/debian I1011 03:08:08.065] 092586df9206: Pulling fs layer I1011 03:08:08.898] 092586df9206: Verifying Checksum I1011 03:08:08.899] 092586df9206: Download complete I1011 03:08:12.507] 092586df9206: Pull complete I1011 03:08:12.537] Digest: sha256:5fb93ce7a427b7c1c2374d5c29d68a159de7d5e781deeda422f8d51a1a9b6480 I1011 03:08:12.560] Status: Downloaded newer image for debian:9 I1011 03:08:12.560] ---> cb15ecf641ad I1011 03:08:12.560] Step 2/6 : RUN apt-get update && apt-get install -y ca-certificates cifs-utils I1011 03:08:17.174] ---> Running in 45bced6cf184 I1011 03:08:18.403] Ign:1 http://cdn-fastly.deb.debian.org/debian stretch InRelease I1011 03:08:18.426] Get:2 http://cdn-fastly.deb.debian.org/debian stretch-updates InRelease [91.0 kB] I1011 03:08:18.477] Get:3 http://security-cdn.debian.org/debian-security stretch/updates InRelease [94.3 kB] I1011 03:08:18.499] Get:4 http://cdn-fastly.deb.debian.org/debian stretch Release [118 kB] I1011 03:08:18.679] Get:5 http://security-cdn.debian.org/debian-security stretch/updates/main amd64 Packages [500 kB] I1011 03:08:18.701] Get:6 http://cdn-fastly.deb.debian.org/debian stretch Release.gpg [2365 B] I1011 03:08:18.871] Get:7 http://cdn-fastly.deb.debian.org/debian stretch-updates/main amd64 Packages [27.4 kB] I1011 03:08:18.894] Get:8 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 Packages [7086 kB] I1011 03:08:20.115] Fetched 7919 kB in 2s (3936 kB/s) I1011 03:08:20.683] Reading package lists... I1011 03:08:21.289] Reading package lists... I1011 03:08:21.394] Building dependency tree... I1011 03:08:21.395] Reading state information... I1011 03:08:21.467] The following additional packages will be installed: I1011 03:08:21.467] bzip2 dbus file krb5-locales libapparmor1 libavahi-client3 I1011 03:08:21.468] libavahi-common-data libavahi-common3 libbsd0 libcups2 libdbus-1-3 libexpat1 I1011 03:08:21.468] libffi6 libgmp10 libgnutls30 libgpm2 libgssapi-krb5-2 libhogweed4 I1011 03:08:21.468] libk5crypto3 libkeyutils1 libkrb5-3 libkrb5support0 libldap-2.4-2 I1011 03:08:21.468] libldap-common libldb1 libmagic-mgc libmagic1 libncurses5 libp11-kit0 I1011 03:08:21.468] libpopt0 libpython-stdlib libpython2.7 libpython2.7-minimal I1011 03:08:21.469] libpython2.7-stdlib libreadline7 libsasl2-2 libsasl2-modules I1011 03:08:21.469] libsasl2-modules-db libsqlite3-0 libssl1.1 libtalloc2 libtasn1-6 libtdb1 I1011 03:08:21.469] libtevent0 libwbclient0 mime-support openssl python python-crypto python-ldb I1011 03:08:21.469] python-minimal python-samba python-talloc python-tdb python2.7 I1011 03:08:21.469] python2.7-minimal readline-common samba-common samba-common-bin samba-libs I1011 03:08:21.469] ucf xz-utils I1011 03:08:21.470] Suggested packages: I1011 03:08:21.470] bzip2-doc keyutils smbclient winbind default-dbus-session-bus I1011 03:08:21.470] | dbus-session-bus cups-common gnutls-bin gpm krb5-doc krb5-user I1011 03:08:21.470] libsasl2-modules-gssapi-mit | libsasl2-modules-gssapi-heimdal I1011 03:08:21.470] libsasl2-modules-ldap libsasl2-modules-otp libsasl2-modules-sql python-doc I1011 03:08:21.470] python-tk python-crypto-dbg python-crypto-doc python-gpgme python2.7-doc I1011 03:08:21.471] binutils binfmt-support readline-doc heimdal-clients I1011 03:08:22.021] The following NEW packages will be installed: I1011 03:08:22.021] bzip2 ca-certificates cifs-utils dbus file krb5-locales libapparmor1 I1011 03:08:22.021] libavahi-client3 libavahi-common-data libavahi-common3 libbsd0 libcups2 I1011 03:08:22.022] libdbus-1-3 libexpat1 libffi6 libgmp10 libgnutls30 libgpm2 libgssapi-krb5-2 I1011 03:08:22.022] libhogweed4 libk5crypto3 libkeyutils1 libkrb5-3 libkrb5support0 I1011 03:08:22.022] libldap-2.4-2 libldap-common libldb1 libmagic-mgc libmagic1 libncurses5 I1011 03:08:22.022] libp11-kit0 libpopt0 libpython-stdlib libpython2.7 libpython2.7-minimal I1011 03:08:22.022] libpython2.7-stdlib libreadline7 libsasl2-2 libsasl2-modules I1011 03:08:22.022] libsasl2-modules-db libsqlite3-0 libssl1.1 libtalloc2 libtasn1-6 libtdb1 I1011 03:08:22.023] libtevent0 libwbclient0 mime-support openssl python python-crypto python-ldb I1011 03:08:22.023] python-minimal python-samba python-talloc python-tdb python2.7 I1011 03:08:22.023] python2.7-minimal readline-common samba-common samba-common-bin samba-libs I1011 03:08:22.023] ucf xz-utils I1011 03:08:22.141] 0 upgraded, 64 newly installed, 0 to remove and 5 not upgraded. I1011 03:08:22.141] Need to get 21.4 MB of archives. I1011 03:08:22.142] After this operation, 81.9 MB of additional disk space will be used. I1011 03:08:22.142] Get:1 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libpython2.7-minimal amd64 2.7.13-2+deb9u3 [389 kB] I1011 03:08:22.142] Get:2 http://security-cdn.debian.org/debian-security stretch/updates/main amd64 libexpat1 amd64 2.2.0-2+deb9u3 [83.7 kB] I1011 03:08:22.208] Get:3 http://security-cdn.debian.org/debian-security stretch/updates/main amd64 libssl1.1 amd64 1.1.0l-1~deb9u1 [1358 kB] I1011 03:08:22.253] Get:5 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 python2.7-minimal amd64 2.7.13-2+deb9u3 [1382 kB] I1011 03:08:22.300] Get:4 http://security-cdn.debian.org/debian-security stretch/updates/main amd64 openssl amd64 1.1.0l-1~deb9u1 [749 kB] I1011 03:08:22.319] Get:6 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 python-minimal amd64 2.7.13-2 [40.5 kB] I1011 03:08:22.320] Get:7 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 mime-support all 3.60 [36.7 kB] I1011 03:08:22.321] Get:8 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libffi6 amd64 3.2.1-6 [20.4 kB] I1011 03:08:22.322] Get:9 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 readline-common all 7.0-3 [70.4 kB] I1011 03:08:22.323] Get:10 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libreadline7 amd64 7.0-3 [151 kB] I1011 03:08:22.325] Get:11 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libsqlite3-0 amd64 3.16.2-5+deb9u1 [572 kB] I1011 03:08:22.332] Get:12 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libpython2.7-stdlib amd64 2.7.13-2+deb9u3 [1897 kB] I1011 03:08:22.554] Get:13 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 python2.7 amd64 2.7.13-2+deb9u3 [285 kB] I1011 03:08:22.559] Get:14 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libpython-stdlib amd64 2.7.13-2 [20.0 kB] I1011 03:08:22.560] Get:15 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 python amd64 2.7.13-2 [154 kB] I1011 03:08:22.563] Get:16 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libbsd0 amd64 0.8.3-1 [83.0 kB] I1011 03:08:22.564] Get:17 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libwbclient0 amd64 2:4.5.16+dfsg-1+deb9u2 [124 kB] I1011 03:08:22.567] Get:18 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 ucf all 3.0036 [70.2 kB] I1011 03:08:22.568] Get:19 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 samba-common all 2:4.5.16+dfsg-1+deb9u2 [174 kB] I1011 03:08:22.570] Get:20 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libpopt0 amd64 1.16-10+b2 [49.4 kB] I1011 03:08:22.571] Get:21 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 bzip2 amd64 1.0.6-8.1 [47.5 kB] I1011 03:08:22.576] Get:22 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libapparmor1 amd64 2.11.0-3+deb9u2 [78.9 kB] I1011 03:08:22.598] Get:23 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libdbus-1-3 amd64 1.10.28-0+deb9u1 [195 kB] I1011 03:08:22.602] Get:24 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 dbus amd64 1.10.28-0+deb9u1 [212 kB] I1011 03:08:22.606] Get:25 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libmagic-mgc amd64 1:5.30-1+deb9u2 [222 kB] I1011 03:08:22.609] Get:26 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libmagic1 amd64 1:5.30-1+deb9u2 [111 kB] I1011 03:08:22.611] Get:27 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 file amd64 1:5.30-1+deb9u2 [64.1 kB] I1011 03:08:22.613] Get:28 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 krb5-locales all 1.15-1+deb9u1 [93.8 kB] I1011 03:08:22.615] Get:29 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libgmp10 amd64 2:6.1.2+dfsg-1 [253 kB] I1011 03:08:22.618] Get:30 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libhogweed4 amd64 3.3-1+b2 [136 kB] I1011 03:08:22.620] Get:31 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libp11-kit0 amd64 0.23.3-2 [111 kB] I1011 03:08:22.622] Get:32 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libtasn1-6 amd64 4.10-1.1+deb9u1 [50.6 kB] I1011 03:08:22.642] Get:33 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libgnutls30 amd64 3.5.8-5+deb9u4 [896 kB] I1011 03:08:22.655] Get:34 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libgpm2 amd64 1.20.4-6.2+b1 [34.2 kB] I1011 03:08:22.656] Get:35 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libkeyutils1 amd64 1.5.9-9 [12.4 kB] I1011 03:08:22.656] Get:36 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libkrb5support0 amd64 1.15-1+deb9u1 [61.9 kB] I1011 03:08:22.657] Get:37 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libk5crypto3 amd64 1.15-1+deb9u1 [119 kB] I1011 03:08:22.659] Get:38 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libkrb5-3 amd64 1.15-1+deb9u1 [311 kB] I1011 03:08:22.662] Get:39 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libgssapi-krb5-2 amd64 1.15-1+deb9u1 [155 kB] I1011 03:08:22.664] Get:40 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libsasl2-modules-db amd64 2.1.27~101-g0780600+dfsg-3 [68.2 kB] I1011 03:08:22.666] Get:41 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libsasl2-2 amd64 2.1.27~101-g0780600+dfsg-3 [105 kB] I1011 03:08:22.667] Get:42 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libldap-common all 2.4.44+dfsg-5+deb9u3 [85.7 kB] I1011 03:08:22.686] Get:43 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libldap-2.4-2 amd64 2.4.44+dfsg-5+deb9u3 [220 kB] I1011 03:08:22.690] Get:44 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 xz-utils amd64 5.2.2-1.2+b1 [266 kB] I1011 03:08:22.693] Get:45 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 ca-certificates all 20161130+nmu1+deb9u1 [182 kB] I1011 03:08:22.695] Get:46 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libtalloc2 amd64 2.1.8-1 [36.3 kB] I1011 03:08:22.837] Get:47 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 cifs-utils amd64 2:6.7-1 [75.8 kB] I1011 03:08:22.838] Get:48 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libavahi-common-data amd64 0.6.32-2 [118 kB] I1011 03:08:22.840] Get:49 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libavahi-common3 amd64 0.6.32-2 [52.0 kB] I1011 03:08:22.841] Get:50 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libavahi-client3 amd64 0.6.32-2 [55.3 kB] I1011 03:08:22.842] Get:51 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libcups2 amd64 2.2.1-8+deb9u4 [307 kB] I1011 03:08:22.847] Get:52 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libtdb1 amd64 1.3.11-2 [43.2 kB] I1011 03:08:22.847] Get:53 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libtevent0 amd64 0.9.31-1 [29.3 kB] I1011 03:08:22.849] Get:54 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libldb1 amd64 2:1.1.27-1+deb9u1 [113 kB] I1011 03:08:22.852] Get:55 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libncurses5 amd64 6.0+20161126-1+deb9u2 [93.4 kB] I1011 03:08:22.854] Get:56 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libpython2.7 amd64 2.7.13-2+deb9u3 [1071 kB] I1011 03:08:22.866] Get:57 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 libsasl2-modules amd64 2.1.27~101-g0780600+dfsg-3 [102 kB] I1011 03:08:22.883] Get:58 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 python-crypto amd64 2.6.1-7 [259 kB] I1011 03:08:23.038] Get:59 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 python-ldb amd64 2:1.1.27-1+deb9u1 [34.8 kB] I1011 03:08:23.191] Get:60 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 python-tdb amd64 1.3.11-2 [16.2 kB] I1011 03:08:23.192] Get:61 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 python-talloc amd64 2.1.8-1 [11.9 kB] I1011 03:08:23.194] Get:62 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 samba-libs amd64 2:4.5.16+dfsg-1+deb9u2 [5231 kB] I1011 03:08:23.258] Get:63 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 python-samba amd64 2:4.5.16+dfsg-1+deb9u2 [1360 kB] I1011 03:08:23.273] Get:64 http://cdn-fastly.deb.debian.org/debian stretch/main amd64 samba-common-bin amd64 2:4.5.16+dfsg-1+deb9u2 [603 kB] I1011 03:08:23.580] debconf: delaying package configuration, since apt-utils is not installed I1011 03:08:23.593] Fetched 21.4 MB in 1s (17.2 MB/s) I1011 03:08:23.654] Selecting previously unselected package libpython2.7-minimal:amd64. I1011 03:08:23.658] (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 6500 files and directories currently installed.) I1011 03:08:23.659] Preparing to unpack .../00-libpython2.7-minimal_2.7.13-2+deb9u3_amd64.deb ... I1011 03:08:23.676] Unpacking libpython2.7-minimal:amd64 (2.7.13-2+deb9u3) ... I1011 03:08:23.880] Selecting previously unselected package python2.7-minimal. I1011 03:08:23.882] Preparing to unpack .../01-python2.7-minimal_2.7.13-2+deb9u3_amd64.deb ... I1011 03:08:23.904] Unpacking python2.7-minimal (2.7.13-2+deb9u3) ... I1011 03:08:24.182] Selecting previously unselected package python-minimal. I1011 03:08:24.183] Preparing to unpack .../02-python-minimal_2.7.13-2_amd64.deb ... I1011 03:08:24.200] Unpacking python-minimal (2.7.13-2) ... I1011 03:08:24.324] Selecting previously unselected package mime-support. I1011 03:08:24.325] Preparing to unpack .../03-mime-support_3.60_all.deb ... I1011 03:08:24.339] Unpacking mime-support (3.60) ... I1011 03:08:24.466] Selecting previously unselected package libexpat1:amd64. I1011 03:08:24.468] Preparing to unpack .../04-libexpat1_2.2.0-2+deb9u3_amd64.deb ... I1011 03:08:24.497] Unpacking libexpat1:amd64 (2.2.0-2+deb9u3) ... I1011 03:08:24.630] Selecting previously unselected package libffi6:amd64. I1011 03:08:24.631] Preparing to unpack .../05-libffi6_3.2.1-6_amd64.deb ... I1011 03:08:24.647] Unpacking libffi6:amd64 (3.2.1-6) ... I1011 03:08:24.755] Selecting previously unselected package readline-common. I1011 03:08:24.756] Preparing to unpack .../06-readline-common_7.0-3_all.deb ... I1011 03:08:24.770] Unpacking readline-common (7.0-3) ... I1011 03:08:24.884] Selecting previously unselected package libreadline7:amd64. I1011 03:08:24.885] Preparing to unpack .../07-libreadline7_7.0-3_amd64.deb ... I1011 03:08:24.900] Unpacking libreadline7:amd64 (7.0-3) ... I1011 03:08:25.032] Selecting previously unselected package libsqlite3-0:amd64. I1011 03:08:25.033] Preparing to unpack .../08-libsqlite3-0_3.16.2-5+deb9u1_amd64.deb ... I1011 03:08:25.048] Unpacking libsqlite3-0:amd64 (3.16.2-5+deb9u1) ... I1011 03:08:25.277] Selecting previously unselected package libssl1.1:amd64. I1011 03:08:25.278] Preparing to unpack .../09-libssl1.1_1.1.0l-1~deb9u1_amd64.deb ... I1011 03:08:25.293] Unpacking libssl1.1:amd64 (1.1.0l-1~deb9u1) ... I1011 03:08:25.532] Selecting previously unselected package libpython2.7-stdlib:amd64. I1011 03:08:25.533] Preparing to unpack .../10-libpython2.7-stdlib_2.7.13-2+deb9u3_amd64.deb ... I1011 03:08:25.547] Unpacking libpython2.7-stdlib:amd64 (2.7.13-2+deb9u3) ... I1011 03:08:25.896] Selecting previously unselected package python2.7. I1011 03:08:25.898] Preparing to unpack .../11-python2.7_2.7.13-2+deb9u3_amd64.deb ... I1011 03:08:25.912] Unpacking python2.7 (2.7.13-2+deb9u3) ... I1011 03:08:26.022] Selecting previously unselected package libpython-stdlib:amd64. I1011 03:08:26.023] Preparing to unpack .../12-libpython-stdlib_2.7.13-2_amd64.deb ... I1011 03:08:26.037] Unpacking libpython-stdlib:amd64 (2.7.13-2) ... I1011 03:08:26.198] Setting up libpython2.7-minimal:amd64 (2.7.13-2+deb9u3) ... I1011 03:08:26.272] Setting up python2.7-minimal (2.7.13-2+deb9u3) ... I1011 03:08:26.564] Linking and byte-compiling packages for runtime python2.7... I1011 03:08:26.593] Setting up python-minimal (2.7.13-2) ... I1011 03:08:26.773] Selecting previously unselected package python. I1011 03:08:26.777] (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 7326 files and directories currently installed.) I1011 03:08:26.778] Preparing to unpack .../00-python_2.7.13-2_amd64.deb ... I1011 03:08:26.799] Unpacking python (2.7.13-2) ... I1011 03:08:26.936] Selecting previously unselected package libbsd0:amd64. I1011 03:08:26.937] Preparing to unpack .../01-libbsd0_0.8.3-1_amd64.deb ... I1011 03:08:26.951] Unpacking libbsd0:amd64 (0.8.3-1) ... I1011 03:08:27.060] Selecting previously unselected package libwbclient0:amd64. I1011 03:08:27.061] Preparing to unpack .../02-libwbclient0_2%3a4.5.16+dfsg-1+deb9u2_amd64.deb ... I1011 03:08:27.076] Unpacking libwbclient0:amd64 (2:4.5.16+dfsg-1+deb9u2) ... I1011 03:08:27.219] Selecting previously unselected package ucf. I1011 03:08:27.221] Preparing to unpack .../03-ucf_3.0036_all.deb ... I1011 03:08:27.236] Moving old data out of the way I1011 03:08:27.237] Unpacking ucf (3.0036) ... I1011 03:08:27.392] Selecting previously unselected package samba-common. I1011 03:08:27.393] Preparing to unpack .../04-samba-common_2%3a4.5.16+dfsg-1+deb9u2_all.deb ... I1011 03:08:27.412] Unpacking samba-common (2:4.5.16+dfsg-1+deb9u2) ... I1011 03:08:27.573] Selecting previously unselected package libpopt0:amd64. I1011 03:08:27.574] Preparing to unpack .../05-libpopt0_1.16-10+b2_amd64.deb ... I1011 03:08:27.589] Unpacking libpopt0:amd64 (1.16-10+b2) ... I1011 03:08:27.703] Selecting previously unselected package bzip2. I1011 03:08:27.704] Preparing to unpack .../06-bzip2_1.0.6-8.1_amd64.deb ... I1011 03:08:27.719] Unpacking bzip2 (1.0.6-8.1) ... I1011 03:08:27.833] Selecting previously unselected package libapparmor1:amd64. I1011 03:08:27.834] Preparing to unpack .../07-libapparmor1_2.11.0-3+deb9u2_amd64.deb ... I1011 03:08:27.849] Unpacking libapparmor1:amd64 (2.11.0-3+deb9u2) ... I1011 03:08:27.971] Selecting previously unselected package libdbus-1-3:amd64. I1011 03:08:27.972] Preparing to unpack .../08-libdbus-1-3_1.10.28-0+deb9u1_amd64.deb ... I1011 03:08:27.988] Unpacking libdbus-1-3:amd64 (1.10.28-0+deb9u1) ... I1011 03:08:28.154] Selecting previously unselected package dbus. I1011 03:08:28.155] Preparing to unpack .../09-dbus_1.10.28-0+deb9u1_amd64.deb ... I1011 03:08:28.178] Unpacking dbus (1.10.28-0+deb9u1) ... I1011 03:08:28.329] Selecting previously unselected package libmagic-mgc. I1011 03:08:28.330] Preparing to unpack .../10-libmagic-mgc_1%3a5.30-1+deb9u2_amd64.deb ... I1011 03:08:28.345] Unpacking libmagic-mgc (1:5.30-1+deb9u2) ... I1011 03:08:28.511] Selecting previously unselected package libmagic1:amd64. I1011 03:08:28.512] Preparing to unpack .../11-libmagic1_1%3a5.30-1+deb9u2_amd64.deb ... I1011 03:08:28.529] Unpacking libmagic1:amd64 (1:5.30-1+deb9u2) ... I1011 03:08:28.629] Selecting previously unselected package file. I1011 03:08:28.630] Preparing to unpack .../12-file_1%3a5.30-1+deb9u2_amd64.deb ... I1011 03:08:28.647] Unpacking file (1:5.30-1+deb9u2) ... I1011 03:08:28.746] Selecting previously unselected package krb5-locales. I1011 03:08:28.747] Preparing to unpack .../13-krb5-locales_1.15-1+deb9u1_all.deb ... I1011 03:08:28.763] Unpacking krb5-locales (1.15-1+deb9u1) ... I1011 03:08:28.885] Selecting previously unselected package libgmp10:amd64. I1011 03:08:28.886] Preparing to unpack .../14-libgmp10_2%3a6.1.2+dfsg-1_amd64.deb ... I1011 03:08:28.902] Unpacking libgmp10:amd64 (2:6.1.2+dfsg-1) ... I1011 03:08:29.059] Selecting previously unselected package libhogweed4:amd64. I1011 03:08:29.060] Preparing to unpack .../15-libhogweed4_3.3-1+b2_amd64.deb ... I1011 03:08:29.075] Unpacking libhogweed4:amd64 (3.3-1+b2) ... I1011 03:08:29.197] Selecting previously unselected package libp11-kit0:amd64. I1011 03:08:29.198] Preparing to unpack .../16-libp11-kit0_0.23.3-2_amd64.deb ... I1011 03:08:29.212] Unpacking libp11-kit0:amd64 (0.23.3-2) ... I1011 03:08:29.350] Selecting previously unselected package libtasn1-6:amd64. I1011 03:08:29.351] Preparing to unpack .../17-libtasn1-6_4.10-1.1+deb9u1_amd64.deb ... I1011 03:08:29.366] Unpacking libtasn1-6:amd64 (4.10-1.1+deb9u1) ... I1011 03:08:29.486] Selecting previously unselected package libgnutls30:amd64. I1011 03:08:29.487] Preparing to unpack .../18-libgnutls30_3.5.8-5+deb9u4_amd64.deb ... I1011 03:08:29.501] Unpacking libgnutls30:amd64 (3.5.8-5+deb9u4) ... I1011 03:08:29.713] Selecting previously unselected package libgpm2:amd64. I1011 03:08:29.714] Preparing to unpack .../19-libgpm2_1.20.4-6.2+b1_amd64.deb ... I1011 03:08:29.729] Unpacking libgpm2:amd64 (1.20.4-6.2+b1) ... I1011 03:08:29.841] Selecting previously unselected package libkeyutils1:amd64. I1011 03:08:29.842] Preparing to unpack .../20-libkeyutils1_1.5.9-9_amd64.deb ... I1011 03:08:29.856] Unpacking libkeyutils1:amd64 (1.5.9-9) ... I1011 03:08:29.970] Selecting previously unselected package libkrb5support0:amd64. I1011 03:08:29.971] Preparing to unpack .../21-libkrb5support0_1.15-1+deb9u1_amd64.deb ... I1011 03:08:29.991] Unpacking libkrb5support0:amd64 (1.15-1+deb9u1) ... I1011 03:08:30.116] Selecting previously unselected package libk5crypto3:amd64. I1011 03:08:30.117] Preparing to unpack .../22-libk5crypto3_1.15-1+deb9u1_amd64.deb ... I1011 03:08:30.138] Unpacking libk5crypto3:amd64 (1.15-1+deb9u1) ... I1011 03:08:30.271] Selecting previously unselected package libkrb5-3:amd64. I1011 03:08:30.272] Preparing to unpack .../23-libkrb5-3_1.15-1+deb9u1_amd64.deb ... I1011 03:08:30.287] Unpacking libkrb5-3:amd64 (1.15-1+deb9u1) ... I1011 03:08:30.465] Selecting previously unselected package libgssapi-krb5-2:amd64. I1011 03:08:30.467] Preparing to unpack .../24-libgssapi-krb5-2_1.15-1+deb9u1_amd64.deb ... I1011 03:08:30.482] Unpacking libgssapi-krb5-2:amd64 (1.15-1+deb9u1) ... I1011 03:08:30.597] Selecting previously unselected package libsasl2-modules-db:amd64. I1011 03:08:30.598] Preparing to unpack .../25-libsasl2-modules-db_2.1.27~101-g0780600+dfsg-3_amd64.deb ... I1011 03:08:30.612] Unpacking libsasl2-modules-db:amd64 (2.1.27~101-g0780600+dfsg-3) ... I1011 03:08:30.723] Selecting previously unselected package libsasl2-2:amd64. I1011 03:08:30.724] Preparing to unpack .../26-libsasl2-2_2.1.27~101-g0780600+dfsg-3_amd64.deb ... I1011 03:08:30.739] Unpacking libsasl2-2:amd64 (2.1.27~101-g0780600+dfsg-3) ... I1011 03:08:30.849] Selecting previously unselected package libldap-common. I1011 03:08:30.850] Preparing to unpack .../27-libldap-common_2.4.44+dfsg-5+deb9u3_all.deb ... I1011 03:08:30.865] Unpacking libldap-common (2.4.44+dfsg-5+deb9u3) ... I1011 03:08:30.989] Selecting previously unselected package libldap-2.4-2:amd64. I1011 03:08:30.990] Preparing to unpack .../28-libldap-2.4-2_2.4.44+dfsg-5+deb9u3_amd64.deb ... I1011 03:08:31.005] Unpacking libldap-2.4-2:amd64 (2.4.44+dfsg-5+deb9u3) ... I1011 03:08:31.141] Selecting previously unselected package xz-utils. I1011 03:08:31.142] Preparing to unpack .../29-xz-utils_5.2.2-1.2+b1_amd64.deb ... I1011 03:08:31.158] Unpacking xz-utils (5.2.2-1.2+b1) ... I1011 03:08:31.295] Selecting previously unselected package openssl. I1011 03:08:31.296] Preparing to unpack .../30-openssl_1.1.0l-1~deb9u1_amd64.deb ... I1011 03:08:31.311] Unpacking openssl (1.1.0l-1~deb9u1) ... I1011 03:08:31.524] Selecting previously unselected package ca-certificates. I1011 03:08:31.526] Preparing to unpack .../31-ca-certificates_20161130+nmu1+deb9u1_all.deb ... I1011 03:08:31.540] Unpacking ca-certificates (20161130+nmu1+deb9u1) ... I1011 03:08:31.730] Selecting previously unselected package libtalloc2:amd64. I1011 03:08:31.731] Preparing to unpack .../32-libtalloc2_2.1.8-1_amd64.deb ... I1011 03:08:31.745] Unpacking libtalloc2:amd64 (2.1.8-1) ... I1011 03:08:31.858] Selecting previously unselected package cifs-utils. I1011 03:08:31.859] Preparing to unpack .../33-cifs-utils_2%3a6.7-1_amd64.deb ... I1011 03:08:31.872] Unpacking cifs-utils (2:6.7-1) ... I1011 03:08:31.964] Selecting previously unselected package libavahi-common-data:amd64. I1011 03:08:31.965] Preparing to unpack .../34-libavahi-common-data_0.6.32-2_amd64.deb ... I1011 03:08:31.984] Unpacking libavahi-common-data:amd64 (0.6.32-2) ... I1011 03:08:32.120] Selecting previously unselected package libavahi-common3:amd64. I1011 03:08:32.121] Preparing to unpack .../35-libavahi-common3_0.6.32-2_amd64.deb ... I1011 03:08:32.135] Unpacking libavahi-common3:amd64 (0.6.32-2) ... I1011 03:08:32.263] Selecting previously unselected package libavahi-client3:amd64. I1011 03:08:32.264] Preparing to unpack .../36-libavahi-client3_0.6.32-2_amd64.deb ... I1011 03:08:32.279] Unpacking libavahi-client3:amd64 (0.6.32-2) ... I1011 03:08:32.396] Selecting previously unselected package libcups2:amd64. I1011 03:08:32.397] Preparing to unpack .../37-libcups2_2.2.1-8+deb9u4_amd64.deb ... I1011 03:08:32.412] Unpacking libcups2:amd64 (2.2.1-8+deb9u4) ... I1011 03:08:32.579] Selecting previously unselected package libtdb1:amd64. I1011 03:08:32.579] Preparing to unpack .../38-libtdb1_1.3.11-2_amd64.deb ... I1011 03:08:32.594] Unpacking libtdb1:amd64 (1.3.11-2) ... I1011 03:08:32.710] Selecting previously unselected package libtevent0:amd64. I1011 03:08:32.711] Preparing to unpack .../39-libtevent0_0.9.31-1_amd64.deb ... I1011 03:08:32.726] Unpacking libtevent0:amd64 (0.9.31-1) ... I1011 03:08:32.848] Selecting previously unselected package libldb1:amd64. I1011 03:08:32.849] Preparing to unpack .../40-libldb1_2%3a1.1.27-1+deb9u1_amd64.deb ... I1011 03:08:32.864] Unpacking libldb1:amd64 (2:1.1.27-1+deb9u1) ... I1011 03:08:33.001] Selecting previously unselected package libncurses5:amd64. I1011 03:08:33.003] Preparing to unpack .../41-libncurses5_6.0+20161126-1+deb9u2_amd64.deb ... I1011 03:08:33.017] Unpacking libncurses5:amd64 (6.0+20161126-1+deb9u2) ... I1011 03:08:33.152] Selecting previously unselected package libpython2.7:amd64. I1011 03:08:33.153] Preparing to unpack .../42-libpython2.7_2.7.13-2+deb9u3_amd64.deb ... I1011 03:08:33.168] Unpacking libpython2.7:amd64 (2.7.13-2+deb9u3) ... I1011 03:08:33.412] Selecting previously unselected package libsasl2-modules:amd64. I1011 03:08:33.413] Preparing to unpack .../43-libsasl2-modules_2.1.27~101-g0780600+dfsg-3_amd64.deb ... I1011 03:08:33.432] Unpacking libsasl2-modules:amd64 (2.1.27~101-g0780600+dfsg-3) ... I1011 03:08:33.558] Selecting previously unselected package python-crypto. I1011 03:08:33.559] Preparing to unpack .../44-python-crypto_2.6.1-7_amd64.deb ... I1011 03:08:33.574] Unpacking python-crypto (2.6.1-7) ... I1011 03:08:33.765] Selecting previously unselected package python-ldb. I1011 03:08:33.766] Preparing to unpack .../45-python-ldb_2%3a1.1.27-1+deb9u1_amd64.deb ... I1011 03:08:33.782] Unpacking python-ldb (2:1.1.27-1+deb9u1) ... I1011 03:08:33.893] Selecting previously unselected package python-tdb. I1011 03:08:33.895] Preparing to unpack .../46-python-tdb_1.3.11-2_amd64.deb ... I1011 03:08:33.911] Unpacking python-tdb (1.3.11-2) ... I1011 03:08:34.023] Selecting previously unselected package python-talloc. I1011 03:08:34.024] Preparing to unpack .../47-python-talloc_2.1.8-1_amd64.deb ... I1011 03:08:34.039] Unpacking python-talloc (2.1.8-1) ... I1011 03:08:34.152] Selecting previously unselected package samba-libs:amd64. I1011 03:08:34.153] Preparing to unpack .../48-samba-libs_2%3a4.5.16+dfsg-1+deb9u2_amd64.deb ... I1011 03:08:34.168] Unpacking samba-libs:amd64 (2:4.5.16+dfsg-1+deb9u2) ... I1011 03:08:34.934] Selecting previously unselected package python-samba. I1011 03:08:34.935] Preparing to unpack .../49-python-samba_2%3a4.5.16+dfsg-1+deb9u2_amd64.deb ... I1011 03:08:34.949] Unpacking python-samba (2:4.5.16+dfsg-1+deb9u2) ... I1011 03:08:35.261] Selecting previously unselected package samba-common-bin. I1011 03:08:35.262] Preparing to unpack .../50-samba-common-bin_2%3a4.5.16+dfsg-1+deb9u2_amd64.deb ... I1011 03:08:35.280] Unpacking samba-common-bin (2:4.5.16+dfsg-1+deb9u2) ... I1011 03:08:35.759] Setting up libncurses5:amd64 (6.0+20161126-1+deb9u2) ... I1011 03:08:35.811] Setting up readline-common (7.0-3) ... I1011 03:08:35.858] Setting up libtdb1:amd64 (1.3.11-2) ... I1011 03:08:35.903] Setting up libpopt0:amd64 (1.16-10+b2) ... I1011 03:08:35.946] Setting up libexpat1:amd64 (2.2.0-2+deb9u3) ... I1011 03:08:35.994] Setting up mime-support (3.60) ... I1011 03:08:36.086] Setting up libgpm2:amd64 (1.20.4-6.2+b1) ... I1011 03:08:36.131] Setting up libldap-common (2.4.44+dfsg-5+deb9u3) ... I1011 03:08:36.196] Setting up libreadline7:amd64 (7.0-3) ... I1011 03:08:36.245] Setting up libsasl2-modules-db:amd64 (2.1.27~101-g0780600+dfsg-3) ... I1011 03:08:36.292] Setting up libsasl2-2:amd64 (2.1.27~101-g0780600+dfsg-3) ... I1011 03:08:36.340] Setting up libbsd0:amd64 (0.8.3-1) ... I1011 03:08:36.387] Setting up ucf (3.0036) ... I1011 03:08:36.516] debconf: unable to initialize frontend: Dialog I1011 03:08:36.517] debconf: (TERM is not set, so the dialog frontend is not usable.) I1011 03:08:36.517] debconf: falling back to frontend: Readline I1011 03:08:36.517] debconf: unable to initialize frontend: Readline I1011 03:08:36.518] debconf: (Can't locate Term/ReadLine.pm in @INC (you may need to install the Term::ReadLine module) (@INC contains: /etc/perl /usr/local/lib/x86_64-linux-gnu/perl/5.24.1 /usr/local/share/perl/5.24.1 /usr/lib/x86_64-linux-gnu/perl5/5.24 /usr/share/perl5 /usr/lib/x86_64-linux-gnu/perl/5.24 /usr/share/perl/5.24 /usr/local/lib/site_perl /usr/lib/x86_64-linux-gnu/perl-base .) at /usr/share/perl5/Debconf/FrontEnd/Readline.pm line 7.) I1011 03:08:36.518] debconf: falling back to frontend: Teletype I1011 03:08:36.593] Setting up libtasn1-6:amd64 (4.10-1.1+deb9u1) ... I1011 03:08:36.641] Setting up libmagic-mgc (1:5.30-1+deb9u2) ... I1011 03:08:36.688] Setting up bzip2 (1.0.6-8.1) ... I1011 03:08:36.739] Setting up libmagic1:amd64 (1:5.30-1+deb9u2) ... I1011 03:08:36.816] Setting up libgmp10:amd64 (2:6.1.2+dfsg-1) ... I1011 03:08:36.864] Setting up krb5-locales (1.15-1+deb9u1) ... I1011 03:08:36.912] Processing triggers for libc-bin (2.24-11+deb9u4) ... I1011 03:08:36.964] Setting up libapparmor1:amd64 (2.11.0-3+deb9u2) ... I1011 03:08:37.022] Setting up libssl1.1:amd64 (1.1.0l-1~deb9u1) ... I1011 03:08:37.133] debconf: unable to initialize frontend: Dialog I1011 03:08:37.133] debconf: (TERM is not set, so the dialog frontend is not usable.) I1011 03:08:37.133] debconf: falling back to frontend: Readline I1011 03:08:37.133] debconf: unable to initialize frontend: Readline I1011 03:08:37.134] debconf: (Can't locate Term/ReadLine.pm in @INC (you may need to install the Term::ReadLine module) (@INC contains: /etc/perl /usr/local/lib/x86_64-linux-gnu/perl/5.24.1 /usr/local/share/perl/5.24.1 /usr/lib/x86_64-linux-gnu/perl5/5.24 /usr/share/perl5 /usr/lib/x86_64-linux-gnu/perl/5.24 /usr/share/perl/5.24 /usr/local/lib/site_perl /usr/lib/x86_64-linux-gnu/perl-base .) at /usr/share/perl5/Debconf/FrontEnd/Readline.pm line 7.) I1011 03:08:37.134] debconf: falling back to frontend: Teletype I1011 03:08:37.209] Setting up xz-utils (5.2.2-1.2+b1) ... I1011 03:08:37.240] update-alternatives: using /usr/bin/xz to provide /usr/bin/lzma (lzma) in auto mode I1011 03:08:37.268] Setting up openssl (1.1.0l-1~deb9u1) ... I1011 03:08:37.328] Setting up libsqlite3-0:amd64 (3.16.2-5+deb9u1) ... I1011 03:08:37.390] Setting up libtalloc2:amd64 (2.1.8-1) ... I1011 03:08:37.445] Setting up libffi6:amd64 (3.2.1-6) ... I1011 03:08:37.497] Setting up libkeyutils1:amd64 (1.5.9-9) ... I1011 03:08:37.552] Setting up libsasl2-modules:amd64 (2.1.27~101-g0780600+dfsg-3) ... I1011 03:08:37.625] Setting up ca-certificates (20161130+nmu1+deb9u1) ... I1011 03:08:37.733] debconf: unable to initialize frontend: Dialog I1011 03:08:37.733] debconf: (TERM is not set, so the dialog frontend is not usable.) I1011 03:08:37.733] debconf: falling back to frontend: Readline I1011 03:08:37.734] debconf: unable to initialize frontend: Readline I1011 03:08:37.734] debconf: (Can't locate Term/ReadLine.pm in @INC (you may need to install the Term::ReadLine module) (@INC contains: /etc/perl /usr/local/lib/x86_64-linux-gnu/perl/5.24.1 /usr/local/share/perl/5.24.1 /usr/lib/x86_64-linux-gnu/perl5/5.24 /usr/share/perl5 /usr/lib/x86_64-linux-gnu/perl/5.24 /usr/share/perl/5.24 /usr/local/lib/site_perl /usr/lib/x86_64-linux-gnu/perl-base .) at /usr/share/perl5/Debconf/FrontEnd/Readline.pm line 7.) I1011 03:08:37.734] debconf: falling back to frontend: Teletype I1011 03:08:38.198] Updating certificates in /etc/ssl/certs... I1011 03:08:39.814] 151 added, 0 removed; done. I1011 03:08:39.933] Setting up libpython2.7-stdlib:amd64 (2.7.13-2+deb9u3) ... I1011 03:08:39.980] Setting up libdbus-1-3:amd64 (1.10.28-0+deb9u1) ... I1011 03:08:40.027] Setting up libavahi-common-data:amd64 (0.6.32-2) ... I1011 03:08:40.070] Setting up libwbclient0:amd64 (2:4.5.16+dfsg-1+deb9u2) ... I1011 03:08:40.113] Setting up python2.7 (2.7.13-2+deb9u3) ... I1011 03:08:40.908] Setting up samba-common (2:4.5.16+dfsg-1+deb9u2) ... I1011 03:08:41.059] debconf: unable to initialize frontend: Dialog I1011 03:08:41.060] debconf: (TERM is not set, so the dialog frontend is not usable.) I1011 03:08:41.060] debconf: falling back to frontend: Readline I1011 03:08:41.060] debconf: unable to initialize frontend: Readline I1011 03:08:41.060] debconf: (Can't locate Term/ReadLine.pm in @INC (you may need to install the Term::ReadLine module) (@INC contains: /etc/perl /usr/local/lib/x86_64-linux-gnu/perl/5.24.1 /usr/local/share/perl/5.24.1 /usr/lib/x86_64-linux-gnu/perl5/5.24 /usr/share/perl5 /usr/lib/x86_64-linux-gnu/perl/5.24 /usr/share/perl/5.24 /usr/local/lib/site_perl /usr/lib/x86_64-linux-gnu/perl-base .) at /usr/share/perl5/Debconf/FrontEnd/Readline.pm line 7.) I1011 03:08:41.060] debconf: falling back to frontend: Teletype I1011 03:08:41.135] I1011 03:08:41.135] Creating config file /etc/samba/smb.conf with new version I1011 03:08:41.251] Setting up file (1:5.30-1+deb9u2) ... I1011 03:08:41.293] Setting up libkrb5support0:amd64 (1.15-1+deb9u1) ... I1011 03:08:41.337] Setting up libhogweed4:amd64 (3.3-1+b2) ... I1011 03:08:41.383] Setting up libpython-stdlib:amd64 (2.7.13-2) ... I1011 03:08:41.426] Setting up libtevent0:amd64 (0.9.31-1) ... I1011 03:08:41.470] Setting up libp11-kit0:amd64 (0.23.3-2) ... I1011 03:08:41.515] Setting up libpython2.7:amd64 (2.7.13-2+deb9u3) ... I1011 03:08:41.561] Setting up libavahi-common3:amd64 (0.6.32-2) ... I1011 03:08:41.607] Setting up dbus (1.10.28-0+deb9u1) ... I1011 03:08:41.988] invoke-rc.d: could not determine current runlevel I1011 03:08:41.991] invoke-rc.d: policy-rc.d denied execution of start. I1011 03:08:42.014] Setting up python (2.7.13-2) ... I1011 03:08:42.070] Setting up python-talloc (2.1.8-1) ... I1011 03:08:42.115] Setting up libk5crypto3:amd64 (1.15-1+deb9u1) ... I1011 03:08:42.160] Setting up python-crypto (2.6.1-7) ... I1011 03:08:42.685] Setting up python-tdb (1.3.11-2) ... I1011 03:08:43.122] Setting up libgnutls30:amd64 (3.5.8-5+deb9u4) ... I1011 03:08:43.167] Setting up libldap-2.4-2:amd64 (2.4.44+dfsg-5+deb9u3) ... I1011 03:08:43.217] Setting up libavahi-client3:amd64 (0.6.32-2) ... I1011 03:08:43.268] Setting up libkrb5-3:amd64 (1.15-1+deb9u1) ... I1011 03:08:43.314] Setting up cifs-utils (2:6.7-1) ... I1011 03:08:43.381] update-alternatives: using /usr/lib/x86_64-linux-gnu/cifs-utils/idmapwb.so to provide /etc/cifs-utils/idmap-plugin (idmap-plugin) in auto mode I1011 03:08:43.411] Setting up libldb1:amd64 (2:1.1.27-1+deb9u1) ... I1011 03:08:43.464] Setting up libgssapi-krb5-2:amd64 (1.15-1+deb9u1) ... I1011 03:08:43.542] Setting up libcups2:amd64 (2.2.1-8+deb9u4) ... I1011 03:08:43.586] Setting up python-ldb (2:1.1.27-1+deb9u1) ... I1011 03:08:44.016] Setting up samba-libs:amd64 (2:4.5.16+dfsg-1+deb9u2) ... I1011 03:08:44.065] Setting up python-samba (2:4.5.16+dfsg-1+deb9u2) ... I1011 03:08:44.757] Setting up samba-common-bin (2:4.5.16+dfsg-1+deb9u2) ... I1011 03:08:44.803] Processing triggers for libc-bin (2.24-11+deb9u4) ... I1011 03:08:44.860] Processing triggers for ca-certificates (20161130+nmu1+deb9u1) ... I1011 03:08:44.879] Updating certificates in /etc/ssl/certs... I1011 03:08:45.328] 0 added, 0 removed; done. I1011 03:08:45.328] Running hooks in /etc/ca-certificates/update.d... I1011 03:08:45.328] done. I1011 03:08:49.970] Removing intermediate container 45bced6cf184 I1011 03:08:49.970] ---> cd272f277ea9 I1011 03:08:49.970] Step 3/6 : LABEL maintainers="andyzhangx" I1011 03:08:50.769] ---> Running in 3e6e8acc438d I1011 03:08:51.355] Removing intermediate container 3e6e8acc438d I1011 03:08:51.355] ---> f037990b4564 I1011 03:08:51.355] Step 4/6 : LABEL description="AzureFile CSI Driver" I1011 03:08:51.535] ---> Running in cc75eb2543ae I1011 03:08:52.093] Removing intermediate container cc75eb2543ae I1011 03:08:52.093] ---> d961613e43f2 I1011 03:08:52.093] Step 5/6 : COPY ./_output/azurefileplugin /azurefileplugin I1011 03:08:53.901] ---> de39731fa1a4 I1011 03:08:53.901] Step 6/6 : ENTRYPOINT ["/azurefileplugin"] I1011 03:08:54.038] ---> Running in bd995c3d7cf4 I1011 03:08:55.079] Removing intermediate container bd995c3d7cf4 I1011 03:08:55.079] ---> d3d6a017cb9b I1011 03:08:55.201] Successfully built d3d6a017cb9b I1011 03:08:55.326] Successfully tagged k8sprowinternal.azurecr.io/azurefile-csi:e2e-78fd0851bcc9d9407385c5678d72c3b7e73d2222 I1011 03:08:55.329] docker push k8sprowinternal.azurecr.io/azurefile-csi:e2e-78fd0851bcc9d9407385c5678d72c3b7e73d2222 I1011 03:08:55.391] The push refers to repository [k8sprowinternal.azurecr.io/azurefile-csi] I1011 03:08:55.402] a68e2fd287c0: Preparing I1011 03:08:55.402] 737a1c936920: Preparing I1011 03:08:55.403] 55e6b89812f3: Preparing I1011 03:08:55.616] 55e6b89812f3: Layer already exists I1011 03:08:58.382] a68e2fd287c0: Pushed I1011 03:09:02.398] 737a1c936920: Pushed I1011 03:09:03.268] e2e-78fd0851bcc9d9407385c5678d72c3b7e73d2222: digest: sha256:7767b6fef5c0d6cb3970ae457a34cdef641539d709617d6eeb1a27a209123a91 size: 953 I1011 03:09:03.279] make[2]: Leaving directory '/go/src/sigs.k8s.io/azurefile-csi-driver' I1011 03:09:03.280] helm install charts/latest/azurefile-csi-driver -n azurefile-csi-driver --namespace kube-system --wait \ I1011 03:09:03.280] --set image.pullPolicy=IfNotPresent \ I1011 03:09:03.281] --set image.repository=k8sprowinternal.azurecr.io/azurefile-csi \ I1011 03:09:03.281] --set image.tag=e2e-78fd0851bcc9d9407385c5678d72c3b7e73d2222 I1011 03:10:35.738] NAME: azurefile-csi-driver I1011 03:10:37.352] LAST DEPLOYED: Fri Oct 11 03:09:04 2019 I1011 03:10:37.352] NAMESPACE: kube-system I1011 03:10:37.352] STATUS: DEPLOYED I1011 03:10:37.352] I1011 03:10:37.353] RESOURCES: I1011 03:10:37.353] ==> v1/Deployment I1011 03:10:37.353] NAME AGE I1011 03:10:37.353] csi-azurefile-controller 1m I1011 03:10:37.353] I1011 03:10:37.353] ==> v1/Pod(related) I1011 03:10:37.353] I1011 03:10:37.354] NAME READY STATUS RESTARTS AGE I1011 03:10:37.354] csi-azurefile-node-4dcrv 3/3 Running 0 1m I1011 03:10:37.354] csi-azurefile-node-xxzp2 3/3 Running 0 1m I1011 03:10:37.354] csi-azurefile-controller-6f7b4cdd76-9lzjj 6/6 Running 0 1m I1011 03:10:37.354] I1011 03:10:37.354] ==> v1/ServiceAccount I1011 03:10:37.354] I1011 03:10:37.355] NAME AGE I1011 03:10:37.355] csi-azurefile-controller-sa 1m I1011 03:10:37.355] I1011 03:10:37.355] ==> v1beta1/CustomResourceDefinition I1011 03:10:37.356] csidrivers.csi.storage.k8s.io 1m I1011 03:10:37.356] csinodeinfos.csi.storage.k8s.io 1m I1011 03:10:37.356] I1011 03:10:37.356] ==> v1/ClusterRole I1011 03:10:37.357] azurefile-cluster-driver-registrar-role 1m I1011 03:10:37.357] azurefile-external-snapshotter-role 1m I1011 03:10:37.357] azurefile-external-attacher-role 1m I1011 03:10:37.357] azurefile-external-provisioner-role 1m I1011 03:10:37.358] I1011 03:10:37.358] ==> v1/ClusterRoleBinding I1011 03:10:37.358] azurefile-csi-driver-registrar-binding 1m I1011 03:10:37.358] azurefile-csi-snapshotter-binding 1m I1011 03:10:37.358] azurefile-csi-attacher-binding 1m I1011 03:10:37.359] azurefile-csi-provisioner-binding 1m I1011 03:10:37.359] I1011 03:10:37.359] ==> v1/Service I1011 03:10:37.359] csi-azurefile-controller 1m I1011 03:10:37.360] I1011 03:10:37.360] ==> v1/DaemonSet I1011 03:10:37.360] csi-azurefile-node 1m I1011 03:10:37.360] I1011 03:10:37.360] I1011 03:10:37.361] NOTES: I1011 03:10:37.361] The Azure File CSI Driver is getting deployed to your cluster. I1011 03:10:37.361] I1011 03:10:37.362] To check Azure File CSI Driver pods status, please run: I1011 03:10:37.362] I1011 03:10:37.362] kubectl --namespace=kube-system get pods --selector="release=azurefile-csi-driver" --watch I1011 03:10:37.362] I1011 03:10:37.363] make[1]: Leaving directory '/go/src/sigs.k8s.io/azurefile-csi-driver' I1011 03:10:37.363] 2019/10/11 03:10:37 Azure File CSI Driver installed I1011 03:10:37.363] Dynamic Provisioning I1011 03:10:37.363] should create a volume on demand and mount it as readOnly in a pod I1011 03:10:37.363] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:105 I1011 03:10:37.364] [BeforeEach] Dynamic Provisioning I1011 03:10:37.364] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:149 I1011 03:10:37.364] STEP: Creating a kubernetes client I1011 03:10:37.364] Oct 11 03:10:37.355: INFO: >>> kubeConfig: /workspace/aks644083025/kubeconfig/kubeconfig.eastus2.json I1011 03:10:37.365] I1011 03:10:37.356156 23305 azurefile.go:84] I1011 03:10:37.365] DRIVER INFORMATION: I1011 03:10:37.365] ------------------- I1011 03:10:37.365] Build Date: N/A I1011 03:10:37.365] Compiler: gc I1011 03:10:37.365] Driver Name: file.csi.azure.com I1011 03:10:37.366] Driver Version: N/A I1011 03:10:37.366] Git Commit: N/A I1011 03:10:37.366] Go Version: go1.12.1 I1011 03:10:37.366] Platform: linux/amd64 I1011 03:10:37.366] I1011 03:10:37.367] Streaming logs below: I1011 03:10:37.367] I1011 03:10:37.357311 23305 driver.go:80] Enabling controller service capability: CREATE_DELETE_VOLUME I1011 03:10:37.367] I1011 03:10:37.357339 23305 driver.go:80] Enabling controller service capability: CREATE_DELETE_SNAPSHOT I1011 03:10:37.367] I1011 03:10:37.357349 23305 driver.go:99] Enabling volume access mode: SINGLE_NODE_WRITER I1011 03:10:37.368] I1011 03:10:37.357353 23305 driver.go:99] Enabling volume access mode: SINGLE_NODE_READER_ONLY I1011 03:10:37.368] I1011 03:10:37.357372 23305 driver.go:99] Enabling volume access mode: MULTI_NODE_READER_ONLY I1011 03:10:37.368] I1011 03:10:37.357376 23305 driver.go:99] Enabling volume access mode: MULTI_NODE_SINGLE_WRITER I1011 03:10:37.368] I1011 03:10:37.357380 23305 driver.go:99] Enabling volume access mode: MULTI_NODE_MULTI_WRITER I1011 03:10:37.368] I1011 03:10:37.357655 23305 server.go:104] Listening for connections on address: &net.UnixAddr{Name:"//tmp/csi-b29a3ea5-ebd4-11e9-9412-024252e495aa.sock", Net:"unix"} I1011 03:10:37.369] STEP: Building a namespace api object, basename azurefile I1011 03:10:38.739] Oct 11 03:10:38.739: INFO: Found PodSecurityPolicies; assuming PodSecurityPolicy is enabled. I1011 03:10:40.344] Oct 11 03:10:40.344: INFO: Found ClusterRoles; assuming RBAC is enabled. I1011 03:10:40.570] STEP: Binding the e2e-test-privileged-psp PodSecurityPolicy to the default service account in azurefile-2430 I1011 03:10:41.545] STEP: Waiting for a default service account to be provisioned in namespace I1011 03:10:41.651] [BeforeEach] Dynamic Provisioning I1011 03:10:41.652] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:39 I1011 03:10:41.652] [It] should create a volume on demand and mount it as readOnly in a pod I1011 03:10:41.652] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:105 I1011 03:10:41.652] STEP: setting up the StorageClass I1011 03:10:41.652] STEP: creating a StorageClass I1011 03:10:41.949] STEP: setting up the PVC and PV I1011 03:10:41.949] STEP: creating a PVC I1011 03:10:42.425] STEP: waiting for PVC to be in phase "Bound" I1011 03:10:42.426] Oct 11 03:10:42.425: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-k8cpg] to have phase Bound I1011 03:10:42.602] Oct 11 03:10:42.602: INFO: PersistentVolumeClaim pvc-k8cpg found but phase is Pending instead of Bound. I1011 03:10:45.031] Oct 11 03:10:45.031: INFO: PersistentVolumeClaim pvc-k8cpg found but phase is Pending instead of Bound. I1011 03:10:47.102] Oct 11 03:10:47.102: INFO: PersistentVolumeClaim pvc-k8cpg found but phase is Pending instead of Bound. I1011 03:10:49.208] Oct 11 03:10:49.208: INFO: PersistentVolumeClaim pvc-k8cpg found but phase is Pending instead of Bound. I1011 03:10:51.313] Oct 11 03:10:51.312: INFO: PersistentVolumeClaim pvc-k8cpg found but phase is Pending instead of Bound. I1011 03:10:53.413] Oct 11 03:10:53.413: INFO: PersistentVolumeClaim pvc-k8cpg found but phase is Pending instead of Bound. I1011 03:10:55.666] Oct 11 03:10:55.666: INFO: PersistentVolumeClaim pvc-k8cpg found but phase is Pending instead of Bound. I1011 03:11:01.264] Oct 11 03:11:01.264: INFO: PersistentVolumeClaim pvc-k8cpg found but phase is Pending instead of Bound. I1011 03:11:03.336] Oct 11 03:11:03.335: INFO: PersistentVolumeClaim pvc-k8cpg found but phase is Pending instead of Bound. I1011 03:11:05.407] Oct 11 03:11:05.407: INFO: PersistentVolumeClaim pvc-k8cpg found but phase is Pending instead of Bound. I1011 03:11:07.478] Oct 11 03:11:07.478: INFO: PersistentVolumeClaim pvc-k8cpg found but phase is Pending instead of Bound. I1011 03:11:09.550] Oct 11 03:11:09.549: INFO: PersistentVolumeClaim pvc-k8cpg found but phase is Pending instead of Bound. I1011 03:11:11.621] Oct 11 03:11:11.621: INFO: PersistentVolumeClaim pvc-k8cpg found but phase is Pending instead of Bound. I1011 03:11:13.694] Oct 11 03:11:13.694: INFO: PersistentVolumeClaim pvc-k8cpg found but phase is Pending instead of Bound. I1011 03:11:15.766] Oct 11 03:11:15.765: INFO: PersistentVolumeClaim pvc-k8cpg found but phase is Pending instead of Bound. I1011 03:11:17.842] Oct 11 03:11:17.841: INFO: PersistentVolumeClaim pvc-k8cpg found but phase is Pending instead of Bound. I1011 03:11:19.913] Oct 11 03:11:19.912: INFO: PersistentVolumeClaim pvc-k8cpg found and phase=Bound (37.487250993s) I1011 03:11:19.913] STEP: checking the PVC I1011 03:11:19.983] STEP: validating provisioned PV I1011 03:11:20.055] STEP: checking the PV I1011 03:11:20.055] STEP: deploying the pod I1011 03:11:20.194] STEP: checking that the pods command exits with an error I1011 03:11:20.195] Oct 11 03:11:20.194: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-vn4pz" in namespace "azurefile-2430" to be "Error status code" I1011 03:11:20.265] Oct 11 03:11:20.265: INFO: Pod "azurefile-volume-tester-vn4pz": Phase="Pending", Reason="", readiness=false. Elapsed: 70.242646ms I1011 03:11:22.336] Oct 11 03:11:22.336: INFO: Pod "azurefile-volume-tester-vn4pz": Phase="Pending", Reason="", readiness=false. Elapsed: 2.141329239s I1011 03:11:24.407] Oct 11 03:11:24.407: INFO: Pod "azurefile-volume-tester-vn4pz": Phase="Pending", Reason="", readiness=false. Elapsed: 4.212836936s I1011 03:11:26.479] Oct 11 03:11:26.478: INFO: Pod "azurefile-volume-tester-vn4pz": Phase="Failed", Reason="", readiness=false. Elapsed: 6.28413523s I1011 03:11:26.479] STEP: Saw pod failure I1011 03:11:26.479] Oct 11 03:11:26.478: INFO: Pod "azurefile-volume-tester-vn4pz" satisfied condition "Error status code" I1011 03:11:26.480] STEP: checking that pod logs contain expected message I1011 03:11:26.578] Oct 11 03:11:26.578: INFO: deleting Pod "azurefile-2430"/"azurefile-volume-tester-vn4pz" I1011 03:11:26.653] Oct 11 03:11:26.653: INFO: Pod azurefile-volume-tester-vn4pz has the following logs: touch: /mnt/test-1/data: Read-only file system I1011 03:11:26.653] I1011 03:11:26.653] STEP: Deleting pod azurefile-volume-tester-vn4pz in namespace azurefile-2430 I1011 03:11:26.729] Oct 11 03:11:26.729: INFO: deleting PVC "azurefile-2430"/"pvc-k8cpg" I1011 03:11:26.730] Oct 11 03:11:26.729: INFO: Deleting PersistentVolumeClaim "pvc-k8cpg" I1011 03:11:26.801] STEP: waiting for claim's PV "pvc-0015ed6b-51d5-4703-a55d-7a04f61fc58c" to be deleted I1011 03:11:26.801] Oct 11 03:11:26.801: INFO: Waiting up to 10m0s for PersistentVolume pvc-0015ed6b-51d5-4703-a55d-7a04f61fc58c to get deleted I1011 03:11:26.871] Oct 11 03:11:26.870: INFO: PersistentVolume pvc-0015ed6b-51d5-4703-a55d-7a04f61fc58c found and phase=Released (69.824943ms) I1011 03:11:31.941] Oct 11 03:11:31.941: INFO: PersistentVolume pvc-0015ed6b-51d5-4703-a55d-7a04f61fc58c was removed I1011 03:11:31.942] Oct 11 03:11:31.941: INFO: Waiting up to 5m0s for PersistentVolumeClaim azurefile-2430 to be removed I1011 03:11:32.012] Oct 11 03:11:32.011: INFO: Claim "azurefile-2430" in namespace "pvc-k8cpg" doesn't exist in the system I1011 03:11:32.012] Oct 11 03:11:32.011: INFO: deleting StorageClass azurefile-2430-file.csi.azure.com-dynamic-sc-pnxfv I1011 03:11:32.084] [AfterEach] Dynamic Provisioning I1011 03:11:32.084] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:150 I1011 03:11:32.084] Oct 11 03:11:32.083: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready I1011 03:11:32.154] STEP: Destroying namespace "azurefile-2430" for this suite. I1011 03:11:38.366] Oct 11 03:11:38.366: INFO: Waiting up to 30s for server preferred namespaced resources to be successfully discovered I1011 03:11:41.126] Oct 11 03:11:41.125: INFO: namespace azurefile-2430 deletion completed in 8.971572298s I1011 03:11:41.126] I1011 03:11:41.126] • [SLOW TEST:63.770 seconds] I1011 03:11:41.126] Dynamic Provisioning I1011 03:11:41.127] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:30 I1011 03:11:41.127] should create a volume on demand and mount it as readOnly in a pod I1011 03:11:41.127] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:105 I1011 03:11:41.127] ------------------------------ I1011 03:11:41.128] Dynamic Provisioning I1011 03:11:41.128] [env] should retain PV with reclaimPolicy "Retain" I1011 03:11:41.128] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:170 I1011 03:11:41.128] [BeforeEach] Dynamic Provisioning I1011 03:11:41.129] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:149 I1011 03:11:41.129] STEP: Creating a kubernetes client I1011 03:11:41.129] Oct 11 03:11:41.126: INFO: >>> kubeConfig: /workspace/aks644083025/kubeconfig/kubeconfig.eastus2.json I1011 03:11:41.129] STEP: Building a namespace api object, basename azurefile I1011 03:11:41.340] STEP: Binding the e2e-test-privileged-psp PodSecurityPolicy to the default service account in azurefile-1217 I1011 03:11:41.581] STEP: Waiting for a default service account to be provisioned in namespace I1011 03:11:41.651] [BeforeEach] Dynamic Provisioning I1011 03:11:41.651] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:39 I1011 03:11:41.651] [It] [env] should retain PV with reclaimPolicy "Retain" I1011 03:11:41.651] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:170 I1011 03:11:41.651] STEP: setting up the StorageClass I1011 03:11:41.652] STEP: creating a StorageClass I1011 03:11:41.722] STEP: setting up the PVC and PV I1011 03:11:41.722] STEP: creating a PVC I1011 03:11:41.795] STEP: waiting for PVC to be in phase "Bound" I1011 03:11:41.795] Oct 11 03:11:41.795: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-4rtmz] to have phase Bound I1011 03:11:41.869] Oct 11 03:11:41.869: INFO: PersistentVolumeClaim pvc-4rtmz found but phase is Pending instead of Bound. I1011 03:11:43.940] Oct 11 03:11:43.940: INFO: PersistentVolumeClaim pvc-4rtmz found and phase=Bound (2.145072963s) I1011 03:11:43.940] STEP: checking the PVC I1011 03:11:44.010] STEP: validating provisioned PV I1011 03:11:44.080] STEP: checking the PV I1011 03:11:44.080] Oct 11 03:11:44.080: INFO: deleting PVC "azurefile-1217"/"pvc-4rtmz" I1011 03:11:44.081] Oct 11 03:11:44.080: INFO: Deleting PersistentVolumeClaim "pvc-4rtmz" I1011 03:11:44.152] Oct 11 03:11:44.152: INFO: Waiting up to 5m0s for PersistentVolumeClaim azurefile-1217 to be removed I1011 03:11:44.222] Oct 11 03:11:44.222: INFO: Claim "azurefile-1217" in namespace "pvc-4rtmz" doesn't exist in the system I1011 03:11:44.223] Oct 11 03:11:44.222: INFO: Waiting up to 10m0s for PersistentVolume pvc-a6b9ebbf-ff9c-4f66-b960-5c0ba2c1daa6 to have phase Released I1011 03:11:44.293] Oct 11 03:11:44.292: INFO: PersistentVolume pvc-a6b9ebbf-ff9c-4f66-b960-5c0ba2c1daa6 found and phase=Released (70.209745ms) I1011 03:11:44.293] STEP: deleting PV "pvc-a6b9ebbf-ff9c-4f66-b960-5c0ba2c1daa6" I1011 03:11:44.293] Oct 11 03:11:44.292: INFO: Deleting PersistentVolume "pvc-a6b9ebbf-ff9c-4f66-b960-5c0ba2c1daa6" I1011 03:11:44.368] STEP: waiting for claim's PV "pvc-a6b9ebbf-ff9c-4f66-b960-5c0ba2c1daa6" to be deleted I1011 03:11:44.368] Oct 11 03:11:44.368: INFO: Waiting up to 10m0s for PersistentVolume pvc-a6b9ebbf-ff9c-4f66-b960-5c0ba2c1daa6 to get deleted I1011 03:11:44.438] Oct 11 03:11:44.438: INFO: PersistentVolume pvc-a6b9ebbf-ff9c-4f66-b960-5c0ba2c1daa6 was removed I1011 03:11:44.438] STEP: deleting azurefile volume "#fb5ee51adebd411e9a63e26#pvc-a6b9ebbf-ff9c-4f66-b960-5c0ba2c1daa6" I1011 03:11:45.252] [AfterEach] Dynamic Provisioning I1011 03:11:45.252] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:150 I1011 03:11:45.253] Oct 11 03:11:45.252: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready I1011 03:11:45.391] STEP: Destroying namespace "azurefile-1217" for this suite. I1011 03:11:51.604] Oct 11 03:11:51.604: INFO: Waiting up to 30s for server preferred namespaced resources to be successfully discovered I1011 03:11:54.347] Oct 11 03:11:54.347: INFO: namespace azurefile-1217 deletion completed in 8.956028663s I1011 03:11:54.348] I1011 03:11:54.348] • [SLOW TEST:13.222 seconds] I1011 03:11:54.348] Dynamic Provisioning I1011 03:11:54.348] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:30 I1011 03:11:54.349] [env] should retain PV with reclaimPolicy "Retain" I1011 03:11:54.349] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:170 I1011 03:11:54.349] ------------------------------ I1011 03:11:54.349] Dynamic Provisioning I1011 03:11:54.350] should delete PV with reclaimPolicy "Delete" I1011 03:11:54.350] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:154 I1011 03:11:54.350] [BeforeEach] Dynamic Provisioning I1011 03:11:54.350] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:149 I1011 03:11:54.350] STEP: Creating a kubernetes client I1011 03:11:54.351] Oct 11 03:11:54.347: INFO: >>> kubeConfig: /workspace/aks644083025/kubeconfig/kubeconfig.eastus2.json I1011 03:11:54.351] STEP: Building a namespace api object, basename azurefile I1011 03:11:54.562] STEP: Binding the e2e-test-privileged-psp PodSecurityPolicy to the default service account in azurefile-3730 I1011 03:11:54.804] STEP: Waiting for a default service account to be provisioned in namespace I1011 03:11:54.874] [BeforeEach] Dynamic Provisioning I1011 03:11:54.874] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:39 I1011 03:11:54.874] [It] should delete PV with reclaimPolicy "Delete" I1011 03:11:54.874] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:154 I1011 03:11:54.874] STEP: setting up the StorageClass I1011 03:11:54.874] STEP: creating a StorageClass I1011 03:11:54.944] STEP: setting up the PVC and PV I1011 03:11:54.945] STEP: creating a PVC I1011 03:11:55.017] STEP: waiting for PVC to be in phase "Bound" I1011 03:11:55.018] Oct 11 03:11:55.017: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-9cxzk] to have phase Bound I1011 03:11:55.088] Oct 11 03:11:55.088: INFO: PersistentVolumeClaim pvc-9cxzk found but phase is Pending instead of Bound. I1011 03:11:57.160] Oct 11 03:11:57.160: INFO: PersistentVolumeClaim pvc-9cxzk found and phase=Bound (2.14250414s) I1011 03:11:57.160] STEP: checking the PVC I1011 03:11:57.230] STEP: validating provisioned PV I1011 03:11:57.301] STEP: checking the PV I1011 03:11:57.301] Oct 11 03:11:57.301: INFO: deleting PVC "azurefile-3730"/"pvc-9cxzk" I1011 03:11:57.302] Oct 11 03:11:57.301: INFO: Deleting PersistentVolumeClaim "pvc-9cxzk" I1011 03:11:57.373] STEP: waiting for claim's PV "pvc-07688d5f-3687-46ea-82ad-3bce3c52330b" to be deleted I1011 03:11:57.374] Oct 11 03:11:57.373: INFO: Waiting up to 10m0s for PersistentVolume pvc-07688d5f-3687-46ea-82ad-3bce3c52330b to get deleted I1011 03:11:57.448] Oct 11 03:11:57.448: INFO: PersistentVolume pvc-07688d5f-3687-46ea-82ad-3bce3c52330b found and phase=Released (74.957882ms) I1011 03:12:02.519] Oct 11 03:12:02.519: INFO: PersistentVolume pvc-07688d5f-3687-46ea-82ad-3bce3c52330b was removed I1011 03:12:02.520] Oct 11 03:12:02.519: INFO: Waiting up to 5m0s for PersistentVolumeClaim azurefile-3730 to be removed I1011 03:12:02.590] Oct 11 03:12:02.590: INFO: Claim "azurefile-3730" in namespace "pvc-9cxzk" doesn't exist in the system I1011 03:12:02.590] [AfterEach] Dynamic Provisioning I1011 03:12:02.590] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:150 I1011 03:12:02.591] Oct 11 03:12:02.590: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready I1011 03:12:02.661] STEP: Destroying namespace "azurefile-3730" for this suite. I1011 03:12:08.874] Oct 11 03:12:08.874: INFO: Waiting up to 30s for server preferred namespaced resources to be successfully discovered I1011 03:12:11.564] Oct 11 03:12:11.564: INFO: namespace azurefile-3730 deletion completed in 8.903412637s I1011 03:12:11.564] I1011 03:12:11.565] • [SLOW TEST:17.217 seconds] I1011 03:12:11.565] Dynamic Provisioning I1011 03:12:11.565] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:30 I1011 03:12:11.565] should delete PV with reclaimPolicy "Delete" I1011 03:12:11.566] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:154 I1011 03:12:11.566] ------------------------------ I1011 03:12:11.566] Dynamic Provisioning I1011 03:12:11.566] should create a volume on demand I1011 03:12:11.567] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:45 I1011 03:12:11.567] [BeforeEach] Dynamic Provisioning I1011 03:12:11.567] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:149 I1011 03:12:11.567] STEP: Creating a kubernetes client I1011 03:12:11.567] Oct 11 03:12:11.564: INFO: >>> kubeConfig: /workspace/aks644083025/kubeconfig/kubeconfig.eastus2.json I1011 03:12:11.568] STEP: Building a namespace api object, basename azurefile I1011 03:12:11.778] STEP: Binding the e2e-test-privileged-psp PodSecurityPolicy to the default service account in azurefile-3561 I1011 03:12:12.021] STEP: Waiting for a default service account to be provisioned in namespace I1011 03:12:12.091] [BeforeEach] Dynamic Provisioning I1011 03:12:12.092] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:39 I1011 03:12:12.092] [It] should create a volume on demand I1011 03:12:12.092] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:45 I1011 03:12:12.092] STEP: setting up the StorageClass I1011 03:12:12.092] STEP: creating a StorageClass I1011 03:12:12.165] STEP: setting up the PVC and PV I1011 03:12:12.165] STEP: creating a PVC I1011 03:12:12.239] STEP: waiting for PVC to be in phase "Bound" I1011 03:12:12.239] Oct 11 03:12:12.239: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-fzzf5] to have phase Bound I1011 03:12:12.311] Oct 11 03:12:12.311: INFO: PersistentVolumeClaim pvc-fzzf5 found but phase is Pending instead of Bound. I1011 03:12:14.383] Oct 11 03:12:14.383: INFO: PersistentVolumeClaim pvc-fzzf5 found and phase=Bound (2.143982747s) I1011 03:12:14.383] STEP: checking the PVC I1011 03:12:14.454] STEP: validating provisioned PV I1011 03:12:14.525] STEP: checking the PV I1011 03:12:14.525] STEP: deploying the pod I1011 03:12:14.598] STEP: checking that the pods command exits with no error I1011 03:12:14.598] Oct 11 03:12:14.598: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-prhhx" in namespace "azurefile-3561" to be "success or failure" I1011 03:12:14.669] Oct 11 03:12:14.669: INFO: Pod "azurefile-volume-tester-prhhx": Phase="Pending", Reason="", readiness=false. Elapsed: 71.010851ms I1011 03:12:16.741] Oct 11 03:12:16.741: INFO: Pod "azurefile-volume-tester-prhhx": Phase="Pending", Reason="", readiness=false. Elapsed: 2.14314034s I1011 03:12:18.813] Oct 11 03:12:18.813: INFO: Pod "azurefile-volume-tester-prhhx": Phase="Pending", Reason="", readiness=false. Elapsed: 4.215235628s I1011 03:12:20.886] Oct 11 03:12:20.885: INFO: Pod "azurefile-volume-tester-prhhx": Phase="Pending", Reason="", readiness=false. Elapsed: 6.287687918s I1011 03:12:22.958] Oct 11 03:12:22.958: INFO: Pod "azurefile-volume-tester-prhhx": Phase="Pending", Reason="", readiness=false. Elapsed: 8.360108207s I1011 03:12:25.030] Oct 11 03:12:25.030: INFO: Pod "azurefile-volume-tester-prhhx": Phase="Pending", Reason="", readiness=false. Elapsed: 10.432287494s I1011 03:12:27.103] Oct 11 03:12:27.102: INFO: Pod "azurefile-volume-tester-prhhx": Phase="Pending", Reason="", readiness=false. Elapsed: 12.504760283s I1011 03:12:29.175] Oct 11 03:12:29.175: INFO: Pod "azurefile-volume-tester-prhhx": Phase="Pending", Reason="", readiness=false. Elapsed: 14.577460573s I1011 03:12:31.247] Oct 11 03:12:31.247: INFO: Pod "azurefile-volume-tester-prhhx": Phase="Pending", Reason="", readiness=false. Elapsed: 16.649456958s I1011 03:12:33.320] Oct 11 03:12:33.320: INFO: Pod "azurefile-volume-tester-prhhx": Phase="Pending", Reason="", readiness=false. Elapsed: 18.722095446s I1011 03:12:35.393] Oct 11 03:12:35.392: INFO: Pod "azurefile-volume-tester-prhhx": Phase="Succeeded", Reason="", readiness=false. Elapsed: 20.794624934s I1011 03:12:35.393] STEP: Saw pod success I1011 03:12:35.393] Oct 11 03:12:35.392: INFO: Pod "azurefile-volume-tester-prhhx" satisfied condition "success or failure" I1011 03:12:35.393] Oct 11 03:12:35.392: INFO: deleting Pod "azurefile-3561"/"azurefile-volume-tester-prhhx" I1011 03:12:35.499] Oct 11 03:12:35.499: INFO: Pod azurefile-volume-tester-prhhx has the following logs: hello world I1011 03:12:35.499] I1011 03:12:35.499] STEP: Deleting pod azurefile-volume-tester-prhhx in namespace azurefile-3561 I1011 03:12:35.589] Oct 11 03:12:35.589: INFO: deleting PVC "azurefile-3561"/"pvc-fzzf5" I1011 03:12:35.590] Oct 11 03:12:35.589: INFO: Deleting PersistentVolumeClaim "pvc-fzzf5" I1011 03:12:35.669] STEP: waiting for claim's PV "pvc-83a28b13-c4bd-490c-a41e-33bc45b9db3a" to be deleted I1011 03:12:35.670] Oct 11 03:12:35.669: INFO: Waiting up to 10m0s for PersistentVolume pvc-83a28b13-c4bd-490c-a41e-33bc45b9db3a to get deleted I1011 03:12:35.755] Oct 11 03:12:35.755: INFO: PersistentVolume pvc-83a28b13-c4bd-490c-a41e-33bc45b9db3a found and phase=Released (85.724565ms) I1011 03:12:40.827] Oct 11 03:12:40.827: INFO: PersistentVolume pvc-83a28b13-c4bd-490c-a41e-33bc45b9db3a was removed I1011 03:12:40.828] Oct 11 03:12:40.827: INFO: Waiting up to 5m0s for PersistentVolumeClaim azurefile-3561 to be removed I1011 03:12:40.899] Oct 11 03:12:40.899: INFO: Claim "azurefile-3561" in namespace "pvc-fzzf5" doesn't exist in the system I1011 03:12:40.899] Oct 11 03:12:40.899: INFO: deleting StorageClass azurefile-3561-file.csi.azure.com-dynamic-sc-69tw6 I1011 03:12:40.973] [AfterEach] Dynamic Provisioning I1011 03:12:40.973] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:150 I1011 03:12:40.973] Oct 11 03:12:40.973: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready I1011 03:12:41.045] STEP: Destroying namespace "azurefile-3561" for this suite. I1011 03:12:47.280] Oct 11 03:12:47.280: INFO: Waiting up to 30s for server preferred namespaced resources to be successfully discovered I1011 03:12:50.010] Oct 11 03:12:50.009: INFO: namespace azurefile-3561 deletion completed in 8.964406273s I1011 03:12:50.010] I1011 03:12:50.010] • [SLOW TEST:38.445 seconds] I1011 03:12:50.010] Dynamic Provisioning I1011 03:12:50.011] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:30 I1011 03:12:50.011] should create a volume on demand I1011 03:12:50.011] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:45 I1011 03:12:50.011] ------------------------------ I1011 03:12:50.011] Dynamic Provisioning I1011 03:12:50.012] should create a deployment object, write and read to it, delete the pod and write and read to it again I1011 03:12:50.012] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:129 I1011 03:12:50.012] [BeforeEach] Dynamic Provisioning I1011 03:12:50.012] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:149 I1011 03:12:50.013] STEP: Creating a kubernetes client I1011 03:12:50.013] Oct 11 03:12:50.009: INFO: >>> kubeConfig: /workspace/aks644083025/kubeconfig/kubeconfig.eastus2.json I1011 03:12:50.013] STEP: Building a namespace api object, basename azurefile I1011 03:12:50.228] STEP: Binding the e2e-test-privileged-psp PodSecurityPolicy to the default service account in azurefile-9367 I1011 03:12:50.472] STEP: Waiting for a default service account to be provisioned in namespace I1011 03:12:50.546] [BeforeEach] Dynamic Provisioning I1011 03:12:50.546] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:39 I1011 03:12:50.546] [It] should create a deployment object, write and read to it, delete the pod and write and read to it again I1011 03:12:50.546] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:129 I1011 03:12:50.546] STEP: setting up the StorageClass I1011 03:12:50.546] STEP: creating a StorageClass I1011 03:12:50.620] STEP: setting up the PVC I1011 03:12:50.620] STEP: creating a PVC I1011 03:12:50.696] STEP: waiting for PVC to be in phase "Bound" I1011 03:12:50.696] Oct 11 03:12:50.696: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-dhjnt] to have phase Bound I1011 03:12:50.767] Oct 11 03:12:50.767: INFO: PersistentVolumeClaim pvc-dhjnt found but phase is Pending instead of Bound. I1011 03:12:52.840] Oct 11 03:12:52.840: INFO: PersistentVolumeClaim pvc-dhjnt found and phase=Bound (2.14420814s) I1011 03:12:52.841] STEP: checking the PVC I1011 03:12:52.912] STEP: validating provisioned PV I1011 03:12:52.984] STEP: checking the PV I1011 03:12:52.984] STEP: setting up the Deployment I1011 03:12:52.984] STEP: deploying the deployment I1011 03:12:53.133] Oct 11 03:12:53.132: 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:63706360373, loc:(*time.Location)(0x34883c0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63706360373, loc:(*time.Location)(0x34883c0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63706360373, loc:(*time.Location)(0x34883c0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63706360372, loc:(*time.Location)(0x34883c0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"ebs-volume-tester-zg7hm-58fcfd7574\" is progressing."}}, CollisionCount:(*int32)(nil)} I1011 03:12:55.205] Oct 11 03:12:55.204: 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:63706360373, loc:(*time.Location)(0x34883c0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63706360373, loc:(*time.Location)(0x34883c0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63706360373, loc:(*time.Location)(0x34883c0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63706360372, loc:(*time.Location)(0x34883c0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"ebs-volume-tester-zg7hm-58fcfd7574\" is progressing."}}, CollisionCount:(*int32)(nil)} I1011 03:12:57.205] Oct 11 03:12:57.204: 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:63706360373, loc:(*time.Location)(0x34883c0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63706360373, loc:(*time.Location)(0x34883c0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63706360373, loc:(*time.Location)(0x34883c0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63706360372, loc:(*time.Location)(0x34883c0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"ebs-volume-tester-zg7hm-58fcfd7574\" is progressing."}}, CollisionCount:(*int32)(nil)} I1011 03:12:59.205] Oct 11 03:12:59.205: 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:63706360373, loc:(*time.Location)(0x34883c0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63706360373, loc:(*time.Location)(0x34883c0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63706360373, loc:(*time.Location)(0x34883c0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63706360372, loc:(*time.Location)(0x34883c0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"ebs-volume-tester-zg7hm-58fcfd7574\" is progressing."}}, CollisionCount:(*int32)(nil)} I1011 03:13:01.205] Oct 11 03:13:01.204: 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:63706360373, loc:(*time.Location)(0x34883c0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63706360373, loc:(*time.Location)(0x34883c0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63706360373, loc:(*time.Location)(0x34883c0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63706360372, loc:(*time.Location)(0x34883c0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"ebs-volume-tester-zg7hm-58fcfd7574\" is progressing."}}, CollisionCount:(*int32)(nil)} I1011 03:13:03.205] Oct 11 03:13:03.205: 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:63706360373, loc:(*time.Location)(0x34883c0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63706360373, loc:(*time.Location)(0x34883c0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63706360373, loc:(*time.Location)(0x34883c0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63706360372, loc:(*time.Location)(0x34883c0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"ebs-volume-tester-zg7hm-58fcfd7574\" is progressing."}}, CollisionCount:(*int32)(nil)} I1011 03:13:05.205] Oct 11 03:13:05.204: 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:63706360373, loc:(*time.Location)(0x34883c0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63706360373, loc:(*time.Location)(0x34883c0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63706360373, loc:(*time.Location)(0x34883c0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63706360372, loc:(*time.Location)(0x34883c0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"ebs-volume-tester-zg7hm-58fcfd7574\" is progressing."}}, CollisionCount:(*int32)(nil)} I1011 03:13:07.206] Oct 11 03:13:07.205: 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:63706360373, loc:(*time.Location)(0x34883c0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63706360373, loc:(*time.Location)(0x34883c0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63706360373, loc:(*time.Location)(0x34883c0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63706360372, loc:(*time.Location)(0x34883c0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"ebs-volume-tester-zg7hm-58fcfd7574\" is progressing."}}, CollisionCount:(*int32)(nil)} I1011 03:13:09.205] Oct 11 03:13:09.204: 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:63706360373, loc:(*time.Location)(0x34883c0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63706360373, loc:(*time.Location)(0x34883c0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63706360373, loc:(*time.Location)(0x34883c0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63706360372, loc:(*time.Location)(0x34883c0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"ebs-volume-tester-zg7hm-58fcfd7574\" is progressing."}}, CollisionCount:(*int32)(nil)} I1011 03:13:11.206] Oct 11 03:13:11.205: 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:63706360373, loc:(*time.Location)(0x34883c0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63706360373, loc:(*time.Location)(0x34883c0)}}, Reason:"MinimumReplicasUnavailable", Message:"Deployment does not have minimum availability."}, v1.DeploymentCondition{Type:"Progressing", Status:"True", LastUpdateTime:v1.Time{Time:time.Time{wall:0x0, ext:63706360373, loc:(*time.Location)(0x34883c0)}}, LastTransitionTime:v1.Time{Time:time.Time{wall:0x0, ext:63706360372, loc:(*time.Location)(0x34883c0)}}, Reason:"ReplicaSetUpdated", Message:"ReplicaSet \"ebs-volume-tester-zg7hm-58fcfd7574\" is progressing."}}, CollisionCount:(*int32)(nil)} I1011 03:13:13.350] STEP: checking that the pod is running I1011 03:13:13.494] STEP: deleting the pod for deployment I1011 03:13:13.494] Oct 11 03:13:13.494: INFO: Deleting pod "ebs-volume-tester-zg7hm-58fcfd7574-pq4b4" in namespace "azurefile-9367" I1011 03:13:13.569] Oct 11 03:13:13.569: INFO: Waiting for pod "ebs-volume-tester-zg7hm-58fcfd7574-pq4b4" in namespace "azurefile-9367" to be fully deleted I1011 03:13:57.714] STEP: checking again that the pod is running I1011 03:14:22.009] STEP: checking pod exec I1011 03:14:22.009] Oct 11 03:14:22.008: INFO: Running '/usr/local/bin/kubectl --kubeconfig=/workspace/aks644083025/kubeconfig/kubeconfig.eastus2.json exec ebs-volume-tester-zg7hm-58fcfd7574-wnk28 --namespace=azurefile-9367 -- cat /mnt/test-1/data' I1011 03:14:23.203] Oct 11 03:14:23.203: INFO: stderr: "" I1011 03:14:23.203] Oct 11 03:14:23.203: INFO: stdout: "hello world\nhello world\n" I1011 03:14:23.204] Oct 11 03:14:23.203: INFO: deleting Deployment "azurefile-9367"/"ebs-volume-tester-zg7hm" I1011 03:14:23.279] Oct 11 03:14:23.279: INFO: Pod ebs-volume-tester-zg7hm-58fcfd7574-wnk28 has the following logs: I1011 03:14:23.353] Oct 11 03:14:23.353: INFO: deleting PVC "azurefile-9367"/"pvc-dhjnt" I1011 03:14:23.353] Oct 11 03:14:23.353: INFO: Deleting PersistentVolumeClaim "pvc-dhjnt" I1011 03:14:23.426] STEP: waiting for claim's PV "pvc-c62deb0e-e8af-4ad4-8031-9cf7170c8c9c" to be deleted I1011 03:14:23.427] Oct 11 03:14:23.426: INFO: Waiting up to 10m0s for PersistentVolume pvc-c62deb0e-e8af-4ad4-8031-9cf7170c8c9c to get deleted I1011 03:14:23.498] Oct 11 03:14:23.497: INFO: PersistentVolume pvc-c62deb0e-e8af-4ad4-8031-9cf7170c8c9c found and phase=Bound (71.313553ms) I1011 03:14:28.570] Oct 11 03:14:28.570: INFO: PersistentVolume pvc-c62deb0e-e8af-4ad4-8031-9cf7170c8c9c found and phase=Bound (5.143752673s) I1011 03:14:33.642] Oct 11 03:14:33.642: INFO: PersistentVolume pvc-c62deb0e-e8af-4ad4-8031-9cf7170c8c9c found and phase=Bound (10.215792487s) I1011 03:14:38.714] Oct 11 03:14:38.714: INFO: PersistentVolume pvc-c62deb0e-e8af-4ad4-8031-9cf7170c8c9c found and phase=Bound (15.287672698s) I1011 03:14:43.787] Oct 11 03:14:43.786: INFO: PersistentVolume pvc-c62deb0e-e8af-4ad4-8031-9cf7170c8c9c found and phase=Bound (20.360279012s) I1011 03:14:48.859] Oct 11 03:14:48.859: INFO: PersistentVolume pvc-c62deb0e-e8af-4ad4-8031-9cf7170c8c9c found and phase=Bound (25.432475721s) I1011 03:14:53.933] Oct 11 03:14:53.932: INFO: PersistentVolume pvc-c62deb0e-e8af-4ad4-8031-9cf7170c8c9c found and phase=Bound (30.50630304s) I1011 03:14:59.006] Oct 11 03:14:59.005: INFO: PersistentVolume pvc-c62deb0e-e8af-4ad4-8031-9cf7170c8c9c was removed I1011 03:14:59.006] Oct 11 03:14:59.005: INFO: Waiting up to 5m0s for PersistentVolumeClaim azurefile-9367 to be removed I1011 03:14:59.077] Oct 11 03:14:59.077: INFO: Claim "azurefile-9367" in namespace "pvc-dhjnt" doesn't exist in the system I1011 03:14:59.077] Oct 11 03:14:59.077: INFO: deleting StorageClass azurefile-9367-file.csi.azure.com-dynamic-sc-7xdfc I1011 03:14:59.152] [AfterEach] Dynamic Provisioning I1011 03:14:59.152] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:150 I1011 03:14:59.152] Oct 11 03:14:59.152: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready I1011 03:14:59.224] STEP: Destroying namespace "azurefile-9367" for this suite. I1011 03:15:05.440] Oct 11 03:15:05.440: INFO: Waiting up to 30s for server preferred namespaced resources to be successfully discovered I1011 03:15:08.152] Oct 11 03:15:08.152: INFO: namespace azurefile-9367 deletion completed in 8.92813668s I1011 03:15:08.152] I1011 03:15:08.152] • [SLOW TEST:138.142 seconds] I1011 03:15:08.153] Dynamic Provisioning I1011 03:15:08.153] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:30 I1011 03:15:08.153] should create a deployment object, write and read to it, delete the pod and write and read to it again I1011 03:15:08.153] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:129 I1011 03:15:08.153] ------------------------------ I1011 03:15:08.154] [azurefile-csi-e2e] [single-az] Pre-Provisioned I1011 03:15:08.154] [env] should use a pre-provisioned volume and mount it as readOnly in a pod I1011 03:15:08.154] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/pre_provisioning.go:66 I1011 03:15:08.154] [BeforeEach] [azurefile-csi-e2e] [single-az] Pre-Provisioned I1011 03:15:08.154] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:149 I1011 03:15:08.154] STEP: Creating a kubernetes client I1011 03:15:08.155] Oct 11 03:15:08.152: INFO: >>> kubeConfig: /workspace/aks644083025/kubeconfig/kubeconfig.eastus2.json I1011 03:15:08.155] STEP: Building a namespace api object, basename azurefile I1011 03:15:08.368] STEP: Binding the e2e-test-privileged-psp PodSecurityPolicy to the default service account in azurefile-8899 I1011 03:15:08.611] STEP: Waiting for a default service account to be provisioned in namespace I1011 03:15:08.682] [BeforeEach] [azurefile-csi-e2e] [single-az] Pre-Provisioned I1011 03:15:08.683] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/pre_provisioning.go:48 I1011 03:15:08.683] [It] [env] should use a pre-provisioned volume and mount it as readOnly in a pod I1011 03:15:08.683] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/pre_provisioning.go:66 I1011 03:15:09.718] STEP: Successfully provisioned AzureFile volume: "#fb5ee51adebd411e9a63e26#pre-provisioned-readonly" I1011 03:15:09.718] I1011 03:15:09.718] STEP: setting up the PV I1011 03:15:09.718] STEP: creating a PV I1011 03:15:09.792] STEP: setting up the PVC I1011 03:15:09.792] STEP: creating a PVC I1011 03:15:09.866] STEP: waiting for PVC to be in phase "Bound" I1011 03:15:09.867] Oct 11 03:15:09.866: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-6px5s] to have phase Bound I1011 03:15:09.940] Oct 11 03:15:09.940: INFO: PersistentVolumeClaim pvc-6px5s found and phase=Bound (73.561969ms) I1011 03:15:09.940] STEP: checking the PVC I1011 03:15:10.011] STEP: validating provisioned PV I1011 03:15:10.082] STEP: checking the PV I1011 03:15:10.083] STEP: deploying the pod I1011 03:15:10.155] STEP: checking that the pods command exits with an error I1011 03:15:10.155] Oct 11 03:15:10.155: INFO: Waiting up to 15m0s for pod "azurefile-volume-tester-mlxch" in namespace "azurefile-8899" to be "Error status code" I1011 03:15:10.226] Oct 11 03:15:10.226: INFO: Pod "azurefile-volume-tester-mlxch": Phase="Pending", Reason="", readiness=false. Elapsed: 71.272453ms I1011 03:15:12.298] Oct 11 03:15:12.298: INFO: Pod "azurefile-volume-tester-mlxch": Phase="Pending", Reason="", readiness=false. Elapsed: 2.143092505s I1011 03:15:14.370] Oct 11 03:15:14.370: INFO: Pod "azurefile-volume-tester-mlxch": Phase="Pending", Reason="", readiness=false. Elapsed: 4.215056358s I1011 03:15:16.442] Oct 11 03:15:16.442: INFO: Pod "azurefile-volume-tester-mlxch": Phase="Pending", Reason="", readiness=false. Elapsed: 6.287356213s I1011 03:15:18.514] Oct 11 03:15:18.514: INFO: Pod "azurefile-volume-tester-mlxch": Phase="Pending", Reason="", readiness=false. Elapsed: 8.359228765s I1011 03:15:20.586] Oct 11 03:15:20.586: INFO: Pod "azurefile-volume-tester-mlxch": Phase="Failed", Reason="", readiness=false. Elapsed: 10.431461019s I1011 03:15:20.587] STEP: Saw pod failure I1011 03:15:20.587] Oct 11 03:15:20.586: INFO: Pod "azurefile-volume-tester-mlxch" satisfied condition "Error status code" I1011 03:15:20.587] STEP: checking that pod logs contain expected message I1011 03:15:20.662] Oct 11 03:15:20.662: INFO: deleting Pod "azurefile-8899"/"azurefile-volume-tester-mlxch" I1011 03:15:20.745] Oct 11 03:15:20.744: INFO: Pod azurefile-volume-tester-mlxch has the following logs: /bin/sh: can't create /mnt/test-1/data: Read-only file system I1011 03:15:20.745] I1011 03:15:20.745] STEP: Deleting pod azurefile-volume-tester-mlxch in namespace azurefile-8899 I1011 03:15:20.821] Oct 11 03:15:20.821: INFO: deleting PVC "azurefile-8899"/"pvc-6px5s" I1011 03:15:20.822] Oct 11 03:15:20.821: INFO: Deleting PersistentVolumeClaim "pvc-6px5s" I1011 03:15:20.894] Oct 11 03:15:20.893: INFO: Waiting up to 5m0s for PersistentVolumeClaim azurefile-8899 to be removed I1011 03:15:20.965] Oct 11 03:15:20.965: INFO: Claim "azurefile-8899" in namespace "pvc-6px5s" doesn't exist in the system I1011 03:15:20.965] STEP: deleting PV "azurefile-8899-file.csi.azure.com-preprovsioned-pv-p46jj" I1011 03:15:20.965] Oct 11 03:15:20.965: INFO: Deleting PersistentVolume "azurefile-8899-file.csi.azure.com-preprovsioned-pv-p46jj" I1011 03:15:21.037] STEP: waiting for claim's PV "azurefile-8899-file.csi.azure.com-preprovsioned-pv-p46jj" to be deleted I1011 03:15:21.037] Oct 11 03:15:21.037: INFO: Waiting up to 10m0s for PersistentVolume azurefile-8899-file.csi.azure.com-preprovsioned-pv-p46jj to get deleted I1011 03:15:21.108] Oct 11 03:15:21.108: INFO: PersistentVolume azurefile-8899-file.csi.azure.com-preprovsioned-pv-p46jj was removed I1011 03:15:21.108] [AfterEach] [azurefile-csi-e2e] [single-az] Pre-Provisioned I1011 03:15:21.109] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:150 I1011 03:15:21.109] Oct 11 03:15:21.108: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready I1011 03:15:21.257] STEP: Destroying namespace "azurefile-8899" for this suite. I1011 03:15:27.473] Oct 11 03:15:27.473: INFO: Waiting up to 30s for server preferred namespaced resources to be successfully discovered I1011 03:15:30.213] Oct 11 03:15:30.212: INFO: namespace azurefile-8899 deletion completed in 8.955765578s I1011 03:15:30.213] [AfterEach] [azurefile-csi-e2e] [single-az] Pre-Provisioned I1011 03:15:30.213] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/pre_provisioning.go:54 I1011 03:15:30.620] I1011 03:15:30.620] • [SLOW TEST:22.468 seconds] I1011 03:15:30.621] [azurefile-csi-e2e] [single-az] Pre-Provisioned I1011 03:15:30.621] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/pre_provisioning.go:36 I1011 03:15:30.621] [env] should use a pre-provisioned volume and mount it as readOnly in a pod I1011 03:15:30.621] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/pre_provisioning.go:66 I1011 03:15:30.622] ------------------------------ I1011 03:15:30.622] Dynamic Provisioning I1011 03:15:30.622] should create multiple PV objects, bind to PVCs and attach all to different pods on the same node I1011 03:15:30.622] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:67 I1011 03:15:30.622] [BeforeEach] Dynamic Provisioning I1011 03:15:30.623] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:149 I1011 03:15:30.623] STEP: Creating a kubernetes client I1011 03:15:30.623] Oct 11 03:15:30.620: INFO: >>> kubeConfig: /workspace/aks644083025/kubeconfig/kubeconfig.eastus2.json I1011 03:15:30.623] STEP: Building a namespace api object, basename azurefile I1011 03:15:30.838] STEP: Binding the e2e-test-privileged-psp PodSecurityPolicy to the default service account in azurefile-2377 I1011 03:15:31.082] STEP: Waiting for a default service account to be provisioned in namespace I1011 03:15:31.153] [BeforeEach] Dynamic Provisioning I1011 03:15:31.154] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:39 I1011 03:15:31.154] [It] should create multiple PV objects, bind to PVCs and attach all to different pods on the same node I1011 03:15:31.154] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:67 I1011 03:15:31.154] STEP: setting up the StorageClass I1011 03:15:31.155] STEP: creating a StorageClass I1011 03:15:31.228] STEP: setting up the PVC and PV I1011 03:15:31.229] STEP: creating a PVC I1011 03:15:31.304] STEP: waiting for PVC to be in phase "Bound" I1011 03:15:31.305] Oct 11 03:15:31.304: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-twbxm] to have phase Bound I1011 03:15:31.376] Oct 11 03:15:31.376: INFO: PersistentVolumeClaim pvc-twbxm found but phase is Pending instead of Bound. I1011 03:15:33.448] Oct 11 03:15:33.448: INFO: PersistentVolumeClaim pvc-twbxm found and phase=Bound (2.143741506s) I1011 03:15:33.448] STEP: checking the PVC I1011 03:15:33.519] STEP: validating provisioned PV I1011 03:15:33.592] STEP: checking the PV I1011 03:15:33.592] STEP: deploying the pod I1011 03:15:33.664] STEP: checking that the pod is running I1011 03:15:55.809] STEP: setting up the StorageClass I1011 03:15:55.809] STEP: creating a StorageClass I1011 03:15:55.882] STEP: setting up the PVC and PV I1011 03:15:55.882] STEP: creating a PVC I1011 03:15:55.956] STEP: waiting for PVC to be in phase "Bound" I1011 03:15:55.956] Oct 11 03:15:55.956: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-fcs4c] to have phase Bound I1011 03:15:56.027] Oct 11 03:15:56.027: INFO: PersistentVolumeClaim pvc-fcs4c found but phase is Pending instead of Bound. I1011 03:15:58.099] Oct 11 03:15:58.099: INFO: PersistentVolumeClaim pvc-fcs4c found and phase=Bound (2.143369999s) I1011 03:15:58.100] STEP: checking the PVC I1011 03:15:58.171] STEP: validating provisioned PV I1011 03:15:58.245] STEP: checking the PV I1011 03:15:58.245] STEP: deploying the pod I1011 03:15:58.318] STEP: checking that the pod is running I1011 03:16:12.463] Oct 11 03:16:12.463: INFO: deleting Pod "azurefile-2377"/"azurefile-volume-tester-9hvg4" I1011 03:16:12.539] Oct 11 03:16:12.539: INFO: Pod azurefile-volume-tester-9hvg4 has the following logs: I1011 03:16:12.540] STEP: Deleting pod azurefile-volume-tester-9hvg4 in namespace azurefile-2377 I1011 03:16:12.614] Oct 11 03:16:12.614: INFO: deleting PVC "azurefile-2377"/"pvc-fcs4c" I1011 03:16:12.614] Oct 11 03:16:12.614: INFO: Deleting PersistentVolumeClaim "pvc-fcs4c" I1011 03:16:12.688] STEP: waiting for claim's PV "pvc-2fa10b34-2502-45be-92a7-0372ab51ebe6" to be deleted I1011 03:16:12.688] Oct 11 03:16:12.687: INFO: Waiting up to 10m0s for PersistentVolume pvc-2fa10b34-2502-45be-92a7-0372ab51ebe6 to get deleted I1011 03:16:12.759] Oct 11 03:16:12.759: INFO: PersistentVolume pvc-2fa10b34-2502-45be-92a7-0372ab51ebe6 found and phase=Bound (71.680455ms) I1011 03:16:17.831] Oct 11 03:16:17.831: INFO: PersistentVolume pvc-2fa10b34-2502-45be-92a7-0372ab51ebe6 found and phase=Bound (5.14396423s) I1011 03:16:22.910] Oct 11 03:16:22.909: INFO: PersistentVolume pvc-2fa10b34-2502-45be-92a7-0372ab51ebe6 found and phase=Bound (10.221923448s) I1011 03:16:27.982] Oct 11 03:16:27.982: INFO: PersistentVolume pvc-2fa10b34-2502-45be-92a7-0372ab51ebe6 found and phase=Bound (15.294447322s) I1011 03:16:33.055] Oct 11 03:16:33.054: INFO: PersistentVolume pvc-2fa10b34-2502-45be-92a7-0372ab51ebe6 found and phase=Bound (20.367097995s) I1011 03:16:38.127] Oct 11 03:16:38.127: INFO: PersistentVolume pvc-2fa10b34-2502-45be-92a7-0372ab51ebe6 found and phase=Bound (25.439445565s) I1011 03:16:43.200] Oct 11 03:16:43.200: INFO: PersistentVolume pvc-2fa10b34-2502-45be-92a7-0372ab51ebe6 found and phase=Bound (30.512360036s) I1011 03:16:48.272] Oct 11 03:16:48.272: INFO: PersistentVolume pvc-2fa10b34-2502-45be-92a7-0372ab51ebe6 was removed I1011 03:16:48.273] Oct 11 03:16:48.272: INFO: Waiting up to 5m0s for PersistentVolumeClaim azurefile-2377 to be removed I1011 03:16:48.344] Oct 11 03:16:48.344: INFO: Claim "azurefile-2377" in namespace "pvc-fcs4c" doesn't exist in the system I1011 03:16:48.345] Oct 11 03:16:48.344: INFO: deleting StorageClass azurefile-2377-file.csi.azure.com-dynamic-sc-gbtd7 I1011 03:16:48.418] Oct 11 03:16:48.418: INFO: deleting Pod "azurefile-2377"/"azurefile-volume-tester-x9qmx" I1011 03:16:48.495] Oct 11 03:16:48.495: INFO: Pod azurefile-volume-tester-x9qmx has the following logs: I1011 03:16:48.495] STEP: Deleting pod azurefile-volume-tester-x9qmx in namespace azurefile-2377 I1011 03:16:48.568] Oct 11 03:16:48.568: INFO: deleting PVC "azurefile-2377"/"pvc-twbxm" I1011 03:16:48.569] Oct 11 03:16:48.568: INFO: Deleting PersistentVolumeClaim "pvc-twbxm" I1011 03:16:48.643] STEP: waiting for claim's PV "pvc-c859a0f0-2875-4c63-bddf-0cccb5439ee6" to be deleted I1011 03:16:48.643] Oct 11 03:16:48.642: INFO: Waiting up to 10m0s for PersistentVolume pvc-c859a0f0-2875-4c63-bddf-0cccb5439ee6 to get deleted I1011 03:16:48.714] Oct 11 03:16:48.714: INFO: PersistentVolume pvc-c859a0f0-2875-4c63-bddf-0cccb5439ee6 found and phase=Bound (71.667554ms) I1011 03:16:53.787] Oct 11 03:16:53.787: INFO: PersistentVolume pvc-c859a0f0-2875-4c63-bddf-0cccb5439ee6 found and phase=Bound (5.144363821s) I1011 03:16:58.860] Oct 11 03:16:58.859: INFO: PersistentVolume pvc-c859a0f0-2875-4c63-bddf-0cccb5439ee6 found and phase=Bound (10.216972885s) I1011 03:17:03.933] Oct 11 03:17:03.932: INFO: PersistentVolume pvc-c859a0f0-2875-4c63-bddf-0cccb5439ee6 found and phase=Bound (15.28981695s) I1011 03:17:09.004] Oct 11 03:17:09.004: INFO: PersistentVolume pvc-c859a0f0-2875-4c63-bddf-0cccb5439ee6 found and phase=Bound (20.361579905s) I1011 03:17:14.077] Oct 11 03:17:14.077: INFO: PersistentVolume pvc-c859a0f0-2875-4c63-bddf-0cccb5439ee6 found and phase=Bound (25.434318865s) I1011 03:17:19.151] Oct 11 03:17:19.151: INFO: PersistentVolume pvc-c859a0f0-2875-4c63-bddf-0cccb5439ee6 found and phase=Bound (30.508266933s) I1011 03:17:24.223] Oct 11 03:17:24.223: INFO: PersistentVolume pvc-c859a0f0-2875-4c63-bddf-0cccb5439ee6 was removed I1011 03:17:24.224] Oct 11 03:17:24.223: INFO: Waiting up to 5m0s for PersistentVolumeClaim azurefile-2377 to be removed I1011 03:17:24.302] Oct 11 03:17:24.302: INFO: Claim "azurefile-2377" in namespace "pvc-twbxm" doesn't exist in the system I1011 03:17:24.303] Oct 11 03:17:24.302: INFO: deleting StorageClass azurefile-2377-file.csi.azure.com-dynamic-sc-gbbcr I1011 03:17:24.376] [AfterEach] Dynamic Provisioning I1011 03:17:24.376] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:150 I1011 03:17:24.376] Oct 11 03:17:24.376: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready I1011 03:17:24.518] STEP: Destroying namespace "azurefile-2377" for this suite. I1011 03:17:30.735] Oct 11 03:17:30.735: INFO: Waiting up to 30s for server preferred namespaced resources to be successfully discovered I1011 03:17:33.463] Oct 11 03:17:33.463: INFO: namespace azurefile-2377 deletion completed in 8.944655318s I1011 03:17:33.463] I1011 03:17:33.463] • [SLOW TEST:122.843 seconds] I1011 03:17:33.464] Dynamic Provisioning I1011 03:17:33.464] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:30 I1011 03:17:33.464] should create multiple PV objects, bind to PVCs and attach all to different pods on the same node I1011 03:17:33.464] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/dynamic_provisioning.go:67 I1011 03:17:33.464] ------------------------------ I1011 03:17:33.465] [azurefile-csi-e2e] [single-az] Pre-Provisioned I1011 03:17:33.465] [env] should use a pre-provisioned volume and retain PV with reclaimPolicy "Retain" I1011 03:17:33.465] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/pre_provisioning.go:100 I1011 03:17:33.465] [BeforeEach] [azurefile-csi-e2e] [single-az] Pre-Provisioned I1011 03:17:33.465] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:149 I1011 03:17:33.466] STEP: Creating a kubernetes client I1011 03:17:33.466] Oct 11 03:17:33.463: INFO: >>> kubeConfig: /workspace/aks644083025/kubeconfig/kubeconfig.eastus2.json I1011 03:17:33.466] STEP: Building a namespace api object, basename azurefile I1011 03:17:33.681] STEP: Binding the e2e-test-privileged-psp PodSecurityPolicy to the default service account in azurefile-4975 I1011 03:17:33.924] STEP: Waiting for a default service account to be provisioned in namespace I1011 03:17:33.995] [BeforeEach] [azurefile-csi-e2e] [single-az] Pre-Provisioned I1011 03:17:33.995] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/pre_provisioning.go:48 I1011 03:17:33.995] [It] [env] should use a pre-provisioned volume and retain PV with reclaimPolicy "Retain" I1011 03:17:33.995] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/pre_provisioning.go:100 I1011 03:17:34.710] STEP: Successfully provisioned AzureFile volume: "#fb5ee51adebd411e9a63e26#pre-provisioned-retain-reclaimpolicy" I1011 03:17:34.710] I1011 03:17:34.711] STEP: setting up the PV I1011 03:17:34.711] STEP: creating a PV I1011 03:17:34.783] STEP: setting up the PVC I1011 03:17:34.783] STEP: creating a PVC I1011 03:17:34.857] STEP: waiting for PVC to be in phase "Bound" I1011 03:17:34.857] Oct 11 03:17:34.857: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-5fwsb] to have phase Bound I1011 03:17:34.929] Oct 11 03:17:34.928: INFO: PersistentVolumeClaim pvc-5fwsb found and phase=Bound (71.742755ms) I1011 03:17:34.929] STEP: checking the PVC I1011 03:17:35.000] STEP: validating provisioned PV I1011 03:17:35.072] STEP: checking the PV I1011 03:17:35.072] Oct 11 03:17:35.072: INFO: deleting PVC "azurefile-4975"/"pvc-5fwsb" I1011 03:17:35.073] Oct 11 03:17:35.072: INFO: Deleting PersistentVolumeClaim "pvc-5fwsb" I1011 03:17:35.145] Oct 11 03:17:35.145: INFO: Waiting up to 5m0s for PersistentVolumeClaim azurefile-4975 to be removed I1011 03:17:35.217] Oct 11 03:17:35.217: INFO: Claim "azurefile-4975" in namespace "pvc-5fwsb" doesn't exist in the system I1011 03:17:35.218] Oct 11 03:17:35.217: INFO: Waiting up to 10m0s for PersistentVolume azurefile-4975-file.csi.azure.com-preprovsioned-pv-kh6xl to have phase Released I1011 03:17:35.290] Oct 11 03:17:35.289: INFO: PersistentVolume azurefile-4975-file.csi.azure.com-preprovsioned-pv-kh6xl found and phase=Released (72.39846ms) I1011 03:17:35.290] STEP: deleting PV "azurefile-4975-file.csi.azure.com-preprovsioned-pv-kh6xl" I1011 03:17:35.290] Oct 11 03:17:35.289: INFO: Deleting PersistentVolume "azurefile-4975-file.csi.azure.com-preprovsioned-pv-kh6xl" I1011 03:17:35.363] STEP: waiting for claim's PV "azurefile-4975-file.csi.azure.com-preprovsioned-pv-kh6xl" to be deleted I1011 03:17:35.363] Oct 11 03:17:35.363: INFO: Waiting up to 10m0s for PersistentVolume azurefile-4975-file.csi.azure.com-preprovsioned-pv-kh6xl to get deleted I1011 03:17:35.434] Oct 11 03:17:35.434: INFO: PersistentVolume azurefile-4975-file.csi.azure.com-preprovsioned-pv-kh6xl was removed I1011 03:17:35.435] [AfterEach] [azurefile-csi-e2e] [single-az] Pre-Provisioned I1011 03:17:35.435] /go/pkg/mod/k8s.io/kubernetes@v1.14.0/test/e2e/framework/framework.go:150 I1011 03:17:35.435] Oct 11 03:17:35.434: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready I1011 03:17:35.577] STEP: Destroying namespace "azurefile-4975" for this suite. I1011 03:17:41.793] Oct 11 03:17:41.792: INFO: Waiting up to 30s for server preferred namespaced resources to be successfully discovered I1011 03:17:44.533] Oct 11 03:17:44.532: INFO: namespace azurefile-4975 deletion completed in 8.9560503s I1011 03:17:44.533] [AfterEach] [azurefile-csi-e2e] [single-az] Pre-Provisioned I1011 03:17:44.533] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/pre_provisioning.go:54 I1011 03:17:44.951] I1011 03:17:44.952] • [SLOW TEST:11.488 seconds] I1011 03:17:44.952] [azurefile-csi-e2e] [single-az] Pre-Provisioned I1011 03:17:44.952] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/pre_provisioning.go:36 I1011 03:17:44.952] [env] should use a pre-provisioned volume and retain PV with reclaimPolicy "Retain" I1011 03:17:44.952] /go/src/sigs.k8s.io/azurefile-csi-driver/test/e2e/pre_provisioning.go:100 I1011 03:17:44.953] ------------------------------ I1011 03:17:44.953] 2019/10/11 03:17:44 Uninstalling Azure File CSI Driver... I1011 03:17:44.953] make[1]: Entering directory '/go/src/sigs.k8s.io/azurefile-csi-driver' I1011 03:17:44.954] helm delete --purge azurefile-csi-driver I1011 03:17:49.543] release "azurefile-csi-driver" deleted I1011 03:17:49.545] make[1]: Leaving directory '/go/src/sigs.k8s.io/azurefile-csi-driver' I1011 03:17:49.545] 2019/10/11 03:17:49 Azure File CSI Driver uninstalled I1011 03:17:49.545] I1011 03:17:49.545] Ran 8 of 8 Specs in 625.960 seconds I1011 03:17:49.545] SUCCESS! -- 8 Passed | 0 Failed | 0 Pending | 0 Skipped I1011 03:17:49.546] --- PASS: TestE2E (625.96s) I1011 03:17:49.546] PASS I1011 03:17:49.548] ok github.com/kubernetes-sigs/azurefile-csi-driver/test/e2e 626.012s W1011 03:17:49.737] 2019/10/11 03:17:49 process.go:155: Step 'make e2e-test' finished in 12m8.83381956s W1011 03:17:49.738] 2019/10/11 03:17:49 e2e.go:519: Dumping logs from nodes to GCS directly at path: gs://kubernetes-upstream/pr-logs/pull/sigs.k8s.io_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/1182483760709373952/artifacts W1011 03:17:49.738] 2019/10/11 03:17:49 process.go:153: Running: ./cluster/log-dump/log-dump.sh /workspace/_artifacts gs://kubernetes-upstream/pr-logs/pull/sigs.k8s.io_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/1182483760709373952/artifacts W1011 03:17:49.747] KUBE_MASTER_IP: W1011 03:17:49.747] KUBE_MASTER: W1011 03:17:49.747] ./cluster/log-dump/log-dump.sh: line 285: MASTER_NAME: unbound variable W1011 03:17:49.748] 2019/10/11 03:17:49 process.go:155: Step './cluster/log-dump/log-dump.sh /workspace/_artifacts gs://kubernetes-upstream/pr-logs/pull/sigs.k8s.io_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/1182483760709373952/artifacts' finished in 10.291179ms W1011 03:17:49.748] 2019/10/11 03:17:49 azure.go:906: Deleting resource group: kubetest-600323a9-ebcf-11e9-b889-024252e495aa. I1011 03:17:49.848] Checking for custom logdump instances, if any I1011 03:17:49.849] Sourcing kube-util.sh I1011 03:17:49.849] Detecting project I1011 03:17:49.849] Skeleton Provider: detect-project not implemented I1011 03:17:49.849] Dumping logs from master locally to '/workspace/_artifacts' W1011 03:27:43.407] 2019/10/11 03:27:43 process.go:96: Saved XML output to /workspace/_artifacts/junit_runner.xml. W1011 03:27:43.408] 2019/10/11 03:27:43 process.go:153: Running: bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}" W1011 03:27:44.093] 2019/10/11 03:27:44 process.go:155: Step 'bash -c . hack/lib/version.sh && KUBE_ROOT=. kube::version::get_version_vars && echo "${KUBE_GIT_VERSION-}"' finished in 685.366603ms W1011 03:27:44.093] 2019/10/11 03:27:44 main.go:319: Something went wrong: encountered 1 errors: [error during ./cluster/log-dump/log-dump.sh /workspace/_artifacts gs://kubernetes-upstream/pr-logs/pull/sigs.k8s.io_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/1182483760709373952/artifacts: exit status 1] W1011 03:27:44.095] Traceback (most recent call last): W1011 03:27:44.095] File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 778, in W1011 03:27:44.095] main(parse_args()) W1011 03:27:44.095] File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 626, in main W1011 03:27:44.095] mode.start(runner_args) W1011 03:27:44.096] File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 262, in start W1011 03:27:44.096] check_env(env, self.command, *args) W1011 03:27:44.096] File "/workspace/./test-infra/jenkins/../scenarios/kubernetes_e2e.py", line 111, in check_env W1011 03:27:44.096] subprocess.check_call(cmd, env=env) W1011 03:27:44.096] File "/usr/lib/python2.7/subprocess.py", line 186, in check_call W1011 03:27:44.096] raise CalledProcessError(retcode, cmd) W1011 03:27:44.097] 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-file-csi-driver=True', '--timeout=420m', '--logexporter-gcs-path=gs://kubernetes-upstream/pr-logs/pull/sigs.k8s.io_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/1182483760709373952/artifacts')' returned non-zero exit status 1 E1011 03:27:44.102] Command failed I1011 03:27:44.102] process 689 exited with code 1 after 55.2m E1011 03:27:44.102] FAIL: pull-azurefile-csi-driver-e2e I1011 03:27:44.103] Call: gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json W1011 03:27:44.854] Activated service account credentials for: [kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com] I1011 03:27:44.886] process 32658 exited with code 0 after 0.0m I1011 03:27:44.886] Call: gcloud config get-value account I1011 03:27:45.131] process 32670 exited with code 0 after 0.0m I1011 03:27:45.131] Will upload results to gs://kubernetes-upstream/pr-logs using kubernetes-upstream@kubernetes-upstream.iam.gserviceaccount.com I1011 03:27:45.131] Upload result and artifacts... I1011 03:27:45.131] Gubernator results at https://gubernator.k8s.io/build/kubernetes-upstream/pr-logs/pull/sigs.k8s.io_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/1182483760709373952 I1011 03:27:45.132] Call: gsutil ls gs://kubernetes-upstream/pr-logs/pull/sigs.k8s.io_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/1182483760709373952/artifacts W1011 03:27:46.319] CommandException: One or more URLs matched no objects. E1011 03:27:46.397] Command failed I1011 03:27:46.397] process 32682 exited with code 1 after 0.0m W1011 03:27:46.397] Remote dir gs://kubernetes-upstream/pr-logs/pull/sigs.k8s.io_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/1182483760709373952/artifacts not exist yet I1011 03:27:46.397] 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_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/1182483760709373952/artifacts I1011 03:27:47.928] process 356 exited with code 0 after 0.0m I1011 03:27:47.928] Call: git rev-parse HEAD I1011 03:27:47.931] process 901 exited with code 0 after 0.0m I1011 03:27:47.931] Call: git rev-parse HEAD I1011 03:27:47.935] process 902 exited with code 0 after 0.0m I1011 03:27:47.935] Call: gsutil stat gs://kubernetes-upstream/pr-logs/directory/pull-azurefile-csi-driver-e2e/jobResultsCache.json I1011 03:27:48.861] process 903 exited with code 0 after 0.0m I1011 03:27:48.862] Call: gsutil -q cat 'gs://kubernetes-upstream/pr-logs/directory/pull-azurefile-csi-driver-e2e/jobResultsCache.json#1570753209638735' I1011 03:27:50.100] process 1047 exited with code 0 after 0.0m I1011 03:27:50.101] Call: gsutil -q -h Content-Type:application/json -h x-goog-if-generation-match:1570753209638735 cp /tmp/gsutil_fnDHoE gs://kubernetes-upstream/pr-logs/directory/pull-azurefile-csi-driver-e2e/jobResultsCache.json I1011 03:27:51.451] process 1191 exited with code 0 after 0.0m I1011 03:27:51.452] Call: gsutil stat gs://kubernetes-upstream/pr-logs/pull/sigs.k8s.io_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/jobResultsCache.json I1011 03:27:52.389] process 1369 exited with code 0 after 0.0m I1011 03:27:52.390] Call: gsutil -q cat 'gs://kubernetes-upstream/pr-logs/pull/sigs.k8s.io_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/jobResultsCache.json#1570753213273770' I1011 03:27:53.536] process 1511 exited with code 0 after 0.0m I1011 03:27:53.536] Call: gsutil -q -h Content-Type:application/json -h x-goog-if-generation-match:1570753213273770 cp /tmp/gsutil_RHkleN gs://kubernetes-upstream/pr-logs/pull/sigs.k8s.io_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/jobResultsCache.json I1011 03:27:54.921] process 1655 exited with code 0 after 0.0m I1011 03:27:54.922] Call: gsutil -q -h Content-Type:application/json cp /tmp/gsutil_1uJ3At gs://kubernetes-upstream/pr-logs/pull/sigs.k8s.io_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/1182483760709373952/finished.json I1011 03:27:56.292] process 1833 exited with code 0 after 0.0m I1011 03:27:56.293] Call: gsutil -q -h Content-Type:text/plain -h 'Cache-Control:private, max-age=0, no-transform' cp /tmp/gsutil_uD7iNb gs://kubernetes-upstream/pr-logs/directory/pull-azurefile-csi-driver-e2e/latest-build.txt I1011 03:27:57.720] process 2011 exited with code 0 after 0.0m I1011 03:27:57.721] Call: gsutil -q -h Content-Type:text/plain -h 'Cache-Control:private, max-age=0, no-transform' cp /tmp/gsutil_GYh6oR gs://kubernetes-upstream/pr-logs/pull/sigs.k8s.io_azurefile-csi-driver/120/pull-azurefile-csi-driver-e2e/latest-build.txt I1011 03:27:59.115] process 2189 exited with code 0 after 0.0m