Здравствуйте, Hexxx, Вы писали:
H>Короче, то что логи — полезная штука, сомнений нет. Но как расставлять функции логирования, и что именно выводить в лог, чтобы потом не помереть читая его — это вопрос?
Могу рассказать, как это сделано у нас. В основном, логи используются для того чтобы отвечать пользователям на вопросы в стиле "Что я только сделал не так?" и воспроизводить баги. Для этого критично знать, что и в какой последовательности происходило в системе. Если по логу не удается точно локализовать баг -- не страшно. Задача лога очертить место поиска и дать достаточно информации для воспроизведения бага.
Уровней логгирования у нас используется четыре:
Debug
Info
Warning
Error
На продакшене всегда включен уровень info. В разработке иногда включаем debug, чтобы воспроизвести какой-то баг. Ниже info уровень логгирования не понижаем никогда, нет смысла. Если какая-то подсистема (чаще всего демон) забивает общий лог своими сообщениями, то для нее выделяется отдельный лог файл. На все изолированные подсистемы выделены отдельные лог файлы. Все логи ротируются раз в сутки и при каждом перезапуске системы чтобы при апгрейдах четко различать какие ошибки относятся к старой версии, а какие к новой. Уровень critical не используется потому что изнутри системы нет возможности обрушить ее целиком и навсегда. ИМХО и не должно быть. Случаи же внешних сбоев должны фиксироваться внешними же средствами. У нас для этого используется внешняя система acceptance мониторинга.
Теперь о том, что и когда логгируется. Поскольку большая часть ошибок сосредоточена на границах модулей, там же происходит большая часть записей в лог.
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);
}
в случае ошибок, не связанных с исключениями
Если есть исключение, вызвавшее ошибку, то оно всегда пишется лог. На одну ошибку достаточно одной записи в лог. Нет необходимости писать в лог на каждом уровне обработки ошибки.
Warning
Общее правило: если какая-то неприятность произошла, но ее появление ожидаемое, она не критична для работы или восстановима автоматически, то пишем warning. Warning пишется в момент обнаружения неприятности если она невосстановима, или же в момент автоматического восстановления. Под warning попадают попытки восстановить соединение с сервером, перечитать файл, и т.п.
Info
С уровнем Info логгируются события на уровне точек входа в систему: действия пользователя, вызовы API, запуск и остановка демонов и т.п.
Debug
Оставляется на усмотрение разработчика. Чаще всего логгируется в местах с нетривиальными алгоритмами и там где для отладки критично знать, по какой из ветвей пошло выполнение.
Ну и несколько метрик напоследок.
— на 1000 строк кода приходится 5 записей в лог. Из них:
— 51% — Error,
— 21% — Warning,
— 13% — Info,
— 15% — Debug.
Здравствуйте, Hexxx, Вы писали:
H>Зачастую логи ведутся хаотично, туда пишется все подряд. А иногда их нет, и их добавляют только когда появляется баг, который невозможно понять. Короче, то что логи — полезная штука, сомнений нет. Но как расставлять функции логирования, и что именно выводить в лог, чтобы потом не помереть читая его — это вопрос?
Мнэээ... тут слишком много встречных вопросов. Например, насколько система в принципе загружена и в состоянии ли она писать логи без ущерба для своей работы? Не повлияют ли они на рабочие процессы (например, таймингом отдельных действий)? В случае realtime систем логгирование становится особо диверсионным.
H>Я пытался найти какую-нить инфу про логирование. Нашел только вот это:
H>http://www.informit.com/guides/content.aspx?g=dotnet&seqNum=228
H>Но тут совсем мало. Может быть есть какая-то книга или статья где вопросы логирования описаны в полной мере?
Дальше расскажу свою практику. Как правило, я работаю с системами, у которых множество подсистем, каждая со своей спецификой (и иногда со своим отдельным разработчиком), при этом собственно библиотек не так много (или относятся к резко специфичным областям). Практически выработался следующий подход:
I. Разделить на концептуальном уровне целевое, контрольное и отладочное логгирование. Это не значит, что их надо обязательно вести разными функциями и подсистемами, но надо понять, где какое и как их различать.
1. Целевое — это то, где лог будет обрабатываться постоянно и не человеком. Это есть не везде. Самое типичное — акаунтинг по логу (самый разумный подход для систем, где не требуется немедленного учёта событий, но требуется неотложный; учёт наработанного времени — кому-то для карточного входа в помещение, кому-то для диалапа...)
2. Контрольное — обрабатывается автоматикой и человеком, используется для анализа необходимости отладки (что я имею в виду: например, перезапуск процесса подсистемы — событие контрольного лога, но ещё не содержит данные, почему он перезапущен; это уже дело контролирующего — определить, был ли перезапуск штатным, и если нет — поставить вопрос об отладке).
3. Отладочное — эпизодически и в основном человеком (хотя, вероятно, и какой-то автоматикой). Целевое ведётся постоянно, отладочное — по необходимости. Отладочное может быть максимально подробным (по необходимости).
Возможно, это деление следует уточнить, но пока что мне хватало.
II. Понятно, что целевое логгирование определено ТЗ. Контрольное следует продумать на этапе начального написания кода. Отладочное создаётся или уже при отладке, или заранее в "предвкушение" определённых типов багов и диагностических проблем. Я считаю, что отладочное логгирование стоит оставлять в итоговом коде. Если оно не необходимо для постоянной работы, можно его замаскировать препроцессором (см, ниже), но оно в коде не мешает, скорее наоборот.
Несколько раз видел и противоположные мнения — что код логгирования сбивает с толку при анализе кода, мешает охватить мысленным взглядом код в целом, и именно этим он вреден; поэтому надо его удалять, как только отладка закончена. Готов поверить, что кому-то это так, но мне такой подход чаще вредил. В конце концов, можно при анализе и не показывать этот код (обучить IDE такому режиму).
Слышал ещё, что необходимость логгировать одни и те же отладочные данные несколько раз — случай кривого кода. Тоже не согласен — часто задача не позволяет сделать идеальную изоляцию компонент (случай вроде индекса массива за пределами — годится только для учебника).
III. Нельзя ограничиваться одинаковым уровнем логгирования для разных частей сложной системы. При анализе ситуации в одной подсистеме такой уровень подробностей может быть излишним (мягко говоря) для другой. Поэтому следует давать возможность регулировать несколько категорий (по-английски часто говорится facility, толком перевести не придумал), часто даже несколько в одной подсистеме.
В зависимости от реализации это может быть или глобальный массив параметров (если по номерам), или глобальный хэш (по именам — для динамических языков), или сохранение уровня из конфигурации для каждой подсистемы отдельно (для Erlang я сейчас делаю именно так). Код в этом случае начинает выглядеть так:
if (DL(12, 10) || DL(15, 6)) {
fprintf(stderr, "foobar: a=%d b=%d\n", a, b);
}
if debug_levels.get('d_cc_routing', 8) >= 15:
DP('foobar: a=%d b=%d' % (a, b))
DL() — функция примерно следующего вида:
inline int
DL(int facility, int threshold)
{
return debug_levels[facility] >= threshold;
}
то есть числовой уровень строится по принципу "включаем всё на этом уровне и с меньшими по номеру".
Кроме того, могут быть глобальные facility на несколько подсистем (и разрешение писать для них проверяется через логическое ИЛИ нескольких проверок).
IV. Собственно об уровнях. У меня сложилась следующая схема уровней, единообразно для всех категорий:
1 — критические проблемы для системы в целом, старший уровень
2 — критические проблемы для системы в целом, младший уровень
3 — серьёзные проблемы подсистемы, старший уровень
4 — серьёзные проблемы подсистемы, младший уровень
5 — предупреждения (warnings), старший уровень
6 — предупреждения (warnings), младший уровень
7 — важное (notice), старший уровень
8 — важное (notice), младший уровень
9 — уровень стандартной информации
10 — базовый жизненный цикл (запуск, остановка)
12 — жизненный цикл плюс глобальные события (реконфигурирование)
15 — детализация жизненного цикла
20 — важные события внутреннего порядка
25 — детали процессов внутреннего порядка, в основе
30 — отладочная детализация
40 — предельные подробности вплоть до регистров после каждой команды;)
схема не жёсткая, точный уровень для каждой записи — вопрос достаточно произвольный, многие уровни не имеют значения для конкретных подсистем, но на практике это оказалось эффективнее жёсткой схемы. Разумеется, схема уровней одинакова на всех (иначе можно сойти с ума пытаясь их согласовать). Уровень по умолчанию для всех подсистем — 8. Если кому-то нужно иное — это корректируется в конфиге.
V. Если отладка мешает работе (даже торможение на 5% уже может быть показательным) — надо думать о варианте делать её условной в зависимости от режима сборки.
В текущем проекте мы операторы лога сделали макросами в зависимости от уровня отладки приложения (минимум, малый, средний, полный) и кроме числового уровня макрос задаёт включение конкретных действий. Например, CLOG_MAJ включается всегда, CLOG_MIN при среднем и большом уровне, CLOG_TOT — при полном. По умолчанию система поставляется собранной при среднем уровне, при плачах на производительность он уменьшается, но в случае если не хватает текущего — ставится версия при полной сборке.
VI. Для постоянно работающих систем крайне важно иметь возможность менять уровни логгирования на ходу без перезапуска.
VII. Ну про всякие таймстампы уже писалось в тех ссылках, не буду повторять. В зависимости от особенностей реализации может иметь смысл в макросах сделать автоматом запись файла, функции и строки, откуда было логгирование вызвано, или не делать. Собственно код формирования записи не так принципиален. Есть ещё, кстати, разные двоичные и структурированные логи, с ними вопрос отдельный.
VIII. Подумать про локи. В случае отладочного логгирования не страшно, если разные нити (процессы) перемешают многострочные данные: человек скорее всего разберёт. Для целевого и контрольного логгирования такое недопустимо. Так что если где-то есть многострочные блоки печати — тщательно подумать о результате.
Здравствуйте, Miroff, Вы писали:
/*...*/
Еще можно добавить категории.
Например так сделано в ATLTRACE.
ATL::CTraceCategory MyCategory( _T("MyCategory")/*Name*/, 1/*nStartLevel*/ );
...
ATLTRACE2( MyCategory, 0, _T("Level0\n") );
ATLTRACE2( MyCategory, 1, _T("Level1\n") );
ATLTRACE2( MyCategory, 2, _T("Level2\n") ); //Этого трейса не будет при nStartLevel == 1
...
В зависимости от nStartLevel ATLTRACE2 будет трейсить соответствующие логи.
Также с помощью утилиты
AtlTraceTool можно динамически менять уровни или вообще отключать трейсинг для процеса/модуля/катерогории.
Здравствуйте, Hexxx, Вы писали:
H>Зачастую логи ведутся хаотично, туда пишется все подряд. А иногда их нет, и их добавляют только когда появляется баг, который невозможно понять. Короче, то что логи — полезная штука, сомнений нет. Но как расставлять функции логирования, и что именно выводить в лог, чтобы потом не помереть читая его — это вопрос?
Постараюсь кратко и по существу, хотя тема сама по себе очень объемна.
1. как сделано технически.
все логируемые события от стадии дебаг до еррор документируются и им присвается идентификатор и сопутствующее текстовое описание. если имеют место быть параметры, то их формат так же описывает в документе. логирование производится в память (большой циклический буфер в разделяемой памяти). в памяти хрантся иденификаторы событий и параметы. по коду события можно определить количество параметров. сами параметры кодируются как тип-значение. строковые патаметры практически исключены, т.к. упаковка-распаковка строк дело требущее рессурсов. но иногда их все таки имеет смысл разрешить. если необходимо изучить лог, то запускается специальный компидятор, который использует текстовые описание событий с параметрами как шаблоны, и гененирует текстовый лог, удобный для чтения человеку. кольцевой буффер в памяти можно сбрасывать на диск, для сохранения логов за длительный интервал времени и последующего анализа с помощью описанного выше компилятора.
Вот так в кратце устроен лог с технической точки зрения.
2. как это выглядит логически.
В процессе подготовки спецификаций и требований к очередному компоненту алгоритм его работы описывается с помошью механизма состояний. Это не значит, что весь модуль-система должны быть реализована на конечных автоматах. Это означает, что внешнее поведение модуля описывается с помощью диаграммы переходов. А то как модуль будет реализован никак не регламентируется. Хотя многие программисты используют такой полдход и при непосредственом написании кода. Но это их личное дело. Точки логирования — это переходы между состояними. Уровень логирования определяется разработчиком и документируется. В обязательном порядке в кольцевом лог-буфере сохраняется информация о текущем состоянии и переходе, в процессе обработки которого сформирована лог-запись.
Используя этот механизм и сами программсты и системные инженеры, настраивающие и запускающие продукт у клиента могут получить четкое понимание того, на какой стадии обработки данных (и каких данных) произошла ошибка или возникло предупреждение. А логирование в память дает возможность включать даже отладочное логирование на живой системе. Хотя в этом случае оказывается целесообразным иметь >500mb кольцевой буфер и запас свободного места на файловой системе (разумеется локальной).
Надеюсь я более менее понятно описал свои принципы логирования.
H>Я пытался найти какую-нить инфу про логирование. Нашел только вот это:
H>http://www.informit.com/guides/content.aspx?g=dotnet&seqNum=228
H>Но тут совсем мало. Может быть есть какая-то книга или статья где вопросы логирования описаны в полной мере?
