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

Всем привет.

Я написал статью о том «за бесплатно», системными методами, сделать так, чтобы логи писали себя сами (https://habr.com/ru/articles/931416/). Статья описывает как сделать так чтобы в логах отражались аргументы вызова метода и возвращаемый результат, при этом не обработанные исключения, тоже будут попадать в логи.

В первом же комментарии к той статье, мне дали ссылку на альтернативный способ (https://github.com/vescon/MethodBoundaryAspect.Fody). Способ через разработку атрибута и применение этого атрибута ко всем методам, которые хочется видеть в логах.

Способ на самом деле удобный, но имеющий свои нюансы. Самый не очевидный состоит в том, что NuGet пакет MethodBoundaryAspect.Fody надо добавить во все проекты где вам нужны логи.

Нюансы использования NuGet пакета MethodBoundaryAspect.Fody

Первое

В моём случае, у меня разработан проект-библиотека которая непосредственно пишет логи, и этот проект добавлен как зависимость в другие проекты. В классах я проставил атрибут на методы, которые хотел логировать. Код успешно компилировался, но логи не писались, пока я в эти проекты не добавил пакет MethodBoundaryAspect.Fody.

Восемь раз подряд одни и те же действия (у меня в солюшене 17 проектов, в восьми нужны были логи), это было пыткой.

Если добавлять в один проект за раз (за день), то конечно ни чего страшного.

Второе

При добавлении NuGet пакета MethodBoundaryAspect.Fody, автоматически создаются два файла:

• FodyWeavers.xml

• FodyWeavers.xsd

Это файл конфигурации (FodyWeavers.xml) и описание формата файла конфигурации (FodyWeavers.xsd).

Эти файлы будут во всех проектах, у меня в солюшене например 17 проектов, из них в 8 эти файлы добавлены, вопрос зачем ? Нельзя ли их куда то задвинуть подальше, чтобы в корне не болтались ?

В остальном всё супер, и все прочие сложности пришлось бы разруливать при любом другом способе логирования.

Порядок действий

Действие первое — добавить пакет:

Install-Package MethodBoundaryAspect.Fody

Добавить можно разными способами, надеюсь разберётесь.

Класс атрибута

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

using MethodBoundaryAspect.Fody.Attributes;  namespace archivist {     public sealed class LogAttribute : OnMethodBoundaryAspect     {         public override void OnEntry(MethodExecutionArgs args)         {             IndependentFileArchivist Archivist = new();              string correlationId = string.Empty;             if (args.Instance != null )             {                 var instance = (ILogable)args.Instance;                 correlationId = instance.GetCorrelationId();             }              Archivist.Initialize(correlationId, args.Method);             Archivist.Before(DateTime.Now, args.Arguments);              args.MethodExecutionTag = Archivist;         }          public override void OnExit(MethodExecutionArgs args)         {             var Archivist = GetArchivist(args);             Archivist.After(DateTime.Now, args.ReturnValue);         }          public override void OnException(MethodExecutionArgs args)         {             var Archivist = GetArchivist(args);             Archivist.Exception(DateTime.Now, args.Exception);         }         private static IndependentFileArchivist GetArchivist(MethodExecutionArgs args)         {             return (IndependentFileArchivist)args.MethodExecutionTag;         }     } }

Каждый метод логера в своей сигнатуре имеет MethodExecutionArgs args. В свойство MethodExecutionTag можно сохранить произвольный объект (можно сохранить состояние логера). Это свойство имеет самый широкий тип object, поэтому при чтении из него надо выполнять приведение типа к нужному.

У статических методов args.Instance будет null, если собираетесь вызывать какой то метод класса для которого задан класс атрибут, то сделайте проверку на null. Как при этом передавать correlation id я не разбирался, возможно это минус этого способа логирования.

Как я использую свойство MethodExecutionTag

# При первом вызове класса обёртки (атрибута) создаём экземпляр "своего" логера IndependentFileArchivist Archivist = new(); # Записываем экземпляр логера (его состояние) в специальное свойство класса args.MethodExecutionTag = Archivist; # При следующих вызовах, восстанавливаем var Archivist = (IndependentFileArchivist)args.MethodExecutionTag

Первый вызов (OnEntry)

Создаём писателя логов и записываем его в MethodExecutionTag:

public override void OnEntry(MethodExecutionArgs args) {        IndependentFileArchivist Archivist = new();   args.MethodExecutionTag = Archivist;

Инициализируем писателя логов

     string correlationId = string.Empty;   Archivist.Initialize(correlationId, args.Method);

Логируем вызов метода помеченного атрибутом LogAttribute

 Archivist.Before(DateTime.Now, args.Arguments);             }

Последующие вызовы (OnExit, OnException)

Вызов на возврате результата

Восстанавливаем писателя:

public override void OnExit(MethodExecutionArgs args) {     var Archivist = GetArchivist(args);

Логируем:

    Archivist.After(DateTime.Now, args.ReturnValue); }

Аналогично с вызовом на необработанном исключении:

public override void OnException(MethodExecutionArgs args) {     var Archivist = GetArchivist(args);     Archivist.Exception(DateTime.Now, args.Exception); }

Особенности работы класса атрибута

Класс атрибут не статический, но видимо под капотом на каждый вызов создаётся новый экземпляр, поэтому у класса на самом деле нет состояния, поэтому приходиться упражняться с args.MethodExecutionTag. Конечно на отладке вы это сами увидите.

Пример использования в коде

Собственно последний третий этап — это применить класс атрибут в коде.

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

Собственно всё использование это строка 28.

using archivist; using Newtonsoft.Json;  namespace archivist {     public interface ILogable     {         public string GetCorrelationId();     } }  namespace PayloadProcessor {     public class Processor : ILogable     {         public Processor(string correlationId)         {             CorrelationId = correlationId;         }          public string CorrelationId { get; }          public string GetCorrelationId()         {             return CorrelationId;         }          [Log]         public string HandlePayload(string payload)         {             var doc = JsonConvert.DeserializeXmlNode(payload);             var result = doc?.InnerXml;              return result ?? "";         }     } }

Класс имеет имя LogAttribute, класс в имени имеет «суффикс» Attribute его можно опустить. В приведённом примере используется короткая форма записи — Log, Компилятор понимает о чём речь. Если класс атрибут не имеет суффикса Attribute, то имя класса надо писать полностью.

Проблемы с логированием генераторов

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

Ниже код который был залогирован совсем не в том порядке, не с теми временными отметками, которые были на самом деле.

[Log] public override string Run(IArgumentStorage arguments) {     var medium = arguments.Extract(         MediumIndex,         "Тип источника сообщений не задан"         );     var options = arguments.Extract(         OptionsIndex,         "Не определены настройки получения сообщений из источника"         );      var messageList = new List<string>();     foreach (var message in ReadMessages(medium, options))     {         messageList.Add(message.ToString());         Console.WriteLine(message);     }      return new archivist.ArrayStringPrinter(messageList.ToArray()).ToString(); }  [Log] public IEnumerable<string> ReadMessages(     string medium,     string options     ) {     var reader = new ReadingInboxLibrary         .InboxReaderFactory()         .Make(medium, CorrelationId);     reader.GetReadyForReading(options);      foreach (var body in reader.LetReadTheMessages())     {         yield return body;     }  }

Как было:

1. вызывается метод Run

2. внутри метода Run вызывается метод ReadMessages, который является генератором

3. метод ReadMessages внутри себя вызывает другой генератор DirectoryObserver.LetReadTheMessages()

4. возвращается значение из LetReadTheMessages

5. возвращается значение из ReadMessages

6. делаем ещё один вызов ReadMessages

7. делаем ещё один вызов LetReadTheMessages

8. из LetReadTheMessages возвращается ответ что в генераторе закончились значения

9. из ReadMessages возвращается ответ что в генераторе закончились значения

10. метод Run возвращает свой результат

Что записано в логах:

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

1. Самая левая колонка это отметки времени в тиках процессора;

2. Идентификатор запуска;

3. Собственно был запуск или было завершение;

4. Аргументы вызова или результат выполнения;

Как видим в логах всё было последовательно:

1. Concierge.CLI.Program -> ReadMessages (строки 1 и 2)

2. ReadingInboxLibrary.DirectoryObserver -> GetReadyForReading (строки 3 и 4)

3. ReadingInboxLibrary.DirectoryObserver -> LetReadTheMessages (строки 5 и 6)

4. ReadingInboxLibrary.DirectoryObserver -> GetReadyForReading (строки 7 и 8)

5. ReadingInboxLibrary.DirectoryObserver -> LetReadTheMessages (строки 9 и 10)

Нет вложенности LetReadTheMessages в ReadMessages.

Имейте в виду эту особенность работы класса атрибута с генераторами.

Наверное это повод стать контрибьютором.

Выводы

Выводы у нас на канале каждый делает для себя сам 🙂

Мне понравилось, я буду использовать.

Ссылки по теме

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

2. Исходники и документация по MethodBoundaryAspect.Fody

3. Код полного примера использования логирования через атрибуты метода