Постановка проблемы
Я работаю над проектом, и мы хотим иметь возможность отслеживать все логи, которые приходят от пользователя, вызывающего одну из наших конечных точек. Это подразумевает простой способ связать вместе журналы, если они были сделаны одним и тем же пользователем, вызывающим конечную точку, и увидеть имя и аргументы функции, из которой исходит журнал. Это позволит нам воспроизвести любые ошибки и проследить путь пользователей.
Чтобы продемонстрировать, чего мы хотим добиться, предположим, что у нас есть приложение flask:
from flask import Flask
import logging
app = Flask(__name__)
logging.basicConfig(format="%(asctime)s | %(levelname)s | %(filename)s | %(message)s",
datefmt="%Y-%m-%dT%H:%M:%S%Z", level=logging.DEBUG)
book_db = {
0: "book_1",
1: "book_2"
}
def get_book(id):
logging.info(f"Getting book with id {id}")
return book_db[id]
@app.route("/books/<int:book_id>", methods=["GET"])
def books(book_id):
logging.info(f"Getting book")
book = get_book(book_id)
logging.info(f"Got book: {book}")
return {"books": [book]}
Тогда, если бы мы вызвали конечную точку http://127.0.0.1:5000/books/1, которую мы хотели бы видеть в наших журналах:
2022-03-06T14:34:16GMT | INFO | app.py | 16d99360-90ad-4e1a-8803-3996b45c6540 | books | {book_id=1} | Getting book
Где
Мы хотели, чтобы вся эта информация была собрана в наших журналах, с минимальными накладными расходами или ручной обработкой, насколько это возможно.
Добавление идентификатора трассировки в журналы
from flask import Flask, g, has_request_context
import logging
import uuid
app = Flask(__name__)
logging.basicConfig(format="%(asctime)s | %(levelname)s | %(filename)s | %(trace_id)s | %(message)s",
datefmt="%Y-%m-%dT%H:%M:%S%Z", level=logging.DEBUG)
@app.before_request
def before_request_func():
g.trace_id = uuid.uuid4()
old_factory = logging.getLogRecordFactory()
def record_factory(*args, **kwargs):
record = old_factory(*args, **kwargs)
if has_request_context():
record.trace_id = g.trace_id
else:
record.trace_id = uuid.uuid4()
return record
logging.setLogRecordFactory(record_factory)
book_db = {
0: "book_1",
1: "book_2"
}
def get_book(id):
logging.info(f"Getting book with id {id}")
return book_db[id]
@app.route("/books/<int:book_id>", methods=["GET"])
def books(book_id):
logging.info(f"Getting book")
book = get_book(book_id)
logging.info(f"Got book: {book}")
return {"books": [book]}
Теперь, если мы вызываем конечную точку http://127.0.0.1:5000/books/1, мы видим в наших журналах идентификатор, связанный с журналом, поэтому мы можем четко отслеживать поток пользователя:
2022-03-06T15:38:05GMT | INFO | app.py | 199934fe-a096-44e4-8780-31ed7a8550b6 | Getting book
2022-03-06T15:38:06GMT | INFO | app.py | 199934fe-a096-44e4-8780-31ed7a8550b6 | Getting book with id 1
2022-03-06T15:38:06GMT | INFO | app.py | 199934fe-a096-44e4-8780-31ed7a8550b6 | Got book: book_2
Добавление имени функции и аргументов в журналы
Предположим, у нас есть конечная точка, которая вызывает несколько функций, а эти функции вызывают другие функции, но мы хотим отслеживать, какие функции и аргументы мы должны записывать в журнал в это время. Чтобы решить эту проблему, я нарисовал ее, чтобы лучше понять:
Нарисовав ее, я заметил, что мы можем использовать стек для отслеживания того, какое имя функции и аргументы мы должны регистрировать.
from flask import Flask, g, has_request_context
import logging
import uuid
app = Flask(__name__)
logging.basicConfig(format="%(asctime)s | %(levelname)s | %(filename)s | %(trace_id)s | %(func_name)s | %(args)s | %(message)s",
datefmt="%Y-%m-%dT%H:%M:%S%Z", level=logging.DEBUG)
def log_function_name_and_args(func):
def inner(*args, **kwargs):
local_args = locals()
g.name_and_args.append((func.__qualname__, local_args))
logging.info("Function started")
output = func(*args, **kwargs)
logging.info(f"Function finished with output {output}")
g.name_and_args.pop()
return output
return inner
@app.before_request
def before_request_func():
g.name_and_args = []
g.trace_id = uuid.uuid4()
old_factory = logging.getLogRecordFactory()
def record_factory(*args, **kwargs):
record = old_factory(*args, **kwargs)
if has_request_context():
record.trace_id = g.trace_id
record.args = g.name_and_args[-1][1]
record.func_name = g.name_and_args[-1][0]
else:
record.trace_id = uuid.uuid4()
record.args = {}
record.func_name = ""
return record
logging.setLogRecordFactory(record_factory)
book_db = {
0: "book_1",
1: "book_2"
}
@log_function_name_and_args
def get_book(id):
logging.info(f"Getting book with id {id}")
return book_db[id]
@app.route("/books/<int:book_id>", methods=["GET"])
@log_function_name_and_args
def books(book_id):
logging.info(f"Getting book")
book = get_book(book_id)
logging.info(f"Got book: {book}")
return {"books": [book]}
Теперь, если мы вызываем конечную точку http://127.0.0.1:5000/books/1, мы видим в наших журналах имя и аргументы функции, из которой был получен журнал:
2022-03-06T15:59:45GMT | INFO | app.py | 3698a090-eb05-4896-ae13-8134bb83e8fc | books | {'args': (), 'kwargs': {'book_id': 1}, 'func': <function books at 0x7fc357c21820>} | Function started
2022-03-06T15:59:45GMT | INFO | app.py | 3698a090-eb05-4896-ae13-8134bb83e8fc | books | {'args': (), 'kwargs': {'book_id': 1}, 'func': <function books at 0x7fc357c21820>} | Getting book
2022-03-06T15:59:45GMT | INFO | app.py | 3698a090-eb05-4896-ae13-8134bb83e8fc | get_book | {'args': (1,), 'kwargs': {}, 'func': <function get_book at 0x7fc357c21550>} | Function started
2022-03-06T15:59:45GMT | INFO | app.py | 3698a090-eb05-4896-ae13-8134bb83e8fc | get_book | {'args': (1,), 'kwargs': {}, 'func': <function get_book at 0x7fc357c21550>} | Getting book with id 1
2022-03-06T15:59:45GMT | INFO | app.py | 3698a090-eb05-4896-ae13-8134bb83e8fc | get_book | {'args': (1,), 'kwargs': {}, 'func': <function get_book at 0x7fc357c21550>} | Function finished with output book_2
2022-03-06T15:59:45GMT | INFO | app.py | 3698a090-eb05-4896-ae13-8134bb83e8fc | books | {'args': (), 'kwargs': {'book_id': 1}, 'func': <function books at 0x7fc357c21820>} | Got book: book_2
2022-03-06T15:59:45GMT | INFO | app.py | 3698a090-eb05-4896-ae13-8134bb83e8fc | books | {'args': (), 'kwargs': {'book_id': 1}, 'func': <function books at 0x7fc357c21820>} | Function finished with output {'books': ['book_2']}
Завершаем!
Теперь у нас есть универсальный журнал, который позволяет нам видеть все журналы, созданные пользователем при обращении к конечной точке, а также имя и аргументы, использованные функцией, из которой был получен журнал. Это позволяет нам воспроизвести поток пользователя и более детально исследовать ошибку.
Одним из основных недостатков этого подхода является то, что мы должны использовать обертку log_function_name_and_args для всех функций/методов, чтобы эта информация появилась в наших логах. Однако, на мой взгляд, это перевешивает технический долг из-за богатства знаний, которые вы получаете.
Если есть способ сделать это без обертки и применить его ко всему приложению, пожалуйста, свяжитесь с нами, я буду рад узнать!
До следующего раза,
Дарра 🙂