логирование api что это такое
Что такое логирование?
Известно, что программисты проводят много времени, отлаживая свои программы, пытаясь разобраться, почему они не работают — или работают неправильно. Когда говорят про отладку, обычно подразумевают либо отладочную печать, либо использование специальных программ – дебагеров. С их помощью отслеживается выполнение кода по шагам, во время которого видно, как меняется содержимое переменных. Эти способы хорошо работают в небольших программах, но в реальных приложениях быстро становятся неэффективными.
Сложность реальных приложений
Возьмем для примера типичный сайт. Что он в себя включает?
И это только самый простой случай. Реальность же значительно сложнее: множество разноплановых серверов, системы кеширования (ускорения доступа), асинхронный код, очереди, внешние сервисы, облачные сервисы. Все это выглядит как многослойный пирог, внутри которого где-то работает нами написанный код. И этот код составляет лишь небольшую часть всего происходящего. Как в такой ситуации понять, на каком этапе был сбой, или все пошло не по плану? Для этого, как минимум, нужно определить, в каком слое произошла ошибка. Но даже это не самое сложное. Об ошибках в работающем приложении узнают не сразу, а уже потом, — когда ошибка случилась и, иногда, больше не воспроизводится.
Логирование
И для всего этого многообразия систем существует единое решение — логирование. В простейшем случае логирование сводится к файлу на диске, куда разные программы записывают (логируют) свои действия во время работы. Такой файл называют логом или журналом. Как правило, внутри лога одна строчка соответствует одному действию.
Выше небольшой кусок лога веб-сервера Хекслета. Из него видно ip-адрес, с которого выполнялся запрос на страницу и какие ресурсы загружались, метод HTTP, ответ бекенда (кода) и размер тела ответа в HTTP. Очень важно наличие даты. Благодаря ей всегда можно найти лог за конкретный период, например на то время, когда возникла ошибка. Для этого логи грепают:
Когда программисты только начинают свой путь, они, часто не зная причину ошибки, опускают руки и говорят «я не знаю, что случилось, и что делать». Опытный же разработчик всегда первым делом говорит «а что в логах?». Анализировать логи — один из базовых навыков в разработке. В любой непонятной ситуации нужно смотреть логи. Логи пишут все программы без исключения, но делают это по-разному и в разные места. Чтобы точно узнать, куда и как, нужно идти в документацию конкретной программы и читать соответствующий раздел документации. Вот несколько примеров:
Многие программы логируют прямо в консоль, например Webpack показывает процесс и результаты сборки:
Во фронтенде файлов нет, поэтому логируют либо прямо в консоль, либо к себе в бекенды (что сложно), либо в специализированные сервисы, такие как LogRocket.
Уровни логирования
Чем больше информации выводится в логах, тем лучше и проще отладка, но когда данных слишком много, то в них тяжело искать нужное. В особо сложных случаях логи могут генерироваться с огромной скоростью и в гигантских размерах. Работать в такой ситуации нелегко. Чтобы как-то сгладить ситуацию, системы логирования вводят разные уровни. Обычно это:
Поддержка уровней осуществляется двумя способами. Во-первых, внутри самой программы расставляют вызовы библиотеки логирования в соответствии с уровнями. Если произошла ошибка, то логируем как error, если это отладочная информация, которая не нужна в обычной ситуации, то уровень debug.
Во-вторых, во время запуска программы указывается уровень логирования, необходимый в конкретной ситуации. По умолчанию используется уровень info, который используется для описания каких-то ключевых и важных вещей. При таком уровне будут выводиться и warning, и error. Если поставить уровень error, то будут выводиться только ошибки. А если debug, то мы получим лог, максимально наполненный данными. Обычно debug приводит к многократному росту выводимой информации.
Уровни логирования, обычно, выставляются через переменную окружения во время запуска программы. Например, так:
Существует и другой подход, основанный не на уровнях, а на пространствах имен. Этот подход получил широкое распространение в JS-среде, и является там основным. Фактически, он построен вокруг одной единственной библиотеки debug для логирования, которой пронизаны практически все JavaScript-библиотеки как на фронтенде, так и на бекенде.
Принцип работы здесь такой. Под нужную ситуацию создается специализированная функция логирования с указанием пространства имен, которая затем используется для всех событий одного процесса. В итоге библиотека позволяет легко отфильтровать только нужные записи, соответствующие нужному пространству.
Запуск с нужным пространством:
Ротация логов
Со временем количество логов становится большим, и с ними нужно что-то делать. Для этого используется ротация логов. Иногда за это отвечает сама программа, но чаще — внешнее приложение, задачей которого является чистка. Эта программа по необходимости разбивает логи на более мелкие файлы, сжимает, перемещает и, если нужно, удаляет. Подобная система встроена в любую операционную систему для работы с логами самой системы и внешних программ, которые могут встраиваться в нее.
С веб-сайтами все еще сложнее. Даже на небольших проектах используется несколько серверов, на каждом из которых свои логи. А в крупных проектах тысячи серверов. Для управления такими системы созданы специализированные программы, которые следят за логами на всех машинах, скачивают их, складывают в заточенные под логи базы данных и предоставляют удобный способ поиска по ним.
Здесь тоже есть несколько путей. Можно воспользоваться готовыми решениями, такими как DataDog Logging, либо устанавливать и настраивать все самостоятельно через, например, ELK Stack
Логирование как инструмент повышения стабильности веб-приложения
Авторизуйтесь
Логирование как инструмент повышения стабильности веб-приложения
техлид в Dunice
Каждый проект так или иначе имеет жизненные циклы: планирование, разработка MVP, тестирование, доработка функциональности и поддержка. Скорость роста проектов может отличаться, но при этом желание не сбавлять обороты и двигаться только вперёд у всех одинаковые. Перед нами встаёт вопрос: как при работе над крупным проектом минимизировать время на выявление, отладку и устранение ошибок и при этом не потерять в качество?
Существует много различных инструментов для повышения стабильности проекта:
В данной статье я хочу поговорить об одном из таких инструментов — логировании.
Логи — это файлы, содержащие системную информацию о работе сервера или любой другой программы, в которые вносятся определённые действия пользователя или программы.
Логи полезны для отладки различных частей приложения, а также для сбора и анализа информации о работе системы с целью выявления ошибок. Всё это необходимо для контроля работы приложения, так как даже после релиза могут встретиться ошибки, а пользователи не всегда сообщают о багах в техподдержку. Чем больше процессов у вас автоматизировано, тем быстрее будет идти разработка.
Допустим, есть клиентское приложение, балансировщик в лице Nginx, серверное приложение и база данных.
В данном примере не важны язык/фреймворк бэкенда, фронтенда или тип базы данных, а вот про веб-сервер Nginx давайте поговорим. В данный момент Nginx популярнее остальных решений для высоконагруженных сайтов. Среди известных проектов, использующих Nginx: Рамблер, Яндекс, ВКонтакте, Facebook, Netflix, Instagram, Mail.ru и многие другие. Nginx записывает логи по умолчанию, без каких-либо дополнительных настроек.
Логи доступны 2 типов:
Клиент отправляет запрос на сервер, и в данной ситуации Nginx будет записывать все входящие запросы. Если возникнут ошибки при обработке запросов, сервером будет записана ошибка.
2020/04/10 13:20:49 [error] 4891#4891: *25197 connect() failed (111: Connection refused) while connecting to upstream, client: 5.139.64.242, server: app.dunice-testing.com, request: «GET /api/v1/users/levels HTTP/2.0», upstream: «http://127.0.0.1:5000/api/v1/users/levels», host: «app.dunice-testing.com»
Всё, что мы смогли бы узнать в случае возникновения ошибки, — это лишь факт наличия таковой, не более. Это полезная информация, но мы пойдём дальше. В данной ситуации помог Nginx и его настройки по умолчанию. Но что же нужно сделать, чтобы решить проблему раз и навсегда? Необходимо настроить логирование на сервере, так как он является общей точкой для всех клиентов и имеет доступ к базе данных.
Первым делом каждый запрос должен получать свой уникальный идентификатор, что поможет отличить его от других запросов. Для этого используем UUID/v4. На случай возникновения ошибки, каждый обработчик запроса на сервере должен иметь обёртку, которая отловит эти самые ошибки. В этой ситуации может помочь конструкция try/catch, реализация которой есть в большинстве языков.
В конце каждого запроса должен сохраняться лог об успешной обработке запроса или, если произошла ошибка, сервер должен обработать её и записать следующие данные: ID запроса, все заголовки, тело запроса, параметры запроса, отметку времени и информацию об ошибке (имя, сообщение, трассировка стека).
Собранная информация даст не только понимание, где произошла ошибка, но и возможную причину её возникновения. Обычно для решения ошибки информации из лога достаточно, но в некоторых случаях может быть полезен контекст запроса. Для этого необходимо при старте запроса не только генерировать ID запроса, но и сгенерировать контекст, в который мы будем записывать всю информацию по работе сервера, начиная от результата вызова функции и заканчивая результатом запроса к базе данных. Такая реализация даст не только входные данные, но и промежуточные результаты работы сервера, что позволит понять причину появления ошибки.
При микросервисном подходе система не ограничивается одним сервером, и при запросе от клиента происходит взаимодействие нескольких серверов внутри системы. Наша реализация логирования на сервере позволит выявить дефект в работе конкретного ресурса, но не позволит понять, почему запрос вернулся с ошибкой. В данной ситуации поможет трассировка запросов.
Трассировка — процесс пошагового выполнения программы. В режиме трассировки программист видит последовательность выполнения команд и значения переменных на каждом шаге выполнения программы.
В нашем случае требуется передавать метаинформацию о запросе при взаимодействии серверов и записывать логи в единое хранилище (такими могут быть ClickHouse, Apache Cassandra или MongoDB). Такой подход позволит привязать различные контексты серверов к уникальному идентификатору запроса, а отметки времени — понять последовательность и последнюю выполненную операцию. После этого команда разработки сможет приступить к устранению.
В некоторых случаях, которые встречаются крайне редко, к ошибке приводят неочевидные факторы: компилятор, ядро операционной системы, конфигурации сервера, юзабилити, сеть. В таких случаях при возникновении ошибки потребуется дополнительно сохранять переменные окружения, слепок оперативной памяти и дамп базы. Такие случаи настолько редки, что не стоит беспочвенно акцентировать на них внимание.
С сервером разобрались, что же делать, если у нас сбои даёт клиент и запросы просто не приходят? В такой ситуации нам помогут логи на стороне клиента. Все обработчики должны отправлять информацию на сервер с пометкой, что ошибка с клиента, а также общие сведения: версия и тип браузера, тип устройства и версия операционной системы. Данная информация позволит понять, какой участок кода дал сбой и в каком окружении пользователь взаимодействовал с информацией.
Также есть возможность отправлять уведомления на почту разработчикам, если произошли ошибки, что позволит оперативно узнавать о сбоях в системе. Такие подходы активно используются в системах мониторинга и аналитики логов.
Способы, которые мы рассмотрели в статье, помогут следить за качеством продукта и минимизируют затраты на исправление недочётов в системе.
Некоторые аспекты логирования ASP.NET-сайта
Сегодня я расскажу, как сделаны некоторые аспекты логирования в сайте, в разработке которого я принимаю участие.
Сайт написан на ASP.NET MVC 5 и Web API 4, для логирования используется библиотека NLog, сайт хостится в облаке Амазона. Записи лога пишутся в три места (target по терминологии NLog): в файловую систему (подпапку Logs папки App_Data, в которую разрешается доступ на запись при стандартных настройках деплоя Amazon Elastic Beanstalk), на сервис logentries и в БД. Записи лога за день ведутся в отдельный файл, в названии которого указывается текущая дата.
Логирование ошибок на клиентской стороне
На сайте есть немного логирования с клиентской стороны: логируются необработанные исключения в джаваскрипте, которые происходят в браузере клиентов. В веб-сайте установлен обработчик всех таких исключений, который делает аякс-запрос на сервер, передавая имеющиеся детали ошибки, поэтому мы в курсе некоторых проблем на клиенте.
Логирование на logentries
Кратко о том, что он представляет из себя
Logentries — сервис, который позволяет хранить, просматривать и анализировать логи. Для многих систем логирования разработаны модули, позволяющие отправлять логи на logentries; есть таргет и для NLog. Имеется возможность отправлять в одно хранилище логи из разных приложений (или с разных машин), где они будут отображаться вместе, упорядоченные по времени добавления.
На запись лога можно навешивать теги, которые будут выделять запись в потоке записей и на таймлайне.
У нас используются теги, которые навешиваются на записи с уровнем Error, на 404-е и 500-е ошибки, на ошибки из JS, на записи о создании пользователей и заказов.
Таймлайн одного из логов за сутки у нас выглядит так: 
Наш проект находится в публичном доступе уже около 9 месяцев. К легкому стыду, мы до сих пор используем бесплатный тарифный план logentries. У него есть ряд ограничений: записи лога хранятся максимум одну неделю, и есть предел сверху на объем хранимой и добавляемой информации. В начале жизни проекта мы слегка превысили эти объемы, отправляя слишком много записей, так что сервис logentries несколько дней не принимал наши логи.
Мы убрали запись в лог, когда она явно была излишней, или изменили их уровни логирования, так что проблема была решена. С того момента мы больше не упирались в ограничения бесплатного тарифного плана, хотя специально не ограничивали себя в логировании.
Исторически сложилось, что уровнем Fatal я не пользуюсь.
В файл на жестком диске и в БД записываются все сообщения.
Логирование в базу данных
Как я уже писал, мы используем бесплатный тарифный план logentries, в котором записи хранятся только одну неделю.
У нас имеется логирование в файлы в папке App_Data/logs сайта. Сейчас мы не используем инкрементальный деплой сайта, некоторое время назад с ним были проблемы: очень часто во время загрузки обновленной версии сайта обрывалось соединение с Амазоном, и деплой прерывался. В результате при обновлении сайта удаляются все имеющиеся в его папке файлы, в том числе и логи за предыдущие дни. Вероятно, можно было бы логировать в папку вне сайта, но сайт должен обладать правами на запись в нее. Если окажется, что ее нужно создавать и настраивать права доступа к ней, усложнится выкладка сайта на новую машину: нужно будет или создавать папку вручную, или дорабатывать скрипт выкладки (которого у нас сейчас вообще нет, вполне обходимся без него, деплоем xcopy).
Подсознательно я чувствовал, что при расследовании инцидентов могут потребоваться логи и значительно большей давности. Были идеи архивировать файлы с логами с веб-серверов на Amazon S3 (хранилище больших объемов данных, a la удаленная файловая система): архивация могла бы происходить по расписанию, в начале суток, копируя файлы логов за предыдущий день. Также нужно было бы не забывать копировать перед деплоем имеющиеся логи за текущие сутки, чтобы не потерять их. Однако вместо этого мы решили логировать и в БД, в таблицу с несколькими полями: дата создания записи, уровень логирования, идентификатор потока, информация о пользователе (его логин или идентификатор, если пользователь анонимный и не имеет логина) и собственно тело записи.
Такое логирование было реализовано, благо NLog позволяет логировать в БД из коробки, но использовалось для расследования ситуаций на сайте очень слабо: пару месяцев назад база часто переставала быть доступной, процессор машины с SQL-сервером был загружен на 100%, а запросы отваливались по таймауту. Была гипотеза, что такая загрузка БД отчасти связана с логами: база логов была самой большой на сервере.
Гипотеза не была ни подтверждена, ни опровергнута, SQL-сервер через несколько дней самостоятельно вернулся к нормальной работе, но я до сих пор не рискую делать запросы к БД логов, опасаясь, что тяжелый запрос без индексов может снова полностью загрузить SQL-сервер.
Чтобы логирование в БД начало работать, пришлось написать собственный layout renderer, который отрисовывает дату в формате, понятном SQL-серверу:
В БД так же, как и в файлы, записываются сообщения логов всех уровней.
Настройка логирования в БД в NLog выглядит так:
Строка подключения к БД логов задается в секции connectionStrings файла web.config под названием Logs.
Состав записи лога
Типичная запись лога выглядит так:
где:
— D — уровень логирования;
— AMAZONA-XY1234ZU/Prod-1 — информация о EC2-инстансе и мнемоническом имени Elasticbeanstalk-окружения;
— 14 — идентификатор потока, из которого была сделана запись;
— 2014-12-31 12:34:56.7890 — текущее время в формате UTC;
— 15472 — номер запроса (о нем я расскажу ниже);
— 9e397bf8-c1bc-4a00-a22f-da3f20be55b6 — идентификатор пользователя, во время запроса которого была сделана запись лога. В данном случае гуид говорит нам, что пользователь анонимный, у которого не задан адрес электронной почты, в противном случае здесь был бы указан email;
— остальное — само тело записи.
Логирование информации, специфичной для Амазона
В каждую запись лога попадает информация о том, с какой машины эта запись была сделана. Эта информация состоит их двух частей: Amazon instance id EC2-машины, который доступен всегда, и имени окружения, которое может отсутствовать, поскольку мы задаем его вручную в настройках при создании Elasticbeanstalk-окружения.
Сервер получает свой amazon instance id, выполняя http get-запрос на внутренний адрес Амазона:
http://169.254.169.254/latest/meta-data/instance-id
Этот адрес описан в документации Амазона.
Запрос делается в статическом конструкторе layout renderer’а, поэтому выполняется он однократно в рамках текущего AppDomain’а, и обернут в пустой блок catch, чтобы исключение при его выполнении не нарушало функционирование сервера; запрос выполняется асинхронно, чтобы не задерживать дальнейший старт сервера:
Вообще, по этому адресу можно получить достаточно много данных о инстансе и его окружении, к примеру, присвоенные инстансу ip-адреса, mac-адрес, публично доступное DNS-имя.
Имя окружения задается вручную в конфигурации окружения Elastic Beanstalk:
Эта настройка попадает в секцию AppSettings web.config’а приложения, откуда ее можно считать также при старте сервера по ключу, который мы указали в настройках окружения.
В результате два этих фрагмента попадают в лог, разделенные слэшем.
Номер запроса
С самого начала в запись лога попадал идентификатор потока, из которого эта запись была сделана. Его можно было использовать, чтобы различать (слегка косвенно) разные потоки сообщений лога — относящиеся к разным запросам. Впрочем, правило «разные запросы — разные потоки» совершенно не работает: во-первых, наверняка может случиться, что два последовательных запроса будет обслуживать один и тот же поток. Кроме того, с некоторого момента мы начали применять асинхронные обработчики запросов, во время исполнения которых код может выполняться в разных потоках (продолжение асинхронного метода после ожидания выполнения асинхронной операции может исполняться в произвольном потоке из пула ASP.NET). Все это уменьшает ценность идентификатора потока (сейчас я задумался, не убрать ли его логирование вовсе).
Чтобы гарантированно отличать записи логов, относящиеся к разным web-запросам, я написал новый layout renderer, который работает в паре с фильтром, глобально навешенным на все API-контроллеры и записывающий в словарь Items запроса его номер. А номер запроса — это просто значение целочисленного статического счетчика, который атомарно инкрементируется каждый раз, когда нужно присвоить номер новому запросу:
Layout renderer, записывающий номер запроса, выглядит так:
В результате у всех записей лога, добавленных при выполнении запроса, одно и то же значение номера запроса, что позволяет легко вычленять их при изучении логов.
На данный момент номер запроса не выставляется для MVC-запросов (тех, которые обрабатываются MVC-контроллерами): в этом есть меньшая потребность, в отличие от API-запросов, поскольку последних и больше, и в них сосредоточены модифицирующие операции.
Идентификатор пользователя
В начале почти каждого запроса выполняется фильтр, который устанавливает, какой пользователь выполняет запрос. Есть разновидности такого фильтра как для API-, так и для MVC-контроллеров.
В нашем проекте информация о пользователе переносится в куки. Фильтр извлекает из БД по значению этой куки данные профиля пользователя, его роли, и записывает в стек, связанный с запросом, который выполняется в данный момент. Когда обработка запроса завершается, информация о пользователе из стека извлекается.
В первой реализации стек хранился в thread-static переменной. Однако такую архитектуру пришлось изменить, когда мы начали использовать асинхронные методы контроллеров, которые могут выполняться разными потоками. Сейчас стек хранится в коллекции Items запроса, которая, как и все данные запроса, сохраняется, если асинхронный метод выполняется с сохранением контекста синхронизации ASP.NET (что происходит по умолчанию), и переносится от потока к потоку.
Web API-фильтр, устаналивающий информацию о пользователе, выполняющем запрос
Интерфейс IUserContextStorage является абстракцией над местом хранения стека пользователей:
Имеется две его реализации: изначальная, хранящая стек в thread local переменной, и обновленная, хранящая его в коллекции Items HttpContext’а :
Кроме того, для красоты и удобства имеется наследник класса ApiController, который позволяет получать текущего пользователя через собственное нестатическое свойство:
Изменение статических правил логирования
Логирование является очень важным инструментом разработчика, но при создании распределённых систем оно становится камнем, который нужно заложить прямо в фундамент вашего приложения, иначе сложность разработки микросервисов очень быстро даст о себе знать.
В этой статье мы возьмём простое веб-апи приложение и организуем логирование, которое будет
сохранять сквозную корелляцию между логами независимых сервисов так, чтобы можно было легко посмотреть все активности, которые были вызваны конкретным запросом с клиента
иметь единую точку входа с удобным анализом, чтобы инструментом логирования смогла пользоваться даже Поддержка, к которой летят вопросы вроде «у меня тут в приложении выскочила ошибка с таким-то айдишником запроса»
Во-первых, нам необходимо определиться с поставщиком логирования в нашем приложении. Главное требование к современному логированию это структурность, т.е. мы должны работать не с плоскими текстовыми сообщениями, а с объектами. Благодаря таким логам мы можем легко строить представления наших сообщений в разных разрезах и проводить аналитику.
Для нашего приложения мы воспользуемся пакетом Serilog (Серилог), который имеет отличную поддержку структурного логирования и богатую систему дополнений. Я опущу базовые этапы его настройки (вы можете найти большое количество статей на эту тему) и сделаю допущение о том, что
Серилог уже сконфигурирован и является логером по-умолчанию у вашего поставщика внедрения зависимостей
в его конфигурации включено обогащение сообщений свойствами контекста (Enrich.FromLogContext)
Следующим шагом необходимо выбрать в какую систему централизованного сбора логов посылать сообщения из Serilog. Пожалуй, самый распространённый на сегодня вариант из открытого ПО это стек ELK (Elasticsearch, Logstash и Kibana), его и возьмём. Для этого воспользуемся предложением от Logz.IO — после регистрации на бесплатном тарифе в наших руках оказывается вся мощь поискового движка Lucene.
Нам остаётся добавить в наш проект пакет Serilog.Sinks.Logz.Io
И добавить соответствующий энричер в конфигурацию нашего логера, скормив ему токен доступа
Запустив приложение мы сможем наблюдать наши сообщения не только в консоли, но и в Кибане.
Интерфейсы
В приложении сервисного типа можно выделить два главных интерфейса его взаимодействия с внешним миром, обозначим их как вертикальный и горизонтальный. Вертикальный интерфейс — это веб-апи, через который прилетают вызовы от клиентского приложения. Горизонтальный — это брокер сообщений, который используется для обмена данными с другими внутренними сервисами.
Рассмотрим этапы внедрения корелляционности на каждом из этих интерфейсов.
Корелляция в HTTP-запросах
Чтобы получать как можно больше информации нам необходимо генерировать идентификатор корелляции как можно ближе к началу активности, т.е. на шлюзе или прямо на клиенте (мобильном или веб). Поскольку мы сегодня имеем дело с бекендным приложением, то просто обозначим на нём требование обязательного заголовка «X-Correlation-ID» во всех запросах к веб-апи.
Добавляем пакет CorrelationID, функция которого заключается в заборе значения из необходимого нам заголовка
Добавим его в конвейер обработки запроса
Теперь с его помощью сделаем простой action-фильтр:
И добавим его в контроллер
В результате контроллер станет выводить 400 Bad request на все запросы без заголовка с соответствующим идентификатором.
После того, как мы стали получать идентификатор от клиента мы должны добавить его в контекст журналирования, сделаем для этого обрамляющую прослойку:
В нашем приложении мы используем стандартный ILogger из пакета Microsoft.Extensions.Logging.Abstractions, поэтому значение будем добавлять с помощью нехитрого расширения к нему.
Добавляем прослойку в конвейер обработки запроса и получаем нужный результат.
Теперь все активности, которые порождены запросами к нашему веб-апи, содержат корелляционный идентификатор по которому их можно легко связать.
Корелляция в сообщениях брокера
Следующим шагом нам необходимо наладить передачу и приём корелляционного идентификатора через брокер сообщений. В нашем примере мы будем использовать RabbitMQ, а в качестве клиента возьмём фреймворк MassTransit (МассТранзит). Опять же, опустим первоначальную настройку работы с МассТранзита и перейдём сразу к настройке логирования.
Для начала мы можем включить логи самого МассТранзита, для этого добавим в наше приложение пакет MassTransit.SerilogIntegration
Теперь после добавления логера в настройки MassTransit мы сможем видеть логи фреймворка.
Пусть наше приложение в качестве реакции на POST-запрос отправляет событие SomethingHappened со значением «Hello». Контракт такого сообщения можно описать так:
Сообщения МассТранзита по сути являются конвертом, в который вложены сообщения брокера. Выглядит конверт примерно так:
В сообщении видны служебные поля, которые необходимы для работы самого фреймворка, но мы имеем возможность добавлять в этот конверт и собственные дополнительные свойства. Более того, MassTransit имеет встроенные средства работы с некоторыми опциональными полями, более всего из которых нам интересен идентификатор корелляционности CorrelationId.
Добавим к контракту сообщения интерфейс CorrelatedBy:
Реализуем его и будем присваивать значение свойству CorrelationId при создании сообщения:
Если мы посмотрим на обновлённое сообщение, то увидим что идентификатор корелляции стал не только частью нашего сообщения, но и частью конверта — этот идентификатор теперь будет также использоваться во всех логах МассТранзита, а значит нам будет гораздо проще разбираться с проблемами на уровне брокера сообщений.
Нам осталось настроить логирование этих служебных свойств сообщения, для этого добавим в проект пакет Serilog.Enrichers.MassTransitMessage. Пакет добавляет фильтр в конвейер обработки сообщений MassTransit, который складывает контекст сообщения в потокобезопасный стек. Серилог читает контекст из стека и добавляет в наши объекты логов эти дополнительные свойства.
В МассТранзите вставляем фильтр
А в конфигурации Серилога добавляем энричер
Поскольку приложение, которое получает сообщение из очереди RabbitMQ, имеет доступ ко всем свойствам конверта MassTransit, мы можем использовать полученный идентификатор корелляционности внутри приложения-потребителя, а также передавать его дальше по всей цепочке вызовов.
В результате наши логи стали содержать CorrelationId не только в пределах одного сервиса, но и при взаимодействии с другими приложениями.
Разумеется, в таком виде логирование не покроет сложные варианты взаимодействия ваших сервисов и различных внешних систем, но наведение подобного порядка в самом начале развития проекта — это одна из тех вещей, за которые вы сами себе не раз скажете спасибо.