Only one line of SimpleHTTPServer output does not appear while running container without '-it'

Question

Note: I am not trying to solve any problem in a real project here. This question is intended for merely understanding the reason behind the results I see in the 2nd experiment (Experiment 2) below.

These experiments were performed using Docker version 17.12.0-ce on macOS Terminal version 2.8 on macOS High Sierra 10.13.1.

Experiment 1: docker run SimpleHTTPServer with -it options

Here is my Dockerfile:

FROM python:2.7-slim
CMD ["python", "-m", "SimpleHTTPServer"]

I build it and run it with this command:

docker build -t pyhttp .
docker run -it -p 8000:8000 pyhttp

In another terminal, I test the container with this command:

curl http://localhost:8000/

The curl command produces expected results: a directory listing. In the terminal running docker run, I see this expected output.

$ docker run -it -p 8000:8000 pyhttp
Serving HTTP on 0.0.0.0 port 8000 ...
172.17.0.1 - - [04/Feb/2018 10:07:33] "GET / HTTP/1.1" 200 -

Finally, I stop this docker container by pressing Ctrl + C.

Experiment 2: docker run SimpleHTTPServer without -it options

Now I run the same pyhttp image with this command:

docker run -p 8000:8000 pyhttp

No output appears on the terminal even though the container is running. I don't see the expected Serving HTTP on 0.0.0.0 port 8000 ... message.

Although if I test the container with curl http://localhost:8000/, I see the log for the GET request appearing in the terminal running docker run.

$ docker run -p 8000:8000 pyhttp
172.17.0.1 - - [04/Feb/2018 10:12:41] "GET / HTTP/1.1" 200 -

Question: Why is it that the initial Serving HTTP on 0.0.0.0 port 8000 ... message does not appear but the subsequent logs for HTTP requests appear?

Experiment 3: docker run Flask app without -it options

I build it and run it with this command:

docker build -t flaskapp .
docker run -p 8000:8000 flaskapp

In another terminal, I test the container with this command:

curl http://localhost:8000/

In the terminal running docker run, I see this expected output.

$ docker run -p 8000:8000 flaskapp
 * Running on http://0.0.0.0:8000/ (Press CTRL+C to quit)
172.17.0.1 - - [04/Feb/2018 10:22:28] "GET / HTTP/1.1" 200 -

Question: Why only in Experiment 2, the Serving HTTP on 0.0.0.0 port 8000 ... message did not appear?

Hypothesis

I thing this depends on how server write those logs. – Archivist

@aerokite Can you elaborate on what aspect or mechanism of writing logs does it depend on? What could the server possibly do which would result in the logs not appearing when the container is run without the -it option? Also, why would the other logs by the server appear in the same container? – Hypothesis

@LoneLearner, Can you check if you are facing the issue described here tarunlalwani.com/post/why-delayed-output-python-docker? – Headed

@TarunLalwani It looks I am facing the same issue. Athough python --help says -u: unbuffered binary stdout and stderr, I see this issue occurs only for stdout (the Serving HTTP on 0.0.0.0 port 8000 ... message) and not for stderr (the GET request logs). And indeed, modifying the CMD instruction in Dockerfile to CMD ["python", "-u", "-m", "SimpleHTTPServer"] resolves this issue. – Hypothesis

Answer 1

The first line of output from python -m SimpleHTTPServer is getting printed to stdout; the remaining lines are printed to stderr. Consider the difference between these invocations:

njv@organon:~/tmp$ python -m SimpleHTTPServer
Serving HTTP on 0.0.0.0 port 8000 ...
172.17.2.26 - - [06/Feb/2018 20:55:52] "GET / HTTP/1.1" 200 -

njv@organon:~/tmp$ python -m SimpleHTTPServer  > /dev/null
172.17.2.26 - - [06/Feb/2018 20:56:26] "GET / HTTP/1.1" 200 -

The second doesn't show the "Serving" line because stdout is discarded, but both show the log lines because stderr is not. Flask, on the other hand, writes its "starting" log to stderr (as well as further log lines):

njv@organon:~/tmp$ python flaskapp.py > /dev/null
* Running on http://127.0.0.1:5000/ (Press CTRL+C to quit)
127.0.0.1 - - [06/Feb/2018 20:58:10] "GET / HTTP/1.1" 200 -

(edited from here) What's happening with your docker invocation of python is that without the -t option, stdout is fully buffered, and with the -t option, it's line-buffered, so it appears immediately after every newline.

$ docker help run|grep -- ' -t'
  -t, --tty                            Allocate a pseudo-TTY

I'm still looking for a definitive source on this (this article looks promising), but it appears that when sys.stdout.isatty() is True, python opens stdout in line-buffered mode, so each line is shown as it's printed, but when it's not, it opens in fully buffered mode, and so output is only printed when the buffer is full.

Boniface