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 03:52
Elapsed51m3s
Revision
Buildergke-prow-default-pool-cf4891d4-wlz7
links{u'resultstore': {u'url': u'https://source.cloud.google.com/results/invocations/99ffb430-c476-46b5-804c-07802b4635a0/targets/test'}}
podd7e7f532-4d4a-11ea-8c6e-1aa579f21cc7
resultstorehttps://source.cloud.google.com/results/invocations/99ffb430-c476-46b5-804c-07802b4635a0/targets/test
infra-commitd7c4c0243
podd7e7f532-4d4a-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 support file as subpath 1m41s

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\sfile\sas\ssubpath$'
/go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:238
Expected error:
    <*errors.errorString | 0xc000fbf040>: {
        s: "expected pod \"pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k\" success: pod \"pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k\" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2020-02-12 04:29:42 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2020-02-12 04:29:09 +0000 UTC Reason:ContainersNotReady Message:containers with unready status: [test-container-subpath-pd-csi-storage-gke-io-dynamicpv-bb6k test-container-volume-pd-csi-storage-gke-io-dynamicpv-bb6k]} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2020-02-12 04:29:09 +0000 UTC Reason:ContainersNotReady Message:containers with unready status: [test-container-subpath-pd-csi-storage-gke-io-dynamicpv-bb6k test-container-volume-pd-csi-storage-gke-io-dynamicpv-bb6k]} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2020-02-12 04:29:09 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.128.0.4 PodIP:10.64.3.12 StartTime:2020-02-12 04:29:09 +0000 UTC InitContainerStatuses:[{Name:init-volume-pd-csi-storage-gke-io-dynamicpv-bb6k State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:0,Signal:0,Reason:Completed,Message:,StartedAt:2020-02-12 04:29:42 +0000 UTC,FinishedAt:2020-02-12 04:29:42 +0000 UTC,ContainerID:docker://ccc410e8a7e1de52908b2d01f8872519d92f75294877f4181fb57dbca4685875,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:true RestartCount:0 Image:busybox:1.29 ImageID:docker-pullable://busybox@sha256:e004c2cc521c95383aebb1fb5893719aa7a8eae2e7a71f316a4410784edb00a9 ContainerID:docker://ccc410e8a7e1de52908b2d01f8872519d92f75294877f4181fb57dbca4685875}] ContainerStatuses:[{Name:test-container-subpath-pd-csi-storage-gke-io-dynamicpv-bb6k State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:0,Signal:0,Reason:Completed,Message:,StartedAt:2020-02-12 04:29:43 +0000 UTC,FinishedAt:2020-02-12 04:30:03 +0000 UTC,ContainerID:docker://8fe57a6406ba7417449331d25b8c17548a0b22c0d428a46a80b2f729d631d655,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:gcr.io/kubernetes-e2e-test-images/mounttest:1.0 ImageID:docker-pullable://gcr.io/kubernetes-e2e-test-images/mounttest@sha256:c0bd6f0755f42af09a68c9a47fb993136588a76b3200ec305796b60d629d85d2 ContainerID:docker://8fe57a6406ba7417449331d25b8c17548a0b22c0d428a46a80b2f729d631d655} {Name:test-container-volume-pd-csi-storage-gke-io-dynamicpv-bb6k State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:128,Signal:0,Reason:ContainerCannotRun,Message:linux runtime spec devices: lstat /dev/sdg: no such file or directory,StartedAt:2020-02-12 04:29:43 +0000 UTC,FinishedAt:2020-02-12 04:29:43 +0000 UTC,ContainerID:docker://defadda080d99a08ace51b46fc986609bc69c2a6758bac5e920e0c4ed04beb02,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:gcr.io/kubernetes-e2e-test-images/mounttest:1.0 ImageID:docker-pullable://gcr.io/kubernetes-e2e-test-images/mounttest@sha256:c0bd6f0755f42af09a68c9a47fb993136588a76b3200ec305796b60d629d85d2 ContainerID:docker://defadda080d99a08ace51b46fc986609bc69c2a6758bac5e920e0c4ed04beb02}] QOSClass:BestEffort}",
    }
    expected pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k" success: pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2020-02-12 04:29:42 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2020-02-12 04:29:09 +0000 UTC Reason:ContainersNotReady Message:containers with unready status: [test-container-subpath-pd-csi-storage-gke-io-dynamicpv-bb6k test-container-volume-pd-csi-storage-gke-io-dynamicpv-bb6k]} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2020-02-12 04:29:09 +0000 UTC Reason:ContainersNotReady Message:containers with unready status: [test-container-subpath-pd-csi-storage-gke-io-dynamicpv-bb6k test-container-volume-pd-csi-storage-gke-io-dynamicpv-bb6k]} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2020-02-12 04:29:09 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.128.0.4 PodIP:10.64.3.12 StartTime:2020-02-12 04:29:09 +0000 UTC InitContainerStatuses:[{Name:init-volume-pd-csi-storage-gke-io-dynamicpv-bb6k State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:0,Signal:0,Reason:Completed,Message:,StartedAt:2020-02-12 04:29:42 +0000 UTC,FinishedAt:2020-02-12 04:29:42 +0000 UTC,ContainerID:docker://ccc410e8a7e1de52908b2d01f8872519d92f75294877f4181fb57dbca4685875,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:true RestartCount:0 Image:busybox:1.29 ImageID:docker-pullable://busybox@sha256:e004c2cc521c95383aebb1fb5893719aa7a8eae2e7a71f316a4410784edb00a9 ContainerID:docker://ccc410e8a7e1de52908b2d01f8872519d92f75294877f4181fb57dbca4685875}] ContainerStatuses:[{Name:test-container-subpath-pd-csi-storage-gke-io-dynamicpv-bb6k State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:0,Signal:0,Reason:Completed,Message:,StartedAt:2020-02-12 04:29:43 +0000 UTC,FinishedAt:2020-02-12 04:30:03 +0000 UTC,ContainerID:docker://8fe57a6406ba7417449331d25b8c17548a0b22c0d428a46a80b2f729d631d655,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:gcr.io/kubernetes-e2e-test-images/mounttest:1.0 ImageID:docker-pullable://gcr.io/kubernetes-e2e-test-images/mounttest@sha256:c0bd6f0755f42af09a68c9a47fb993136588a76b3200ec305796b60d629d85d2 ContainerID:docker://8fe57a6406ba7417449331d25b8c17548a0b22c0d428a46a80b2f729d631d655} {Name:test-container-volume-pd-csi-storage-gke-io-dynamicpv-bb6k State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:128,Signal:0,Reason:ContainerCannotRun,Message:linux runtime spec devices: lstat /dev/sdg: no such file or directory,StartedAt:2020-02-12 04:29:43 +0000 UTC,FinishedAt:2020-02-12 04:29:43 +0000 UTC,ContainerID:docker://defadda080d99a08ace51b46fc986609bc69c2a6758bac5e920e0c4ed04beb02,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:gcr.io/kubernetes-e2e-test-images/mounttest:1.0 ImageID:docker-pullable://gcr.io/kubernetes-e2e-test-images/mounttest@sha256:c0bd6f0755f42af09a68c9a47fb993136588a76b3200ec305796b60d629d85d2 ContainerID:docker://defadda080d99a08ace51b46fc986609bc69c2a6758bac5e920e0c4ed04beb02}] QOSClass:BestEffort}
not to have occurred
/go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/util.go:2395
				
				Click to see stdout/stderrfrom junit_10.xml

Find pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k mentions in log files | View test history on testgrid


Show 26 Passed Tests

Show 2134 Skipped Tests

Error lines from build-log.txt

... skipping 237 lines ...
W0212 04:24:58.518] Trying to find master named 'e2e-test-prow-master'
W0212 04:24:58.518] Looking for address 'e2e-test-prow-master-ip'
W0212 04:24:59.474] Using master: e2e-test-prow-master (external IP: 35.238.46.249)
I0212 04:24:59.574] Waiting up to 300 seconds for cluster initialization.
I0212 04:24:59.575] 
I0212 04:24:59.575]   This will continually check to see if the API for kubernetes is reachable.
I0212 04:24:59.575]   This may time out if there was some uncaught error during start up.
I0212 04:24:59.575] 
I0212 04:26:09.159] ...............Kubernetes cluster created.
I0212 04:26:09.368] Cluster "k8s-jkns-gce-ingress1-4_e2e-test-prow" set.
I0212 04:26:09.569] User "k8s-jkns-gce-ingress1-4_e2e-test-prow" set.
I0212 04:26:09.802] Context "k8s-jkns-gce-ingress1-4_e2e-test-prow" created.
I0212 04:26:10.034] Switched to context "k8s-jkns-gce-ingress1-4_e2e-test-prow".
... skipping 20 lines ...
I0212 04:27:02.331] NAME                              STATUS                     ROLES    AGE   VERSION
I0212 04:27:02.331] e2e-test-prow-master              Ready,SchedulingDisabled   <none>   18s   v1.13.5
I0212 04:27:02.331] e2e-test-prow-minion-group-bn19   Ready                      <none>   14s   v1.13.5
I0212 04:27:02.331] e2e-test-prow-minion-group-d1kk   Ready                      <none>   22s   v1.13.5
I0212 04:27:02.332] e2e-test-prow-minion-group-hfg7   Ready                      <none>   15s   v1.13.5
I0212 04:27:02.660] Validate output:
I0212 04:27:02.923] NAME                 STATUS    MESSAGE              ERROR
I0212 04:27:02.923] etcd-1               Healthy   {"health": "true"}   
I0212 04:27:02.923] controller-manager   Healthy   ok                   
I0212 04:27:02.923] scheduler            Healthy   ok                   
I0212 04:27:02.924] etcd-0               Healthy   {"health": "true"}   
I0212 04:27:02.929] Cluster validation succeeded
W0212 04:27:03.029] Done, listing cluster services:
... skipping 116 lines ...
W0212 04:27:19.844]   "details": {
W0212 04:27:19.844]     "name": "cloud-sa",
W0212 04:27:19.844]     "kind": "secrets"
W0212 04:27:19.844]   },
W0212 04:27:19.845]   "code": 404
W0212 04:27:19.845] }]
W0212 04:27:19.845] F0212 04:27:19.842062   62633 helpers.go:116] Error from server (NotFound): secrets "cloud-sa" not found
W0212 04:27:19.848] + /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/f45f6507-4d4f-11ea-819d-1200b4212e95/cloud-sa.json -n default
W0212 04:27:19.986] I0212 04:27:19.986513   62675 loader.go:359] Config loaded from file /root/.kube/config
W0212 04:27:19.987] I0212 04:27:19.987507   62675 loader.go:359] Config loaded from file /root/.kube/config
W0212 04:27:19.989] I0212 04:27:19.988998   62675 loader.go:359] Config loaded from file /root/.kube/config
W0212 04:27:19.995] I0212 04:27:19.992328   62675 request.go:942] Request Body: {"apiVersion":"v1","data":{"cloud-sa.json":"ewogICJ0eXBlIjogInNlcnZpY2VfYWNjb3VudCIsCiAgInByb2plY3RfaWQiOiAia3ViZXJuZXRlcy1qZW5raW5zLXB1bGwiLAogICJwcml2YXRlX2tleV9pZCI6ICI5ZGMxNDU3YzBiMjQ5ZWZlMTRmOTkzMzM3OTRkMDA2MTNiNzRkMTE2IiwKICAicHJpdmF0ZV9rZXkiOiAiLS0tLS1CRUdJTiBQUklWQVRFIEtFWS0tLS0tXG5NSUlFdlFJQkFEQU5CZ2txaGtpRzl3MEJBUUVGQUFTQ0JLY3dnZ1NqQWdFQUFvSUJBUUNrcEx2WmdOdC9BME1XXG5RdTR4UENkeWgreUg3Z09xdXNEQjMxMGNmL2xwN2sxNmJkL0U4aDdVTmp0S2xpaC90UVZCdjdiejh3c0pIUmpvXG5LZ1JDbjd3NmczVFB5Q0Q1YmtUUzFNT1RMMjRiU3F3YW9BUFhGd0k3eEt5NlNDTnpDckVPazJ2b3F6NE5LT3BhXG5Ob0UrV0lBblg0TVQvS0xWbERVMlRmaTE5R2NCbHBiMlFaOGlFWmtUQTZWNHFXM0oxSFNlemhtczhsTHZ1akJ4XG5namdlWlY1SDBJaHZjMFFDTG9rejhIelh6TnBzaXRaQWVSL0hIWVY2TElsUkhLTjRMb0p0RkY2NHBnQjREZkI3XG5OU1ZwdXQ3M3k5OE1lUkhUU1l5MmRqVlFHTlYzYVdqdmhVZzVyUE5DUjBKRWxKeENTaXZUMW4xUTJRU0d2eDZtXG4rVS9pTjhyUEFnTUJBQUVDZ2dFQUJNVk5PQ2syc3dCNk1pdndVUGJvUWJaVWtUL0JWWEloNGJ4Q0szQTkzdWJyXG4wYzliTzQ2MGUvdXlUaC81dm5HVlhHbGN1TWJqRy9sKzNrTlJha2pNb0hsc3FoU25kL0xOQmJycWk5cEUrMzkzXG5heklWeW1hOVJ0UVZHVFM3NmpwMkZQRUtvR3hOMlAzRmhLV3Rxd3ZQY3RTZXJMYVdWVS85RnJ5OXB6QVV5QVAwXG5KZE4rUnVYcGRVMkJ6WTRGbm1MWnk2WXdlZmF2ekFtRHBjYTFVOWpJSHExdkIwSnFZWGFXU200VkIwL1Y0dzZFXG5RWXlMYjFKa29hd1p3VUZkeTBlaDBGTzNLVG9KOUtjNHVaQm1sWVBScy9NWlBNM21HNk9JVmVQeDY5ZEUxemNtXG5BZnBXcm4xV3VITWZNK1J5WFBIRHMzRW1yQXJiYzhtQ0ttaGVRaFB3S1FLQmdRRFZSY0VrYXVFYmM1c3dyQnRxXG5OUG1jR0dMeVlvS2x6TGIvTGgzVFhiOWozYnRnWFFzbjNzMmd2MEFLYlpERVpKRzJxU3hNQ1FvRHNLRWcvTXhhXG5wUTZQUEg4MlZ2bzUxTHBUTkhoZDJyWU5xVnEwblJTdzNCYWdoTUFvREVnd1I3cnA0emJ2WWVvTkwxd1FmTTl0XG5rbmxBL2szVE40YTBOaTRrYkQzS0F3UjN5d0tCZ1FERm9PbWRrL3FuaE5zSFU2ZmZxdVpxTDFXenZXZkJRcVo4XG50Mm5vSFlRbFd5M2Rzd21vZlV5NFU3N3h3VmJBVHRQZjBXM2JjY3hWc2tKSXZJRHhoRmJ3WFVSNkZUVkJXc2F3XG5jcXIzQmJycDMyTWUydERHckV0VGlPVGJBcTFlV015cHc5NFpHaFdCOExMa1E1SXd5bjJuWndMcmRHRlljM3lnXG51blZWUit0d2pRS0JnUURFSVJMZWw3K09URUZpZ0ZQeDF1ZlpxZitNb2hVOXZrWm40NVFnSmUxMVBKc3Rva001XG5Ga2VKMVhkaVg2SXJTY1ZLOHNhKzRlMG91WTFrVmJia2dUZ2pkMklScWVrUnQ5VGw0Ykh6dGNlSVJyOFlyQUEwXG5LU0pSMmVNUXNVTE55NWxUcjlWOFRWSTliOWs5ZkZvUmpRc2ZQdjU1Q0c1RFdqUVM0TXZ0ODlwdkF3S0JnQ1BuXG5JY25RMGw2UWtrSDRmcXp4blQ1NUx2YWlXREVSN0xFSG1TUGtDTmZJZ3NLZC9na3dDam9LYk12NnRjbm1DRFBIXG5GbEFoa2wrWExOZU45MWJwRmVwQTUybk9aSWhrOTJlaXpWQm5LQmZJejNjUmhaQXlTTlQ2TDZsaUNTRDB2T215XG5mYXpOd2s2QzdkenVNYWJQZ3BoZzdIVGVCYmxOOGJ3NVk0dUVyMDhaQW9HQUpBeURiZmthN0hWNlJwWkkvTEcxXG5Zakd0OU5QNm42UklxRUUxVWFiMEFaY2pJWDVlK0RTUnV6RVRUSXRiN0hNYUZVOE1sWmdDTWNmWDk1ckN1RmhhXG45bkFQeGZNWEd6WVdXRlVMWmNPbWdBTWQ2RkNDUlFNSjVEUm9JYU5iNGIwdVhUYWk1Z1BaUDdGQ3hNTVdrbzJQXG56NFV0WFBCVXY1am8zZUxYUHFWVVNCQT1cbi0tLS0tRU5EIFBSSVZBVEUgS0VZLS0tLS1cbiIsCiAgImNsaWVudF9lbWFpbCI6ICJwci1rdWJla2luc0BrdWJlcm5ldGVzLWplbmtpbnMtcHVsbC5pYW0uZ3NlcnZpY2VhY2NvdW50LmNvbSIsCiAgImNsaWVudF9pZCI6ICIxMTM2MDA2MzMyODUwMDYyODMxMzAiLAogICJhdXRoX3VyaSI6ICJodHRwczovL2FjY291bnRzLmdvb2dsZS5jb20vby9vYXV0aDIvYXV0aCIsCiAgInRva2VuX3VyaSI6ICJodHRwczovL29hdXRoMi5nb29nbGVhcGlzLmNvbS90b2tlbiIsCiAgImF1dGhfcHJvdmlkZXJfeDUwOV9jZXJ0X3VybCI6ICJodHRwczovL3d3dy5nb29nbGVhcGlzLmNvbS9vYXV0aDIvdjEvY2VydHMiLAogICJjbGllbnRfeDUwOV9jZXJ0X3VybCI6ICJodHRwczovL3d3dy5nb29nbGVhcGlzLmNvbS9yb2JvdC92MS9tZXRhZGF0YS94NTA5L3ByLWt1YmVraW5zJTQwa3ViZXJuZXRlcy1qZW5raW5zLXB1bGwuaWFtLmdzZXJ2aWNlYWNjb3VudC5jb20iCn0K"},"kind":"Secret","metadata":{"creationTimestamp":null,"name":"cloud-sa"}}
W0212 04:27:19.995] I0212 04:27:19.992599   62675 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 lShidH1o6qAl4YpmvBzlMnrCQi9yNFEs" 'https://35.238.46.249/api/v1/namespaces/default/secrets'
... skipping 29 lines ...
W0212 04:27:20.220]     "name": "cluster-admin-binding",
W0212 04:27:20.220]     "group": "rbac.authorization.k8s.io",
W0212 04:27:20.220]     "kind": "clusterrolebindings"
W0212 04:27:20.220]   },
W0212 04:27:20.220]   "code": 404
W0212 04:27:20.220] }]
W0212 04:27:20.220] F0212 04:27:20.187488   62716 helpers.go:116] Error from server (NotFound): clusterrolebindings.rbac.authorization.k8s.io "cluster-admin-binding" not found
W0212 04:27:20.220] ++ gcloud config get-value account
W0212 04:27:20.673] + /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 04:27:20.824] I0212 04:27:20.823891   62773 loader.go:359] Config loaded from file /root/.kube/config
W0212 04:27:20.825] I0212 04:27:20.825117   62773 loader.go:359] Config loaded from file /root/.kube/config
W0212 04:27:20.826] I0212 04:27:20.826509   62773 loader.go:359] Config loaded from file /root/.kube/config
W0212 04:27:20.831] I0212 04:27:20.831292   62773 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 04:27:21.656] 00000670  74 65 73 29 20 6f 72 20  61 20 63 6f 6e 66 69 67  |tes) or a config|
W0212 04:27:21.657] 00000680  75 72 61 74 69 6f 6e 20  63 68 61 6e 67 65 20 6f  |uration change o|
W0212 04:27:21.657] 00000690  6e 20 74 68 65 20 73 65  72 76 65 72 2c 20 74 68  |n the server, th|
W0212 04:27:21.657] 000006a0  65 20 73 65 72 76 65 72  20 77 69 6c 6c 20 72 65  |e server will re|
W0212 04:27:21.657] 000006b0  73 70 6f 6e 64 20 77 69  74 68 20 61 20 34 31 30  |spond with a 410|
W0212 04:27:21.657] 000006c0  20 52 65 73 6f 75 72 63  65 45 78 70 69 72 65 64  | ResourceExpired|
W0212 04:27:21.658] 000006d0  20 65 72 72 6f 72 20 74  6f 67 65 74 68 65 72 20  | error together |
W0212 04:27:21.658] 000006e0  77 69 74 68 20 61 20 63  6f 6e 74 69 6e 75 65 20  |with a continue |
W0212 04:27:21.658] 000006f0  74 6f 6b 65 6e 2e 20 49  66 20 74 68 65 20 63 6c  |token. If the cl|
W0212 04:27:21.658] 00000700  69 65 6e 74 20 6e 65 65  64 73 20 61 20 63 6f 6e  |ient needs a con|
W0212 04:27:21.658] 00000710  73 69 73 74 65 6e 74 20  6c 69 73 74 2c 20 69 74  |sistent list, it|
W0212 04:27:21.658] 00000720  20 6d 75 73 74 20 72 65  73 74 61 72 74 20 74 68  | must restart th|
W0212 04:27:21.659] 00000730  65 69 72 20 6c 69 73 74  20 77 69 74 68 6f 75 74  |eir list without|
... skipping 1215 lines ...
I0212 04:29:57.198] Feb 12 04:29:01.277: INFO: PersistentVolumeClaim pvc-kdp92 found but phase is Pending instead of Bound.
I0212 04:29:57.198] Feb 12 04:29:03.281: INFO: PersistentVolumeClaim pvc-kdp92 found but phase is Pending instead of Bound.
I0212 04:29:57.198] Feb 12 04:29:05.319: INFO: PersistentVolumeClaim pvc-kdp92 found but phase is Pending instead of Bound.
I0212 04:29:57.199] Feb 12 04:29:07.323: INFO: PersistentVolumeClaim pvc-kdp92 found but phase is Pending instead of Bound.
I0212 04:29:57.199] Feb 12 04:29:09.351: INFO: PersistentVolumeClaim pvc-kdp92 found but phase is Pending instead of Bound.
I0212 04:29:57.199] Feb 12 04:29:11.354: INFO: PersistentVolumeClaim pvc-kdp92 found and phase=Bound (18.145063869s)
I0212 04:29:57.199] [It] should fail if subpath directory is outside the volume [Slow]
I0212 04:29:57.199]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:245
I0212 04:29:57.199] STEP: Creating pod pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-r4h6
I0212 04:29:57.200] STEP: Checking for subpath error in container status
I0212 04:29:57.200] Feb 12 04:29:33.384: INFO: Deleting pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-r4h6" in namespace "e2e-tests-csi-volumes-gpdll"
I0212 04:29:57.200] Feb 12 04:29:33.393: INFO: Wait up to 5m0s for pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-r4h6" to be fully deleted
I0212 04:29:57.200] [AfterEach] [Testpattern: Dynamic PV (default fs)] subPath
I0212 04:29:57.200]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:120
I0212 04:29:57.201] STEP: Deleting pod
I0212 04:29:57.201] Feb 12 04:29:45.431: INFO: Deleting pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-r4h6" in namespace "e2e-tests-csi-volumes-gpdll"
... skipping 20 lines ...
I0212 04:29:57.204] [sig-storage] CSI Volumes
I0212 04:29:57.204] /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/framework.go:22
I0212 04:29:57.205]   [Driver: pd.csi.storage.gke.io][Feature: gcePD-external]
I0212 04:29:57.205]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/csi_volumes.go:129
I0212 04:29:57.205]     [Testpattern: Dynamic PV (default fs)] subPath
I0212 04:29:57.205]     /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:99
I0212 04:29:57.205]       should fail if subpath directory is outside the volume [Slow]
I0212 04:29:57.206]       /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:245
I0212 04:29:57.206] ------------------------------
I0212 04:29:57.206] SSSSSSS
I0212 04:29:57.206] ------------------------------
I0212 04:29:57.206] Feb 12 04:29:57.204: INFO: Running AfterSuite actions on all nodes
I0212 04:29:57.206] 
... skipping 19 lines ...
I0212 04:29:57.254] Feb 12 04:28:54.488: INFO: PersistentVolumeClaim pvc-q4fx7 found but phase is Pending instead of Bound.
I0212 04:29:57.255] Feb 12 04:28:56.497: INFO: PersistentVolumeClaim pvc-q4fx7 found but phase is Pending instead of Bound.
I0212 04:29:57.255] Feb 12 04:28:58.505: INFO: PersistentVolumeClaim pvc-q4fx7 found but phase is Pending instead of Bound.
I0212 04:29:57.255] Feb 12 04:29:00.517: INFO: PersistentVolumeClaim pvc-q4fx7 found but phase is Pending instead of Bound.
I0212 04:29:57.255] Feb 12 04:29:02.534: INFO: PersistentVolumeClaim pvc-q4fx7 found but phase is Pending instead of Bound.
I0212 04:29:57.255] Feb 12 04:29:04.540: INFO: PersistentVolumeClaim pvc-q4fx7 found and phase=Bound (12.083334504s)
I0212 04:29:57.255] [It] should fail if non-existent subpath is outside the volume [Slow]
I0212 04:29:57.256]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:261
I0212 04:29:57.256] STEP: Creating pod pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-9m46
I0212 04:29:57.256] STEP: Checking for subpath error in container status
I0212 04:29:57.256] Feb 12 04:29:24.575: INFO: Deleting pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-9m46" in namespace "e2e-tests-csi-volumes-fq9mz"
I0212 04:29:57.256] Feb 12 04:29:24.584: INFO: Wait up to 5m0s for pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-9m46" to be fully deleted
I0212 04:29:57.257] WARNING: pod log: pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-9m46/test-container-subpath-pd-csi-storage-gke-io-dynamicpv-9m46: pods "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-9m46" not found
I0212 04:29:57.257] WARNING: pod log: pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-9m46/test-container-volume-pd-csi-storage-gke-io-dynamicpv-9m46: pods "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-9m46" not found
I0212 04:29:57.257] [AfterEach] [Testpattern: Dynamic PV (default fs)] subPath
I0212 04:29:57.258]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:120
... skipping 25 lines ...
I0212 04:29:57.262] [sig-storage] CSI Volumes
I0212 04:29:57.262] /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/framework.go:22
I0212 04:29:57.263]   [Driver: pd.csi.storage.gke.io][Feature: gcePD-external]
I0212 04:29:57.263]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/csi_volumes.go:129
I0212 04:29:57.263]     [Testpattern: Dynamic PV (default fs)] subPath
I0212 04:29:57.263]     /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:99
I0212 04:29:57.263]       should fail if non-existent subpath is outside the volume [Slow]
I0212 04:29:57.263]       /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:261
I0212 04:29:57.264] ------------------------------
I0212 04:29:57.264] Feb 12 04:29:57.251: INFO: Running AfterSuite actions on all nodes
I0212 04:29:57.264] 
I0212 04:29:57.853] 
I0212 04:29:57.854] [BeforeEach] [sig-storage] CSI Volumes
... skipping 1138 lines ...
I0212 04:30:28.052] Feb 12 04:29:07.785: INFO: PersistentVolumeClaim pvc-8j7vb found but phase is Pending instead of Bound.
I0212 04:30:28.052] Feb 12 04:29:09.793: INFO: PersistentVolumeClaim pvc-8j7vb found but phase is Pending instead of Bound.
I0212 04:30:28.053] Feb 12 04:29:11.797: INFO: PersistentVolumeClaim pvc-8j7vb found but phase is Pending instead of Bound.
I0212 04:30:28.053] Feb 12 04:29:13.800: INFO: PersistentVolumeClaim pvc-8j7vb found but phase is Pending instead of Bound.
I0212 04:30:28.053] Feb 12 04:29:15.805: INFO: PersistentVolumeClaim pvc-8j7vb found but phase is Pending instead of Bound.
I0212 04:30:28.053] Feb 12 04:29:17.807: INFO: PersistentVolumeClaim pvc-8j7vb found and phase=Bound (20.060404431s)
I0212 04:30:28.053] [It] should fail if subpath file is outside the volume [Slow]
I0212 04:30:28.054]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:253
I0212 04:30:28.054] STEP: Creating pod pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-jvpz
I0212 04:30:28.054] STEP: Checking for subpath error in container status
I0212 04:30:28.054] Feb 12 04:29:53.835: INFO: Deleting pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-jvpz" in namespace "e2e-tests-csi-volumes-4k9gw"
I0212 04:30:28.054] Feb 12 04:29:53.847: INFO: Wait up to 5m0s for pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-jvpz" to be fully deleted
I0212 04:30:28.055] WARNING: pod log: pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-jvpz/test-container-subpath-pd-csi-storage-gke-io-dynamicpv-jvpz: pods "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-jvpz" not found
I0212 04:30:28.055] WARNING: pod log: pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-jvpz/test-container-volume-pd-csi-storage-gke-io-dynamicpv-jvpz: pods "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-jvpz" not found
I0212 04:30:28.055] [AfterEach] [Testpattern: Dynamic PV (default fs)] subPath
I0212 04:30:28.055]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:120
... skipping 25 lines ...
I0212 04:30:28.060] [sig-storage] CSI Volumes
I0212 04:30:28.061] /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/framework.go:22
I0212 04:30:28.061]   [Driver: pd.csi.storage.gke.io][Feature: gcePD-external]
I0212 04:30:28.061]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/csi_volumes.go:129
I0212 04:30:28.061]     [Testpattern: Dynamic PV (default fs)] subPath
I0212 04:30:28.062]     /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:99
I0212 04:30:28.062]       should fail if subpath file is outside the volume [Slow]
I0212 04:30:28.062]       /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:253
I0212 04:30:28.062] ------------------------------
I0212 04:30:28.063] Feb 12 04:30:28.047: INFO: Running AfterSuite actions on all nodes
I0212 04:30:28.063] 
I0212 04:30:32.113] 
I0212 04:30:32.113] [BeforeEach] [sig-storage] CSI Volumes
... skipping 52 lines ...
I0212 04:30:32.128] Feb 12 04:29:53.445: INFO: Pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k": Phase="Running", Reason="", readiness=false. Elapsed: 44.191439498s
I0212 04:30:32.128] Feb 12 04:29:55.459: INFO: Pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k": Phase="Running", Reason="", readiness=false. Elapsed: 46.206213005s
I0212 04:30:32.129] Feb 12 04:29:57.468: INFO: Pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k": Phase="Running", Reason="", readiness=false. Elapsed: 48.214810013s
I0212 04:30:32.129] Feb 12 04:29:59.486: INFO: Pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k": Phase="Running", Reason="", readiness=false. Elapsed: 50.232608305s
I0212 04:30:32.129] Feb 12 04:30:01.489: INFO: Pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k": Phase="Running", Reason="", readiness=false. Elapsed: 52.235944703s
I0212 04:30:32.130] Feb 12 04:30:03.493: INFO: Pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k": Phase="Running", Reason="", readiness=false. Elapsed: 54.239408225s
I0212 04:30:32.130] Feb 12 04:30:05.496: INFO: Pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k": Phase="Failed", Reason="", readiness=false. Elapsed: 56.243100412s
I0212 04:30:32.130] Feb 12 04:30:05.514: INFO: Output of node "e2e-test-prow-minion-group-bn19" pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k" container "test-container-subpath-pd-csi-storage-gke-io-dynamicpv-bb6k": content of file "/test-volume": e2e-tests-csi-volumes-wb285
I0212 04:30:32.131] 
I0212 04:30:32.131] Unexpected content. Expected: mount-tester new file
I0212 04:30:32.131] . Retryingcontent of file "/test-volume": e2e-tests-csi-volumes-wb285
I0212 04:30:32.131] 
I0212 04:30:32.131] Unexpected content. Expected: mount-tester new file
... skipping 19 lines ...
I0212 04:30:32.134] 
I0212 04:30:32.135] Unexpected content. Expected: mount-tester new file
I0212 04:30:32.135] . Retryingcontent of file "/test-volume": e2e-tests-csi-volumes-wb285
I0212 04:30:32.135] 
I0212 04:30:32.135] Unexpected content. Expected: mount-tester new file
I0212 04:30:32.135] . Retrying
I0212 04:30:32.136] Feb 12 04:30:05.526: INFO: Output of node "e2e-test-prow-minion-group-bn19" pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k" container "test-container-volume-pd-csi-storage-gke-io-dynamicpv-bb6k": failed to open log file "/var/log/pods/3653b379-4d50-11ea-a5bc-42010a800002/test-container-volume-pd-csi-storage-gke-io-dynamicpv-bb6k/0.log": open /var/log/pods/3653b379-4d50-11ea-a5bc-42010a800002/test-container-volume-pd-csi-storage-gke-io-dynamicpv-bb6k/0.log: no such file or directory
I0212 04:30:32.136] STEP: delete the pod
I0212 04:30:32.136] Feb 12 04:30:05.543: INFO: Waiting for pod pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k to disappear
I0212 04:30:32.136] Feb 12 04:30:05.552: INFO: Pod pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k no longer exists
I0212 04:30:32.139] Feb 12 04:30:05.552: INFO: Unexpected error occurred: expected pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k" success: pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2020-02-12 04:29:42 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2020-02-12 04:29:09 +0000 UTC Reason:ContainersNotReady Message:containers with unready status: [test-container-subpath-pd-csi-storage-gke-io-dynamicpv-bb6k test-container-volume-pd-csi-storage-gke-io-dynamicpv-bb6k]} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2020-02-12 04:29:09 +0000 UTC Reason:ContainersNotReady Message:containers with unready status: [test-container-subpath-pd-csi-storage-gke-io-dynamicpv-bb6k test-container-volume-pd-csi-storage-gke-io-dynamicpv-bb6k]} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2020-02-12 04:29:09 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.128.0.4 PodIP:10.64.3.12 StartTime:2020-02-12 04:29:09 +0000 UTC InitContainerStatuses:[{Name:init-volume-pd-csi-storage-gke-io-dynamicpv-bb6k State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:0,Signal:0,Reason:Completed,Message:,StartedAt:2020-02-12 04:29:42 +0000 UTC,FinishedAt:2020-02-12 04:29:42 +0000 UTC,ContainerID:docker://ccc410e8a7e1de52908b2d01f8872519d92f75294877f4181fb57dbca4685875,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:true RestartCount:0 Image:busybox:1.29 ImageID:docker-pullable://busybox@sha256:e004c2cc521c95383aebb1fb5893719aa7a8eae2e7a71f316a4410784edb00a9 ContainerID:docker://ccc410e8a7e1de52908b2d01f8872519d92f75294877f4181fb57dbca4685875}] ContainerStatuses:[{Name:test-container-subpath-pd-csi-storage-gke-io-dynamicpv-bb6k State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:0,Signal:0,Reason:Completed,Message:,StartedAt:2020-02-12 04:29:43 +0000 UTC,FinishedAt:2020-02-12 04:30:03 +0000 UTC,ContainerID:docker://8fe57a6406ba7417449331d25b8c17548a0b22c0d428a46a80b2f729d631d655,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:gcr.io/kubernetes-e2e-test-images/mounttest:1.0 ImageID:docker-pullable://gcr.io/kubernetes-e2e-test-images/mounttest@sha256:c0bd6f0755f42af09a68c9a47fb993136588a76b3200ec305796b60d629d85d2 ContainerID:docker://8fe57a6406ba7417449331d25b8c17548a0b22c0d428a46a80b2f729d631d655} {Name:test-container-volume-pd-csi-storage-gke-io-dynamicpv-bb6k State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:128,Signal:0,Reason:ContainerCannotRun,Message:linux runtime spec devices: lstat /dev/sdg: no such file or directory,StartedAt:2020-02-12 04:29:43 +0000 UTC,FinishedAt:2020-02-12 04:29:43 +0000 UTC,ContainerID:docker://defadda080d99a08ace51b46fc986609bc69c2a6758bac5e920e0c4ed04beb02,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:gcr.io/kubernetes-e2e-test-images/mounttest:1.0 ImageID:docker-pullable://gcr.io/kubernetes-e2e-test-images/mounttest@sha256:c0bd6f0755f42af09a68c9a47fb993136588a76b3200ec305796b60d629d85d2 ContainerID:docker://defadda080d99a08ace51b46fc986609bc69c2a6758bac5e920e0c4ed04beb02}] QOSClass:BestEffort}
I0212 04:30:32.140] [AfterEach] [Testpattern: Dynamic PV (default fs)] subPath
I0212 04:30:32.140]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:120
I0212 04:30:32.140] STEP: Deleting pod
I0212 04:30:32.140] Feb 12 04:30:05.553: INFO: Deleting pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k" in namespace "e2e-tests-csi-volumes-wb285"
I0212 04:30:32.140] STEP: Deleting pvc
I0212 04:30:32.141] Feb 12 04:30:05.558: INFO: Deleting PersistentVolumeClaim "pvc-8lbh8"
... skipping 11 lines ...
I0212 04:30:32.142] STEP: Collecting events from namespace "e2e-tests-csi-volumes-wb285".
I0212 04:30:32.143] STEP: Found 16 events.
I0212 04:30:32.143] Feb 12 04:30:25.612: INFO: At 2020-02-12 04:28:53 +0000 UTC - event for pvc-8lbh8: {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 04:30:32.143] Feb 12 04:30:25.612: INFO: At 2020-02-12 04:29:04 +0000 UTC - event for pvc-8lbh8: {pd.csi.storage.gke.io_csi-gce-pd-controller-0_0388b05a-4d50-11ea-89b8-a6b62038ba88 } Provisioning: External provisioner is provisioning volume for claim "e2e-tests-csi-volumes-wb285/pvc-8lbh8"
I0212 04:30:32.144] Feb 12 04:30:25.612: INFO: At 2020-02-12 04:29:08 +0000 UTC - event for pvc-8lbh8: {pd.csi.storage.gke.io_csi-gce-pd-controller-0_0388b05a-4d50-11ea-89b8-a6b62038ba88 } ProvisioningSucceeded: Successfully provisioned volume pvc-2cac859d-4d50-11ea-a5bc-42010a800002
I0212 04:30:32.144] Feb 12 04:30:25.612: INFO: At 2020-02-12 04:29:09 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k: {default-scheduler } Scheduled: Successfully assigned e2e-tests-csi-volumes-wb285/pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k to e2e-test-prow-minion-group-bn19
I0212 04:30:32.144] Feb 12 04:30:25.612: INFO: At 2020-02-12 04:29:24 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k: {attachdetach-controller } FailedAttachVolume: AttachVolume.Attach failed for volume "pvc-2cac859d-4d50-11ea-a5bc-42010a800002" : attachment timeout for volume projects/k8s-jkns-gce-ingress1-4/zones/us-central1-b/disks/pvc-2cac859d-4d50-11ea-a5bc-42010a800002
I0212 04:30:32.145] Feb 12 04:30:25.612: INFO: At 2020-02-12 04:29:28 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k: {attachdetach-controller } FailedAttachVolume: AttachVolume.Attach failed for volume "pvc-2cac859d-4d50-11ea-a5bc-42010a800002" : rpc error: code = DeadlineExceeded desc = context deadline exceeded
I0212 04:30:32.145] Feb 12 04:30:25.612: INFO: At 2020-02-12 04:29:29 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k: {attachdetach-controller } SuccessfulAttachVolume: AttachVolume.Attach succeeded for volume "pvc-2cac859d-4d50-11ea-a5bc-42010a800002" 
I0212 04:30:32.145] Feb 12 04:30:25.612: INFO: At 2020-02-12 04:29:42 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k: {kubelet e2e-test-prow-minion-group-bn19} Pulled: Container image "docker.io/library/busybox:1.29" already present on machine
I0212 04:30:32.146] Feb 12 04:30:25.612: INFO: At 2020-02-12 04:29:42 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k: {kubelet e2e-test-prow-minion-group-bn19} Created: Created container
I0212 04:30:32.146] Feb 12 04:30:25.612: INFO: At 2020-02-12 04:29:42 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k: {kubelet e2e-test-prow-minion-group-bn19} Started: Started container
I0212 04:30:32.146] Feb 12 04:30:25.612: INFO: At 2020-02-12 04:29:42 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k: {kubelet e2e-test-prow-minion-group-bn19} Created: Created container
I0212 04:30:32.147] Feb 12 04:30:25.612: INFO: At 2020-02-12 04:29:42 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k: {kubelet e2e-test-prow-minion-group-bn19} Pulled: Container image "gcr.io/kubernetes-e2e-test-images/mounttest:1.0" already present on machine
I0212 04:30:32.147] Feb 12 04:30:25.612: INFO: At 2020-02-12 04:29:43 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k: {kubelet e2e-test-prow-minion-group-bn19} Pulled: Container image "gcr.io/kubernetes-e2e-test-images/mounttest:1.0" already present on machine
I0212 04:30:32.147] Feb 12 04:30:25.612: INFO: At 2020-02-12 04:29:43 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k: {kubelet e2e-test-prow-minion-group-bn19} Created: Created container
I0212 04:30:32.147] Feb 12 04:30:25.612: INFO: At 2020-02-12 04:29:43 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k: {kubelet e2e-test-prow-minion-group-bn19} Failed: Error: failed to start container "test-container-volume-pd-csi-storage-gke-io-dynamicpv-bb6k": Error response from daemon: linux runtime spec devices: lstat /dev/sdg: no such file or directory
I0212 04:30:32.148] Feb 12 04:30:25.612: INFO: At 2020-02-12 04:29:43 +0000 UTC - event for pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k: {kubelet e2e-test-prow-minion-group-bn19} Started: Started container
I0212 04:30:32.148] Feb 12 04:30:25.626: INFO: POD                                                    NODE                             PHASE    GRACE  CONDITIONS
I0212 04:30:32.148] Feb 12 04:30:25.626: INFO: csi-gce-pd-controller-0                                e2e-test-prow-minion-group-bn19  Running         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 04:27:31 +0000 UTC  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 04:27:43 +0000 UTC  } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 04:27:43 +0000 UTC  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 04:27:22 +0000 UTC  }]
I0212 04:30:32.149] Feb 12 04:30:25.626: INFO: csi-gce-pd-node-8l4lk                                  e2e-test-prow-minion-group-bn19  Running         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 04:27:31 +0000 UTC  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 04:27:43 +0000 UTC  } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 04:27:43 +0000 UTC  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 04:27:21 +0000 UTC  }]
I0212 04:30:32.149] Feb 12 04:30:25.626: INFO: csi-gce-pd-node-jm6qx                                                                   Pending         [{PodScheduled False 2020-02-12 04:30:25 +0000 UTC 2020-02-12 04:27:23 +0000 UTC Unschedulable 0/4 nodes are available: 1 Insufficient cpu, 3 node(s) didn't match node selector.}]
I0212 04:30:32.150] Feb 12 04:30:25.626: INFO: csi-gce-pd-node-mkp4k                                  e2e-test-prow-minion-group-hfg7  Running         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 04:27:38 +0000 UTC  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 04:27:46 +0000 UTC  } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 04:27:46 +0000 UTC  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 04:27:21 +0000 UTC  }]
... skipping 29 lines ...
I0212 04:30:32.167] Feb 12 04:30:25.627: INFO: metadata-proxy-v0.1-n829t                              e2e-test-prow-minion-group-d1kk  Running         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 04:26:41 +0000 UTC  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 04:27:26 +0000 UTC  } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 04:27:26 +0000 UTC  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 04:26:41 +0000 UTC  }]
I0212 04:30:32.168] Feb 12 04:30:25.627: INFO: metadata-proxy-v0.1-srb2p                              e2e-test-prow-master             Running         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 04:26:44 +0000 UTC  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 04:27:05 +0000 UTC  } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 04:27:05 +0000 UTC  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 04:26:44 +0000 UTC  }]
I0212 04:30:32.168] Feb 12 04:30:25.627: INFO: metrics-server-v0.3.1-58d65f8d6-rpr6w                  e2e-test-prow-minion-group-d1kk  Running         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 04:27:26 +0000 UTC  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 04:27:32 +0000 UTC  } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 04:27:32 +0000 UTC  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2020-02-12 04:27:01 +0000 UTC  }]
I0212 04:30:32.168] Feb 12 04:30:25.627: INFO: 
I0212 04:30:32.169] Feb 12 04:30:25.630: INFO: 
I0212 04:30:32.169] Logging node info for node e2e-test-prow-master
I0212 04:30:32.174] Feb 12 04:30:25.633: 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:dfe3ced4-4d4f-11ea-a5bc-42010a800002,ResourceVersion:2334,Generation:0,CreationTimestamp:2020-02-12 04:26:44 +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.1.0/24,DoNotUse_ExternalID:,ProviderID:gce://k8s-jkns-gce-ingress1-4/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 04:26:52 +0000 UTC 2020-02-12 04:26:52 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2020-02-12 04:30:25 +0000 UTC 2020-02-12 04:26:44 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2020-02-12 04:30:25 +0000 UTC 2020-02-12 04:26:44 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2020-02-12 04:30:25 +0000 UTC 2020-02-12 04:26:44 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2020-02-12 04:30:25 +0000 UTC 2020-02-12 04:26:44 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.128.0.2} {ExternalIP 35.238.46.249} {InternalDNS e2e-test-prow-master.c.k8s-jkns-gce-ingress1-4.internal} {Hostname e2e-test-prow-master.c.k8s-jkns-gce-ingress1-4.internal}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:36a0af066c77cbf053d99da981f0aaad,SystemUUID:36A0AF06-6C77-CBF0-53D9-9DA981F0AAAD,BootID:90b63112-c9f1-49e9-8716-1d3e275a5e40,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 04:30:32.174] Feb 12 04:30:25.633: INFO: 
I0212 04:30:32.174] Logging kubelet events for node e2e-test-prow-master
I0212 04:30:32.174] Feb 12 04:30:25.646: INFO: 
I0212 04:30:32.175] Logging pods the kubelet thinks is on node e2e-test-prow-master
I0212 04:30:32.175] Feb 12 04:30:25.666: INFO: etcd-empty-dir-cleanup-e2e-test-prow-master started at <nil> (0+0 container statuses recorded)
I0212 04:30:32.175] Feb 12 04:30:25.666: INFO: etcd-server-events-e2e-test-prow-master started at <nil> (0+0 container statuses recorded)
... skipping 14 lines ...
I0212 04:30:32.179] Feb 12 04:30:25.716: INFO: {Operation: Method:pod_start_latency_microseconds Quantile:0.99 Latency:24.901647s}
I0212 04:30:32.179] Feb 12 04:30:25.716: INFO: {Operation: Method:pod_start_latency_microseconds Quantile:0.9 Latency:22.464917s}
I0212 04:30:32.179] Feb 12 04:30:25.717: INFO: {Operation:pull_image Method:docker_operations_latency_microseconds Quantile:0.99 Latency:19.347344s}
I0212 04:30:32.180] Feb 12 04:30:25.717: INFO: {Operation:pull_image Method:docker_operations_latency_microseconds Quantile:0.9 Latency:19.034695s}
I0212 04:30:32.180] Feb 12 04:30:25.717: INFO: 
I0212 04:30:32.180] Logging node info for node e2e-test-prow-minion-group-bn19
I0212 04:30:32.187] Feb 12 04:30:25.720: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:e2e-test-prow-minion-group-bn19,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/e2e-test-prow-minion-group-bn19,UID:e22e1fb5-4d4f-11ea-a5bc-42010a800002,ResourceVersion:2272,Generation:0,CreationTimestamp:2020-02-12 04:26:48 +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-bn19,},Annotations:map[string]string{csi.volume.kubernetes.io/nodeid: {"pd.csi.storage.gke.io":"projects/k8s-jkns-gce-ingress1-4/zones/us-central1-b/instances/e2e-test-prow-minion-group-bn19"},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-gce-ingress1-4/us-central1-b/e2e-test-prow-minion-group-bn19,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-12 04:29:51 +0000 UTC 2020-02-12 04:25:35 +0000 UTC NoFrequentUnregisterNetDevice node is functioning properly} {FrequentKubeletRestart False 2020-02-12 04:29:51 +0000 UTC 2020-02-12 04:25:35 +0000 UTC NoFrequentKubeletRestart kubelet is functioning properly} {FrequentDockerRestart False 2020-02-12 04:29:51 +0000 UTC 2020-02-12 04:25:35 +0000 UTC NoFrequentDockerRestart docker is functioning properly} {FrequentContainerdRestart False 2020-02-12 04:29:51 +0000 UTC 2020-02-12 04:25:35 +0000 UTC NoFrequentContainerdRestart containerd is functioning properly} {CorruptDockerOverlay2 False 2020-02-12 04:29:51 +0000 UTC 2020-02-12 04:25:35 +0000 UTC NoCorruptDockerOverlay2 docker overlay2 is functioning properly} {KernelDeadlock False 2020-02-12 04:29:51 +0000 UTC 2020-02-12 04:25:35 +0000 UTC KernelHasNoDeadlock kernel has no deadlock} {ReadonlyFilesystem False 2020-02-12 04:29:51 +0000 UTC 2020-02-12 04:25:35 +0000 UTC FilesystemIsNotReadOnly Filesystem is not read-only} {NetworkUnavailable False 2020-02-12 04:27:03 +0000 UTC 2020-02-12 04:27:03 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2020-02-12 04:30:19 +0000 UTC 2020-02-12 04:26:48 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2020-02-12 04:30:19 +0000 UTC 2020-02-12 04:26:48 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2020-02-12 04:30:19 +0000 UTC 2020-02-12 04:26:48 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2020-02-12 04:30:19 +0000 UTC 2020-02-12 04:26:48 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.128.0.4} {ExternalIP 35.223.54.5} {InternalDNS e2e-test-prow-minion-group-bn19.c.k8s-jkns-gce-ingress1-4.internal} {Hostname e2e-test-prow-minion-group-bn19.c.k8s-jkns-gce-ingress1-4.internal}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:b2fd5d8f70911cc79b61dd2d31f2c4f8,SystemUUID:B2FD5D8F-7091-1CC7-9B61-DD2D31F2C4F8,BootID:8e4959bb-f0b3-4c66-a1d6-feb5664a1b6f,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} {[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} {[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:[kubernetes.io/csi/pd.csi.storage.gke.io^projects/k8s-jkns-gce-ingress1-4/zones/us-central1-b/disks/pvc-2d010108-4d50-11ea-a5bc-42010a800002],VolumesAttached:[{kubernetes.io/csi/pd.csi.storage.gke.io^projects/k8s-jkns-gce-ingress1-4/zones/us-central1-b/disks/pvc-2d010108-4d50-11ea-a5bc-42010a800002 csi-c3981065e5602ad503b445559539c9405d60758b0c31d8a90508acf34fab05ee}],Config:&NodeConfigStatus{Assigned:nil,Active:nil,LastKnownGood:nil,Error:,},},}
I0212 04:30:32.187] Feb 12 04:30:25.720: INFO: 
I0212 04:30:32.187] Logging kubelet events for node e2e-test-prow-minion-group-bn19
I0212 04:30:32.188] Feb 12 04:30:25.729: INFO: 
I0212 04:30:32.188] Logging pods the kubelet thinks is on node e2e-test-prow-minion-group-bn19
I0212 04:30:32.188] Feb 12 04:30:25.739: INFO: csi-gce-pd-node-8l4lk started at 2020-02-12 04:27:31 +0000 UTC (0+2 container statuses recorded)
I0212 04:30:32.188] Feb 12 04:30:25.739: INFO: 	Container csi-driver-registrar ready: true, restart count 0
... skipping 17 lines ...
I0212 04:30:32.193] Latency metrics for node e2e-test-prow-minion-group-bn19
I0212 04:30:32.193] Feb 12 04:30:25.776: INFO: {Operation: Method:pod_start_latency_microseconds Quantile:0.99 Latency:43.287124s}
I0212 04:30:32.193] Feb 12 04:30:25.776: INFO: {Operation: Method:pod_start_latency_microseconds Quantile:0.9 Latency:35.347886s}
I0212 04:30:32.194] Feb 12 04:30:25.776: INFO: {Operation:start_container Method:docker_operations_latency_microseconds Quantile:0.99 Latency:30.984058s}
I0212 04:30:32.194] Feb 12 04:30:25.776: INFO: 
I0212 04:30:32.194] Logging node info for node e2e-test-prow-minion-group-d1kk
I0212 04:30:32.201] Feb 12 04:30:25.780: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:e2e-test-prow-minion-group-d1kk,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/e2e-test-prow-minion-group-d1kk,UID:ddd39282-4d4f-11ea-a5bc-42010a800002,ResourceVersion:2313,Generation:0,CreationTimestamp:2020-02-12 04:26: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-d1kk,},Annotations:map[string]string{csi.volume.kubernetes.io/nodeid: {"pd.csi.storage.gke.io":"projects/k8s-jkns-gce-ingress1-4/zones/us-central1-b/instances/e2e-test-prow-minion-group-d1kk"},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-gce-ingress1-4/us-central1-b/e2e-test-prow-minion-group-d1kk,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 04:29:46 +0000 UTC 2020-02-12 04:25:36 +0000 UTC FilesystemIsNotReadOnly Filesystem is not read-only} {CorruptDockerOverlay2 False 2020-02-12 04:29:46 +0000 UTC 2020-02-12 04:25:36 +0000 UTC NoCorruptDockerOverlay2 docker overlay2 is functioning properly} {FrequentKubeletRestart False 2020-02-12 04:29:46 +0000 UTC 2020-02-12 04:25:36 +0000 UTC NoFrequentKubeletRestart kubelet is functioning properly} {FrequentDockerRestart False 2020-02-12 04:29:46 +0000 UTC 2020-02-12 04:25:36 +0000 UTC NoFrequentDockerRestart docker is functioning properly} {FrequentContainerdRestart False 2020-02-12 04:29:46 +0000 UTC 2020-02-12 04:25:36 +0000 UTC NoFrequentContainerdRestart containerd is functioning properly} {FrequentUnregisterNetDevice False 2020-02-12 04:29:46 +0000 UTC 2020-02-12 04:25:36 +0000 UTC NoFrequentUnregisterNetDevice node is functioning properly} {KernelDeadlock False 2020-02-12 04:29:46 +0000 UTC 2020-02-12 04:25:36 +0000 UTC KernelHasNoDeadlock kernel has no deadlock} {NetworkUnavailable False 2020-02-12 04:26:53 +0000 UTC 2020-02-12 04:26:53 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2020-02-12 04:30:22 +0000 UTC 2020-02-12 04:26:40 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2020-02-12 04:30:22 +0000 UTC 2020-02-12 04:26:40 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2020-02-12 04:30:22 +0000 UTC 2020-02-12 04:26:40 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2020-02-12 04:30:22 +0000 UTC 2020-02-12 04:26:41 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.128.0.5} {ExternalIP 104.197.29.224} {InternalDNS e2e-test-prow-minion-group-d1kk.c.k8s-jkns-gce-ingress1-4.internal} {Hostname e2e-test-prow-minion-group-d1kk.c.k8s-jkns-gce-ingress1-4.internal}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:fdb88a4d53d2cd95853a266136fc8288,SystemUUID:FDB88A4D-53D2-CD95-853A-266136FC8288,BootID:696f2813-7662-4a72-8d22-ad4abeceec23,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 04:30:32.201] Feb 12 04:30:25.781: INFO: 
I0212 04:30:32.201] Logging kubelet events for node e2e-test-prow-minion-group-d1kk
I0212 04:30:32.202] Feb 12 04:30:25.790: INFO: 
I0212 04:30:32.202] Logging pods the kubelet thinks is on node e2e-test-prow-minion-group-d1kk
I0212 04:30:32.202] Feb 12 04:30:25.798: INFO: kube-proxy-e2e-test-prow-minion-group-d1kk started at <nil> (0+0 container statuses recorded)
I0212 04:30:32.202] Feb 12 04:30:25.798: INFO: metadata-proxy-v0.1-n829t started at 2020-02-12 04:26:41 +0000 UTC (0+2 container statuses recorded)
... skipping 26 lines ...
I0212 04:30:32.209] Feb 12 04:30:25.864: INFO: {Operation: Method:pod_start_latency_microseconds Quantile:0.9 Latency:44.972709s}
I0212 04:30:32.209] Feb 12 04:30:25.864: INFO: {Operation:start_container Method:docker_operations_latency_microseconds Quantile:0.99 Latency:28.219763s}
I0212 04:30:32.210] Feb 12 04:30:25.864: INFO: {Operation: Method:pod_worker_start_latency_microseconds Quantile:0.99 Latency:24.445624s}
I0212 04:30:32.210] Feb 12 04:30:25.864: INFO: {Operation:pull_image Method:docker_operations_latency_microseconds Quantile:0.99 Latency:12.860447s}
I0212 04:30:32.210] Feb 12 04:30:25.864: INFO: 
I0212 04:30:32.210] Logging node info for node e2e-test-prow-minion-group-hfg7
I0212 04:30:32.218] Feb 12 04:30:25.867: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:e2e-test-prow-minion-group-hfg7,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/e2e-test-prow-minion-group-hfg7,UID:e2112b69-4d4f-11ea-a5bc-42010a800002,ResourceVersion:2281,Generation:0,CreationTimestamp:2020-02-12 04:26:47 +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-hfg7,},Annotations:map[string]string{csi.volume.kubernetes.io/nodeid: {"pd.csi.storage.gke.io":"projects/k8s-jkns-gce-ingress1-4/zones/us-central1-b/instances/e2e-test-prow-minion-group-hfg7"},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-gce-ingress1-4/us-central1-b/e2e-test-prow-minion-group-hfg7,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-12 04:29:58 +0000 UTC 2020-02-12 04:25:32 +0000 UTC NoCorruptDockerOverlay2 docker overlay2 is functioning properly} {FrequentUnregisterNetDevice False 2020-02-12 04:29:58 +0000 UTC 2020-02-12 04:25:32 +0000 UTC NoFrequentUnregisterNetDevice node is functioning properly} {KernelDeadlock False 2020-02-12 04:29:58 +0000 UTC 2020-02-12 04:25:32 +0000 UTC KernelHasNoDeadlock kernel has no deadlock} {ReadonlyFilesystem False 2020-02-12 04:29:58 +0000 UTC 2020-02-12 04:25:32 +0000 UTC FilesystemIsNotReadOnly Filesystem is not read-only} {FrequentKubeletRestart False 2020-02-12 04:29:58 +0000 UTC 2020-02-12 04:25:32 +0000 UTC NoFrequentKubeletRestart kubelet is functioning properly} {FrequentDockerRestart False 2020-02-12 04:29:58 +0000 UTC 2020-02-12 04:25:32 +0000 UTC NoFrequentDockerRestart docker is functioning properly} {FrequentContainerdRestart False 2020-02-12 04:29:58 +0000 UTC 2020-02-12 04:25:32 +0000 UTC NoFrequentContainerdRestart containerd is functioning properly} {NetworkUnavailable False 2020-02-12 04:27:02 +0000 UTC 2020-02-12 04:27:02 +0000 UTC RouteCreated RouteController created a route} {MemoryPressure False 2020-02-12 04:30:19 +0000 UTC 2020-02-12 04:26:47 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2020-02-12 04:30:19 +0000 UTC 2020-02-12 04:26:47 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {PIDPressure False 2020-02-12 04:30:19 +0000 UTC 2020-02-12 04:26:47 +0000 UTC KubeletHasSufficientPID kubelet has sufficient PID available} {Ready True 2020-02-12 04:30:19 +0000 UTC 2020-02-12 04:26:48 +0000 UTC KubeletReady kubelet is posting ready status. AppArmor enabled}],Addresses:[{InternalIP 10.128.0.3} {ExternalIP 35.226.128.188} {InternalDNS e2e-test-prow-minion-group-hfg7.c.k8s-jkns-gce-ingress1-4.internal} {Hostname e2e-test-prow-minion-group-hfg7.c.k8s-jkns-gce-ingress1-4.internal}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:8a2d0369805a57dd376100688c9e03cd,SystemUUID:8A2D0369-805A-57DD-3761-00688C9E03CD,BootID:27617096-d36a-4d70-bc90-aec934f0c068,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} {[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} {[k8s.gcr.io/cluster-proportional-autoscaler-amd64@sha256:4fd37c5b29a38b02c408c56254bd1a3a76f3e236610bc7a8382500bbf9ecfc76 k8s.gcr.io/cluster-proportional-autoscaler-amd64:1.3.0] 45844959} {[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:[kubernetes.io/csi/pd.csi.storage.gke.io^projects/k8s-jkns-gce-ingress1-4/zones/us-central1-b/disks/pvc-304ffe6f-4d50-11ea-a5bc-42010a800002 kubernetes.io/csi/pd.csi.storage.gke.io^projects/k8s-jkns-gce-ingress1-4/zones/us-central1-b/disks/pvc-4fe5abab-4d50-11ea-a5bc-42010a800002],VolumesAttached:[{kubernetes.io/csi/pd.csi.storage.gke.io^projects/k8s-jkns-gce-ingress1-4/zones/us-central1-b/disks/pvc-304ffe6f-4d50-11ea-a5bc-42010a800002 csi-01f1515433b5cdcebffb6a436b9166585bd2c8296058ea190f094d710ba3383e} {kubernetes.io/csi/pd.csi.storage.gke.io^projects/k8s-jkns-gce-ingress1-4/zones/us-central1-b/disks/pvc-4fe5abab-4d50-11ea-a5bc-42010a800002 csi-b49f37a762a952bdf2d1d6f289da13832ecee55b73b83fe8212d40befd4e09d2}],Config:&NodeConfigStatus{Assigned:nil,Active:nil,LastKnownGood:nil,Error:,},},}
I0212 04:30:32.218] Feb 12 04:30:25.868: INFO: 
I0212 04:30:32.219] Logging kubelet events for node e2e-test-prow-minion-group-hfg7
I0212 04:30:32.219] Feb 12 04:30:25.876: INFO: 
I0212 04:30:32.219] Logging pods the kubelet thinks is on node e2e-test-prow-minion-group-hfg7
I0212 04:30:32.219] Feb 12 04:30:25.886: INFO: kube-proxy-e2e-test-prow-minion-group-hfg7 started at <nil> (0+0 container statuses recorded)
I0212 04:30:32.220] Feb 12 04:30:25.886: INFO: fluentd-gcp-v3.2.0-xjbf9 started at 2020-02-12 04:28:47 +0000 UTC (0+2 container statuses recorded)
... skipping 40 lines ...
I0212 04:30:32.230]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/csi_volumes.go:129
I0212 04:30:32.230]     [Testpattern: Dynamic PV (default fs)] subPath
I0212 04:30:32.230]     /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:99
I0212 04:30:32.231]       should support file as subpath [It]
I0212 04:30:32.231]       /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:238
I0212 04:30:32.231] 
I0212 04:30:32.231]       Expected error:
I0212 04:30:32.231]           <*errors.errorString | 0xc000fbf040>: {
I0212 04:30:32.235]               s: "expected pod \"pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k\" success: pod \"pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k\" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2020-02-12 04:29:42 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2020-02-12 04:29:09 +0000 UTC Reason:ContainersNotReady Message:containers with unready status: [test-container-subpath-pd-csi-storage-gke-io-dynamicpv-bb6k test-container-volume-pd-csi-storage-gke-io-dynamicpv-bb6k]} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2020-02-12 04:29:09 +0000 UTC Reason:ContainersNotReady Message:containers with unready status: [test-container-subpath-pd-csi-storage-gke-io-dynamicpv-bb6k test-container-volume-pd-csi-storage-gke-io-dynamicpv-bb6k]} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2020-02-12 04:29:09 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.128.0.4 PodIP:10.64.3.12 StartTime:2020-02-12 04:29:09 +0000 UTC InitContainerStatuses:[{Name:init-volume-pd-csi-storage-gke-io-dynamicpv-bb6k State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:0,Signal:0,Reason:Completed,Message:,StartedAt:2020-02-12 04:29:42 +0000 UTC,FinishedAt:2020-02-12 04:29:42 +0000 UTC,ContainerID:docker://ccc410e8a7e1de52908b2d01f8872519d92f75294877f4181fb57dbca4685875,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:true RestartCount:0 Image:busybox:1.29 ImageID:docker-pullable://busybox@sha256:e004c2cc521c95383aebb1fb5893719aa7a8eae2e7a71f316a4410784edb00a9 ContainerID:docker://ccc410e8a7e1de52908b2d01f8872519d92f75294877f4181fb57dbca4685875}] ContainerStatuses:[{Name:test-container-subpath-pd-csi-storage-gke-io-dynamicpv-bb6k State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:0,Signal:0,Reason:Completed,Message:,StartedAt:2020-02-12 04:29:43 +0000 UTC,FinishedAt:2020-02-12 04:30:03 +0000 UTC,ContainerID:docker://8fe57a6406ba7417449331d25b8c17548a0b22c0d428a46a80b2f729d631d655,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:gcr.io/kubernetes-e2e-test-images/mounttest:1.0 ImageID:docker-pullable://gcr.io/kubernetes-e2e-test-images/mounttest@sha256:c0bd6f0755f42af09a68c9a47fb993136588a76b3200ec305796b60d629d85d2 ContainerID:docker://8fe57a6406ba7417449331d25b8c17548a0b22c0d428a46a80b2f729d631d655} {Name:test-container-volume-pd-csi-storage-gke-io-dynamicpv-bb6k State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:128,Signal:0,Reason:ContainerCannotRun,Message:linux runtime spec devices: lstat /dev/sdg: no such file or directory,StartedAt:2020-02-12 04:29:43 +0000 UTC,FinishedAt:2020-02-12 04:29:43 +0000 UTC,ContainerID:docker://defadda080d99a08ace51b46fc986609bc69c2a6758bac5e920e0c4ed04beb02,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:gcr.io/kubernetes-e2e-test-images/mounttest:1.0 ImageID:docker-pullable://gcr.io/kubernetes-e2e-test-images/mounttest@sha256:c0bd6f0755f42af09a68c9a47fb993136588a76b3200ec305796b60d629d85d2 ContainerID:docker://defadda080d99a08ace51b46fc986609bc69c2a6758bac5e920e0c4ed04beb02}] QOSClass:BestEffort}",
I0212 04:30:32.235]           }
I0212 04:30:32.239]           expected pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k" success: pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-bb6k" failed with status: {Phase:Failed Conditions:[{Type:Initialized Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2020-02-12 04:29:42 +0000 UTC Reason: Message:} {Type:Ready Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2020-02-12 04:29:09 +0000 UTC Reason:ContainersNotReady Message:containers with unready status: [test-container-subpath-pd-csi-storage-gke-io-dynamicpv-bb6k test-container-volume-pd-csi-storage-gke-io-dynamicpv-bb6k]} {Type:ContainersReady Status:False LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2020-02-12 04:29:09 +0000 UTC Reason:ContainersNotReady Message:containers with unready status: [test-container-subpath-pd-csi-storage-gke-io-dynamicpv-bb6k test-container-volume-pd-csi-storage-gke-io-dynamicpv-bb6k]} {Type:PodScheduled Status:True LastProbeTime:0001-01-01 00:00:00 +0000 UTC LastTransitionTime:2020-02-12 04:29:09 +0000 UTC Reason: Message:}] Message: Reason: NominatedNodeName: HostIP:10.128.0.4 PodIP:10.64.3.12 StartTime:2020-02-12 04:29:09 +0000 UTC InitContainerStatuses:[{Name:init-volume-pd-csi-storage-gke-io-dynamicpv-bb6k State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:0,Signal:0,Reason:Completed,Message:,StartedAt:2020-02-12 04:29:42 +0000 UTC,FinishedAt:2020-02-12 04:29:42 +0000 UTC,ContainerID:docker://ccc410e8a7e1de52908b2d01f8872519d92f75294877f4181fb57dbca4685875,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:true RestartCount:0 Image:busybox:1.29 ImageID:docker-pullable://busybox@sha256:e004c2cc521c95383aebb1fb5893719aa7a8eae2e7a71f316a4410784edb00a9 ContainerID:docker://ccc410e8a7e1de52908b2d01f8872519d92f75294877f4181fb57dbca4685875}] ContainerStatuses:[{Name:test-container-subpath-pd-csi-storage-gke-io-dynamicpv-bb6k State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:0,Signal:0,Reason:Completed,Message:,StartedAt:2020-02-12 04:29:43 +0000 UTC,FinishedAt:2020-02-12 04:30:03 +0000 UTC,ContainerID:docker://8fe57a6406ba7417449331d25b8c17548a0b22c0d428a46a80b2f729d631d655,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:gcr.io/kubernetes-e2e-test-images/mounttest:1.0 ImageID:docker-pullable://gcr.io/kubernetes-e2e-test-images/mounttest@sha256:c0bd6f0755f42af09a68c9a47fb993136588a76b3200ec305796b60d629d85d2 ContainerID:docker://8fe57a6406ba7417449331d25b8c17548a0b22c0d428a46a80b2f729d631d655} {Name:test-container-volume-pd-csi-storage-gke-io-dynamicpv-bb6k State:{Waiting:nil Running:nil Terminated:&ContainerStateTerminated{ExitCode:128,Signal:0,Reason:ContainerCannotRun,Message:linux runtime spec devices: lstat /dev/sdg: no such file or directory,StartedAt:2020-02-12 04:29:43 +0000 UTC,FinishedAt:2020-02-12 04:29:43 +0000 UTC,ContainerID:docker://defadda080d99a08ace51b46fc986609bc69c2a6758bac5e920e0c4ed04beb02,}} LastTerminationState:{Waiting:nil Running:nil Terminated:nil} Ready:false RestartCount:0 Image:gcr.io/kubernetes-e2e-test-images/mounttest:1.0 ImageID:docker-pullable://gcr.io/kubernetes-e2e-test-images/mounttest@sha256:c0bd6f0755f42af09a68c9a47fb993136588a76b3200ec305796b60d629d85d2 ContainerID:docker://defadda080d99a08ace51b46fc986609bc69c2a6758bac5e920e0c4ed04beb02}] QOSClass:BestEffort}
I0212 04:30:32.240]       not to have occurred
I0212 04:30:32.240] 
I0212 04:30:32.240]       /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/util.go:2395
I0212 04:30:32.240] ------------------------------
I0212 04:30:32.240] Feb 12 04:30:32.113: INFO: Running AfterSuite actions on all nodes
I0212 04:30:32.240] 
... skipping 406 lines ...
I0212 04:30:54.468] STEP: creating a claim
I0212 04:30:54.469] Feb 12 04:29:52.152: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-2d4zg] to have phase Bound
I0212 04:30:54.469] Feb 12 04:29:52.173: INFO: PersistentVolumeClaim pvc-2d4zg found but phase is Pending instead of Bound.
I0212 04:30:54.469] Feb 12 04:29:54.176: INFO: PersistentVolumeClaim pvc-2d4zg found but phase is Pending instead of Bound.
I0212 04:30:54.469] Feb 12 04:29:56.192: INFO: PersistentVolumeClaim pvc-2d4zg found but phase is Pending instead of Bound.
I0212 04:30:54.469] Feb 12 04:29:58.197: INFO: PersistentVolumeClaim pvc-2d4zg found and phase=Bound (6.044842021s)
I0212 04:30:54.469] [It] should fail if subpath with backstepping is outside the volume [Slow]
I0212 04:30:54.470]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:269
I0212 04:30:54.470] STEP: Creating pod pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-djgg
I0212 04:30:54.470] STEP: Checking for subpath error in container status
I0212 04:30:54.470] Feb 12 04:30:20.261: INFO: Deleting pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-djgg" in namespace "e2e-tests-csi-volumes-9bcjs"
I0212 04:30:54.470] Feb 12 04:30:20.275: INFO: Wait up to 5m0s for pod "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-djgg" to be fully deleted
I0212 04:30:54.471] WARNING: pod log: pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-djgg/test-container-subpath-pd-csi-storage-gke-io-dynamicpv-djgg: pods "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-djgg" not found
I0212 04:30:54.471] WARNING: pod log: pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-djgg/test-container-volume-pd-csi-storage-gke-io-dynamicpv-djgg: pods "pod-subpath-test-pd-csi-storage-gke-io-dynamicpv-djgg" not found
I0212 04:30:54.471] [AfterEach] [Testpattern: Dynamic PV (default fs)] subPath
I0212 04:30:54.471]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:120
... skipping 25 lines ...
I0212 04:30:54.475] [sig-storage] CSI Volumes
I0212 04:30:54.475] /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/framework.go:22
I0212 04:30:54.476]   [Driver: pd.csi.storage.gke.io][Feature: gcePD-external]
I0212 04:30:54.476]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/csi_volumes.go:129
I0212 04:30:54.476]     [Testpattern: Dynamic PV (default fs)] subPath
I0212 04:30:54.476]     /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:99
I0212 04:30:54.476]       should fail if subpath with backstepping is outside the volume [Slow]
I0212 04:30:54.476]       /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/subpath.go:269
I0212 04:30:54.477] ------------------------------
I0212 04:30:54.477] Feb 12 04:30:54.466: INFO: Running AfterSuite actions on all nodes
I0212 04:30:54.477] 
I0212 04:30:55.929] 
I0212 04:30:55.929] [BeforeEach] [sig-storage] CSI Volumes
... skipping 280 lines ...
I0212 04:34:08.414] [BeforeEach] [sig-storage] CSI Volumes
I0212 04:34:08.414]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/csi_volumes.go:87
I0212 04:34:08.414] [BeforeEach] [Driver: pd.csi.storage.gke.io][Feature: gcePD-external]
I0212 04:34:08.414]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/csi_volumes.go:132
I0212 04:34:08.415] [BeforeEach] [Testpattern: Dynamic PV (block volmode)] volumeMode
I0212 04:34:08.415]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/volumemode.go:119
I0212 04:34:08.415] [It] should fail in binding dynamic provisioned PV to PVC
I0212 04:34:08.415]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/volumemode.go:315
I0212 04:34:08.416] STEP: Creating sc
I0212 04:34:08.416] STEP: Creating pv and pvc
I0212 04:34:08.416] Feb 12 04:28:53.126: INFO: Waiting up to 5m0s for PersistentVolumeClaims [pvc-frjk7] to have phase Bound
I0212 04:34:08.416] Feb 12 04:28:53.195: INFO: PersistentVolumeClaim pvc-frjk7 found but phase is Pending instead of Bound.
I0212 04:34:08.416] Feb 12 04:28:55.200: INFO: PersistentVolumeClaim pvc-frjk7 found but phase is Pending instead of Bound.
... skipping 167 lines ...
I0212 04:34:08.457] [sig-storage] CSI Volumes
I0212 04:34:08.457] /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/framework.go:22
I0212 04:34:08.457]   [Driver: pd.csi.storage.gke.io][Feature: gcePD-external]
I0212 04:34:08.457]   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/csi_volumes.go:129
I0212 04:34:08.458]     [Testpattern: Dynamic PV (block volmode)] volumeMode
I0212 04:34:08.458]     /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/volumemode.go:109
I0212 04:34:08.458]       should fail in binding dynamic provisioned PV to PVC
I0212 04:34:08.458]       /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/volumemode.go:315
I0212 04:34:08.458] ------------------------------
I0212 04:34:08.458] Feb 12 04:34:08.411: INFO: Running AfterSuite actions on all nodes
I0212 04:34:08.459] 
I0212 04:35:29.453] 
I0212 04:35:29.454] Feb 12 04:30:16.689: INFO: Running AfterSuite actions on all nodes
... skipping 14 lines ...
I0212 04:35:29.456] 
I0212 04:35:29.456] Specify --start=43367 in the next get-serial-port-output invocation to get only the new output starting from here.
I0212 04:35:29.457] scp: /var/log/cluster-autoscaler.log*: No such file or directory
I0212 04:35:29.457] scp: /var/log/fluentd.log*: No such file or directory
I0212 04:35:29.457] scp: /var/log/kubelet.cov*: No such file or directory
I0212 04:35:29.457] scp: /var/log/startupscript.log*: No such file or directory
I0212 04:35:29.457] ERROR: (gcloud.compute.scp) [/usr/bin/scp] exited with return code [1].
I0212 04:35:29.457] Dumping logs from nodes locally to '/workspace/_artifacts'
I0212 04:35:29.458] Detecting nodes in the cluster
I0212 04:35:29.458] Changing logfiles to be world-readable for download
I0212 04:35:29.458] Changing logfiles to be world-readable for download
I0212 04:35:29.458] Changing logfiles to be world-readable for download
I0212 04:35:29.458] Copying 'kube-proxy.log fluentd.log node-problem-detector.log kubelet.cov startupscript.log' from e2e-test-prow-minion-group-bn19
... skipping 6 lines ...
I0212 04:35:29.460] 
I0212 04:35:29.460] Specify --start=62673 in the next get-serial-port-output invocation to get only the new output starting from here.
I0212 04:35:29.460] scp: /var/log/fluentd.log*: No such file or directory
I0212 04:35:29.460] scp: /var/log/node-problem-detector.log*: No such file or directory
I0212 04:35:29.461] scp: /var/log/kubelet.cov*: No such file or directory
I0212 04:35:29.461] scp: /var/log/startupscript.log*: No such file or directory
I0212 04:35:29.461] ERROR: (gcloud.compute.scp) [/usr/bin/scp] exited with return code [1].
I0212 04:35:29.461] scp: /var/log/fluentd.log*: No such file or directory
I0212 04:35:29.461] scp: /var/log/node-problem-detector.log*: No such file or directory
I0212 04:35:29.462] scp: /var/log/kubelet.cov*: No such file or directory
I0212 04:35:29.462] scp: /var/log/startupscript.log*: No such file or directory
I0212 04:35:29.462] ERROR: (gcloud.compute.scp) [/usr/bin/scp] exited with return code [1].
I0212 04:35:29.462] scp: /var/log/fluentd.log*: No such file or directory
I0212 04:35:29.462] scp: /var/log/node-problem-detector.log*: No such file or directory
I0212 04:35:29.462] scp: /var/log/kubelet.cov*: No such file or directory
I0212 04:35:29.463] scp: /var/log/startupscript.log*: No such file or directory
I0212 04:35:29.463] ERROR: (gcloud.compute.scp) [/usr/bin/scp] exited with return code [1].
I0212 04:35:29.463] 
I0212 04:35:29.463] 
I0212 04:35:29.463] 
I0212 04:35:29.463] Summarizing 1 Failure:
I0212 04:35:29.463] 
I0212 04:35:29.464] [Fail] [sig-storage] CSI Volumes [Driver: pd.csi.storage.gke.io][Feature: gcePD-external] [Testpattern: Dynamic PV (default fs)] subPath [It] should support file as subpath 
I0212 04:35:29.464] /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/util.go:2395
I0212 04:35:29.464] 
I0212 04:35:29.464] Ran 27 of 2161 Specs in 470.447 seconds
I0212 04:35:29.470] FAIL! -- 26 Passed | 1 Failed | 0 Pending | 2134 Skipped 
I0212 04:35:29.471] 
I0212 04:35:29.471] Ginkgo ran 1 suite in 7m53.971696186s
I0212 04:35:29.471] Test Suite Failed
I0212 04:35:29.489] Deleting driver
I0212 04:35:29.493] PKGDIR is /go/src/sigs.k8s.io/gcp-compute-persistent-disk-csi-driver
W0212 04:35:29.594] !!! Error in ./hack/ginkgo-e2e.sh:143
W0212 04:35:29.596]   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 04:35:29.596] Call stack:
W0212 04:35:29.596]   1: ./hack/ginkgo-e2e.sh:143 main(...)
W0212 04:35:29.597] Exiting with status 1
W0212 04:35:29.597] 2020/02/12 04:35:29 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 7m55.115635723s
W0212 04:35:29.597] 2020/02/12 04:35:29 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 04:35:29.716] I0212 04:35:29.716042   65491 loader.go:359] Config loaded from file /root/.kube/config
W0212 04:35:29.717] I0212 04:35:29.717756   65491 loader.go:359] Config loaded from file /root/.kube/config
W0212 04:35:29.720] I0212 04:35:29.720196   65491 loader.go:359] Config loaded from file /root/.kube/config
W0212 04:35:29.720] I0212 04:35:29.720743   65491 decoder.go:224] decoding stream as YAML
W0212 04:35:29.722] I0212 04:35:29.722384   65491 loader.go:359] Config loaded from file /root/.kube/config
W0212 04:35:29.733] I0212 04:35:29.733552   65491 loader.go:359] Config loaded from file /root/.kube/config
... skipping 268 lines ...
W0212 04:35:48.072] NODE_NAMES=e2e-test-prow-minion-group-bn19 e2e-test-prow-minion-group-d1kk e2e-test-prow-minion-group-hfg7
I0212 04:35:48.173] Bringing down cluster
W0212 04:35:50.847] Deleting Managed Instance Group...
W0212 04:38:28.569] ..................................Deleted [https://www.googleapis.com/compute/v1/projects/k8s-jkns-gce-ingress1-4/zones/us-central1-b/instanceGroupManagers/e2e-test-prow-minion-group].
W0212 04:38:28.570] done.
W0212 04:38:32.452] Deleted [https://www.googleapis.com/compute/v1/projects/k8s-jkns-gce-ingress1-4/global/instanceTemplates/e2e-test-prow-minion-template].
I0212 04:38:36.703] {"message":"Internal Server Error"}Removing etcd replica, name: e2e-test-prow-master, port: 2379, result: 0
I0212 04:38:37.850] {"message":"Internal Server Error"}Removing etcd replica, name: e2e-test-prow-master, port: 4002, result: 0
W0212 04:38:42.753] Updated [https://www.googleapis.com/compute/v1/projects/k8s-jkns-gce-ingress1-4/zones/us-central1-b/instances/e2e-test-prow-master].
W0212 04:41:16.001] Deleted [https://www.googleapis.com/compute/v1/projects/k8s-jkns-gce-ingress1-4/zones/us-central1-b/instances/e2e-test-prow-master].
W0212 04:41:32.173] Deleted [https://www.googleapis.com/compute/v1/projects/k8s-jkns-gce-ingress1-4/global/firewalls/e2e-test-prow-master-https].
W0212 04:41:32.679] Deleted [https://www.googleapis.com/compute/v1/projects/k8s-jkns-gce-ingress1-4/global/firewalls/e2e-test-prow-master-etcd].
W0212 04:41:33.668] Deleted [https://www.googleapis.com/compute/v1/projects/k8s-jkns-gce-ingress1-4/global/firewalls/e2e-test-prow-minion-all].
W0212 04:41:39.500] Deleted [https://www.googleapis.com/compute/v1/projects/k8s-jkns-gce-ingress1-4/regions/us-central1/addresses/e2e-test-prow-master-ip].
... skipping 8 lines ...
I0212 04:42:45.271] Property "clusters.k8s-jkns-gce-ingress1-4_e2e-test-prow" unset.
I0212 04:42:45.414] Property "users.k8s-jkns-gce-ingress1-4_e2e-test-prow" unset.
I0212 04:42:45.553] Property "users.k8s-jkns-gce-ingress1-4_e2e-test-prow-basic-auth" unset.
I0212 04:42:45.692] Property "contexts.k8s-jkns-gce-ingress1-4_e2e-test-prow" unset.
I0212 04:42:45.697] Cleared config for k8s-jkns-gce-ingress1-4_e2e-test-prow from /root/.kube/config
I0212 04:42:45.697] Done
W0212 04:42:46.299] F0212 04:42:46.299685    1168 main.go:68] Failed to run integration test: failed to run tests: failed to run tests on e2e cluster: exit status 1
W0212 04:42:46.306] Traceback (most recent call last):
W0212 04:42:46.306]   File "/workspace/./test-infra/jenkins/../scenarios/execute.py", line 50, in <module>
W0212 04:42:46.306]     main(ARGS.env, ARGS.cmd + ARGS.args)
W0212 04:42:46.306]   File "/workspace/./test-infra/jenkins/../scenarios/execute.py", line 41, in main
W0212 04:42:46.307]     check(*cmd)
W0212 04:42:46.307]   File "/workspace/./test-infra/jenkins/../scenarios/execute.py", line 30, in check
W0212 04:42:46.307]     subprocess.check_call(cmd)
W0212 04:42:46.307]   File "/usr/lib/python2.7/subprocess.py", line 190, in check_call
W0212 04:42:46.307]     raise CalledProcessError(retcode, cmd)
W0212 04:42:46.308] subprocess.CalledProcessError: Command '('test/run-k8s-integration.sh',)' returned non-zero exit status 255
E0212 04:42:46.316] Command failed
I0212 04:42:46.316] process 441 exited with code 1 after 50.5m
E0212 04:42:46.316] FAIL: ci-gcp-compute-persistent-disk-csi-driver-release-0-4-k8s-1-13-5-integration
I0212 04:42:46.317] Call:  gcloud auth activate-service-account --key-file=/etc/service-account/service-account.json
W0212 04:42:46.938] Activated service account credentials for: [pr-kubekins@kubernetes-jenkins-pull.iam.gserviceaccount.com]
I0212 04:42:47.009] process 66444 exited with code 0 after 0.0m
I0212 04:42:47.010] Call:  gcloud config get-value account
I0212 04:42:47.504] process 66457 exited with code 0 after 0.0m
I0212 04:42:47.504] Will upload results to gs://kubernetes-jenkins/logs using pr-kubekins@kubernetes-jenkins-pull.iam.gserviceaccount.com
I0212 04:42:47.504] Upload result and artifacts...
I0212 04:42:47.505] 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/1227440039231754240
I0212 04:42:47.506] Call:  gsutil ls gs://kubernetes-jenkins/logs/ci-gcp-compute-persistent-disk-csi-driver-release-0-4-k8s-1-13-5-integration/1227440039231754240/artifacts
W0212 04:42:49.123] CommandException: One or more URLs matched no objects.
E0212 04:42:49.329] Command failed
I0212 04:42:49.330] process 66470 exited with code 1 after 0.0m
W0212 04:42:49.330] Remote dir gs://kubernetes-jenkins/logs/ci-gcp-compute-persistent-disk-csi-driver-release-0-4-k8s-1-13-5-integration/1227440039231754240/artifacts not exist yet
I0212 04:42:49.330] 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/1227440039231754240/artifacts
I0212 04:43:00.399] process 66615 exited with code 0 after 0.2m
W0212 04:43:00.400] metadata path /workspace/_artifacts/metadata.json does not exist
W0212 04:43:00.400] metadata not found or invalid, init with empty metadata
... skipping 15 lines ...