Scrutor: логирование отменённых HTTP-запросов

Привет! В этой статье я бы хотел поделиться интересным практическим кейсом, который связан с логированием ошибок в ASP.NET Core и использованием библиотеки Scrutor для декорирования классов на уровне IoC.

Предыстория

Представьте клиент-серверную архитектуру, где фронтенд написан на React, бэкенд — на ASP.NET Core, а для логирования на стороне бэкенда используется NLog.

Иногда может происходить следующий сценарий: пользователь находится на веб-странице и выполняет какое-то действие (например, нажимает на кнопку «Обновить»). В этот момент фронтенд присылает HTTP запрос на бэкенд, и по какой-то причине этот запрос начинает долго обрабатываться на бэкенде. В это время пользователь уходит со страницы, браузер присылает отмену запроса, бэкенд получает сигнал отмены (CancellationToken), выбрасывается OperationCanceledException, и в логи улетает полноценная ошибка.

С точки зрения observability такие записи в логах представляют собой чистый шум: это штатная ситуация, ошибки бэкенда тут нет, и реагировать технической поддержке или разработчикам тут не на что. Однако сам факт таких логов представляет собой проблему: они засоряют файлы, на основе которых строятся отчёты о работоспособности системы, и приучают команду игнорировать алерты.

Чтобы этого не происходило, мы можем поставить задачу следующим образом: сделать так, чтобы исключение OperationCanceledException не логировалось, если оно было связано с отменой HTTP-запроса. Ниже описан путь от пары неудачных попыток до решения через декоратор, зарегистрированный с помощью Scrutor, и разбор того, почему это решение оказалось системным паттерном, а не костылём под одну задачу.

Оговорюсь сразу: код, представленный в данной статье, является реконструкцией по памяти спустя время, а не дословным воспроизведением продакшен-кода. Саму задачу и общее направление решения (декорирование через Scrutor) я помню хорошо, а вот конкретные детали реализации, скорее всего, где-то отличаются от того, что реально было в коде.

Что мы перепробовали до декоратора

Прежде чем добраться до Scrutor, мы попробовали два более очевидных пути, и оба закрыли. Но не потому, что варианты «не понравились», а по конкретным техническим причинам.

Попытка №1: правила в NLog.config

Первая идея — не трогать код вообще, а решить всё конфигурацией логгера. Тем более, у NLog есть механизм <filters> внутри <rules>, который умеет отбрасывать записи по условию (см. документацию NLog по фильтрам):

<?xml version="1.0" encoding="utf-8" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">

  <targets>
    <target xsi:type="File" name="mainFile" fileName="logs/app.log" />
  </targets>

  <rules>
    <logger name="*" minlevel="Error" writeTo="mainFile">
      <filters defaultAction="Log">
        <when condition="contains('${exception:format=Type}', 'OperationCanceledException')"
              action="Ignore" />
      </filters>
    </logger>
  </rules>
</nlog>

На первый взгляд решение выглядит рабочим: ${exception:format=Type} рендерит тип исключения, contains(...) проверяет вхождение подстроки, action="Ignore" отбрасывает запись. Но у этого подхода есть принципиальная дыра — конфиг логгера ничего не знает про HTTP-контекст.

В нашем случае, OperationCanceledException, который мы настроили в конфиге — это не эксклюзивный маркер «пользователь закрыл вкладку». Такой тип исключения также прилетает, когда:

• истёк таймаут запроса к БД (CommandTimeout или CancellationTokenSource с TimeSpan);

• не дождались ответа от внешнего сервиса и сами отменили вызов;

• где-то в фоновом коде вручную отменили CancellationTokenSource.

Получается, правило в NLog.config фильтрует по типу исключения, а нам нужно фильтровать по причине — «отменил ли конкретно пользователь конкретно этот HTTP-запрос» (см. HttpContext.RequestAborted). Эта информация уже потеряна в момент, когда NLog применяет правило к готовой строке лога: конфигурационный файл не может обратиться к HttpContext текущего запроса. В результате, правило либо слишком жадное (игнорирует реальные проблемы с БД и внешними сервисами под тем же типом исключения), либо продолжает логировать отмененные HTTP-запросы. В обоих случаях это не решает исходную задачу.

Попытка №2: перехват в middleware

Вторая попытка сводилась к следующей идее: не трогать логирование вообще, а перехватывать отмену на уровне HTTP-конвейера (см. документацию ASP.NET Core по middleware — стандартный паттерн exception-handling middleware):

public sealed class SuppressCancelledRequestLoggingMiddleware(RequestDelegate next)
{
    public async Task InvokeAsync(HttpContext context)
    {
        try
        {
            await next(context);
        }
        catch (OperationCanceledException) when (context.RequestAborted.IsCancellationRequested)
        {
            // Запрос отменён клиентом на нашей стороне — это не ошибка, не логируем.
        }
    }
}

Это действительно работает, но только для части сценариев: если исключение долетает до middleware необработанным, мы его тихо игнорируем прямо здесь, и оно нигде не оседает как ошибка.

Проблема — «если долетает». Middleware стоит на самом верху конвейера, а между ним и точкой, где реально бросается исключение, может быть несколько слоёв кода со своим логированием. Классический случай — репозиторий с собственной обработкой ошибок:

public async Task<Order> GetOrderAsync(int id, CancellationToken ct)
{
    try
    {
        return await _db.Orders.SingleAsync(o => o.Id == id, ct);
    }
    catch (Exception ex)
    {
        _logger.LogError(ex, "Failed to load order {OrderId}", id);
        throw;
    }
}

Если отмена прилетает в момент выполнения запроса к БД, OperationCanceledException попадает в catch (Exception ex) репозитория — и уже там логируется как LogError, до того как исключение вообще успевает подняться до middleware. Наш try/catch в middleware в этот момент абсолютно бесполезен: он ловит исключение уже после того, как оно залогировано где-то ниже по стеку.

Формально тут есть два решения:

1. Убрать try/catch-логирование из репозиториев по всему проекту;

2. Инжектировать IHttpContextAccessor в конструктор репозитория и в catch обращаться к HttpContext.RequestAborted. И таким образом можно научиться отличать отмену HTTP запроса от реальной ошибки.

На практике оба варианта подразумевают, что нам нужно было бы переписать (и не забывать переписывать в будущем) каждое место в кодовой базе со своим обработчиком исключений и логированием. По сути, мы бы размазали одну и ту же проверку по всему проекту вместо того, чтобы держать её в одном месте.

Решение: декорируем ILoggerProvider через Scrutor

Раз проблему нельзя решить ни конфигом, ни точкой входа в конвейер, логично зайти с другой стороны — с точки выхода, то есть с самого логгера. Если перехватить запись лога перед тем, как она уйдёт в NLog/консоль/куда угодно ещё, и на этом этапе проверить одновременно (а) тип исключения и (б) состояние HttpContext текущего запроса, то задача решается ровно в одном месте.

Для регистрации такого перехватчика в DI-контейнере мы использовали Scrutor — библиотеку, которая добавляет в IServiceCollection метод Decorate<TService, TDecorator>() для оборачивания уже зарегистрированных сервисов.

Почему декорируем именно ILoggerProvider, а не ILogger

Первое, что напрашивается, — это задекорировать ILogger<T>, поскольку именно его инжектят в сервисы. Технически это вполне возможно, т.к. ILogger<T> обычно регистрируется в DI контейнере как открытый generic (см. AddLogging()):

services.TryAdd(ServiceDescriptor.Singleton(typeof(ILogger<>), typeof(Logger<>)));

В свою очередь, Scrutor умеет декорировать открытые generic’и точно так же, как закрытые типы. Поэтому если мы используем services.Decorate(typeof(ILogger<>), typeof(MyDecorator<>)), то, в целом, решение соберётся и отработает.

Проблема в том, что этого может быть недостаточно в определенных сценариях. Как мы увидели, Logger<T> — это тот самый класс, который реально стоит за ILogger<T>, и он в своём конструкторе делает следующее:

public Logger(ILoggerFactory factory)
{
    ArgumentNullException.ThrowIfNull(factory);

    _logger = factory.CreateLogger(GetCategoryName());
}

То есть декорирование ILogger<T> перехватит только те логи, что попадают в приложение через конструкторную инъекцию ILogger<T>. Однако огромная часть логов в типичном ASP.NET Core приложении идёт из Kestrel, роутинга, EF Core и вообще любой библиотеки, которая держит у себя ILoggerFactory и вызывает factory.CreateLogger("Какая-то.Категория") напрямую. И такие логи вообще не проходят через DI-регистрацию ILogger<T>, соответственно, декоратор поверх неё эти логи просто не увидит.

А вот ILoggerProvider — это обычный плоский (не generic) интерфейс, который LoggerFactory использует, чтобы создавать реальные ILogger-объекты под каждую категорию (CreateLogger(string categoryName)), и через него в конечном счёте проходит любой ILogger, независимо от того, получен он через DI или через ILoggerFactory.CreateLogger(string) напрямую.

Именно эта полнота покрытия стала причиной декорировать ILoggerProvider, а не ILogger<T>.

Реализация подхода

Код провайдера-декоратора и логгера, отсекающего лишние записи, может выглядеть примерно следующим образом:

public sealed class CancelledHttpLoggerProvider(
    ILoggerProvider inner,
    IHttpContextAccessor accessor) : ILoggerProvider
{
    public ILogger CreateLogger(string categoryName) =>
        new CancelledHttpLogger(inner.CreateLogger(categoryName), accessor);

    public void Dispose() => inner.Dispose();
}

public sealed class CancelledHttpLogger(
    ILogger inner,
    IHttpContextAccessor accessor) : ILogger
{
    public IDisposable? BeginScope<TState>(TState state) where TState : notnull =>
        inner.BeginScope(state);

    public bool IsEnabled(LogLevel logLevel) => inner.IsEnabled(logLevel);

    public void Log<TState>(
        LogLevel logLevel,
        EventId eventId,
        TState state,
        Exception? exception,
        Func<TState, Exception?, string> formatter)
    {
        if (exception is OperationCanceledException &&
            accessor.HttpContext?.RequestAborted.IsCancellationRequested == true)
        {
            return;
        }

        inner.Log(logLevel, eventId, state, exception, formatter);
    }
}

и регистрация:

services.AddHttpContextAccessor();
services.Decorate<ILoggerProvider, CancelledHttpLoggerProvider>();

CancelledHttpLoggerProvider не резолвится и не подменяется в контейнере напрямую — он оборачивает уже существующий ILoggerProvider, а CancelledHttpLogger создаётся вручную внутри CreateLogger(). Оба класса реализуют тот же интерфейс, что и то, что оборачивают, поэтому LoggerFactory (и вообще всё, что стоит выше по цепочке) не видит между ними разницы и не должно ничего знать о декорировании. Получается классический Decorator, без прокси и рефлексии в рантайме.

Важная деталь. Если провайдеров несколько (Console + NLog + Debug), то метод services.Decorate<ILoggerProvider, X>() задекорирует все зарегистрированные ILoggerProvider разом, потому что механизм декорирования сравнивает только тип сервиса, а не конкретную реализацию. К этому (и ещё одной похожей ловушке) мы вернёмся отдельно — в разделе «Подводные камни» ниже.

В демонстрационном коде проверка на равенство токенов отмены (OperationCanceledException.CancellationToken == RequestAborted) намеренно упрощена. Если ваше приложение активно работает с внешними HTTP-интеграциями или очередями по коротким внутренним таймаутам, этот нюанс стоит учесть отдельно, чтобы случайное совпадение по времени не скрыло реальный сбой стороннего сервиса.

Также стоит отметить, что на практике OperationCanceledException может быть обернуто во фреймворковые структуры вроде AggregateException (например, при параллельном выполнении задач). Для продакшена имеет смысл добавить рекурсивную проверку или распаковку InnerExceptions.

Кроме того, обратите внимание, что внедрение IHttpContextAccessor в синглтон-декоратор ILoggerProvider не создаёт captive dependency, поскольку сам IHttpContextAccessor регистрируется в качестве синглтона и безопасно работает с потоками через AsyncLocal под капотом (см. также AddHttpContextAccessor()):

public static class HttpServiceCollectionExtensions
{
    public static IServiceCollection AddHttpContextAccessor(
        this IServiceCollection services)
    {
        ArgumentNullException.ThrowIfNull(services, "services");
        services.TryAddSingleton<IHttpContextAccessor, HttpContextAccessor>();
        return services;
    }
}

Подводные камни

В данном разделе мы рассмотрим два момента, которые не видны из кода выше, но с высокой вероятностью всплывут на проде.

Ловушка №1: NullReferenceException в фоновых задачах

Проверка в декораторе выглядит безопасной только если внимательно смотреть на знак вопроса ?.:

accessor.HttpContext?.RequestAborted.IsCancellationRequested == true

Этот ?. легко потерять при переносе кода между проектами. И если его убрать, то декоратор упадёт с NullReferenceException в любой ситуации, когда лог пишется вне HTTP-конвейера:

• в фоновом IHostedService/BackgroundService;

• в консюмере очереди сообщений (RabbitMQ/Kafka-воркер);

• при логировании во время Program.Main/composition root, до старта первого запроса;

• в Scoped-сервисе, вызванном из IHostedService через IServiceScopeFactory.

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

Ловушка №2: декоратор накрывает все провайдеры сразу

Как отмечалось выше, Decorate<ILoggerProvider, X>() не умеет декорировать «только NLog» — он декорирует все ILoggerProvider, зарегистрированные к этому моменту, потому что механизм декорирования сопоставляет их по типу сервиса, а не по конкретной реализации. Если в Development дополнительно зарегистрирован AddConsole(), он тоже окажется обёрнут в CancelledHttpLoggerProvider — что чаще всего безвредно (логика одна и та же для всех синков), но может удивить, если для разных провайдеров нужна разная логика подавления.

Если требуется точечная фильтрация только одного конкретного синка, проще и надежнее всего перенести эту проверку внутрь самого фабричного метода декоратора:

public ILogger CreateLogger(string categoryName)
{
    var baseLogger = inner.CreateLogger(categoryName);
    
    // Подавляем шум только для NLog, остальные провайдеры (например, Console) возвращаем как есть
    return inner is NLogLoggerProvider
        ? new CancelledHttpLogger(baseLogger, accessor)
        : baseLogger;
}

Для нашей задачи (подавлять шум от отмен) декорирование «оптом» было осознанным и приемлемым выбором. Но это должно быть взвешенным решением, а не побочным эффектом, который принимается неявно.

А что по перформансу?

Декоратор оборачивает ILoggerProvider, а значит, добавленная проверка выполняется на каждый вызов Log() во всём приложении — на LogInformation, LogDebug, LogWarning (все уровни и все категории). Звучит настораживающе, поэтому вместо «поверьте, это дёшево» предлагаю посмотреть на реальные цифры.

Смотрим, из чего состоит сама проверка:

exception is OperationCanceledException &&
accessor.HttpContext?.RequestAborted.IsCancellationRequested == true

• exception is OperationCanceledException — это проверка типа через паттерн-матчинг; компилятор превращает её в isinst/сравнение указателя на таблицу типов. Никаких аллокаций, никакой рефлексии, стоимость — на уровне сравнения ссылок.

• accessor.HttpContext?.RequestAborted — это null-проверка плюс чтение поля структуры CancellationToken. Тоже без аллокаций.

• == true на bool? — сравнение значения.

Чтобы не ограничиваться теоретическими рассуждениями о наносекундах, я прогнал тесты с помощью BenchmarkDotNet. Замеры проводились в среде .NET 10 на процессоре AMD Ryzen 7 PRO 2700 (команда запуска: dotnet run -c Release). Чтобы оценить чистые накладные расходы декоратора, а не скорость дисковой подсистемы, логи отправлялись в пустой no-operation sink (т.е. логи не записывались никуда).

Для оценки чистых накладных расходов декоратора, я сравнил три сценария выполнения ILogger.LogError(...):

Главные выводы

• Аллокаций нет. Паттерн-матчинг is, null-проверка ?. и чтение полей структуры CancellationToken не трогают кучу.

• Прохождение насквозь дороже подавления. Подавленный лог выходит из метода на первой же строчке проверки. Обычный лог обязан пройти все условия декоратора и вызвать нижестоящий логгер. То есть декоратор в худшем случае (когда ничего не подавляет) стоит дороже, чем когда экономит работу.

• +4 наносекунды — это статистическая погрешность. Любая физическая запись лога в консоль, файл или отправка по сети (то, ради чего и подключают NLog) занимает от сотен наносекунд до миллисекунд. Накладные расходы обёртки на 2–4 порядка меньше стоимости самого ввода-вывода (IO) и никогда не станут узким местом приложения.

Единственный сценарий, где к этому вообще стоит возвращаться, — система с экстремально высоким QPS логирования на Trace/Debug-уровне, где и без декоратора уже стоит вопрос, не логируете ли вы слишком много.

Методика и код бенчмарка — в репозитории, числа выше воспроизводимы через dotnet run -c Release --project src/Demo.Benchmarks (у себя на другом железе вы получите другие абсолютные наносекунды, но соотношение и отсутствие аллокаций должны сохраниться).

Аналогичные сценарии применения Scrutor

Декоратор поверх ILoggerProvider с обращением к IHttpContextAccessor — не разовый хак под одну задачу, а частный случай общего паттерна: «обогатить операцию данными из текущего HTTP-запроса, не протаскивая эти данные вручную через все слои приложения». Вот ещё два примера того же приёма.

Retry-обёртка вокруг HTTP-клиента

Есть IPaymentGatewayClient, который иногда падает с транзиентной сетевой ошибкой. Нужны повторные попытки — но без изменения основной реализации и без ручного оборачивания каждого вызова в Polly в вызывающем коде.

public interface IPaymentGatewayClient
{
    Task<PaymentResult> ChargeAsync(PaymentRequest request, CancellationToken ct);
}

public sealed class PaymentGatewayClient : IPaymentGatewayClient
{
    public Task<PaymentResult> ChargeAsync(PaymentRequest request, CancellationToken ct) =>
        /* реальный HTTP-вызов */;
}

public sealed class RetryingPaymentGatewayClient(
    IPaymentGatewayClient inner,
    ILogger<RetryingPaymentGatewayClient> logger) : IPaymentGatewayClient
{
    public async Task<PaymentResult> ChargeAsync(PaymentRequest request, CancellationToken ct)
    {
        const int maxRetries = 3;

        for (int attempt = 1; attempt <= maxRetries; attempt++)
        {
            try
            {
                return await inner.ChargeAsync(request, ct);
            }
            catch (HttpRequestException ex)
            {
                logger.LogWarning(ex, "Payment gateway call failed, retrying (attempt {Attempt} of {MaxRetries})", attempt, maxRetries);
                
                // На последней попытке ждать и ловить ошибку уже не нужно, пусть летит наверх
                if (attempt == maxRetries)
                {
                    throw;
                }

                await Task.Delay(TimeSpan.FromMilliseconds(200 * attempt), ct);
            }
        }

        // Этот throw нужен только чтобы успокоить компилятор, хотя поток выполнения сюда не дойдет
        throw new InvalidOperationException("Unexpected control flow in retry loop.");
    }
}

Декорируется это аналогичным образом:

services.AddHttpClient<IPaymentGatewayClient, PaymentGatewayClient>();
services.Decorate<IPaymentGatewayClient, RetryingPaymentGatewayClient>();

Это тот же самый механизм закрытого декорирования одного интерфейса, что и с ILoggerProvider. В продакшене для ретраев поверх HttpClient обычно разумнее взять Microsoft.Extensions.Http.Resilience или Polly — они готовы из коробки и покрывают больше edge-кейсов. Но сам приём «явный декоратор через Scrutor» полезен, когда условия ретрая специфичны для домена и тащить целую библиотеку ради одного if не хочется.

Аудит изменений с привязкой к текущему пользователю

Допустим, нужно логировать факт изменения сущности (кто, когда, что изменил) в отдельный audit-лог, не размазывая эту логику по всей кодовой базе. Для этого мы сначала изолируем получение ID пользователя:

public interface ICurrentUserProvider
{
    string GetCurrentUserId();
}

public sealed class HttpCurrentUserProvider(IHttpContextAccessor accessor) : ICurrentUserProvider
{
    private const string SystemUserId = "system";

    public string GetCurrentUserId()
    {
        var user = accessor.HttpContext?.User;
        return user?.FindFirst(ClaimTypes.NameIdentifier)?.Value ?? SystemUserId;
    }
}

Затем переходим к декорации репозитория IOrderRepository:

public interface IOrderRepository
{
    Task SaveAsync(Order order, CancellationToken ct);
}

public sealed class SqlOrderRepository : IOrderRepository
{
    public Task SaveAsync(Order order, CancellationToken ct) => /* запись в БД */;
}

public sealed class AuditingOrderRepository(
    IOrderRepository inner,
    ICurrentUserProvider userProvider,
    IAuditLog auditLog) : IOrderRepository
{
    public async Task SaveAsync(Order order, CancellationToken ct)
    {
        await inner.SaveAsync(order, ct);
        var userId = userProvider.GetCurrentUserId();
        await auditLog.RecordAsync($"Order {order.Id} saved by {userId}", ct);
    }
}

Регистрация в DI:

services.AddHttpContextAccessor();
services.AddScoped<ICurrentUserProvider, HttpCurrentUserProvider>();
services.AddScoped<IOrderRepository, SqlOrderRepository>();
services.Decorate<IOrderRepository, AuditingOrderRepository>();

Это практически та же схема, что и CancelledHttpLogger, только применённая не к логгеру, а к репозиторию IOrderRepository: и там, и там декоратор через IHttpContextAccessor обогащает операцию контекстом текущего запроса (в одном случае — «был ли запрос отменён", в другом — «кто сейчас залогинен").

И, конечно, та же самая ловушка №1 из раздела «Подводные камни» актуальна и здесь: если SaveAsync может быть вызван из фоновой джобы (например, при импорте заказов пачкой), то accessor.HttpContext будет null, и обращение к нему обязано быть защищено через ?. — как в примере выше.

Итого

Ни конфигурация логгера, ни middleware не могут целиком решить задачу «не логировать отменённые пользователем запросы» — потому что в момент, когда решение принимается, у них либо нет доступа к HttpContext, либо исключение уже успело залогироваться где-то ниже по стеку.

Декоратор поверх ILoggerProvider, зарегистрированный через Scrutor, решает это в одной точке, но платит за это парой не самых очевидных нюансов (нулабельный HttpContext, декорирование всех провайдеров сразу). Эти нюансы обязательно нужно проговаривать явно, а не оставлять как сюрприз для тех, кто будет сопровождать код после вас. При этом сам приём — «декоратор + IHttpContextAccessor» — куда шире одной задачи с логированием: это общий инструмент для прозрачного протаскивания контекста текущего запроса в глубокие слои приложения.

Всё, что описано выше, работает и объясняется на уровне «вот API, вот код, вот почему он корректен». Если же интересно, что стоит за самой строчкой services.Decorate<...>() — как Scrutor переписывает регистрации в контейнере, как DI-контейнер .NET строит из этого дерево вызовов и превращает его в исполняемый код, и что в итоге оказывается в памяти процесса, вплоть до заголовка объекта и указателей — это отдельный разбор, которому будет посвящена отдельная статья.

Исходный код решения, бенчмарки и тесты доступны в репозитории. Дополнительные сценарии применения паттерна из финала статьи приведены исключительно как концептуальные сниппеты и в коде репозитория не рассматриваются.