Недавно мы разбирали, что такое логгеры, и подключали их к проектам на JavaScript. Смысл в том, чтобы научить наши программы отчитываться о своей работе, что упростит нам отладку.
Вот короткая версия того, что было в предыдущих частях:
- логгер — это специальный модуль или библиотека, которая фиксирует определённые события в нашей программе;
- на что реагировать и как фиксировать — решает программист;
- для этого он пишет специальную команду типа лог.добавить(‘Запускаем главный модуль’) или лог.ошибка(‘Файл не найден’) ;
- сам по себе лог ничего не исправляет — он только сообщает о том, что происходит в программе;
- есть несколько основных уровней логирования — ошибки, предупреждения, информационные сообщения, сообщения отладки и разовые события;
- эти уровни нужны для того, чтобы фильтровать сообщения по степени важности, например посмотреть только сообщения об ошибках или о штатных срабатываниях;
- лог можно выводить в консоль, в файл или передавать с помощью сокетов или API в другую программу;
- когда мы подключили логгер в наш проект с арканоидом на JavaScript, то неожиданно для себя нашли ошибку, которую без логгера мы не замечали.
Теперь поработаем с логгером в проекте на Python и посмотрим, найдём ли мы ещё ошибки в своём коде.
Профессиональная отладка программ | Ведение логов | Сообщения об ошибках в программе | debug
Настраиваем логгер
Обратите внимание, что мы на объекте logger вызываем метод Trace(). Он имеет соответствующее значение — запись в лог сообщения типа Trace. Если обратиться к определению класса Logger, то можно обнаружить, там также присутствуют и другие методы для всех уровней лога, которые мы будем использовать далее.
Теперь давайте добавим несколько сообщений уровня Debug. Как мы помним, это тоже отладочная информация, но менее детальная. Данный подход мы используем в другом методе, для наглядности:
public List GetStudents() < //здесь моделируется ситуация реальной выборки студентов из базы данных. logger.Debug(«Произведено подключение к базе данных»); logger.Debug(«Произведена выборка всех студентов»); return _studentsList; >
Идем далее. На уровне Info мы описываем регулярные операции в нашем приложении, то есть поднимаемся еще на уровень выше. Предположим, что мы работаем над ASP.NET MVC приложением, и у нас есть действие в контроллере, которое обращается к ранее описанному методу GetStudentById():
public ActionResult GetStudent(int id)
Теперь добавим в логи сообщения уровня Warn. Как мы помним, на этом уровне логирования мы описываем все потенциально опасные ситуации, странное и нелогичное поведение компонентов. Будем заносить в лог запись, если студенту меньше 15 лет:
//. Student student = repository.GetStudentById(id); logger.Trace(«Выборка прошла успешно. Выбран студент с + student.Id); if (student.Age < 15) logger.Warn(«Выбран студент моложе 15 лет»); //.
Далее обработаем ошибку в нашем коде и запишем в лог сообщение уровня Error:
Что такое лог (log) программы
var student = _studentsList.FirstOrDefault(x => x.Id == id); if (student == null) logger.Error(«Ошибка. Не найден студент с » + id); logger.Trace(«Выборка прошла успешно. Выбран студент с + student.Id); if (student.Age < 15) logger.Warn(«Выбран студент моложе 15 лет»);
Теперь определим, что же нам записать на уровне Fatal. В нашем простейшем примере просто смоделируем подобную ситуацию:
//. logger.Fatal(«Достигнут максимально допустимый в приложении предел использования оперативной памяти 90%»); //.
Логирование в Java: что, как, где и чем?
Давайте разберем реальные случаи, в которых логирование решало бы проблему. Вот пример из моей работы. Есть точки приложений, которые интегрируются с другими сервисами. Я использую логирование этих точек для “алиби”: если интеграция не сработает, будет легко разобраться, с какой стороны возникла проблема.
Еще желательно логировать важную информацию, которая сохраняется в базу данных. Например создание пользователя администратора. Это как раз то, что хорошо бы логировать.
Инструменты для логирования в Java
Из известных решений по логированию в Java можно выделить:
- log4j
- JUL — java.util.logging
- JCL — jakarta commons logging
- Logback
- SLF4J — simple logging facade for java
| Обзорно рассмотрим каждое из них, а в практической части материала возьмем за основу связку Slf4j — log4j. Сейчас это может показаться странным, но не переживайте: к концу статьи все будет понятно. |
System.err.println
Первоначально был, разумеется, System.err.println (вывод записи в консоль). Его и сейчас используют для быстрого получения лога при дебаге. Конечно, говорить о каких-то настройках здесь не приходится, поэтому просто запомним его и пойдем дальше.
Log4j
Это уже было полноценное решение, которое создавалось из потребностей разработчиков. Получился действительно интересный инструмент, который можно использовать. В силу разных обстоятельств это решение так и не попало в JDK, чем очень расстроило все комьюнити.
В log4j были возможности по конфигурации таким образом, чтобы можно было включить логирование в пакете com.example.type и выключить его в подпакете com.example.type.generic . Это позволяло быстро отсечь то, что нужно логировать, от того, что не нужно. Здесь важно отметить, что есть две версии log4j: 1.2.х и 2.х.х, которые несовместимы друг с другом. log4j добавил такое понятие как appender, то есть инструмент, с помощью которого записываются логи и layout — форматирование логов. Это позволяет записывать только то, что нужно и как нужно. Больше о appender поговорим чуть позже.
JUL — java.util.logging
Одно из ключевых преимуществ это решения — JUL включен в JDK (Java development kit). К сожалению, при его разработке за основу взяли не популярный log4j, а решение от IBM, что и повлияло на его развитие. По факту на данный момент JUL есть, но им никто не пользуется. Из “такого себе”: в JUL уровни логирования отличаются от того, что есть в Logback, Log4j, Slf4j, и это ухудшает понимание между ними. Создание логгера более менее похожее. Для этого нужно сделать импорт:
java.util.logging.Logger log = java.util.logging.Logger.getLogger(LoggingJul.class.getName());
Имя класса специально передается для того, чтобы знать, откуда идет логирование. Начиная с Java 8, можно передавать Supplier . Это помогает считать и создавать строку только в тот момент, когда это действительно нужно, а не каждый раз, как это было до этого. Только с выходом Java 8 разработчики решили важные проблемы, после чего JUL по-настоящему стало возможно в использовании. А именно, методы с аргументом Supplier msgSupplier , как показано ниже:
public void info(Supplier msgSupplier)
JCL — jakarta commons logging
Из-за того, что долгое время не было промышленного стандарта в логировании и был период, когда многие создавали свой кастомный логгер, решили выпустить JCL — общую обертку, которая использовалась бы над другими. Почему? Когда в проект добавлялись какие-то зависимости, они могли использовать логгер, отличный от логгера на проекте.
Из-за этого они транзитивно добавлялись в проект, что создавало реальные проблемы при попытке все это собрать воедино. К сожалению, обертка была очень бедна на функциональность и никаких дополнений не вносила. Наверное, было бы удобно, если бы все использовали JCL для работы. Но на деле так не получалось, поэтому на данный момент применять JCL — не лучшая идея.
Logback
- улучшена производительность;
- добавлена нативная поддержка slf4j;
- расширена опция фильтрации.
app.log %d %-5p [%c] — %m%n
SLF4J — simple logging facade for java
Где-то в 2006 году один из отцов-основателей log4j вышел из проекта и создал slf4j — Simple Logging Facade for Java — обертку вокруг log4j, JUL, common-loggins и logback.
Как видим, прогресс дошел до того, что создали обертку над оберткой… Причем она делится на две части: API, который используется в приложении и реализация, которая добавляется отдельными зависимостями для каждого вида логирования. Например, slf4j-log4j12.jar , slf4j-jdk14.jar . Достаточно подключить правильную реализацию и все: весь проект будет работать с ней. Slf4j поддерживает все новые функции, такие как форматирование строк для логирования. До этого была такая проблема. Допустим, есть запись в лог:
log.debug(«User » + user + » connected from » + request.getRemoteAddr());
В объекте user происходит неявное преобразование user.toString() из-за конкатенации строк, и это занимает время, которое тормозит систему. И все ок, если мы дебажим приложение. Проблемы начинаются, если для этого класса уровень логирования INFO и выше.
То есть этот лог не должен быть записан, и конкатенация строк также не должна быть произведена. По идее это должна была решить сама библиотека логирования. Причем это и оказалось самой большой проблемой первой версии log4j. Решения нормального не завезли, а предложили делать вот так:
if (log.isDebugEnabled())
То есть вместо одной строки логирования предлагали писать 3(!). Логирование должно минимизировать изменения в коде, и три строки явно противоречили общему подходу. У slf4j не было проблем совместимости с JDK и API, поэтому сходу возникло красивое решение:
log.debug(«User <> connected from <>», user, request.getRemoteAddr());
где <> обозначают вставки аргументов, которые передаются в методе. То есть первая <> соответствует user , вторая <> — request.getRemoteAddr() . Благодаря чему, только в случае, если уровень логирования позволяет записывать в лог, это сообщение конкатенировать в единое. После этого SJF4J стал быстро расти в популярности, и на данный момент это лучшее решение. Поэтому будем рассматривать логирование на примере связки slf4j-log4j12 .
Что нужно логировать
- Начало/конец работы приложения. Нужно знать, что приложение действительно запустилось, как мы и ожидали, и завершилось так же ожидаемо.
- Вопросы безопасности. Здесь хорошо бы логировать попытки подбора пароля, логирование входа важных юзеров и т.д.
- Некоторые состояния приложения. Например, переход из одного состояния в другое в бизнес процессе.
- Некоторая информация для дебага, с соответственным уровнем логирования.
- Некоторые SQL скрипты. Есть реальные случаи, когда это нужно. Опять-таки, умелым образом регулируя уровни, можно добиться отличных результатов.
- Выполняемые нити(Thread) могут быть логированы в случаях с проверкой корректной работы.
Популярные ошибки в логировании
- Избыток логирования. Не стоит логировать каждый шаг, который чисто теоретически может быть важным. Есть правило: логи могут нагружать работоспособность не более, чем на 10%. Иначе будут проблемы с производительностью.
- Логирование всех данных в один файл. Это приведет к тому, что в определенный момент чтение/запись в него будет очень сложной, не говоря о том, что есть ограничения по размеру файлов в определенных системах.
- Использование неверных уровней логирования. У каждого уровня логирования есть четкие границы, и их стоит соблюдать. Если граница расплывчатая, можно договориться какой из уровней использовать.
Уровни логирования
| FATAL | ERROR | WARN | INFO | DEBUG | TRACE | ALL |
| OFF | ||||||
| FATAL | ||||||
| ERROR | ||||||
| WARN | ||||||
| INFO | ||||||
| DEBUG | ||||||
| TRACE | ||||||
| ALL |
- OFF: никакие логи не записываются, все будут проигнорированы;
- FATAL: ошибка, после которой приложение уже не сможет работать и будет остановлено, например, JVM out of memory error;
- ERROR: уровень ошибок, когда есть проблемы, которые нужно решить. Ошибка не останавливает работу приложения в целом. Остальные запросы могут работать корректно;
- WARN: обозначаются логи, которые содержат предостережение. Произошло неожиданное действие, несмотря на это система устояла и выполнила запрос;
- INFO: лог, который записывает важные действия в приложении. Это не ошибки, это не предостережение, это ожидаемые действия системы;
- DEBUG: логи, необходимые для отладки приложения. Для уверенности в том, что система делает именно то, что от нее ожидают, или описания действия системы: “method1 начал работу”;
- TRACE: менее приоритетные логи для отладки, с наименьшим уровнем логирования;
- ALL: уровень, при котором будут записаны все логи из системы.
Запись и отправка логов: Appender
Этот процесс будем рассматривать на примере log4j: он предоставляет широкие возможности для записи/отправки логов:
- для записи в файл — решение DailyRollingFileAppender;
- для получения данных в консоль приложения — ConsoleAppender;
- для записи логов в базу данных — JDBCAppender;
- для контроля передачи через TCP/IP — TelnetAppender;
- для того, чтобы запись логов не била по быстродействию — AsyncAppender.
Есть еще несколько реализаций: полный список можно получить здесь. Кстати, если нужного аппендера не будет, это не проблема. Можно написать свой аппендер, имплементировав интерфейс Appender, который как раз принимает log4j.
Узлы логирования
Для демонстрации будем использовать интерфейс slf4j, а реализацию — от log4j. Создать логгер очень просто: нужно написать в классе с именем MainDemo , в котором будет логирование, следующее:
org.slf4j.Logger logger = org.slf4j.LoggerFactory.getLogger(MainDemo.class);
Это и создаст нам логгер. Чтобы сделать запись в лог, можно использовать множество методов, которые показывают, с каким уровнем будут записи. Например:
logger.trace(«Method 1 started with argument=<>», argument); logger.debug(«Database updated with script = <>», script); logger.info(«Application has started on port = <>», port); logger.warn(«Log4j didn’t find log4j.properties. Please, provide them»); logger.error(«Connection refused to host = <>», host);
Хоть мы и передаем класс, по итогу записывается именно полное имя класса с пакетами. Это делается, чтобы потом можно было разделить логирование на узлы, и для каждого узла настроить уровень логирования и аппендер. Например, имя класса: com.github.romankh3.logginglecture.MainDemo — в нем создался логгер. И вот таким образом его можно разделить на узлы логирования. Главный узел — нулевой RootLogger.
Это узел, который принимает все логи всего приложения. Остальные можно изобразить, как показано ниже: Аппендеры настраивают свою работу именно на узлы логирования. Сейчас на примере log4j.properties будем смотреть, как их настроить.
Пошаговая настройка Log4j.properties
Сейчас мы поэтапно все настроим и посмотрим, что можно сделать:
log4j.appender.CONSOLE=org.apache.log4j.ConsoleAppender
Эта строка говорит, что мы регистрируем аппендер CONSOLE, который использует реализацию org.apache.log4j.ConsoleAppender. Этот аппендер записывает данные в консоль. Далее зарегистрируем еще один аппендер, который будет записывать в файл:
log4j.appender.FILE=org.apache.log4j.RollingFileAppender
Важно отметить, что аппендеры нужно будет еще настроить. Когда у нас уже есть зарегистрированные аппендеры, мы можем определить, какой будет уровень логирования в узлах и какие аппендеры будут при этом использоваться.
log4j.rootLogger=DEBUG, CONSOLE, FILE
- log4j.rootLogger означает, что будем настраивать главный узел, в котором находятся все логи;
- после знака равно первое слово говорит о том, с каким уровнем и выше будут записываться логи (в нашем случае это DEBUG);
- далее после запятой указываются все аппендеры, которые будут использоваться.
log4j.logger.com.github.romankh3.logginglecture=TRACE, OWN, CONSOLE
где log4j.logger. используется для настройки определенного узла, в нашем случае это com.github.romankh3.logginglecture. А теперь поговорим о настройке CONSOLE аппендера:
# CONSOLE appender customisation log4j.appender.CONSOLE=org.apache.log4j.ConsoleAppender log4j.appender.CONSOLE.threshold=DEBUG log4j.appender.CONSOLE.layout=org.apache.log4j.PatternLayout log4j.appender.CONSOLE.layout.ConversionPattern=[%-5p] : %c:%L : %m%n
Здесь мы видим, что можно задать уровень, с которого будет обрабатывать именно аппендер.
Реальная ситуация: сообщение с уровнем info принял узел логирования и передал аппендеру, который к нему приписан, а вот уже аппендер, с уровнем warn и выше, лог этот принял, но ничего с ним не сделал. Далее нужно определиться с тем, какой шаблон будет в сообщении. Я использую в примере PatternLayout, но там существует множество решений. В данной статье они не будут раскрыты. Пример настройки FILE аппенедра:
# File appender customisation log4j.appender.FILE=org.apache.log4j.RollingFileAppender log4j.appender.FILE.File=./target/logging/logging.log log4j.appender.FILE.MaxFileSize=1MB log4j.appender.FILE.threshold=DEBUG log4j.appender.FILE.MaxBackupIndex=2 log4j.appender.FILE.layout=org.apache.log4j.PatternLayout log4j.appender.FILE.layout.ConversionPattern=[ %-5p] — %c:%L — %m%n
Здесь можно настроить, в какой именно файл будут записываться логи, как видно из
log4j.appender.FILE.File=./target/logging/logging.log
Запись идет в файл logging.log . Чтобы не было проблем с размером файла, можно настроить максимальный: в данном случае — 1МБ. MaxBackupIndex — говорит о том, сколько будет таких файлов. Если создается больше этого числа, то первый файл будет удален. Чтоб посмотреть на реальный пример, где настроено логирование, можно перейти на открытый репозиторий на GitHub.
Закрепим результат
- Создайте свой проект по типу того, что есть в примере выше.
- Если есть знания использования Maven — используем, если нет, то вот ссылка на статью, где описано как подключить библиотеку.
Подведем итоги
- Мы поговорили о том, какие бывают решения в Java.
- Почти все известные библиотеки по логированию написали под управлением одного человека 😀
- Мы узнали, что нужно логировать, а что не стоит.
- Разобрались с уровнями логирования.
- Познакомились с узлами логирования.
- Рассмотрели, что такое аппендер и для чего он.
- Поэтапно настроили log4j.proterties файл.
Дополнительные материалы
- JavaRush: Логирование. Размотать клубок стектрейса
- JavaRush: Logger lecture
- Хабр: Java logging. Hello world
- Хабр: Java logging: история кошмара
- Youtube: Головач курсы. Логирование. Часть 1, Часть 2, Часть 3, Часть 4
- Log4j: appender
- Log4j: layout
- Как тестовое задание на собеседование превратилось в open-source библиотеку
- Создание системы мониторинга цен на авиабилеты: пошаговое руководство [Часть 1]
- Гайд по созданию клиента для Skyscanner API и его публикации в jCenter и Maven Central [Часть 1]
- Debug в Intellij IDEA: гайд для новичков
Источник: javarush.com