Umożliwienie znalezienia kodu przy użyciu unikatowych globalnie identyfikatorów wiadomości

Wspólny wzorzec lokalizowania błędu wynika z tego skryptu:

1. Obserwuj dziwność, na przykład brak wyjścia lub zawieszający się program.
2. Znajdź odpowiedni komunikat w wynikach dziennika lub programu, na przykład „Nie można znaleźć Foo”. (Poniższe informacje mają znaczenie tylko wtedy, gdy jest to ścieżka podana w celu zlokalizowania błędu. Jeśli ślad stosu lub inne informacje debugowania są łatwo dostępne, to inna historia).
3. Znajdź kod, w którym wiadomość jest drukowana.
4. Debuguj kod między pierwszym miejscem, w którym Foo wchodzi (lub powinien wejść) na zdjęcie, a miejscem, w którym wiadomość jest drukowana.

Na trzecim etapie proces debugowania często zatrzymuje się, ponieważ w kodzie jest wiele miejsc, w których Could not find {name}drukowane jest „Could not find Foo” (lub ciąg szablonów ). W rzeczywistości kilkakrotnie błąd pisowni pomógł mi znaleźć rzeczywistą lokalizację znacznie szybciej niż w innym przypadku - sprawił, że komunikat był unikalny w całym systemie i często na całym świecie, co spowodowało natychmiastowe trafienie w odpowiednią wyszukiwarkę.

Oczywistym wnioskiem z tego jest to, że powinniśmy używać globalnie unikatowych identyfikatorów wiadomości w kodzie, kodować na stałe jako część ciągu wiadomości i być może weryfikować, czy w bazie kodu występuje tylko jedno wystąpienie każdego identyfikatora. Jeśli chodzi o łatwość konserwacji, co zdaniem tej społeczności są najważniejsze zalety i wady tego podejścia i jak byś to wdrożył lub w inny sposób zapewniłby, że jego wdrożenie nigdy nie będzie konieczne (zakładając, że oprogramowanie będzie zawsze zawierało błędy)?

Ogólnie jest to ważna i cenna strategia. Oto kilka myśli.

Strategia ta znana jest również jako „telemetria” w tym sensie, że kiedy wszystkie takie informacje są połączone, pomagają „triangulować” ślad wykonania i pozwalają narzędziu do rozwiązywania problemów zrozumieć, co użytkownik / aplikacja próbuje osiągnąć i co faktycznie się wydarzyło .

Niektóre niezbędne dane, które należy zgromadzić (które wszyscy znamy) to:

• Lokalizacja kodu, tj. Stos wywołań i przybliżona linia kodu
  • „Przybliżona linia kodu” nie jest potrzebna, jeśli funkcje są rozsądnie rozłożone na odpowiednio małe jednostki.
• Wszelkie fragmenty danych odnoszące się do powodzenia / niepowodzenia funkcji
• „Komenda” wysokiego poziomu, która może ustalić, co próbuje osiągnąć użytkownik / agent zewnętrzny / użytkownik interfejsu API.
  • Chodzi o to, że oprogramowanie akceptuje i przetwarza polecenia pochodzące skądś.
  • Podczas tego procesu mogły mieć miejsce dziesiątki do setek tysięcy wywołań funkcji.
  • Chcielibyśmy, aby wszelkie dane telemetryczne generowane w tym procesie były identyfikowalne z powrotem do polecenia najwyższego poziomu, które uruchamia ten proces.
  • W przypadku systemów internetowych oryginalne żądanie HTTP i jego dane byłyby przykładem takich „informacji o żądaniach wysokiego poziomu”
  • W przypadku systemów GUI użytkownik klikający na coś pasowałby do tego opisu.

Często tradycyjne metody rejestrowania są niewystarczające, ponieważ nie można prześledzić komunikatu dziennika niskiego poziomu z powrotem do polecenia najwyższego poziomu, które je uruchamia. Śledzenie stosu przechwytuje tylko nazwy funkcji wyższego rzędu, które pomogły obsłużyć polecenie najwyższego poziomu, a nie szczegóły (dane), które czasami są potrzebne do scharakteryzowania tego polecenia.

Zwykle oprogramowanie nie zostało napisane w celu wdrożenia tego rodzaju wymagań dotyczących identyfikowalności. Utrudnia to korelowanie komunikatu niskiego poziomu z poleceniem wysokiego poziomu. Problem jest szczególnie poważny w swobodnie wielowątkowych systemach, w których wiele żądań i odpowiedzi może się nakładać, a przetwarzanie może zostać przeniesione do innego wątku niż pierwotny wątek odbierający żądania.

Dlatego, aby uzyskać jak największą wartość z telemetrii, potrzebne będą zmiany w ogólnej architekturze oprogramowania. Większość interfejsów i wywołań funkcji będzie musiała zostać zmodyfikowana, aby zaakceptować i propagować argument „tracer”.

Nawet funkcje narzędziowe będą musiały dodać argument „tracer”, tak że jeśli się nie powiedzie, komunikat dziennika pozwoli na korelację z pewną komendą wysokiego poziomu.

Innym błędem, który utrudni śledzenie telemetrii, jest brak odniesień do obiektu (zerowe wskaźniki lub odniesienia). Gdy brakuje jakiegoś ważnego elementu danych, niemożliwe może być zgłoszenie czegoś przydatnego w przypadku awarii.

W zakresie pisania komunikatów do dziennika:

• Niektóre projekty oprogramowania mogą wymagać lokalizacji (tłumaczenia na język obcy), nawet w przypadku komunikatów dziennika przeznaczonych wyłącznie dla administratorów.
• Niektóre projekty oprogramowania mogą wymagać wyraźnego rozdziału między danymi wrażliwymi a danymi niewrażliwymi, nawet do celów logowania, a administratorzy nie mieliby szansy przypadkowo zobaczyć niektóre dane wrażliwe.
• Nie próbuj zaciemniać komunikatu o błędzie. Podważyłoby to zaufanie klientów. Administratorzy klientów oczekują odczytania tych dzienników i ich zrozumienia. Nie pozwól im poczuć, że istnieje jakiś zastrzeżony sekret, który należy ukryć przed administratorami klientów.
• Nie spodziewaj się, że klienci przyniosą kawałek dziennika telemetrycznego i grillują twoich pracowników pomocy technicznej. Oczekują wiedzieć. Przeszkol swój personel pomocy technicznej, aby poprawnie wyjaśniał dziennik telemetrii.

Wyobraź sobie, że masz trywialną funkcję narzędzia, która jest używana w setkach miejsc w kodzie:

decimal Inverse(decimal input)
{
    return 1 / input;
}

Gdybyśmy zrobili tak, jak sugerujesz, moglibyśmy napisać

decimal Inverse(decimal input)
{
    try 
    {
        return 1 / input;
    }
    catch(Exception ex)
    {
        log.Write("Error 27349262 occurred.");
    }
}

Błąd, który może wystąpić, to jeśli wejście miałoby zero; spowodowałoby to podzielenie przez zero wyjątku.

Powiedzmy, że widzisz 27349262 w danych wyjściowych lub dziennikach. Gdzie szukasz kodu, który przekroczył zerową wartość? Pamiętaj, że funkcja - z unikalnym identyfikatorem - jest używana w setkach miejsc. Więc chociaż możesz wiedzieć, że nastąpił podział przez zero, nie masz pojęcia, kto 0to jest.

Wydaje mi się, że jeśli masz kłopot z rejestrowaniem identyfikatorów wiadomości, równie dobrze możesz zarejestrować ślad stosu.

Jeśli przeszkadza Ci gadatliwość śladu stosu, nie musisz zrzucać go jako ciągu w sposób, w jaki przekazuje ci go środowisko wykonawcze. Możesz to dostosować. Na przykład, jeśli chcesz, aby skrót stosu przechodził tylko do npoziomów, możesz napisać coś takiego (jeśli używasz c #):

static class ExtensionMethods
{
    public static string LimitedStackTrace(this Exception input, int layers)
    {
        return string.Join
        (
            ">",
            new StackTrace(input)
                .GetFrames()
                .Take(layers)
                .Select
                (
                    f => f.GetMethod()
                )
                .Select
                (
                    m => string.Format
                    (
                        "{0}.{1}", 
                        m.DeclaringType, 
                        m.Name
                    )
                )
                .Reverse()
        );
    }
}

I użyj tego w ten sposób:

public class Haystack
{
    public static void Needle()
    {
        throw new Exception("ZOMG WHERE DID I GO WRONG???!");
    }

    private static void Test()
    {
        Needle();
    }

    public static void Main()
    {
        try
        {
            Test();
        }
        catch(System.Exception e)
        {
            //Get 3 levels of stack trace
            Console.WriteLine
            (
                "Error '{0}' at {1}", 
                e.Message, 
                e.LimitedStackTrace(3)
            );  
        }
    }
}

Wynik:

Error 'ZOMG WHERE DID I GO WRONG???!' at Haystack.Main>Haystack.Test>Haystack.Needle

Może łatwiejsze niż utrzymywanie identyfikatorów wiadomości i bardziej elastyczne.

Kradnij mój kod z DotNetFiddle

SAP NetWeaver robi to od dziesięcioleci.

Okazało się, że jest cennym narzędziem podczas rozwiązywania problemów z błędami ogromnego kodu, który jest typowym systemem SAP ERP.

Komunikaty o błędach są zarządzane w centralnym repozytorium, w którym każdy komunikat jest identyfikowany przez klasę i numer komunikatu.

Gdy chcesz wysyłać komunikat o błędzie, podajesz tylko zmienne dotyczące klasy, liczby, istotności i specyficzne dla komunikatu. Tekstowa reprezentacja wiadomości jest tworzona w czasie wykonywania. Zazwyczaj klasa i numer wiadomości są widoczne w dowolnym kontekście, w którym pojawiają się wiadomości. Ma to kilka fajnych efektów:

• Możesz automatycznie znaleźć dowolne wiersze kodu w bazie kodów ABAP, które tworzą określony komunikat o błędzie.

• Można ustawić dynamiczne punkty przerwania debugowania, które będą wyzwalane po wygenerowaniu określonego komunikatu o błędzie.

• Możesz wyszukiwać błędy w artykułach z bazy wiedzy SAP i uzyskiwać trafniejsze wyniki wyszukiwania niż w przypadku „Nie można znaleźć Foo”.

• Tekstowe reprezentacje wiadomości można przetłumaczyć. Zachęcając do używania komunikatów zamiast ciągów, zyskujesz także możliwości i18n.

Przykład wyskakującego błędu z numerem komunikatu:

Wyszukiwanie tego błędu w repozytorium błędów:

Znajdź w bazie kodu:

Istnieją jednak wady. Jak widać, te wiersze kodu nie są już samo-dokumentujące. Kiedy czytasz kod źródłowy i widzisz MESSAGEzdanie takie jak na powyższym zrzucie ekranu, możesz wywnioskować z kontekstu, co to właściwie oznacza. Czasami ludzie implementują niestandardowe programy obsługi błędów, które odbierają klasę i numer komunikatu w czasie wykonywania. W takim przypadku błędu nie można znaleźć automatycznie lub nie można go znaleźć w miejscu, w którym błąd rzeczywiście wystąpił. Obejściem pierwszego problemu jest nawyk, aby zawsze dodawać komentarz w kodzie źródłowym informujący czytelnika, co oznacza komunikat. Drugi problem został rozwiązany przez dodanie martwego kodu, aby upewnić się, że automatyczne wyszukiwanie wiadomości działa. Przykład:

" Do not use special characters
my_custom_error_handler->post_error( class = 'EU' number = '271').
IF 1 = 2.
   MESSAGE e271(eu).
ENDIF.    

Ale są sytuacje, w których nie jest to możliwe. Istnieją na przykład niektóre narzędzia do modelowania procesów biznesowych oparte na interfejsie użytkownika, w których można skonfigurować komunikaty o błędach, aby pojawiały się w przypadku naruszenia reguł biznesowych. Implementacja tych narzędzi jest całkowicie oparta na danych, więc te błędy nie pojawią się na liście używanych. Oznacza to, że zbyt wiele polegając na liście używanych, gdy próbujesz znaleźć przyczynę błędu, może być czerwony śledź.

Problem z tym podejściem polega na tym, że prowadzi do coraz bardziej szczegółowego rejestrowania. 99,9999%, z których nigdy nie będziesz oglądać.

Zamiast tego zalecam uchwycenie stanu na początku procesu i powodzenie / niepowodzenie procesu.

Pozwala to na lokalne odtworzenie błędu, przejście przez kod i ogranicza rejestrowanie do dwóch miejsc na proces. na przykład.

OrderPlaced {id:xyz; ...order data..}
OrderPlaced {id:xyz; ...Fail, ErrorMessage..}

Teraz mogę użyć dokładnie tego samego stanu na mojej maszynie deweloperskiej do odtworzenia błędu, przejścia przez kod w moim debuggerze i napisania nowego testu jednostkowego w celu potwierdzenia poprawki.

Ponadto w razie potrzeby mogę uniknąć rejestrowania, rejestrując tylko błędy rejestrowania lub utrzymując stan w innym miejscu (baza danych? Kolejka komunikatów?)

Oczywiście musimy zachować szczególną ostrożność przy logowaniu poufnych danych. Działa to szczególnie dobrze, jeśli twoje rozwiązanie używa kolejek komunikatów lub wzorca magazynu zdarzeń. Ponieważ dziennik musi tylko powiedzieć „Komunikat xyz nie powiódł się”

Sugerowałbym, że rejestrowanie nie jest sposobem, aby to zrobić, ale raczej, że ta okoliczność jest uważana za wyjątkową (blokuje twój program) i powinien zostać zgłoszony wyjątek. Powiedz, że Twój kod to:

public Foo GetFoo() {

     //Expecting that this should never by null.
     var aFoo = ....;

     if (aFoo == null) Log("Could not find Foo.");

     return aFoo;
}

Wygląda na to, że Twój kod nie jest skonfigurowany do radzenia sobie z faktem, że Foo nie istnieje i możesz potencjalnie być:

public Foo GetFooById(int id) {
     var aFoo = ....;

     if (aFoo == null) throw new ApplicationException("Could not find Foo for ID: " + id);

     return aFoo;
}

Zwróci to ślad stosu wraz z wyjątkiem, którego można użyć do pomocy w debugowaniu.

Alternatywnie, jeśli oczekujemy, że Foo może być zerowy po odzyskaniu i jest w porządku, musimy naprawić strony wywołujące:

void DoSomeFoo(Foo aFoo) {

    //Guard checks on your input - complete with stack trace!
    if (aFoo == null) throw new ArgumentNullException(nameof(aFoo));

    ... operations on Foo...
}

Fakt, że twoje oprogramowanie zawiesza się lub działa „dziwnie” w nieoczekiwanych okolicznościach, wydaje mi się niewłaściwy - jeśli potrzebujesz Foo i nie możesz sobie z nim poradzić, to nie jest tak, że lepiej jest zawiesić się niż próbować iść ścieżką, która może uszkodzić twój system.

Właściwe biblioteki rejestrujące zapewniają mechanizmy rozszerzenia, więc jeśli chcesz poznać metodę, z której pochodzi komunikat dziennika, mogą to zrobić od razu po wyjęciu z pudełka. Ma to wpływ na wykonanie, ponieważ proces wymaga wygenerowania śladu stosu i przejścia go do momentu wyjścia z biblioteki rejestrowania.

To powiedziawszy, to naprawdę zależy od tego, co chcesz zrobić dla Ciebie:

• Czy powiązać komunikaty o błędach przekazywane użytkownikowi z dziennikami?
• Podaj notację o tym, jaki kod był wykonywany podczas generowania wiadomości?
• Śledzić nazwę komputera i wystąpienie usługi?
• Śledzić identyfikator wątku?

Wszystkie te czynności można wykonać natychmiast po wyjęciu z pudełka za pomocą odpowiedniego oprogramowania rejestrującego (tj. Nie Console.WriteLine()lub Debug.WriteLine()).

Osobiście ważniejsza jest zdolność do rekonstrukcji ścieżek wykonania. Właśnie do tego służą narzędzia takie jak Zipkin . Jeden identyfikator do śledzenia zachowania jednej akcji użytkownika w całym systemie. Umieszczając swoje dzienniki w centralnej wyszukiwarce, możesz nie tylko znaleźć najdłużej działające akcje, ale także wywołać dzienniki, które dotyczą tej jednej akcji (np. Stosu ELK ).

Nieprzezroczyste identyfikatory zmieniające się przy każdej wiadomości nie są zbyt przydatne. Spójny identyfikator używany do śledzenia zachowania w całym pakiecie mikrousług ... niezwykle użyteczny.