Separate STDERR and STDOUT in docker compose output

[raiyanyahya]

Is your feature request related to a problem? Please describe.
Docker compose outputs container stderr output to stdout
Refer to the sample below:
docker-compose.yml :

version: "3.3"
services:
  stderr:
    image: alpine
    command: /bin/ash /log_to_stderr.sh
    volumes:
           - ./log_to_stderr.sh:/log_to_stderr.sh

log_to_stderr.sh:

>&2 echo "log to stderr"
echo "log to stdout"

Running the bash script separately we get the output:

❯ ./log_to_stderr.sh 2> /dev/null
log to stdout

BUT
when running docker-compose we get:

❯ docker-compose up 2> /dev/null
Attaching to composeissue_stderr_1
stderr_1  | log to stderr
stderr_1  | log to stdout
composeissue_stderr_1 exited with code 0

Note:
Just running the image with docker seems to give us the expected behaviour:

❯ docker run --rm -v ${PWD}/log_to_stderr.sh:/log_to_stderr.sh alpine /bin/ash /log_to_stderr.sh 2> /dev/null 
log to stdout

Describe the solution you'd like
Docker compose should use the same output stream as the container.

[dexter74]

Hello,

I think was a error them line command. (Log : ash is not found ?)

Before:

version: "3.3"
services:
  stderr:
    image: alpine
    command: /bin/ash /log_to_stderr.sh
    volumes:
           - ./log_to_stderr.sh:/log_to_stderr.sh

After:

version: "3.3"
services:
  stderr:
    image: alpine
    command: /bin/bash /log_to_stderr.sh
    volumes:
           - ./log_to_stderr.sh:/log_to_stderr.sh

[LennartC]

Hi Marc,

That's not going to be the issue.
In the Alpine docker image, bash is not installed by default, but ash is. But it makes no difference whether you use bash or ash.

Example with debian:buster-slim and bash:

version: "3.3"
services:
  stderr:
    image: debian:buster-slim
    command: /bin/bash /log_to_stderr.sh
    volumes:
           - ./log_to_stderr.sh:/log_to_stderr.sh

$ docker-compose up 2> /dev/null
Attaching to composeissue_stderr_1
stderr_1  | log to stdout
stderr_1  | log to stderr
composeissue_stderr_1 exited with code 0

The "error" really is with docker compose itself, merging the stdout and stderr stream of the containers.

[thaJeztah]

So the equivalent of the docker run example for compose would be;

docker-compose run -T stderr 2> /dev/null
log to stdout

(unlike docker run, docker-compose by default attaches a TTY, so use -T to not have it attach a TTY)

As to the docker-compose up case, I'm a bit on the fence. docker-compose up; it does not print the "raw" output of any of the services (it decorates the logs by prefixing service names, and also produces (informational) output messages of docker-compose itself).

Splitting stderr/stdout in this case is done to separate "informational output messages" of compose itself (stderr) and "expected output" (output of containers) on stdout.

For example;

$ docker-compose up
WARNING: The Docker Engine you're using is running in swarm mode.

Compose does not use swarm mode to deploy services to multiple nodes in a swarm. All containers will be scheduled on the current node.

To deploy your application across the swarm, use `docker stack deploy`.

Starting repro-8098_stderr_1 ... done
Attaching to repro-8098_stderr_1
stderr_1  | log to stdout
stderr_1  | log to stderr
repro-8098_stderr_1 exited with code 0

And the same, this time redirecting stderr suppresses the informational warnings;

$ docker-compose up 2> /dev/null
Attaching to repro-8098_stderr_1
stderr_1  | log to stdout
stderr_1  | log to stderr
repro-8098_stderr_1 exited with code 0

That said, docker-compose logs, which would be more suitable to get the raw logs/output of a service (unfortunately) currently cannot be used as a replacement/equivalent of docker logs.

Comparing;

$ docker logs repro-8098_stderr_run_770ad5840016
log to stdout
log to stderr

$ docker logs repro-8098_stderr_run_770ad5840016 2> /dev/null
log to stdout

And (docker-compose);

$ docker-compose logs stderr
Attaching to repro-8098_stderr_1
stderr_1  | log to stdout
stderr_1  | log to stderr

$ docker-compose logs stderr 2> /dev/null
Attaching to repro-8098_stderr_1
stderr_1  | log to stdout
stderr_1  | log to stderr

This may be (at least partially) because docker-compose logs allows for one or more services logs to be printed, and therefore somewhat "requires" the output to include the prefixes (to know which service / service instance produced a log entry). Having "raw" (non-modified) log output of containers would still be usefull though, so perhaps there should be an option to disable that functionality and output the logs as-is.

[thaJeztah]

One thing that (IMO) should be fixed at least is to (in the docker-compose logs example) either skip the Attaching to ... message, or at least move it to stderr, so that output is purely the output of the containers (I don't think the "Attaching to" is providing much value to the user; it would only be relevant if attaching failed)

[deriksson]

For the docker-compose up case: Since the output from the containers is already decorated with the service name prefix, couldn't docker-compose also, optionally, annotate the log entries with information of which output stream they were sent to by the container?

[thaJeztah]

couldn't docker-compose also, optionally, annotate the log entries with information of which output stream they were sent to by the container?

I think this depends on how it collects the output; containers with a TTY attached send a "raw" stream over the API, whereas containers without a TTY send a multiplexed stream that contains information about stderr/stdout. I must admit I'm not familiar enough with the compose codebase, and would have to look into that.

That said; there's development ongoing to implement docker compose in "go" (preview already included in docker desktop, repository is in https://github.com/docker/compose-cli), which may give more flexibility for things like that. We're discussing formatting options for "log" output, and such a feature could be considered as part of that.

[ndeloof]

skip the Attaching to ... message, or at least move it to stderr

unfortunately POSIX is missing a stdinfo stream, so I'm not sure stderr is the adequate stream we should use for informational messages. But we could support a --quiet flag to just skip them all.

I'll need to read more about TTY and how those actually can eventually split a raw process stream back into stdout+stderr, if reasonably portable we could get the same implemented in compose to process the TTY log output and redirect logs into console streams.

[thaJeztah]

unfortunately POSIX is missing a stdinfo stream, so I'm not sure stderr is the adequate stream we should use for informational messages

Yes, a stdinfo stream would've been nice, but it's not a thing, and general convention is to use stderr for that purpose to allow redirecting.

[brian-dlee]

This is also the case for docker compose exec. I use docker containers to perform database dumps to avoid missing or mismatched client libraries. When using docker-compose exec XXX mysqldump I can easily redirect stdout to a file resulting in a valid mysql dump file. I've recently switched over to using docker compose exec instead of docker-compose exec, but I'm not getting the same results. In this case, it's merging stderr and stdout into the same stream which results in a corrupted mysql dump file.

Reproduce steps

Pass: docker-compose

cat >docker-compose.yml <<EOF
version: "3.4"
services:
  database:
    image: mysql:5.7
    environment:
      - MYSQL_ALLOW_EMPTY_PASSWORD=yes
EOF
docker-compose down -v
docker-compose up -d
sleep 10
docker-compose exec -T database mysql <<<"CREATE DATABASE mydb;"
docker-compose exec database mysqldump -u root -h 127.0.0.1 --databases mydb >dump.sql
docker-compose exec -T database mysql <<<"DROP DATABASE mydb;"
docker-compose exec -T database mysql <dump.sql
docker-compose exec -T database mysql <<<"SHOW DATABASES;"

Fail: docker compose

cat >docker-compose.yml <<EOF
version: "3.4"
services:
  database:
    image: mysql:5.7
    environment:
      - MYSQL_ALLOW_EMPTY_PASSWORD=yes
EOF
docker compose down -v
docker compose up -d
sleep 10
docker compose exec -T database mysql <<<"CREATE DATABASE mydb;"
docker compose exec database mysqldump -u root --databases mydb >dump.sql
docker compose exec -T database mysql <<<"DROP DATABASE mydb;"
docker compose exec -T database mysql <dump.sql
docker compose exec -T database mysql <<<"SHOW DATABASES;"

[rfay]

This is an important issue in docker-compose v2 and really should be sorted out.