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

"Добрый день, сегодня был зафиксирован инцидент на проме, прошу разработчика присоединиться к группе разбора." Примерно так может начаться один из ваших дней на работе, а может утро — не важно. Но начнем все по порядку. Решая задачи тут на 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...) — их много, но суть одна^ записывать историю действий. Официальный туториал