Fatal error warn info debug trace

I find it more helpful to think about severities from the perspective of viewing the log file.

Fatal/Critical: Overall application or system failure that should be investigated immediately. Yes, wake up the SysAdmin. Since we prefer our SysAdmins alert and well-rested, this severity should be used very infrequently. If it’s happening daily and that’s not a BFD, it has lost its meaning. Typically, a Fatal error only occurs once in the process lifetime, so if the log file is tied to the process, this is typically the last message in the log.

Error: Definitely a problem that should be investigated. SysAdmin should be notified automatically, but doesn’t need to be dragged out of bed. By filtering a log to look at errors and above you get an overview of error frequency and can quickly identify the initiating failure that might have resulted in a cascade of additional errors. Tracking error rates as versus application usage can yield useful quality metrics such as MTBF which can be used to assess overall quality. For example, this metric might help inform decisions about whether or not another beta testing cycle is needed before a release.

Warning: This MIGHT be problem, or might not. For example, expected transient environmental conditions such as short loss of network or database connectivity should be logged as Warnings, not Errors. Viewing a log filtered to show only warnings and errors may give quick insight into early hints at the root cause of a subsequent error. Warnings should be used sparingly so that they don’t become meaningless. For example, loss of network access should be a warning or even an error in a server application, but might be just an Info in a desktop app designed for occasionally disconnected laptop users.

Info: This is important information that should be logged under normal conditions such as successful initialization, services starting and stopping or successful completion of significant transactions. Viewing a log showing Info and above should give a quick overview of major state changes in the process providing top-level context for understanding any warnings or errors that also occur. Don’t have too many Info messages. We typically have < 5% Info messages relative to Trace.

Trace: Trace is by far the most commonly used severity and should provide context to understand the steps leading up to errors and warnings. Having the right density of Trace messages makes software much more maintainable but requires some diligence because the value of individual Trace statements may change over time as programs evolve. The best way to achieve this is by getting the dev team in the habit of regularly reviewing logs as a standard part of troubleshooting customer reported issues. Encourage the team to prune out Trace messages that no longer provide useful context and to add messages where needed to understand the context of subsequent messages. For example, it is often helpful to log user input such as changing displays or tabs.

Debug: We consider Debug < Trace. The distinction being that Debug messages are compiled out of Release builds. That said, we discourage use of Debug messages. Allowing Debug messages tends to lead to more and more Debug messages being added and none ever removed. In time, this makes log files almost useless because it’s too hard to filter signal from noise. That causes devs to not use the logs which continues the death spiral. In contrast, constantly pruning Trace messages encourages devs to use them which results in a virtuous spiral. Also, this eliminates the possibility of bugs introduced because of needed side-effects in debug code that isn’t included in the release build. Yeah, I know that shouldn’t happen in good code, but better safe than sorry.

Зачем нужны логи

Очевидно, что логи делаются для разработчиков, чтобы облегчить им (нам) жизнь. Основные цели, ради которых существуют логи:

• сказать, что же делает система прямо сейчас, не прибегая к помощи отладчика, т.к. это иногда не оправдано;
• провести «расследование» обстоятельств, которые привели к определённому состоянию системы (например, падению или багу);
• проанализировать, на что тратится больше времени/ресурсов, т.е. профилирование.

Примитивный подход

Казалось бы, всё просто:

public static void Log(string message) {
 File.AppendAllText("log.txt", message);
}

Зачем что-то ещё придумывать, подключать внешние библиотеки, настраивать конфиги?
На практике, оказывается, что всё не так: одного лог-файла становится уже недостаточно, возникают проблемы с многопоточностью, форматом логов, записью времени, производительностью итд.
Какие же фичи должен поддерживать хороший логгер?

Фичи добропорядочного логгера

Уровни логгирования и фильтрация сообщений
Типичные уровни: Debug, Info, Warn, Error, Fatal
Уровни помогают определить критичность сообщения и приемлемое время реакции на него, об этом подробнее ниже.
Ротация лог-файлов
Логи со временем разрастаются, старые становятся ненужными. Хороший логгер должен уметь подменять активный файл при наступлении определённых условий. Есть два режима: по дате и по размеру файла.
Возможность записи сообщений не только в файлы
Не всегда файл – лучший способ хранения сообщений, хороший логгер должен поддерживать отправку сообщений по протоколу UDP, запись в базу, взаимодействие с очередями сообщений, такими, как MSMQ или JMS. Кроме того, отлично, когда логгер предоставляет возможность реализации собственного потребителя сообщений (обычно это называется термином message consumer, или message appender).
Thread-safety
Потокобезопасность – очень важное требование к логгеру. Плохой логгер может:

• пропустить часть сообщений;
• выбросить исключение
• отрицательно повлиять на производительность

Грамотная реализация потокобезопасности в логгере – один из ключевых моментов.
Асинхронное логгирование
Типичная практика логгирования – асинхронная запись. При этом важно, чтобы размер буфера был гибко настраиваемый, например, debug-сообщения можно писать по 100 штук, а error – немедленно после возникновения.
Формат и конфигурация логов
Формат должен быть настраиваемый, с возможностью указать то, что писать и куда писать. Например, можно писать в файл, хранящийся по пути из переменной окружения. Кроме того, полезная фича – динамическая конфигурация логгера, слежение за файлом конфигурации. Надо включить debug-режим – поменяли конфиг и наслаждаемся вкусными логами без перезапуска приложения.

Что и как писать в логи

Фичи логгеров мы рассмотрели. Но чтобы получить хороший, читаемый лог, надо вести логи правильно.
Начнём с того, что обычно «закон» какого-либо сервиса, отдела – это SLA, соглашение об уровнях сервиса (service level agreement). В нём указываются допустимые уровни восстановления после сбоя, время приемлемой реакции на сообщения итд. Чтобы помочь соблюсти SLA и вовремя отреагировать на событие, существуют уровни логгирования.

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

Очень важно понимать, что любое сообщение несёт в себе информацию определённой критичности, и время реакции на сообщения отличаются. Я приведу пример:
Debug. Отправлен запрос в базу на сохранение
Debug. Завершён запрос в базу на сохранение
Debug. Запрос в базу занял 0.02 секунды, извлечено 1000 записей
Info. Проведена транзакция по счёту 40000000000 (John Doe), получено $2000.
Warn. Отклонена транзакция с суммой платежа 0.
Error. Ошибка при сохранении транзакции 123: …..
Fatal. Не могу запустить модуль отправки исходящих сообщений MSMQ, из-за ошибки конфигурации модуля (…). Транзакции не будут обрабатываться.


Что означает каждый уровень?

Debug: сообщения отладки, профилирования. В production системе обычно сообщения этого уровня включаются при первоначальном запуске системы или для поиска узких мест (bottleneck-ов).
Info: обычные сообщения, информирующие о действиях системы. Реагировать на такие сообщения вообще не надо, но они могут помочь, например, при поиске багов, расследовании интересных ситуаций итд.
Warn: записывая такое сообщение, система пытается привлечь внимание обслуживающего персонала. Произошло что-то странное. Возможно, это новый тип ситуации, ещё не известный системе. Следует разобраться в том, что произошло, что это означает, и отнести ситуацию либо к инфо-сообщению, либо к ошибке. Соответственно, придётся доработать код обработки таких ситуаций.
Error: ошибка в работе системы, требующая вмешательства. Что-то не сохранилось, что-то отвалилось. Необходимо принимать меры довольно быстро! Ошибки этого уровня и выше требуют немедленной записи в лог, чтобы ускорить реакцию на них. Нужно понимать, что ошибка пользователя – это не ошибка системы. Если пользователь ввёл в поле -1, где это не предполагалось – не надо писать об этом в лог ошибок.
Fatal: это особый класс ошибок. Такие ошибки приводят к неработоспособности системы в целом, или неработоспособности одной из подсистем. Чаще всего случаются фатальные ошибки из-за неверной конфигурации или отказов оборудования. Требуют срочной, немедленной реакции. Возможно, следует предусмотреть уведомление о таких ошибках по SMS.

Правильное определение уровней ошибок сказывается на качестве системы и простоте её сопровождения.

Жизненный пример выбора уровней

Давайте представим, что разрабатываемая система – сотрудник почты, который принимает посылки. Принесли посылку.
Debug: Получена посылка 1. Проверяю размер…
Debug: Размер посылки 1: 40x100
Debug: Взвешиваю посылку…
Debug: Вес посылки 1: 1кг
Debug: Проверяю соответствие нормам…
Info (не Error!): Посылка 1 размером 40x100, весом 1кг, отклонена: превышен максимальный размер
…
Info: Посылка 2 размером 20x60, весом 0.5 кг передана на обработку оператору 1
…
Warn: Отказано в обработке для посылки 3: дата на посылке относится к будущему: 2050-01-01
…
Error: Не удалось отдать посылку оператору: оператор не отвечает: таймаут ожидания ответа оператора
…
Fatal: Произошёл отказ весов. Посылки не будут приниматься до восстановления работоспособности.


Логи и исключения

Они неотделимы друг от друга, как Ленин и партия. Обработка исключительных ситуаций или ошибок очень часто нуждается в правильном логгировании.
Плохой пример:

Log(ex.ToString());

Ещё хуже:

Log(ex.Message);

Не пишите исключения без сопроводительного текста в логи. Увидев ни о чём не говорящий stack trace, лично я прихожу в панику. Что это такое – ошибка, уведомление? Как отреагировала программа на это исключение? Продолжила работу в нормальном режиме, упала, ждёт реакции администратора? К сожалению, часто встречаю такое в коде, что весьма печально. Правильный путь:

Log("При записи истории комментариев для аккаунта {0} в хранилище произошла ошибка, данные за сегодня не будут доступны: {1}", account, ex);

Правила записи исключений в логи

• выберите уровень (подсистему), где Вы будете логгировать исключения;
• если вы обработали исключение, возможны три случая:
  • исключение считается обработанным и не пробрасывается выше по стеку. В этом случае запишите исключение с подробным стеком в лог;
  • исключение пробрасывается выше по стеку в той же подсистеме. Не логгируйте такое исключение. Однако убедитесь, что выше по стеку его запишут;
  • исключение пробрасывается выше по стеку в другую подсистему. Например, на другую машину или в другой процесс. Залоггируйте такое исключение, или запишите диагностическое сообщение об исключении;

• если исключение не обрабатывается – не логгируйте его. Однако убедитесь, что выше это исключение будет обязательно залоггировано. Я поясню:
  

  try { … } catch (Exception ex) { Log(ex); throw; }

  Ветка catch, в которой один вызов логгера – неверный вариант. Избавьтесь от такого catch.

Эти простые правила помогают не превратить логи в свалку из stack trace-ов при наступлении ошибки.
Да, не забывайте, что ex.ToString() – выведет исключение с текстом и stark trace-ом. Иногда почему-то забывают про этот полезный метод.

Сравнение логгеров

Давайте сравним, что нам предлагают NLog, Log4net, Enterprise Library.

Ранее я использовал log4net, сейчас перешёл на NLog, т.к. log4net забросили (а жаль).

Выводы

• Не пишите логгер сами;
• изучите конфиги и возможности логгера, который используете;
• правильно выбирайте уровень сообщений в логе;
• следите за логгированием исключений.

Ссылки

• Сравнение логгеров — почитать оттуда можно про NLog, log4net и Enterprise Library
• Принципы логгирования

How to Choose Levels of Logging

March 2, 2021

Application logging is an essential practice a developer can implement in their code to facilitate production support. Entries in log files contain essential information, including a timestamp, contextual information, and messages. Yet log messages are not the easiest to understand.

Most log management solutions that collect data and accept data from various sources have different log structures. Therefore, it may be challenging to understand them. It is crucial to keep meaningful log levels as we develop applications.

This will ensure that anyone who reads the logs can make meaning of the intended message. It is essential to use the best logging practices. This article will give a historical background of logging levels and describes different logging levels.

What is a logging level?

A logging level is a way of classifying the entries in your log file in terms of urgency. Classifying helps filter your log files during search and helps control the amount of information in your logs. Sometimes, categorizing may require you to balance storage use. You may want to capture every detail that may be useful in troubleshooting.

Yet, doing this may use up storage causing your production code to slow down. While implementing logging levels, you do not necessarily need to know everything that happens in production. You can outline how to identify warning conditions or problems for troubleshooting purposes.

Background of logging levels

Logging levels distinguish various log events from each other. They are a way of filtering important information about your system’s state and reduce information noise or alert fatigue.

Log levels were introduced in the 1980s in a project named Sendmail. Eric Allman developed the Sendmail project. The project owners needed a logging solution that eventually led to the creation of a System Logging Protocol (Syslog) server and the idea of severity levels.

Ultimately, Syslog was embraced by numerous applications and has become a standard protocol for sending system log and event messages to the Syslog server.

Over the years, programming languages have evolved. So did the emergence of logging into app frameworks, such as log4net. Log4net helps programmers output log messages to different output targets without changing the application binary.

Concepts such as severity level also came along and are seen in logging levels today. These severity levels are emergency, critical, alert, error, warning, debug, informational, and notice.

Each programming language has a logging framework that allows you to store data in different formats. This way, you can ship the data to various destinations such as text files. Beyond the multiple destinations and formats, it is essential to realize that the logging event level is key in this process.

Logging levels explained

The most common logging levels include FATAL, ERROR, WARN, INFO, DEBUG, TRACE, ALL, and OFF. Some of them are important, others less important, while others are meta-considerations. The standard ranking of logging levels is as follows: ALL

Peer Review Contributions by: Geoffrey Mungai

Источник

Fatal error warn info debug trace

Что пишут в блогах

Дорогие друзья, коллеги и партнеры! От всей души мы поздравляем вас с уже наступившим Новым 2023 годом !

(Все факты выдуманы

Все совпадения случайны)

Жил тестировщик по имени Толя,

В офис ходил и из дома работал.

И незадолго до Happy New Year

Что пишут в блогах (EN)

Разделы портала

Онлайн-тренинги

Автор: Корина Пип (Corina Pip)
Оригинал статьи
Перевод: Ольга Алифанова

Мы запускаем наши автотесты или на локальных машинах, или в CI-системах. В некоторых случаях мы неспособны наблюдать, что делают наши тесты. Если это API-тест, то если он не дает результат в консоли, мы не можем узнать, что он делает, пока тест не закончится. Если это UI-тест, то пока мы не увидим, что происходит в браузере, мы не поймем, что там творится. Поэтому в некоторых случаях нам нужно выводить информацию в консоль. Эта информация даст нам понять состояние теста или данные, используемые тестом. Одна из возможностей записывать ход теста в консоль предоставлена библиотекойApache Log4j.

Простейшее использование этой библиотеки в проекте тест-автоматизации – это логирование информации, которую мы приказали фиксировать. Это очень похоже на выполнение System.out, но позволяет более тонкую настройку. Результат можно настроить для следования определенным шаблонам, чтобы мы могли легко найти определенные действия.

Какую информацию мы хотим фиксировать? Если речь о длинных UI-тестах, мы можем записывать в консоль старт определенного шага или его успешное завершение. Если мы используем случайную генерацию данных вроде дат или имен, мы можем выводить их в консоль. Эта информация поможет вручную воспроизводить упавший сценарий.

Чем больше информации мы выводим, тем лучше понимаем, что делают наши тесты. Однако избыток информации сильно затруднит ее чтение, и мы начнем что-то пропускать или просто перестанем видеть нужное. Поэтому важно логировать только то, что относится к прогону и возможному падению теста.

Импорт Log4j в проект Maven

Если у вас проект Maven, вам нужно перейти на сайт репозитория Maven и найти ‘log4j-core’. Выберите последний релиз. На данный момент зависимость, которую вам нужно добавить в pom.xml, выглядит так:

Не забудьте выполнить операцию «clean install» в вашем проекте перед началом использования этой библиотеки.

Конфигурационный файл

Прежде чем начать использовать библиотеку, нужно создать файл конфигурации. Единственное требование для его размещения – находиться в classpath. Так как эта конфигурация используется в тестах, рекомендую разместить ее в srctestresources. Имя файла должно быть ‘log4j2.xml’.

В секции Appenders настраивается шаблон для системных результатов. Это значит, что каждый раз, когда что-то логируется, в консоль будет выводиться информация о времени, состоящая из часа, минут и секунд, уровень (про который я расскажу ниже), имена класса и метода, для которых ведется логирование, собственно само сообщение как строка, и затем новая строка. Пример форматированного результата:

В теге ‘Root’ мы устанавливаем уровень логирования. В примере выше это уровень ‘all’.

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

Как я уже упоминала ранее, избыточная логируемая информация затрудняет ее чтение, однако было бы здорово логировать наиболее важную информацию. Или, если уж мы логируем все, как минимум иметь возможность игнорировать нерелевантную для определенного прогона информацию. С этим нам помогут уровни.

По умолчанию Log4j поддерживает ряд стандартных уровней. По нисходящему уровню критичности это FATAL, ERROR, WARN, INFO, DEBUG, TRACE. При логировании информации FATAL должен использоваться для наиболее критичной. Когда уровни используют разработчики, то FATAL сигнализирует, что в ходе работы приложения возникла серьезнейшая ошибка. ERROR тоже говорит об ошибке, но менее влиятельной по сравнению с FATAL. Конечно, наименее серьезная проблема – это TRACE.

Как мы увидим в разделе «Настройка уровня логирования», мы можем конфигурировать уровни – и можем ограничить прогон теста только самой релевантной информацией, или же всей вообще. Следовательно, разделяйте эти уровни, логируя результаты тестов.

Логирование в тестах

Сначала нам нужно инициализировать логгер. Мы можем сделать это в тест-классе напрямую, или в классе, расширяемом тестами (базовом классе). Допустим, что все тесты расширяют базовый класс. В этом случае мы инициализируем защищенную переменную:

The required imports for our logging are:

Теперь каждый тест-класс может логировать информацию о прогоне, используя переменную LOGGER. Логирование проводится путем вызова метода для переменной LOGGER в соответствии с уровнем логирования. Вывод в консоли подсвечивается разными цветами в зависимости от уровня логирования. В тестах нам может потребоваться всего 2-3 уровня, но давайте разберемся, как логируется каждый возможный. Мы передаем простую строку как параметр – это сообщение, которое будет отображаться в консоли.

Результат команд выше при запуске тестов из IntelliJ будет выглядеть так:

Как можно видеть на скриншоте, INFO выглядит так же, как обычный System.out. Остальные детали логирования раскрашены в зависимости от «критичности». Логирование FATAL подсвечено красным и указывает на крайне важную информацию. Схожим образом ERROR подсвечен оранжевым. Это второй по важности тип логируемой информации.

Думайте о логировании разного уровня в следующем ключе: детали, чье присутствие не помешает, должны быть на уровне низкой серьезности вроде INFO. Самая важная информация, которая должна сразу бросаться в глаза при прогоне тестов – это уровни ERROR или FATAL.

Примечание: в некоторых CI-системах цвета не появляются в консоли. При запуске тестов из IDE вроде IntelliJ цвета будут присутствовать. В этом случае в CI можно искать конкретную информацию по имени уровня.

Настройка уровня логирования

В примерах выше все команды успешно запустились (все логирование было выведено в консоль). Это вызвано установкой тега Root в файле конфигурации на ‘all’. Эта настройка помогает ограничить тип информации, которую вы хотите видеть при прогоне теста. Допустим, что для определенного прогона вам нужна только «обязательная» информация, без «дополнительной». В этой ситуации вам нужно установить другой, более жесткий уровень. К примеру, если вы хотите видеть только ‘ERROR’ и ‘FATAL’, установите тэг ‘Root’ на ‘error’.

Дополнительная информация

У библиотеки log4j большой потенциал. О ее возможностях можно узнать в официальной документации.

Источник

Trace, Info, Warning, Error, Fatal — кто все эти люди.

Обычно библиотеки логгирования предлагают из коробки сразу несколько «уровней» важности, с которыми Вы можете записывать сообщения. В документации к ним можно найти рекомендации — как лучше этими уровнями пользоваться, примерно такие:

Info : все ожидаемые события, учет которых запланирован.
Warning : неожиданные/подозрительные события — иначе говоря аномалии, после которых еще возможно продолжение работы приложения.
Error : событие, после которого невозможно дальнейшее выполнение программы.
Fatal : событие, требующее по-настоящему немедленного вмешательства.

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

«Продолжить работу»

Трактовать “возможно продолжить работу” можно очень по разному. Скажем, на экране пользователя можно настроить любимый цвет рамки вокруг экрана: пусть будет розовый. Если по каким-то причинам хранилище, где мы держим эти настройки цвета было недоступно и мы не можем отобразить этот цвет — можно ли это считать как “возможно продолжить” или это катастрофа? К сожалению, я еще ни разу не встречал хорошего универсального формального критерия, чтобы четко можно было разделять «катастрофа-терпимо». А раз не можешь остановить — значит нужно направить. Потому я предлагаю инвертировать споры об “это неправильный уровень”: если в коде написано, что отсутствие цвета — это Error — значит программист Вам говорит, что этот цвет чертовски важен в этом домене — возможно, именно этот цвет сигнализирует, что сейчас надо продавать акции на миллионы долларов, и наоборот. Соответственно, чтение кода немного меняется: когда видите место, где из-за какой-то на Ваш взгляд ерунды прерывается выполнение, вопрос, который должен возникать автору, “Почему ты считаешь, что это так важно?” вместо “Истинно тебе говорю — ты программируешь неправильно!”.

Схожая инверсия может помочь в вечных спорах на тему “это исключительная ситуация или нет”. Опять же, все довольно просто. Важна не техническая составляющая: “нет соединения к базе — это исключение”, а “серверу прислали неправильный id — так это ожидаемо”. Важно то, чья это будет головная боль и как ее можно избежать или хотя бы минимизировать урон. Чьи планы на вечер пятницы пойдут к черту из-за того, что это сломалось? Если Вашим сервисом пользуются приложения, которые вне Вашего контроля, то Вам действительно плевать на то, что они присылают некорректные id и у них там что-то идет не так. Если Ваше приложение — это инструмент для управления базой данный — наподобие Sql Server Magement Studio — очевидно, что отсутствие доступа к базе — не Ваша печаль. А если Вашим сервисом пользуются приложения, за которые Вы же и в ответе — то это Ваши неприятности в конечном счете. Вопрос лишь в том, как и когда Вы об этом узнаете — быстро из сработавшей сигнализации или от звонка злого как черт владельца бизнеса, которому Вы пишете софт. А также вопрос в том, как “дешево, надежно и сердито” эту сигнализацию наладить.

«Error»

Давайте представим себе экран, где есть кнопка “Открыть” и текстовое поле. Эта кнопка по замыслу должна открыть Вам какой-то полезный функционал, а в текстовом поле предполагается ввести имя и фамилию. После нажатия на кнопку принципиально возможны два сценария: приложение либо крэшится либо нет. Если же мы были удачливы и оно не упало, у нас опять два варианта: мы получили желанный экран или мы получили сообщение об ошибке вместо него. Сообщение об ошибке в свою очередь можно принципиально разделить еще на два класса: может ли пользователь сам исправить ситуацию в рамках программы или нет — имеется ввиду корректирование своего ввода, а не “обратиться к Вашему системному администратору”.

Жаль, что нет комикса о том, как программист ловит льва в пустыне — он здесь был бы очень уместен

На практике сообщение вида “Обратитесь к администратору” это просто подслащенные крэш. Да, несомненно это лучше, чем убить весь процесс со всеми пользовательскими данными, но от этого оно не перестает фактически блокировать работу. В тоже время ошибка может быть сообщением о неправильных с точки зрения программы действиях, а именно надо было ввести имя и фамилию “Джон Иванов”, а человек ввел просто “Джон” и валидатору это не нравится. К чему это все? Что вообще у нас тут речь идет о 3-х достаточно разных сущностях, но при том на каждую из них можно сослаться как Error, что вызывает изрядную путаницу. Крэш приложения — это несомненно уровень Error в нашей системе определений, но это очень важный Error .

Ошибка валидации имя-фамилии — это несомненно уровень Info — мы ждем, что пользователь будет норовить записать все что угодно, а мы — пресекать это. Ну и записывать все те разы, когда пользователь был неправ. Но от этого ошибки не перестают бесить людей, которые их видят. То, что напрямую связано с людьми и их UX — важно; и неплохо бы присматривать за этим, не допускать, чтобы сообщения об этом тонули в километрах унылых Info записей “Пользователь такой-то залогинился”. Иными словами, чтобы устранить путаницу, хочется иметь уровни Error+ и Info+ .

Я предвижу восклицания “Так погодите, ведь крэш приложения — это недопустимо! Надо сразу действовать! Это Fatal уровень!» На это я неспеша прикурю воображаемую сигарету, затянусь и задумчиво отвечу: “Ну… всех ведь все равно не спасти. «. Ладно, я не курю, но, думаю, образ понятен. Появление сообщения Fatal должно быть эквивалентом запуска тревоги воздушной угрозы, когда в офисе разработки врубается сирена и это жуткое красное аварийное освещение. Вот честно, Вы именно так реагируете на то, что у кого-то из бухгалтерии на экране, который раз в сто лет запускают, упало приложение? Вполне может быть нормально, что у Вас сейчас даже и нет подобной ситуации, где уровень Fatal — согласно такой системы определений — нужен. Так вот трюк в том, чтобы не блокировать возможность добавить обработку такой потенциальной ситуации в будущем, забивая сейчас Fatal уровень сообщениями, которым важность Error+ в самый раз.

Таким образом, мы приходим к тому, что в действительности неплохо бы иметь уровни вида

Info
Info+
Warning
Error
Error+
Fatal

“Плюсовые” уровни можно легко организовать в Вашей любимой библиотеке логгирования расширив ее существующие методы Error/Info , которые бы просто унифицировано добавляли какой-то хэштэг в обычные сообщения, скажем #IMPORTANT.

Что ж — это все, что я хотел сказать об ошибках и их логгировании. Буду рад, если этот текст добавит разработчикам больше взаимопонимания и уменьшит споры о том, как «правильно».

Источник

Автор: Корина Пип (Corina Pip)
Оригинал статьи
Перевод: Ольга Алифанова

Мы запускаем наши автотесты или на локальных машинах, или в CI-системах. В некоторых случаях мы неспособны наблюдать, что делают наши тесты. Если это API-тест, то если он не дает результат в консоли, мы не можем узнать, что он делает, пока тест не закончится. Если это UI-тест, то пока мы не увидим, что происходит в браузере, мы не поймем, что там творится. Поэтому в некоторых случаях нам нужно выводить информацию в консоль. Эта информация даст нам понять состояние теста или данные, используемые тестом. Одна из возможностей записывать ход теста в консоль предоставлена библиотекойApache Log4j.

Простейшее использование этой библиотеки в проекте тест-автоматизации – это логирование информации, которую мы приказали фиксировать. Это очень похоже на выполнение System.out, но позволяет более тонкую настройку. Результат можно настроить для следования определенным шаблонам, чтобы мы могли легко найти определенные действия.

Какую информацию мы хотим фиксировать? Если речь о длинных UI-тестах, мы можем записывать в консоль старт определенного шага или его успешное завершение. Если мы используем случайную генерацию данных вроде дат или имен, мы можем выводить их в консоль. Эта информация поможет вручную воспроизводить упавший сценарий.

Чем больше информации мы выводим, тем лучше понимаем, что делают наши тесты. Однако избыток информации сильно затруднит ее чтение, и мы начнем что-то пропускать или просто перестанем видеть нужное. Поэтому важно логировать только то, что относится к прогону и возможному падению теста.

Импорт Log4j в проект Maven

Если у вас проект Maven, вам нужно перейти на сайт репозитория Maven и найти ‘log4j-core’. Выберите последний релиз. На данный момент зависимость, которую вам нужно добавить в pom.xml, выглядит так:

<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-core</artifactId>
    <version>2.14.1</version>
</dependency>

Не забудьте выполнить операцию «clean install» в вашем проекте перед началом использования этой библиотеки.

Конфигурационный файл

Прежде чем начать использовать библиотеку, нужно создать файл конфигурации. Единственное требование для его размещения – находиться в classpath. Так как эта конфигурация используется в тестах, рекомендую разместить ее в srctestresources. Имя файла должно быть ‘log4j2.xml’.

<?xml version="1.0" encoding="UTF-8"?>
<Configuration>
    <Appenders>
        <Console target="SYSTEM_OUT">
            <PatternLayout pattern="%d{HH:mm:ss} %-5level %class.%method{36} - %msg%n"/>
        </Console>
    </Appenders>
<Loggers>
    <Root level="all">
        <AppenderRef ref="Console"/>
    </Root>
</Loggers>
</Configuration>

В секции Appenders настраивается шаблон для системных результатов. Это значит, что каждый раз, когда что-то логируется, в консоль будет выводиться информация о времени, состоящая из часа, минут и секунд, уровень (про который я расскажу ниже), имена класса и метода, для которых ведется логирование, собственно само сообщение как строка, и затем новая строка. Пример форматированного результата:

22:05:05 INFO com.imalittletester.log4j.Log4jTest.firstTest - This is a message of type: info

В теге ‘Root’ мы устанавливаем уровень логирования. В примере выше это уровень ‘all’.

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

Как я уже упоминала ранее, избыточная логируемая информация затрудняет ее чтение, однако было бы здорово логировать наиболее важную информацию. Или, если уж мы логируем все, как минимум иметь возможность игнорировать нерелевантную для определенного прогона информацию. С этим нам помогут уровни.

По умолчанию Log4j поддерживает ряд стандартных уровней. По нисходящему уровню критичности это FATAL, ERROR, WARN, INFO, DEBUG, TRACE. При логировании информации FATAL должен использоваться для наиболее критичной. Когда уровни используют разработчики, то FATAL сигнализирует, что в ходе работы приложения возникла серьезнейшая ошибка. ERROR тоже говорит об ошибке, но менее влиятельной по сравнению с FATAL. Конечно, наименее серьезная проблема – это TRACE.

Как мы увидим в разделе «Настройка уровня логирования», мы можем конфигурировать уровни – и можем ограничить прогон теста только самой релевантной информацией, или же всей вообще. Следовательно, разделяйте эти уровни, логируя результаты тестов.

Логирование в тестах

Сначала нам нужно инициализировать логгер. Мы можем сделать это в тест-классе напрямую, или в классе, расширяемом тестами (базовом классе). Допустим, что все тесты расширяют базовый класс. В этом случае мы инициализируем защищенную переменную:

protected static final Logger LOGGER = LogManager.getLogger();

The required imports for our logging are:

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

Теперь каждый тест-класс может логировать информацию о прогоне, используя переменную LOGGER. Логирование проводится путем вызова метода для переменной LOGGER в соответствии с уровнем логирования. Вывод в консоли подсвечивается разными цветами в зависимости от уровня логирования. В тестах нам может потребоваться всего 2-3 уровня, но давайте разберемся, как логируется каждый возможный. Мы передаем простую строку как параметр – это сообщение, которое будет отображаться в консоли.

• trace:

LOGGER.trace("This is a message of type: trace");

• debug:

LOGGER.debug("This is a message of type: debug");

• info:

LOGGER.info("This is a message of type: info");

• warn:

LOGGER.warn("This is a message of type: warn");

• error:

LOGGER.error("This is a message of type: error");

• fatal:

LOGGER.fatal("This is a message of type: fatal");

Результат команд выше при запуске тестов из IntelliJ будет выглядеть так:

Как можно видеть на скриншоте, INFO выглядит так же, как обычный System.out. Остальные детали логирования раскрашены в зависимости от «критичности». Логирование FATAL подсвечено красным и указывает на крайне важную информацию. Схожим образом ERROR подсвечен оранжевым. Это второй по важности тип логируемой информации.

Думайте о логировании разного уровня в следующем ключе: детали, чье присутствие не помешает, должны быть на уровне низкой серьезности вроде INFO. Самая важная информация, которая должна сразу бросаться в глаза при прогоне тестов – это уровни ERROR или FATAL.

Примечание: в некоторых CI-системах цвета не появляются в консоли. При запуске тестов из IDE вроде IntelliJ цвета будут присутствовать. В этом случае в CI можно искать конкретную информацию по имени уровня.

Настройка уровня логирования

В примерах выше все команды успешно запустились (все логирование было выведено в консоль). Это вызвано установкой тега Root в файле конфигурации на ‘all’. Эта настройка помогает ограничить тип информации, которую вы хотите видеть при прогоне теста. Допустим, что для определенного прогона вам нужна только «обязательная» информация, без «дополнительной». В этой ситуации вам нужно установить другой, более жесткий уровень. К примеру, если вы хотите видеть только ‘ERROR’ и ‘FATAL’, установите тэг ‘Root’ на ‘error’.

Дополнительная информация

У библиотеки log4j большой потенциал. О ее возможностях можно узнать в официальной документации.

Обсудить в форуме

Обычно библиотеки логгирования предлагают из коробки сразу несколько «уровней» важности, с которыми Вы можете записывать сообщения. В документации к ним можно найти рекомендации — как лучше этими уровнями пользоваться, примерно такие:

Info: все ожидаемые события, учет которых запланирован.
Warning: неожиданные/подозрительные события — иначе говоря аномалии, после которых еще возможно продолжение работы приложения.
Error: событие, после которого невозможно дальнейшее выполнение программы.
Fatal: событие, требующее по-настоящему немедленного вмешательства.

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

«Продолжить работу»

Трактовать “возможно продолжить работу” можно очень по разному. Скажем, на экране пользователя можно настроить любимый цвет рамки вокруг экрана: пусть будет розовый. Если по каким-то причинам хранилище, где мы держим эти настройки цвета было недоступно и мы не можем отобразить этот цвет — можно ли это считать как “возможно продолжить” или это катастрофа? К сожалению, я еще ни разу не встречал хорошего универсального формального критерия, чтобы четко можно было разделять «катастрофа-терпимо». А раз не можешь остановить — значит нужно направить. Потому я предлагаю инвертировать споры об “это неправильный уровень”: если в коде написано, что отсутствие цвета — это Error — значит программист Вам говорит, что этот цвет чертовски важен в этом домене — возможно, именно этот цвет сигнализирует, что сейчас надо продавать акции на миллионы долларов, и наоборот. Соответственно, чтение кода немного меняется: когда видите место, где из-за какой-то на Ваш взгляд ерунды прерывается выполнение, вопрос, который должен возникать автору, “Почему ты считаешь, что это так важно?” вместо “Истинно тебе говорю — ты программируешь неправильно!”.

Схожая инверсия может помочь в вечных спорах на тему “это исключительная ситуация или нет”. Опять же, все довольно просто. Важна не техническая составляющая: “нет соединения к базе — это исключение”, а “серверу прислали неправильный id — так это ожидаемо”. Важно то, чья это будет головная боль и как ее можно избежать или хотя бы минимизировать урон. Чьи планы на вечер пятницы пойдут к черту из-за того, что это сломалось? Если Вашим сервисом пользуются приложения, которые вне Вашего контроля, то Вам действительно плевать на то, что они присылают некорректные id и у них там что-то идет не так. Если Ваше приложение — это инструмент для управления базой данный — наподобие Sql Server Magement Studio — очевидно, что отсутствие доступа к базе — не Ваша печаль. А если Вашим сервисом пользуются приложения, за которые Вы же и в ответе — то это Ваши неприятности в конечном счете. Вопрос лишь в том, как и когда Вы об этом узнаете — быстро из сработавшей сигнализации или от звонка злого как черт владельца бизнеса, которому Вы пишете софт. А также вопрос в том, как “дешево, надежно и сердито” эту сигнализацию наладить.

«Error»

Давайте представим себе экран, где есть кнопка “Открыть” и текстовое поле. Эта кнопка по замыслу должна открыть Вам какой-то полезный функционал, а в текстовом поле предполагается ввести имя и фамилию. После нажатия на кнопку принципиально возможны два сценария: приложение либо крэшится либо нет. Если же мы были удачливы и оно не упало, у нас опять два варианта: мы получили желанный экран или мы получили сообщение об ошибке вместо него. Сообщение об ошибке в свою очередь можно принципиально разделить еще на два класса: может ли пользователь сам исправить ситуацию в рамках программы или нет — имеется ввиду корректирование своего ввода, а не “обратиться к Вашему системному администратору”.

На практике сообщение вида “Обратитесь к администратору” это просто подслащенные крэш. Да, несомненно это лучше, чем убить весь процесс со всеми пользовательскими данными, но от этого оно не перестает фактически блокировать работу. В тоже время ошибка может быть сообщением о неправильных с точки зрения программы действиях, а именно надо было ввести имя и фамилию “Джон Иванов”, а человек ввел просто “Джон” и валидатору это не нравится. К чему это все? Что вообще у нас тут речь идет о 3-х достаточно разных сущностях, но при том на каждую из них можно сослаться как Error, что вызывает изрядную путаницу. Крэш приложения — это несомненно уровень Error в нашей системе определений, но это очень важный Error.

Ошибка валидации имя-фамилии — это несомненно уровень Info — мы ждем, что пользователь будет норовить записать все что угодно, а мы — пресекать это. Ну и записывать все те разы, когда пользователь был неправ. Но от этого ошибки не перестают бесить людей, которые их видят. То, что напрямую связано с людьми и их UX — важно; и неплохо бы присматривать за этим, не допускать, чтобы сообщения об этом тонули в километрах унылых Info записей “Пользователь такой-то залогинился”. Иными словами, чтобы устранить путаницу, хочется иметь уровни Error+ и Info+.

Я предвижу восклицания “Так погодите, ведь крэш приложения — это недопустимо! Надо сразу действовать! Это Fatal уровень!» На это я неспеша прикурю воображаемую сигарету, затянусь и задумчиво отвечу: “Ну… всех ведь все равно не спасти…». Ладно, я не курю, но, думаю, образ понятен. Появление сообщения Fatal должно быть эквивалентом запуска тревоги воздушной угрозы, когда в офисе разработки врубается сирена и это жуткое красное аварийное освещение. Вот честно, Вы именно так реагируете на то, что у кого-то из бухгалтерии на экране, который раз в сто лет запускают, упало приложение? Вполне может быть нормально, что у Вас сейчас даже и нет подобной ситуации, где уровень Fatal — согласно такой системы определений — нужен. Так вот трюк в том, чтобы не блокировать возможность добавить обработку такой потенциальной ситуации в будущем, забивая сейчас Fatal уровень сообщениями, которым важностьError+ в самый раз.

Таким образом, мы приходим к тому, что в действительности неплохо бы иметь уровни вида

Info 
 Info+
 Warning
 Error
 Error+
 Fatal

“Плюсовые” уровни можно легко организовать в Вашей любимой библиотеке логгирования расширив ее существующие методы Error/Info, которые бы просто унифицировано добавляли какой-то хэштэг в обычные сообщения, скажем #IMPORTANT.

Что ж — это все, что я хотел сказать об ошибках и их логгировании. Буду рад, если этот текст добавит разработчикам больше взаимопонимания и уменьшит споры о том, как «правильно».