Docker build log says "CACHED" even when what it means is SKIPPED

FFdhorkin commented 7 months ago

Description

I was having an issue where a docker build seemed to be caching layers even when I had gone to extensive lengths (like docker system prune -a, and even doing a clean install of docker) to ensure that I was building from a clean state. Even when I used --no-cache, it was saying layers were cached. This seemed very bizarre, and Google searches weren't being very helpful.

Eventually, I decided that there was no way it was possibly cached, and figured out that the issue was because Docker was using some sort of lookahead logic, realizing that a later part of the build was going to fail, and fast-failing early. I don't have any issue with this behavior, but it was 100% not clear this was what was happening.

In my case, since the part that was failing was later in the Dockerfile and I was expecting a failure there (and just hadn't gotten to updating that part yet), I was ignoring the fact the build was failing and focused on trying to figure out why earlier layers were being cached when there was no way they should have been cached.

Commenting out that other part that I knew was broken suddenly caused previous parts of the Dockerfile to no longer claim to be cached.

Ultimately, this is more of a design bug than a code bug. It should absolutely not say CACHED unless it means it's actually cached - in this case, it should say SKIPPED or ABORTING something like that. Or just omit the skipped layers from the log, and jump right to the detected problem later in the Dockerfile.

Reproduce

Here's a minimal example of what was triggering this behavior for me:

Dockerfile:

FROM node:18.14.1-alpine AS node-builder
WORKDIR /usr/src/app

# copy just the files needed for configuring dependencies
COPY ["package.json", "yarn.lock", "./"]
# logs were claiming this next line was cached, even though there was no way it was cached because I'd just added this and it had never been run!
RUN yarn run my-script-name
# packages folder doesn't exist, so build expected to fail here
COPY ["./packages", "./packages"]

Expected behavior

if a step/layer is skipped because Docker realizes a file it's supposed to copy doesn't exist, it should indicate it's skipping steps, aborting the build, or just fully omit that section from the log.

docker version

Client: Docker Engine - Community
 Cloud integration: v1.0.35+desktop.5
 Version:           24.0.7
 API version:       1.43
 Go version:        go1.20.10
 Git commit:        afdd53b
 Built:             Thu Oct 26 09:08:17 2023
 OS/Arch:           linux/amd64
 Context:           default

Server: Docker Desktop
 Engine:
  Version:          24.0.7
  API version:      1.43 (minimum version 1.12)
  Go version:       go1.20.10
  Git commit:       311b9ff
  Built:            Thu Oct 26 09:08:02 2023
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          1.6.25
  GitCommit:        d8f198a4ed8892c764191ef7b3b06d8a2eeb5c7f
 runc:
  Version:          1.1.10
  GitCommit:        v1.1.10-0-g18a0cb0
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0

docker info

Client: Docker Engine - Community
 Version:    24.0.7
 Context:    default
 Debug Mode: false
 Plugins:
  buildx: Docker Buildx (Docker Inc.)
    Version:  v0.12.0-desktop.2
    Path:     /usr/local/lib/docker/cli-plugins/docker-buildx
  compose: Docker Compose (Docker Inc.)
    Version:  v2.23.3-desktop.2
    Path:     /usr/local/lib/docker/cli-plugins/docker-compose
  dev: Docker Dev Environments (Docker Inc.)
    Version:  v0.1.0
    Path:     /usr/local/lib/docker/cli-plugins/docker-dev
  extension: Manages Docker extensions (Docker Inc.)
    Version:  v0.2.21
    Path:     /usr/local/lib/docker/cli-plugins/docker-extension
  feedback: Provide feedback, right in your terminal! (Docker Inc.)
    Version:  0.1
    Path:     /usr/local/lib/docker/cli-plugins/docker-feedback
  init: Creates Docker-related starter files for your project (Docker Inc.)
    Version:  v0.1.0-beta.10
    Path:     /usr/local/lib/docker/cli-plugins/docker-init
  sbom: View the packaged-based Software Bill Of Materials (SBOM) for an image (Anchore Inc.)
    Version:  0.6.0
    Path:     /usr/local/lib/docker/cli-plugins/docker-sbom
  scan: Docker Scan (Docker Inc.)
    Version:  v0.26.0
    Path:     /usr/local/lib/docker/cli-plugins/docker-scan
  scout: Docker Scout (Docker Inc.)
    Version:  v1.2.0
    Path:     /usr/local/lib/docker/cli-plugins/docker-scout

Server:
 Containers: 0
  Running: 0
  Paused: 0
  Stopped: 0
 Images: 0
 Server Version: 24.0.7
 Storage Driver: overlay2
  Backing Filesystem: extfs
  Supports d_type: true
  Using metacopy: false
  Native Overlay Diff: true
  userxattr: false
 Logging Driver: json-file
 Cgroup Driver: cgroupfs
 Cgroup Version: 2
 Plugins:
  Volume: local
  Network: bridge host ipvlan macvlan null overlay
  Log: awslogs fluentd gcplogs gelf journald json-file local logentries splunk syslog
 Swarm: inactive
 Runtimes: io.containerd.runc.v2 runc
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: d8f198a4ed8892c764191ef7b3b06d8a2eeb5c7f
 runc version: v1.1.10-0-g18a0cb0
 init version: de40ad0
 Security Options:
  seccomp
   Profile: unconfined
  cgroupns
 Kernel Version: 5.15.133.1-microsoft-standard-WSL2
 Operating System: Docker Desktop
 OSType: linux
 Architecture: x86_64
 CPUs: 20
 Total Memory: 15.47GiB
 Name: docker-desktop
 ID: 4e30e950-a999-4f1a-9ab7-20ed06642dbf
 Docker Root Dir: /var/lib/docker
 Debug Mode: false
 HTTP Proxy: http.docker.internal:3128
 HTTPS Proxy: http.docker.internal:3128
 No Proxy: hubproxy.docker.internal
 Experimental: false
 Insecure Registries:
  hubproxy.docker.internal:5555
  127.0.0.0/8
 Live Restore Enabled: false

WARNING: daemon is not using the default seccomp profile

Diagnostics ID

225DAB08-088F-4B5D-9122-FD010F1A0C06/20240125224854

Additional Info

Actual log:

docker/for-win#4 [node-builder 1/9] FROM docker.io/library/node:18.14.1-alpine@sha256:e0a779479fca9cf43cae2852291bee70e730ae3ad27fea1211060bd344b696b8
docker/for-win#4 DONE 0.0s

docker/for-win#5 [internal] load build context
docker/for-win#5 transferring context: 7.09kB 0.0s done
docker/for-win#5 DONE 0.0s

docker/for-win#6 [node-builder 2/9] WORKDIR /usr/src/app
docker/for-win#6 CACHED

docker/for-win#7 [node-builder 3/9] RUN apk --no-cache --update add rsync curl
docker/for-win#7 CACHED

docker/for-win#8 [node-builder 4/9] COPY [package.json, yarn.lock, ./]
docker/for-win#8 CACHED

docker/for-win#9 [node-builder 5/9] RUN yarn run my-script-name
docker/for-win#9 CACHED

docker/for-win#10 [node-builder 6/9] COPY [./packages, ./packages]
docker/for-win#10 ERROR: failed to calculate checksum of ref 4e30e950-a999-4f1a-9ab7-20ed06642dbf::p3ptgg363g15z8bsf2hq67apu: "/packages": not found
------
 > [node-builder 6/9] COPY [./packages, ./packages]:
------
Dockerfile:58
--------------------
  56 |         COPY ["package.json", "yarn.lock", "./"]
  57 |         RUN yarn run my-script-name
  58 | >>>     COPY ["./packages", "./packages"]
  59 |
  60 |         RUN --mount=type=cache,target=/usr/local/share/.cache/yarn,sharing=locked,id=fc_nodecache \
--------------------
ERROR: failed to solve: failed to compute cache key: failed to calculate checksum of ref 4e30e950-a999-4f1a-9ab7-20ed06642dbf::p3ptgg363g15z8bsf2hq67apu: "/packages": not found
make: *** [Makefile:15: build] Error 1

Example of desired log (partial):

docker/for-win#9 [node-builder 5/9] RUN yarn run my-script-name
docker/for-win#9 SKIPPED: build expected to fail due to missing file (see below)

docker/for-win#10 [node-builder 6/9] COPY [./packages, ./packages]
docker/for-win#10 ERROR: failed to calculate checksum of ref 4e30e950-a999-4f1a-9ab7-20ed06642dbf::p3ptgg363g15z8bsf2hq67apu: "/packages": not found

Alternatively:

docker/for-win#9 ABORTING: build expected to fail due to missing file (see below)

thaJeztah commented 7 months ago

looks related to https://github.com/moby/buildkit/issues/4535#issuecomment-1881657648

@tonistiigi do you know if there's a tracking issue for that in buildkit?

bsutton commented 7 months ago

Just wasted a couple of hours on this one due to the misleading information. I was trying to diagnose a problem with an earlier line so wasn't concerned with the line that was reporting the failure ( I was going to fix that problem after I had sorted the problem in the earlier line).

So we definitely need a better error message to indicate what is going on.

I agree with @FFdhorkin suggestion of a message such as:

docker/for-win#9 SKIPPED: build expected to fail due to missing file (see below)

terion-name commented 4 months ago

On mac is the same

KharabinDev42 commented 2 months ago

this wastes so much time

0xfede7c8 commented 1 week ago

Same issue. Wasted at least 2 hours on this unnecesarily.

docker / buildx