NullPointerException w Javie bez StackTrace

333

Miałem instancje naszego kodu Java catch a NullPointerException, ale kiedy próbuję zalogować StackTrace (który w zasadzie kończy się wywołaniem Throwable.printStackTrace()), otrzymuję tylko:

java.lang.NullPointerException

Czy ktoś jeszcze to spotkał? Próbowałem google dla „java null wskaźnik pusty stos śledzenia”, ale nie natrafiłem na coś takiego.

Edward Shtern
źródło
Jaki jest kontekst? Czy w grę wchodzi wiele wątków? Mam problemy z uzyskaniem śladu stosu wyjątku w SwingWorker.
Michael Myers
Nie dotyczy to wątków, po prostu stara Java.
Edward Shtern,
1
@Bozho - nope - jeszcze nie wiem, jak odtworzyć NullPointer.
Edward Shtern,
1
powiązane: stackoverflow.com/questions/1076191/…
Joshua Goldberg
Więcej informacji na -XX:-OmitStackTraceInFastThrowdupie: stackoverflow.com/questions/4659151/…
Vadzim

Odpowiedzi:

407

Prawdopodobnie używasz HotSpot JVM (pierwotnie Sun Sunystems, później kupiony przez Oracle, część OpenJDK), który wykonuje wiele optymalizacji. Aby odzyskać ślady stosu, musisz przekazać opcję -XX:-OmitStackTraceInFastThrowdo JVM.

Optymalizacja polega na tym, że gdy wyjątek (zwykle NullPointerException) pojawia się po raz pierwszy, drukowany jest ślad pełnego stosu, a JVM zapamiętuje ślad stosu (a może po prostu lokalizację kodu). Gdy ten wyjątek występuje wystarczająco często, ślad stosu nie jest już drukowany, zarówno w celu uzyskania lepszej wydajności, jak i nie zalewania dziennika identycznymi śladami stosu.

Aby zobaczyć, jak jest to zaimplementowane w maszynie JVM HotSpot, pobierz jego kopię i wyszukaj zmienną globalną OmitStackTraceInFastThrow. Ostatnim razem, gdy patrzyłem na kod (w 2019 r.), Był on w pliku graphKit.cpp .

Roland Illig
źródło
1
Dzięki za wskazówkę. Masz pomysł, czy istnieją jakieś ukryte problemy z przekazaniem tej opcji (wydaje się to dość niewinne, o ile moja aplikacja nie rzuca mnóstwa wyjątków)?
Edward Shtern,
Nie znam ukrytych gotch, o których wiem. Gdy spojrzysz na kod źródłowy Hotspot, zobaczysz, że ta opcja jest używana tylko w jednym miejscu (graphKit.cpp). I dla mnie to wygląda dobrze.
Roland Illig,
34
Pomyślałem, że dodam dodatkową informację, że kiedy śledzenie stosu zostanie zoptymalizowane, to dlatego, że przynajmniej raz zostało w pełni obsłużone: jawspeak.com/2010/05/26/...
sharakan
1
Korzystam z JVM OpenJDK w wersji 1.8.0u171 (Debian 9) i wydaje się, że akceptuje także -XX:-OmitStackTraceInFastThrowflagę. Muszę jeszcze potwierdzić, czy właśnie dlatego nie udało mi się również wydrukować śladów stosu (np. Przy użyciu e.printStackTrace), ale wydaje się to bardzo prawdopodobne. Rozszerzyłem odpowiedź, aby odzwierciedlić to odkrycie.
Chris W.,
W naszym przypadku pierwsze 125 wyjątków miało ślad stosu, a następnie pozostałe w 3 rotacjach plików dziennika nie miały żadnego. Ta odpowiedź była bardzo pomocna w znalezieniu sprawcy.
sukhmel
61

Jak wspomniałeś w komentarzu, używasz log4j. Odkryłem (mimowolnie) miejsce, w którym napisałem

LOG.error(exc);

zamiast typowego

LOG.error("Some informative message", e);

przez lenistwo lub może po prostu o tym nie myśląc. Niefortunne jest to, że nie zachowuje się tak, jak się spodziewasz. Interfejs API programu rejestrującego faktycznie przyjmuje Object jako pierwszy argument, a nie ciąg znaków - a następnie wywołuje metodę argumentString (). Zamiast więc ładnego śladu ładnego stosu, po prostu drukuje toString - co w przypadku NPE jest dość bezużyteczne.

Być może właśnie tego doświadczasz?

Steven Schlansker
źródło
+1: To wyjaśniałoby opisane zachowanie i nie tylko ty to odkryłeś :)
Peter Lang
4
W rzeczywistości mamy standardową zasadę, aby nigdy nie używać pierwszego formularza powyżej (LOG.error (exc);) - zawsze używamy sygnatury 2 parametrów, aby dodawać do dzienników opisową instrukcję zamiast zwykłego śledzenia stosu.
Edward Shtern,
5
Jasne, ale polityka nie oznacza, że ​​zawsze jest wykonywana poprawnie! Pomyślałem, że przynajmniej warto o tym wspomnieć.
Steven Schlansker,
To prawda, ale w tym przypadku tak było ;-)
Edward Shtern,
28

Widzieliśmy to samo zachowanie w przeszłości. Okazało się, że z jakiegoś szalonego powodu, jeśli NullPointerException wystąpił wielokrotnie w tym samym miejscu w kodzie, po pewnym czasie za pomocąLog.error(String, Throwable) przestałoby zawierać ślady pełnego stosu.

Spróbuj spojrzeć wstecz na swój dziennik. Możesz znaleźć winowajcę.

EDYCJA: ten błąd wydaje się istotny, ale został naprawiony tak dawno temu, prawdopodobnie nie jest to przyczyną.

Matt Solnit
źródło
2
Błąd jest zamknięty, ale flaga -XX: -OmitStackTraceInFastThrow jest nadal potrzebna do obejścia optymalizacji wydajności.
Joshua Goldberg
Ostatnio dużo to widziałem. Wszelkie wskazówki, co może być tego przyczyną lub jak to naprawić? System rejestrowania mógł działać od wielu dni, a faktyczna przyczyna się skończyła, nie trzeba jednak żmudnych poszukiwań ...
Paweł Veselov,
5
Pawel, czy próbowałeś -XX:-OmitStackTraceInFastThrowflagi JVM zasugerowanej przez Jozuego? Zobacz także stackoverflow.com/a/2070568/6198 .
Matt Solnit,
1
To było dla nas. Dzięki.
Andrew Cheong,
20

Oto wyjaśnienie: Hotspot spowodował, że wyjątki utraciły ślady stosu w produkcji - i poprawkę

Przetestowałem to na Mac OS X.

  • wersja Java „1.6.0_26”
  • Środowisko wykonawcze Java (TM) SE (kompilacja 1.6.0_26-b03-383-11A511)
  • 64-bitowa maszyna wirtualna serwera Java HotSpot ™ (wersja 20.1-b02-383, tryb mieszany)

    Object string = "abcd";
    int i = 0;
    while (i < 12289) {
        i++;
        try {
            Integer a = (Integer) string;
        } catch (Exception e) {
            e.printStackTrace();
        }
    }

W przypadku tego konkretnego fragmentu kodu wydaje się, że 12288 iteracji (+ częstotliwość?) Jest limitem, w którym JVM zdecydowało się na użycie wstępnie przydzielonego wyjątku ...

Benoît Guérout
źródło
10

exception.toString nie daje ci StackTrace, tylko zwraca

krótki opis tego rzutu. Rezultatem jest konkatenacja:

* the name of the class of this object
* ": " (a colon and a space)
* the result of invoking this object's getLocalizedMessage() method

exception.printStackTraceZamiast tego użyj polecenia OutputTrace.

Peter Lang
źródło
Przepraszam, pomyliłem się w swoim oryginalnym poście. Rejestruję je za pomocą Log4J, który korzysta z printStackTrace ().
Edward Shtern,
1
Czy próbowałeś użyć, getStackTrace()aby upewnić się, że problem nie dotyczy Twojego programu rejestrującego?
Peter Lang,
1
Jeśli używasz log4j, pamiętaj, aby wysłać wyjątek jako część argumentu do metody log. Prześlę odpowiedź z tym.
Ravi Wallau,
@raviaw ważny punkt! @ Edward Shtern: czy możesz potwierdzić, że zdecydowanie używasz 2-argumentowej formy metody log4j? Wiem, że wspomniałeś w dalszej odpowiedzi, że jest to polityka firmy, ale czy absolutnie jesteś pewien, że w tym przypadku przestrzegasz polityki?
KarstenF,
To może być długa szansa, ale czy możliwe jest, że wyjątek pochodzi z jakiegoś kodu innej firmy? Być może jest to (źle napisane) opakowanie wyjątku, którego toString () po prostu zwraca nazwę klasy opakowanego wyjątku, i który nie zapewnia podstawowego śledzenia stosu. Spróbuj umieścić coś w rodzaju logger.info („Exception class =” + exc.class.getCanonicalName ()) w swoim bloku catch i zobacz, co otrzymujesz.
KarstenF,
4

Alternatywne sugestie - jeśli używasz Eclipse, możesz ustawić punkt przerwania w samym NullPointerException (w perspektywie debugowania przejdź do zakładki „Punkty przerwania” i kliknij małą ikonę z ikoną!)

Sprawdź opcje „złapany” i „nie złapany” - teraz, gdy uruchomisz NPE, natychmiast osiągniesz punkt przerwania, a następnie możesz przejść i zobaczyć, jak dokładnie jest obsługiwany i dlaczego nie otrzymujesz śledzenia stosu.

Steven Schlansker
źródło
1

toString()zwraca tylko nazwę wyjątku i opcjonalny komunikat. Sugerowałbym dzwonienie

exception.printStackTrace()

aby zrzucić wiadomość lub jeśli potrzebujesz krwawych szczegółów:

 StackTraceElement[] trace = exception.getStackTrace()
Sheldon Young
źródło
Patrz wyżej - źle napisałem - używam printStackTrace ().
Edward Shtern,
1

(Twoje pytanie jest nadal niejasne, czy Twój kod dzwoni, printStackTrace()czy jest to wykonywane przez program rejestrujący.)

Oto kilka możliwych wyjaśnień na temat tego, co może się dziać:

  • Używany program rejestrujący / moduł obsługi został skonfigurowany tak, aby wyświetlał tylko ciąg komunikatu wyjątku, a nie śledzenie pełnego stosu.

  • Twoja aplikacja (lub biblioteka innej firmy) rejestruje wyjątek, używając LOG.error(ex);zamiast 2-argumentowej formy (na przykład) metody log4j Logger.

  • Wiadomość przychodzi z innego miejsca niż myślisz; np. nadchodzi jakaś metoda biblioteczna innej firmy lub jakieś przypadkowe rzeczy pozostawione z wcześniejszych prób debugowania.

  • Rejestrowany wyjątek spowodował przeciążenie niektórych metod zasłaniania stosu śledzenia. W takim przypadku wyjątek nie będzie oryginalnym wyjątkiem NullPointerException, ale będzie niestandardowym podtypem NPE lub nawet niepowiązanym wyjątkiem.

Myślę, że ostatnie możliwe wyjaśnienie jest mało prawdopodobne, ale ludzie przynajmniej zastanawiają się nad zrobieniem tego rodzaju rzeczy, aby „zapobiec” inżynierii odwrotnej. Oczywiście naprawdę udaje się tylko utrudniać życie uczciwym programistom.

Stephen C.
źródło
1

Gdy używasz AspectJ w swoim projekcie, może się zdarzyć, że jakiś aspekt ukrywa swoją część śladu stosu. Na przykład dzisiaj miałem:

java.lang.NullPointerException:
  at com.company.product.MyTest.test(MyTest.java:37)

Ten ślad stosu został wydrukowany podczas uruchamiania testu przez pewnik Maven.

Z drugiej strony podczas uruchamiania testu w IntelliJ wydrukowano inny ślad stosu:

java.lang.NullPointerException
  at com.company.product.library.ArgumentChecker.nonNull(ArgumentChecker.java:67)
  at ...
  at com.company.product.aspects.CheckArgumentsAspect.wrap(CheckArgumentsAspect.java:82)
  at ...
  at com.company.product.MyTest.test(MyTest.java:37)
Roland Illig
źródło
0

Spowoduje to wygenerowanie wyjątku, używaj go tylko do debugowania, powinieneś lepiej obsługiwać wyjątki.

import java.io.PrintWriter;
import java.io.StringWriter;
    public static String getStackTrace(Throwable t)
    {
        StringWriter sw = new StringWriter();
        PrintWriter pw = new PrintWriter(sw, true);
        t.printStackTrace(pw);
        pw.flush();
        sw.flush();
        return sw.toString();
    }
Michael D. Irizarry
źródło