e2e waiting for dc timed out flake

[stevekuznetsov]

Flake in e2e here:

[INFO] Waiting for command to finish: 'oc get rc/failing-dc-1 --template={{.metadata.annotations}} | grep openshift.io/deployment.phase:Failed'...
[ ERR] Gave up waiting for: 'oc get rc/failing-dc-1 --template={{.metadata.annotations}} | grep openshift.io/deployment.phase:Failed'

[FAIL] !!!!! Test Failed !!!!

[deads2k]

On a recent run, I saw the a 30 second pause between: https://github.com/openshift/origin/blob/master/Godeps/_workspace/src/k8s.io/kubernetes/pkg/kubelet/dockertools/manager.go#L774 and https://github.com/openshift/origin/blob/master/Godeps/_workspace/src/k8s.io/kubernetes/pkg/kubelet/dockertools/manager.go#L787 as observed by the log

I0119 16:43:55.623942    5487 manager.go:774] Container test/failing-dc-1-deploy/POD: setting entrypoint "[]" and command "[]"

and the event

- apiVersion: v1
  count: 1
  firstTimestamp: 2016-01-19T16:44:34Z
  involvedObject:
    apiVersion: v1
    fieldPath: implicitly required container POD
    kind: Pod
    name: failing-dc-1-deploy
    namespace: test
    resourceVersion: "612"
    uid: d434b476-becb-11e5-8ee6-0eedf2df3a43
  kind: Event
  lastTimestamp: 2016-01-19T16:44:34Z
  message: Created with docker id 4128ed24c02d
  metadata:
    creationTimestamp: 2016-01-19T16:44:34Z
    name: failing-dc-1-deploy.142ae19864e5898a
    namespace: test
    resourceVersion: "115"
    selfLink: /api/v1/namespaces/test/events/failing-dc-1-deploy.142ae19864e5898a
    uid: eb8f751c-becb-11e5-8ee6-0eedf2df3a43
  reason: Created
  source:
    component: kubelet
    host: ip-172-18-8-143.ec2.internal

[deads2k]

I should add the call would have eventually succeeded based on these snippets:

I0119 16:43:55.289046    5487 factory.go:220] About to try and schedule pod failing-dc-1-deploy

I0119 16:43:55.615285    5487 rest.go:118] Deployment test/failing-dc-1 is in Pending state, waiting for it to start...

I0119 16:43:55.623942    5487 manager.go:774] Container test/failing-dc-1-deploy/POD: setting entrypoint "[]" and command "[]"
I0119 16:43:55.624219    5487 server.go:736] Event(api.ObjectReference{Kind:"Pod", Namespace:"test", Name:"failing-dc-1-deploy", UID:"d434b476-becb-11e5-8ee6-0eedf2df3a43", APIVersion:"v1", ResourceVersion:"612", FieldPath:"implicitly required container POD"}): reason: 'Pulled' Container image "openshift/origin-pod:7274051" already present on machine

I0119 16:44:35.322048    5487 controller.go:111] Updated Deployment test/failing-dc-1 status from Pending to Running

and the events showing:

- apiVersion: v1
  count: 1
  firstTimestamp: 2016-01-19T16:44:35Z
  involvedObject:
    apiVersion: v1
    fieldPath: spec.containers{deployment}
    kind: Pod
    name: failing-dc-1-deploy
    namespace: test
    resourceVersion: "612"
    uid: d434b476-becb-11e5-8ee6-0eedf2df3a43
  kind: Event
  lastTimestamp: 2016-01-19T16:44:35Z
  message: Started with docker id ae53ed30b454
  metadata:
    creationTimestamp: 2016-01-19T16:44:35Z
    name: failing-dc-1-deploy.142ae1989517c35b
    namespace: test
    resourceVersion: "128"
    selfLink: /api/v1/namespaces/test/events/failing-dc-1-deploy.142ae1989517c35b
    uid: ec0974b2-becb-11e5-8ee6-0eedf2df3a43
  reason: Started
  source:
    component: kubelet
    host: ip-172-18-8-143.ec2.internal

In that time we saw:

E0119 16:44:04.811188    5487 etcd.go:150] etcd failure response: HTTP/1.1 500 Internal Server Error
E0119 16:44:14.766616    5487 etcd.go:150] etcd failure response: HTTP/1.1 500 Internal Server Error

In close proximity to:

I0119 16:44:07.759769    5487 trace.go:57] Trace "Update *api.Node" (started 2016-01-19 16:43:57.809063718 +0000 UTC):
[9.950676825s] [9.950676825s] END
I0119 16:44:17.247243    5487 trace.go:57] Trace "Update *api.Node" (started 2016-01-19 16:44:07.764999044 +0000 UTC):
[9.482220915s] [9.482220915s] END

This all adds up to "the machine suddenly and dramatically slowed down in the 16:44 minute. My kingdom for the utilization numbers.

Also, @danmcp the artifacts seems to have disappeared from my run: https://ci.openshift.redhat.com/jenkins/job/test_pull_requests_origin/8874/. Aggressive cleaning?

[danmcp]

@deads2k We keep the artifacts for the last 20 runs. We used to keep 50 until someone starting writing 20GB of data per test run.

[deads2k]

@deads2k We keep the artifacts for the last 20 runs. We used to keep 50 until someone starting writing 20GB of data per test run.

Quota gone wild!

We need to bump that number of previous runs up since we're running them two at a time. I turned my back for 2 hours and my artifacts were gone. Can we prefer to prune successful artifacts (figuring they're all showing the same thing) until we're size pressure?

[stevekuznetsov]

If we're under size constraints there are some optimizations that can be made for what we choose to write to disk. For instance, I left the plaintext data for syslogging used to generate the plots as well as the same data in the binary from the logger...

[smarterclayton]

This is the etcd timeout issue.