Bug: progress output substitutes environment variables where it should not

I noticed this when I started writing a reply / example for https://github.com/moby/moby/issues/42937.

Docker itself (docker build) does not perform environment variable substitution in CMD, ENTRYPOINT and RUN commands (see https://docs.docker.com/engine/reference/builder/#environment-replacement). Environment variables in those commands are handled by the shell (unless the JSON / "exec form" syntax is used), which means that those variables are evaluated the moment the shell is executed.

• For RUN, this means: the moment when the RUN command is executed as part of the build
• For CMD and ENTRYPOINT this means: after the image has been built, and when the container is started

However, BuildKit progress looks to be substituting these variables, which makes the output confusing as it "appears" the variables are substituted before executing.

For example, the following Dockerfile:

FROM alpine
ENV FOO=hello
ARG BAR=world
RUN echo FOO is $FOO and BAR is $BAR
RUN ["/bin/sh", "-c", "echo FOO is $FOO and BAR is $BAR"]
ENV SH_ENV=/bin/sh
RUN ["$SH_ENV", "-c", "echo FOO is $FOO and BAR is $BAR"]

In the above, no variable substitution takes place in any of the RUN commands, but progress looks like below:

docker build --no-cache -<<'EOF'
FROM alpine
ENV FOO=hello
ARG BAR=world
RUN echo FOO is $FOO and BAR is $BAR
RUN ["/bin/sh", "-c", "echo FOO is $FOO and BAR is $BAR"]
ENV SH_ENV=/bin/sh
RUN ["$SH_ENV", "-c", "echo FOO is $FOO and BAR is $BAR"]
EOF
[+] Building 0.9s (7/7) FINISHED
 => [internal] load build definition from Dockerfile                         0.0s
 => => transferring dockerfile: 256B                                         0.0s
 => [internal] load .dockerignore                                            0.0s
 => => transferring context: 2B                                              0.0s
 => [internal] load metadata for docker.io/library/alpine:latest             0.0s
 => CACHED [1/4] FROM docker.io/library/alpine                               0.0s
 => [2/4] RUN echo FOO is hello and BAR is world                             0.2s
 => [3/4] RUN ["/bin/sh", "-c", "echo FOO is hello and BAR is world"]        0.3s
 => ERROR [4/4] RUN ["/bin/sh", "-c", "echo FOO is hello and BAR is world"]  0.3s
------
 > [4/4] RUN ["/bin/sh", "-c", "echo FOO is hello and BAR is world"]:
#7 0.243 container_linux.go:380: starting container process caused: exec: "$SH_ENV": executable file not found in $PATH
------
executor failed running [$SH_ENV -c echo FOO is $FOO and BAR is $BAR]: exit code: 1

The correct output for the above would be something like:

 => [2/4] RUN echo FOO is $FOO and BAR is $BAR                               0.2s
 => [3/4] RUN ["/bin/sh", "-c", "echo FOO $FOO and BAR is $BAR"]             0.3s
 => ERROR [4/4] RUN ["$SH_ENV", "-c", "echo FOO $FOO and BAR is $BAR"]       0.3s
------
 > [4/4] RUN ["$SH_ENV", "-c", "echo FOO $FOO and BAR is $BAR"]:
#7 0.243 container_linux.go:380: starting container process caused: exec: "$SH_ENV": executable file not found in $PATH
------
executor failed running [$SH_ENV -c echo FOO is $FOO and BAR is $BAR]: exit code: 1

Nit: probably the executor failed running should also print the JSON format of what's executed (instead of the string representation);

- executor failed running [$SH_ENV -c echo FOO is $FOO and BAR is $BAR]: exit code: 1
+ executor failed running ["$SH_ENV", "-c", "echo FOO is $FOO and BAR is $BAR"]: exit code: 1

Note that this is a regression (compared to the classic builder), which does not show this problem:

DOCKER_BUILDKIT=0 docker build --no-cache -<<'EOF'
FROM alpine
ENV FOO=hello
ARG BAR=world
RUN echo FOO is $FOO and BAR is $BAR
RUN ["/bin/sh", "-c", "echo FOO is $FOO and BAR is $BAR"]
ENV SH_ENV=/bin/sh
RUN ["$SH_ENV", "-c", "echo FOO is $FOO and BAR is $BAR"]
EOF

Sending build context to Docker daemon  2.048kB
Step 1/7 : FROM alpine
 ---> 14119a10abf4
Step 2/7 : ENV FOO=hello
 ---> Running in 272281384b45
Removing intermediate container 272281384b45
 ---> ce9edafb60b8
Step 3/7 : ARG BAR=world
 ---> Running in e0aa96c678ca
Removing intermediate container e0aa96c678ca
 ---> f978170c97cc
Step 4/7 : RUN echo FOO is $FOO and BAR is $BAR
 ---> Running in 414467a8ac72
FOO is hello and BAR is world
Removing intermediate container 414467a8ac72
 ---> 77160e213f97
Step 5/7 : RUN ["/bin/sh", "-c", "echo FOO is $FOO and BAR is $BAR"]
 ---> Running in 171b2d974c05
FOO is hello and BAR is world
Removing intermediate container 171b2d974c05
 ---> 986101102b89
Step 6/7 : ENV SH_ENV=/bin/sh
 ---> Running in c37dfdaf39ec
Removing intermediate container c37dfdaf39ec
 ---> e0fa28d9c936
Step 7/7 : RUN ["$SH_ENV", "-c", "echo FOO is $FOO and BAR is $BAR"]
 ---> Running in af9088799576
OCI runtime create failed: container_linux.go:380: starting container process caused: exec: "$SH_ENV": executable file not found in $PATH: unknown

I should also note that the same would NOT apply to other instructions. For example, docker build DOES perform variable substitution in LABEL commands, however, LABEL instructions are not currently printed in build progress (perhaps they should?)

Use the supplied Dockerfile reproduction to observe BuildKit progress for shell-form and JSON-form RUN commands, then trace the progress rendering path that formats those commands. Compare the output with the documented Dockerfile behavior and the classic builder output. Done means progress preserves the literal variables and JSON command form where appropriate, with regression coverage for the examples.