Compose: Why does docker-compose log to STDERR for `Building ....` instead of STDOUT when executing docker-compose build

[devedse]

Description of the issue

I'm working on an Azure DevOps extension which needs to read the docker-compose build output. I was however running into the issue that the STDOUT had some missing log lines: (Lines with #### in front of it where missing from STDOUT)

##### Building sample1 <-- missing
Step 1/2 : FROM nginx:alpine
 ---> 377c0837328f
Step 2/2 : COPY . /usr/share/nginx/html
 ---> Using cache
 ---> 6cac8912ab73

Successfully built 6cac8912ab73
Successfully tagged sample1:latest
##### Building sample2 <-- missing
Step 1/2 : FROM nginx:alpine
 ---> 377c0837328f
Step 2/2 : COPY . /usr/share/nginx/html
 ---> Using cache
 ---> 6cac8912ab73

Successfully built 6cac8912ab73
Successfully tagged sample2:latest

I've been doing some investigation and have created a repository to reproduce this:
https://github.com/devedse/STDOUTMissingError/blob/master/README.md

As you can see there, apparently the lines Building ... are being written to STDERR instead of STDOUT.

Does anyone have any idea on why this is happening?

Context information (for bug reports)

Output of docker-compose version

docker-compose version 1.25.4, build 8d51620a

Output of docker version

Client: Docker Engine - Community
 Version:           19.03.8
 API version:       1.40
 Go version:        go1.12.17
 Git commit:        afacb8b
 Built:             Wed Mar 11 01:23:10 2020
 OS/Arch:           windows/amd64
 Experimental:      false

Server: Docker Engine - Community
 Engine:
  Version:          19.03.8
  API version:      1.40 (minimum version 1.12)
  Go version:       go1.12.17
  Git commit:       afacb8b
  Built:            Wed Mar 11 01:29:16 2020
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          v1.2.13
  GitCommit:        7ad184331fa3e55e52b890ea95e65ba581ae3429
 runc:
  Version:          1.0.0-rc10
  GitCommit:        dc9208a3303feef5b3839f4323d9beb36df0a9dd
 docker-init:
  Version:          0.18.0
  GitCommit:        fec3683

Output of docker-compose config
See the repository linked above, I've added automated builds to that.

Steps to reproduce the issue

1. Clone the repository linked above
2. Execute tsc in the ./src directory
3. Execute node index.js in the ./src directory

(Or simply check the build output in my repository)

Observed result

Step 1/2 : FROM nginx:alpine
 ---> 377c0837328f
Step 2/2 : COPY . /usr/share/nginx/html
 ---> Using cache
 ---> 6cac8912ab73

Successfully built 6cac8912ab73
Successfully tagged sample1:latest
Step 1/2 : FROM nginx:alpine
 ---> 377c0837328f
Step 2/2 : COPY . /usr/share/nginx/html
 ---> Using cache
 ---> 6cac8912ab73

Successfully built 6cac8912ab73
Successfully tagged sample2:latest

Expected result

Building sample1
Step 1/2 : FROM nginx:alpine
 ---> 377c0837328f
Step 2/2 : COPY . /usr/share/nginx/html
 ---> Using cache
 ---> 6cac8912ab73

Successfully built 6cac8912ab73
Successfully tagged sample1:latest
Building sample2
Step 1/2 : FROM nginx:alpine
 ---> 377c0837328f
Step 2/2 : COPY . /usr/share/nginx/html
 ---> Using cache
 ---> 6cac8912ab73

Successfully built 6cac8912ab73
Successfully tagged sample2:latest

Stacktrace / full error message

Well technically 😆:

Building sample1
Building sample2

But in fact, there's not really an error log.

Additional information

Happens on both linux (Travis-ci) and windows (Appveyor)

[devedse]

Could it have something to do with this line:

https://github.com/docker/compose/blob/13bacba2b9aecdf1f3d9a4aa9e01fbc1f9e293ce/compose/cli/main.py#L65

Apparently it was added in this commit by @bfirsh :
https://github.com/docker/compose/commit/6d0702e6075e8bdc9d4094fbd063214870f407cc

[devedse]

@shin- and everyone else

STDOUT instead of STDERR

I've been looking through some other Github issues and it seems that as of now this could be a choice made by the docker-compose team:

https://github.com/docker/compose/issues/5590
https://github.com/docker/compose/issues/5296
https://github.com/docker/compose/issues/5590#issuecomment-359110186

To me the choice to (ab)use STDERR to split logging for docker and docker-compose seems like a wrong decision.

StackExchange has some good information on how to use STDOUT and STDERR and I don't think docker-compose is complying to these standards:

https://unix.stackexchange.com/questions/331611/do-progress-reports-logging-information-belong-on-stderr-or-stdout

Let's see if the docker-compose team agrees on this as well and hopefully get this fixed as soon as possible.

Some information on why this fix is important for me

I'm currently parsing the logs of docker-compose but the best way to find out what build log belongs to what container is parsing through the log and finding the Building .... statement. As this states the beginning of a new container build. However since this specific line is missing in the docker-compose log it makes it a lot harder to find out what build belongs to what part of your docker-compose file.

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[pwagland]

I just came across this issue, since we have a build process that alerts us when something is printed to stderr… we recently added docker-compose, and of course it alerts. We can (and are going to) redirected stderr to stdout, but then any _real_ errors won't be seen. It would be very useful to have this standard output _not_ turn up in the error stream.

[stale[bot]]

This issue has been automatically marked as not stale anymore due to the recent activity.

[rjlasko]

I agree that this is still an issue. Changing the log level does nothing to address writing output to STDERR. I run this in cron and utilize cronic (which is highly regarded in the linux world) to send emails when actual errors occur. This is my crontab:

@hourly cronic docker-compose --log-level=ERROR --no-ansi --file ~/docker-compose.yml run --rm my_service

The log level does nothing for me, so i get the following in my emails:

Cronic detected failure or error output for the command:
docker-compose --log-level=ERROR --no-ansi --file ~/docker-compose.yml run --rm my_service

RESULT CODE: 0

ERROR OUTPUT:
Creating test_my_service_run ... 
Creating test_my_service_run ... done

STANDARD OUTPUT: