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:

compose/compose/cli/main.py

Line 65 in 13bacba

console_handler = logging.StreamHandler(sys.stderr)

Apparently it was added in this commit by @bfirsh :
6d0702e

[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:

#5590
#5296
#5590 (comment)

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]

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]

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:

[phuxman]

We are currently running into the same problem on our automatic deploy system. We have two solutions:

• Redirect STDERR -> No real error output. Make devs nervous.
• Leave it and ignore errors on deploy step.-> Pseudo-errors make devs nervous.

So we have nervous devs...

Maybe it is possible to do some intelligent redirecting by scripted parsing?

[ASHXOR]

I have done something similar, redirected STDERR into a file, but then added a step into my pipe that will rely on an actual step failure to go and display the error log, I also added it as a step to display the error log on success pointing out that it contains these types of non error messages, then it was a matter of educating the devs about this.

[shaneseaton]

This is complete rubbish. Writing log messages to STDERR is poor practice. Fix it please, so we dont have to ignore our CI/CD messages.

[Ninglin]

It has been an year since this issue was opened. Me as well as several other people are experiencing this issue, this is due to the fact that a large majority of users rely on Build Servers to build their changes. These Build Servers usually include the feature of interpreting output on stderr as an error and fail builds based on it (and they should because if something writes to stderr, by convention, it means that the process executed with errors).
I can't fathom the design decision of using stderr to write normal output messages just to differentiate execution context.
Given all the information in this issue, are you able to provide with an update regarding this. Is this on the roadmap?

[shaneseaton]

At the very least, even if you have the worlds best argument for logging on STDERR, perhaps you could provide a flag, or argument in the docker-compose file for people who like logging to go elsewhere:

log-output: stdout | stderr | none

[alexwenzel]

bump up

[maanloper]

Have been scratching my head why my script stopped working since I added docker-compose instead of docker run commands. I support the flag idea if the default behaviour is rather left untouched.

[dilnuwan-calcey]

Issue still exists

[brunobertechini]

Is there any update on this issue?

[pseudocoder]

Agree, writing non-errors to stderr is bad practice and breaks many standard workflows for checking and storing output.

It's particularly bad as many docker-compose commands don't allow suppression of verbose output either.

[yaguanggu]

Bump up

[yaguanggu]

CD pipeline reports output messages from docker-compose as errors. Have to tell people that errors from docker-compose are normal messages and just ignore them. Please fix it.

[eboboshka]

Add likes to first message.
The problem has been going on for too long! -_-'

[awmcclain]

For us as well. At least let us configure it.

[alexwenzel]

+1

[emimontesdeoca]

Any news on this? We are currently using Azure DevOps and we have to ignore the error messages due to this.

[ndeloof]

I'm also not convinced use of os.stderr to display information on the current operation is not the best decision we made.
unfortunately there's nothing like os.stdinfo we could rely on to distinguish such messages vs plain build/run logs.

[avk999]

Bump. The problem is still here. Logging to STDERROR is wrong on so many errors...

[Andrei-NZ]

ny news on this? We are currently using Azure DevOps and we have to ignore the error messages due to this.

If this helps, I worked around this issue by redirecting stderr to stdout in Azure pipelines

sudo docker-compose pull "app" 2>&1

[emimontesdeoca]

ny news on this? We are currently using Azure DevOps and we have to ignore the error messages due to this.

If this helps, I worked around this issue by redirecting stderr to stdout in Azure pipelines

sudo docker-compose pull "app" 2>&1

Thanks, will do that!

[domdeger]

ny news on this? We are currently using Azure DevOps and we have to ignore the error messages due to this.

If this helps, I worked around this issue by redirecting stderr to stdout in Azure pipelines

sudo docker-compose pull "app" 2>&1

That really resolves the issue and does not swallow errors since in case of error non zero code is returned and recognized as error at least in azure pipelines.

[michvllni]

For me (still using TFS2018) this somehow didn't work any more...what worked for me instead (using a windows agent and thus powershell) was the following:

function Invoke-DockerComposeCommand {
    param(
        [string]
        $arguments
    )
    $cmdarguments = @("/c", "docker-compose") + ($arguments -split " ")
    $processStartInfo = New-Object System.Diagnostics.ProcessStartInfo
    $processStartInfo.WorkingDirectory = (pwd).Path
    $processStartInfo.FileName = "C:\windows\system32\cmd.exe"
    $processStartInfo.RedirectStandardError = $true
    $processStartInfo.RedirectStandardOutput = $true
    $processStartInfo.UseShellExecute = $false     
    $processStartInfo.Arguments = $cmdarguments

    $process = New-Object System.Diagnostics.Process

    $process.StartInfo = $processStartInfo
    Write-Host "docker-compose $arguments..." -NoNewline
    $process.Start() | Out-Null
    $process.WaitForExit()
    if ($process.ExitCode -ne 0) {
        Write-Host "error"
        throw [Exception]::new("Error on docker-compose $($arguments): $($process.StandardError.ReadToEnd())")
    }else{
        Write-Host "done"
    }
}

Invoking it as following:

Invoke-DockerComposeCommand "up -d"

[fede843]

any workaround when using cronic?

[fede843]

OK, I've been trying to get this to work (for a cron job), and noticed there are 2 cronic/chronic commands actually. I was trying to get it done using cronic, same as one user mentioned before, whereas the solution proposed here #5296 talks about chronic. There is a sutil difference here.
Cronic defines error as (in other words trigger the cron job) "any non-trace error output or a non-zero result code." whereas chronic does it as "exits nonzero or crashes". And that is the key here, having the chance to look only for exit code alone. For the latest one, you can use "-e" option to have a similar behaviour than cronic. Hope this can help somebody.

[breakbitman]

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:

Redirect "Creating * ... * "-messages from STDERR to STDOUT:

#!/usr/bin/env bash

redirect_crap_to_stdout () {
  while read line; do
    if [[ $line =~ ^Creating ]] && [[ $line =~ \.\.\. ]]; then
      echo $line
    else
      echo $line 1>&2
    fi
  done
}

{ docker-compose --log-level=ERROR --no-ansi --file ~/docker-compose.yml run --rm my_service \
  2>&1 1>&3 | redirect_crap_to_stdout; } 3>&1

[ShaneBurkhart]

It appears that stdout to stderr was intentional. If there is a breaking reason, can you add a setting to not pipe stdout to stderr? Let the default be backwards compatible but also let anyone use stderr appropriately if we like.

[Parsa2820]

I wrote handle_sdterr function as a workaround for this issue.

handle_stderr() {
  output=$($1 2>&1)
  exit_code=$?
  if [ $exit_code -eq 0 ]
  then
    echo "$output"
  else
    >&2 echo "$output"
    exit $exit_code
  fi
}

handle_stderr "docker compose pull"
handle_stderr "docker compose up --detach"

[workingmachine]

Issue still exists.

[ndeloof]

That's sad there's no such thing like a POSIX stdinfo we could use here. Decision to use stderr for status message was driven by the need to easily filter out container output on docker compose up vs status messages, and then used for other commands for homogeneity.
On #10549 I'm proposing to make this configurable via an environment variable to have compose use stdout. Let me know with a 👍 or 👎 reaction if this sounds an adequate proposal

[ton77v]

It seems the issue still exists with docker build e.g.

  test('Build Docker Image', async () => {
    const { stdout, stderr } = await execAsync(
        `docker build -t ${imageName} .`);
    expect(stdout).toEqual('');
    expect(stderr).toContain('DONE');
  });

Assertions should be the other way around 🙃

[ndeloof]

@ton77v docker build is implemented by https://github.com/docker/buildx

[dcrouch79]

COMPOSE_STATUS_STDOUT=1 to redirect secondary info to stdout instead of stderr.

(Fixed by #10549 but not clear to see on this issue)