Дзен логування. Як полюбити свої логи та почати жити
Мене звати Євгеній Сафонов. Я Senior Software Developer у компанії Terrasoft, де моя робота зосереджена довкола систем з мікросервісною архітектурою. У статті я спробував зібрати весь позитивний і негативний досвід у підходах до організації логів. Матеріал буде корисний тим, хто лише задумується про логування у своєму продукті, а також тим, хто хоче щось змінити у логах, але не знає, з чого почати.
Так уже склалося, що людям з давніх-давен потрібно вести хронологію подій під час певного процесу. Приклад? Напевно, кожен з вас читав романи або ж дивився фільми про морські пригоди. Пригадуєте, як капітан корабля щодня заповнював бортовий журнал (англ. log book)? Дата, курс, швидкість, погодні умови, стан команди. Все це могло допомогти під час вирішення питань і проблем із судновласником, для відновлення подій при катастрофах, журнал мав юридичну силу в суді. І до нашого часу це залишається незмінним. Зокрема, всі ми знаємо про «чорні ящики» літаків. Тож, як ми бачимо, реєстрація подій, параметрів, стану системи завжди була актуальна в багатьох галузях, коли вже постфактум потрібно проаналізувати та виявити причини проблем, несправностей, аварій.
З виникненням автоматизованих комп’ютерних систем нічого особливо не змінилося і програмісти нічого нового не винайшли — вони почали писати такі ж «бортові журнали», що відомі нам як логи. Логи — це хронологічний запис подій, параметрів і станів системи під час її функціонування. Звучить просто і зрозуміло — просто бери й пиши те, що відбувається у системі, але на практиці виникає багато запитань: що писати? Скільки писати? Про що подумати заздалегідь? Як написати так, щоб потім було зручно читати (можливо, в критичний момент та у стресовій ситуації).
У цій статті я буду оминати конкретні системи/фреймворки логування, тут не буде порівнянь характеристик продуктів. Якщо цікаво, які інструменти ми використовуємо для збору та аналізу логів, прочитайте ось цю статтю. Тут буде лише про підходи та практики, про те, як спробувати досягти «дзену» та «нірвани» в логуванні або хоча б перестати мріяти про нормальні логи, а просто взяти та зробити. Не гарантую, що найгірший день вашого інженерного життя ніколи не настане після цієї статті, але принаймні у вас будуть логи. Вйо до логування!
Для чого потрібні логи і якими вони мають бути
Часто на старті проєкту логуванню приділяють недостатньо уваги, тому виникає одна з трьох ситуацій:
- Логів немає взагалі, адже все і так працює (до певного моменту).
- Логи є, але структура їх не продумана, вони малоінформативні.
- Залоговано абсолютно все, що перевантажує логи та ускладнює їхній аналіз.
Програмістам більш цікавим видається вибір фреймворків та систем логування — читання порівняльних статей типу ELK vs GrayLog vs Splunk (тисячі їх!). Але як щодо того, що саме логувати?
Логи можна оцінити за трьома параметрами:
- Якість — чи містить окремо взяте повідомлення цінну інформацію.
- Цілісність — чи можна на основі наявних повідомлень побудувати закінчений логічний ланцюжок подій, що призвів до проблеми.
- Повнота — чи достатньо в логах інформації для відтворення проблеми на середовищі розробника, чи достатньо даних, щоб одразу пофіксити.
Без докладного попереднього оцінювання того, що саме треба логувати, будь-який найпродуктивніший кластер збору та аналізу логів перетвориться на машину з виробництва купи непотребу...
Тож якими мають бути логи? Що в них має бути, а чого не повинно бути взагалі? Однозначних відповідей на ці питання немає, як і немає нічого цілковито однозначного в нашому житті. Спершу дозволю собі побути всім відомим Капітаном і зазначити кілька очевидних речей, які від того є не менш важливими.
Добре продумайте вміст логів: у них має міститися лише корисна інформація, яка допоможе розв’язати проблеми. Згадайте, як часто ви бачили повідомлення, які хотілося скоротити до мінімуму, бо обсяг тексту був величезний, а суть можна було б вмістити у кілька слів. Логічним продовженням цієї думки є те, що логи повинні мати однорідну структуру у всіх підсистемах та модулях. З таким підходом у вас швидко з’являться прості та ефективні патерни пошуку потрібної інформації. І, мабуть, найкритичніше зауваження — швидкий і простий доступ. Неважливо, наскільки гарні ваші логи, якщо їх вам доставляють голуби якщо ви не можете отримати їх вчасно або у зрозумілому вигляді. Це призведе до критичних затримок під час вирішення питань клієнтів, які звернулися у технічну підтримку. Користувачі не зможуть отримати гарний сервіс, а бізнес втратить гроші.
Це звучить як «за все хороше, проти всього поганого» (або радше як улюблена приказка нашої команди: «Все, що має бути зроблено, має бути зроблено»), але згадаймо такі принципи розробки, як KISS, DRY, YAGNI. Вони ж теж очевидні. Насправді всі підходи, що закликають до простоти, ощадливості, зрозумілості, тяжіють до філософського принципу «бритва Оккама». Думайте про нього, створюючи щось нове, навіть якщо це «всього лише логи».
Гаразд, логи мають бути лаконічними, читабельними й бути під рукою. Але визначмося з тим, що варто записувати до логу, а від чого варто утриматися. Логи не повинні містити:
- Приватні та персональні дані: логіни, паролі, секретні ключі, персональні дані клієнтів, все, що може випадково потрапити у зовнішній світ. Як часто буває, що для вирішення проблеми службі підтримки потрібно вивантажити логи й передати їх команді розробки на аналіз або ще кудись?
- Метрики, статистика швидкодії та продуктивності — для цього є окремий вид систем для збору та аналізу метрик, залиште це їм.
- Бізнес-дані — система лише пише журнал, читаєте його ви. Ваша система не повинна функціонувати, спираючись на дані з власного логу (мені про це навіть писати дико, але таке я бачив).
Логи можуть містити:
- Активність користувачів — початок і завершення сесії, які процеси запускаються, які запити виконуються.
- Активність системних процесів — якщо у вашій системі виконуються фонові процеси, що не ініціюються користувачами прямо, ви повинні знати, коли і як це відбувається.
- Нетипова активність — спроби неавторизованого під’єднання, запити, що не пройшли валідацію. Усе, що не є винятковою ситуацією, але вибивається з нормального процесу.
- Винятки та помилки — будь-які виняткові ситуації, що продукує чи перехоплює ваш код.
- Докладна інформація для розробників — все те, що допоможе розібратися під час виникнення проблем.
Ці п’ять пунктів, що роблять ваші логи корисними, а вас успішним та щасливим розробником, насправді гарно описуються різними рівнями логування. Рівень логування — це параметр, що вказує, наскільки детальними є логи та яка інформація збирається. Які є рівні логування і що вони означають (від найвищого до найнижчого):
Trace. Схоже на пацієнта, під’єднаного до різноманітних приладів для збору всіх можливих показників, може закінчитися розтином. До логу записуються значення всіх властивостей екземплярів класів у кожен момент змін, всі параметри методів та їхні виклики, в особливо критичних місцях логується виконання кожного рядка коду. Цей рівень ви вмикаєте тільки в середовищі розробки/тестування.
Debug. Похід у медичну лабораторію для здачі аналізів. Деталізована інформація про роботу системи для розробника, те, що недоступно зовнішньому світу у звичайних умовах. Значення системних параметрів, всі запити до джерел даних, виклики методів. Можливе увімкнення цього рівня на продуктивному середовищі на короткий час для виявлення складних помилок (так, наша команда це практикує, але ми цим не пишаємося і вас просимо бути обережними).
Information. Щось відбулося, щось почалося або закінчилося, хроніка діяльності вашої системи. Коли станеться помилка, саме ці логи допоможуть зрозуміти, що відбувалося до/після виникнення критичної ситуації.
Warning. Все в нормі, але відбулося щось підозріле, некритична позаштатна ситуація. Спроба неавторизованого під’єднання, не вдалося прочитати параметр з конфігураційного файлу, тому буде використовуватися значення за замовчуванням тощо.
Error. Те, що призводить до звернень клієнтів у техпідтримку. Події, що переривають виконання поточної операції, але не впливають на подальшу роботу. Це можуть бути винятки, перехоплені від під’єднаних фреймворків, зовнішніх систем, чи згенеровані вашою ж системою. І пам’ятайте головне: «У вашій системі може бути будь-яка кількість помилок, доки ця кількість дорівнює нулю», як казав Генрі Форд (а може, Джейсон Стейтем, але це не точно).
Fatal. Це останній подих системи, ваш телефон розривається від дзвінків. З таким рівнем ви маєте логувати помилки та виняткові ситуації, коли ваша система не може продовжувати функціонувати за поточних умов: відсутнє під’єднання до бази даних, втрачено зв’язок з іншими компонентами системи, основний процес завершився некоректно і систему ось-ось буде перезавантажено.
Важливо зазначити, що, вмикаючи в конфігурації системи один з рівнів логування, також будуть залоговані й повідомлення нижчих рівнів. Наприклад, увімкнувши рівень information, ви матимете записи логів warning, error, fatal. Однак фреймворки логування дають змогу налаштовувати фільтрацію більш гнучко.
Як бачите, різні рівні логування передбачають різний обсяг інформації та інтенсивність запису даних: fatal логується найрідше, задля вашого ж блага та спокою, trace — ледь не на кожному кроці. Отже, варто пам’ятати, що в продуктивному середовищі не варто вмикати логування вище рівня information. Debug, а тим паче trace — лише для розробника для діагностування проблеми постфактум.
А практика?
Дописавши статтю до цього моменту, мені вже самому (сподіваюся, як і вам, любі читачі) хочеться чогось більш практичного, щось увімкнути, налаштувати, так щоб «вжух» — і є логи. Але ні. Дива не буде. Розробники за своєю природою люди ліниві, а отже, постає питання: невже я, як автор коду, маю власноруч скрізь писати щось типу mySweetLogger.Information("Incoming request", requestBody, ...), в try..catch конструкціях зазначати mySweetLogger.Error("Error message«, exception), а також на кожному кроці розставляти mySweetLogger.Debug(...)? Відповідь: так.
Логування — це невіддільна частина розробки у великих системах, і якщо розробники проігнорували логування, то зі зростанням продукту вам доведеться знову перебрати весь код, щоб розставити логування з необхідними рівнями в потрібних місцях.
Мене якось запитували, чи є системи, які самі будуть писати, що відбувається всередині програмного продукту? Так, є. Наприклад, New Relic. Ця та інші схожі системи здатні слухати ваш вебсервіс, записувати всі запити до нього, до БД, винятки та іншу статистику. Вони налаштовуються дуже швидко, мають дружній інтерфейс і надають багато інструментів для аналітики та моніторингу роботи системи. Але:
- На швидкодію системи починає впливати так званий ефект спостерігача, коли запит опрацьовується не лише вашим кодом, а й сторонньою системою, що додає часу на обробку.
- Ви маєте тільки ту інформацію, що дозволяє збирати ця система, а її не завжди достатньо.
- Ви не можете детально залогувати кожен крок критичного процесу.
- Найімовірніше, вам буде складно масштабувати таке логування зі зростанням системи.
- New Relic платний.
Антипатерни
Виявляється, в логуванні є патерни. А там, де герої, є й антагоністи. Перед тим як розібрати приклади, варто замислитися над тим, звідки беруться антипатерни. Виявляється, якщо не аналізувати проблеми, не вивчати найкращі практики та підходи, не обговорювати задачі з колегами, не робити код-рев’ю, не займатися парним програмуванням тощо, легко їх знайдете. Найпростіше написати так, як придумав тут і зараз. Але це все виливається в кілька антипатернів.
Антипатерн: беззмістовні info-логи
Що ми бачимо в цих записах? Щось відбулося. І це «щось» зайняло певну кількість часу. Очевидно, це метрика швидкодії, але в логах їй не місце, адже не зрозуміло, як ці цифри агрегувати. Невідомо навіть, яка подія відбувається, які параметри оброблялися. Але що найгірше в цих логах: вони займають місце і створюють шум, з яким потрібно якось боротися.
Ліки: патерн «Аудит»
Антипатерн: беззмістовні стеки виклику
У цьому прикладі ми бачимо, що сталася помилка під час виконання SQL-запиту. Дослідивши стек виклику, можемо з’ясувати, яка саме бізнес-логіка виконувалася, знайти місце в коді, де сталася помилка. А от дізнатися причину ми не можемо! Проблема в синтаксисі запиту? У параметрах? Проблема в структурі таблиці? А може, її взагалі немає? Чи ми не туди під’єдналися? А може, з кодом і базою все окей, але ми не провалідували вхідні дані? Мені аж припікає від думки, скільки місць потрібно перевірити: код, структура БД, параметри під’єднання на проді, вхідні дані. Йосип босий, гори воно все в пеклі! [Чути матюки, удари та хрускіт розтрощеної клавіатури.]
Ліки: патерн «Відстежування винятків»
Антипатерн: погана зв’язаність логів
До вже знайомого нам SQL-запиту додамо ще один лог (нас цікавить виділений рядок). Відразу спойлер: це два пов’язані повідомлення, EventSyncLogger просто каже нам, що синхронізація даних провалилася, а EventHandlerLogger — що це сталося через виконання SQL-команди. Насправді про їхню пов’язаність я знаю з досвіду, а не тому, що це вказано в логах. Усе, що їх пов’язує на перший погляд — це час повідомлення. Ось що ми маємо: кілька логерів, що логують одну ітерацію певного процесу. Перший логер пише повідомлення на рівні web-api, другий — на рівні бізнес-логіки, третій на рівні репозиторіїв даних. Але їхні повідомлення ніяк не пов’язані прямо хоча б якимись спільними параметрами, як-от сесія, ідентифікатор користувача, сам об’єкт даних, бодай щось. Тобто, аналізуючи проблему, ми не можемо побудувати послідовність розвитку подій за цими повідомленнями, залишається тільки здогадуватися про їхню спільну долю, наприклад, за часом.
Ліки: патерн «Трасування розподілених подій».
Антипатерн: переоцінені винятки
Усі чули стару казку про хлопчика, який кричав «Вовк!»? А чи стикалися ви з ситуацією, коли, читаючи з досвідченим колегою логи в пошуках проблеми, ви помічали багато Error-повідомлень. А коли вказували на це своєму напарнику, чули у відповідь: «А, та забий, воно завжди так працює, то не в тому проблема. Тут щось інше». Відчули сюр? У логах стільки помилок, які начебто не впливають на працездатність системи, що на них вже просто не зважають. То як же серед цієї купи непотребу знайти помилку, яка й справді має значення і є причиною поточної проблеми? Або ніяк, або з витрачанням багатьох зусиль і часу.
Одна історія для прикладу. Наша система інтегрована з кількома сторонніми сервісами по REST API. І зазвичай, якщо ці сервіси на запити відповідали не HTTP Satus 200 OK, то це означало, що в них щось зламалося. Звісно, ми ці винятки логували як Error, окремо були налаштовані метрики з нотифікаціями, що прилітають у Telegram-чат. І ось один з таких сервісів вирішив стати RESTful. Якщо наш запит не проходив валідацію, то у відповідь присилали не 200 OK { success: false}, а 400 BadRequest { success: false}. У лог стали сипатися помилки, а чат почав рясніти повідомленнями, що «все пропало». Ми деякий час просто перевіряли ці сповіщення, щоб упевнитися, що тривога хибна. І скоро стали пропускати справжні проблеми. І дізнавалися про них уже не з нотифікацій, а від клієнтів. Просто тому, що звикли до великої кількості хибних Еrror-повідомлень.
Антипатерн: файлові логи для великих систем
Немає нічого більш нудного і марного в контексті витрати часу, ніж читання файлових, або, як ми їх називаємо, «паперових», логів. Ти перебираєш ці величезні файли, що не хочуть відкриватися у текстових редакторах, грепаєш і парсиш їх у пошуку послідовності подій, що призвели до проблеми. А якщо ваші сервіси ще й на різних серверах, де кожен пише логи собі на диск... Це настільки здоровецька халепа, що навіть писати про це не можу.
Ліки: патерн «Агрегація логів»
Патерни
І от нарешті ми дійшли до патернів, що допоможуть втамувати біль і тугу від марно витрачених часу і зусиль, зробити пошук несправностей набагато легшим і значно приємнішим. Важливе зауваження: лише комплексне впровадження цих патернів буде ефективним, оскільки кожен закриває певну проблему. А невирішеним проблемам властиво вигулькувати у найбільш невдалий момент.
Патерн: аудит
Як дізнатися, що відбувається у системі? Ні, навіть не так. Як дізнатися, що відбувалося у системі до того, як все впало і вам почали сипатися сповіщення на пошту, в чат або, що гірше, як звернення у службу підтримки? Використовувати патерн «Аудит».
Насправді в ньому немає нічого магічного та принципово нового. Він просто каже: логуйте активність користувачів та процесів у системі. Якщо щось відбулося, ви повинні мати запис про це на рівні info-повідомлень. Таким чином матимете історію подій до моменту виникнення помилки, тож вам не знадобиться запитувати у користувачів кейси для відтворення.
Можливо, з часом частина цих логів стане непотрібною у нормальному режимі роботи й перейде на рівень Debug. А на практиці логування деяких компонентів системи взагалі може вмикатися на рівень Error, коли робота налагоджена і проміжна інформація обробки даних не потрібна. На рівні Info у нас логуються лише сервіси, що приймають вхідні дані, і ті, які відсилають дані до зовнішніх систем. Таким чином ми знаємо, у якому вигляді дані прийшли до нас і в якому вигляді ми відіслали їх далі третім системам.
Патерн: відстежування винятків
Я вже писав про те, як жахливо виглядають логи помилок без детального опису. Це, мабуть, найбільший розпач під час розв’язання проблем. Коли ти відкриваєш лог помилок, знаходиш потрібне повідомлення у потрібний час і бачиш лише стек виклику і тип винятку NullReferenceException. Потім заглядаєш у код потрібного методу і бачиш
Тому й важливо при виникненні винятку залогувати максимум корисної інформації: запит, якщо це вебсервіс (але пам’ятаємо про GDPR), вхідні параметри методу, будь-які змінні середовища, що впливають на логіку коду. Не забувайте про ідентифікатор користувача / сесії / процесу, щоб однозначно зв’язати проблему, що виникла у клієнта, з тими помилками, які ви знайшли у логах. Буде прикро, якщо виявиться, що зроблений фікс не стосується поточної проблеми, а запобігає іншій, яка ще не сталася (і ви молодець, але не у цей момент). І, що не менш важливо, лог помилки не повинен бути просто суперінформативним, він має бути зв’язаним з усіма повідомленнями усіх рівнів, що були залоговані з самого початку процесу чи обробки запиту.
Патерн: агрегація логів
Добре жити в моноліті. Добре жити в моноліті на одному екземплярі сервісу: запит, що приходить на сервіс, обробляється на цьому ж сервісі, логи теж поруч у файловій системі. Зовсім інша історія, коли ви прийшли до мікросервісної архітектури: неможливо ефективно аналізувати логи, якщо вони розташовуються окремо для кожного сервісу.
Цей патерн говорить про те, що необхідно збирати логи в одну централізовану систему, яка має відповідати двом простим вимогам:
- швидкий доступ, будь-де і будь-коли;
- зручний пошук і перегляд.
Всі інші вимоги на кшталт налаштування сповіщень, дашборди, розмежування прав доступу — корисні, але не обов’язкові бонуси. Все, що вам потрібно у критичній ситуації, це швидко знайти проблему та віднайти послідовність подій, що до неї призвели. Як саме це зробити? Читайте далі.
Патерн: трасування розподілених подій
Отже, ви зібрали всі логи в одному місці. Обрана система за лічені мілісекунди повертає на ваш запит логи будь-якого сервісу. Але що робити, якщо процес обробки одного бізнес-кейсу відбувається на кількох різних сервісах? Що, як запит надійшов на сервіс A, виняток виник у сервісі F, а причина в тому, що сервіс C відпрацював некоректно, про що є запис у вигляді Warning-повідомлення. Як побудувати цей причинно-наслідковий зв’язок?
Відповідь на це питання дадуть герої казки братів Грімм — Гензель і Гретель. Ідучи лісом, вони кидали на землю крихти, щоб залишити слід і повернутися по ньому додому. У них все вийшло не так просто і добре, але ідея гарна, тож і ми нею скористаємося. Додавайте до ваших повідомлень ідентифікатори користувача, сесії або інші параметри, що допоможуть об’єднати всі події в опис одного цілісного процесу від початку до кінця. Це може бути навіть випадковий абстрактний TraceId, що генерується на вході у сервіс і передається разом із запитами на всі інші проміжні сервіси до кінця бізнес-процесу. Алгоритм дій під час пошуку проблеми простий:
- Ви знаєте клієнта/користувача, у якого виникла проблема, і приблизний час, коли це сталося.
- Шукаєте в логах відповідні вхідні запити за цей час для цього користувача.
- Дізнаєтеся з цих логів TraceId та знаходите всі повідомлення, що пов’язані з цим запитом, у якому б сервісі вони не були оброблені.
- Бінго! Фікс — деплой або просто консультація, що так робити не можна.
А тепер про GDPR
Дуже зручно для розв’язання проблем логувати максимум інформації, зокрема вхідні запити від користувачів API. Але відколи з’явився GDPR, ми не можемо собі дозволити зайве зберігання персональних даних клієнтів та, можливо, їхніх клієнтів, котрі взагалі не знають про існування нашої системи. І логи — це перше місце, де ви маєте позбутися будь-якої персоналізації, тому що для бізнес-процесів дані в логах не потрібні, а служба підтримки/розробники, що цими логами послуговуються, даруйте, обійдеться. Таке життя. Тому:
- Залиште в логах лише анонімні ідентифікатори, за якими ви зможете знайти потрібні дані в БД (на зберігання в якій користувач дає згоду, але знову ж таки на обмежений період).
- Доцільніше не просто видаляти персональні дані, а заміняти їх на анонімізований рядок. Тоді, читаючи логи, ви хоча б будете розуміти, що ті дані там усе-таки були, а не просто надійшов кривий запит.
- Якщо ви не подумаєте про GDPR на етапі проєктування, то вам потім доведеться поспіхом передивитися все логування в системі на наявність персональних даних. У нас саме так і трапилося, але наша система з’явилася раніше за GDPR.
Епілог
Ми вже давно живемо у світі, де все, що ви робите онлайн, опрацьовується дуже багатьма системами. І якщо так уже трапилося, що ви серед авторів схожих систем, то це ваша відповідальність полегшувати власне життя під час виникнення позаштатних ситуацій.
Ви повинні мати всі необхідні інструменти й дані для швидкого вирішення проблем, і логи — невіддільна частина всієї цієї кухні. І пам’ятайте, що логування має зароджуватися разом з архітектурою системи, адже потім набагато складніше елегантно увімкнути його у кожен бізнес-кейс і водночас нічого не забути.
