Why print doesn't work correctly with async generator?

Question

I tried to print the values ​​using print, but it works only after a complete exhaustion of the asynchronous generator

import asyncio
import logging

logging.basicConfig(
    format='[%(asctime)s]\t%(levelname)s\t%(filename)s:%(lineno)d\t%(message)s',
    level=logging.INFO
)


async def range_stream(length, interval=1):
    for i in range(length):
        yield i
        await asyncio.sleep(interval)


async def infinite_stream(interval=1):
    i = 0
    while True:
        yield i
        await asyncio.sleep(interval)
        i += 1


async def main():
    logging.info('Start range stream')
    async for i in range_stream(5):
        logging.info(i)
        print(i)

    # logging.info('Start infinite stream')
    # async for i in infinite_stream():
    #     logging.info(i)
    #     print(i)

loop = asyncio.get_event_loop()
loop.run_until_complete(main())

I received the following output:

[2019-03-09 09:41:11,271]       INFO    tmp.py:25       Start range stream
[2019-03-09 09:41:11,271]       INFO    tmp.py:27       0
[2019-03-09 09:41:12,273]       INFO    tmp.py:27       1
[2019-03-09 09:41:13,275]       INFO    tmp.py:27       2
[2019-03-09 09:41:14,277]       INFO    tmp.py:27       3
[2019-03-09 09:41:15,279]       INFO    tmp.py:27       4
0                                                                                           
1                                              
2                                   
3                 
4

The first print worked only after the last logger.info.

If you add infinity async generator then print will not be executed at all:

[2019-03-09 10:04:21,113]       INFO    tmp.py:25       Start range stream
[2019-03-09 10:04:21,113]       INFO    tmp.py:27       0
[2019-03-09 10:04:22,114]       INFO    tmp.py:27       1
[2019-03-09 10:04:23,117]       INFO    tmp.py:27       2
[2019-03-09 10:04:24,118]       INFO    tmp.py:27       3
[2019-03-09 10:04:25,120]       INFO    tmp.py:27       4
[2019-03-09 10:04:26,121]       INFO    tmp.py:30       Start infinite stream
[2019-03-09 10:04:26,122]       INFO    tmp.py:32       0
[2019-03-09 10:04:27,123]       INFO    tmp.py:32       1
[2019-03-09 10:04:28,125]       INFO    tmp.py:32       2
[2019-03-09 10:04:29,126]       INFO    tmp.py:32       3
[2019-03-09 10:04:30,128]       INFO    tmp.py:32       4
[2019-03-09 10:04:31,130]       INFO    tmp.py:32       5
[2019-03-09 10:04:32,133]       INFO    tmp.py:32       6
[2019-03-09 10:04:33,134]       INFO    tmp.py:32       7
[2019-03-09 10:04:34,136]       INFO    tmp.py:32       8
...

Why it happens? What is the fundamental difference between working with stdout in the print function and in the logging module? Is this bug?

UPD: Thank you user4815162342 for the idea - this behavior is reproduced only in the case of the docker environment, and then only if you do not specify -it flag on docker run command and use default stream for logging (stderr) and print (stdout). So maybe this is quite normal behavior.

Answer 1

I cannot reproduce the behavior by running your program - for me, the number-only lines produced by print are mixed with log lines. If the program is being run in an environment that redirects its output to a pipe, you will need to explicitly flush lines to have them appear immediately:

print(..., flush=True)