Unable to push to swift storage backend

Bug #1809041 reported by Jamon Camisso
12
This bug affects 2 people
Affects Status Importance Assigned to Milestone
Docker Registry Charm
Triaged
Medium
Kevin W Monroe

Bug Description

Somehow the swift backend can time out and stop an image from being uploaded. Debug level errors from the registry look like this:

{"err.code":"unknown","err.detail":"swift: Timeout expired while waiting for segments of /docker/registry/v2/blobs/sha256/03/0330ca45a200e1fcef05ae97f434366d262a1c50b3dc053e7928b58dd37211dd/data to show up","err.message":"unknown error","go.version":"go1.10.4","http.request.host":"registry.jujucharms.com","http.request.id":"cdc35629-693b-452d-b6a6-60e214c4d9ca","http.request.method":"PUT","http.request.remoteaddr":"....","http.request.uri":"/v2/jamon/kubeflow-tf-hub/jupyterhub-image/blobs/uploads/92fe2adb-00f8-4515-8743-88bb23e76450?_state=....digest=sha256%3A0330ca45a200e1fcef05ae97f434366d262a1c50b3dc053e7928b58dd37211dd","http.request.useragent":"docker/18.06.1-ce go/go1.10.4 git-commit/e68fc7a kernel/4.15.0-42-generic os/linux arch/amd64 UpstreamClient(Go-http-client/1.1)","http.response.contenttype":"application/json; charset=utf-8","http.response.duration":"13.171153577s","http.response.status":500,"http.response.written":104,"level":"error","msg":"response completed with error","time":"2018-12-18T20:06:53.271720479Z","vars.name":"jamon/kubeflow-tf-hub/jupyterhub-image","vars.uuid":"92fe2adb-00f8-4515-8743-88bb23e76450"}

The " Timeout expired while waiting for segments" message, and 0 length data file make me think that the issue is this upstream bug: https://github.com/docker/distribution/issues/1013

For example, in that failed upload, the files in question look like this in swift:

$ swift stat --lh docker-registry-blobs files/docker/registry/v2/repositories/juju/kubeflow-tf-hub/jupyterhub-image/_layers/sha256/0330ca45a200e1fcef05ae97f434366d262a1c50b3dc053e7928b58dd37211dd/link
       Account: AUTH_18fdda09da1747f4885b940cadff4cc0
     Container: docker-registry-blobs
        Object: files/docker/registry/v2/repositories/juju/kubeflow-tf-hub/jupyterhub-image/_layers/sha256/0330ca45a200e1fcef05ae97f434366d262a1c50b3dc053e7928b58dd37211dd/link
  Content Type: application/octet-stream
Content Length: 71
 Last Modified: Tue, 11 Dec 2018 05:39:19 GMT
          ETag: 239c76eecd4fd38d448173f554cb4a36
 Accept-Ranges: bytes
   X-Timestamp: 1544506758.53727
    X-Trans-Id: txae919e1f3a5a4b0ea0622-005c1955de

$ swift stat --lh docker-registry-blobs files/docker/registry/v2/blobs/sha256/03/0330ca45a200e1fcef05ae97f434366d262a1c50b3dc053e7928b58dd37211dd/data
       Account: AUTH_18fdda09da1747f4885b940cadff4cc0
     Container: docker-registry-blobs
        Object: files/docker/registry/v2/blobs/sha256/03/0330ca45a200e1fcef05ae97f434366d262a1c50b3dc053e7928b58dd37211dd/data
  Content Type: application/octet-stream
Content Length: 0
 Last Modified: Tue, 11 Dec 2018 05:39:15 GMT
          ETag: "d41d8cd98f00b204e9800998ecf8427e"
      Manifest: docker-registry-blobs/segments/2f6/46f636b65722f72656769737472792f76322f7265706f7369746f726965732f6a756a752f6b756265666c6f772d74662d6875622f6a7570797465726875622d696d6167652f5f75706c6f6164732f33353635356461622d346234652d343263382d613532312d6536316433336366613434632f64617461425d87ada26ee6929920326a4d60f263d0cd2c939385f948139e4791eb2d69a6da39a3ee5e6b4b0d3255bfef95601890afd80709
 Accept-Ranges: bytes
   X-Timestamp: 1544506754.17360
    X-Trans-Id: tx2f2d17d03c0248a8a7444-005c1955fb

Anyone pushing an image that contains the layer in question will run into the error, since the files in swift are named based on the sha256 hash. The upstream issue doesn't really have much in the way of fixes.

The workaround for now is to delete the files, and then re-push the image in question.

Jamon Camisso (jamon)
summary: - Unable to push to registry with swift storage backend
+ Unable to push to swift storage backend
description: updated
Changed in layer-docker-registry:
status: New → Triaged
Revision history for this message
Jamon Camisso (jamon) wrote :

I can reproduce the error manually by deleting a segment from a layer:

'swift delete docker-registry segments/2f6/46f636b65722f7......'

Or all of them like this):

'swift list docker-registry |grep segments |xargs swift delete docker-registry'

The following seems to recover things consistently:

REGISTRY=$(docker ps |awk '{print $1}'|tail -n 1)
CONTAINER=docker-registry
FILES=$(docker logs $REGISTRY | jq -r -R 'fromjson? |.["err.detail"] | match("swift: Timeout expired while waiting for segments of (.+sha256.+) to show up"; "g") | .captures[0] .string' |sort |uniq)
for f in $FILES; do
        swift stat --lh $CONTAINER "files$f" 2>&1 |grep -q "Content Length: 0"
        if [ $? -eq 0 ]; then
                echo "Removing $f"
                swift delete $CONTAINER "files$f" > /dev/null 2>&1
        fi
done

Then push again and things will work.

Revision history for this message
Tom Haddon (mthaddon) wrote :

This workaround isn't feasible for us, as there's no way of running it at the point of "docker push", as it requires access to the docker registry logs and swift write access.

However, we suspect, based on reading some of the upstream issues on GH and where we've seen this issue happening, that this may have something to do with the proxying setup. We're going to try a few different permutations and will update this bug report once we've done that and confirmed (or otherwise).

Revision history for this message
Jamon Camisso (jamon) wrote :
Download full text (4.7 KiB)

Here's some more data to add to this issue, and hopefully narrow things down:

These two configurations will reliably trigger the issue about 15-20% of the time. During testing, I almost thought the Haproxy & docker only setup with balance source to pin sessions was working but I hit the bug there too.

1. 2x Apache front-ends, 2x Haproxy mid-ends, 2x docker-registry backends.
2. 2x Haproxy front-ends, 2x docker-registry backends

Interestingly, stopping one docker-registry backend (systemctl stop docker) and then pushing doesn't seem to trigger the bug.

To that end, manually generating an Haproxy configuration and marking one server as a 'backup' seems to also avoid the issue.

Here is an Haproxy configuration that can be used to reproduce the issue given the above. I created this configuration by hand. Doing it with the juju services config option for Haproxy seems difficult during testing given the relations and need to bind on port 80 & 443 in the same frontend.

---------------------------------------------------
global
    log /dev/log local0
    log /dev/log local1 notice
    maxconn 4096
    user haproxy
    group haproxy
    spread-checks 0
    tune.ssl.default-dh-param 1024
    ssl-default-bind-ciphers ECDHE-RSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-AES256-GCM-SHA384:DHE-RSA-AES128-GCM-SHA256:DHE-DSS-AES128-GCM-SHA256:kEDH+AESGCM:ECDHE-RSA-AES128-SHA256:ECDHE-ECDSA-AES128-SHA256:ECDHE-RSA-AES128-SHA:ECDHE-ECDSA-AES128-SHA:ECDHE-RSA-AES256-SHA384:ECDHE-ECDSA-AES256-SHA384:ECDHE-RSA-AES256-SHA:ECDHE-ECDSA-AES256-SHA:DHE-RSA-AES128-SHA256:!DHE-RSA-AES128-SHA:DHE-DSS-AES128-SHA256:DHE-RSA-AES256-SHA256:DHE-DSS-AES256-SHA:!DHE-RSA-AES256-SHA:AES128-GCM-SHA256:AES256-GCM-SHA384:AES128-SHA256:AES256-SHA256:AES128-SHA:AES256-SHA:AES:!CAMELLIA:DES-CBC3-SHA:!aNULL:!eNULL:!EXPORT:!DES:!RC4:!MD5:!PSK:!aECDH:!EDH-DSS-DES-CBC3-SHA:!EDH-RSA-DES-CBC3-SHA:!KRB5-DES-CBC3-SHA

defaults
    log global
    mode http
    option httplog
    option dontlognull
    retries 3
    timeout queue 20000
    timeout client 50000
    timeout connect 5000
    timeout server 50000

frontend haproxy-1-443
    bind 0.0.0.0:80
    bind 0.0.0.0:443 ssl crt /var/lib/haproxy/default.pem no-sslv3
    mode http
    option forwardfor
    http-request set-header X-Forwarded-Proto https if { ssl_fc }
    redirect scheme https if !{ ssl_fc }
    default_backend docker-registry_be

backend docker-registry_be
    mode http
    balance source
    hash-type consistent
    redirect scheme https if !{ ssl_fc }
    option httpchk GET / HTTP/1.0
    server docker-registry-2-5000 10.55.32.146:5000 check inter 2000 rise 2 fall 5 maxconn 4096
    server docker-registry-3-5000 10.55.32.153:5000 check inter 2000 rise 2 fall 5 maxconn 4096
---------------------------------------------------

1. Steps to reproduce:
juju deploy haproxy
juju add-unit haproxy
juju deploy cs:~containers/docker-registry-25
juju add-unit docker-registry
juju add-relation haproxy docker-registry

2. Add DNS entries for the haproxy units, e.g. I used registry.jamon.ca.

3. Generate a self-signed TLS key/cert pair the registry and configure Haproxy to use them:
juj...

Read more...

Revision history for this message
Tom Haddon (mthaddon) wrote :

So this looks to me like we need to update the docker-registry relation to HAProxy so that it configures things in active/passive rather than active/active mode - i.e. any HAProxy sitting in front of docker-registry should only send traffic to one of the docker-registry backend unless that backend is down. This will mean we're not getting the load-spreading benefits of multiple docker-registry units, but should solve this issue.

Marking this as critical as it currently affects any deployment with more than one docker-registry unit and HAProxy infront of it.

Changed in layer-docker-registry:
importance: Undecided → Critical
Changed in layer-docker-registry:
assignee: nobody → Kevin W Monroe (kwmonroe)
assignee: Kevin W Monroe (kwmonroe) → nobody
status: Triaged → In Progress
assignee: nobody → Kevin W Monroe (kwmonroe)
Revision history for this message
Kevin W Monroe (kwmonroe) wrote :

Fixed with https://github.com/CanonicalLtd/docker-registry-charm/pull/23, currently in the beta channel as cs:~containers/docker-registry-65

This was a relatively simple fix that only configures the haproxy for the docker-registry leader. As Tom mentioned, we'll lose load balancing capabilities, but gain a consistent proxied registry with hot-spare capabilities.

Changed in layer-docker-registry:
status: In Progress → Fix Committed
Changed in layer-docker-registry:
status: Fix Committed → Fix Released
Revision history for this message
Martin Hilton (martin-hilton) wrote :

This issue is still causing us problems in production. (see https://rt.admin.canonical.com/Ticket/Display.html?id=115963)

Revision history for this message
Kevin W Monroe (kwmonroe) wrote :

Martin, we confirmed the original fix didn't always work between docker-registry-65 and -87. The issue was that registry leadership did not enforce anything about the order of multiple registries, meaning multiple proxies fronting multiple registries could disagree about the order of registries to contact, which led to multiple proxies talking to different backend registries, which would re-trigger this bug.

This should be fixed for good in docker-registry >= 87, as discussed in this bug:

https://bugs.launchpad.net/layer-docker-registry/+bug/1815459

And this PR:

https://github.com/CanonicalLtd/docker-registry-charm/pull/26

Please upgrade to the latest stable rev (anything >= 87 should be fine).

Revision history for this message
Jay Kuri (jk0ne) wrote :

Hello! Unfortunately, this bug is still showing up.

I've done a fair amount of research and am fairly certain that the issue we are encountering is specifically this one:

https://github.com/docker/distribution/issues/2188

What appears to be the actual bug is that the swift backend does a swift.move, and then removes the temporary upload files. This, combined with swift's internal handling of move can result in missing segments and an essentially corrupt object which has to be removed manually in order to un-stick the related image.

A workaround is to trigger a complete rebuild of the image, so no layers are reused, essentially stepping around the broken object.

An excellent explanation of the actual issue can be found in this docker PR:

https://github.com/docker/distribution/pull/2878

Applying the patch in the PR may be the most direct path to a solution to this problem in the short term.

There is another backend driver also, but it is not officially supported, and the PR above seems to be a less invasive solution.

Tom Haddon (mthaddon)
Changed in layer-docker-registry:
status: Fix Released → New
Revision history for this message
Kevin W Monroe (kwmonroe) wrote :

I don't see docker-charm changes required here. If I'm reading comment #8 correctly, the deployment simply needs to be configured with jetpackdanger's image:

juju config docker-registry registry-image='jetpackdanger/registry:pr2878'

Let me know if there's more todo for the charm. Otherwise, I think we workaround by setting a custom registry image until upstream accepts:

https://github.com/docker/distribution/pull/2878

Changed in layer-docker-registry:
status: New → Incomplete
Revision history for this message
Kevin W Monroe (kwmonroe) wrote :

Per irc discussion, the workaround from comment 9 makes this bug less critical. Long term, we'll either need upstream to merge pr2878, or adjust the default registry-image config in this charm to ensure it works well for swift backends.

I'm not comfortable changing the default config today as the custom image hasn't been tested against non-swift backends. Todo here is to beef up this charm's tests to gain confidence that our defaults are safe (and fix the original swift issue).

Changed in layer-docker-registry:
importance: Critical → High
status: Incomplete → Triaged
George Kraft (cynerva)
Changed in layer-docker-registry:
importance: High → Medium
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.