Когда рассказываешь о принципах, нет ничего лучше, чем подкрепить его реальным примером из жизни.
Сейчас будет история одного бага, в который мы с коллегами влетели совсем недавно.
Логика приложения
Дано: классическое веб-приложение на Laravel. Рекламная биржа.
Рекламодатели запускают рекламные кампании с баннерами, “паблишеры” показывают эти баннеры на своих ресурсах.
В приложение идёт запрос от паблишера: дайте мне баннер.
Также в запросе передаётся ID пользователя и его “свойства”: например, предпочитаемый язык.
Наша система по своей логике фильтрует доступные рекламные кампании, выбирает наиболее подходящее для этого паблишера и пользователя объявление, отдаёт его в ответе.
Условие
Среди условий отбора есть такое: показ одного и того же объявления одному пользователю может быть не более N раз в сутки, N настраивается в свойствах рекламной кампании.
Если счётчик показов достиг N, более мы ему это объявление не показываем.
Баг
Нам сообщили, что это условие не срабатывает. Для некоторых пользователей счётчик переходит за лимит, причём через некоторое время всё равно останавливается.
Отладка
Мы стали изучать. Первым делом подтвердили, что баг действительно имеет место. Отследили конкретных пользователей, по которым счётчик перешагнул за лимит.
Далее проверили локально и в проде, но воспроизвести не получилось: ограничение срабатывало как положено.
Версии
Было несколько версий, основанных на предположениях.
Версия 1. Параллельные запросы из-за нагрузки
Судя по записям в БД, счётчик сбоил ночью. Предположили, что всё дело в том что ночью было больше трафика, который нагружал приложение.
Может, в нагруженном сервере долго обрабатывались запросы и шли параллельно? Из-за этого проверка была по старому значению счётчика?
Версия 2. Кеш в БД
Возможно БД что-то там неправильно кеширует?
Версия 3. Некорректный запрос
Может быть, SQL запрос был составлен неправильно, там опечатка по невнимательности?
Проверка версий
Мы проанализировали, проверили и признали несостоятельными все эти версии.
Магия. Должно работать, но не работает и неизвестно почему.
Проверьте себя
Разгадка покажется вам банальной, как только вы её прочитаете.
Но прежде чем хмыкнуть “это же было элементарно” попробуйте проверить себя: можете ли вы угадать причину сейчас, пока не дочитали статью до конца?
Когда будете готовы, листайте дальше.
.
.
.
.
.
.
.
.
.
.
.
.
.
.
.
.
.
.
.
.
.
.
.
Разгадка
Где-то через полдня поисков, обратив ещё раз внимание на часы, в которые фиксировался баг, было замечено что это период примерно с 21 до 24 часов.
Возникла догадка: может, косяк во временной зоне?
Взглянув ещё раз на код и на запрос, догадка усилилась. Ну и следующим шагом в проде был проверен код, который окончательно подтвердил догадку.
Запрос по рекламным кампаниям
SELECT ...
WHERE DATE(campaign_views.created_at) = CURDATE() ...
Так мы искали счётчик в БД
CampaignViews::...->whereDate('created_at', Carbon::today())...
В первом случае время определял сервер MySQL и оно было московское, а во втором время бралось из PHP и считалось по UTC (Гринвич).
Из-за разницы часовых поясов, когда в Москве было 22 часа 20 сентября, по Гринвичу уже был 1 час 21 сентября.
Таким образом, ограничение на лимит счётчика показов в рекламной кампании не срабатывало, потому что в промежуток с 21 до 24 по Москве в запросе вычислялась неправильная дата.
Выводы
Несмотря на 80%-90% уверенность в версиях основанных на предположениях, ошибка оказалась совсем не там где мы её искали.
Что ещё раз доказывает, как мало мы можем угадать и предсказать. Не надейтесь на догадки!
Что нам помогло:
1. Интуиция — подсказавшая приглядеться ко времени когда появлялся баг;
2. Логика — позволившая не тратить время на доказывание версий, которые признаны логически неверными;
3. Открытое обсуждение — заставившее мозги работать на полную катушку и вырваться из хождения по кругу.