Nie lubię logowania

Nie lubię logowania — brudzi mi w kodzie; narzekam, gdy podczas ratowania produkcji brak logów — jak żyć?!

Jestem leniwy, nie lubię pamiętać o tym i tamtym — lubię, gdy rzeczy dzieją się same i nie muszę sobie zawracać tym głowy. Ale bez przesady! Logi to najgorsze i najlepsze co może spotkać programistów — z jednej strony logi zaśmiecają kod, z drugiej strony dają podgląd na to, co użytkownicy wymyślili na produkcji.

AOP

Logowanie przy pomocy AOP oczyszcza kod w przypadku typowego i klasycznego podejścia do logów, ok — może to zrobić. Często szukam w logach tego, co zostało uruchomione i z jakim parametrem, aby zrozumieć, co poszło nie tak. Nie lubię ^C^V takiego kodu na początku każdej metody. Niestety nie znalazłem dobrego rozwiązania AOP (czytaj darmowego) a interfejs IIntercept z jakiegoś powodu nie chce zostać uruchomiony (ale jest tworzony — kiedyś to zrozumiem); z tego powodu przy pomocy internetów znalazłem DispatchProxy które świetnie robi swoją robotę.

DispatchProxy

Otóż chciałbym mieć możliwość logowania tego, co i jak się wywołuje z możliwością włączenia / wyłączenia detali (poziomy logowania w moim przypadku, lub inna forma konfiguracji). Chce móc przeczytać logi i dowiedzieć się co się wywołuje i z jakim parametrami, dla każdej metody, dodatkowo bez potrzeby modyfikacji kodu, gdy dana metoda się zmieni.

Można to zrobić przy pomocy DispatchProxy które przechwyci wywołanie metody i umożliwi wykonanie dowolnego kodu; przed; po czy też podczas błędu.

	public class LoggingDecorator<T> : DispatchProxy
	{
	private T _decorated;
	private ILogger<T> _logger;
	protected override object Invoke(MethodInfo targetMethod, object[] args)
	{
	_logger.LogTrace(">PROXY!");
	_logger.LogInformation($"{targetMethod.Name}");
	var pd = string.Join(',', targetMethod.GetParameters().Select(p => $"{p.Name} : {p.ParameterType}"));
	var p = string.Join(',', args?.Select(a => Newtonsoft.Json.JsonConvert.SerializeObject(a)));
	_logger.LogDebug($"with params: {pd}");
	_logger.LogDebug($"with params: {p}");
	var result = targetMethod.Invoke(_decorated, args);
	_logger.LogTrace("<PROXY!");
	return result;
	}
	public static T Create(T decorated, ILoggerFactory loggerFactory)
	{
	var proxy = Create<T, LoggingDecorator<T>>();
	if (proxy is LoggingDecorator<T> p)
	{
	p._decorated = decorated;
	p._logger = loggerFactory.CreateLogger<T>();
	}
	else
	{
	throw new Exception("Failed to create proxy class");
	}
	return (T)proxy;
	}
	}

view raw 20230219-dynamic-proxy-log.cs hosted with by GitHub

Otóż taka klasa opina ładnie swoją docelową klasę T , a następnie podczas tworzenia zwraca takie proxy, udając klasę typu podstawowego. Tutaj uwaga: konstruktor musi być pusty, a ewentualne przekazanie parametrów i ich  przypisanie następuje w metody fabrykującej (wewnątrz if)

Gdy użytkownik takiej klasy wywołuje metodę docelową, na proxy wcześniej zostanie zawołane Invoke gdzie można czynić cuda.
Ja na przykład na poziomie `Information` loguje nazwę wywoływanej metody, a na poziomie Debug dorzucam także nazwy i wartości przekazanych argumentów.

Rejestracja

Piękne jest to, że DispatchProxy nie wymaga zewnętrznych bibliotek i działa na czysto z .net. Zależność do klasy rejestruje w taki sposób:

	public static class IocExtensions
	{
	public static IServiceCollection AddTransientWithLogs<I, C>(this IServiceCollection services) where C : class, I where I : class
	{
	services.AddTransient<C>();
	services.AddTransient<I>(b =>
	{
	var c = b.GetRequiredService<C>();
	var lf = b.GetRequiredService<ILoggerFactory>();
	var i = LoggingDecorator<I>.Create(c, lf);
	return i;
	});
	return services;
	}
	}
	/// ...
	/// method call
	/// ...
	builder.Services.AddTransientWithLogs<IService, Service>();

view raw 202302190-dynamic-proxy-ioc.cs hosted with by GitHub

Akcja

Działa to tak:

Tutaj przykład konsumpcji oraz wykorzystania przykładowego serwisu

	// typical ioc injection
	public WeatherForecastController(ILogger<WeatherForecastController> logger, IService service)
	{
	_logger = logger;
	_service = service;
	}
	// ... code
	[HttpGet(Name = "GetWeatherForecast")]
	public IEnumerable<WeatherForecast> Get()
	{
	_service.DoWork(null, null);
	_service.DoWork(new ServiceParams(), string.Empty);
	_service.DoWork(new ServiceParams(), "asd");
	_service.DoWork(null, "asd");
	// some code goes here
	}

view raw 20230219-dynamic-proxy-example-of-logs.cs hosted with by GitHub

A tutaj logi:

	trce: IService[0]
	>PROXY!
	info: IService[0]
	DoWork
	dbug: IService[0]
	with params: p : ServiceParams,s : System.String
	dbug: IService[0]
	with params: null,null
	I actually do work
	trce: IService[0]
	<PROXY!
	trce: IService[0]
	>PROXY!
	info: IService[0]
	DoWork
	dbug: IService[0]
	with params: p : ServiceParams,s : System.String
	dbug: IService[0]
	with params: {"Type":"asd","Type1":42,"Type2":{"key":"obj"}},""
	I actually do work
	trce: IService[0]
	<PROXY!
	trce: IService[0]
	>PROXY!
	info: IService[0]
	DoWork
	dbug: IService[0]
	with params: p : ServiceParams,s : System.String
	dbug: IService[0]
	with params: {"Type":"asd","Type1":42,"Type2":{"key":"obj"}},"asd"
	I actually do work
	trce: IService[0]
	<PROXY!
	trce: IService[0]
	>PROXY!
	info: IService[0]
	DoWork
	dbug: IService[0]
	with params: p : ServiceParams,s : System.String
	dbug: IService[0]
	with params: null,"asd"
	I actually do work
	trce: IService[0]
	<PROXY!

view raw 20230219-dynamic-proxy-logs.example.txt hosted with by GitHub

Serwis jest nudny do bólu i prawie o nim zapomniałem:

	public interface IService
	{
	void DoWork(ServiceParams p, string s);
	}
	public class Service : IService
	{
	public void DoWork(ServiceParams p, string s)
	{
	Console.WriteLine("I actually do work");
	}
	}

view raw 20230219-dynamic-proxy-example-of-service.cs hosted with by GitHub

Siup

W tak przygotowanym kodzie, zależności rejestrowane z pomocą logera powinny samodzielnie wrzucać informację o tym, co i jak się wykonało. Oczywiście można dodać sobie flagi do optymalizacji tego, czy przed, czy po co w sytuacjach wyjątkowych ma się logować i na jakim poziomie. Warto także pomyśleć o tym, jak takie logi ze sobą łączyć za pomocy correlationId – ale to pozostawiam już waszej wyobraźni.

ps.
dzisiaj bez obrazka