SbWereWolf 27 июл в 06:02

C#, Логи которые пишут себя сами

Простой

9 мин

3.1K

C#*

Туториал

Recovery Mode

Всем привет.

Пару лет назад мне пришлось заняться интеграцией СБП с АБС банка, писать надо было на C#. Первое о чём я подумал, конечно, это было логирование. Писать логи руками это конечно не мой выбор. Конечно хотелось чтобы при вызове метода в логи записывались его входные аргументы и выходные результаты и конечно эксепшены.

В C#, на тот момент (конец 2023 года), для этого надо было делать обёртку над классом, пример обёртки я приведу ниже. Этот код был проверкой гипотезы, для использования в работе надо дописать обработку множество нюансов (работа с итераторами хотя бы).

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

Класс обёртка

Что нужно нашей обёртке ?

Класс обёртка должен быть наследником от DispatchProxy (using System.Reflection;)

Свойства класса:

Конечно логгер (FileArchivist Archivist)
Собственно экземпляр вложенного класса (T? _decorated)
Идентификатор входящего вызова для отслеживания цепочки выполнения (_correlationId)

public class LoggingDecorator<T> : DispatchProxy{
  private readonly FileArchivist Archivist = new();

  private T? _decorated;
  private string? _correlationId;  
}

Реализацию логирования пишем в методе:

protected override object? Invoke(
    MethodInfo? targetMethod,
    object?[]? args
    )

Выполнение логирования

Собственно реализация:

var shouldLogging = targetMethod?.Name != "ToString";

if (shouldLogging)
{
    Archivist.Before(DateTime.Now, args);
}

object? result;
try
{
    result = targetMethod?.Invoke(_decorated, args);
}
catch (Exception ex) when (ex is TargetInvocationException)
{
    var realException = ex.InnerException ?? ex;

    if (shouldLogging)
    {
        Archivist.Exception(DateTime.Now, realException);
    }

    throw realException;
}

if (shouldLogging)
{
    Archivist.After(DateTime.Now, result);
}

return result;

Разберём построчно, что тут происходит.

var shouldLogging = targetMethod?.Name != "ToString";

Определяемся с тем надо ли нам логировать этот вызов (хотя бы что бы не попасть на рекурсию).

if (shouldLogging)
{
    Archivist.Before(DateTime.Now, args);
}

Если логировать надо, то логируем аргументы вызова.

object? result;
try
{
    result = targetMethod?.Invoke(_decorated, args);
}

Вызов оборачиваем в try / catch, что бы перехватить эксепшен, если он случиться.

catch (Exception ex) when (ex is TargetInvocationException)
{
    var realException = ex.InnerException ?? ex;

    if (shouldLogging)
    {
        Archivist.Exception(DateTime.Now, realException);
    }

    throw realException;
}

Перехватываем исключения только от механизма вызова нужного метода у заданного экземпляра. Логируем исключение, если надо.

if (shouldLogging)
{
    Archivist.After(DateTime.Now, result);
}

return result;

Если надо логировать, то логируем результат.

Результат вызова возвращаем.

Как этим пользоваться

Теперь о том как этим пользоваться.

С использованием есть пара трудностей.

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

Второе, у класса обёртки в конструкторе не может быть ни каких аргументов, то есть инициализация состояния происходит отдельно, от создания экземпляра.

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

public static T Create(T decorated, string? correlationId)
{
    object proxy = Create<T, LoggingDecorator<T>>() ??
        throw new ArgumentNullException(
            "Fail on create proxy for "
            + (decorated?.GetType().FullName ?? "")
            );
    ((LoggingDecorator<T>)proxy)
        .SetParameters(decorated, correlationId);

    return (T)proxy;
}

С помощью рефлексии создаём экземпляр класса обёртки, и инициализируем состояние экземпляра.

Метод инициализации:

private void SetParameters(T decorated, string? correlationId)
{
    if (decorated == null)
    {
        throw new ArgumentNullException(nameof(decorated));
    }

    _decorated = decorated;
    _correlationId = correlationId;

    Archivist.Initialize(
        _correlationId,
        _decorated);
}

Использование в коде

Интерфейс для класса, который хотим автоматически логировать:

public interface ICliProgram
{
    public IArgumentStorage ProcureArguments(
string[] args,
ArgumentStorageFactory storageFactory
);
    public string Run(IArgumentStorage arguments);
    public IConfigurationRoot LoadProgramSettings();
    public string[]? GatherArgumentsFromInput(
        string? input,
        string cliArgumentsSeparator,
        string optionNumbers
        );
    public void SetCorrelationId(string correlationId);
}

В логах мы увидим только эти методы. Методы с модификатором доступа private и protected мы в логах не увидим. Из-за этого приходиться делать public методы, которые на самом деле private, но автоматически логи того стоят.

Собственно код с автоматическим логированием:

public static void Main(string[] args)
{
    var correlationId = GetCorrelationId(args);

    var app = archivist.
        LoggingDecorator<ICliProgram>.
        Create(new Program(SettingsKey), correlationId);

    app.SetCorrelationId(correlationId);

    var arguments = app.ProcureArguments(
        args, 
        new ArgumentStorageFactory()
        );
    app.Run(arguments);
}

Построчный разбор кода с автоматическим логированием

Построчно:

    var app = archivist.
        LoggingDecorator<ICliProgram>.
        Create(new Program(SettingsKey), correlationId);

Создали прокси класс над нужным классом (что бы автоматически логировать его вызовы).

    var arguments = app.ProcureArguments(
        args, 
        new ArgumentStorageFactory()
        );

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

Архитектура предполагает вызов каждого приложения (CLI программы), как с аргументами вызова из командной строки, так и с аргументами вызова из "консольного" ввода (из потока STD_IN программы), откуда брать аргументы задаётся в конфиге программы.

app.Run(arguments);

Запустили программу с надлежащими аргументами. В логах увидим с какими аргументами вызывали метод и какой результат он вернул.

Стоит ли так заморачиваться ради того, чтобы логи писали себя сами ? Я считаю оно того стоит. Такой стиль логирования побуждает дробить код на небольшие методы, потому что если писать стену текста, тогда и логи придётся писать вручную, а эта работа кажется лишней, когда эту работу за нас может сделать сам "компилятор".

Сериализация значений для записи в логи

Теперь про само логирование, о том как записывать в текстовый файл значения аргументов, которые не всегда строки. То есть каждый аргумент должен стать строкой, для этого можно у каждого класса переопределить метод ToString(). Но есть способ проще.

Воспользуемся сериализацией в JSON:

private static string serializeWithJson(object? obj)
{
    var serilized = JsonConvert.SerializeObject(obj);
    if (serilized == "{}")
    {
        serilized = obj?.ToString();
    }

    return serilized ?? "non-serializable-value";
}

Если после сериализации получили пустой объект, то вызываем встроенный метод приведения к строке - ToString().

Если не смогли получить строковое представление, то возвращаем "non-serializable-value". (Когда увидим в логах "non-serializable-value", тогда напишем "кастомный" ToString() для этого класса).

Сериализация входных аргументов

args ??= Array.Empty<object>();

var arguments = new List<string?>();
foreach (var obj in args)
{
    string serialized = serializeWithJson(obj);
    arguments.Add(serialized);
}
var values = new StringBuilder().
    AppendJoin('\u00A0', arguments.ToArray());

Аргументы вызова могу отсутствовать, это не редкость, поэтому если массив аргументов не задан, то присваиваем значение Array.Empty().

Каждый аргумент сериализуем отдельно, и склеиваем всё в одну строку через символ неразрывный пробел ('\u00A0'). Логи надо писать так ,чтобы было потом удобно парсить, поэтому тут подумайте как будет лучше их писать - какой выбрать разделитель для отдельных частей лога, чтобы потом по этому разделителю, разбить строку на семантические части.

Сериализация результата на выходе

var jsonResult = serializeWithJson(result);

Куда писать логи: в файл, в STD_OUT, в какой то сервис по UDP дело вкуса.

Полный код классов

Приведу законченные примеры кода для класса обёртки и для класса логера.

Класс обёртка

using System.Reflection;

namespace archivist
{
    /* base on https://learn.microsoft.com/ru-ru/archive/msdn-magazine/2014/february/aspect-oriented-programming-aspect-oriented-programming-with-the-realproxy-class */
    /* base on https://stackoverflow.com/questions/38467753/realproxy-in-dotnet-core */
    public class LoggingDecorator<T> : DispatchProxy
    {
        private readonly FileArchivist Archivist = new();

        private T? _decorated;
        private string? _correlationId;

        protected override object? Invoke(
            MethodInfo? targetMethod,
            object?[]? args
            )
        {
            var shouldLogging = targetMethod?.Name != "ToString";
            if (shouldLogging && !Archivist.WasInitialized)
            {
                Archivist.Initialize(_correlationId, _decorated);
            }
            if (shouldLogging)
            {
                Archivist.GetReady(targetMethod);
            }

            if (shouldLogging)
            {
                Archivist.Before(DateTime.Now, args);
            }

            object? result;
            try
            {
                result = targetMethod?.Invoke(_decorated, args);
            }
            catch (Exception ex) when (ex is TargetInvocationException)
            {
                var realException = ex.InnerException ?? ex;

                if (shouldLogging)
                {
                    Archivist.Exception(DateTime.Now, realException);
                }

                throw realException;
            }

            if (shouldLogging)
            {
                Archivist.After(DateTime.Now, result);
            }

            return result;
        }

        public static T Create(T decorated, string? correlationId)
        {
            object proxy = Create<T, LoggingDecorator<T>>() ??
                throw new ArgumentNullException(
                    "Fail on create proxy for "
                    + (decorated?.GetType().FullName ?? "")
                    );
            ((LoggingDecorator<T>)proxy)
                .SetParameters(decorated, correlationId);

            return (T)proxy;
        }

        private void SetParameters(T decorated, string? correlationId)
        {
            if (decorated == null)
            {
                throw new ArgumentNullException(nameof(decorated));
            }

            _decorated = decorated;
            _correlationId = correlationId;

            Archivist.Initialize(_correlationId, _decorated);
        }
    }
}

Класс логер

using Microsoft.Extensions.Configuration;
using Newtonsoft.Json;
using System.Reflection;
using System.Text;

namespace archivist
{
    /* base on https://markpelf.com/1072/logging-proxy-in-c/ */
    public class FileArchivist
    {
        private string CorrelationId = string.Empty;
        private string InvokeId = string.Empty;
        private string ClassName = string.Empty;
        private string MethodName = string.Empty;

        private Object LogLocker = new();

        protected const string SettingsKey =
            "integrated-logger-settings-file";
        private string? LogFilename = null;

        public bool WasInitialized { get; private set; }

        public FileArchivist()
        {
            WasInitialized = false;
        }

        private static string ProcureLogFilename
        {
            get
            {
                var secretConfig = new ConfigurationBuilder()
                    .AddUserSecrets<FileArchivist>()
                    .Build();
                var fileWithSettings = secretConfig[SettingsKey] ?? "";

                var config = File.ReadAllText(fileWithSettings);
                config = config.Trim(Environment.NewLine.ToArray<char>());


                return config ?? string.Empty;
            }
        }

        private void MakeLogFilename()
        {
            if (LogFilename == null)
            {
                var filename = ProcureLogFilename;

                var isFileDefined = !string.IsNullOrEmpty(filename);
                if (!isFileDefined)
                {
                    throw new Exception("Log filename is not defined");
                }

                LogFilename =
                new StringBuilder().
                AppendJoin(
                '_',
                new string?[] {
                    filename,
                    CorrelationId,
                    DateTime.Now.Ticks.ToString(),
                    $"{Guid.NewGuid()}.log"
                }
                ).
                ToString();
            }
        }

        public void Initialize(
            string? correlationId,
            object? classExemplar
            )
        {
            CorrelationId = correlationId ?? string.Empty;
            ClassName = classExemplar?.GetType().FullName ?? "";

            MakeLogFilename();

            WasInitialized = true;
        }

        public void GetReady(
            MethodInfo? methodInfo
            )
        {
            InvokeId = $"invokeId={Guid.NewGuid()}";
            MethodName = methodInfo?.Name ?? string.Empty;
        }

        public async void Before(
            DateTime now,
            object?[]? args)
        {
            args ??= Array.Empty<object>();

            var arguments = new List<string?>();
            foreach (var obj in args)
            {
                string serialized = SerializeWithJson(obj);
                arguments.Add(serialized);
            }
            var values = new StringBuilder().
                AppendJoin('\u00A0', arguments.ToArray());

            var message = new StringBuilder().
                AppendJoin(
                ' ',
                new string?[] {
                    now.Ticks.ToString(),
                    CorrelationId,
                    InvokeId,
                    "RUN",
                    ClassName,
                    "->",
                    MethodName,
                    $"input ({values})",
                }
                ).
                ToString();

            await WriteLogToFile(message);
        }

        private static string SerializeWithJson(object? obj)
        {
            var serialized = JsonConvert.SerializeObject(obj);
            if (serialized == "{}")
            {
                serialized = obj?.ToString();
            }

            return serialized ?? "non-serializable-value";
        }

        public async void After(
            DateTime now,
            object? result
            )
        {
            var jsonResult = SerializeWithJson(result);

            var message = new StringBuilder().
                AppendJoin(
                ' ',
                new string?[] {
                    now.Ticks.ToString(),
                    CorrelationId,
                    InvokeId,
                    "END",
                    ClassName,
                    "->",
                    MethodName,
                    $"output {jsonResult}",
                }
                ).
                ToString();

            await WriteLogToFile(message);
        }

        public async void Exception(
            DateTime now,
            Exception exception)
        {
            var message = new StringBuilder().
                AppendJoin(
                ' ',
                new string?[] {
                    now.Ticks.ToString(),
                    CorrelationId,
                    InvokeId,
                    "EXC",
                    ClassName,
                    "->",
                    MethodName,
                    exception.Message,
                }
                ).
                ToString();

            await WriteLogToFile(message);
        }

        private Task WriteLogToFile(string logMessage)
        {
            lock (LogLocker)
            {
                if (!string.IsNullOrWhiteSpace(LogFilename))
                {
                    File.AppendAllText(
                        LogFilename,
                        logMessage + Environment.NewLine
                        );
                }
            }

            return Task.CompletedTask;

        }
    }
}

Проверку гипотезы (рабочий код) можно посмотреть на Гитхабе: https://github.com/SbWereWolf/ips-gateway

Подсказки в интернете которыми был вдохновлён этот код:

Хабы:

C#, Логи которые пишут себя сами

Класс обёртка

Выполнение логирования

Как этим пользоваться

Использование в коде

Построчный разбор кода с автоматическим логированием

Сериализация значений для записи в логи

Сериализация входных аргументов

Сериализация результата на выходе

Полный код классов

Класс обёртка

Класс логер

Публикации

Ближайшие события