Как трассировка запросов сломала API

TL;DR;

История провала со счастливым концом о том, как команда узнала о трассировке запросов, AOP, а потом сломала API.

Невинное начало

Каждый проект содержит логирование. Наш проект использовал Lombok и его @Slf4j аннотацию. Мы логировали выполнение бизнес операций, но нам не хватало контекста. Логи содержали что-то типа такого:

Create order
Create order
Order created.
Failed to create order

Но нам хотелось видеть принадлежность к конкретному запросу. Чтобы мы понимали, вот пришел запрос и вот так он проходил и вот так он закончился. Нам хотелось что-то типа такого:

REQ#1 Create order
REQ#2 Create order
REQ#2 Order created.
REQ#1 Failed to create order

А теперь детективная история. Добро пожаловать в текстовый микрокомикс :)

Условный понедельник

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

Короче, всё по ТЗ. Ну ок, поехали.

Тимлид в отдельной ветке добавляет в один из классов пример использования MDC для решения поставленной задачи. Отдает свой код команде на ревью. Команда узнала что-то новое. Команда рада. Тимлид доволен. Ревью проходит успешно и код вливается в основную ветку.

Условный вторник

Тимлид просит свою команду сделать по аналогии логирование еще для нескольких важных мест в проекте. Команда задачу поняла. Команда сделала. Все довольны.

Условная среда

Давящее чувство, связанное с дублированием кода в нескольких местах (для установки сгенерированного уникального идентификатора, а потом для его очистки) гложет команду и подрывает моральный дух. Вроде проблему решили, но как-то не круто.

На обеденном перерыве тимлид вспоминает, что есть такая штука как AOP. Тимлид знает, что это особая эльфийская магия и что надо ей пользоваться аккуратно. Но тимлид верит в свою команду. Что вообще может пойти не так?

Условный четверг

Команда узнает от тимлида про AOP и о том, как это может помочь решить проблему дублирования кода. Один из разработчиков получает задание внедрить Spring AOP и прикрутить логирование запросов. Получилось что-то такое:

@Around("execution(public * super.pupper.web.api.*.*Api.*(..))")
public void aroundApi(ProceedingJoinPoint jp) throws Throwable {
    LogUtil.initTraceId();
    jp.proceed()
    LogUtil.clearTraceId();
}

Для команды AOP штука новая. Команда смотрит на код, выглядит ок. Мерджим.

Условная пятница

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

Внимательный читатель уже знает в чем причина, давайте уже наконец раскроем карты. Все дело в коде (естественно):

@Around("execution(public * super.pupper.web.api.*.*Api.*(..))")
public void aroundApi(ProceedingJoinPoint jp) throws Throwable {
    LogUtil.initTraceId();
    jp.proceed();
    LogUtil.clearTraceId();
}

Вся ошибка в том, что результат вызова тихо мирно умалчивается, и API метод ничего в буквально смысле не возвращает. Заголовок Content-Length: 0. Правильная реализация должна быть примерно такой:

@Around("execution(public * super.pupper.web.api.*.*Api.*(..))")
public Object aroundApi(ProceedingJoinPoint jp) throws Throwable {
    LogUtil.initTraceId();
    try {
        return jp.proceed();
    } finally {
        LogUtil.clearTraceId();
    }
}

Разработчик заливает фикс. Все рады. Успехов вам на код-ревью и на отладке! :)