BaseConsumer: тело сообщения в логе ошибки ограничено по размеру

[VitaliyChaban]

Проблема

При падении консьюмера BaseConsumer.LogError писал тело сообщения целиком и с деструктуризацией
({@MessageData}). Structured-синк разворачивает каждую коллекцию скаляров в отдельное поле, поэтому
сообщение со справочником на десятки тысяч записей давало нечитаемую запись с массивами во весь набор —
и повторялось на каждый ретрай.

Источник: GorodPay-group/GorodPay.Backend#59

Решение

Запись об ошибке сохранена — она нужна для разбора инцидентов, — но ограничена по размеру.

Форма записи (ConsumerLoggerExtensions.LogConsumeError):

Consumer process failed. MessageType: {MessageType}, MessageId: {MessageId},
ConversationId: {ConversationId}, RetryAttempt: {RetryAttempt}, MessageData: {MessageData}

• тело уходит одним скаляром: усечённый JSON строкой, а не последовательностью. Последовательность
  (в том числе IEnumerable<char>) structured-синк разворачивает поэлементно, то есть возвращает
  исходную проблему в другой форме;
• MessageType, MessageId, ConversationId, RetryAttempt — в теле их нет, от лимита они не
  зависят. MessageId сопоставляет запись с сообщением в _error-очереди, RetryAttempt отличает
  повтор одной ошибки от нескольких разных сообщений;
• TraceId/SpanId намеренно не добавлены: их пишет сам ECS-слой из Activity.Current, которую
  ставит ActivityTracingConsumeFilter. Дублировать значит развести поиск по двум полям.

Лимит — protected virtual int MessageDataLimit, по умолчанию 4000 байт UTF-8, переопределяется
наследником. Байты, а не символы: ограничение на длину терма в хранилище логов считается в байтах.

Как считается тело (MessageDataFormatter):

• сериализация идёт в буфер фиксированного размера, а не в строку: размер тела ничем не ограничен
  сверху, и сериализация в строку на большом сообщении сама даёт OutOfMemory в обработчике ошибки;
• на переполнении буфера обход графа прекращается: всё после лимита всё равно отбрасывается;
• сбой сериализации отдаётся текстом <not serialized: ИмяИсключения> — своё исключение подменило бы
  исходное, ради которого запись и пишется;
• незакрытый хвост UTF-8 после обреза по байтам отбрасывается, иначе на его месте символ замены;
• нелатинский текст не экранируется в \uXXXX: иначе запись нечитаема, и на символ уходит втрое больше
  отведённого объёма. Экранирование кавычек и управляющих символов сохранено, JSON разбираемый.

Ключ идемпотентности. IdempotentConsumer переопределяет LogError и добавляет IdempotentKey
областью логирования, не дублируя шаблон базового класса. Раньше ключ попадал в лог только как поле
развёрнутого тела, то есть после ограничения тела пропал бы. Вычисление ключа обёрнуто в перехват:
GetIdempotentKey бросает, если у сообщения нет ни IIdempotentKey, ни MessageId.

LogError стал virtual, форма записи вынесена в расширение над ILogger. Консьюмер на несколько
типов сообщений не может наследовать BaseConsumer<TMessage> (одноаргументный
IdempotentConsumer<TDbContext> — ровно этот случай), а запись ему нужна такая же: он зовёт
logger.LogConsumeError(context, e) из своего catch.

Замеры

Release, прогрев, GC.GetAllocatedBytesForCurrentThread, лимит 4000 байт. Сообщение — массив записей
справочника (Id, Name, MunicipalityId).

подготовка тела	100 Б	2.5 МБ	20 МБ
вся строка + обрезка	2.7 мкс / 240 Б	14.7 мс / 5.5 МБ	77 мс / 45.3 МБ
буфер	1.4 мкс / 4 КБ	7.8 мс / 18 КБ	60 мс / 18 КБ
буфер + прекращение обхода	1.4 мкс / 4 КБ	52 мкс / 18 КБ	45 мкс / 18 КБ

Остаточные 45 мкс — буфер Utf8JsonWriter (16 КБ): в поток он флашится не сразу, поэтому до остановки
сериализатор проходит первые ~16 КБ тела, а не ровно лимит.

Тесты

Два новых тест-проекта, у обоих пакетов тестов не было.

проект	предмет	тестов
Dex.MassTransit/Tests/Dex.MassTransit.Rabbit.Tests	форма записи, усечение, прямой вызов расширения, форматтер	12
Dex.Cap/Tests/Dex.Cap.OnceExecutor.MassTransit.Test	ключ идемпотентности в записи	3

Наборы проверены мутациями:

мутация	покраснело
значение снова последовательностью (.Take().Concat())	4
лимит снят, буфер по размеру данных	2
признак усечения не ставится	2
обход графа не прекращается на лимите	1
обрез незакрытого хвоста UTF-8 убран	2
поля идентификации убраны из шаблона	1
RetryAttempt убран из шаблона	1
catch вокруг сериализации снят	1
FullName → Name в расширении	2
BaseConsumer не передаёт свой лимит	2
override LogError в IdempotentConsumer убран	3
try/catch вокруг вычисления ключа снят	1

Прогон: dotnet test src/Dex.MassTransit/Dex.MassTransit.sln и
dotnet test src/Dex.Cap/Tests/Dex.Cap.OnceExecutor.MassTransit.Test/Dex.Cap.OnceExecutor.MassTransit.Test.csproj.

Влияние на потребителей

Поведение меняется у всех наследников BaseConsumer, включая IdempotentConsumer и
TransactionalConsumer из Dex.Cap.

Тело перестаёт быть набором полей и становится одной строкой. Выборки и дашборды, построенные на
подполях развёрнутого тела, на новых записях искать перестанут — это надо сказать поддержке до выката.
Кому нужен прежний объём, поднимает MessageDataLimit у своего консьюмера.

Публичный API вырос на ConsumerLoggerExtensions (LogConsumeError, DefaultMessageDataLimit) и
BaseConsumer.MessageDataLimit; LogError из protected void стал protected virtual void.
InternalsVisibleTo("Dex.MassTransit.Rabbit.Tests") в Dex.MassTransit.Rabbit.

Вне этого PR

• Патч-версии пакетов подняты вместе с обновлением зависимостей в src/Directory.Build.targets
  (коммиты 7f79a3e7, 6594fe32, 0202648e).
• Dex.MassTransit.ActivityTrace: трейс рвётся, если публикация идёт без ambient Activity #244 — трейс рвётся, если публикация идёт без ambient Activity. Пока это так, брокерные
  идентификаторы в записи и нужны.
• Лимиты деструктуризации Serilog на стороне сервиса (пункт 1 исходного ишью) — отдельный MR в
  GorodPay.Backend, здесь их нет.