Nullpointers and connection leaking

[sigdestad]

When running the link-checker with the "logging" branch i get a bunch of "invalid links" reported even for good links. The following is reported in the logs:

08:45:21.311 WARN okhttp3.OkHttpClient - A connection to https://blog.enonic.com/ was leaked. Did you forget to close a response body? To see where this was allocated, set the OkHttpClient logger level to FINE: Logger.getLogger(OkHttpClient.class.getName()).setLevel(Level.FINE);08:45:21.311 WARN okhttp3.OkHttpClient - A connection to https://moz.com/ was leaked. Did you forget to close a response body? To see where this was allocated, set the OkHttpClient logger level to FINE: Logger.getLogger(OkHttpClient.class.getName()).setLevel(Level.FINE); 08:45:21.312 WARN okhttp3.OkHttpClient - A connection to https://blog.enonic.com/ was leaked. Did you forget to close a response body? To see where this was allocated, set the OkHttpClient logger level to FINE: Logger.getLogger(OkHttpClient.class.getName()).setLevel(Level.FINE);08:45:21.312 WARN okhttp3.OkHttpClient - A connection to https://blog.enonic.com/ was leaked. Did you forget to close a response body? To see where this was allocated, set the OkHttpClient logger level to FINE: Logger.getLogger(OkHttpClient.class.getName()).setLevel(Level.FINE); 08:45:21.312 WARN okhttp3.OkHttpClient - A connection to https://www.w3.org/ was leaked. Did you forget to close a response body? To see where this was allocated, set the OkHttpClient logger level to FINE: Logger.getLogger(OkHttpClient.class.getName()).setLevel(Level.FINE);08:45:21.312 WARN okhttp3.OkHttpClient - A connection to https://blog.enonic.com/ was leaked. Did you forget to close a response body? To see where this was allocated, set the OkHttpClient logger level to FINE: Logger.getLogger(OkHttpClient.class.getName()).setLevel(Level.FINE); 08:45:21.312 WARN okhttp3.OkHttpClient - A connection to https://theuxblog.com/ was leaked. Did you forget to close a response body? To see where this was allocated, set the OkHttpClient logger level to FINE: Logger.getLogger(OkHttpClient.class.getName()).setLevel(Level.FINE);08:45:21.312 WARN okhttp3.OkHttpClient - A connection to https://www.steptwo.com.au/ was leaked. Did you forget to close a response body? To see where this was allocated, set the OkHttpClient logger level to FINE: Logger.getLogger(OkHttpClient.class.getName()).setLevel(Level.FINE); 08:45:21.312 WARN okhttp3.OkHttpClient - A connection to https://blog.enonic.com/ was leaked. Did you forget to close a response body? To see where this was allocated, set the OkHttpClient logger level to FINE: Logger.getLogger(OkHttpClient.class.getName()).setLevel(Level.FINE);08:45:21.313 WARN okhttp3.OkHttpClient - A connection to https://blog.enonic.com/ was leaked. Did you forget to close a response body? To see where this was allocated, set the OkHttpClient logger level to FINE: Logger.getLogger(OkHttpClient.class.getName()).setLevel(Level.FINE); 08:45:21.313 WARN okhttp3.OkHttpClient - A connection to http://webagility.com/ was leaked. Did you forget to close a response body? To see where this was allocated, set the OkHttpClient logger level to FINE: Logger.getLogger(OkHttpClient.class.getName()).setLevel(Level.FINE);08:45:21.313 WARN okhttp3.OkHttpClient - A connection to https://blog.enonic.com/ was leaked. Did you forget to close a response body? To see where this was allocated, set the OkHttpClient logger level to FINE: Logger.getLogger(OkHttpClient.class.getName()).setLevel(Level.FINE); 08:45:21.522 ERROR no.bouvet.app.linkchecker - (/services/LinkChecker/LinkChecker.js) java.lang.NullPointerException 08:45:21.522 INFO no.bouvet.app.linkchecker - (/services/LinkChecker/LinkChecker.js) Checking URL: https://pwa-directory.appspot.com/pwas/6254862074380288 08:45:22.272 ERROR no.bouvet.app.linkchecker - (/services/LinkChecker/LinkChecker.js) java.lang.NullPointerException 08:45:22.273 INFO no.bouvet.app.linkchecker - (/services/LinkChecker/LinkChecker.js) Checking URL: https://www.youtube.com/watch?v=Ar0D4LCDcGY 08:45:22.443 ERROR no.bouvet.app.linkchecker - (/services/LinkChecker/LinkChecker.js) java.lang.NullPointerException 08:45:22.443 INFO no.bouvet.app.linkchecker - (/services/LinkChecker/LinkChecker.js) Checking URL: https://enonic.com/progressive-web-apps 08:45:22.951 ERROR no.bouvet.app.linkchecker - (/services/LinkChecker/LinkChecker.js) java.lang.NullPointerException 08:45:22.952 INFO no.bouvet.app.linkchecker - (/services/LinkChecker/LinkChecker.js) Checking URL: https://blog.enonic.com/find-what-cms-website-uses

[mortyeriksen]

@olesaggau, Vi har en del kunder som har begynt å titte på Link Checker nå. Fint om du får sjekket opp denne feilen. Vi får nullpointer på det meste hos oss.

Mvh Morten

[olesaggau]

Jeg klarer ikke gjenskape denne nullpointer buggen lokalt eller på diverse sider vi tester på. Jeg har oppdatert logging branchen til å bruke httpClientLib 1.0.4, dette antar jeg vil fikse leaking, ref https://discuss.enonic.com/t/http-lib-doesnt-close-respone-body/1716/2

Kanskje dette vil fikse nullpointer for dere?

[olesaggau]

I try catch'en som printer NullPointerException

log.info("Checking URL: " + url);
  try {
    if (url.indexOf("http://") == -1 && url.indexOf("https://") == -1) {
      url = "http://" + url;
    }
    var response = httpClientLib.request({
      url: url,
      ...
    });
    log.info("^ Status: " + response.status);
    return response.status;
  } catch (error) {
    log.error(error);

Så er det som jeg ser bare httpClientLib som kan gi en slik java exception

[mortyeriksen]

Her er en curl fra serveren mot en url som feiler hvis det hjelper noe: root@17fc0fbc35d0:/# curl -sSL -D - https://enonic.com/privacy-policy -o /dev/null HTTP/1.1 200 OK Date: Thu, 20 Dec 2018 14:31:24 GMT Content-Type: text/html Transfer-Encoding: chunked Connection: keep-alive Set-Cookie: xxxxxxxx; expires=Fri, 20-Dec-19 14:31:23 GMT; path=/; domain=.enonic.com; HttpOnly Strict-Transport-Security: max-age=15768000 Vary: Accept-Encoding Expect-CT: max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct" Server: cloudflare CF-RAY: 48c2cff5cb89b4bc-RIX

Vi tester på nytt.

[sigdestad]

Har testet, og når koden nærmer seg slutten velter det ut "Leaked" connections, samt at det fortsatt er fullt av nullpointers gjennom hele kjøringen.

I tillegg så et jeg et par av denne. 15:06:19.845 ERROR no.bouvet.app.linkchecker - (/services/LinkChecker/LinkChecker.js) java.lang.IllegalStateException: Unable to load publicsuffixes.gz resource from the classpath.

Her er det som kommer ifm Leaked connections: 15:13:17.215 WARN okhttp3.OkHttpClient - A connection to https://www.w3schools.com/ was leaked. Did you forget to close a response body? To see where this was allocated, set the OkHttpClient logger level to FINE: Logger.getLogger(OkHttpClient.class.getName()).setLevel(Level.FINE);

Hvis vi ikke får fikset dette må jeg vurdere å pause app'en på market da appen kan påvirke stabiliteten hos kunder.

Det hadde jo vært nyttig om du logget noe mer enn "nullpointer", så man kunne sett hva som faktisk feiler? Alt som kommer i dag er dette: 15:08:33.763 ERROR no.bouvet.app.linkchecker - (/services/LinkChecker/LinkChecker.js) java.lang.NullPointerException

For meg virker det som om det er en sammenheng mellom nullpointeren, og påfølgende leak?

En annen intressant ting når jeg søkte i loggen var at det kun kom "checking https://support.enonic.com" 1 gang, men det kom 5 ganger at "a connection was leaked" til samme url?

[dholmen]

lib-http-client bruker en 1,5 år gammel versjon av okhttp (3.7 april 2017). Det er mange titalls bugfikser som har kommet til siden det. Nyeste versjon av okhttp per nå er 3.12.

I og med at vi ikke klarer å framprovosere feilene dere får på noen av sitene vi har testet det på (relativt store sites med mye innhold), ser det ut som det er noe spesielt med konfigurasjonen hos dere som framprovoserer feilene. Det er også vanskelig å teste utenfor deres miljø. Har dere fått tilbakemelding fra noen andre på at link-checker ikke fungerer? Dere kjører enonic.com bak cloudflare?

Mitt forslag er at vi lager en egen branch av link-checker hvor vi inkluderer en oppgradert okhttp, og så kan dere bygge og teste den hos dere.

Edit: når jeg ser nærmere etter, ser jeg at dere ikke bundler okhttp med lib-http-client, men at den ligger i xp sentralt. Da blir det hakket vanskeligere å teste ut.

[sigdestad]

Hei igjen. Har testet på ny ved å kjøre samme data på min localhost. Jeg får bare noen få broken links nå - noen av de ser fine ut når jeg besøker siden, men det oppfører seg helt annerledes enn i vårt produksjonsmijlø. Dette må være relatert til utgående trafikk fra serverne på et vis, uten at jeg helt skjønner hvorfor.

Oppgradering av okhttp er sikkert smart, men usikker på om problemet ligger der. Tror vi må ta en titt på dette i vårt miljø over på nyåret.

[dholmen]

Ja, jeg var ikke sikker på om okhttp-versjonen ville ha noe å si her, men det var det eneste utenom miljø jeg kunne klare å finne.

Det er interessant å se hva feilen er til slutt.

Vi har identifisert og fikset et par andre bugs, og kommer med en ny versjon på nyåret som inneholder disse fiksene pluss oppgradering til lib-http-client 1.0.4 for å unngå connection leaks.

[sigdestad]

Husk, dere må gjerne også lage en pull request med som oppgraderer http client :-)

[vi-h]

I og med at https://github.com/enonic/lib-http-client/issues/16 er lukket, og vi nå bruker versjon 3.2.0 av Http Client Lib, så antar jeg at denne er løst og kan lukkes. Si ifra om det viser seg å være feil :)