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.
Czytam Twój log już od dosyć dawna, do tej pory nie zabierałem jednak głosu. Ciekawe informacje tu znajduję, część udaje mi się wykorzystywać w życiu zawodowym. Dzięki.
Jeśli zaś chodzi o Twój post. Nie jestem pewien, czy dobrze zrozumiałem Twoje intencje dodawania Guid-a do każej logowanej informacji. Chodzi o grupowanie wpisów loga w środowisku wielowątkowym?
Osobiście używam log4net. Można konfigurować jakie informacje mają być logowane. Między innymi id wątku, nazwa loggera (u mnie to zawsze nazwa klasy z której następuje logowanie).
@Jacek:
Zachęcam zatem do dalszego komentowania:).
Ja używam log4net w jednym projekcie i nLog w pozostałych (polecam!). Także korzystam z nazwy klasy jako nazwy loggera. Jednak to nie wystarcza – te same informacje mogą pojawić się jednocześnie z kilku wątków. Masz rację, można logowanie nr wątku, jednak to dla mnie również za mało. Chcę:
1) znaleźć w logu interesująca mnie informację
2) skopiować guid zawarty na początku loga
3) wyfiltrować z plików logów wszystkie wpisy z tym guidem
4) prześledzić tok wykonywana kilkukrokowej operacji
Para [nazwa klasy trzymającej loggera + nr wątku] nie tworzy unikalnej kombinacji, prędzej czy później ten sam wątek wykona tą operację ponownie. Z kolei GUID mi to gwarantuje.
Ja zaś nie rozumiem po co utworzyłeś extension method. Ze względów estetycznych (nazwa obiektu oraz metody tworzy logiczną całość)?
@Łukasz K:
Tak. Dodatkowo jest to krótsze niż standardowe wywołanie metody. Chciałem w poście bonusowo przemycić przykład takiego zastosowania ext methods:). Bo na zwykłą metodę w obiekcie to się na pewno nie nadaje.
1. Nigdy nie wpadłem na pomysł napisania extension method do swojej klasy. I nie czuję się przekonany, że to dobry pomysł.
2. Czym przeszukujesz logi? Masz coś ciekawego pod ręką?
Artur
@Artur:
Takiego śmiecia jak metoda "ken()" dorzucać do klasy to bezeceństwo:)
A logi przeglądam zwykle notepad2, czasami Kiwi lub baregrep.