Пользователь
0,0
рейтинг
11 августа 2014 в 15:42

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

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: EC2 Name Configuration
Эта настройка попадает в секцию 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.

Благодарю коллег Гульназ, Диму и Андрея за плодотворные дискуссии во время работы над описанным в этой статье кодом.
Михаил Бринчук @Thecentury
карма
17,0
рейтинг 0,0
Реклама помогает поддерживать и развивать наши сервисы

Подробнее
Спецпроект

Самое читаемое Разработка

Комментарии (19)

  • +1
    Подождите-подождите, логирование asp.net и не слова об ELMAH?

    Часто рекомендуют вызывать асинхронные методы, настраивая awaiter, чтобы он не вызывал продолжение в том же контексте синхронизации, из которого он был вызван сам: это увеличивает производительность.

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

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

    Какому именно коду-продолжению? Для кода в вашем собственном методе можно всю информацию захватить в его начале. Для кода вне вашего метода не имеет значение, как вы настраивали awaiter.

    • +2
      Да, ни слова об ELMAH, потому что мы его не используем. Я рассказал о том, что используем мы.

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

      Расскажете, каких ситуаций?
      • –2
        Да, ни слова об ELMAH, потому что мы его не используем. Я рассказал о том, что используем мы.

        А почему вы его не используете?

        Расскажете, каких ситуаций?

        У вас есть некий обработчик верхнего уровня, который по каким-то причинам не использует async. В нем, соответственно, нижележеащий асинхронный метод вызывается через блаблаблаAsync().Result. В этот момент поток блокируется на контексте синхронизации asp.net (том самом, про который вы пишете. Если теперь в любом коде ниже вызвать .Result, .Wait или асинхронный метод без .ConfigureAwait(false), они встанут в блокировку на том же контексте синхронизации — и мы успешно получим дедлок. Подробности — у Стивена Клири.
        • +1
          А, ясно. Такой блокировки у нас не будет, потому что к .Result мы не обращаемся, используем решение из http://stackoverflow.com/questions/5095183/how-would-i-run-an-async-taskt-method-synchronously
          • 0
            Вы уверены, что в коде уровне выше вашего обработчика никто и никогда не поставит блокирующий вызов? Проблема в том, что этот вид ошибки ловится только в рантайме.

            А во-вторых, то ли я чего-то не понимаю, то ли приведенное вами решение выполняет метод не в текущем контексте синхронизации.
            • 0
              Да, я в этом не уверен, и второе ваше замечание тоже верно, обдумаю, как мы можем это исправить.
              Проблем не возникало, видимо, потому, что а) синхронно асинхронные методы мы вызываем мало; б) информация о пользователе захватывается в его начале и передается явно через параметры.
              • 0
                информация о пользователе захватывается в его начале и передается явно через параметры.

                Вот поэтому я и не понимаю, какому коду-продолжению не будет доступна информация из контекста (цитата в первом комментарии).
          • 0
            Да, я прав: тот же самый Клири в комментариях к вашему решению пишет, что оно не работает там, где нужен asp-шный контекст синхронизации.
        • +1
          А почему вы его не используете?

          Видимо, пока ни разу не наткнулись на рекомендацию использовать его, когда искали, как решить ту или иную задачу. Для чего его используете вы? Он может решить что-то из того, что я описал?
          • –3
            Вообще-то, ELMAH упоминается почти на любом базовом докладе по asp.net. Он позволяет отлавливать «непойманные» ошибки в asp.net с адекватным логгированием и их отображением в дальнейшем.
            • +3
              У меня есть ощущение, что он ортогонален тому, о чем рассказал я:)
              Но спасибо за его упоминание, попробую понять, чем он может быть нам полезен.
  • +1
    Какой адЪ написан для юзеров…

    Уж ежели у вас нигде не используется ConfigureAwait(false) и используется await/async и у вас .net 4.5+ тогда вам просто надо было юзера вашего отнаследовать от IPrincipal, записать в Thread.CurrentIdentity и в HttpContext.Current.User в начале запроса (да хоть в OnBeginRequest в самом деле) и жить счастливо, т.к. AspNetSynchronizationContext будет вам сохранять HttpContext.Current (и юзера как его часть) до конца запроса благодаря введённому в .net45 так называемого task-friendly синхронизационного контекста (обязательно указание либо httpRuntime targetFramework=«4.5» в web.config либо aspnet:UseTaskFriendlySynchronizationContext в true в app.settings).

    А ежели у вас .net4 и ниже, то использовать надобно LogicalCallContext, который есть часть ExecutionContext-та и сохранению которого наплевать на синхронизационный контекст (который пока что тоже вообще говоря часть ExecutionContext-та) в силу того что все методы, порождающие асинхронность (и Task-и в том числе) используют ExecutionContext.Run для исполнения делагата, который и является «телом» задачи (а нужно это для сохранения CAS правил, импресонализации и сохранения LogicalCallContext).

    Короче надо бы как-нибудь просвятить местный народ касательно контекстов, async/await-тов и того как вообще работают Task-и, потоки и чем поток (thread) отличается от логического потока (control flow), а-то походу тут у многих в головах каша…

    • 0
      Вы знаете, я не думаю, что концептуально наше решение отличается от предложенного вами. Пользователь в HttpContext.Current.Items так же, как и из CurrentIdentity, переезжает из потока в поток.
      • 0
        Ну, пора начинать думать-то… Свой велосипед против готового и работающего из коробки, понятного всем? Так-то и нога ничем от руки концептуально не отличается…
  • 0
    Добрый день,

    Подскажите пожалуйста, кто нибудь встречал открытые проекты подобные Logentries, желательно сделанные на платформе .NET, которые можно взять и поставить у себя на сервере?
    • 0
      graylog2, logstash, splunk например. Иные подскажут опытные админы (им эта тема имхо ближе).
  • 0
    А чем не устроили штатные Health Monitoring и System.Diagnostics.Trace?
    • 0
      Не было с ними знакомства. Trace, насколько я знаю, даже по сигнатуре методов «логирования» сильно проигрывает NLog. Мы смогли бы с его помощью гибко настраивать, что логировать, данные, которые войдут в каждую запись, настраивать, в какие получатели будут отправлены записи? Смогли бы из коробки логировать в БД, на logentries? Хотя бы смогли бы писать логи в файлы, ротируя их каждые сутки?

      Про штатный Health Monitoring вообще ничего не знаю, расскажите, пожалуйста.
      • 0
        Не проблема :)
        Основы тут:
        msdn.microsoft.com/en-us/library/vstudio/bb398933%28v=vs.100%29.aspx
        По умолчанию поддерживает следующие типы событий:
        msdn.microsoft.com/en-us/library/system.web.management%28v=vs.110%29.aspx
        Типы стандартных кодов событий описаны тут:
        msdn.microsoft.com/en-us/library/system.web.management.webeventcodes%28v=vs.110%29.aspx

        Из коробки поддерживаются следующие провайдеры событий:
        • EventLogWebEventProvider — По стандарту всё пишется в евентлог. Меняется в глобальном Web.config'е
        • SqlWebEventProvider — Пишет всё в MSSQL. Хранимки и таблицы ставлятся через aspnet_regiis
        • WmiWebEventProvider — Отправляет все события через WMI
        • SimpleMailWebEventProvider / TemplatedMailWebEventProvider — Отправляет мыло. Второй позволяет указать шаблон отправки
        • TraceWebEventProvider — Отправляет всё в System.Diagnostics.Trace


        По умолчанию, пишет события в нечитабельном виде:
        Пример события типа исключение в базовом варианте
        Event message: An unhandled exception has occurred.
        Event code: 3005
        Event detail code: 0
        Event time: 21.08.2014 18:21:05
        Event ID: 1505644e-6d09-4c01-978e-e3250e964ce0
        Event sequence: 388911
        Event occurence: 2030
        
        Application information:
          Machine name: AAA
          Application domain: AAA
          Trust level: Full
          Application Virtual Path: /
          Application Path: D:\www\AAA\
        Process information:
          Process ID: 188364
          Process name: w3wp
          Accont name: 
        Exception information:
          Exception type: NullReferenceException
          Exception message: Object reference not set to an instance of an object.
          Stack trace:
        
        Request information:
          Request URL: http://aaa/default.aspx
          Request path: /default.aspx
          User host address: 192.168.1.1
          User: 
          Is authenticated: False
        



        Немного поколдовав над выводом данных и добавив свой провайдер логирования на централизованный лог-сервер получил такой результат:
        Пример события типа исключение в дописанном варианте
        <?xml version="1.0" encoding="utf-16"?>
        <Event>
         <Message>An unhandled exception has occurred.</Message>
         <EventId>1505644e-6d09-4c01-978e-e3250e964ce0</EventId>
         <Type>Error</Type>
         <Source>System.Web.HttpResponse</Source>
         <Code>3005</Code>
         <DetailCode>0</DetailCode>
         <Occurrence>2030</Occurrence>
         <Sequence>388911</Sequence>
         <TimeCreated>21.08.2014 18:21:05</TimeCreated>
         <Exception>
          <Type>NullReferenceException</Type>
          <Message>Object reference not set to an instance of an object.</Message>
          <StackTrace>AAA</StackTrace>
          <ExceptionString>AAA</ExceptionString>
         </Exception>
         <System>
          <MachineName>AAA</MachineName>
          <InstructionSet>X86</InstructionSet>
          <ApplicationName>AAA</ApplicationName>
          <DomainName>/LM/W3SVC/1/ROOT-4</DomainName>
          <Path>D:\www\AAA\</Path>
         </System>
         <Thread>
          <IsImpersonating>False</IsImpersonating>
          <ThreadId>63</ThreadId>
          <AccountName>NT AUTHORITY\NETWORK SERVICE</AccountName>
         </Thread>
         <Process>
          <ProcessId>188364</ProcessId>
          <CurrentProcessId>188364</CurrentProcessId>
          <ProcessName>w3wp</ProcessName>
          <AccountName />
         </Process>
         <Iis>
          <VirtualPath>/</VirtualPath>
          <TrustLevel>Full</TrustLevel>
          <Request>
           <Url>http://AAA/default.aspx</Url>
           <User Name="" AuthenticationType="" IsAuthenticated="False">System.Security.Principal.GenericIdentity</User>
           <RequestPath>/default.aspx</RequestPath>
           <UserHostAddress>192.168.1.1</UserHostAddress>
           <UserAgent>AAA</UserAgent>
          </Request>
         </Iis>
        </Event>
        



        Нашёл на хабре статью про внедрение HM (Возможно ещё есть. Первая на глаза попалась):
        habrahabr.ru/post/27847/

        Если будут ещё вопросы — спрашивайте. Буду рад помочь. :)

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