Структурное логирование и интерполированные строки в C# 10
В последние годы все большую популярность у разработчиков завоевывает структурное логирование. Поэтому неудивительно, что Microsoft добавило его поддержку в пакет Microsoft.Extensions.Logging, являющийся составляющей частью .Net Core/.Net 5/.Net 6. В этой статье я хотел бы рассмотреть, как мы можем использовать структурное логирование с данным пакетом и показать идею, как мы можем расширить его с использованием новых возможностей C# 10.
Первоначальная настройка
Как известно, Microsoft.Extensions.Logging представляет собой фасад, к которому мы можем подключать различные нижележащие провайдеры логирования. В данной статье я буду использовать Serilog в качестве такого провайдера и настрою его для вывода логов на консоль в формате JSON.
В качестве примера мы будем рассматривать простое консольное приложение (ссылка на GitHub), в котором конфигурация логирования имеет следующий вид:
// Конфигурируем Serilog
Log.Logger = new LoggerConfiguration()
.MinimumLevel.Information()
.WriteTo.Console(new CompactJsonFormatter())
.CreateLogger();
// Регистрируем Serilog при создании Microsoft.Extensions.Logging.LoggerFactory
using var loggerFactory = LoggerFactory.Create(builder => builder.AddSerilog(dispose: true));
// Создаем экземпляр ILogger при помощи фабрики
var logger = loggerFactory.CreateLogger(); Также, создадим две записи, которые будем использовать в дальнейших примерах:
public record Point(double X, double Y);
public record Segment(Point Start, Point End)
{
public double GetLength()
{
var dx = Start.X - End.X;
var dy = Start.Y - End.Y;
return Math.Sqrt(dx * dx + dy * dy);
}
}Использование ILogger
Для логирования мы будем использовать интерфейс ILogger, который предоставляет несколько перегрузок метода Log, позволяющего указать уровень логирования в качестве параметра, а также методов вида Log<уровень>, например LogInformation, LogError и т.п. Все эти методы принимают в качестве параметров строку шаблона и массив аргументов (params object[]).
Залогируем, для примера, результат вычисления длины отрезка:
var segment = new Segment(new (1, 2), new (4, 6));
var length = segment.GetLength();
logger.LogInformation("The length of segment {@segment} is {length}.", segment, length);Строка формата имеет два аргумента, заключенных в фигурные скобки: segment и length. Значения аргументов передаются как последующие параметры метода. Символ @ перед аргументом segment является частью соглашения Message Template и означает, что Serilog должен развернуть структуру аргумента как объект. Без данного символа Serilog по умолчанию просто залогировал бы результат вызова метода segment.ToString().
В результате мы получим в логе следующую запись:
{
"@t": "2021-11-13T19:57:31.8636016Z",
"@mt": "The length of segment {@segment} is {length}.",
"segment": {
"Start": {
"X": 1,
"Y": 2,
"$type": "Point"
},
"End": {
"X": 4,
"Y": 6,
"$type": "Point"
},
"$type": "Segment"
},
"length": 5,
"SourceContext": "Program"
}Получившийся JSON-объект имеет свойство @mt, содержащее нашу строку шаблона, а также свойства segment и length, содержащие наши аргументы.
Несмотря на то, что данный подход достаточно прост и прямолинеен, он имеет ряд существенных недостатков:
Необходимость разбирать строку формата во время выполнения, что является достаточно затратным. Чтобы сгладить этот недостаток, инфраструктура логирования имеет кэш на 1024 строки.
Необходимость выделять память под массив аргументов даже в том случае, если указанный уровень логирования отключен.
Аргументы значимых типов упаковываются при помещении в массив объектов.
Дублирование имен переменных в строке шаблона и в параметрах метода.
Легко забыть один из параметров или перепутать их порядок.
В качестве альтернативы, лишенной всех этих недостатков, .Net 6 предлагает использовать новый генератор исходного кода: мы можем объявить частичный (partial) метод, принимающий нужные нам параметры и пометить его атрибутом LoggerMessageAttribute, как показано в следующем примере:
[LoggerMessage(0, LogLevel.Information, "The length of segment {segment} is {length}.")]
public static partial void LogSegmentLength(this ILogger logger, Segment segment, double length);Данный подход позволяет обеспечить наивысшую производительность логирования, однако также имеет свои недостатки:
Захламляет исходный код объявлениями частичных методов.
Не позволяет использовать символ
@перед имена аргументов, из-за чего Serilog не разворачивает их значения в объекты JSON.
Добавляем поддержку интерполированных строк в ILogger
Итак, нам бы хотелось найти выразительный способ писать структурные логи и по возможности избежать описанных выше недостатков. Удобным способом могло бы стать интерполирование строк. Однако, для этого нам придется сначала проделать дополнительную работу.
Если мы попробуем вызвать метод логирования с интерполированной строкой, например:
logger.LogInformation($"The length of segment {segment} is {length}.");то в логах мы получим следующую запись:
{
"@t": "2021-11-13T23:40:23.1323976Z",
"@mt": "The length of segment Segment { Start = Point { X = 1, Y = 2 }, End = Point { X = 4, Y = 6 } } is 5.",
"SourceContext": "Program"
}Как и следовало ожидать, мы потеряли всю информацию об аргументах. Это произошло потому, что компилятор C# превратил нашу интерполированную строку в обычный вызов метода String.Format.
Вообще говоря, до C# 10, компилятор мог преобразовать интерполированную строку либо в объект типа FormattableString, либо в обычную строку. Объекты типа FormattableString уже больше похожи на то, что нам нужно для решения нашей задачи, так как содержат в себе строку форматирования и массив аргументов в неизменном виде, однако их возможностей все еще недостаточно, так как мы теряем имена аргументов. Кроме того, при выборе перегрузки метода, C# отдает предпочтение версии, принимающей строку, что также не очень удобно на практике.
К счастью, в C# 10 появился новый механизм для интерполированных строк, которые позволит нам добиться того, чего мы хотим. Вкратце, мы можем создать структуру-обработчик интерполированных строк, предназначенную специально для нашей задачи:
[InterpolatedStringHandler]
public ref struct StructuredLoggingInterpolatedStringHandler
{
// Код обработчика будет приведен ниже
}Далее мы можем использовать ее как аргумент метода. Создадим, для примера, метод расширения Log:
public static partial class LoggerExtensions
{
public static void Log(this ILogger logger, LogLevel logLevel,
[InterpolatedStringHandlerArgument("logger", "logLevel")] ref StructuredLoggingInterpolatedStringHandler handler)
{
// Код метода будет приведен ниже
}
}Если теперь мы попробуем, передать интерполированную строку в наш метод Log:
logger.Log(LogLevel.Information, $"The length of segment {segment} is {length}.");то компилятор превратит этот вызов в следующий код:
var handler = new StructuredLoggingInterpolatedStringHandler(27, 2, logger, LogLevel.Information, out bool isEnabled);
if (isEnabled)
{
handler.AppendLiteral("The length of segment ");
handler.AppendFormatted(segment);
handler.AppendLiteral(" is ");
handler.AppendFormatted(length);
handler.AppendLiteral(".");
}
logger.Log(LogLevel.Information, ref handler);Как мы видим, компилятор использует вызов метода AppendLiteral для добавления литеральной части строки и вызов метода AppendFormatted для аргументов, а значит мы можем написать наш обработчик так, чтобы он сформировал строку шаблона, которую мы сможем передать в оригинальный метод ILogger.Log, а также список аргументов.
У вас может возникнуть вопрос, а откуда мы получим имена наших аргументов. В это нам поможет еще одна новая возможность C# 10 — CallerArgumentExpressionAttribute. Как и в случае с другими родственными Caller*-атрибутами, мы можем пометить им дополнительный строковый параметр метода AppendFormatted, и компилятор вставит в качестве значения C#-выражение, использованное при вызове метода для другого параметра этого же метода.
Итак, давайте соберем все то, что мы узнали вместе и напишем код нашего обработчика.
Для начала, объявим поля для хранения шаблона сообщения и его аргументов, а также свойство IsEnabled, в котором мы будем хранить значение, указывающее является ли включенным требуемый уровень логирования.
[InterpolatedStringHandler]
public ref struct StructuredLoggingInterpolatedStringHandler
{
private readonly StringBuilder _template = null!;
private readonly List _arguments = null!;
public bool IsEnabled { get; }
// ...
}
Далее мы должны создать конструктор, принимающий длину строкового литерала, количество аргументов, экземпляр ILogger, уровень логирования для сообщения и выходной параметр IsEnabled.
public StructuredLoggingInterpolatedStringHandler(int literalLength, int formattedCount, ILogger logger, LogLevel logLevel, out bool isEnabled)
{
IsEnabled = isEnabled = logger.IsEnabled(logLevel);
if (isEnabled)
{
_builder = new StringBuilder(literalLength);
_arguments = new List(formattedCount);
}
} Обратите внимание, что мы создаем StringBuilder и List только в случае, если переданный уровень логирования включен, тем самым экономя ресурсы, если это не так.
Также у вас мог возникнуть вопрос, откуда компилятор получает ILogger и уровень логирования. Если вы посмотрите немного выше на объявление метода Log, то увидите, что параметр обработчика помечен атрибутом [InterpolatedStringHandlerArgument("logger", "logLevel")] с двумя аргументами. Эти агрументы указывают имена параметров этого метода, которые содержат эти объекты.
Далее, добавим метод AppendLiteral:
public void AppendLiteral(string s)
{
if (!IsEnabled)
return;
_template.Append(s.Replace("{", "{{", StringComparison.Ordinal).Replace("}", "}}", StringComparison.Ordinal));
}В коде этого метода мы также экранируем фигурные скобки вызовами метода String.Replace. На самом деле мы могли бы провести экранирование в один проход, однако для простоты примера оставим этот код как есть.
Наконец, добавим метод AppendFormatted:
public void AppendFormatted(T value, [CallerArgumentExpression("value")] string name = "")
{
if (!IsEnabled)
return;
_arguments.Add(value);
_template.Append($"{{@{name}}}");
} Как я и говорил ранее, он содержит параметр name со значением по-умолчанию и помеченный атрибутом [CallerArgumentExpression("value")]. Вместо значения по умолчанию компилятор подставит C#-выражение использованное при вызове для параметра value (в простейшем случае — имя переменной).
Обратите внимание, что я всегда добавляю символ @ перед именем аргумента. Насколько я вижу, Serilog нормально обрабатывает его в том числе для примитивных/встроенных типов. Впрочем, если бы это было не так, мы всегда могли бы сделать отдельные перегрузки метода AppendFormatted для таких типов.
StringBuilder.Append
Кстати, в этом методе используется перегрузка StringBuilder.Append(ref System.Text.StringBuilder.AppendInterpolatedStringHandler handler) появившаяся в .Net 6, которая в свою очередь также использует новый механизм интерполирования строк.
Наконец добавим метод, возвращающий построенный шаблон сообщения и массив аргументов:
public (string, object?[]) GetTemplateAndArguments() => (_template.ToString(), _arguments.ToArray());Наш обработчик готов! Полный его код вы можете найти под спойлером:
Код обработчика
[InterpolatedStringHandler]
public ref struct StructuredLoggingInterpolatedStringHandler
{
private readonly StringBuilder _template = null!;
private readonly List _arguments = null!;
public bool IsEnabled { get; }
public StructuredLoggingInterpolatedStringHandler(int literalLength, int formattedCount, ILogger logger, LogLevel logLevel, out bool isEnabled)
{
IsEnabled = isEnabled = logger.IsEnabled(logLevel);
if (isEnabled)
{
_template = new (literalLength);
_arguments = new (formattedCount);
}
}
public void AppendLiteral(string s)
{
if (!IsEnabled)
return;
_template.Append(s.Replace("{", "{{", StringComparison.Ordinal).Replace("}", "}}", StringComparison.Ordinal));
}
public void AppendFormatted(T value, [CallerArgumentExpression("value")] string name = "")
{
if (!IsEnabled)
return;
_arguments.Add(value);
_template.Append($"{{@{name}}}");
}
public (string, object?[]) GetTemplateAndArguments() => (_template.ToString(), _arguments.ToArray());
} Наш метод расширения Log может использовать его следующим образом:
public static partial class LoggerExtensions
{
public static void Log(this ILogger logger, LogLevel logLevel,
[InterpolatedStringHandlerArgument("logger", "logLevel")] ref StructuredLoggingInterpolatedStringHandler handler)
{
if (handler.IsEnabled)
{
var (template, arguments) = handler.GetTemplateAndArguments();
logger.Log(logLevel, template, arguments);
}
}
}Теперь все готово, чтобы использовать его для логирования:
logger.Log(LogLevel.Information, $"The length of segment {segment} is {length}.");В результате мы получим правильное сообщение:
{
"@t": "2021-11-14T02:13:34.8380946Z",
"@mt": "The length of segment {@segment} is {@length}.",
"segment": {
"Start": {
"X": 1,
"Y": 2,
"$type": "Point"
},
"End": {
"X": 4,
"Y": 6,
"$type": "Point"
},
"$type": "Segment"
},
"length": 5,
"SourceContext": "Program"
}Кстати, обратите внимание на то, что перегрузка метода, принимающая обработчик, имеет приоритет над перегрузкой, принимающей строку. В данном случае, по моему мнению, разработчики C# исправили ошибку с приоритетами, которую допустили с FormattableString в C# 6.
Итак, теперь у нас есть метод расширения, позволяющий писать в лог с указанным уровнем. Нам также хотелось бы иметь методы специфичные для каждого уровня логирования, такие как LogError. Мы можем создать их по аналогии, однако наш оригинальный обработчик требует передачи уровня логирования в качестве аргумента, который отсутствует в наших методах. Чтобы решить эту проблему, нам придется создать отдельный обработчик для каждого уровня логирования. К счастью, мы можем воспользоваться композицией и переиспользовать наш StructuredLoggingInterpolatedStringHandler внутри этих обработчиков. Пример такого обработчика приведен под спойлером:
Код обработчика
[InterpolatedStringHandler]
public ref struct StructuredLoggingErrorInterpolatedStringHandler
{
private readonly StructuredLoggingInterpolatedStringHandler _handler;
public StructuredLoggingErrorInterpolatedStringHandler(int literalLength, int formattedCount, ILogger logger, out bool isEnabled)
{
_handler = new StructuredLoggingInterpolatedStringHandler(literalLength, formattedCount, logger, LogLevel.Error, out isEnabled);
}
public bool IsEnabled => _handler.IsEnabled;
[MethodImpl(MethodImplOptions.AggressiveInlining)]
public void AppendLiteral(string s) => _handler.AppendLiteral(s);
[MethodImpl(MethodImplOptions.AggressiveInlining)]
public void AppendFormatted(T value, [CallerArgumentExpression("value")] string name = "") => _handler.AppendFormatted(value, name);
[MethodImpl(MethodImplOptions.AggressiveInlining)]
public (string, object?[]) GetTemplateAndArguments() => _handler.GetTemplateAndArguments();
} Код метода
public static void LogError(this ILogger logger, [InterpolatedStringHandlerArgument("logger")] ref StructuredLoggingErrorInterpolatedStringHandler handler)
{
if (handler.IsEnabled)
{
var (template, arguments) = handler.GetTemplateAndArguments();
logger.LogError(template, arguments);
}
}Полный код проекта можно найти на GitHub.
Заключение
В результате у нас получилось с помощью C# 10 добавить поддержку структурного логирования с использованием интерполированных строк и избавиться от проблем с дублированием аргументов, передачей неверного количества аргументов, а также от выделения памяти в случае, когда данный уровень логирования выключен.
В коде все еще присутствуют некоторые проблемы, такие как отсутствие экранирования имен (так, Serilog требует, чтобы имена были правильными C#-идентификаторами) или неоптимальная реализация экранирования фигурных скобок. Тем не менее, он вполне может послужить основой для создания законченного промышленного решения для структурного логирования.
