Статьи

Темное искусство лесозаготовок

Ведение журнала — это механизм отслеживания поведения приложения во время выполнения, главным образом для целей отладки / трассировки. Почти во всех существенно сложных / жизненно важных приложениях поддержание надлежащего журнала приложений является обязательным; следовательно, почти все разработчики хорошо знакомы с парадигмой ведения журналов. И это не ракетостроение. Вам просто нужно вызвать простой метод с тем, что вы хотите зарегистрировать, и возиться с простым файлом конфигурации, и все. Так в чем же дело?

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

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

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

Журнал о контексте

Важно помнить, что в файл журнала записывается достаточное количество информации о контексте. Рассмотрим следующий пример метода, который вызывает сложную бизнес-операцию с двумя параметрами, передаваемыми пользователем.

public void invokeBusinessOperation(String param1, String param2) {

if (LOG.isTraceEnabled()) {
LOG.trace("Invoking the foo() business operation");
}

businessObject.foo(param1, param2);

}

Это напишет следующее в наш вывод журнала.

Invoking the foo() business operation

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

Подумайте о ситуации, когда это приложение используется несколькими одновременными пользователями. То, что мы увидим в файле журнала, выглядит примерно так.

Some arbitary log message from another component.
Invoking the foo() business operation
Another log message
Another log message
Invoking the foo() business operation
Some arbitary log message from another component.
Another log message
Invoking the foo() business operation
Invoking the foo() business operation
Another log message

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

public void invokeBusinessOperation(String param1, String param2) {

if (LOG.isTraceEnabled()) {
LOG.trace("Invoking the foo() business operation with params : " + param1 + ", " + param2);
}

businessObject.foo(param1, param2);

}
Some arbitary log message from another component.
Invoking the foo() business operation with params : abc, def
Another log message
Another log message
Invoking the foo() business operation with params : xyz, ght
Some arbitary log message from another component.
Another log message
Invoking the foo() business operation with params : bar, tea
Invoking the foo() business operation with params : jkl, mno
Another log message

Ниже приведен реальный пример вывода журнала, который действительно показывает важность ведения журнала в контексте.

Reservation Validation Failed: Contract does not cover Meal Plan
Reservation Validation Failed (Reg.ID : 12) - No Contract Rate in Contract (33) covers the Meal Plan  (1 : FB)

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

С учетом контекстной информации вывод журнала становится более значимым и гораздо более полезным в будущих действиях по трассировке / отладке. Поэтому важно, чтобы мы регистрировали полезную контекстную информацию при ведении журнала. В противном случае он не предназначен для ведения файла журнала.

Вход достаточно — не слишком много, не слишком мало

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

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

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

Вход на правильном уровне

Все каркасы журналирования поддерживают различные уровни журналирования. Эти уровни журнала существуют, чтобы позволить разработчикам контролировать вывод файлов журнала, используя конфигурации, чтобы отфильтровывать ненужные сообщения. Я буду использовать уровни журналов, поддерживаемые API ведения журнала Apache Commons для этого обсуждения, но аналоги существуют в других каркасах журналов под разными именами (обратите внимание, что приоритет уровня журнала увеличивается вниз).

уровень Описание
TRACE Это самый низкий уровень регистрации. Это следует использовать для отслеживания действий, таких как вызов метода и регистрация параметров и т. Д.
DEBUG Этот уровень журнала обычно используется для операторов отладки приложений. Этот уровень следует использовать для регистрации сообщений, которые полезны при отладке, но которые слишком многословны для записи в журнал в обычных ситуациях.
ИНФОРМАЦИЯ Это уровень информации журнала. Это следует использовать для записи операторов, которые, как ожидается, будут записаны в журнал во время обычных операций. Например, выполнение важной бизнес-операции должно быть зарегистрировано под этим уровнем.
WARN Уровень предупреждения. Это следует использовать для регистрации предупреждений, которые обычно бывают непредвиденными, но не оказывают существенного влияния на функциональность бизнеса.
ОШИБКА Уровень ошибок должен использоваться для регистрации всех ошибок и исключений, которые влияют на бизнес-функциональность приложения.
FATAL Уровень фатального журнала используется для записи экстремальных ситуаций, когда по какой-либо причине может быть затронуто выполнение всего приложения.

Журнал перед выбрасыванием исключений

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

Обычно операторы журнала для исключения пишутся на уровне ОШИБКИ. Однако, если выбрасываемое вами исключение является частью бизнес-потока (что некоторые задают вопрос), было бы лучше регистрировать такие события на более низком уровне, например, WARN или INFO.

Например, в одном из моих прошлых проектов нам нужно было выполнить сложную последовательность проверки, и мы использовали исключения в качестве механизма уведомления о сбоях проверки. Однако мы не хотели загрязнять журнал приложения операторами ERROR для таких случаев, которые обычно ожидаются во время выполнения приложения (операторы ERROR следует использовать для реальных ошибок). Поэтому вместо уровня ОШИБКА мы использовали уровень ИНФО для этих сообщений.

Избегайте System.out / System.err

Удивительно видеть, что некоторые разработчики приложений масштаба предприятия прибегают к System.out или System.err, в то время как в приложении используется надлежащая структура ведения журналов. Если мы используем System.out, в то время как остальная часть приложения использует каркас журналирования, мы теряем преимущество каркаса журналирования. Каркасы журналирования могут быть сконфигурированы для регистрации на разных уровнях и шаблонах, но вызовы System.out будут вне этой конфигурации. Поэтому всегда лучше использовать одну и ту же структуру ведения журнала во всем приложении.

Еще одна вещь заключается в том, что автоматическая генерация кода для блоков try-catch в IDE генерирует ex.printStackTrace () в качестве блока catch по умолчанию. Метод printStackTrace () выполняет запись в System.err, и этого следует избегать при наличии каркаса ведения журнала. Вместо этого используйте средства, предоставляемые каркасом ведения журнала для этой задачи.

LOG.error("error description message here", ex);

Подумайте и о «производительности»

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

Например, рассмотрим гипотетическое приложение, в котором для каждого вызова бизнес-операции (выполнение которого занимает менее секунды) мы записываем 1 КБ вывода журнала в файл. Если это приложение интенсивно используется параллельными пользователями, скажем, 10000 бизнес-операций в секунду, тогда нашему приложению нужно будет написать 1KB * 10000 = Approx. 10 МБ данных в секунду. Если мы предположим, что логика приложения, которую необходимо выполнить, может справиться с такой нагрузкой без каких-либо проблем, узким местом приложения будет часть ведения журнала, поскольку для этого требуется медленный дисковый ввод-вывод.

Кроме того, в большинстве случаев запись контекстной информации в журнал требует сложных конкатенаций строк. Конкатенация строк довольно медленная, и она не будет выводить мусор в пул строковых констант Java. Тем не менее, мы не можем избежать этого (вы можете использовать String Builder, если есть много конкатенаций, но это не будет хорошим представлением о том, что количество конкатенаций меньше). Одна вещь, которую мы могли бы сделать, это использовать защитные условия для операторов ведения журнала, чтобы, если соответствующий уровень журнала был отключен, мы могли пропустить накладные расходы на конкатенацию и выполнение кода API ведения журнала.

Например,

if (LOG.isDebugEnabled()) {
LOG.debug("Dispatching " + topic + " emails to : " + emailAddress);
}

При условии «если» запись журнала будет вызываться только тогда, когда включен соответствующий уровень журнала. Если это не так, оператор log не будет выполнен, и конкатенация строк также не произойдет. Если условия «если» не было, тогда произойдет объединение, и тогда метод будет выполнен. В ходе выполнения метода он выяснит, что регистрация уровня отключена, а затем отбросит сообщение журнала. Рекомендуется использовать эти защитные блоки для более низких уровней регистрации, таких как TRACE и DEBUG, которые обычно отключаются при настройке производства.

Получите ваш IDE, чтобы сделать тяжелую работу

Большинство IDE поддерживает шаблоны кодирования, которые очень полезны, когда дело доходит до регистрации. Эти шаблоны могут генерировать стандартный код, который является исчерпывающим для написания. Тогда нужно просто выполнить шаблон, когда вы пишете свои записи в журнале и т. Д.

Следующие примеры предназначены для Eclipse, но аналогичные подходы существуют и для других IDE.

В Eclipse вы можете создавать шаблоны кода через Window -> Preferences -> Java -> Editor -> Templates.

Для генерации объявления логгера (используя Commons Logging) я использую следующий шаблон, который я назвал ‘getlog’.

${:import(org.apache.commons.logging.Log, org.apache.commons.logging.LogFactory)}
private static final Log LOG = LogFactory.getLog(${enclosing_type}.class);

Поэтому, когда я набираю команду getlog и нажимаю Ctrl + Space, Eclipse генерирует для меня следующее с правильным именем класса.

private static final Log LOG = LogFactory.getLog(THE CLASS NAME.class);

Аналогично, мы можем создать шаблоны для генерации блоков if для уровня DEBUG следующим образом.

if (LOG.isDebugEnabled()) {
LOG.debug("${msg}");
}

При этом, когда вы вводите отладку и нажимаете Ctrl + Space и запускаете шаблон, вы получите полный блок if, и ваш курсор будет помещен в двойные кавычки, готовые напечатать сообщение.

Еще одна вещь для настройки IDE — изменить стандартный шаблон кода для блоков try-catch, который содержит метод printStackTrace (). Это можно изменить через Окно -> Настройки -> Java -> Стиль кода -> Шаблоны кода. Измените шаблон Code -> ‘Catch block body’ и ‘Code in new catch blocks’ на следующий.

LOG.error("${msg}", ${exception_var});

И наконец,

Как всегда, легче сказать, чем сделать. Это требует некоторой практики, чтобы овладеть этим, но как только вы это сделаете, вы будете инстинктивно знать, когда и как вы должны войти, а когда нет.

 

С http://blog.yohanliyanage.com/2010/11/the-dark-art-of-logging/