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

39

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)?

l0b0
źródło
54
Zamiast tego użyj śladów stosu. Śledzenie stosu nie tylko powie dokładnie, gdzie wystąpił błąd, ale także każdą funkcję, która wywołała każdą funkcję, która ją wywołała. W razie potrzeby zarejestruj cały ślad po wystąpieniu wyjątku. Jeśli pracujesz w języku, który nie ma wyjątków, takim jak C, to inna historia.
Robert Harvey
6
@ l0b0 mała rada na temat sformułowań. „co myśli ta społeczność… plusy i minusy” to frazy, które mogą być postrzegane jako zbyt szerokie. To jest strona, która pozwala na „dobre subiektywne” pytania, aw zamian za dopuszczenie do tego rodzaju pytań, ty, jako OP, oczekujesz, że wykonasz pracę „pasterstwa” komentarzy i odpowiedzi w kierunku znaczącego konsensusu.
rwong
@rwong Dziękujemy! Wydaje mi się, że pytanie otrzymało już bardzo dobrą i szybką odpowiedź, chociaż lepiej zadać to pytanie na forum. Cofnąłem swoją odpowiedź na komentarz Roberta Harvey po przeczytaniu wyjaśniającej odpowiedzi JohnWu, na wypadek, gdyby o to ci chodziło. Jeśli nie, czy masz jakieś konkretne wskazówki dla pasterzy?
l0b0
1
Moje wiadomości wyglądają jak „Nie można znaleźć Foo podczas połączenia z bar ()”. Problem rozwiązany. Wzruszać ramionami. Minusem jest to, że klienci są trochę nieszczelni, ale i tak zwykle ukrywamy przed nimi szczegóły komunikatów o błędach, udostępniając je tylko administratorom, którzy nie mogli dać małpom dostępu do niektórych nazw funkcji. Jeśli tak się nie stanie, tak, wystarczy mały, niepowtarzalny identyfikator / kod.
Wyścigi lekkości z Moniką
1
Jest to BARDZO przydatne, gdy klient dzwoni do Ciebie, a jego komputer nie działa w języku angielskim! Znacznie mniejszy problem w dzisiejszych czasach, ponieważ mamy teraz wiadomości e-mail i pliki dziennika .....
Ian

Odpowiedzi:

12

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.
rwong
źródło
1
Rzeczywiście, AOP reklamował przede wszystkim swoją nieodłączną zdolność rozwiązania tego problemu - dodając Tracer do każdego odpowiedniego połączenia - przy minimalnej inwazji na bazę kodu.
biskup
Dodałbym również do listy „pisania dzienników”, że ważne jest scharakteryzowanie niepowodzenia pod względem „dlaczego” i „jak naprawić” zamiast po prostu „co”.
biskup
58

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

John Wu
źródło
32
Hmm, chyba nie wyraziłem się jasno. Wiem, że są wyjątkowymi Robertami - według lokalizacji kodu . Nie są one unikalne dla każdej ścieżki kodu . Znajomość lokalizacji jest często bezużyteczna, np. Jeśli prawdziwym problemem jest to, że dane wejściowe nie zostały ustawione poprawnie. Lekko zredagowałem swój język, aby podkreślić.
John Wu
1
Dobre punkty, oboje. Istnieje inny problem ze śladami stosu, który może, ale nie musi, przerywać transakcje w zależności od sytuacji: ich rozmiar może spowodować, że zamieniają komunikaty, szczególnie jeśli chcesz dołączyć cały ślad stosu, a nie skróconą wersję, jak niektóre języki zrobić domyślnie. Być może alternatywą byłoby osobne zapisanie dziennika śledzenia stosu i dołączenie numerowanych indeksów do tego dziennika w danych wyjściowych aplikacji.
l0b0
12
Jeśli dostajesz ich tak wiele, że martwisz się zalaniem I / O, coś jest naprawdę nie tak. A może po prostu jesteś skąpy? Prawdziwym hitem wydajności jest prawdopodobnie rozwój stosu.
John Wu
9
Edytowane z rozwiązaniem skracania śladów stosu, na wypadek, gdy piszesz logi na dyskietce 3.5;)
John Wu
7
@JohnWu I nie zapomnij także o „IOException„ Nie znaleziono pliku ”w [...]”, który mówi o około pięćdziesięciu warstwach stosu wywołań, ale nie mówi, jaki dokładnie cholerny plik nie został znaleziony.
Joker_vD
6

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:

błąd 1

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

błąd 2

Znajdź w bazie kodu:

błąd 3

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ź.

Philipp
źródło
Katalogi komunikatów są również częścią GNU / Linux - i UNIX ogólnie jako standard POSIX - od pewnego czasu.
biskup
@bishop Zwykle nie programuję specjalnie dla systemów POSIX, więc nie jestem z tym zaznajomiony. Może możesz napisać inną odpowiedź, która wyjaśnia katalogi komunikatów POSIX i czego OP może się nauczyć z ich implementacji.
Philipp
3
Byłem częścią projektu, który zrobił to w latach 90-tych. Jednym z problemów, na które natrafiliśmy, było to, że wraz ze wszystkim innym umieściliśmy ludzki komunikat „nie można połączyć się z bazą danych” w bazie danych.
JimmyJames
5

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ę”

Ewan
źródło
Umieszczanie poufnych danych w kolejce wciąż je rejestruje. Nie jest to zalecane, podobnie jak przechowywanie wrażliwych danych wejściowych w DB bez jakiejś formy kryptografii.
jpmc26
jeśli w systemie są uruchamiane kolejki lub baza danych, dane już tam są, podobnie jak zabezpieczenia. Zbyt częste rejestrowanie jest złe tylko dlatego, że dziennik zwykle wykracza poza kontrolę bezpieczeństwa.
Ewan
Racja, ale o to chodzi. Nie zaleca się, ponieważ dane pozostają tam na stałe i zwykle w postaci całkowicie czytelnego tekstu. W przypadku wrażliwych danych lepiej po prostu nie ryzykować i zminimalizować miejsce przechowywania okresu, a następnie być bardzo świadomym i bardzo ostrożnym, jak je przechowujesz.
jpmc26
Jest to tradycyjnie trwałe, ponieważ piszesz do pliku. Ale kolejka błędów jest przejściowa.
Ewan
Powiedziałbym, że prawdopodobnie zależy to od implementacji (a być może nawet ustawień) kolejki. Nie możesz po prostu zrzucić go w kolejce i oczekiwać, że będzie bezpieczny. Co dzieje się po zużyciu kolejki? Dzienniki muszą wciąż być gdzieś, aby ktoś mógł je zobaczyć. Ponadto nie jest to dodatkowy wektor ataku, który chciałbym otworzyć nawet tymczasowo. Jeśli atak odkryje, że przechodzą tam poufne dane, nawet najnowsze wpisy mogą być cenne. Istnieje także ryzyko, że ktoś nie będzie wiedział i nie przerzuci przełącznika, aby również zaczął się logować na dysk. To tylko puszka robaków.
jpmc26
1

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.

Paddy
źródło
0

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.

Berin Loritsch
źródło