Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

SSLEngine closed already Error #536

Closed
pluttrell opened this issue Nov 28, 2018 · 12 comments
Closed

SSLEngine closed already Error #536

pluttrell opened this issue Nov 28, 2018 · 12 comments
Labels
type/bug A general bug
Milestone
0.7.13.RELEASE

Comments

@pluttrell
Copy link

Steps to reproduce

This problem happens intermittently. We're seeing it maybe once out of 50 requests from our full lifecycle health check calls.

Reactor Core version

3.2.2.RELEASE, which we're including with spring boot 2.1.0.RELEASE (latest at the time of this report).

JVM version (e.g. java -version)

openjdk version "11.0.1" 2018-10-16
OpenJDK Runtime Environment (build 11.0.1+13-Debian-2)
OpenJDK 64-Bit Server VM (build 11.0.1+13-Debian-2, mixed mode, sharing)

OS version (e.g. uname -a)

Linux 0c553deebac8 4.9.125-linuxkit #1 SMP Fri Sep 7 08:20:28 UTC 2018 x86_64 GNU/Linux

Actual behavior

2018-11-28 16:45:04.873 ERROR 1 --- [-client-epoll-8] r.n.resources.PooledConnectionProvider   : [id: 0x3895fc60, L:/100.97.182.70:48794 - R:{our-dns-hostname}/{one-of-our-ec2-public-ips}:443] Pooled connection observed an error

javax.net.ssl.SSLException: SSLEngine closed already
	at io.netty.handler.ssl.SslHandler.wrap(...)(Unknown Source) ~[netty-handler-4.1.29.Final.jar!/:4.1.29.Final]

Full stacktrace:

reactor.core.Exceptions$ReactiveException: javax.net.ssl.SSLException: SSLEngine closed already
	at reactor.core.Exceptions.propagate(Exceptions.java:326) ~[reactor-core-3.2.2.RELEASE.jar!/:3.2.2.RELEASE]
	at reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:91) ~[reactor-core-3.2.2.RELEASE.jar!/:3.2.2.RELEASE]
	at reactor.core.publisher.Mono.block(Mono.java:1475) ~[reactor-core-3.2.2.RELEASE.jar!/:3.2.2.RELEASE]
	at {our-code}
	at jdk.internal.reflect.GeneratedMethodAccessor82.invoke(Unknown Source) ~[na:na]
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
	at java.base/java.lang.reflect.Method.invoke(Method.java:566) ~[na:na]
	at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:215) ~[spring-web-5.1.2.RELEASE.jar!/:5.1.2.RELEASE]
	at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:142) ~[spring-web-5.1.2.RELEASE.jar!/:5.1.2.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:102) ~[spring-webmvc-5.1.2.RELEASE.jar!/:5.1.2.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:895) ~[spring-webmvc-5.1.2.RELEASE.jar!/:5.1.2.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:800) ~[spring-webmvc-5.1.2.RELEASE.jar!/:5.1.2.RELEASE]
	at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) ~[spring-webmvc-5.1.2.RELEASE.jar!/:5.1.2.RELEASE]
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1038) ~[spring-webmvc-5.1.2.RELEASE.jar!/:5.1.2.RELEASE]
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:942) ~[spring-webmvc-5.1.2.RELEASE.jar!/:5.1.2.RELEASE]
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:998) ~[spring-webmvc-5.1.2.RELEASE.jar!/:5.1.2.RELEASE]
	at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:901) ~[spring-webmvc-5.1.2.RELEASE.jar!/:5.1.2.RELEASE]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:660) ~[tomcat-embed-core-9.0.12.jar!/:9.0.12]
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:875) ~[spring-webmvc-5.1.2.RELEASE.jar!/:5.1.2.RELEASE]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:741) ~[tomcat-embed-core-9.0.12.jar!/:9.0.12]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) ~[tomcat-embed-core-9.0.12.jar!/:9.0.12]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.12.jar!/:9.0.12]
	at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53) ~[tomcat-embed-websocket-9.0.12.jar!/:9.0.12]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.12.jar!/:9.0.12]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.12.jar!/:9.0.12]
	at org.springframework.boot.actuate.web.trace.servlet.HttpTraceFilter.doFilterInternal(HttpTraceFilter.java:90) ~[spring-boot-actuator-2.1.0.RELEASE.jar!/:2.1.0.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-5.1.2.RELEASE.jar!/:5.1.2.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.12.jar!/:9.0.12]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.12.jar!/:9.0.12]
	at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99) ~[spring-web-5.1.2.RELEASE.jar!/:5.1.2.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-5.1.2.RELEASE.jar!/:5.1.2.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.12.jar!/:9.0.12]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.12.jar!/:9.0.12]
	at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:92) ~[spring-web-5.1.2.RELEASE.jar!/:5.1.2.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-5.1.2.RELEASE.jar!/:5.1.2.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.12.jar!/:9.0.12]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.12.jar!/:9.0.12]
	at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:93) ~[spring-web-5.1.2.RELEASE.jar!/:5.1.2.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-5.1.2.RELEASE.jar!/:5.1.2.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.12.jar!/:9.0.12]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.12.jar!/:9.0.12]
	at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.filterAndRecordMetrics(WebMvcMetricsFilter.java:154) ~[spring-boot-actuator-2.1.0.RELEASE.jar!/:2.1.0.RELEASE]
	at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.filterAndRecordMetrics(WebMvcMetricsFilter.java:122) ~[spring-boot-actuator-2.1.0.RELEASE.jar!/:2.1.0.RELEASE]
	at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:107) ~[spring-boot-actuator-2.1.0.RELEASE.jar!/:2.1.0.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-5.1.2.RELEASE.jar!/:5.1.2.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.12.jar!/:9.0.12]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.12.jar!/:9.0.12]
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:200) ~[spring-web-5.1.2.RELEASE.jar!/:5.1.2.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-5.1.2.RELEASE.jar!/:5.1.2.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.12.jar!/:9.0.12]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.12.jar!/:9.0.12]
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199) ~[tomcat-embed-core-9.0.12.jar!/:9.0.12]
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) ~[tomcat-embed-core-9.0.12.jar!/:9.0.12]
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:490) ~[tomcat-embed-core-9.0.12.jar!/:9.0.12]
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139) ~[tomcat-embed-core-9.0.12.jar!/:9.0.12]
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92) ~[tomcat-embed-core-9.0.12.jar!/:9.0.12]
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74) ~[tomcat-embed-core-9.0.12.jar!/:9.0.12]
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343) ~[tomcat-embed-core-9.0.12.jar!/:9.0.12]
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:408) ~[tomcat-embed-core-9.0.12.jar!/:9.0.12]
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) ~[tomcat-embed-core-9.0.12.jar!/:9.0.12]
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:770) ~[tomcat-embed-core-9.0.12.jar!/:9.0.12]
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1415) ~[tomcat-embed-core-9.0.12.jar!/:9.0.12]
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-embed-core-9.0.12.jar!/:9.0.12]
	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.12.jar!/:9.0.12]
	at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]
	Suppressed: java.lang.Exception: #block terminated with an error
		at reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:93) ~[reactor-core-3.2.2.RELEASE.jar!/:3.2.2.RELEASE]
		... 66 common frames omitted
Caused by: javax.net.ssl.SSLException: SSLEngine closed already
	at io.netty.handler.ssl.SslHandler.wrap(...)(Unknown Source) ~[netty-handler-4.1.29.Final.jar!/:4.1.29.Final]

Expected behavior

If the root cause is a bug, naturally the expected behavior would be for it to work.

If the root cause is an SSL issue with the service that we're connecting to, then it would much more useful to receive an error message that indicates what the actual problem.
@simonbasle simonbasle transferred this issue from reactor/reactor-core Nov 29, 2018
@violetagg
Copy link
Member

@pluttrell I see some stack trace from Tomcat so may be that's the server and some stack trace from Reactor Netty Http Client, but what's the scenario that you are executing?

@violetagg violetagg added the for/user-attention This issue needs user attention (feedback, rework, etc...) label Nov 29, 2018
@pluttrell
Copy link
Author

Not exactly sure what you mean by 'scenario', but perhaps this info will help. This is a Spring Boot service based on org.springframework.boot:spring-boot-starter-web, which includes Tomcat. We would have used the WebFlux version, but part of the implementation requires relational db access, which isn't reactive.

As part of responding to one of the requests, we're using the WebClient to make a call to another service. Here's an example of the code:

webClient
  .post()
  .uri("https://...")
  .header(HttpHeaders.CONTENT_TYPE, MediaType.APPLICATION_JSON_VALUE)
  .body(Mono.just(car), Car.class)
  .retrieve()
  .onStatus(HttpStatus::is4xxClientError, clientResponse -> ...)
  .bodyToMono(ReservationResource.class);

Does that help?

@violetagg violetagg added type/bug A general bug and removed for/user-attention This issue needs user attention (feedback, rework, etc...) labels Nov 30, 2018
@violetagg violetagg added this to the 0.7.13.RELEASE milestone Nov 30, 2018
@violetagg
Copy link
Member

@pluttrell I committed a fix, so please try it 0.7.13.BUILD-SNAPSHOT/0.8.4.BUILD-SNAPSHOT.
Snapshots repository https://repo.spring.io/snapshot
We can reopen the issue if there are still issues.

This was referenced Nov 30, 2018
Merged
Closed
Closed
@dave-fl
Copy link

dave-fl commented Feb 2, 2019

@violetagg This is pretty easy to reproduce on Californium 0.85 snapshot.

Create two gateways and a responsive back end.

E.g Gateway 1 -> Gateway 2 -> Back End

Set a timeout of 500ms on Gateway 1.

Setup a gatling script which makes many calls < 500 ms (GET and POST). And setup a single call that will take longer than 500ms (GET and POST).

You will end up with the following in the gateway 1 logs. Gateway 2 is fine.

2019-02-02T14:13:44.78-0500 [APP/PROC/WEB/0] OUT javax.net.ssl.SSLException: SSLEngine closed already
2019-02-02T14:13:44.78-0500 [APP/PROC/WEB/0] OUT     at io.netty.handler.ssl.SslHandler.wrap(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar!/:4.1.33.Final]

@dave-fl
Copy link

dave-fl commented Feb 2, 2019

Sample script.

val scn = scenario("RecordedSimulation")
	.asLongAs(session => (System.currentTimeMillis - start) < duration) {
		exec(http("request_0")
			.get("/api/test/fast").check(status.is(200)))
		.exec(http("request_1")
			.post("/api/test/echo")
			.headers(headers_post)
			.body(rawBody).check(status.is(200)))
		.exec(http("request_2")
			.get("/api/test/medium").check(status.is(200)))
		.exec(http("request_5")
			.get("/api/test/user-defined?millis=550").check(status.in(200,504)))
		.exec(http("request_6")
			.post("/api/test/echo-delay?millis=550")
			.headers(headers_post)
			.body(rawBody).check(status.in(200,504)))


	}

@violetagg
Copy link
Member

@dave-fl Do you have SSL only for the origin or also for gateway2?

@dave-fl
Copy link

dave-fl commented Feb 9, 2019 •
edited
Loading

@violetagg Both. All my tests always have SSL turned on.

@fern4n
Copy link

fern4n commented Feb 13, 2019

I have a service running Spring Boot v2.1.2.RELEASE (reactor-core v3.2.5.RELEASE & reactor-netty v0.8.4.RELEASE) and it uses WebClient to communicate with other backend services.

I have the same error in my logs:

2019-02-13T10:02:01.826+01:00` [level=ERROR thread=reactor-http-nio-37 logger=r.n.h.c.HttpClientConnect ] The connection observed an error
javax.net.ssl.SSLException: SSLEngine closed already
	at io.netty.handler.ssl.SslHandler.wrap(...)(Unknown Source)

@muhmud
Copy link

muhmud commented Feb 24, 2019

0.8.5 fixed this for me

@anatoliy-balakirev
Copy link

Getting similar error with reactor-netty 0.8.5:

2019-05-22 13:17:21.260 ERROR [service_name,5ea1a26deac14023,5ea1a26deac14023,87c71bdd9433fa15,2a1f2e7b-e4e7-430d-9b9b-d887790951c6] 1 --- [reactor-http-epoll-2]  o.s.w.s.a.HttpWebHandlerAdapter:298 : [36a69c8b] Error [javax.net.ssl.SSLException: SSLEngine closed already] for HTTP GET "/user/2a1f2e7b-e4e7-430d-9b9b-d887790951c6/subscription", but ServerHttpResponse already committed (404 NOT_FOUND)

2019-05-22 13:17:21.264 ERROR [service_name,5ea1a26deac14023,5ea1a26deac14023,87c71bdd9433fa15,2a1f2e7b-e4e7-430d-9b9b-d887790951c6] 1 --- [reactor-http-epoll-2]  r.n.h.s.HttpServerOperations:319 : [id: 0x36a69c8b, L:/100.96.17.84:7003 - R:/100.96.21.34:35364] Error finishing response. Closing connection

javax.net.ssl.SSLException: SSLEngine closed already
	at io.netty.handler.ssl.SslHandler.wrap(...)(Unknown Source)

Happens sporadically. Can't find any patterns in logs.

@venkatnpedada
Copy link

Getting similar exception with reactor-netty 0.8.5 & 0.8.6

Cloud Gateway version:2.1.3 RELEASE
Reactor Netty version: 0.8.5 RELEASE

In our production system, we are observing "javax.net.ssl.SSLException: SSLEngine closed already" exceptions. The exception encounter rate depending on the route count and traffic.

I'm using the elastic pool(default) and below is the stack trace from logs:

reactor-http-nio-150 HttpClientConnect - [id: 0x21e26b17, L:/127.0.0.1:29974 - R:localhost/127.0.0.1:8872] The connection observed an error
javax.net.ssl.SSLException: SSLEngine closed already
at io.netty.handler.ssl.SslHandler.wrap(...)(Unknown Source)

I am suspecting the connection is already closed on other end, but elastic connection pool is still trying to use the same connection which is causing this issue. seems netty connection pool not doing health checks whether the connection is already broken or not.

@nnanda2016
Copy link

This is happening in reactor-netty 0.8.9 version as well. (BOM: Californium-SR9)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
type/bug A general bug
Projects
None yet
Milestone
0.7.13.RELEASE
Development

No branches or pull requests
8 participants
@violetagg @fern4n @dave-fl @pluttrell @muhmud @anatoliy-balakirev @nnanda2016 @venkatnpedada