You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@tomcat.apache.org by Eirik Lykken <ei...@protonmail.ch> on 2017/10/05 17:11:03 UTC
Tomcat 8.5.23 - Nio2 Connector - Error reading request, ignored
Dear All,
We are running Tomcat 8.5.23 production server on a CentOS 6.9 machine, Oracle JVM 1.8.0_144, and OpenSSL 1.1.0f. The server hosts a web application where almost all the traffic is https.
We used to have a Http11NioProtocol connector with Java SSL using HTTP 1.1 but we switched to Http2Protocol upgrade because of problems with Apple clients (KeepAlive timeout, server dropped the connection, etc..). We also switched to OpenSSL for ALPN.
Since then we have had several problems with the different connectors, all of them tested with Tomcat 8.5.16, 8.5.20 and 8.5.23.
- Http11NioProtocol has a memory leak, we experienced the same behaviour as this bug https://bz.apache.org/bugzilla/show_bug.cgi?id=57546 so we have to restart the server regularly.
- Http11AprProtocol runs fine but the JVM crashes unexpectedly with a core dump from time to time.
- Http11Nio2Protocol runs fine but some requests are not processed. We have not found a way to reproduce the problem but it happens once every 5 minutes. The server processes 1.13 million requests per day so it's one request failed every 4000 approximately. We can't reproduce the failed requests, but some crawling tools report them as if the server failed to respond (no status code)
This is the exception we get:
05-Oct-2017 17:13:32.535 SEVERE [https-openssl-nio2-94.229.64.230-443-exec-19701] org.apache.coyote.AbstractProtocol$ConnectionHandler.process Error reading request, ignored
java.lang.IllegalStateException
at org.apache.coyote.http2.Http2UpgradeHandler.fill(Http2UpgradeHandler.java:1314)
at org.apache.coyote.http2.Http2UpgradeHandler.fill(Http2UpgradeHandler.java:1290)
at org.apache.coyote.http2.Http2Parser.readConnectionPreface(Http2Parser.java:574)
at org.apache.coyote.http2.Http2UpgradeHandler.init(Http2UpgradeHandler.java:243)
at org.apache.coyote.http2.Http2UpgradeHandler.upgradeDispatch(Http2UpgradeHandler.java:310)
at org.apache.coyote.http11.upgrade.UpgradeProcessorInternal.dispatch(UpgradeProcessorInternal.java:54)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:53)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
at org.apache.tomcat.util.net.Nio2Endpoint$SocketProcessor.doRun(Nio2Endpoint.java:1693)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
at org.apache.tomcat.util.net.AbstractEndpoint.processSocket(AbstractEndpoint.java:946)
at org.apache.tomcat.util.net.SecureNio2Channel$HandshakeWriteCompletionHandler.completed(SecureNio2Channel.java:115)
at org.apache.tomcat.util.net.SecureNio2Channel$HandshakeWriteCompletionHandler.completed(SecureNio2Channel.java:108)
at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:126)
at sun.nio.ch.Invoker.invokeDirect(Invoker.java:157)
at sun.nio.ch.UnixAsynchronousSocketChannelImpl.implWrite(UnixAsynchronousSocketChannelImpl.java:736)
at sun.nio.ch.AsynchronousSocketChannelImpl.write(AsynchronousSocketChannelImpl.java:382)
at sun.nio.ch.AsynchronousSocketChannelImpl.write(AsynchronousSocketChannelImpl.java:399)
at java.nio.channels.AsynchronousSocketChannel.write(AsynchronousSocketChannel.java:577)
at org.apache.tomcat.util.net.SecureNio2Channel.handshakeInternal(SecureNio2Channel.java:273)
at org.apache.tomcat.util.net.SecureNio2Channel.handshake(SecureNio2Channel.java:204)
at org.apache.tomcat.util.net.Nio2Endpoint$SocketProcessor.doRun(Nio2Endpoint.java:1671)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
at org.apache.tomcat.util.net.AbstractEndpoint.processSocket(AbstractEndpoint.java:946)
at org.apache.tomcat.util.net.SecureNio2Channel$HandshakeReadCompletionHandler.completed(SecureNio2Channel.java:98)
at org.apache.tomcat.util.net.SecureNio2Channel$HandshakeReadCompletionHandler.completed(SecureNio2Channel.java:91)
at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:126)
at sun.nio.ch.Invoker$2.run(Invoker.java:218)
at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:748)
This is our current Connector configuration:
<Connector port="443" address="xxx" protocol="org.apache.coyote.http11.Http11Nio2Protocol" SSLEnabled="true"
maxThreads="1500" acceptCount="5000" scheme="https" secure="true"
defaultSSLHostConfigName="xxx"
hostName="xxx"
connectionTimeout="70000"
URIEncoding="UTF-8"
server="Apache"
enableLookups="false"
compression="on" compressionMinSize="2048"
compressableMimeType="text/html,text/xml,text/csv,text/css,text/javascript,text/html,text/plain,application/javascript,application/x-javascript"
sslImplementationName="org.apache.tomcat.util.net.openssl.OpenSSLImplementation"
><UpgradeProtocol className="org.apache.coyote.http2.Http2Protocol" readTimeout="70000" writeTimeout="70000" maxConcurrentStreams="400" maxConcurrentStreamExecution="400"/>
<SSLHostConfig hostName="xxx"
disableSessionTickets="true"
protocols= "TLSv1,TLSv1.1,TLSv1.2"
ciphers="ECDHE-RSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-AES256-GCM-SHA384:DHE-RSA-AES128-GCM-SHA256:DHE-DSS-AES128-GCM-SHA256:kEDH+AESGCM:ECDHE-RSA-AES128-SHA256:ECDHE-ECDSA-AES128-SHA256:ECDHE-RSA-AES128-SHA:ECDHE-ECDSA-AES128-SHA:ECDHE-RSA-AES256-SHA384:ECDHE-ECDSA-AES256-SHA384:ECDHE-RSA-AES256-SHA:ECDHE-ECDSA-AES256-SHA:DHE-RSA-AES128-SHA256:DHE-RSA-AES128-SHA:DHE-DSS-AES128-SHA256:DHE-RSA-AES256-SHA256:DHE-DSS-AES256-SHA:DHE-RSA-AES256-SHA:ECDHE-RSA-DES-CBC3-SHA:ECDHE-ECDSA-DES-CBC3-SHA:AES128-GCM-SHA256:AES256-GCM-SHA384:AES128-SHA256:AES256-SHA256:AES128-SHA:AES256-SHA:AES:DES-CBC3-SHA:HIGH:!aNULL:!eNULL:!EXPORT:!DES:!RC4:!MD5:!PSK:!aECDH:!EDH-DSS-DES-CBC3-SHA:!EDH-RSA-DES-CBC3-SHA:!KRB5-DES-CBC3-SHA"
honorCipherOrder="true"
>
<Certificate certificateFile="xxx" certificateKeyFile="xxx" certificateChainFile="xxx"/>
</SSLHostConfig>
</Connector>
We have experimented with different parameters of the Http2Protocol connector to improve performance and control the leak with Http11NioProtocol connector but the exceptions are there with any of the values or removing the extra parameters.
We also tried Tomcat/9.0.0.M26 and the exception we got was:
22-Sep-2017 19:16:26.872 SEVERE [https-openssl-nio2-94.229.64.230-443-exec-229] org.apache.catalina.core.StandardWrapperValve.invoke Servlet.service() for servlet [default] in context with path [] threw exception
java.lang.NullPointerException
at org.apache.coyote.http2.HpackEncoder$TableEntry.access$100(HpackEncoder.java:339)
at org.apache.coyote.http2.HpackEncoder.findInTable(HpackEncoder.java:297)
at org.apache.coyote.http2.HpackEncoder.encode(HpackEncoder.java:150)
at org.apache.coyote.http2.Http2UpgradeHandler.doWriteHeaders(Http2UpgradeHandler.java:573)
at org.apache.coyote.http2.Http2AsyncUpgradeHandler.writeHeaders(Http2AsyncUpgradeHandler.java:138)
at org.apache.coyote.http2.Stream.writeHeaders(Stream.java:411)
at org.apache.coyote.http2.StreamProcessor.prepareResponse(StreamProcessor.java:100)
...
Any suggestions?
Thanks in advance.
Eirik.
Re: Tomcat 8.5.23 - Nio2 Connector - Error reading request, ignored
Posted by Rémy Maucherat <re...@apache.org>.
On Thu, Oct 5, 2017 at 7:11 PM, Eirik Lykken <ei...@protonmail.ch>
wrote:
>
> 05-Oct-2017 17:13:32.535 SEVERE [https-openssl-nio2-94.229.64.230-443-exec-19701]
> org.apache.coyote.AbstractProtocol$ConnectionHandler.process Error
> reading request, ignored
> java.lang.IllegalStateException
> at org.apache.coyote.http2.Http2UpgradeHandler.fill(Http2Upgrad
> eHandler.java:1314)
> at org.apache.coyote.http2.Http2UpgradeHandler.fill(Http2Upgrad
> eHandler.java:1290)
> at org.apache.coyote.http2.Http2Parser.readConnectionPreface(Ht
> tp2Parser.java:574)
> at org.apache.coyote.http2.Http2UpgradeHandler.init(Http2Upgrad
> eHandler.java:243)
> at org.apache.coyote.http2.Http2UpgradeHandler.upgradeDispatch(
> Http2UpgradeHandler.java:310)
> at org.apache.coyote.http11.upgrade.UpgradeProcessorInternal.di
> spatch(UpgradeProcessorInternal.java:54)
> at org.apache.coyote.AbstractProcessorLight.process(AbstractPro
> cessorLight.java:53)
> at org.apache.coyote.AbstractProtocol$ConnectionHandler.process
> (AbstractProtocol.java:868)
> at org.apache.tomcat.util.net.Nio2Endpoint$SocketProcessor.doRu
> n(Nio2Endpoint.java:1693)
> at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketPro
> cessorBase.java:49)
> at org.apache.tomcat.util.net.AbstractEndpoint.processSocket(Ab
> stractEndpoint.java:946)
> at org.apache.tomcat.util.net.SecureNio2Channel$HandshakeWriteC
> ompletionHandler.completed(SecureNio2Channel.java:115)
> at org.apache.tomcat.util.net.SecureNio2Channel$HandshakeWriteC
> ompletionHandler.completed(SecureNio2Channel.java:108)
> at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:126)
> at sun.nio.ch.Invoker.invokeDirect(Invoker.java:157)
> at sun.nio.ch.UnixAsynchronousSocketChannelImpl.implWrite(UnixA
> synchronousSocketChannelImpl.java:736)
> at sun.nio.ch.AsynchronousSocketChannelImpl.write(AsynchronousS
> ocketChannelImpl.java:382)
> at sun.nio.ch.AsynchronousSocketChannelImpl.write(AsynchronousS
> ocketChannelImpl.java:399)
> at java.nio.channels.AsynchronousSocketChannel.write(Asynchrono
> usSocketChannel.java:577)
> at org.apache.tomcat.util.net.SecureNio2Channel.handshakeIntern
> al(SecureNio2Channel.java:273)
> at org.apache.tomcat.util.net.SecureNio2Channel.handshake(Secur
> eNio2Channel.java:204)
> at org.apache.tomcat.util.net.Nio2Endpoint$SocketProcessor.doRu
> n(Nio2Endpoint.java:1671)
> at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketPro
> cessorBase.java:49)
> at org.apache.tomcat.util.net.AbstractEndpoint.processSocket(Ab
> stractEndpoint.java:946)
> at org.apache.tomcat.util.net.SecureNio2Channel$HandshakeReadCo
> mpletionHandler.completed(SecureNio2Channel.java:98)
> at org.apache.tomcat.util.net.SecureNio2Channel$HandshakeReadCo
> mpletionHandler.completed(SecureNio2Channel.java:91)
> at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:126)
> at sun.nio.ch.Invoker$2.run(Invoker.java:218)
> at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousCh
> annelGroupImpl.java:112)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPool
> Executor.java:1149)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoo
> lExecutor.java:624)
> at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.r
> un(TaskThread.java:61)
> at java.lang.Thread.run(Thread.java:748)
>
I think the state of the handshake is most likely ok despite the weird
looking stack. The code doing blocking SSL reads is complex also, it would
be returning 0 bytes for a blocking read in this case. To examine the issue
it would need to be reproduced. Although it might simply be an IO error
that doesn't get reported as it should and you see that stack instead (but
the result is then the same).
>
> This is our current Connector configuration:
>
> <Connector port="443" address="xxx" protocol="org.apache.coyote.http11.Http11Nio2Protocol"
> SSLEnabled="true"
> maxThreads="1500" acceptCount="5000" scheme="https" secure="true"
> defaultSSLHostConfigName="xxx"
> hostName="xxx"
> connectionTimeout="70000"
> URIEncoding="UTF-8"
> server="Apache"
> enableLookups="false"
> compression="on" compressionMinSize="2048"
> compressableMimeType="text/html,text/xml,text/csv,text/css,t
> ext/javascript,text/html,text/plain,application/javascript,a
> pplication/x-javascript"
> sslImplementationName="org.apache.tomcat.util.net.openssl.Op
> enSSLImplementation"
>
> ><UpgradeProtocol className="org.apache.coyote.http2.Http2Protocol"
> readTimeout="70000" writeTimeout="70000" maxConcurrentStreams="400"
> maxConcurrentStreamExecution="400"/>
>
maxConcurrentStreamExecution="400" that's waaaaay too much, don't do that.
> We have experimented with different parameters of the Http2Protocol
> connector to improve performance and control the leak with
> Http11NioProtocol connector but the exceptions are there with any of the
> values or removing the extra parameters.
>
> We also tried Tomcat/9.0.0.M26 and the exception we got was:
>
> 22-Sep-2017 19:16:26.872 SEVERE [https-openssl-nio2-94.229.64.230-443-exec-229]
> org.apache.catalina.core.StandardWrapperValve.invoke Servlet.service()
> for servlet [default] in context with path [] threw exception
> java.lang.NullPointerException
> at org.apache.coyote.http2.HpackEncoder$TableEntry.access$100(H
> packEncoder.java:339)
> at org.apache.coyote.http2.HpackEncoder.findInTable(HpackEncode
> r.java:297)
> at org.apache.coyote.http2.HpackEncoder.encode(HpackEncoder.jav
> a:150)
> at org.apache.coyote.http2.Http2UpgradeHandler.doWriteHeaders(H
> ttp2UpgradeHandler.java:573)
> at org.apache.coyote.http2.Http2AsyncUpgradeHandler.writeHeader
> s(Http2AsyncUpgradeHandler.java:138)
> at org.apache.coyote.http2.Stream.writeHeaders(Stream.java:411)
> at org.apache.coyote.http2.StreamProcessor.prepareResponse(Stre
> amProcessor.java:100)
> ...
>
>
I don't understand how this stack can happen.
Rémy