[FIXED] docker compose asyncio.sleep block statements before

Issue

I've been beating myself to solve this problem that seems very weird. Consider this python code:

import asyncio

async def main():
    print("hello")
    await asyncio.sleep(10)
    print("world")

asyncio.run(main())

I'd like to run this as a docker compose service, so here's my Dockerfile.

FROM python:3.12-slim

WORKDIR /app
COPY ./main.py /app

CMD ["python", "main.py"]

and docker-compose.yaml is simply:

version: "3.9"
services: 
  dnsgen:
    build: ./dnsgen

Now here's the issue if I run docker compose up dnsgen --build --timestamps the prints happen simultaneously after waiting 10 seconds:

dnsgen-1  | 2024-02-04T01:16:25.341721172+01:00hello
dnsgen-1  | 2024-02-04T01:16:25.341784837+01:00world

This doesn't happen of course if I run python main.py on my machine or even when I run docker compose run dnsgen. I invite you to try this out and see if this problem persists, and please let me know what I'm doing wrong?

Solution

I don't think you're doing anything wrong.

I suspect that this is simply a buffering issue: printed output doesn't show up in the logs until (a) the output buffer is full or (b) the program exits. The timestamps you see don't have anything to do with when the print statement was executed; they represent when the output was delivered to the output logging mechanism.

You can verify this by using unbuffered output -- either by printing to stderr instead of stdout (stderr is unbuffered by default), or by running Python with the -u option. E.g., if we write the Dockerfile like this:

FROM python:3.12-slim

WORKDIR /app
COPY ./main.py /app

CMD ["python", "-u", "main.py"]

Then we see:

Attaching to dnsgen-1
dnsgen-1  | 2024-02-03T19:48:07.972264989-05:00hello
dnsgen-1  | 2024-02-03T19:48:17.985659019-05:00world
dnsgen-1 exited with code 0

Answered By - larsks