How to fix "Http11NioProtocol: Error reading request, ignored"

Question

My spring-boot application fails after start with an NPE in the tomcat server when running on azure kubernetes service with SSL.

First, what does work successfully: I have a minimal Spring-boot application created with Spring Initializr:

• Gradle project
• Java 11
• Spring Boot 2.1.8
• The only dependency: Spring Web

I want to use it with a kubernetes cluster on the azure cloud. For this, I have an Azure Kubernetes Service (AKS). And I use jib for building the docker image. Up to this point, everything works fine. I can deploy my docker image to the azure docker registry, start a kubernetes cluster (with 1 node) and I get my "hello world" after calling "http://public-ip:8443/hello". I use port 8443 but with normal http to make sure that this port is not the source of my problem.

I want my application to support HTTPS, therefore I made a self-signed certificate with keytool (like described here: Enable HTTPS with self-signed certificate in Spring Boot 2.0). This works fine on localhost. It also works inside minikube running on localhost. But when I use that docker image on AKS, my application fails a few seconds after startup.

I activated

logging.level.org.apache.tomcat=DEBUG
logging.level.org.apache.catalina=DEBUG

in my application.properties. The output of my application is:

2019-09-19 08:22:51.291  INFO 1 --- [           main] com.example.demo.DemoApplication         : Started DemoApplication in 9.623 seconds (JVM running for 10.419)
2019-09-19 08:22:53.775 DEBUG 1 --- [o-8443-Acceptor] o.apache.tomcat.util.threads.LimitLatch  : Counting up[https-jsse-nio-8443-Acceptor] latch=1
2019-09-19 08:22:58.764 DEBUG 1 --- [o-8443-Acceptor] o.apache.tomcat.util.threads.LimitLatch  : Counting up[https-jsse-nio-8443-Acceptor] latch=2
2019-09-19 08:22:58.793 DEBUG 1 --- [nio-8443-exec-1] org.apache.tomcat.util.modeler.Registry  : Managed= Tomcat:type=RequestProcessor,worker="https-jsse-nio-8443",name=HttpRequest1
2019-09-19 08:22:58.793 DEBUG 1 --- [nio-8443-exec-1] org.apache.tomcat.util.modeler.Registry  : Looking for descriptor 
2019-09-19 08:22:58.793 DEBUG 1 --- [nio-8443-exec-1] org.apache.tomcat.util.modeler.Registry  : Introspecting 
2019-09-19 08:22:58.793 DEBUG 1 --- [nio-8443-exec-1] m.m.MbeansDescriptorsIntrospectionSource : Introspected attribute virtualHost public java.lang.String org.apache.coyote.RequestInfo.getVirtualHost() null
<snipped 20 lines of "Introspected attribute xyz">
2019-09-19 08:22:58.796 DEBUG 1 --- [nio-8443-exec-1] m.m.MbeansDescriptorsIntrospectionSource : Introspected attribute lastRequestProcessingTime public long org.apache.coyote.RequestInfo.getLastRequestProcessingTime() public void org.apache.coyote.RequestInfo.setLastRequestProcessingTime(long)
2019-09-19 08:22:58.796 DEBUG 1 --- [nio-8443-exec-1] m.m.MbeansDescriptorsIntrospectionSource : Introspected attribute errorCount public int org.apache.coyote.RequestInfo.getErrorCount() public void org.apache.coyote.RequestInfo.setErrorCount(int)
2019-09-19 08:22:58.796 DEBUG 1 --- [nio-8443-exec-1] m.m.MbeansDescriptorsIntrospectionSource : Setting name: org.apache.coyote.RequestInfo
2019-09-19 08:22:58.797 DEBUG 1 --- [nio-8443-exec-1] o.a.tomcat.util.modeler.BaseModelMBean   : preRegister org.apache.coyote.RequestInfo@21c6ab25 Tomcat:type=RequestProcessor,worker="https-jsse-nio-8443",name=HttpRequest1
2019-09-19 08:22:58.797 ERROR 1 --- [nio-8443-exec-1] o.a.coyote.http11.Http11NioProtocol      : Error reading request, ignored

java.lang.NullPointerException: null
    at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.getSslSupport(NioEndpoint.java:1392) ~[tomcat-embed-core-9.0.24.jar:9.0.24]
    at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:853) ~[tomcat-embed-core-9.0.24.jar:9.0.24]
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1593) ~[tomcat-embed-core-9.0.24.jar:9.0.24]
    at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-embed-core-9.0.24.jar:9.0.24]
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na]
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na]
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-9.0.24.jar:9.0.24]
    at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]

Can anyone give me a hint what my problem might be? Thanks!

Answer 1

That is a known bug in Apache Tomcat 9.0.24. It is triggered by sending plain text to an TLS enabled connector. It is safe to ignore but since it is rather noisy you probably want to upgrade to the recently released 9.0.26 where this has been fixed.