Buildkit: Problems with build output

[Monnoroch]

Some CI tools do not support updating rows in logs. This feature makes the output very nice and dynamic in most terminals, but terrible in CI tools. For example:

#2 [internal] load Dockerfile
#2       digest: sha256:2c6f8b4480264b5726c0d71b15eabc3fcc89c57ff9726fcb7423900978eb2011
#2         name: "[internal] load Dockerfile"
#2      started: 2018-08-08 20:20:55.499773549 +0000 UTC
#2    completed: 2018-08-08 20:20:55.508116402 +0000 UTC
#2     duration: 8.342853ms
#2      started: 2018-08-08 20:20:55.55401781 +0000 UTC
#2 transferring dockerfile:
#2 transferring dockerfile: 8.36kB 0.1s done
#2    completed: 2018-08-08 20:20:56.02282162 +0000 UTC
#2     duration: 468.80381ms


#1 [internal] load .dockerignore
#1       digest: sha256:cd79e09d00ab98ba8a18ffae0192aae97f5141509285d80a1e57f853d3219db7
#1         name: "[internal] load .dockerignore"
#1      started: 2018-08-08 20:20:55.499686297 +0000 UTC
#1    completed: 2018-08-08 20:20:55.50802369 +0000 UTC
#1     duration: 8.337393ms
#1      started: 2018-08-08 20:20:55.553973005 +0000 UTC
#1 transferring context: 182B 0.1s done
#1    completed: 2018-08-08 20:20:56.222713362 +0000 UTC
#1     duration: 668.740357ms


#3 [internal] load metadata for docker.io/library/buildpack-deps:stretch-sc...
#3       digest: sha256:041cad18349bb3a69a06b0e8e8309e12a1c508911575a32a13ab199c6d7ecad8
#3         name: "[internal] load metadata for docker.io/library/buildpack-deps:stretch-scm"
#3      started: 2018-08-08 20:20:56.403116254 +0000 UTC
#3    completed: 2018-08-08 20:20:57.870701656 +0000 UTC
#3     duration: 1.467585402s

The same issue sometimes happens if you are ssh-ed through multiple layers of servers. Would it be possible to add a flag that disables outputting all the metadata for dynamic log updates?

[tonistiigi]

What part of the output are you specifically referring in here? The repeated started/completed in here are different stages and mean cache-lookup and execution phases so not really related to the non-console output.

cc @tiborvass

[Monnoroch]

I'm referring to ALL parts. This output is more machine-readable than human-readable. If you run a build from a nice terminal emulator, you get very nice log with progress bars updating in place. I assume that this is possible because of these prefixes #N XX.YY and all those metadata fields. However this is very much not useful when the build command is running in CI environments that can't automatically fold these machine-readable logs designed for clever terminals or something.

[tonistiigi]

The output formatting is different when you run on a terminal and when you don't. The output above is not how the terminal output would look automatically. Eg. it has command outputs and prefix to ease grepping. Feel free to suggest your own format that you find better but don't forget that different steps in buildkit do not run in a single thread sequence.

[Monnoroch]

Is there a way to have logs similar to docker build output?

[tonistiigi]

Depends on what you mean by similar. Like I said, the only real difference is that buildkit executes things in parallel and it would be very bad to hide the output of parallel steps like would happen with a single thread output of current docker build. Maybe it is true that you don't actually need all this info that is provided and some of it is more confusing than useful but for that we need to look at specific issues and specific proposals for fixes.

For CI specifically, another solution could be to provide a special trace output after build has completed. This output can be much more precise and deterministic then as we know all the data until the end of the build.

[Monnoroch]

Having one single output at the end is not a particularly great idea. CI jobs can take a long time and can hang when there are bugs or infra issues. Having logs being outputted continuously is a good way of debugging such problems. To be honest, I'm not seeing any problems with parallel execution. If there are dependencies between steps, they will be executed and logged sequentially. If two steps are independent, fine, I don't really care about log order either. It's just a matter of synchronizing the stdout writer in this case. Or am I missing something?

[tiborvass]

@Monnoroch if you're curious you can try a build of buildkit before #438 and try --no-progress. It is probably not exactly what you're looking for, but maybe it will help us understand each other better.

We think that log order is important to be able to understand the output faster, otherwise you might as well not show them.