search

openshift / origin

Conformance test suite for OpenShift
http://www.openshift.org
Apache License 2.0
8.48k stars 4.7k forks source link

flake: crio: Back-off pulling image "openshift/origin-deployer:4762d6a" #18365

Closed tnozicka closed 6 years ago

tnozicka commented 6 years ago

crio job is failing because it can't pull deployer image openshift/origin-deployer:4762d6a

This is #1 flake (49 times) in https://snowstorm-origin-ci.svc.ci.openshift.org/

@mfojtik @stevekuznetsov @runcom

deployer image should be pre-pulled likely or at least pulled faster than 5 minutes.

  containerStatuses:
  - image: openshift/origin-deployer:4762d6a
    imageID: ""
    lastState: {}
    name: deployment
    ready: false
    restartCount: 0
    state:
      waiting:
        message: Back-off pulling image "openshift/origin-deployer:4762d6a"
        reason: ImagePullBackOff

https://ci.openshift.redhat.com/jenkins/job/test_branch_origin_extended_conformance_crio/503/consoleFull
[Feature:DeploymentConfig] deploymentconfigs won't deploy RC with unresolved images [Conformance] 
  when patched with empty image [Suite:openshift/conformance/parallel]
  /go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/test/extended/deployments/deployments.go:1405

[BeforeEach] [Top Level]
  /go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/test/extended/util/test.go:53
[BeforeEach] [Feature:DeploymentConfig] deploymentconfigs
  /go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:134
STEP: Creating a kubernetes client
Jan 27 14:14:23.646: INFO: >>> kubeConfig: /etc/origin/master/admin.kubeconfig
STEP: Building a namespace api object
Jan 27 14:14:23.670: INFO: configPath is now "/tmp/extended-test-cli-deployment-j4d8f-xwrkj-user.kubeconfig"
Jan 27 14:14:23.670: INFO: The user is now "extended-test-cli-deployment-j4d8f-xwrkj-user"
Jan 27 14:14:23.670: INFO: Creating project "extended-test-cli-deployment-j4d8f-xwrkj"
Jan 27 14:14:23.735: INFO: Waiting on permissions in project "extended-test-cli-deployment-j4d8f-xwrkj" ...
STEP: Waiting for a default service account to be provisioned in namespace
[JustBeforeEach] [Feature:DeploymentConfig] deploymentconfigs
  /go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/test/extended/deployments/deployments.go:43
[It] when patched with empty image [Suite:openshift/conformance/parallel]
  /go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/test/extended/deployments/deployments.go:1405
STEP: creating DC
STEP: tagging the busybox:latest as test:v1 image to create ImageStream
Jan 27 14:14:23.775: INFO: Running 'oc tag --config=/tmp/extended-test-cli-deployment-j4d8f-xwrkj-user.kubeconfig --namespace=extended-test-cli-deployment-j4d8f-xwrkj docker.io/busybox:latest test:v1'
Jan 27 14:14:24.055: INFO: Tag test:v1 set to docker.io/busybox:latest.
STEP: waiting for deployment #1 to complete
[AfterEach] won't deploy RC with unresolved images [Conformance]
  /go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/test/extended/deployments/deployments.go:1401
Jan 27 14:19:24.061: INFO: Running 'oc get --config=/tmp/extended-test-cli-deployment-j4d8f-xwrkj-user.kubeconfig --namespace=extended-test-cli-deployment-j4d8f-xwrkj dc/example -o yaml'
Jan 27 14:19:24.314: INFO: 
apiVersion: v1
kind: DeploymentConfig
metadata:
  creationTimestamp: 2018-01-27T14:14:23Z
  generation: 2
  labels:
    app: example
  name: example
  namespace: extended-test-cli-deployment-j4d8f-xwrkj
  resourceVersion: "42060"
  selfLink: /oapi/v1/namespaces/extended-test-cli-deployment-j4d8f-xwrkj/deploymentconfigs/example
  uid: 600c3ed1-036c-11e8-ba4b-0e7ab02740dc
spec:
  replicas: 1
  revisionHistoryLimit: 10
  selector:
    app: example
  strategy:
    activeDeadlineSeconds: 21600
    resources: {}
    rollingParams:
      intervalSeconds: 1
      maxSurge: 25%
      maxUnavailable: 25%
      timeoutSeconds: 600
      updatePeriodSeconds: 1
    type: Rolling
  template:
    metadata:
      creationTimestamp: null
      labels:
        app: example
    spec:
      containers:
      - command:
        - /bin/sleep
        - "100"
        image: docker.io/busybox@sha256:4cee1979ba0bf7db9fc5d28fb7b798ca69ae95a47c5fecf46327720df4ff352d
        imagePullPolicy: Always
        name: test
        resources: {}
        terminationMessagePath: /dev/termination-log
        terminationMessagePolicy: File
      dnsPolicy: ClusterFirst
      restartPolicy: Always
      schedulerName: default-scheduler
      securityContext: {}
      terminationGracePeriodSeconds: 30
  test: false
  triggers:
  - imageChangeParams:
      automatic: true
      containerNames:
      - test
      from:
        kind: ImageStreamTag
        name: test:v1
        namespace: extended-test-cli-deployment-j4d8f-xwrkj
      lastTriggeredImage: docker.io/busybox@sha256:4cee1979ba0bf7db9fc5d28fb7b798ca69ae95a47c5fecf46327720df4ff352d
    type: ImageChange
status:
  availableReplicas: 0
  conditions:
  - lastTransitionTime: 2018-01-27T14:14:23Z
    lastUpdateTime: 2018-01-27T14:14:23Z
    message: Deployment config does not have minimum availability.
    status: "False"
    type: Available
  - lastTransitionTime: 2018-01-27T14:14:24Z
    lastUpdateTime: 2018-01-27T14:14:24Z
    message: replication controller "example-1" is waiting for pod "example-1-deploy"
      to run
    status: Unknown
    type: Progressing
  details:
    causes:
    - type: ConfigChange
    message: config change
  latestVersion: 1
  observedGeneration: 2
  replicas: 0
  unavailableReplicas: 0
  updatedReplicas: 0

Jan 27 14:19:24.328: INFO: Running 'oc get --config=/tmp/extended-test-cli-deployment-j4d8f-xwrkj-user.kubeconfig --namespace=extended-test-cli-deployment-j4d8f-xwrkj rc/example-1 -o yaml'
Jan 27 14:19:24.567: INFO: 
apiVersion: v1
kind: ReplicationController
metadata:
  annotations:
    kubectl.kubernetes.io/desired-replicas: "1"
    openshift.io/deployer-pod.created-at: 2018-01-27 14:14:24 +0000 UTC
    openshift.io/deployer-pod.name: example-1-deploy
    openshift.io/deployment-config.latest-version: "1"
    openshift.io/deployment-config.name: example
    openshift.io/deployment.phase: Pending
    openshift.io/deployment.replicas: "0"
    openshift.io/deployment.status-reason: config change
    openshift.io/encoded-deployment-config: |
      {"kind":"DeploymentConfig","apiVersion":"v1","metadata":{"name":"example","namespace":"extended-test-cli-deployment-j4d8f-xwrkj","selfLink":"/apis/apps.openshift.io/v1/namespaces/extended-test-cli-deployment-j4d8f-xwrkj/deploymentconfigs/example","uid":"600c3ed1-036c-11e8-ba4b-0e7ab02740dc","resourceVersion":"42052","generation":2,"creationTimestamp":"2018-01-27T14:14:23Z","labels":{"app":"example"}},"spec":{"strategy":{"type":"Rolling","rollingParams":{"updatePeriodSeconds":1,"intervalSeconds":1,"timeoutSeconds":600,"maxUnavailable":"25%","maxSurge":"25%"},"resources":{},"activeDeadlineSeconds":21600},"triggers":[{"type":"ImageChange","imageChangeParams":{"automatic":true,"containerNames":["test"],"from":{"kind":"ImageStreamTag","namespace":"extended-test-cli-deployment-j4d8f-xwrkj","name":"test:v1"},"lastTriggeredImage":"docker.io/busybox@sha256:4cee1979ba0bf7db9fc5d28fb7b798ca69ae95a47c5fecf46327720df4ff352d"}}],"replicas":1,"revisionHistoryLimit":10,"test":false,"selector":{"app":"example"},"template":{"metadata":{"creationTimestamp":null,"labels":{"app":"example"}},"spec":{"containers":[{"name":"test","image":"docker.io/busybox@sha256:4cee1979ba0bf7db9fc5d28fb7b798ca69ae95a47c5fecf46327720df4ff352d","command":["/bin/sleep","100"],"resources":{},"terminationMessagePath":"/dev/termination-log","terminationMessagePolicy":"File","imagePullPolicy":"Always"}],"restartPolicy":"Always","terminationGracePeriodSeconds":30,"dnsPolicy":"ClusterFirst","securityContext":{},"schedulerName":"default-scheduler"}}},"status":{"latestVersion":1,"observedGeneration":1,"replicas":0,"updatedReplicas":0,"availableReplicas":0,"unavailableReplicas":0,"details":{"message":"config change","causes":[{"type":"ConfigChange"}]},"conditions":[{"type":"Available","status":"False","lastUpdateTime":"2018-01-27T14:14:23Z","lastTransitionTime":"2018-01-27T14:14:23Z","message":"Deployment config does not have minimum availability."}]}}
  creationTimestamp: 2018-01-27T14:14:24Z
  generation: 1
  labels:
    app: example
    openshift.io/deployment-config.name: example
  name: example-1
  namespace: extended-test-cli-deployment-j4d8f-xwrkj
  ownerReferences:
  - apiVersion: apps.openshift.io/v1
    blockOwnerDeletion: true
    controller: true
    kind: DeploymentConfig
    name: example
    uid: 600c3ed1-036c-11e8-ba4b-0e7ab02740dc
  resourceVersion: "42059"
  selfLink: /api/v1/namespaces/extended-test-cli-deployment-j4d8f-xwrkj/replicationcontrollers/example-1
  uid: 6059717f-036c-11e8-ba4b-0e7ab02740dc
spec:
  replicas: 0
  selector:
    app: example
    deployment: example-1
    deploymentconfig: example
  template:
    metadata:
      annotations:
        openshift.io/deployment-config.latest-version: "1"
        openshift.io/deployment-config.name: example
        openshift.io/deployment.name: example-1
      creationTimestamp: null
      labels:
        app: example
        deployment: example-1
        deploymentconfig: example
    spec:
      containers:
      - command:
        - /bin/sleep
        - "100"
        image: docker.io/busybox@sha256:4cee1979ba0bf7db9fc5d28fb7b798ca69ae95a47c5fecf46327720df4ff352d
        imagePullPolicy: Always
        name: test
        resources: {}
        terminationMessagePath: /dev/termination-log
        terminationMessagePolicy: File
      dnsPolicy: ClusterFirst
      restartPolicy: Always
      schedulerName: default-scheduler
      securityContext: {}
      terminationGracePeriodSeconds: 30
status:
  observedGeneration: 1
  replicas: 0

Jan 27 14:19:24.567: INFO: Running 'oc get --config=/tmp/extended-test-cli-deployment-j4d8f-xwrkj-user.kubeconfig --namespace=extended-test-cli-deployment-j4d8f-xwrkj pod/example-1-deploy -o yaml'
Jan 27 14:19:24.809: INFO: 
apiVersion: v1
kind: Pod
metadata:
  annotations:
    openshift.io/deployment-config.name: example
    openshift.io/deployment.name: example-1
    openshift.io/scc: restricted
  creationTimestamp: 2018-01-27T14:14:24Z
  labels:
    openshift.io/deployer-pod-for.name: example-1
  name: example-1-deploy
  namespace: extended-test-cli-deployment-j4d8f-xwrkj
  ownerReferences:
  - apiVersion: v1
    kind: ReplicationController
    name: example-1
    uid: 6059717f-036c-11e8-ba4b-0e7ab02740dc
  resourceVersion: "42466"
  selfLink: /api/v1/namespaces/extended-test-cli-deployment-j4d8f-xwrkj/pods/example-1-deploy
  uid: 605ce612-036c-11e8-ba4b-0e7ab02740dc
spec:
  activeDeadlineSeconds: 21600
  containers:
  - env:
    - name: KUBERNETES_MASTER
      value: https://ip-172-18-12-166.ec2.internal:8443
    - name: OPENSHIFT_MASTER
      value: https://ip-172-18-12-166.ec2.internal:8443
    - name: BEARER_TOKEN_FILE
      value: /var/run/secrets/kubernetes.io/serviceaccount/token
    - name: OPENSHIFT_CA_DATA
      value: |
        -----BEGIN CERTIFICATE-----
        MIIC6jCCAdKgAwIBAgIBATANBgkqhkiG9w0BAQsFADAmMSQwIgYDVQQDDBtvcGVu
        c2hpZnQtc2lnbmVyQDE1MTcwNTI0NjMwHhcNMTgwMTI3MTEyNzQzWhcNMjMwMTI2
        MTEyNzQ0WjAmMSQwIgYDVQQDDBtvcGVuc2hpZnQtc2lnbmVyQDE1MTcwNTI0NjMw
        ggEiMA0GCSqGSIb3DQEBAQUAA4IBDwAwggEKAoIBAQC1sNtqcZ2QeHVzzQsM/xVl
        yZ8h8XGzw8P3o+0m1LpfyzyvuJmc5xzvcBL1b5DNMk5BnOVrH8gPFSCUpTBM8sn7
        ODAxq++GXdPM4tfCM9feSR7XxEoGGu/pN4jUY4UGWOSFgdjOjub1GwTnfMziXS7S
        eLwOTN/vUFRbquTUnTMcbpOJIBn/+dsP0mKu5ySMKYPJp2IZO6eHfBclqSWzLgs8
        k1s7y0dTK7CvxZpi15/3g2b6E38AAWYDltu0ljuFJqcYMuDyIHP16peX3KUjCkWb
        f5LWCWQY+Ll8FToD8V+2gh7P5jJwNn3lyxVDpJ8uVL9zL6/DfzJ1ulTZDPKnzpR/
        AgMBAAGjIzAhMA4GA1UdDwEB/wQEAwICpDAPBgNVHRMBAf8EBTADAQH/MA0GCSqG
        SIb3DQEBCwUAA4IBAQAqUQwfUJhOAjY4LRf6PkAQLyx3/SCdC38HS8x/Yk07qiZX
        9vwqkkdgEvGtDxRAOTh8Vp7x3PxkcbCfv1OY89AJe6qOINvQ07QEzH6gH6hhr0y4
        Qd6lMN7QMKlsk2nxXYwaDoPJKX6I+PTYeYoYlTLiLUwaGrxL3b2u7eXHk6TPqMyE
        Xv/idy6PCaFo1pShlcosHEcA2fZpZ6te2nlJX0kCTs3bIefWK0HU8rXfjstQjDUE
        OZAnS58yoZ/CrG+TLdKrPKuhkA3UQAleHgn0Ngyia1y092DZpV4bbypQz5Wcn37y
        haRjXnmKPolftFv8WnFIsDxRITDgaoqHRfIRQoe7
        -----END CERTIFICATE-----
    - name: OPENSHIFT_DEPLOYMENT_NAME
      value: example-1
    - name: OPENSHIFT_DEPLOYMENT_NAMESPACE
      value: extended-test-cli-deployment-j4d8f-xwrkj
    image: openshift/origin-deployer:4762d6a
    imagePullPolicy: IfNotPresent
    name: deployment
    resources: {}
    securityContext:
      capabilities:
        drop:
        - KILL
        - MKNOD
        - SETGID
        - SETUID
      runAsUser: 1002350000
    terminationMessagePath: /dev/termination-log
    terminationMessagePolicy: File
    volumeMounts:
    - mountPath: /var/run/secrets/kubernetes.io/serviceaccount
      name: deployer-token-wszgz
      readOnly: true
  dnsPolicy: ClusterFirst
  imagePullSecrets:
  - name: deployer-dockercfg-v4kf9
  nodeName: ip-172-18-12-166.ec2.internal
  nodeSelector:
    region: infra
  restartPolicy: Never
  schedulerName: default-scheduler
  securityContext:
    fsGroup: 1002350000
    seLinuxOptions:
      level: s0:c48,c47
  serviceAccount: deployer
  serviceAccountName: deployer
  terminationGracePeriodSeconds: 10
  volumes:
  - name: deployer-token-wszgz
    secret:
      defaultMode: 420
      secretName: deployer-token-wszgz
status:
  conditions:
  - lastProbeTime: null
    lastTransitionTime: 2018-01-27T14:14:24Z
    status: "True"
    type: Initialized
  - lastProbeTime: null
    lastTransitionTime: 2018-01-27T14:14:24Z
    message: 'containers with unready status: [deployment]'
    reason: ContainersNotReady
    status: "False"
    type: Ready
  - lastProbeTime: null
    lastTransitionTime: 2018-01-27T14:14:24Z
    status: "True"
    type: PodScheduled
  containerStatuses:
  - image: openshift/origin-deployer:4762d6a
    imageID: ""
    lastState: {}
    name: deployment
    ready: false
    restartCount: 0
    state:
      waiting:
        message: Back-off pulling image "openshift/origin-deployer:4762d6a"
        reason: ImagePullBackOff
  hostIP: 172.18.12.166
  phase: Pending
  podIP: 10.128.1.69
  qosClass: BestEffort
  startTime: 2018-01-27T14:14:24Z

Jan 27 14:19:24.809: INFO: Running 'oc logs --config=/tmp/extended-test-cli-deployment-j4d8f-xwrkj-user.kubeconfig --namespace=extended-test-cli-deployment-j4d8f-xwrkj pod/example-1-deploy --timestamps=true'
Jan 27 14:19:25.061: INFO: Error running &{/data/src/github.com/openshift/origin/_output/local/bin/linux/amd64/oc [oc logs --config=/tmp/extended-test-cli-deployment-j4d8f-xwrkj-user.kubeconfig --namespace=extended-test-cli-deployment-j4d8f-xwrkj pod/example-1-deploy --timestamps=true] []   Error from server (BadRequest): container "deployment" in pod "example-1-deploy" is waiting to start: trying and failing to pull image
 Error from server (BadRequest): container "deployment" in pod "example-1-deploy" is waiting to start: trying and failing to pull image
 [] <nil> 0xc421701cb0 exit status 1 <nil> <nil> true [0xc4215547d8 0xc421554808 0xc421554808] [0xc4215547d8 0xc421554808] [0xc4215547e0 0xc4215547f8] [0x9895b0 0x9896b0] 0xc42169c120 <nil>}:
Error from server (BadRequest): container "deployment" in pod "example-1-deploy" is waiting to start: trying and failing to pull image
Jan 27 14:19:25.061: INFO: --- pod example-1-deploy logs
Error from server (BadRequest): container "deployment" in pod "example-1-deploy" is waiting to start: trying and failing to pull image---

[AfterEach] [Feature:DeploymentConfig] deploymentconfigs
  /go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/test/extended/deployments/deployments.go:62
[AfterEach] [Feature:DeploymentConfig] deploymentconfigs
  /go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:135
STEP: Collecting events from namespace "extended-test-cli-deployment-j4d8f-xwrkj".
STEP: Found 8 events.
Jan 27 14:19:27.065: INFO: At 2018-01-27 14:14:24 +0000 UTC - event for example: {deploymentconfig-controller } DeploymentCreated: Created new replication controller "example-1" for version 1
Jan 27 14:19:27.065: INFO: At 2018-01-27 14:14:24 +0000 UTC - event for example-1-deploy: {default-scheduler } Scheduled: Successfully assigned example-1-deploy to ip-172-18-12-166.ec2.internal
Jan 27 14:19:27.065: INFO: At 2018-01-27 14:14:24 +0000 UTC - event for example-1-deploy: {kubelet ip-172-18-12-166.ec2.internal} SuccessfulMountVolume: MountVolume.SetUp succeeded for volume "deployer-token-wszgz" 
Jan 27 14:19:27.065: INFO: At 2018-01-27 14:14:26 +0000 UTC - event for example-1-deploy: {kubelet ip-172-18-12-166.ec2.internal} Pulling: pulling image "openshift/origin-deployer:4762d6a"
Jan 27 14:19:27.065: INFO: At 2018-01-27 14:14:26 +0000 UTC - event for example-1-deploy: {kubelet ip-172-18-12-166.ec2.internal} Failed: Failed to pull image "openshift/origin-deployer:4762d6a": rpc error: code = Unknown desc = manifest unknown: manifest unknown
Jan 27 14:19:27.065: INFO: At 2018-01-27 14:14:26 +0000 UTC - event for example-1-deploy: {kubelet ip-172-18-12-166.ec2.internal} Failed: Error: ErrImagePull
Jan 27 14:19:27.065: INFO: At 2018-01-27 14:14:27 +0000 UTC - event for example-1-deploy: {kubelet ip-172-18-12-166.ec2.internal} BackOff: Back-off pulling image "openshift/origin-deployer:4762d6a"
Jan 27 14:19:27.065: INFO: At 2018-01-27 14:14:27 +0000 UTC - event for example-1-deploy: {kubelet ip-172-18-12-166.ec2.internal} Failed: Error: ImagePullBackOff
Jan 27 14:19:27.072: INFO: POD                          NODE                           PHASE    GRACE  CONDITIONS
Jan 27 14:19:27.072: INFO: docker-registry-1-m9cd2      ip-172-18-12-166.ec2.internal  Running         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 11:31:56 +0000 UTC  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 11:31:58 +0000 UTC  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 11:31:56 +0000 UTC  }]
Jan 27 14:19:27.072: INFO: registry-console-1-nrrsw     ip-172-18-12-166.ec2.internal  Running         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 11:32:18 +0000 UTC  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 11:32:35 +0000 UTC  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 11:32:18 +0000 UTC  }]
Jan 27 14:19:27.072: INFO: router-1-rx6zp               ip-172-18-12-166.ec2.internal  Running         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 11:31:40 +0000 UTC  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 11:31:51 +0000 UTC  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 11:31:40 +0000 UTC  }]
Jan 27 14:19:27.072: INFO: mydockertest-1-build         ip-172-18-12-166.ec2.internal  Pending         [{Initialized False 0001-01-01 00:00:00 +0000 UTC 2018-01-27 13:21:52 +0000 UTC ContainersNotInitialized containers with incomplete status: [git-clone manage-dockerfile]} {Ready False 0001-01-01 00:00:00 +0000 UTC 2018-01-27 13:21:52 +0000 UTC ContainersNotReady containers with unready status: [docker-build]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 13:21:52 +0000 UTC  }]
Jan 27 14:19:27.072: INFO: mys2itest-1-build            ip-172-18-12-166.ec2.internal  Pending         [{Initialized False 0001-01-01 00:00:00 +0000 UTC 2018-01-27 14:10:23 +0000 UTC ContainersNotInitialized containers with incomplete status: [git-clone manage-dockerfile]} {Ready False 0001-01-01 00:00:00 +0000 UTC 2018-01-27 14:10:23 +0000 UTC ContainersNotReady containers with unready status: [sti-build]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 14:10:23 +0000 UTC  }]
Jan 27 14:19:27.072: INFO: sample-build-1-build         ip-172-18-12-166.ec2.internal  Pending         [{Initialized False 0001-01-01 00:00:00 +0000 UTC 2018-01-27 13:20:32 +0000 UTC ContainersNotInitialized containers with incomplete status: [git-clone manage-dockerfile]} {Ready False 0001-01-01 00:00:00 +0000 UTC 2018-01-27 13:20:32 +0000 UTC ContainersNotReady containers with unready status: [sti-build]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 13:20:32 +0000 UTC  }]
Jan 27 14:19:27.072: INFO: example-1-deploy             ip-172-18-12-166.ec2.internal  Pending         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 14:14:24 +0000 UTC  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2018-01-27 14:14:24 +0000 UTC ContainersNotReady containers with unready status: [deployment]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 14:14:24 +0000 UTC  }]
Jan 27 14:19:27.072: INFO: docker-build-1-build         ip-172-18-12-166.ec2.internal  Pending         [{Initialized False 0001-01-01 00:00:00 +0000 UTC 2018-01-27 13:22:44 +0000 UTC ContainersNotInitialized containers with incomplete status: [manage-dockerfile]} {Ready False 0001-01-01 00:00:00 +0000 UTC 2018-01-27 13:22:44 +0000 UTC ContainersNotReady containers with unready status: [docker-build]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 13:22:44 +0000 UTC  }]
Jan 27 14:19:27.072: INFO: apiserver-v5k29              ip-172-18-12-166.ec2.internal  Running         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 11:33:37 +0000 UTC  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 11:33:42 +0000 UTC  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 11:33:38 +0000 UTC  }]
Jan 27 14:19:27.072: INFO: controller-manager-fgsqk     ip-172-18-12-166.ec2.internal  Running         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 11:33:37 +0000 UTC  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 11:33:58 +0000 UTC  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 11:33:38 +0000 UTC  }]
Jan 27 14:19:27.072: INFO: prometheus-0                 ip-172-18-12-166.ec2.internal  Running         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 11:45:21 +0000 UTC  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 11:46:03 +0000 UTC  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 11:45:21 +0000 UTC  }]
Jan 27 14:19:27.072: INFO: asb-1-deploy                 ip-172-18-12-166.ec2.internal  Failed          [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 11:34:07 +0000 UTC  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2018-01-27 11:44:10 +0000 UTC ContainersNotReady containers with unready status: [deployment]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 11:34:07 +0000 UTC  }]
Jan 27 14:19:27.072: INFO: asb-etcd-1-deploy            ip-172-18-12-166.ec2.internal  Failed          [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 11:34:08 +0000 UTC  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2018-01-27 11:44:12 +0000 UTC ContainersNotReady containers with unready status: [deployment]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 11:34:08 +0000 UTC  }]
Jan 27 14:19:27.072: INFO: apiserver-g7ltb              ip-172-18-12-166.ec2.internal  Running         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 11:34:20 +0000 UTC  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 11:34:37 +0000 UTC  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 11:34:24 +0000 UTC  }]
Jan 27 14:19:27.072: INFO: webconsole-69c864449c-tw8n9  ip-172-18-12-166.ec2.internal  Running         [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 11:34:49 +0000 UTC  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 11:35:01 +0000 UTC  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2018-01-27 11:34:49 +0000 UTC  }]
Jan 27 14:19:27.072: INFO: 
Jan 27 14:19:27.074: INFO: 
Logging node info for node ip-172-18-12-166.ec2.internal
Jan 27 14:19:27.076: INFO: Node Info: &Node{ObjectMeta:k8s_io_apimachinery_pkg_apis_meta_v1.ObjectMeta{Name:ip-172-18-12-166.ec2.internal,GenerateName:,Namespace:,SelfLink:/api/v1/nodes/ip-172-18-12-166.ec2.internal,UID:785e7c6b-0355-11e8-ba4b-0e7ab02740dc,ResourceVersion:42660,Generation:0,CreationTimestamp:2018-01-27 11:30:26 +0000 UTC,DeletionTimestamp:<nil>,DeletionGracePeriodSeconds:nil,Labels:map[string]string{beta.kubernetes.io/arch: amd64,beta.kubernetes.io/os: linux,kubernetes.io/hostname: ip-172-18-12-166.ec2.internal,node-role.kubernetes.io/master: true,openshift-infra: apiserver,region: infra,registry: true,router: true,zone: default,},Annotations:map[string]string{volumes.kubernetes.io/controller-managed-attach-detach: true,},OwnerReferences:[],Finalizers:[],ClusterName:,Initializers:nil,},Spec:NodeSpec{PodCIDR:,ExternalID:ip-172-18-12-166.ec2.internal,ProviderID:,Unschedulable:false,Taints:[],ConfigSource:nil,},Status:NodeStatus{Capacity:ResourceList{cpu: {{4 0} {<nil>} 4 DecimalSI},memory: {{16656699392 0} {<nil>} 16266308Ki BinarySI},pods: {{40 0} {<nil>} 40 DecimalSI},},Allocatable:ResourceList{cpu: {{4 0} {<nil>} 4 DecimalSI},memory: {{16551841792 0} {<nil>} 16163908Ki BinarySI},pods: {{40 0} {<nil>} 40 DecimalSI},},Phase:,Conditions:[{OutOfDisk False 2018-01-27 14:19:19 +0000 UTC 2018-01-27 11:30:26 +0000 UTC KubeletHasSufficientDisk kubelet has sufficient disk space available} {MemoryPressure False 2018-01-27 14:19:19 +0000 UTC 2018-01-27 11:30:26 +0000 UTC KubeletHasSufficientMemory kubelet has sufficient memory available} {DiskPressure False 2018-01-27 14:19:19 +0000 UTC 2018-01-27 12:03:45 +0000 UTC KubeletHasNoDiskPressure kubelet has no disk pressure} {Ready True 2018-01-27 14:19:19 +0000 UTC 2018-01-27 11:31:08 +0000 UTC KubeletReady kubelet is posting ready status}],Addresses:[{InternalIP 172.18.12.166} {Hostname ip-172-18-12-166.ec2.internal}],DaemonEndpoints:NodeDaemonEndpoints{KubeletEndpoint:DaemonEndpoint{Port:10250,},},NodeInfo:NodeSystemInfo{MachineID:4372f1e2f8c642d3a2f3ed11aa3fe654,SystemUUID:EC215B86-AE12-2D5A-4C86-79FE72AD3649,BootID:1e42fcc7-c01c-4b86-baf6-44f7f44860bc,KernelVersion:3.10.0-693.17.1.el7.x86_64,OSImage:Red Hat Enterprise Linux Server 7.4 (Maipo),ContainerRuntimeVersion:cri-o://1.9.2-dev,KubeletVersion:v1.9.1+a0ce1bc657,KubeProxyVersion:v1.9.1+a0ce1bc657,OperatingSystem:linux,Architecture:amd64,},Images:[{[docker.io/openshift/origin-haproxy-router:4762d6a] 1279509128} {[docker.io/centos/nodejs-6-centos7:latest] 515826975} {[docker.io/centos/mongodb-34-centos7:latest] 507285392} {[docker.io/openshift/origin-web-console:latest] 501206984} {[docker.io/openshift/origin-docker-registry:4762d6a] 466450956} {[docker.io/centos/mysql-57-centos7:latest] 447153977} {[docker.io/cockpit/kubernetes:latest] 399544576} {[docker.io/openshift/origin-template-service-broker:latest] 313282745} {[docker.io/openshift/origin-service-catalog:latest] 287397545} {[docker.io/openshift/prometheus:v2.0.0] 275096478} {[docker.io/openshift/origin-pod:latest] 228579489} {[docker.io/openshift/origin-pod:4762d6a] 228579292} {[docker.io/openshift/oauth-proxy:v1.0.0] 228244754} {[docker.io/openshift/prometheus-alertmanager:v0.9.1] 220898782} {[docker.io/openshift/prometheus-alert-buffer:v0.0.2] 200523944} {[docker.io/library/nginx:latest] 108499054} {[gcr.io/google-containers/nginx-slim-amd64:0.20] 103595087} {[gcr.io/google_containers/dnsutils:e2e] 8901417} {[gcr.io/kubernetes-e2e-test-images/hostexec-amd64:1.0] 8377623} {[gcr.io/kubernetes-e2e-test-images/netexec-amd64:1.0] 6230968} {[gcr.io/kubernetes-e2e-test-images/serve-hostname-amd64:1.0] 5472826} {[gcr.io/kubernetes-e2e-test-images/test-webserver-amd64:1.0] 4396136} {[gcr.io/kubernetes-e2e-test-images/liveness-amd64:1.0] 4281457} {[gcr.io/google_containers/busybox:latest] 2439416} {[gcr.io/kubernetes-e2e-test-images/mounttest-user-amd64:1.0] 1452588} {[gcr.io/kubernetes-e2e-test-images/mounttest-amd64:1.0] 1452489} {[] 1148393} {[docker.io/library/busybox:latest] 1148393} {[gcr.io/google_containers/pause-amd64:3.0] 751477} {[docker.io/kubernetes/pause:latest] 246793}],VolumesInUse:[],VolumesAttached:[],},}
Jan 27 14:19:27.076: INFO: 
Logging kubelet events for node ip-172-18-12-166.ec2.internal
Jan 27 14:19:27.078: INFO: 
Logging pods the kubelet thinks is on node ip-172-18-12-166.ec2.internal
Jan 27 14:19:27.087: INFO: apiserver-g7ltb started at 2018-01-27 11:34:20 +0000 UTC (0+1 container statuses recorded)
Jan 27 14:19:27.087: INFO:  Container c ready: true, restart count 0
Jan 27 14:19:27.087: INFO: asb-1-deploy started at 2018-01-27 11:34:07 +0000 UTC (0+1 container statuses recorded)
Jan 27 14:19:27.087: INFO:  Container deployment ready: false, restart count 0
Jan 27 14:19:27.087: INFO: webconsole-69c864449c-tw8n9 started at 2018-01-27 11:34:49 +0000 UTC (0+1 container statuses recorded)
Jan 27 14:19:27.087: INFO:  Container webconsole ready: true, restart count 0
Jan 27 14:19:27.087: INFO: mydockertest-1-build started at 2018-01-27 13:21:52 +0000 UTC (2+1 container statuses recorded)
Jan 27 14:19:27.087: INFO:  Init container git-clone ready: false, restart count 0
Jan 27 14:19:27.087: INFO:  Init container manage-dockerfile ready: false, restart count 0
Jan 27 14:19:27.087: INFO:  Container docker-build ready: false, restart count 0
Jan 27 14:19:27.087: INFO: controller-manager-fgsqk started at 2018-01-27 11:33:37 +0000 UTC (0+1 container statuses recorded)
Jan 27 14:19:27.087: INFO:  Container controller-manager ready: true, restart count 2
Jan 27 14:19:27.087: INFO: docker-build-1-build started at 2018-01-27 13:22:44 +0000 UTC (1+1 container statuses recorded)
Jan 27 14:19:27.087: INFO:  Init container manage-dockerfile ready: false, restart count 0
Jan 27 14:19:27.087: INFO:  Container docker-build ready: false, restart count 0
Jan 27 14:19:27.087: INFO: router-1-rx6zp started at 2018-01-27 11:31:40 +0000 UTC (0+1 container statuses recorded)
Jan 27 14:19:27.087: INFO:  Container router ready: true, restart count 0
Jan 27 14:19:27.087: INFO: asb-etcd-1-deploy started at 2018-01-27 11:34:08 +0000 UTC (0+1 container statuses recorded)
Jan 27 14:19:27.087: INFO:  Container deployment ready: false, restart count 0
Jan 27 14:19:27.087: INFO: prometheus-0 started at 2018-01-27 11:45:21 +0000 UTC (0+6 container statuses recorded)
Jan 27 14:19:27.087: INFO:  Container alert-buffer ready: true, restart count 0
Jan 27 14:19:27.087: INFO:  Container alertmanager ready: true, restart count 0
Jan 27 14:19:27.087: INFO:  Container alertmanager-proxy ready: true, restart count 0
Jan 27 14:19:27.087: INFO:  Container alerts-proxy ready: true, restart count 0
Jan 27 14:19:27.087: INFO:  Container prom-proxy ready: true, restart count 0
Jan 27 14:19:27.087: INFO:  Container prometheus ready: true, restart count 0
Jan 27 14:19:27.087: INFO: registry-console-1-nrrsw started at 2018-01-27 11:32:18 +0000 UTC (0+1 container statuses recorded)
Jan 27 14:19:27.087: INFO:  Container registry-console ready: true, restart count 0
Jan 27 14:19:27.087: INFO: docker-registry-1-m9cd2 started at 2018-01-27 11:31:56 +0000 UTC (0+1 container statuses recorded)
Jan 27 14:19:27.087: INFO:  Container registry ready: true, restart count 0
Jan 27 14:19:27.087: INFO: apiserver-v5k29 started at 2018-01-27 11:33:37 +0000 UTC (0+1 container statuses recorded)
Jan 27 14:19:27.087: INFO:  Container apiserver ready: true, restart count 0
Jan 27 14:19:27.087: INFO: sample-build-1-build started at 2018-01-27 13:20:32 +0000 UTC (2+1 container statuses recorded)
Jan 27 14:19:27.087: INFO:  Init container git-clone ready: false, restart count 0
Jan 27 14:19:27.087: INFO:  Init container manage-dockerfile ready: false, restart count 0
Jan 27 14:19:27.087: INFO:  Container sti-build ready: false, restart count 0
Jan 27 14:19:27.087: INFO: mys2itest-1-build started at 2018-01-27 14:10:23 +0000 UTC (2+1 container statuses recorded)
Jan 27 14:19:27.087: INFO:  Init container git-clone ready: false, restart count 0
Jan 27 14:19:27.087: INFO:  Init container manage-dockerfile ready: false, restart count 0
Jan 27 14:19:27.087: INFO:  Container sti-build ready: false, restart count 0
Jan 27 14:19:27.087: INFO: example-1-deploy started at 2018-01-27 14:14:24 +0000 UTC (0+1 container statuses recorded)
Jan 27 14:19:27.087: INFO:  Container deployment ready: false, restart count 0
W0127 14:19:27.090149   76271 metrics_grabber.go:81] Master node is not registered. Grabbing metrics from Scheduler, ControllerManager and ClusterAutoscaler is disabled.
Jan 27 14:19:27.113: INFO: 
Latency metrics for node ip-172-18-12-166.ec2.internal
Jan 27 14:19:27.113: INFO: {Operation:create Method:pod_worker_latency_microseconds Quantile:0.99 Latency:2m3.025489s}
Jan 27 14:19:27.113: INFO: {Operation:create Method:pod_worker_latency_microseconds Quantile:0.9 Latency:2m3.025489s}
STEP: Dumping a list of prepulled images on each node...
Jan 27 14:19:27.115: INFO: Waiting up to 3m0s for all (but 0) nodes to be ready
STEP: Destroying namespace "extended-test-cli-deployment-j4d8f-xwrkj" for this suite.
Jan 27 14:19:39.128: INFO: Waiting up to 30s for server preferred namespaced resources to be successfully discovered
Jan 27 14:19:39.204: INFO: namespace: extended-test-cli-deployment-j4d8f-xwrkj, resource: bindings, ignored listing per whitelist
Jan 27 14:19:39.290: INFO: namespace extended-test-cli-deployment-j4d8f-xwrkj deletion completed in 12.17237357s

• Failure [315.643 seconds]
[Feature:DeploymentConfig] deploymentconfigs
/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/test/extended/deployments/deployments.go:37
  won't deploy RC with unresolved images [Conformance]
  /go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/test/extended/deployments/deployments.go:1398
    when patched with empty image [Suite:openshift/conformance/parallel] [It]
    /go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/test/extended/deployments/deployments.go:1405

    Expected error:
        <*errors.errorString | 0xc4202cfd40>: {
            s: "timed out waiting for the condition",
        }
        timed out waiting for the condition
    not to have occurred

    /go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/test/extended/deployments/deployments.go:1437
runcom commented 6 years ago

This is because the image is being removed by the image GC. We're working with @stevekuznetsov to upgrade disk size on CFI-O instances to fix the issue.

tnozicka commented 6 years ago

@runcom is that also the reason why it doesn't get pulled again? The test is waiting for 5 minutes on the pull.

/assign @runcom @stevekuznetsov

runcom commented 6 years ago

@runcom is that also the reason why it doesn't get pulled again? The test is waiting for 5 minutes on the pull.

yes, that images can't be pulled, it's built as part of the whole test so that's why it's failing to pull it.

tnozicka commented 6 years ago

makes sense, thx for explaining it ;)

runcom commented 6 years ago

Fixed by increasing disk size of test instances