Журналы приложений раскрывают информацию о внешних и внутренних событиях, которые видит приложение в ходе исполнения. Когда при деплое возникает баг, взлом или аномалия, журналы самое полезное и надёжное доказательство для проведения анализа причин инцидента.
Давайте разберемся, как писать в журнал полезные сообщения, которые всем понравятся.
1. Что журналировать
Входящие и исходящие сообщения
Если компоненты взаимодействуют друг с другом с помощью сообщений, то нужно записывать входящие и исходящие сообщения с указанием URLов конечных точек API, параметры запросов, исходные и промежуточные IP запросов, заголовки запросов, информацию об авторе, тела запросов и ответов, бизнес-контекст, временные метки и этапы внутренней обработки.
Очень важно, чтобы каждому сообщению был присвоен уникальный идентификатор (обычно генерируемый на уровне менеджера API или сервиса). Это нужно для отслеживания обмена сообщениями между сервисами в системе.
Вызов сервисов и функций
При вызове сервиса или функции желательно подробнее журналировать их контекст, в основном для отладки (используйте TRACE или DEBUG). Эти журналы помогут в расследовании проблем, связанных с бизнес-логикой, особенно при отсутствии привилегий по прикреплению отладчика к приложению (например, при развёртывании в тестовое, staging или pre-prod-окружение).
Действия пользователей и бизнес-статистика
У каждого приложения есть уникальные бизнес-сценарии и пользовательские маршруты (user journey), которые дают много информации профильным специалистам. Например, не слишком ли долго выполнялась определённая транзакция, или не застревают ли пользователи на какой-то функциональности всё это очень важные данные с точки зрения пользовательского опыта. Иная информация, относящаяся к бизнесу, количество транзакций и активных пользователей, а также их этапы важна для поиска причинно-следственных связей, и даже может применяться в бизнес-анализе.
Операции с данными (журнал аудита)
По соображениям безопасности и соблюдения требований регулятора в большинстве enterprise-приложений требуется вести отдельные журналы по операциям со всей важной информацией, такой как идентификаторы доступа (пользователей и систем), точные экземпляры сервисов и использованные привилегии ролей, временные метки, запросы на данные, слепки предыдущего и нового состояния изменённых данных (diff). Журнал аудита должен фиксировать все операции с данными (доступ, импорт, экспорт и т. д.), а также CRUD-операции (создание, чтение, обновление, удаление), выполненные пользователями, иными системами и сервисами.
Системные события
К ним относится информация о поведении (запусках, остановках, перезапусках и событиях, связанных с безопасностью), переходных режимах (холодный, разогрев, горячий), межсервисному взаимодействию (handshake, статусы установки соединения подключено, отключено, переподключено, повторные попытки), идентификаторы экземпляров сервисов, активно обслуживающие API, активно прослушивающие диапазоны IP и портов, загруженные конфигурации (первоначальные загрузки и динамические обновления), общее состояние сервисов, а также всё, что поможет понять поведение системы.
Статистика производительности
Усердие прекрасная характеристика вычислительных устройств, но они могут работать не идеально. В любое время могут возникнуть проблемы с производительностью или внезапные неожиданные ухудшения обслуживания (в основном из-за необработанных ошибок и повреждённых данных). Чтобы их определить, всегда рекомендуется публиковать статистику общего состояния и производительности системы. Она может содержать информацию вроде счётчиков вызовов API (успешно обслуженных и сбойных), сетевую задержку, среднюю длительность roundtripов, потребление памяти и прочую специфическую для приложения информацию (обычно определяется бизнес-контекстом).
Угрозы и уязвимости
Раскрытие угроз и уязвимостей с помощью runtimea приложения и журнала это искусство, которым должен овладеть любой разработчик enterprise-ПО. Обычно взломы и сбои не происходят внезапно. Чаще всего есть признаки, которые сначала никто не замечает. Поэтому нужно всегда журналировать подозрительную человеческую активность (например, ошибочные попытки аутентификации и верификации с приложением всей низкоуровневой информации вроде использованных сетей, источников запросов, пользовательских ролей и привилегий), а также поведение системы (например, рост пиков в паттернах потребления ресурсов, высокую нагрузку на веб-серверы, случайные сбои сервисов). Когда вы замечаете подозрительное событие, убедитесь, что журналы содержат всю связанную с ним информацию. В идеале, чтобы это была full-stack-трассировка со значениями параметров и дополнительной информацией, полученной из контекста приложения.
2. Что не нужно журналировать
Информацию личного порядка
Почти все законы, регулирующие вопросы приватности (например, GDPR, CCPA) прямо рекомендуют разработчикам не журналировать информацию, позволяющую установить личность. Сюда относятся ФИО, ники, пол, день рождения, почтовый адрес, электронную почту, телефонные номера, номер социального страхования и номера кредитных карт.
Названия компаний и контактную информацию
Убедитесь, что вы не записываете имена компаний, информацию о сотрудниках, клиентах, поставщиках, а также контактную информацию компании и отдельных людей. Журнал никогда не должен раскрывать деловые взаимосвязи и операций с третьими сторонами. Для отслеживания конкретных транзакций используйте вместо настоящих названий идентификаторы событий, сгенерированные системой, и передавайте их другим сервисам.
Финансовые данные (банковские счета, реквизиты банковских карт, пересылаемые суммы и т. д.)
По закону все финансовые данные должны быть полностью убраны или замаскированы. Раскрытие такой информации в журналах легко может привести к серьёзному судебному иску (вплоть до уголовной ответственности). Избегайте этого всеми способами.
Пароли, ключи безопасности и секреты, токены аутентификации
Учётные данные и токены аутентификации считаются конфиденциальной информацией, поэтому их наличие в журналах поможет злоумышленникам легко найти бреши в системе. Поэтому не допускайте эти данные в журналы.
Примечание: вам легко будет определять, какую информацию нужно скрыть от журналов, если вы добавите в каждое поле атрибут, определяющий уровень видимости (например, show, mask, hide, encrypt). Если у вас есть такой механизм, то вы сможете менять видимость полей, просто обновляя свойства в конфигурации. Это хорошее решение в тех случаях, когда нужно журналировать какую-нибудь пользовательскую информацию в небоевых окружениях, особенно для тестирования и отладки. Или можно написать парсеры, которые фильтруют журналы и обрабатывают конфиденциальные поля в соответствии с заранее прописанными для этого окружения инструкциями.
3. Лучшие методики
Знайте, когда нужно использовать тот или иной уровень журналирования
Уровень журналирования используется для обозначения серьёзности каждого элемента системы. В большинстве фреймворков для журналирования есть такие уровни:
- FATAL: очень серьёзные ошибки, которые наверняка приводят к прерыванию приложения. Обычно это заканчивается серьезными сбоями.
- ERROR: ошибки, с которыми приложение ещё может продолжить работу, но с ухудшением определённых возможностей.
- WARN: менее опасные события по сравнению с ошибками. Обычно не приводят к ухудшению возможностей или полному сбою приложения. Но это всё ещё важные события, которые необходимо расследовать.
- INFO: важные баннеры событий и информационные сообщения в поведении приложения.
- DEBUG: специфическая и подробная информация, обычно используемая в отладке. Эти журналы помогают нам путешествовать по коду.
- TRACE: самые низкоуровневые данные, вроде трассировок стека, которые содержат больше всего информации об определённом событии или контексте. Эти журналы помогают исследовать значения переменных и полные стеки ошибок.
В Linux Syslog есть и более серьёзные уровни, такие как Emergency, Alert, Critical, Error, Warning, Notice, Informational и Debug.
Вне зависимости от сложности и глубины каждого уровня журналирования, мы должны корректно настраивать их в своём коде, чтобы предоставлять оптимальное количество информации в каждом сценарии. Например, все данные, используемые разработчиками для отладки и технического анализа, должны идти на уровнях DEBUG или TRACE, а баннеры с системными данными опускаются ниже INFO.
Используйте английский язык
Некоторые инструменты и консоли не поддерживают вывод и хранение журналов с определёнными Unicode-символами. Поэтому локализация и прочие улучшения могут доставить трудности. Придерживайтесь английского языка и всегда используйте для записи сообщений широко поддерживаемый набор символов.
2020-11-11 13:52:18 DEBUG App:36 - Loading adapters..2020-11-11 13:52:21 DEBUG Adapters:10 - Loading adapter docs/v12020-11-11 13:52:22 DEBUG Adapters:16 - Loading adapter mongo/v12020-11-11 13:52:26 DEBUG Docs:38 - docs adapter initialized2020-11-11 13:52:27 DEBUG Mongo:38 - mongo adapter initialized2020-11-11 13:52:22 DEBUG Adapters:20 - Successfully loaded all
Добавляйте удобные для разработчиков сообщения (краткие и содержательные)
Если журналировать слишком мало, но мы не сможем получить нужную информацию для воссоздания контекста каждого важного события. А если журналировать слишком много, то это ухудшит производительность: запись огромного файла журнала увеличит операции ввода-вывода и потребление ресурсов дискового хранилища. Если файловая система не поддерживает его, это снизит общую производительность системы.
Для оптимизации сообщений вам необходимо чёткое понимание функциональных и нефункциональных ожиданий от системы и планирование нужного качества и количества сообщений. Каждый журнал должен быть содержательным и соответствующим контексту: всегда пишите кратко и по делу.
2020-11-11 13:52:27 DEBUG Users:18 - Successfully created new user (RecordID: 5f5a0d594d17e22b848ee570)2020-11-11 13:52:27 ERROR Users:34 - Failed to update DB (E: inactive user, RecordID: 5f5a0d594d17e22b848ee570)
Создайте справочные идентификаторы, псевдонимы и упрощённые шаблоны для часто используемых и длинных сообщений
Вместо того, чтобы каждый раз записывать полное описание, попробуйте создать справочные идентификаторы или упрощённые шаблоны, чтобы представлять в журнале длинные повторяющиеся описания. Это уменьшает общее количество и длину сообщений, а также повышает гибкость в сокрытии определённой информации. Например, вместо того, чтобы описывать в текстовом журнале описание уязвимости, лучше использовать псевдоним или идентификатор, чтобы только профильные специалисты могли разобраться в актуальном сценарии.
2020-11-11 13:52:27 ERROR DB:22 - Failed to write (E:ORA-01017)// ORA-01017 denotes "invalid username/password; logon denied" error message
Используйте корректные временные метки
Временные метки позволяют понять последовательность событий, они необходимы для отладки и анализа. При фиксировании времени рекомендуется использовать наиболее подробные значения (например, на уровне милли- или микросекунд), чтобы легче было определять смежные события. Также убедитесь, что временные метки стоят в начале сообщения в формате yyyy-mm-dd HH:mm:ss. Всегда указывайте часовой пояс, если не используете на сервере время по умолчанию (UTC).
// with default server time (UTC)2020-11-11 13:52:12 INFO XYZ Integration API Manager v2.0.0// with timezone (e.g. PST - Pacific Standard Time)2020-11-11 13:52:12PST INFO XYZ Integration API Manager v2.0.0
Указывайте источник или происхождение журнальных данных (для DEBUG, TRACE, ERROR)
Это очень полезно для чёткого определения места, которое привело к соответствующему сообщению. Некоторые фреймворки для журналирования позволяют указывать источники на самом подробном уровне (вплоть до название файлов с номерами строк), но чаще всего достаточно упоминания только класса, функции или названия файла.
2020-11-11 13:52:12 INFO app - XYZ Integration API Manager v2.0.02020-11-11 13:52:15 INFO app - Loading configurations..2020-11-11 13:52:18 INFO app - *** InstanceID APIM_V2_I022020-11-11 13:52:18 INFO app *** BaseURL http://10.244.2.168:30002020-11-11 13:52:19 INFO app - *** LogLevel 05 (DEBUG)2020-11-11 13:52:12 DEBUG App:22 - Initializing Swagger UI..2020-11-11 13:52:14 DEBUG App:28 - Generating schemata..2020-11-11 13:52:14 DEBUG App:30 - Initializing REST services..2020-11-11 13:52:15 DEBUG App:32 - Generating documentation..2020-11-11 13:52:18 DEBUG App:36 - Loading adapters..2020-11-11 13:52:21 DEBUG Adapters:10 - Loading adapter docs/v12020-11-11 13:52:22 DEBUG Adapters:16 - Loading adapter mongo/v12020-11-11 13:52:26 DEBUG Docs:38 - docs adapter initialized2020-11-11 13:52:27 DEBUG Mongo:38 - mongo adapter initialized2020-11-11 13:52:22 DEBUG Adapters:20 - Successfully loaded all2020-11-11 13:52:31 INFO app - Started listening...
Каждый журнал должен быть уникален в рамках системы
Большинство новичков совершают одну и ту же ошибку копипастят образец сообщения в разных файлах, собирая финальный журнал из одинаковых строк, приходящих из разных частей системы. В этом случае трудно отследить конкретное место, которое вызвало это событие. Если набор слов нельзя менять, то хотя бы упомяните в сообщении источник, чтобы строки в финальном файле отличались друг от друга. Кроме того, если журналирование обрабатывается родительским классом, то отправляйте при инициализации идентификатор и применяйте его для записи сообщений о поведении дочерних классов.
2020-11-11 13:52:18 DEBUG App:36 - Loading adapters..2020-11-11 13:52:21 DEBUG Adapters:10 - Loading adapter docs/v12020-11-11 13:52:22 DEBUG Adapters:16 - Loading adapter mongo/v12020-11-11 13:52:26 DEBUG Docs:38 - docs adapter initialized2020-11-11 13:52:27 DEBUG Mongo:38 - mongo adapter initialized2020-11-11 13:52:22 DEBUG Adapters:20 - Successfully loaded all
Добавьте в сообщение отслеживаемый идентификатор или токен сообщения
Когда событие или сообщение попадает в систему, ему обычно присваивается уникальный идентификатор. Его можно передавать на другие этапы обработки, чтобы отслеживать движение события по системе, это полезно для отладки, конкурентной обработки и операций, связанных с данными. В идеале, в системе должен быть уникальный идентификатор события в рамках всех модулей и сервисов.
[87d4s-a98d7-9a8742jsd] Request Body: { "request_id": "87d4s-a98d7-9a8742jsd", "app_id": "TX001", "option_val": "IBM", "req_type_id": "0013", "data": {...........}[87d4s-a98d7-9a8742jsd] Sending request to RefData: href="http://personeltest.ru/away/10.244.2.168:8280/v1
Указывайте соответствие идентификаторов в точках перехода
В определённых случаях, особенно при передаче события из одной системы в другую, идентификаторы меняются в соответствии с принятым в другой системе соглашением. В таких точках перехода нужно отдельным сообщением явно указывать соответствие старого и нового идентификатора, с добавлением необходимого контекста.
[1000508] ***** Incoming request from 10.244.2.168:3000 *****[1000508] Origin Id: 87d4s-a98d7-9a8742jsd -> System ID: 1000508[1000508] Transaction successfully added to Rabbit Queue
Указывайте идентификаторы всех экземпляров сервиса
Большинство enterprise-систем являются распределёнными вычислительными платформами, в которых присутствует много экземпляров одних и тех же сервисов с разнообразными конфигурациями приложения, ресурсами, версиями и сетевыми свойствами. Рекомендуется присвоить экземплярам идентификаторы и использовать их при межсервисном взаимодействии.
2020-11-11 13:52:12 INFO app - XYZ Integration API Manager v2.0.02020-11-11 13:52:15 INFO app - Loading configurations..2020-11-11 13:52:18 INFO app - *** InstanceID APIM_V2_I022020-11-11 13:52:18 INFO app *** BaseURL http://10.244.2.168:30002020-11-11 13:52:19 INFO app - *** LogLevel 05 (DEBUG)
Настройте активный уровень журналирования
Активный уровень журналирования нужно менять в зависимости от окружения развёртывания. Для production рекомендуется выводить журналы вплоть до уровня INFO. В других окружениях журналы выводятся до уровня DEBUG или TRACE, в зависимости от степени подробности, которая нужна командам разработки и эксплуатации.
// Active Log Level = DEBUG2020-11-11 13:52:12 INFO app - XYZ Integration API Manager v2.0.02020-11-11 13:52:15 INFO app - Loading configurations..2020-11-11 13:52:18 INFO app - *** InstanceID APIM_V2_I022020-11-11 13:52:18 INFO app *** BaseURL http://10.244.2.168:30002020-11-11 13:52:19 INFO app - *** LogLevel 05 (DEBUG)2020-11-11 13:52:12 DEBUG App:22 - Initializing Swagger UI..2020-11-11 13:52:14 DEBUG App:28 - Generating schemata..2020-11-11 13:52:14 DEBUG App:30 - Initializing REST services..2020-11-11 13:52:15 DEBUG App:32 - Generating documentation..2020-11-11 13:52:18 DEBUG App:36 - Loading adapters..2020-11-11 13:52:21 DEBUG Adapters:10 - Loading adapter docs/v12020-11-11 13:52:22 DEBUG Adapters:16 - Loading adapter mongo/v12020-11-11 13:52:26 DEBUG Docs:38 - docs adapter initialized2020-11-11 13:52:27 DEBUG Mongo:38 - mongo adapter initialized2020-11-11 13:52:22 DEBUG Adapters:20 - Successfully loaded all2020-11-11 13:52:31 INFO app - Started listening...// Active Log Level = INFO2020-11-11 13:52:12 INFO app - XYZ Integration API Manager v2.0.02020-11-11 13:52:15 INFO app - Loading configurations..2020-11-11 13:52:18 INFO app - *** InstanceID API_V2_I022020-11-11 13:52:18 INFO app *** BaseURL http://10.244.2.168:30002020-11-11 13:52:19 INFO app - *** LogLevel 04 (INFO)2020-11-11 13:52:31 INFO app - Started listening...
Предоставляйте достаточный контекст для ошибок и сбоев
Ошибки и сбои требуют самого тщательного расследования. Для этого приложение должно предоставлять профильным специалистам необходимую информацию, а также технологический и бизнес-контекст. Например, если запрос или сообщение не удалось обработать, то в дополнение к ошибке очень полезно журналировать и тело сбойного запроса.
[1000508] ***** Incoming request from 10.244.2.168:3000 *****[1000508] Origin Id: 87d4s-a98d7-9a8742jsd -> System ID: 1000508[1000508] Failed to validate msg body (E: Uncaught ReferenceError: missing params - option_val)[1000508] Failed Message: { "request_id": "87d4s-a98d7-9a8742jsd", "app_id": "TX001", "req_type_id": "0013", "data": {...........}}
Подтверждайте доказательствами операции с данными (не предполагайте!)
При каждой операции с данными не принимайте на веру успешность её выполнения. Всегда проверяйте конечное состояние с помощью доказательств. Например, когда вы создаёте, обновляете или удаляете запись в базе данных, она возвращает счётчик изменённых записей и саму обновлённую запись. Всегда выполняйте проверку ожидаемого счётчика или результата. Другой пример: когда вы вставляете запись в структуру данных (например, в очередь), то проверяйте, увеличился ли её размер. Предположим, в вашей системе используются конкурентные операции, но очередь их не поддерживает. Тогда вы можете терять какие-то записи, и единственный способ обнаружить такие скрытые ошибки в коде это проверка длины.
DEBUG BatchWriter:28 - Successfully connected to DB. Trying to insert 24 accounts...DEBUG BatchWriter:35 - Successfully inserted 24 accounts. Total DB rows affected: 24
Шифруйте или маскируйте конфиденциальные данные
Обычно закон требует маскировать и/или шифровать конфиденциальную информацию пользователей и внутренних систем. В зависимости от вашей отрасли и места работы могут меняться и требования регуляторов. Выясните все нюансы и реализуйте в приложении корректные процедуры. В некоторых случаях перед началом эксплуатации вам может потребоваться представить стратегию журналирования службе безопасности и получить их утверждение или сертификат.
[1000508] ***** Incoming request from 10.244.2.168:3000 *****[1000508] Origin Id: 87d4s-a98d7-9a8742jsd -> System ID: 1000508[1000508] Request Body: {user_id:XXXXXXXXXX,personal_details:{ firstName:XXXXXXXXXX, lastName:XXXXXXXXXX, DOB:XXXXXXXXXX, gender:Male, proffessional:Software Architect, industry:IT, SSN:XXXXXXXXXX},address_history:[ {streetAdress:Street No 1,zipcode:XXXXX,state:CA}, {streetAdress:Street No 2,zipcode:XXXXX,state:NY}, {streetAdress:Street No 2,zipcode:XXXXX,state:AL}],card_info:[ {type:amex,card_number:XXXXXXXXX,credit_limit:XXXXX}, {type:visa,card_number:XXXXXXXXX,credit_limit:XXXXX}]}
Настройте именование файлов журналов, политики ротации, размер хранилищ и процедуры резервного копирования
Если вы пишете журналы в файлы, то убедитесь, что они хранятся на отдельном диске, который никак не влияет на работающее приложение (например, можно выделить том на удалённом сервере и прикрепить его к серверу приложений). Также выясните частоту журналирования и характер увеличения файлов. Убедитесь, что у вас есть политика ротации журналов с корректными соглашениями по наименованиям (например, при создании к названию добавляется временная метка), чтобы поддерживать идеальный размер и количество файлов. Также у вас должен быть механизм резервного копирования старых журналов в безопасное место, и механизм регулярной очистки хранилищ. В зависимости от вашей отрасли можно настроить резервное копирование по времени (обычно каждые несколько месяцев или лет), с уничтожением всех предыдущих файлов в конце периода.
[ec2-user@ip-XXX-XX-X-XXX logs]$ ls..APIM_V2_I02-2020-11-20_04:38:43.logAPIM_V2_I02-2020-11-23_02:05:35.logAPIM_V2_I02-2020-11-24_04:38:17.logAPIM_V2_I02-2020-11-27_03:28:37.logAPIM_V2_I02-2020-11-27_12:06:45.log...
4. Дополнительные рекомендации
Используйте центральный агрегатор журналов
Очень распространённая практика среди разработчиков enterprise-приложений создание центрального доступного сервера или места для сбора журналов. Обычно такие агрегаторы отслеживают журналы не только приложений, но также устройств и операционных систем (например, Linux Syslog), сети, сетевых экранов, баз данных и т. д. К тому же они отделяют файлы журналов от серверов приложений и позволяют хранить журналы в более защищённых, упорядоченных и эффективных форматах более длительное время. В некоторых отраслях (например, банковской и финансовой) необходимо хранить журналы как в локальном, так и в центральном хранилище, чтобы злоумышленники не могли получить доступ к обоим местам и одновременно удалить доказательства своей деятельности. Так что избыточность данных и их несоответствие между двумя хранилищами могут помочь заметить проникновения.
Пишите парсеры и предусмотрительно отслеживайте журналы
Возможность написания парсеров и фильтров встроена в большинство инструментов для мониторинга журналов так называемая SIEM-интеграция (security information and event management). Парсеры помогают сохранять журналы в более упорядоченных форматах, а запрашивать данные становится гораздо проще и быстрее. Также правильно организованные данные можно передавать системам мониторинга и поиска аномалий для профилактического мониторинга и прогнозирования будущих событий. Эти инструменты обладают очень широкими возможностями по графическому отображению данных на основе временных последовательностей и в реальном времени.
Настройте оповещения и push-уведомления для критических инцидентов
Почти все инструменты мониторинга журналов позволяют задавать определённым уровням свои пороговые значения. Когда система достигает таких значений, инструмент заранее обнаруживает их, помогает журналировать данные и уведомляет сисадминов с помощью оповещений, API push-уведомлений (например, Slack Audit Logs API), электронных писем и т. д. Также их можно заранее настроить на инициирование автоматических процессов вроде динамического масштабирования, резервного копирования системы, переброски нагрузки и т. д. Но если вы вкладываетесь в коммерческое ПО для мониторинга журналов, внимательно его изучите, потому что такие инструменты могут быть избыточны для небольших и средних программных систем.
5. Рекомендуемые инструменты
Фреймворки для журналирования
JavaScript/TypeScript: Log4js / pino
Java: Log4j
Golang: Logrus
Serverless-функции: aws-lambda-powertools-python / Самописное
Изучение, агрегирование и мониторинг журналов
CLI-инструменты: less, vim
Облачные инструменты: Fluentd, AWS CloudWatch
SIEM-инструменты: SolarWinds, Splunk, McAfee ESM, DataDog, IBM QRadar
Прочие: ELK Stack (ElasticSearch, Logstash, Kibana, Beats), Loggly
