Про логирование времени работы над задачей. Логирование как способ отлаживать код

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

Раньше я рассуждал просто. Моя работа заключается в том, чтобы писать код. Значит, когда я пишу код, я работаю. Получается, что мне нужно логировать время написания кода. После месяца таких логирований возникал вопрос: почему по цифрам получается, что вместо 40 часов в неделю я работал 25-30?

Первый же вывод, к которому легче всего прийти, - я весь месяц работал меньше положенного. Значит следующий месяц надо работать более активно! Но после месяца такой «активной» работы получалось, что работа-то сделана, а с самочувствием что-то явно не так. А ещё все лампочки горят красным , и работа как-то всё медленнее и медленнее работается.

Читателю со стороны, конечно, очевидно, что дело в неправильном логировании. Но если подходить к работе ответственно, самостоятельно в это сложно поверить. Ведь ты по-честному логируешь время, которое потратил на задачу, и по ощущениям ты не можешь потратить на неё больше. «Но у других ведь получается?»

За ответом можно сходить в храм под названием «Наука». Вот что рассказывает Барбара Окли в первом же видео курса Learning How to Learn (в недавней годноте была ссылка на конспект курса):

Что вы делаете, когда не получается до чего-то «додуматься»? Для зомби всё просто: они просто продолжают биться головой о стену. Но живой мозг куда сложнее. Однако, если вы поймёте хотя бы основы того, как он работает, то сможете учиться с большей лёгкостью и с меньшим разочарованием.

Исследователи выяснили, что у нас есть два абсолютно разных «режима мышления». Назовём их сфокусированный и расслабленный.

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

Используем аналогию с пинболом, чтобы разобраться.

Если вы помните, пинбол работает так: вы оттягиваете поршень, затем отпускаете его, он бьёт по шарику, и тот движется внутри автомата, сталкиваясь с резиновыми препятствиями и тем самым накапливая вам очки. Это похоже на то, как работает мозг. В сфокусированном режиме резиновые препятствия стоят очень близко друг к другу, и шарик может двигаться по одной и той же «тропинке», безрезультатно пытаясь вырваться за пределы. А за пределами этих препятствий (может даже совсем в другом углу «автомата») вполне может быть «правильная тропинка», которая приведёт вас к решению текущей задачи. И что же делать в таком случае?

Чтобы добраться до этой «правильной тропинки» вам нужен иной способ мышления - расслабленный. В нём препятствия стоят на большем расстоянии друг от друга, и потому шарик может спокойно двигаться от одного к другому, затрагивая максимально возможное количество оных, и таким образом создавая новые нейронные связи, которых так не хватало в сфокусированном режиме.

Важно понимать, что вы не можете находиться в обоих режимах сразу. Это как монета, которая может быть повёрнута к вам только одной стороной: или сфокусированной, или расслабленной.

Это был мой вольный перевод-пересказ первой лекции , которая доступна без подписки на курс. Лучше посмотрите оригинал, если понимаете английский.

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

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

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

Нужно логировать всё, что помогает решить задачу. В том числе и отдых.

Почему так важно запретить самому себе отладку руками?

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

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

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

Проблематика: Сложно отлаживать составной код

1. Разбить на отдельные части
2. Выкидываем отладку, просто запрещаем пользоваться режимом Debug
3. Анализируем отдельные части (придумываем для них невалидные ситуации, граничные случаи)
4. Пишем тесты на каждую отдельную часть всего алгоритма
5. В тестах иногда приходится узнавать промежуточные данные, но…
   Отладка нам боле недоступна, поэтому втыкаем Trace в те части, где возникает подозрение на некорректное выполнение алгоритма
6. По трассировке нужно понять причину проблемы
7. Если не понятно, то чаще всего либо стоит написать ещё тест, либо выполнить трассировку на один этап раньше

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

Давайте посмотрим пример. Вы знаете, что по отдельности все реализации интерфейсов работают (т.к. написаны тесты, доказывающие это). Но при взаимодействии всего вместе возникает некорректное поведение. Что вам нужно? Нужно логировать ответы от «корректных» интерфейсов:

Void Register(User user) { // на этом участке не нужно ничего логировать, // т.к. всё будет понятно из исключения var isExists = _userRepository.IsUserExists(user); if (isExists) { throw new InvalidOperationException($"User already exists: {user}"); } // а вот это уже можно и залогировать, // т.к. от этого зависят дальнейшие детали алгоритма var roleInOtherService = _removeService.GetRole(user); _log.Trace($"Remote role: {roleInOtherService}") switch (roleInOtherService) { case "...": break; ... } // тут нам не критично, если пользователю не добавили // определённые привелегии в каком-то удалённом сервисе, // но мы бы хотели знать об этом foreach (var privilege in Privileges) { var isSuccess = _privilegeRemoteService.Grant(user, privilege); if (isSuccess) { _log.Trace($"Add privilege: {privilege} to User: {user}"); } else { _log.Trace($"Privilege: {privilege} not added to User: {user}"); } } ... }
В этом примере видно, как мы трассируем отдельные части алгоритма для того, чтобы можно было зафиксировать тот или иной этап его выполнения. Посмотрев на логи, станет ясно в чём причина. В реальной жизни весь этот алгоритм стоило бы разбить на отдельные методы, но суть от этого не меняется.

Всё это в разы ускоряет написание кода. Вам не нужно бежать по циклу с F10 для того, чтобы понять на какой итерации цикла возникла проблема. Просто залогируйте состояние нужных вам объектов при определённых условиях на определённой итерации цикла.

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

Что если нам не нужен этот мусор? В таком случае выполняйте трассировку только в рамках отладки, а затем подчищайте за собой.

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

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

Типы логов (механизмы логирования информации)

Конфигурирование логирования

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

Интенсивное логирование может серьезно повлиять на производительность системы

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

1. Имя файла, директория или полный путь к тому файлу, в который пишется лог. Это очень полезно, если логирование необходимо и есть возможность или необходимость организовать запись логов на отдельный жесткий диск, сетевой диск и т. п. Такой способ удобен, если логи будут интерпретироваться сторонним приложением, которое находится на отдельном компьютере и каким-либо образом может повлиять на работу основной системы.
2. Критерий замены лога (Log Rotation). Рано или поздно логи становятся большими или их становится слишком много. Чтобы избежать проблем, которые с этим связаны (постоянная работа с огромным файлом отрицательно сказывается на производительности системы), программы, осуществляющие логирование, обычно используют что-нибудь из следующего списка возможностей управления логами:
   • Каждый день (неделю, месяц и т. д.) система использует новый лог-файл. Обычно если смена лог-файлов связана с каким-либо исчислением времени (каждый день, каждый год и т. п.), то в имени используется время (дата и время или только дата, иногда какая-нибудь производная) создания или финального закрытия (финализации) данного лог-файла. Если система использует уникальное имя (а имя с датой, временем или их производной можно считать уникальным, так как время монотонно возрастает), то такие логи обычно не очищаются системой. К примеру, Symantec Antivirus или Tivoli Access Manager for e-Business используют лог-файлы, которые хранят в своем имени время смены лог-файла. В множестве таких логов, которые, к примеру, скопились за долгое время, очень удобно искать информацию, относящуюся к конкретному промежутку времени. Кроме того, выработав критерий длительности хранения старых логов, довольно легко очищать уже устаревшие логи.
   • Смена файла происходит по достижении им определенного размера. Старый файл обычно сохраняется определенное время. Может быть, удаление старых файлов оставлено на решение пользователя, то есть в случае с файлами, которые хранят в своем имени дату и время, они могут храниться вечно, так как система не заботится о них, но пользователь в любой момент может решить, что старые файлы ему не нужны, и удалить их. В этом, кстати, дополнительное удобство — в имени файла хранится дата его создания, то есть всегда легко понять, нужен такой файл или нет. Имя файла может содержать порядковый номер этого лога, то есть каждая последующая смена увеличивает счетчик на единицу. Количество таких файлов тоже может быть произвольно, кроме того, они могут быть дополнительно заархивированы, что экономит некоторое место при длительном хранении. Типичным примером является Linux (UNIX) Syslog, который позволяет настраивать как размер файла, так и количество используемых файлов.
   • Смена файла происходит одновременно с перезапуском сервиса, который пишет лог. Случай представляет собой некоторую опасность, так как в некоторых случаях сервис может не перезапускаться месяцами, а то и годами. Это приводит (точно-точно, такие случае не очень часты, но все равно бывают) к тому, что в определенный момент становится понятно, что лог-файл уже занимает огромное место на жестком диске, которое рациональнее использовать для чего-либо иного. Используется, к примеру, HP Tru64 UNIX (вообще говоря, HP Tru64 имеет некое ограничение на размер Audit Log, которые пишутся между перезапуском сервисов, но это ограничение довольно велико – около 300 Mб).
   • Частота сброса информации в файл. Такой параметр редко предоставляется для открытой модификации, но довольно часто он все же присутствует (к примеру, Tivoli Access Manager for e-Business). Он хорош тем, что при грамотной настройке несколько уменьшает число обращений к жесткому диску от логирующей программы, а плох тем, что, модифицировав его, довольно легко серьезно снизить производительность сервера.

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

Набор событий, которые будут логироваться. Довольно часто важно иметь возможность настроить логирование только тех событий, которые реально необходимы. К примеру, часто нет необходимости логировать информацию обо всех транзакциях в базе данных, особенно если это куча select-запросов, которые, вероятно, не содержат угрозы с точки зрения безопасности. В таком случае можно изрядно снизить нагрузку на сервер, выключив логирование транзакций, но оставив учет только реально необходимых событий: попыток авторизации, попыток доступа к файлам, изменения системных настроек и т. п. Обычно производитель предоставляет свои профили логирования: от полного выключения и до полного логирования всего происходящего. Довольно часто есть возможность указать даже не профиль, а настройки логирования для каждого конкретного события (например, такая возможность есть в MS SQL Server C2 Audit). Такие настройки позволяют сделать очень гибкое логирование информации, которая нужна в конкретном случае. Увы, но настройка логируемых событий встречается далеко не во всех программах.

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

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

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

Вообще, на сегодняшний момент ни одно более или менее серьезное приложение не обходится без написания логов.

Лог (log) - это специальный журнал, в котором хранится информация о состоянии работы приложения (программы).

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

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

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

Trace - максимально детальная информация о том, что происходит с целевым участком кода, по шагам . Например: Попытка открыть подключение к БД, успешно\неуспешно. Сколько времени заняла эта операция. Сколько времени выполнялась выборка из БД, успешно\неуспешно. Сколько записей извлечено. Какая была нагрузка на систему, сколько использовано памяти. Сколько записей прошло нужную фильтрацию. Сколько записей оказалось в результирующей выборке, куда эти записи отправились дальше. Проверка нужных значений в каждой записи.

Debug - это информация для отладки. Логирование крупных операций, менее детально, чем в Trace. Здесь мы не так подробно описываем весь процесс операции, но, тем не менее, заносим в журнал основные операции . Например: Совершено обращение к БД. Из базы выбрано N записей. Записи успешно обработаны и отправлены клиенту.

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

Warn - сообщения о странной или подозрительной работе приложения. Это еще не серьезная ошибка, но следует обратить внимание на такое поведение системы. Например: Добавлен студент с возрастом 2 года. Студент получил отрицательный балл. Преподаватель завершил курс, в котором училось 0 студентов. В группе находится больше студентов, чем максимально возможно.

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

Fatal - сообщения об очень серьезных ошибках в системе. Чаще всего это связано с работоспособностью всего приложения или его окружения на сервере. На такие сообщения следует реагировать МАКСИМАЛЬНО оперативно. Например: Приложение постоянно перезагружается из-за нехватки памяти или места на жестком диске. Приложение завершило работу по неизвестной причине. Нет доступа к базе данных. Нет доступа к сети. Заблокирован какой-то порт.

То есть, прежде чем отправить какое-то сообщение в лог, нам нужно отнести его к той или иной группе.

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

Подобным образом мы можем описать, как работает наше приложение в целом, сообщения будут с пометкой Info.

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

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

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

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

Для того, чтобы начать логирование, мы подключим в наш проект платформу 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 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 лет"); //...

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, также рассмотрели ее возможности и как можно настроить генерацию логов на этой платформе.

Давайте научимся следить за выполнением логики в нашей программе, для этого мы научимся использовать логирование, поймем зачем оно и где используется.

Шаг 0. Обзор

Логирование – не используя термины википедии, то это возможность следить за процесом выполнения бизнес-логики проекта.

Зачем нужно логирование и что оно даёт?

Допустим у вас есть WEB-проект, и он что-то делает, сейчас не важно что именно. Допустим это интернет магазин, на котором при оформлении заказа нужно отправить на почту покупателю отчет о его покупке, но почтовый сервер вышел из строя, и программно письмо не отправилось.

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

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

В данном уроке мы рассмотрим как сконфигурировать и начать использовать Log4j.

Шаг 1. Создаем проект и добавляем завимости

Запускаем всеми любимую Intellij IDEA и тыкаем New Project выбираем Maven Module и называем его:

Теперь в pom.xml жлбавим зависимость:

log4j log4j 1.2.17

Это все зависимости, которые надо было подключить.

Шаг 2. Создание примитивной логики для примера

Давайте создадим класс в котором была бы бизнес-логика, назовем его OrderLogic :

Package com.devcolibri.logpack; public class OrderLogic { public void doOrder(){ // какае-то логика System.out.println("Заказ оформлен!"); addToCart(); } private void addToCart() { // добавление товара в корзину System.out.println("Товар добавлен в корзину"); } }

Хочу обратить ваше внимание на то, что логика данного проекта не важна, так как мы рассматриваем логирование, для этого я и подготовил примитивную логику класса OrderLogic.

И теперь создаем Main класс:

Package com.devcolibri.logpack; public class Main { private static OrderLogic logic; public static void main(String args) { logic = new OrderLogic(); logic.doOrder(); } }

В результате выполнения данного кода, мы получим следующее:

Заказ оформлен! Товар добавлен в корзину

Как видите пока ничего нового.

Шаг 3. Конфигурируем Log4j

Чтобы гибко управлять логированием стоит создать в resources/ файл log4j .properties:

Теперь в этот файл добавим пару строк конфигураций:

# Уровень логирования log4j.rootLogger=INFO, file # Апендер для работы с файлами log4j.appender.file=org.apache.log4j.RollingFileAppender # Путь где будет создаваться лог файл log4j.appender.file.File=C:\\TMP\\log_file.log # Указываем максимальный размер файла с логами log4j.appender.file.MaxFileSize=1MB # Конфигурируем шаблон вывода логов в файл log4j.appender.file.layout=org.apache.log4j.PatternLayout log4j.appender.file.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1}:%L - %m%n

Теперь давайте более детальней разберем строку формирования шаблона:

Log4j.appender.file.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1}:%L - %m%n

Значения:

%d{yyyy-MM-dd HH:mm:ss} – выводит дату в формате 2014-01-14 23:55:57

%-5p – выводит уровень лога (ERROR , DEBUG , INFO …), цифра 5 означает что всегда использовать 5 символов остальное дополнится пробелами, а минус (-), то что позиционирование по левой стороне.

%L – номер строки в которой произошёл вызов записи в лог.

%m – сообщение, которое передали в лог.

%n – переход на новую строку.

Шаг 4. Добавляем примитивное логирование

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

Package com.devcolibri.logpack; import org.apache.log4j.Logger; public class OrderLogic { // Инициализация логера private static final Logger log = Logger.getLogger(OrderLogic.class); public void doOrder(){ // какае-то логика System.out.println("Заказ оформлен!"); // логируем инфо log.info("Это информационное сообщение!"); addToCart(); } private void addToCart() { // добавление товара в корзину System.out.println("Товар добавлен в корзину"); // логируем ошибку log.error("Это сообщение ошибки"); } }

Теперь давайте запустим код опять. Мы получим тот же результат, вот только уже по пути C://TMP/ будет лежать файл log_file.log со следующим содержимым:

2014-01-14 23:55:57 INFO OrderLogic:12 - Это информационное сообщение! 2014-01-14 23:55:57 ERROR OrderLogic:19 - Это сообщение ошибки