如何获取具有不同结构和不同字段的 JSON 格式的 FastAPI 应用程序控制台日志？

Question

我有一个 FastAPI 应用程序，我希望将默认日志写入 STDOUT，并使用 JSON 格式的以下数据：

应用程序日志应如下所示：

{
 "XYZ": {
   "log": {
     "level": "info",
     "type": "app",
     "timestamp": "2022-01-16T08:30:08.181Z",
     "file": "api/predictor/predict.py",
     "line": 34,
     "threadId": 435454,
     "message": "API Server started on port 8080 (development)"
    }
  }
}

访问日志应如下所示：

{
 "XYZ": {
   "log": {
     "level": "info",
     "type": "access",
     "timestamp": "2022-01-16T08:30:08.181Z",
     "message": "GET /app/health 200 6ms"
   },
   "req": {
     "url": "/app/health",
     "headers": {
       "host": "localhost:8080",
       "user-agent": "curl/7.68.0",
       "accept": "*/*"
     },
     "method": "GET",
     "httpVersion": "1.1",
     "originalUrl": "/app/health",
     "query": {}
   },
   "res": {
     "statusCode": 200,
     "body": {
       "statusCode": 200,
       "status": "OK"
      }
    }
  }
}

我尝试过的

我尝试使用json-logging这个包。使用此示例，我可以访问 json 格式的请求日志并更改结构。但我无法找到如何访问和更改应用程序日志。

当前输出日志结构

{"written_at": "2022-01-28T09:31:38.686Z", "written_ts": 1643362298686910000, "msg": 
"Started server process [12919]", "type": "log", "logger": "uvicorn.error", "thread": 
"MainThread", "level": "INFO", "module": "server", "line_no": 82, "correlation_id": 
"-"}

{"written_at": "2022-01-28T09:31:38.739Z", "written_ts": 1643362298739838000, "msg": 
"Started server process [12919]", "type": "log", "logger": "uvicorn.error", "thread": 
"MainThread", "level": "INFO", "module": "server", "line_no": 82, "correlation_id": 
"-"}

{"written_at": "2022-01-28T09:31:38.739Z", "written_ts": 1643362298739951000, "msg": 
"Waiting for application startup.", "type": "log", "logger": "uvicorn.error", 
"thread": "MainThread", "level": "INFO", "module": "on", "line_no": 45, 
"correlation_id": "-"}

Answer 1

您可以通过使用内置记录器模块创建自定义格式化程序来做到这一点。您可以extra在记录消息时使用该参数来传递上下文信息，例如 url 和标头。Python 的 JSON 模块已经在函数中实现了漂亮打印 JSON 数据dump()，使用indent允许您定义缩进级别的参数。下面是一个使用自定义格式化程序以您在问题中描述的格式记录消息的工作示例。例如，对于“App”日志，请使用logger.info('sample log message')，而对于“Access”日志，请使用logger.info('sample log message', extra={'extra_info': get_extra_info(request)})。通过将request实例传递给该get_extra_info()方法，您可以提取诸如上面提到的信息。有关更多LogRecord属性，请查看此处。下面的示例FileHandler也使用 a 将消息记录到磁盘上的日志文件中。如果不需要，可以在get_logger()方法中注释掉。

下面的方法使用FastAPIMiddleware来记录请求/响应，它允许您在某些特定端点处理之前处理request, 以及response在返回给客户端之前处理 , 。此外，下面演示的方法使用 aBackgroundTask来记录数据（如本答案中所述）。后台任务“仅在发送响应后运行”（根据Starlette 文档），这意味着客户端在接收响应之前不必等待日志记录完成。另请参阅此相关答案。

app_logger.py

import logging, sys


def get_file_handler(formatter, log_filename):
    file_handler = logging.FileHandler(log_filename)
    file_handler.setLevel(logging.DEBUG)
    file_handler.setFormatter(formatter)
    return file_handler


def get_stream_handler(formatter):
    stream_handler = logging.StreamHandler(sys.stdout)
    stream_handler.setLevel(logging.DEBUG)
    stream_handler.setFormatter(formatter)
    return stream_handler


def get_logger(name, formatter, log_filename = "logfile.log"):
    logger = logging.getLogger(name)
    logger.setLevel(logging.DEBUG)
    logger.addHandler(get_file_handler(formatter, log_filename))
    logger.addHandler(get_stream_handler(formatter))
    return logger

app_logger_formatter.py

import json, logging


def get_app_log(record):
    json_obj = {'XYZ': {'log': {
        'level': record.levelname,
        'type': 'app',
        'timestamp': record.asctime,
        #'filename': record.filename,
        'pathname': record.pathname,
        'line': record.lineno,
        'threadId': record.thread,
        'message': record.message
        }}}

    return json_obj


def get_access_log(record):
    json_obj = {'XYZ': {'log': {
        'level': record.levelname,
        'type': 'access',
        'timestamp': record.asctime,
        'message': record.message},
        'req': record.extra_info['req'],
        'res': record.extra_info['res']}}

    return json_obj


class CustomFormatter(logging.Formatter):

    def __init__(self, formatter):
        logging.Formatter.__init__(self, formatter)
    
    def format(self, record):
        logging.Formatter.format(self, record)
        if not hasattr(record, 'extra_info'):
            return json.dumps(get_app_log(record), indent=2)
        else:
            return json.dumps(get_access_log(record), indent=2)

应用程序.py

import app_logger
from app_logger_formatter import CustomFormatter
from fastapi import FastAPI, Request, Response
from http import HTTPStatus
from starlette.background import BackgroundTask
import uvicorn

app = FastAPI()
formatter = CustomFormatter('%(asctime)s')
logger = app_logger.get_logger(__name__, formatter)
status_reasons = {x.value:x.name for x in list(HTTPStatus)}

def get_extra_info(request: Request, response: Response):
    return {'req': {
        'url': request.url.path,
        'headers': {'host': request.headers['host'],
                    'user-agent': request.headers['user-agent'],
                    'accept': request.headers['accept']},
        'method': request.method,
        'httpVersion': request.scope['http_version'],
        'originalUrl': request.url.path,
        'query': {}
        },
        'res': {'statusCode': response.status_code, 'body': {'statusCode': response.status_code,
                   'status': status_reasons.get(response.status_code)}}}

def write_log_data(request, response):
    logger.info(request.method + ' ' + request.url.path, extra={'extra_info': get_extra_info(request, response)})

@app.middleware("http")
async def log_request(request: Request, call_next):
    response = await call_next(request)
    response.background = BackgroundTask(write_log_data, request, response)
    return response

@app.get("/foo")
def foo(request: Request):
    return "success"

if __name__ == '__main__':
    logger.info("Server started listening on port: 8000")
    uvicorn.run(app, host='0.0.0.0', port=8000)

输出：

{
  "XYZ": {
    "log": {
      "level": "INFO",
      "type": "app",
      "timestamp": "2022-01-28 10:46:01,904",
      "pathname": ".../app.py",
      "line": 33,
      "threadId": 408,
      "message": "Server started listening on port: 8000"
    }
  }
}
{
  "XYZ": {
    "log": {
      "level": "INFO",
      "type": "access",
      "timestamp": "2022-01-28 10:46:03,587",
      "message": "GET /foo"
    },
    "req": {
      "url": "/foo",
      "headers": {
        "host": "127.0.0.1:8000",
        "user-agent": "Mozilla/5.0 ...",
        "accept": "text/html,..."
      },
      "method": "GET",
      "httpVersion": "1.1",
      "originalUrl": "/foo",
      "query": {}
    },
    "res": {
      "statusCode": 200,
      "body": {
        "statusCode": 200,
        "status": "OK"
      }
    }
  }
}