LimitRange defaults flake

[bparees]

• Failure in Spec Teardown (AfterEach) [300.360 seconds]
[k8s.io] LimitRange
/data/src/github.com/openshift/origin/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:793
  should create a LimitRange with defaults and ensure pod has those defaults applied. [AfterEach]
  /data/src/github.com/openshift/origin/vendor/k8s.io/kubernetes/test/e2e/limit_range.go:102

  Sep 26 03:54:52.649: Couldn't delete ns: "e2e-tests-limitrange-c4yb1": namespace e2e-tests-limitrange-c4yb1 was not deleted with limit: timed out waiting for the condition, namespace is empty but is not yet removed (&errors.errorString{s:"namespace e2e-tests-limitrange-c4yb1 was not deleted with limit: timed out waiting for the condition, namespace is empty but is not yet removed"})

  /data/src/github.com/openshift/origin/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:338

as seen in:
https://ci.openshift.redhat.com/jenkins/job/test_pull_requests_origin_conformance/6466/consoleFull

[gnufied]

@derekwaynecarr are you working on this? If not I would like to take a stab at it?

[derekwaynecarr]

Please do.

On Wednesday, October 5, 2016, Hemant Kumar notifications@github.com
wrote:

@derekwaynecarr https://github.com/derekwaynecarr are you working on
this? If not I would like to take a stab at it?

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
#11094 (comment),
or mute the thread
https://github.com/notifications/unsubscribe-auth/AF8dbIzXm7uBtVMb6KYBHtoMy4LbBzg5ks5qw9qpgaJpZM4KGdMQ
.

[mfojtik]

bumping the priority as this can be seen more and more often.

[gnufied]

So far from my debugging, I have found following:

# request to delete namespace received
110427:I1010 13:28:50.104496   13879 audit.go:97] AUDIT: id="db017281-5cda-4eab-81f7-4cc4cc031cc4" ip="xxxxx.xxxx" method="DELETE" user="system:serviceaccount:openshift-infra:namespace-controller" as="<self>" asgroups="" namespace="e2e-tests-limitrange-9t4ap" uri="/api/v1/namespaces/e2e-tests-limitrange-9t4ap"
# response for delete request
110460:I1010 13:28:50.145487   13879 audit.go:25] AUDIT: id="db017281-5cda-4eab-81f7-4cc4cc031cc4" response="200"
# check if namespace was truly deleted
110468:I1010 13:28:50.171589   13879 audit.go:97] AUDIT: id="3c66e5dc-eb8f-41cf-a8c4-3effe4d68262" ip="xxxxxx.xxxx.xxxx" method="GET" user="system:serviceaccount:openshift-infra:namespace-controller" as="<self>" asgroups="" namespace="e2e-tests-limitrange-9t4ap" uri="/api/v1/namespaces/e2e-tests-limitrange-9t4ap"
110469-I1010 13:28:50.173091   13879 audit.go:25] AUDIT: id="3c66e5dc-eb8f-41cf-a8c4-3effe4d68262" response="404"

And yet the conformance test logs print:

Oct 10 13:22:56.858: INFO: Waiting up to 1m0s for all nodes to be ready
STEP: Destroying namespace "e2e-tests-limitrange-9t4ap" for this suite.
Oct 10 13:27:56.903: INFO: Couldn't delete ns: "e2e-tests-limitrange-9t4ap": namespace

Which makes it look like 5 minute timeout is sometimes not enough for namespace to be deleted. I am thinking of increasing Namespace deletion timeout just for this e2e test case.

[gnufied]

I have opened a PR in upstream repo - kubernetes/kubernetes#34614

[0xmichalis]

Another instance of this in the deployment suite:
https://ci.openshift.redhat.com/jenkins/job/test_pull_requests_origin_conformance/7195/testReport/junit/(root)/Extended/deploymentconfigs_when_run_iteratively__Conformance__should_immediately_start_a_new_deployment/

cc: @mfojtik

[gnufied]

So I ran some comparison between time taken to delete a namespace in openshift vs k8s:

For OpenShift

Time taken for deleting namespace 240.018105771
Time taken for deleting namespace 240.005871789

For k8s:

Time is took to delete a namespace is 125.002902668
Time is took to delete a namespace is 205.002347593
Time is took to delete a namespace is 125.002965305

This is running on same hardware btw. @liggitt What you think? Can we merge the flake PR?

[liggitt]

those times are in seconds? is this test creating any openshift resources or just kube resources?

[gnufied]

The times are in seconds yes. The tests are only creating kube resources. In fact - e2e test file(limit_range.go) in kube and origin are identical. But when I did oc get namespace foo -o yaml - there is an additional finalizer listed for namespaces created in openshift .

[liggitt]

@derekwaynecarr do you know why the original namespace finalizer would add 1-2 minutes to clean up a namespace containing no origin resources? Seems like it would be a bunch of list calls returning nothing, then a single finalize call to remove the origin finalizer. Both controllers already retry the finalize call on conflict errors.

[gnufied]

Just to make it clearer - please take above benchmarks with pinch of salt. I only posted highest values I saw. The time taken varies between 20s to 240s in case of origin and 20s to 205s in case of k8s.

I am looking at bits of code that gets invoked when a namespace is deleted.

[liggitt]

Right, but I'd expect 2-3 seconds overhead for the origin namespace max

[gnufied]

@liggitt @derekwaynecarr so I did some more debugging around this and found that - origin finalizer is actually running multiple times when a namespace is deleted. And it isn't running multiple times because previous invocation of finalizer failed or something, but it is running even if previous invocation deleted all the origin resources and was successful.

So basically this https://github.com/openshift/origin/blob/master/pkg/project/admission/lifecycle/admission.go#L52 code runs again and again (like 5-10 times) while the namespace is being deleted and it adds back the previously deleted openshift finalizer.

I tried printing attributes of admission when this happens and got something like:

I1026 10:14:38.653781   20125 admission.go:53] dspace lotr ~~~ calling Admin for - :e2e-tests-limitrange-puldo:events::CREATE
I1026 10:14:38.703963   20125 admission.go:53] dspace lotr ~~~ calling Admin for - :e2e-tests-limitrange-puldo:events::CREATE
I1026 10:14:38.804018   20125 admission.go:53] dspace lotr ~~~ calling Admin for - :e2e-tests-limitrange-puldo:events::CREATE
I1026 10:14:38.856005   20125 admission.go:53] dspace lotr ~~~ calling Admin for - :e2e-tests-limitrange-puldo:events::CREATE

[liggitt]

caused by the project lifecycle admission plugin re-adding the origin finalizer when admitting creations to a terminating namespace

the plugin used to check if the namespace was terminating and reject out-of-hand, but that meant a rapid (delete ns, create ns, create resource) would either fail (if the plugin rejected if it thought the ns was terminating), or incorrectly not add the origin finalizer (if the plugin skipped adding the finalizer if it thought the ns was terminating)

mustfix for 1.4

[liggitt]

debugged back to before the rebase onto kube 1.4 and still encountered the issue