О важности логирования и тестирования

Есть такая фраза — «Сапожник без сапог». Это сегодня в какой-то мере про меня. А учитывая, что я разрабатываю сервис доставки, проверки и аудита вебхуков, ситуация выглядит вдвойне комично. Но сначала предыстория.

Сегодня вышел новый релиз Adal CLI v0.1.2, а вместе с ним и некоторые обновления на стороне сервера.

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

Одним из предстоящих улучшений будет ограничение хранения body запроса. Это может быть важно для некоторых категорий пользователей, которые пересылают через вебхуки данные, содержимое которых является, например, конфиденциальным и хранение которых третьей стороной запрещено.

После внесения соответствующих изменений в код, я протестировал его работоспособность. Вебхуки принимаются, обрабатываются, флаги хранения устанавливаются, всё доходит до CLI и отправляется на конечный destination.

В качестве конечных destinations у меня установлено два адреса: один ссылается на точно работающий хост, а второй ссылается на точно не работающий. Ну, это вполне объяснимо: чтобы видеть как обрабатываются разные сценарии доставки вебхуков.

Но я не учёл одного: а что именно получает конечный хост? А он получал запрос без исходного body и заголовков. Вместо ожидаемого payload до него доходили только внутренние служебные данные, которые не предназначены для конечного получателя.

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

Ошибка заключалась в том, что запросу, при его сохранении, флаг типа хранения устанавливался, но не проверялся сервисом доставки пользователю. Сервис, который формирует payload для доставки пользователю, получал неизвестный тип хранения и в таком случае возвращал пустой результат.

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

Можно было бы сделать условие «если не знаем тип, то считаем его типом по умолчанию», но я посчитал, что лучше будет считать «если мы не знаем что это, то мы не обрабатываем это». Потому что «считать по умолчанию» — это что-то из blackbox, ведь потом приходится гадать «почему на этот запрос получил именно такой ответ».

Этот случай ещё раз напомнил мне простую вещь: тестировать нужно не отдельный сервис и не отдельную функцию, а весь пользовательский сценарий целиком. Можно убедиться, что вебхук принят. Можно убедиться, что он сохранён. Можно убедиться, что он поставлен в очередь и доставлен. Но пока не посмотрел, что именно получил конечный endpoint, проверка не завершена. Именно поэтому хорошие логи и наблюдаемость важны не меньше, чем сама бизнес-логика.

Поэтому я создал ещё один endpoint для наблюдения и изменил адрес хоста, который точно работает, на адрес нового endpoint. Теперь я буду точно видеть, что именно приходит в запросе. И в очередной раз убедился: ничто не находит баги лучше, чем использование собственного продукта каждый день. Особенно когда этот продукт предназначен для для решения твоих собственных задач.