Bug 61914 - NPE at org.apache.tomcat.util.net.AbstractJsseEndpoint.createSSLEngine with SNI on Java 9
Summary: NPE at org.apache.tomcat.util.net.AbstractJsseEndpoint.createSSLEngine with S...
Status: RESOLVED FIXED
Alias: None
Product: Tomcat 9
Classification: Unclassified
Component: Util (show other bugs)
Version: 9.0.2
Hardware: PC Linux
: P2 normal (vote)
Target Milestone: -----
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2017-12-17 02:39 UTC by Evgenij Ryazanov
Modified: 2017-12-21 12:21 UTC (History)
0 users



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Evgenij Ryazanov 2017-12-17 02:39:44 UTC
I have a lot of

java.lang.NullPointerException
at org.apache.tomcat.util.net.AbstractJsseEndpoint.createSSLEngine(AbstractJsseEndpoint.java:180)
at org.apache.tomcat.util.net.SecureNioChannel.processSNI(SecureNioChannel.java:325)
at org.apache.tomcat.util.net.SecureNioChannel.handshake(SecureNioChannel.java:175)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1353)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)

in system journal with Tomcat 9.0.2 running on Java 9.

Code in SecureNioChannel.processSNI() passes null value of clientRequestedApplicationProtocols if TLSClientHelloExtractor.getResult() is not COMPLETE or NEED_INFO.

But code in AbstractJsseEndpoint.createSSLEngine does not perform check and unconditionally calls size() method on Java 9 here:

if (JreCompat.isJre9Available() && clientRequestedApplicationProtocols.size() > 0 &&
Comment 1 Evgenij Ryazanov 2017-12-17 03:47:24 UTC
SecureNio2Channel.processSNI() is very similar to SecureNioChannel.processSNI() and may have the same issue.
Comment 2 Evgenij Ryazanov 2017-12-17 15:13:24 UTC
I've just checked old records in system journal, access log, and atop records.

After restart there are a 5–10 such warings per hour. But after a few hours the rate of exceptions dramatically increases to 10–20 per second. After a some more time (about a day) Tomcat begins to eat slightly more than 100% of CPU on 2-core system and becomes unresponsible.

I also have a heap dump in unresponsible state, but it contains some sensitive information and I cannot see nothing unusual in it. I'm not sure if this failure related to NPEs in createSSLEngine() or not.
Comment 3 Evgenij Ryazanov 2017-12-21 07:31:44 UTC
I replaced

clientRequestedApplicationProtocols.size() > 0

with

clientRequestedApplicationProtocols != null && clientRequestedApplicationProtocols.size() > 0

on my installation some time ago and with this change server still works as expected. Can someone fix this is SVN?
Comment 4 thibaud KIEFFER 2017-12-21 10:29:31 UTC
When I start a tomcat 9 with MobaXterm from windows I have these java exceptions, it's since tomcat 9, I never had this issue before and I don't have this issue with Putty :

21-Dec-2017 11:20:24.942 INFO [main] org.apache.catalina.core.ApplicationContext.log Initializing Spring root WebApplicationContext
21-Dec-2017 11:20:42.708 SEVERE [main] org.apache.catalina.core.StandardContext.filterStart Exception starting filter [javamelody]
 java.lang.UnsatisfiedLinkError: /opt/jdk1.8.0_121/jre/lib/i386/libawt_xawt.so: libXtst.so.6: cannot open shared object file: No such file or directory
        at java.lang.ClassLoader$NativeLibrary.load(Native Method)
        at java.lang.ClassLoader.loadLibrary0(ClassLoader.java:1941)
        at java.lang.ClassLoader.loadLibrary(ClassLoader.java:1824)
        at java.lang.Runtime.load0(Runtime.java:809)
        at java.lang.System.load(System.java:1086)
        at java.lang.ClassLoader$NativeLibrary.load(Native Method)
        at java.lang.ClassLoader.loadLibrary0(ClassLoader.java:1941)
        at java.lang.ClassLoader.loadLibrary(ClassLoader.java:1845)
        at java.lang.Runtime.loadLibrary0(Runtime.java:870)
        at java.lang.System.loadLibrary(System.java:1122)
        at java.awt.Toolkit$3.run(Toolkit.java:1636)
        at java.awt.Toolkit$3.run(Toolkit.java:1634)
        at java.security.AccessController.doPrivileged(Native Method)
        at java.awt.Toolkit.loadLibraries(Toolkit.java:1633)
        at java.awt.Toolkit.<clinit>(Toolkit.java:1668)
        at java.awt.Color.<clinit>(Color.java:275)
        at net.bull.javamelody.JRobin.<clinit>(JRobin.java:58)
        at net.bull.javamelody.FilterContext.initCollect(FilterContext.java:230)
        at net.bull.javamelody.FilterContext.<init>(FilterContext.java:109)
        at net.bull.javamelody.MonitoringFilter.init(MonitoringFilter.java:130)
        at org.apache.catalina.core.ApplicationFilterConfig.initFilter(ApplicationFilterConfig.java:277)
        at org.apache.catalina.core.ApplicationFilterConfig.getFilter(ApplicationFilterConfig.java:258)
        at org.apache.catalina.core.ApplicationFilterConfig.<init>(ApplicationFilterConfig.java:104)
        at org.apache.catalina.core.StandardContext.filterStart(StandardContext.java:4491)
        at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5131)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:740)
        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:716)
        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:703)
        at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:976)
        at org.apache.catalina.startup.HostConfig$DeployWar.run(HostConfig.java:1847)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75)
        at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:112)
        at org.apache.catalina.startup.HostConfig.deployWARs(HostConfig.java:761)
        at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:431)
        at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1575)
        at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:308)
        at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:123)
        at org.apache.catalina.util.LifecycleBase.setStateInternal(LifecycleBase.java:424)
        at org.apache.catalina.util.LifecycleBase.setState(LifecycleBase.java:367)
        at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:964)
        at org.apache.catalina.core.StandardHost.startInternal(StandardHost.java:839)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
        at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1425)
        at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1415)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75)
        at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:134)
        at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:941)
        at org.apache.catalina.core.StandardEngine.startInternal(StandardEngine.java:258)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
        at org.apache.catalina.core.StandardService.startInternal(StandardService.java:422)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
        at org.apache.catalina.core.StandardServer.startInternal(StandardServer.java:770)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
        at org.apache.catalina.startup.Catalina.start(Catalina.java:671)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:353)
        at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:493)

21-Dec-2017 11:20:42.847 INFO [main] org.apache.catalina.core.ApplicationContext.log Closing Spring root WebApplicationContext
21-Dec-2017 11:20:55.707 INFO [main] org.apache.catalina.core.ApplicationContext.log 1 Spring WebApplicationInitializers detected on classpath
21-Dec-2017 11:20:56.634 INFO [main] org.apache.catalina.core.ApplicationContext.log Initializing Spring root WebApplicationContext
21-Dec-2017 11:21:01.668 SEVERE [main] org.apache.catalina.core.StandardContext.filterStart Exception starting filter [javamelody]
 java.lang.NoClassDefFoundError: Could not initialize class java.awt.Color
        at net.bull.javamelody.JRobin.<clinit>(JRobin.java:58)
        at net.bull.javamelody.FilterContext.initCollect(FilterContext.java:230)
        at net.bull.javamelody.FilterContext.<init>(FilterContext.java:109)
        at net.bull.javamelody.MonitoringFilter.init(MonitoringFilter.java:130)
        at org.apache.catalina.core.ApplicationFilterConfig.initFilter(ApplicationFilterConfig.java:277)
        at org.apache.catalina.core.ApplicationFilterConfig.getFilter(ApplicationFilterConfig.java:258)
        at org.apache.catalina.core.ApplicationFilterConfig.<init>(ApplicationFilterConfig.java:104)
        at org.apache.catalina.core.StandardContext.filterStart(StandardContext.java:4491)
        at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5131)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:740)
        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:716)
        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:703)
        at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:976)
        at org.apache.catalina.startup.HostConfig$DeployWar.run(HostConfig.java:1847)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75)
        at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:112)
        at org.apache.catalina.startup.HostConfig.deployWARs(HostConfig.java:761)
        at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:431)
        at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1575)
        at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:308)
        at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:123)
        at org.apache.catalina.util.LifecycleBase.setStateInternal(LifecycleBase.java:424)
        at org.apache.catalina.util.LifecycleBase.setState(LifecycleBase.java:367)
        at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:964)
        at org.apache.catalina.core.StandardHost.startInternal(StandardHost.java:839)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
        at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1425)
        at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1415)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75)
        at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:134)
        at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:941)
        at org.apache.catalina.core.StandardEngine.startInternal(StandardEngine.java:258)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
        at org.apache.catalina.core.StandardService.startInternal(StandardService.java:422)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
        at org.apache.catalina.core.StandardServer.startInternal(StandardServer.java:770)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
        at org.apache.catalina.startup.Catalina.start(Catalina.java:671)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:353)
        at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:493)

21-Dec-2017 11:21:01.683 INFO [main] org.apache.catalina.core.ApplicationContext.log Closing Spring root WebApplicationContext
Comment 5 Remy Maucherat 2017-12-21 12:21:57 UTC
The fix will be in 9.0.3 and 8.5.25.