Some aspects of logging an ASP.NET site

    Hello!

    Today I will tell you how some aspects of logging in the site are made, in the development of which I take part.

    The site is written in ASP.NET MVC 5 and Web API 4, the NLog library is used for logging , the site is hosted in the Amazon cloud . Log entries are written in three places (target in NLog terminology): to the file system (the Logs subfolder of the App_Data folder, into which write access is allowed under the standard Amazon Elastic Beanstalk deployment settings), to the logentries service and to the database. Daily log entries are kept in a separate file, the name of which indicates the current date.

    Client side error logging


    There is a little logging on the site from the client side: unhandled javascript exceptions that occur in the client browser are logged. The website has a handler for all such exceptions, which makes an ajax request to the server, passing the existing error details, so we are aware of some problems on the client.

    // Ограничим количество ошибок, которые могут насыпаться с одной страницы
    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);
    };
    


    Logging on logentries


    Briefly about what he is

    Logentries is a service that allows you to store, view and analyze logs. For many logging systems, modules have been developed that allow sending logs to logentries; There is a target for NLog . It is possible to send logs to one repository from different applications (or from different machines), where they will be displayed together, sorted by time of addition.
    You can hang tags on the log record that will highlight the record in the stream of records and on the timeline.
    We use tags that are hung on records with the Error level, on the 404th and 500th errors, on errors from JS, on records about creating users and orders.
    The timeline of one of the logs per day looks like this:

    Our project has been in the public domain for about 9 months. To easy shame, we still use the free logentries plan. It has a number of restrictions: log entries are stored for a maximum of one week, and there is a limit on the top of the amount of information stored and added. At the beginning of the project’s life, we slightly exceeded these volumes by sending too many records, so the logentries service did not accept our logs for several days.

    We removed the log entry when it was clearly redundant, or changed their logging levels, so the problem was resolved. From that moment, we no longer rested on the limitations of the free tariff plan, although we did not specifically limit ourselves to logging.

    Messages of levels Debugand higher are written on logentries ( logging levels are predefined in NLogTrace, Debug, Info, Warn, ErrorAnd Fatal). We do not have any clearly formulated strategy about what level to record information in the log, I adhere to the following rules:
    - Tracing is written with the level Trace. By tracing, I mean records about the client’s web-requests to the site, records when entering the method about the fact of his call and the arguments that arrived; such records are partially made with the help of an interceptor that wraps calls to methods of several interfaces and is implemented using Castle Dynamic Proxy ;
    - Minor messages about what is happening in the code - with a level Debug. For example, if a query deleted n records by some criterion, I will write this to the log with this logging level;
    - I will write messages about events interesting from the point of view of business logic with a level Info: for example, these are records about creating a new user, creating an order or deleting it;
    - The level Warnwill contain records of suspicious situations when, for example, the expected entity was not found, which, however, did not lead to the complete impossibility to continue processing the request;
    - Finally, with the level, Errorentries are made about exceptions that occurred during the operation of the site.

    Historically, FatalI do not use the level .

    All messages are written to the file on the hard disk and to the database.

    Database Logging


    As I already wrote, we use the free logentries tariff plan, in which entries are stored for only one week.
    We have logging to files in the folderApp_Data/logssite. Now we do not use the incremental deployment of the site, some time ago there were problems with it: very often during the download of the updated version of the site the connection with Amazon was disconnected, and the deployment was interrupted. As a result, when a site is updated, all files in its folder are deleted, including the logs for previous days. It would probably be possible to log into a folder outside the site, but the site should have write permissions to it. If it turns out that you need to create it and configure access rights to it, the layout of the site on a new machine will become more complicated: you will either need to create a folder manually, or modify the layout script (which we don’t have at all now, we can do without it, deploy xcopy).
    Subconsciously, I felt that when investigating incidents, logs might be required and much more long ago. There were ideas to archive log files from web servers on Amazon S3 (storage of large amounts of data, a la remote file system): archiving could take place on a schedule, at the beginning of the day, copying log files for the previous day. Also, one should not forget to copy the existing logs for the current day before the deployment, so as not to lose them. However, instead, we decided to log in the database, to a table with several fields: date of record creation, logging level, stream identifier, user information (his login or identifier, if the user is anonymous and does not have a login) and the body of the record itself.
    Such logging was implemented, the benefit of NLog allows you to log into the database out of the box, but it was used very little to investigate situations on the site: a couple of months ago the database often ceased to be available, the processor of the machine with the SQL server was 100% loaded, and the requests fell off by timeout . There was a hypothesis that such a database load was partly related to logs: the database of logs was the largest on the server.
    The hypothesis was neither confirmed nor refuted, after a few days the SQL server returned to normal operation on its own, but I still do not risk making queries to the log database, fearing that a heavy query without indexes may again load the SQL server completely.

    To start logging in the database, I had to write my own layout renderer, which renders the date in a format that is understandable to the SQL server:

    // Рендерер полной даты, который пишет 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' ) );
    	}
    }
    

    In the database, as well as in files, log messages of all levels are recorded.

    Setting up database logging in NLog looks like this:
    Logs
          insert into Logs(CreatedTimeUtc, CreatedTimeMoscow, ThreadId, Severity, Logger, UserId, InstanceId, Message)
          values(@time, @moscowTime, @threadId, @severity, @logger, @userId, @instanceId, @message)
        

    The connection string to the log database is set in a section of the connectionStringsfile web.configcalled Logs.

    Log entry composition


    A typical log entry looks like this:
    [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
    

    where:
    - Dis the level of logging;
    - AMAZONA-XY1234ZU/Prod-1- information about the EC2 instance and the mnemonic name of the Elasticbeanstalk environment;
    - 14- identifier of the stream from which the record was made;
    - 2014-12-31 12:34:56.7890- current time in UTC;
    - 15472- request number (I will talk about it below);
    - 9e397bf8-c1bc-4a00-a22f-da3f20be55b6- identifier of the user during the request of which the log was recorded. In this case, the guide tells us that the user is anonymous, who does not have an email address, otherwise email would be indicated here;
    - the rest is the recording body itself.

    Amazon-specific logging


    Each log entry contains information about which machine this entry was made from. This information consists of two parts: the Amazon instance id of the EC2 machine, which is always available, and the name of the environment, which may be absent, since we manually set it in the settings when creating the Elasticbeanstalk environment.
    The server receives its amazon instance id by executing an http get request to the internal Amazon address:
    http://169.254.169.254/latest/meta-data/instance-id
    This address is described in the Amazon documentation .
    The request is made in the static constructor of the renderer layout, therefore it is executed once within the current AppDomain, and is wrapped in an empty catch block so that an exception during its execution does not interfere with the functioning of the server; the request is executed asynchronously so as not to delay the further start of the server:
    [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 );
    		}
    	}
    }
    

    In general, at this address you can get a lot of data about the instance and its environment, for example, the IP addresses assigned to the instance, the mac address, and the publicly available DNS name.

    The name of the environment is set manually in the configuration environment of Elastic Beanstalk: EC2 Name Configuration
    This setting gets into the AppSettingsweb.config section of the application, where it can also be read when starting the server using the key that we specified in the environment settings.

    As a result, these two fragments fall into the log, separated by a slash.

    Request Number


    From the very beginning, the identifier of the stream from which this record was made fell into the log entry. It could be used to distinguish (slightly indirectly) different flows of log messages - related to different requests. However, the rule “different requests - different threads” does not work at all: firstly, it may happen that two consecutive requests will be served by the same thread. In addition, at some point we began to use asynchronous request handlers, during which code can be executed in different threads (the continuation of the asynchronous method after waiting for the asynchronous operation to be executed can be executed in an arbitrary thread from the ASP.NET pool). All this reduces the value of the stream identifier (now I wondered whether to remove its logging at all).
    To ensure that log entries related to different web requests are guaranteed to be different, I wrote a new layout renderer that works in tandem with a filter that is globally hung on all API controllers and writes Itemsits number into the request dictionary . And the request number is simply the value of an integer static counter, which is atomically incremented every time you need to assign a number to a new request:
    // Управляет номером текущего веб-запроса.
    public static class WebRequestNumber
    {
    	private static int _currentRequestNumber;
    	private const string RequestNumberItemsKey = "ProjectName_RequestNumber";
    	// Возвращает следующий номер запроса.
    	public static int GetNextRequestNumber()
    	{
    		return Interlocked.Increment( ref _currentRequestNumber );
    	}
    	// Возвращает номер текущего запроса, или null, если запрос сейчас не обрабатывается.
    	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, recording the request number, looks like this:
    // Выводит в лог номер текущего веб-запроса, либо "-", если он не установлен.
    [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 );
    		}
    	}
    }
    


    As a result, all log entries added when executing the request have the same value of the request number, which makes it easy to isolate them when studying the logs.
    At the moment, the request number is not set for MVC requests (those processed by MVC controllers): this is less necessary, unlike API requests, since there are more of them and modifying operations are concentrated in them.

    User ID


    At the beginning of almost every request, a filter is executed that sets which user is executing the request. There are varieties of such a filter for both API and MVC controllers.
    In our project, user information is transferred to cookies. The filter extracts from the database by the value of this cookie the user profile data, its role, and writes it to the stack associated with the request that is currently being executed. When the request processing completes, the user information is retrieved from the stack.
    In the first implementation, the stack was stored in a thread-static variable. However, we had to change this architecture when we started using asynchronous controller methods, which can be executed by different threads. Now the stack is stored in the collectionItems a request, which, like all request data, is saved if the asynchronous method is executed while maintaining the ASP.NET synchronization context (which happens by default), and is transferred from stream to stream.

    Web API filter setting information about the user executing the request

    [AttributeUsage( AttributeTargets.Class | AttributeTargets.Method, AllowMultiple = false )]
    public sealed class SetAuthorizationInfoHttpAttribute : ActionFilterAttribute
    {
    	// Сервис, предоставляющий доступ к учетным записям пользователей; значение в свойство будет записано Autofac'ом 
    	public IUserAccountsService UserAccountsService { get; set; }
    	public async Task ExecuteActionFilterAsync( HttpActionContext actionContext, CancellationToken cancellationToken, Func> 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();
    	}
    }
    

    The interface IUserContextStorageis an abstraction over the storage location of the user stack:
    public interface IUserContextStorage
    {
    	// возвращает пользователя на вершине стека, или null, если стек пуст
    	[CanBeNull]
    	UserInfo PeekUserInfo();
    	// помещает пользователя на вершину стека
    	void Push( [NotNull] UserInfo userInfo );
    	// убирает пользователя с вершины стека
    	void Pop();
    }
    

    There are two implementations of it: the original one, which stores the stack in the thread local variable, and the updated one, which stores it in the Items collection HttpContext'а:
    public sealed class ThreadLocalUserContextStorage : IUserContextStorage
    {
    	private static readonly ThreadLocal> currentUsers = new ThreadLocal>( () => new Stack() );
    	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 GetUserInfos()
    	{
    		var httpContext = HttpContext.Current;
    		if ( httpContext == null )
    		{
    			return new Stack();
    		}
    		var items = httpContext.Items;
    		Stack userInfos;
    		if ( items.Contains( UserInfosKey ) )
    		{
    			userInfos = (Stack)items[UserInfosKey];
    		}
    		else
    		{
    			userInfos = new Stack();
    			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();
    	}
    }
    

    To obtain information about the current user, refer to the static property UserContext.CurrentUser, which returns the value from the top of the user stack or an empty user without rights if there is no user information. Basically, I try to access this static property in controllers by passing information about the current user to methods that actually execute business logic explicitly.

    In addition, for beauty and convenience, there is an heir to the ApiController class , which allows you to get the current user through its own non-static property:
    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; }
    	}
    }
    

    It is often recommended that you call asynchronous methods, setting up awaiter so that it does not cause a continuation in the same synchronization context from which it was called: it increases performance. However, in this case, information about the request, including its belonging to the user, will not be available to the continuation code, which will be executed after the asynchronous operation. Therefore, in order not to receive incorrect data about the current user,. ConfigureAwait (false) we do not use.

    Changing Static Logging Rules


    Logentries for me is the main tool for studying logs, it is with its help that I monitor whether everything is in order when we upload a new version of the site to the prod and understand problematic situations. As I already wrote, we send messages of a level Debugand higher to it. In most cases, this is enough and allows not to clutter up the log from a visual point of view, so as not to go beyond the limitations of the free tariff plan. On the other hand, sometimes level messages are Traceneeded to figure out why this or that happened, or why it even happened. Therefore, I decided that it would be nice to have all levels of logentries added during query processing if at least one of them has a level Warnor higher.
    At first I tried to write a system that would allow me to achieve this, myself.
    The idea was simple: a special wrapper on the logentries target, which would let all the records through itself, and if it found out that the record was being processed during the processing of the request (focusing on HttpContext.Current), it would not transfer the record further to logentries, but it would start to accumulate in the collection, associated with the request. To determine that the request has finished processing and to analyze the accumulated records and send them directly to logentries, I planned to use the HttpApplication.RequestCompleted event . However, here, due to poor knowledge of this part of ASP.NET, I failed: I signed up for the eventHttpApplication каждый раз, когда поступало сообщение лога для нового запроса, что впоследствии приводило к исключению внутри ASP.NET, который, видимо, не поддерживает добавление обработчиков событий HttpApplication динамически, во время работы сайта. Думаю, я смог бы в конечном итоге реализовать свою идею и сам, но я наткнулся на уже имеющуюся в NLog функциональность: таргет AspNetBufferingWrapper из nuget-пакета NLog.Extended буферизует сообщения лога, поступающие во время запроса, а PostFilteringWrapper позволяет анализировать массив сообщений и определять собственные правила, по которым сообщения будут переданы далее.
    Подписка на события HttpApplication делается однократно в HttpModuleNLogHttpModule, который нужно добавить в web.config(True, I had to add it to the collection of modules, different from the one indicated in the documentation: instead system.web/httpModules- to system.webServer/modules).
    As a result, the target writing to logentries is configured as follows:
    = Debug -->


    You may notice a target wrapper not mentioned previously SingleEventAsArraybetween AspNetBufferingWrapperand PostFilteringWrapper. It had to be implemented, because messages on our site can be written to the log even in the absence of a web request, for example, when the application starts. In this case , it HttpContext.Currentreturns nullthat it is correctly processed in AspNetBufferingWrapper: the message is not added to the collection, but transferred to the internal target, while, however, not being wrapped in an array.
    But he is PostFilteringWrappernot able to handle such situations, execution reaches the void Write(LogEventInfo logEvent)base class method WrapperTargetBase, which throws an exception:
    protected sealed override void Write(LogEventInfo logEvent)
    {
    	throw new NotSupportedException("This target must not be invoked in a synchronous way.");
    }
    

    In my wrapper, SingleEventAsArrayI wrap one message in an array and pass it not to the method Writeto which it would go by itself, but to 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 );
    	}
    }
    


    PS

    I thank colleagues Gulnaz, Dima and Andrey for fruitful discussions during the work on the code described in this article.

    Also popular now: