Blog| Создание класса Logger

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

Работоспособность
Код работает, как заявлено?
Лицензирование
Код выпущен под необходимой лицензией?
Соответствие
Код полностью перекрывает поставленную задачу?

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

Error - ошибка в работе системы, требующая вмешательства.
Что-то не сохранилось, что-то "отвалилось". Программа не сможет продолжать работу без вмешательства персонала. Ошибки этого уровня и выше требуют немедленной записи в лог, чтобы ускорить реакцию на них. Нужно понимать, что ошибка пользователя – это не ошибка системы. Если пользователь ввёл в поле букву, хотя ожидалось число – не надо писать об этом в лог ошибок.

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

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

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

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

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

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

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

Каналы логирования

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

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

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

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

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

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

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

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

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

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

Простейший 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)
    {
        Log(level, string message, null);
    }

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

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

Более удобный 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)
    {
        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)
    {
        Debug(message, null);
    }

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

    public static Info(string message)
    {
        Info(message, null);
    }

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

    public static Warn(string message)
    {
        Warn(message, null);
    }

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

    public static Error(string message)
    {
        Error(message, null);
    }

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

    public static Fatal(string message)
    {
        Fatal(message, null);
    }

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

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

Асинхронный Logger

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

Потокобезопасный Logger

Чтобы использовать такой логгер в многопоточном приложении, необходимо добавить в реализацию функции работы с каналом логирования мьютексы (в разных языках программирования могут называться по разному). Ваша задача позаботиться о том, чтобы файл блокировался на запись на минимально возможное время и при этом не возникало deadlock`ов. Это улучшение уже требует определенных навыков программирования и существенно снижает отказоустойчивость Logger при хоть сколько-нибудь неверной реализации.

Logger поддерживающий разные каналы логирования

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

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

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

public int calculateDaysBeforeSunday()
{
    Logger.Debug("Enter function");
    var daysBeforeMonday = getDaysBeforeMonday();
    Logger.Debug(string.Format("Days before monday: %d", daysBeforeMonday);
    var result = daysBeforeMonday - 1;
    Logger.Debug("Exit function");
    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;
}

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

Метод 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 не рекомендуется, однако в случае если это необходимо, следует придерживаться следующих правил проектирования класса:

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