Java Логирование. Размотать клубок стектрейса

Логирование в Java это процесс записи событий, происходящих в приложении, для последующего анализа и отладки. Вместо System.out.println используются специальные фреймворки, которые позволяют управлять уровнями детализации (например, INFO, DEBUG, ERROR) и направлять вывод в консоль, файлы или другие системы. Теперь, когда вы знаете, что такое логирование, давайте на простом примере разберем, почему без него невозможно представить себе разбор инцидентов на реальном проекте.

Кратко

• Логирование это запись того, что делает приложение, в консоль или файл. Отладчиком ночную аварию не поймаешь, а по логам утром разберешься.
• Каждая запись состоит из трех частей: дата и время (подставляются сами), уровень события и сообщение.
• Уровень выбирает автор записи. Привычная четверка это DEBUG, INFO, WARN и ERROR, но в java.util.logging они называются иначе: FINE, INFO, WARNING и SEVERE.
• java.util.logging встроен в JDK, подключать ничего не нужно. Настраивается обычным файлом свойств: куда писать (handlers), с каким уровнем и каким форматтером.
• Исключение передавайте логеру отдельным аргументом, объектом: log(уровень, "текст", e). Тогда в лог попадет весь стектрейс, а не одна строка.
• Главное качество лога это осмысленность. Записи вроде «что-то пошло не так» бесполезны и только мешают разбору.

Зачем логи нужны на реальном проекте

"Добрый день, сегодня был зафиксирован инцидент на проме, прошу разработчика присоединиться к группе разбора." Примерно так может начаться один из ваших дней на работе, а может утро, не важно. Но начнем все по порядку. Решая задачи тут на JavaRush, ты учишься писать код, который работает и выполняет то, что от него ждут. Если взглянуть на раздел помощь, то ясно, что это не всегда получается с первого раза. На работе будет так же. Ты не всегда будешь с первого раза решать задачу: баги это вечные наши спутники, и с ними придется жить. О том, зачем вообще заводить логи, у нас есть отдельная статья. Важно, чтобы можно было восстановить события появления бага. Давай сразу на примере. Представим, что ты полицейский. Тебя вызвали на место происшествия (в магазине разбили стекло), ты приехал, и от тебя ждут ответов, что произошло. С чего начать? Я не знаю, как работает полиция. Очень условно: они начинают искать свидетелей, улики и все такое прочее. А что если бы само место могло рассказать в подробностях, что произошло? Например, так:

• 21:59 владелец включил сигнализацию (5 минут до полного включения)
• 22:00 владелец закрыл дверь
• 22:05 полное включение сигнализации
• 22:06 владелец подергал ручку
• 23:15 включился датчик шума
• 23:15 мимо, громко лая, пробежала стая собак
• 23:15 датчик шума выключился
• 01:17 включился датчик удара на внешнем стекле витрины
• 01:17 голубь влетел в стекло
• 01:17 стекло разбилось
• 01:17 включена сирена
• 01:17 голубь отряхнулся и улетел

Ну вот, с такими подробностями долго копаться не придется, сразу ясно, что случилось. В разработке так же. Очень круто, когда по записям ты можешь рассказать, что происходило. Сейчас ты, возможно, вспоминаешь дебаг, ведь можно все отдебажить. А вот и нет. Ты ушел домой, а ночью все сломалось, дебажить нечего: надо понять, почему сломалось и починить. Вот тут на сцену и выходят логи, история всего что произошло за ночь. Предлагаю тебе по ходу статьи подумать, какой один из самых известных логеров (не совсем логер, скорее мониторинг), о котором, наверно, слышали все, кто слушает (смотрит) новости? Благодаря ему восстанавливают некоторые события.

Что такое логирование в Java

А теперь серьезно. Логирование в Java это процесс записи каких-либо событий, которые происходят в коде. Это твоя обязанность как программиста: записать, что сделал твой код, потому что потом тебе же эти логи и дадут для разбора. Если все сделать хорошо, тогда любая бага будет очень быстро разобрана и устранена. Тут, наверное, не буду углубляться в то, какие логеры есть. В данной статье ограничимся простым java.util.logging.Logger: он встроен в JDK, и для знакомства его более чем достаточно.

Из чего состоит запись в логе

Каждая запись лога содержит дату-время, уровень события, сообщение. Дата-время проставляется автоматом.

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

Уровень события выбирает автор сообщения. Уровней есть несколько. Основные это info, debug, error.

• INFO: обычно это информационные сообщения о том, что происходит, что-то вроде истории по датам. 1915: произошло то-то. 1916: еще что-то.
• DEBUG: подробнее описывает события конкретного момента. Например, подробности какой-либо битвы в истории это уровень debug: «Полководец Такойтович выдвинулся со своей армией в сторону села Селовича».
• ERROR: сюда обычно пишут ошибки, которые происходят. Ты, наверно, замечал, когда оборачиваешь что-то в try-catch, в блоке catch подставляется e.printStackTrace(). Он выводит запись только в консоль. С помощью логера можно отправить эту запись в логер (ха-ха), ну ты понял.
• WARN: сюда пишут предупреждения. Например, лампочка перегрева в машине. Это просто предупреждение, и лучше что-то поменять, но это еще не поломка. Вот когда машина сломается, тогда логировать будем с уровнем ERROR.

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

Как настроить логер

Дальше настройки. Логерам можно указать, куда писать (в консоль, файл, jms или еще куда-либо), указать уровень (info, error, debug...). Пример настроек для нашего простого логера выглядит так:

handlers = java.util.logging.FileHandler, java.util.logging.ConsoleHandler

java.util.logging.FileHandler.level     = INFO
java.util.logging.FileHandler.formatter = java.util.logging.SimpleFormatter
java.util.logging.FileHandler.append    = true
java.util.logging.FileHandler.pattern   = log.%u.%g.txt

java.util.logging.ConsoleHandler.level     = INFO
java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter

В данном случае все настроено так, чтобы логер писал в файл и в консоль одновременно. На тот случай, если в консоли что-то сотрется, плюс искать по файлу проще. Уровень INFO для обоих. Также для файла задан паттерн имени: в документации к FileHandler сказано, что %u в нем это уникальный номер на случай конфликта имен, а %g это номер поколения файла при ротации. Это минимальный конфиг, который позволяет писать сразу и в консоль, и в файл. java.util.logging.FileHandler.append установлен в true, чтобы старые записи не стирались в файле.

Пример: логер в работе

Пример использования такой (без комментариев, логер сам себя комментирует):

public class Main {
    static Logger LOGGER;
    static {
        try(FileInputStream ins = new FileInputStream("C:\\log.config")){ //полный путь до файла с конфигами
            LogManager.getLogManager().readConfiguration(ins);
            LOGGER = Logger.getLogger(Main.class.getName());
        }catch (Exception ignore){
            ignore.printStackTrace();
        }
    }
    public static void main(String[] args) {
        try {
            LOGGER.log(Level.INFO,"Начало main, создаем лист с типизацией Integers");
            List<Integer> ints = new ArrayList<Integer>();
            LOGGER.log(Level.INFO,"присваиваем лист Integers листу без типизации");
            List empty = ints;
            LOGGER.log(Level.INFO,"присваиваем лист без типизации листу строк");
            List<String> string = empty;
            LOGGER.log(Level.WARNING,"добавляем строку \"бла бла\" в наш переприсвоенный лист, возможна ошибка");
            string.add("бла бла");
            LOGGER.log(Level.WARNING,"добавляем строку \"бла 23\" в наш переприсвоенный лист, возможна ошибка");
            string.add("бла 23");
            LOGGER.log(Level.WARNING,"добавляем строку \"бла 34\" в наш переприсвоенный лист, возможна ошибка");
            string.add("бла 34");


            LOGGER.log(Level.INFO,"выводим все элементы листа с типизацией Integers в консоль");
            for (Object anInt : ints) {
                System.out.println(anInt);
            }

            LOGGER.log(Level.INFO,"Размер равен " + ints.size());
            LOGGER.log(Level.INFO,"Получим первый элемент");
            Integer integer = ints.get(0);
            LOGGER.log(Level.INFO,"выведем его в консоль");
            System.out.println(integer);

        }catch (Exception e){
            LOGGER.log(Level.SEVERE,"что-то пошло не так" , e);
        }
    }
}

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

Что попало в лог

Пример вывода:

апр 19, 2019 1:10:14 AM generics.Main main
INFO: Начало main, создаем лист с типизацией Integers
апр 19, 2019 1:10:14 AM generics.Main main
INFO: присваиваем лист Integers листу без типизации
апр 19, 2019 1:10:14 AM generics.Main main
INFO: присваиваем лист без типизации листу строк
апр 19, 2019 1:10:14 AM generics.Main main
WARNING: добавляем строку "бла бла" в наш переприсвоенный лист, возможна ошибка
апр 19, 2019 1:10:14 AM generics.Main main
WARNING: добавляем строку "бла 23" в наш переприсвоенный лист, возможна ошибка
апр 19, 2019 1:10:14 AM generics.Main main
WARNING: добавляем строку "бла 34" в наш переприсвоенный лист, возможна ошибка
апр 19, 2019 1:10:14 AM generics.Main main
INFO: выводим все элементы листа с типизацией Integers в консоль
апр 19, 2019 1:10:14 AM generics.Main main
INFO: Размер равен 3
апр 19, 2019 1:10:14 AM generics.Main main
INFO: Получим первый элемент
апр 19, 2019 1:10:14 AM generics.Main main
SEVERE: что-то пошло не так
java.lang.ClassCastException: java.lang.String cannot be cast to java.lang.Integer
	at generics.Main.main(Main.java:45)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at com.intellij.rt.execution.application.AppMain.main(AppMain.java:147)

Как размотать этот клубок

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

1. Первая строка это тип исключения и сообщение: java.lang.ClassCastException, а следом пояснение, что строку попытались привести к Integer. Уже отсюда ясно, что именно случилось.
2. Ниже идут строки at ..., это стек вызовов. Верхняя из них показывает место, где рвануло, а каждая следующая это тот, кто вызвал предыдущую, и так до точки входа в программу.
3. Найди в этом списке первую строку со своим пакетом. Здесь это generics.Main.main(Main.java:45): файл Main.java, строка 45. Открывать надо именно ее.
4. Все, что ниже (sun.reflect..., java.lang.reflect.Method.invoke, com.intellij...), это служебные кадры JVM и запускалки среды разработки. К твоей ошибке они отношения не имеют, читать их не нужно.

И обрати внимание, чего стоят записи выше по логу. Без них ты знал бы только про строку 45. А с ними видна вся цепочка: создали лист Integer, переприсвоили его в переменную без типизации, оттуда в лист строк, добавили туда три строки и только потом попытались достать из исходного листа число. Учти, что вывод в примере снят на Java 8, и сегодня тот же сбой выглядит иначе. Сообщение у ClassCastException стало длиннее: к именам классов добавились модуль и загрузчик. Служебные кадры sun.reflect... называются теперь jdk.internal.reflect..., а самая нижняя строка зависит от того, чем ты запускаешь программу. Суть при этом не меняется, просто не ищи у себя дословно те же строки.

Как не надо писать в лог

Тут хочу сделать акцент на записях:

апр 19, 2019 1:10:14 AM generics.Main main
INFO: Размер равен 3
апр 19, 2019 1:10:14 AM generics.Main main
INFO: Получим первый элемент

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

SEVERE: что-то пошло не так

Не стоит писать такое: это лог ради лога, он будет только мешать. Старайтесь всегда писать осмысленные вещи.

Чего не хватает java.util.logging

Думаю этого достаточно, чтобы перестать пользоваться System.out.println и перейти к взрослым игрушкам. У java.util.logging есть недостатки. Например, привычные имена уровней тут совпадают только наполовину: INFO и WARNING на месте, а вот DEBUG и ERROR называются по-другому. Полный список уровней по документации такой, от старшего к младшему: SEVERE, WARNING, INFO, CONFIG, FINE, FINER, FINEST. Плюс два служебных значения: OFF выключает логирование целиком, ALL включает все. Для статьи я выбрал java.util.logging потому, что он не требует дополнительных манипуляций с подключением. Замечу также, что можно использовать LOGGER.info вместо LOGGER.log(Level.INFO... Один из недостатков всплывает уже тут: LOGGER.log(Level.SEVERE,"что-то пошло не так" , e); позволяет передать и сообщение, и объект Exception, логер сам его красиво запишет. В то же время LOGGER.warning(""); принимает только сообщение, то есть исключение передать нельзя, надо самому переводить его в строку. Раз уж речь зашла про удобство: с Java 8 у логера есть перегрузки, которые принимают не строку, а Supplier<String>, то есть лямбду. Выглядит это так: LOGGER.fine(() -> "заказ " + order.getId() + " собран за " + ms + " мс"). Разница в том, что склейка строки произойдет, только если уровень FINE сейчас включен. Если подробные записи выключены, лямбда просто не вызовется, и время на сборку сообщения не потратится. В подробных логах внутри циклов это заметно. Надеюсь, такого примера достаточно, чтобы познакомиться с Java логированием. Дальше можно подключить другие логеры (log4j, slf4j, Logback...), их много, но суть одна: записывать историю действий. Как подключить log4j и slf4j к проекту, разобрано в отдельной статье.

Вопросы и ответы

Чем логирование лучше System.out.println?

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

Какие уровни логирования есть в java.util.logging?

Семь рабочих, от старшего к младшему: SEVERE, WARNING, INFO, CONFIG, FINE, FINER, FINEST. Плюс два служебных: OFF выключает логирование целиком, ALL включает все. Привычных по другим библиотекам DEBUG и ERROR тут нет: их место занимают FINE и SEVERE. Важная деталь: включив какой-то уровень, вы включаете и все уровни выше него.

Как настроить java.util.logging на запись и в файл, и в консоль?

Через файл свойств. В нем перечисляют обработчики: handlers = java.util.logging.FileHandler, java.util.logging.ConsoleHandler, а дальше для каждого задают .level, .formatter, а для файлового еще и .pattern с .append. Подсунуть этот файл можно двумя способами: ключом -Djava.util.logging.config.file=путь при запуске или прямо из кода, через LogManager.getLogManager().readConfiguration(поток), как сделано в примере выше.

Как записать в лог исключение целиком, вместе со стектрейсом?

Передать его логеру отдельным аргументом: LOGGER.log(Level.SEVERE, "не удалось обработать заказ", e). У метода log есть перегрузка, которая принимает Throwable, и логер сам развернет стектрейс в лог. А вот короткие методы вроде warning(String) принимают только текст, поэтому исключение через них полноценно не запишешь.

Как читать стектрейс из лога?

Сверху вниз. Первая строка это тип исключения и сообщение: в примере выше это java.lang.ClassCastException и пояснение, что строку попытались привести к Integer. Ниже идут строки at ..., это стек вызовов от места падения к точке входа. Ищите в нем первую строку со своим пакетом: здесь это generics.Main.main(Main.java:45), то есть 45-я строка вашего класса Main. Все, что ниже, это служебные кадры JVM и запускалки среды разработки, к вашей ошибке они отношения не имеют.

Каким должно быть сообщение в логе?

Таким, чтобы по нему можно было восстановить события, не открывая код. «Что-то пошло не так» и «Получим первый элемент» бесполезны: они не говорят ни что за объект, ни с какими данными шла работа. Полезная запись называет действие и его параметры: «не удалось списать сумму 1500 по заказу 42, счет не найден». Пишите так, будто читать это будете не вы и через полгода.

Читайте также

• Зачем нужно логирование
• Логирование в Java: что, как, где и чем?
• Как обрабатывать исключения в Java (Exception)
• Java Generics