TestNewAppRunBuilds fails with unexpected error: no match for "centos/mongodb-26-centos7"

[liggitt]

https://ci.openshift.redhat.com/jenkins/job/merge_pull_requests_origin/5552/consoleFull

I0410 23:47:53.278646   23318 dockerimagelookup.go:312] Adding Docker image "centos/mongodb-26-centos7" (tag "latest"), 31e98a6, from Docker Hub, author SoftwareCollections.org <[email protected]> as component match for "centos/mongodb-26-centos7" with score 0
I0410 23:47:53.278677   23318 resolve.go:450] Using "centos/mongodb-26-centos7" as the source for build
I0410 23:47:53.278692   23318 resolve.go:452] Pairing with component centos/mysql-56-centos7
I0410 23:47:53.278711   23318 resolve.go:167] Code [centos/mongodb-26-centos7]
I0410 23:47:53.278721   23318 resolve.go:168] Components [centos/mysql-56-centos7]
I0410 23:47:53.278742   23318 newapp.go:265] found group: centos/mysql-56-centos7
I0410 23:47:53.278753   23318 newapp.go:276] will add "" secrets into a build for a source build of "centos/mongodb-26-centos7"
I0410 23:47:53.278768   23318 newapp.go:280] will use "centos/mysql-56-centos7" as the base image for a source build of "centos/mongodb-26-centos7"
--- FAIL: TestNewAppRunBuilds-2 (2.10s)
    newapp_test.go:1198: successful input image source build with a repository: unexpected error: no match for "centos/mongodb-26-centos7"

[smarterclayton]

This is lower priority because this is calling our legacy pkg/dockerregistry code path (we use ImageStreamImport everywhere else now). However, ImageStreamImport calls pkg/dockerregistry, so this may expose a crazy legacy flake

[smarterclayton]

If anyone sees this again please look for the debugging output I added in #8552

[smarterclayton]

Debug output:

I0418 19:28:33.010787   12617 client.go:320] Found registry v2 API at https://registry-1.docker.io/v2/
I0418 19:28:33.061608   12617 client.go:539] passed valid auth token, but unable to find tagged image at "https://registry-1.docker.io/v2/centos/mongodb-26-centos7/manifests/latest", 401 map[Content-Type:[application/json; charset=utf-8] Docker-Distribution-Api-Version:[registry/2.0] Www-Authenticate:[Bearer realm="https://auth.docker.io/token",service="registry.docker.io",scope="repository:centos/mongodb-26-centos7:pull",error="invalid_token"] Date:[Mon, 18 Apr 2016 23:28:32 GMT] Content-Length:[157] Strict-Transport-Security:[max-age=31536000]]: {"errors":[{"code":"UNAUTHORIZED","message":"authentication required","detail":[{"Type":"repository","Name":"centos/mongodb-26-centos7","Action":"pull"}]}]}
I0418 19:28:33.061678   12617 dockerimagelookup.go:279] tag not found: the default tag "latest" has not been set on repository "centos/mongodb-26-centos7"

[smarterclayton]

So this looks like some sort of race condition with the docker registry - we have a valid token, but then we get a 401 from the registry. I bet this is also happening on import. I think what we need to do is track when we have a token and the age on it - then retry if it's within a window. If it's a truly public image, and we get this error, we should retry a lot more times - there is no reason for a public image not to retry.

Going to whip something up.

[smarterclayton]

Looks like a transient flake in the registry:

I0418 12:29:36.847812   15382 controller.go:171] Import stream cmd-newapp/mysql partial=true import: &api.ImageStream{TypeMeta:unversioned.TypeMeta{Kind:"", APIVersion:""}, ObjectMeta:api.ObjectMeta{Name:"mysql", GenerateName:"", Namespace:"cmd-newapp", SelfLink:"", UID:"ba4e6431-0582-11e6-ad6c-0e32afea2687", ResourceVersion:"3123", Generation:2, CreationTimestamp:unversioned.Time{Time:time.Time{sec:63596593771, nsec:0, loc:(*time.Location)(0x593fde0)}}, DeletionTimestamp:(*unversioned.Time)(nil), DeletionGracePeriodSeconds:(*int64)(nil), Labels:map[string]string(nil), Annotations:map[string]string{"openshift.io/image.dockerRepositoryCheck":"2016-04-18T16:29:36Z"}}, Spec:api.ImageStreamSpec{DockerImageRepository:"", Tags:map[string]api.TagReference{"5.5":api.TagReference{Name:"5.5", Annotations:map[string]string{"iconClass":"icon-mysql-database", "tags":"mysql", "version":"5.5", "description":"Provides a MySQL v5.5 database"}, From:(*api.ObjectReference)(0xc210e8afc0), Reference:false, Generation:(*int64)(0xc212a34108), ImportPolicy:api.TagImportPolicy{Insecure:false, Scheduled:false}}, "5.6":api.TagReference{Name:"5.6", Annotations:map[string]string{"tags":"mysql", "version":"5.6", "description":"Provides a MySQL v5.6 database", "iconClass":"icon-mysql-database"}, From:(*api.ObjectReference)(0xc210e8b0a0), Reference:false, Generation:(*int64)(0xc212a34118), ImportPolicy:api.TagImportPolicy{Insecure:false, Scheduled:false}}, "latest":api.TagReference{Name:"latest", Annotations:map[string]string{"description":"Provides a MySQL database", "iconClass":"icon-mysql-database", "tags":"mysql"}, From:(*api.ObjectReference)(0xc210e8b180), Reference:false, Generation:(*int64)(0xc212a34168), ImportPolicy:api.TagImportPolicy{Insecure:false, Scheduled:false}}}}, Status:api.ImageStreamStatus{DockerImageRepository:"172.30.125.56:5000/cmd-newapp/mysql", Tags:map[string]api.TagEventList{"5.5":api.TagEventList{Items:[]api.TagEvent{api.TagEvent{Created:unversioned.Time{Time:time.Time{sec:63596593776, nsec:0, loc:(*time.Location)(0x593fde0)}}, DockerImageReference:"openshift/mysql-55-centos7@sha256:060242e91078b3c1eed98451ca9d1b01435e82ad9c27fc9f5d2dde08e7911ca8", Image:"sha256:060242e91078b3c1eed98451ca9d1b01435e82ad9c27fc9f5d2dde08e7911ca8", Generation:2}}, Conditions:[]api.TagEventCondition(nil)}, "5.6":api.TagEventList{Items:[]api.TagEvent{api.TagEvent{Created:unversioned.Time{Time:time.Time{sec:63596593776, nsec:0, loc:(*time.Location)(0x593fde0)}}, DockerImageReference:"centos/mysql-56-centos7@sha256:71c53370d49aac48ec093de8daed44dd656771baf5b75d1432debb7a4fdedb55", Image:"sha256:71c53370d49aac48ec093de8daed44dd656771baf5b75d1432debb7a4fdedb55", Generation:2}}, Conditions:[]api.TagEventCondition(nil)}, "latest":api.TagEventList{Items:[]api.TagEvent{api.TagEvent{Created:unversioned.Time{Time:time.Time{sec:63596593776, nsec:0, loc:(*time.Location)(0x593fde0)}}, DockerImageReference:"centos/mysql-56-centos7@sha256:71c53370d49aac48ec093de8daed44dd656771baf5b75d1432debb7a4fdedb55", Image:"sha256:71c53370d49aac48ec093de8daed44dd656771baf5b75d1432debb7a4fdedb55", Generation:2}}, Conditions:[]api.TagEventCondition(nil)}}}}
I0418 12:29:36.848620   15382 image_change_controller.go:47] Build image change controller detected ImageStream change 172.30.125.56:5000/cmd-newapp/mysql
I0418 12:29:36.848778   15382 controller.go:132] Importing stream cmd-newapp/postgresql partial=true...
I0418 12:29:36.848789   15382 factory.go:142] DEBUG: stream postgresql was just imported
I0418 12:29:36.849923   15382 importer.go:308] importing remote Docker repository registry=https://registry-1.docker.io repository=centos/postgresql-94-centos7 insecure=false
I0418 12:29:36.887741   15382 credentials.go:139] Being asked for https://auth.docker.io/token, trying index.docker.io/v1 for legacy behavior
I0418 12:29:36.887768   15382 credentials.go:144] Being asked for //index.docker.io/v1, trying docker.io for legacy behavior
I0418 12:29:36.887783   15382 credentials.go:147] Unable to find a secret to match //docker.io (docker.io)
I0418 12:29:36.950198   15382 controller.go:82] Handling build cmd-builds/ruby-sample-build-invalidtag-2
I0418 12:29:36.953054   15382 factory.go:39] Retrying Build cmd-builds/ruby-sample-build-invalidtag-2 with error: the referenced output image stream cmd-builds/origin-ruby-sample does not exist
I0418 12:29:37.025286   15382 importer.go:308] importing remote Docker repository registry=https://registry-1.docker.io repository=openshift/postgresql-92-centos7 insecure=false
I0418 12:29:37.027702   15382 credentials.go:139] Being asked for https://auth.docker.io/token, trying index.docker.io/v1 for legacy behavior
I0418 12:29:37.027723   15382 credentials.go:144] Being asked for //index.docker.io/v1, trying docker.io for legacy behavior
I0418 12:29:37.027736   15382 credentials.go:147] Unable to find a secret to match //docker.io (docker.io)
I0418 12:29:37.056259   15382 importer.go:430] unable to access tag "latest" for repository &importer.importRepository{Ref:api.DockerImageReference{Registry:"", Namespace:"openshift", Name:"postgresql-92-centos7", Tag:"latest", ID:""}, Registry:(*url.URL)(0xc2117b8f00), Name:"openshift/postgresql-92-centos7", Insecure:false, Tags:[]importer.importTag{importer.importTag{Name:"latest", Image:(*api.Image)(nil), Err:error(nil)}}, Digests:[]importer.importDigest(nil), MaximumTags:0, AdditionalTags:[]string(nil), Err:error(nil)}: errcode.Errors{errcode.Error{Code:1002, Message:"authentication required", Detail:[]interface {}{map[string]interface {}{"Type":"repository", "Name":"openshift/postgresql-92-centos7", "Action":"pull"}}}}
I0418 12:29:37.057196   15382 helper.go:335] Image metadata already filled for sha256:18b2de4a1ad747675549aec4c3b8632efa2504919e4113e0785b8a03d95b9e3a
I0418 12:29:37.069574   15382 helper.go:335] Image metadata already filled for sha256:18b2de4a1ad747675549aec4c3b8632efa2504919e4113e0785b8a03d95b9e3a
I0418 12:29:37.069783   15382 rest.go:250] updated stream {"name":"postgresql","namespace":"cmd-newapp","uid":"ba50d3d6-0582-11e6-ad6c-0e32afea2687","resourceVersion":"3114","generation":1,"creationTimestamp":"2016-04-18T16:29:31Z","Spec":{"DockerImageRepository":"","Tags":{"9.2":{"Name":"9.2","Annotations":{"description":"Provides a PostgreSQL v9.2 database","iconClass":"icon-postgresql","tags":"postgresql","version":"9.2"},"From":{"kind":"DockerImage","name":"openshift/postgresql-92-centos7:latest"},"Reference":false,"Generation":

A: 1,"ImportPolicy":{"Insecure":false,"Scheduled":false}},"9.4":{"Name":"9.4","Annotations":{"description":"Provides a PostgreSQL v9.4 database","iconClass":"icon-postgresql","tags":"postgresql","version":"9.4"},"From":{"kind":"DockerImage","name":"centos/postgresql-94-centos7:latest"},"Reference":false,"Generation":1,"ImportPolicy":{"Insecure":false,"Scheduled":false}},"latest":{"Name":"latest","Annotations":{"description":"Provides a PostgreSQL database","iconClass":"icon-postgresql","tags":"postgresql"},"From":{"kind":"ImageStreamTag","name":"9.4"},"Reference":false,"Generation":1,"ImportPolicy":{"Insecure":false,"Scheduled":false}}}},"Status":{"DockerImageRepository":"172.30.125.56:5000/cmd-newapp/postgresql","Tags":{}}}

B: 0,"ImportPolicy":{"Insecure":false,"Scheduled":false}},"9.4":{"Name":"9.4","Annotations":{"description":"Provides a PostgreSQL v9.4 database","iconClass":"icon-postgresql","tags":"postgresql","version":"9.4"},"From":{"kind":"DockerImage","name":"centos/postgresql-94-centos7:latest"},"Reference":false,"Generation":0,"ImportPolicy":{"Insecure":false,"Scheduled":false}},"latest":{"Name":"latest","Annotations":{"description":"Provides a PostgreSQL database","iconClass":"icon-postgresql","tags":"postgresql"},"From":{"kind":"ImageStreamTag","name":"9.4"},"Reference":false,"Generation":1,"ImportPolicy":{"Insecure":false,"Scheduled":false}}}},"Status":{"DockerImageRepository":"172.30.125.56:5000/cmd-newapp/postgresql","Tags":{"9.2":{"Items":null,"Conditions":[{"Type":"ImportSuccess","Status":"False","LastTransitionTime":"2016-04-18T16:29:37Z","Reason":"Unauthorized","Message":"you may not have access to the Docker image \"openshift/postgresql-92-centos7:latest\"","Generation":2}]},"9.4":{"Items":[{"Created":"2016-04-18T16:29:37Z","DockerImageReference":"centos/postgresql-94-centos7@sha256:18b2de4a1ad747675549aec4c3b8632efa2504919e4113e0785b8a03d95b9e3a","Image":"sha256:18b2de4a1ad747675549aec4c3b8632efa2504919e4113e0785b8a03d95b9e3a","Generation":2}],"Conditions":null}}}}

I0418 12:29:37.070475   15382 helper.go:578] UpdateTrackingTags: stream=cmd-newapp/postgresql, updatedTag=9.4, updatedImage.dockerImageReference=centos/postgresql-94-centos7@sha256:18b2de4a1ad747675549aec4c3b8632efa2504919e4113e0785b8a03d95b9e3a, updatedImage.image=sha256:18b2de4a1ad747675549aec4c3b8632efa2504919e4113e0785b8a03d95b9e3a
I0418 12:29:37.070492   15382 helper.go:580] Examining spec tag "9.2", tagRef=api.TagReference{Name:"9.2", Annotations:map[string]string{"description":"Provides a PostgreSQL v9.2 database", "iconClass":"icon-postgresql", "tags":"postgresql", "version":"9.2"}, From:(*api.ObjectReference)(0xc210eb5340), Reference:false, Generation:(*int64)(0xc20b1a2170), ImportPolicy:api.TagImportPolicy{Insecure:false, Scheduled:false}}
I0418 12:29:37.070534   15382 helper.go:590] tagRef.Kind "DockerImage" isn't ImageStreamTag, skipping
I0418 12:29:37.070542   15382 helper.go:580] Examining spec tag "9.4", tagRef=api.TagReference{Name:"9.4", Annotations:map[string]string{"description":"Provides a PostgreSQL v9.4 database", "iconClass":"icon-postgresql", "tags":"postgresql", "version":"9.4"}, From:(*api.ObjectReference)(0xc210eb5960), Reference:false, Generation:(*int64)(0xc20b1a2170), ImportPolicy:api.TagImportPolicy{Insecure:false, Scheduled:false}}
I0418 12:29:37.070572   15382 helper.go:590] tagRef.Kind "DockerImage" isn't ImageStreamTag, skipping
I0418 12:29:37.070580   15382 helper.go:580] Examining spec tag "latest", tagRef=api.TagReference{Name:"latest", Annotations:map[string]string{"description":"Provides a PostgreSQL database", "iconClass":"icon-postgresql", "tags":"postgresql"}, From:(*api.ObjectReference)(0xc210eb5570), Reference:false, Generation:(*int64)(0xc21320c940), ImportPolicy:api.TagImportPolicy{Insecure:false, Scheduled:false}}
I0418 12:29:37.070605   15382 helper.go:620] tagRefName="postgresql", tag="9.4"
I0418 12:29:37.070616   15382 helper.go:635] stream updated
I0418 12:29:37.070622   15382 helper.go:578] UpdateTrackingTags: stream=cmd-newapp/postgresql, updatedTag=latest, updatedImage.dockerImageReference=centos/postgresql-94-centos7@sha256:18b2de4a1ad747675549aec4c3b8632efa2504919e4113e0785b8a03d95b9e3a, updatedImage.image=sha256:18b2de4a1ad747675549aec4c3b8632efa2504919e4113e0785b8a03d95b9e3a
I0418 12:29:37.070629   15382 helper.go:580] Examining spec tag "9.4", tagRef=api.TagReference{Name:"9.4", Annotations:map[string]string{"tags":"postgresql", "version":"9.4", "description":"Provides a PostgreSQL v9.4 database", "iconClass":"icon-postgresql"}, From:(*api.ObjectReference)(0xc210eb5960), Reference:false, Generation:(*int64)(0xc20b1a2170), ImportPolicy:api.TagImportPolicy{Insecure:false, Scheduled:false}}
I0418 12:29:37.070657   15382 helper.go:590] tagRef.Kind "DockerImage" isn't ImageStreamTag, skipping
I0418 12:29:37.070664   15382 helper.go:580] Examining spec tag "latest", tagRef=api.TagReference{Name:"latest", Annotations:map[string]string{"description":"Provides a PostgreSQL database", "iconClass":"icon-postgresql", "tags":"postgresql"}, From:(*api.ObjectReference)(0xc210eb5570), Reference:false, Generation:(*int64)(0xc21320c940), ImportPolicy:api.TagImportPolicy{Insecure:false, Scheduled:false}}
I0418 12:29:37.070687   15382 helper.go:620] tagRefName="postgresql", tag="9.4"
I0418 12:29:37.070696   15382 helper.go:630] tag "9.4" doesn't match updated tag "latest" - skipping
I0418 12:29:37.070703   15382 helper.go:580] Examining spec tag "9.2", tagRef=api.TagReference{Name:"9.2", Annotations:map[string]string{"iconClass":"icon-postgresql", "tags":"postgresql", "version":"9.2", "description":"Provides a PostgreSQL v9.2 database"}, From:(*api.ObjectReference)(0xc210eb5340), Reference:false, Generation:(*int64)(0xc20b1a2170), ImportPolicy:api.TagImportPolicy{Insecure:false, Scheduled:false}}
I0418 12:29:37.070727   15382 helper.go:590] tagRef.Kind "DockerImage" isn't ImageStreamTag, skipping

We import two, back to back, then fail on one. We succeed first, then fail second, which may be token propagation or possibly even that one of the Hub registry services has a clock skew and is rejecting newly minted tokens.

[smarterclayton]

I'm going to try to do a confined fix - where if we get a 401, we retry a few times - and if we've successfully pulled an image we replenish the retry. Or something complex like this. I assume this may also happen on the protected registry, and on docker trusted registries.

[smarterclayton]

I think I have a fix. Was able to consistently recreate it, it's around ~1/200 calls to the hub, and usually happens on the first request to the hub after getting an auth token.

[smarterclayton]

I'll need to have a separate bit of code for pkg/dockerregistry - debating whether it's even worth it since we only call the v2 code path in that one test. I may just switch the test to imagestreamimport and declare the old code path for pkg/dockerregistry dead.

[0xmichalis]

https://ci.openshift.redhat.com/jenkins/job/test_pull_requests_origin_integration/257/consoleFull

[smarterclayton]

This latest is actually a different error:

I0509 13:53:33.112063    8634 client.go:567] unable to find tagged image at "https://registry-1.docker.io/v2/openshift/origin-base/manifests/latest", 404 map[Content-Type:[application/json; charset=utf-8] Docker-Distribution-Api-Version:[registry/2.0] Date:[Mon, 09 May 2016 17:53:33 GMT] Content-Length:[297] Strict-Transport-Security:[max-age=31536000]]: {"errors":[{"code":"MANIFEST_UNKNOWN","message":"manifest unknown","detail":{"DriverName":"s3","Enclosed":{"Op":"Get","URL":"https://s3-external-1.amazonaws.com/docker-images-prod/registry-v2/docker/registry/v2/repositories/openshift/origin-base/_manifests/tags/latest/current/link","Err":{}}}}]}
I0509 13:53:33.112137    8634 dockerimagelookup.go:279] tag not found: the default tag "latest" has not been set on repository "openshift/origin-base"