This job view page is being replaced by Spyglass soon. Check out the new job view.
PRbertinatto: Add storage tests for Azure File in-tree storage plugin
ResultABORTED
Tests 0 failed / 32 succeeded
Started2021-11-25 12:25
Elapsed55m32s
Revisiond67e1ef1e5be69a6a0d8307408a431a3a97ef3bd
Refs 106678

No Test Failures!


Show 32 Passed Tests

Error lines from build-log.txt

... skipping 714 lines ...
Looking for address 'e2e-106678-95a39-master-ip'
Looking for address 'e2e-106678-95a39-master-internal-ip'
Using master: e2e-106678-95a39-master (external IP: 35.231.217.222; internal IP: 10.40.0.2)
Waiting up to 300 seconds for cluster initialization.

  This will continually check to see if the API for kubernetes is reachable.
  This may time out if there was some uncaught error during start up.

Kubernetes cluster created.
Cluster "k8s-infra-e2e-boskos-scale-07_e2e-106678-95a39" set.
User "k8s-infra-e2e-boskos-scale-07_e2e-106678-95a39" set.
Context "k8s-infra-e2e-boskos-scale-07_e2e-106678-95a39" created.
Switched to context "k8s-infra-e2e-boskos-scale-07_e2e-106678-95a39".
... skipping 227 lines ...
e2e-106678-95a39-minion-group-xq3f   Ready                         <none>   59s    v1.24.0-alpha.0.9+9a80291fc00d84
e2e-106678-95a39-minion-group-z0m1   Ready                         <none>   61s    v1.24.0-alpha.0.9+9a80291fc00d84
e2e-106678-95a39-minion-heapster     Ready                         <none>   91s    v1.24.0-alpha.0.9+9a80291fc00d84
Warning: v1 ComponentStatus is deprecated in v1.19+
Validate output:
Warning: v1 ComponentStatus is deprecated in v1.19+
NAME                 STATUS    MESSAGE                         ERROR
etcd-0               Healthy   {"health":"true","reason":""}   
etcd-1               Healthy   {"health":"true","reason":""}   
scheduler            Healthy   ok                              
controller-manager   Healthy   ok                              
Cluster validation encountered some problems, but cluster should be in working order
...ignoring non-fatal errors in validate-cluster
Done, listing cluster services:

Kubernetes control plane is running at https://35.231.217.222
GLBCDefaultBackend is running at https://35.231.217.222/api/v1/namespaces/kube-system/services/default-http-backend:http/proxy
CoreDNS is running at https://35.231.217.222/api/v1/namespaces/kube-system/services/kube-dns:dns/proxy
Metrics-server is running at https://35.231.217.222/api/v1/namespaces/kube-system/services/https:metrics-server:/proxy
... skipping 333 lines ...
I1125 12:49:11.947476   87528 framework.go:274] Applying /home/prow/go/src/k8s.io/perf-tests/clusterloader2/pkg/prometheus/manifests/default/prometheus-serviceMonitorLegacyKubeDNS.yaml
I1125 12:49:11.983245   87528 prometheus.go:296] Exposing kube-apiserver metrics in the cluster
I1125 12:49:12.121714   87528 framework.go:274] Applying /home/prow/go/src/k8s.io/perf-tests/clusterloader2/pkg/prometheus/manifests/master-ip/master-endpoints.yaml
I1125 12:49:12.157647   87528 framework.go:274] Applying /home/prow/go/src/k8s.io/perf-tests/clusterloader2/pkg/prometheus/manifests/master-ip/master-service.yaml
I1125 12:49:12.196281   87528 framework.go:274] Applying /home/prow/go/src/k8s.io/perf-tests/clusterloader2/pkg/prometheus/manifests/master-ip/master-serviceMonitor.yaml
I1125 12:49:12.233216   87528 prometheus.go:375] Waiting for Prometheus stack to become healthy...
W1125 12:49:42.269844   87528 util.go:72] error while calling prometheus api: the server is currently unable to handle the request (get services http:prometheus-k8s:9090), response: "k8s\x00\n\f\n\x02v1\x12\x06Status\x12]\n\x06\n\x00\x12\x00\x1a\x00\x12\aFailure\x1a3no endpoints available for service \"prometheus-k8s\"\"\x12ServiceUnavailable0\xf7\x03\x1a\x00\"\x00"
I1125 12:50:12.378020   87528 util.go:101] 86/112 targets are ready, example not ready target: {map[endpoint:http-metrics instance:10.40.3.204:10249 job:kube-proxy namespace:kube-system pod:kube-proxy-e2e-106678-95a39-minion-group-f3w5 service:kube-proxy] unknown}
I1125 12:50:42.315987   87528 util.go:104] All 112 expected targets are ready
I1125 12:50:42.389569   87528 util.go:104] All 1 expected targets are ready
I1125 12:50:42.389624   87528 prometheus.go:240] Prometheus stack set up successfully
I1125 12:50:42.389699   87528 exec_service.go:62] Exec service: setting up service!
I1125 12:50:42.495207   87528 framework.go:274] Applying pkg/execservice/manifest/exec_deployment.yaml
... skipping 39 lines ...
I1125 12:51:24.582309   87528 util.go:93] Not enough active targets (0), expected at least (3), waiting for more to become active...
I1125 12:51:24.758846   87528 util.go:93] Not enough active targets (0), expected at least (6), waiting for more to become active...
I1125 12:51:39.582397   87528 util.go:93] Not enough active targets (0), expected at least (3), waiting for more to become active...
I1125 12:51:39.761537   87528 util.go:93] Not enough active targets (0), expected at least (6), waiting for more to become active...
I1125 12:51:54.583386   87528 util.go:93] Not enough active targets (0), expected at least (3), waiting for more to become active...
I1125 12:51:54.757837   87528 util.go:93] Not enough active targets (0), expected at least (6), waiting for more to become active...
E1125 12:51:54.886117   87528 etcd_metrics.go:147] EtcdMetrics: failed to collect etcd database size
I1125 12:52:09.587021   87528 util.go:101] 1/3 targets are ready, example not ready target: {map[container:dns endpoint:metrics instance:10.64.88.3:8080 job:dns namespace:probes pod:dns-7c5f768667-692sm service:dns] unknown}
I1125 12:52:09.761863   87528 util.go:101] 4/6 targets are ready, example not ready target: {map[container:ping-server endpoint:metrics instance:10.64.55.3:8080 job:ping-server namespace:probes pod:ping-server-56d8b8978-wc656 service:ping-server] unknown}
I1125 12:52:24.587132   87528 util.go:104] All 3 expected targets are ready
I1125 12:52:24.587186   87528 prometheus_measurement.go:75] SLOMeasurement has started
I1125 12:52:24.762848   87528 util.go:101] 5/6 targets are ready, example not ready target: {map[container:ping-server endpoint:metrics instance:10.64.55.3:8080 job:ping-server namespace:probes pod:ping-server-56d8b8978-wc656 service:ping-server] unknown}
I1125 12:52:39.769704   87528 util.go:104] All 6 expected targets are ready
... skipping 8 lines ...
I1125 12:52:50.377402   87528 wait_for_controlled_pods.go:175] WaitForControlledPodsRunning: starting wait for controlled pods measurement...
I1125 12:52:50.377511   87528 wait_for_controlled_pods.go:175] WaitForControlledPodsRunning: starting wait for controlled pods measurement...
I1125 12:52:50.377601   87528 wait_for_controlled_pods.go:175] WaitForControlledPodsRunning: starting wait for controlled pods measurement...
I1125 12:52:50.377648   87528 wait_for_controlled_pods.go:175] WaitForControlledPodsRunning: starting wait for controlled pods measurement...
I1125 12:52:50.478432   87528 simple_test_executor.go:173] Step "[step: 05] Starting measurement for 'create objects'" ended
I1125 12:52:50.478460   87528 simple_test_executor.go:145] Step "[step: 06] create objects" started
E1125 12:52:55.423604   87528 etcd_metrics.go:147] EtcdMetrics: failed to collect etcd database size
I1125 12:52:55.689643   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-236): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 12:52:56.096168   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-178): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 12:52:56.218136   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-142): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 12:52:59.207198   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-160): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 12:52:59.231541   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-296): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 12:52:59.626091   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-108): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
... skipping 124 lines ...
I1125 12:53:52.926625   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-261): Pods: 5 out of 5 created, 3 running (3 updated), 2 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 12:53:53.141447   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-74): Pods: 5 out of 5 created, 3 running (3 updated), 2 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 12:53:53.154639   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-165): Pods: 5 out of 5 created, 2 running (2 updated), 3 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 12:53:53.574754   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-290): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 12:53:54.587725   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-212): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 12:53:54.792733   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=medium-deployment-8): Pods: 30 out of 30 created, 30 running (30 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
E1125 12:53:55.967421   87528 etcd_metrics.go:147] EtcdMetrics: failed to collect etcd database size
I1125 12:53:56.125951   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-184): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 12:53:56.515435   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-120): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 12:53:56.600187   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-118): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 12:53:56.640772   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=medium-deployment-3): Pods: 30 out of 30 created, 30 running (30 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 12:53:56.926315   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=big-deployment-0): Pods: 250 out of 250 created, 250 running (250 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 12:53:56.927413   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-57): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
... skipping 155 lines ...
I1125 12:54:53.913719   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-183): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 12:54:54.040631   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-295): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 12:54:54.820282   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-117): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 12:54:54.995225   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-13): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 12:54:55.252690   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-279): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 12:54:55.774058   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=medium-deployment-10): Pods: 30 out of 30 created, 30 running (30 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
E1125 12:54:56.549146   87528 etcd_metrics.go:147] EtcdMetrics: failed to collect etcd database size
I1125 12:54:56.986718   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-47): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 12:54:57.277124   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-109): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 12:54:57.686600   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-156): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 12:54:58.544759   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-263): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 12:54:59.182364   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-278): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 12:54:59.610637   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=medium-deployment-16): Pods: 30 out of 30 created, 30 running (30 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
... skipping 167 lines ...
I1125 12:55:50.603023   87528 phase_latency.go:146] PodStartupLatency: perc50: 0s, perc90: 0s, perc99: 0s
I1125 12:55:50.603347   87528 phase_latency.go:141] PodStartupLatency: 0 worst pod_startup latencies: []
I1125 12:55:50.603363   87528 phase_latency.go:146] PodStartupLatency: perc50: 0s, perc90: 0s, perc99: 0s; threshold 1h0m0s
I1125 12:55:50.603445   87528 simple_test_executor.go:173] Step "[step: 12] Collecting scheduler throughput measurements" ended
I1125 12:55:50.603466   87528 simple_test_executor.go:145] Step "[step: 13] delete scheduler throughput pods" started
I1125 12:55:55.743868   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-2), labelSelector(name=scheduler-throughput-deployment-0): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
E1125 12:55:57.077791   87528 etcd_metrics.go:147] EtcdMetrics: failed to collect etcd database size
I1125 12:56:25.694595   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-3), labelSelector(name=scheduler-throughput-deployment-0): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 12:56:55.693420   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-4), labelSelector(name=scheduler-throughput-deployment-0): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
E1125 12:56:57.621225   87528 etcd_metrics.go:147] EtcdMetrics: failed to collect etcd database size
I1125 12:57:25.694301   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-5), labelSelector(name=scheduler-throughput-deployment-0): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 12:57:55.694409   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-6), labelSelector(name=scheduler-throughput-deployment-0): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
E1125 12:57:58.165550   87528 etcd_metrics.go:147] EtcdMetrics: failed to collect etcd database size
I1125 12:58:25.697389   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-7), labelSelector(name=scheduler-throughput-deployment-0): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 12:58:55.697668   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-8), labelSelector(name=scheduler-throughput-deployment-0): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
E1125 12:58:58.698062   87528 etcd_metrics.go:147] EtcdMetrics: failed to collect etcd database size
I1125 12:59:25.748056   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-9), labelSelector(name=scheduler-throughput-deployment-0): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 12:59:55.699167   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-10), labelSelector(name=scheduler-throughput-deployment-0): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
E1125 12:59:59.236109   87528 etcd_metrics.go:147] EtcdMetrics: failed to collect etcd database size
I1125 13:00:25.699989   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-11), labelSelector(name=scheduler-throughput-deployment-0): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:00:50.614581   87528 simple_test_executor.go:173] Step "[step: 13] delete scheduler throughput pods" ended
I1125 13:00:50.614627   87528 simple_test_executor.go:145] Step "[step: 14] Waiting for scheduler throughput pods to be deleted" started
I1125 13:00:50.614669   87528 wait_for_controlled_pods.go:200] WaitForControlledPodsRunning: waiting for controlled pods measurement...
I1125 13:00:55.666171   87528 wait_for_controlled_pods.go:267] WaitForControlledPodsRunning: running 0, deleted 10, timeout: 0, unknown: 0
I1125 13:00:55.666202   87528 wait_for_controlled_pods.go:281] WaitForControlledPodsRunning: 0/0 Deployments are running with all pods
... skipping 2 lines ...
I1125 13:00:56.100898   87528 simple_test_executor.go:173] Step "[step: 15] delete huge services" ended
I1125 13:00:56.100929   87528 simple_test_executor.go:145] Step "[step: 16] Starting latency pod measurements" started
I1125 13:00:56.100973   87528 wait_for_controlled_pods.go:175] WaitForControlledPodsRunning: starting wait for controlled pods measurement...
I1125 13:00:56.101013   87528 pod_startup_latency.go:127] PodStartupLatency: labelSelector(group = latency): starting pod startup latency measurement...
I1125 13:00:56.201559   87528 simple_test_executor.go:173] Step "[step: 16] Starting latency pod measurements" ended
I1125 13:00:56.201600   87528 simple_test_executor.go:145] Step "[step: 17] Creating latency pods" started
E1125 13:00:59.791719   87528 etcd_metrics.go:147] EtcdMetrics: failed to collect etcd database size
I1125 13:01:01.292115   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-0): Pods: 1 out of 1 created, 1 running (1 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:01:01.489674   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-1): Pods: 1 out of 1 created, 1 running (1 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:01:01.690902   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-2): Pods: 1 out of 1 created, 1 running (1 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:01:01.890048   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-3): Pods: 1 out of 1 created, 1 running (1 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:01:02.091205   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-4): Pods: 1 out of 1 created, 1 running (1 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:01:02.291688   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-5): Pods: 1 out of 1 created, 1 running (1 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
... skipping 283 lines ...
I1125 13:01:59.252641   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-289): Pods: 1 out of 1 created, 1 running (1 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:01:59.451964   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-290): Pods: 1 out of 1 created, 1 running (1 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:01:59.653398   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-291): Pods: 1 out of 1 created, 1 running (1 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:01:59.852635   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-292): Pods: 1 out of 1 created, 1 running (1 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:02:00.052717   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-293): Pods: 1 out of 1 created, 1 running (1 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:02:00.253302   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-294): Pods: 1 out of 1 created, 1 running (1 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
E1125 13:02:00.354093   87528 etcd_metrics.go:147] EtcdMetrics: failed to collect etcd database size
I1125 13:02:00.453611   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-295): Pods: 1 out of 1 created, 1 running (1 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:02:00.656161   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-296): Pods: 1 out of 1 created, 1 running (1 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:02:00.856520   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-297): Pods: 1 out of 1 created, 1 running (1 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:02:01.067492   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-298): Pods: 1 out of 1 created, 1 running (1 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:02:01.255938   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-299): Pods: 1 out of 1 created, 1 running (1 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:02:01.459317   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-300): Pods: 1 out of 1 created, 1 running (1 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
... skipping 270 lines ...
I1125 13:02:59.739387   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-64): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:02:59.940962   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-65): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:03:00.141569   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-66): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:03:00.344937   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-67): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:03:00.543127   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-68): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:03:00.743556   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-69): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
E1125 13:03:00.886696   87528 etcd_metrics.go:147] EtcdMetrics: failed to collect etcd database size
I1125 13:03:00.943137   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-70): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:03:01.143798   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-71): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:03:01.345610   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-72): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:03:01.545359   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-73): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:03:01.746219   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-74): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:03:01.945323   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-75): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
... skipping 290 lines ...
I1125 13:04:00.314926   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-366): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:04:00.515372   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-367): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:04:00.717648   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-368): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:04:00.917520   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-369): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:04:01.118126   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-370): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:04:01.319322   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-371): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
E1125 13:04:01.428767   87528 etcd_metrics.go:147] EtcdMetrics: failed to collect etcd database size
I1125 13:04:01.519716   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-372): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:04:01.720864   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-373): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:04:01.925095   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-374): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:04:02.122380   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-375): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:04:02.322562   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-376): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:04:02.523515   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=latency-deployment-377): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
... skipping 367 lines ...
I1125 13:05:01.392562   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=medium-deployment-12): Pods: 25 out of 25 created, 25 running (25 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:05:01.451163   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-188): Pods: 3 out of 3 created, 3 running (3 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:05:01.748872   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-245): Pods: 3 out of 3 created, 3 running (3 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:05:01.767790   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-12): Pods: 7 out of 7 created, 7 running (7 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:05:01.780822   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-192): Pods: 4 out of 4 created, 4 running (4 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:05:01.979570   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-220): Pods: 7 out of 7 created, 7 running (7 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
E1125 13:05:01.990525   87528 etcd_metrics.go:147] EtcdMetrics: failed to collect etcd database size
I1125 13:05:02.200898   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=medium-deployment-18): Pods: 34 out of 34 created, 34 running (34 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:05:02.387027   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-95): Pods: 2 out of 2 created, 2 running (2 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:05:02.400924   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=medium-job-0): Pods: 40 out of 40 created, 40 running (40 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:05:02.617040   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-31): Pods: 3 out of 3 created, 3 running (3 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:05:02.675818   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-270): Pods: 2 out of 2 created, 2 running (2 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I1125 13:05:02.693909   87528 wait_for_pods.go:96] WaitForControlledPodsRunning: namespace(test-wgtkhm-1), labelSelector(name=small-deployment-264): Pods: 7 out of 7 created, 7 running (7 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
... skipping 120 lines ...