Логи как лучшее средство от дебага

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

Логи в реальной жизни

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

Логирование — это когда муж приходит домой и кричит жене: «Лена, я дома!». Логирование — это когда ребенок, уходя на улицу, кричит родителям в другой комнате: «папа, буду вечером!». И наконец, обычный школьный дневник или аттестат — чем не лог? Можно ли хорошо учиться без дневника и аттестата? Запросто. Обязательно ли, заходя в квартиру, вещать всем «я дома»? Нет. Вас, вероятно, и так заметят через минуту. Всё это логирование — периферийный, второстепенный процесс, который не выполняет никакого реального дела. Но только до тех пор, пока не появится проблема.

Мама, грепни мой дневник
Если в один прекрасный день вашего ребенка выгоняют из школы по причине плохой успеваемости, то можно, конечно, начать «дебажить». Задать ребенку пару наводящих вопросов, звякнуть учителям и спросить об успеваемости на протяжении года, пообщаться с одноклассниками и выяснить активность ребенка на уроках. В конце концов, после небольшого детективного расследования вам удастся выяснить причину и начать ломать голову над тем, как вернуть ребенка в школу. Но не проще ли было регулярно «грепать» дневник и аттестат?

И родители грепают. Для удобства дневники расчерчены в таблицы, где виден месяц, день недели, число. Напротив каждого предмета есть место для оценки и замечания, которое пишется красным цветом, который зарезервирован только для учителя. Эти логи неплохо оформлены и позволяют быстро найти причину, по которой ребенка выгнали из школы. Более того, еженедельный смотр логов позволяет увидеть тенденции в успеваемости ребенка и заранее предпринять какие-нибудь меры, чтобы приложение не «упало». Почему бы тогда не уделять логам на проектах больше внимания?

Чем лучше логи, тем меньше дебага

Конечно, если возникает проблема, то можно кинуть пару Exception’ов, включить Debug, отловить всё и пофиксить. Можно также добавить ситуативные logger.info() или старый добрый System.out.println(). Если приложение валится где-нибудь на продакшене, то вполне реально справиться с помощью Remote Debug (хоть и не всегда). Но всё это суета. Грамотно оформленные логи могут позволить почти не использовать Debug. И эти же логи помогут заглянуть в такие глубины приложения, где не ступала нога удаленного дебага. Поэтому мы просто обязаны сделать логи удобочитаемыми и удобогрепаемыми.

Принципы грамотного логирования:

1. Логи должны отражать все важные события. Например: запуск приложения, старт/стоп транзакций, успешный логин, возникновение ошибок и так далее.

2. Их должно быть легко грепать. Как вариант, есть смысл не только позаботиться об уникальности тех слов/символов, по которым вероятен поиск, но и исключить часто повторяющиеся слова. Не хотелось бы попасть в ситуацию, когда грепать нужно по <apple.juice.com>, который упоминается в каждой строчке лога.

3. Добавляйте [TAGS] для маркировки концепций приложения. Например: [TRANSACTION], [DEVICE], [LOGIN] и так далее. Грепая по этим тегам, можно получить срез логов по девайсам, транзакциям и другим процессам, которые обычно «размазаны» по нескольким классам.

4. Все логи конкретного проекта должны соответствовать определенному формату. Например, команда может условиться использовать такой порядок: ---> [TAG] текст_сообщения ### [IP]. В реальной жизни это было бы похоже на:
INFO transaction.ScheduledReportTransactionService ---> [TRANSACTION] starting to execute on schedule ### [127.0.0.1]
Унифицированный подход к оформлению логов облегчит их чтение не только для самих разработчиков, но и для тех людей (например, клиентов), которым потом придется с ними работать.

5. Одна строка — одно сообщение. Стоит ограничиться выводом одного сообщения на строку, иначе греп будет не так эффективен.

6. Логов не должно быть слишком много и они не должны быть избыточными — лишняя информация будет засорять экран. Только самое важное и нужное.

И наконец, следует сознательно пользоваться разными уровнями логирования: INFO, WARNING, ERROR, FATAL. На многих проектах девелоперы повально увлеклись уровнем INFO. Может, потому, что сообщения в logger.info() не выделяются жутким красным цветом? Мухи отдельно, котлеты отдельно — называя вещи своими именами, мы облегчаем себе диагностику ситуации. Если есть потенциальная проблема — быть WARN’у, если это ошибка — быть ERROR’у, ну, а если мы хотим дать безобидное сообщение и всё хорошо — включаем INFO.

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

Если у вас есть свои фишки, связанные с логированием, — делитесь в комментах.

👍НравитсяПонравилось0
В избранноеВ избранном0
Подписаться на автора
LinkedIn



Підписуйтесь: Soundcloud | Google Podcast | YouTube


60 комментариев

Подписаться на комментарииОтписаться от комментариев Комментарии могут оставлять только пользователи с подтвержденными аккаунтами.

у нас триггер на бд на каждый чих изменений — реально спасает, особенно когда идут разборки кто побил хрупкое — менеджеры или программисты. и обычно таки менеджеры)

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

интересно послушать про структурированные логи

Две сущности: Event, Category.

Category — справочник, который задаёт категорию аудит-сообщения со строковым ключом в формате level1.level2...levelN — зависит от глубины структуры, которая обычно строится по детализации предметной области. Не что иное как хитрый способ отфильтровать дочерние подкатегории, не прибегая к иерархическим запросам — через LIKE ’parentId.%’, ну и суррогат обхода всего дерева через простой ORDER BY id. Тут же хранится человеческое название категории, severity level (тот самый INFO, WARN, etc), ну и самое интересное — атрибут pattern, о котором чуть позже.

Event — собственно, событие, эквивалент одной записи в лог-файле. Содержит время регистрации, обязательную ссылку на сущность Category, привязку к каким-то прочим сущностям, связанным с событием — например пользователя, породившего событие. И самое главное — произвольный набор текстовых атрибутов «ключ/значение». В реляционной БД это будет третья таблица, для правильного ORM это выглядит как обычный атрибут Map[String,String], ну а для NoSQL — это вообще родная концепция. Там хранятся параметры конкретного события, всё то, что когда-нибудь может понадобиться для анализа.

Таким образом мы обеспечили машинную читаемость событий, что же касается человеко-читаемости, то она реализуется атрибутом Category.pattern, который представляет из себя выражение с синтаксисом какого-нибудь простого движка-шаблонизатора, который не сложно реализовать и самостоятельно, где, помимо статических фрагментов текста, могут присутствовать ссылки на атрибуты события. Например: «User {user.login} logged in from {ip:unknown IP}». Генерация финального текстового выражения происходит динамически уже на уровне поближе к пользовательскому интерфейсу. Это даёт возможность впоследствии изменить шаблон сообщения, например, добавив новые параметры или ввести возможность многоязыковых сообщений.

Теперь о некоторых полезных расширениях, построенных на этой концепции. Можем определить интерфейс с одним методом, например такой (дальше пойдёт код на Scala, но это не принципиально):

trait Auditable {
def auditAttributes: Map[String, Any]
}

class User extends Entity with Auditable {
// model entity definition...

override def auditAttributes = super.auditAttributes ++ Map(
«login» → login,
«name.full» → s"$firstName $lastName«,
«roles» → roles sortBy (_.id) map (_.name)
)
}

теперь можем определить метод для логгирования как:

class AuditService {
def log(category: String, attributes: (String, Any)*) = ???
}

и реализовать в нём раскрытие параметров через интерфейс Auditable.

Таким образом, вызов

auditService.log("security.login«, «user» → user, «ip» → ip)

сгенерирует событие с примерно таким набором атрибутов:

user.id=123
user.login=basil
user.name.full=Basil Pupkin
user.name.roles=Administrator Manager
user.name.roles.0=Administrator
user.name.roles.1=Manager
ip=1.2.3.4

что по вышеприведённому шаблону построит текстовое сообщение: «User basil logged in from 1.2.3.4»

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

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

def diff[T <: Auditable, R](category: String, obj: T)(action: ⇒ R): R = ???

что откроет возможность такого рода трюкам:

val user = load[User](userId)
auditService.diff("user.change«, user) {
user.firstName = request.firstName
user.lastName = request.lastName
}

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

Ну вот, вкратце, суть идеи. Буду рад, если кому-нибудь ещё пригодится.

>>Почему-то все зациклены на текстовых лог-файлах

Потому что их всегда можно прочитать.

Почему-то все зациклены на текстовых лог-файлах,

Потому, что тема посвящена отладочным логам, а не контрольным или целевым. Рядом я расписывал различия. Нетекстовые структуры в отладочном логе это что-то совсем специфическое.

С другой стороны, и отладочные логи можно вести так:

(общий префикс) starting transaction for incoming request 498379837 from user vasya for /goods?id=2348

а можно так:

(общий префикс) %DB-TL-TRANS-START: starting transaction for incoming request; req_id=498379837 username=vasya product_id=2348

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

ыыы, и вот из за этого verobose "

starting transaction for incoming request
" я качаю по 300мб с США сервера с черепашьей скоростью и теряю каждый раз по несколько минут.
Мой подход — не надо конечно шифроваться, но лишний трындеж в логах тоже напрягает, особенно когда он в каждой из 50000 записей

Если сообщения часто повторяются, эти повторы легко сожмутся любым ближайшим gzip или более мощным аналогом.
Если нет — ну да, можно оставить только кода, поставить локальный расшифровщик и напускать его на полученные файлы. Но совсем без комментария можем прийти к стилю логов OS/360, когда наткнувшись на очередное «IEA0123A X=14 M=0 T=111» надо было лезть в подручную книжку читать, что это за зверь и почему. Но там поток событий был, мягко говоря, поменьше.

Тема реально интересная. Хочу поделиться фишками со своего проекта.

Юзаем log4net, но там нет Trace левела и поэтому в новых проектах стараюсь использовать NLog.

Вот дефиниция лог-левелов:
*Trace — very detailed logs, which may include high-volume information such as protocol payloads. This log level is typically only enabled during development.
*Debug — debugging information, less detailed than trace, typically not enabled in production environment.
*Info — information messages, which are normally enabled in production environment.
*Warn — anything that can potentially cause an application limitation, such as license expiring, switching from a primary to backup server, retrying an operation etc. Usually an automatic recovery is defined for such situations.
*Error — any error fatal to the operation but not to the application itself such as, cannot open file, missing data, input data format incorrect, etc.
*Fatal — any error that forces application to shut down and may result in data corruption or loss.

А вот формат лог-сообщения:

<date> <time> [<process_id>] [<thread_id>] <log_level> <logger_name> — Message (<message_token>) <direction> <source target="">. Details — <message_details>

Where:
 <process_id> — is the id of the process in which the message was processed. Useful in multiprocess applications.
 <thread_id> — is the id of the thread in which the message was processed. Useful for multithreading applications.
 <log_level> — is one of the possible NLog log levels.
 <message_token> — is a random six digit number which identifies the message chain. Application may receive some event, do calculations and send it further in different thread. To be able to trace this chain, all messages in a single chain will have the same token.
 <direction> — is the direction of the message. Could be: FROM, TO.
 <source target=""> - usually a component name. Depending on <direction> this parameter shows the source or target component for this message.
 <message_details> — specific message information.

Для анализа логов использую Hoo Win Tail (www.hootech.com/WinTail ). Там есть подсвтка по ключевым словам, а главное фильтрация. И я могу отфильтровать любую цепочку сообщений или все сообщения на входе компонента, или все что компонент отправил и т.д.

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

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

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

ТОлько мне кажется что кроме велосидедов вокруг fprintf() здесь больше никто ничего не пользует?

Всё в основе правильно, но некоторые моменты желательно уточнить.

1. В вашем сообщении отсутствует принципиальное разделение логов на целевые, контрольные и отладочные. Если кому неизвестна терминология:
* целевые — описывающие штатное функционирование, которые должны на постоянной основе анализируются программами, и это входит в ТЗ; например, для httpd это access.log, для системы доступа юзеров — лог, по которому далее формируется акаунтинг;
* контрольные — для мониторинга основных характеристик и журналирования статистики работы; должны быть пригодны к автоматизированному анализу;
* отладочные — предназначенные для нерегулярного, вызванного проблемами, анализа людьми и специализированными скриптами.

Всё сказанное в сообщении, по сути, относится к отладочным логам и частично к контрольным (и то, регуляция уровня контрольных — нечасто полезно). Описанное неприменимо к целевому логу и к большинству задач контрольного лога.

2. Набор указанных уровней недостаточен для большинства интересных случаев. Как минимум, требуется notice (выше info, но ниже warning), debug, а для тяжёлых случаев и trace.

В частности, всё описанное как

Логи должны отражать все важные события. Например: запуск приложения, старт/стоп транзакций, успешный логин, возникновение ошибок и так далее.

разделяется на: запуск, останов, реконфигурация приложения и все периодические «5 секунд, полёт нормальный» — notice (и параллельно в контрольный лог); логин, отработка запроса в целом — info; старт/стоп транзакций — debug; ошибки — warning или error.

3. Вся линия log4xxx (log4j, log4cplus, logging в Python, etc.), насколько я видел, неверно сделана в плане уровня логов. Так как уровень принципиально ограничен самым логически высоким fatal, то этот fatal должен быть в основании шкалы; а группы уровней debug и trace должны допускать подробную грануляцию. Поэтому должно быть в числовом смысле fatal самым низким, а trace самым высоким, и диапазоном (не одно значение, а не менее 10 разных). У log4xxx — наоборот, что показывает, что их авторы сделали реализацию «на отцепись». Это кажется мелочью, но становится принципиальным для регулировки плотности заполнения диска:)

У нас, например, система уровней
* 1-2 — fatal
* 3-4 — alert
* 5-6 — error
* 7-8 — warning
* 9-10 — notice
* 11-15 — info
* 16-30 — debug
* 31-INT_MAX:) — trace

сделана намеренно с избытком, и местами таки важно разделять уровни типа 11 и 14, или 35 и 40:)

4. Во многих случаях жизненно важно обеспечить раздельную регулировку уровней по профилям активности в рамках одного приложения. Если это нельзя сделать назначением уровня на «logger», то сколь-нибудь сложная диагностика превращается в кошмар начального grep’а среди десятков гигабайт.

Например, в системе с доступом по вебу выделяются примерно такие профили
* HTTP морда (начало, конец отработки запроса)
* доступ к базе (транзакции, ошибки, количество переданных данных)
* очереди и пулы асинхронного исполнения
* фоновые процессы

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

Как не видимое с первого взгляда следствие, желательна регулировка уровней отдельно от конфигурации выходных каналов (appender’ов), что нарушается во всех известных мне «промышленных» библиотеках логгирования.

Как именно это регулируется — отдельный файл с таблицей уровней, управляющий интерфейс через сокет/RPC, etc. — выбирается по месту.

6. Конфигурирование уровней должно допускать проверку уровня в рантайме (а не, например, после того, как сообщение пробежало пару AMQP релеев). Само форматирование для какого-то уровня может быть избыточно дорогим. Если известно, что форматирование дорогое, то код вида


    if (logger.enabled(LOG_DEBUG)) {
       logger.debug(...)
    }

может сохранить скорость работы там, где просто logger.debug(...) её убьёт в 0.

Как вариант, если есть препроцессор (в C/C++, Erlang, некоторых других), можно делать макры под конкретный заказ сборки (самая быстрая, самая подробная, промежуточные — в одном проекте у нас было 4 уровня).

7. Структура тегов строк логов большого приложения должна быть иерархической. (log4j с аналогами могут обеспечить это сохранением «имени» логгера. Но иногда этого недостаточно.)

8. Отдельная серьёзная тема — централизованный сбор логов разных источников и перераспределение на логгирующих хостах. Тут идут или средства типа Kafka от Apache, или что-то самописное (например, поверх 0MQ с адекватным назначением префиксов для лёгкой фильтрации).

Уф, кажется, всё:)

Очень хорошо. Написали бы статью здесь. Я бы ее в закладки заложил, чтобы не забывать и смотреть периодически.

Хм, подумаю

Уровень погружения в тему и объем информации — тянет на полноценнную статью )

П.С. поздно увидел, что тема старая и поднялась, видимо, из-за каких-то комментов...

Зачем писать

    if (logger.enabled(LOG_DEBUG)) {
       logger.debug(...)
    }
Если уже есть объект logger то можно туда запихнуть фильтр, а дальше через конфиг приложения выставлять уровень логирования.
Если уже есть объект logger то можно туда запихнуть фильтр,

А данные к фильтру поступают как, уже отформатированной строкой или комбинацией fmt+args? (Пока что предполагаем контекст, что весь выход — текстовый)
Если второе — ok, для большинства случаев фильтрация по уровню дёшева. Если первое — как раз я и объяснял, что тогда нужна явная проверка.

Более того, даже во втором случае создание объекта LogRecord (питоновый logging) или аналога может быть дорогой операцией. Тут рядом несколько раз уже упоминались случаи, когда GC очень дорог.
В таких местах и создавать объект на строку лога — безумно дорого...

А данные к фильтру поступают как, уже отформатированной строкой или комбинацией fmt+args? (Пока что предполагаем контекст, что весь выход — текстовый)
Ну возможны варианты зачастую передается просто строка и уровень лога, можно конечно и по отдельному методу состряпать на каждый уровень для наглядности. Вы логеру кстати, что передаете строку или подготовленный объект ?
Более того, даже во втором случае создание объекта LogRecord (питоновый logging) или аналога может быть дорогой операцией.
Тут вспоминается один пример про то сколько объектов типа date в java можно создать на дохленькой 1Гц машинке. Кажись было около 750К.
Вы логеру кстати, что передаете строку или подготовленный объект ?

Обычно — форматную строку и аргументы.

Тут вспоминается один пример про то сколько объектов типа date в java можно создать на дохленькой 1Гц машинке. Кажись было около 750К.

Мой телепатический модуль отказывается это расшифровывать.
750K объектов в 1GB RAM? Какие-то слишком толстые объекты.
750K объектов в секунду на 1ГГц машине (не 1Гц, конечно)? Ну в среднем по больнице нормальная скорость, но не там, где считают наносекунды.

750K объектов в секунду на 1ГГц машине (не 1Гц, конечно)?
Да, само собой =).
Ну в среднем по больнице нормальная скорость, но не там, где считают наносекунды.
Не думаю что так уже много проектов наберется, чтоб это было критично, но для картины в целом имеет смысл учитывать и это.

Тут должна быть длинная строка о том, почему я люблю C/C++ и считаю глупостью удаление из Java текстовых макросов.

а еще логи не спасают в многотредовых приложениях.

От гейзенбагов синхронизации — да, могут не спасать. Но для них вообще нужны отдельные подходы.

>От гейзенбагов синхронизации — да, могут не спасать.

они их создают

И как же логи их создают?

Колись баг з синхронизацією в ядрі QNX логами відловили. А яка розумная цьому альтернатива? ©

Наоборот. Только логи и спасают.

ага, а потом доганяют и еще раз спасают :)))

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

... уровнями логирования: INFO, WARNING, ERROR, FATAL.
Потенциальная проблема. Стартует дейли таска, чего то там импортит или чистит. Как отметить ее старт и стоп, которые согласно этой публикации обязательно должны быть залогированы ? Старт таски — это ж не ошибка ? не. Поэтому INFO.
Потом на продакшин выкатили, пару багов пофиксили, ессна, в процессе разработки навернули всякого МОДНОГО ХЛАМА, который тормозит, поэтому обвинили в тормозах логирование, и перешли на ERROR.
В итоге, что и когда стартует, вообще в логах НЕ ПОЯВЛЯЕТСЯ.
И так каждый раз :(.
Решение: обязательно FORCED левел логирования.

не — тут просто нужно изучить материальную часть. как уже заметили — автору не хватает базовой подготовки.

Как отметить ее старт и стоп, которые согласно этой публикации обязательно должны быть залогированы ? Старт таски — это ж не ошибка ? не. Поэтому INFO.

Поэтому notice. Если какой-то логгер не знает такого уровня — для реальной работы он не годен.

Потом на продакшин выкатили, пару багов пофиксили, ессна, в процессе разработки навернули всякого МОДНОГО ХЛАМА, который тормозит, поэтому обвинили в тормозах логирование, и перешли на ERROR.

Даже не warning, а сразу error? Тогда того, кто такое разрешил — метлой из профессии.

Решение: обязательно FORCED левел логирования.

Расшифруйте, пожалуйста.
Если имеется в виду, что этот forced это ещё один уровень, типа выше fatal, потому что пишется всегда и во всём — то это плохо уже тем, что фильтрация некоторого выходного потока/канала по принципу «>=error», которая может работать, например, на
* зажигание красной лампочки
* SMS дежурному инженеру
* механический счётчик проблем, который пишется ежечасно в бумажный журнал
* срочное заседание СНБО
* etc.

перестанет адекватно работать только потому, что кто-то решил, что поставить такой уровень проще, чем сделать по-умному.

ну собственно FORCED это похоже на Ваш notice.
В реальности приходится использовать log4j или стандартный логгер жавы. Которые, странно, но не предусмотрели ничего для логирования «интересных случаев».
Ну вот такая примитивная штука и позволяет «выходить из положения»:
public void logForced(Logger logger, Level level, String msg) {
Level savedLevel = logger.getLevel();
logger.setLevel(level);
logger.log(level, msg);
logger.setLevel(savedLevel);
}
То есть в логе это может быть запись инфо уровня, но срабатывает всегда, и лампочки не зажигает ;)

ну собственно FORCED это похоже на Ваш notice.

Если он таки forced, то он явно выше всех остальных.

В реальности приходится использовать log4j или стандартный логгер жавы. Которые, странно, но не предусмотрели ничего для логирования «интересных случаев».

Я ж говорю, они дурные кривули.

fatal, error, warning, info — это только называется уровнем логирования. На самом деле — это категории серьезности лог сообщений.
Например, давайте в работающей системе поставим fatal уровень логгирования ? Все сразу — низзя.
Как минимум — warning.
Тогда вопрос — а зачем нам разные fatal, error, warning — если ПО ЛЮБОМУ ВСЕГДА надо выводить. Чем тогда отличаются fatal, error, warning ? приходим к выводу — что не уровнем логгирования.
В общем, беда всех систем логгирования — путаница и смешивание уровней логгирования и категорий сообщений. Если человек отрывается от одномерного подхода, сразу все складывается.
Итак, то что я называю FORCED — по категории важности равно INFO, а по уровню логгирования —
FORCED = FATAL = ERROR — все это по любому логгируется, даже если есть формальная возможность отключить

fatal, error, warning, info — это только называется уровнем логирования. На самом деле — это категории серьезности лог сообщений.

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

Например, давайте в работающей системе поставим fatal уровень логгирования ? Все сразу — низзя.
Как минимум — warning.

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

Но представьте себе софтину, которая идеально вылизана поколениями разработчиков под давно устоявшиеся требования. Да, знаю, что в стране единорогов принцессы не имеют бытовых проблем. Но представим себе такое:) И что, от неё нужен лог уровня warning? Да на самом деле там даже fatal можно не писать, ибо его не бывает. :) Тогда что же реально важно? А то, например, что error, alert, critical, fatal могут отражать какие-то пришедшие извне проблемы. А ещё, как я писал в первом же своём комментарии в этой теме,
* alert, fatal — должны, скорее всего, немедленно передаваться в систему мониторинга и создавать в ней алармы (считаем, в стране единорогов есть мониторинг);
* >=error — должны анализироваться на регулярной основе и, скорее всего, человеком; кроме того, централизоваться в отдельный источник;
* >=warning — должны анализироваться на регулярной основе, попадать под сбор статистики подобных сообщений и анализ этой статистики; возможно, не централизуются, а остаются на конкретном хосте (и в центр пойдёт только статистика, или избранные категории, а остальная масса останется на локальном роторе).

Вот вам уже и различие уровней несмотря на то, что где-то кричат «пишем всё начиная от warning». Пишем — да, но в разные выходные логи. Обычно, лог уровня warning включает в себя и все уровни повыше.

Тогда вопрос — а зачем нам разные fatal, error, warning — если ПО ЛЮБОМУ ВСЕГДА надо выводить. Чем тогда отличаются fatal, error, warning ? приходим к выводу — что не уровнем логгирования.

Вот именно, что _уровнем_. Только Вы не хотите понимать, при чём тут этот уровень и где он применяется. Возможно, для Ваших задач это и не нужно?

В общем, беда всех систем логгирования — путаница и смешивание уровней логгирования и категорий сообщений. Если человек отрывается от одномерного подхода, сразу все складывается.

Что именно в данном случае Вы называете категорией сообщения? Мне привычно понимать под этим указание на подсистему/слой источника, по которому можно отдельно задавать уровень (в syslog это зовётся facility, а в log4xxx это текстовое имя логгера). И да, это даёт уже минимум двумерный подход (а с учётом иерархии — 2.5-мерный;))
Если Вы имеете в виду что-то другое — уточните.

Итак, то что я называю FORCED — по категории важности равно INFO, а по уровню логгирования —
FORCED = FATAL = ERROR — все это по любому логгируется, даже если есть формальная возможность отключить

Вот и плохо, что «по любому логгируется». Это значит, что если мне нужен лог fatal’ов со всей фермы на 100500 источников, я должен отдельный фильтр на все входы напускать??

«Яблука, як найкращий засіб від апельсинів».

— Логи как лучшее средство от дебага
— Новая модель рекрутинга: ставим на долгожителей
— Когда толковый программист задает идиотские вопросы
— Особенности поиска программистов, о чем молчат девушки-рекрутеры
— Не так страшно нашествие новичков в IT, как его рисуют
— Agile, который вначале радует, а затем вызывает депрессию
— Мелочи офисного быта, из-за которых сотрудники

#доунетортнувапче

В следующий раз можете сделать со ссылками, чтоб не дразнить читателей.

В следующий раз можете сделать со ссылками, чтоб не дразнить читателей.
В общем-то вы дали __себе__ замечательный совет :)
.
Но поскольку я в вас «верю», то поясню подробнее:
Тема замечательная (даже техническая).
А вот исполнение как обычно: Много воды; нет структуры; не рассмотрены «типовые решения», как в плане организации логирования, так и в плане анализа (греп — это хорошо, но вот не упомянуть про какой-то logstash или что-то в этом роде — это как бы недоработка).

Боюсь, всё несколько хуже. Впрочем, не «боюсь» — знаю. Приведенный список — простая констатация простого факта: «автор» — не специалист. Как вообще. Так и ни в одном из затронутых предметов. Констатировать факт, что автор еще и не специалист в техническом писательстве как и в технической журналистике — уже банальность. Упоминание при этом ДОУ — простая констатация простого факта: мозаика сложилась.

Такая активность — один из методов «запустить начало конца».

А почему бы им тогда не пойти по пути tut.by — только дайджест итэшных новостей со всего мира?

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

Да, логи это конечно нужно и хорошо, но когда у вас сложная система и много серверов — логи не спасают. Нужны инструменты другого уровня, например Kibana www.elasticsearch.org/...verview/kibana

Пример использования: i57.tinypic.com/2e578sn.jpg

Вопрос к читателям и к автору. Как вы относитесь к использованию существующей инфраструктуры для логирования? Я имею в виду линуховые rsyslog или всякие новомодные journald. С первым относительно просто интегрироваться через тот же log4j. На мой взгляд это даст возможность гибко использовать уже существующие системы мониторинга типа того же nagios, которые натравливаются на логи.

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

плохо. syslog хорош только когда у тебя один сервер на сервере крутится. ну или пара. ну а на рабочую станцию он просто не масшабируется.

Не заплутуйтесь :)
Бо є як мінімум декілька популярних логера: rsyslog, syslog-ng, sysklogd, metalog, ну і останнім часом «всюди-пропихаємий» systemd.
У всіх різні можливості.

У всіх різні можливості.

ага, пока пользовать не начнешь. хотя systemd я еще не пробовал

Был свой пет-проект системы обработки сообщений. Функционал примерно был такой: древовидные папки в которых можно создавать, редактировать и удалять сообщения. На папки можно было вешать слушатели, которые экспортировали сообщения из системы в виде файла или почтового сообщения. Но помимо подробнейшего лога на украинском (!!!) еще сделал создания сообщения на каждое исключение в системе. Просто валило все в одну папку как сообщение самой системы. На папку потом навешивал слушатель на отправку почты и ошибки летели на мой адрес. Лулзы начались когда в коде выпуска исключения выплыла ошибка. Бедная программа отсылала исключение, получала еще одно и пыталась уже отослать новое, но получала еще одно исключение и так по кругу, пока стек не кончался. Потом уже пофиксил. Если бы не забросил написание модулей вывода, то можно было бы эти ошибки хоть на facebook высылать.
P.S. В продакшене сейчас все прозаичнее: ACRA.

и так по кругу, пока стек не кончался
жесть

Отстреливать ноги на петпроекте приятнее чем на рабочем. И последствий меньше. Там же была ситуация когда клиент слал сообщение в систему и не дожидаясь подтверждение рвал соединение слал еще раз. За секунд 40 система приняла более 30 000 сообщений и даже позаписывала их. В логе аж свистело.

Вставлю свои пять евроцентов.

1. На продакшене запустить logrotate на логи, и можно архивы не удалять вообще. Места хватит.

2. Я ещё добавил такую фишку (у нас веб-приложение), что при критических ошибках пользователю показывается краткое сообщение в духе «2014-12-10 13:23:34 — Произошло что-то страшное, последние слова системы были: <Краткое описание ошибки>». Кмк, когда добавлено точное время, будет проще сопоставлять вылет ошибки у конечного юзера и лог (в который мы пишем уже детальную ошибку). Юзеры ведь скопипейстят текст, я их знаю, а мы по логам и точному времени увидим, что там конкретно свалилось внутри.

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

4. Насчёт того, что именно логировать. Я в первую очередь логирую необратимые процессы (удаление, например), потом что-то связанное с главной областью работы юзера, потом все попытки соединения с внешними сервисами (чтобы в случае чего понять на какой стороне ошибка), потом остальное.

Дебаг всё равно используем, но меньше. С остальным согласен, но нам повезло — встроенный Yii-шный логгер почти всё это делает за нас.

Graylog2 или kibana для централизации. В graylog2 различные streams на продукты/сервисы/типы событий. Стримы важны, так как по графику 3-х дневному стрима можно понять есть ли какая-то просадка. Для эксепшенов или ошибок — лучше sentry.

логи пишутся в произвольном порядке — даже на порталах Нацбанка и Налоговой
surprisingly!

Спасибо за статью. У нас используется самописное mongodb-logger.catware.org или сервис www.loggly.com

www.loggly.com

“No more logging into individual machines.” То есть раутинг к центру отсох — и всё, данных больше нет?

Что первый, что второй не отменяет стандартный логинг в файл (но и это можно отключить, если не хочешь logrotate настраивать). Для loggly проще настроить rsyslog, и пиши куда хочешь :)

Подписаться на комментарии