Čo je to Stack trace? (resp. Backtrace alebo Stack traceback)
Stack trace je, zjednodušene povedané, zoznam metód vyvolaných počas behu aplikácie do určitého časového okamihu (typicky, no nie nutne, do okamihu vyvolania výnimky).
Detailnejšie vysvetlenie s kontextom:
- zásobník (stack) je dátová štruktúra, do ktorej ukladáme bloky dát, pre ktoré je typické, že dáta uložené ako posledné, sú čítané ako prvé (tzv. LIFO = „Last In – First Out“),
- pri behu aplikácie sa používa zásobnik, ktorý pre rozlíšenie nazývame runtime stack:
- vždy, keď sa vyvolá funkcia, na vrch tohoto zásobníku sa umiestni blok, do ktorého sa uložia parametre funkcie a lokálne premenné deklarované v tejto funkcii,
- po vykonaní funkcie sa tento blok odstráni a na vrchu zásobníku bude blok s dátami volajúcej funkcie, ktorá ešte nedobehla,
- programátori využívajú tento zásobnik typicky dvomi spôsobmi:
- program v určitom mieste zastavia (pomocou breakpointu) a na zásobniku sledujú postupnosť, ako sa funkcie postupne volali (vnárali), pričom sa môžu postupne po volaniach vracať späť a prezerať si aj obsah premenných,
- druhé využitie je typicky po páde programu (vyhodení výnimky), kedy vo výpise zásobníku môžeme zistiť, kde v programe nastala chybe (nie nutne, kde bola spôsobená) a tiež dôvod tejto chyby,
- prezeranie, resp. trasovanie zásobníku sa nazýva stacktracing.
Ako čítať výnimky zo Stack trace?
Jednoduchý príklad
Pozrime sa na nasledujúci jednoduchý výpis:
Exception in thread "main" java.lang.NullPointerException at com.example.myproject.Book.getTitle(Book.java:16) at com.example.myproject.Author.getBookTitles(Author.java:25) at com.example.myproject.Bootstrap.main(Bootstrap.java:14)
Miesto, kde sa vyskytla chyba, môžeme nájsť tak, že začneme hľadať vo výpise riadky začínajúce s „at …„. Hľadáme riadok čo najviac hore, ktorý obsahuje volanie „našej“ metódy. V tomto prípade je to:
at com.example.myproject.Book.getTitle(Book.java:16)
Pre ladenie tejto chyby teda otvoríme súbor Book.java a pozrieme sa na riadok 16:
public String getTitle() {
System.out.println(title.toString());
return title;
}
Z popisu chyby vieme, že niečo (pravdepodobne title) je null:
Exception in thread "main" java.lang.NullPointerException
Príklad so zreťazenými výnimkami
Niekedy aplikácia zachytí výnimku a následne ju znova vyhodí ako príčinu (cause) inej výnimky (tzv. reťazenie výnimiek). Toto typicky vyzerá asi takto:
public void getBookIds(int id) {
try {
book.getId(id); // táto metóda výhodí NullPointerException na riadku 22
} catch (NullPointerException e) {
throw new IllegalStateException("A book has a null property", e)
}
}
Výpis zo zásobníka potom môže vyzerať takto:
Exception in thread "main" java.lang.IllegalStateException: A book has a null property at com.example.myproject.Author.getBookIds(Author.java:38) at com.example.myproject.Bootstrap.main(Bootstrap.java:14) Caused by: java.lang.NullPointerException at com.example.myproject.Book.getId(Book.java:22) at com.example.myproject.Author.getBookIds(Author.java:36) ... 1 more
Rozdiel oproti predošlému príkladu je sekcia „Caused by„, pričom niekedy môžu mať výnimky týchto sekcií aj viac. V takomto prípade sa typicky snažíme nájsť počiatočnú príčinu, ktorá je jedna z najnižších „Caused by“ sekcií vo výpise. V našom prípade:
Caused by: java.lang.NullPointerException <-- počiatočná príčina at com.example.myproject.Book.getId(Book.java:22) <-- dôležitý riadok
Takže v tomto prípade by sme sa mali pozrieť na riadok 22 v súbore Book.java, aby sme zistili, čo spôsobilo NullPointerException.
Zložitejší príklad
Zvyčajne je výpis zásobníka oveľa zložitejší ako ukážky vyššie. Tu je príklad (je dlhý a demonštruje niekoľko úrovni reťazenia výnimiek):
javax.servlet.ServletException: Something bad happened at com.example.myproject.OpenSessionInViewFilter.doFilter(OpenSessionInViewFilter.java:60) at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157) at com.example.myproject.ExceptionHandlerFilter.doFilter(ExceptionHandlerFilter.java:28) at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157) at com.example.myproject.OutputBufferFilter.doFilter(OutputBufferFilter.java:33) at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157) at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:388) at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216) at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:182) at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:765) at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:418) at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152) at org.mortbay.jetty.Server.handle(Server.java:326) at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:542) at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:943) at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:756) at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:218) at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:404) at org.mortbay.jetty.bio.SocketConnector$Connection.run(SocketConnector.java:228) at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:582) Caused by: com.example.myproject.MyProjectServletException at com.example.myproject.MyServlet.doPost(MyServlet.java:169) at javax.servlet.http.HttpServlet.service(HttpServlet.java:727) at javax.servlet.http.HttpServlet.service(HttpServlet.java:820) at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:511) at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1166) at com.example.myproject.OpenSessionInViewFilter.doFilter(OpenSessionInViewFilter.java:30) ... 27 more Caused by: org.hibernate.exception.ConstraintViolationException: could not insert: [com.example.myproject.MyEntity] at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:96) at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66) at org.hibernate.id.insert.AbstractSelectingDelegate.performInsert(AbstractSelectingDelegate.java:64) at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2329) at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2822) at org.hibernate.action.EntityIdentityInsertAction.execute(EntityIdentityInsertAction.java:71) at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:268) at org.hibernate.event.def.AbstractSaveEventListener.performSaveOrReplicate(AbstractSaveEventListener.java:321) at org.hibernate.event.def.AbstractSaveEventListener.performSave(AbstractSaveEventListener.java:204) at org.hibernate.event.def.AbstractSaveEventListener.saveWithGeneratedId(AbstractSaveEventListener.java:130) at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.saveWithGeneratedOrRequestedId(DefaultSaveOrUpdateEventListener.java:210) at org.hibernate.event.def.DefaultSaveEventListener.saveWithGeneratedOrRequestedId(DefaultSaveEventListener.java:56) at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.entityIsTransient(DefaultSaveOrUpdateEventListener.java:195) at org.hibernate.event.def.DefaultSaveEventListener.performSaveOrUpdate(DefaultSaveEventListener.java:50) at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.onSaveOrUpdate(DefaultSaveOrUpdateEventListener.java:93) at org.hibernate.impl.SessionImpl.fireSave(SessionImpl.java:705) at org.hibernate.impl.SessionImpl.save(SessionImpl.java:693) at org.hibernate.impl.SessionImpl.save(SessionImpl.java:689) at sun.reflect.GeneratedMethodAccessor5.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.hibernate.context.ThreadLocalSessionContext$TransactionProtectionWrapper.invoke(ThreadLocalSessionContext.java:344) at $Proxy19.save(Unknown Source) at com.example.myproject.MyEntityService.save(MyEntityService.java:59) <-- relevatný riadok (pozri poznámky nižšie) at com.example.myproject.MyServlet.doPost(MyServlet.java:164) ... 32 more Caused by: java.sql.SQLException: Violation of unique constraint MY_ENTITY_UK_1: duplicate value(s) for column(s) MY_COLUMN in statement [...] at org.hsqldb.jdbc.Util.throwError(Unknown Source) at org.hsqldb.jdbc.jdbcPreparedStatement.executeUpdate(Unknown Source) at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeUpdate(NewProxyPreparedStatement.java:105) at org.hibernate.id.insert.AbstractSelectingDelegate.performInsert(AbstractSelectingDelegate.java:57) ... 54 more
V tomto príklade je toho oveľa viac. To čo nás najviac zaujíma sú metódy z nášho kódu, čo znamená, že je to čokoľvek z balíčku com.example.myproject. Na základe skúsenosti z druhého príkladu budeme najprv na konci výpisu hľadať počiatočnú príčinu, ktorá je:
Caused by: java.sql.SQLException
Avšak, keď sa bližšie pozrieme, všetky metódy volané v tejto sekcii sú z knižníc. Preto prejdeme na najbližiu sekciu „Caused by“ smerom vyššie a nájdeme prvé volanie metódy z nášho kódu, a teda:
at com.example.myproject.MyEntityService.save(MyEntityService.java:59)
Následne postupujeme obdobne ako v predošlých príkladoch a teda sa pozrieme na riadok 59 do súboru MyEntityService.java, pretože to je miesto, kde vznikla chyba (v tomto prípade je chyba zrejmá aj z hlášky SQL výnimky, ale miesto kde je potrebné začat ladiť aplikáciu je to, ktoré sme si ukázali).
Záver
Pri ladení aplikácii sa človek nesmie nechať vystrašiť a zmiasť dlhými výpismi výnimiek. Je potrebné mať na pamäti:
- bezprostredná príčina býva posledná výnimky vo výpise,
- keď nám jej popis nestačí, je príliš všeobecný alebo neobsahuje žiadne podrobnosti, je potrebné postupovať smerom hore po zreťazených výnimkach,
- spočiatku je vo výpisoch dobré ignorovať všetko okrem „našich“ zdrojákov (a tiež všetko, čo je generované v runtime),
- miesto výskytu chyby je potom zase opačne to najviac hore vo výpise zásobníku,
- t.j. v prvom zásobníku odspodu (= „poslednej výnimke“) prvá „naša“ trieda zhora,
- tu väčšinou vidíme, či ide o bežnú programátorsku chybu alebo je chyba v konfigurácii (Spring, Hibernate…), prípadne postupujeme smerom dole vo výpise,
- až úplne nakoniec sa pozeráme na knižnicový a generovaný kód, keď dochádza k chybe tam, problém bude pravdedodobne v nejakej konfigurácii,
- v Spring aplikáciach sa občas stáva, že výnimky sa vypisujú najmenej dvakrát, niečo vypisuje Spring a niečo my, aby sa nám to náhodou „nestratilo“.
Zdroje
- Wikipedia: Stack trace (27. 4. 2017),
- Rob Hruska: What is a stack trace, and how can I use it to debug my application errors? (27. 4. 2017).