0

配置 FastAPI/Uvicorn/Hypercorn 的访问日志

 1 year ago
source link: https://yanbin.blog/configure-fastapi-uvicorn-access-log/
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.

配置 FastAPI/Uvicorn/Hypercorn 的访问日志

2023-05-03 | 阅读(6)

有了 FastAPI 之后，用 Python 实现 API 或 Web 都不再考虑 Flask 了。Flask 最早在 13 年前的 2010 年 4 月 1 日发布，实现的是 WSGI; FastAPI 较为年轻，于 4 年前的 2018 年 12 月 5 日发布，支持 ASGI。性能方面普遍是 FastAPI 比 Flask 高，编程方面就各取所好吧，使用 Flask 的时候还是 1.x 的版本，最近用 FastAPI 较多，所以无法对比。

FastAPI 本身没提供启动 Web 服务的代码，不像 Flask 还能通过 Flask 对象 或 flask 命令启动一个开发用途的 Web 服务，而 FastAPI 必须用其他的组件(ASGI server)来启动，比如各种 *corn 或 Daphne

  1. Uvicorn: FastAPI 官方的出品，默认启用访问日志，相关的参数有 --log-config <path>, --access-log/ --no-access-log 启用或关闭访问日志，默认是开启的。
  2. Hypercorn: 相关的配置选项有 --access-logformat, --access-logfile
  3.  Hypercorn: 它只是实现了 WSGI 规格的服务，所以不兼容 FastAPI, 只能作为 Uvicorn 进程的管理器。Gunicorn 作为 WSGI 服务器有丰富的访问日志配置，但访问日志仍然是由 Uvicorn 输出

顺道插一句，SpringBoot 用内嵌 Tomcat 配置访问日志的格式比较简单，通过 server.tomcat.accesslog.pattern 属性，格式参考  Tomcat 的文档 Tomcat AccessLogging，只是如果要借用  SLFJ 等日志框架来输出访问日志有些许麻烦。

Uvicorn 的访问日志配置

本人通常在应用中使用 Uvicorn 来启动服务，所以先来看看 Uvicorn 如何配置访问日志的格式。如果我们用下面的代码来启动 Uvicorn 服务

from fastapi import FastAPI
import uvicorn
app = FastAPI()
if __name__ == '__main__':
    uvicorn.run(app)

或者用命令

$ uvicorn main:app

当访问 http://localhost:8000/api/health 时，服务的控制台打印出的访问日志是

INFO: 127.0.0.1:51725 - "GET /api/health HTTP/1.1" 200 OK

这里有几个问题

  1. 日志的默认格式是什么，如何配置访问日志的格式。先交代一下默认的日志格式为：%(levelprefix)s %(client_addr)s - \"%(request_line)s\" %(status_code)s。如何获知默认格式，后面会讲到
  2. 如果有 Load Balancer 或 AWS 的 Target group, Health 检测 API 的访问日志大量输出，有什么办法可以专门屏蔽 /api/health 访问日志的输出
  3. 日志能否通过 logging 来输出
  4. 如何定义更多的输出项，如日志中包含 ECS 容器的 ID 等

这里只爆出疑问，并不打算在本文中回答所有的问题。

根据 Uvicorn 的命令参数解释

  1. --log-config PATH:  Logging configuration file. Supported formats: .ini, .json, .yaml
  2. --access-log / --no-access-log: Enable / Disable access log

看来要配置 Uvicorn 的访问日志格式无法直接用类似 log-format 来配置，而是要通过 --log-config 指定配置文件。可是日志的配置文件格式是什么，Uvicorn  并没有详细的说明。

 Google 搜索后找到这个有用的链接 Add example of logging config file #491，大概念是通过下面的方式能修改访问日志的输出格式

import uvicorn
from uvicorn.config import LOGGING_CONFIG
def main():
    LOGGING_CONFIG["formatters"]["access"]["fmt"] = '%(asctime)s %(levelprefix)s %(client_addr)s - "%(request_line)s" %(status_code)s'
    uvicorn.run(app)

尝试了一下，日志输出变成了

2023-05-02 00:13:55,501 INFO: 127.0.0.1:59579 - "GET /api/health HTTP/1.1" 200 OK

于是这就有了一个线索，LOGGING_CONFIG 就是默认的日志输出配置，用代码把它打印出来看看吧

print(json.dumps(LOGGING_CONFIG, indent=4))

LOGGING_CONFIG 的完整配置如下：

    "version": 1,
    "disable_existing_loggers": false,
    "formatters": {
        "default": {
            "()": "uvicorn.logging.DefaultFormatter",
            "fmt": "%(levelprefix)s %(message)s",
            "use_colors": null
        "access": {
            "()": "uvicorn.logging.AccessFormatter",
            "fmt": "%(levelprefix)s %(client_addr)s - \"%(request_line)s\" %(status_code)s"
    "handlers": {
        "default": {
            "formatter": "default",
            "class": "logging.StreamHandler",
            "stream": "ext://sys.stderr"
        "access": {
            "formatter": "access",
            "class": "logging.StreamHandler",
            "stream": "ext://sys.stdout"
    "loggers": {
        "uvicorn": {
            "handlers": [
                "default"
            "level": "INFO"
        "uvicorn.error": {
            "level": "INFO"
        "uvicorn.access": {
            "handlers": [
                "access"
            "level": "INFO",
            "propagate": false

它来自于 Uvicorn  的源代码 config.py 的 LOGGING_CONFIG 变量，它是一个标准的 Pythong logging 配置，在启动  uvicorn 时可用 json, yml/yaml 进行配置。

但访问日志特殊的 client_addr, request_line,  和 status_code 字段是怎么来的，还有哪些字段可使用。通过断点可以深究到 Uvicorn 的 uvicorn/protocols/http/h11_impl.py#L497-L505  代码

            if self.access_log:
                self.access_logger.info(
                    '%s - "%s %s HTTP/%s" %d',
                    get_client_addr(self.scope),
                    self.scope["method"],
                    get_path_with_query_string(self.scope),
                    self.scope["http_version"],
                    status_code,

最后发现 Uvicorn 对访问日志的配置能力极为有限，见 uvicorn/logging.py#L104-L110

            client_addr,
            method,
            full_path,
            http_version,
            status_code,
        ) = recordcopy.args  # type: ignore[misc]

client_addr, method, full_path, http_version, status_code 已经是它的全部 家当了, 不能再指望 Uvicorn 输出更详细的访问日志。任凭如何修改 LOGGING_CONFIG 的 access/fmt 都没多大的意义。

但有一件事是可以做的，就是如何屏蔽 /api/health 访问日志的输出，给 uvicorn.access logger 加 filter

class DisableHealthCheckAccessLogFilter(logging.Filter):
    def filter(self, record: logging.LogRecord) -> bool:
        return "/api/health" not in (" ".join([str(s) for s in record.args]))
logging.getLogger("uvicorn.access").addFilter(DisableHealthCheckAccessLogFilter())
if __name__ == '__main__':
    import uvicorn
    uvicorn.run(app)

想要在访问日志中包含更多字段的话只能求助于 Hypercorn 了，像请求，响应数据的长度，User-Agent 等。

Hypercorn 的访问日志配置

Hypercorn 也是一个 ASGI 服务组件，也能与 FastAPI 完美结合。安装 Hypercorn

pip install hypercorn

这里先使用编程方式来启动 app = FastAPI()

if __name__ == '__main__':
    from hypercorn import run
    from hypercorn.config import Config
    config = Config()
    config.application_path = "main:app"
    run.run(config)

main 为模块名，如果含有包层次的话，用 abc.xyz.main:app。通常在实际应用中会直接运行 hypercorn 命令，如

$ hypercorn main:app

默认服务启动在 http://127.0.0.1:8000，现在访问 http://127.0.0.1:8000(假设 FastAPI 存在 / endpoint), 在控制台不会打印出访问日志，也不会产生访问日志文件。因为在 Hypercorn 的 logging.py#L80-L86 中

    async def access(
        self, request: "WWWScope", response: "ResponseSummary", request_time: float
    ) -> None:
        if self.access_logger is not None:
            self.access_logger.info(
                self.access_log_format, self.atoms(request, response, request_time)

没有配置 access_logger, 所以 self.access_logger 的值是 None。要输出访问日志就必须设置 config.accesslog 属性，它可接受的类型有

accesslog: Union[logging.Logger, str, None] = None
先配置一个 str  试下

config.accesslog = 'access_log.txt'

重新启动，再访问 http://localhost:8000, 访问

$ curl http://127.0.0.1:8000

控制台没有访问日志而输出，不过在当前目录中产生了一个文件 access_log.txt, 内容为

[2023-05-03 11:00:49 -0500] [16475] [INFO] 127.0.0.1:55131 - - [03/May/2023:11:00:49 -0500] "GET / 1.1" 200 15 "-" "curl/7.87.0"
输出格式为 hypercorn/config.py 中的默认 access_log_format 配置

access_log_format = '%(h)s %(l)s %(l)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s"'

我们可以自定义 access_log_format，通过设置 hypercorn.config.Config 对象的 access_log_format 属性。Hypercorn 的 access_log_format 能支持的字段请参考官方文档 https://pgjones.gitlab.io/hypercorn/how_to_guides/logging.html. 它是 Gunicorn 访问日志配置的超集。 列示如下

h             remote address
u             user name
t             date of the request
r             status line without query string (e.g. GET / h11)
R             status line with query string (e.g. GET /?a=b h11)
m             request method
U             URL path without query string
Uq            URL path with query string
q             query string
H             protocol
s             status
st            status phrase (e.g. OK, Forbidden, Not Found)
S             scheme {http, https, ws, wss}
B             response length
b             response length or '-' (CLF format)
f             referer
a             user agent
T             request time in seconds
D             request time in microseconds
L             request time in decimal seconds
p             process ID
{Header}i     request header
{Header}o     response header
{Variable}e   environment variable

如果要输出访问日志到控制台又该如何做呢？这似乎只能看 hypercorn 的源代码 https://github.com/pgjones/hypercorn/blob/0.14.3/src/hypercorn/logging.py#L19-L58，官方文档也没看到源代码中揭示出来的诀窍，那就是

config.accesslog='-'

创建访问日志对象时

        self.access_logger = _create_logger(
            "hypercorn.access",
            config.accesslog,
            config.loglevel,
            sys.stdout,
            propagate=False,

传入日志输出目的地为 sys.stdout, 在 _create_logger() 函数中

    if isinstance(target, logging.Logger):
        return target
    if target:
        logger = logging.getLogger(name)
        logger.handlers = [
            logging.StreamHandler(sys_default) if target == "-" else logging.FileHandler(target)  # type: ignore # noqa: E501

重启, 访问 http://localhost:8000, 只看到控制台输出

[2023-05-03 12:10:36 -0500] [19773] [INFO] 127.0.0.1:56071 - - [03/May/2023:12:10:36 -0500] "GET / 1.1" 200 15 "-" "curl/7.87.0"

再就是直接配置 config.accesslog 为一个  logging.Logger  对象，如下

logger = logging.Logger("access_log", level=logging.INFO)
config.accesslog = logger

可是很不幸实际测试后最终的 logger 并不是赋值给 config.accesslog 的初始值，而是只取了相同的 logger name access_log 重新创建了一个新的 logger, loglevel 回到了默认的 WARNING。并且给该 logger 的任何 handler, filter 都将消失。一句话就是不能输出想要的访问日志，最终的 logger 实例是在子进程中创建的。

解决办法可以由  config.logger_class 提供自定义 Logger 子类，然后在其中定制 level, handler, filter 等。这里就不再细说了，还有一种使用配置文件的方式定制 logger。

accesslog 与 logconfig/logconfig_dict 一同使用

前面体验过单纯设置 acesslog  是无法输出 access log 的, 另一种解决办法是它需要与 logconfig 或 logconfig_dict 共同使用。比如我们重要 Hypercorn 的日志名称 hypercorn.access 和  hypercorn.error，采用如下 JSON 格式的日志配置

hypercorn_logconfig.json

  "version": 1,
  "disable_existing_loggers": false,
  "formatters": {
    "error": {
      "format": "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
    "access": {
      "format": "%(asctime)s - %(name)s - %(levelname)s - %(funcName)s:%(lineno)d - %(message)s"
  "handlers": {
    "error": {
      "formatter": "error",
      "class": "logging.StreamHandler",
      "stream": "ext://sys.stderr"
    "access": {
      "formatter": "access",
      "class": "logging.StreamHandler",
      "stream": "ext://sys.stdout"
  "loggers": {
    "hypercorn.error": {
      "level": "INFO",
      "handlers": [
        "error"
    "hypercorn.access": {
      "handlers": [
        "access"
      "level": "INFO",
      "propagate": false

给 config 指定 accesslog 和 logconfig 属性

config.accesslog = "hypercorn.access"
config.logconfig = "json:hypercorn_logconfig.json"

重启 Hypercorn 后访问 http://localhost:8000, 看到控制台输出

2023-05-03 14:40:41,601 - hypercorn.access - INFO - access:84 - 127.0.0.1:64821 - - [03/May/2023:14:40:41 -0500] "GET / 1.1" 200 15 "-" "curl/7.87.0"

Hypercorn 的文档对此用法似乎描述不清，不得不阅读源代码 hypercorn/logging.py#L19-L86(以 tag 0.14.3 为例，当前 main(原 master) 分支也是一样的)

def _create_logger(
    name: str,
    target: Union[logging.Logger, str, None],
    level: Optional[str],
    sys_default: IO,
    propagate: bool = True,
) -> Optional[logging.Logger]:
    if isinstance(target, logging.Logger):
        return target
    if target:
        logger = logging.getLogger(name)
        logger.handlers = [
            logging.StreamHandler(sys_default) if target == "-" else logging.FileHandler(target)  # type: ignore # noqa: E501
        logger.propagate = propagate
        formatter = logging.Formatter(
            "%(asctime)s [%(process)d] [%(levelname)s] %(message)s",
            "[%Y-%m-%d %H:%M:%S %z]",
        logger.handlers[0].setFormatter(formatter)
        if level is not None:
            logger.setLevel(logging.getLevelName(level.upper()))
        return logger
    else:
        return None
class Logger:
    def __init__(self, config: "Config") -> None:
        self.access_log_format = config.access_log_format
        self.access_logger = _create_logger(
            "hypercorn.access",
            config.accesslog,
            config.loglevel,
            sys.stdout,
            propagate=False,
        self.error_logger = _create_logger(
            "hypercorn.error", config.errorlog, config.loglevel, sys.stderr
        if config.logconfig is not None:
            if config.logconfig.startswith("json:"):
                with open(config.logconfig[5:]) as file_:
                    dictConfig(json.load(file_))
            elif config.logconfig.startswith("toml:"):
                with open(config.logconfig[5:]) as file_:
                    dictConfig(toml.load(file_))
            else:
                log_config = {
                    "__file__": config.logconfig,
                    "here": os.path.dirname(config.logconfig),
                fileConfig(config.logconfig, defaults=log_config, disable_existing_loggers=False)
        else:
            if config.logconfig_dict is not None:
                dictConfig(config.logconfig_dict)
    async def access(
        self, request: "WWWScope", response: "ResponseSummary", request_time: float
    ) -> None:
        if self.access_logger is not None:
            self.access_logger.info(
                self.access_log_format, self.atoms(request, response, request_time)

才能掌握 accesslog 和 logconfig/logconfig_dict 结合才能见到效果(贴了一大段代码把本文的篇幅也撑大了)。

不配置 accesslog 则 access_logger 为 None, 不能输出访问日志，如果直接给  accesslog 指定一个  logging.Logger 实例，Hypercorn 却不直接用它，则无法控制最终 Logger 的 level, handler, filter 等属性。

以上日志文件可以配置为 toml 格式的，或为一个字典对象，用 logconfig_dict 指派。

相应的，如果要配置 errorlog 就指定

config.errorlog = "hypercorn.error"

另外，config.access_log_format 是专门用来定制访问日志的输出格式，其中才能用到 %(h)  等字段，access_log_format 产生的整体内容会填充到 Python logging 的 logger format 的 %(message) 部分。通过 hypercorn_logconfig.json 文件也能加入 filter 控制某些 url 的访问不记录。


report

Recommend

About Joyk


Aggregate valuable and interesting links.
Joyk means Joy of geeK