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

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

Регулярно люди спрашивают как и что писать в логи. Могу рассказать как это сделано в одном реальном проекте. Способов применения логов ровно два: а) помогать инженерам отвечать на вопросы пользователей в стиле "Что я только сделал не так?", и б) помогать разработчикам воспроизводить баги. Для этого критично знать, что, как и в какой последовательности происходило в системе. Если по логу не удается локализовать баг с точностью до строчки кода -- не страшно. Задача лога примерно очертить место поиска.

Уровней логгирования используется всего четыре:

DEBUG

INFO

WARNING

ERROR

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

На продакшене всегда включен уровень INFO. Очень редко, когда требуется воспроизвести особо злобный баг или проверить правильность алгоритма логгирование переключается на DEBUG. Снижать уровень до WARNING или ERROR не имеет смысла, потому что теряется необходимая информация. Если какая-то подсистема (чаще всего демон) забивает общий лог своими сообщениями, то для нее выделяется отдельный лог файл. Разные части системы пишут в собственные лог файлы. Все логи ротируются раз в сутки, а также при каждом перезапуске системы. Это полезно при апгрейдах, чтобы четко различать какие ошибки относятся к старой версии, а какие к новой.

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

ERROR

Логгирование с уровнем ERROR пишется в следующих местах:

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

  
  if (phaseOfMoon.isIncorrect()) {     
      log.error("Incorrect phase of moon at " + someEnvironment);     
      throw new AstronomyException("Incorrect phase of moon"); 
  } 
  

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

  
  } catch (SQLException ex) {     
      log.error("Databse error", ex);
      throw new SomeInterfaceException("Шеф, все пропало, шеф.") 
  } 
  

• там, где исключение пробрасывается выше границы нашей системы
• там, где прекращается обработка исключения
  

  
  } catch (SomeException ex) { 
      log.error("Не шмогла, ну и ладно", ex); 
  }
  

• в случае ошибок, не связанных с исключениями
  

  
  if (positiveValue < 0) {
      log.error("Sanity check: positive is negative");
      return;
  }
  

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

WARNING

Общее правило: если какая-то неприятность произошла, но ее появление ожидаемо, неприятность не критична для работы или status quo может быть восстановлен автоматически, то это WARNING. Он пишется в момент обнаружения если неприятность невосстановима, или же в момент автоматического восстановления. Под warning попадают попытки восстановить соединение с сервером, перечитать файл, и т.п.

INFO

На уровне INFO логгируются события на уровне точек входа в систему: действия пользователя, вызовы API, запуск и остановка демонов и т.п.

DEBUG

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

Ну и напоследок несколько метрик. На 1000 строк кода приходится 5 записей в лог. Из них:

• 51% — Error
• 21% — Warning
• 13% — Info
• 15% — Debug