Skip to content

调用微服务接口报heartbeat fail,Failed to create SSL connection #1659

@Astronaut24

Description

@Astronaut24

微服务之间调用接口,服务端日志先报了heartbeat fail,message: Failed to create SSL connection,客户端在调用该接口时经常出现handshake timed out错误,现象是接口性能下降了,接口偶尔调用失败,请问可能是什么原因引起的?

服务端日志:
[2020/03/16 16:30:16.720][ERROR][PUT /v4/default/registry/microservices/b44f40294f56477d7c961080f821d440c9012694/instances/31132854675811ea9b65482b3c4d5e1f/heartbeat fail, endpoint is 18.35.41.171:30100, message: Failed to create SSL connection][org.apache.servicecomb.serviceregistry.client.http.RestUtils][lambda$null$1,95][registry-vert.x-eventloop-thread-0]PUT /v4/default/registry/microservices/b44f40294f56477d7c961080f821d440c9012694/instances/31132854675811ea9b65482b3c4d5e1f/heartbeat fail, endpoint is 18.35.41.171:30100, message: Failed to create SSL connection
[2020/03/16 16:30:22.303][WARN][invoke service [/v4/default/registry/microservices/b44f40294f56477d7c961080f821d440c9012694/instances/31132854675811ea9b65482b3c4d5e1f/heartbeat] failed, retry.][org.apache.servicecomb.serviceregistry.client.http.ServiceRegistryClientImpl][retry,105][registry-vert.x-eventloop-thread-0]invoke service [/v4/default/registry/microservices/b44f40294f56477d7c961080f821d440c9012694/instances/31132854675811ea9b65482b3c4d5e1f/heartbeat] failed, retry.
[2020/03/16 16:30:26.380][INFO][Change service center address from 18.35.41.171:30100 to 18.35.41.171:30100][org.apache.servicecomb.serviceregistry.client.IpPortManager][getNextAvailableAddress,100][registry-vert.x-eventloop-thread-0]Change service center address from 18.35.41.171:30100 to 18.35.41.171:30100
[2020/03/16 16:30:26.381][ERROR][Unexpected error in server.cause:SSLException,message:handshake timed out][org.apache.servicecomb.transport.rest.vertx.RestServerVerticle][lambda$start$1,112][vert.x-eventloop-thread-24]Unexpected error in server.cause:SSLException,message:handshake timed out
[2020/03/16 16:30:26.389][WARN][sc task taken more than 36505ms to execute][org.apache.servicecomb.serviceregistry.task.ServiceCenterTaskMonitor][endCycle,51][Service Center Task [java.util.concurrent.ThreadPoolExecutor$Worker@4ad1ca85[State = -1, empty queue][95]]]sc task taken more than 36505ms to execute
[2020/03/16 16:36:27.070][INFO][stats of instance dc550f7965a311ea9b65482b3c4d5e1f removed.][org.apache.servicecomb.loadbalance.ServiceCombLoadBalancerStats][onRemoval,145][LoadBalancerStatsTimer]stats of instance dc550f7965a311ea9b65482b3c4d5e1f removed.
[2020/03/16 16:36:27.071][ERROR][Failed to send request, local:18.35.41.171:34328, remote:/18.35.41.171:9086.][org.apache.servicecomb.transport.rest.client.http.RestClientInvocation][lambda$invoke$0,104][vert.x-eventloop-thread-3]Failed to send request, local:18.35.41.171:34328, remote:/18.35.41.171:9086.
io.vertx.core.VertxException: Connection was closed
[2020/03/16 16:36:27.071][ERROR][service CONSUMER rest CISAresService.configNotifications.pollNotification, call error, msg is cause:InvocationException,message:InvocationException: code=490;msg=CommonExceptionData [message=Cse Internal Bad Request];cause:VertxException,message:Connection was closed, server is rest://18.35.41.171:9086?sslEnabled=true ][org.apache.servicecomb.loadbalance.LoadbalanceHandler][lambda$null$0,370][vert.x-eventloop-thread-3]service CONSUMER rest CISAresService.configNotifications.pollNotification, call error, msg is cause:InvocationException,message:InvocationException: code=490;msg=CommonExceptionData [message=Cse Internal Bad Request];cause:VertxException,message:Connection was closed, server is rest://18.35.41.171:9086?sslEnabled=true
[2020/03/16 16:36:27.072][ERROR][Invoke server failed. Operation CONSUMER rest CISAresService.configNotifications.pollNotification; server rest://18.35.41.171:9086?sslEnabled=true; 0-0 msg cause:InvocationException,message:InvocationException: code=490;msg=CommonExceptionData [message=Cse Internal Bad Request];cause:VertxException,message:Connection was closed][org.apache.servicecomb.loadbalance.LoadbalanceHandler][onExceptionWithServer,295][vert.x-eventloop-thread-3]Invoke server failed. Operation CONSUMER rest CISAresService.configNotifications.pollNotification; server rest://18.35.41.171:9086?sslEnabled=true; 0-0 msg cause:InvocationException,message:InvocationException: code=490;msg=CommonExceptionData [message=Cse Internal Bad Request];cause:VertxException,message:Connection was closed
[2020/03/16 16:36:27.082][ERROR][Unexpected error in server.cause:SSLException,message:Received close_notify during handshake][org.apache.servicecomb.transport.rest.vertx.RestServerVerticle][lambda$start$1,112][vert.x-eventloop-thread-23]Unexpected error in server.cause:SSLException,message:Received close_notify during handshake
[2020/03/16 16:36:27.091][ERROR][Unexpected error in server.cause:SSLException,message:Received close_notify during handshake][org.apache.servicecomb.transport.rest.vertx.RestServerVerticle][lambda$start$1,112][vert.x-eventloop-thread-19]Unexpected error in server.cause:SSLException,message:Received close_notify during handshake
[2020/03/16 16:36:27.092][ERROR][Unexpected error in server.cause:SSLException,message:Received close_notify during handshake][org.apache.servicecomb.transport.rest.vertx.RestServerVerticle][lambda$start$1,112][vert.x-eventloop-thread-22]Unexpected error in server.cause:SSLException,message:Received close_notify during handshake
[2020/03/16 16:36:27.089][ERROR][Unhandled exception][io.vertx.core.impl.ContextImpl][reportException,342][vert.x-eventloop-thread-21]Unhandled exception
java.lang.IllegalStateException: Response is closed
at io.vertx.core.http.impl.HttpServerResponseImpl.checkValid(HttpServerResponseImpl.java:575) ~[vertx-core-3.7.0.jar:3.7.0]
at io.vertx.core.http.impl.HttpServerResponseImpl.end(HttpServerResponseImpl.java:323) ~[vertx-core-3.7.0.jar:3.7.0]
at org.apache.servicecomb.foundation.vertx.http.VertxServerResponseToHttpServletResponse.internalFlushBuffer(VertxServerResponseToHttpServletResponse.java:122) ~[foundation-vertx-1.2.1.jar:1.2.1]
at org.apache.servicecomb.foundation.vertx.http.VertxServerResponseToHttpServletResponse.lambda$flushBuffer$0(VertxServerResponseToHttpServletResponse.java:112) ~[foundation-vertx-1.2.1.jar:1.2.1]
at io.vertx.core.impl.ContextImpl.executeTask(ContextImpl.java:320) ~[vertx-core-3.7.0.jar:3.7.0]
at io.vertx.core.impl.EventLoopContext.lambda$executeAsync$0(EventLoopContext.java:38) ~[vertx-core-3.7.0.jar:3.7.0]
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164) [netty-all-4.1.45.Final.jar:4.1.45.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472) [netty-all-4.1.45.Final.jar:4.1.45.Final]
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:500) [netty-all-4.1.45.Final.jar:4.1.45.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) [netty-all-4.1.45.Final.jar:4.1.45.Final]
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [netty-all-4.1.45.Final.jar:4.1.45.Final]
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [netty-all-4.1.45.Final.jar:4.1.45.Final]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_242]

客户端日志:
[2020/03/16 16:30:08.792][ERROR][Failed to send request, local:not connected, remote:/18.35.41.171:9087.][org.apache.servicecomb.transport.rest.client.http.RestClientInvocation][lambda$invoke$0,104][vert.x-eventloop-thread-1]
javax.net.ssl.SSLHandshakeException: Failed to create SSL connection
at io.vertx.core.net.impl.ChannelProvider$1.userEventTriggered(ChannelProvider.java:111) [vertx-core-3.7.0.jar:3.7.0]
at io.netty.channel.AbstractChannelHandlerContext.invokeUserEventTriggered(AbstractChannelHandlerContext.java:344) [netty-transport-4.1.45.Final.jar:4.1.45.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeUserEventTriggered(AbstractChannelHandlerContext.java:330) [netty-transport-4.1.45.Final.jar:4.1.45.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireUserEventTriggered(AbstractChannelHandlerContext.java:322) [netty-transport-4.1.45.Final.jar:4.1.45.Final]
at io.netty.handler.ssl.SslUtils.handleHandshakeFailure(SslUtils.java:347) [netty-handler-4.1.45.Final.jar:4.1.45.Final]
at io.netty.handler.ssl.SslHandler$5.run(SslHandler.java:2004) [netty-handler-4.1.45.Final.jar:4.1.45.Final]
at io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98) [netty-common-4.1.45.Final.jar:4.1.45.Final]
at io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:170) [netty-common-4.1.45.Final.jar:4.1.45.Final]
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164) [netty-common-4.1.45.Final.jar:4.1.45.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472) [netty-common-4.1.45.Final.jar:4.1.45.Final]
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:500) [netty-transport-4.1.45.Final.jar:4.1.45.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) [netty-common-4.1.45.Final.jar:4.1.45.Final]
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [netty-common-4.1.45.Final.jar:4.1.45.Final]
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [netty-common-4.1.45.Final.jar:4.1.45.Final]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_242]
Caused by: javax.net.ssl.SSLException: handshake timed out
at io.netty.handler.ssl.SslHandler$5.run(SslHandler.java:2001) ~[netty-handler-4.1.45.Final.jar:4.1.45.Final]
... 9 more

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions