Некоторые аспекты логирования ASP.NET-сайта

Здравствуйте!

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

Сайт написан на ASP.NET MVC 5 и Web API 4, для логирования используется библиотека NLog, сайт хостится в облаке Амазона. Записи лога пишутся в три места (target по терминологии NLog): в файловую систему (подпапку Logs папки App_Data, в которую разрешается доступ на запись при стандартных настройках деплоя Amazon Elastic Beanstalk), на сервис logentries и в БД. Записи лога за день ведутся в отдельный файл, в названии которого указывается текущая дата.

Логирование ошибок на клиентской стороне

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

// Ограничим количество ошибок, которые могут насыпаться с одной страницы
var errorsLimit = 100;

// Универсальный обработчик ошибок, отправляет лог на сервер, где мы всё сможем видеть.
window.onerror = function(message, url, line, charPos, error) {
	if (!errorsLimit) {
		return;
	}
	errorsLimit--;

	var data = {
		"Message": message,
		"Url": url,
		"Line": line
	};

	if (charPos != undefined) {
		data["Char"] = charPos;
	}
	if (error != undefined && error.stack) {
		data["Stack"] = error.stack;
	}

	var errurl = "/javascript-error-api-controller-url/";
	$.get(errurl, data);
};

Логирование на logentries

Кратко о том, что он представляет из себя

Logentries — сервис, который позволяет хранить, просматривать и анализировать логи. Для многих систем логирования разработаны модули, позволяющие отправлять логи на logentries; есть таргет и для NLog. Имеется возможность отправлять в одно хранилище логи из разных приложений (или с разных машин), где они будут отображаться вместе, упорядоченные по времени добавления.
На запись лога можно навешивать теги, которые будут выделять запись в потоке записей и на таймлайне.
У нас используются теги, которые навешиваются на записи с уровнем Error, на 404-е и 500-е ошибки, на ошибки из JS, на записи о создании пользователей и заказов.
Таймлайн одного из логов за сутки у нас выглядит так:

Наш проект находится в публичном доступе уже около 9 месяцев. К легкому стыду, мы до сих пор используем бесплатный тарифный план logentries. У него есть ряд ограничений: записи лога хранятся максимум одну неделю, и есть предел сверху на объем хранимой и добавляемой информации. В начале жизни проекта мы слегка превысили эти объемы, отправляя слишком много записей, так что сервис logentries несколько дней не принимал наши логи.

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

На logentries пишутся сообщения уровней Debug и выше (в NLog предопределены уровни логирования Trace, Debug, Info, Warn, Error и Fatal). Какой-либо четко сформулированной стратегии о том, с каким уровнем записывать в лог информацию, у нас нет, я придерживаюсь следующих правил:
— Трассировка пишется с уровнем Trace. Под трассировкой я подразумеваю записи о выполняемых клиентом веб-запросах к сайту, записи при входе в метод о самом факте его вызова и пришедших аргументах; такие записи частично делаются у нас с помощью интерцептора, оборачивающего вызовы методов нескольких интерфейсов и реализованного с помощью Castle Dynamic Proxy;
— Малозначительные сообщения о происходящем в коде — с уровнем Debug. К примеру, если запрос удалил по некоторому критерию n записей, я запишу это в лог именно с этим уровнем логирования;
— Сообщения о событиях, интересных с точки зрения бизнес-логики, я запишу с уровнем Info: например, это записи о создании нового пользователя, создании заказа или его удалении;
— С уровнем Warn будут идти записи о подозрительных ситуациях, когда, к примеру, не была найдена ожидаемая сущность, что, однако не привело к полной невозможности продолжить обработку запроса;
— Наконец, с уровнем Error делаются записи о произошедших при работе сайта исключениях.

Исторически сложилось, что уровнем Fatal я не пользуюсь.

В файл на жестком диске и в БД записываются все сообщения.

Логирование в базу данных

Как я уже писал, мы используем бесплатный тарифный план logentries, в котором записи хранятся только одну неделю.
У нас имеется логирование в файлы в папке App_Data/logs сайта. Сейчас мы не используем инкрементальный деплой сайта, некоторое время назад с ним были проблемы: очень часто во время загрузки обновленной версии сайта обрывалось соединение с Амазоном, и деплой прерывался. В результате при обновлении сайта удаляются все имеющиеся в его папке файлы, в том числе и логи за предыдущие дни. Вероятно, можно было бы логировать в папку вне сайта, но сайт должен обладать правами на запись в нее. Если окажется, что ее нужно создавать и настраивать права доступа к ней, усложнится выкладка сайта на новую машину: нужно будет или создавать папку вручную, или дорабатывать скрипт выкладки (которого у нас сейчас вообще нет, вполне обходимся без него, деплоем xcopy).
Подсознательно я чувствовал, что при расследовании инцидентов могут потребоваться логи и значительно большей давности. Были идеи архивировать файлы с логами с веб-серверов на Amazon S3 (хранилище больших объемов данных, a la удаленная файловая система): архивация могла бы происходить по расписанию, в начале суток, копируя файлы логов за предыдущий день. Также нужно было бы не забывать копировать перед деплоем имеющиеся логи за текущие сутки, чтобы не потерять их. Однако вместо этого мы решили логировать и в БД, в таблицу с несколькими полями: дата создания записи, уровень логирования, идентификатор потока, информация о пользователе (его логин или идентификатор, если пользователь анонимный и не имеет логина) и собственно тело записи.
Такое логирование было реализовано, благо NLog позволяет логировать в БД из коробки, но использовалось для расследования ситуаций на сайте очень слабо: пару месяцев назад база часто переставала быть доступной, процессор машины с SQL-сервером был загружен на 100%, а запросы отваливались по таймауту. Была гипотеза, что такая загрузка БД отчасти связана с логами: база логов была самой большой на сервере.
Гипотеза не была ни подтверждена, ни опровергнута, SQL-сервер через несколько дней самостоятельно вернулся к нормальной работе, но я до сих пор не рискую делать запросы к БД логов, опасаясь, что тяжелый запрос без индексов может снова полностью загрузить SQL-сервер.

Чтобы логирование в БД начало работать, пришлось написать собственный layout renderer, который отрисовывает дату в формате, понятном SQL-серверу:

// Рендерер полной даты, который пишет 3 знака миллисекунд, а не 4, как LongDateLayoutRenderer, что не переваривается БД.
// Творчески переосмысленный копипаст из исходников NLog'а.
[LayoutRenderer( LayoutRendererNames.DbSafeLongDate )]
[ThreadAgnostic]
public sealed class DbSafeLongDateLayoutRenderer : LayoutRenderer
{
	// Gets or sets a value indicating whether to output UTC time instead of local time.
	[DefaultValue( false )]
	public bool UniversalTime { get; set; }

	// Renders the date in the long format (yyyy-MM-dd HH:mm:ss.mmm) and appends it to the specified StringBuilder.
	protected override void Append( StringBuilder builder, LogEventInfo logEvent )
	{
		DateTime dt = logEvent.TimeStamp;
		if ( UniversalTime )
		{
			dt = dt.ToUniversalTime();
		}

		builder.Append( dt.Year );
		builder.Append( '-' );
		Append2DigitsZeroPadded( builder, dt.Month );
		builder.Append( '-' );
		Append2DigitsZeroPadded( builder, dt.Day );
		builder.Append( ' ' );
		Append2DigitsZeroPadded( builder, dt.Hour );
		builder.Append( ':' );
		Append2DigitsZeroPadded( builder, dt.Minute );
		builder.Append( ':' );
		Append2DigitsZeroPadded( builder, dt.Second );
		builder.Append( '.' );
		Append3DigitsZeroPadded( builder, dt.Millisecond );
	}

	private static void Append2DigitsZeroPadded( StringBuilder builder, int number )
	{
		builder.Append( (char)( ( number / 10 ) + '0' ) );
		builder.Append( (char)( ( number % 10 ) + '0' ) );
	}

	private static void Append3DigitsZeroPadded( StringBuilder builder, int number )
	{
		builder.Append( (char)( ( ( number / 100 ) % 10 ) + '0' ) );
		builder.Append( (char)( ( ( number / 10 ) % 10 ) + '0' ) );
		builder.Append( (char)( ( ( number / 1 ) % 10 ) + '0' ) );
	}
}

В БД так же, как и в файлы, записываются сообщения логов всех уровней.

Настройка логирования в БД в NLog выглядит так:

<target xsi:type="AsyncWrapper" name="database" overflowAction="Grow">
  <target xsi:type="Database">
    <connectionStringName>Logs</connectionStringName>
    <commandText>
      insert into Logs(CreatedTimeUtc, CreatedTimeMoscow, ThreadId, Severity, Logger, UserId, InstanceId, Message)
      values(@time, @moscowTime, @threadId, @severity, @logger, @userId, @instanceId, @message)
    </commandText>
    <parameter name="@time" layout="${DbSafeLongDate:universalTime=True}"/>
    <parameter name="@moscowTime" layout="${MoscowTime}"/>
    <parameter name="@threadId" layout="${threadid}"/>
    <parameter name="@severity" layout="${substring:${uppercase:${level}}}"/>
    <parameter name="@logger" layout="${logger:shortName=True}"/>
    <parameter name="@userId" layout="${EmailOrUserAccountId}"/>
    <parameter name="@instanceId" layout="${AmazonInstanceNameOrId}"/>
    <parameter name="@message" layout="[${RequestNumber}] ${message} ${exception:format=ToString}"/>
  </target>
</target>

Строка подключения к БД логов задается в секции connectionStrings файла web.config под названием Logs.

Состав записи лога

Типичная запись лога выглядит так:

[D] [AMAZONA-XY1234ZU/Prod-1] [ 14] 2014-08-08 12:34:56.7890 [15472] [9e397bf8-c1bc-4a00-a22f-da3f20be55b6] OrderService CreateOrder: IP = 127.342.781.9

где:
— 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, чтобы исключение при его выполнении не нарушало функционирование сервера; запрос выполняется асинхронно, чтобы не задерживать дальнейший старт сервера:

[LayoutRenderer( LayoutRendererNames.AmazonInstanceId )]
[ThreadAgnostic]
public sealed class AmazonInstanceIdRenderer : LayoutRenderer
{
	// http://stackoverflow.com/questions/625644/find-out-the-instance-id-from-within-an-ec2-machine
	private const string _instanceIdUrl = "http://169.254.169.254/latest/meta-data/instance-id";

	private static string _instanceId;

	static AmazonInstanceIdRenderer()
	{
		Task.Factory.StartNew( () =>
		{
			try
			{
				WebClient webClient = new WebClient();
				_instanceId = webClient.DownloadString( _instanceIdUrl );
			}
			catch ( Exception exc )
			{
				ExceptionHandler.Ignore( exc );
			}
		} );
	}

	public static string InstanceId
	{
		get { return _instanceId; }
	}

	protected override void Append( StringBuilder builder, LogEventInfo logEvent )
	{
		if ( !String.IsNullOrEmpty( _instanceId ) )
		{
			builder.Append( _instanceId );
		}
	}
}

Вообще, по этому адресу можно получить достаточно много данных о инстансе и его окружении, к примеру, присвоенные инстансу ip-адреса, mac-адрес, публично доступное DNS-имя.

Имя окружения задается вручную в конфигурации окружения Elastic Beanstalk:
Эта настройка попадает в секцию AppSettings web.config'а приложения, откуда ее можно считать также при старте сервера по ключу, который мы указали в настройках окружения.

В результате два этих фрагмента попадают в лог, разделенные слэшем.

Номер запроса

С самого начала в запись лога попадал идентификатор потока, из которого эта запись была сделана. Его можно было использовать, чтобы различать (слегка косвенно) разные потоки сообщений лога — относящиеся к разным запросам. Впрочем, правило «разные запросы — разные потоки» совершенно не работает: во-первых, наверняка может случиться, что два последовательных запроса будет обслуживать один и тот же поток. Кроме того, с некоторого момента мы начали применять асинхронные обработчики запросов, во время исполнения которых код может выполняться в разных потоках (продолжение асинхронного метода после ожидания выполнения асинхронной операции может исполняться в произвольном потоке из пула ASP.NET). Все это уменьшает ценность идентификатора потока (сейчас я задумался, не убрать ли его логирование вовсе).
Чтобы гарантированно отличать записи логов, относящиеся к разным web-запросам, я написал новый layout renderer, который работает в паре с фильтром, глобально навешенным на все API-контроллеры и записывающий в словарь Items запроса его номер. А номер запроса — это просто значение целочисленного статического счетчика, который атомарно инкрементируется каждый раз, когда нужно присвоить номер новому запросу:

// Управляет номером текущего веб-запроса.
public static class WebRequestNumber
{
	private static int _currentRequestNumber;
	private const string RequestNumberItemsKey = "ProjectName_RequestNumber";

	// Возвращает следующий номер запроса.
	public static int GetNextRequestNumber()
	{
		return Interlocked.Increment( ref _currentRequestNumber );
	}
	
	// Возвращает номер текущего запроса, или <c>null</c>, если запрос сейчас не обрабатывается.
	public static int? CurrentRequestNumber
	{
		get
		{
			var httpContext = HttpContext.Current;

			if ( httpContext == null )
			{
				return null;
			}

			object currentRequestNumber = httpContext.Items[RequestNumberItemsKey];
			return (int?)currentRequestNumber;
		}
	}

	// Устанавливает номер текущего запроса.
	public static void SetCurrentRequestNumber( int requestNumber )
	{
		var httpContext = HttpContext.Current;

		if ( httpContext == null )
		{
			return;
		}

		httpContext.Items[RequestNumberItemsKey] = requestNumber;
	}
}

Layout renderer, записывающий номер запроса, выглядит так:

// Выводит в лог номер текущего веб-запроса, либо "-", если он не установлен.
[LayoutRenderer( LayoutRendererNames.RequestNumber )]
public sealed class RequestNumberRenderer : LayoutRenderer
{
	protected override void Append( StringBuilder builder, LogEventInfo logEvent )
	{
		int? currentRequestNumber = WebRequestNumber.CurrentRequestNumber;
		if ( currentRequestNumber == null )
		{
			builder.Append( "-" );
		}
		else
		{
			builder.Append( currentRequestNumber.Value );
		}
	}
}

В результате у всех записей лога, добавленных при выполнении запроса, одно и то же значение номера запроса, что позволяет легко вычленять их при изучении логов.
На данный момент номер запроса не выставляется для MVC-запросов (тех, которые обрабатываются MVC-контроллерами): в этом есть меньшая потребность, в отличие от API-запросов, поскольку последних и больше, и в них сосредоточены модифицирующие операции.

Идентификатор пользователя

В начале почти каждого запроса выполняется фильтр, который устанавливает, какой пользователь выполняет запрос. Есть разновидности такого фильтра как для API-, так и для MVC-контроллеров.
В нашем проекте информация о пользователе переносится в куки. Фильтр извлекает из БД по значению этой куки данные профиля пользователя, его роли, и записывает в стек, связанный с запросом, который выполняется в данный момент. Когда обработка запроса завершается, информация о пользователе из стека извлекается.
В первой реализации стек хранился в thread-static переменной. Однако такую архитектуру пришлось изменить, когда мы начали использовать асинхронные методы контроллеров, которые могут выполняться разными потоками. Сейчас стек хранится в коллекции Items запроса, которая, как и все данные запроса, сохраняется, если асинхронный метод выполняется с сохранением контекста синхронизации ASP.NET (что происходит по умолчанию), и переносится от потока к потоку.

Web API-фильтр, устаналивающий информацию о пользователе, выполняющем запрос

[AttributeUsage( AttributeTargets.Class | AttributeTargets.Method, AllowMultiple = false )]
public sealed class SetAuthorizationInfoHttpAttribute : ActionFilterAttribute
{
	// Сервис, предоставляющий доступ к учетным записям пользователей; значение в свойство будет записано Autofac'ом 
	public IUserAccountsService UserAccountsService { get; set; }

	public async Task<HttpResponseMessage> ExecuteActionFilterAsync( HttpActionContext actionContext, CancellationToken cancellationToken, Func<Task<HttpResponseMessage>> continuation )
	{
		try
		{
			// извлечь из куки информацию об авторизации,
			// извлечь информацию о пользователе
			// и записать в стек
			
			// выполнить следующие обработчики запроса: фильтры и сам action
			var body = continuation();
			var response = await body;

			return response;
		}
		finally
		{
			// удалить информацию о пользователе из стека
			UserContext.Pop();
		}
	}
}		

// Предоставляет доступ к текущему пользователю
public static class UserContext
{
	// абстракция над стеком, хранящим информацию о пользователях
	private static IUserContextStorage userContextStorage = new ThreadLocalUserContextStorage();
	
	// возвращает текущего пользователя, или анонимного, если информация о пользователе в запросе отсутствует
	public static UserInfo CurrentUser
	{
		get { return userContextStorage.PeekUserInfo() ?? UserInfo.CreateAnonymousUserInfo(); }
	}

	public static void SetData( [NotNull] UserInfo userInfo )
	{
		if ( userInfo == null )
		{
			throw new ArgumentNullException( "userInfo" );
		}

		userContextStorage.Push( userInfo );
	}

	public static void Pop()
	{
		userContextStorage.Pop();
	}
}

Интерфейс IUserContextStorage является абстракцией над местом хранения стека пользователей:

public interface IUserContextStorage
{
	// возвращает пользователя на вершине стека, или null, если стек пуст
	[CanBeNull]
	UserInfo PeekUserInfo();
	
	// помещает пользователя на вершину стека
	void Push( [NotNull] UserInfo userInfo );
	
	// убирает пользователя с вершины стека
	void Pop();
}

Имеется две его реализации: изначальная, хранящая стек в thread local переменной, и обновленная, хранящая его в коллекции Items HttpContext'а:

public sealed class ThreadLocalUserContextStorage : IUserContextStorage
{
	private static readonly ThreadLocal<Stack<UserInfo>> currentUsers = new ThreadLocal<Stack<UserInfo>>( () => new Stack<UserInfo>() );

	public UserInfo PeekUserInfo()
	{
		return currentUsers.Value.PeekOrDefault();
	}

	public void Push( UserInfo userInfo )
	{
		if ( userInfo == null )
		{
			throw new ArgumentNullException( "userInfo" );
		}
		currentUsers.Value.Push( userInfo );
	}

	public void Pop()
	{
		var stack = currentUsers.Value;

		if ( stack.Count > 0 )
		{
			stack.Pop();
		}
	}
}

public sealed class HttpContextUserContextStorage : IUserContextStorage
{
	// ключ, по которому стек пользователей будет доступен в словаре Items
	private const string UserInfosKey = "__UserInfos_57726";

	[NotNull]
	private static Stack<User> GetUserInfos()
	{
		var httpContext = HttpContext.Current;
		if ( httpContext == null )
		{
			return new Stack<UserInfo>();
		}

		var items = httpContext.Items;
		Stack<UserInfo> userInfos;
		if ( items.Contains( UserInfosKey ) )
		{
			userInfos = (Stack<UserInfo>)items[UserInfosKey];
		}
		else
		{
			userInfos = new Stack<UserInfo>();
			items.Add( UserInfosKey, userInfos );
		}

		return userInfos;
	}

	public UserInfo PeekUserInfo()
	{
		var stack = GetUserInfos();
		return stack.PeekOrDefault();
	}

	public void Push( UserInfo userInfo )
	{
		if ( userInfo == null )
		{
			throw new ArgumentNullException( "userInfo" );
		}

		var stack = GetUserInfos();
		stack.Push( userInfo );
	}

	public void Pop()
	{
		var stack = GetUserInfos();
		stack.Pop();
	}
}

Получить информацию о текущем пользователе можно, обратившись к статическому свойству UserContext.CurrentUser, который возвратит значение с вершины стека пользователей или пустого пользователя без прав, если данных о пользователе нет. В основном я стараюсь обращаться к этому статическому свойству в контроллерах, передавая информацию о текущем пользователе в методы, которые фактически выполняют бизнес-логику, явно.

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

public abstract class TourConstructorApiController : ApiController
{
	protected UserInfo CurrentUser
	{
		get { return UserContext.CurrentUser; }
	}

	protected Guid CurrentUserId
	{
		get { return CurrentUser.AccountId; }
	}

	protected Guid? CurrentSessionId
	{
		get { return UserContext.CurrentSessionId; }
	}
}

Часто рекомендуют вызывать асинхронные методы, настраивая awaiter, чтобы он не вызывал продолжение в том же контексте синхронизации, из которого он был вызван сам: это увеличивает производительность. Однако в этом случае информация о запросе, в том числе и его принадлежность пользователю, не будет доступна коду-продолжению, который будет выполняться после асинхронной операции. Поэтому, чтобы не получать неверные данные о текущем пользователе, .ConfigureAwait(false) мы не используем.

Изменение статических правил логирования

Logentries для меня — основное средство для изучения логов, именно с его помощью я слежу, все ли в порядке, когда мы выкладываем на прод новую версию сайта, и разбираюсь в проблемных ситуациях. Как я уже писал, в него мы отправляем сообщения уровня Debug и выше. В большинстве случаев этого достаточно и позволяет не захламлять лог как с визуальной точки зрения, так и чтобы не выйти за ограничения бесплатного тарифного плана. С другой стороны, иногда сообщения уровня Trace нужны, чтобы разобраться, почему произошло то или иное, или почему оно вообще произошло. Поэтому я решил, что было бы неплохо иметь на logentries записи всех уровней, добавленные во время обработки запроса, если хотя бы одна из них имеет уровень Warn или выше.
Сначала я попытался написать систему, которая позволяла бы достичь этого, сам.
Идея была проста: особая обертка на таргетом logentries, которая пропускала бы через себя все записи, и если обнаруживала, что запись выполняется во время обработки запроса (ориентируясь на HttpContext.Current), то не передавала бы запись дальше, в logentries, а начинала накапливать в коллекции, ассоциированной с запросом. Чтобы определять, что запрос закончил обрабатываться, и следует провести анализ накопленных записей и отправить их непосредственно в logentries, я планировал использовать событие HttpApplication.RequestCompleted. Однако тут из-за слабого знания этой части ASP.NET я потерпел фиаско: я подписывался на событие HttpApplication каждый раз, когда поступало сообщение лога для нового запроса, что впоследствии приводило к исключению внутри ASP.NET, который, видимо, не поддерживает добавление обработчиков событий HttpApplication динамически, во время работы сайта. Думаю, я смог бы в конечном итоге реализовать свою идею и сам, но я наткнулся на уже имеющуюся в NLog функциональность: таргет AspNetBufferingWrapper из nuget-пакета NLog.Extended буферизует сообщения лога, поступающие во время запроса, а PostFilteringWrapper позволяет анализировать массив сообщений и определять собственные правила, по которым сообщения будут переданы далее.
Подписка на события HttpApplication делается однократно в HttpModule NLogHttpModule, который нужно добавить в web.config (правда, мне пришлось добавить его в коллекцию модулей, отличную от указанной в документации: вместо system.web/httpModules — в system.webServer/modules).
В итоге таргет, записывающий в logentries, настроен так:

<!-- Если во время обработки запроса были записи лога уровня Warn или Error, то пишет на logentries все, а не только >= Debug -->
<target xsi:type="AspNetBufferingWrapper" name="logentries">
  <target xsi:type="SingleEventAsArray">
    <target xsi:type="PostFilteringWrapper" defaultFilter="level >= LogLevel.Debug">
      <target type="Logentries" 
              layout="…"/>
      <when exists="level >= LogLevel.Warn" filter="true" />
    </target>
  </target>
</target>

Вы можете заметить не упомянутый ранее таргет-обертку SingleEventAsArray между AspNetBufferingWrapper и PostFilteringWrapper. Его пришлось реализовать, поскольку в нашем сайте сообщения могут писаться в лог и в отсутствие web-запроса, например, при старте приложения. В этом случае HttpContext.Current возвращает null, что корректно обрабатывается в AspNetBufferingWrapper: сообщение не добавляется в коллекцию, а передается во внутренний таргет, при этом, однако, не будучи обернутым в массив.
А вот PostFilteringWrapper не умеет обрабатывать такие ситуации, исполнение доходит до метода void Write(LogEventInfo logEvent) базового класса WrapperTargetBase, который бросает исключение:

protected sealed override void Write(LogEventInfo logEvent)
{
	throw new NotSupportedException("This target must not be invoked in a synchronous way.");
}

В своей обертке SingleEventAsArray я оборачиваю одно сообщение в массив и передаю его не в метод Write, в который оно пошло бы само по себе, а в WriteAsyncLogEvents:

[Target( LoggingTargetsNames.SingleEventAsArray, IsWrapper = true )]
public sealed class SingleEventAsArrayWrapper : WrapperTargetBase
{
	protected override void Write( AsyncLogEventInfo logEvent )
	{
		WrappedTarget.WriteAsyncLogEvents( logEvent );
	}

	protected override void Write( AsyncLogEventInfo[] logEvents )
	{
		WrappedTarget.WriteAsyncLogEvents( logEvents );
	}
}

P. S.

Благодарю коллег Гульназ, Диму и Андрея за плодотворные дискуссии во время работы над описанным в этой статье кодом.