Compose: Docker-compose stops printing to terminal if stdout is idle for some time

[Gaabe]

Description of the issue

When the stdout is idle for some time, it stops printing anything forever on the terminal.

Context information (for bug reports)

I noticed this error running a django server on a docker container using docker-compose. After starting the server, it would print the requests normally, and keep printing everything it the requests kept coming. But if there was no requests for some time, two minutes or so, the following requests wouldn't print. So I created a python script to debug it, and it is still happening.

docker-compose version 1.22.0, build f46880f
docker-py version: 3.5.0
CPython version: 2.7.15rc1
OpenSSL version: OpenSSL 1.1.0g  2 Nov 2017

Client:
 Version:           18.06.1-ce
 API version:       1.38
 Go version:        go1.10.3
 Git commit:        e68fc7a
 Built:             Tue Aug 21 17:24:51 2018
 OS/Arch:           linux/amd64
 Experimental:      false

Server:
 Engine:
  Version:          18.06.1-ce
  API version:      1.38 (minimum version 1.12)
  Go version:       go1.10.3
  Git commit:       e68fc7a
  Built:            Tue Aug 21 17:23:15 2018
  OS/Arch:          linux/amd64
  Experimental:     false

networks:
  default:
    name: project_default
services:
  app:
    build:
      args:
        ALLOWED_HOSTS: localhost
        PORT: '8000'
        REQUIREMENTS: requirements/dev.txt
      context: /home/user/Development/project/project/src
    container_name: project_app
    entrypoint: /code/docker-entrypoint.sh
    environment:
      ALLOWED_HOSTS: localhost
      COMPOSE_PROJECT_NAME: project
      DEBUG: "True"
      DJANGO_SETTINGS_MODULE: project.settings.dev
      PORT: '8000'
      PYTHONUNBUFFERED: '1'
      REQUIREMENTS: requirements/dev.txt
      SERVER_EMAIL: [email protected]
    expose:
    - '8000'
    image: project
    links:
    - db
    - cache
    networks:
      default: null
    restart: unless-stopped
    tty: true
    volumes:
    - /home/user/Development/project/project/src:/code:rw
    - /code/node_modules  
version: '3.5'

Steps to reproduce the issue

1. Create a docker image from python:3
2. Run the image with docker-compose up
3. Execute the following python program in the docker-compose entrypoint

import random
import time

i = 0
while True:
    print("still printing", i)
    i += 1
    if i == 10:
        time.sleep(120)
    time.sleep(random.randint(2, 10))

Observed result

It will print up to 9, than hang for about 2 minutes as expected, then it won't print anything else. If you check the logs with docker-compose logs, it will still be printing fine.

Expected result

It should keep printing in the terminar, the same way it keeps printing in the logs

Additional information

Running on Ubuntu 18.04, installed docker-compose via pip

[shin-]

Thanks for the report @Gaabe

Unfortunately, I'm not able to reproduce the issue (working on Ubuntu 18.04 as well, Compose installed as a python package, same version). Is the Docker Engine running locally on the same machine as Compose? Are you connected to it using the (default) UNIX socket?

One thing you may want to try is to install Compose with Python 3 instead and see if that changes anything.

[goodspark]

I see similar problem on my system as well.

It happens off and on with no consistent way (_yet_) to recreate the error. But I was able to see the problem. I've minimized the setup even further:

• Ubuntu 18.04

Client:
 Version:           18.06.1-ce
 API version:       1.38
 Go version:        go1.10.3
 Git commit:        e68fc7a
 Built:             Tue Aug 21 17:24:51 2018
 OS/Arch:           linux/amd64
 Experimental:      false
Server:
 Engine:
  Version:          18.06.1-ce
  API version:      1.38 (minimum version 1.12)
  Go version:       go1.10.3
  Git commit:       e68fc7a
  Built:            Tue Aug 21 17:23:15 2018
  OS/Arch:          linux/amd64
  Experimental:     false

docker-compose version 1.22.0, build f46880f
docker-py version: 3.5.0
CPython version: 2.7.14
OpenSSL version: OpenSSL 1.1.0g  2 Nov 2017

docker-compose.yml

version: '3.5'
services:
  app:
    image: python:2.7.14
    volumes:
      - .:/code:rw

printy.py

#!/usr/bin/env python
import random
import time
i = 0
while True:
    print('still printing', i)
    i += 1
    if (i % 10) == 0:
        time.sleep(120)
    time.sleep(0.3)

And the following command:

docker-compose run app /code/printy.py

[shin-]

@goodspark Thanks. An answer to these questions would help us progress quite a bit. Specifically, please try installing Compose with python 3 and see if the problem persists.

[dfeinzeig]

any updates?

[dfeinzeig]

i'm seeing this behavior too. using docker desktop for windows with docker-compose 1.24.0 from WSL ubuntu 18.04 pointing at desktop for windows. i've set pythonunbuffered=1 and docker logs -f is still showing updates from the app, but the docker-compose up output just stops refreshing.

[leenr]

We've encountered that bug too.

I tried to run docker-compose up with strace -ff -etrace=connect,sendto,recvfrom and saw this:

strace: Process 244944 attached
Starting 909db07a14198ae0_tests_1_b5414f35b455 ...
strace: Process 244945 attached
[pid 244945] connect(13, {sa_family=AF_LOCAL, sun_path="/var/run/docker.sock"}, 22) = 0
[pid 244945] sendto(13, "POST /v1.22/containers/9e6660c4d755e849dd2e6fe9108f5a36aa90ecbff8fb5893861de0c78e2f010f/attach?stream=1&logs=0&stderr=1&stdout=1 HTTP/1.1\r\nHost: localhost\r\nConnection: Upgrade\r\nAccept-Encoding: gzip, deflate\r\nAccept: */*\r\nUser-Agent: docker-compose/1.23.1 docker-py/3.5.1 Linux/4.14.94-38\r\nUpgrade: tcp\r\nContent-Length: 0\r\n\r\n", 325, 0, NULL, 0) = 325
...
Starting 909db07a14198ae0_tests_1_b5414f35b455 ... done
[pid 244944] +++ exited with 0 +++
Attaching to 909db07a14198ae0_tests_1_b5414f35b455
strace: Process 245042 attached
strace: Process 245043 attached
[pid 245043] connect(15, {sa_family=AF_LOCAL, sun_path="/var/run/docker.sock"}, 22) = 0
[pid 245043] sendto(15, "GET /v1.22/events?filters=%7B%22label%22%3A+%5B%22com.docker.compose.project%3D909db07a14198ae0%22%2C+%22com.docker.compose.oneoff%3DFalse%22%5D%7D HTTP/1.1\r\nHost: localhost\r\nConnection: keep-alive\r\nAccept-Encoding: gzip, deflate\r\nAccept: */*\r\nUser-Agent: docker-compose/1.23.1 docker-py/3.5.1 Linux/4.14.94-38\r\n\r\n", 314, 0, NULL, 0) = 314
[pid 245043] recvfrom(15, "HTTP/1.1 200 OK\r\nApi-Version: 1.39\r\nContent-Type: application/json\r\nDocker-Experimental: false\r\nOstype: linux\r\nServer: Docker/18.09.3 (linux)\r\nDate: Tue, 21 May 2019 16:30:18 GMT\r\nTransfer-Encoding: chunked\r\n\r\n", 8192, 0, NULL, NULL) = 210
[pid 245043] recvfrom(15,  <unfinished ...>
[pid 245042] recvfrom(13, "\1\0\0\0\0\0\0\37", 8, 0, NULL, NULL) = 8
[pid 245042] recvfrom(13, "GLOB sdist-make: /mnt/setup.py\n", 31, 0, NULL, NULL) = 31
tests_1_b5414f35b455 | GLOB sdist-make: /mnt/setup.py
[pid 245042] recvfrom(13, "\1\0\0\0\0\0\0\35", 8, 0, NULL, NULL) = 8
[pid 245042] recvfrom(13, "py37 recreate: /tmp/tox/py37\n", 29, 0, NULL, NULL) = 29
tests_1_b5414f35b455 | py37 recreate: /tmp/tox/py37
[pid 245042] recvfrom(13, "\1\0\0\0\0\0\0F", 8, 0, NULL, NULL) = 8
[pid 245042] recvfrom(13, "py37 inst: /tmp/tox/.tmp/package/10/some_project-0.8.403+g6b9fba6.zip\n", 70, 0, NULL, NULL) = 70
tests_1_b5414f35b455 | py37 inst: /tmp/tox/.tmp/package/10/some_project-0.8.403+g6b9fba6.zip
[pid 245042] connect(16, {sa_family=AF_LOCAL, sun_path="/var/run/docker.sock"}, 22) = 0
[pid 245042] sendto(16, "POST /v1.22/containers/9e6660c4d755e849dd2e6fe9108f5a36aa90ecbff8fb5893861de0c78e2f010f/wait HTTP/1.1\r\nHost: localhost\r\nConnection: keep-alive\r\nAccept-Encoding: gzip, deflate\r\nAccept: */*\r\nUser-Agent: docker-compose/1.23.1 docker-py/3.5.1 Linux/4.14.94-38\r\nContent-Length: 0\r\n\r\n", 278, 0, NULL, 0) = 278
[pid 245042] recvfrom(16, ...

As I see, after some timeout without any new messages in /attach Docker API request, there was a reconnect and /wait Docker API call in the same pid (last 3 lines).
Socket 13 at this point is abandoned and I saw non-zero Recv-Q in ss output for this socket - probably the missed messages.
My guess, it is a timeout occurring somewhere.

[nickjj]

I'm experiencing the same issue here. I had a hunch it was related to being idle but I couldn't say for sure. This wasn't always the case with older versions of Docker / Docker Compose.

It's happening here with both Phoenix and Node apps too, and I imagine it affects any process running in the foreground (like a web server or webpack watcher, etc.).

I've configured WSL to connect to Docker for Windows. Running Win 10 Pro stable 18.09 but this build of Windows worked fine with older versions of Docker and Docker Compose. Docker for Windows is 18.09.2 and I'm using Docker Compose 1.24.0 (pip installed - Python 2) inside of WSL (Ubuntu 18.04).

I'm not a bug classification expert but I would say this comes in at nearly the top of "worst bug possible for day to day development".

Edit: Installed Docker Compose with pip3 and so far things are looking promising. I'm seeing output after idling multiple times for random amounts of time between 2-10 minutes.

Here's a 1 liner to remove compose for Python 2, install pip3 and install compose for your user:
pip uninstall docker-compose && sudo apt-get install python3-pip && pip3 install --user docker-compose

Edit 2: Had a chance to put in a multiple hour coding session where I would have had the issue happen at least 10 times by now. With Python 3 it's all good. The output always comes through.

[kindermax]

Hi, I am experiencing the same issue when output from commands is delayed until some moment.

Example here is using webpack with --progress and --watch flags.

The expected behavior is when I can see progress in percentage, basically, the last line overrides every time a percentage of build changes.

Current behavior - I see a webpack is watching the files… line for a couple of minutes until webpack build is done, then I see webpack build final outout.

I've connected to docker-compose process with strace in the time webpack was building project
Here is the output.

sudo strace -ff -etrace=connect,sendto,recvfrom -p 31199
strace: Process 31199 attached with 3 threads
[pid 31200] recvfrom(12,  <unfinished ...>
[pid 31199] recvfrom(10, "\10 \10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10"..., 4096, 0, NULL, NULL) = 1294
[pid 31199] recvfrom(10, "\10 \10\10 \10\10 \10\10 \10\10 \10\10 \10\10 \10\10 \10\10 \10\10\10\10\10\10"..., 4096, 0, NULL, NULL) = 2460
[pid 31199] recvfrom(10, "\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10"..., 4096, 0, NULL, NULL) = 379
[pid 31199] recvfrom(10, "\10 \10\10 \10\10 \10\10 \10\10 \10\10 \10\10 \10\10 \10\10 \10\10 \10\10 "..., 4096, 0, NULL, NULL) = 445
[pid 31199] recvfrom(10, "\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10"..., 4096, 0, NULL, NULL) = 335
[pid 31199] recvfrom(10, "\10 \10\10 \10\10 \10\10 \10\10 \10\10 \10\10 \10\10 \10\10 \10\10 \10\10 "..., 4096, 0, NULL, NULL) = 415
[pid 31199] recvfrom(10, "\10 \10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10"..., 4096, 0, NULL, NULL) = 341
[pid 31199] recvfrom(10, "\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10"..., 4096, 0, NULL, NULL) = 338
[pid 31199] recvfrom(10, "\10 \10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10"..., 4096, 0, NULL, NULL) = 339
[pid 31199] recvfrom(10, "\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10"..., 4096, 0, NULL, NULL) = 336
[pid 31199] recvfrom(10, "\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10"..., 4096, 0, NULL, NULL) = 168
[pid 31199] recvfrom(10, " 68% building 4409/4508 modules "..., 4096, 0, NULL, NULL) = 514
[pid 31199] recvfrom(10, "\10 \10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10"..., 4096, 0, NULL, NULL) = 353
[pid 31199] recvfrom(10, "\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10"..., 4096, 0, NULL, NULL) = 350
[pid 31199] recvfrom(10, "\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10"..., 4096, 0, NULL, NULL) = 350
[pid 31199] recvfrom(10, "\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10"..., 4096, 0, NULL, NULL) = 350
[pid 31199] recvfrom(10, "\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10"..., 4096, 0, NULL, NULL) = 350
[pid 31199] recvfrom(10, "\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10"..., 4096, 0, NULL, NULL) = 350
[pid 31199] recvfrom(10, "\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10"..., 4096, 0, NULL, NULL) = 350
[pid 31199] recvfrom(10, "\10 \10\10 \10\10 \10\10 \10\10 \10\10 \10\10 \10\10 \10\10 \10\10 \10\10 "..., 4096, 0, NULL, NULL) = 341
[pid 31199] recvfrom(10, "\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10"..., 4096, 0, NULL, NULL) = 296
[pid 31199] recvfrom(10, "\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10"..., 4096, 0, NULL, NULL) = 296
[pid 31199] recvfrom(10, "\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10\10"..., 4096, 0, NULL, NULL) = 331
[pid 31199] recvfrom(10, "\10 \10\10 \10\10 \10\10 \10\10 \10\10 \10\10 \10\10 \10\10 \10\10 \10\10 "..., 4096, 0, NULL, NULL) = 253
[pid 31199] recvfrom(10, " 68% building 4431/4519 modules "..., 4096, 0, NULL, NULL) = 446

As you can see there are lines 68% building 4409/4508 modules which means webpack output is correct but still not shown in docker-compose output

[kindermax]

I can confirm that using run instead of up if fixing the problem (with some additional useful changes as FORCE_COLOR=2 env var and -T flag for run command

[anhtu812]

log of my c++ process is very delay (15 minutes or no print out) if i use docker compose up. No delay with docker compose run. I can't debug with delay log. Please fix it.

I installed Compose with python 3, have similar problem.

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

[stale[bot]]

This issue has been automatically closed because it had not recent activity during the stale period.