Why delayed output for python process in my Docker logs?

Recently while moving one of our projects to Docker, we had a weird error that our python script would not output any data in docker logs. We thought the scripts were stuck, but later we realized the logs had a delayed output

When we were running the script inside the docker image through bash they would give all output on the console fine. Which kind of puzzled us

So we created a simple project to recreate the issue

Dockerfile

FROM python:2.7
WORKDIR /data
COPY ./app.py /data/app.py
COPY ./timer.sh /data/timer.sh
CMD ["python", "app.py"]

app.py is a simple script which prints time after every second for 10 secs

app.py

import time
import datetime

count = 10
while count:
    print datetime.datetime.now()
    time.sleep(1)
    count -= 1

timer.sh

A similar script to app.py but in bash

#!/bin/bash

i="0"

while [ $i -lt 10 ]
do
i=$[$i+1]
echo "$i `date`"
done

docker-compose.yml

version: '2'
services:
  server:
    build: .
  server_sh:
    build: .
    command: ["/bin/bash", "/data/timer.sh"]

Now when we run the composition docker-compose up command we get the following output

vagrant@vagrant:/vagrant/python-no-output$ docker-compose up
Creating pythonnooutput_server_sh_1
Creating pythonnooutput_server_1
Attaching to pythonnooutput_server_1, pythonnooutput_server_sh_1
server_sh_1  | 1 Fri May 26 19:11:54 UTC 2017
server_sh_1  | 2 Fri May 26 19:11:55 UTC 2017
server_sh_1  | 3 Fri May 26 19:11:56 UTC 2017
server_sh_1  | 4 Fri May 26 19:11:57 UTC 2017
server_sh_1  | 5 Fri May 26 19:11:58 UTC 2017
server_sh_1  | 6 Fri May 26 19:11:59 UTC 2017
server_sh_1  | 7 Fri May 26 19:12:00 UTC 2017
server_sh_1  | 8 Fri May 26 19:12:01 UTC 2017
server_sh_1  | 9 Fri May 26 19:12:02 UTC 2017
server_sh_1  | 10 Fri May 26 19:12:03 UTC 2017
server_1     | 2017-05-26 19:11:54.363404
server_1     | 2017-05-26 19:11:55.364241
server_1     | 2017-05-26 19:11:56.365709
server_1     | 2017-05-26 19:11:57.367153
server_1     | 2017-05-26 19:11:58.368840
server_1     | 2017-05-26 19:11:59.370574
server_1     | 2017-05-26 19:12:00.371755
server_1     | 2017-05-26 19:12:01.372124
server_1     | 2017-05-26 19:12:02.372288
server_1     | 2017-05-26 19:12:03.373790
pythonnooutput_server_1 exited with code 0
pythonnooutput_server_sh_1 exited with code 0

As you can see there is no output from python script at start and then after some delay all the outputs show up

After some digging I found that python buffers all its console output.

The same can be fixed by passing the -u flag to python or by defining the environment variable PYTHONUNBUFFERED. For more details about the same refer here

So define the environment variable in docker-compose.yml

docker-compose.yml

version: '2'
services:
  server:
    build: .
    environment:
      - "PYTHONUNBUFFERED=1"
  server_sh:
    build: .
    command: ["/bin/bash", "/data/timer.sh"]

Now when we run the composition again

vagrant@vagrant:/vagrant/python-no-output$ docker-compose up
Creating pythonnooutput_server_sh_1
Creating pythonnooutput_server_1
Attaching to pythonnooutput_server_sh_1, pythonnooutput_server_1
server_sh_1  | 1 Fri May 26 19:14:54 UTC 2017
server_1     | 2017-05-26 19:14:54.061717
server_sh_1  | 2 Fri May 26 19:14:55 UTC 2017
server_1     | 2017-05-26 19:14:55.063070
server_sh_1  | 3 Fri May 26 19:14:56 UTC 2017
server_1     | 2017-05-26 19:14:56.064899
server_sh_1  | 4 Fri May 26 19:14:57 UTC 2017
server_1     | 2017-05-26 19:14:57.066194
server_sh_1  | 5 Fri May 26 19:14:58 UTC 2017
server_1     | 2017-05-26 19:14:58.067593
server_sh_1  | 6 Fri May 26 19:14:59 UTC 2017
server_1     | 2017-05-26 19:14:59.069434
server_sh_1  | 7 Fri May 26 19:15:00 UTC 2017
server_1     | 2017-05-26 19:15:00.070952
server_sh_1  | 8 Fri May 26 19:15:01 UTC 2017
server_1     | 2017-05-26 19:15:01.072400
server_sh_1  | 9 Fri May 26 19:15:02 UTC 2017
server_1     | 2017-05-26 19:15:02.074138
server_sh_1  | 10 Fri May 26 19:15:03 UTC 2017
server_1     | 2017-05-26 19:15:03.075766
pythonnooutput_server_sh_1 exited with code 0
pythonnooutput_server_1 exited with code 0

As you can see, issue is fixed and the output now is non-buffered.

Home