标签：uWSGI

本文基于 Flask 0.12.2 。

当 Flask App 被部署到生产环境时，我们会选择关闭 DEBUG 配置。在这种情况下，Flask 中使用 flask.current_app.logger.info() 打印的 LOG 仿佛消失了一样。它们去了哪里呢？

默认的 Handler

下面的源码位于 [flask.logging][loggin] 中。从源码可以看出，Flash 自动创建了 logger 并加入了一个 DEBUG 级别的 Handler 和一个 ERROR 级别的 Handler。根据 DEBUG 变量的值，DEBUG Handler 在生产环境下是不生效的。因此我们就只能看到来自于 ProductHandler 的 ERROR 级别 Log 信息。

def create_logger(app):
    """Creates a logger for the given application.  This logger works
    similar to a regular Python logger but changes the effective logging
    level based on the application's debug flag.  Furthermore this
    function also removes all attached handlers in case there was a
    logger with the log name before.
    """
    Logger = getLoggerClass()
    class DebugLogger(Logger):
        def getEffectiveLevel(self):
            if self.level == 0 and app.debug:
                return DEBUG
            return Logger.getEffectiveLevel(self)
    class DebugHandler(StreamHandler):
        def emit(self, record):
            if app.debug and _should_log_for(app, 'debug'):
                StreamHandler.emit(self, record)
    class ProductionHandler(StreamHandler):
        def emit(self, record):
            if not app.debug and _should_log_for(app, 'production'):
                StreamHandler.emit(self, record)
    debug_handler = DebugHandler()
    debug_handler.setLevel(DEBUG)
    debug_handler.setFormatter(Formatter(DEBUG_LOG_FORMAT))
    prod_handler = ProductionHandler(_proxy_stream)
    prod_handler.setLevel(ERROR)
    prod_handler.setFormatter(Formatter(PROD_LOG_FORMAT))
    logger = getLogger(app.logger_name)
    # just in case that was not a new logger, get rid of all the handlers
    # already attached to it.
    del logger.handlers[:]
    logger.__class__ = DebugLogger
    logger.addHandler(debug_handler)
    logger.addHandler(prod_handler)
    # Disable propagation by default
    logger.propagate = False
    return logger

要解决这个问题，我们需要创建自己的 Handler 。

创建自己的 Handler

在创建了 Flask app 之后，调用下面的 _set_logger 方法将 app 实例传入即可。详细的介绍见代码中的注释。

def _set_logger(flaskapp):
    """
    设置 Flask app 的logger
    """
    # 删除 Flask 的默认 Handler
    del flaskapp.logger.handlers[:]
    if flaskapp.config.get('DEBUG'):
        # 在 DEBUG 模式下，使用 StreamHandler，并使用 DEBUG 级别，这样可以将所有的信息都输出到控制台
        hdr = logging.StreamHandler()
        hdr.setLevel(logging.DEBUG)
        flask.logger.setLevel(DEBUG)
    else:
        # 不使用 StreamHandler 的原因，是 uwsgi 可能会在标准输出中加入它自己的 Log，为了避免Log被弄乱，单独使用一个 FileHandler
        hdr = logging.FileHandler(config.getdir('logs', 'app.log'), encoding='utf8')
        hdr.setLevel(logging.INFO)
        flask.logger.setLevel(INFO)
    # 加入足够详细的信息
    LOG_FORMAT = """
[%(asctime)s] %(levelname)s in %(module)s.%(funcName)s [%(pathname)s:%(lineno)d]:
%(message)s"""
    hdr.setFormatter(logging.Formatter(LOG_FORMAT))
    # 如果存在 sqlalchemy 的 Log 对象，也为其加入这个 Handler
    for log in (flaskapp.logger, logging.getLogger('sqlalchemy')):
        if log:
            log.addHandler(hdr)

我们还可以重写 Flask 对象的 log_exception 方法，自动将所有的异常记录下来，并提供一些更详细的信息：

class MYFlask(Flask):
    def log_exception(self, exc_info):
        """...description omitted..."""
        self.logger.error(
            """
Request:   {method} {path}
IP:        {ip}
Agent:     {agent_platform} | {agent_browser} {agent_browser_version}
Raw Agent: {agent}
            """.format(
                method=request.method,
                path=request.path,
                ip=request.remote_addr,
                agent_platform=request.user_agent.platform,
                agent_browser=request.user_agent.browser,
                agent_browser_version=request.user_agent.version,
                agent=request.user_agent.string,
            ), exc_info=exc_info
        )

uWSGI 的 Logging 配置

我使用 INI 格式的配置文件，文件名一般为 uwsgi.ini。其中关于 Logging 的配置，我常用这样几个：

; 将写入 log 的工作委托给 master 进程
log-master = true
; 单独开一个线程进行 log 写入工作，这样有更好的性能
threaded-log = true
; 所有 log 都会写入这个文件
; 若希望所有 log 放在一起，设置了此选项后，不要设置 req-logger 和 logger 选项
; %d 代表 uwsgi.ini 所在文件夹（包含结尾的/）， %n 代表 uwsgi.ini 的主文件名
; 魔术变量： http://uwsgi-docs-zh.readthedocs.io/zh_CN/latest/Configuration.html#magicvars
daemonize = %dlogs/%n.log
; 将 uWSGI 请求 log 写入单独的 log 文件，这样做可以让log更加分离，便于查错
; 设置了此选项后，daemonize 设置的输出文件就得不到任何输出了
req-logger = file:%dlogs/req.log
; 将 uWSGI stdout/stderr log 写入单独的 log 文件
; 因为设定了 req-logger ，必须同时设定 logger ，此时 daemonize 不会有任何输出
logger = file:%dlogs/%n.log

自定义 uWSGI 的请求 log

uWSGI 会在 log 中自动写入请求 log，默认的格式如下：

[pid: 22740|app: 0|req: 162/324] 127.0.0.1 () {36 vars in 608 bytes} [Wed Nov 29 11:42:08 2017] GET /login/?code=001SkzFb1ppEDu0lTzHb1WPCFb1SkzF0 => generated 181 bytes in 69 msecs (HTTP/1.1 200) 5 headers in 209 bytes (2 switches on core 1)

关于其中信息如何解释，文档中并没有详细进行介绍，只能通过阅读 源码 logging.c 理解。

我在 uWSGI 的邮件列表中找到一封邮件 Default Log Format Explained? 介绍了 log 中每个项的详细作用。

pid -> the pid of the worker managing the request
app -> the id (it is a integer, starting from 0) of the app, it makes
sense when multiple apps are hosted in the same instance. It is -1 when no
app managed the request (like when serving static files) or when the ‘app’
concept does not apply (like with php or cgi’s)
req: N/M -> N is the number of managed requests by the current worker for
the specific app, M is the grand total (sum of all requests of all
workers)

then you have REMOTE_ADDR followd by the (optional) REMOTE_USER (very
similar to apache)

vars are the number of CGI vars in the request, and their size (from the
uwsgi protocol point of view). The size is never higher than the
–buffer-size (higher requests are discarded)

The time of the request follows

Then you have REQUEST_METHOD + REQUEST_URI

Then the response size and the time required for generating it

“via” is the techology used to send the response, currently can be
sendfile, routing or offloading.

The response status follows, as well as the number of response headers.

“core” is the low-level concept for uWSGI concurrency context in a process
(can be a thread or a greenlet or a fiber or a goroutine and so on…)
while switches count is incremented whenever an app “yield” its status
(this has various meanings based on the lower concurrency model used)

根据上面找到的资料和 格式化uWSGI请求日志 文档，通过设置 log-format 选项，我们可以模仿出默认的请求 log：

log-format = [pid: %(pid)] %(addr) (%(user)) {%(vars) vars in %(pktsize) bytes} [%(ctime)] %(method) %(uri) => generated %(rsize) bytes in %(msecs) msecs (%(proto) %(status)) %(headers) headers in %(hsize) bytes (%(switches) switches on core %(core))

除了 app: 和 req: 没有提供对应变量，其它的值都可以显示出来。

其它

日志编码器 也是一个重要的选项，若有需要可以添加该设置。

uWSGI 还可以使用 touch-logrotate 和 touch-logreopen 来实现 logging rotate，但为了让系统更加简单的独立，我建议使用 logrotate 来实现 logging rotate，并已经在 uWSGI+rsyslog 实现 rotating logging 一文中介绍过具体做法。

需要注意的是，我在 单独使用 logrotate 中提到的使用 copytruncate 选项替换 create 选项，是因为没有通知 uWSGI 重新打开 log 文件。要做到这一点非常简单，除了使用刚才提到的 touch-logreopen 之外，还可以使用 Master FIFO 中的 l 命令。