Openstack组件日志中添加request_id

2019独角兽企业重金招聘Python工程师标准>>>

简介

openstack组件中的日志内容都包含request_id， 这样大大方便了依据日志内容进行问题的追踪和分析。Python中内置的记录日志的模块是logging模块。 在openstack中对logging模块进行了封装， 开发了一个供所有openstack组件使用的日志记录项目， 名称为: oslo.log。 一般request_id都是放到context中的， 所以要想在日志中打印request_id， 也需要用到另外一个openstack项目, oslo.context

记录日志流程

python中的记录日志模块是logging， 这里面涉及几个概念：

• logger
• handler
• formatter
• record

每次需要记录日志时， 必须要有一个logger， logger才是记录日志的主体， 接收到日志记录请求后， logger会生成一个record实例， 每个logger可以有若干个handler， 每个handler在调用handle方法时会使用formatter进行format。

原理分析

日志内容中的request_id是在格式化日志内容时从context中获取的， 借助oslo.log中formatters模块中定义的ContextFormatter类， 会在类中定义的format(self, record)方法中将需要记录的日志record格式化， 并通过调用_update_record_with_context(record)方法， 将context中的属性赋给record对象。

在_update_record_with_context(record)中的context获取方式是首先尝试从record中获取context， 如果没有的话在获取当前线程中全局的context， 源代码如下:

from oslo_context import context as context_utils


def _dictify_context(context):
    if context is None:
        return {}
    if not isinstance(context, dict) and getattr(context, 'to_dict', None):
        context = context.to_dict()
    return context


def _update_record_with_context(record):
    context = record.__dict__.get(
        'context',
        context_utils.get_current()
    )
    d = _dictify_context(context)
    # Copy the context values directly onto the record so they can be
    # used by the formatting strings.
    for k, v in d.items():
        setattr(record, k, v)
    return context

一般来讲record不会有context属性， 都是借助oslo.context项目中context.py模块中定义的get_current()函数来获取当前线程中的context对象。 其源代码如下:

import threading

_request_store = threading.local()


def get_current():
    """Return this thread's current context

    If no context is set, returns None
    """
    return getattr(_request_store, 'context', None)

这里就涉及到当前线程中的context属性是如何赋值的问题。 在openstack项目中要想在日志内容中有request_id， 则必须同时用到oslo.log项目和oslo.context项目。 在get_current函数定义的context.py模块中还定义了一个RequestContext类，每次实例化该类时， 默认会更新当前线程的context属性，其源代码节选如下：

import threading

_request_store = threading.local()

class RequestContext(object):

    def __init__(self, auth_token=None, request_id=None, ..., overwrite=True, ....):
        
        ...
        
        if overwrite or not get_current():
            self.update_store()
            
            
    def update_store(self):
        _request_store.context = self

实例分析

oslo.log文档中给出了一个很简单的通过使用oslo.log和oslo.context项目来在日志中添加request_id的例子。 可以发现， 只要在调用日志记录方法之前实例化一个oslo.context项目中提供的RequestContext类实例就可以在打印的日志中看大req-[uuid]字样了。

明白了上述流程， 进一步我们以nova项目为例进行分析。

经过全局搜索RequestContext， 发现在nova/context.py模块中通过继承oslo.context项目中context.py模块中的RequestContext定义了一个RequestContext类。 然后在nova/api/auth.py模块中定义了一个NovaKeystoneContext的Middleware， 在其__call__方法中会通过调用nova/context.py中定义的RequestContext.from_environ方法来实例化一个ctx， 从而实例化一个oslo.context中context.py模块中定义的RequestContext实例， 将context绑定到当前线程， 这样每次在nova中调用LOG.info的话打印的日志就包含了request_id。 而NovaKeystoneContext这个Middleware会在api-paste.ini中用到。

[composite:osapi_compute]
use = call:nova.api.openstack.urlmap:urlmap_factory
/: oscomputeversions
# v21 is an exactly feature match for v2, except it has more stringent
# input validation on the wsgi surface (prevents fuzzing early on the
# API). It also provides new features via API microversions which are
# opt into for clients. Unaware clients will receive the same frozen
# v2 API feature set, but with some relaxed validation
/v2: openstack_compute_api_v21_legacy_v2_compatible
/v2.1: openstack_compute_api_v21

[composite:openstack_compute_api_v21]
use = call:nova.api.auth:pipeline_factory_v21
noauth2 = cors http_proxy_to_wsgi compute_req_id faultwrap sizelimit osprofiler noauth2 osapi_compute_app_v21
keystone = cors http_proxy_to_wsgi compute_req_id faultwrap sizelimit osprofiler authtoken keystonecontext osapi_compute_app_v21

[filter:keystonecontext]
paste.filter_factory = nova.api.auth:NovaKeystoneContext.factory

定义的filter会最终在openstack_compute_api_v21中进行使用， 最终是被osapi_compute使用， 也就是nova-api启动时需要加载的wsgi application。

转载于:https://my.oschina.net/alazyer/blog/1501329