404 pushing to imagestream in registry

[bparees]

https://openshift-gce-devel.appspot.com/build/origin-ci-test/pr-logs/pull/17429/test_pull_request_origin_extended_conformance_gce/12430/

build got an error pushing to the imagestream:

2017-12-05T22:23:29.380468000Z Pushing image docker-registry.default.svc:5000/extended-test-docker-build-pullsecret-l4xm6-gcrp2/image1:latest ...
2017-12-05T22:23:31.703007000Z Registry server Address: 
2017-12-05T22:23:31.703304000Z Registry server User Name: serviceaccount
2017-12-05T22:23:31.703542000Z Registry server Email: [email protected]
2017-12-05T22:23:31.703809000Z Registry server Password: <<non-empty>>
2017-12-05T22:23:31.836478000Z error: build error: Failed to push image: Error: Status 404 trying to push repository extended-test-docker-build-pullsecret-l4xm6-gcrp2/image1: "404 page not found\n"

why wouldn't it just create the repo?

registry logs:

Dec  5 22:23:34.130: INFO: Running 'oc logs --config=/tmp/cluster-admin.kubeconfig --namespace=default dc/docker-registry --since=12.130927986s'
Dec  5 22:23:34.474: INFO: 172.16.2.1 - - [05/Dec/2017:22:23:30 +0000] "GET /healthz HTTP/2.0" 200 0 "" "kube-probe/1.8"
172.16.4.1 - - [05/Dec/2017:22:23:31 +0000] "GET /v1/_ping HTTP/1.1" 404 19 "" "docker/1.12.6 go/go1.8.3 kernel/3.10.0-693.5.2.el7.x86_64 os/linux arch/amd64 UpstreamClient(go-dockerclient)"
172.16.4.1 - - [05/Dec/2017:22:23:31 +0000] "PUT /v1/repositories/extended-test-docker-build-pullsecret-l4xm6-gcrp2/image1/ HTTP/1.1" 404 19 "" "docker/1.12.6 go/go1.8.3 kernel/3.10.0-693.5.2.el7.x86_64 os/linux arch/amd64 UpstreamClient(go-dockerclient)"

[miminar]

My guess is that the registry was not ready at the time the build started. The docker always hits /v2/ endpoint first. If it fails, it continues with /v1/ endpoint. The fallback to /v1/ often happens when the test doesn't wait for the registry to be ready.

Unfortunately, the log doesn't reveal much. It's oddly short. I think we should capture at least +10s more context or use timestamps instead. The timestamp has a benefit of picking up always the same starting log line regardless of delay between issuing oc logs and actually running it.

[bparees]

it's an extended test running on the cluster shared by the extended test framework, so if something should be waiting for the registry to be"up", it should be the extended test framework that stood up the cluster. Can you look into what we're doing there and make sure it's the right thing?

I'm not sure how +10s logging context would help... we dumped the entire registry log after the push had failed. Why would we expect additional logs to show up 10s later?

You can definitely add "--timestamps" to our various extended test util log dumpers.

[miminar]

You can see --since=12.130927986s added to the log dumper. The few lines printed is certainly not the full log. Initialization part is not shown.

I'll look into the test framework.

[bparees]

@miminar ok, i don't know why that was put in place but it should be removed. we should be dumping full registry logs.

[bparees]

@dmage @legionus i think i sent a different flake your way recently that was also caused by a 404 result against the /v1 endpoint. Perhaps you can combine that issue with this one.

[bparees]

this is the related issue i was thinking of: #17897

[dmage]

the registry was not ready at the time the build started.

@miminar nice, it's a very plausible scenario.

[bparees]

going to optimistically assume this is the same as #17897