This job view page is being replaced by Spyglass soon. Check out the new job view.
ResultFAILURE
Tests 1 failed / 26 succeeded
Started2020-02-12 11:53
Elapsed38m56s
Revision
Buildergke-prow-default-pool-cf4891d4-m8gw
links{u'resultstore': {u'url': u'https://source.cloud.google.com/results/invocations/fdf02198-1910-4ac5-bac6-c62b719f3c39/targets/test'}}
pod2d5243ef-4d8e-11ea-8c6e-1aa579f21cc7
resultstorehttps://source.cloud.google.com/results/invocations/fdf02198-1910-4ac5-bac6-c62b719f3c39/targets/test
infra-commit87c059793
pod2d5243ef-4d8e-11ea-8c6e-1aa579f21cc7
reposigs.k8s.io/gcp-compute-persistent-disk-csi-driver
repo-commitcbb21d5a05a614e3299ac96c23cf1019271e0024
repos{u'sigs.k8s.io/gcp-compute-persistent-disk-csi-driver': u'release-0.4.0'}

Test Failures


[sig-storage] CSI Volumes [Driver: pd.csi.storage.gke.io][Feature: gcePD-external] [Testpattern: Dynamic PV (default fs)] subPath should fail if subpath file is outside the volume [Slow] 6m36s

go run hack/e2e.go -v --test --test_args='--ginkgo.focus=\[sig\-storage\]\sCSI\sVolumes\s\[Driver\:\spd\.csi\.storage\.gke\.io\]\[Feature\:\sgcePD\-external\]\s\[Testpattern\:\sDynamic\sPV\s\(default\sfs\)\]\ssubPath\sshould\sfail\sif\ssubpath\sfile\sis\soutside\sthe\svolume\s\[Slow\]$'
/go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:120
Persistent Volume pvc-55870a9b-4d91-11ea-ba4c-42010a800002 not deleted by dynamic provisioner
Expected error:
    <*errors.errorString | 0xc000377590>: {
        s: "PersistentVolume pvc-55870a9b-4d91-11ea-ba4c-42010a800002 still exists within 5m0s",
    }
    PersistentVolume pvc-55870a9b-4d91-11ea-ba4c-42010a800002 still exists within 5m0s
not to have occurred
/go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/base.go:213
				
				Click to see stdout/stderrfrom junit_07.xml

Filter through log files | View test history on testgrid


Show 26 Passed Tests

Show 2134 Skipped Tests

Error lines from build-log.txt

... skipping 238 lines ...
W0212 12:12:22.452] Trying to find master named 'e2e-test-prow-master'
W0212 12:12:22.452] Looking for address 'e2e-test-prow-master-ip'
W0212 12:12:23.492] Using master: e2e-test-prow-master (external IP: 35.222.213.144)
I0212 12:12:23.593] Waiting up to 300 seconds for cluster initialization.
I0212 12:12:23.593] 
I0212 12:12:23.593]   This will continually check to see if the API for kubernetes is reachable.
I0212 12:12:23.593]   This may time out if there was some uncaught error during start up.
I0212 12:12:23.593] 
I0212 12:13:29.010] ................Kubernetes cluster created.
I0212 12:13:29.244] Cluster "k8s-boskos-gce-project-14_e2e-test-prow" set.
I0212 12:13:29.445] User "k8s-boskos-gce-project-14_e2e-test-prow" set.
I0212 12:13:29.656] Context "k8s-boskos-gce-project-14_e2e-test-prow" created.
I0212 12:13:29.882] Switched to context "k8s-boskos-gce-project-14_e2e-test-prow".
... skipping 20 lines ...
I0212 12:14:20.178] NAME                              STATUS                     ROLES    AGE   VERSION
I0212 12:14:20.178] e2e-test-prow-master              Ready,SchedulingDisabled   <none>   20s   v1.13.5
I0212 12:14:20.179] e2e-test-prow-minion-group-bl5h   Ready                      <none>   17s   v1.13.5
I0212 12:14:20.179] e2e-test-prow-minion-group-ckng   Ready                      <none>   16s   v1.13.5
I0212 12:14:20.179] e2e-test-prow-minion-group-p6g9   Ready                      <none>   17s   v1.13.5
I0212 12:14:20.422] Validate output:
I0212 12:14:20.657] NAME                 STATUS    MESSAGE              ERROR
I0212 12:14:20.657] controller-manager   Healthy   ok                   
I0212 12:14:20.657] scheduler            Healthy   ok                   
I0212 12:14:20.658] etcd-0               Healthy   {"health": "true"}   
I0212 12:14:20.658] etcd-1               Healthy   {"health": "true"}   
I0212 12:14:20.668] Cluster validation succeeded
W0212 12:14:20.769] Done, listing cluster services:
... skipping 116 lines ...
W0212 12:14:35.661]   "details": {
W0212 12:14:35.661]     "name": "cloud-sa",
W0212 12:14:35.661]     "kind": "secrets"
W0212 12:14:35.661]   },
W0212 12:14:35.661]   "code": 404
W0212 12:14:35.661] }]
W0212 12:14:35.662] F0212 12:14:35.658887   64497 helpers.go:116] Error from server (NotFound): secrets "cloud-sa" not found
W0212 12:14:35.671] + /go/src/sigs.k8s.io/gcp-compute-persistent-disk-csi-driver/test/k8s-integration/src/k8s.io/kubernetes/cluster/kubectl.sh create secret generic cloud-sa -v=9 --from-file=/tmp/3af90021-4d91-11ea-8683-8aef1bbba954/cloud-sa.json -n default
W0212 12:14:35.884] I0212 12:14:35.884651   64541 loader.go:359] Config loaded from file /root/.kube/config
W0212 12:14:35.886] I0212 12:14:35.885835   64541 loader.go:359] Config loaded from file /root/.kube/config
W0212 12:14:35.887] I0212 12:14:35.887515   64541 loader.go:359] Config loaded from file /root/.kube/config
W0212 12:14:35.894] I0212 12:14:35.891530   64541 request.go:942] Request Body: {"apiVersion":"v1","data":{"cloud-sa.json":"ewogICJ0eXBlIjogInNlcnZpY2VfYWNjb3VudCIsCiAgInByb2plY3RfaWQiOiAia3ViZXJuZXRlcy1qZW5raW5zLXB1bGwiLAogICJwcml2YXRlX2tleV9pZCI6ICI5ZGMxNDU3YzBiMjQ5ZWZlMTRmOTkzMzM3OTRkMDA2MTNiNzRkMTE2IiwKICAicHJpdmF0ZV9rZXkiOiAiLS0tLS1CRUdJTiBQUklWQVRFIEtFWS0tLS0tXG5NSUlFdlFJQkFEQU5CZ2txaGtpRzl3MEJBUUVGQUFTQ0JLY3dnZ1NqQWdFQUFvSUJBUUNrcEx2WmdOdC9BME1XXG5RdTR4UENkeWgreUg3Z09xdXNEQjMxMGNmL2xwN2sxNmJkL0U4aDdVTmp0S2xpaC90UVZCdjdiejh3c0pIUmpvXG5LZ1JDbjd3NmczVFB5Q0Q1YmtUUzFNT1RMMjRiU3F3YW9BUFhGd0k3eEt5NlNDTnpDckVPazJ2b3F6NE5LT3BhXG5Ob0UrV0lBblg0TVQvS0xWbERVMlRmaTE5R2NCbHBiMlFaOGlFWmtUQTZWNHFXM0oxSFNlemhtczhsTHZ1akJ4XG5namdlWlY1SDBJaHZjMFFDTG9rejhIelh6TnBzaXRaQWVSL0hIWVY2TElsUkhLTjRMb0p0RkY2NHBnQjREZkI3XG5OU1ZwdXQ3M3k5OE1lUkhUU1l5MmRqVlFHTlYzYVdqdmhVZzVyUE5DUjBKRWxKeENTaXZUMW4xUTJRU0d2eDZtXG4rVS9pTjhyUEFnTUJBQUVDZ2dFQUJNVk5PQ2syc3dCNk1pdndVUGJvUWJaVWtUL0JWWEloNGJ4Q0szQTkzdWJyXG4wYzliTzQ2MGUvdXlUaC81dm5HVlhHbGN1TWJqRy9sKzNrTlJha2pNb0hsc3FoU25kL0xOQmJycWk5cEUrMzkzXG5heklWeW1hOVJ0UVZHVFM3NmpwMkZQRUtvR3hOMlAzRmhLV3Rxd3ZQY3RTZXJMYVdWVS85RnJ5OXB6QVV5QVAwXG5KZE4rUnVYcGRVMkJ6WTRGbm1MWnk2WXdlZmF2ekFtRHBjYTFVOWpJSHExdkIwSnFZWGFXU200VkIwL1Y0dzZFXG5RWXlMYjFKa29hd1p3VUZkeTBlaDBGTzNLVG9KOUtjNHVaQm1sWVBScy9NWlBNM21HNk9JVmVQeDY5ZEUxemNtXG5BZnBXcm4xV3VITWZNK1J5WFBIRHMzRW1yQXJiYzhtQ0ttaGVRaFB3S1FLQmdRRFZSY0VrYXVFYmM1c3dyQnRxXG5OUG1jR0dMeVlvS2x6TGIvTGgzVFhiOWozYnRnWFFzbjNzMmd2MEFLYlpERVpKRzJxU3hNQ1FvRHNLRWcvTXhhXG5wUTZQUEg4MlZ2bzUxTHBUTkhoZDJyWU5xVnEwblJTdzNCYWdoTUFvREVnd1I3cnA0emJ2WWVvTkwxd1FmTTl0XG5rbmxBL2szVE40YTBOaTRrYkQzS0F3UjN5d0tCZ1FERm9PbWRrL3FuaE5zSFU2ZmZxdVpxTDFXenZXZkJRcVo4XG50Mm5vSFlRbFd5M2Rzd21vZlV5NFU3N3h3VmJBVHRQZjBXM2JjY3hWc2tKSXZJRHhoRmJ3WFVSNkZUVkJXc2F3XG5jcXIzQmJycDMyTWUydERHckV0VGlPVGJBcTFlV015cHc5NFpHaFdCOExMa1E1SXd5bjJuWndMcmRHRlljM3lnXG51blZWUit0d2pRS0JnUURFSVJMZWw3K09URUZpZ0ZQeDF1ZlpxZitNb2hVOXZrWm40NVFnSmUxMVBKc3Rva001XG5Ga2VKMVhkaVg2SXJTY1ZLOHNhKzRlMG91WTFrVmJia2dUZ2pkMklScWVrUnQ5VGw0Ykh6dGNlSVJyOFlyQUEwXG5LU0pSMmVNUXNVTE55NWxUcjlWOFRWSTliOWs5ZkZvUmpRc2ZQdjU1Q0c1RFdqUVM0TXZ0ODlwdkF3S0JnQ1BuXG5JY25RMGw2UWtrSDRmcXp4blQ1NUx2YWlXREVSN0xFSG1TUGtDTmZJZ3NLZC9na3dDam9LYk12NnRjbm1DRFBIXG5GbEFoa2wrWExOZU45MWJwRmVwQTUybk9aSWhrOTJlaXpWQm5LQmZJejNjUmhaQXlTTlQ2TDZsaUNTRDB2T215XG5mYXpOd2s2QzdkenVNYWJQZ3BoZzdIVGVCYmxOOGJ3NVk0dUVyMDhaQW9HQUpBeURiZmthN0hWNlJwWkkvTEcxXG5Zakd0OU5QNm42UklxRUUxVWFiMEFaY2pJWDVlK0RTUnV6RVRUSXRiN0hNYUZVOE1sWmdDTWNmWDk1ckN1RmhhXG45bkFQeGZNWEd6WVdXRlVMWmNPbWdBTWQ2RkNDUlFNSjVEUm9JYU5iNGIwdVhUYWk1Z1BaUDdGQ3hNTVdrbzJQXG56NFV0WFBCVXY1am8zZUxYUHFWVVNCQT1cbi0tLS0tRU5EIFBSSVZBVEUgS0VZLS0tLS1cbiIsCiAgImNsaWVudF9lbWFpbCI6ICJwci1rdWJla2luc0BrdWJlcm5ldGVzLWplbmtpbnMtcHVsbC5pYW0uZ3NlcnZpY2VhY2NvdW50LmNvbSIsCiAgImNsaWVudF9pZCI6ICIxMTM2MDA2MzMyODUwMDYyODMxMzAiLAogICJhdXRoX3VyaSI6ICJodHRwczovL2FjY291bnRzLmdvb2dsZS5jb20vby9vYXV0aDIvYXV0aCIsCiAgInRva2VuX3VyaSI6ICJodHRwczovL29hdXRoMi5nb29nbGVhcGlzLmNvbS90b2tlbiIsCiAgImF1dGhfcHJvdmlkZXJfeDUwOV9jZXJ0X3VybCI6ICJodHRwczovL3d3dy5nb29nbGVhcGlzLmNvbS9vYXV0aDIvdjEvY2VydHMiLAogICJjbGllbnRfeDUwOV9jZXJ0X3VybCI6ICJodHRwczovL3d3dy5nb29nbGVhcGlzLmNvbS9yb2JvdC92MS9tZXRhZGF0YS94NTA5L3ByLWt1YmVraW5zJTQwa3ViZXJuZXRlcy1qZW5raW5zLXB1bGwuaWFtLmdzZXJ2aWNlYWNjb3VudC5jb20iCn0K"},"kind":"Secret","metadata":{"creationTimestamp":null,"name":"cloud-sa"}}
W0212 12:14:35.897] I0212 12:14:35.896964   64541 round_trippers.go:419] curl -k -v -XPOST  -H "Accept: application/json" -H "User-Agent: kubectl/v1.13.5 (linux/amd64) kubernetes/2166946" -H "Authorization: Bearer w8EOcdOwV5EyqRwttsBgZVMA99vMI2EW" 'https://35.222.213.144/api/v1/namespaces/default/secrets'
... skipping 29 lines ...
W0212 12:14:36.160]     "name": "cluster-admin-binding",
W0212 12:14:36.160]     "group": "rbac.authorization.k8s.io",
W0212 12:14:36.169]     "kind": "clusterrolebindings"
W0212 12:14:36.169]   },
W0212 12:14:36.169]   "code": 404
W0212 12:14:36.169] }]
W0212 12:14:36.170] F0212 12:14:36.157881   64583 helpers.go:116] Error from server (NotFound): clusterrolebindings.rbac.authorization.k8s.io "cluster-admin-binding" not found
W0212 12:14:36.172] ++ gcloud config get-value account
W0212 12:14:36.736] + /go/src/sigs.k8s.io/gcp-compute-persistent-disk-csi-driver/test/k8s-integration/src/k8s.io/kubernetes/cluster/kubectl.sh create clusterrolebinding cluster-admin-binding -v=9 --clusterrole cluster-admin --user pr-kubekins@kubernetes-jenkins-pull.iam.gserviceaccount.com
W0212 12:14:36.943] I0212 12:14:36.943310   64640 loader.go:359] Config loaded from file /root/.kube/config
W0212 12:14:36.944] I0212 12:14:36.944319   64640 loader.go:359] Config loaded from file /root/.kube/config
W0212 12:14:36.945] I0212 12:14:36.945684   64640 loader.go:359] Config loaded from file /root/.kube/config
W0212 12:14:36.952] I0212 12:14:36.952330   64640 request.go:942] Request Body: {"apiVersion":"rbac.authorization.k8s.io/v1beta1","kind":"ClusterRoleBinding","metadata":{"creationTimestamp":null,"name":"cluster-admin-binding"},"roleRef":{"apiGroup":"rbac.authorization.k8s.io","kind":"ClusterRole","name":"cluster-admin"},"subjects":[{"apiGroup":"rbac.authorization.k8s.io","kind":"User","name":"pr-kubekins@kubernetes-jenkins-pull.iam.gserviceaccount.com"}]}
... skipping 562 lines ...
W0212 12:14:37.949] 00000670  74 65 73 29 20 6f 72 20  61 20 63 6f 6e 66 69 67  |tes) or a config|
W0212 12:14:37.949] 00000680  75 72 61 74 69 6f 6e 20  63 68 61 6e 67 65 20 6f  |uration change o|
W0212 12:14:37.949] 00000690  6e 20 74 68 65 20 73 65  72 76 65 72 2c 20 74 68  |n the server, th|
W0212 12:14:37.949] 000006a0  65 20 73 65 72 76 65 72  20 77 69 6c 6c 20 72 65  |e server will re|
W0212 12:14:37.949] 000006b0  73 70 6f 6e 64 20 77 69  74 68 20 61 20 34 31 30  |spond with a 410|
W0212 12:14:37.950] 000006c0  20 52 65 73 6f 75 72 63  65 45 78 70 69 72 65 64  | ResourceExpired|
W0212 12:14:37.950] 000006d0  20 65 72 72 6f 72 20 74  6f 67 65 74 68 65 72 20  | error together |
W0212 12:14:37.950] 000006e0  77 69 74 68 20 61 20 63  6f 6e 74 69 6e 75 65 20  |with a continue |
W0212 12:14:37.950] 000006f0  74 6f 6b 65 6e 2e 20 49  66 20 74 68 65 20 63 6c  |token. If the cl|
W0212 12:14:37.950] 00000700  69 65 6e 74 20 6e 65 65  64 73 20 61 20 63 6f 6e  |ient needs a con|
W0212 12:14:37.951] 00000710  73 69 73 74 65 6e 74 20  6c 69 73 74 2c 20 69 74  |sistent list, it|
W0212 12:14:37.951] 00000720  20 6d 75 73 74 20 72 65  73 74 61 72 74 20 74 68  | must restart th|
W0212 12:14:37.951] 00000730  65 69 72 20 6c 69 73 74  20 77 69 74 68 6f 75 74  |eir list without|
... skipping 796 lines ...
I0212 12:15:02.644] 
I0212 12:15:17.869] Feb 12 12:15:07.391: INFO: cluster-master-image: cos-stable-65-10323-64-0
I0212 12:15:17.869] Feb 12 12:15:07.391: INFO: cluster-node-image: cos-stable-65-10323-64-0
I0212 12:15:17.869] Feb 12 12:15:07.391: INFO: >>> kubeConfig: /root/.kube/config
I0212 12:15:17.869] Feb 12 12:15:07.399: INFO: Waiting up to 30m0s for all (but 0) nodes to be schedulable
I0212 12:15:17.870] Feb 12 12:15:07.454: INFO: Waiting up to 10m0s for all pods (need at least 0) in namespace 'kube-system' to be running and ready
I0212 12:15:17.870] Feb 12 12:15:07.830: INFO: The status of Pod coredns-fff89c9b9-mdp8p is Pending (Ready = false), waiting for it to be either Running (with Ready = true) or Failed
I0212 12:15:17.870] Feb 12 12:15:07.830: INFO: The status of Pod heapster-v1.6.0-beta.1-5f77ccd9dd-q2qsc is Pending (Ready = false), waiting for it to be either Running (with Ready = true) or Failed
I0212 12:15:17.870] Feb 12 12:15:07.830: INFO: The status of Pod kubernetes-dashboard-66bb48f98c-26dkb is Pending (Ready = false), waiting for it to be either Running (with Ready = true) or Failed
I0212 12:15:17.871] Feb 12 12:15:07.830: INFO: 26 / 29 pods in namespace 'kube-system' are running and ready (0 seconds elapsed)
I0212 12:15:17.871] Feb 12 12:15:07.830: INFO: expected 9 pod replicas in namespace 'kube-system', 6 are Running and Ready.
I0212 12:15:17.871] Feb 12 12:15:07.830: INFO: POD                                      NODE                             PHASE    GRACE  CONDITIONS
I0212 12:15:17.872] Feb 12 12:15:07.830: INFO: coredns-fff89c9b9-mdp8p                  e2e-test-prow-minion-group-p6g9  Pending         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:15:06 +0000 UTC  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:15:06 +0000 UTC ContainersNotReady containers with unready status: [coredns]} {ContainersReady False 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:15:06 +0000 UTC ContainersNotReady containers with unready status: [coredns]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:14:59 +0000 UTC  }]
I0212 12:15:17.872] Feb 12 12:15:07.830: INFO: heapster-v1.6.0-beta.1-5f77ccd9dd-q2qsc  e2e-test-prow-minion-group-p6g9  Pending         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:14:44 +0000 UTC  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:14:44 +0000 UTC ContainersNotReady containers with unready status: [heapster heapster-nanny]} {ContainersReady False 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:14:44 +0000 UTC ContainersNotReady containers with unready status: [heapster heapster-nanny]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:14:24 +0000 UTC  }]
I0212 12:15:17.873] Feb 12 12:15:07.830: INFO: kubernetes-dashboard-66bb48f98c-26dkb    e2e-test-prow-minion-group-ckng  Pending         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:14:47 +0000 UTC  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:14:47 +0000 UTC ContainersNotReady containers with unready status: [kubernetes-dashboard]} {ContainersReady False 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:14:47 +0000 UTC ContainersNotReady containers with unready status: [kubernetes-dashboard]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:14:17 +0000 UTC  }]
I0212 12:15:17.873] Feb 12 12:15:07.830: INFO: 
I0212 12:15:17.873] Feb 12 12:15:10.128: INFO: The status of Pod fluentd-gcp-v3.2.0-xzw8z is Running (Ready = false), waiting for it to be either Running (with Ready = true) or Failed
I0212 12:15:17.874] Feb 12 12:15:10.128: INFO: The status of Pod kubernetes-dashboard-66bb48f98c-26dkb is Pending (Ready = false), waiting for it to be either Running (with Ready = true) or Failed
I0212 12:15:17.874] Feb 12 12:15:10.128: INFO: 27 / 29 pods in namespace 'kube-system' are running and ready (2 seconds elapsed)
I0212 12:15:17.874] Feb 12 12:15:10.128: INFO: expected 9 pod replicas in namespace 'kube-system', 8 are Running and Ready.
I0212 12:15:17.874] Feb 12 12:15:10.128: INFO: POD                                    NODE                             PHASE    GRACE  CONDITIONS
I0212 12:15:17.875] Feb 12 12:15:10.128: INFO: fluentd-gcp-v3.2.0-xzw8z               e2e-test-prow-minion-group-ckng  Running  60s    [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:14:05 +0000 UTC  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:15:07 +0000 UTC ContainersNotReady containers with unready status: [fluentd-gcp prometheus-to-sd-exporter]} {ContainersReady False 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:15:07 +0000 UTC ContainersNotReady containers with unready status: [fluentd-gcp prometheus-to-sd-exporter]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:14:04 +0000 UTC  }]
I0212 12:15:17.876] Feb 12 12:15:10.128: INFO: kubernetes-dashboard-66bb48f98c-26dkb  e2e-test-prow-minion-group-ckng  Pending         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:14:47 +0000 UTC  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:14:47 +0000 UTC ContainersNotReady containers with unready status: [kubernetes-dashboard]} {ContainersReady False 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:14:47 +0000 UTC ContainersNotReady containers with unready status: [kubernetes-dashboard]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:14:17 +0000 UTC  }]
I0212 12:15:17.876] Feb 12 12:15:10.128: INFO: 
I0212 12:15:17.876] Feb 12 12:15:11.852: INFO: The status of Pod fluentd-gcp-v3.2.0-xzw8z is Running (Ready = false), waiting for it to be either Running (with Ready = true) or Failed
I0212 12:15:17.876] Feb 12 12:15:11.852: INFO: 28 / 29 pods in namespace 'kube-system' are running and ready (4 seconds elapsed)
I0212 12:15:17.876] Feb 12 12:15:11.852: INFO: expected 9 pod replicas in namespace 'kube-system', 9 are Running and Ready.
I0212 12:15:17.877] Feb 12 12:15:11.852: INFO: POD                       NODE                             PHASE    GRACE  CONDITIONS
I0212 12:15:17.877] Feb 12 12:15:11.852: INFO: fluentd-gcp-v3.2.0-xzw8z  e2e-test-prow-minion-group-ckng  Running  60s    [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:14:05 +0000 UTC  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:15:07 +0000 UTC ContainersNotReady containers with unready status: [fluentd-gcp prometheus-to-sd-exporter]} {ContainersReady False 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:15:07 +0000 UTC ContainersNotReady containers with unready status: [fluentd-gcp prometheus-to-sd-exporter]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:14:04 +0000 UTC  }]
I0212 12:15:17.877] Feb 12 12:15:11.852: INFO: 
I0212 12:15:17.878] Feb 12 12:15:13.864: INFO: The status of Pod fluentd-gcp-v3.2.0-xzw8z is Running (Ready = false), waiting for it to be either Running (with Ready = true) or Failed
I0212 12:15:17.878] Feb 12 12:15:13.864: INFO: 28 / 29 pods in namespace 'kube-system' are running and ready (6 seconds elapsed)
I0212 12:15:17.878] Feb 12 12:15:13.864: INFO: expected 9 pod replicas in namespace 'kube-system', 9 are Running and Ready.
I0212 12:15:17.878] Feb 12 12:15:13.864: INFO: POD                       NODE                             PHASE    GRACE  CONDITIONS
I0212 12:15:17.879] Feb 12 12:15:13.864: INFO: fluentd-gcp-v3.2.0-xzw8z  e2e-test-prow-minion-group-ckng  Running  60s    [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:14:05 +0000 UTC  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:15:07 +0000 UTC ContainersNotReady containers with unready status: [fluentd-gcp prometheus-to-sd-exporter]} {ContainersReady False 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:15:07 +0000 UTC ContainersNotReady containers with unready status: [fluentd-gcp prometheus-to-sd-exporter]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:14:04 +0000 UTC  }]
I0212 12:15:17.879] Feb 12 12:15:13.864: INFO: 
I0212 12:15:17.880] Feb 12 12:15:15.853: INFO: The status of Pod fluentd-gcp-v3.2.0-4kgtf is Pending (Ready = false), waiting for it to be either Running (with Ready = true) or Failed
I0212 12:15:17.881] Feb 12 12:15:15.853: INFO: 28 / 29 pods in namespace 'kube-system' are running and ready (8 seconds elapsed)
I0212 12:15:17.881] Feb 12 12:15:15.853: INFO: expected 9 pod replicas in namespace 'kube-system', 9 are Running and Ready.
I0212 12:15:17.881] Feb 12 12:15:15.853: INFO: POD                       NODE                             PHASE    GRACE  CONDITIONS
I0212 12:15:17.882] Feb 12 12:15:15.853: INFO: fluentd-gcp-v3.2.0-4kgtf  e2e-test-prow-minion-group-ckng  Pending         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:15:14 +0000 UTC  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:15:14 +0000 UTC ContainersNotReady containers with unready status: [fluentd-gcp prometheus-to-sd-exporter]} {ContainersReady False 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:15:14 +0000 UTC ContainersNotReady containers with unready status: [fluentd-gcp prometheus-to-sd-exporter]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:15:14 +0000 UTC  }]
I0212 12:15:17.882] Feb 12 12:15:15.853: INFO: 
I0212 12:15:17.882] Feb 12 12:15:17.853: INFO: 29 / 29 pods in namespace 'kube-system' are running and ready (10 seconds elapsed)
... skipping 296 lines ...
I0212 12:16:27.450] Feb 12 12:15:30.626: INFO: PersistentVolumeClaim pvc-lkd7w found but phase is Pending instead of Bound.
I0212 12:16:27.450] Feb 12 12:15:32.750: INFO: PersistentVolumeClaim pvc-lkd7w found but phase is Pending instead of Bound.
I0212 12:16:27.451] Feb 12 12:15:34.858: INFO: PersistentVolumeClaim pvc-lkd7w found but phase is Pending instead of Bound.
I0212 12:16:27.452] Feb 12 12:15:37.006: INFO: PersistentVolumeClaim pvc-lkd7w found but phase is Pending instead of Bound.
I0212 12:16:27.452] Feb 12 12:15:39.084: INFO: PersistentVolumeClaim pvc-lkd7w found but phase is Pending instead of Bound.
I0212 12:16:27.453] Feb 12 12:15:41.230: INFO: PersistentVolumeClaim pvc-lkd7w found and phase=Bound (20.749528159s)
I0212 12:16:27.453] [It] should fail if non-existent subpath is outside the volume [Slow]
I0212 12:16:27.454]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:261
I0212 12:16:27.454] STEP: Creating pod pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-h9jr
I0212 12:16:27.455] STEP: Checking for subpath error in container status
I0212 12:16:27.455] Feb 12 12:16:03.900: INFO: Deleting pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-h9jr" in namespace "e2e-tests-csi-volumes-wlv6f"
I0212 12:16:27.456] Feb 12 12:16:03.925: INFO: Wait up to 5m0s for pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-h9jr" to be fully deleted
I0212 12:16:27.456] [AfterEach] [Testpattern: Dynamic PV (default fs)] subPath
I0212 12:16:27.457]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:120
I0212 12:16:27.457] STEP: Deleting pod
I0212 12:16:27.457] Feb 12 12:16:14.202: INFO: Deleting pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-h9jr" in namespace "e2e-tests-csi-volumes-wlv6f"
... skipping 20 lines ...
I0212 12:16:27.468] [sig-storage] CSI Volumes
I0212 12:16:27.468] /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/framework.go:22
I0212 12:16:27.469]   [Driver: pd.csi.storage.gke.io][Feature: gcePD-external]
I0212 12:16:27.469]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/csi_volumes.go:129
I0212 12:16:27.470]     [Testpattern: Dynamic PV (default fs)] subPath
I0212 12:16:27.470]     /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:99
I0212 12:16:27.471]       should fail if non-existent subpath is outside the volume [Slow]
I0212 12:16:27.471]       /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:261
I0212 12:16:27.472] ------------------------------
I0212 12:16:28.197] SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
I0212 12:16:28.198] ------------------------------
I0212 12:16:28.198] Feb 12 12:16:28.197: INFO: Running AfterSuite actions on all nodes
I0212 12:16:28.199] 
... skipping 939 lines ...
I0212 12:17:06.732] STEP: creating a StorageClass e2e-tests-csi-volumes-hkzqg-pd.csi.storage.gke.io-sc
I0212 12:17:06.733] STEP: creating a claim
I0212 12:17:06.733] Feb 12 12:16:04.818: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-mphp9] to have phase Bound
I0212 12:17:06.733] Feb 12 12:16:04.889: INFO: PersistentVolumeClaim pvc-mphp9 found but phase is Pending instead of Bound.
I0212 12:17:06.734] Feb 12 12:16:06.917: INFO: PersistentVolumeClaim pvc-mphp9 found but phase is Pending instead of Bound.
I0212 12:17:06.734] Feb 12 12:16:08.953: INFO: PersistentVolumeClaim pvc-mphp9 found and phase=Bound (4.134746448s)
I0212 12:17:06.735] [It] should fail if subpath directory is outside the volume [Slow]
I0212 12:17:06.735]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:245
I0212 12:17:06.735] STEP: Creating pod pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-2knw
I0212 12:17:06.736] STEP: Checking for subpath error in container status
I0212 12:17:06.736] Feb 12 12:16:31.063: INFO: Deleting pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-2knw" in namespace "e2e-tests-csi-volumes-hkzqg"
I0212 12:17:06.737] Feb 12 12:16:31.084: INFO: Wait up to 5m0s for pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-2knw" to be fully deleted
I0212 12:17:06.737] [AfterEach] [Testpattern: Dynamic PV (default fs)] subPath
I0212 12:17:06.737]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:120
I0212 12:17:06.738] STEP: Deleting pod
I0212 12:17:06.738] Feb 12 12:16:45.217: INFO: Deleting pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-2knw" in namespace "e2e-tests-csi-volumes-hkzqg"
... skipping 20 lines ...
I0212 12:17:06.749] [sig-storage] CSI Volumes
I0212 12:17:06.749] /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/framework.go:22
I0212 12:17:06.749]   [Driver: pd.csi.storage.gke.io][Feature: gcePD-external]
I0212 12:17:06.749]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/csi_volumes.go:129
I0212 12:17:06.750]     [Testpattern: Dynamic PV (default fs)] subPath
I0212 12:17:06.750]     /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:99
I0212 12:17:06.750]       should fail if subpath directory is outside the volume [Slow]
I0212 12:17:06.750]       /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:245
I0212 12:17:06.750] ------------------------------
I0212 12:17:06.750] Feb 12 12:17:06.492: INFO: Running AfterSuite actions on all nodes
I0212 12:17:06.750] 
I0212 12:17:06.751] 
I0212 12:17:06.751] [BeforeEach] [sig-storage] CSI Volumes
... skipping 183 lines ...
I0212 12:17:11.903] Feb 12 12:15:21.829: INFO: PersistentVolumeClaim pvc-66wt2 found but phase is Pending instead of Bound.
I0212 12:17:11.903] Feb 12 12:15:23.834: INFO: PersistentVolumeClaim pvc-66wt2 found but phase is Pending instead of Bound.
I0212 12:17:11.903] Feb 12 12:15:25.890: INFO: PersistentVolumeClaim pvc-66wt2 found but phase is Pending instead of Bound.
I0212 12:17:11.904] Feb 12 12:15:27.924: INFO: PersistentVolumeClaim pvc-66wt2 found but phase is Pending instead of Bound.
I0212 12:17:11.904] Feb 12 12:15:29.932: INFO: PersistentVolumeClaim pvc-66wt2 found but phase is Pending instead of Bound.
I0212 12:17:11.904] Feb 12 12:15:31.945: INFO: PersistentVolumeClaim pvc-66wt2 found and phase=Bound (12.172050593s)
I0212 12:17:12.244] [It] should fail if subpath with backstepping is outside the volume [Slow]
I0212 12:17:12.245]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:269
I0212 12:17:12.245] STEP: Creating pod pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-snr2
I0212 12:17:12.245] STEP: Checking for subpath error in container status
I0212 12:17:12.245] Feb 12 12:15:56.291: INFO: Deleting pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-snr2" in namespace "e2e-tests-csi-volumes-2lpr7"
I0212 12:17:12.246] Feb 12 12:15:56.594: INFO: Wait up to 5m0s for pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-snr2" to be fully deleted
I0212 12:17:12.246] [AfterEach] [Testpattern: Dynamic PV (default fs)] subPath
I0212 12:17:12.246]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:120
I0212 12:17:12.246] STEP: Deleting pod
I0212 12:17:12.246] Feb 12 12:16:04.701: INFO: Deleting pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-snr2" in namespace "e2e-tests-csi-volumes-2lpr7"
... skipping 30 lines ...
I0212 12:17:12.333] [sig-storage] CSI Volumes
I0212 12:17:12.346] /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/framework.go:22
I0212 12:17:12.347]   [Driver: pd.csi.storage.gke.io][Feature: gcePD-external]
I0212 12:17:12.347]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/csi_volumes.go:129
I0212 12:17:12.347]     [Testpattern: Dynamic PV (default fs)] subPath
I0212 12:17:12.347]     /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:99
I0212 12:17:12.348]       should fail if subpath with backstepping is outside the volume [Slow]
I0212 12:17:12.348]       /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:269
I0212 12:17:12.348] ------------------------------
I0212 12:17:12.348] Feb 12 12:17:11.515: INFO: Running AfterSuite actions on all nodes
I0212 12:17:12.349] 
I0212 12:17:15.212] 
I0212 12:17:15.213] [BeforeEach] [sig-storage] CSI Volumes
... skipping 807 lines ...
I0212 12:20:37.038] [BeforeEach] [sig-storage] CSI Volumes
I0212 12:20:37.039]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/csi_volumes.go:87
I0212 12:20:37.039] [BeforeEach] [Driver: pd.csi.storage.gke.io][Feature: gcePD-external]
I0212 12:20:37.039]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/csi_volumes.go:132
I0212 12:20:37.040] [BeforeEach] [Testpattern: Dynamic PV (block volmode)] volumeMode
I0212 12:20:37.041]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/volumemode.go:119
I0212 12:20:37.041] [It] should fail in binding dynamic provisioned PV to PVC
I0212 12:20:37.041]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/volumemode.go:315
I0212 12:20:37.042] STEP: Creating sc
I0212 12:20:37.042] STEP: Creating pv and pvc
I0212 12:20:37.043] Feb 12 12:15:19.897: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-rmv2b] to have phase Bound
I0212 12:20:37.043] Feb 12 12:15:19.918: INFO: PersistentVolumeClaim pvc-rmv2b found but phase is Pending instead of Bound.
I0212 12:20:37.044] Feb 12 12:15:21.922: INFO: PersistentVolumeClaim pvc-rmv2b found but phase is Pending instead of Bound.
... skipping 163 lines ...
I0212 12:20:37.150] [sig-storage] CSI Volumes
I0212 12:20:37.151] /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/framework.go:22
I0212 12:20:37.151]   [Driver: pd.csi.storage.gke.io][Feature: gcePD-external]
I0212 12:20:37.151]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/csi_volumes.go:129
I0212 12:20:37.152]     [Testpattern: Dynamic PV (block volmode)] volumeMode
I0212 12:20:37.162]     /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/volumemode.go:109
I0212 12:20:37.162]       should fail in binding dynamic provisioned PV to PVC
I0212 12:20:37.163]       /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/volumemode.go:315
I0212 12:20:37.163] ------------------------------
I0212 12:20:37.163] Feb 12 12:20:37.048: INFO: Running AfterSuite actions on all nodes
I0212 12:20:37.163] 
I0212 12:21:54.579] 
I0212 12:21:54.580] [BeforeEach] [sig-storage] CSI Volumes
... skipping 15 lines ...
I0212 12:21:54.583] STEP: creating a claim
I0212 12:21:54.583] Feb 12 12:15:18.913: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-rcnhl] to have phase Bound
I0212 12:21:54.584] Feb 12 12:15:18.973: INFO: PersistentVolumeClaim pvc-rcnhl found but phase is Pending instead of Bound.
I0212 12:21:54.584] Feb 12 12:15:20.976: INFO: PersistentVolumeClaim pvc-rcnhl found but phase is Pending instead of Bound.
I0212 12:21:54.584] Feb 12 12:15:22.980: INFO: PersistentVolumeClaim pvc-rcnhl found but phase is Pending instead of Bound.
I0212 12:21:54.584] Feb 12 12:15:24.994: INFO: PersistentVolumeClaim pvc-rcnhl found and phase=Bound (6.081741616s)
I0212 12:21:54.584] [It] should fail if subpath file is outside the volume [Slow]
I0212 12:21:54.584]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:253
I0212 12:21:54.585] STEP: Creating pod pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-rcvj
I0212 12:21:54.585] STEP: Checking for subpath error in container status
I0212 12:21:54.585] Feb 12 12:16:35.102: INFO: Deleting pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-rcvj" in namespace "e2e-tests-csi-volumes-j6snf"
I0212 12:21:54.585] Feb 12 12:16:35.129: INFO: Wait up to 5m0s for pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-rcvj" to be fully deleted
I0212 12:21:54.586] [AfterEach] [Testpattern: Dynamic PV (default fs)] subPath
I0212 12:21:54.586]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:120
I0212 12:21:54.586] STEP: Deleting pod
I0212 12:21:54.586] Feb 12 12:16:45.281: INFO: Deleting pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-rcvj" in namespace "e2e-tests-csi-volumes-j6snf"
... skipping 57 lines ...
I0212 12:21:54.598] Feb 12 12:21:17.910: INFO: PersistentVolume pvc-55870a9b-4d91-11ea-ba4c-42010a800002 found and phase=Released (4m32.240952062s)
I0212 12:21:54.598] Feb 12 12:21:22.916: INFO: PersistentVolume pvc-55870a9b-4d91-11ea-ba4c-42010a800002 found and phase=Released (4m37.246611869s)
I0212 12:21:54.598] Feb 12 12:21:27.921: INFO: PersistentVolume pvc-55870a9b-4d91-11ea-ba4c-42010a800002 found and phase=Released (4m42.251483098s)
I0212 12:21:54.599] Feb 12 12:21:32.928: INFO: PersistentVolume pvc-55870a9b-4d91-11ea-ba4c-42010a800002 found and phase=Released (4m47.258362951s)
I0212 12:21:54.599] Feb 12 12:21:37.933: INFO: PersistentVolume pvc-55870a9b-4d91-11ea-ba4c-42010a800002 found and phase=Released (4m52.263194515s)
I0212 12:21:54.599] Feb 12 12:21:42.939: INFO: PersistentVolume pvc-55870a9b-4d91-11ea-ba4c-42010a800002 found and phase=Released (4m57.269965082s)
I0212 12:21:54.599] Feb 12 12:21:47.940: INFO: Unexpected error occurred: PersistentVolume pvc-55870a9b-4d91-11ea-ba4c-42010a800002 still exists within 5m0s
I0212 12:21:54.599] [AfterEach] [Driver: pd.csi.storage.gke.io][Feature: gcePD-external]
I0212 12:21:54.600]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/csi_volumes.go:138
I0212 12:21:54.600] [AfterEach] [sig-storage] CSI Volumes
I0212 12:21:54.600]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/framework.go:154
I0212 12:21:54.600] STEP: Collecting events from namespace "e2e-tests-csi-volumes-j6snf".
I0212 12:21:54.600] STEP: Found 15 events.
I0212 12:21:54.600] Feb 12 12:21:47.945: INFO: At 2020-02-12 12:15:18 +0000 UTC - event for pvc-rcnhl: {persistentvolume-controller } ExternalProvisioning: waiting for a volume to be created, either by external provisioner "pd.csi.storage.gke.io" or manually created by system administrator
I0212 12:21:54.601] Feb 12 12:21:47.945: INFO: At 2020-02-12 12:15:19 +0000 UTC - event for pvc-rcnhl: {pd.csi.storage.gke.io_csi-gce-pd-controller-0_4ef14b27-4d91-11ea-8ae4-eeb0178aa9af } Provisioning: External provisioner is provisioning volume for claim "e2e-tests-csi-volumes-j6snf/pvc-rcnhl"
I0212 12:21:54.601] Feb 12 12:21:47.945: INFO: At 2020-02-12 12:15:23 +0000 UTC - event for pvc-rcnhl: {pd.csi.storage.gke.io_csi-gce-pd-controller-0_4ef14b27-4d91-11ea-8ae4-eeb0178aa9af } ProvisioningSucceeded: Successfully provisioned volume pvc-55870a9b-4d91-11ea-ba4c-42010a800002
I0212 12:21:54.602] Feb 12 12:21:47.945: INFO: At 2020-02-12 12:15:25 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-rcvj: {default-scheduler } Scheduled: Successfully assigned e2e-tests-csi-volumes-j6snf/pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-rcvj to e2e-test-prow-minion-group-p6g9
I0212 12:21:54.602] Feb 12 12:21:47.945: INFO: At 2020-02-12 12:15:40 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-rcvj: {attachdetach-controller } FailedAttachVolume: AttachVolume.Attach failed for volume "pvc-55870a9b-4d91-11ea-ba4c-42010a800002" : attachment timeout for volume projects/k8s-boskos-gce-project-14/zones/us-central1-b/disks/pvc-55870a9b-4d91-11ea-ba4c-42010a800002
I0212 12:21:54.603] Feb 12 12:21:47.945: INFO: At 2020-02-12 12:15:41 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-rcvj: {attachdetach-controller } FailedAttachVolume: AttachVolume.Attach failed for volume "pvc-55870a9b-4d91-11ea-ba4c-42010a800002" : rpc error: code = DeadlineExceeded desc = context deadline exceeded
I0212 12:21:54.603] Feb 12 12:21:47.945: INFO: At 2020-02-12 12:15:57 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-rcvj: {attachdetach-controller } SuccessfulAttachVolume: AttachVolume.Attach succeeded for volume "pvc-55870a9b-4d91-11ea-ba4c-42010a800002" 
I0212 12:21:54.603] Feb 12 12:21:47.945: INFO: At 2020-02-12 12:16:32 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-rcvj: {kubelet e2e-test-prow-minion-group-p6g9} Pulled: Container image "docker.io/library/busybox:1.29" already present on machine
I0212 12:21:54.603] Feb 12 12:21:47.945: INFO: At 2020-02-12 12:16:32 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-rcvj: {kubelet e2e-test-prow-minion-group-p6g9} Created: Created container
I0212 12:21:54.604] Feb 12 12:21:47.945: INFO: At 2020-02-12 12:16:32 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-rcvj: {kubelet e2e-test-prow-minion-group-p6g9} Failed: Error: failed to prepare subPath for volumeMount "test-volume" of container "test-container-subpath-pd-csi-storage-gke-io-dynamicpv-rcvj"
I0212 12:21:54.604] Feb 12 12:21:47.945: INFO: At 2020-02-12 12:16:32 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-rcvj: {kubelet e2e-test-prow-minion-group-p6g9} Pulled: Container image "gcr.io/kubernetes-e2e-test-images/mounttest:1.0" already present on machine
I0212 12:21:54.604] Feb 12 12:21:47.945: INFO: At 2020-02-12 12:16:32 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-rcvj: {kubelet e2e-test-prow-minion-group-p6g9} Created: Created container
I0212 12:21:54.605] Feb 12 12:21:47.945: INFO: At 2020-02-12 12:16:32 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-rcvj: {kubelet e2e-test-prow-minion-group-p6g9} Started: Started container
I0212 12:21:54.605] Feb 12 12:21:47.945: INFO: At 2020-02-12 12:16:32 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-rcvj: {kubelet e2e-test-prow-minion-group-p6g9} Pulled: Container image "gcr.io/kubernetes-e2e-test-images/mounttest:1.0" already present on machine
I0212 12:21:54.605] Feb 12 12:21:47.945: INFO: At 2020-02-12 12:16:33 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-rcvj: {kubelet e2e-test-prow-minion-group-p6g9} Started: Started container
I0212 12:21:54.606] Feb 12 12:21:47.957: INFO: POD                                           NODE                             PHASE    GRACE  CONDITIONS
... skipping 30 lines ...
I0212 12:21:54.620] Feb 12 12:21:47.958: INFO: metadata-proxy-v0.1-9mkpq                     e2e-test-prow-minion-group-ckng  Running         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:14:05 +0000 UTC  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:14:47 +0000 UTC  } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:14:47 +0000 UTC  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:14:04 +0000 UTC  }]
I0212 12:21:54.621] Feb 12 12:21:47.958: INFO: metadata-proxy-v0.1-t8b9l                     e2e-test-prow-master             Running         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:14:01 +0000 UTC  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:14:41 +0000 UTC  } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:14:41 +0000 UTC  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:14:01 +0000 UTC  }]
I0212 12:21:54.621] Feb 12 12:21:47.958: INFO: metrics-server-v0.3.1-58d65f8d6-fdb6w         e2e-test-prow-minion-group-p6g9  Running         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:14:44 +0000 UTC  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:15:06 +0000 UTC  } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:15:06 +0000 UTC  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 12:14:24 +0000 UTC  }]
I0212 12:21:54.621] Feb 12 12:21:47.958: INFO: 
I0212 12:21:54.621] Feb 12 12:21:47.961: INFO: 
I0212 12:21:54.622] Logging node info for node e2e-test-prow-master
I0212 12:21:54.625] Feb 12 12:21:47.964: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:e2e-test-prow-master,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/e2e-test-prow-master,UID:27078ef6-4d91-11ea-ba4c-42010a800002,ResourceVersion:2978,Generation:0,CreationTimestamp:2020-02-12 12:14:00 +0000 UTC,DeletionTimestamp:<nil>,DeletionGracePeriodSeconds:nil,Labels:map[string]string{beta.kubernetes.io/arch: amd64,beta.kubernetes.io/fluentd-ds-ready: true,beta.kubernetes.io/instance-type: n1-standard-1,beta.kubernetes.io/metadata-proxy-ready: true,beta.kubernetes.io/os: linux,failure-domain.beta.kubernetes.io/region: us-central1,failure-domain.beta.kubernetes.io/zone: us-central1-b,kubernetes.io/hostname: e2e-test-prow-master,},Annotations:map[string]string{node.alpha.kubernetes.io/ttl: 0,volumes.kubernetes.io/controller-managed-attach-detach: true,},OwnerReferences:[],Finalizers:[],ClusterName:,Initializers:nil,},Spec:NodeSpec{PodCIDR:10.64.0.0/24,DoNotUse_ExternalID:,ProviderID:gce://k8s-boskos-gce-project-14/us-central1-b/e2e-test-prow-master,Unschedulable:true,Taints:[{node.kubernetes.io/unschedulable  NoSchedule <nil>}],ConfigSource:nil,},Status:NodeStatus{Capacity:ResourceList{attachable-volumes-gce-pd: {{32 0} {<nil>} 32 DecimalSI},cpu: {{1 0} {<nil>} 1 DecimalSI},ephemeral-storage: {{16684785664 0} {<nil>}  BinarySI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{3885404160 0} {<nil>} 3794340Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Allocatable:ResourceList{attachable-volumes-gce-pd: {{32 0} {<nil>} 32 DecimalSI},cpu: {{1 0} {<nil>} 1 DecimalSI},ephemeral-storage: {{15016307073 0} {<nil>} 15016307073 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{3623260160 0} {<nil>} 3538340Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Phase:,Conditions:[{NetworkUnavailable False 2020-02-12 12:14:08 +0000 UTC 2020-02-12 12:14:08 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2020-02-12 12:21:43 +0000 UTC 2020-02-12 12:14:00 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2020-02-12 12:21:43 +0000 UTC 2020-02-12 12:14:00 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2020-02-12 12:21:43 +0000 UTC 2020-02-12 12:14:00 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2020-02-12 12:21:43 +0000 UTC 2020-02-12 12:14:01 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.128.0.2} {ExternalIP 35.222.213.144} {InternalDNS e2e-test-prow-master.c.k8s-boskos-gce-project-14.internal} {Hostname e2e-test-prow-master.c.k8s-boskos-gce-project-14.internal}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:eb1ab3ea98c060bbedfe753cab6492ba,SystemUUID:EB1AB3EA-98C0-60BB-EDFE-753CAB6492BA,BootID:47c94127-4def-4cd8-aa7d-c6aae37a7441,KernelVersion:4.4.111+,OSImage:Container-Optimized OS from Google,ContainerRuntimeVersion:docker://17.3.2,KubeletVersion:v1.13.5,KubeProxyVersion:v1.13.5,OperatingSystem:linux,Architecture:amd64,},Images:[{[gcr.io/stackdriver-agents/stackdriver-logging-agent@sha256:f8d5231b67b9c53f60068b535a11811d29d1b3efd53d2b79f2a2591ea338e4f2 gcr.io/stackdriver-agents/stackdriver-logging-agent:0.6-1.6.0-1] 223242132} {[k8s.gcr.io/etcd@sha256:905d7ca17fd02bc24c0eba9a062753aba15db3e31422390bc3238eb762339b20 k8s.gcr.io/etcd:3.2.24-1] 219655340} {[k8s.gcr.io/kube-apiserver:v1.13.5] 180890537} {[k8s.gcr.io/kube-controller-manager:v1.13.5] 146171465} {[k8s.gcr.io/kube-addon-manager@sha256:2fd1daf3d3cf0e94a753f2263b60dbb0d42b107b5cde0c75ee3fc5c830e016e4 k8s.gcr.io/kube-addon-manager:v8.9] 99240637} {[k8s.gcr.io/prometheus-to-sd@sha256:6c0c742475363d537ff059136e5d5e4ab1f512ee0fd9b7ca42ea48bc309d1662 k8s.gcr.io/prometheus-to-sd:v0.3.1] 88077694} {[k8s.gcr.io/kube-scheduler:v1.13.5] 79542185} {[k8s.gcr.io/ingress-gce-glbc-amd64@sha256:14f14351a03038b238232e60850a9cfa0dffbed0590321ef84216a432accc1ca k8s.gcr.io/ingress-gce-glbc-amd64:v1.2.3] 71797285} {[k8s.gcr.io/etcd-empty-dir-cleanup@sha256:c9c0dea9dbdbdaca436e33947a7559dbe2a60ad2bfa4e77518cb7088e443e28a k8s.gcr.io/etcd-empty-dir-cleanup:3.2.24.0] 31724043} {[k8s.gcr.io/metadata-proxy@sha256:5be758058e67b578f7041498e2daca46ccd7426bc602d35ed0f50bd4a3659d50 k8s.gcr.io/metadata-proxy:v0.1.10] 8953717} {[k8s.gcr.io/pause@sha256:f78411e19d84a252e53bff71a4407a5686c46983a2c2eeed83929b888179acea k8s.gcr.io/pause:3.1] 742472}],VolumesInUse:[],VolumesAttached:[],Config:&NodeConfigStatus{Assigned:nil,Active:nil,LastKnownGood:nil,Error:,},},}
I0212 12:21:54.626] Feb 12 12:21:47.964: INFO: 
I0212 12:21:54.626] Logging kubelet events for node e2e-test-prow-master
I0212 12:21:54.626] Feb 12 12:21:47.973: INFO: 
I0212 12:21:54.626] Logging pods the kubelet thinks is on node e2e-test-prow-master
I0212 12:21:54.626] Feb 12 12:21:47.995: INFO: metadata-proxy-v0.1-t8b9l started at 2020-02-12 12:14:01 +0000 UTC (0+2 container statuses recorded)
I0212 12:21:54.627] Feb 12 12:21:47.995: INFO: 	Container metadata-proxy ready: true, restart count 0
... skipping 15 lines ...
I0212 12:21:54.629] Feb 12 12:21:48.046: INFO: {Operation: Method:pod_start_latency_microseconds Quantile:0.9 Latency:25.644817s}
I0212 12:21:54.630] Feb 12 12:21:48.046: INFO: {Operation:pull_image Method:docker_operations_latency_microseconds Quantile:0.99 Latency:19.951778s}
I0212 12:21:54.630] Feb 12 12:21:48.047: INFO: {Operation:pull_image Method:docker_operations_latency_microseconds Quantile:0.9 Latency:18.120499s}
I0212 12:21:54.630] Feb 12 12:21:48.047: INFO: {Operation:start_container Method:docker_operations_latency_microseconds Quantile:0.99 Latency:14.686652s}
I0212 12:21:54.630] Feb 12 12:21:48.047: INFO: 
I0212 12:21:54.630] Logging node info for node e2e-test-prow-minion-group-bl5h
I0212 12:21:54.636] Feb 12 12:21:48.052: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:e2e-test-prow-minion-group-bl5h,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/e2e-test-prow-minion-group-bl5h,UID:2872b445-4d91-11ea-ba4c-42010a800002,ResourceVersion:2983,Generation:0,CreationTimestamp:2020-02-12 12:14:03 +0000 UTC,DeletionTimestamp:<nil>,DeletionGracePeriodSeconds:nil,Labels:map[string]string{beta.kubernetes.io/arch: amd64,beta.kubernetes.io/fluentd-ds-ready: true,beta.kubernetes.io/instance-type: n1-standard-2,beta.kubernetes.io/metadata-proxy-ready: true,beta.kubernetes.io/os: linux,failure-domain.beta.kubernetes.io/region: us-central1,failure-domain.beta.kubernetes.io/zone: us-central1-b,kubernetes.io/hostname: e2e-test-prow-minion-group-bl5h,},Annotations:map[string]string{csi.volume.kubernetes.io/nodeid: {"pd.csi.storage.gke.io":"projects/k8s-boskos-gce-project-14/zones/us-central1-b/instances/e2e-test-prow-minion-group-bl5h"},node.alpha.kubernetes.io/ttl: 0,volumes.kubernetes.io/controller-managed-attach-detach: true,},OwnerReferences:[],Finalizers:[],ClusterName:,Initializers:nil,},Spec:NodeSpec{PodCIDR:10.64.1.0/24,DoNotUse_ExternalID:,ProviderID:gce://k8s-boskos-gce-project-14/us-central1-b/e2e-test-prow-minion-group-bl5h,Unschedulable:false,Taints:[],ConfigSource:nil,},Status:NodeStatus{Capacity:ResourceList{attachable-volumes-gce-pd: {{64 0} {<nil>} 64 DecimalSI},cpu: {{2 0} {<nil>} 2 DecimalSI},ephemeral-storage: {{101241290752 0} {<nil>}  BinarySI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{7848767488 0} {<nil>} 7664812Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Allocatable:ResourceList{attachable-volumes-gce-pd: {{64 0} {<nil>} 64 DecimalSI},cpu: {{2 0} {<nil>} 2 DecimalSI},ephemeral-storage: {{91117161526 0} {<nil>} 91117161526 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{7586623488 0} {<nil>} 7408812Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Phase:,Conditions:[{KernelDeadlock False 2020-02-12 12:21:03 +0000 UTC 2020-02-12 12:12:57 +0000 UTC KernelHasNoDeadlock kernel has no deadlock} {ReadonlyFilesystem False 2020-02-12 12:21:03 +0000 UTC 2020-02-12 12:12:57 +0000 UTC FilesystemIsNotReadOnly Filesystem is not read-only} {FrequentUnregisterNetDevice False 2020-02-12 12:21:03 +0000 UTC 2020-02-12 12:17:58 +0000 UTC UnregisterNetDevice node is functioning properly} {FrequentKubeletRestart False 2020-02-12 12:21:03 +0000 UTC 2020-02-12 12:17:58 +0000 UTC FrequentKubeletRestart kubelet is functioning properly} {FrequentDockerRestart False 2020-02-12 12:21:03 +0000 UTC 2020-02-12 12:17:59 +0000 UTC FrequentDockerRestart docker is functioning properly} {FrequentContainerdRestart False 2020-02-12 12:21:03 +0000 UTC 2020-02-12 12:18:01 +0000 UTC FrequentContainerdRestart containerd is functioning properly} {CorruptDockerOverlay2 False 2020-02-12 12:21:03 +0000 UTC 2020-02-12 12:17:59 +0000 UTC CorruptDockerOverlay2 docker overlay2 is functioning properly} {NetworkUnavailable False 2020-02-12 12:14:19 +0000 UTC 2020-02-12 12:14:19 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2020-02-12 12:21:46 +0000 UTC 2020-02-12 12:14:03 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2020-02-12 12:21:46 +0000 UTC 2020-02-12 12:14:03 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2020-02-12 12:21:46 +0000 UTC 2020-02-12 12:14:03 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2020-02-12 12:21:46 +0000 UTC 2020-02-12 12:14:03 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.128.0.5} {ExternalIP 35.226.184.18} {InternalDNS e2e-test-prow-minion-group-bl5h.c.k8s-boskos-gce-project-14.internal} {Hostname e2e-test-prow-minion-group-bl5h.c.k8s-boskos-gce-project-14.internal}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:ed64a2b613278f9100302a53e947b63c,SystemUUID:ED64A2B6-1327-8F91-0030-2A53E947B63C,BootID:0c4548e7-f59e-4f2b-8ded-408485289743,KernelVersion:4.4.111+,OSImage:Container-Optimized OS from Google,ContainerRuntimeVersion:docker://17.3.2,KubeletVersion:v1.13.5,KubeProxyVersion:v1.13.5,OperatingSystem:linux,Architecture:amd64,},Images:[{[gcr.io/stackdriver-agents/stackdriver-logging-agent@sha256:f8d5231b67b9c53f60068b535a11811d29d1b3efd53d2b79f2a2591ea338e4f2 gcr.io/stackdriver-agents/stackdriver-logging-agent:0.6-1.6.0-1] 223242132} {[gcr.io/gke-release/gcp-compute-persistent-disk-csi-driver@sha256:65527562c25ba2ecb1a6e8f80bf9aa5ad100be32c3417c4b31119eeea09b6080 gcr.io/gke-release/gcp-compute-persistent-disk-csi-driver:v0.4.0-gke.0] 133411124} {[k8s.gcr.io/event-exporter@sha256:7f9cd7cb04d6959b0aa960727d04fa86759008048c785397b7b0d9dff0007516 k8s.gcr.io/event-exporter:v0.2.3] 94171943} {[k8s.gcr.io/prometheus-to-sd@sha256:6c0c742475363d537ff059136e5d5e4ab1f512ee0fd9b7ca42ea48bc309d1662 k8s.gcr.io/prometheus-to-sd:v0.3.1] 88077694} {[k8s.gcr.io/kube-proxy:v1.13.5] 80186087} {[k8s.gcr.io/heapster-amd64@sha256:9fae0af136ce0cf4f88393b3670f7139ffc464692060c374d2ae748e13144521 k8s.gcr.io/heapster-amd64:v1.6.0-beta.1] 76016169} {[gcr.io/gke-release/csi-node-driver-registrar@sha256:dc4e6c0fa39134e71c26972a7e2d2fb0c371bfc449b434e0fb2532a9410a4139 gcr.io/gke-release/csi-node-driver-registrar:v1.0.1-gke.0] 68977975} {[k8s.gcr.io/metrics-server-amd64@sha256:78938f933822856f443e6827fe5b37d6cc2f74ae888ac8b33d06fdbe5f8c658b k8s.gcr.io/metrics-server-amd64:v0.3.1] 40767713} {[k8s.gcr.io/coredns@sha256:81936728011c0df9404cb70b95c17bbc8af922ec9a70d0561a5d01fefa6ffa51 k8s.gcr.io/coredns:1.2.6] 40017418} {[k8s.gcr.io/addon-resizer@sha256:a31822f30e947885d038812f4a5a5675e72f92c06cef17b1989c80426aa89012 k8s.gcr.io/addon-resizer:1.8.4] 38349857} {[nginx@sha256:a3a0c4126587884f8d3090efca87f5af075d7e7ac8308cffc09a5a082d5f4760 nginx:1.14-alpine] 16032814} {[k8s.gcr.io/metadata-proxy@sha256:5be758058e67b578f7041498e2daca46ccd7426bc602d35ed0f50bd4a3659d50 k8s.gcr.io/metadata-proxy:v0.1.10] 8953717} {[k8s.gcr.io/defaultbackend-amd64@sha256:4dc5e07c8ca4e23bddb3153737d7b8c556e5fb2f29c4558b7cd6e6df99c512c7 k8s.gcr.io/defaultbackend-amd64:1.5] 5132544} {[gcr.io/kubernetes-e2e-test-images/mounttest@sha256:c0bd6f0755f42af09a68c9a47fb993136588a76b3200ec305796b60d629d85d2 gcr.io/kubernetes-e2e-test-images/mounttest:1.0] 1563521} {[busybox@sha256:e004c2cc521c95383aebb1fb5893719aa7a8eae2e7a71f316a4410784edb00a9 busybox:1.29] 1154361} {[k8s.gcr.io/pause@sha256:f78411e19d84a252e53bff71a4407a5686c46983a2c2eeed83929b888179acea k8s.gcr.io/pause:3.1] 742472}],VolumesInUse:[],VolumesAttached:[],Config:&NodeConfigStatus{Assigned:nil,Active:nil,LastKnownGood:nil,Error:,},},}
I0212 12:21:54.636] Feb 12 12:21:48.053: INFO: 
I0212 12:21:54.636] Logging kubelet events for node e2e-test-prow-minion-group-bl5h
I0212 12:21:54.636] Feb 12 12:21:48.074: INFO: 
I0212 12:21:54.636] Logging pods the kubelet thinks is on node e2e-test-prow-minion-group-bl5h
I0212 12:21:54.637] Feb 12 12:21:48.085: INFO: fluentd-gcp-v3.2.0-82z68 started at 2020-02-12 12:15:21 +0000 UTC (0+2 container statuses recorded)
I0212 12:21:54.637] Feb 12 12:21:48.085: INFO: 	Container fluentd-gcp ready: true, restart count 0
... skipping 17 lines ...
I0212 12:21:54.641] Feb 12 12:21:48.120: INFO: {Operation: Method:pod_start_latency_microseconds Quantile:0.99 Latency:49.579711s}
I0212 12:21:54.641] Feb 12 12:21:48.120: INFO: {Operation: Method:pod_start_latency_microseconds Quantile:0.9 Latency:48.851987s}
I0212 12:21:54.641] Feb 12 12:21:48.120: INFO: {Operation:start_container Method:docker_operations_latency_microseconds Quantile:0.99 Latency:34.300473s}
I0212 12:21:54.641] Feb 12 12:21:48.120: INFO: {Operation:pull_image Method:docker_operations_latency_microseconds Quantile:0.99 Latency:11.60282s}
I0212 12:21:54.641] Feb 12 12:21:48.120: INFO: 
I0212 12:21:54.642] Logging node info for node e2e-test-prow-minion-group-ckng
I0212 12:21:54.648] Feb 12 12:21:48.125: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:e2e-test-prow-minion-group-ckng,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/e2e-test-prow-minion-group-ckng,UID:29445b4d-4d91-11ea-ba4c-42010a800002,ResourceVersion:2985,Generation:0,CreationTimestamp:2020-02-12 12:14:04 +0000 UTC,DeletionTimestamp:<nil>,DeletionGracePeriodSeconds:nil,Labels:map[string]string{beta.kubernetes.io/arch: amd64,beta.kubernetes.io/fluentd-ds-ready: true,beta.kubernetes.io/instance-type: n1-standard-2,beta.kubernetes.io/metadata-proxy-ready: true,beta.kubernetes.io/os: linux,failure-domain.beta.kubernetes.io/region: us-central1,failure-domain.beta.kubernetes.io/zone: us-central1-b,kubernetes.io/hostname: e2e-test-prow-minion-group-ckng,},Annotations:map[string]string{csi.volume.kubernetes.io/nodeid: {"pd.csi.storage.gke.io":"projects/k8s-boskos-gce-project-14/zones/us-central1-b/instances/e2e-test-prow-minion-group-ckng"},node.alpha.kubernetes.io/ttl: 0,volumes.kubernetes.io/controller-managed-attach-detach: true,},OwnerReferences:[],Finalizers:[],ClusterName:,Initializers:nil,},Spec:NodeSpec{PodCIDR:10.64.3.0/24,DoNotUse_ExternalID:,ProviderID:gce://k8s-boskos-gce-project-14/us-central1-b/e2e-test-prow-minion-group-ckng,Unschedulable:false,Taints:[],ConfigSource:nil,},Status:NodeStatus{Capacity:ResourceList{attachable-volumes-gce-pd: {{64 0} {<nil>} 64 DecimalSI},cpu: {{2 0} {<nil>} 2 DecimalSI},ephemeral-storage: {{101241290752 0} {<nil>}  BinarySI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{7848767488 0} {<nil>} 7664812Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Allocatable:ResourceList{attachable-volumes-gce-pd: {{64 0} {<nil>} 64 DecimalSI},cpu: {{2 0} {<nil>} 2 DecimalSI},ephemeral-storage: {{91117161526 0} {<nil>} 91117161526 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{7586623488 0} {<nil>} 7408812Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Phase:,Conditions:[{ReadonlyFilesystem False 2020-02-12 12:21:13 +0000 UTC 2020-02-12 12:13:07 +0000 UTC FilesystemIsNotReadOnly Filesystem is not read-only} {FrequentUnregisterNetDevice False 2020-02-12 12:21:13 +0000 UTC 2020-02-12 12:18:08 +0000 UTC UnregisterNetDevice node is functioning properly} {FrequentKubeletRestart False 2020-02-12 12:21:13 +0000 UTC 2020-02-12 12:18:08 +0000 UTC FrequentKubeletRestart kubelet is functioning properly} {FrequentDockerRestart False 2020-02-12 12:21:13 +0000 UTC 2020-02-12 12:18:10 +0000 UTC FrequentDockerRestart docker is functioning properly} {FrequentContainerdRestart False 2020-02-12 12:21:13 +0000 UTC 2020-02-12 12:18:11 +0000 UTC FrequentContainerdRestart containerd is functioning properly} {CorruptDockerOverlay2 False 2020-02-12 12:21:13 +0000 UTC 2020-02-12 12:18:09 +0000 UTC CorruptDockerOverlay2 docker overlay2 is functioning properly} {KernelDeadlock False 2020-02-12 12:21:13 +0000 UTC 2020-02-12 12:13:07 +0000 UTC KernelHasNoDeadlock kernel has no deadlock} {NetworkUnavailable False 2020-02-12 12:14:17 +0000 UTC 2020-02-12 12:14:17 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2020-02-12 12:21:47 +0000 UTC 2020-02-12 12:14:04 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2020-02-12 12:21:47 +0000 UTC 2020-02-12 12:14:04 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2020-02-12 12:21:47 +0000 UTC 2020-02-12 12:14:04 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2020-02-12 12:21:47 +0000 UTC 2020-02-12 12:14:04 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.128.0.3} {ExternalIP 34.69.85.238} {InternalDNS e2e-test-prow-minion-group-ckng.c.k8s-boskos-gce-project-14.internal} {Hostname e2e-test-prow-minion-group-ckng.c.k8s-boskos-gce-project-14.internal}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:db6ca3fa706a157076d5f5b4727a4b86,SystemUUID:DB6CA3FA-706A-1570-76D5-F5B4727A4B86,BootID:8e8f82fe-75e5-493f-ab3b-82cc83e8c886,KernelVersion:4.4.111+,OSImage:Container-Optimized OS from Google,ContainerRuntimeVersion:docker://17.3.2,KubeletVersion:v1.13.5,KubeProxyVersion:v1.13.5,OperatingSystem:linux,Architecture:amd64,},Images:[{[gcr.io/stackdriver-agents/stackdriver-logging-agent@sha256:f8d5231b67b9c53f60068b535a11811d29d1b3efd53d2b79f2a2591ea338e4f2 gcr.io/stackdriver-agents/stackdriver-logging-agent:0.6-1.6.0-1] 223242132} {[gcr.io/gke-release/gcp-compute-persistent-disk-csi-driver@sha256:65527562c25ba2ecb1a6e8f80bf9aa5ad100be32c3417c4b31119eeea09b6080 gcr.io/gke-release/gcp-compute-persistent-disk-csi-driver:v0.4.0-gke.0] 133411124} {[k8s.gcr.io/kubernetes-dashboard-amd64@sha256:0ae6b69432e78069c5ce2bcde0fe409c5c4d6f0f4d9cd50a17974fea38898747 k8s.gcr.io/kubernetes-dashboard-amd64:v1.10.1] 121711221} {[k8s.gcr.io/fluentd-gcp-scaler@sha256:457a13df66534b94bab627c4c2dc2df0ee5153a5d0f0afd27502bd46bd8da81d k8s.gcr.io/fluentd-gcp-scaler:0.5] 103488147} {[k8s.gcr.io/prometheus-to-sd@sha256:6c0c742475363d537ff059136e5d5e4ab1f512ee0fd9b7ca42ea48bc309d1662 k8s.gcr.io/prometheus-to-sd:v0.3.1] 88077694} {[gcr.io/gke-release/csi-provisioner@sha256:947ea3f13799a4759d811ff088611e9d20b5c12451ba139537b5f154d6db359c gcr.io/gke-release/csi-provisioner:v1.0.1-gke.0] 80410503} {[k8s.gcr.io/kube-proxy:v1.13.5] 80186087} {[gcr.io/gke-release/csi-node-driver-registrar@sha256:dc4e6c0fa39134e71c26972a7e2d2fb0c371bfc449b434e0fb2532a9410a4139 gcr.io/gke-release/csi-node-driver-registrar:v1.0.1-gke.0] 68977975} {[gcr.io/gke-release/csi-attacher@sha256:ffb2694c1228c9da3f5516cced5bf54c35b0bc1debd74890fa10fdbe5977dbea gcr.io/gke-release/csi-attacher:v1.0.1-gke.0] 63581374} {[k8s.gcr.io/cluster-proportional-autoscaler-amd64@sha256:4fd37c5b29a38b02c408c56254bd1a3a76f3e236610bc7a8382500bbf9ecfc76 k8s.gcr.io/cluster-proportional-autoscaler-amd64:1.3.0] 45844959} {[k8s.gcr.io/metadata-proxy@sha256:5be758058e67b578f7041498e2daca46ccd7426bc602d35ed0f50bd4a3659d50 k8s.gcr.io/metadata-proxy:v0.1.10] 8953717} {[gcr.io/kubernetes-e2e-test-images/mounttest@sha256:c0bd6f0755f42af09a68c9a47fb993136588a76b3200ec305796b60d629d85d2 gcr.io/kubernetes-e2e-test-images/mounttest:1.0] 1563521} {[busybox@sha256:e004c2cc521c95383aebb1fb5893719aa7a8eae2e7a71f316a4410784edb00a9 busybox:1.29] 1154361} {[k8s.gcr.io/pause@sha256:f78411e19d84a252e53bff71a4407a5686c46983a2c2eeed83929b888179acea k8s.gcr.io/pause:3.1] 742472}],VolumesInUse:[],VolumesAttached:[],Config:&NodeConfigStatus{Assigned:nil,Active:nil,LastKnownGood:nil,Error:,},},}
I0212 12:21:54.648] Feb 12 12:21:48.125: INFO: 
I0212 12:21:54.649] Logging kubelet events for node e2e-test-prow-minion-group-ckng
I0212 12:21:54.649] Feb 12 12:21:48.138: INFO: 
I0212 12:21:54.649] Logging pods the kubelet thinks is on node e2e-test-prow-minion-group-ckng
I0212 12:21:54.649] Feb 12 12:21:48.151: INFO: fluentd-gcp-v3.2.0-4kgtf started at 2020-02-12 12:15:14 +0000 UTC (0+2 container statuses recorded)
I0212 12:21:54.650] Feb 12 12:21:48.151: INFO: 	Container fluentd-gcp ready: true, restart count 0
... skipping 22 lines ...
I0212 12:21:54.654] Feb 12 12:21:48.205: INFO: {Operation:start_container Method:docker_operations_latency_microseconds Quantile:0.99 Latency:30.16787s}
I0212 12:21:54.654] Feb 12 12:21:48.205: INFO: {Operation: Method:pod_worker_start_latency_microseconds Quantile:0.99 Latency:30.145467s}
I0212 12:21:54.655] Feb 12 12:21:48.205: INFO: {Operation: Method:pod_worker_start_latency_microseconds Quantile:0.9 Latency:30.091399s}
I0212 12:21:54.655] Feb 12 12:21:48.205: INFO: {Operation:pull_image Method:docker_operations_latency_microseconds Quantile:0.99 Latency:10.667922s}
I0212 12:21:54.655] Feb 12 12:21:48.205: INFO: 
I0212 12:21:54.655] Logging node info for node e2e-test-prow-minion-group-p6g9
I0212 12:21:54.662] Feb 12 12:21:48.208: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:e2e-test-prow-minion-group-p6g9,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/e2e-test-prow-minion-group-p6g9,UID:28dde320-4d91-11ea-ba4c-42010a800002,ResourceVersion:2982,Generation:0,CreationTimestamp:2020-02-12 12:14:03 +0000 UTC,DeletionTimestamp:<nil>,DeletionGracePeriodSeconds:nil,Labels:map[string]string{beta.kubernetes.io/arch: amd64,beta.kubernetes.io/fluentd-ds-ready: true,beta.kubernetes.io/instance-type: n1-standard-2,beta.kubernetes.io/metadata-proxy-ready: true,beta.kubernetes.io/os: linux,failure-domain.beta.kubernetes.io/region: us-central1,failure-domain.beta.kubernetes.io/zone: us-central1-b,kubernetes.io/hostname: e2e-test-prow-minion-group-p6g9,},Annotations:map[string]string{csi.volume.kubernetes.io/nodeid: {"pd.csi.storage.gke.io":"projects/k8s-boskos-gce-project-14/zones/us-central1-b/instances/e2e-test-prow-minion-group-p6g9"},node.alpha.kubernetes.io/ttl: 0,volumes.kubernetes.io/controller-managed-attach-detach: true,},OwnerReferences:[],Finalizers:[],ClusterName:,Initializers:nil,},Spec:NodeSpec{PodCIDR:10.64.2.0/24,DoNotUse_ExternalID:,ProviderID:gce://k8s-boskos-gce-project-14/us-central1-b/e2e-test-prow-minion-group-p6g9,Unschedulable:false,Taints:[],ConfigSource:nil,},Status:NodeStatus{Capacity:ResourceList{attachable-volumes-gce-pd: {{64 0} {<nil>} 64 DecimalSI},cpu: {{2 0} {<nil>} 2 DecimalSI},ephemeral-storage: {{101241290752 0} {<nil>}  BinarySI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{7848767488 0} {<nil>} 7664812Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Allocatable:ResourceList{attachable-volumes-gce-pd: {{64 0} {<nil>} 64 DecimalSI},cpu: {{2 0} {<nil>} 2 DecimalSI},ephemeral-storage: {{91117161526 0} {<nil>} 91117161526 DecimalSI},hugepages-2Mi: {{0 0} {<nil>} 0 DecimalSI},memory: {{7586623488 0} {<nil>} 7408812Ki BinarySI},pods: {{110 0} {<nil>} 110 DecimalSI},},Phase:,Conditions:[{FrequentDockerRestart False 2020-02-12 12:21:01 +0000 UTC 2020-02-12 12:17:57 +0000 UTC FrequentDockerRestart docker is functioning properly} {FrequentContainerdRestart False 2020-02-12 12:21:01 +0000 UTC 2020-02-12 12:17:58 +0000 UTC FrequentContainerdRestart containerd is functioning properly} {CorruptDockerOverlay2 False 2020-02-12 12:21:01 +0000 UTC 2020-02-12 12:17:56 +0000 UTC CorruptDockerOverlay2 docker overlay2 is functioning properly} {KernelDeadlock False 2020-02-12 12:21:01 +0000 UTC 2020-02-12 12:12:55 +0000 UTC KernelHasNoDeadlock kernel has no deadlock} {ReadonlyFilesystem False 2020-02-12 12:21:01 +0000 UTC 2020-02-12 12:12:55 +0000 UTC FilesystemIsNotReadOnly Filesystem is not read-only} {FrequentUnregisterNetDevice False 2020-02-12 12:21:01 +0000 UTC 2020-02-12 12:17:56 +0000 UTC UnregisterNetDevice node is functioning properly} {FrequentKubeletRestart False 2020-02-12 12:21:01 +0000 UTC 2020-02-12 12:17:56 +0000 UTC FrequentKubeletRestart kubelet is functioning properly} {NetworkUnavailable False 2020-02-12 12:14:19 +0000 UTC 2020-02-12 12:14:19 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2020-02-12 12:21:46 +0000 UTC 2020-02-12 12:14:03 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2020-02-12 12:21:46 +0000 UTC 2020-02-12 12:14:03 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2020-02-12 12:21:46 +0000 UTC 2020-02-12 12:14:03 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2020-02-12 12:21:46 +0000 UTC 2020-02-12 12:14:04 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.128.0.4} {ExternalIP 35.202.40.84} {InternalDNS e2e-test-prow-minion-group-p6g9.c.k8s-boskos-gce-project-14.internal} {Hostname e2e-test-prow-minion-group-p6g9.c.k8s-boskos-gce-project-14.internal}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:83e2820da55d593fa46a99bd820644f9,SystemUUID:83E2820D-A55D-593F-A46A-99BD820644F9,BootID:cd7d6463-c69c-4a6b-bcda-3fb3d84846cb,KernelVersion:4.4.111+,OSImage:Container-Optimized OS from Google,ContainerRuntimeVersion:docker://17.3.2,KubeletVersion:v1.13.5,KubeProxyVersion:v1.13.5,OperatingSystem:linux,Architecture:amd64,},Images:[{[gcr.io/stackdriver-agents/stackdriver-logging-agent@sha256:f8d5231b67b9c53f60068b535a11811d29d1b3efd53d2b79f2a2591ea338e4f2 gcr.io/stackdriver-agents/stackdriver-logging-agent:0.6-1.6.0-1] 223242132} {[gcr.io/gke-release/gcp-compute-persistent-disk-csi-driver@sha256:65527562c25ba2ecb1a6e8f80bf9aa5ad100be32c3417c4b31119eeea09b6080 gcr.io/gke-release/gcp-compute-persistent-disk-csi-driver:v0.4.0-gke.0] 133411124} {[k8s.gcr.io/prometheus-to-sd@sha256:6c0c742475363d537ff059136e5d5e4ab1f512ee0fd9b7ca42ea48bc309d1662 k8s.gcr.io/prometheus-to-sd:v0.3.1] 88077694} {[k8s.gcr.io/kube-proxy:v1.13.5] 80186087} {[k8s.gcr.io/heapster-amd64@sha256:9fae0af136ce0cf4f88393b3670f7139ffc464692060c374d2ae748e13144521 k8s.gcr.io/heapster-amd64:v1.6.0-beta.1] 76016169} {[gcr.io/gke-release/csi-node-driver-registrar@sha256:dc4e6c0fa39134e71c26972a7e2d2fb0c371bfc449b434e0fb2532a9410a4139 gcr.io/gke-release/csi-node-driver-registrar:v1.0.1-gke.0] 68977975} {[k8s.gcr.io/metrics-server-amd64@sha256:78938f933822856f443e6827fe5b37d6cc2f74ae888ac8b33d06fdbe5f8c658b k8s.gcr.io/metrics-server-amd64:v0.3.1] 40767713} {[k8s.gcr.io/coredns@sha256:81936728011c0df9404cb70b95c17bbc8af922ec9a70d0561a5d01fefa6ffa51 k8s.gcr.io/coredns:1.2.6] 40017418} {[k8s.gcr.io/addon-resizer@sha256:a31822f30e947885d038812f4a5a5675e72f92c06cef17b1989c80426aa89012 k8s.gcr.io/addon-resizer:1.8.4] 38349857} {[nginx@sha256:a3a0c4126587884f8d3090efca87f5af075d7e7ac8308cffc09a5a082d5f4760 nginx:1.14-alpine] 16032814} {[k8s.gcr.io/metadata-proxy@sha256:5be758058e67b578f7041498e2daca46ccd7426bc602d35ed0f50bd4a3659d50 k8s.gcr.io/metadata-proxy:v0.1.10] 8953717} {[gcr.io/kubernetes-e2e-test-images/mounttest@sha256:c0bd6f0755f42af09a68c9a47fb993136588a76b3200ec305796b60d629d85d2 gcr.io/kubernetes-e2e-test-images/mounttest:1.0] 1563521} {[busybox@sha256:e004c2cc521c95383aebb1fb5893719aa7a8eae2e7a71f316a4410784edb00a9 busybox:1.29] 1154361} {[k8s.gcr.io/pause@sha256:f78411e19d84a252e53bff71a4407a5686c46983a2c2eeed83929b888179acea k8s.gcr.io/pause:3.1] 742472}],VolumesInUse:[],VolumesAttached:[],Config:&NodeConfigStatus{Assigned:nil,Active:nil,LastKnownGood:nil,Error:,},},}
I0212 12:21:54.662] Feb 12 12:21:48.208: INFO: 
I0212 12:21:54.662] Logging kubelet events for node e2e-test-prow-minion-group-p6g9
I0212 12:21:54.662] Feb 12 12:21:48.218: INFO: 
I0212 12:21:54.662] Logging pods the kubelet thinks is on node e2e-test-prow-minion-group-p6g9
I0212 12:21:54.663] Feb 12 12:21:48.228: INFO: kube-proxy-e2e-test-prow-minion-group-p6g9 started at <nil> (0+0 container statuses recorded)
I0212 12:21:54.663] Feb 12 12:21:48.228: INFO: coredns-fff89c9b9-mdp8p started at 2020-02-12 12:15:06 +0000 UTC (0+1 container statuses recorded)
... skipping 32 lines ...
I0212 12:21:54.671] [sig-storage] CSI Volumes
I0212 12:21:54.671] /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/framework.go:22
I0212 12:21:54.671]   [Driver: pd.csi.storage.gke.io][Feature: gcePD-external]
I0212 12:21:54.671]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/csi_volumes.go:129
I0212 12:21:54.672]     [Testpattern: Dynamic PV (default fs)] subPath
I0212 12:21:54.672]     /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:99
I0212 12:21:54.672]       should fail if subpath file is outside the volume [Slow] [AfterEach]
I0212 12:21:54.672]       /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:253
I0212 12:21:54.672] 
I0212 12:21:54.672]       Persistent Volume pvc-55870a9b-4d91-11ea-ba4c-42010a800002 not deleted by dynamic provisioner
I0212 12:21:54.672]       Expected error:
I0212 12:21:54.672]           <*errors.errorString | 0xc000377590>: {
I0212 12:21:54.673]               s: "PersistentVolume pvc-55870a9b-4d91-11ea-ba4c-42010a800002 still exists within 5m0s",
I0212 12:21:54.673]           }
I0212 12:21:54.673]           PersistentVolume pvc-55870a9b-4d91-11ea-ba4c-42010a800002 still exists within 5m0s
I0212 12:21:54.673]       not to have occurred
I0212 12:21:54.673] 
... skipping 20 lines ...
I0212 12:24:44.189] 
I0212 12:24:44.189] Specify --start=41440 in the next get-serial-port-output invocation to get only the new output starting from here.
I0212 12:24:44.189] scp: /var/log/cluster-autoscaler.log*: No such file or directory
I0212 12:24:44.189] scp: /var/log/fluentd.log*: No such file or directory
I0212 12:24:44.190] scp: /var/log/kubelet.cov*: No such file or directory
I0212 12:24:44.190] scp: /var/log/startupscript.log*: No such file or directory
I0212 12:24:44.190] ERROR: (gcloud.compute.scp) [/usr/bin/scp] exited with return code [1].
I0212 12:24:44.190] Dumping logs from nodes locally to '/workspace/_artifacts'
I0212 12:24:44.190] Detecting nodes in the cluster
I0212 12:24:44.190] Changing logfiles to be world-readable for download
I0212 12:24:44.191] Changing logfiles to be world-readable for download
I0212 12:24:44.191] Changing logfiles to be world-readable for download
I0212 12:24:44.191] Copying 'kube-proxy.log fluentd.log node-problem-detector.log kubelet.cov startupscript.log' from e2e-test-prow-minion-group-p6g9
... skipping 6 lines ...
I0212 12:24:44.192] 
I0212 12:24:44.193] Specify --start=58659 in the next get-serial-port-output invocation to get only the new output starting from here.
I0212 12:24:44.193] scp: /var/log/fluentd.log*: No such file or directory
I0212 12:24:44.193] scp: /var/log/node-problem-detector.log*: No such file or directory
I0212 12:24:44.193] scp: /var/log/kubelet.cov*: No such file or directory
I0212 12:24:44.193] scp: /var/log/startupscript.log*: No such file or directory
I0212 12:24:44.193] ERROR: (gcloud.compute.scp) [/usr/bin/scp] exited with return code [1].
I0212 12:24:44.194] scp: /var/log/fluentd.log*: No such file or directory
I0212 12:24:44.194] scp: /var/log/node-problem-detector.log*: No such file or directory
I0212 12:24:44.194] scp: /var/log/kubelet.cov*: No such file or directory
I0212 12:24:44.194] scp: /var/log/startupscript.log*: No such file or directory
I0212 12:24:44.194] ERROR: (gcloud.compute.scp) [/usr/bin/scp] exited with return code [1].
I0212 12:24:44.194] scp: /var/log/fluentd.log*: No such file or directory
I0212 12:24:44.195] scp: /var/log/node-problem-detector.log*: No such file or directory
I0212 12:24:44.195] scp: /var/log/kubelet.cov*: No such file or directory
I0212 12:24:44.195] scp: /var/log/startupscript.log*: No such file or directory
I0212 12:24:44.195] ERROR: (gcloud.compute.scp) [/usr/bin/scp] exited with return code [1].
I0212 12:24:44.195] 
I0212 12:24:44.195] 
I0212 12:24:44.195] 
I0212 12:24:44.196] Summarizing 1 Failure:
I0212 12:24:44.196] 
I0212 12:24:44.196] [Fail] [sig-storage] CSI Volumes [Driver: pd.csi.storage.gke.io][Feature: gcePD-external] [Testpattern: Dynamic PV (default fs)] subPath [AfterEach] should fail if subpath file is outside the volume [Slow] 
I0212 12:24:44.196] /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/base.go:213
I0212 12:24:44.196] 
I0212 12:24:44.197] Ran 27 of 2161 Specs in 588.104 seconds
I0212 12:24:44.211] FAIL! -- 26 Passed | 1 Failed | 0 Pending | 2134 Skipped 
I0212 12:24:44.211] 
I0212 12:24:44.211] Ginkgo ran 1 suite in 9m51.928073223s
I0212 12:24:44.211] Test Suite Failed
I0212 12:24:44.237] Deleting driver
I0212 12:24:44.240] PKGDIR is /go/src/sigs.k8s.io/gcp-compute-persistent-disk-csi-driver
W0212 12:24:44.341] !!! Error in ./hack/ginkgo-e2e.sh:143
W0212 12:24:44.342]   Error in ./hack/ginkgo-e2e.sh:143. '"${ginkgo}" "${ginkgo_args[@]:+${ginkgo_args[@]}}" "${e2e_test}" -- "${auth_config[@]:+${auth_config[@]}}" --ginkgo.flakeAttempts="${FLAKE_ATTEMPTS}" --host="${KUBE_MASTER_URL}" --provider="${KUBERNETES_PROVIDER}" --gce-project="${PROJECT:-}" --gce-zone="${ZONE:-}" --gce-region="${REGION:-}" --gce-multizone="${MULTIZONE:-false}" --gke-cluster="${CLUSTER_NAME:-}" --kube-master="${KUBE_MASTER:-}" --cluster-tag="${CLUSTER_ID:-}" --cloud-config-file="${CLOUD_CONFIG:-}" --repo-root="${KUBE_ROOT}" --node-instance-group="${NODE_INSTANCE_GROUP:-}" --prefix="${KUBE_GCE_INSTANCE_PREFIX:-e2e}" --network="${KUBE_GCE_NETWORK:-${KUBE_GKE_NETWORK:-e2e}}" --node-tag="${NODE_TAG:-}" --master-tag="${MASTER_TAG:-}" --cluster-monitoring-mode="${KUBE_ENABLE_CLUSTER_MONITORING:-standalone}" --prometheus-monitoring="${KUBE_ENABLE_PROMETHEUS_MONITORING:-false}" --dns-domain="${KUBE_DNS_DOMAIN:-cluster.local}" ${KUBE_CONTAINER_RUNTIME:+"--container-runtime=${KUBE_CONTAINER_RUNTIME}"} ${MASTER_OS_DISTRIBUTION:+"--master-os-distro=${MASTER_OS_DISTRIBUTION}"} ${NODE_OS_DISTRIBUTION:+"--node-os-distro=${NODE_OS_DISTRIBUTION}"} ${NUM_NODES:+"--num-nodes=${NUM_NODES}"} ${E2E_REPORT_DIR:+"--report-dir=${E2E_REPORT_DIR}"} ${E2E_REPORT_PREFIX:+"--report-prefix=${E2E_REPORT_PREFIX}"} "${@:-}"' exited with status 1
W0212 12:24:44.342] Call stack:
W0212 12:24:44.343]   1: ./hack/ginkgo-e2e.sh:143 main(...)
W0212 12:24:44.343] Exiting with status 1
W0212 12:24:44.343] 2020/02/12 12:24:44 process.go:155: Step './hack/ginkgo-e2e.sh --ginkgo.focus=CSI.*gcePD-external --ginkgo.skip=\[Disruptive\]|\[Serial\]|kubelet.*down --report-dir=/workspace/_artifacts' finished in 9m53.237132823s
W0212 12:24:44.343] 2020/02/12 12:24:44 main.go:316: Something went wrong: encountered 1 errors: [error during ./hack/ginkgo-e2e.sh --ginkgo.focus=CSI.*gcePD-external --ginkgo.skip=\[Disruptive\]|\[Serial\]|kubelet.*down --report-dir=/workspace/_artifacts: exit status 1]
W0212 12:24:44.475] I0212 12:24:44.475652   67357 loader.go:359] Config loaded from file /root/.kube/config
W0212 12:24:44.477] I0212 12:24:44.477217   67357 loader.go:359] Config loaded from file /root/.kube/config
W0212 12:24:44.479] I0212 12:24:44.479218   67357 loader.go:359] Config loaded from file /root/.kube/config
W0212 12:24:44.479] I0212 12:24:44.479666   67357 decoder.go:224] decoding stream as YAML
W0212 12:24:44.481] I0212 12:24:44.481055   67357 loader.go:359] Config loaded from file /root/.kube/config
W0212 12:24:44.481] I0212 12:24:44.481530   67357 round_trippers.go:419] curl -k -v -XGET  -H "Accept: application/json, */*" -H "User-Agent: kubectl/v1.13.5 (linux/amd64) kubernetes/2166946" -H "Authorization: Bearer w8EOcdOwV5EyqRwttsBgZVMA99vMI2EW" 'https://35.222.213.144/api?timeout=32s'
... skipping 537 lines ...
W0212 12:25:07.599] NODE_NAMES=e2e-test-prow-minion-group-bl5h e2e-test-prow-minion-group-ckng e2e-test-prow-minion-group-p6g9
I0212 12:25:07.700] Bringing down cluster
W0212 12:25:11.199] Deleting Managed Instance Group...
W0212 12:27:48.771] ..................................Deleted [https://www.googleapis.com/compute/v1/projects/k8s-boskos-gce-project-14/zones/us-central1-b/instanceGroupManagers/e2e-test-prow-minion-group].
W0212 12:27:48.771] done.
W0212 12:27:53.361] Deleted [https://www.googleapis.com/compute/v1/projects/k8s-boskos-gce-project-14/global/instanceTemplates/e2e-test-prow-minion-template].
I0212 12:27:58.594] {"message":"Internal Server Error"}Removing etcd replica, name: e2e-test-prow-master, port: 2379, result: 0
I0212 12:28:00.159] {"message":"Internal Server Error"}Removing etcd replica, name: e2e-test-prow-master, port: 4002, result: 0
W0212 12:28:05.618] Updated [https://www.googleapis.com/compute/v1/projects/k8s-boskos-gce-project-14/zones/us-central1-b/instances/e2e-test-prow-master].
W0212 12:30:22.043] Deleted [https://www.googleapis.com/compute/v1/projects/k8s-boskos-gce-project-14/zones/us-central1-b/instances/e2e-test-prow-master].
W0212 12:30:31.095] Deleted [https://www.googleapis.com/compute/v1/projects/k8s-boskos-gce-project-14/global/firewalls/e2e-test-prow-master-https].
W0212 12:30:32.413] Deleted [https://www.googleapis.com/compute/v1/projects/k8s-boskos-gce-project-14/global/firewalls/e2e-test-prow-master-etcd].
W0212 12:30:37.208] Deleted [https://www.googleapis.com/compute/v1/projects/k8s-boskos-gce-project-14/global/firewalls/e2e-test-prow-minion-all].
W0212 12:30:43.944] Deleted [https://www.googleapis.com/compute/v1/projects/k8s-boskos-gce-project-14/regions/us-central1/addresses/e2e-test-prow-master-ip].
... skipping 8 lines ...
I0212 12:31:50.781] Property "clusters.k8s-boskos-gce-project-14_e2e-test-prow" unset.
I0212 12:31:51.542] Property "users.k8s-boskos-gce-project-14_e2e-test-prow" unset.
I0212 12:31:52.337] Property "users.k8s-boskos-gce-project-14_e2e-test-prow-basic-auth" unset.
I0212 12:31:53.237] Property "contexts.k8s-boskos-gce-project-14_e2e-test-prow" unset.
I0212 12:31:53.257] Cleared config for k8s-boskos-gce-project-14_e2e-test-prow from /root/.kube/config
I0212 12:31:53.260] Done
W0212 12:31:54.935] F0212 12:31:54.921054    1219 main.go:68] Failed to run integration test: failed to run tests: failed to run tests on e2e cluster: exit status 1
W0212 12:31:54.985] Traceback (most recent call last):
W0212 12:31:54.985]   File "/workspace/./test-infra/jenkins/../scenarios/execute.py", line 50, in <module>
W0212 12:31:54.985]     main(ARGS.env, ARGS.cmd + ARGS.args)
W0212 12:31:54.985]   File "/workspace/./test-infra/jenkins/../scenarios/execute.py", line 41, in main
W0212 12:31:54.985]     check(*cmd)
W0212 12:31:54.986]   File "/workspace/./test-infra/jenkins/../scenarios/execute.py", line 30, in check
W0212 12:31:54.986]     subprocess.check_call(cmd)
W0212 12:31:54.986]   File "/usr/lib/python2.7/subprocess.py", line 190, in check_call
W0212 12:31:54.986]     raise CalledProcessError(retcode, cmd)
W0212 12:31:54.986] subprocess.CalledProcessError: Command '('test/run-k8s-integration.sh',)' returned non-zero exit status 255
E0212 12:31:54.987] Command failed
I0212 12:31:54.987] process 465 exited with code 1 after 38.1m
E0212 12:31:54.987] FAIL: ci-gcp-compute-persistent-disk-csi-driver-release-0-4-k8s-1-13-5-integration
I0212 12:31:54.988] Call:  gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json
W0212 12:31:56.922] Activated service account credentials for: [pr-kubekins@kubernetes-jenkins-pull.iam.gserviceaccount.com]
I0212 12:31:57.068] process 68313 exited with code 0 after 0.0m
I0212 12:31:57.089] Call:  gcloud config get-value account
I0212 12:31:58.497] process 68326 exited with code 0 after 0.0m
I0212 12:31:58.497] Will upload results to gs://kubernetes-jenkins/logs using pr-kubekins@kubernetes-jenkins-pull.iam.gserviceaccount.com
I0212 12:31:58.497] Upload result and artifacts...
I0212 12:31:58.497] Gubernator results at https://gubernator.k8s.io/build/kubernetes-jenkins/logs/ci-gcp-compute-persistent-disk-csi-driver-release-0-4-k8s-1-13-5-integration/1227561342081175552
I0212 12:31:58.498] Call:  gsutil ls gs://kubernetes-jenkins/logs/ci-gcp-compute-persistent-disk-csi-driver-release-0-4-k8s-1-13-5-integration/1227561342081175552/artifacts
W0212 12:32:02.495] CommandException: One or more URLs matched no objects.
E0212 12:32:02.927] Command failed
I0212 12:32:02.927] process 68339 exited with code 1 after 0.1m
W0212 12:32:02.928] Remote dir gs://kubernetes-jenkins/logs/ci-gcp-compute-persistent-disk-csi-driver-release-0-4-k8s-1-13-5-integration/1227561342081175552/artifacts not exist yet
I0212 12:32:02.929] Call:  gsutil -m -q -o GSUtil:use_magicfile=True cp -r -c -z log,txt,xml /workspace/_artifacts gs://kubernetes-jenkins/logs/ci-gcp-compute-persistent-disk-csi-driver-release-0-4-k8s-1-13-5-integration/1227561342081175552/artifacts
I0212 12:32:21.735] process 68484 exited with code 0 after 0.3m
W0212 12:32:21.737] metadata path /workspace/_artifacts/metadata.json does not exist
W0212 12:32:21.737] metadata not found or invalid, init with empty metadata
... skipping 15 lines ...