openstack-ocata nova oslo.log模块浅析

仍然使用compute服务进行分析，在启动时的log服务预初始化：

log.register_options(CONF)
log.set_defaults(default_log_levels=log.get_default_log_levels() +
                     extra_default_log_levels)

注册了oslo_log库的config默认值。之后进入log服务的初始化， 方法为logging.setup(CONF, 'nova')，我们在此只分析默认情况publish_errors/use_syslog全部为False，进入了以下代码：

def _setup_logging_from_conf(conf, project, version):
    log_root = getLogger(None).logger

    # Remove all handlers
    for handler in list(log_root.handlers):
        log_root.removeHandler(handler)

    logpath = _get_log_file_path(conf)
    if logpath:
        if conf.watch_log_file and platform.system() == 'Linux':
            from oslo_log import watchers
            file_handler = watchers.FastWatchedFileHandler
        else:
            file_handler = logging.handlers.WatchedFileHandler

        filelog = file_handler(logpath)
        log_root.addHandler(filelog)

    if conf.use_stderr:
        streamlog = handlers.ColorHandler()
        log_root.addHandler(streamlog)

    elif not logpath:
        # 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:
        handler = importutils.import_object(
            "oslo_messaging.notify.log_handler.PublishErrorsHandler",
            logging.ERROR)
        log_root.addHandler(handler)

    if conf.use_syslog:
        global syslog
        if syslog is None:
            raise RuntimeError("syslog is not available on this platform")
        facility = _find_facility(conf.syslog_log_facility)
        syslog_handler = handlers.OSSysLogHandler(facility=facility)
        log_root.addHandler(syslog_handler)

    datefmt = conf.log_date_format
    for handler in log_root.handlers:
        handler.setFormatter(formatters.ContextFormatter(project=project,
                                                         version=version,
                                                         datefmt=datefmt,
                                                         config=conf))
    _refresh_root_level(conf.debug, conf.verbose)

    for pair in conf.default_log_levels:
        mod, _sep, level_name = pair.partition('=')
        logger = logging.getLogger(mod)
        numeric_level = None
        try:
            # NOTE(harlowja): integer's are valid level names, and for some
            # libraries they have a lower level than DEBUG that is typically
            # defined at level 5, so to make that accessible, try to convert
            # this to a integer, and if not keep the original...
            numeric_level = int(level_name)
        except ValueError:  # nosec
            pass
        if numeric_level is not None:
            logger.setLevel(numeric_level)
        else:
            logger.setLevel(level_name)

_loggers = {}

逻辑：

• 代码逻辑易知log_root = RootLogger(WARNING);
• 一般我们会在conf中配置log文件的位置logpath，之后会：

file_handler = logging.handlers.WatchedFileHandler
filelog = file_handler(logpath)
log_root.addHandler(filelog)

通过加锁，将filelog添加至logging.Logger的self.handler列表中

• 默认配置use_stderr为True时：

if conf.use_stderr:
    streamlog = handlers.ColorHandler()
    log_root.addHandler(streamlog)
同上

• 对以上handler，调用其setFormatter方法，将以下formatter加入其self.formatter属性中：

formatters.ContextFormatter(project=project,
                            version=version,
                            datefmt=datefmt,
                            config=conf)

• _refresh_root_level(conf.debug, conf.verbose)此方法调用了log_root的setLevel方法，将Logger的self.lever属性设定成指定的lever，如debug为10，info为20

• 对于在default_log_levers中默认的config列表中的所有pair（mod， _sep， lever_name）：

DEFAULT_LOG_LEVELS = ['amqp=WARN', 'amqplib=WARN', 'boto=WARN',
                      'qpid=WARN', 'sqlalchemy=WARN', 'suds=INFO',
                      'oslo.messaging=INFO', 'iso8601=WARN',
                      'requests.packages.urllib3.connectionpool=WARN',
                      'urllib3.connectionpool=WARN', 'websocket=WARN',
                      'requests.packages.urllib3.util.retry=WARN',
                      'urllib3.util.retry=WARN',
                      'keystonemiddleware=WARN', 'routes.middleware=WARN',
                      'stevedore=WARN', 'taskflow=WARN',
                      'keystoneauth=WARN', 'oslo.cache=INFO',
                      'dogpile.core.dogpile=INFO']

进行了logger = logging.getLogger(mod)，执行代码：

                rv = (self.loggerClass or _loggerClass)(name)
                rv.manager = self
                self.loggerDict[name] = rv
                self._fixupParents(rv)

其中：
rv = (self.loggerClass or _loggerClass)(name) = Logger(name)
self._fixupParents(rv)作用：对于rv.name模块名称为非根路径（即xxx.xxx.xxx命名方式），找到其父模块中定义的logger实例并赋值为rv.parent。如果没有定义，则将log_root赋值为rv.parent。

最后将对应的level通过logger的setLevel设置到logger实例的level属性上。至此通过config的logging模块初始化完成。

下面我们看在模块中使用时如何使用logging将信息打入到log文件中。

例如，在nova.compute.manager中，打印一个DEBUG级别的日志，例如

LOG.debug('Error setting migration status '
                              'for instance %s.',
                              migration.instance_uuid, exc_info=True)

LOG = logging.getLogger(name)`，调用其debug方法在LoggerAdapter类中进行了定义：

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

首先看self.process，因为默认使用了KeywordArgumentAdapter，所以调用其实例的process方法：

    def process(self, msg, kwargs):
        # Make a new extra dictionary combining the values we were
        # given when we were constructed and anything from kwargs.
        extra = {}
        extra.update(self.extra)
        if 'extra' in kwargs:
            extra.update(kwargs.pop('extra'))
        # Move any unknown keyword arguments into the extra
        # dictionary.
        for name in list(kwargs.keys()):
            if name == 'exc_info':
                continue
            extra[name] = kwargs.pop(name)
        # NOTE(dhellmann): The gap between when the adapter is called
        # and when the formatter needs to know what the extra values
        # are is large enough that we can't get back to the original
        # extra dictionary easily. We leave a hint to ourselves here
        # in the form of a list of keys, which will eventually be
        # attributes of the LogRecord processed by the formatter. That
        # allows the formatter to know which values were original and
        # which were extra, so it can treat them differently (see
        # JSONFormatter for an example of this). We sort the keys so
        # it is possible to write sane unit tests.
        extra['extra_keys'] = list(sorted(extra.keys()))
        # Place the updated extra values back into the keyword
        # arguments.
        kwargs['extra'] = extra

        # NOTE(jdg): We would like an easy way to add resource info
        # to logging, for example a header like 'volume-<uuid>'
        # Turns out Nova implemented this but it's Nova specific with
        # instance.  Also there's resource_uuid that's been added to
        # context, but again that only works for Instances, and it
        # only works for contexts that have the resource id set.
        resource = kwargs['extra'].get('resource', None)
        if resource:

            # Many OpenStack resources have a name entry in their db ref
            # of the form <resource_type>-<uuid>, let's just use that if
            # it's passed in
            if not resource.get('name', None):

                # For resources that don't have the name of the format we wish
                # to use (or places where the LOG call may not have the full
                # object ref, allow them to pass in a dict:
                # resource={'type': volume, 'id': uuid}

                resource_type = resource.get('type', None)
                resource_id = resource.get('id', None)

                if resource_type and resource_id:
                    kwargs['extra']['resource'] = ('[' + resource_type +
                                                   '-' + resource_id + '] ')
            else:
                # FIXME(jdg): Since the name format can be specified via conf
                # entry, we may want to consider allowing this to be configured
                # here as well
                kwargs['extra']['resource'] = ('[' + resource.get('name', '')
                                               + '] ')

        return msg, kwargs

简述逻辑：

整理kwargs（调用LOG.debug方法时的kwargs）中的'extra'字段：

 - 去掉kwargs中'exc_info'字段；
 - 将kwargs中的k、v，以kwargs['extra'][k] = v放入；
 - 将kwargs['extra'].keys()进行排序，放入kwargs['extra']['extra_keys']列表；
 - 如果在kwargs['extra']中有'resource'字段，对此字段进行处理（具体处理请看代码）；
 - 最后返回msg, kwargs

之后，调用此LoggerAdapter中绑定的Logger的debug方法，如未指定loggerClass则采用log_root：

    def debug(self, msg, *args, **kwargs):
        """
        Log 'msg % args' with severity 'DEBUG'.

        To pass exception information, use the keyword argument exc_info with
        a true value, e.g.

        logger.debug("Houston, we have a %s", "thorny problem", exc_info=1)
        """
        if self.isEnabledFor(DEBUG):
            self._log(DEBUG, msg, args, **kwargs)
↓
    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)
↓
    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
↓
class LogRecord(object):
    """
    A LogRecord instance represents an event being logged.

    LogRecord instances are created every time something is logged. They
    contain all the information pertinent to the event being logged. The
    main information passed in is in msg and args, which are combined
    using str(msg) % args to create the message field of the record. The
    record also includes information such as when the record was created,
    the source line where the logging call was made, and any exception
    information to be logged.
    """
    def __init__(self, name, level, pathname, lineno,
                 msg, args, exc_info, func=None):
        """
        Initialize a logging record with interesting information.
        """
        ct = time.time()
        self.name = name
        self.msg = msg
        #
        # The following statement allows passing of a dictionary as a sole
        # argument, so that you can do something like
        #  logging.debug("a %(a)d b %(b)s", {'a':1, 'b':2})
        # Suggested by Stefan Behnel.
        # Note that without the test for args[0], we get a problem because
        # during formatting, we test to see if the arg is present using
        # 'if self.args:'. If the event being logged is e.g. 'Value is %d'
        # and if the passed arg fails 'if self.args:' then no formatting
        # is done. For example, logger.warn('Value is %d', 0) would log
        # 'Value is %d' instead of 'Value is 0'.
        # For the use case of passing a dictionary, this should not be a
        # problem.
        # Issue #21172: a request was made to relax the isinstance check
        # to hasattr(args[0], '__getitem__'). However, the docs on string
        # formatting still seem to suggest a mapping object is required.
        # Thus, while not removing the isinstance check, it does now look
        # for collections.Mapping rather than, as before, dict.
        if (args and len(args) == 1 and isinstance(args[0], collections.Mapping)
            and args[0]):
            args = args[0]
        self.args = args
        self.levelname = getLevelName(level)
        self.levelno = level
        self.pathname = pathname
        try:
            self.filename = os.path.basename(pathname)
            self.module = os.path.splitext(self.filename)[0]
        except (TypeError, ValueError, AttributeError):
            self.filename = pathname
            self.module = "Unknown module"
        self.exc_info = exc_info
        self.exc_text = None      # used to cache the traceback text
        self.lineno = lineno
        self.funcName = func
        self.created = ct
        self.msecs = (ct - long(ct)) * 1000
        self.relativeCreated = (self.created - _startTime) * 1000
        if logThreads and thread:
            self.thread = thread.get_ident()
            self.threadName = threading.current_thread().name
        else:
            self.thread = None
            self.threadName = None
        if not logMultiprocessing:
            self.processName = None
        else:
            self.processName = 'MainProcess'
            mp = sys.modules.get('multiprocessing')
            if mp is not None:
                # Errors may occur if multiprocessing has not finished loading
                # yet - e.g. if a custom import hook causes third-party code
                # to run when multiprocessing calls import. See issue 8200
                # for an example
                try:
                    self.processName = mp.current_process().name
                except StandardError:
                    pass
        if logProcesses and hasattr(os, 'getpid'):
            self.process = os.getpid()
        else:
            self.process = None

解析逻辑：

 - 组合参数，生成一个LogRecord实例rv；
 - 将之前kwargs['extra']中的k, v以rv.__dict__['k'] = v放入，同时判断无法覆写rv中同名属性；
 - 调用self.handle，将之前添加进self.handler中的所有handler取出，调用它们的handle方法对rv进行处理

下面回到之前log_root所启用的handler上，即logging.handlers.WatchedFileHandler/handlers.ColorHandler。首先看前者：

    def handle(self, record):
        """
        Conditionally emit the specified logging record.

        Emission depends on filters which may have been added to the handler.
        Wrap the actual emission of the record with acquisition/release of
        the I/O thread lock. Returns whether the filter passed the record for
        emission.
        """
        rv = self.filter(record)
        if rv:
            self.acquire()
            try:
                self.emit(record)
            finally:
                self.release()
        return rv
↓
    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)
↓
    def emit(self, record):
        """
        Emit a record.

        If the stream was not opened because 'delay' was specified in the
        constructor, open it before calling the superclass's emit.
        """
        if self.stream is None:
            self.stream = self._open()
        StreamHandler.emit(self, record)
↓
    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)

主要逻辑是调用各个handler覆写的不同emit方法，对rv进行处理。解析:

 - 检测并处理是否进行了logrotate，确保出现类似情况可以切换正确的log文件；
 - 确保打开文件，形成log流准备写入；
 - 调用预设的formatter，使用其定制的format格式处理rv

至此，log内容就按照格式打印在了log文件中。