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

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 package for this. Using this 示例，我能够访问 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

您可以通过创建自定义 Formatter using the built-in logger module. You can use the extra parameter when logging messages to pass contextual information, such as url and headers. Python's JSON module already implements pretty-printing JSON data in the dump() function, using the indent parameter to define the indent level. Below is a working example using a custom formatter to log messages in the format you described in your question. For App logs use, for instance, logger.info('sample log message'), whereas, for Access logs, use logger.info('sample log message', extra={'extra_info': get_extra_info(request)}). By passing the request instance to the get_extra_info() method, you can extract information such as the one you mentioned above. For more LogRecord attributes, have a look here 来做到这一点。下面的示例也使用 FileHandler 将消息记录在日志文件中。如果不需要，可以在get_logger()方法中注释掉。

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)

app.py

import app_logger
from app_logger_formatter import CustomFormatter
from fastapi import FastAPI, Request
import uvicorn

app = FastAPI()
formatter = CustomFormatter('%(asctime)s')
logger = app_logger.get_logger(__name__, formatter)


def get_extra_info(request):
    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': 200, 'body': {'statusCode': 200,
                   'status': 'OK'}}}


@app.get("/foo")
def foo(request: Request):
    logger.info('GET ' + request.url.path, extra={'extra_info': get_extra_info(request)})
    return "success"


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

更新 1

记录 requests/responses 的更好方法是添加一个 FastAPI Middleware，它会获取应用程序收到的每个请求以及返回前的每个响应。下面给出示例（app_logger.py和app_logger_formatter.py与上面相同）。

app.py

import app_logger
from app_logger_formatter import CustomFormatter
from fastapi import FastAPI, Request, Response
import uvicorn
from http import HTTPStatus

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)}}}


@app.middleware("http")
async def log_request(request: Request, call_next):
    response = await call_next(request)
    logger.info(request.method + ' ' + request.url.path, extra={'extra_info': get_extra_info(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='127.0.0.1', port=8000)

更新 2

除了之前的更新，你还可以有一个background task for logging the data, instead of waiting for the logging to complete before returning the response. A background task "will run only once the response has been sent" (as per Starlette documentation)。可以在后台定义一个任务函数运行用于写入日志数据，如下图：

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

然后，在中间件内部，您可以将（上述）任务函数传递给 background tasks，如下所示（致谢 this post）：

from starlette.background import BackgroundTask

@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

输出:

{
  "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"
      }
    }
  }
}

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

How do I get my FastAPI application's console log in JSON format with a different structure and different fields?

python

logging

gunicorn

fastapi

uvicorn

更新 1

更新 2