如何解决openstack中协程切换后request_id打印不对或者不打印的问题的

OpenStack各组件一般都对外提供REST服务，当某个API请求过来之后，由于可能会涉及多个方法和进程的处理，为了方便的跟踪这个请求和后续通过日志定位，我们需要有个唯一标示来追踪这个请求，这样就能从大量日志信息中找到和这个请求相关的日志了。

OpenStack是有这个能力跟踪某个API请求的，在M版本中是通过oslo_middleware中的request_id这个中间件来实现的

[filter:request_id]
paste.filter_factory = oslo_middleware:RequestId.factory

看一下这个中间件的实现：

ENV_REQUEST_ID = 'openstack.request_id'
HTTP_RESP_HEADER_REQUEST_ID = 'x-openstack-request-id'

class RequestId(base.ConfigurableMiddleware):
"""Middleware that ensures request ID.

It ensures to assign request ID for each API request and set it to
request environment. The request ID is also added to API response.
"""

@webob.dec.wsgify
def __call__(self, req):
req_id = context.generate_request_id()
req.environ[ENV_REQUEST_ID] = req_id
response = req.get_response(self.application)
if HTTP_RESP_HEADER_REQUEST_ID not in response.headers:
response.headers.add(HTTP_RESP_HEADER_REQUEST_ID, req_id)
return response

可以发现一旦有API请求经过这个中间件，他就会在req环境变量中随机生成一个uuid的标示，用来记录这个请求，这个请求标示是可以打印到日志里面的，只需要在我们的日志配置项中加上request_id这个配置项即可，具体的来讲是在logging_context_format_string 中加上request_id，这样日志里面就能打印出request_id了。

logging_context_format_string=%(asctime)s [%(threadName)s %(processName)s][%(filename)s %(levelno)s %(funcName)s] [%(request_id)s] %(levelname)s %(message)s
logging_default_format_string=%(asctime)s [%(threadName)s %(processName)s][%(filename)s %(levelno)s %(funcName)s] %(levelname)s %(message)s
logging_debug_format_suffix=

以karbor查询plan为例，这个请求所有相关的日志都和他对应的request_iq关联起来了，能完整的看到请求的处理流程。

[MainThread MainProcess][wsgi.py 20 __call__] [req-6a20874c-5563-46cc-bb96-197020a8428a] INFO GET http://127.0.0.1:8799/v1/72cc8edb-f3b2-4aa6-ab42-930724da6dcf/plans [MainThread MainProcess][wsgi.py 10 get_body] [req-6a20874c-5563-46cc-bb96-197020a8428a] DEBUG Empty body provided in request
[MainThread MainProcess][plans.py 20 index] [req-6a20874c-5563-46cc-bb96-197020a8428a] INFO Show plan list
[MainThread MainProcess][plans.py 20 _get_all] [req-6a20874c-5563-46cc-bb96-197020a8428a] INFO Get all plans completed successfully.
[MainThread MainProcess][plans.py 20 index] [req-6a20874c-5563-46cc-bb96-197020a8428a] INFO Show plan list request issued successfully.
[MainThread MainProcess][wsgi.py 20 _process_stack] [req-6a20874c-5563-46cc-bb96-197020a8428a] INFO http://127.0.0.1:8799/v1/72cc8edb-f3b2-4aa6-ab42-930724da6dcf/plans returned with HTTP 200
[MainThread MainProcess][wsgi.py 20 handle_one_response] [req-6a20874c-5563-46cc-bb96-197020a8428a] INFO 127.0.0.1 - - [26/Dec/2016 00:07:13] "GET /v1/72cc8edb-f3b2-4aa6-ab42-930724da6dcf/plans HTTP/1.1" 200 999 0.060000

那我们打印日志的时候是如何获取到这个request_id的呢，我们并没有明确的传入任何信息表明要打印哪个request_id。
首先在request_id这个中间件生成request_id后，在生成context的时候，除了会将这个信息记录到context外，还会保存这个context到线程局部变量中

import threading
import uuid

_request_store = threading.local()

def update_store(self):
"""Store the context in the current thread."""
_request_store.context = self #将context对象保存到线程局部变量里
def _update_record_with_context(record):
"""Given a log record, update it with context information.

The request context, if there is one, will either be in the
extra values for the incoming record or in the global
thread-local store.
"""
context = record.__dict__.get(
'context',
context_utils.get_current()
) #获取context用作打印
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

所以某个请求通过context中间件生成context的时候，默认也会保存这个context到线程局部变量里面，而在日志打印的时候会尝试去取这个context，如果线程变量里面保存了这个context，那么就能获取到context里面的request_id，从而打印出来，这就是日志打印能打印出request_id的原理。

如果我们代码中自己手动创建了协程并进行了切换，那么之前保存的context就丢了，从而发现打印出来没有request_id，或者被其他context干扰，打印有误。比如在karbor代码里面我们显示创建个协程池，在自己写个方法通过协程池来运行。

def _wait(self):
LOG.info("try first",)
sleep(5)
LOG.info("try agian.")
sleep(5)
LOG.info("OK")

g = greenpool.GreenPool()
g.spawn(self._wait)

[MainThread MainProcess][wsgi.py 20 _process_stack] [req-46e3ac43-ff93-4ec4-b663-df81737b2762] INFO http://127.0.0.1:8799/v1/72cc8edb-f3b2-4aa6-ab42-930724da6dcf/plans returned with HTTP 200
[MainThread MainProcess][wsgi.py 20 handle_one_response] [req-46e3ac43-ff93-4ec4-b663-df81737b2762] INFO 127.0.0.1 - - [26/Dec/2016 00:44:26] "GET /v1/72cc8edb-f3b2-4aa6-ab42-930724da6dcf/plans HTTP/1.1" 200 999 0.520000
[GreenThread-3 MainProcess][plans.py 20 _wait] INFO try first
[GreenThread-3 MainProcess][plans.py 20 _wait] INFO try agian.
[GreenThread-3 MainProcess][plans.py 20 _wait] INFO OK

跟之前的日志相比，这样打印的日志就丢失了request_id。
如何解决这个问题呢？思路有两个：

1.刚才已经提到了，如果我们不传入context，那么打印日志会自动去取当前context变量的request_id，所以我们可以在日志打印的时候指定要用的context，把刚才的_wait方法改写一下，接受context参数

def _wait(self, cxt):
LOG.info("try first", context=cxt)
sleep(5)
LOG.info("try agian.")
sleep(5)
LOG.info("OK", context=cxt)再次运行，我们看下这次的日志打印效果。
[GreenThread-3 MainProcess][plans.py 20 _wait] [req-3961603c-129f-4e2d-965a-ec6b70957dba] INFO try first
[GreenThread-3 MainProcess][plans.py 20 _wait] INFO try agian.
[GreenThread-3 MainProcess][plans.py 20 _wait] [req-3961603c-129f-4e2d-965a-ec6b70957dba] INFO OK可以看到，指定了context的打印，正确打印了request_id，如果不指定context，那么还是没有，这是因为没有把context保存在环境变量里面。

2.第二种思路是，在新的协程里面也保存这个context，从而只要是这个协程里面的打印，都会获取到这个context，把request_id打印出来，我们改写下之前的方法，这次不显示指定context进行打印。
from oslo_context.context import _request_store

def wrap_context(cxt, fun, *args, **kwargs):
if not getattr(_request_store, 'context', None):
_request_store.context = cxt
return fun(*args, **kwargs)
def _wait(self):
LOG.info("try first")
sleep(5)
LOG.info("try agian.")
sleep(5)
LOG.info("OK")
g = greenpool.GreenPool()
g.spawn(wrap_context, context, self._wait)同时发送两个请求，再次执行

[GreenThread-3 MainProcess][plans.py 20 _wait] [req-1cf43d19-2227-45c7-b32e-d6251a033905] INFO try first
[GreenThread-4 MainProcess][plans.py 20 _wait] [req-845000a7-9cf2-47f7-9478-c355552a4eb0] INFO try first
[GreenThread-3 MainProcess][plans.py 20 _wait] [req-1cf43d19-2227-45c7-b32e-d6251a033905] INFO try agian.
[GreenThread-4 MainProcess][plans.py 20 _wait] [req-845000a7-9cf2-47f7-9478-c355552a4eb0] INFO try agian.
[GreenThread-3 MainProcess][plans.py 20 _wait] [req-1cf43d19-2227-45c7-b32e-d6251a033905] INFO OK
[GreenThread-4 MainProcess][plans.py 20 _wait] [req-845000a7-9cf2-47f7-9478-c355552a4eb0] INFO OK

可以从日志里面看到，2个协程分别正确的打印了各自的request_id，至此我们的问题已解决。