子进程 stdout readline 挂起以进行特殊命令调用

subprocess stdout readline hang for special command call

我有一个二进制文件,它将在那里等待外部触发:

# ./a2dp_sink_demo
Packet Log: /tmp/hci_dump.pklg
No audio playback.
Audio will be stored to 'av2dp_sink_demo.wav' file.
Starting BTstack ...

我使用下一个 python 脚本来调用它,并得到这个二进制文件的输出,我确认日志转到标准输出,而不是标准错误 ./a2dp_sink_demo > log.txt:

test.py:

import subprocess

# demo_full_path = "ping -c 4 127.0.0.1"
demo_full_path = "./a2dp_sink_demo"
proc = subprocess.Popen(demo_full_path, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, shell=True, bufsize=0)
while proc.poll() is None:
    print("start")
    line = proc.stdout.readline()
    print("output is %s " % line)
proc.kill()

接下来是 运行 日志,它只是挂在 readline,永远不会继续。另外,如果用ps aux | grep a2dp查,子流程是运行:

# python test.py
start

问题:为什么proc.stdout.readline()无法获取该二进制文件的日志?

但是,如果我注释demo_full_path = "./a2dp_sink_demo"并取消注释demo_full_path = "ping 127.0.0.1",它将运行为下一个:

start
output is b'PING 127.0.0.1 (127.0.0.1) 56(84) bytes of data.\n'
start
output is b'64 bytes from 127.0.0.1: icmp_seq=1 ttl=64 time=0.016 ms\n'
start
output is b'64 bytes from 127.0.0.1: icmp_seq=2 ttl=64 time=0.050 ms\n'
start
output is b'64 bytes from 127.0.0.1: icmp_seq=3 ttl=64 time=0.046 ms\n'
start
output is b'64 bytes from 127.0.0.1: icmp_seq=4 ttl=64 time=0.047 ms\n'
start
output is b'\n'
start
output is b'--- 127.0.0.1 ping statistics ---\n'
start
output is b'4 packets transmitted, 4 received, 0% packet loss, time 76ms\n'

这里有什么奇怪的?

你可以看到相同的代码:调用子进程 ping 可以,但是 a2dp_sink_demo 不行。

a2dp_sink_demo来自一个开源项目,source here

如何重现?

为了给你一个可以重现我的问题的环境,我在 docker 集线器上创建了一个 docker 图像,包括二进制文件 a2dp_sink_demo,你可以使用 next 来重现我的问题:

$ docker run --rm -it atline/abc:1 /bin/bash
root@8c7a267930d3:/tmp# python --version
Python 3.9.1
root@8c7a267930d3:/tmp# ls
a2dp_sink_demo  test.py
root@8c7a267930d3:/tmp# python test.py
start
Traceback (most recent call last):
  File "/tmp/test.py", line 9, in <module>
    line = proc.stdout.readline()
KeyboardInterrupt

对于 python 代码中可能的原因和可能的修复有什么特别的想法吗?谢谢!

我自己找到了答案:看起来这个二进制文件的输出是完全缓冲的。因此,将输出更改为使用 stdbuf 缓冲的行让我解决了这个问题:

NAME

stdbuf - Run COMMAND, with modified buffering operations for its standard streams.

-o, --output=MODE
    adjust standard output stream buffering

If MODE is 'L' the corresponding stream will be line buffered.

test.py:

import subprocess
import os
import signal

demo_full_path = "stdbuf -oL ./a2dp_sink_demo"
proc = subprocess.Popen(
    demo_full_path,
    stdin=subprocess.PIPE,
    stdout=subprocess.PIPE,
    shell=True,
    preexec_fn=os.setsid,
)
while proc.poll() is None:
    line = proc.stdout.readline().decode()
    print("output is: %s " % line)
    if line.find("Starting BTstack") >= 0:
        break

os.killpg(os.getpgid(proc.pid), signal.SIGTERM)

执行:

root@cdd1898ee06a:/tmp# python3 test.py
output is: Packet Log: /tmp/hci_dump.pklg

output is: No audio playback.
 tcsetattr(): Inappropriate ioctl for device
tcsetattr ICANON: Inappropriate ioctl for device

output is: Audio will be stored to 'av2dp_sink_demo.wav' file.

output is: Starting BTstack ...