Bug 1531676

we're going to need logs from the registries and a timestamp for when the push was performed.

So with Stefanie's useful starting point, I was at least able to construct some manageable greps.  Still entry level triage.  Need either Ben or our SMEs in Brno to take a crack.  Got this single error log with this grep:

gmontero ~/bz1531676 $ grep "level=error" docker-registry-*.log | grep "T19:08" | grep pod-infrastructure
time="2018-01-05T19:08:41.411990087Z" level=error msg="response completed with error" err.code="blob unknown" err.detail=sha256:f2967472fbfad5233fa3c828e79dab398a8bf2615413109f915470113854b509 err.message="blob unknown to registry" go.version=go1.7.6 http.request.host="registry.reg-aws.openshift.com:443" http.request.id=520c69dd-e4b1-4b86-b983-90a64eb04591 http.request.method=HEAD http.request.remoteaddr=66.187.233.206 http.request.uri="/v2/rhel7/pod-infrastructure/blobs/sha256:f2967472fbfad5233fa3c828e79dab398a8bf2615413109f915470113854b509" http.request.useragent="docker/1.12.6 go/go1.8.3 kernel/3.10.0-693.el7.x86_64 os/linux arch/amd64 UpstreamClient(Docker-Client/1.12.6 \\(linux\\))" http.response.contenttype="application/json; charset=utf-8" http.response.duration=30.227278858s http.response.status=404 http.response.written=157 instance.id=b8e19ff6-d885-4993-a937-630caa21068f openshift.auth.user=aos-ci-jenkins36 openshift.auth.userid=3226cdaa-7868-11e7-a068-0e3533cbf8ac openshift.logger=registry vars.digest="sha256:f2967472fbfad5233fa3c828e79dab398a8bf2615413109f915470113854b509" vars.name="rhel7/pod-infrastructure" 
gmontero ~/bz1531676 $ 

There are 17 instances of those "blob-unknown" for with "pod-infrastructure" across all the logs.  There are 658 "blob-unknown" overall though.  So *maybe* a red herring??

aside from those "blob unknown" errors, I see a fair amount of:

1) manifest unknown

docker-registry-6-067qv.log:time="2018-01-05T16:10:20.092791641Z" level=error msg="response completed with error" err.code="manifest unknown" err.detail="unknown tag=v3.7.19" err.message="manifest unknown" go.version=go1.7.6 http.request.host="registry.reg-aws.openshift.com:443" http.request.id=aa61d1aa-ecc9-4457-9d57-2b7d45cb1e8f http.request.method=GET http.request.remoteaddr=52.91.95.85 http.request.uri="/v2/rhel7/pod-infrastructure/manifests/v3.7.19" http.request.useragent="docker/1.12.6 go/go1.8.3 kernel/3.10.0-693.11.6.el7.x86_64 os/linux arch/amd64 UpstreamClient(Docker-Client/1.12.6 \\(linux\\))" http.response.contenttype="application/json; charset=utf-8" http.response.duration=25.6455ms http.response.status=404 http.response.written=97 instance.id=2e435a5c-de98-45c5-8509-20e3f9f42606 openshift.auth.user=ops-prod-pull36 openshift.auth.userid=2f6e1844-67f9-11e7-a502-0eca478c6462 openshift.logger=registry vars.name="rhel7/pod-infrastructure" vars.reference=v3.7.19 
docker-registry-6-4fmwk.log:time="2018-01-05T16:09:54.13155374Z" level=error msg="response completed with error" err.code="manifest unknown" err.detail="unknown tag=v3.7.19-1" err.message="manifest unknown" go.version=go1.7.6 http.request.host="registry.reg-aws.openshift.com:443" http.request.id=2765e92c-9365-4278-9f7c-ad06b70ca9fb http.request.method=GET http.request.remoteaddr=52.91.95.85 http.request.uri="/v2/rhel7/pod-infrastructure/manifests/v3.7.19-1" http.request.useragent="docker/1.12.6 go/go1.8.3 kernel/3.10.0-693.11.6.el7.x86_64 os/linux arch/amd64 UpstreamClient(Docker-Client/1.12.6 \\(linux\\))" http.response.contenttype="application/json; charset=utf-8" http.response.duration=35.950734ms http.response.status=404 http.response.written=99 instance.id=b8e19ff6-d885-4993-a937-630caa21068f openshift.auth.user=ops-prod-pull36 openshift.auth.userid=2f6e1844-67f9-11e7-a502-0eca478c6462 openshift.logger=registry vars.name="rhel7/pod-infrastructure" vars.reference=v3.7.19-1 

there are 2 of those (http rc 404) with "pod-infrastructure", but 13,744 overall ... red herring most likely

2) auth errors

time="2018-01-05T19:08:23.053348836Z" level=error msg="error authorizing context: authorization header required" go.version=go1.7.6 http.request.host="registry.reg-aws.openshift.com:443" http.request.id=89f4fd95-b8f4-4ff1-aa3e-cff5de638723 http.request.method=GET http.request.remoteaddr=66.187.233.202 http.request.uri="/v2/" http.request.useragent="docker/1.12.6 go/go1.8.3 kernel/3.10.0-693.el7.x86_64 os/linux arch/amd64 UpstreamClient(Go-http-client/1.1)" instance.id=b8e19ff6-d885-4993-a937-630caa21068f openshift.logger=registry 

But that doesn't reference pod-infrastructure;  Seems more like a red herring but deferring to the SMEs.

3) 

Can't find any reference to a 504 rc in either the registry logs or master audit log.

Can we recycle the registry pods?  I'm wondering if they have some invalid blob id content cached.

Also, Alexey/Oleg we definitely need to sort out why we appear to be returning an incorrect 504 response code (or perhaps we're not responding at all and the proxy is returning the 504, but that would be bad also).

Do we have any API logs for these 158 requests with timings? We need to figure out whether the requests were rate-limited on client side or on server side.

It would be also good to see some prometheus metrics when this is reproduced to see the API request times on images endpoint.

While the performance degradation is unfortunate and we should investigate, I don't consider this a blocker bug unless we see the performance degradation in other places as well.