Если пришлось изобрести велосипед. Проектируем класс Logger

Я считаю, что "изобретение велосипедов" в программировании имеет смысл только в учебных целях. В тех случаях, когда нам приходится писать коммерческую систему (вообще любую программу, которой должны пользоваться люди), желательно использовать как можно больше уже готовых и проверенных решений других команд. Конечно, как и в обычной жизни, перегибы в использовании чужого кода недопустимы:

• Доверяй, но проверяй (уверены, что чужой код работает, как заявлено)?
• Лицензирование (код, который вы используете, выпущен под необходимой Вам лицензией)?
• Полнота (иногда, готовое решение по своей функциональности не перекрывает поставленной задачи, а значит его использование в исходном виде является неприемлемым)

Однако, иногда создаются проекты, в которых по тем или иным причинам невозможно использовать готовые библиотеки. В таких случаях необходимо написать минимальный необходимый вариант для решения задачи. Рассмотрим задачу логирования работы системы силами самописного класса Logger.

Понятие логирования

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

Логирование - это информация, необходимая инженеру, ведущему поддержку своей разработки.

Журналирование - это информация необходимая пользователю, работающему с программой.

Разберём задачу логирования, помня о том, что чисто технически, задача журналирования решается теми же средствами.

Зачем нужны логи

В процессе изучения этой проблемы меня вполне удовлетворил список целей использования Logger из этого источника [1]. Позволю себе кратко его пересказать своими словами:

• Отладка. Без использования отладчика
Не всегда есть отладчик под требуемую систему, не всегда есть время им пользоваться, не всегда отладчик позволяет легко "поймать" ошибку.
• Расследование. В том числе и в сфере ИБ
Ошибки бывают плавающие, и тогда очень трудно понять, когда они возникают. Чтобы не пытаться безуспешно вызвать плавающую ошибку, пишут логи, которые при возникновении такой ошибки позволят быстро понять, что пошло не так.
• Профилирование. В основном на динамически развивающихся системах
Часто программа работает после деплоя немного иначе, нежели на процессе разработки. Это может быть связано с различной настройкой системы, использованием различного железа, получением разных входных данных. Тогда очень важно вовремя отслеживать возникающие "бутылочные горлышки" и вовремя их устранять.

Давайте определим, что такое идеальный логгер:

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

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

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

Важные параметры логгеров

Уровни логирования

Предназначены для разделения потоков сообщений по степени важности. Рассмотрим основные пять уровней логирования: DEBUG, INFO, WARNING, ERROR, FATAL. О ситуации, в которой надо использовать тот или иной вариант, очень хорошо написано в статье [1]:

Debug: сообщения отладки, профилирования. В production системе обычно сообщения этого уровня включаются при первоначальном запуске системы или для поиска узких мест (bottleneck-ов).
Info: обычные сообщения, информирующие о действиях системы. Реагировать на такие сообщения вообще не надо, но они могут помочь, например, при поиске багов, расследовании интересных ситуаций итд.
Warn: записывая такое сообщение, система пытается привлечь внимание обслуживающего персонала. Произошло что-то странное. Возможно, это новый тип ситуации, ещё не известный системе. Следует разобраться в том, что произошло, что это означает, и отнести ситуацию либо к инфо-сообщению, либо к ошибке. Соответственно, придётся доработать код обработки таких ситуаций.
Error: ошибка в работе системы, требующая вмешательства. Что-то не сохранилось, что-то отвалилось. Необходимо принимать меры довольно быстро! Ошибки этого уровня и выше требуют немедленной записи в лог, чтобы ускорить реакцию на них. Нужно понимать, что ошибка пользователя – это не ошибка системы. Если пользователь ввёл в поле -1, где это не предполагалось – не надо писать об этом в лог ошибок.
Fatal: это особый класс ошибок. Такие ошибки приводят к неработоспособности системы в целом, или неработоспособности одной из подсистем. Чаще всего случаются фатальные ошибки из-за неверной конфигурации или отказов оборудования. Требуют срочной, немедленной реакции. Возможно, следует предусмотреть уведомление о таких ошибках по SMS.

Пример, хорошо иллюстрирующий, как надо выбирать уровни логирования, Вы также можете найти здесь [1]. Конечно уровней может быть и больше, но это не существенно в рамках большинства задач.

Формат логирования

Формат в котором сообщения выводятся в соответствующий лог-файл (или любой другой вывод, предназначенный для ведения логов). Обычно библиотечные логгеры позволяют включать некоторую служебную информацию в строку сообщения:

• Время (от начала запуска программы, или глобальное);
• Уровень сообщения (присвоенный сообщению уровень логирования);
• Функция, в которой производится логирование (имя функции средствами рефлексии);
• Текст сообщения (основная информация о событии);
• Stack trace (позволяет понять место возникновения исключения
и т. д.

Ротация лог-файлов

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

Направления вывода

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

Потокобезопасность

Использование класса Logger в многопоточных приложениях ни в коем случае не должно влиять на его работоспособность. Другими словами, не должно возникать взаимных блокировок, затирания данных, "гонок" и прочих ошибок работы в многопоточных приложениях.

Асинхронность

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

Работа с исключениями

При выводе информации об исключении в лог необходимо знать всю служебную информацию: название исключения, его параметры (имя, тип, где возникло и т. д.), Stack trace исключения. При этом необходимо, чтобы класс Logger сам умел преобразовывать в читаемый вид эту информацию без участия разработчика в процессе форматирования вывода.

Архитектура логгера

По условию задачи, мы не имеем возможности использовать библиотеки логирования любых сторонних производителей, а значит должны сами написать класс Logger. Так как общие принципы одинаковые для большинства объектно-ориентированных языков, то все примеры кода будут написаны с использованием псевдокода (похожего на код C#).

1. Простейший Logger
Требования:
• умеет построчно писать в любой один файл в виде текста;
• гарантирует сохранность лога при любом варианте завершения работы программы;
• имеет пять вышеописанных уровней логирования.
Анализ требований: Для хранения уровней логирования нас устроит обычное перечисление. В случае, если по каким-то причинам нельзя использовать перечисление, то подойдут обычные именованные константы. Чаще всего для логирования используют статический класс, который фактически выполняет функции библиотеки: группирует внутри себя всю логику, не позволяя размазать логирование по другим классам. Вот так выглядит скелет класса, который должен реализовать требуемую функциональность.

public static class Logger
{
 public enum Level
 {
  DEBUG,
  INFO,
  WARNING,
  ERROR,
  FATAL
 }

 private static Level currentLevel = Level.DEBUG;
 private static string fileName = "logFIlename.log";

 public static Log(Level level, string message)
 {
  if(currentLevel >= level)
  {
   Log(level, string message, null);
  }
 }

 public static Log(Level level, string message, Exception exception)
 {
  if(currentLevel >= level)
  {
   if(/*файл существует*/)
   {
    /*Открываем файл для добавления*/
    /*Пишем в файл строку*/
    /*Закрываем файл*/
   }
  }
 }
}

Реализация записи в файл построчно сильно зависит от языка программирования, на котором пишется класс,а потому не приведена здесь совсем. Вместо этого я добавил комментарии, которые приблизительно описывают требуемые действия.
2. Более удобный Logger
Дополнительные требования:
• Должен иметь методы, соответствующие уровням вывода сообщений (для удобства);
• Должен получать настройки из файла (хотя бы уровень логирования и имя лог-файла);
• Должен иметь возможность ротации файлов.
Анализ требований: Создадим группу перегруженных методов, для более удобного использования в логируемом коде, тогда отпадёт необходимость указывать уровень логирования. Настройки из файла получаются один раз при запуске программы, поэтому инициализация помещена в статический конструктор класса (типа). Он вызывается один раз при создании в памяти этого типа (а не экземпляров типа). Так как класс статический, то и все его члены тоже должны быть статическими. Для реализации ротации файлов поместим в файл настроек два дополнительных параметра: лимит по времени и лимит по размеру. Если представить, что настройки хранятся в файле типа json, то файл настроек может выглядеть следующим образом:

{
  "currentLevel": 0,
  "logFileName": "simple.log",
  "rotationSizeLimit": 100,
  "rotationTimeLimit": "10:00:00"
}

public static class Logger
{
 public enum Level
 {
  DEBUG,
  INFO,
  WARNING,
  ERROR,
  FATAL
 }

 private static  Level _currentLevel;
 private static string _fileName;
 private static unsigned int _rotationSizeLimit;
 private static DateTime _rotationTimeLimit;

 static Logger()
 {
  if(/*Файл настроек не существует*/)
  {
   throw new Exception();  // Выбрасываем исключение, специфичное для вашего языка
  }
  /*Открываем файл на чтение*/
  string settings = /*Читаем все данные из файла в переменную*/;
  /*Закрываем файл*/
  ParseSettings(settings);
 }

 private static void ParseSettings(string settings)
 {
  /*Как-то парсим настройки*/
  _currentLevel = /*какое-то значение уровня*/;
  _fileName = /*какое-то имя файла*/;
  _rotationTimeLimit = /*Какое-то значение*/;
  _rotationSizeLimit = /*Какое-то значение*/;
 }

 public static Log(Level level, string message)
 {
  if(_currentLevel >= level)
  {
   Log(level, string message, null);
  }
 }

 public static Log(Level level, string message, Exception exception)
 {
  if(_currentLevel >= level)
  {
   if(/*файл _fileName существует*/)
   {
    if(IsNeedRotation(/*Указатель на файл*/))
    {
     /*Переименовываем старый файл (если необходимо, либо новый файл должен быть с новым именем)*/
     /*Создаём новый файл*/
    }
    else
    {
     /*Открываем файл для добавления*/
    }
   }
   else
   {
    /*Создаём новый файл*/
   }
   /*Пишем в файл строку*/
   /*Закрываем файл*/
  }
 }

 public static IsNeedRotation(/*Указатель на файл*/)
 {
  return (_rotationSizeLimit != -1 && /*размер файла*/ >= _rotationSizeLimit) 
  || (_rotationTimeLimit != null && /*Дата создания файла*/ >= _rotationTimeLimit);
 }

 public static Debug(string message)
 {
  if(_currentLevel >= Level.DEBUG)
  {
   Log(Level.DEBUG, message);
  }
 }

 public static Debug(string message, Exception exception)
 {
  if(_currentLevel >= Level.DEBUG)
  {
   Log(Level.DEBUG, message, exception);
  }
 }

 public static Info(string message)
 {
  if(_currentLevel >= Level.INFO)
  {
   Log(Level.INFO, message);
  }
 }

 public static Info(string message, Exception exception)
 {
  if(_currentLevel >= Level.INFO)
  {
   Log(Level.INFO, message, exception);
  }
 }

 public static Warn(string message)
 {
  if(_currentLevel >= Level.WARNING)
  {
   Log(Level.WARNING, message);
  }
 }

 public static Warn(string message, Exception exception)
 {
  if(_currentLevel >= Level.WARNING)
  {
   Log(Level.WARNING, message, exception);
  }
 }

 public static Error(string message)
 {
  if(_currentLevel >= Level.ERROR)
  {
   Log(Level.ERROR, message);
  }
 }

 public static Error(string message, Exception exception)
 {
  if(_currentLevel >= Level.ERROR)
  {
   Log(Level.ERROR, message, exception);
  }
 }

 public static Fatal(string message)
 {
  if(_currentLevel >= Level.FATAL)
  {
   Log(Level.FATAL, message);
  }
 }

 public static Fatal(string message, Exception exception)
 {
  if(_currentLevel >= Level.FATAL)
  {
   Log(Level.FATAL, message, exception);
  }
 }
}

Дальнейшие улучшения требуют композиции всех методов работы с файлом в отдельный класс. Также следует заметить, что дальнейшее улучшение Logger (при помощи добавления новых функций) является сложной операцией и, возможно, уже стоит всё-таки найти способ использовать стороннюю библиотеку.
3. Асинхронный Logger
В большинстве языков программирования присутствуют асинхронные функции записи в файл. Используйте их в функции Log, чтобы добиться асинхронной записи в файл. Также не забудьте, что при завершении работы программы следует позаботиться о том, чтобы все асинхронные операции завершились, иначе данные могут потеряться.
4. Потокобезопасный Logger
Чтобы использовать такой логгер в многопоточном приложении, необходимо добавить в реализацию функции работы с файлом мьютексы (в разных языках программирования могут называться по разному). Ваша задача позаботиться о том, чтобы файл блокировался на запись на минимально возможное время и при этом не возникало deadlock`ов. Это улучшение уже требует определенных навыков программирования и существенно снижает отказоустойчивость Logger при хоть сколько-нибудь неверной реализации.
5. Logger поддерживающий разные направления вывода
Не всегда удобно использовать именно запись в файл. Вместо этого можно передавать данные куда угодно, хоть по сети. Однако, стоит помнить, что если Вам необходимо писать в несколько мест, да ещё и не дай Бог в многопоточном приложении, то рекомендую любыми силами найти возможность использовать готовые библиотеки. Как минимум брать из них примеры кода. Если же необходимо использовать несколько логгеров, то можно воспользоваться шаблоном "Цепочка обязанностей".

Использование логгера

Пример вызова методов класса будет выглядеть примерно вот так:

Logger.Debug("Something happens")

Метод Debug() следует использовать в местах, где необходимо получить данные, не описывающие значимые события системы, но необходимые для настройки её корректного функционирования.
Например:

public int calculateDaysBeforeSunday()
{
  Logger.Debug("Вход в тело функции");
  var daysBeforeMonday = getDaysBeforeMonday();
  Logger.Debug(string.Format("Days before monday: %d", daysBeforeMonday);
  var result = daysBeforeMonday - 1;
  Logger.Debug("Выход из функции");
  return result;
}

В данном участке кода метод Debug() используется для вывода в лог служебной информации, позволяющей отследить исполнение функции calculateDaysBeforeSunday(). Эти данные не будут полезны после того как приложение будет готово, но могут оказать очень полезными на этапе разработки.

Метод Info() следует использовать в местах, где происходят важные для системы события, однако они являются штатными и не требуют вмешательства извне.
Например:

public void Registration(string email, string password)
{
  if(IsCorrectEmail(email) && IsSecurePassword(password)
  {
    writeNewUserToDb(email, password);
    Logger.Info(string.Format("Пользователь с адресом почты %s был успешно зарегистрирован", email);
  }
}

Из приведенного участка кода видно, что при успешной регистрации пользователя информация об этом попадает в лог-файл, а система продолжает работу в штатном режиме. Фактически этот метод может использоваться для журналирования (особенно если запись ведётся в отдельный файл).

Метод Warn() следует использовать в местах, где происходит неожиданная ситуация, не влияющая на работоспособность системы, однако не предусмотренная разработчиком.
Например:

public File OpenFileVer2(string filename)
{
  if(File.IsExist(filename)
  {
    if(checkFileVersion(filename) == "ver. 1")
    {
      Logger.Debug("Попытка открыть файл версии 1 как файл версии 2. Некоторые данные могут быть отображены некорректно");
    }
    return Open(filename, "rb", "ver. 2");
  }
  return null;
}

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

Метод Error является одним из самых часто применяемых. В подавляющем большинстве случаев он используется для того, чтобы логировать исключения. Его появление в логе говорит о том, что какая-то часть системы отработала неверно, однако это не обязательно ведёт за собой сбой работы всего приложения.

Например:

public float calculateDummyBodyMassIndex(float weight, float height)
{
  float dummyIndex = 0.0;
  try
  {
    dummyIndex = weight / height;
  }
  catch(ZeroDivisionException e)
  {
    Logger.Error("Не указан рост. Индекс не будет рассчитан!", e);
  }
  return dummyIndex;
}

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

Метод Fatal() пожалуй самый редко используемый метод. Появление такого события в логе говорит о том, что программа не смогла выполнится успешно, поэтому будет завершена. Фактически это как BSOD только не для операционной системы, а для приложения. Именно такие события и логирует этот метод.
Например:

public void LoadDecryptPayloadAlgorithm()
{
  if(!IsNetworkAvailable())
  {
    Logger.Fatal("Network is anavailable! Can't load decryption algorithm. Program can't execute");
    exit(NOT_AVAILABLE_PAYLOAD);
  }
  // ...
}

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

Заключение

Использовать самописный класс Logger не рекомендуется, однако в случае если это необходимо, следует придерживаться следующих правил проектирования класса:

• Должен быть проще палки. Ещё проще!
• Должен реализовывать только минимально необходимый функционал;
• Как минимум должен иметь пять уровней логирования;
• Должен писать только в один поток (файловый, сетевой, бинарный, и т. д.);
• Желательно делать статическим, чтобы ни один объект в системе не отвечал за его жизненный цикл

Использованные источники:
[1] https://habrahabr.ru/post/98638/
[2] https://stackoverflow.com/questions/5057567/how-to-do-logging-in-c
[3] https://softwareengineering.stackexchange.com/questions/221490/which-design-pattern-is-more-suitable-for-logging

Что почитать:
https://www.thekua.com/atwork/2008/11/application-logging-principles/
https://docs.python.org/3/howto/logging.html
https://habrahabr.ru/post/313686/