Ведение логов помогает разработчику в процессе создания и последующего сопровождения приложения, при поиске ошибок в коде и в разрешении непонятных ситуаций, когда наше приложение в момент работы ведет себя странным образом, и нам нужно найти причину такого поведения.
Любой разработчик сталкивается с подобными ситуациями, когда какой-то компонент приложения отрабатывает странным образом, выдает не тот результат или вообще перестает работать. Использование логов поможет нам в подобных ситуациях. Время поиска проблемных мест в нашем коде сократится в разы, и мы быстрее сможем решить ту или иную проблему.
Вообще, на сегодняшний момент ни одно более или менее серьезное приложение не обходится без написания логов.
Под таким журналом можно понимать и записи в обычный текстовый файл, и записи в базу данных, и записи на удаленный веб-сервис, и даже email-письма на определенный адрес о тех или иных состояниях нашего приложения.
Какие записи делать в этот журнал, то есть, какую конкретно информацию записывать, определяет сам разработчик. Это могут быть сведения о том, что все работает в штатном режиме, то есть просто ежедневный мониторинг нашего приложения, или что произошла какая-то ошибка, на которую нужно максимально срочно отреагировать и устранить, и так далее.
Всего существует шесть уровней логирования, каждый из которых предназначен для сообщений того или иного типа, той или иной важности:
Trace – максимально детальная информация о том, что происходит с целевым участком кода, по шагам. Например: Попытка открыть подключение к БД, успешно\неуспешно. Сколько времени заняла эта операция. Сколько времени выполнялась выборка из БД, успешно\неуспешно. Сколько записей извлечено. Какая была нагрузка на систему, сколько использовано памяти. Сколько записей прошло нужную фильтрацию. Сколько записей оказалось в результирующей выборке, куда эти записи отправились дальше. Проверка нужных значений в каждой записи.
Debug – это информация для отладки. Логирование крупных операций, менее детально, чем в Trace. Здесь мы не так подробно описываем весь процесс операции, но, тем не менее, заносим в журнал основные операции. Например: Совершено обращение к БД. Из базы выбрано N записей. Записи успешно обработаны и отправлены клиенту.
Info – это более общие информационные сообщения о текущей работе приложения, что происходит с системой в процессе ее использования. Например: Была выгрузка студентов в Excel-файл. На сайте зарегистрирован новый студент. Студент добавил новый отчет. Студент перемещен в другую группу.
Warn – сообщения о странной или подозрительной работе приложения. Это еще не серьезная ошибка, но следует обратить внимание на такое поведение системы. Например: Добавлен студент с возрастом 2 года. Студент получил отрицательный балл. Преподаватель завершил курс, в котором училось 0 студентов. В группе находится больше студентов, чем максимально возможно.
Error – сообщения об ошибках в приложении. Подобные сообщения – это уже большая проблема, которую нужно решить для дальнейшей правильной работы системы. Например: Ошибка сохранения нового студента в БД. Невозможно загрузить студентов в данной группе. Ошибка при входе в личный кабинет студента.
Fatal – сообщения об очень серьезных ошибках в системе. Чаще всего это связано с работоспособностью всего приложения или его окружения на сервере. На такие сообщения следует реагировать МАКСИМАЛЬНО оперативно. Например: Приложение постоянно перезагружается из-за нехватки памяти или места на жестком диске. Приложение завершило работу по неизвестной причине. Нет доступа к базе данных. Нет доступа к сети. Заблокирован какой-то порт.
То есть, прежде чем отправить какое-то сообщение в лог, нам нужно отнести его к той или иной группе.
Например, мы написали новый функционал и хотим его протестировать, как правильно и быстро он работает. Для этого мы будем использовать тип сообщений Trace, то есть все наши сообщения в логе будут помечены как Trace.
Подобным образом мы можем описать, как работает наше приложение в целом, сообщения будут с пометкой Info.
Если же в опасных участках кода мы генерируем исключение, то теперь мы также добавим запись в лог с пометкой Error.
К какой группе отнести то или иное сообщение решает сам разработчик. К данному вопросу следует подойти с максимальной серьезностью. Очевидно, что ошибки не следует помечать как Info, не следует игнорировать ошибки и просто не записывать их в лог. От правильно настроенной системы логирования будет зависеть простота сопровождения всей системы, оперативность реагирования на ошибки и время, затраченное на устранение проблемы.
Иногда разработчики ленятся писать логи, не хотят тратить на это время. В дальнейшем оказывается, что время, затраченное на поиск и исправление ошибок, в разы больше времени, которое потребовалось бы на создание системы логов.
Естественно, многое зависит от сложности проекта. Если вы создаете простейший трехстраничный сайт-визитку или консольное приложение для собственных нужд у себя на локальном компьютере, то написание сложной системы логирования может быть дольше, чем создание самого проекта. В таком случае в логи можно записывать только сообщения об ошибках или почему упал сайт. Но если вы работаете над сложным проектом в команде с другими разработчиками, то грамотное ведение логов просто обязательно.
Для того, чтобы начать логирование, мы подключим в наш проект платформу NLog. Это можно легко сделать посредством менеджера NuGet (прямо из Visual Studio).
Обратите внимание на конфигурационный файл NLog.config. В этом файле находятся настройки логгера (куда будут выводиться логи, формат записи логов и т.д.). Давайте настроим файл следующим образом:
<targets>
<target xsi:type="File" name="main" fileName="${basedir}/logs/${shortdate}.log" layout="${longdate} | ${callsite} | ${uppercase:${level}} | ${message} ${newline}" />
<target xsi:type="File" name="error" fileName="${basedir}/logs/errors/${shortdate}.log" layout="${longdate} | ${callsite} | ${uppercase:${level}} | ${message} ${newline}" />
</targets>
<rules>
<logger name="*" maxlevel="Warn" writeTo="main" />
<logger name="*" minlevel="Error" writeTo="error" />
</rules>
Здесь мы описали два правила и цели, к которым они применяются. Мы хотим чтобы отладочная информация была записана в один файл, а информация об ошибках - в другой (в поддиректории errors). Оба лога будут писаться в текстовый файл. Также мы используем специальные теги (директивы), которые понимает NLog. На их место будут подставлены соответствующие значения в процессе выполнения. Опишем теги, которые используются у нас в конфигурации (описание всех тегов и любую другую информацию можно найти на официальном сайте проекта NLog):
- ${basedir} - корневой каталог нашего приложения
- ${shortdate} - текущая дата в формате yyyy-MM-dd
- ${longdate} - текущая дата в формате yyyy-MM-dd HH:mm:ss.ffff
- ${callsite} - место вызова лога (название класса, название метода)
- ${uppercase:${level} - уровень логирования
- ${message} - непосредственно сообщение, которое будет записано в лог
- ${newline} - символ новой строки
Далее уже в коде объявим новый логгер (здесь код проекта приводится в сокращенном виде, исходный код всего проекта можно скачать в конце статьи):
public class StudentsRepository
{
private static Logger logger = LogManager.GetCurrentClassLogger();
//...
}
Чаще всего следует объявлять один статичный логгер в пределах всего класса. Здесь мы посредством класса-менеджера LogManager объявили новый логгер, с которым будем работать.
Начнем логирование с уровня Trace. В методе, где мы выбираем студента по его идентификатору, давайте максимально подробно опишем как это происходит:
public Student GetStudentById(int id)
{
//здесь моделируется ситуация реальной выборки студента из базы данных...
logger.Trace("Запрашиваемый id студента: " + id);
logger.Trace("Попытка подключения к источнику данных");
logger.Trace("Подключение к источнику данных прошло успешно. Затраченное время(мс): " + new TimeSpan(0, 0, 0, 0, 20).Milliseconds);
var student = _studentsList.FirstOrDefault(x => x.Id == id);
logger.Trace("Выборка прошла успешно. Выбран студент с id==" + student.Id);
return student;
}
Обратите внимание, что мы на объекте logger вызываем метод Trace(). Он имеет соответствующее значение - запись в лог сообщения типа Trace. Если обратиться к определению класса Logger, то можно обнаружить, там также присутствуют и другие методы для всех уровней лога, которые мы будем использовать далее.
Теперь давайте добавим несколько сообщений уровня Debug. Как мы помним, это тоже отладочная информация, но менее детальная. Данный подход мы используем в другом методе, для наглядности:
public List<Student> GetStudents()
{
//здесь моделируется ситуация реальной выборки студентов из базы данных...
logger.Debug("Произведено подключение к базе данных");
logger.Debug("Произведена выборка всех студентов");
return _studentsList;
}
Идем далее. На уровне Info мы описываем регулярные операции в нашем приложении, то есть поднимаемся еще на уровень выше. Предположим, что мы работаем над ASP.NET MVC приложением, и у нас есть действие в контроллере, которое обращается к ранее описанному методу GetStudentById():
public ActionResult GetStudent(int id)
{
logger.Info("Преподаватель запросил студента с id == " + id);
StudentsRepository repository = new StudentsRepository();
Student student = repository.GetStudentById(id);
return View(student);
}
Теперь добавим в логи сообщения уровня Warn. Как мы помним, на этом уровне логирования мы описываем все потенциально опасные ситуации, странное и нелогичное поведение компонентов. Будем заносить в лог запись, если студенту меньше 15 лет:
//...
Student student = repository.GetStudentById(id);
logger.Trace("Выборка прошла успешно. Выбран студент с id==" + student.Id);
if (student.Age < 15)
logger.Warn("Выбран студент моложе 15 лет");
//...
Далее обработаем ошибку в нашем коде и запишем в лог сообщение уровня Error:
var student = _studentsList.FirstOrDefault(x => x.Id == id);
if (student == null)
logger.Error("Ошибка. Не найден студент с id == " + id);
logger.Trace("Выборка прошла успешно. Выбран студент с id==" + student.Id);
if (student.Age < 15)
logger.Warn("Выбран студент моложе 15 лет");
Теперь определим, что же нам записать на уровне Fatal. В нашем простейшем примере просто смоделируем подобную ситуацию:
//...
logger.Fatal("Достигнут максимально допустимый в приложении предел использования оперативной памяти 90%");
//...
Мы рассмотрели все шесть уровней логирования и описали процесс работы нашего приложения максимально подробно. Теперь мы можем сразу проанализировать работу сайта, просто изучив логи, и не заглядывать в исходный код.
Подобным образом происходит логирование. В нашем простейшем примере, где мы моделируем работу со студентами, все предельно ясно и прозрачно даже без логов. Но в сложных проектах ведение логов является неотъемлемой частью разработки.
Конечно, это далеко не полные возможности настройки платформы NLog. В конфигурационном файле можно настроить запись логов в другие места, например, в базу данных, на консоль, в оперативную память, отправлять как емаил-сообщение, отправлять сообщения по сети и так далее. Также можно настроить фильтрацию сообщений, более сложный шаблон сообщений. Если вас не устраивает стандартный функционал логгера, то можно написать свое собственное расширение и подключить.
На этом здесь все, давайте подведем небольшой итог. Мы изучили тему логирования в приложении. Посмотрели как правильно логировать те или иные участки кода, а также познакомились с одной из самых популярных платформ логирования – это NLog Platform, также рассмотрели ее возможности и как можно настроить генерацию логов на этой платформе.
Видеокурс C#. От простого к сложному
