为什么使用异步生成器时打印输出不正确？

Question

我尝试使用print打印这些值，但只有在异步生成器完全耗尽之后才能正常工作。

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())

我收到了以下输出：

[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

第一个打印语句只有在最后一个logger.info之后才能执行成功。

如果添加无限的异步生成器，那么打印语句将完全不会被执行：

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

为什么会出现这种情况？在print函数和logging模块中使用stdout的根本区别是什么？这个问题是否是个bug？

更新：感谢user4815162342的建议 - 只有在docker环境下才能复现这种行为，而且只有在docker run命令中没有指定-it标志并且使用默认的日志流(stderr)和打印(stdout)时才会出现。因此，这可能是正常的行为。

- Daniil Stepanenko

---

正在缓冲。在 print 中使用 flush=True 可能会解决此问题。 - Artemij Rodionov

我无法通过运行您的程序来重现这种行为 - 对我来说，print 产生的仅包含数字的行与日志行混合在一起。您是从某个 IDE 运行程序吗？ - user4815162342

无法重现。请尝试在控制台中运行您的代码。如果问题仍然存在，请添加有关您的环境信息。 - Mikhail Gerasimov

Answer 1

我无法通过运行您的程序重现这种行为 - 对于我来说，print产生的仅数字行与日志行混合在一起。 如果程序在将其输出重定向到管道的环境中运行，则需要显式刷新行才能立即出现：

print(..., flush=True)

- user4815162342