This job view page is being replaced by Spyglass soon. Check out the new job view.
ResultFAILURE
Tests 1 failed / 26 succeeded
Started2020-02-15 08:10
Elapsed35m7s
Revision
Buildergke-prow-default-pool-cf4891d4-sgj5
links{u'resultstore': {u'url': u'https://source.cloud.google.com/results/invocations/890df659-bf2d-46ad-924d-3d93912c106e/targets/test'}}
pod656f0fee-4fca-11ea-9bea-16a0f55e352c
resultstorehttps://source.cloud.google.com/results/invocations/890df659-bf2d-46ad-924d-3d93912c106e/targets/test
infra-commitf5dd3ee0e
pod656f0fee-4fca-11ea-9bea-16a0f55e352c
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 support readOnly file specified in the volumeMount 6m11s

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\ssupport\sreadOnly\sfile\sspecified\sin\sthe\svolumeMount$'
/go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:120
Persistent Volume pvc-7a89b035-4fcd-11ea-b4f3-42010a800002 not deleted by dynamic provisioner
Expected error:
    <*errors.errorString | 0xc000a07230>: {
        s: "PersistentVolume pvc-7a89b035-4fcd-11ea-b4f3-42010a800002 still exists within 5m0s",
    }
    PersistentVolume pvc-7a89b035-4fcd-11ea-b4f3-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_18.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 237 lines ...
W0215 08:27:54.293] Trying to find master named 'e2e-test-prow-master'
W0215 08:27:54.293] Looking for address 'e2e-test-prow-master-ip'
W0215 08:27:55.418] Using master: e2e-test-prow-master (external IP: 35.232.159.219)
I0215 08:27:55.519] Waiting up to 300 seconds for cluster initialization.
I0215 08:27:55.519] 
I0215 08:27:55.519]   This will continually check to see if the API for kubernetes is reachable.
I0215 08:27:55.519]   This may time out if there was some uncaught error during start up.
I0215 08:27:55.519] 
I0215 08:29:04.294] ................Kubernetes cluster created.
I0215 08:29:04.706] Cluster "k8s-jkns-gci-gce-kubenet_e2e-test-prow" set.
I0215 08:29:05.109] User "k8s-jkns-gci-gce-kubenet_e2e-test-prow" set.
I0215 08:29:05.707] Context "k8s-jkns-gci-gce-kubenet_e2e-test-prow" created.
I0215 08:29:05.970] Switched to context "k8s-jkns-gci-gce-kubenet_e2e-test-prow".
... skipping 19 lines ...
I0215 08:29:43.099] NAME                              STATUS                     ROLES    AGE   VERSION
I0215 08:29:43.099] e2e-test-prow-master              Ready,SchedulingDisabled   <none>   5s    v1.13.5
I0215 08:29:43.099] e2e-test-prow-minion-group-bb2l   Ready                      <none>   2s    v1.13.5
I0215 08:29:43.100] e2e-test-prow-minion-group-jkrv   Ready                      <none>   3s    v1.13.5
I0215 08:29:43.100] e2e-test-prow-minion-group-zth4   Ready                      <none>   4s    v1.13.5
I0215 08:29:43.326] Validate output:
I0215 08:29:43.489] NAME                 STATUS    MESSAGE              ERROR
I0215 08:29:43.489] controller-manager   Healthy   ok                   
I0215 08:29:43.489] scheduler            Healthy   ok                   
I0215 08:29:43.489] etcd-0               Healthy   {"health": "true"}   
I0215 08:29:43.490] etcd-1               Healthy   {"health": "true"}   
I0215 08:29:43.496] Cluster validation succeeded
W0215 08:29:43.596] Done, listing cluster services:
... skipping 116 lines ...
W0215 08:30:13.076]   "details": {
W0215 08:30:13.076]     "name": "cloud-sa",
W0215 08:30:13.076]     "kind": "secrets"
W0215 08:30:13.077]   },
W0215 08:30:13.077]   "code": 404
W0215 08:30:13.077] }]
W0215 08:30:13.077] F0215 08:30:13.074325   64223 helpers.go:116] Error from server (NotFound): secrets "cloud-sa" not found
W0215 08:30:13.080] + /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/5c8db995-4fcd-11ea-812d-9eb8a5c5a482/cloud-sa.json -n default
W0215 08:30:13.214] I0215 08:30:13.214097   64267 loader.go:359] Config loaded from file /root/.kube/config
W0215 08:30:13.215] I0215 08:30:13.215148   64267 loader.go:359] Config loaded from file /root/.kube/config
W0215 08:30:13.216] I0215 08:30:13.216473   64267 loader.go:359] Config loaded from file /root/.kube/config
W0215 08:30:13.223] I0215 08:30:13.220392   64267 request.go:942] Request Body: {"apiVersion":"v1","data":{"cloud-sa.json":"ewogICJ0eXBlIjogInNlcnZpY2VfYWNjb3VudCIsCiAgInByb2plY3RfaWQiOiAia3ViZXJuZXRlcy1qZW5raW5zLXB1bGwiLAogICJwcml2YXRlX2tleV9pZCI6ICI5ZGMxNDU3YzBiMjQ5ZWZlMTRmOTkzMzM3OTRkMDA2MTNiNzRkMTE2IiwKICAicHJpdmF0ZV9rZXkiOiAiLS0tLS1CRUdJTiBQUklWQVRFIEtFWS0tLS0tXG5NSUlFdlFJQkFEQU5CZ2txaGtpRzl3MEJBUUVGQUFTQ0JLY3dnZ1NqQWdFQUFvSUJBUUNrcEx2WmdOdC9BME1XXG5RdTR4UENkeWgreUg3Z09xdXNEQjMxMGNmL2xwN2sxNmJkL0U4aDdVTmp0S2xpaC90UVZCdjdiejh3c0pIUmpvXG5LZ1JDbjd3NmczVFB5Q0Q1YmtUUzFNT1RMMjRiU3F3YW9BUFhGd0k3eEt5NlNDTnpDckVPazJ2b3F6NE5LT3BhXG5Ob0UrV0lBblg0TVQvS0xWbERVMlRmaTE5R2NCbHBiMlFaOGlFWmtUQTZWNHFXM0oxSFNlemhtczhsTHZ1akJ4XG5namdlWlY1SDBJaHZjMFFDTG9rejhIelh6TnBzaXRaQWVSL0hIWVY2TElsUkhLTjRMb0p0RkY2NHBnQjREZkI3XG5OU1ZwdXQ3M3k5OE1lUkhUU1l5MmRqVlFHTlYzYVdqdmhVZzVyUE5DUjBKRWxKeENTaXZUMW4xUTJRU0d2eDZtXG4rVS9pTjhyUEFnTUJBQUVDZ2dFQUJNVk5PQ2syc3dCNk1pdndVUGJvUWJaVWtUL0JWWEloNGJ4Q0szQTkzdWJyXG4wYzliTzQ2MGUvdXlUaC81dm5HVlhHbGN1TWJqRy9sKzNrTlJha2pNb0hsc3FoU25kL0xOQmJycWk5cEUrMzkzXG5heklWeW1hOVJ0UVZHVFM3NmpwMkZQRUtvR3hOMlAzRmhLV3Rxd3ZQY3RTZXJMYVdWVS85RnJ5OXB6QVV5QVAwXG5KZE4rUnVYcGRVMkJ6WTRGbm1MWnk2WXdlZmF2ekFtRHBjYTFVOWpJSHExdkIwSnFZWGFXU200VkIwL1Y0dzZFXG5RWXlMYjFKa29hd1p3VUZkeTBlaDBGTzNLVG9KOUtjNHVaQm1sWVBScy9NWlBNM21HNk9JVmVQeDY5ZEUxemNtXG5BZnBXcm4xV3VITWZNK1J5WFBIRHMzRW1yQXJiYzhtQ0ttaGVRaFB3S1FLQmdRRFZSY0VrYXVFYmM1c3dyQnRxXG5OUG1jR0dMeVlvS2x6TGIvTGgzVFhiOWozYnRnWFFzbjNzMmd2MEFLYlpERVpKRzJxU3hNQ1FvRHNLRWcvTXhhXG5wUTZQUEg4MlZ2bzUxTHBUTkhoZDJyWU5xVnEwblJTdzNCYWdoTUFvREVnd1I3cnA0emJ2WWVvTkwxd1FmTTl0XG5rbmxBL2szVE40YTBOaTRrYkQzS0F3UjN5d0tCZ1FERm9PbWRrL3FuaE5zSFU2ZmZxdVpxTDFXenZXZkJRcVo4XG50Mm5vSFlRbFd5M2Rzd21vZlV5NFU3N3h3VmJBVHRQZjBXM2JjY3hWc2tKSXZJRHhoRmJ3WFVSNkZUVkJXc2F3XG5jcXIzQmJycDMyTWUydERHckV0VGlPVGJBcTFlV015cHc5NFpHaFdCOExMa1E1SXd5bjJuWndMcmRHRlljM3lnXG51blZWUit0d2pRS0JnUURFSVJMZWw3K09URUZpZ0ZQeDF1ZlpxZitNb2hVOXZrWm40NVFnSmUxMVBKc3Rva001XG5Ga2VKMVhkaVg2SXJTY1ZLOHNhKzRlMG91WTFrVmJia2dUZ2pkMklScWVrUnQ5VGw0Ykh6dGNlSVJyOFlyQUEwXG5LU0pSMmVNUXNVTE55NWxUcjlWOFRWSTliOWs5ZkZvUmpRc2ZQdjU1Q0c1RFdqUVM0TXZ0ODlwdkF3S0JnQ1BuXG5JY25RMGw2UWtrSDRmcXp4blQ1NUx2YWlXREVSN0xFSG1TUGtDTmZJZ3NLZC9na3dDam9LYk12NnRjbm1DRFBIXG5GbEFoa2wrWExOZU45MWJwRmVwQTUybk9aSWhrOTJlaXpWQm5LQmZJejNjUmhaQXlTTlQ2TDZsaUNTRDB2T215XG5mYXpOd2s2QzdkenVNYWJQZ3BoZzdIVGVCYmxOOGJ3NVk0dUVyMDhaQW9HQUpBeURiZmthN0hWNlJwWkkvTEcxXG5Zakd0OU5QNm42UklxRUUxVWFiMEFaY2pJWDVlK0RTUnV6RVRUSXRiN0hNYUZVOE1sWmdDTWNmWDk1ckN1RmhhXG45bkFQeGZNWEd6WVdXRlVMWmNPbWdBTWQ2RkNDUlFNSjVEUm9JYU5iNGIwdVhUYWk1Z1BaUDdGQ3hNTVdrbzJQXG56NFV0WFBCVXY1am8zZUxYUHFWVVNCQT1cbi0tLS0tRU5EIFBSSVZBVEUgS0VZLS0tLS1cbiIsCiAgImNsaWVudF9lbWFpbCI6ICJwci1rdWJla2luc0BrdWJlcm5ldGVzLWplbmtpbnMtcHVsbC5pYW0uZ3NlcnZpY2VhY2NvdW50LmNvbSIsCiAgImNsaWVudF9pZCI6ICIxMTM2MDA2MzMyODUwMDYyODMxMzAiLAogICJhdXRoX3VyaSI6ICJodHRwczovL2FjY291bnRzLmdvb2dsZS5jb20vby9vYXV0aDIvYXV0aCIsCiAgInRva2VuX3VyaSI6ICJodHRwczovL29hdXRoMi5nb29nbGVhcGlzLmNvbS90b2tlbiIsCiAgImF1dGhfcHJvdmlkZXJfeDUwOV9jZXJ0X3VybCI6ICJodHRwczovL3d3dy5nb29nbGVhcGlzLmNvbS9vYXV0aDIvdjEvY2VydHMiLAogICJjbGllbnRfeDUwOV9jZXJ0X3VybCI6ICJodHRwczovL3d3dy5nb29nbGVhcGlzLmNvbS9yb2JvdC92MS9tZXRhZGF0YS94NTA5L3ByLWt1YmVraW5zJTQwa3ViZXJuZXRlcy1qZW5raW5zLXB1bGwuaWFtLmdzZXJ2aWNlYWNjb3VudC5jb20iCn0K"},"kind":"Secret","metadata":{"creationTimestamp":null,"name":"cloud-sa"}}
W0215 08:30:13.224] I0215 08:30:13.224270   64267 round_trippers.go:419] curl -k -v -XPOST  -H "User-Agent: kubectl/v1.13.5 (linux/amd64) kubernetes/2166946" -H "Accept: application/json" -H "Authorization: Bearer uArXmzdUAtce8myyEFbaGhvJxqWec9P5" 'https://35.232.159.219/api/v1/namespaces/default/secrets'
... skipping 29 lines ...
W0215 08:30:13.455]     "name": "cluster-admin-binding",
W0215 08:30:13.456]     "group": "rbac.authorization.k8s.io",
W0215 08:30:13.456]     "kind": "clusterrolebindings"
W0215 08:30:13.456]   },
W0215 08:30:13.456]   "code": 404
W0215 08:30:13.456] }]
W0215 08:30:13.456] F0215 08:30:13.420789   64309 helpers.go:116] Error from server (NotFound): clusterrolebindings.rbac.authorization.k8s.io "cluster-admin-binding" not found
W0215 08:30:13.456] ++ gcloud config get-value account
W0215 08:30:13.850] + /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
W0215 08:30:13.999] I0215 08:30:13.999707   64366 loader.go:359] Config loaded from file /root/.kube/config
W0215 08:30:14.001] I0215 08:30:14.000887   64366 loader.go:359] Config loaded from file /root/.kube/config
W0215 08:30:14.002] I0215 08:30:14.002478   64366 loader.go:359] Config loaded from file /root/.kube/config
W0215 08:30:14.007] I0215 08:30:14.006438   64366 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 ...
W0215 08:30:14.752] 00000670  74 65 73 29 20 6f 72 20  61 20 63 6f 6e 66 69 67  |tes) or a config|
W0215 08:30:14.752] 00000680  75 72 61 74 69 6f 6e 20  63 68 61 6e 67 65 20 6f  |uration change o|
W0215 08:30:14.752] 00000690  6e 20 74 68 65 20 73 65  72 76 65 72 2c 20 74 68  |n the server, th|
W0215 08:30:14.752] 000006a0  65 20 73 65 72 76 65 72  20 77 69 6c 6c 20 72 65  |e server will re|
W0215 08:30:14.753] 000006b0  73 70 6f 6e 64 20 77 69  74 68 20 61 20 34 31 30  |spond with a 410|
W0215 08:30:14.753] 000006c0  20 52 65 73 6f 75 72 63  65 45 78 70 69 72 65 64  | ResourceExpired|
W0215 08:30:14.753] 000006d0  20 65 72 72 6f 72 20 74  6f 67 65 74 68 65 72 20  | error together |
W0215 08:30:14.753] 000006e0  77 69 74 68 20 61 20 63  6f 6e 74 69 6e 75 65 20  |with a continue |
W0215 08:30:14.753] 000006f0  74 6f 6b 65 6e 2e 20 49  66 20 74 68 65 20 63 6c  |token. If the cl|
W0215 08:30:14.753] 00000700  69 65 6e 74 20 6e 65 65  64 73 20 61 20 63 6f 6e  |ient needs a con|
W0215 08:30:14.754] 00000710  73 69 73 74 65 6e 74 20  6c 69 73 74 2c 20 69 74  |sistent list, it|
W0215 08:30:14.754] 00000720  20 6d 75 73 74 20 72 65  73 74 61 72 74 20 74 68  | must restart th|
W0215 08:30:14.754] 00000730  65 69 72 20 6c 69 73 74  20 77 69 74 68 6f 75 74  |eir list without|
... skipping 836 lines ...
I0215 08:30:39.408] 
I0215 08:30:49.618] Feb 15 08:30:43.380: INFO: cluster-master-image: cos-stable-65-10323-64-0
I0215 08:30:49.618] Feb 15 08:30:43.380: INFO: cluster-node-image: cos-stable-65-10323-64-0
I0215 08:30:49.618] Feb 15 08:30:43.380: INFO: >>> kubeConfig: /root/.kube/config
I0215 08:30:49.623] Feb 15 08:30:43.383: INFO: Waiting up to 30m0s for all (but 0) nodes to be schedulable
I0215 08:30:49.626] Feb 15 08:30:43.402: INFO: Waiting up to 10m0s for all pods (need at least 0) in namespace 'kube-system' to be running and ready
I0215 08:30:49.626] Feb 15 08:30:43.452: INFO: The status of Pod coredns-fff89c9b9-6ml8n is Pending (Ready = false), waiting for it to be either Running (with Ready = true) or Failed
I0215 08:30:49.627] Feb 15 08:30:43.452: INFO: The status of Pod heapster-v1.6.0-beta.1-5f77ccd9dd-zckvm is Pending (Ready = false), waiting for it to be either Running (with Ready = true) or Failed
I0215 08:30:49.627] Feb 15 08:30:43.452: INFO: The status of Pod kubernetes-dashboard-66bb48f98c-6bs6w is Pending (Ready = false), waiting for it to be either Running (with Ready = true) or Failed
I0215 08:30:49.627] Feb 15 08:30:43.452: INFO: The status of Pod metrics-server-v0.3.1-58d65f8d6-f78g2 is Pending (Ready = false), waiting for it to be either Running (with Ready = true) or Failed
I0215 08:30:49.628] Feb 15 08:30:43.452: INFO: 24 / 28 pods in namespace 'kube-system' are running and ready (0 seconds elapsed)
I0215 08:30:49.628] Feb 15 08:30:43.452: INFO: expected 9 pod replicas in namespace 'kube-system', 5 are Running and Ready.
I0215 08:30:49.628] Feb 15 08:30:43.452: INFO: POD                                      NODE                             PHASE    GRACE  CONDITIONS
I0215 08:30:49.630] Feb 15 08:30:43.452: INFO: coredns-fff89c9b9-6ml8n                  e2e-test-prow-minion-group-bb2l  Pending         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:25 +0000 UTC  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:25 +0000 UTC ContainersNotReady containers with unready status: [coredns]} {ContainersReady False 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:25 +0000 UTC ContainersNotReady containers with unready status: [coredns]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:25 +0000 UTC  }]
I0215 08:30:49.631] Feb 15 08:30:43.452: INFO: heapster-v1.6.0-beta.1-5f77ccd9dd-zckvm  e2e-test-prow-minion-group-bb2l  Pending         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:18 +0000 UTC  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:18 +0000 UTC ContainersNotReady containers with unready status: [heapster heapster-nanny]} {ContainersReady False 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:18 +0000 UTC ContainersNotReady containers with unready status: [heapster heapster-nanny]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:00 +0000 UTC  }]
I0215 08:30:49.632] Feb 15 08:30:43.452: INFO: kubernetes-dashboard-66bb48f98c-6bs6w    e2e-test-prow-minion-group-bb2l  Pending         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:18 +0000 UTC  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:18 +0000 UTC ContainersNotReady containers with unready status: [kubernetes-dashboard]} {ContainersReady False 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:18 +0000 UTC ContainersNotReady containers with unready status: [kubernetes-dashboard]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:29:54 +0000 UTC  }]
I0215 08:30:49.633] Feb 15 08:30:43.452: INFO: metrics-server-v0.3.1-58d65f8d6-f78g2    e2e-test-prow-minion-group-jkrv  Pending         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:21 +0000 UTC  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:21 +0000 UTC ContainersNotReady containers with unready status: [metrics-server metrics-server-nanny]} {ContainersReady False 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:21 +0000 UTC ContainersNotReady containers with unready status: [metrics-server metrics-server-nanny]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:00 +0000 UTC  }]
I0215 08:30:49.633] Feb 15 08:30:43.452: INFO: 
I0215 08:30:49.634] Feb 15 08:30:45.798: INFO: The status of Pod coredns-fff89c9b9-6ml8n is Pending (Ready = false), waiting for it to be either Running (with Ready = true) or Failed
I0215 08:30:49.634] Feb 15 08:30:45.798: INFO: The status of Pod heapster-v1.6.0-beta.1-5f77ccd9dd-zckvm is Pending (Ready = false), waiting for it to be either Running (with Ready = true) or Failed
I0215 08:30:49.634] Feb 15 08:30:45.798: INFO: The status of Pod kubernetes-dashboard-66bb48f98c-6bs6w is Pending (Ready = false), waiting for it to be either Running (with Ready = true) or Failed
I0215 08:30:49.635] Feb 15 08:30:45.798: INFO: 25 / 28 pods in namespace 'kube-system' are running and ready (2 seconds elapsed)
I0215 08:30:49.635] Feb 15 08:30:45.798: INFO: expected 9 pod replicas in namespace 'kube-system', 6 are Running and Ready.
I0215 08:30:49.635] Feb 15 08:30:45.798: INFO: POD                                      NODE                             PHASE    GRACE  CONDITIONS
I0215 08:30:49.636] Feb 15 08:30:45.798: INFO: coredns-fff89c9b9-6ml8n                  e2e-test-prow-minion-group-bb2l  Pending         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:25 +0000 UTC  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:25 +0000 UTC ContainersNotReady containers with unready status: [coredns]} {ContainersReady False 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:25 +0000 UTC ContainersNotReady containers with unready status: [coredns]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:25 +0000 UTC  }]
I0215 08:30:49.637] Feb 15 08:30:45.798: INFO: heapster-v1.6.0-beta.1-5f77ccd9dd-zckvm  e2e-test-prow-minion-group-bb2l  Pending         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:18 +0000 UTC  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:18 +0000 UTC ContainersNotReady containers with unready status: [heapster heapster-nanny]} {ContainersReady False 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:18 +0000 UTC ContainersNotReady containers with unready status: [heapster heapster-nanny]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:00 +0000 UTC  }]
I0215 08:30:49.638] Feb 15 08:30:45.798: INFO: kubernetes-dashboard-66bb48f98c-6bs6w    e2e-test-prow-minion-group-bb2l  Pending         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:18 +0000 UTC  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:18 +0000 UTC ContainersNotReady containers with unready status: [kubernetes-dashboard]} {ContainersReady False 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:18 +0000 UTC ContainersNotReady containers with unready status: [kubernetes-dashboard]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:29:54 +0000 UTC  }]
I0215 08:30:49.638] Feb 15 08:30:45.798: INFO: 
I0215 08:30:49.638] Feb 15 08:30:47.797: INFO: The status of Pod coredns-fff89c9b9-6ml8n is Pending (Ready = false), waiting for it to be either Running (with Ready = true) or Failed
I0215 08:30:49.640] Feb 15 08:30:47.797: INFO: The status of Pod heapster-v1.6.0-beta.1-5f77ccd9dd-zckvm is Pending (Ready = false), waiting for it to be either Running (with Ready = true) or Failed
I0215 08:30:49.640] Feb 15 08:30:47.797: INFO: The status of Pod kubernetes-dashboard-66bb48f98c-6bs6w is Pending (Ready = false), waiting for it to be either Running (with Ready = true) or Failed
I0215 08:30:49.640] Feb 15 08:30:47.797: INFO: 25 / 28 pods in namespace 'kube-system' are running and ready (4 seconds elapsed)
I0215 08:30:49.640] Feb 15 08:30:47.797: INFO: expected 9 pod replicas in namespace 'kube-system', 6 are Running and Ready.
I0215 08:30:49.641] Feb 15 08:30:47.797: INFO: POD                                      NODE                             PHASE    GRACE  CONDITIONS
I0215 08:30:49.641] Feb 15 08:30:47.797: INFO: coredns-fff89c9b9-6ml8n                  e2e-test-prow-minion-group-bb2l  Pending         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:25 +0000 UTC  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:25 +0000 UTC ContainersNotReady containers with unready status: [coredns]} {ContainersReady False 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:25 +0000 UTC ContainersNotReady containers with unready status: [coredns]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:25 +0000 UTC  }]
I0215 08:30:49.642] Feb 15 08:30:47.797: INFO: heapster-v1.6.0-beta.1-5f77ccd9dd-zckvm  e2e-test-prow-minion-group-bb2l  Pending         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:18 +0000 UTC  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:18 +0000 UTC ContainersNotReady containers with unready status: [heapster heapster-nanny]} {ContainersReady False 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:18 +0000 UTC ContainersNotReady containers with unready status: [heapster heapster-nanny]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:00 +0000 UTC  }]
I0215 08:30:49.643] Feb 15 08:30:47.797: INFO: kubernetes-dashboard-66bb48f98c-6bs6w    e2e-test-prow-minion-group-bb2l  Pending         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:18 +0000 UTC  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:18 +0000 UTC ContainersNotReady containers with unready status: [kubernetes-dashboard]} {ContainersReady False 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:18 +0000 UTC ContainersNotReady containers with unready status: [kubernetes-dashboard]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:29:54 +0000 UTC  }]
... skipping 159 lines ...
I0215 08:31:51.513] STEP: creating a claim
I0215 08:31:51.514] Feb 15 08:30:49.963: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-ljw29] to have phase Bound
I0215 08:31:51.514] Feb 15 08:30:50.000: INFO: PersistentVolumeClaim pvc-ljw29 found but phase is Pending instead of Bound.
I0215 08:31:51.514] Feb 15 08:30:52.064: INFO: PersistentVolumeClaim pvc-ljw29 found but phase is Pending instead of Bound.
I0215 08:31:51.514] Feb 15 08:30:54.069: INFO: PersistentVolumeClaim pvc-ljw29 found but phase is Pending instead of Bound.
I0215 08:31:51.514] Feb 15 08:30:56.075: INFO: PersistentVolumeClaim pvc-ljw29 found and phase=Bound (6.111790312s)
I0215 08:31:51.515] [It] should fail if subpath with backstepping is outside the volume [Slow]
I0215 08:31:51.515]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:269
I0215 08:31:51.515] STEP: Creating pod pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-qr6f
I0215 08:31:51.515] STEP: Checking for subpath error in container status
I0215 08:31:51.515] Feb 15 08:31:16.304: INFO: Deleting pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-qr6f" in namespace "e2e-tests-csi-volumes-rn5gn"
I0215 08:31:51.516] Feb 15 08:31:16.478: INFO: Wait up to 5m0s for pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-qr6f" to be fully deleted
I0215 08:31:51.516] [AfterEach] [Testpattern: Dynamic PV (default fs)] subPath
I0215 08:31:51.516]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:120
I0215 08:31:51.516] STEP: Deleting pod
I0215 08:31:51.517] Feb 15 08:31:24.685: INFO: Deleting pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-qr6f" in namespace "e2e-tests-csi-volumes-rn5gn"
... skipping 23 lines ...
I0215 08:31:51.521] [sig-storage] CSI Volumes
I0215 08:31:51.521] /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/framework.go:22
I0215 08:31:51.521]   [Driver: pd.csi.storage.gke.io][Feature: gcePD-external]
I0215 08:31:51.522]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/csi_volumes.go:129
I0215 08:31:51.522]     [Testpattern: Dynamic PV (default fs)] subPath
I0215 08:31:51.522]     /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:99
I0215 08:31:51.523]       should fail if subpath with backstepping is outside the volume [Slow]
I0215 08:31:51.523]       /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:269
I0215 08:31:51.523] ------------------------------
I0215 08:31:54.137] SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
I0215 08:31:54.137] ------------------------------
I0215 08:31:54.138] [BeforeEach] [sig-storage] CSI Volumes
I0215 08:31:54.138]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/framework.go:153
... skipping 139 lines ...
I0215 08:32:07.723] Feb 15 08:31:00.861: INFO: PersistentVolumeClaim pvc-ww4pg found but phase is Pending instead of Bound.
I0215 08:32:07.724] Feb 15 08:31:02.865: INFO: PersistentVolumeClaim pvc-ww4pg found but phase is Pending instead of Bound.
I0215 08:32:07.724] Feb 15 08:31:04.868: INFO: PersistentVolumeClaim pvc-ww4pg found but phase is Pending instead of Bound.
I0215 08:32:07.724] Feb 15 08:31:06.871: INFO: PersistentVolumeClaim pvc-ww4pg found but phase is Pending instead of Bound.
I0215 08:32:07.724] Feb 15 08:31:08.890: INFO: PersistentVolumeClaim pvc-ww4pg found but phase is Pending instead of Bound.
I0215 08:32:07.724] Feb 15 08:31:11.027: INFO: PersistentVolumeClaim pvc-ww4pg found and phase=Bound (18.237016833s)
I0215 08:32:07.725] [It] should fail if subpath directory is outside the volume [Slow]
I0215 08:32:07.725]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:245
I0215 08:32:07.725] STEP: Creating pod pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bg5d
I0215 08:32:07.725] STEP: Checking for subpath error in container status
I0215 08:32:07.725] Feb 15 08:31:33.453: INFO: Deleting pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bg5d" in namespace "e2e-tests-csi-volumes-nbvsj"
I0215 08:32:07.725] Feb 15 08:31:33.464: INFO: Wait up to 5m0s for pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bg5d" to be fully deleted
I0215 08:32:07.726] WARNING: pod log: pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bg5d/test-container-subpath-pd-csi-storage-gke-io-dynamicpv-bg5d: pods "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bg5d" not found
I0215 08:32:07.726] WARNING: pod log: pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bg5d/test-container-volume-pd-csi-storage-gke-io-dynamicpv-bg5d: pods "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bg5d" not found
I0215 08:32:07.726] [AfterEach] [Testpattern: Dynamic PV (default fs)] subPath
I0215 08:32:07.726]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:120
... skipping 25 lines ...
I0215 08:32:07.730] [sig-storage] CSI Volumes
I0215 08:32:07.730] /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/framework.go:22
I0215 08:32:07.730]   [Driver: pd.csi.storage.gke.io][Feature: gcePD-external]
I0215 08:32:07.731]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/csi_volumes.go:129
I0215 08:32:07.731]     [Testpattern: Dynamic PV (default fs)] subPath
I0215 08:32:07.731]     /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:99
I0215 08:32:07.731]       should fail if subpath directory is outside the volume [Slow]
I0215 08:32:07.731]       /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:245
I0215 08:32:07.731] ------------------------------
I0215 08:32:07.732] Feb 15 08:32:07.719: INFO: Running AfterSuite actions on all nodes
I0215 08:32:07.732] 
I0215 08:32:11.470] 
I0215 08:32:11.471] [BeforeEach] [sig-storage] CSI Volumes
... skipping 217 lines ...
I0215 08:32:18.805] Feb 15 08:31:07.417: INFO: PersistentVolumeClaim pvc-zwk7q found but phase is Pending instead of Bound.
I0215 08:32:18.805] Feb 15 08:31:09.523: INFO: PersistentVolumeClaim pvc-zwk7q found but phase is Pending instead of Bound.
I0215 08:32:18.805] Feb 15 08:31:11.633: INFO: PersistentVolumeClaim pvc-zwk7q found but phase is Pending instead of Bound.
I0215 08:32:18.805] Feb 15 08:31:13.761: INFO: PersistentVolumeClaim pvc-zwk7q found but phase is Pending instead of Bound.
I0215 08:32:18.806] Feb 15 08:31:15.934: INFO: PersistentVolumeClaim pvc-zwk7q found but phase is Pending instead of Bound.
I0215 08:32:18.806] Feb 15 08:31:18.062: INFO: PersistentVolumeClaim pvc-zwk7q found and phase=Bound (24.81201032s)
I0215 08:32:18.806] [It] should fail if non-existent subpath is outside the volume [Slow]
I0215 08:32:18.806]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:261
I0215 08:32:18.821] STEP: Creating pod pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-nxhp
I0215 08:32:18.821] STEP: Checking for subpath error in container status
I0215 08:32:18.822] Feb 15 08:31:42.438: INFO: Deleting pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-nxhp" in namespace "e2e-tests-csi-volumes-997q7"
I0215 08:32:18.822] Feb 15 08:31:42.449: INFO: Wait up to 5m0s for pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-nxhp" to be fully deleted
I0215 08:32:18.822] WARNING: pod log: pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-nxhp/test-container-subpath-pd-csi-storage-gke-io-dynamicpv-nxhp: pods "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-nxhp" not found
I0215 08:32:18.823] WARNING: pod log: pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-nxhp/test-container-volume-pd-csi-storage-gke-io-dynamicpv-nxhp: pods "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-nxhp" not found
I0215 08:32:18.823] [AfterEach] [Testpattern: Dynamic PV (default fs)] subPath
I0215 08:32:18.823]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:120
... skipping 25 lines ...
I0215 08:32:18.829] [sig-storage] CSI Volumes
I0215 08:32:18.829] /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/framework.go:22
I0215 08:32:18.829]   [Driver: pd.csi.storage.gke.io][Feature: gcePD-external]
I0215 08:32:18.829]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/csi_volumes.go:129
I0215 08:32:18.829]     [Testpattern: Dynamic PV (default fs)] subPath
I0215 08:32:18.830]     /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:99
I0215 08:32:18.830]       should fail if non-existent subpath is outside the volume [Slow]
I0215 08:32:18.830]       /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:261
I0215 08:32:18.830] ------------------------------
I0215 08:32:18.830] Feb 15 08:32:18.799: INFO: Running AfterSuite actions on all nodes
I0215 08:32:18.831] 
I0215 08:32:19.100] 
I0215 08:32:19.100] [BeforeEach] [sig-storage] CSI Volumes
... skipping 1036 lines ...
I0215 08:32:36.611] Feb 15 08:30:58.569: INFO: PersistentVolumeClaim pvc-s5zpk found but phase is Pending instead of Bound.
I0215 08:32:36.612] Feb 15 08:31:00.574: INFO: PersistentVolumeClaim pvc-s5zpk found but phase is Pending instead of Bound.
I0215 08:32:36.612] Feb 15 08:31:02.579: INFO: PersistentVolumeClaim pvc-s5zpk found but phase is Pending instead of Bound.
I0215 08:32:36.612] Feb 15 08:31:04.602: INFO: PersistentVolumeClaim pvc-s5zpk found but phase is Pending instead of Bound.
I0215 08:32:36.612] Feb 15 08:31:06.623: INFO: PersistentVolumeClaim pvc-s5zpk found but phase is Pending instead of Bound.
I0215 08:32:36.612] Feb 15 08:31:08.627: INFO: PersistentVolumeClaim pvc-s5zpk found and phase=Bound (16.10157491s)
I0215 08:32:36.612] [It] should fail if subpath file is outside the volume [Slow]
I0215 08:32:36.613]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:253
I0215 08:32:36.613] STEP: Creating pod pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-kqjw
I0215 08:32:36.613] STEP: Checking for subpath error in container status
I0215 08:32:36.614] Feb 15 08:31:30.782: INFO: Deleting pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-kqjw" in namespace "e2e-tests-csi-volumes-hnnc2"
I0215 08:32:36.614] Feb 15 08:31:30.956: INFO: Wait up to 5m0s for pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-kqjw" to be fully deleted
I0215 08:32:36.614] [AfterEach] [Testpattern: Dynamic PV (default fs)] subPath
I0215 08:32:36.615]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:120
I0215 08:32:36.615] STEP: Deleting pod
I0215 08:32:36.615] Feb 15 08:31:35.072: INFO: Deleting pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-kqjw" in namespace "e2e-tests-csi-volumes-hnnc2"
... skipping 30 lines ...
I0215 08:32:36.621] [sig-storage] CSI Volumes
I0215 08:32:36.622] /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/framework.go:22
I0215 08:32:36.622]   [Driver: pd.csi.storage.gke.io][Feature: gcePD-external]
I0215 08:32:36.622]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/csi_volumes.go:129
I0215 08:32:36.622]     [Testpattern: Dynamic PV (default fs)] subPath
I0215 08:32:36.622]     /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:99
I0215 08:32:36.623]       should fail if subpath file is outside the volume [Slow]
I0215 08:32:36.623]       /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:253
I0215 08:32:36.623] ------------------------------
I0215 08:32:36.623] Feb 15 08:32:36.607: INFO: Running AfterSuite actions on all nodes
I0215 08:32:36.623] 
I0215 08:32:38.003] 
I0215 08:32:38.003] [BeforeEach] [sig-storage] CSI Volumes
... skipping 768 lines ...
I0215 08:37:02.058] Feb 15 08:36:25.447: INFO: PersistentVolume pvc-7a89b035-4fcd-11ea-b4f3-42010a800002 found and phase=Released (4m30.414373401s)
I0215 08:37:02.059] Feb 15 08:36:30.450: INFO: PersistentVolume pvc-7a89b035-4fcd-11ea-b4f3-42010a800002 found and phase=Released (4m35.418151183s)
I0215 08:37:02.059] Feb 15 08:36:35.454: INFO: PersistentVolume pvc-7a89b035-4fcd-11ea-b4f3-42010a800002 found and phase=Released (4m40.421748847s)
I0215 08:37:02.059] Feb 15 08:36:40.457: INFO: PersistentVolume pvc-7a89b035-4fcd-11ea-b4f3-42010a800002 found and phase=Released (4m45.425127509s)
I0215 08:37:02.059] Feb 15 08:36:45.461: INFO: PersistentVolume pvc-7a89b035-4fcd-11ea-b4f3-42010a800002 found and phase=Released (4m50.428352342s)
I0215 08:37:02.059] Feb 15 08:36:50.464: INFO: PersistentVolume pvc-7a89b035-4fcd-11ea-b4f3-42010a800002 found and phase=Released (4m55.431980248s)
I0215 08:37:02.060] Feb 15 08:36:55.465: INFO: Unexpected error occurred: PersistentVolume pvc-7a89b035-4fcd-11ea-b4f3-42010a800002 still exists within 5m0s
I0215 08:37:02.060] [AfterEach] [Driver: pd.csi.storage.gke.io][Feature: gcePD-external]
I0215 08:37:02.060]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/csi_volumes.go:138
I0215 08:37:02.060] [AfterEach] [sig-storage] CSI Volumes
I0215 08:37:02.060]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/framework.go:154
I0215 08:37:02.060] STEP: Collecting events from namespace "e2e-tests-csi-volumes-n58ms".
I0215 08:37:02.060] STEP: Found 16 events.
I0215 08:37:02.061] Feb 15 08:36:55.469: INFO: At 2020-02-15 08:30:53 +0000 UTC - event for pvc-m8gd9: {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
I0215 08:37:02.061] Feb 15 08:36:55.469: INFO: At 2020-02-15 08:31:08 +0000 UTC - event for pvc-m8gd9: {pd.csi.storage.gke.io_csi-gce-pd-controller-0_7903315d-4fcd-11ea-9ee2-ca4462bbc7a7 } Provisioning: External provisioner is provisioning volume for claim "e2e-tests-csi-volumes-n58ms/pvc-m8gd9"
I0215 08:37:02.061] Feb 15 08:36:55.469: INFO: At 2020-02-15 08:31:13 +0000 UTC - event for pvc-m8gd9: {pd.csi.storage.gke.io_csi-gce-pd-controller-0_7903315d-4fcd-11ea-9ee2-ca4462bbc7a7 } ProvisioningSucceeded: Successfully provisioned volume pvc-7a89b035-4fcd-11ea-b4f3-42010a800002
I0215 08:37:02.062] Feb 15 08:36:55.469: INFO: At 2020-02-15 08:31:16 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-tdrw: {default-scheduler } Scheduled: Successfully assigned e2e-tests-csi-volumes-n58ms/pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-tdrw to e2e-test-prow-minion-group-zth4
I0215 08:37:02.062] Feb 15 08:36:55.469: INFO: At 2020-02-15 08:31:31 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-tdrw: {attachdetach-controller } FailedAttachVolume: AttachVolume.Attach failed for volume "pvc-7a89b035-4fcd-11ea-b4f3-42010a800002" : attachment timeout for volume projects/k8s-jkns-gci-gce-kubenet/zones/us-central1-b/disks/pvc-7a89b035-4fcd-11ea-b4f3-42010a800002
I0215 08:37:02.062] Feb 15 08:36:55.469: INFO: At 2020-02-15 08:31:32 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-tdrw: {attachdetach-controller } FailedAttachVolume: AttachVolume.Attach failed for volume "pvc-7a89b035-4fcd-11ea-b4f3-42010a800002" : rpc error: code = DeadlineExceeded desc = context deadline exceeded
I0215 08:37:02.063] Feb 15 08:36:55.469: INFO: At 2020-02-15 08:31:47 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-tdrw: {attachdetach-controller } SuccessfulAttachVolume: AttachVolume.Attach succeeded for volume "pvc-7a89b035-4fcd-11ea-b4f3-42010a800002" 
I0215 08:37:02.063] Feb 15 08:36:55.469: INFO: At 2020-02-15 08:31:50 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-tdrw: {kubelet e2e-test-prow-minion-group-zth4} Pulled: Container image "docker.io/library/busybox:1.29" already present on machine
I0215 08:37:02.063] Feb 15 08:36:55.469: INFO: At 2020-02-15 08:31:50 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-tdrw: {kubelet e2e-test-prow-minion-group-zth4} Created: Created container
I0215 08:37:02.064] Feb 15 08:36:55.469: INFO: At 2020-02-15 08:31:50 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-tdrw: {kubelet e2e-test-prow-minion-group-zth4} Started: Started container
I0215 08:37:02.064] Feb 15 08:36:55.469: INFO: At 2020-02-15 08:31:50 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-tdrw: {kubelet e2e-test-prow-minion-group-zth4} Started: Started container
I0215 08:37:02.064] Feb 15 08:36:55.469: INFO: At 2020-02-15 08:31:50 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-tdrw: {kubelet e2e-test-prow-minion-group-zth4} Pulled: Container image "gcr.io/kubernetes-e2e-test-images/mounttest:1.0" already present on machine
... skipping 35 lines ...
I0215 08:37:02.081] Feb 15 08:36:55.483: INFO: metadata-proxy-v0.1-t55dx                     e2e-test-prow-minion-group-jkrv  Running         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:29:40 +0000 UTC  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:20 +0000 UTC  } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:20 +0000 UTC  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:29:40 +0000 UTC  }]
I0215 08:37:02.081] Feb 15 08:36:55.483: INFO: metadata-proxy-v0.1-vhrwd                     e2e-test-prow-minion-group-bb2l  Running         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:29:41 +0000 UTC  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:19 +0000 UTC  } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:19 +0000 UTC  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:29:41 +0000 UTC  }]
I0215 08:37:02.082] Feb 15 08:36:55.483: INFO: metrics-server-v0.3.1-58d65f8d6-f78g2         e2e-test-prow-minion-group-jkrv  Running         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:21 +0000 UTC  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:44 +0000 UTC  } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:44 +0000 UTC  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-02-15 08:30:00 +0000 UTC  }]
I0215 08:37:02.082] Feb 15 08:36:55.483: INFO: 
I0215 08:37:02.082] Feb 15 08:36:55.487: INFO: 
I0215 08:37:02.082] Logging node info for node e2e-test-prow-master
I0215 08:37:02.086] Feb 15 08:36:55.491: 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:4de55939-4fcd-11ea-b4f3-42010a800002,ResourceVersion:2908,Generation:0,CreationTimestamp:2020-02-15 08:29:38 +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-jkns-gci-gce-kubenet/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-15 08:29:44 +0000 UTC 2020-02-15 08:29:44 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2020-02-15 08:36:51 +0000 UTC 2020-02-15 08:29:38 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2020-02-15 08:36:51 +0000 UTC 2020-02-15 08:29:38 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2020-02-15 08:36:51 +0000 UTC 2020-02-15 08:29:38 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2020-02-15 08:36:51 +0000 UTC 2020-02-15 08:29:38 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.128.0.2} {ExternalIP 35.232.159.219} {InternalDNS e2e-test-prow-master.c.k8s-jkns-gci-gce-kubenet.internal} {Hostname e2e-test-prow-master.c.k8s-jkns-gci-gce-kubenet.internal}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:08a44a115e84ab374a5072bee2a0fbeb,SystemUUID:08A44A11-5E84-AB37-4A50-72BEE2A0FBEB,BootID:5f0c9b8c-3b46-4621-8d02-9b50ea2110d7,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:,},},}
I0215 08:37:02.086] Feb 15 08:36:55.491: INFO: 
I0215 08:37:02.086] Logging kubelet events for node e2e-test-prow-master
I0215 08:37:02.086] Feb 15 08:36:55.501: INFO: 
I0215 08:37:02.086] Logging pods the kubelet thinks is on node e2e-test-prow-master
I0215 08:37:02.087] Feb 15 08:36:55.521: INFO: kube-controller-manager-e2e-test-prow-master started at <nil> (0+0 container statuses recorded)
I0215 08:37:02.087] Feb 15 08:36:55.521: INFO: l7-lb-controller-v1.2.3-e2e-test-prow-master started at <nil> (0+0 container statuses recorded)
... skipping 17 lines ...
I0215 08:37:02.090] Feb 15 08:36:55.551: INFO: {Operation:create Method:pod_worker_latency_microseconds Quantile:0.99 Latency:20.357881s}
I0215 08:37:02.090] Feb 15 08:36:55.551: INFO: {Operation:create Method:pod_worker_latency_microseconds Quantile:0.5 Latency:20.357881s}
I0215 08:37:02.090] Feb 15 08:36:55.551: INFO: {Operation:pull_image Method:docker_operations_latency_microseconds Quantile:0.99 Latency:18.681061s}
I0215 08:37:02.091] Feb 15 08:36:55.551: INFO: {Operation:pull_image Method:docker_operations_latency_microseconds Quantile:0.9 Latency:18.621662s}
I0215 08:37:02.091] Feb 15 08:36:55.551: INFO: 
I0215 08:37:02.091] Logging node info for node e2e-test-prow-minion-group-bb2l
I0215 08:37:02.096] Feb 15 08:36:55.555: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:e2e-test-prow-minion-group-bb2l,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/e2e-test-prow-minion-group-bb2l,UID:4fae3c20-4fcd-11ea-b4f3-42010a800002,ResourceVersion:2914,Generation:0,CreationTimestamp:2020-02-15 08:29:41 +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-bb2l,},Annotations:map[string]string{csi.volume.kubernetes.io/nodeid: {"pd.csi.storage.gke.io":"projects/k8s-jkns-gci-gce-kubenet/zones/us-central1-b/instances/e2e-test-prow-minion-group-bb2l"},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-jkns-gci-gce-kubenet/us-central1-b/e2e-test-prow-minion-group-bb2l,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:[{CorruptDockerOverlay2 False 2020-02-15 08:36:33 +0000 UTC 2020-02-15 08:33:28 +0000 UTC CorruptDockerOverlay2 docker overlay2 is functioning properly} {KernelDeadlock False 2020-02-15 08:36:33 +0000 UTC 2020-02-15 08:28:26 +0000 UTC KernelHasNoDeadlock kernel has no deadlock} {ReadonlyFilesystem False 2020-02-15 08:36:33 +0000 UTC 2020-02-15 08:28:26 +0000 UTC FilesystemIsNotReadOnly Filesystem is not read-only} {FrequentUnregisterNetDevice False 2020-02-15 08:36:33 +0000 UTC 2020-02-15 08:33:28 +0000 UTC UnregisterNetDevice node is functioning properly} {FrequentKubeletRestart False 2020-02-15 08:36:33 +0000 UTC 2020-02-15 08:33:28 +0000 UTC FrequentKubeletRestart kubelet is functioning properly} {FrequentDockerRestart False 2020-02-15 08:36:33 +0000 UTC 2020-02-15 08:33:29 +0000 UTC FrequentDockerRestart docker is functioning properly} {FrequentContainerdRestart False 2020-02-15 08:36:33 +0000 UTC 2020-02-15 08:33:31 +0000 UTC FrequentContainerdRestart containerd is functioning properly} {NetworkUnavailable False 2020-02-15 08:29:53 +0000 UTC 2020-02-15 08:29:53 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2020-02-15 08:36:53 +0000 UTC 2020-02-15 08:29:41 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2020-02-15 08:36:53 +0000 UTC 2020-02-15 08:29:41 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2020-02-15 08:36:53 +0000 UTC 2020-02-15 08:29:41 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2020-02-15 08:36:53 +0000 UTC 2020-02-15 08:29:41 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.128.0.4} {ExternalIP 34.66.182.187} {InternalDNS e2e-test-prow-minion-group-bb2l.c.k8s-jkns-gci-gce-kubenet.internal} {Hostname e2e-test-prow-minion-group-bb2l.c.k8s-jkns-gci-gce-kubenet.internal}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:181b5dd89bf228aba70c12c8853fc34a,SystemUUID:181B5DD8-9BF2-28AB-A70C-12C8853FC34A,BootID:3835ae16-4926-4aa6-8f5b-53cf46538559,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/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/cluster-proportional-autoscaler-amd64@sha256:4fd37c5b29a38b02c408c56254bd1a3a76f3e236610bc7a8382500bbf9ecfc76 k8s.gcr.io/cluster-proportional-autoscaler-amd64:1.3.0] 45844959} {[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} {[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:,},},}
I0215 08:37:02.096] Feb 15 08:36:55.555: INFO: 
I0215 08:37:02.096] Logging kubelet events for node e2e-test-prow-minion-group-bb2l
I0215 08:37:02.096] Feb 15 08:36:55.571: INFO: 
I0215 08:37:02.097] Logging pods the kubelet thinks is on node e2e-test-prow-minion-group-bb2l
I0215 08:37:02.097] Feb 15 08:36:55.585: INFO: kube-proxy-e2e-test-prow-minion-group-bb2l started at <nil> (0+0 container statuses recorded)
I0215 08:37:02.097] Feb 15 08:36:55.585: INFO: fluentd-gcp-v3.2.0-8n6mq started at 2020-02-15 08:30:21 +0000 UTC (0+2 container statuses recorded)
... skipping 24 lines ...
I0215 08:37:02.101] Feb 15 08:36:55.636: INFO: {Operation:create Method:pod_worker_latency_microseconds Quantile:0.5 Latency:11.862008s}
I0215 08:37:02.101] Feb 15 08:36:55.636: INFO: {Operation:create Method:pod_worker_latency_microseconds Quantile:0.99 Latency:11.862008s}
I0215 08:37:02.101] Feb 15 08:36:55.636: INFO: {Operation:pull_image Method:docker_operations_latency_microseconds Quantile:0.99 Latency:11.104494s}
I0215 08:37:02.101] Feb 15 08:36:55.636: INFO: {Operation:pull_image Method:docker_operations_latency_microseconds Quantile:0.9 Latency:10.792244s}
I0215 08:37:02.101] Feb 15 08:36:55.636: INFO: 
I0215 08:37:02.102] Logging node info for node e2e-test-prow-minion-group-jkrv
I0215 08:37:02.107] Feb 15 08:36:55.639: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:e2e-test-prow-minion-group-jkrv,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/e2e-test-prow-minion-group-jkrv,UID:4f2aee64-4fcd-11ea-b4f3-42010a800002,ResourceVersion:2910,Generation:0,CreationTimestamp:2020-02-15 08:29:40 +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-jkrv,},Annotations:map[string]string{csi.volume.kubernetes.io/nodeid: {"pd.csi.storage.gke.io":"projects/k8s-jkns-gci-gce-kubenet/zones/us-central1-b/instances/e2e-test-prow-minion-group-jkrv"},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-jkns-gci-gce-kubenet/us-central1-b/e2e-test-prow-minion-group-jkrv,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:[{FrequentContainerdRestart False 2020-02-15 08:36:32 +0000 UTC 2020-02-15 08:33:30 +0000 UTC FrequentContainerdRestart containerd is functioning properly} {CorruptDockerOverlay2 False 2020-02-15 08:36:32 +0000 UTC 2020-02-15 08:33:28 +0000 UTC CorruptDockerOverlay2 docker overlay2 is functioning properly} {FrequentUnregisterNetDevice False 2020-02-15 08:36:32 +0000 UTC 2020-02-15 08:33:27 +0000 UTC UnregisterNetDevice node is functioning properly} {KernelDeadlock False 2020-02-15 08:36:32 +0000 UTC 2020-02-15 08:28:26 +0000 UTC KernelHasNoDeadlock kernel has no deadlock} {ReadonlyFilesystem False 2020-02-15 08:36:32 +0000 UTC 2020-02-15 08:28:26 +0000 UTC FilesystemIsNotReadOnly Filesystem is not read-only} {FrequentKubeletRestart False 2020-02-15 08:36:32 +0000 UTC 2020-02-15 08:33:27 +0000 UTC FrequentKubeletRestart kubelet is functioning properly} {FrequentDockerRestart False 2020-02-15 08:36:32 +0000 UTC 2020-02-15 08:33:29 +0000 UTC FrequentDockerRestart docker is functioning properly} {NetworkUnavailable False 2020-02-15 08:29:56 +0000 UTC 2020-02-15 08:29:56 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2020-02-15 08:36:52 +0000 UTC 2020-02-15 08:29:40 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2020-02-15 08:36:52 +0000 UTC 2020-02-15 08:29:40 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2020-02-15 08:36:52 +0000 UTC 2020-02-15 08:29:40 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2020-02-15 08:36:52 +0000 UTC 2020-02-15 08:29:40 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.128.0.3} {ExternalIP 34.70.100.247} {InternalDNS e2e-test-prow-minion-group-jkrv.c.k8s-jkns-gci-gce-kubenet.internal} {Hostname e2e-test-prow-minion-group-jkrv.c.k8s-jkns-gci-gce-kubenet.internal}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:6e819dd3b1be74d382b1fa712571a51f,SystemUUID:6E819DD3-B1BE-74D3-82B1-FA712571A51F,BootID:9fde1acf-c1a7-4694-8443-b8dc1c838a1e,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/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/metrics-server-amd64@sha256:78938f933822856f443e6827fe5b37d6cc2f74ae888ac8b33d06fdbe5f8c658b k8s.gcr.io/metrics-server-amd64:v0.3.1] 40767713} {[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:,},},}
I0215 08:37:02.107] Feb 15 08:36:55.640: INFO: 
I0215 08:37:02.107] Logging kubelet events for node e2e-test-prow-minion-group-jkrv
I0215 08:37:02.107] Feb 15 08:36:55.647: INFO: 
I0215 08:37:02.108] Logging pods the kubelet thinks is on node e2e-test-prow-minion-group-jkrv
I0215 08:37:02.108] Feb 15 08:36:55.660: INFO: fluentd-gcp-scaler-68b55c6dc5-2krgg started at 2020-02-15 08:29:40 +0000 UTC (0+1 container statuses recorded)
I0215 08:37:02.108] Feb 15 08:36:55.660: INFO: 	Container fluentd-gcp-scaler ready: true, restart count 0
... skipping 17 lines ...
I0215 08:37:02.112] Feb 15 08:36:55.689: INFO: 
I0215 08:37:02.112] Latency metrics for node e2e-test-prow-minion-group-jkrv
I0215 08:37:02.112] Feb 15 08:36:55.689: INFO: {Operation: Method:pod_start_latency_microseconds Quantile:0.99 Latency:40.212921s}
I0215 08:37:02.112] Feb 15 08:36:55.689: INFO: {Operation: Method:pod_start_latency_microseconds Quantile:0.9 Latency:38.722985s}
I0215 08:37:02.112] Feb 15 08:36:55.689: INFO: 
I0215 08:37:02.112] Logging node info for node e2e-test-prow-minion-group-zth4
I0215 08:37:02.118] Feb 15 08:36:55.692: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:e2e-test-prow-minion-group-zth4,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/e2e-test-prow-minion-group-zth4,UID:4e962be8-4fcd-11ea-b4f3-42010a800002,ResourceVersion:2909,Generation:0,CreationTimestamp:2020-02-15 08:29:39 +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-zth4,},Annotations:map[string]string{csi.volume.kubernetes.io/nodeid: {"pd.csi.storage.gke.io":"projects/k8s-jkns-gci-gce-kubenet/zones/us-central1-b/instances/e2e-test-prow-minion-group-zth4"},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-jkns-gci-gce-kubenet/us-central1-b/e2e-test-prow-minion-group-zth4,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:[{FrequentUnregisterNetDevice False 2020-02-15 08:36:36 +0000 UTC 2020-02-15 08:33:30 +0000 UTC UnregisterNetDevice node is functioning properly} {FrequentKubeletRestart False 2020-02-15 08:36:36 +0000 UTC 2020-02-15 08:33:30 +0000 UTC FrequentKubeletRestart kubelet is functioning properly} {FrequentDockerRestart False 2020-02-15 08:36:36 +0000 UTC 2020-02-15 08:33:31 +0000 UTC FrequentDockerRestart docker is functioning properly} {FrequentContainerdRestart False 2020-02-15 08:36:36 +0000 UTC 2020-02-15 08:33:33 +0000 UTC FrequentContainerdRestart containerd is functioning properly} {CorruptDockerOverlay2 False 2020-02-15 08:36:36 +0000 UTC 2020-02-15 08:33:31 +0000 UTC CorruptDockerOverlay2 docker overlay2 is functioning properly} {KernelDeadlock False 2020-02-15 08:36:36 +0000 UTC 2020-02-15 08:28:29 +0000 UTC KernelHasNoDeadlock kernel has no deadlock} {ReadonlyFilesystem False 2020-02-15 08:36:36 +0000 UTC 2020-02-15 08:28:29 +0000 UTC FilesystemIsNotReadOnly Filesystem is not read-only} {NetworkUnavailable False 2020-02-15 08:29:56 +0000 UTC 2020-02-15 08:29:56 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2020-02-15 08:36:51 +0000 UTC 2020-02-15 08:29:39 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2020-02-15 08:36:51 +0000 UTC 2020-02-15 08:29:39 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2020-02-15 08:36:51 +0000 UTC 2020-02-15 08:29:39 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2020-02-15 08:36:51 +0000 UTC 2020-02-15 08:29:39 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.128.0.5} {ExternalIP 34.68.175.138} {InternalDNS e2e-test-prow-minion-group-zth4.c.k8s-jkns-gci-gce-kubenet.internal} {Hostname e2e-test-prow-minion-group-zth4.c.k8s-jkns-gci-gce-kubenet.internal}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:bfaebec944d9de75532336b3320fa5cf,SystemUUID:BFAEBEC9-44D9-DE75-5323-36B3320FA5CF,BootID:bde25877-a60d-451c-915e-80905b2852b6,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:,},},}
I0215 08:37:02.118] Feb 15 08:36:55.693: INFO: 
I0215 08:37:02.118] Logging kubelet events for node e2e-test-prow-minion-group-zth4
I0215 08:37:02.118] Feb 15 08:36:55.701: INFO: 
I0215 08:37:02.118] Logging pods the kubelet thinks is on node e2e-test-prow-minion-group-zth4
I0215 08:37:02.119] Feb 15 08:36:55.713: INFO: fluentd-gcp-v3.2.0-b9khq started at 2020-02-15 08:30:21 +0000 UTC (0+2 container statuses recorded)
I0215 08:37:02.119] Feb 15 08:36:55.713: INFO: 	Container fluentd-gcp ready: true, restart count 0
... skipping 36 lines ...
I0215 08:37:02.124]     [Testpattern: Dynamic PV (default fs)] subPath
I0215 08:37:02.124]     /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:99
I0215 08:37:02.124]       should support readOnly file specified in the volumeMount [AfterEach]
I0215 08:37:02.124]       /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:337
I0215 08:37:02.124] 
I0215 08:37:02.125]       Persistent Volume pvc-7a89b035-4fcd-11ea-b4f3-42010a800002 not deleted by dynamic provisioner
I0215 08:37:02.125]       Expected error:
I0215 08:37:02.125]           <*errors.errorString | 0xc000a07230>: {
I0215 08:37:02.125]               s: "PersistentVolume pvc-7a89b035-4fcd-11ea-b4f3-42010a800002 still exists within 5m0s",
I0215 08:37:02.125]           }
I0215 08:37:02.125]           PersistentVolume pvc-7a89b035-4fcd-11ea-b4f3-42010a800002 still exists within 5m0s
I0215 08:37:02.125]       not to have occurred
I0215 08:37:02.125] 
... skipping 11 lines ...
I0215 08:37:09.567] [BeforeEach] [sig-storage] CSI Volumes
I0215 08:37:09.567]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/csi_volumes.go:87
I0215 08:37:09.567] [BeforeEach] [Driver: pd.csi.storage.gke.io][Feature: gcePD-external]
I0215 08:37:09.568]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/csi_volumes.go:132
I0215 08:37:09.568] [BeforeEach] [Testpattern: Dynamic PV (block volmode)] volumeMode
I0215 08:37:09.568]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/volumemode.go:119
I0215 08:37:09.568] [It] should fail in binding dynamic provisioned PV to PVC
I0215 08:37:09.568]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/volumemode.go:315
I0215 08:37:09.568] STEP: Creating sc
I0215 08:37:09.568] STEP: Creating pv and pvc
I0215 08:37:09.569] Feb 15 08:31:54.444: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-zgcfj] to have phase Bound
I0215 08:37:09.569] Feb 15 08:31:54.485: INFO: PersistentVolumeClaim pvc-zgcfj found but phase is Pending instead of Bound.
I0215 08:37:09.569] Feb 15 08:31:56.491: INFO: PersistentVolumeClaim pvc-zgcfj found but phase is Pending instead of Bound.
... skipping 167 lines ...
I0215 08:37:09.602] [sig-storage] CSI Volumes
I0215 08:37:09.602] /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/framework.go:22
I0215 08:37:09.602]   [Driver: pd.csi.storage.gke.io][Feature: gcePD-external]
I0215 08:37:09.602]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/csi_volumes.go:129
I0215 08:37:09.602]     [Testpattern: Dynamic PV (block volmode)] volumeMode
I0215 08:37:09.603]     /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/volumemode.go:109
I0215 08:37:09.603]       should fail in binding dynamic provisioned PV to PVC
I0215 08:37:09.603]       /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/volumemode.go:315
I0215 08:37:09.603] ------------------------------
I0215 08:37:09.603] Feb 15 08:37:09.566: INFO: Running AfterSuite actions on all nodes
I0215 08:37:09.603] 
I0215 08:38:26.084] 
I0215 08:38:26.085] Feb 15 08:32:38.003: INFO: Running AfterSuite actions on all nodes
... skipping 14 lines ...
I0215 08:38:26.087] 
I0215 08:38:26.088] Specify --start=43954 in the next get-serial-port-output invocation to get only the new output starting from here.
I0215 08:38:26.088] scp: /var/log/cluster-autoscaler.log*: No such file or directory
I0215 08:38:26.088] scp: /var/log/fluentd.log*: No such file or directory
I0215 08:38:26.088] scp: /var/log/kubelet.cov*: No such file or directory
I0215 08:38:26.088] scp: /var/log/startupscript.log*: No such file or directory
I0215 08:38:26.088] ERROR: (gcloud.compute.scp) [/usr/bin/scp] exited with return code [1].
I0215 08:38:26.088] Dumping logs from nodes locally to '/workspace/_artifacts'
I0215 08:38:26.089] Detecting nodes in the cluster
I0215 08:38:26.089] Changing logfiles to be world-readable for download
I0215 08:38:26.089] Changing logfiles to be world-readable for download
I0215 08:38:26.089] Changing logfiles to be world-readable for download
I0215 08:38:26.089] Copying 'kube-proxy.log fluentd.log node-problem-detector.log kubelet.cov startupscript.log' from e2e-test-prow-minion-group-zth4
... skipping 6 lines ...
I0215 08:38:26.091] 
I0215 08:38:26.091] Specify --start=57078 in the next get-serial-port-output invocation to get only the new output starting from here.
I0215 08:38:26.091] scp: /var/log/fluentd.log*: No such file or directory
I0215 08:38:26.091] scp: /var/log/node-problem-detector.log*: No such file or directory
I0215 08:38:26.091] scp: /var/log/kubelet.cov*: No such file or directory
I0215 08:38:26.092] scp: /var/log/startupscript.log*: No such file or directory
I0215 08:38:26.092] ERROR: (gcloud.compute.scp) [/usr/bin/scp] exited with return code [1].
I0215 08:38:26.092] scp: /var/log/fluentd.log*: No such file or directory
I0215 08:38:26.092] scp: /var/log/node-problem-detector.log*: No such file or directory
I0215 08:38:26.092] scp: /var/log/kubelet.cov*: No such file or directory
I0215 08:38:26.092] scp: /var/log/startupscript.log*: No such file or directory
I0215 08:38:26.093] ERROR: (gcloud.compute.scp) [/usr/bin/scp] exited with return code [1].
I0215 08:38:26.093] scp: /var/log/fluentd.log*: No such file or directory
I0215 08:38:26.093] scp: /var/log/node-problem-detector.log*: No such file or directory
I0215 08:38:26.093] scp: /var/log/kubelet.cov*: No such file or directory
I0215 08:38:26.093] scp: /var/log/startupscript.log*: No such file or directory
I0215 08:38:26.093] ERROR: (gcloud.compute.scp) [/usr/bin/scp] exited with return code [1].
I0215 08:38:26.093] 
I0215 08:38:26.094] 
I0215 08:38:26.094] 
I0215 08:38:26.094] Summarizing 1 Failure:
I0215 08:38:26.094] 
I0215 08:38:26.094] [Fail] [sig-storage] CSI Volumes [Driver: pd.csi.storage.gke.io][Feature: gcePD-external] [Testpattern: Dynamic PV (default fs)] subPath [AfterEach] should support readOnly file specified in the volumeMount 
I0215 08:38:26.094] /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/base.go:213
I0215 08:38:26.095] 
I0215 08:38:26.095] Ran 27 of 2161 Specs in 473.221 seconds
I0215 08:38:26.102] FAIL! -- 26 Passed | 1 Failed | 0 Pending | 2134 Skipped 
I0215 08:38:26.102] 
I0215 08:38:26.102] Ginkgo ran 1 suite in 7m58.99229799s
I0215 08:38:26.102] Test Suite Failed
I0215 08:38:26.118] Deleting driver
I0215 08:38:26.120] PKGDIR is /go/src/sigs.k8s.io/gcp-compute-persistent-disk-csi-driver
W0215 08:38:26.220] !!! Error in ./hack/ginkgo-e2e.sh:143
W0215 08:38:26.221]   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
W0215 08:38:26.221] Call stack:
W0215 08:38:26.222]   1: ./hack/ginkgo-e2e.sh:143 main(...)
W0215 08:38:26.222] Exiting with status 1
W0215 08:38:26.222] 2020/02/15 08:38:26 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 8m0.198636706s
W0215 08:38:26.222] 2020/02/15 08:38:26 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]
W0215 08:38:26.314] I0215 08:38:26.313803   67104 loader.go:359] Config loaded from file /root/.kube/config
W0215 08:38:26.315] I0215 08:38:26.314867   67104 loader.go:359] Config loaded from file /root/.kube/config
W0215 08:38:26.316] I0215 08:38:26.316330   67104 loader.go:359] Config loaded from file /root/.kube/config
W0215 08:38:26.316] I0215 08:38:26.316835   67104 decoder.go:224] decoding stream as YAML
W0215 08:38:26.317] I0215 08:38:26.317787   67104 loader.go:359] Config loaded from file /root/.kube/config
W0215 08:38:26.324] I0215 08:38:26.324231   67104 loader.go:359] Config loaded from file /root/.kube/config
... skipping 267 lines ...
W0215 08:38:43.943] NODE_NAMES=e2e-test-prow-minion-group-bb2l e2e-test-prow-minion-group-jkrv e2e-test-prow-minion-group-zth4
I0215 08:38:44.043] Bringing down cluster
W0215 08:38:46.477] Deleting Managed Instance Group...
W0215 08:41:19.067] .................................Deleted [https://www.googleapis.com/compute/v1/projects/k8s-jkns-gci-gce-kubenet/zones/us-central1-b/instanceGroupManagers/e2e-test-prow-minion-group].
W0215 08:41:19.068] done.
W0215 08:41:23.289] Deleted [https://www.googleapis.com/compute/v1/projects/k8s-jkns-gci-gce-kubenet/global/instanceTemplates/e2e-test-prow-minion-template].
I0215 08:41:27.707] {"message":"Internal Server Error"}Removing etcd replica, name: e2e-test-prow-master, port: 2379, result: 0
I0215 08:41:28.924] {"message":"Internal Server Error"}Removing etcd replica, name: e2e-test-prow-master, port: 4002, result: 0
W0215 08:41:33.895] Updated [https://www.googleapis.com/compute/v1/projects/k8s-jkns-gci-gce-kubenet/zones/us-central1-b/instances/e2e-test-prow-master].
W0215 08:43:46.189] Deleted [https://www.googleapis.com/compute/v1/projects/k8s-jkns-gci-gce-kubenet/zones/us-central1-b/instances/e2e-test-prow-master].
W0215 08:43:55.302] Deleted [https://www.googleapis.com/compute/v1/projects/k8s-jkns-gci-gce-kubenet/global/firewalls/e2e-test-prow-master-https].
W0215 08:43:57.367] Deleted [https://www.googleapis.com/compute/v1/projects/k8s-jkns-gci-gce-kubenet/global/firewalls/e2e-test-prow-master-etcd].
W0215 08:44:02.302] Deleted [https://www.googleapis.com/compute/v1/projects/k8s-jkns-gci-gce-kubenet/global/firewalls/e2e-test-prow-minion-all].
W0215 08:44:08.162] Deleted [https://www.googleapis.com/compute/v1/projects/k8s-jkns-gci-gce-kubenet/regions/us-central1/addresses/e2e-test-prow-master-ip].
... skipping 8 lines ...
I0215 08:45:21.692] Property "clusters.k8s-jkns-gci-gce-kubenet_e2e-test-prow" unset.
I0215 08:45:21.845] Property "users.k8s-jkns-gci-gce-kubenet_e2e-test-prow" unset.
I0215 08:45:21.999] Property "users.k8s-jkns-gci-gce-kubenet_e2e-test-prow-basic-auth" unset.
I0215 08:45:22.141] Property "contexts.k8s-jkns-gci-gce-kubenet_e2e-test-prow" unset.
I0215 08:45:22.147] Cleared config for k8s-jkns-gci-gce-kubenet_e2e-test-prow from /root/.kube/config
I0215 08:45:22.148] Done
W0215 08:45:22.796] F0215 08:45:22.795704    1169 main.go:68] Failed to run integration test: failed to run tests: failed to run tests on e2e cluster: exit status 1
W0215 08:45:22.801] Traceback (most recent call last):
W0215 08:45:22.802]   File "/workspace/./test-infra/jenkins/../scenarios/execute.py", line 50, in <module>
W0215 08:45:22.802]     main(ARGS.env, ARGS.cmd + ARGS.args)
W0215 08:45:22.802]   File "/workspace/./test-infra/jenkins/../scenarios/execute.py", line 41, in main
W0215 08:45:22.802]     check(*cmd)
W0215 08:45:22.803]   File "/workspace/./test-infra/jenkins/../scenarios/execute.py", line 30, in check
W0215 08:45:22.803]     subprocess.check_call(cmd)
W0215 08:45:22.803]   File "/usr/lib/python2.7/subprocess.py", line 190, in check_call
W0215 08:45:22.803]     raise CalledProcessError(retcode, cmd)
W0215 08:45:22.803] subprocess.CalledProcessError: Command '('test/run-k8s-integration.sh',)' returned non-zero exit status 255
E0215 08:45:22.810] Command failed
I0215 08:45:22.810] process 429 exited with code 1 after 34.8m
E0215 08:45:22.810] FAIL: ci-gcp-compute-persistent-disk-csi-driver-release-0-4-k8s-1-13-5-integration
I0215 08:45:22.811] Call:  gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json
W0215 08:45:23.324] Activated service account credentials for: [pr-kubekins@kubernetes-jenkins-pull.iam.gserviceaccount.com]
I0215 08:45:23.383] process 68060 exited with code 0 after 0.0m
I0215 08:45:23.384] Call:  gcloud config get-value account
I0215 08:45:23.805] process 68073 exited with code 0 after 0.0m
I0215 08:45:23.805] Will upload results to gs://kubernetes-jenkins/logs using pr-kubekins@kubernetes-jenkins-pull.iam.gserviceaccount.com
I0215 08:45:23.805] Upload result and artifacts...
I0215 08:45:23.806] 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/1228592143979778048
I0215 08:45:23.806] Call:  gsutil ls gs://kubernetes-jenkins/logs/ci-gcp-compute-persistent-disk-csi-driver-release-0-4-k8s-1-13-5-integration/1228592143979778048/artifacts
W0215 08:45:24.740] CommandException: One or more URLs matched no objects.
E0215 08:45:24.870] Command failed
I0215 08:45:24.871] process 68086 exited with code 1 after 0.0m
W0215 08:45:24.871] Remote dir gs://kubernetes-jenkins/logs/ci-gcp-compute-persistent-disk-csi-driver-release-0-4-k8s-1-13-5-integration/1228592143979778048/artifacts not exist yet
I0215 08:45:24.871] 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/1228592143979778048/artifacts
I0215 08:45:28.828] process 68231 exited with code 0 after 0.1m
W0215 08:45:28.829] metadata path /workspace/_artifacts/metadata.json does not exist
W0215 08:45:28.829] metadata not found or invalid, init with empty metadata
... skipping 15 lines ...