Bug 63814 - Socket timeout -1 no longer allowed since Java 13, leading to IllegalArgumentException and unit test hang for TestAbstractAjpProcessor
Summary: Socket timeout -1 no longer allowed since Java 13, leading to IllegalArgument...
Status: RESOLVED FIXED
Alias: None
Product: Tomcat 7
Classification: Unclassified
Component: Catalina (show other bugs)
Version: trunk
Hardware: PC All
: P2 normal (vote)
Target Milestone: ---
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
: 63837 (view as bug list)
Depends on:
Blocks:
 
Reported: 2019-10-08 11:08 UTC by Rainer Jung
Modified: 2019-10-11 15:07 UTC (History)
1 user (show)


Attachments
Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.
Description Rainer Jung 2019-10-08 11:08:17 UTC 
I observed the same hang on three different Linux systems when using 
OpenJDK 13 (GA, Build 33). The hang is always in 
TestAbstractAjpProcessor for NIO in test testKeepAlive. The hanging JVM 
process only shows the AJP client (stacks from 7.0.96, but problem still in 7.0.97):

"main" #1 prio=5 os_prio=0 cpu=1497.40ms elapsed=18779.47s 
tid=0x00007ff040017800 nid=0x7ea3 runnable  [0x00007ff046b74000]
    java.lang.Thread.State: RUNNABLE
         at sun.nio.ch.SocketDispatcher.read0(java.base@13-ea/Native Method)
         at 
sun.nio.ch.SocketDispatcher.read(java.base@13-ea/SocketDispatcher.java:47)
         at 
sun.nio.ch.NioSocketImpl.tryRead(java.base@13-ea/NioSocketImpl.java:262)
         at 
sun.nio.ch.NioSocketImpl.implRead(java.base@13-ea/NioSocketImpl.java:313)
         at 
sun.nio.ch.NioSocketImpl.read(java.base@13-ea/NioSocketImpl.java:351)
         at 
sun.nio.ch.NioSocketImpl$1.read(java.base@13-ea/NioSocketImpl.java:802)
         at 
java.net.Socket$SocketInputStream.read(java.base@13-ea/Socket.java:919)
         at 
org.apache.coyote.ajp.SimpleAjpClient.read(SimpleAjpClient.java:390)
         at 
org.apache.coyote.ajp.SimpleAjpClient.readMessage(SimpleAjpClient.java:365)
         at 
org.apache.coyote.ajp.SimpleAjpClient.cping(SimpleAjpClient.java:350)
         at 
org.apache.coyote.ajp.TestAbstractAjpProcessor.testKeepAlive(TestAbstractAjpProcessor.java:526)
...

but the log indicates a problem:

INFO: Starting test case [testKeepAlive]
Jul 26, 2019 5:20:37 PM org.apache.coyote.AbstractProtocol init
INFO: Initializing ProtocolHandler ["ajp-nio-127.0.0.1-auto-6"]
Jul 26, 2019 5:20:37 PM org.apache.coyote.AbstractProtocol init
SEVERE: Failed to initialize end point associated with ProtocolHandler 
["ajp-nio-127.0.0.1-auto-6-34726"]
java.lang.IllegalArgumentException: timeout < 0
         at 
java.base/sun.nio.ch.ServerSocketAdaptor.setSoTimeout(ServerSocketAdaptor.java:153)
         at 
org.apache.tomcat.util.net.NioEndpoint.bind(NioEndpoint.java:477)
         at 
org.apache.tomcat.util.net.AbstractEndpoint.init(AbstractEndpoint.java:728)
         at 
org.apache.coyote.AbstractProtocol.init(AbstractProtocol.java:452)
         at 
org.apache.catalina.connector.Connector.initInternal(Connector.java:978)
         at 
org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:102)
         at 
org.apache.catalina.core.StandardService.initInternal(StandardService.java:560)
         at 
org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:102)
         at 
org.apache.catalina.core.StandardServer.initInternal(StandardServer.java:840)
         at 
org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:102)
         at 
org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:135)
         at org.apache.catalina.startup.Tomcat.start(Tomcat.java:449)
         at 
org.apache.catalina.startup.TomcatBaseTest$TomcatWithFastSessionIDs.start(TomcatBaseTest.java:808)
         at 
org.apache.coyote.ajp.TestAbstractAjpProcessor.testKeepAlive(TestAbstractAjpProcessor.java:513)
         at 
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native 
Method)
         at 
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
         at 
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
         at java.base/java.lang.reflect.Method.invoke(Method.java:567)
         at 
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
         at 
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
         at 
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
         at 
org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
         at 
org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
         at 
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
         at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:55)
         at org.junit.rules.RunRules.evaluate(RunRules.java:20)
         at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
         at 
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
         at 
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
         at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
         at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
         at 
org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
         at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
         at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
         at 
org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
         at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
         at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:38)
         at 
org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:536)
         at 
org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:1178)
         at 
org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:1032)

Jul 26, 2019 5:20:37 PM org.apache.catalina.core.StandardService 
initInternal
SEVERE: Failed to initialize connector 
[Connector[org.apache.coyote.ajp.AjpNioProtocol-auto-6]]
org.apache.catalina.LifecycleException: Failed to initialize component 
[Connector[org.apache.coyote.ajp.AjpNioProtocol-auto-6]]
         at 
org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:107)
         at 
org.apache.catalina.core.StandardService.initInternal(StandardService.java:560)
         at 
org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:102)
         at 
org.apache.catalina.core.StandardServer.initInternal(StandardServer.java:840)
         at 
org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:102)
         at 
org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:135)
         at org.apache.catalina.startup.Tomcat.start(Tomcat.java:449)
         at 
org.apache.catalina.startup.TomcatBaseTest$TomcatWithFastSessionIDs.start(TomcatBaseTest.java:808)
         at 
org.apache.coyote.ajp.TestAbstractAjpProcessor.testKeepAlive(TestAbstractAjpProcessor.java:513)
         at 
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native 
Method)
         at 
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
         at 
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
         at java.base/java.lang.reflect.Method.invoke(Method.java:567)
         at 
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
         at 
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
         at 
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
         at 
org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
         at 
org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
         at 
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
         at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:55)
         at org.junit.rules.RunRules.evaluate(RunRules.java:20)
         at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
         at 
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
         at 
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
         at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
         at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
         at 
org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
         at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
         at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
         at 
org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
         at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
         at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:38)
         at 
org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:536)
         at 
org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:1178)
         at 
org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:1032)
Caused by: org.apache.catalina.LifecycleException: Protocol handler 
initialization failed
         at 
org.apache.catalina.connector.Connector.initInternal(Connector.java:980)
         at 
org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:102)
         ... 34 more
Caused by: java.lang.IllegalArgumentException: timeout < 0
         at 
java.base/sun.nio.ch.ServerSocketAdaptor.setSoTimeout(ServerSocketAdaptor.java:153)
         at 
org.apache.tomcat.util.net.NioEndpoint.bind(NioEndpoint.java:477)
         at 
org.apache.tomcat.util.net.AbstractEndpoint.init(AbstractEndpoint.java:728)
         at 
org.apache.coyote.AbstractProtocol.init(AbstractProtocol.java:452)
         at 
org.apache.catalina.connector.Connector.initInternal(Connector.java:978)
         ... 35 more
Jul 26, 2019 5:20:37 PM org.apache.catalina.core.StandardService 
startInternal
INFO: Starting service Tomcat
Jul 26, 2019 5:20:37 PM org.apache.catalina.core.StandardEngine 
startInternal
INFO: Starting Servlet Engine: Apache Tomcat/7.0.96
Jul 26, 2019 5:20:37 PM org.apache.catalina.startup.TldConfig execute
INFO: At least one JAR was scanned for TLDs yet contained no TLDs. 
Enable debug logging for this logger for a complete list of JARs that 
were scanned but no TLDs were found in them. Skipping unneeded JARs 
during scanning can improve startup time and JSP compilation time.

The test seems to set a socket timeout to -1, which is no longer allowed 
by the following change:

https://github.com/unofficial-openjdk/openjdk/commit/3a77350f194df226cb6d618589a59d36fae9dc9c

in JDK 13+.

The magic value -1 for timeouts are more frequent in our code, but I 
don't know which of these might end up in a setSoTimeout() call.

I haven't checked TC 8.5 and 9 yet.
Comment 1 Remy Maucherat 2019-10-08 11:22:32 UTC 
The javadoc already said the value must be > 0 and it's handled in 8.5 and 9.
Comment 2 Remy Maucherat 2019-10-08 11:37:22 UTC 
The fix will be in 7.0.98.
Comment 3 Remy Maucherat 2019-10-11 15:07:27 UTC 
*** Bug 63837 has been marked as a duplicate of this bug. ***