Ведение логов в полевых условиях

Доброго времени суток. Я хочу порассуждать о такой, казалось бы, банальной вещи, как логи.

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

Возьмем с потолка задачу. Допустим, есть некий метод, который сначала собирает данные из БД, формирует какой-то документ (XML, конечно же!) и отправляет его куда-то на сторонний сервис по HTTP. Этот метод запускается периодически по крону. Несложная задача, правда? Теперь, что мы (не только мы, этого же хотят тестировщики и суппорт) хотим видеть в логах? Во первых, факт того, что процесс начался. Затем, хорошо бы получить хоть какую-то оценку того, что мы достали из БД, например, количество новых записей. Далее, какой документ у нас получился (на первых порах его можно писать в логи и целиком) и получился ли он вообще. Кроме того, нас интересует, сколько времени займет отправка на сторонний сервис, т.к. если данные вдруг перестанут приезжать туда, куда они должны приезжать, придется доказывать, что верблюды не мы. То есть, мы желаем отразить факт отправки запроса, его характеристики, тело ответа, HTTP-код тоже не забываем, сетевые ошибки так же аккуратно записываются. Ничего не забыли?

Теперь, попробуем «реализовать» это все в уме с использованием ООП.
Сбор данных из БД — обычно удел моделей. Класс номер раз.
Формирование тела документа — еще один класс, если документ сложнее анекдота.
Отправка запроса и получение ответа — самое вкусное, тут возможна куча вариантов развития событий, никогда не знаешь что придет в ответ и придет ли вообще. Наверняка, у вас завалялся свой клевый базовый класс, который готов ко всем неожиданностям. Наследуем?

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

Мы хотели простого — в отдельном файле видеть весь процесс отправки документа от начала и до конца, а тут кто-то дергает наши классы и они мусорят в этот же самый лог, вводя в заблуждение поддержку. Кроме того, если их вызвали из другого конца проекта, то и логи хотели бы видеть там же. Получается, что логирование мешает принципу DRY?

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

Какие тут могут быть решения? Во первых, логирование нужно учитывать еще при проектировании. В особо сложных случаях, если логирование производится куда-то кроме локального файла, например, специальный сервер логов, нужно учитывать, что здесь тоже возможны «поломки», которые ни в коем случае не должны влиять на работоспособность всего сервиса. Рабочие процессы декомпозируются до разумных пределов, записи в лог делаются между функциями-блоками прямо на стрелочках (если представить в виде схемы).
Второй пункт вытекает из первого — не писать логи где попало, а только на том уровне абстракции, где и реализована бизнес-логика. Третий пункт — использование разных хитростей. Например, таких (для примера взял Ruby):

# foo.rb class Foo   attr_reader :log_history    def do_some_work     log 'Foo start!'     ...     log 'Working'     ...     log 'Almost done'     ...     log 'Profit!'     true   rescue Error > e     log "Ooops! #{e.class}: #{e.message}"     false   end    def log(message)     (@log_history ||= []) << message   end end  # bar.rb logger.info 'Using Foo class' foo = Foo.new.do_some_work foo_history = foo.log_history.join("\n") if foo   logger.info(foo_history) else   logger.error(foo_history) end logger.info 'Foo finished.' 

Для не знакомых с Ruby поясню: класс Foo записывает сообщения логов в массив — переменную экземпляра @log_history, который можно получить с помощью одноименного геттера, что и делается в файле bar.rb.

Что нам это дает? Здесь мы убиваем сразу нескольких зайцев. Во первых, мы можем использовать класс Foo откуда угодно и сами решаем, куда запишем логи. Во вторых, мы можем записывать логи не всегда, а только если что-то случилось. В третьих, мы можем подобным образом собрать логи в кучку и записать их в файл одним пакетом, который уже не смешается с сообщениями других потоков. Бонусный заяц — мы можем сначала причесать логи перед тем, как записать в файл, например, добавить к ним поясняющий префикс.
Конечно, этот способ не лишен недостатков. Очевидно, что мы потеряем всю историю класса Foo и последние намеки на источник ошибки, если вовремя не перехватим неожиданное исключение.

Попробую резюмировать. Ведение логов — не то, что нужно добавлять в последний момент. Об этом нужно «думать заранее», это должно быть частью архитектуры. В идеале — нужно иметь целую методику, формализующую отражение бизнес-процессов в логе — от языка (да да, кириллица до сих пор доставляет неудобства и норовит выйти кракозябрами) до шаблонов сообщений для облегчения парсинга лог-файлов.

Ну, на этом желаю удачи всем программистам, дружите с тестировщиками, находите общий язык с менеджерами и с наступающим!

P.S. Если знаете какие-то еще интересные способы ведения логов, пишите в комментариях.