Bug 1381689

Summary: Build stuck in pending for almost a minute
Product: OpenShift Online Reporter: Steve Speicher <sspeiche>
Component: PodAssignee: Derek Carr <decarr>
Status: CLOSED WORKSFORME QA Contact: DeShuai Ma <dma>
Severity: high Docs Contact:
Priority: unspecified    
Version: 3.xCC: aos-bugs, bleanhar, jokerman, mmccomas, sspeiche
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2016-10-13 20:42:22 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:

Description Steve Speicher 2016-10-04 18:21:25 UTC
Description of problem:
When I manually kick off a build, I get a long delay (pending state) before the build is running. Once it starts running, it takes an expected amount of time.

Version-Release number of selected component (if applicable):
OpenShift Online Dev Preview (prod)
OpenShift Master: v3.3.0.33
Kubernetes Master: v1.3.0+52492b4


How reproducible:
Create project and app, I used nodejs-ex with defaults. Repeat the build process a number of times, it occurred on my 13th build. Unlucky 13 maybe?

Expected results:
To take <5s to from the time I click "start build" to when the build is running.

Additional info:

Hard to see from 'oc describe' (but I witnessed it a couple times from the UI)
Events:
  FirstSeen	LastSeen	Count	From					SubobjectPath			Type		Reason		Message
  ---------	--------	-----	----					-------------			--------	------		-------
  1h		1h		1	{default-scheduler }							Normal		Scheduled	Successfully assigned njs-13-build to ip-172-31-10-162.ec2.internal
  1h		1h		1	{kubelet ip-172-31-10-162.ec2.internal}	spec.containers{sti-build}	Normal		Pulling		pulling image "registry.ops.openshift.com/openshift3/ose-sti-builder:v3.3.0.33"
  1h		1h		1	{kubelet ip-172-31-10-162.ec2.internal}	spec.containers{sti-build}	Normal		Pulled		Successfully pulled image "registry.ops.openshift.com/openshift3/ose-sti-builder:v3.3.0.33"
  1h		1h		1	{kubelet ip-172-31-10-162.ec2.internal}	spec.containers{sti-build}	Normal		Created		Created container with docker id e460f8d10a8a
  1h		1h		1	{kubelet ip-172-31-10-162.ec2.internal}	spec.containers{sti-build}	Normal		Started		Started container with docker id e460f8d10a8a


Vital pieces from events json:
       {
            "count": 1,
            "firstTimestamp": "2016-10-04T17:13:42Z",
            "involvedObject": {
                "apiVersion": "v1",
                "kind": "Pod",
                "name": "njs-13-build",
                "namespace": "sspeiche",
                "resourceVersion": "205130796",
                "uid": "e67288f1-8a55-11e6-8a06-0ebeb1070c7f"
            },
            "lastTimestamp": "2016-10-04T17:13:42Z",
            "message": "Successfully assigned njs-13-build to ip-172-31-10-162.ec2.internal",
            "metadata": {
                "creationTimestamp": "2016-10-04T17:13:42Z",
                "name": "njs-13-build.147a637e679fd732",
                "namespace": "sspeiche",
                "resourceVersion": "205130799",
                "selfLink": "/api/v1/namespaces/sspeiche/events/njs-13-build.147a637e679fd732",
                "uid": "e6761e5f-8a55-11e6-8a06-0ebeb1070c7f"
            },
            "reason": "Scheduled",
            "source": {
                "component": "default-scheduler"
            },
            "type": "Normal"
        },
        {
            "count": 1,
            "firstTimestamp": "2016-10-04T17:14:39Z",
            "involvedObject": {
                "apiVersion": "v1",
                "fieldPath": "spec.containers{sti-build}",
                "kind": "Pod",
                "name": "njs-13-build",
                "namespace": "sspeiche",
                "resourceVersion": "205130798",
                "uid": "e67288f1-8a55-11e6-8a06-0ebeb1070c7f"
            },
            "lastTimestamp": "2016-10-04T17:14:39Z",
            "message": "pulling image \"registry.ops.openshift.com/openshift3/ose-sti-builder:v3.3.0.33\"",
            "metadata": {
                "creationTimestamp": "2016-10-04T17:14:39Z",
                "name": "njs-13-build.147a638bacfc8b88",
                "namespace": "sspeiche",
                "resourceVersion": "205132635",
                "selfLink": "/api/v1/namespaces/sspeiche/events/njs-13-build.147a638bacfc8b88",
                "uid": "086f9934-8a56-11e6-ba92-0e63b9c1c48f"
            },
            "reason": "Pulling",
            "source": {
                "component": "kubelet",
                "host": "ip-172-31-10-162.ec2.internal"
            },
            "type": "Normal"
        },
        {
            "count": 1,
            "firstTimestamp": "2016-10-04T17:14:40Z",
            "involvedObject": {
                "apiVersion": "v1",
                "fieldPath": "spec.containers{sti-build}",
                "kind": "Pod",
                "name": "njs-13-build",
                "namespace": "sspeiche",
                "resourceVersion": "205130798",
                "uid": "e67288f1-8a55-11e6-8a06-0ebeb1070c7f"
            },
            "lastTimestamp": "2016-10-04T17:14:40Z",
            "message": "Successfully pulled image \"registry.ops.openshift.com/openshift3/ose-sti-builder:v3.3.0.33\"",
            "metadata": {
                "creationTimestamp": "2016-10-04T17:14:40Z",
                "name": "njs-13-build.147a638bd065c8a3",
                "namespace": "sspeiche",
                "resourceVersion": "205132707",
                "selfLink": "/api/v1/namespaces/sspeiche/events/njs-13-build.147a638bd065c8a3",
                "uid": "08ca47cd-8a56-11e6-ba92-0e63b9c1c48f"
            },
            "reason": "Pulled",
            "source": {
                "component": "kubelet",
                "host": "ip-172-31-10-162.ec2.internal"
            },
            "type": "Normal"
        },
        {
            "count": 1,
            "firstTimestamp": "2016-10-04T17:14:41Z",
            "involvedObject": {
                "apiVersion": "v1",
                "fieldPath": "spec.containers{sti-build}",
                "kind": "Pod",
                "name": "njs-13-build",
                "namespace": "sspeiche",
                "resourceVersion": "205130798",
                "uid": "e67288f1-8a55-11e6-8a06-0ebeb1070c7f"
            },
            "lastTimestamp": "2016-10-04T17:14:41Z",
            "message": "Created container with docker id e460f8d10a8a",
            "metadata": {
                "creationTimestamp": "2016-10-04T17:14:41Z",
                "name": "njs-13-build.147a638c0f9bcf2c",
                "namespace": "sspeiche",
                "resourceVersion": "205132782",
                "selfLink": "/api/v1/namespaces/sspeiche/events/njs-13-build.147a638c0f9bcf2c",
                "uid": "096c0b06-8a56-11e6-ba92-0e63b9c1c48f"
            },
            "reason": "Created",
            "source": {
                "component": "kubelet",
                "host": "ip-172-31-10-162.ec2.internal"
            },
            "type": "Normal"
        },
        {
            "count": 1,
            "firstTimestamp": "2016-10-04T17:14:41Z",
            "involvedObject": {
                "apiVersion": "v1",
                "fieldPath": "spec.containers{sti-build}",
                "kind": "Pod",
                "name": "njs-13-build",
                "namespace": "sspeiche",
                "resourceVersion": "205130798",
                "uid": "e67288f1-8a55-11e6-8a06-0ebeb1070c7f"
            },
            "lastTimestamp": "2016-10-04T17:14:41Z",
            "message": "Started container with docker id e460f8d10a8a",
            "metadata": {
                "creationTimestamp": "2016-10-04T17:14:41Z",
                "name": "njs-13-build.147a638c2265b4d6",
                "namespace": "sspeiche",
                "resourceVersion": "205132800",
                "selfLink": "/api/v1/namespaces/sspeiche/events/njs-13-build.147a638c2265b4d6",
                "uid": "099c1e1e-8a56-11e6-ba92-0e63b9c1c48f"
            },
            "reason": "Started",
            "source": {
                "component": "kubelet",
                "host": "ip-172-31-10-162.ec2.internal"
            },
            "type": "Normal"
        }

Comment 1 Cesar Wong 2016-10-04 18:26:30 UTC
From the time that the pod is assigned to the node til the time it starts pulling the image, it's about 1 minute. It seems like the node is taking its time with creating the container.

Comment 2 Steve Speicher 2016-10-04 18:49:51 UTC
(In reply to Steve Speicher from comment #0)
> Description of problem:
> When I manually kick off a build, I get a long delay (pending state) before
> the build is running. Once it starts running, it takes an expected amount of
> time.
Correction, stuck in "New". Hit it again with build #30.

Comment 3 Derek Carr 2016-10-04 19:41:01 UTC
What was the creation time for the pod?

I see the delay from scheduling until kubelet acknowleding the pod was scheduled.  Not much I can do about the image pull time.  I am wondering if you saw an additional delay from point of pod creation to actual scheduling occurring.

Comment 4 Steve Speicher 2016-10-05 21:02:35 UTC
@Derek, I don't have the pod info anymore. JSON above is all I have unless dakini has more logs from her end.

Comment 5 Brenton Leanhardt 2016-10-13 20:12:56 UTC
Hi Steve,

Is this still happening?

Comment 6 Steve Speicher 2016-10-13 20:42:22 UTC
(In reply to Brenton Leanhardt from comment #5)
> Hi Steve,
> 
> Is this still happening?

I'm not seeing it anymore. What did you do?

Comment 7 Brenton Leanhardt 2016-10-13 20:56:13 UTC
I don't think anyone has done anything yet.  Just trying to get an idea if this bug is reproducible or not or if we should close it.