Python

Как использовать декораторы Python для логирования вызовов функций без изменения кода

В Python декоратор можно использовать как обертку вокруг функции: сама функция остается прежней, а дополнительный код выполняется до вызова, после вызова или при ошибке. Поэтому декораторы хорошо подходят для логирования вызовов функций без изменения их исходного кода

Если сказать совсем просто, декоратор ставится над функцией через @, принимает исходную функцию, создает новую функцию-обертку и возвращает ее вместо исходной. Для внешнего кода это выглядит так, будто функция просто получила дополнительное поведение

Самый простой пример декоратора для логирования

Начнем без модуля logging, чтобы была понятна механика

def log_call(func):
    def wrapper(*args, **kwargs):
        print("Вызываем функцию:", func.__name__)
        result = func(*args, **kwargs)
        print("Функция завершилась:", func.__name__)
        return result
    return wrapper

@log_call
def add(a, b):
    return a + b

print(add(10, 5))

Что происходит при запуске

Python видит @log_call над функцией add
Функция add передается в log_call
log_call возвращает wrapper
Теперь при вызове add(10, 5) на самом деле вызывается wrapper(10, 5)
Внутри wrapper можно вывести лог, вызвать исходную функцию и вернуть результат

Главная польза в том, что тело add() не меняется. В нем по-прежнему только бизнес-логика: сложить два числа

Почему нужны `args` и `*kwargs`

Функции бывают разными: у одной два позиционных аргумента, у другой именованные параметры, у третьей вообще нет аргументов. Если декоратор должен работать с разными функциями, он должен принимать любые аргументы

def log_call(func):
    def wrapper(*args, **kwargs):
        print("args:", args)
        print("kwargs:", kwargs)
        return func(*args, **kwargs)
    return wrapper

args собирает позиционные аргументы в кортеж, а *kwargs собирает именованные аргументы в словарь. После этого мы передаем их в исходную функцию в том же виде

Пример

@log_call
def create_user(name, role="user"):
    return {"name": name, "role": role}

print(create_user("Анна", role="admin"))

Такой декоратор уже можно применять к разным функциям без переписывания под каждую сигнатуру

Рабочий вариант через модуль logging

Для реального проекта лучше использовать стандартный модуль logging, а не print(). Логи можно настроить по уровню, формату, времени, файлу и месту вывода

import logging
from functools import wraps

logging.basicConfig(
    level=logging.INFO,
    format="%(asctime)s %(levelname)s %(message)s"
)

def log_calls(func):
    @wraps(func)
    def wrapper(*args, **kwargs):
        logging.info(
            "Вызов %s args=%s kwargs=%s",
            func.__name__,
            args,
            kwargs
        )

        result = func(*args, **kwargs)

        logging.info(
            "Результат %s -> %r",
            func.__name__,
            result
        )

        return result

    return wrapper

@log_calls
def multiply(a, b):
    return a * b

print(multiply(6, 7))

При запуске вы увидите обычный результат функции и строки логов с именем функции, аргументами и результатом

Зачем нужен functools.wraps

Без @wraps(func) функция-обертка скрывает часть информации об исходной функции. Например, имя функции может стать wrapper, а документация и метаданные потеряются

functools.wraps переносит имя, docstring и другие полезные атрибуты исходной функции на обертку

from functools import wraps

def log_calls(func):
    @wraps(func)
    def wrapper(*args, **kwargs):
        return func(*args, **kwargs)
    return wrapper

Это особенно важно, если код использует автодокументацию, тесты, introspection, фреймворки или другие декораторы

Как логировать ошибки функции

Часто нужно записать не только успешный вызов, но и ошибку. Для этого внутри обертки используют try и except

import logging
from functools import wraps

logging.basicConfig(level=logging.INFO)

def log_errors(func):
    @wraps(func)
    def wrapper(*args, **kwargs):
        try:
            logging.info("Старт %s", func.__name__)
            return func(*args, **kwargs)
        except Exception:
            logging.exception("Ошибка в функции %s", func.__name__)
            raise
    return wrapper

@log_errors
def divide(a, b):
    return a / b

print(divide(10, 2))
print(divide(10, 0))

logging.exception() удобно использовать внутри except: он сохраняет не только сообщение, но и traceback. После логирования ошибка снова пробрасывается через raise, чтобы программа не делала вид, будто все прошло нормально

Как добавить время выполнения

Декоратор может логировать не только факт вызова, но и длительность работы функции

import logging
import time
from functools import wraps

logging.basicConfig(level=logging.INFO)

def log_time(func):
    @wraps(func)
    def wrapper(*args, **kwargs):
        started_at = time.perf_counter()
        try:
            return func(*args, **kwargs)
        finally:
            elapsed = time.perf_counter() - started_at
            logging.info("%s выполнена за %.4f сек", func.__name__, elapsed)
    return wrapper

@log_time
def slow_sum(numbers):
    total = 0
    for number in numbers:
        total += number
    return total

print(slow_sum(range(100000)))

Здесь используется finally, чтобы время записалось даже в случае ошибки. Это удобно для диагностики медленных участков кода

Когда такой декоратор действительно полезен

Декоратор для логирования уместен, когда одно и то же поведение нужно добавить ко многим функциям

Подходящие случаи

логировать вызовы сервисных функций
измерять время выполнения
записывать ошибки с traceback
видеть аргументы функций при отладке
контролировать вход и выход из важных операций
временно диагностировать поведение программы без переписывания тела функций

Не стоит использовать такой декоратор везде подряд. Если логировать каждую маленькую функцию, журнал станет шумным, и полезные события потеряются

Безопасность: что не нужно писать в логи

Логи часто живут дольше, чем кажется. Их могут отправлять в файлы, облачные системы, админки и мониторинг. Поэтому нельзя бездумно логировать все аргументы

Не пишите в логи

пароли
токены
приватные ключи
номера карт
персональные данные без необходимости
большие бинарные данные
содержимое файлов, если оно может быть чувствительным

Если функция принимает секреты, лучше логировать только имя функции и факт вызова

def log_safe(func):
    @wraps(func)
    def wrapper(*args, **kwargs):
        logging.info("Вызов %s", func.__name__)
        return func(*args, **kwargs)
    return wrapper

Мини-практика

Создайте декоратор log_calls, который логирует имя функции и результат. Примените его к двум функциям: сложению чисел и приветствию пользователя

@log_calls
def add(a, b):
    return a + b

@log_calls
def greet(name):
    return f"Привет, {name}"

Проверьте, что декоратор работает с разным количеством аргументов. После этого добавьте обработку ошибок и попробуйте функцию деления на ноль

Частые ошибки

Не возвращать результат исходной функции

Если внутри wrapper вызвать func(args, *kwargs), но не вернуть результат через return, внешняя функция начнет возвращать None

*Не использовать args и kwargs

Такой декоратор будет работать только с одной сигнатурой функции и быстро сломается на другом примере

Глотать исключение после логирования

Если вы поймали ошибку и не сделали raise, программа может продолжить работу в неправильном состоянии

Логировать слишком много данных

Аргументы функции могут содержать секреты или огромные структуры. В реальном проекте логирование нужно дозировать

Что почитать дальше по Python

Если нужен общий маршрут по теме, откройте рубрику Python. Для соседних задач пригодятся эти разборы:

0 комментариев

Старые

Новые Популярные