×Закрыть

Тернистим шляхом до системи логування Graylog

Цю статтю спрямовано на огляд дуже універсальної системи логування, приклади й практичний досвід наводитимемо через призму всесвіту .NET / .NET Core. Але вірю, що ця інформація може допомогти всім без винятку, хто шукає системи такого класу.

Матеріал написано у співавторстві з Олександром Гілєвим, .NET розробником в Terrasoft

Пролог. Частина лірична й не обов’язкова

Хто входить тут, покинь усю надію.

Данте Аліг’єрі, «Божественна комедія»

З чого починається збір логів у будь-якому проекті? З того, що одного разу ваш продукт, що добре й стабільно працює, перестає таким бути, а відповіді на запитання «чому?» у вас немає. І ми не маємо на увазі систему в продакшн-середовищі: це може бути навіть beta-демка, MVP та інші варіанти доведення правильності концепції вашої майбутньої системи. Ось у такі моменти й з’являються логи. Зазвичай у вигляді файлів у директорії Log поруч з бінарними файлами вашого продукту. Звісно, досвідчений програміст відразу долучає зручний і потужний фреймворк для логування, наприклад log4net, як зробили ми. Тепер усю важливу інформацію в читабельному й добре структурованому вигляді розкладено на рівнях Error, Warn, Info й Debug, і розробники / адміністратори / технічна підтримка системи мають відповіді на всі запитання й можуть розв’язати будь-яку проблему. Який чудесний світ новий.

У нашому випадку системою, у якій велике значення мали якісні логи, був веб-сервіс, написаний, як ви могли здогадатися, на .NET Framework і розміщений в IIS на єдиному сервері. Усі логи писали на окремий диск і їх було розділено на окремі файли відповідно до підсистем (incoming requests, Web API, engine й outcoming requests). На перший час цього було досить, і навіть спеціалісти служби підтримки мали змогу ці файли читати й знаходити там відповіді в разі виникнення проблем.

Так ми прожили майже рік. Сервіс стрімко розвивався, кількість клієнтів сервісу зростала, а разом з нею зростала й кількість логів. Пошук інформації в логах став важким і марудним процесом: просто через великий обсяг файлів (понад 100К повідомлень), а також їхню велику кількість (до 100 файлів одного логера на добу). Часом, щоб відстежити початок і закінчення обробки реквесту, потрібно було розпарсити кілька десятків таких файлів. Особливо це стало бентежити службу підтримки, де час на надання відповіді дуже критичний, і якоїсь миті вони відмовилися самостійно копирсатися в логах і повернули цей привілей команді розробки.

Оскільки розробники — люди дуже ліниві й схильні до зменшення кількості страждань завдяки автоматизації, з’явилася чудова ідея: нам потрібна централізована система збору й обробки логів зі зручним пошуком, дружнім інтерфейсом, грою в дурня та панянками.

Поява героя

В один з періодів обговорення проблеми логів зринула назва Graylog, і після кількох експериментів із цією системою було вирішено запустити її в продакшн-середовище. З іншими такими системами глибоких порівнянь та аналізу не проводили. На той час це була ще версія 1.0, на час написання статті в релізі вже версія 3.0. Що відразу підкуповувало в цій системі:

  • Проста інтеграція з нашим сервісом. Фактично в конфігураційних файлах log4net просто з’явився новий апендер Gelf4net (за посиланням знайдете інструкції з налаштування). У самому коді жодних змін (майже).
  • Зрозумілий і дружній веб-інтерфейс самого Graylog.
  • Швидкий пошук зі зрозумілим форматом запитів, завдячуючи Elasticsearch під капотом.

Тепер трохи більше деталей.

GELF — власний формат опису й передачі логів. Але завдяки наявним бібліотекам вам не доведеться в ньому дуже розбиратися. Ви можете просто під’єднати апендер до конфігураційного файлу, і все запрацює. Але що зручно — є можливість додавати до ваших логів нові поля для розширення інформації та зручності подальшого пошуку. У вищезгаданому репозиторії GitHub є приклади з додавання additional fields як константами в конфігураційному файлі, так і з коду. І це дуже важливо для подальшої ефективності пошуку: замість того, щоб додавати назву поточного модуля або яку завгодно ключову інформацію до тексту вашого повідомлення, додайте окреме поле, яке швидко індексуватиметься в Elasticsearch.

Щодо протоколу доставки даних у Graylog: на той час ми спробували HttpAppender та UdpAppender. Вибір зробили на користь другого через набагато більшу швидкість передачі. Elasticsearch було розгорнуто в кластері з 2 нод. Також було 2 ноди веб-сервісу самого Graylog.

За деякий час виявилося, що сервісом неможливо користуватися: UI постійно зависає, результати пошуку повертаються по 5 хвилин, половина логів просто губиться. Усе це відбувалося через те, що:

  • Ми під’єднали до Graylog занадто багато систем, незалежно від географічної віддаленості серверів.
  • Кластер Elasticsearch було некоректно налаштовано, і, як наслідок, обидві ноди займалися й пошуком, і зберіганням, і прийомом логів.
  • UDP. Це протокол без гарантії доставки, і в миті великих навантажень ми просто викидали дані в нікуди.

Три окремі проблеми, які вкупі вбили на той час подальше використання нами цієї системи.

Нова надія

Так уже сталося, що тоді через брак часу й ресурсів ми припинили пошуки шляхів розв’язання виявлених проблем і повернулися до зберігання логів у файловій системі. Крок назад? Так. Але ми суттєво переглянули інформацію, що логується, і позбулися інформаційного сміття: щось зовсім перестали логувати, щось перевели на рівень Debug. У продакшн-середовищі в деяких компонентах логування перевели лише на рівень Error, знаючи, що інші рівні повідомлень там не потрібні. Наприклад, для Web API нам потрібні логи вхідних запитів, щоб знати, які дані надходять до сервісу, — це рівень Info; а от для фонових процесів нашої системи нам не важливо знати їхні проміжні дані, потрібно лише знати, коли трапляються виняткові ситуації, — це рівень Error.

Також чималий ефект дало використання BufferingForwardingAppender, що виконує запис у файл не на кожне повідомлення, а тільки коли набере певну їх кількість у буфер: можна налаштовувати як кількість повідомлень у буфері, так і інтервал, за який нагромаджені повідомлення скидати у файл.

Ці кроки дали нам змогу зоптимізувати не тільки якість логів, а ще й швидкодію системи (про швидкість є хороша стаття тут).

Наступним каталізатором до відновлення пошуку дорослої системи обробки логів став .NET Core. Усі компоненти нашого сервісу набули вигляду акуратних контейнерів у Docker під управлінням Kubernetes, а правильний збір і зберігання логів стали нагальною потребою. І знову ми згадали про Graylog, звісно, пам’ятаючи перший негативний досвід. Читачі статті можуть поставити логічне запитання: чому не ELK? Для нас Graylog мав такі переваги:

  • Простий дружній інтерфейс, з яким уже знайома служба підтримки.
  • Можливість створення й розмежування прав юзерів.
  • Можливість створення й перегляду в UI потоків логів (початкове розмежування вхідних логів з фільтрацією + розмежування прав на потоки).
  • Можливість об’єднання логів з різних хостів в одну групу.
  • Простота розгортання: робоча система з коробки розгортається кількома командами. Для потреб dev-середовища це дуже корисно: я, як розробник, запускаю Graylog у докері трьома командами з офіційної документації.
  • Розширена документація й активне community.

На тему порівняння Graylog vs. ELK також є досить докладна стаття.

Що ми змінили, маючи перший негативний досвід:

  • Кожен окремий кластер сервісів, що обслуговує певний регіон користувачів, має власний екземпляр Graylog.
  • Кластер Elasticsearch має окремі ноди для прийому, зберігання й пошуку даних.
  • Відмова від UDP на користь AMQP.

Elasticsearch — кластер усьому голова

Можна прочитати цілу купу статей про налаштування кластера Elasticsearch, але кількість запитань тільки збільшиться. А можна прочитати best practices з офіційного сайту й бути абсолютно щасливим. Ми вже згадували про те, як у час першого знайомства з Graylog у нас був кластер Elasticsearch із двох нод, які були й master, і data, та ingest, що дуже зіпсувало нам настрій. Яку конфігурацію ми маємо тепер (нагадаю, що ми маємо окремі кластери, що обслуговують окремий географічний регіон):

  • Master — дві ноди. Майстер координує роботу кластера. Для вибору, хто зараз самий-самий Майстер Йода, має бути хоча б одна доступна нода (параметр minimum_master_nodes = 1). Можна із цим сперечатися, адже ми відійшли від best practices, але далі буде пояснення, чому в нас це працює.
  • Data — дві ноди, власне сховище даних.
  • Ingest — дві ноди, які приймають дані, а також обробляють вхідні запити пошуку.

Стосовно того, чому в нас 2 master-ноди. Є така небезпечна річ, як split brain. Це ситуація, коли, наприклад, minimum_master_nodes = 1 та одна з master-нод утрачає мережевий зв’язок з іншими master-нодами, але все ще зв’язана з підлеглими нодами кластера. Ця нода сама себе обирає головною, але залишається також і стара головна нода — виникає конфлікт. Саме тому рекомендують мати 3 ноди з кворумом 2 — тоді тільки дві ноди можуть обрати головну. Як уже згадувалося вище, уся мікросервісна архітектура в нас розгорнута під управлінням Kubernetes, який пильно наглядає за наявністю й роботою всіх екземплярів сервісів. Допомагають йому в цьому сервіси проб — liveness і readiness. Перший каже про те, що сервіс запущено, другий — про те, що сервіс готовий до роботи. І якщо раптом один із цих показників стане негативним для екземпляра сервісу, Kubernetes не дасть йому обробляти запити до того, як коректний стан відновиться. Саме це й дає змогу зекономити на одному екземплярі master-ноди.

AMQP доставляє

Подивившись на наявні апендери в бібліотеці Gelf4net, ми знайшли реалізацію для протоколу AMQP. Тобто, змінивши кілька рядків у конфігураційних файлах log4net, ми могли відправляти наші логи до брокера повідомлень. А це було для нас зручно, бо ми вже давно використовуємо RabbitMQ, що показав себе як швидкий і стабільний продукт. Звичайно ж, у самому Graylog кількома кліками можна налаштувати прийом повідомлень із брокера. Але остаточно ми були задоволені, коли почали використовувати AsyncGelfAmqpAppender, що, як порівняти із синхронним апендером, дав приріст швидкості передачі логів учетверо!

Разом зі швидкістю передачі даних (просто з коробки RabbitMQ може приймати 20К повідомлень на секунду) ми також здобули більшу надійність:

  • У миті високого навантаження Graylog не страждає й забирає із черги логи з комфортною для нього швидкістю. Увесь цей час логи перебувають у persistent-черзі й уже не зникнуть, навіть якщо цей інстанс брокера перезавантажиться.
  • Якщо Graylog тимчасово вийде з ладу, логи, знову-таки, залишаться в черзі.
  • Кожен сервіс має свою чергу логів, тому сервіси не заважають один одному.
  • Також у брокері ми маємо свою статистику надходження повідомлень у зручному інтерфейсі.

А ось такий вигляд має приклад користі від брокерів повідомлень, коли помирає Elasticsearch: усі логи є, але вони в черзі й за деякий час будуть доступні для оперування.

Моніторинг

Життя розробника бентежне, особливо на буремному шляху мікросервісів. Не обійшлося без ситуації, коли виникла проблема в нашому продукті, а, звернувшись до логів, ми виявили, що їх не просто немає, а немає вже кілька днів. Просто через помилку під час налаштування конфігураційних файлів. Завдячуючи випадковості, це сталося на демо-середовищі. Проте ця ситуація показала нам, що навіть компонент логування потребує моніторингу для проактивного реагування.

Відтоді в нас з’явився моніторинг наявності логів, який було налаштовано засобами самого Graylog. А сповіщення надходять до групи Telegram.

Епілог

Наразі Graylog став місцем зберігання логів усіх мікросервісних продуктів багатьох команд R&D у Terrasoft. Розпочинаючи новий проект, команда не морочиться над тим, що робити з логами: є шаблонні рішення та практичний досвід, що зменшує кількість стресу в нашому житті. Ми дотримуємося думки, що кожен вдалий експеримент має ставати практикою, поширюватися й бути частиною нашого повсякденного життя.

Підсумовуючи, можна окреслити такі пункти, що описують наше щасливе життя:

  • Усі логи сервісу в одному місці з доступом через LDAP.
  • Швидкий і простий пошук: завдяки можливості додавання нових полів для індексування (сервіс, модуль, ідентифікатор клієнта, окремі теги тощо) пошук потрібної інформації серед 230М повідомлень на місяць виконується за 2 секунди. Додайте сюди можливості повнотекстового пошуку в тексті повідомлення, і ви побачите чудовий інструмент для розв’язання проблем вашої системи.
  • Служба підтримки радіє: web UI набагато зручніший, ніж пошук у NotePad++ у теці файлів.
  • Виправили +100 500 виняткових ситуацій, які раніше не було видно через складність оперування логами.
  • Наявність у системі зручних дашбордів, які показують активність окремих модулів, що також може наштовхнути на оптимізації й поліпшення логування.

LinkedIn

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

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

ELK ніхто хіба не використовує?
Kibana — дуже потужний інструмент, що дозволяє не тільки шукати логи, а і будувати візуалізації, досліджувати тренди, знаходити причини аварій, є дешборди і ще багато плюшок.
3 роки використовуємо і ніяких нарікань, треба тільки кластер еластіка приготувати добре. 200Гб догів щодня, купу індексів для різних типів служб
Nginx access логи окремо
App логи — окремий індекс
Мікро сервіси зі своєю структурою догів — теж в окремий індекс

Чому ж ніхто :) ELK якраз дуже мейнстрімна штука, а в поєднанні з Kafka може пережувати взагалі все. Але graylog виявився трішки простішим у налаштуванні і інтеграції в продукт. Простий підхід — з двох інструментів, що задовольняють твоїм потребам, вибери найменший і найпростіший. Наступним кроком розвитку буде вже ELK, якщо graylog стане замалим :)

Штука достаточно прожорливая (как и все приложения на java), есть старая статья по месячной стоимости в облаках: thehftguy.com/...​-graylog-lessons-learned

250 Gb в день це круто) ми маємо в середньому близько 5Gb і 1 800 000 повідомлень на день, для цього треба значно менші ресурси. Дата ноди, для прикладу, мають по 300Gb диску всього, з них десь 80-100 на кожній займають всі логи за місяць

зачем это когда есть стейт/ридер монада в которую можно записать сколько угодно логов и в конце флоу эти логи скаситить в json и запихнуть в монгу?

А як ви будете шукати в монзі? Регулярками?

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

Скільки завгодно логів можна будь-куди записати — наскільки зручно потім ними оперувати, не лише розробнику, але й службі підтримки, як у нашому випадку? Та й кастити логи в json нам не доводиться, за нас це graylog робить. Плюс можливість сповіщень, що налаштовуються в кілька кліків, плюс аналітика в дашбордах. Можна що завгодно побудувати з нуля, але можливо готові рішення вже закривають наявні потреби.

Можна що завгодно побудувати з нуля, але можливо готові рішення вже закривають наявні потреби.

І в цьому випадку — дуже швидко.
В нас є практика тестувати роботу сервісів локально, тобто вся інфраструктура піднімається на одній дев машині. В цьому випадку весь стек Graylog ставиться трьома командами з офіційного сайту в докері за 4 хвилини.

Чота ржу (tm)
Вибачте за ранкову жовчъ:

> З чого починається збір логів у будь-якому проекті? З того, що одного разу ваш продукт, що добре й стабільно працює, перестає таким бути, а відповіді на запитання «чому?» у вас немає.

Якщо логів в «продукті» не було, і їх додають, коли «перестає добре і стабільно працювати»... це не продукт, а те, що грекі зробили з Трої.

> Зазвичай у вигляді файлів у директорії Log поруч з бінарними файлами вашого продукту.

Повіяло ad hoc самопалом для windows... а хоча чого це я, все ж сказано...

> Звісно, досвідчений програміст відразу долучає зручний і потужний фреймворк для логування, наприклад log4net, як зробили ми. Тепер усю важливу інформацію в читабельному й добре структурованому вигляді розкладено на рівнях Error, Warn, Info й Debug

Що до «зручний» можна сперечатись, а що до рівнів... в цих фреймворках головне — категорії, а не рівні.
А ще кожний будує власний закат сонця для керування

> Швидкий пошук зі зрозумілим форматом запитів, завдячуючи Elasticsearch під капотом.

Типове використання Elasticsearch для логів проходить так:
1. Ой яка чудова штука! Зараз все запхаємо в неї...
2. Ой не вистачає продуктивности... вимикаємо повнотекстову індексацію...
3. Вимикаємо все крім явно вказаних ключів... так, майже вистачає...
4. Вимкнули все що могли... ой, а навіщо нам цей шмат тягару? Просте сховище на якомусь мюскулі було б в рази дешевше.
5. ... (вирізано цензурою)
6. Переходимо на mysql (postgres, tokyocabinet, кому що ближче), всі ключі явні; якщо можна індексувати не в реальному часі, ще краще.
7. PROFIT!
(Іноді: 8. Новий PM: терміново ввернути сюди Elasticsearch!)

Я бачу, ви десь на кроку 3.

> Також чималий ефект дало використання BufferingForwardingAppender, що виконує запис у файл не на кожне повідомлення, а тільки коли набере певну їх кількість у буфер:

Ну, якщо процес цілком не падає — мабуть, це таки вирішення. На локальній ділянці :)

> Усі логи сервісу в одному місці з доступом через LDAP.

Так таки і LDAP? Через його пошук?
Чи це сказано лише про авторизацію доступу?

Радий, що наша стаття дарує позитив :) перші тези про відсутність логів/логи в файлах — це все ж таки про початкові етапи проекту, це не аксіома, але таке трапляється і це потрібно виправляти, бажано на чужому досвіді.
LDAP — так ми вористовуємо лише авторизацію в ui.
Використання реляційних БД для зберігання логів — спірне питання, не їх задача працювати з великим текстом, все ж таки ElasticSearch створений саме для цього, головне правильне налаштування.
Про BufferingForwardingAppender — знову ж таки це був проміжний етап в нашому логуванні, він замінений на асинхронний amqp апендер. А з буфером проблем не було, знову ж таки головне налаштувати не лише розмір буферу, а й періодичність його скидання.

Аналог Serilog, только никому не известный ?
Я правильно понял посыл статьи ?

Як логер в самих .net сервісах ми використовуємо log4net від самого початку, він і є аналогом Serilog. GrayLog — це така собі альтернатива лог файлам, яка працює окремо від основного додатку і додає зручності в пошуку й зберіганні логів. Посил статті в тому, що не пишучи жодного рядка коду в сервісах (змінили апендер в конфігах 🙂 ), ми переїхали з служби в windows в мікросервіси з оркестрацією в k8s і отримали вже звичні нам логи, тільки не в файлах, а через милу UI’йку й з повнотекстовим пошуком.

log4net не може бути аналогом serilog так як не має основної фічі serilog — структуровані логи. По крайній мірі не мав, може зараз вже має, на 100% стверджувати не буду :). В принципі, стандартний логер в .net core вже все вміє і ні log4net ні serilog вже не так потрібні.

Elasicsearch та інші подібні бази розкривають себе на 100% лише з структурованими логами. Ви же лише скинули всі логи із всіх сервісів із файлів в одне місце з хорошим інтерфейсом і в кращому випадку можете робити full text search по ним. Ну і фільтрувати по сервісам. Іншими словами той же смітник, тільки трохи зручніший.

Як апендер в log4net ми використовуємо AsyncGelfAmqpAppender, який вже пише об’єкт з нашим повідомленням і додатковими параметрами в лог. Сам log4net дає можливіть додавати AdditionalFields, в які ми винесли все, що може знадобитись під час фільтрації. Я от спеціально шукав і не знайшов, на даний момент, у нас місця, де було б потрібно логувати якісь цілі об’єкти для подальшого пошуку по них, який можливий тільки з структурними логами. Зараз нам вистачає приблизно такої схеми: community.graylog.org/...​uctured-logs-to-gelf/4635

Іншими словами той же смітник, тільки трохи зручніший.

Цей новий і гарний смітник економить цілі години пошуків і дозволяє за секунди знаходити опис всіх подій для конкретних даних, тому ми його дуже любимо й хотіли з вами поділитись.
Дуже можливо, що прямо завтра ситуація зміниться і ми замінимо log4net на щось інше й будуть у нас теж структурні логи. Завдяки вашим коментам з’явились деякі майже готові напрацювання))

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