openstack 早期版本（非oslo.log）log输出过程浅析

本文以nova f版为例，浅析openstack log模块的启动及配置过程。

在nova-api的启动模块中，可以看到类似如下代码：

from nova.openstack.common import log as logginglogging.setup("nova")

此为入口函数，我们看一下函数代码：

def setup(product_name):    """Setup logging."""    sys.excepthook = _create_logging_excepthook(product_name)    if CONF.log_config:        try:            logging.config.fileConfig(CONF.log_config)        except Exception:            traceback.print_exc()            raise    else:        _setup_logging_from_conf(product_name)

其中sys.excepthook = _create_logging_excepthook(product_name)创建了一个critical钩子callback函数，具体作用在用到时我们进行了解。
先继续往下看在默认情况下所调用的_setup_logging_from_conf(product_name):

def _setup_logging_from_conf(product_name):    log_root = getLogger(product_name).logger    for handler in log_root.handlers:        log_root.removeHandler(handler)    if CONF.use_syslog:        facility = _find_facility_from_conf()        syslog = logging.handlers.SysLogHandler(address='/dev/log',                                                facility=facility)        log_root.addHandler(syslog)    logpath = _get_log_file_path()    if logpath:        filelog = logging.handlers.WatchedFileHandler(logpath)        log_root.addHandler(filelog)        mode = int(CONF.logfile_mode, 8)        st = os.stat(logpath)        if st.st_mode != (stat.S_IFREG | mode):            os.chmod(logpath, mode)    if CONF.use_stderr:        streamlog = ColorHandler()        log_root.addHandler(streamlog)    elif not CONF.log_file:        # pass sys.stdout as a positional argument        # python2.6 calls the argument strm, in 2.7 it's stream        streamlog = logging.StreamHandler(sys.stdout)        log_root.addHandler(streamlog)    if CONF.publish_errors:        log_root.addHandler(PublishErrorsHandler(logging.ERROR))    for handler in log_root.handlers:        datefmt = CONF.log_date_format        if CONF.log_format:            handler.setFormatter(logging.Formatter(fmt=CONF.log_format,                                                   datefmt=datefmt))        handler.setFormatter(LegacyFormatter(datefmt=datefmt))    if CONF.verbose or CONF.debug:        log_root.setLevel(logging.DEBUG)    else:        log_root.setLevel(logging.INFO)    level = logging.NOTSET    for pair in CONF.default_log_levels:        mod, _sep, level_name = pair.partition('=')        level = logging.getLevelName(level_name)        logger = logging.getLogger(mod)        logger.setLevel(level)        for handler in log_root.handlers:            logger.addHandler(handler)

首先，log_root = getLogger(product_name).logger中的getLogger(product_name)生成了一个ContextAdapter类实例，这个类继承自python内建logging库的LoggerAdapter类，其logger属性生成了logging库中一个name=’nova’的Logger object。继续：

    for handler in log_root.handlers:        log_root.removeHandler(handler)

此段代码逻辑重置了logger的handlers，具体作用之后讲解。继续：

    if CONF.use_syslog:        facility = _find_facility_from_conf()        syslog = logging.handlers.SysLogHandler(address='/dev/log',                                                facility=facility)        log_root.addHandler(syslog)

如果使用了syslog协议，增加将logger记录的log发送至指定syslog目的地址的handler。相当简单不再解析。继续：

    logpath = _get_log_file_path()    if logpath:        filelog = logging.handlers.WatchedFileHandler(logpath)        log_root.addHandler(filelog)        mode = int(CONF.logfile_mode, 8)        st = os.stat(logpath)        if st.st_mode != (stat.S_IFREG | mode):            os.chmod(logpath, mode)

此段代码获取了logfile路径，增加了一个WatchedFileHandler的实例作为handler，作用是监测logfile的日志流。如果发生了logrotate之类操作，可以从旧file优雅过度到新的file中。并且按照logfile_mode设置的文件权限对logfile进行权限设置。继续：

    if CONF.use_stderr:        streamlog = ColorHandler()        log_root.addHandler(streamlog)

如果使用标准错误输出，为其不同级别告警分配不同颜色。继续：

    elif not CONF.log_file:        # pass sys.stdout as a positional argument        # python2.6 calls the argument strm, in 2.7 it's stream        streamlog = logging.StreamHandler(sys.stdout)        log_root.addHandler(streamlog)

如果没有指定logfile，把标准输出当做参数生成stream handler，加入logger中。继续：

    if CONF.publish_errors:        log_root.addHandler(PublishErrorsHandler(logging.ERROR))

notification推送error级别日志的开关。如果开启，则使用notifier发布ERROR级别的告警给接受者。继续：

    for handler in log_root.handlers:        datefmt = CONF.log_date_format        if CONF.log_format:            handler.setFormatter(logging.Formatter(fmt=CONF.log_format,                                                   datefmt=datefmt))        handler.setFormatter(LegacyFormatter(datefmt=datefmt))

此段代码为上面所有handler添加了对应的formatter，用于将handler发布的log以对应格式展现。具体可以查看logging库formatter介绍，在此不再一一具体分析，最后会找例子来看这个函数的意义。往下：

    if CONF.verbose or CONF.debug:        log_root.setLevel(logging.DEBUG)    else:        log_root.setLevel(logging.INFO)

开关控制nova logger的级别，默认情况为INFO级别，level值为20。继续：

    for pair in CONF.default_log_levels:        mod, _sep, level_name = pair.partition('=')        level = logging.getLevelName(level_name)        logger = logging.getLogger(mod)        logger.setLevel(level)        for handler in log_root.handlers:            logger.addHandler(handler)

把default_log_levels里标注的模块与级别分别设定成对应的logger，并且使用nova的handler标准对各模块生成handler。到此_setup_logging_from_conf方法结束。

下面我们从实际例子出发来解析如何将ERROR级别日志输出到文本中。

在nova的模块中，经常可以看到如下打印error级别日志的方法：

LOG = logging.getLogger(__name__)msg = _("xxxxx") % xxxxxLOG.error(msg)

我们知道以上代码中LOG指向logging库中ContextAdapter的实例，其error方法继承自父类LoggerAdapter：

    def error(self, msg, *args, **kwargs):        """        Delegate an error call to the underlying logger, after adding        contextual information from this adapter instance.        """        msg, kwargs = self.process(msg, kwargs)        self.logger.error(msg, *args, **kwargs)

而self.logger指向以模块的__name__为name参数的logging.Logger类实例，看它的error方法：

    def error(self, msg, *args, **kwargs):        """        Log 'msg % args' with severity 'ERROR'.        To pass exception information, use the keyword argument exc_info with        a true value, e.g.        logger.error("Houston, we have a %s", "major problem", exc_info=1)        """        if self.isEnabledFor(ERROR):            self._log(ERROR, msg, args, **kwargs)    def isEnabledFor(self, level):        """        Is this logger enabled for level 'level'?        """        if self.manager.disable >= level:            return 0        return level >= self.getEffectiveLevel()

首先判断了是否此logger可以记录ERROR级别日志，由于默认info为20，error为40，故会对ERROR进行记录：

    def _log(self, level, msg, args, exc_info=None, extra=None):        """        Low-level logging routine which creates a LogRecord and then calls        all the handlers of this logger to handle the record.        """        if _srcfile:            #IronPython doesn't track Python frames, so findCaller raises an            #exception on some versions of IronPython. We trap it here so that            #IronPython can use logging.            try:                fn, lno, func = self.findCaller()            except ValueError:                fn, lno, func = "(unknown file)", 0, "(unknown function)"        else:            fn, lno, func = "(unknown file)", 0, "(unknown function)"        if exc_info:            if not isinstance(exc_info, tuple):                exc_info = sys.exc_info()        record = self.makeRecord(self.name, level, fn, lno, msg, args, exc_info, func, extra)        self.handle(record)

其中fn, lno, func分别代表调用log记录时的文件名、行数、函数。record = self.makeRecord()返回了一个LogRecord实例，其初始化时将传入的参数进行处理赋值成了实例参数，并且如果有extra存在时以dict存储相关信息。

    def makeRecord(self, name, level, fn, lno, msg, args, exc_info, func=None, extra=None):        """        A factory method which can be overridden in subclasses to create        specialized LogRecords.        """        rv = LogRecord(name, level, fn, lno, msg, args, exc_info, func)        if extra is not None:            for key in extra:                if (key in ["message", "asctime"]) or (key in rv.__dict__):                    raise KeyError("Attempt to overwrite %r in LogRecord" % key)                rv.__dict__[key] = extra[key]        return rv

其余具体可看LogRecord类代码，不再具体说明。self.handle(record)调用了self.callHandlers(record):

    def callHandlers(self, record):        """        Pass a record to all relevant handlers.        Loop through all handlers for this logger and its parents in the        logger hierarchy. If no handler was found, output a one-off error        message to sys.stderr. Stop searching up the hierarchy whenever a        logger with the "propagate" attribute set to zero is found - that        will be the last logger whose handlers are called.        """        c = self        found = 0        while c:            for hdlr in c.handlers:                found = found + 1                if record.levelno >= hdlr.level:                    hdlr.handle(record)            if not c.propagate:                c = None    #break out            else:                c = c.parent        if (found == 0) and raiseExceptions and not self.manager.emittedNoHandlerWarning:            sys.stderr.write("No handlers could be found for logger"                             " \"%s\"\n" % self.name)            self.manager.emittedNoHandlerWarning = 1

在之前的方法logging.getLogger(name)中，对各个模块的logger进行了parent关系梳理。引用官方文档说明：

The name is potentially a period-separated hierarchical value, like foo.bar.baz (though it could also be just plain foo, for example). Loggers that are further down in the hierarchical list are children of loggers higher up in the list. For example, given a logger with a name of foo, loggers with names of foo.bar, foo.bar.baz, and foo.bam are all descendants of foo.

所以，以上函数其实是对目前的logger以及其父logger的所有相关handler，调用了handle(record)方法。而在此方法中，其实调用的是Handler类中的emit(record)方法。我们挑选最开始时的streamlog = logging.StreamHandler(sys.stdout)这个handler，看一下它所提供的emit：

    def emit(self, record):        """        Emit a record.        If a formatter is specified, it is used to format the record.        The record is then written to the stream with a trailing newline.  If        exception information is present, it is formatted using        traceback.print_exception and appended to the stream.  If the stream        has an 'encoding' attribute, it is used to determine how to do the        output to the stream.        """        try:            msg = self.format(record)            stream = self.stream            fs = "%s\n"            if not _unicode: #if no unicode support...                stream.write(fs % msg)            else:                try:                    if (isinstance(msg, unicode) and                        getattr(stream, 'encoding', None)):                        ufs = u'%s\n'                        try:                            stream.write(ufs % msg)                        except UnicodeEncodeError:                            #Printing to terminals sometimes fails. For example,                            #with an encoding of 'cp1251', the above write will                            #work if written to a stream opened or wrapped by                            #the codecs module, but fail when writing to a                            #terminal even when the codepage is set to cp1251.                            #An extra encoding step seems to be needed.                            stream.write((ufs % msg).encode(stream.encoding))                    else:                        stream.write(fs % msg)                except UnicodeError:                    stream.write(fs % msg.encode("UTF-8"))            self.flush()        except (KeyboardInterrupt, SystemExit):            raise        except:            self.handleError(record)

其中self.format(record)在之前的代码中可知，调用了nova.openstack.common.log.LegacyFormatter的format()：

    def format(self, record):        """Uses contextstring if request_id is set, otherwise default."""        # NOTE(sdague): default the fancier formating params        # to an empty string so we don't throw an exception if        # they get used        for key in ('instance', 'color'):            if key not in record.__dict__:                record.__dict__[key] = ''        if record.__dict__.get('request_id', None):            self._fmt = CONF.logging_context_format_string        else:            self._fmt = CONF.logging_default_format_string        if (record.levelno == logging.DEBUG and            CONF.logging_debug_format_suffix):            self._fmt += " " + CONF.logging_debug_format_suffix        # Cache this on the record, Logger will respect our formated copy        if record.exc_info:            record.exc_text = self.formatException(record.exc_info, record)        return logging.Formatter.format(self, record)

其中对含有request_id、级别为DEBUG、有exc_info的record设置了专有的_fmt格式及Exception格式，最后调用了父类的format()：

    def format(self, record):        """        Format the specified record as text.        The record's attribute dictionary is used as the operand to a        string formatting operation which yields the returned string.        Before formatting the dictionary, a couple of preparatory steps        are carried out. The message attribute of the record is computed        using LogRecord.getMessage(). If the formatting string uses the        time (as determined by a call to usesTime(), formatTime() is        called to format the event time. If there is exception information,        it is formatted using formatException() and appended to the message.        """        record.message = record.getMessage()        if self.usesTime():            record.asctime = self.formatTime(record, self.datefmt)        s = self._fmt % record.__dict__        if record.exc_info:            # Cache the traceback text to avoid converting it multiple times            # (it's constant anyway)            if not record.exc_text:                record.exc_text = self.formatException(record.exc_info)        if record.exc_text:            if s[-1:] != "\n":                s = s + "\n"            try:                s = s + record.exc_text            except UnicodeError:                # Sometimes filenames have non-ASCII chars, which can lead                # to errors when s is Unicode and record.exc_text is str                # See issue 8924.                # We also use replace for when there are multiple                # encodings, e.g. UTF-8 for the filesystem and latin-1                # for a script. See issue 13232.                s = s + record.exc_text.decode(sys.getfilesystemencoding(),                                               'replace')        return s

首先，record.message = record.getMessage()会用传入record的msg和args（如果有的话）合并出message并设定为record的message属性。然后用之前指定的_fmt格式和record.__dict__包含的参数组合出一条log中具体的信息，然后把出错信息按照指定格式添加到上述信息之后，最后返回message。

再次回到emit方法中，剩下的逻辑比较简单，将已经生成的最终的message，断行，并且做编码转换。

附：下面再看一下之前filelog = logging.handlers.WatchedFileHandler(logpath)这个handler中的emit是如何进行的（写入日志文件的默认handler）：

    def emit(self, record):        """        Emit a record.        First check if the underlying file has changed, and if it        has, close the old stream and reopen the file to get the        current stream.        """        # Reduce the chance of race conditions by stat'ing by path only        # once and then fstat'ing our new fd if we opened a new log stream.        # See issue #14632: Thanks to John Mulligan for the problem report        # and patch.        try:            # stat the file by path, checking for existence            sres = os.stat(self.baseFilename)        except OSError as err:            if err.errno == errno.ENOENT:                sres = None            else:                raise        # compare file system stat with that of our stream file handle        if not sres or sres[ST_DEV] != self.dev or sres[ST_INO] != self.ino:            if self.stream is not None:                # we have an open file handle, clean it up                self.stream.flush()                self.stream.close()                self.stream = None  # See Issue #21742: _open () might fail.                # open a new file handle and get new stat info from that fd                self.stream = self._open()                self._statstream()        logging.FileHandler.emit(self, record)

首先在此handler的初始化方法中调用了:

    def _statstream(self):        if self.stream:            sres = os.fstat(self.stream.fileno())            self.dev, self.ino = sres[ST_DEV], sres[ST_INO]

返回了当前handler对应的log文件的fileobject的描述符的设备信息与inode值。之后，在每次emit方法向文件中写入record之前，会对同名log文件计算以上信息。如果发现无法获取信息或者信息不一致，但仍然能打开同名log文件，则会判断已经进行了logrotate。这时会将当前内存中log信息写入老文件（即使文件名已改变，但对应的文件标识仍能找到），然后重新打开新的log文件，继续在新文件中写入record。这样就成功处理了logrotate。
继续到logging.FileHandler.emit(self, record)，转入了StreamHandler.emit(self, record),即转入到之前解析的stream handler。

至此，f版nova的log记录过程大致解析完成。