Unable to complete build for a multi-stage Dockerfile when using caching

[jamesdh]

Behaviour

Unable to complete the build for a multi-stage Dockerfile, regardless if registry (GitHub Container Registry) or local (actions/cache@v2) cache is used. No error, the process just freezes after "preparing build cache for export" finishes. Build works just fine if the cache arguments are removed. Adding debug flag doesn't appear to show any additional information.

Steps to reproduce this issue

1. Define a multi-stage Dockerfile
2. Utilize build-push-action with either a local or registry based cache
3. Execute

Expected behaviour

Cache export finishes, remainder of workflow completes, and subsequent builds are able to utilize the cache to speed up docker build times

Actual behaviour

Jobs become "stuck" after "preparing build cache for export x.xs done" and never complete until manually terminated.

Configuration

- name: Cache Docker layers
  uses: actions/cache@v2
  with:
    path: /tmp/.buildx-cache
    key: ${{ runner.os }}-buildx-${{ github.sha }}
    restore-keys: |
      ${{ runner.os }}-buildx-

- name: Set up Docker Buildx
  uses: docker/setup-buildx-action@v1
  with:
    install: true

- name: Build and push
  uses: docker/build-push-action@v2
  with:
    version: latest
    buildkitd-flags: --debug
    # cache-from: type=registry,ref=ghcr.io/moltenbits/tt-grails
    # cache-to: type=registry,ref=ghcr.io/moltenbits/tt-grails,mode=max
    cache-from: type=local,src=/tmp/.buildx-cache
    cache-to: type=local,dest=/tmp/.buildx-cache
    context: ./back
    file: ./back/Dockerfile.prod
    push: true
    tags: ghcr.io/moltenbits/tt-grails:latest    

Logs

2020-12-19T15:00:41.5394086Z 26 exporting to image
2020-12-19T15:00:41.5394602Z 26 exporting layers
2020-12-19T15:00:59.2386163Z 26 exporting layers 17.8s done
2020-12-19T15:00:59.3887834Z 26 exporting manifest sha256:5be4d8e3cf7172c58e4927f5427b59fab979257d21a3854a2c22f6e1338f7079 done
2020-12-19T15:00:59.3889617Z 26 exporting config sha256:c692c40f701bdebf651c9ea5bf8bf5bf23bf0b579834a63a54b885b9fc0114e7 done
2020-12-19T15:00:59.3890857Z 26 pushing layers
2020-12-19T15:01:04.1877777Z 26 pushing layers 4.9s done
2020-12-19T15:01:04.1879183Z 26 pushing manifest for ghcr.io/moltenbits/tt-grails:latest
2020-12-19T15:01:05.0884514Z 26 pushing manifest for ghcr.io/moltenbits/tt-grails:latest 0.8s done
2020-12-19T15:01:05.0885197Z 26 DONE 23.5s
2020-12-19T15:01:05.0885485Z
2020-12-19T15:01:05.0885893Z 27 exporting cache
2020-12-19T15:01:05.0886406Z 27 preparing build cache for export
2020-12-19T15:01:05.9889797Z 27 preparing build cache for export 0.9s done
2020-12-19T15:22:19.4836222Z ##[error]The operation was canceled.

[crazy-max]

@jamesdh Thanks for your report.

Remove version: latest and buildkitd-flags: --debug from Build and push step. These inputs are not valid for this action but valid for docker/setup-buildx-action.

Also can you update the Set up Docker Buildx step with the following content and let me know:

      - name: Set up Docker Buildx
        uses: docker/setup-buildx-action@v1
        with:
          version: latest
          buildkitd-flags: --debug

[jamesdh]

@crazy-max yea I just caught that after this last build. Thanks for the fast response!

Oddly enough, I just gave this another go but after removing

with:
  install: true

...from the setup-buildx-action, and that time it worked. Then after rerunning the job, it correctly retrieved the layers for the entire docker image, not needing to build a single one, but again it appears frozen at "preparing build cache for export done"

[jamesdh]

Something I just noticed though from the build that appeared to have finished was this error message at the end:

#27 preparing build cache for export
#27 preparing build cache for export 1.3s done
#27 writing layer sha256:2709df21cc5c45e6ba42dc474d05ea8285faa664d2042b606fd341c7d9cdd9fe done
#27 writing layer sha256:3bfb431a8cf58da7549a3b65069b4c0cf8b55d3d7111ae29f45ae5695e9b1d37 done
#27 writing layer sha256:4c9629641dffe75e1d7c99ab85b204a0e85eea432c81024d33f9dd9ce4abadfa done
#27 writing layer sha256:6c33745f49b41daad28b7b192c447938452ea4de9fe8c7cc3edf1433b1366946 done
#27 writing layer sha256:a0380f744c1febb7db49761c5805a45c88c29115258893ae383cdce8b5b3478c
#27 writing layer sha256:a0380f744c1febb7db49761c5805a45c88c29115258893ae383cdce8b5b3478c 4.0s done
#27 writing layer sha256:c0afb8e68e0bcdc1b6e05acaa713a6fe0d818086c596bd1ad99133665c4efe63 done
#27 writing layer sha256:c858ff45b2fd83ef6a387d599f89da29413d589d027b16bce170b129edd2826a done
#27 writing layer sha256:d599c07d28e6c920ef615f4f9b5cd0d52eb106fcd20c3a7daef389f14edd4ef5 done
#27 writing layer sha256:e8a829023b9788da5ec65dda4e9dc7e606ea09b94f9a59b5349bff21dc1d265c done
#27 writing layer sha256:ef072fc32a84ef237dd4fcc7dff2c5e2a77565f24d63977d0fa654a6d8512dd8 done
#27 writing config sha256:5ddec2f61d3e21bea6fdf13a6e91706d37251aa9e001a4db99dfeff781c51ba4 done
#27 writing manifest sha256:8e998e0883b4d29dfa9290864a604db300daeb16c3a976077d19f6afd61c01df 0.0s done
#27 DONE 5.4s
2020/12/19 17:24:00 http2: server connection error from localhost: connection error: PROTOCOL_ERROR
time="2020-12-19T17:24:00Z" level=error msg="(*service).Write failed" error="rpc error: code = Canceled desc = context canceled" expected="sha256:8e998e0883b4d29dfa9290864a604db300daeb16c3a976077d19f6afd61c01df" ref="sha256:8e998e0883b4d29dfa9290864a604db300daeb16c3a976077d19f6afd61c01df" total=3541
🛒 Extracting digest...
sha256:38836bcef5602410233b836e770539bfab0c1c1336b984af7dc4bb764cad8b81

[crazy-max]

@jamesdh Have you tried with my suggestion? Do you have a link to your repo for repro please?

[jamesdh]

Yea, I added those flags but it didn't appear to add much info:

Sat, 19 Dec 2020 17:40:15 GMT #29 exporting cache
Sat, 19 Dec 2020 17:40:15 GMT #29 sha256:2700d4ef94dee473593c5c614b55b2dedcca7893909811a8f2b48291a1f581e4
Sat, 19 Dec 2020 17:40:15 GMT #29 preparing build cache for export done
Sat, 19 Dec 2020 17:45:36 GMT Error: The operation was canceled.

Unfortunately it's a private repo, but I might try pushing something similar to a public one if I have time today

[crazy-max]

@jamesdh

# cache-to: type=registry,ref=ghcr.io/moltenbits/tt-grails,mode=max

Fyi, mode=max is quite aggressive. Caches for all stages of your Dockerfile will be pushed.

Yea, I added those flags but it didn't appear to add much info:

Have you tried with the recommended values for cache-from and cache-to for Cache to registry?:

cache-from: type=registry,ref=ghcr.io/moltenbits/tt-grails
cache-to: type=inline

I might try pushing something similar to a public one if I have time today

Yes please

[jamesdh]

@crazy-max

Fyi, mode=max is quite aggressive. Caches for all stages of your Dockerfile will be pushed.

That's the intent. Without it, not sure there's much purpose to using a multi-stage build. I have stages for resolving dependencies which is easily the most time consuming part. They don't change that often, so re-resolving them every time is eating up my clock. Yes I could cache them external from the Dockerfile and then COPY them into the image during build time, but I've been bitten in the past due to platform specific resolution issues and would prefer to keep them resolved by the platform that the final binary will be running within.

Have you tried with the recommended values for cache-from and cache-to for Cache to registry?:

Yes, just tried w/ type=inline and that worked, although only the final layer (containing the resulting binary) is cached, which makes it fairly ineffective given my setup.

[jauderho]

You might also want to see #252.

I'm going to do some experimenting in my repo