Incorrect image loading time in WITH DOCKER

[rrjjvv]

What went wrong?

Nothing went wrong; it's closer to a cosmetic issue than an true bug. The very awesome change in #3377 artificially inflates its awesomeness due to differences in date precision. I exclusively use the alpine d-in-d images, which will always (falsely) show single- or double-digit millisecond load times. Only the ubuntu variant is accurate.

Log snippet from a realistic project:

   ./functional+test | Loading images from BuildKit via embedded registry...
   ./functional+test | Pulling 172.30.0.1:8371/sess-k7b9l51bl0bes9p0wdgzzakg2:img-4 and retagging as app-image:latest
   ./functional+test | Pulling 172.30.0.1:8371/sess-k7b9l51bl0bes9p0wdgzzakg2:img-8 and retagging as bats:latest
   ./functional+test | Pulling 172.30.0.1:8371/sess-k7b9l51bl0bes9p0wdgzzakg2:img-6 and retagging as consul-server:latest
   ./functional+test | Pulling 172.30.0.1:8371/sess-k7b9l51bl0bes9p0wdgzzakg2:img-3 and retagging as consul-template:latest
   ./functional+test | Pulling 172.30.0.1:8371/sess-k7b9l51bl0bes9p0wdgzzakg2:img-9 and retagging as gcr.io/cadvisor/cadvisor:v0.47.2
   ./functional+test | Pulling 172.30.0.1:8371/sess-k7b9l51bl0bes9p0wdgzzakg2:img-2 and retagging as hashi-vault-agent:latest
   ./functional+test | Pulling 172.30.0.1:8371/sess-k7b9l51bl0bes9p0wdgzzakg2:img-1 and retagging as k8s-vault-agent:latest
   ./functional+test | Pulling 172.30.0.1:8371/sess-k7b9l51bl0bes9p0wdgzzakg2:img-0 and retagging as kind:latest
   ./functional+test | Pulling 172.30.0.1:8371/sess-k7b9l51bl0bes9p0wdgzzakg2:img-10 and retagging as registry.k8s.io/metrics-server/metrics-server:v0.6.4
   ./functional+test | Pulling 172.30.0.1:8371/sess-k7b9l51bl0bes9p0wdgzzakg2:img-7 and retagging as vault-seeder:latest
   ./functional+test | Pulling 172.30.0.1:8371/sess-k7b9l51bl0bes9p0wdgzzakg2:img-5 and retagging as vault-server:latest
<snip>
   ./functional+test | Loading images done in 12 ms

After applying the end-user workaround, I get a much more realistic

   ./functional+test | Loading images done in 10318 ms

Illustration:

VERSION 0.7

RUN:
    COMMAND
    WITH DOCKER --pull busybox
        RUN echo "nanos: $(date +%s%N)" && \
            echo "digits: $(date +%s%N | wc -c)" && \
            start=$(date +%s%N | cut -b1-13) && \
            echo "Sleeping for 5 seconds" && sleep 5 && \
            end=$(date +%s%N | cut -b1-13) && \
            echo "Slept for $((end-start)) ms" && echo
    END

dind-alpine-old:
    FROM earthly/dind:alpine
    RUN --no-cache echo "not ok"
    DO +RUN

dind-alpine-new:
    FROM earthly/dind:alpine-3.18
    RUN --no-cache echo "not ok"
    DO +RUN

dind-ubuntu:
    FROM earthly/dind:ubuntu
    RUN --no-cache echo "ok"
    DO +RUN

dind-alpine-fixed:
    FROM earthly/dind:alpine-3.18
    RUN apk add --no-cache coreutils
    RUN --no-cache echo "ok"
    DO +RUN

$ earthly -version
earthly version v0.7.21 f4c9f47e48c3815e95fe9574e824524d34a20219 linux/amd64; Ubuntu 22.04.3 LTS (Jammy Jellyfish)

$ earthly -P +dind-alpine-old 
 <snip>
    +dind-alpine-old | Loading images done in 0 ms
    +dind-alpine-old | nanos: 1699663367
    +dind-alpine-old | digits: 11
    +dind-alpine-old | Sleeping for 5 seconds
    +dind-alpine-old | Slept for 5 ms
<snip>

$ earthly -P +dind-alpine-new 
<snip>
    +dind-alpine-new | Loading images done in 0 ms
    +dind-alpine-new | nanos: 1699663457
    +dind-alpine-new | digits: 11
    +dind-alpine-new | Sleeping for 5 seconds
    +dind-alpine-new | Slept for 5 ms
<snip>

$ earthly -P +dind-ubuntu 
<snip>
        +dind-ubuntu | Loading images done in 129 ms
        +dind-ubuntu | nanos: 1699663512009486883
        +dind-ubuntu | digits: 20
        +dind-ubuntu | Sleeping for 5 seconds
        +dind-ubuntu | Slept for 5001 ms
<snip>

What should have happened?

Regardless of d-in-d image used, the output should be realistic.

An end-user workaround entails adding coreutils to the image (+dind-alpine-fixed from above):

$ earthly -P +dind-alpine-fixed 
<snip>
  +dind-alpine-fixed | Loading images done in 164 ms
  +dind-alpine-fixed | nanos: 1699663833606672134
  +dind-alpine-fixed | digits: 20
  +dind-alpine-fixed | Sleeping for 5 seconds
  +dind-alpine-fixed | Slept for 5001 ms
<snip>

Other Helpful Information

The easy solution would be to just calculate seconds; if it was a no-brainer choice, I would have just given a PR rather than this report. Using seconds would have been easier to start, but you went through the effort of using nanos to get millis. The easiest way to maintain that is by adding coreutils, but would require pushing new images (or maybe that's not a big deal).

I tried to come up with an alternative that didn't require new images, but couldn't come up with anything good. Using /proc/uptime (with some massaging) will get you centiseconds. In the old alpine image you can use python, but it's only there as a requirement for legacy docker compose (thus not present in the alpine-3.18 flavor).

(It appears busybox can support nanoseconds, but it's disabled by default.)

[ingwarsw]

Thats one of the reasons I think that earthly should support internally some kind of language to do all ifs and other stuff.... to not have to worry about the images under the hood..

[rrjjvv]

@alexcb FYI, this didn't get automatically closed. It appears that you have to repeat the keyword ("close 1, close 2") for each issue. Only the first issue you mentioned (not this one) got magically linked.