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

Логирование в Java — это процесс записи событий, происходящих в приложении, для последующего анализа и отладки. Вместо System.out.println используются специальные фреймворки, которые позволяют управлять уровнями детализации (например, INFO, DEBUG, ERROR) и направлять вывод в консоль, файлы или другие системы. Теперь, когда вы знаете, что такое логирование, давайте на простом примере разберём, почему без него невозможно представить себе разбор инцидентов на реальном проекте. "Добрый день, сегодня был зафиксирован инцидент на проме, прошу разработчика присоединиться к группе разбора." Примерно так может начаться один из ваших дней на работе, а может утро — не важно. Но начнем все по порядку. Решая задачи тут на 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.util.Logger: его более чем достаточно для знакомства. Каждая запись лога содержит дату-время, уровень события, сообщение. Дата-время проставляется автоматом. Уровень события выбирает автор сообщения. Уровней есть несколько. Основные — это 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 для обоих. Также для файла задан паттерн имени. Это минимальный конфиг, который позволяет писать сразу и в консоль, и в файл. 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.WARNING,"что-то пошло не так" , 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
WARNING: что-то пошло не так
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)

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

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

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

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

Не стоит писать такое: это лог ради лога, он будет только мешать. Старайтесь всегда писать осмысленные вещи. Думаю этого достаточно, чтобы перестать пользоваться System.out.println и перейти к взрослым игрушкам. У java.util.logging есть недостатки. Например, уровни, тех, что я описал выше, тут нет, но они есть в большинстве используемых логгеров. Для статьи я выбрал java.util.logging потому, что он не требует дополнительных манипуляций с подключением. Замечу также, что можно использовать LOGGER.info вместо LOGGER.log(Level.INFO... Один из недостатков всплывает уже тут: LOGGER.log(Level.WARNING,"что-то пошло не так" , e); — позволяет передать сообщение и объект Exception, логер сам его красиво запишет. В тоже время как LOGGER.warning(""); принимает только сообщение, т.е. исключение передать нельзя, надо самому переводить его в строку. Надеюсь такого примера достаточно, чтобы познакомитmся с Java логированием. Дальше можно подключить другие логеры (log4j, slf4j, Logback...) — их много, но суть одна^ записывать историю действий.