Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Extended.[builds][Conformance] oc new-app should succeed with a --name of 58 characters #14043

Closed
deads2k opened this issue May 4, 2017 · 53 comments
Assignees
Labels
component/apps lifecycle/stale Denotes an issue or PR has remained open with no activity and has become stale. priority/P2
Milestone

Comments

@deads2k
Copy link
Contributor

deads2k commented May 4, 2017

Extended.[builds][Conformance] oc new-app should succeed with a --name of 58 characters

https://ci.openshift.redhat.com/jenkins/job/test_pull_request_origin/1132/

@deads2k deads2k added the kind/test-flake Categorizes issue or PR as related to test flakes. label May 4, 2017
@ncdc
Copy link
Contributor

ncdc commented May 4, 2017

It failed trying to push to the registry (it got a 404). Unfortunately in this test setup, we don't gather any logs from gce. Also, the test code that dumps the registry log is currently broken (I'm fixing it). I'm going to close this because it's impossible to triage. We can reopen if we see it again with appropriate logging.

@bparees
Copy link
Contributor

bparees commented Jun 23, 2017

https://ci.openshift.redhat.com/jenkins/job/merge_pull_request_origin/1092/testReport/junit/(root)/Extended/_builds__Conformance__oc_new_app_should_succeed_with_a___name_of_58_characters/

@mfojtik these are deployment failures
including @jim-minter because he's working on adding better debug dumps when deployments fail in extended tests.

@enj
Copy link
Contributor

enj commented Jun 24, 2017

Seen https://ci.openshift.redhat.com/jenkins/job/test_pull_request_origin/2552/

jUnit
Failed

Extended.[builds][Conformance] oc new-app should succeed with a --name of 58 characters (from (empty))
Failing for the past 1 build (Since Failed#2552 )
Took 2 min 9 sec.
Stacktrace

/openshifttmp/openshift/build-rpm-release/tito/rpmbuild-originE1K0LZ/BUILD/origin-3.6.0/_output/local/go/src/github.com/openshift/origin/test/extended/builds/new_app.go:44
Expected error:
    <*errors.errorString | 0xc421ef52e0>: {
        s: "The deployment \"a234567890123456789012345678901234567890123456789012345678\" status is \"Failed\"",
    }
    The deployment "a234567890123456789012345678901234567890123456789012345678" status is "Failed"
not to have occurred
/openshifttmp/openshift/build-rpm-release/tito/rpmbuild-originE1K0LZ/BUILD/origin-3.6.0/_output/local/go/src/github.com/openshift/origin/test/extended/builds/new_app.go:43

Standard Output

[BeforeEach] [Top Level]
  /openshifttmp/openshift/build-rpm-release/tito/rpmbuild-originE1K0LZ/BUILD/origin-3.6.0/_output/local/go/src/github.com/openshift/origin/test/extended/util/test.go:51
[BeforeEach] [builds][Conformance] oc new-app
  /openshifttmp/openshift/build-rpm-release/tito/rpmbuild-originE1K0LZ/BUILD/origin-3.6.0/_output/local/go/src/github.com/openshift/origin/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:120
STEP: Creating a kubernetes client
Jun 23 10:08:36.345: INFO: >>> kubeConfig: /tmp/cluster-admin.kubeconfig

STEP: Building a namespace api object
Jun 23 10:08:36.507: INFO: configPath is now "/tmp/extended-test-new-app-9wtdd-4qx0x-user.kubeconfig"
Jun 23 10:08:36.507: INFO: The user is now "extended-test-new-app-9wtdd-4qx0x-user"
Jun 23 10:08:36.507: INFO: Creating project "extended-test-new-app-9wtdd-4qx0x"
STEP: Waiting for a default service account to be provisioned in namespace
[JustBeforeEach] [builds][Conformance] oc new-app
  /openshifttmp/openshift/build-rpm-release/tito/rpmbuild-originE1K0LZ/BUILD/origin-3.6.0/_output/local/go/src/github.com/openshift/origin/test/extended/builds/new_app.go:27
STEP: waiting for builder service account
[It] should succeed with a --name of 58 characters
  /openshifttmp/openshift/build-rpm-release/tito/rpmbuild-originE1K0LZ/BUILD/origin-3.6.0/_output/local/go/src/github.com/openshift/origin/test/extended/builds/new_app.go:44
STEP: calling oc new-app
Jun 23 10:08:36.995: INFO: Running 'oc new-app --config=/tmp/extended-test-new-app-9wtdd-4qx0x-user.kubeconfig --namespace=extended-test-new-app-9wtdd-4qx0x https://github.com/openshift/nodejs-ex --name a234567890123456789012345678901234567890123456789012345678'
--> Found image cec407c (23 hours old) in image stream "openshift/nodejs" under tag "6" for "nodejs"

    Node.js 6 
    --------- 
    Platform for building and running Node.js 6 applications

    Tags: builder, nodejs, nodejs6

    * The source repository appears to match: nodejs
    * A source build using source code from https://github.com/openshift/nodejs-ex will be created
      * The resulting image will be pushed to image stream "a234567890123456789012345678901234567890123456789012345678:latest"
      * Use 'start-build' to trigger a new build
    * This image will be deployed in deployment config "a234567890123456789012345678901234567890123456789012345678"
    * Port 8080/tcp will be load balanced by service "a234567890123456789012345678901234567890123456789012345678"
      * Other containers can access this service through the hostname "a234567890123456789012345678901234567890123456789012345678"

--> Creating resources ...
    imagestream "a234567890123456789012345678901234567890123456789012345678" created
    buildconfig "a234567890123456789012345678901234567890123456789012345678" created
    deploymentconfig "a234567890123456789012345678901234567890123456789012345678" created
    service "a234567890123456789012345678901234567890123456789012345678" created
--> Success
    Build scheduled, use 'oc logs -f bc/a234567890123456789012345678901234567890123456789012345678' to track its progress.
    Run 'oc status' to view your app.
STEP: waiting for the build to complete
STEP: waiting for the deployment to complete


Dumping logs for deploymentconfig "a234567890123456789012345678901234567890123456789012345678" in namespace "extended-test-new-app-9wtdd-4qx0x"



Describing deploymentconfig "a234567890123456789012345678901234567890123456789012345678" pod "a2345678901234567890123456789012345678901234567890123456786rswm"
Jun 23 10:10:03.806: INFO: Running 'oc describe --config=/tmp/extended-test-new-app-9wtdd-4qx0x-user.kubeconfig --namespace=extended-test-new-app-9wtdd-4qx0x pod/a2345678901234567890123456789012345678901234567890123456786rswm'
Name:			a2345678901234567890123456789012345678901234567890123456786rswm
Namespace:		extended-test-new-app-9wtdd-4qx0x
Security Policy:	restricted
Node:			ci-prtest-5a37c28-3544-ig-n-c4xx/10.128.0.3
Start Time:		Fri, 23 Jun 2017 10:09:59 -0400
Labels:			app=a234567890123456789012345678901234567890123456789012345678
			deployment=a234567890123456789012345678901234567890123456789012345678-1
			deploymentconfig=a234567890123456789012345678901234567890123456789012345678
Annotations:		kubernetes.io/created-by={"kind":"SerializedReference","apiVersion":"v1","reference":{"kind":"ReplicationController","namespace":"extended-test-new-app-9wtdd-4qx0x","name":"a23456789012345678901234567...
			openshift.io/deployment-config.latest-version=1
			openshift.io/deployment-config.name=a234567890123456789012345678901234567890123456789012345678
			openshift.io/deployment.name=a234567890123456789012345678901234567890123456789012345678-1
			openshift.io/generated-by=OpenShiftNewApp
			openshift.io/scc=restricted
Status:			Pending
IP:			
Controllers:		ReplicationController/a234567890123456789012345678901234567890123456789012345678-1
Containers:
  a234567890123456789012345678901234567890123456789012345678:
    Container ID:	
    Image:		172.30.201.114:5000/extended-test-new-app-9wtdd-4qx0x/a234567890123456789012345678901234567890123456789012345678@sha256:3bb7a6a423752a2048e85c711ee61604fe03794c76fd523c20ce05869dfaf281
    Image ID:		
    Port:		8080/TCP
    State:		Waiting
      Reason:		ContainerCreating
    Ready:		False
    Restart Count:	0
    Environment:	<none>
    Mounts:
      /var/run/secrets/kubernetes.io/serviceaccount from default-token-11k6t (ro)
Conditions:
  Type		Status
  Initialized 	True 
  Ready 	False 
  PodScheduled 	True 
Volumes:
  default-token-11k6t:
    Type:	Secret (a volume populated by a Secret)
    SecretName:	default-token-11k6t
    Optional:	false
QoS Class:	BestEffort
Node-Selectors:	role=app
Tolerations:	<none>
Events:
  FirstSeen	LastSeen	Count	From						SubObjectPath									Type		Reason			Message
  ---------	--------	-----	----						-------------									--------	------			-------
  5s		5s		1	default-scheduler														Normal		Scheduled		Successfully assigned a2345678901234567890123456789012345678901234567890123456786rswm to ci-prtest-5a37c28-3544-ig-n-c4xx
  4s		4s		1	kubelet, ci-prtest-5a37c28-3544-ig-n-c4xx	spec.containers{a234567890123456789012345678901234567890123456789012345678}	Normal		Pulling			pulling image "172.30.201.114:5000/extended-test-new-app-9wtdd-4qx0x/a234567890123456789012345678901234567890123456789012345678@sha256:3bb7a6a423752a2048e85c711ee61604fe03794c76fd523c20ce05869dfaf281"
  4s		2s		3	kubelet, ci-prtest-5a37c28-3544-ig-n-c4xx											Warning		DNSSearchForming	Found and omitted duplicated dns domain in host search line: 'cluster.local' during merging with cluster dns domains
  2s		2s		1	kubelet, ci-prtest-5a37c28-3544-ig-n-c4xx	spec.containers{a234567890123456789012345678901234567890123456789012345678}	Normal		Pulled			Successfully pulled image "172.30.201.114:5000/extended-test-new-app-9wtdd-4qx0x/a234567890123456789012345678901234567890123456789012345678@sha256:3bb7a6a423752a2048e85c711ee61604fe03794c76fd523c20ce05869dfaf281"
  2s		2s		1	kubelet, ci-prtest-5a37c28-3544-ig-n-c4xx	spec.containers{a234567890123456789012345678901234567890123456789012345678}	Normal		Created			Created container
  2s		2s		1	kubelet, ci-prtest-5a37c28-3544-ig-n-c4xx	spec.containers{a234567890123456789012345678901234567890123456789012345678}	Normal		Started			Started container



Log for deploymentconfig "a234567890123456789012345678901234567890123456789012345678" pod "a2345678901234567890123456789012345678901234567890123456786rswm"
---->
Jun 23 10:10:04.337: INFO: Running 'oc logs --config=/tmp/extended-test-new-app-9wtdd-4qx0x-user.kubeconfig --namespace=extended-test-new-app-9wtdd-4qx0x pod/a2345678901234567890123456789012345678901234567890123456786rswm'
Environment: 
	DEV_MODE=false
	NODE_ENV=production
	DEBUG_PORT=5858
Launching via npm...
npm info it worked if it ends with ok
npm info using [email protected]
npm info using [email protected]
npm info lifecycle [email protected]~prestart: [email protected]
npm info lifecycle [email protected]~start: [email protected]
> [email protected] start /opt/app-root/src
> node server.js
Server running on http://0.0.0.0:8080
<----end of log for "a2345678901234567890123456789012345678901234567890123456786rswm"
[AfterEach] [builds][Conformance] oc new-app
  /openshifttmp/openshift/build-rpm-release/tito/rpmbuild-originE1K0LZ/BUILD/origin-3.6.0/_output/local/go/src/github.com/openshift/origin/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:121
STEP: Collecting events from namespace "extended-test-new-app-9wtdd-4qx0x".
STEP: Found 30 events.
Jun 23 10:10:04.860: INFO: At 2017-06-23 10:08:38 -0400 EDT - event for a234567890123456789012345678901234567890123456789012345678-1-build: {kubelet ci-prtest-5a37c28-3544-ig-n-c4xx} DNSSearchForming: Found and omitted duplicated dns domain in host search line: 'cluster.local' during merging with cluster dns domains
Jun 23 10:10:04.860: INFO: At 2017-06-23 10:08:38.520560156 -0400 EDT - event for a234567890123456789012345678901234567890123456789012345678: {buildconfig-controller } BuildConfigInstantiateFailed: gave up on Build for BuildConfig extended-test-new-app-9wtdd-4qx0x/a234567890123456789012345678901234567890123456789012345678 (0) due to fatal error: the LastVersion(1) on build config extended-test-new-app-9wtdd-4qx0x/a234567890123456789012345678901234567890123456789012345678 does not match the build request LastVersion(0)
Jun 23 10:10:04.860: INFO: At 2017-06-23 10:08:38.575211719 -0400 EDT - event for a234567890123456789012345678901234567890123456789012345678-1-build: {default-scheduler } Scheduled: Successfully assigned a234567890123456789012345678901234567890123456789012345678-1-build to ci-prtest-5a37c28-3544-ig-n-c4xx
Jun 23 10:10:04.860: INFO: At 2017-06-23 10:08:39.695925753 -0400 EDT - event for a234567890123456789012345678901234567890123456789012345678-1-build: {kubelet ci-prtest-5a37c28-3544-ig-n-c4xx} Pulled: Container image "openshift/origin-sti-builder:v3.6.0-alpha.2" already present on machine
Jun 23 10:10:04.860: INFO: At 2017-06-23 10:08:39.778942351 -0400 EDT - event for a234567890123456789012345678901234567890123456789012345678-1-build: {kubelet ci-prtest-5a37c28-3544-ig-n-c4xx} Created: Created container
Jun 23 10:10:04.860: INFO: At 2017-06-23 10:08:40.031892643 -0400 EDT - event for a234567890123456789012345678901234567890123456789012345678-1-build: {kubelet ci-prtest-5a37c28-3544-ig-n-c4xx} Started: Started container
Jun 23 10:10:04.860: INFO: At 2017-06-23 10:08:40.863607013 -0400 EDT - event for a234567890123456789012345678901234567890123456789012345678-1: {build-controller } BuildStarted: Build extended-test-new-app-9wtdd-4qx0x/a234567890123456789012345678901234567890123456789012345678-1 is now running
Jun 23 10:10:04.860: INFO: At 2017-06-23 10:09:56 -0400 EDT - event for a234567890123456789012345678901234567890123456789012345678-1-deploy: {kubelet ci-prtest-5a37c28-3544-ig-n-nl7c} DNSSearchForming: Found and omitted duplicated dns domain in host search line: 'cluster.local' during merging with cluster dns domains
Jun 23 10:10:04.860: INFO: At 2017-06-23 10:09:56.080852858 -0400 EDT - event for a234567890123456789012345678901234567890123456789012345678: {deploymentconfig-controller } DeploymentCreated: Created new replication controller "a234567890123456789012345678901234567890123456789012345678-1" for version 1
Jun 23 10:10:04.860: INFO: At 2017-06-23 10:09:56.13782711 -0400 EDT - event for a234567890123456789012345678901234567890123456789012345678-1-deploy: {default-scheduler } Scheduled: Successfully assigned a234567890123456789012345678901234567890123456789012345678-1-deploy to ci-prtest-5a37c28-3544-ig-n-nl7c
Jun 23 10:10:04.860: INFO: At 2017-06-23 10:09:58.501474065 -0400 EDT - event for a234567890123456789012345678901234567890123456789012345678-1: {build-controller } BuildCompleted: Build extended-test-new-app-9wtdd-4qx0x/a234567890123456789012345678901234567890123456789012345678-1 completed successfully
Jun 23 10:10:04.860: INFO: At 2017-06-23 10:09:58.709878332 -0400 EDT - event for a234567890123456789012345678901234567890123456789012345678-1-deploy: {kubelet ci-prtest-5a37c28-3544-ig-n-nl7c} Pulled: Container image "openshift/origin-deployer:v3.6.0-alpha.2" already present on machine
Jun 23 10:10:04.860: INFO: At 2017-06-23 10:09:58.824709586 -0400 EDT - event for a234567890123456789012345678901234567890123456789012345678-1-deploy: {kubelet ci-prtest-5a37c28-3544-ig-n-nl7c} Created: Created container
Jun 23 10:10:04.860: INFO: At 2017-06-23 10:09:59.222688319 -0400 EDT - event for a234567890123456789012345678901234567890123456789012345678-1-deploy: {kubelet ci-prtest-5a37c28-3544-ig-n-nl7c} Started: Started container
Jun 23 10:10:04.860: INFO: At 2017-06-23 10:09:59.826566809 -0400 EDT - event for a234567890123456789012345678901234567890123456789012345678-1: {replication-controller } SuccessfulCreate: Created pod: a2345678901234567890123456789012345678901234567890123456786rswm
Jun 23 10:10:04.860: INFO: At 2017-06-23 10:09:59.87523166 -0400 EDT - event for a2345678901234567890123456789012345678901234567890123456786rswm: {default-scheduler } Scheduled: Successfully assigned a2345678901234567890123456789012345678901234567890123456786rswm to ci-prtest-5a37c28-3544-ig-n-c4xx
Jun 23 10:10:04.860: INFO: At 2017-06-23 10:10:00 -0400 EDT - event for a2345678901234567890123456789012345678901234567890123456786rswm: {kubelet ci-prtest-5a37c28-3544-ig-n-c4xx} DNSSearchForming: Found and omitted duplicated dns domain in host search line: 'cluster.local' during merging with cluster dns domains
Jun 23 10:10:04.860: INFO: At 2017-06-23 10:10:00.976129025 -0400 EDT - event for a2345678901234567890123456789012345678901234567890123456786rswm: {kubelet ci-prtest-5a37c28-3544-ig-n-c4xx} Pulling: pulling image "172.30.201.114:5000/extended-test-new-app-9wtdd-4qx0x/a234567890123456789012345678901234567890123456789012345678@sha256:3bb7a6a423752a2048e85c711ee61604fe03794c76fd523c20ce05869dfaf281"
Jun 23 10:10:04.860: INFO: At 2017-06-23 10:10:01 -0400 EDT - event for a234567890123456789012345678901234567890123456789012345678: {deploymentconfig-controller } DeploymentAwaitingCancellation: Deployment of version 2 awaiting cancellation of older running deployments
Jun 23 10:10:04.860: INFO: At 2017-06-23 10:10:01.697788004 -0400 EDT - event for a234567890123456789012345678901234567890123456789012345678: {deploymentconfig-controller } DeploymentCancelled: Cancelled deployment "a234567890123456789012345678901234567890123456789012345678-1" superceded by version 2
Jun 23 10:10:04.860: INFO: At 2017-06-23 10:10:02.443450654 -0400 EDT - event for a2345678901234567890123456789012345678901234567890123456786rswm: {kubelet ci-prtest-5a37c28-3544-ig-n-c4xx} Pulled: Successfully pulled image "172.30.201.114:5000/extended-test-new-app-9wtdd-4qx0x/a234567890123456789012345678901234567890123456789012345678@sha256:3bb7a6a423752a2048e85c711ee61604fe03794c76fd523c20ce05869dfaf281"
Jun 23 10:10:04.860: INFO: At 2017-06-23 10:10:02.654288502 -0400 EDT - event for a2345678901234567890123456789012345678901234567890123456786rswm: {kubelet ci-prtest-5a37c28-3544-ig-n-c4xx} Created: Created container
Jun 23 10:10:04.860: INFO: At 2017-06-23 10:10:02.719506104 -0400 EDT - event for a234567890123456789012345678901234567890123456789012345678-1-deploy: {kubelet ci-prtest-5a37c28-3544-ig-n-nl7c} Killing: Killing container with id docker://deployment:Need to kill Pod
Jun 23 10:10:04.860: INFO: At 2017-06-23 10:10:02.984433686 -0400 EDT - event for a2345678901234567890123456789012345678901234567890123456786rswm: {kubelet ci-prtest-5a37c28-3544-ig-n-c4xx} Started: Started container
Jun 23 10:10:04.860: INFO: At 2017-06-23 10:10:03.738991023 -0400 EDT - event for a234567890123456789012345678901234567890123456789012345678: {deployer-controller } RolloutCancelled: a234567890123456789012345678901234567890123456789012345678-1: Rollout for "extended-test-new-app-9wtdd-4qx0x/a234567890123456789012345678901234567890123456789012345678-1" cancelled
Jun 23 10:10:04.860: INFO: At 2017-06-23 10:10:03.746944183 -0400 EDT - event for a234567890123456789012345678901234567890123456789012345678: {deploymentconfig-controller } DeploymentCreated: Created new replication controller "a234567890123456789012345678901234567890123456789012345678-2" for version 2
Jun 23 10:10:04.860: INFO: At 2017-06-23 10:10:03.781700988 -0400 EDT - event for a234567890123456789012345678901234567890123456789012345678-2-deploy: {default-scheduler } Scheduled: Successfully assigned a234567890123456789012345678901234567890123456789012345678-2-deploy to ci-prtest-5a37c28-3544-ig-n-nl7c
Jun 23 10:10:04.860: INFO: At 2017-06-23 10:10:04 -0400 EDT - event for a234567890123456789012345678901234567890123456789012345678-2-deploy: {kubelet ci-prtest-5a37c28-3544-ig-n-nl7c} DNSSearchForming: Found and omitted duplicated dns domain in host search line: 'cluster.local' during merging with cluster dns domains
Jun 23 10:10:04.860: INFO: At 2017-06-23 10:10:04.70330552 -0400 EDT - event for a234567890123456789012345678901234567890123456789012345678-2-deploy: {kubelet ci-prtest-5a37c28-3544-ig-n-nl7c} Pulled: Container image "openshift/origin-deployer:v3.6.0-alpha.2" already present on machine
Jun 23 10:10:04.860: INFO: At 2017-06-23 10:10:04.775415892 -0400 EDT - event for a234567890123456789012345678901234567890123456789012345678-2-deploy: {kubelet ci-prtest-5a37c28-3544-ig-n-nl7c} Created: Created container
Jun 23 10:10:04.954: INFO: POD                                                                    NODE                              PHASE      GRACE  CONDITIONS
Jun 23 10:10:04.954: INFO: docker-registry-2-crmrp                                                ci-prtest-5a37c28-3544-ig-m-t9p0  Running           [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:04:38 -0400 EDT  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:04:42 -0400 EDT  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:04:38 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: registry-console-1-05qr6                                               ci-prtest-5a37c28-3544-ig-m-t9p0  Running           [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:04:49 -0400 EDT  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:05:19 -0400 EDT  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:04:49 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: router-1-cxpbp                                                         ci-prtest-5a37c28-3544-ig-m-t9p0  Running           [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:02:24 -0400 EDT  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:02:44 -0400 EDT  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:02:24 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: test-webserver-8bde1462-581d-11e7-a677-0e26f8716e8c                    ci-prtest-5a37c28-3544-ig-n-nl7c  Running           [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:18 -0400 EDT  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:18 -0400 EDT ContainersNotReady containers with unready status: [test-webserver]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:18 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: liveness-exec                                                          ci-prtest-5a37c28-3544-ig-n-c4xx  Running           [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:08:00 -0400 EDT  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:08:02 -0400 EDT  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:08:00 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: dns-test-a62601c9-581d-11e7-ac9d-0e26f8716e8c                          ci-prtest-5a37c28-3544-ig-n-rlc0  Pending           [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:10:02 -0400 EDT  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:10:02 -0400 EDT ContainersNotReady containers with unready status: [webserver querier jessie-querier]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:10:02 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: update-demo-nautilus-cp5v7                                             ci-prtest-5a37c28-3544-ig-n-c4xx  Running    30s    [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:55 -0400 EDT  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:59 -0400 EDT  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:55 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: update-demo-nautilus-h3n1x                                             ci-prtest-5a37c28-3544-ig-n-rlc0  Running    30s    [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:55 -0400 EDT  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:59 -0400 EDT  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:55 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: netserver-0                                                            ci-prtest-5a37c28-3544-ig-m-t9p0  Running           [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:58 -0400 EDT  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:58 -0400 EDT ContainersNotReady containers with unready status: [webserver]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:58 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: netserver-1                                                            ci-prtest-5a37c28-3544-ig-n-c4xx  Running           [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:58 -0400 EDT  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:58 -0400 EDT ContainersNotReady containers with unready status: [webserver]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:58 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: netserver-2                                                            ci-prtest-5a37c28-3544-ig-n-nl7c  Running           [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:58 -0400 EDT  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:58 -0400 EDT ContainersNotReady containers with unready status: [webserver]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:58 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: netserver-3                                                            ci-prtest-5a37c28-3544-ig-n-rlc0  Running           [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:58 -0400 EDT  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:58 -0400 EDT ContainersNotReady containers with unready status: [webserver]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:58 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: pod-update-activedeadlineseconds-a20e7c8c-581d-11e7-9a69-0e26f8716e8c  ci-prtest-5a37c28-3544-ig-n-c4xx  Failed            []
Jun 23 10:10:04.954: INFO: optimized-build                                                        ci-prtest-5a37c28-3544-ig-n-rlc0  Succeeded         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:51 -0400 EDT PodCompleted } {Ready False 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:10:01 -0400 EDT PodCompleted } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:51 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: deployment-simple-1-7xrdx                                              ci-prtest-5a37c28-3544-ig-n-rlc0  Running    30s    [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:36 -0400 EDT  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:46 -0400 EDT  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:36 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: deployment-simple-1-gs4mp                                              ci-prtest-5a37c28-3544-ig-n-nl7c  Running    30s    [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:36 -0400 EDT  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:46 -0400 EDT  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:36 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: deployment-simple-2-58hp7                                              ci-prtest-5a37c28-3544-ig-n-nl7c  Running    30s    [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:42 -0400 EDT  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:52 -0400 EDT  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:42 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: deployment-simple-2-m23xs                                              ci-prtest-5a37c28-3544-ig-n-rlc0  Running    30s    [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:42 -0400 EDT  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:52 -0400 EDT  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:42 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: deployment-simple-3-5rnd5                                              ci-prtest-5a37c28-3544-ig-n-rlc0  Running    30s    [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:49 -0400 EDT  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:54 -0400 EDT  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:49 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: deployment-simple-3-nj7r4                                              ci-prtest-5a37c28-3544-ig-n-nl7c  Running    30s    [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:49 -0400 EDT  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:56 -0400 EDT  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:49 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: deployment-simple-4-38rrb                                              ci-prtest-5a37c28-3544-ig-n-c4xx  Running    30s    [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:55 -0400 EDT  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:55 -0400 EDT ContainersNotReady containers with unready status: [myapp]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:55 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: deployment-simple-4-deploy                                             ci-prtest-5a37c28-3544-ig-n-rlc0  Failed     10s    [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:53 -0400 EDT  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:10:00 -0400 EDT ContainersNotReady containers with unready status: [deployment]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:53 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: deployment-simple-4-xgk50                                              ci-prtest-5a37c28-3544-ig-n-rlc0  Running    30s    [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:55 -0400 EDT  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:10:01 -0400 EDT  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:55 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: deployment-simple-5-2lcmw                                              ci-prtest-5a37c28-3544-ig-n-nl7c  Pending           [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:10:04 -0400 EDT  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:10:04 -0400 EDT ContainersNotReady containers with unready status: [myapp]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:10:04 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: deployment-simple-5-deploy                                             ci-prtest-5a37c28-3544-ig-n-c4xx  Running           [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:10:01 -0400 EDT  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:10:04 -0400 EDT  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:10:01 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: deployment-simple-5-hbxfr                                              ci-prtest-5a37c28-3544-ig-n-rlc0  Pending           [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:10:04 -0400 EDT  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:10:04 -0400 EDT ContainersNotReady containers with unready status: [myapp]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:10:04 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: deployment-simple-1-deploy                                             ci-prtest-5a37c28-3544-ig-n-c4xx  Running           [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:10:00 -0400 EDT  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:10:04 -0400 EDT  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:10:00 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: deployment-simple-1-fjmd2                                              ci-prtest-5a37c28-3544-ig-n-c4xx  Pending           [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:10:03 -0400 EDT  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:10:03 -0400 EDT ContainersNotReady containers with unready status: [myapp]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:10:02 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: deployment-simple-1-rgw27                                              ci-prtest-5a37c28-3544-ig-n-nl7c  Pending           [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:10:02 -0400 EDT  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:10:02 -0400 EDT ContainersNotReady containers with unready status: [myapp]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:10:02 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: brokendeployment-1-deploy                                              ci-prtest-5a37c28-3544-ig-n-c4xx  Failed            [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:08:26 -0400 EDT  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:08:31 -0400 EDT ContainersNotReady containers with unready status: [deployment]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:08:26 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: brokendeployment-1-hook-pre                                            ci-prtest-5a37c28-3544-ig-n-rlc0  Failed            [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:08:27 -0400 EDT  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:08:27 -0400 EDT ContainersNotReady containers with unready status: [lifecycle]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:08:27 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: a234567890123456789012345678901234567890123456789012345678-1-build     ci-prtest-5a37c28-3544-ig-n-c4xx  Succeeded         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:08:38 -0400 EDT PodCompleted } {Ready False 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:58 -0400 EDT PodCompleted } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:08:38 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: a234567890123456789012345678901234567890123456789012345678-1-deploy    ci-prtest-5a37c28-3544-ig-n-nl7c  Failed     10s    [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:56 -0400 EDT  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:10:03 -0400 EDT ContainersNotReady containers with unready status: [deployment]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:56 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: a234567890123456789012345678901234567890123456789012345678-2-deploy    ci-prtest-5a37c28-3544-ig-n-nl7c  Pending           [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:10:03 -0400 EDT  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:10:03 -0400 EDT ContainersNotReady containers with unready status: [deployment]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:10:03 -0400 EDT  }]
Jun 23 10:10:04.954: INFO: a2345678901234567890123456789012345678901234567890123456786rswm        ci-prtest-5a37c28-3544-ig-n-c4xx  Running           [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:59 -0400 EDT  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:10:04 -0400 EDT  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-06-23 10:09:59 -0400 EDT  }]
Jun 23 10:10:04.955: INFO: 
Jun 23 10:10:04.990: INFO: 
Logging node info for node ci-prtest-5a37c28-3544-ig-m-t9p0
Jun 23 10:10:05.020: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:ci-prtest-5a37c28-3544-ig-m-t9p0,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/ci-prtest-5a37c28-3544-ig-m-t9p0,UID:354a5171-581c-11e7-bee6-42010a800002,ResourceVersion:19116,Generation:0,CreationTimestamp:2017-06-23 09:59:43.448097509 -0400 EDT,DeletionTimestamp:<nil>,DeletionGracePeriodSeconds:nil,Labels:map[string]string{beta.kubernetes.io/arch: amd64,beta.kubernetes.io/instance-type: n1-standard-2,beta.kubernetes.io/os: linux,failure-domain.beta.kubernetes.io/region: us-central1,failure-domain.beta.kubernetes.io/zone: us-central1-a,kubernetes.io/hostname: ci-prtest-5a37c28-3544-ig-m-t9p0,role: infra,subrole: master,},Annotations:map[string]string{volumes.kubernetes.io/controller-managed-attach-detach: true,},OwnerReferences:[],Finalizers:[],ClusterName:,},Spec:NodeSpec{PodCIDR:,ExternalID:6540016969563809140,ProviderID:gce://openshift-gce-devel-ci/us-central1-a/ci-prtest-5a37c28-3544-ig-m-t9p0,Unschedulable:false,Taints:[],},Status:NodeStatus{Capacity:ResourceList{cpu: {{2 0} {<nil>} 2 DecimalSI},memory: {{7674597376 0} {<nil>} 7494724Ki BinarySI},pods: {{20 0} {<nil>} 20 DecimalSI},},Allocatable:ResourceList{cpu: {{2 0} {<nil>} 2 DecimalSI},memory: {{7569739776 0} {<nil>} 7392324Ki BinarySI},pods: {{20 0} {<nil>} 20 DecimalSI},},Phase:,Conditions:[{NetworkUnavailable False 0001-01-01 00:00:00 +0000 UTC 2017-06-23 09:59:43 -0400 EDT RouteCreated openshift-sdn cleared kubelet-set NoRouteCreated} {OutOfDisk False 2017-06-23 10:10:02 -0400 EDT 2017-06-23 09:59:43 -0400 EDT KubeletHasSufficientDisk kubelet has sufficient disk space available} {MemoryPressure False 2017-06-23 10:10:02 -0400 EDT 2017-06-23 09:59:43 -0400 EDT KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2017-06-23 10:10:02 -0400 EDT 2017-06-23 09:59:43 -0400 EDT KubeletHasNoDiskPressure kubelet has no disk pressure} {Ready True 2017-06-23 10:10:02 -0400 EDT 2017-06-23 09:59:49 -0400 EDT KubeletReady kubelet is posting ready status}],Addresses:[{InternalIP 10.128.0.2} {ExternalIP 35.192.73.43} {Hostname ci-prtest-5a37c28-3544-ig-m-t9p0}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:02f1ddb1415c4feba9880b2b8c4c5925,SystemUUID:F25E0FC5-F70F-5CFB-2D27-17EBAE168E04,BootID:df1113c7-e48a-4919-85c6-aeb82394c270,KernelVersion:3.10.0-514.6.1.el7.x86_64,OSImage:Red Hat Enterprise Linux Server 7.3 (Maipo),ContainerRuntimeVersion:docker://1.12.5,KubeletVersion:v1.6.1+5115d708d7,KubeProxyVersion:v1.6.1+5115d708d7,OperatingSystem:linux,Architecture:amd64,},Images:[{[docker.io/openshift/origin-docker-registry@sha256:0e66e864f17fb657f32ab676f981aa2749689d5f4054ec50a9b003895e182766 docker.io/openshift/origin-docker-registry:v3.6.0-alpha.2] 1100600520} {[docker.io/openshift/origin-haproxy-router@sha256:8fab0f79a06a686955a90f05c029192b71d55bbb90637e3ab175ca99dbbe5642 docker.io/openshift/origin-haproxy-router:v3.6.0-alpha.2] 1023465533} {[docker.io/openshift/origin-deployer@sha256:7e4722436e0e4237ff710116fc24c852588da9b334432c0ae59c995425b74156 docker.io/openshift/origin-deployer:v3.6.0-alpha.2] 1002389829} {[docker.io/cockpit/kubernetes@sha256:d08dfd9f1619ada63e9ce370eade80f5475c25a9593b6505ab5550cc4f35029b docker.io/cockpit/kubernetes:latest] 396605721} {[docker.io/openshift/origin-pod@sha256:d4033f01475399bd540083b9fec0beb5d4928e8769149996d65743c605b080f9 docker.io/openshift/origin-pod:v3.6.0-alpha.2] 213324499} {[gcr.io/google_containers/nginx-slim@sha256:dd4efd4c13bec2c6f3fe855deeab9524efe434505568421d4f31820485b3a795 gcr.io/google_containers/nginx-slim:0.7] 86864428} {[gcr.io/google_containers/hostexec@sha256:cab8d4e2526f8f767c64febe4ce9e0f0e58cd35fdff81b3aadba4dd041ba9f00 gcr.io/google_containers/hostexec:1.2] 13209617} {[gcr.io/google_containers/netexec@sha256:56c53846f44ea214e4aa5df37c9c50331f0b09e64a32cc7cf17c7e1808d38eef gcr.io/google_containers/netexec:1.7] 8016035}],VolumesInUse:[],VolumesAttached:[],},}
Jun 23 10:10:05.020: INFO: 
Logging kubelet events for node ci-prtest-5a37c28-3544-ig-m-t9p0
Jun 23 10:10:05.052: INFO: 
Logging pods the kubelet thinks is on node ci-prtest-5a37c28-3544-ig-m-t9p0
Jun 23 10:10:05.118: INFO: registry-console-1-05qr6 started at 2017-06-23 10:04:49 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:05.118: INFO: 	Container registry-console ready: true, restart count 0
Jun 23 10:10:05.118: INFO: router-1-cxpbp started at 2017-06-23 10:02:24 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:05.118: INFO: 	Container router ready: true, restart count 0
Jun 23 10:10:05.118: INFO: netserver-0 started at 2017-06-23 10:09:58 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:05.118: INFO: 	Container webserver ready: false, restart count 0
Jun 23 10:10:05.118: INFO: docker-registry-2-crmrp started at 2017-06-23 10:04:38 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:05.118: INFO: 	Container registry ready: true, restart count 0
Jun 23 10:10:05.485: INFO: 
Latency metrics for node ci-prtest-5a37c28-3544-ig-m-t9p0
Jun 23 10:10:05.485: INFO: {Operation:sync Method:pod_worker_latency_microseconds Quantile:0.5 Latency:2m0.000675s}
Jun 23 10:10:05.485: INFO: {Operation:sync Method:pod_worker_latency_microseconds Quantile:0.9 Latency:2m0.000675s}
Jun 23 10:10:05.485: INFO: {Operation:sync Method:pod_worker_latency_microseconds Quantile:0.99 Latency:2m0.000675s}
Jun 23 10:10:05.485: INFO: {Operation: Method:pod_start_latency_microseconds Quantile:0.99 Latency:22.720422s}
Jun 23 10:10:05.485: INFO: {Operation:pull_image Method:docker_operations_latency_microseconds Quantile:0.99 Latency:21.105009s}
Jun 23 10:10:05.485: INFO: {Operation:pull_image Method:docker_operations_latency_microseconds Quantile:0.9 Latency:21.105009s}
Jun 23 10:10:05.485: INFO: {Operation: Method:pod_start_latency_microseconds Quantile:0.9 Latency:20.15491s}
Jun 23 10:10:05.485: INFO: 
Logging node info for node ci-prtest-5a37c28-3544-ig-n-c4xx
Jun 23 10:10:05.524: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:ci-prtest-5a37c28-3544-ig-n-c4xx,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/ci-prtest-5a37c28-3544-ig-n-c4xx,UID:3515f9fb-581c-11e7-bee6-42010a800002,ResourceVersion:19283,Generation:0,CreationTimestamp:2017-06-23 09:59:43.105072187 -0400 EDT,DeletionTimestamp:<nil>,DeletionGracePeriodSeconds:nil,Labels:map[string]string{beta.kubernetes.io/arch: amd64,beta.kubernetes.io/instance-type: n1-standard-2,beta.kubernetes.io/os: linux,failure-domain.beta.kubernetes.io/region: us-central1,failure-domain.beta.kubernetes.io/zone: us-central1-a,kubernetes.io/hostname: ci-prtest-5a37c28-3544-ig-n-c4xx,role: app,},Annotations:map[string]string{volumes.kubernetes.io/controller-managed-attach-detach: true,},OwnerReferences:[],Finalizers:[],ClusterName:,},Spec:NodeSpec{PodCIDR:,ExternalID:2590001114403349876,ProviderID:gce://openshift-gce-devel-ci/us-central1-a/ci-prtest-5a37c28-3544-ig-n-c4xx,Unschedulable:false,Taints:[],},Status:NodeStatus{Capacity:ResourceList{cpu: {{2 0} {<nil>} 2 DecimalSI},memory: {{7674597376 0} {<nil>} 7494724Ki BinarySI},pods: {{20 0} {<nil>} 20 DecimalSI},},Allocatable:ResourceList{cpu: {{2 0} {<nil>} 2 DecimalSI},memory: {{7569739776 0} {<nil>} 7392324Ki BinarySI},pods: {{20 0} {<nil>} 20 DecimalSI},},Phase:,Conditions:[{NetworkUnavailable False 0001-01-01 00:00:00 +0000 UTC 2017-06-23 09:59:43 -0400 EDT RouteCreated openshift-sdn cleared kubelet-set NoRouteCreated} {OutOfDisk False 2017-06-23 10:10:04 -0400 EDT 2017-06-23 09:59:43 -0400 EDT KubeletHasSufficientDisk kubelet has sufficient disk space available} {MemoryPressure False 2017-06-23 10:10:04 -0400 EDT 2017-06-23 09:59:43 -0400 EDT KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2017-06-23 10:10:04 -0400 EDT 2017-06-23 09:59:43 -0400 EDT KubeletHasNoDiskPressure kubelet has no disk pressure} {Ready True 2017-06-23 10:10:04 -0400 EDT 2017-06-23 09:59:48 -0400 EDT KubeletReady kubelet is posting ready status}],Addresses:[{InternalIP 10.128.0.3} {ExternalIP 35.192.86.26} {Hostname ci-prtest-5a37c28-3544-ig-n-c4xx}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:02f1ddb1415c4feba9880b2b8c4c5925,SystemUUID:5FBD4BF9-AC02-0B5A-EC01-0DC18381602E,BootID:57eeb737-d83e-4073-8c21-ab7bc77f3902,KernelVersion:3.10.0-514.6.1.el7.x86_64,OSImage:Red Hat Enterprise Linux Server 7.3 (Maipo),ContainerRuntimeVersion:docker://1.12.5,KubeletVersion:v1.6.1+5115d708d7,KubeProxyVersion:v1.6.1+5115d708d7,OperatingSystem:linux,Architecture:amd64,},Images:[{[docker.io/openshift/origin-sti-builder@sha256:6ca6f666403798ebdd81a0cca8508d452cf339bfdd63db4161fe4b4b84a99a53 docker.io/openshift/origin-sti-builder:v3.6.0-alpha.2] 1002389829} {[docker.io/openshift/origin-deployer@sha256:7e4722436e0e4237ff710116fc24c852588da9b334432c0ae59c995425b74156 docker.io/openshift/origin-deployer:v3.6.0-alpha.2] 1002389829} {[docker.io/openshift/origin-docker-builder@sha256:6abfafec5dc99bf74b4fae59a02fadfab5d5213a88a1c42322cf137121bb53d3 docker.io/openshift/origin-docker-builder:v3.6.0-alpha.2] 1002389829} {[docker.io/centos/mongodb-32-centos7@sha256:aa37993c3be2d4731db79c0c7aba11db3e9352b1adc586c7e9054f57808789c0] 567712604} {[docker-registry.default.svc:5000/extended-test-new-app-9wtdd-4qx0x/a234567890123456789012345678901234567890123456789012345678:latest] 507441587} {[docker.io/centos/nodejs-6-centos7@sha256:41545d2d42683fa0f1515592293334a23f8ddded6b2e321cc8477d8fed2b5ca6] 493560058} {[docker.io/centos/ruby-23-centos7@sha256:33bca22eb1c4d8625efb95285f1aeee006ea1120dbfbd16ee7ee4499c4eb2a8a] 486839472} {[docker.io/centos/ruby-22-centos7@sha256:cb11ef7551a101513e9114027ba33e1bd35a89bb3f4345929290786c20528d80 docker.io/centos/ruby-22-centos7:latest] 472193130} {[docker.io/openshift/origin-pod@sha256:d4033f01475399bd540083b9fec0beb5d4928e8769149996d65743c605b080f9 docker.io/openshift/origin-pod:v3.6.0-alpha.2] 213324499} {[docker.io/centos@sha256:aebf12af704307dfa0079b3babdca8d7e8ff6564696882bcb5d11f1d461f9ee9 docker.io/centos:centos7] 192555856} {[gcr.io/google_containers/nginx-slim@sha256:dd4efd4c13bec2c6f3fe855deeab9524efe434505568421d4f31820485b3a795 gcr.io/google_containers/nginx-slim:0.7] 86864428} {[gcr.io/google_containers/nettest@sha256:8af3a0e8b8ab906b0648dd575e8785e04c19113531f8ffbaab9e149aa1a60763 gcr.io/google_containers/nettest:1.7] 24051275} {[gcr.io/google_containers/hostexec@sha256:cab8d4e2526f8f767c64febe4ce9e0f0e58cd35fdff81b3aadba4dd041ba9f00 gcr.io/google_containers/hostexec:1.2] 13209617} {[gcr.io/google_containers/netexec@sha256:56c53846f44ea214e4aa5df37c9c50331f0b09e64a32cc7cf17c7e1808d38eef gcr.io/google_containers/netexec:1.7] 8016035} {[gcr.io/google_containers/serve_hostname@sha256:a49737ee84a3b94f0b977f32e60c5daf11f0b5636f1f7503a2981524f351c57a gcr.io/google_containers/serve_hostname:v1.4] 6222101} {[gcr.io/google_containers/update-demo@sha256:89ac104fa7c43880d2324f377b79be95b0b2b3fb32e4bd03b8d1e6d91a41f009 gcr.io/google_containers/update-demo:nautilus] 4555533} {[gcr.io/google_containers/test-webserver@sha256:f804e8837490d1dfdb5002e073f715fd0a08115de74e5a4847ca952315739372 gcr.io/google_containers/test-webserver:e2e] 4534272} {[gcr.io/google_containers/portforwardtester@sha256:306879729d3eff635a11b89f3e62e440c9f2fe4dabdfb9ef02bc67f2275f67ab gcr.io/google_containers/portforwardtester:1.2] 1892642} {[gcr.io/google_containers/mounttest@sha256:bec3122ddcf8bd999e44e46e096659f31241d09f5236bc3dc212ea584ca06856 gcr.io/google_containers/mounttest:0.8] 1450761} {[gcr.io/google_containers/busybox@sha256:4bdd623e848417d96127e16037743f0cd8b528c026e9175e22a84f639eca58ff gcr.io/google_containers/busybox:1.24] 1113554} {[docker.io/busybox@sha256:be3c11fdba7cfe299214e46edc642e09514dbb9bbefcd0d3836c05a1e0cd0642] 1106304} {[docker.io/busybox@sha256:29f5d56d12684887bdfa50dcd29fc31eea4aaf4ad3bec43daf19026a7ce69912] 1093484} {[gcr.io/google_containers/pause-amd64@sha256:163ac025575b775d1c0f9bf0bdd0f086883171eb475b5068e7defa4ca9e76516 gcr.io/google_containers/pause-amd64:3.0] 746888}],VolumesInUse:[],VolumesAttached:[],},}
Jun 23 10:10:05.524: INFO: 
Logging kubelet events for node ci-prtest-5a37c28-3544-ig-n-c4xx
Jun 23 10:10:05.586: INFO: 
Logging pods the kubelet thinks is on node ci-prtest-5a37c28-3544-ig-n-c4xx
Jun 23 10:10:05.672: INFO: a2345678901234567890123456789012345678901234567890123456786rswm started at 2017-06-23 10:09:59 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:05.672: INFO: 	Container a234567890123456789012345678901234567890123456789012345678 ready: true, restart count 0
Jun 23 10:10:05.672: INFO: deployment-simple-1-fjmd2 started at 2017-06-23 10:10:03 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:05.672: INFO: 	Container myapp ready: false, restart count 0
Jun 23 10:10:05.672: INFO: liveness-exec started at 2017-06-23 10:08:00 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:05.672: INFO: 	Container liveness ready: true, restart count 0
Jun 23 10:10:05.672: INFO: pod-update-activedeadlineseconds-a20e7c8c-581d-11e7-9a69-0e26f8716e8c started at 2017-06-23 10:09:55 -0400 EDT (0+0 container statuses recorded)
Jun 23 10:10:05.672: INFO: deployment-simple-5-deploy started at 2017-06-23 10:10:01 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:05.672: INFO: 	Container deployment ready: true, restart count 0
Jun 23 10:10:05.672: INFO: a234567890123456789012345678901234567890123456789012345678-1-build started at 2017-06-23 10:08:38 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:05.672: INFO: 	Container sti-build ready: false, restart count 0
Jun 23 10:10:05.672: INFO: netserver-1 started at 2017-06-23 10:09:58 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:05.672: INFO: 	Container webserver ready: false, restart count 0
Jun 23 10:10:05.672: INFO: update-demo-nautilus-cp5v7 started at 2017-06-23 10:09:55 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:05.672: INFO: 	Container update-demo ready: true, restart count 0
Jun 23 10:10:05.672: INFO: deployment-simple-1-deploy started at 2017-06-23 10:10:00 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:05.672: INFO: 	Container deployment ready: true, restart count 0
Jun 23 10:10:05.672: INFO: brokendeployment-1-deploy started at 2017-06-23 10:08:26 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:05.672: INFO: 	Container deployment ready: false, restart count 0
Jun 23 10:10:05.672: INFO: deployment-simple-4-38rrb started at 2017-06-23 10:09:55 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:05.672: INFO: 	Container myapp ready: false, restart count 0
Jun 23 10:10:06.138: INFO: 
Latency metrics for node ci-prtest-5a37c28-3544-ig-n-c4xx
Jun 23 10:10:06.138: INFO: {Operation:sync Method:pod_worker_latency_microseconds Quantile:0.99 Latency:2m1.257083s}
Jun 23 10:10:06.138: INFO: {Operation:sync Method:pod_worker_latency_microseconds Quantile:0.9 Latency:2m1.135133s}
Jun 23 10:10:06.138: INFO: {Operation: Method:pod_start_latency_microseconds Quantile:0.99 Latency:34.031388s}
Jun 23 10:10:06.138: INFO: {Operation:update Method:pod_worker_latency_microseconds Quantile:0.99 Latency:31.172715s}
Jun 23 10:10:06.138: INFO: {Operation:update Method:pod_worker_latency_microseconds Quantile:0.9 Latency:30.383554s}
Jun 23 10:10:06.138: INFO: {Operation:stop_container Method:docker_operations_latency_microseconds Quantile:0.99 Latency:30.359002s}
Jun 23 10:10:06.138: INFO: {Operation:pull_image Method:docker_operations_latency_microseconds Quantile:0.99 Latency:21.245483s}
Jun 23 10:10:06.138: INFO: 
Logging node info for node ci-prtest-5a37c28-3544-ig-n-nl7c
Jun 23 10:10:06.224: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:ci-prtest-5a37c28-3544-ig-n-nl7c,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/ci-prtest-5a37c28-3544-ig-n-nl7c,UID:350e11dc-581c-11e7-bee6-42010a800002,ResourceVersion:19108,Generation:0,CreationTimestamp:2017-06-23 09:59:43.053254501 -0400 EDT,DeletionTimestamp:<nil>,DeletionGracePeriodSeconds:nil,Labels:map[string]string{beta.kubernetes.io/arch: amd64,beta.kubernetes.io/instance-type: n1-standard-2,beta.kubernetes.io/os: linux,failure-domain.beta.kubernetes.io/region: us-central1,failure-domain.beta.kubernetes.io/zone: us-central1-a,kubernetes.io/hostname: ci-prtest-5a37c28-3544-ig-n-nl7c,role: app,},Annotations:map[string]string{volumes.kubernetes.io/controller-managed-attach-detach: true,},OwnerReferences:[],Finalizers:[],ClusterName:,},Spec:NodeSpec{PodCIDR:,ExternalID:6903883128547353971,ProviderID:gce://openshift-gce-devel-ci/us-central1-a/ci-prtest-5a37c28-3544-ig-n-nl7c,Unschedulable:false,Taints:[],},Status:NodeStatus{Capacity:ResourceList{cpu: {{2 0} {<nil>} 2 DecimalSI},memory: {{7674597376 0} {<nil>} 7494724Ki BinarySI},pods: {{20 0} {<nil>} 20 DecimalSI},},Allocatable:ResourceList{cpu: {{2 0} {<nil>} 2 DecimalSI},memory: {{7569739776 0} {<nil>} 7392324Ki BinarySI},pods: {{20 0} {<nil>} 20 DecimalSI},},Phase:,Conditions:[{NetworkUnavailable False 0001-01-01 00:00:00 +0000 UTC 2017-06-23 09:59:43 -0400 EDT RouteCreated openshift-sdn cleared kubelet-set NoRouteCreated} {OutOfDisk False 2017-06-23 10:10:02 -0400 EDT 2017-06-23 09:59:43 -0400 EDT KubeletHasSufficientDisk kubelet has sufficient disk space available} {MemoryPressure False 2017-06-23 10:10:02 -0400 EDT 2017-06-23 09:59:43 -0400 EDT KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2017-06-23 10:10:02 -0400 EDT 2017-06-23 09:59:43 -0400 EDT KubeletHasNoDiskPressure kubelet has no disk pressure} {Ready True 2017-06-23 10:10:02 -0400 EDT 2017-06-23 09:59:49 -0400 EDT KubeletReady kubelet is posting ready status}],Addresses:[{InternalIP 10.128.0.4} {ExternalIP 35.192.65.232} {Hostname ci-prtest-5a37c28-3544-ig-n-nl7c}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:02f1ddb1415c4feba9880b2b8c4c5925,SystemUUID:CF9CD6CC-3C1D-F37D-013A-C474E24BE05C,BootID:97656f50-ad37-4b64-9d05-02e2a9e23e59,KernelVersion:3.10.0-514.6.1.el7.x86_64,OSImage:Red Hat Enterprise Linux Server 7.3 (Maipo),ContainerRuntimeVersion:docker://1.12.5,KubeletVersion:v1.6.1+5115d708d7,KubeProxyVersion:v1.6.1+5115d708d7,OperatingSystem:linux,Architecture:amd64,},Images:[{[docker.io/openshift/origin-sti-builder@sha256:6ca6f666403798ebdd81a0cca8508d452cf339bfdd63db4161fe4b4b84a99a53 docker.io/openshift/origin-sti-builder:v3.6.0-alpha.2] 1002389829} {[docker.io/openshift/origin-deployer@sha256:7e4722436e0e4237ff710116fc24c852588da9b334432c0ae59c995425b74156 docker.io/openshift/origin-deployer:v3.6.0-alpha.2] 1002389829} {[docker-registry.default.svc:5000/extended-test-build-valuefrom-59czn-t9pcm/test@sha256:aaac08e58d0659019fe1730edb55e88e0a01e21f9095512d5ef6acf66b4465b7 docker-registry.default.svc:5000/extended-test-build-valuefrom-59czn-t9pcm/test:latest] 537513253} {[docker.io/centos/php-70-centos7@sha256:b963a0c6daf776a452cf765ab66c0a80ba431d861f91ad352e72e4448f1eae50 docker.io/centos/php-70-centos7:latest] 519661989} {[docker.io/centos/ruby-23-centos7@sha256:33bca22eb1c4d8625efb95285f1aeee006ea1120dbfbd16ee7ee4499c4eb2a8a] 486839472} {[docker.io/centos/ruby-22-centos7@sha256:cb11ef7551a101513e9114027ba33e1bd35a89bb3f4345929290786c20528d80 docker.io/centos/ruby-22-centos7:latest] 472193130} {[gcr.io/google_containers/redis@sha256:f066bcf26497fbc55b9bf0769cb13a35c0afa2aa42e737cc46b7fb04b23a2f25 gcr.io/google_containers/redis:e2e] 419003740} {[docker.io/openshift/origin-pod@sha256:d4033f01475399bd540083b9fec0beb5d4928e8769149996d65743c605b080f9 docker.io/openshift/origin-pod:v3.6.0-alpha.2] 213324499} {[docker.io/openshift/origin-pod@sha256:e114c37d9889e321eb386c499d87e5f4db073e5e74c2edf026e2ef9f8e5f15a8 docker.io/openshift/origin-pod:latest] 213263512} {[docker.io/centos@sha256:aebf12af704307dfa0079b3babdca8d7e8ff6564696882bcb5d11f1d461f9ee9 docker.io/centos:centos7] 192555856} {[gcr.io/google_containers/nginx-slim@sha256:dd4efd4c13bec2c6f3fe855deeab9524efe434505568421d4f31820485b3a795 gcr.io/google_containers/nginx-slim:0.7] 86864428} {[gcr.io/google_containers/hostexec@sha256:cab8d4e2526f8f767c64febe4ce9e0f0e58cd35fdff81b3aadba4dd041ba9f00 gcr.io/google_containers/hostexec:1.2] 13209617} {[gcr.io/google_containers/dnsutils@sha256:cd9182f6d74e616942db1cef6f25e1e54b49ba0330c2e19d3ec061f027666cc0 gcr.io/google_containers/dnsutils:e2e] 8897789} {[gcr.io/google_containers/netexec@sha256:56c53846f44ea214e4aa5df37c9c50331f0b09e64a32cc7cf17c7e1808d38eef gcr.io/google_containers/netexec:1.7] 8016035} {[gcr.io/google_containers/serve_hostname@sha256:a49737ee84a3b94f0b977f32e60c5daf11f0b5636f1f7503a2981524f351c57a gcr.io/google_containers/serve_hostname:v1.4] 6222101} {[gcr.io/google_containers/porter@sha256:076acdada33f35b917c9eebe89eba95923601302beac57274985e418b70067e2 gcr.io/google_containers/porter:cd5cb5791ebaa8641955f0e8c2a9bed669b1eaab] 5010921} {[gcr.io/google_containers/test-webserver@sha256:f804e8837490d1dfdb5002e073f715fd0a08115de74e5a4847ca952315739372 gcr.io/google_containers/test-webserver:e2e] 4534272} {[gcr.io/google_containers/eptest@sha256:bb088b26ed78613cce171420168db9a6c62a8dbea17d7be13077e7010bae162f gcr.io/google_containers/eptest:0.1] 2970692} {[gcr.io/google_containers/mounttest@sha256:c4dcedb26013ab4231a2b2aaa4eebd5c2a44d5c597fa0613c9ff8bde4fb9fe02 gcr.io/google_containers/mounttest:0.7] 2052704} {[gcr.io/google_containers/portforwardtester@sha256:306879729d3eff635a11b89f3e62e440c9f2fe4dabdfb9ef02bc67f2275f67ab gcr.io/google_containers/portforwardtester:1.2] 1892642} {[gcr.io/google_containers/mounttest-user@sha256:5487c126b03abf4119a8f7950cd5f591f72dbe4ab15623f3387d3917e1268b4e gcr.io/google_containers/mounttest-user:0.5] 1450761} {[gcr.io/google_containers/mounttest@sha256:bec3122ddcf8bd999e44e46e096659f31241d09f5236bc3dc212ea584ca06856 gcr.io/google_containers/mounttest:0.8] 1450761} {[gcr.io/google_containers/busybox@sha256:4bdd623e848417d96127e16037743f0cd8b528c026e9175e22a84f639eca58ff gcr.io/google_containers/busybox:1.24] 1113554} {[gcr.io/google_containers/pause-amd64@sha256:163ac025575b775d1c0f9bf0bdd0f086883171eb475b5068e7defa4ca9e76516 gcr.io/google_containers/pause-amd64:3.0] 746888}],VolumesInUse:[],VolumesAttached:[],},}
Jun 23 10:10:06.225: INFO: 
Logging kubelet events for node ci-prtest-5a37c28-3544-ig-n-nl7c
Jun 23 10:10:06.261: INFO: 
Logging pods the kubelet thinks is on node ci-prtest-5a37c28-3544-ig-n-nl7c
Jun 23 10:10:06.370: INFO: deployment-simple-1-rgw27 started at 2017-06-23 10:10:02 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:06.370: INFO: 	Container myapp ready: false, restart count 0
Jun 23 10:10:06.370: INFO: test-webserver-8bde1462-581d-11e7-a677-0e26f8716e8c started at 2017-06-23 10:09:18 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:06.370: INFO: 	Container test-webserver ready: false, restart count 0
Jun 23 10:10:06.370: INFO: deployment-simple-3-nj7r4 started at 2017-06-23 10:09:49 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:06.370: INFO: 	Container myapp ready: true, restart count 0
Jun 23 10:10:06.370: INFO: a234567890123456789012345678901234567890123456789012345678-1-deploy started at 2017-06-23 10:09:56 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:06.370: INFO: 	Container deployment ready: false, restart count 0
Jun 23 10:10:06.370: INFO: a234567890123456789012345678901234567890123456789012345678-2-deploy started at 2017-06-23 10:10:03 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:06.370: INFO: 	Container deployment ready: false, restart count 0
Jun 23 10:10:06.370: INFO: deployment-simple-1-gs4mp started at 2017-06-23 10:09:36 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:06.370: INFO: 	Container myapp ready: true, restart count 0
Jun 23 10:10:06.370: INFO: netserver-2 started at 2017-06-23 10:09:58 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:06.370: INFO: 	Container webserver ready: false, restart count 0
Jun 23 10:10:06.370: INFO: deployment-simple-2-58hp7 started at 2017-06-23 10:09:42 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:06.370: INFO: 	Container myapp ready: true, restart count 0
Jun 23 10:10:06.370: INFO: deployment-simple-5-2lcmw started at 2017-06-23 10:10:04 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:06.370: INFO: 	Container myapp ready: false, restart count 0
Jun 23 10:10:06.999: INFO: 
Latency metrics for node ci-prtest-5a37c28-3544-ig-n-nl7c
Jun 23 10:10:06.999: INFO: {Operation:sync Method:pod_worker_latency_microseconds Quantile:0.99 Latency:2m3.120502s}
Jun 23 10:10:06.999: INFO: {Operation:sync Method:pod_worker_latency_microseconds Quantile:0.9 Latency:2m1.94368s}
Jun 23 10:10:06.999: INFO: {Operation:sync Method:pod_worker_latency_microseconds Quantile:0.5 Latency:2m1.037278s}
Jun 23 10:10:06.999: INFO: {Operation:update Method:pod_worker_latency_microseconds Quantile:0.99 Latency:30.356168s}
Jun 23 10:10:06.999: INFO: {Operation:update Method:pod_worker_latency_microseconds Quantile:0.9 Latency:30.356168s}
Jun 23 10:10:06.999: INFO: {Operation: Method:pod_start_latency_microseconds Quantile:0.99 Latency:24.614242s}
Jun 23 10:10:06.999: INFO: {Operation:pull_image Method:docker_operations_latency_microseconds Quantile:0.99 Latency:19.904338s}
Jun 23 10:10:06.999: INFO: 
Logging node info for node ci-prtest-5a37c28-3544-ig-n-rlc0
Jun 23 10:10:07.038: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:ci-prtest-5a37c28-3544-ig-n-rlc0,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/ci-prtest-5a37c28-3544-ig-n-rlc0,UID:351ab99d-581c-11e7-bee6-42010a800002,ResourceVersion:18951,Generation:0,CreationTimestamp:2017-06-23 09:59:43.136192416 -0400 EDT,DeletionTimestamp:<nil>,DeletionGracePeriodSeconds:nil,Labels:map[string]string{beta.kubernetes.io/arch: amd64,beta.kubernetes.io/instance-type: n1-standard-2,beta.kubernetes.io/os: linux,failure-domain.beta.kubernetes.io/region: us-central1,failure-domain.beta.kubernetes.io/zone: us-central1-a,kubernetes.io/hostname: ci-prtest-5a37c28-3544-ig-n-rlc0,role: app,},Annotations:map[string]string{volumes.kubernetes.io/controller-managed-attach-detach: true,},OwnerReferences:[],Finalizers:[],ClusterName:,},Spec:NodeSpec{PodCIDR:,ExternalID:7478147627849131379,ProviderID:gce://openshift-gce-devel-ci/us-central1-a/ci-prtest-5a37c28-3544-ig-n-rlc0,Unschedulable:false,Taints:[],},Status:NodeStatus{Capacity:ResourceList{cpu: {{2 0} {<nil>} 2 DecimalSI},memory: {{7674597376 0} {<nil>} 7494724Ki BinarySI},pods: {{20 0} {<nil>} 20 DecimalSI},},Allocatable:ResourceList{cpu: {{2 0} {<nil>} 2 DecimalSI},memory: {{7569739776 0} {<nil>} 7392324Ki BinarySI},pods: {{20 0} {<nil>} 20 DecimalSI},},Phase:,Conditions:[{NetworkUnavailable False 0001-01-01 00:00:00 +0000 UTC 2017-06-23 09:59:43 -0400 EDT RouteCreated openshift-sdn cleared kubelet-set NoRouteCreated} {OutOfDisk False 2017-06-23 10:10:00 -0400 EDT 2017-06-23 09:59:43 -0400 EDT KubeletHasSufficientDisk kubelet has sufficient disk space available} {MemoryPressure False 2017-06-23 10:10:00 -0400 EDT 2017-06-23 09:59:43 -0400 EDT KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2017-06-23 10:10:00 -0400 EDT 2017-06-23 09:59:43 -0400 EDT KubeletHasNoDiskPressure kubelet has no disk pressure} {Ready True 2017-06-23 10:10:00 -0400 EDT 2017-06-23 09:59:48 -0400 EDT KubeletReady kubelet is posting ready status}],Addresses:[{InternalIP 10.128.0.5} {ExternalIP 35.192.71.117} {Hostname ci-prtest-5a37c28-3544-ig-n-rlc0}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:02f1ddb1415c4feba9880b2b8c4c5925,SystemUUID:3D8785CA-CE74-16FC-725D-1D88C7295333,BootID:aebaa5a2-a23d-4f94-bf1a-1ada1bba21d7,KernelVersion:3.10.0-514.6.1.el7.x86_64,OSImage:Red Hat Enterprise Linux Server 7.3 (Maipo),ContainerRuntimeVersion:docker://1.12.5,KubeletVersion:v1.6.1+5115d708d7,KubeProxyVersion:v1.6.1+5115d708d7,OperatingSystem:linux,Architecture:amd64,},Images:[{[docker.io/openshift/origin-deployer@sha256:7e4722436e0e4237ff710116fc24c852588da9b334432c0ae59c995425b74156 docker.io/openshift/origin-deployer:v3.6.0-alpha.2] 1002389829} {[docker.io/openshift/origin-sti-builder@sha256:6ca6f666403798ebdd81a0cca8508d452cf339bfdd63db4161fe4b4b84a99a53 docker.io/openshift/origin-sti-builder:v3.6.0-alpha.2] 1002389829} {[docker.io/centos/ruby-22-centos7@sha256:cb11ef7551a101513e9114027ba33e1bd35a89bb3f4345929290786c20528d80 docker.io/centos/ruby-22-centos7:latest] 472193130} {[gcr.io/google_containers/redis@sha256:f066bcf26497fbc55b9bf0769cb13a35c0afa2aa42e737cc46b7fb04b23a2f25 gcr.io/google_containers/redis:e2e] 419003740} {[docker.io/openshift/origin-base@sha256:3848ab52436662e4193f34063bbfd259c0c09cbe91562acec7dd6eb510ca2e94 docker.io/openshift/origin-base:latest] 363035993} {[docker.io/openshift/origin-pod@sha256:d4033f01475399bd540083b9fec0beb5d4928e8769149996d65743c605b080f9 docker.io/openshift/origin-pod:v3.6.0-alpha.2] 213324499} {[docker.io/centos@sha256:aebf12af704307dfa0079b3babdca8d7e8ff6564696882bcb5d11f1d461f9ee9 docker.io/centos:centos7] 192555856} {[gcr.io/google_containers/jessie-dnsutils@sha256:2460d596912244b5f8973573f7150e7264b570015f4becc2d0096f0bd1d17e36 gcr.io/google_containers/jessie-dnsutils:e2e] 190148402} {[gcr.io/google_containers/nginx-slim@sha256:dd4efd4c13bec2c6f3fe855deeab9524efe434505568421d4f31820485b3a795 gcr.io/google_containers/nginx-slim:0.7] 86864428} {[gcr.io/google_containers/hostexec@sha256:cab8d4e2526f8f767c64febe4ce9e0f0e58cd35fdff81b3aadba4dd041ba9f00 gcr.io/google_containers/hostexec:1.2] 13209617} {[gcr.io/google_containers/dnsutils@sha256:cd9182f6d74e616942db1cef6f25e1e54b49ba0330c2e19d3ec061f027666cc0 gcr.io/google_containers/dnsutils:e2e] 8897789} {[gcr.io/google_containers/netexec@sha256:56c53846f44ea214e4aa5df37c9c50331f0b09e64a32cc7cf17c7e1808d38eef gcr.io/google_containers/netexec:1.7] 8016035} {[gcr.io/google_containers/serve_hostname@sha256:a49737ee84a3b94f0b977f32e60c5daf11f0b5636f1f7503a2981524f351c57a gcr.io/google_containers/serve_hostname:v1.4] 6222101} {[gcr.io/google_containers/fakegitserver@sha256:e974692bb4d422a4e9ea6ff9df85fa36f189010703400496fea44aac6589d0dd gcr.io/google_containers/fakegitserver:0.1] 5007469} {[gcr.io/google_containers/update-demo@sha256:89ac104fa7c43880d2324f377b79be95b0b2b3fb32e4bd03b8d1e6d91a41f009 gcr.io/google_containers/update-demo:nautilus] 4555533} {[gcr.io/google_containers/test-webserver@sha256:f804e8837490d1dfdb5002e073f715fd0a08115de74e5a4847ca952315739372 gcr.io/google_containers/test-webserver:e2e] 4534272} {[gcr.io/google_containers/liveness@sha256:90994881062c7de7bb1761f2f3d020fe9aa3d332a90e00ebd3ca9dcc1ed74f1c gcr.io/google_containers/liveness:e2e] 4387474} {[gcr.io/google_containers/eptest@sha256:bb088b26ed78613cce171420168db9a6c62a8dbea17d7be13077e7010bae162f gcr.io/google_containers/eptest:0.1] 2970692} {[gcr.io/google_containers/busybox@sha256:d8d3bc2c183ed2f9f10e7258f84971202325ee6011ba137112e01e30f206de67 gcr.io/google_containers/busybox:latest] 2433303} {[gcr.io/google_containers/mounttest@sha256:bec3122ddcf8bd999e44e46e096659f31241d09f5236bc3dc212ea584ca06856 gcr.io/google_containers/mounttest:0.8] 1450761} {[gcr.io/google_containers/mounttest-user@sha256:5487c126b03abf4119a8f7950cd5f591f72dbe4ab15623f3387d3917e1268b4e gcr.io/google_containers/mounttest-user:0.5] 1450761} {[gcr.io/google_containers/busybox@sha256:4bdd623e848417d96127e16037743f0cd8b528c026e9175e22a84f639eca58ff gcr.io/google_containers/busybox:1.24] 1113554} {[docker.io/busybox@sha256:be3c11fdba7cfe299214e46edc642e09514dbb9bbefcd0d3836c05a1e0cd0642] 1106304} {[gcr.io/google_containers/pause-amd64@sha256:163ac025575b775d1c0f9bf0bdd0f086883171eb475b5068e7defa4ca9e76516 gcr.io/google_containers/pause-amd64:3.0] 746888} {[gcr.io/google-containers/pause@sha256:9ce5316f9752b8347484ab0f6778573af15524124d52b93230b9a0dcc987e73e gcr.io/google-containers/pause:2.0] 350164}],VolumesInUse:[],VolumesAttached:[],},}
Jun 23 10:10:07.039: INFO: 
Logging kubelet events for node ci-prtest-5a37c28-3544-ig-n-rlc0
Jun 23 10:10:07.097: INFO: 
Logging pods the kubelet thinks is on node ci-prtest-5a37c28-3544-ig-n-rlc0
Jun 23 10:10:07.189: INFO: deployment-simple-1-7xrdx started at 2017-06-23 10:09:36 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:07.189: INFO: 	Container myapp ready: true, restart count 0
Jun 23 10:10:07.189: INFO: deployment-simple-2-m23xs started at 2017-06-23 10:09:42 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:07.189: INFO: 	Container myapp ready: true, restart count 0
Jun 23 10:10:07.189: INFO: optimized-build started at 2017-06-23 10:09:51 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:07.189: INFO: 	Container docker-build ready: false, restart count 0
Jun 23 10:10:07.189: INFO: deployment-simple-3-5rnd5 started at 2017-06-23 10:09:49 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:07.189: INFO: 	Container myapp ready: true, restart count 0
Jun 23 10:10:07.189: INFO: netserver-3 started at 2017-06-23 10:09:58 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:07.189: INFO: 	Container webserver ready: false, restart count 0
Jun 23 10:10:07.189: INFO: update-demo-nautilus-h3n1x started at 2017-06-23 10:09:55 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:07.189: INFO: 	Container update-demo ready: false, restart count 0
Jun 23 10:10:07.189: INFO: deployment-simple-4-xgk50 started at 2017-06-23 10:09:55 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:07.189: INFO: 	Container myapp ready: true, restart count 0
Jun 23 10:10:07.189: INFO: dns-test-a62601c9-581d-11e7-ac9d-0e26f8716e8c started at 2017-06-23 10:10:02 -0400 EDT (0+3 container statuses recorded)
Jun 23 10:10:07.189: INFO: 	Container jessie-querier ready: false, restart count 0
Jun 23 10:10:07.189: INFO: 	Container querier ready: false, restart count 0
Jun 23 10:10:07.189: INFO: 	Container webserver ready: true, restart count 0
Jun 23 10:10:07.189: INFO: deployment-simple-5-hbxfr started at 2017-06-23 10:10:04 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:07.189: INFO: 	Container myapp ready: false, restart count 0
Jun 23 10:10:07.189: INFO: deployment-simple-4-deploy started at 2017-06-23 10:09:53 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:07.189: INFO: 	Container deployment ready: false, restart count 0
Jun 23 10:10:07.189: INFO: brokendeployment-1-hook-pre started at 2017-06-23 10:08:27 -0400 EDT (0+1 container statuses recorded)
Jun 23 10:10:07.190: INFO: 	Container lifecycle ready: false, restart count 0
Jun 23 10:10:07.676: INFO: 
Latency metrics for node ci-prtest-5a37c28-3544-ig-n-rlc0
Jun 23 10:10:07.677: INFO: {Operation:sync Method:pod_worker_latency_microseconds Quantile:0.99 Latency:2m1.656545s}
Jun 23 10:10:07.677: INFO: {Operation:sync Method:pod_worker_latency_microseconds Quantile:0.9 Latency:2m1.234548s}
Jun 23 10:10:07.677: INFO: {Operation:sync Method:pod_worker_latency_microseconds Quantile:0.5 Latency:2m0.001059s}
Jun 23 10:10:07.677: INFO: {Operation:update Method:pod_worker_latency_microseconds Quantile:0.99 Latency:30.249146s}
Jun 23 10:10:07.677: INFO: {Operation:update Method:pod_worker_latency_microseconds Quantile:0.9 Latency:30.249146s}
Jun 23 10:10:07.677: INFO: {Operation: Method:pod_start_latency_microseconds Quantile:0.99 Latency:22.648838s}
Jun 23 10:10:07.677: INFO: {Operation:pull_image Method:docker_operations_latency_microseconds Quantile:0.99 Latency:21.115971s}
Jun 23 10:10:07.677: INFO: {Operation:create Method:pod_worker_latency_microseconds Quantile:0.99 Latency:10.091481s}
Jun 23 10:10:07.677: INFO: {Operation:create Method:pod_worker_latency_microseconds Quantile:0.9 Latency:10.091481s}
STEP: Dumping a list of prepulled images on each node
Jun 23 10:10:07.719: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready
STEP: Destroying namespace "extended-test-new-app-9wtdd-4qx0x" for this suite.
Jun 23 10:10:44.503: INFO: namespace: extended-test-new-app-9wtdd-4qx0x, resource: bindings, ignored listing per whitelist

@mfojtik
Copy link
Contributor

mfojtik commented Jun 26, 2017

seems like the deployment is waiting for the container to create, maybe a docker slowness?

@mfojtik
Copy link
Contributor

mfojtik commented Jun 26, 2017

Seems like slow Docker:

#14367

@bparees
Copy link
Contributor

bparees commented Jun 26, 2017

thanks @mfojtik.

@tnozicka
Copy link
Contributor

@tnozicka
Copy link
Contributor

tnozicka commented Jun 27, 2017

yet again https://ci.openshift.redhat.com/jenkins/job/test_pull_request_origin/2682/

@mfojtik devicemapper connected?

Identified problems

yum flake network unreachable

https://github.com/openshift/origin/issues/10162
Indication 1 

Devicemapper error

device mapper flake (does not always cause a test failure) https://github.com/openshift/origin/issues/13271
Indication 2 

btw. twice in a row on #14773

@jim-minter
Copy link
Contributor

I wonder whether the rather broken implementation of WaitForADeployment could be at least partially responsible for this, in which case merging #14885 should help

@bparees
Copy link
Contributor

bparees commented Jun 27, 2017

@tnozicka the devicemapper thing is a very old red herring at this point i believe, we should probably remove it from the jenkins cause analysis list entirely.

the yum flake is a "sometimes" root cause but generally it's obvious if it was. since your job actually ran some tests, that is not likely relevant either.

@bparees bparees removed the kind/test-flake Categorizes issue or PR as related to test flakes. label Jun 30, 2017
@bparees
Copy link
Contributor

bparees commented Jun 30, 2017

i removed the test flake label since we don't want to ignore this as a flake. also i removed the test case in question from conformance so it should no longer be flaking on people.

@mfojtik
Copy link
Contributor

mfojtik commented Jun 30, 2017

once we have registry rebuilt with #14882 in place and the playbooks for GCE are updated, we can re-test if this is fixed.

@smarterclayton
Copy link
Contributor

smarterclayton commented Jun 30, 2017 via email

@bparees
Copy link
Contributor

bparees commented Jun 30, 2017

When this issue is resolved we need to move the new-app test back into the conformance bucket (and i still think we need a new deployment specific test that will do a better job of validating the behavior...)

@mfojtik
Copy link
Contributor

mfojtik commented Jul 3, 2017

@bparees I think we need to cut a new 3.6 release and rebuilt the registry image to make this work. I will watch that and once we have new registry image out I will re-enable the test.

@bparees
Copy link
Contributor

bparees commented Jul 3, 2017 via email

@mfojtik
Copy link
Contributor

mfojtik commented Jul 3, 2017

@bparees why we should tolerate multiple deployments? that failure was legit, it pointed us to pretty much a release blocker problem :-)

@mfojtik
Copy link
Contributor

mfojtik commented Jul 3, 2017

agree we need DC test

@bparees
Copy link
Contributor

bparees commented Jul 3, 2017

@bparees why we should tolerate multiple deployments? that failure was legit, it pointed us to pretty much a release blocker problem :-)

@mfojtik we don't want to, but i wanted the test to start passing again (so that it's failure wasn't covering up other issues) and the main point of the test is not to check if deployments are working. hence:
https://github.com/openshift/origin/blob/master/test/extended/util/framework.go#L741-L747

@smarterclayton
Copy link
Contributor

smarterclayton commented Jul 3, 2017 via email

@mfojtik
Copy link
Contributor

mfojtik commented Jul 20, 2017

@bparees i see the test is re-enabled and everything seems to operate normally, ok to close this?

@bparees
Copy link
Contributor

bparees commented Jul 20, 2017

@mfojtik it's certainly not a p0 anymore, but you should still use either this issue or a new issue to:

  1. introduce an explicit test that ensure we only get exactly one deployment triggered
  2. tighten this check: https://github.com/openshift/origin/blob/master/test/extended/util/framework.go#L741-L747

@sdodson
Copy link
Member

sdodson commented Aug 11, 2017

@enj you said this was happening now because we need to fix openshift/openshift-ansible#5021 ?

@enj
Copy link
Contributor

enj commented Aug 11, 2017

No it's only consistent on #15021 because we need the 3.7 release tag. openshift/openshift-ansible#5021 is related but not to this flake.

@smarterclayton
Copy link
Contributor

smarterclayton commented Aug 14, 2017 via email

@openshift-bot
Copy link
Contributor

Issues go stale after 90d of inactivity.

Mark the issue as fresh by commenting /remove-lifecycle stale.
Stale issues rot after an additional 30d of inactivity and eventually close.
Exclude this issue from closing by commenting /lifecycle frozen.

If this issue is safe to close now please do so with /close.

/lifecycle stale

@openshift-ci-robot openshift-ci-robot added the lifecycle/stale Denotes an issue or PR has remained open with no activity and has become stale. label Feb 21, 2018
@bparees
Copy link
Contributor

bparees commented Feb 21, 2018 via email

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
component/apps lifecycle/stale Denotes an issue or PR has remained open with no activity and has become stale. priority/P2
Projects
None yet
Development

No branches or pull requests