Crono job behaving erratically

[schancel]

I'm seeing crono logs that look like this frequently. Basically, any error is causing crono to wipe out images that exist. This causes audit information about images to get lost. It's also strange that the CatalogJob randomly takes a very long time -- but there doens't seem to be any particular slowness on the part of the registry.

I'm running a build based on #1093 and everything else seems to be working normally most of the time. (e.g. tokens are issued properly and work)

From crono job logs:

2017-03-03T17:02:35.376 protus-host I, [2017-03-03T17:02:35.101031 #12]  INFO -- : Perform CatalogJob
2017-03-03T17:03:27.357 protus-host [catalog] Could not fetch manifest for 'ci/build_test' with tag '2017.2.4-2-g423f343': Net::OpenTimeout
2017-03-03T17:03:49.220 protus-host [catalog] Removed the tag '2'.
2017-03-03T17:03:49.220 protus-host [catalog] Removed the tag 'latest'.
2017-03-03T17:03:49.220 protus-host [catalog] Removed the image 'busytest'.
2017-03-03T17:03:49.221 protus-host I, [2017-03-03T17:03:49.062569 #12]  INFO -- : Finished CatalogJob in 73.96 seconds
2017-03-03T17:12:35.232 protus-host I, [2017-03-03T17:12:35.101291 #12]  INFO -- : Perform CatalogJob
2017-03-03T17:12:39.696 protus-host [catalog] Created the tag '2'.
2017-03-03T17:12:39.972 protus-host [catalog] Created the tag 'latest'.
2017-03-03T17:12:43.142 protus-host I, [2017-03-03T17:12:43.001148 #12]  INFO -- : Finished CatalogJob in 7.90 seconds
2017-03-03T17:22:35.229 protus-host I, [2017-03-03T17:22:35.101554 #12]  INFO -- : Perform CatalogJob
2017-03-03T17:22:42.609 protus-host I, [2017-03-03T17:22:42.511144 #12]  INFO -- : Finished CatalogJob in 7.41 seconds
2017-03-03T17:32:35.158 protus-host I, [2017-03-03T17:32:35.101762 #12]  INFO -- : Perform CatalogJob
2017-03-03T17:32:42.343 protus-host I, [2017-03-03T17:32:42.315894 #12]  INFO -- : Finished CatalogJob in 7.21 seconds
2017-03-03T17:42:35.151 protus-host I, [2017-03-03T17:42:35.101963 #12]  INFO -- : Perform CatalogJob
2017-03-03T17:42:42.084 protus-host I, [2017-03-03T17:42:42.068054 #12]  INFO -- : Finished CatalogJob in 6.97 seconds
2017-03-03T17:52:35.401 protus-host I, [2017-03-03T17:52:35.102211 #12]  INFO -- : Perform CatalogJob
2017-03-03T17:52:42.432 protus-host I, [2017-03-03T17:52:42.290566 #12]  INFO -- : Finished CatalogJob in 7.19 seconds

On the registry side, I see things like this happening:

2017-03-03T17:03:00.473 docker-registry time="2017-03-03T17:03:00.304385762Z" level=info msg="response completed" go.version=go1.6.3 http.request.host=docker-registry.cfdata.org http.request.id=664744c5-bf7a-4d80-9dfe-797e133f72c6 http.request.method=GET http.request.remoteaddr="<portus-ip-address>" http.request.uri="/v2/johndoe/test/busybox/tags/list?n=100" http.request.useragent=Ruby http.response.contenttype="application/json; charset=utf-8" http.response.duration=25.630354ms http.response.status=200 http.response.written=47 instance.id=3ceb3bb1-92a9-4170-88f0-59ffc005774b version=v2.5.1 
2017-03-03T17:03:00.473 docker-registry 10.36.16.20 - - [03/Mar/2017:17:03:00 +0000] "GET /v2/johndoe/test/busybox/tags/list?n=100 HTTP/1.1" 200 47 "" "Ruby"
2017-03-03T17:03:01.201 docker-registry time="2017-03-03T17:03:00.953367245Z" level=warning msg="error authorizing context: insufficient scope" go.version=go1.6.3 http.request.host=docker-registry.cfdata.org http.request.id=e11c24f7-5246-4636-bc03-929ca4b41dfd http.request.method=GET http.request.remoteaddr="<portus-ip-address>" http.request.uri="/v2/johndoe/busybox/tags/list?n=100" http.request.useragent=Ruby instance.id=3ceb3bb1-92a9-4170-88f0-59ffc005774b vars.name="shammah/busybox" version=v2.5.1 
2017-03-03T17:03:01.201 docker-registry 10.36.16.20 - - [03/Mar/2017:17:03:00 +0000] "GET /v2/johndoe/busybox/tags/list?n=100 HTTP/1.1" 401 147 "" "Ruby"
2017-03-03T17:03:03.030 docker-registry 10.36.21.20 - - [03/Mar/2017:17:03:02 +0000] "GET / HTTP/1.1" 200 0 "" "spray-can/1.3.3"
2017-03-03T17:03:03.567 docker-registry time="2017-03-03T17:03:03.512651142Z" level=info msg="response completed" go.version=go1.6.3 http.request.host=docker-registry.lol http.request.id=8b9600db-cf7b-40e7-83df-86b48dcb8243 http.request.method=GET http.request.remoteaddr="<portus-ip-address>" http.request.uri="/v2/johndoe/busybox/tags/list?n=100" http.request.useragent=Ruby http.response.contenttype="application/json; charset=utf-8" http.response.duration=47.094616ms http.response.status=200 http.response.written=45 instance.id=3ceb3bb1-92a9-4170-88f0-59ffc005774b version=v2.5.1 
2017-03-03T17:03:03.567 docker-registry 10.36.16.20 - - [03/Mar/2017:17:03:03 +0000] "GET /v2/johndoe/busybox/tags/list?n=100 HTTP/1.1" 200 45 "" "Ruby"
2017-03-03T17:03:04.173 docker-registry time="2017-03-03T17:03:04.170857063Z" level=warning msg="error authorizing context: authorization token required" go.version=go1.6.3 http.request.host=docker-registry.lol http.request.id=3077c7ae-2a6d-4240-8ad3-ecc3d41ff055 http.request.method=GET http.request.remoteaddr="<portus-ip-address>" http.request.uri="/v2/auto/busybox/manifests/latest" http.request.useragent=Ruby instance.id=3ceb3bb1-92a9-4170-88f0-59ffc005774b vars.name="auto/busybox" vars.reference=latest version=v2.5.1 

At the same time you see these in portus' logs:

2017-03-03T17:03:02.205 portus-host Started GET "/v2/token?account=portus&scope=repository%3Ajohndoe%2Fbusybox%3Apull&service=docker-registry.lol" for <portus-ip-address> at 2017-03-03 17:03:01 +0000
2017-03-03T17:03:02.205 portus-host Processing by Api::V2::TokensController#show as JSON
2017-03-03T17:03:02.205 portus-host   Parameters: {"account"=>"portus", "scope"=>"repository:johndoe/busybox:pull", "service"=>"docker-registry.lol"}
2017-03-03T17:03:02.505 portus-host Completed 200 OK in 462ms (Views: 0.3ms | ActiveRecord: 373.9ms)
2017-03-03T17:03:04.466 portus-host Started GET "/v2/token?account=portus&scope=repository%3Aauto%2Fbusybox%3Apull&service=docker-registry.lol" for <portus-ip-address> at 2017-03-03 17:03:04 +0000
2017-03-03T17:03:04.466 portus-host Processing by Api::V2::TokensController#show as JSON
2017-03-03T17:03:04.466 portus-host   Parameters: {"account"=>"portus", "scope"=>"repository:auto/busybox:pull", "service"=>"docker-registry.lol"}
2017-03-03T17:03:04.466 portus-host Completed 200 OK in 115ms (Views: 0.2ms | ActiveRecord: 16.0ms)
2017-03-03T17:03:05.640 portus-host Started GET "/v2/token?account=portus&scope=repository%3Abusybox%3Apull&service=docker-registry.lol" for <portus-ip-address> at 2017-03-03 17:03:05 +0000
2017-03-03T17:03:05.640 portus-host Processing by Api::V2::TokensController#show as JSON
2017-03-03T17:03:05.641 portus-host   Parameters: {"account"=>"portus", "scope"=>"repository:busybox:pull", "service"=>"docker-registry.lol"}
2017-03-03T17:03:05.641 portus-host Completed 200 OK in 94ms (Views: 0.2ms | ActiveRecord: 3.0ms)

[schancel]

This is probably associated with #1184

[mssola]

Closing in favor of #1599.