Zwykle zapisując do logów jakąś informację dobrze jest zachować pewne powiązanie pomiędzy następującymi po sobie czynnościami.
Dobrym przykładem takiej sytuacji jest np. wywoływanie ApplicationEvent, wysyłanie maila, czy właściwie jakikolwiek proces składający się z więcej niż 1 kroku. Po co? A no po to, aby potem w pliku z logami móc wyfiltrować tylko te informacje które nas faktycznie interesują. Szczególnie w środowisku wielowątkowym (czyli właściwie… zawsze?) bez tego ciężko jest dojść OCB
Do tej pory podchodziłem do tego w sposób bardzo banalny: tworzyłem Guida i doklejałem go do każdej informacji zapisywanej do loga. Przykład kodu, który rzuci trochę światła na to moje intencje:
1: Guid token = Guid.NewGuid(); 2: _log.Debug("{0} Raising event {1}", token, @event.GetType().Name); 3: foreach (var handler in allHandlers) 4: { 5: _log.Trace("{0} Handling event {1} with handler {2}...", token, @event.GetType().Name, handler.GetType().Name); 6: handler.Handle(@event); 7: _log.Trace("{0} Successfully handled event {1} with handler {2}...", token, @event.GetType().Name, handler.GetType().Name); 8: } 9: _log.Trace("{0} Finished raising event {1}", token, @event.GetType().Name);
Z czasem przy jednym projekcie pojawiła się jednak myśl, że fajnie byłoby to uprościć. Szczególnie mile widziane byłoby choćby usunięcie tego durnego {0} przed każdą wiadomością. I narodził się pomysł klasy TokenContext.
Zastosowałem tutaj TDD, żeby mi samemu poukładało się w głowie czego tak naprawdę potrzebuję. Efektem kilkunastu minut zastanowienia jest ten zestaw testów:
1: private static readonly int _guidLength = Guid.NewGuid().ToString().Length; 2: 3: [Fact] 4: public void prepends_generated_strings_with_guid() 5: { 6: string str = Randomizer.String(); 7: 8: var ctx = new TokenContext(); 9: 10: string result = ctx.Tokenize(str); 11: 12: int guidLength = _guidLength; 13: 14: Assert.Equal('[', result[0]); 15: 16: string token = result.Substring(1, guidLength); 17: Assert.DoesNotThrow(() => Guid.Parse(token)); 18: 19: Assert.Equal(']', result[guidLength + 1]); 20: Assert.Equal(' ', result[guidLength + 2]); 21: 22: string afterToken = result.Substring(guidLength + 3); 23: Assert.Equal(str, afterToken); 24: } 25: 26: [Fact] 27: public void one_instance_uses_one_guid_for_all_strings() 28: { 29: string str1 = Randomizer.String(); 30: string str2 = Randomizer.String(); 31: 32: var ctx = new TokenContext(); 33: 34: string result1 = ctx.Tokenize(str1); 35: string result2 = ctx.Tokenize(str2); 36: string result3 = ctx.Tokenize(str2); 37: 38: Guid token1 = Guid.Parse(result1.Substring(1, _guidLength)); 39: Guid token2 = Guid.Parse(result1.Substring(1, _guidLength)); 40: 41: Assert.Equal(token1, token2); 42: 43: Assert.Equal(result2, result3); 44: } 45: 46: [Theory] 47: [InlineData(null)] 48: [InlineData("")] 49: public void returns_only_tokens_for_empty_and_nulls(string p) 50: { 51: var ctx = new TokenContext(); 52: string result = ctx.Tokenize(p); 53: 54: Assert.Equal('[', result[0]); 55: Assert.DoesNotThrow(() => Guid.Parse(result.Substring(1, _guidLength))); 56: Assert.Equal(']', result[result.Length - 2]); 57: Assert.Equal(' ', result[result.Length - 1]); 58: } 59: 60: [Fact] 61: public void does_not_break_strings_that_contain_format_placeholders() 62: { 63: var ctx = new TokenContext(); 64: 65: string formatInput = "abc {0}def {1} xyz"; 66: 67: string result = ctx.Tokenize(formatInput).FormatWith("11", "22"); 68: 69: Assert.Equal("abc 11def 22 xyz", result.Substring(3 + _guidLength)); 70: }
W sumie chodzi o prostą rzecz – doklejenie stałego guida otoczonego nawiasami z przodu stringa.
Napisanie samej klasy było kwestią chwili:
1: /// <summary> 2: /// Prepends a group of strings with a guid, making it easier to track some context in logs. 3: /// </summary> 4: public class TokenContext 5: { 6: private readonly string _token; 7: 8: public TokenContext() 9: { 10: _token = Guid.NewGuid().ToString(); 11: } 12: 13: public string Tokenize(string input) 14: { 15: return "[{0}] {1}".FormatWith(_token, input); 16: } 17: }
Mogłem teraz darować sobie ręczne tworzenie guida i ręczne doklejanie go do stringa:
1: var ctx = new TokenContext(); 2: _log.Debug(ctx.Tokenize("Raising event {0}"), @event.GetType().Name);
Wszystko fajnie, ale… wpadłem na pomysł dodatkowego "uładnienia" (osobista preferencja) tego kodu. Zdefiniowałem extension method takiej postaci:
1: public static class TokenContextExtensions 2: { 3: public static string ken(this TokenContext @this, string input) 4: { 5: return @this.Tokenize(input); 6: } 7: }
Zapytać można: "po co???"
Odpowiedź jest prosta… po to:
1: var to = new TokenContext(); 2: _log.Debug(to.ken("Raising event {0}"), @event.GetType().Name);
Moim zdaniem całkiem sprytne, choć zdaję sobie sprawę że nie każdemu może to odpowiadać.
Tak czy siak sam mechanizm cały czas okazuje się dość przydatny.
Można pokusić się o rozwinięcie tej koncepcji o kolejne informacje, jak np. mierzenie czasu pomiędzy logowaniami, co nie powinno raczej nikomu sprawić trudności.
