python - 记录标准输出，但在每个条目上得到第二个空行

Question

我在 Linux Ubuntu 12.04 系统上。我一直在使用此代码将所有 stdout 和 stderr + INFO 级别的附加日志记录到文件中..

class LogFile(object):
    def __init__(self, name=None):
        self.logger = logging.getLogger(name)

    def write(self, msg, level=logging.INFO):
        self.logger.log(level, msg)

    def flush(self):
        for handler in self.logger.handlers:
            handler.flush()

logging.basicConfig(level=logging.INFO, 
                    format='%(asctime)s %(name)-12s %(levelname)-8s %(message)s',
                    datefmt='%m-%d-%y %H:%M:%S',
                    filename='logging.log')
sys.stdout = LogFile('stdout')
sys.stderr = LogFile('stderr')

出于某种原因，每当我得到一个条目时，它后面总是跟着一个空行，这是我的日志的一个小输出:

08-09-12 09:52:54 stdout       INFO     CheckCon: Checking Portal access.
08-09-12 09:52:54 stdout       INFO     

08-09-12 09:52:54 stdout       INFO     CheckCon: Portal ping successful.
08-09-12 09:52:54 stdout       INFO     

08-09-12 09:53:08 stderr       INFO     Bottle server starting up (using PasteServer())...

08-09-12 09:53:08 stderr       INFO     Listening on http://0.0.0.0:8654/

08-09-12 09:53:08 stderr       INFO     Hit Ctrl-C to quit.


08-09-12 09:53:08 stdout       INFO     URI: Generated https://*****
08-09-12 09:53:08 stdout       INFO     

08-09-12 09:53:08 stdout       INFO     CheckCon: Checking Portal access.
08-09-12 09:53:08 stdout       INFO     

08-09-12 09:53:08 stdout       INFO     serving on 0.0.0.0:8654 view at http://127.0.0.1:8654
08-09-12 09:53:08 stdout       INFO     

08-09-12 09:53:08 stdout       INFO     CheckCon: Google ping successful.
08-09-12 09:53:08 stdout       INFO     

这是它在文件中的样子，有一个空的 stdout 行，然后是一个完整的空行。如果您注意到 bottle 服务器的输出似乎没有空行，但每行之间仍然有一个空行。

有人知道是什么原因造成的，或者我该如何预防？

编辑:

根据建议，我已将所有打印更改为 logging.info，我仍然遇到瓶和粘贴服务器正在执行常规打印的问题:\

所以我的日志现在修改了格式 format='%(asctime)s %(levelname)-4s: %(message)s':

08-09-12 12:44:40 INFO: URI: Generated https://****
08-09-12 12:44:40 INFO: CheckCon: Checking Portal access.
08-09-12 12:44:40 INFO: serving on 0.0.0.0:9002 view at http://127.0.0.1:9002
08-09-12 12:44:40 INFO: 

08-09-12 12:44:40 INFO: CheckCon: Google ping successful.
08-09-12 12:44:40 INFO: FullW: opening url: ****
08-09-12 12:44:40 INFO: FullW: showing.
08-09-12 12:44:40 INFO: LOOP: starting.

据我所见，额外的空行也是因为空信息行，所以现在越来越近了..

编辑以澄清输出:有趣的一点:

+++08-09-12 13:01:04 stdout       INFO     serving on 0.0.0.0:9002 view at     http://127.0.0.1:9002+++
+++08-09-12 13:01:04 stdout       INFO     
+++

最终编辑:

更改了我的写入以检查消息的长度是否小于 2 个字符，并消除了空行。但仍然不能 100% 确定原因。

def write(self, msg, level=logging.INFO):
    if len(msg) < 2:
        pass
    else:
        self.logger.log(level, msg)

Answer 1

这是由于 print 的工作方式所致。

我已经修改了您的示例，以便在 write() 方法中有一个 print (level, msg)。

它向我展示了以下内容:

>>> x=LogFile("foo")
>>> print >>x, "123\n321\n444", "321", "222",
(20, '123\n321\n444')
(20, ' ')
(20, '321')
(20, ' ')
(20, '222')
>>> print >>x, "123\n321\n444", "321", "222"
(20, ' ')
(20, '123\n321\n444')
(20, ' ')
(20, '321')
(20, ' ')
(20, '222')
(20, '\n')

如果每个调用都被转移到一个 logger 调用中，您将获得每个调用的条目。

为了解决这个问题，您可以实现一种缓冲，它只在完整行和关闭时调用 logger.log()。