Разработчики периодически разрываются между желанием логировать как можно больше информации и необходимостью сделать объём логов разумно компактным.

Когда речь идёт о небольшом локальном сервисе с нагрузкой 10 запросов в день, можно позволить себе писать в логи всё: от полного текста запроса до полного текста ответа с кучей промежуточной информации (что пришло из базы, какой запрос послали во внешний сервис и что получили в ответ и т.д.). Когда же речь об относительно высоконагруженном сервисе, обрабатывающем порядка 1000 rps даже малая часть этой информации за пару дней запросто может вызвать переполнение современного жёсткого диска.

Возникает логичный вопрос: как логировать только нужную информацию?

Проблематика

Подавляющее большинство современных систем логирования поддерживают несколько уровней сообщений. В разных системах они могут именоваться немного по-разному, но суть, в целом, одна: Debug, Info, Warn, Error, Critical.

Не буду сейчас останавливаться на них подробно, скажу лишь, что они весьма условно решают описанную проблему. Да, мы можем грамотно расставить приоритет сообщений и принять решение, что мы будем, допустим, писать в логи только сообщения уровнем не ниже Info, а потом, когда у нас место под логи начнёт стремительно заканчиваться, исправлением одной строчки в файле конфигурации порежем и всё, что ниже Warn. И это решит проблему размера логов. Увы, но лишь частично.

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

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

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

В современных системах логирования, например, Serilog, есть такое понятие, как обогащение логов. Но этот механизм больше подходит для сценария, когда нам надо во все записи прокинуть дополнительные параметры, например, идентификатор трассировки, а не сгруппировать данные по нескольким записям.

В общем, надо писать что-то своё…

И немного кода

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

Рассмотрим его на примере Log4net, так как у нас на проекте всё ещё активно используется именно он. Там есть специальная переменная уровня контекста потока (LogicalThreadContext), в которую можно складывать временные значения. После некоторых упрощений код будет выглядеть показанным ниже образом. Аналогичный код можно написать и для Serilog.

Создадим обёртку над LoggerFactory, чтобы возвращать перегруженный логгер.

internal class DecoratedLoggerFactory : ILoggerFactory
{
	private readonly ILoggerFactory log4NetLoggerFactory;

	public DecoratedLoggerFactory(ILoggerFactory log4NetLoggerFactory)
	{
		this.log4NetLoggerFactory = log4NetLoggerFactory;
	}

	public Logger CreateLogger(ILoggerRepository repository, string name)
	{
		var logger = log4NetLoggerFactory.CreateLogger(repository, name);
		return new DecoratedLog4NetLogger(logger.Name);
	}
}

А затем и собственно логгер.

internal class DecoratedLog4NetLogger : Logger
{
	public DecoratedLog4NetLogger(string name) : base(name) { }

	public override void Log(Level level, object message, Exception exception)
	{
		if(IsEnabledFor(level)
            && LogicalThreadContext.Properties["trace"] is TraceContext traceContext
            && traceContext.IsTraceEnabled)
		{
			if(level > Level.Info)
				base.Log(level, message, exception);
			traceContext.Add(level, $"{message} {exception}");
		}
		else
			base.Log(level, message, exception);
		}
	}
	// аналогичный код для перегруженных методов
}

Код перегруженного метода довольно простой. Мы смотрим, что логирование для данного уровня разрешено, у нас есть в LogicalThreadContext нужное свойство и оно соответствует по типу заданному. После чего добавляем нашу запись в объект traceContext. Кроме того, все высокоприоритетные записи логируются сразу, а не просто помещаются в контекст «до лучших времён». О серьёзных проблемах надо узнавать незамедлительно, так как при глобальных ЧП логи из контекста могут не успеть записаться.

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

Объект TraceContext – это коллекция объектов TraceItem, в которых хранится уровень сообщения, время его возникновения, собственно текст и величина смещения момент записи относительно начала трассировки.

internal class TraceItem
{
	public TraceItem(Level level, DateTime utcNow, string message, double offset)
	{
		Message = message;
		Offset = offset;
		WritedAt = utcNow;
		Level = level;
	}

	public string Message { get; private set; }
	public double Offset { get; private set; }
	public DateTime WritedAt { get; private set; }
	public TraceLevel Level { get; private set; }
}

А сам объект TraceContext выглядит следующим образом:

public class TraceContext
{
	private readonly ConcurrentQueue<TraceItem> items = new();
	private readonly Stopwatch stopwatch = new();
	private readonly object lockObject = new();

	public bool IsTraceEnabled { get; set; }
	public CurrentLevel Level { get; private set; }

	public TraceContext()
	{
		IsTraceEnabled = true;
		CurrentLevel = Level.Debug;
		stopwatch.Start();
	}

	public void Add(Level level, string message)
	{
		if(!IsTraceEnabled)
			return;

		if(level > CurrentLevel)
		{
			lock(lockObject)
			{
				if(level > CurrentLevel)
				{
					CurrentLevel = level;
				}
			}
		}

		items.Enqueue(new TraceItem(level, DateTime.UtcNow, message, stopwatch.Elapsed.TotalMilliseconds));
	}

	public override string ToString()
	{
		if(!IsTraceEnabled)
			return string.Empty;

		StringBuilder stringBuilder = new();
		stringBuilder.AppendFormat(CultureInfo.InvariantCulture, "Max level: {0}. Total time: {1} ms", Level, stopwatch.Elapsed.TotalMilliseconds);
		stringBuilder.AppendLine();
		var i = 0;
		foreach(var e in items)
		{
			stringBuilder.AppendFormat(CultureInfo.InvariantCulture,
                    "{0} of {1} [{2}] at {3}, offset {4}: {5}", i + 1, items.Count, e.Level.ToString().ToUpper(), e.WritedAt.ToString("O"), e.Offset, e.Message);
			stringBuilder.AppendLine();
			i++;
		}
		return stringBuilder.ToString();
	}
}

В этом коде мы, по сути, делаем три вещи.

Во-первых, при добавлении записи мы сохраняем её в потокобезопасную коллекцию, отмерив момент выполнения команды. Во вторых, мы, при необходимости, поднимаем уровень ошибки всей трассировки с изначального Debug до того, который пришёл с текущим запросом и гарантируем, что более низкий приоритет не перезатрёт более высокий, если он уже был установлен. А в-третьих, мы перегрузили ToString, чтобы обеспечить вывод данных в некотором определённом формате, так, что у нас вся детальная «простыня» выдалась одним запросом.

И последнее, что нам остаётся сделать – это написать Middleware, которая будет перехватывать запросы и проверять их на наличие признаков, говорящих о том, что детали запроса надо вывести в лог.

public class LoggingMiddleware
{
	private readonly RequestDelegate next;
	private readonly ILogger logger;
	private readonly ISettings settingsProvider;

	public LoggingMiddleware(RequestDelegate next, ILogger<LoggingMiddleware> logger, ISettings settingsProvider)
	{
		this.next = next;
		this.logger = logger;
		this.settingsProvider = settingsProvider;
	}

	public async Task InvokeAsync(HttpContext context)
	{
		var sw = Stopwatch.StartNew();
		if(settingsProvider.EnableGlobalTracing)
			LogicalThreadContext.Properties["trace"] = new TraceContext();
		else
			LogicalThreadContext.Properties["trace"] = null;
		await next(context);

		sw.Stop();
		if(LogicalThreadContext.Properties["trace"] is TraceContext traceContext
			&& (traceContext.Level >= Level.Warn
				|| sw?.ElapsedMilliseconds >= settingsProvider.LongCallTriggerDurationMs))
		{
			LogicalThreadContext.Properties["trace"] = null;
			if(traceContext.Level >= TraceLevel.Warn)
				logger.Log(Convert(traceContext.Level), traceContext.ToString());
			else
				logger.LogWarning($"Long call. {traceContext}");
		}
		LogicalThreadContext.Properties["trace"] = null;
	}
}

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

Результат в логах выглядит примерно так:

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

Вывод

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

Отдельно разработчики отметили, что с получившейся «простынёй» работать стало несколько удобнее, чем искать сперва по косвенным признакам проблемный запрос, а потом вытаскивать все запросы с таким же id.

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