Логування: що, як, де і чим?

Усім привіт, JavaRush спільнота! Сьогодні поговоримо про логування:

1. Що це, навіщо це. Коли краще за все використовувати, а коли – ні.
2. Які бувають реалізації логування в Java і що з цим розмаїттям нам робити.
Рівні логування. Обговоримо, що таке appender і як його правильно налаштувати.
3. Вузли логування і як правильно їх налаштовувати, щоб усе працювало так, як ми хочемо.

Цей матеріал розрахований на широку аудиторію. Він буде зрозумілий і тим, хто тільки знайомиться з Java, і тим, хто вже працює, але розібрався тільки з logger.info("log something"); Поїхали!

Для чого потрібне логування

Давайте розберемо реальні випадки, у яких логування вирішувало б проблему. Ось приклад із моєї роботи. Є точки застосунків, які інтегруються з іншими сервісами. Я використовую логування цих точок для "алібі": якщо інтеграція не спрацює, буде легко розібратися, з якого боку виникла проблема. Ще бажано логувати важливу інформацію, яка зберігається в базу даних. Наприклад створення користувача адміністратора. Це якраз те, що добре б логувати.

Інструменти для логування в Java

- Серед відомих рішень щодо логування в Java можна виділити:

• log4j
• JUL — java.util.logging
• JCL — jakarta commons logging
• Logback
• SLF4J — simple logging facade for java

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<String>. Це допомагає рахувати і створювати рядок тільки в той момент, коли це дійсно потрібно, а не щоразу, як це було до цього. Тільки з виходом Java 8 розробники розв'язали важливі проблеми, після чого JUL по-справжньому стало можливо використовувати. А саме, методи з аргументом Supplier<String> msgSupplier, як показано нижче:

public void info(Supplier<String> msgSupplier) {
   log(Level.INFO, msgSupplier);
}

JCL — jakarta commons logging

Через те, що тривалий час не було промислового стандарту в логуванні та був період, коли багато хто створював свій кастомний логгер, вирішили випустити JCL – загальну обгортку, яка використовувалася б над іншими. Чому? Коли в проєкт додавалися якісь залежності, вони могли використовувати логгер, який відрізнявся від логгера на проєкті. Через це їх транзитивно додавали в проєкт, що створювало реальні проблеми під час спроби все це зібрати воєдино. На жаль, обгортка була дуже бідна на функціональність і жодних доповнень не вносила. Напевно, було б зручно, якби всі використовували JCL для роботи. Але на ділі так не виходило, тому наразі застосовувати JCL – не найкраща ідея.

Logback

Який же тернистий шлях open-source... Logback написав той самий розробник, що й log4j, щоб створити йому наступника. В основі була та сама ідея, що і в log4j. Відмінності були в тому, що в logback:

• покращено продуктивність;
• додано нативну підтримку slf4j;
• розширено опцію фільтрації.

Стандартно logback не вимагає будь-яких налаштувань і записує всі логи починаючи з рівня DEBUG і вище. Якщо потрібне налаштування, його можна виконати через xml конфігурацію:

<configuration> 
    <appender name="FILE" class="ch.qos.logback.core.FileAppender"> 
        <file>app.log</file> 
        <encoder> 
            <pattern>%d{HH:mm:ss,SSS} %-5p [%c] - %m%n</pattern> 
        </encoder> 
    </appender> 
    <logger name="org.hibernate.SQL" level="DEBUG" /> 
    <logger name="org.hibernate.type.descriptor.sql" level="TRACE" /> 
    <root level="info"> 
        <appender-ref ref="FILE" /> 
    </root> 
</configuration>

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()) {
    log.debug("User " + user + " connected from " + request.getRemoteAddr());
}

Тобто замість одного рядка логування пропонували писати 3(!). Логування має мінімізувати зміни в коді, і три рядки явно суперечили загальному підходу. У slf4j не було проблем сумісності з JDK і API, тому відразу виникло гарне рішення:

log.debug("User {} connected from {}", user, request.getRemoteAddr());

де {} позначають вставки аргументів, які передаються в методі. Тобто перша {} відповідає user, друга {} – request.getRemoteAddr(). Завдяки чому, тільки в разі, якщо рівень логування дозволяє записувати в лог, це повідомлення можна конкатенувати в єдине. Після цього SJF4J став швидко набувати популярності, і на цей час це найкраще рішення. Тому будемо розглядати логування на прикладі зв'язки slf4j-log4j12.

Що потрібно логувати

Зрозуміло, логувати все підряд не варто. Іноді це і не потрібно, і навіть небезпечно. Наприклад, якщо залогувати чиїсь особисті дані і це якимось чином спливе на поверхню, виникнуть реальні проблеми, особливо на проєктах, орієнтованих на Захід. Але є й те, що логувати обов'язково:

1. Початок/кінець роботи програми. Потрібно знати, що застосунок дійсно запустився, як ми й очікували, і завершився так само очікувано.
2. Питання безпеки. Тут добре б логувати спроби підбору пароля, логування входу важливих юзерів тощо.
3. Деякі стани програми. Наприклад, перехід з одного стану в інший у бізнес-процесі.
4. Деяка інформація для дебага, з відповідним рівнем логування.
5. Деякі SQL скрипти. Існують реальні випадки, коли це потрібно. Знову-таки, вміло регулюючи рівні, можна домогтися чудових результатів.
6. Виконувані нитки(Thread) можуть бути логовані у разі перевірки коректної роботи.

Популярні помилки в логуванні

Нюансів багато, але можна виділити кілька розповсюджених помилок:

1. Надлишок логування. Не варто логувати кожен крок, який суто теоретично може бути важливим. Є правило: логи можуть навантажувати працездатність максимум на 10%. Інакше виникнуть проблеми з продуктивністю.
2. Логування всіх даних в один файл. Це призведе до того, що в певний момент здійснювати читання/запис у нього буде дуже складно, не кажучи про те, що існують обмеження за розміром файлів у певних системах.
3. Використання неправильних рівнів логування. У кожного рівня логування є чіткі межі, і їх варто дотримуватися. Якщо межа розпливчаста, можна домовитися, який із рівнів використовувати.

Рівні логування

Що таке рівні логування? Для того, щоб якось ранжувати логи, потрібно було дати певні позначення і розмежування. Для цього впровадили рівні логування. Рівень можна задати в застосунку. Якщо запис належить до рівня, нижчого за зазначений, його не вносять у лог. Наприклад, у нас є логи, за допомогою яких дебажуть застосунок. У нормальній роботі на продакшені (коли застосунок використовують за призначенням), такі логи не потрібні. Тому рівень логування буде вищим, ніж для дебага. Давайте розглянемо рівні на прикладі log4j. Решта рішень, крім JUL, використовують такі самі рівні. Ось вони в порядку зменшення:

• OFF: жодні логи не записуються, усі будуть проігноровані;
• FATAL: помилка, після якої застосунок уже не зможе працювати і буде зупинений, наприклад, JVM out of memory error;
• ERROR: рівень помилок, коли є проблеми, які потрібно вирішити. Помилка не зупиняє роботу програми загалом. Решта запитів можуть працювати коректно;
• WARN: позначаються логи, які містять застереження. Сталася несподівана дія, незважаючи на це система встояла і виконала запит;
• INFO: лог, який записує важливі дії в застосунку. Це не помилки, це не застереження, це очікувані дії системи;
• DEBUG: логи, необхідні для налагодження програми. Для впевненості в тому, що система робить саме те, що від неї очікують, або опису дії системи: "method1 почав роботу";
• TRACE: менш пріоритетні логи для налагодження, з найменшим рівнем логування;
• ALL: рівень, за якого будуть записані всі логи із системи.

Виходить, що якщо в застосунку в якомусь місці ввімкнено рівень логування INFO, будуть логуватися всі рівні, починаючи з INFO і до FATAL. Якщо буде рівень логування FATAL, будуть записані тільки логи з цим рівнем.

Запис і відправлення логів: 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 – використовуємо, якщо ні, то вчимося підключити бібліотеку.

Підіб'ємо підсумки

1. Ми поговорили про те, які бувають рішення в Java.
2. Майже всі відомі бібліотеки з логування були написані під управлінням однієї людини :D
3. Ми дізналися, що потрібно логувати, а що не варто.
4. Розібралися з рівнями логування.
5. Познайомилися з вузлами логування.
6. Розглянули, що таке апендер і для чого він.
7. Поетапно налаштували log4j.proterties файл.

Додаткові матеріали

1. Log4j: appender
2. Log4j: layout