блог разработчика о насущном

Логирование как средство от депрессии

Ночь, баги, лог, библиотека,
Бессмысленный и тусклый свет.
Дебажь ещё хоть четверть века —
Всё будет так. Исхода нет.


Ништяк, если есть время вдумчиво, не торопясь выискивать причину бага. Но чаще бывает так, что знатно подгорает, и оперативное решение или хотя бы определение причины нужно вчера. Поэтому хочу поделиться некоторыми простыми, но действенными приёмами, которые помогут сэкономить на нервах и антидепрессантах (либо просто на времени, если вы опытный пофигист). Поехали!
Идентификация исключений
Допустим, вы получили информацию об ошибке с сообщением такого вида:
Если вам ещё и описали кейс воспроизведения — прекрасно. В таком случае дальнейшие действия понятны: лезем в логи ищем по "INTERNAL_ERROR". Всё в порядке, когда подобных ошибок 1-2. А если их десятки или сотни, и причины возникновения разные? Улучшение, которое приходит в голову — добавить временную метку — вызывает опасение, что огребем на синхронизации времени логов и ошибки.

Поэтому считаю не худшим решением добавлять UUID в ошибку. В итоге мы имеем:
{
    "code": "INTERNAL_ERROR",
    "message": "Че ты мне шлешь, псина"	
}

{ 

"code": "INTERNAL_ERROR", 

"message": "Че ты мне шлешь, псина", 

"uid": "90d341cc-8945-4303-bd08-baaeb36032eb" 

}
а в логах моментально и безошибочно находим стектрейс по данному UUID. 
2020-02-14 16:08:05.630 ERROR --- a.b.c.base.CommonExceptionHelper : #### Exception UUID: 90d341cc-8945-4303-bd08-baaeb36032eb #### 
Required parameter 'ololo' is not present
Деликатные места
Предположим, что у нас сложная бизнес логика. Входные данные в конкретный функционал могут дополняться, изменяться в зависимости от условий, как и выходные. В итоге, если мы имеем ошибку в реализации функционала, то получаем некорректные данные на выходе, в БД, другом сервисе. Поэтому стоит «обмазать» логами все деликатные места, чтобы, получив некорректные данные, можно было отследить место, где они мутировали.
логирование java-разработчик баги rocket science
Так себе:
   public Some method(long id) {
        Some some = someRepository.getById(id);

        if (somme.getInnerSome() == null) {
            some.setInnerSome(anotherService.getInnerSome(id));
        }

        lod.debug("method: Finished with: {}, for id: {}", some, id);

        return some;
    }
Ништяк:
 public Some method(long id) {
        log.trace("method: Started with id: {}.", id);

        Some some = someService.getById(id);

        if (some.getInnerSome() == null) {
            Some innerSome = anotherService.getInnerSome(id);

            log.debug("method: AnotherService#getInnerSome finished with: {}", innerSome);

            some.setInnerSome(innerSome);
        }

        log.debug("method: Finished for id {} with: {}", id, some);

        return some;
    }
Хлебные крошки
Предположим, что мы успешно внедрили предыдущие два решения и словили некорректное поведение приложения. Мы открываем логи, ищем ошибку по UUID или по известным признакам, если исключения не было. Здесь мы встречаемся со следующей проблемой: несколько десятков, а может, и сотен, потоков внесли записи в наш замечательный лог. В итоге найти путь нашего запроса так же легко, как найти иголку сами знаете где.

Решением этой проблемы может быть идентификация пути запроса в записи лога: таким образом логи именно нашего запроса можно отследить на раз-два.
логирование java-разработчик баги
Что тут происходит?!
2020-02-14 01:03:52.619 DEBUG --- Some : someMethod: {some data}
2020-02-14 01:03:52.613 DEBUG --- Some : someMethod: {some data}
2020-02-14 01:03:56.855 DEBUG --- Some : someMethod: {some data}
2020-02-14 01:03:56.856 DEBUG --- Some : someMethod: {some data}
2020-02-14 01:03:57.779 DEBUG --- Some : someMethod: {some data}
2020-02-14 01:03:57.779 DEBUG --- Some : someMethod: {some data}
Я всё понял!
Например, в наших проектах мы используем Spring Cloud Sleuth. Он также позволяет передавать идентификатор запроса в сторонние web-сервисы, что ускоряет анализ логов в микросервисной архитектуре. 
2020-02-14 01:03:52.619 DEBUG [930b7e12eb58f9d1] --- Some : someMethod: {some data}
2020-02-14 01:03:52.613 DEBUG [0fb03fb24ee402a8] --- Some : someMethod: {some data}
2020-02-14 01:03:56.855 DEBUG [ec285e3363cb9687] --- Some : someMethod: {some data}
2020-02-14 01:03:56.856 DEBUG [0fb03fb24ee402a8] --- Some : someMethod: {some data}
2020-02-14 01:03:57.779 DEBUG [ec285e3363cb9687] --- Some : someMethod: {some data}
2020-02-14 01:03:57.779 DEBUG [930b7e12eb58f9d1] --- Some : someMethod: {some data}
Сырые данные
Нередко встречаются ситуации, когда в приложение приходят данные по сети. Форматов много, но большая часть имеет строгую структуру. Представим, что отсылающая сторона каким-то образом повредила структуру, тогда на нашей стороне может либо произойти ошибка десериализации, либо не произойдёт ничего, и вы получите неполную или пустую структуру. Но помочь (или натыкать носом, если с той стороны сыплются упрёки «это все твой говносервис, я отправил правильно») товарищам, реализующим сторонний сервис стоит, указав, в чём же, собственно, проблема. 
2020-02-14 11:49:09.302  DEBUG --- ControllerLoggingFilter : GET /api/v1/test start with details: '{body={"param1":"value1","param2":"value2"}, headers={Accept=application/json, Accept-Encoding=gzip,deflate, Content-Type=application/json}}'

...

2020-02-14 11:49:09.302  DEBUG --- ControllerLoggingFilter : GET /api/v1/test end with status '200' and details: '{"data":{"param":"value"},"error":null}'
Поэтому козырным решением будет логировать сырые данные как входящие, так и исходящие, чтобы не оказаться на месте вышеописанных ребят.

Спасибо, что прочитали! Буду рад, если эти решения помогут вам в работе.
previous
Переход на Testcontainers, вызванный одной очень длинной компанией
Наш java-разработчик Стас Усенков рассказывает о небольшом пойманном баге на проекте бэкенда для мобильных приложений.
2023 © Rocket Science — команда опытных Java/Kotlin финтех разработчиков. Данные о результатах специальной оценки условий труда
Инстаграм и Фейсбук — соцсети, запрещенные на территории России.