Opened 6 months ago
Last modified 5 days ago
#2592 assigned defect
libjetty NPE on debian 0.9.41-8
| Reported by: | Eche|on | Owned by: | str4d |
|---|---|---|---|
| Priority: | major | Milestone: | undecided |
| Component: | apps/plugins | Version: | 0.9.41 |
| Keywords: | Cc: | str4d | |
| Parent Tickets: | #2601 | Sensitive: | no |
Description
Hi
I did upgrade my buster system with 0.9.41-8 build.
I did get this now into log:
8/17/19, 11:43:34 AM ERROR [tion tunnels] 2ptunnel.TunnelControllerGroup?: Error loading the client app properties from /home/echelon/.i2p/i2ptunnel.config java.io.FileNotFoundException?: /home/echelon/.i2p/i2ptunnel.config (No such file or directory)
8/17/19, 11:43:34 AM WARN [tion tunnels] 2ptunnel.TunnelControllerGroup?: No i2ptunnel configurations found in /home/echelon/.i2p/i2ptunnel.config or /home/echelon/.i2p/i2ptunnel.config.d
8/17/19, 11:43:34 AM WARN [rtup tunnels] 2ptunnel.TunnelControllerGroup?: No configured tunnels to start
8/17/19, 12:22:44 PM WARN [r-2099968475] rg.eclipse.jetty.server.Server: : java.lang.NullPointerException?
8/17/19, 12:22:44 PM 16 similar messages omitted
8/17/19, 12:32:44 PM 11 similar messages omitted
8/17/19, 12:42:44 PM 10 similar messages omitted
lots of NPE in jetty
dpkg -l |grep jetty
ii libjetty9-extra-java 9.4.15-1 all Java servlet engine and webserver — extra libraries
ii libjetty9-java 9.4.15-1 all Java servlet engine and webserver — core libraries
Java version: Debian 11.0.4 (OpenJDK Runtime Environment 11.0.4+11-post-Debian-1deb10u1)
Wrapper version: 3.5.30
Server version: 9.4.15.v20190215
Servlet version: Jasper JSP 2.3 Engine
JSTL version: standard-taglib 1.2.5
Platform: Linux amd64 4.19.0-5-amd64
Processor: Kaby Lake Core i3/i5/i7 (coreibwl)
JBigI status: Locally optimized native BigInteger? library loaded from file
GMP version: 6.1.2
JBigI version: 4
JCpuId version: 3
Encoding: UTF-8
Charset: UTF-8
Built By: Undefined
Subtickets
Change History (11)
comment:1 Changed 6 months ago by
| Component: | package/debian → apps/jetty |
|---|
comment:2 Changed 6 months ago by
HI
could be related to i2pbote
8/18/19, 12:37:10 PM WARN [luginStarter] rg.eclipse.jetty.server.Server: Failed startup of context o.e.j.w.WebAppContext?@2e5c7043{/i2pbote,jar:file:///opt/i2p/plugins/i2pbote/console/webapps/i2pbote.war!/,UNAVAILABLE}{/i2pbote.war}
java.io.FileNotFoundException?: JAR entry WEB-INF/lib/tomcat-el-api-8.5.40.jar!/ not found in /opt/i2p/plugins/i2pbote/console/webapps/i2pbote.war
at java.base/sun.net.www.protocol.jar.JarURLConnection.connect(JarURLConnection.java:147)
at java.base/sun.net.www.protocol.jar.JarURLConnection.getJarFile(JarURLConnection.java:92)
at org.eclipse.jetty.webapp.MetaInfConfiguration?.getTlds(MetaInfConfiguration?.java:438)
at org.eclipse.jetty.webapp.MetaInfConfiguration?.scanForTlds(MetaInfConfiguration?.java:355)
at org.eclipse.jetty.webapp.MetaInfConfiguration?.scanJars(MetaInfConfiguration?.java:173)
at org.eclipse.jetty.webapp.MetaInfConfiguration?.preConfigure(MetaInfConfiguration?.java:107)
at org.eclipse.jetty.webapp.WebAppContext?.preConfigure(WebAppContext?.java:506)
at org.eclipse.jetty.webapp.WebAppContext?.doStart(WebAppContext?.java:544)
at org.eclipse.jetty.util.component.AbstractLifeCycle?.start(AbstractLifeCycle?.java:68)
at net.i2p.router.web.WebAppStarter?.startWebApp(WebAppStarter?.java:71)
at net.i2p.router.web.PluginStarter?.startPlugin(PluginStarter?.java:478)
at net.i2p.router.web.PluginStarter?.startPlugins(PluginStarter?.java:267)
at net.i2p.router.web.PluginStarter?.run(PluginStarter?.java:127)
at java.base/java.lang.Thread.run(Thread.java:834)
at net.i2p.util.I2PThread.run(I2PThread.java:103)
8/18/19, 12:37:10 PM ERROR [luginStarter] t.i2p.router.web.PluginStarter?: Error resolving '/home/echelon/.i2p/plugins/i2pbote/console/webapps/i2pbote.war' in '/home/echelon/.i2p/plugins/i2pbote/console/webapps
java.io.FileNotFoundException?: JAR entry WEB-INF/lib/tomcat-el-api-8.5.40.jar!/ not found in /opt/i2p/plugins/i2pbote/console/webapps/i2pbote.war
at java.base/sun.net.www.protocol.jar.JarURLConnection.connect(JarURLConnection.java:147)
at java.base/sun.net.www.protocol.jar.JarURLConnection.getJarFile(JarURLConnection.java:92)
at org.eclipse.jetty.webapp.MetaInfConfiguration?.getTlds(MetaInfConfiguration?.java:438)
at org.eclipse.jetty.webapp.MetaInfConfiguration?.scanForTlds(MetaInfConfiguration?.java:355)
at org.eclipse.jetty.webapp.MetaInfConfiguration?.scanJars(MetaInfConfiguration?.java:173)
at org.eclipse.jetty.webapp.MetaInfConfiguration?.preConfigure(MetaInfConfiguration?.java:107)
at org.eclipse.jetty.webapp.WebAppContext?.preConfigure(WebAppContext?.java:506)
at org.eclipse.jetty.webapp.WebAppContext?.doStart(WebAppContext?.java:544)
at org.eclipse.jetty.util.component.AbstractLifeCycle?.start(AbstractLifeCycle?.java:68)
at net.i2p.router.web.WebAppStarter?.startWebApp(WebAppStarter?.java:71)
at net.i2p.router.web.PluginStarter?.startPlugin(PluginStarter?.java:478)
at net.i2p.router.web.PluginStarter?.startPlugins(PluginStarter?.java:267)
at net.i2p.router.web.PluginStarter?.run(PluginStarter?.java:127)
at java.base/java.lang.Thread.run(Thread.java:834)
at net.i2p.util.I2PThread.run(I2PThread.java:103)
8/18/19, 12:37:12 PM WARN [ handler 1/1] er.transport.udp.PacketHandler?: NTP failure, UDP adjusting clock by 349ms
8/18/19, 12:37:20 PM WARN [Timestamper ] .router.time.RouterTimestamper?: Unable to reach any of the NTP servers [85.125.61.2, 129.27.2.3] - network disconnected? Or set time.sntpServerList=myserver1.com,myserver2.com in advanced configuration.
8/18/19, 12:37:40 PM WARN [JettyStarter?] rg.eclipse.jetty.server.Server: GzipFilter? is deprecated. Use GzipHandler?
8/18/19, 12:38:02 PM WARN [ole Jetty-97] rg.eclipse.jetty.server.Server: Problem checking if id 1faxo0sy8esvm1qtng8vlcp3l3 is in use java.lang.NullPointerException?
8/18/19, 12:39:02 PM WARN [ole Jetty-97] rg.eclipse.jetty.server.Server: Problem checking if id u2f72ps679hc11cete9rpkvoy is in use java.lang.NullPointerException?
8/18/19, 12:40:02 PM WARN [ole Jetty-97] rg.eclipse.jetty.server.Server: Problem checking if id 1npk55nq8zh3fbwpr95w3lteg is in use java.lang.NullPointerException?
8/18/19, 12:40:59 PM WARN [ole Jetty-97] rg.eclipse.jetty.server.Server: Problem checking if id 114ego5aft5ep17nxf3v5l27v6 is in use java.lang.NullPointerException?
8/18/19, 12:42:00 PM WARN [le Jetty-137] rg.eclipse.jetty.server.Server: Problem checking if id 1chxfom9qbxxd1ve8sdzy7hwxt is in use java.lang.NullPointerException?
8/18/19, 12:43:00 PM WARN [le Jetty-137] rg.eclipse.jetty.server.Server: Problem checking if id xp5s4nmujw3ccehezk9t8pm2 is in use java.lang.NullPointerException?
8/18/19, 12:44:00 PM WARN [le Jetty-137] rg.eclipse.jetty.server.Server: Problem checking if id 1tltoxs1eolka1v298hx9rm7fc is in use java.lang.NullPointerException?
8/18/19, 12:45:00 PM WARN [ole Jetty-99] rg.eclipse.jetty.server.Server: Problem checking if id 8zo48l2c38v31344zddjpj1po is in use java.lang.NullPointerException?
8/18/19, 12:45:57 PM WARN [ole Jetty-99] rg.eclipse.jetty.server.Server: Problem checking if id 15yftc1gcwg7aeyk5sp89rm2p is in use java.lang.NullPointerException?
8/18/19, 12:46:57 PM WARN [ole Jetty-99] rg.eclipse.jetty.server.Server: Problem checking if id y5w6pvvgtagvs5382hlj8n1x is in use java.lang.NullPointerException?
8/18/19, 12:47:57 PM WARN [ole Jetty-99] rg.eclipse.jetty.server.Server: Problem checking if id 1s9m768xpikk416nw62i4qq20 is in use java.lang.NullPointerException?
comment:3 Changed 6 months ago by
unfortunately due to flaws in the jetty-to-i2p logging bridge, that still isn't giving us the stack trace we need… working on it…
comment:4 Changed 6 months ago by
Logging fix in a9a28e378ec94e24e77a59e13f546c7fbc147f46 0.9.41-9-rc, please retest with that to hopefully get a stack trace for the NPE
comment:5 Changed 6 months ago by
| Cc: | str4d added |
|---|
Also, something's going on with bote. Bote is bundling 3 tomcat jars in its war, and they are not being loaded. We already have those jars in the distribution. These jars should not be bundled. Why jetty isn't loading them, I'm not sure. I do see similar errors here (with jetty 9.2.25) when I start bote, but it isn't fatal… bote still runs.
It's possible that it is fatal on 9.4.15 and is the cause of the NPEs? not sure. Once you have the stack traces, please disable the bote plugin and then restart and see if that fixes it.
comment:6 Changed 6 months ago by
| Cc: | str4d removed |
|---|
8/18/19, 5:16:31 PM WARN [le Jetty-140] rg.eclipse.jetty.server.Server: Problem checking if id 1vn28fnzbevl81d7xtp84tcwyl is in use java.lang.NullPointerException java.lang.NullPointerException at org.eclipse.jetty.server.session.SessionHandler.isIdInUse(SessionHandler.java:1462) at org.eclipse.jetty.server.session.DefaultSessionIdManager.isIdInUse(DefaultSessionIdManager.java:325) at org.eclipse.jetty.server.session.DefaultSessionIdManager.newSessionId(DefaultSessionIdManager.java:230) at org.eclipse.jetty.server.session.SessionHandler.newHttpSession(SessionHandler.java:858) at org.eclipse.jetty.server.Request.getSession(Request.java:1570) at org.eclipse.jetty.server.Request.getSession(Request.java:1543) at javax.servlet.http.HttpServletRequestWrapper.getSession(HttpServletRequestWrapper.java:250) at org.apache.jasper.runtime.PageContextImpl.initialize(PageContextImpl.java:133) at org.apache.jasper.runtime.JspFactoryImpl.internalGetPageContext(JspFactoryImpl.java:109) at org.apache.jasper.runtime.JspFactoryImpl.getPageContext(JspFactoryImpl.java:60) at net.i2p.router.web.jsp.xhr1_jsp._jspService(xhr1_jsp.java:114) at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:70) at javax.servlet.http.HttpServlet.service(HttpServlet.java:741) at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:873) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1623) at net.i2p.servlet.filters.XSSFilter.doFilter(XSSFilter.java:30) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1602) at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:540) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:146) at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:257) at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1701) at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255) at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1345) at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203) at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:480) at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1668) at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201) at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1247) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) at net.i2p.router.web.LocaleWebAppHandler.handle(LocaleWebAppHandler.java:104) at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:220) at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:753) at net.i2p.router.web.HostCheckHandler.handle(HostCheckHandler.java:118) at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:126) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) at org.eclipse.jetty.server.Server.handle(Server.java:502) at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:370) at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:267) at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305) at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126) at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366) at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:765) at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:683) at java.base/java.lang.Thread.run(Thread.java:834) 8/18/19, 5:16:36 PM WARN [JettyStarter] rg.eclipse.jetty.server.Server: GzipFilter is deprecated. Use GzipHandler 8/18/19, 5:17:31 PM WARN [le Jetty-138] rg.eclipse.jetty.server.Server: Problem checking if id gngabmwxriemjjppo185dtng is in use java.lang.NullPointerException java.lang.NullPointerException
comment:7 Changed 6 months ago by
| Cc: | str4d added |
|---|
comment:8 Changed 6 months ago by
Thanks. No ideas so far. SessionHandler?.doStart() is apparently not being called so _sessionCache is null in isIdInUse(). It's coming from the sidebar XHR so it's triggered once a minute. Seems harmless as it's being caught. Haven't seen here yet on 9.2 (with/without bote), but haven't tried with 9.4 yet.
comment:10 Changed 6 months ago by
Tested with my jetty94 branch (not Debian) and got the same file not found errors as in comment 3, and bote failed to start. I did not get any NPEs.
comment:11 Changed 5 days ago by
| Component: | apps/jetty → apps/plugins |
|---|---|
| Owner: | changed from zzz to str4d |
| Parent Tickets: | → 2601 |
| Priority: | minor → major |
| Status: | new → assigned |
The NPE could only happen on 9.4.x, the jetty code is completely different in 9.2.x.
It appears to be a jetty bug that could only happen if the handler initialization was not completed due to an earlier error, which is what we see in comment 2 above.
So the root cause is #2601
Please set org.eclipse.jetty.server.Server=WARN on /configlogging which should then produce a stack trace for the exception, and paste one of them over here