Пользователь Сергеев Виктор
Сергеев Виктор
40 уровень
Санкт-Петербург

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

Статья из группы Random
"Добрый день, сегодня был зафиксирован инцидент на проме, прошу разработчика присоединиться к группе разбора." Примерно так может начаться один из ваших дней на работе, а может утро — не важно. Но начнем все по порядку. Решая задачи тут на JavaRush, ты учишься писать код, который работает и выполняет то, что от него ждут. Если взглянуть на раздел помощь, то ясно, что это не всегда получается с первого раза. На работе будет так же. Ты не всегда будешь с первого раза решать задачу: баги — вечные наши спутники. Важно, чтобы можно было восстановить события появления бага. Логирование. Размотать клубок стектрейса - 1Давай сразу на примере. Представим, что ты полицейский. Тебя вызвали на место происшествия (в магазине разбили стекло), ты приехал, и от тебя ждут ответов, что произошло. С чего начать? Я не знаю, как работает полиция. Очень условно — они начинают искать свидетелей, улики и все такое прочее. А что если бы само место могло рассказать в подробностях, что произошло? Например, так:
  • 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.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ся с логированием. Дальше можно подключить другие логеры (log4j, slf4j, Logback...) — их много, но суть одна^ записывать историю действий. Официальный туториал
Комментарии (7)
Чтобы просмотреть все комментарии или оставить свой,
перейдите в полную версию
Viktor Korotkov 19 уровень, Москва
29 января 2021
Большое спасибо за статью! Особенно порадовало слово типипзация:)))😆
7 сентября 2020
Доброй ночи. Вы вампир?
vinsler 35 уровень, Санкт-Петербург Expert
21 апреля 2019
Я не юзал логгер еще ни разу. )) Скорее всего могу предположить, что это нужно для средних проектов, на пол года + времени разработки в 5+ разработчиков, хотя могу ошибаться. Пару вопросов, которые были бы интересны, ну мне: 1) Как определять места для логирования? Может есть туториалы или правила или еще что? 2) Нужна ли информация из стектрейса в логгер или есть какие-то общие правила как заполнять систему вывода в сообщении, помимо времени и даты, например такой-то класс, такая-то функция, ошибка между строками при действии таком-то итд итп? Или логгер просто выводит точку в которой произошла ошибка, а потом для дебага все-равно ничего лучше sout не придумали? ))) 3) Если проект маленький, и заказчику на этот логер пофигу, а так же он не просит поддерживать проект после сдачи и на сопровождение он положил, стоит игра свеч?
Стас Пасинков 26 уровень, Киев Master
20 апреля 2019
я думаю самый популярный вопрос по логгированию у новичков - это чем отличается log4j от slf4j :) и какой из них лучше)))