【python】subprocess readline日志未完全输出的问题

前面有关于如何监听执行时间并实时输出日志的总结【python】subprocess获取子进程输出且设置执行超时，在使用时发现一个，子进程执行的最后几行数据未输出

一、现象

p.stdout.readline输出

直接执行日志打印

经过比对发现，后面7行数据未打印

二、问题定位

2.1 输出方式

由于使用的是subprocess.PIPE管道方式，怀疑是否与此有关
将subprocess.Popen中的参数设置修改为：

stdin=None
stdout=None
stderr=None

即没有任何重定向，继承父进程，但此方式修改后问题依旧存在

2.2 数据缓冲

由于仅仅是最后7行数据未输出，是否因为最后的数据在缓冲区导致
将subprocess.Popen中增加参数设置

bufsize=0

其中0为无缓冲，1为行缓冲，但是问题依旧

在读取数据前增加处理：

sys.stdout.flush()

同样无效

2.3 数据换行符

读取打印数据的方式为

line = p.stdout.readline()
Logger.logger.info(line.decode('utf-8'))

是否由于读取未遇到换行符导致数据未输出打印
使用完整读取方式：

p.stdout.read()

确实可以打印完整的数据，但此方式等完全执行后再输出结果，不符合需求

那是否与未包含换行符有关？

查看数据输出端的打印

log.info(xpath)
log.info("任务终止|用例执行失败")

正常的日志打印

后面发现其实与换行没有任何关系

2.4 单一变量

p.stdout.readline为阻塞性质的读取数据，为了排除干扰，仅仅是持续打印日志，发现竟然可以正确输出

去除其他的业务逻辑，逐个排查问题干扰项，发现问题竟然是因为time.sleep(1)

寻找原因但是并未发现其中的关联项

三、问题解决

既然time.sleep(1) 影响导致，那么需要不能使用根据时钟计数的方式判断是否在预设时间内没有输出则终止服务

其实原先的设置中并未达到这样的效果，原因在于p.stdout.readline是阻塞性的，即未读取到数据时一直阻塞等待，则并能计数等待时间

既然不能使用计数的方式，则通过计算时间差的方式，那怎么解决阻塞的问题呢？

poll_obj = select.poll()
poll_obj.register(p.stdout, select.POLLIN)

# 预判断数据流
poll_result = poll_obj.poll(0)
if poll_result:
    last_line_received = time.time()
    line = p.stdout.readline()
    line = line.strip()
	# TODO

四、完整实现

import os
import time
import datetime
import signal
import subprocess
import platform
import select

def run_cmd(cmd_string, timeout=10):
    Logger.logger.info("命令为：" + cmd_string)
    start = datetime.datetime.now()
    p = subprocess.Popen(cmd_string, stderr=subprocess.STDOUT, stdout=subprocess.PIPE, shell=True, close_fds=True,
                         start_new_session=True)
    poll_obj = select.poll()
    poll_obj.register(p.stdout, select.POLLIN)
    formats = 'gbk' if platform.system() == "Windows" else 'utf-8'
    # 初始化继续flag
    continue_flag = True
    # 初始化执行状态
    code = 2
    # 初始化执行结果信息
    msg = "[SUCCESS]执行成功！！！"
    try:
        last_line_received = time.time()
        while p.poll() is None and continue_flag:
            poll_result = poll_obj.poll(0)
            if poll_result:
                last_line_received = time.time()
                line = p.stdout.readline()
                line = line.strip()
                if line:
                    Logger.logger.info(line.decode(formats))
            if (datetime.datetime.now() - start).seconds > timeout:
                continue_flag = False
                code = 4
                msg = "[FAIL]执行时长：{}s超时".format(timeout)
                _kill_thread(p)
            elif time.time()-last_line_received > no_content_time_limit:
                continue_flag = False
                code = 4
                msg = "[FAIL]执行日志持续没有输出时长：{}秒".format(no_content_time_limit)
                _kill_thread(p)
        if continue_flag:
            if p.returncode:
                code = 4
                msg = "[FAIL]p.returncode为1，执行异常终止，需要确认异常原因"
                _kill_thread(p)
    except subprocess.TimeoutExpired:
        _kill_thread(p)
        code = 4
        msg = "[FAIL]Timeout Error : Command '" + cmd_string + "' timed out after " + str(timeout) + " seconds"
    except Exception as e:
        _kill_thread(p)
        code = 4
        msg = "[FAIL]Unknown Error : " + str(e)
    Logger.logger.info("执行完成!!!")
    Logger.logger.info("执行状态码：{}".format(code))
    Logger.logger.info("执行结果信息：{}".format(msg))
    return code,msg