Python 日志记录：以 'w' 模式时 FileHandler 不起作用，但以 'a' 模式可以正常工作

Question

在Windows下的Python 2.7.5中，当FileHandler处于'w'模式（在写入之前截断文件）时，处理器不仅会写入最后一行。而当处于'a'模式时则一切正常。

我的logging.conf文件：

[loggers]
keys=root

[handlers]
keys=consoleHandler,fileHandler

[formatters]
keys=simpleFormatter

[logger_root]
level=NOTSET
handlers=fileHandler

[handler_consoleHandler]
class=StreamHandler
level=DEBUG
formatter=simpleFormatter
args=(sys.stdout,)

[handler_fileHandler]
class=FileHandler
level=DEBUG
formatter=simpleFormatter
args=('generator.log', 'a', 'utf8', 0)

[formatter_simpleFormatter]
format=[ %(asctime)s ] [ %(name)s ] [ %(levelname)-5s ] - %(message)s
datefmt=

我的 oracle.py 文件：

__author__ = 'wbar'
import cx_Oracle
from contextlib import closing
import logging


class Connector(object):
    __connection__ = None
    __user_name__ = None
    __password__ = None
    __tns_name__ = None
    __logger__ = None

    def get_connection(self, auto_connect=True):
        if auto_connect and not self.__connection__:
            self.__logger__.info(u'Connecting into Oracle: %s@%s', self.__user_name__, self.__tns_name__)
            self.__connection__ = cx_Oracle.connect(
                u'%s/%s@%s' % (self.__user_name__, self.__password__, self.__tns_name__))
        return self.__connection__

    def __init__(self, user_name, password, tns_name):
        self.__user_name__ = user_name
        self.__password__ = password
        self.__tns_name__ = tns_name
        self.__logger__ = logging.getLogger('OracleConnector')
        self.__logger__.addHandler(logging.NullHandler())

    def __del__(self):
        self.close_connection()

    def close_connection(self):
        connection = self.get_connection(auto_connect=False)
        if connection:
            self.__logger__.info(u'Closing connection with Oracle: %s@%s', self.__user_name__, self.__tns_name__)
            connection.close()

    def execute(self, sql):
        with closing(self.get_connection().cursor()) as cursor:
            self.__logger__.debug(u'Executing: %s', sql)
            cursor.execute(sql)
            return cursor.fetchall()

最后，我的主文件generator.py如下：

__author__ = 'wbar'
import logging
import logging.config

logging.FileHandler
logging.config.fileConfig('logging.conf')

from oracle import Connector as OracleConnector
DATABASE = OracleConnector(user_name=u'foo', password=u'bar', tns_name=u'db_local')

for line in DATABASE.execute('select * from dual'):
    print(line[0])

logger = logging.getLogger('root')

logger.debug('DEBUG')
logger.info('INFO')
logger.error('ERROR')

当模式为'a'时，日志文件的样式如下:

[ 2013-11-13 17:15:25,608 ] [ OracleConnector ] [ INFO  ] - Connecting into Oracle: pms_test@db_impaq_local
[ 2013-11-13 17:15:25,727 ] [ OracleConnector ] [ DEBUG ] - Executing: select * from dual
[ 2013-11-13 17:15:25,730 ] [ root ] [ DEBUG ] - DEBUG
[ 2013-11-13 17:15:25,730 ] [ root ] [ INFO  ] - INFO
[ 2013-11-13 17:15:25,730 ] [ root ] [ ERROR ] - ERROR
[ 2013-11-13 17:15:25,734 ] [ OracleConnector ] [ INFO  ] - Closing connection with Oracle: pms_test@db_impaq_local

当模式为'w'时，日志文件看起来像：

[ 2013-11-13 17:06:24,239 ] [ OracleConnector ] [ INFO  ] - Closing connection with Oracle: pms_test@db_impaq_local

- WBAR

---

抱歉，请问具体问题是什么？你首先说当 FileHandler 处于 'w' 模式（在写入之前截断文件）时，处理器不仅会写入最后一行，但随后向我们展示了仅有一行（最后一行）的日志。 - Martijn Pieters

@MartijnPieters 记录器每次写入条目时都会打开文件吗？创建 FileHandler 时它只会打开一次文件吗？ - WBAR

Answer 1

logging 模块注册了一个 atexit 关闭钩子 以关闭所有处理程序。这将在 Python 退出时关闭打开的 'w' 文件对象。

然而，你的 oracle.Connector() 类有一个 __del__ 方法，在 Python 退出时也会被调用。Python 在全局变量被清理之前调用 atexit，因此操作的确切顺序如下：

1. logging 的 atexit 钩子被调用，文件被关闭。
2. oracle.Connector().__del__() 被调用，它调用了 self.__logger__.info()。这将重新打开已关闭的文件处理程序进行日志记录，并截断文件。

为了防止这种情况的发生，在退出 Python 之前明确关闭连接器：

DATABASE.close_connection()

- Martijn Pieters

---

你能提供一种不使用__del__方法自动执行的解决方案来关闭这个连接吗？ - WBAR

@WBAR：在__del__钩子中关闭时不记录日志，或者只使用“a”追加模式。 - Martijn Pieters

我在close_connection中添加了asap参数 :) 谢谢！老兄！ - WBAR