Давно не писал сюда. Было много дел и интересных проектов. Нужно было прочитать много интересных книг и найти новую работу.
Надеюсь, найду время рассказать тут обо всём самом интересном.
Сегодня решил поделиться забавным случаем: как я искал неуловимый баг.
Баг был плавающим, т.к. smoke тесты (интеграционные тесты, запускавшиеся как отдельный сервис и проверявшие совместную работу нескольких сервисов) падали примерно 1 раз в неделю. Как водится, тесты падали на выходных и ночью, когда рядом не было посторонних наблюдателей, которые могли посмотреть, что в тот момент происходило с сервисом.
Понедельник. Видим, что тест упал в воскресенье.
По результатам исследования логов вижу, что один из сервисов выбрасывает исключение OptimisticLockingException. Такое исключение выбрасывает Hibernate, когда разные потоки пытаются одновременно внести изменения в какую-нибудь сущность и сохранить их в базе данных.
В сервисе, выбросившем исключение, вперемежку используются синхронные (REST) и асинхронные (Apache Kafka) вызовы.
Предполагаю, что асинхронно вызванный метод конфликтует с синхронно вызванным методом за изменение одной из сущностей и сохранение её в базу данных.
Добавляю между двумя тестами паузу, прогоняю несолько раз "зелёные" тесты, рапортую об исправлении бага.
Вторник. Ночью упал тот же самый тест, что и в прошлый раз.
Возможно, паузы между тестами тут не при чём...
Запускаю сервисы и тесты локально и удалённо, читаю скудные логи сервисов и тестов, развёрнутых на dev и staging площадках.
"Брутфорс" не даёт результатов.
Добавляю в ответственные участки кода тестов и сервиса логирование каждого шага и жду нового падения тестов.
Тесты весь день "зелёные". Начинаю подумывать об исправлении бага за счёт "эффекта наблюдателя" (добавил логи).
Среда. Ночное падение тестов.
Читаю логи. Вижу проблему: один из сервисов получает от другого сервиса 1 запрос и возвращает на него 2 идентичных ответа. Через Кафку возвращает. Асинхронно.
Как говорил Шерлок Холмс: отбросьте невозможное и оставшееся, каким бы невероятным оно ни было, и будет ответом на ваш вопрос.
Сыщик из меня неочень хороший. Поэтому первая моя рабочая гипотеза была такой: где-то в сервисе завёлся поток-призрак (или процесс), который возвращает второй ответ. Невероятно? Ещё бы! Следовательно, по Конан Дойлю, это и есть правильный ответ.
Задвигаю сомнения подальше, начинаю с энтузиазмом прорабатывать свою невероятную версию.
Не нахожу ответа. Внимательно смотрю в логи. Вижу то, что меня смущает: в ответ возвращается сущность, сохранённая в базу данных под уникальным ID и в ответах-близнецах ID возвращаемой сущности всегда одинаковый. Да, быть такого не может, чтобы 2 раза отработавший метод сохранил одну и ту же сущность в базу данных под одним и тем же ID!
Лезу ещё раз в код метода...
Итог оказался таким: код метода, ответственный за возвращение ответа, был продублирован. Произошло это, судя по всему, при разрешении мерж-конфликта.
Тесты этого не видели, т.к. не проверяли, сколько раз этот метод дёргает другие методы и, сколько ответов возвращает.
Выводы?
Побольше логов на стадии отладки.
Внимательно разрешать мерж-конфликты.
Писать тесты, проверяющие не только выдачу методом правильного ответа, но и всё остальное поведение кода: какой код и сколько раз вызывается из метода.
Надеюсь, найду время рассказать тут обо всём самом интересном.
Сегодня решил поделиться забавным случаем: как я искал неуловимый баг.
Баг был плавающим, т.к. smoke тесты (интеграционные тесты, запускавшиеся как отдельный сервис и проверявшие совместную работу нескольких сервисов) падали примерно 1 раз в неделю. Как водится, тесты падали на выходных и ночью, когда рядом не было посторонних наблюдателей, которые могли посмотреть, что в тот момент происходило с сервисом.
Понедельник. Видим, что тест упал в воскресенье.
По результатам исследования логов вижу, что один из сервисов выбрасывает исключение OptimisticLockingException. Такое исключение выбрасывает Hibernate, когда разные потоки пытаются одновременно внести изменения в какую-нибудь сущность и сохранить их в базе данных.
В сервисе, выбросившем исключение, вперемежку используются синхронные (REST) и асинхронные (Apache Kafka) вызовы.
Предполагаю, что асинхронно вызванный метод конфликтует с синхронно вызванным методом за изменение одной из сущностей и сохранение её в базу данных.
Добавляю между двумя тестами паузу, прогоняю несолько раз "зелёные" тесты, рапортую об исправлении бага.
Вторник. Ночью упал тот же самый тест, что и в прошлый раз.
Возможно, паузы между тестами тут не при чём...
Запускаю сервисы и тесты локально и удалённо, читаю скудные логи сервисов и тестов, развёрнутых на dev и staging площадках.
"Брутфорс" не даёт результатов.
Добавляю в ответственные участки кода тестов и сервиса логирование каждого шага и жду нового падения тестов.
Тесты весь день "зелёные". Начинаю подумывать об исправлении бага за счёт "эффекта наблюдателя" (добавил логи).
Среда. Ночное падение тестов.
Читаю логи. Вижу проблему: один из сервисов получает от другого сервиса 1 запрос и возвращает на него 2 идентичных ответа. Через Кафку возвращает. Асинхронно.
Как говорил Шерлок Холмс: отбросьте невозможное и оставшееся, каким бы невероятным оно ни было, и будет ответом на ваш вопрос.
Сыщик из меня неочень хороший. Поэтому первая моя рабочая гипотеза была такой: где-то в сервисе завёлся поток-призрак (или процесс), который возвращает второй ответ. Невероятно? Ещё бы! Следовательно, по Конан Дойлю, это и есть правильный ответ.
Задвигаю сомнения подальше, начинаю с энтузиазмом прорабатывать свою невероятную версию.
Не нахожу ответа. Внимательно смотрю в логи. Вижу то, что меня смущает: в ответ возвращается сущность, сохранённая в базу данных под уникальным ID и в ответах-близнецах ID возвращаемой сущности всегда одинаковый. Да, быть такого не может, чтобы 2 раза отработавший метод сохранил одну и ту же сущность в базу данных под одним и тем же ID!
Лезу ещё раз в код метода...
Итог оказался таким: код метода, ответственный за возвращение ответа, был продублирован. Произошло это, судя по всему, при разрешении мерж-конфликта.
Тесты этого не видели, т.к. не проверяли, сколько раз этот метод дёргает другие методы и, сколько ответов возвращает.
Выводы?
Побольше логов на стадии отладки.
Внимательно разрешать мерж-конфликты.
Писать тесты, проверяющие не только выдачу методом правильного ответа, но и всё остальное поведение кода: какой код и сколько раз вызывается из метода.
Комментариев нет:
Отправить комментарий