buildkit icon indicating copy to clipboard operation
buildkit copied to clipboard

docker build command outputs general information lines to stderr instead of stdout when buildKit is enabled.

Open pratiksanglikar opened this issue 4 years ago • 44 comments

Description

docker build commands output general information lines to standard error instead of standard output when buildKit is enabled.

This is particularly problematic for extra tooling we have around docker which depend on lines on stderror to determine if the command was successful.

Following is the output of docker build command which is returned on the stderr instead of stdout. The process has exitcode=0 so, it shouldn't ideally put these lines on stderr.

Steps to reproduce the issue:

  1. Make sure to have Docker version >= 19.03
  2. Enable BuildKit by setting environment variable - DOCKER_BUILDKIT=1
  3. Run docker build command on any project.
  4. Verify the output of the command is on stderr instead of stdout.

Describe the results you received: General information lines are present on stderr.

#2 [internal] load .dockerignore
#2 transferring context: 35B done
#2 DONE 0.1s

#1 [internal] load build definition from Dockerfile
#1 transferring dockerfile: 32B done
#1 DONE 0.1s

#3 [internal] load metadata for mcr.microsoft.com/dotnet/core/aspnet:3.0-bu...
#3 DONE 0.1s

#4 [base 1/2] FROM mcr.microsoft.com/dotnet/core/aspnet:3.0-buster-slim@sha...
#4 resolve mcr.microsoft.com/dotnet/core/aspnet:3.0-buster-slim@sha256:b0fd451ed5dcd9c86a5c5364b478ebfb411beada0740369127fa53bca365650f done
#4 DONE 0.0s

#5 [base 2/2] WORKDIR /app
#5 CACHED

#6 exporting to image
#6 exporting layers done
#6 writing image sha256:96324b5520b19fef0877dffb950a9f7b62ab23dcc65d3f1fb1cb09dabf113c7b
#6 writing image sha256:96324b5520b19fef0877dffb950a9f7b62ab23dcc65d3f1fb1cb09dabf113c7b 0.0s done
#6 naming to docker.io/library/webapplication7:dev done
#6 DONE 0.1s

Describe the results you expected: General information lines should be present on stdout when there is no error.

Additional information you deem important (e.g. issue happens only occasionally):

Output of docker version:

Client: Docker Engine - Community
 Version:           19.03.2
 API version:       1.40
 Go version:        go1.12.8
 Git commit:        6a30dfc
 Built:             Thu Aug 29 05:26:49 2019
 OS/Arch:           windows/amd64
 Experimental:      true

Server: Docker Engine - Community
 Engine:
  Version:          19.03.2
  API version:      1.40 (minimum version 1.12)
  Go version:       go1.12.8
  Git commit:       6a30dfc
  Built:            Thu Aug 29 05:32:21 2019
  OS/Arch:          linux/amd64
  Experimental:     true
 containerd:
  Version:          v1.2.6
  GitCommit:        894b81a4b802e4eb2a91d1ce216b8817763c29fb
 runc:
  Version:          1.0.0-rc8
  GitCommit:        425e105d5a03fabd737a126ad93d62a9eeede87f
 docker-init:
  Version:          0.18.0
  GitCommit:        fec3683

Output of docker info:

Client:
 Debug Mode: false
 Plugins:
  app: Docker Application (Docker Inc., v0.8.0)
  buildx: Build with BuildKit (Docker Inc., v0.3.0-5-g5b97415-tp-docker)

Server:
 Containers: 0
  Running: 0
  Paused: 0
  Stopped: 0
 Images: 1
 Server Version: 19.03.2
 Storage Driver: overlay2
  Backing Filesystem: extfs
  Supports d_type: true
  Native Overlay Diff: true
 Logging Driver: json-file
 Cgroup Driver: cgroupfs
 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: runc
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: 894b81a4b802e4eb2a91d1ce216b8817763c29fb
 runc version: 425e105d5a03fabd737a126ad93d62a9eeede87f
 init version: fec3683
 Security Options:
  seccomp
   Profile: default
 Kernel Version: 4.9.184-linuxkit
 Operating System: Docker Desktop
 OSType: linux
 Architecture: x86_64
 CPUs: 2
 Total Memory: 1.952GiB
 Name: docker-desktop
 ID: AVON:LYQZ:TO6V:5KVI:QJDV:E5OH:5EYZ:L6TJ:3AZL:HISV:F5QX:DEFA
 Docker Root Dir: /var/lib/docker
 Debug Mode: true
  File Descriptors: 28
  Goroutines: 43
  System Time: 2019-10-02T21:27:32.2913151Z
  EventsListeners: 1
 Registry: https://index.docker.io/v1/
 Labels:
 Experimental: true
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: false
 Product License: Community Engine

Additional environment details (AWS, VirtualBox, physical, etc.): Physical machine. Running docker commands through Containers Tools for Visual Studio.

pratiksanglikar avatar Oct 02 '19 21:10 pratiksanglikar

Treating prints to stderr as error is not correct. Stdout is used for actual build results (eg. you can pipe a tarball of the built files) or for id with -q. https://www.jstorimer.com/blogs/workingwithcode/7766119-when-to-use-stderr-instead-of-stdout

tonistiigi avatar Oct 03 '19 00:10 tonistiigi

In what scenario is that a thing for Docker? The build output isn't files, it's images, and trying to cram an image into STDOUT...I don't even think that would be possible.

Using STDERR for all logging output, while arguably technically correct, is highly irregular, and likely to cause more problems than solve.

bwateratmsft avatar Oct 03 '19 17:10 bwateratmsft

It would be nice to be able to build a container and capture the image ID at the end (like -q) but still have the build output as a separate stream.

mdonoughe avatar Jun 29 '20 22:06 mdonoughe

@mdonoughe --iidfile

@bwateratmsft

The build output isn't files, it's images

Build output is whatever you define in --output, eg. for stdout docker build -o - . > t.tar

tonistiigi avatar Jun 29 '20 22:06 tonistiigi

It would be nice to be able to build a container and capture the image ID at the end (like -q) but still have the build output as a separate stream.

How would one do that? Seems not to be possible, normal docker build always writes everything to stdout, and buildkit doesn't write anything to stdout. And --iidfile wants a physical file, so process substitition doesn't work either. :(

marc-guenther avatar Nov 26 '20 19:11 marc-guenther

The opinions here by the maintainers are categorically wrong. Unix tools all throughout the ecosystem utilize stderr for progress-like output. Since buildkit's output is highly erratic it wouldn't even make sense to try to capture it to begin with, so the usefulness of outputting it to stdout is limited.

I've run into this issue so many times now, where I would like to capture the resulting ID from stdout but still show the build progress on stderr. Docker tools have always been scripting-hostile and this is no exception - please improve this.

Qix- avatar Oct 05 '21 19:10 Qix-

@Qix- I'm not sure who you arguing here with. Buildkit does use stderr and only stderr for progress.

tonistiigi avatar Oct 05 '21 20:10 tonistiigi

The ultimate comment still stands - there is no way to extract a resulting image sha from the output of docker build in a standardized way (buildkit or not) akin to -q without also silencing build output.

EDIT: Without brittle text processing commands, which completely disable or break the compact and neatly formatted ANSI-escaped output.

Qix- avatar Oct 05 '21 20:10 Qix-

Yes, there is no --write-iid flag. Because we can't add a flag for absolutely every use case. --iidfile is more general and covers more use cases. We can't change the behavior of -q, not because where we write progress but because it is unexpected to the current users. -q first and foremost means "quiet" so printing progress is unexpected whatever the fd is. Another reason we can't print the id is that stdout is already used by -o so we would need to detect conflicts and add confusion to users.

In buildx I would recommend that nobody should use -q as it is a historic hack. Instead, you should configure behavior separately: --iidfile if you want to know the image ID and --progress=quiet if you want to suppress progress output. --progress=quiet does not currently exists in in regular docker build but we are standardizing in https://github.com/docker/cli/pull/3314

tonistiigi avatar Oct 05 '21 20:10 tonistiigi

Hello, I got hit by this yesterday. We were previously using docker without buildkit and decided to migrate to it to get all the goodies. Long story short, docker/buildkit is integrated in a custom CI, and a low lvl library handling processes was not fair regarding the priority to give to output. (hint: stdout had the priority)

What happened is that, everything went fine at first, but if the build was emitting too many logs, due to unfairness, the process handling the output of buildkit was not picking up line on stderr fast enough. Up to a certain point, the pipe of stderr got full and buildkit build was stuck on write syscall waiting for this pipe to get some room. So after this threshold, everything was working, but was extremly slow...

I double down on moving logs output to stdout, it is not very common to send everything to stderr

erebe avatar Mar 22 '22 08:03 erebe

Let's say I have a bash script that wants to build an image with docker build, take the resulting image id, and then run it.

With non-BuildKit, the command docker build dir_with_dockerfile 2> /dev/null will output:

Sending build context to Docker daemon  2.048kB
Step 1/1 : FROM ubuntu:bionic
 ---> 886eca19e611
Successfully built 886eca19e611

Pragmatically speaking, this is completely useless. You might could parse the image id out but that's probably not an ideal way to go. The only way to do it currently is to apply the --quiet argument which gives a viable image id.

With BuildKit, the command docker buildx build dir_with_dockerfile 2> /dev/null will output:

It outputs nothing. The logs and progress are output to stderr so redirecting stderr to /dev/null silences the logs. This is still useless because it doesn't output the image id. Ironically, if you give it --quiet, only then will it output the image id.

So, with the above, the problem is there is no way to reliably have both the docker build log / progress output and also obtain the image id in a meaningful way.

What I think should change:

  • Any version of docker build should always output only the resulting image id to stdout.
  • Logs and progress should only be put out to stderr.
  • Simply remove the --quiet argument altogether or have it to where it only effects the stderr output.

If people want the logs output to stdout, they can redirect stderr to stdout. If they don't want the logs at all, they can redirect it to null or somewhere it's not seen. This gives us the most flexibility.

computerquip-work avatar Mar 24 '22 19:03 computerquip-work

...Since buildkit's output is highly erratic it wouldn't even make sense to try to capture it to begin with

Not if you set BUILDKIT_PROGRESS=plain - then it outputs in a more "standard" fashion. Although it still outputs some lines to stderr that are not even error messages 😞

cocowalla avatar Apr 06 '22 12:04 cocowalla

Got hit by this today, after enabling BuildKit in an Azure DevOps pipeline, as AzDo fails tasks by default if anything is written to stderr. AzDo's default has never been an issue for me in years of working with it - it's absolutely bizarre that BuildKit writes stuff to stderr that are not even error messages!! :confused:

I get BuildKit wants some means to redirect image output, but surely that unusual case could be behind a flag?

cocowalla avatar Apr 06 '22 13:04 cocowalla

Got hit by this today, after enabling BuildKit in an Azure DevOps pipeline, as AzDo fails tasks by default if anything is written to stderr. AzDo's default has never been an issue for me in years of working with it - it's absolutely bizarre that BuildKit writes stuff to stderr that are not even error messages!! confused

I get BuildKit wants some means to redirect image output, but surely that unusual case could be behind a flag?

Historically, stderr has been used for logging, so much so that some languages and libraries have called it the log stream. The whole point is that when meaningful output is possible, you use stderr as a means of human-readable output and stdout as a means for pragmatic output.

Frankly, causing anything to fail if something is written to stderr is downright dumb as a default. That behavior should be fixed rather than expecting every application that uses stderr for disposable logs to stop using stderr. I find it more bizarre that this default hasn't caused you more issues.

In addition, it's trivial to redirect stderr to stdout if that's what's wanted.

computerquip-work avatar Apr 06 '22 15:04 computerquip-work

The whole point is that when meaningful output is possible, you use stderr as a means of human-readable output and stdout as a means for pragmatic output.

Then why is there no meaningful output on stdout? Like, for example, the image sha? Which would allow to do something simple like this, which would be incredibly unbelievably useful: docker run `docker build .` ...

Instead I'm required to... , well, actually I don't even know what I'm required to do, all I know is that something which should be easy and obvious will probably take me at least 30min to figure out, and will require juggling and cleaning up temporary files or some complicated shell redirection magic with non standard file descriptors.

Guys and gals, all I want is to be able to type docker build-n-run mvn install, and Docker builds the container and runs my Maven command inside it (preferably with the directory mounted inside). This is my most common use case. Why is this so complicated? Am I the only one who needs this?

marc-guenther avatar Apr 06 '22 16:04 marc-guenther

The whole point is that when meaningful output is possible, you use stderr as a means of human-readable output and stdout as a means for pragmatic output.

Then why is there no meaningful output on stdout? Like, for example, the image sha? Which would allow to do something simple like this, which would be incredibly unbelievably useful: docker run `docker build .` ...

Instead I'm required to... , well, actually I don't even know what I'm required to do, all I know is that something which should be easy and obvious will probably take me at least 30min to figure out, and will require juggling and cleaning up temporary files or some complicated shell redirection magic with non standard file descriptors.

Guys and gals, all I want is to be able to type docker build-n-run mvn install, and Docker builds the container and runs my Maven command inside it (preferably with the directory mounted inside). This is my most common use case. Why is this so complicated? Am I the only one who needs this?

That's the whole point of the issue, if you would read my previous reply explaining the changes I think should be made. For reference, other tools like buildah do exactly that.

EDIT: Also, you can already do that with BuildKit.

image_id=$(docker buildx build --quiet -f <Dockerfile>)
docker run "$image_id"

The problem here is you lose diagnostics.

computerquip-work avatar Apr 06 '22 16:04 computerquip-work

Yes, I absolutely agree. The question is, we have the year 2022, why are easy and obvious changes like this not being made?

EDIT: and of course I would rather prefer to see the diagnostic output...

marc-guenther avatar Apr 06 '22 16:04 marc-guenther

Yes, I absolutely agree. The question is, we have the year 2022, why are easy and obvious changes like this not being made?

EDIT: and of course I would rather prefer to see the diagnostic output...

Because half the people in the thread appear to think shoving everything into stdout is how things should be done. For the other half, while my suggestion is simple, it has a compatibility break as shown here: https://github.com/moby/buildkit/issues/1186#issuecomment-934804909

EDIT: And mine isn't the only suggestion and it differs slightly from others.

There probably has to be some consensus which appears to be hard to come to.

computerquip-work avatar Apr 06 '22 17:04 computerquip-work

As an alternative, something like this would also work:

img_file=$(mktemp)
docker buildx build . --iidfile "$img_file"
img_id=$(cat "$img_file")

Just remember to cleanup the temp file.

computerquip-work avatar Apr 06 '22 17:04 computerquip-work

Sorry for being verbose on the thread (I swear I'm not usually this chatty), but another thing that could be done is just keep --iidfile the way it is but fix the deletion logic. Currently, if you do something like docker buildx build . --iidfile /dev/stdout or docker buildx build . --iidfile >(cat), it fails because it appears to try to delete the iid file first. I'd argue this is probably not desirable to begin with but if that's fixed, the temp file hack above wouldn't be necessary either and it's fully backwards compatible.

computerquip-work avatar Apr 06 '22 17:04 computerquip-work

Thanks for saving me the 30min. ;) Yea, that's what I meant by require juggling and cleaning up temporary files. Probably something like: trap 'rm -f "$img_file"' 0 Yes, the quoting still interpolates the variable, and yes, this is waaaay too complicated for such a simple task.

marc-guenther avatar Apr 06 '22 17:04 marc-guenther

@computerquip-work

Any version of docker build should always output only the resulting image id to stdout.

Image ID is what the user needs only for specific types of builds: when build exported an image (into Docker image store), that image was not multi-arch and that image was not exported(eg. in OCI format). Even with all of these constraints most people just want to see the best progress information about their build, not a line in hex.

-q continues to work and output the image ID in stdout if the user wants it for backward compatibility. For everything else stdout works together with -o flag and allows redirecting the output(result) of the build.

Logs and progress should only be put out to stderr.

This is how it is today.

Simply remove the --quiet argument altogether or have it to where it only effects the stderr output.

I agree that we should deprecate it and suggest people to use the new flags that are single purpose and don't do multiple things at once.

@cocowalla

Azure DevOps pipeline, as AzDo fails tasks by default if anything is written to stderr. AzDo's default has never been an issue for me in years of working with it

This claim sounded so bizarre I needed to set up Azure DevOps for the first time. No surprise that it is not the case.

Screen Shot 2022-04-06 at 11 48 01 AM

How do you think the most common unix tools like wget, curl -v, time etc. print their progress information? Or do they fail on every invocation?

@marc-guenther

Then why is there no meaningful output on stdout?

which would be incredibly unbelievably useful: docker run docker build . ...

Instead I'm required to... , well, actually I don't even know what I'm required to do

Stdout is used for -o/--output redirects and for -q for backward compatibility exactly for the case you show in the example. This has been explained numerous times in previous comments.

@computerquip-work

but fix the deletion logic. Currently, if you do something like docker buildx build . --iidfile /dev/stdout or docker buildx build . --iidfile >(cat), it fails because it appears to try to delete the iid file first. I'd argue this is probably not desirable to begin with but if that's fixed, the temp file hack above wouldn't be necessary either and it's fully backwards compatible.

I'm not OK with removing the deletion logic as that is clearly the expected behavior of --iidfile on regular files, but we could detect the /dev/stdout is not a regular file and have a different behavior for it.

tonistiigi avatar Apr 06 '22 19:04 tonistiigi

I'm not OK with removing the deletion logic as that is clearly the expected behavior of --iidfile on regular files, but we could detect the /dev/stdout is not a regular file and have a different behavior for it.

Is it the file deletion logic that's expected or just that the file is cleared before writing to it? For example, in python (since I don't know how to emulate it in bash), you should be able to open a /dev/stdout device file with truncate mode like so it should work for regular files as well:

f = open('/dev/stdout', 'w+b', buffering=0)
f.write(b'bob\n')
f.close()

This won't work if the filesystem is set to read-only though and other issues.

computerquip-work avatar Apr 06 '22 19:04 computerquip-work

@computerquip-work Truncate mode is not ideal as it would leave an empty file if there is a crash. It should either clear the file or switch it with an atomic rename(there might be some tricky cases for unprivileged users).

tonistiigi avatar Apr 06 '22 19:04 tonistiigi

@cocowalla This claim sounded so bizarre I needed to set up Azure DevOps for the first time. No surprise that it is not the case.

It certainly is the case with the SSH task (we SSH into a VM to build containers)

cocowalla avatar Apr 06 '22 22:04 cocowalla

I think we need to go back to conventions and what developers expect of build tools.

  • make
  • mvn
  • gradle
  • dart pub
  • docker build

All of these build tools (I would guess every other language's build tool) output progress to stdout and errors to stderr. The content of build artifacts are never output to either stdout or stderr.

To break these long-standing conventions is a rather brave and pointless decision.

bsutton avatar Jun 15 '22 22:06 bsutton

What problem is being solved by doing that? I'd also argue that's not a long-standing convention, I've seen more projects output to stderr for progress than I have to stdout. If I were to proclaim the opposite as the long-standing convention and say To break these long-standing conventions is a rather brave and pointless decision., there isn't really much discussion to be had and it's not very productive.

computerquip-work avatar Jun 16 '22 15:06 computerquip-work

I haven't just proclaimed it, I've given concrete examples of other build tools that all conform to the convention, including Dockers own build tool.

Let me repeat that: including Dockers own build tool.

This reason this thread exist is that this change is a breaking change to docker, a change that appears to provide no benefits and which broke my code and clearly others.

On Fri, 17 June 2022, 1:49 am computerquip-work, @.***> wrote:

What problem is being solved by doing that? I'd also argue that's not a long-standing convention, I've seen more projects output to stderr for progress than I have to stdout. If I were to proclaim the opposite as the long-standing convention and say To break these long-standing conventions is a rather brave and pointless decision., there isn't really much discussion to be had and it's not very productive.

— Reply to this email directly, view it on GitHub https://github.com/moby/buildkit/issues/1186#issuecomment-1157822157, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAG32OB3UHMLT6DFDZQ6DK3VPNEJZANCNFSM4I43Z46A . You are receiving this because you commented.Message ID: @.***>

bsutton avatar Jun 16 '22 21:06 bsutton

  • buildah, podman, and kaniko don't do that
  • Just about every compiler and linking tool doesn't do that
  • Most Unix-style utilities obviously don't do that otherwise piping wouldn't function

The "gotcha" arguments are really not productive. The benefit of it is that it allows one to do something like tar=$(docker buildx build -o type=oci,dest=-) without the need to create a temporary file.

If you can make a simple example where you can pragmatically run an image that you just built without race conditions or temporary files, you would have a stronger argument.

computerquip-work avatar Jun 16 '22 21:06 computerquip-work