[KAFKA-7450] "Handshake message sequence violation" related ssl handshake failure leads to high cpu usage

• Type: Bug
• Status: Open
• Priority: Major
• Resolution: Unresolved
• Affects Version/s: 2.0.0
• Component/s: controller
• Assignee: Unassigned
• Reporter: Yu Yang
• Created: 28/Sep/18 06:37
• Updated: 05/May/20 13:52

Description

After updating security.inter.broker.protocol to SSL for our cluster, we observed that the controller can get into almost 100% cpu usage from time to time. 

listeners=PLAINTEXT://:9092,SSL://:9093
security.inter.broker.protocol=SSL

There is no obvious error in server.log. But in controller.log, there is repetitive SSL handshare failure error as below:

[2018-09-28 05:53:10,821] WARN [RequestSendThread controllerId=6042] Controller 6042's connection to broker datakafka06176.ec2.pin220.com:9093 (id: 6176 rack: null) was unsuccessful (kafka.controller.RequestSendThread)
org.apache.kafka.common.errors.SslAuthenticationException: SSL handshake failed
Caused by: javax.net.ssl.SSLProtocolException: Handshake message sequence violation, 2
        at sun.security.ssl.Handshaker.checkThrown(Handshaker.java:1487)
        at sun.security.ssl.SSLEngineImpl.checkTaskThrown(SSLEngineImpl.java:535)
        at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:813)
        at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:781)
        at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624)
        at org.apache.kafka.common.network.SslTransportLayer.handshakeUnwrap(SslTransportLayer.java:468)
        at org.apache.kafka.common.network.SslTransportLayer.doHandshake(SslTransportLayer.java:331)
        at org.apache.kafka.common.network.SslTransportLayer.handshake(SslTransportLayer.java:258)
        at org.apache.kafka.common.network.KafkaChannel.prepare(KafkaChannel.java:125)
        at org.apache.kafka.common.network.Selector.pollSelectionKeys(Selector.java:487)
        at org.apache.kafka.common.network.Selector.poll(Selector.java:425)
        at org.apache.kafka.clients.NetworkClient.poll(NetworkClient.java:510)
        at org.apache.kafka.clients.NetworkClientUtils.awaitReady(NetworkClientUtils.java:73)
        at kafka.controller.RequestSendThread.brokerReady(ControllerChannelManager.scala:279)
        at kafka.controller.RequestSendThread.doWork(ControllerChannelManager.scala:233)
        at kafka.utils.ShutdownableThread.run(ShutdownableThread.scala:82)
Caused by: javax.net.ssl.SSLProtocolException: Handshake message sequence violation, 2
        at sun.security.ssl.ClientHandshaker.processMessage(ClientHandshaker.java:196)
        at sun.security.ssl.Handshaker.processLoop(Handshaker.java:1026)
        at sun.security.ssl.Handshaker$1.run(Handshaker.java:966)
        at sun.security.ssl.Handshaker$1.run(Handshaker.java:963)
        at java.security.AccessController.doPrivileged(Native Method)
        at sun.security.ssl.Handshaker$DelegatedTask.run(Handshaker.java:1416)
        at org.apache.kafka.common.network.SslTransportLayer.runDelegatedTasks(SslTransportLayer.java:393)
        at org.apache.kafka.common.network.SslTransportLayer.handshakeUnwrap(SslTransportLayer.java:473)
        ... 10 more

[2018-09-30 00:30:13,609] WARN [ReplicaFetcher replicaId=59, leaderId=66, fetcherId=0] Error in response for fetch request (type=FetchRequest, replicaId=59, maxWait=500, minBytes=1, maxBytes=10485760, fetchData={the_test_topic-18=(offset=462333447, logStartOffset=462286948, maxBytes=4194304), the_test_topic-58=(offset=462312762, logStartOffset=462295078, maxBytes=4194304)}, isolationLevel=READ_UNCOMMITTED, toForget=, metadata=(sessionId=1991153671, epoch=INITIAL)) (kafka.server.ReplicaFetcherThread)
org.apache.kafka.common.errors.SslAuthenticationException: SSL handshake failed
Caused by: javax.net.ssl.SSLProtocolException: Handshake message sequence violation, 2
    at sun.security.ssl.Handshaker.checkThrown(Handshaker.java:1538)
    at sun.security.ssl.SSLEngineImpl.checkTaskThrown(SSLEngineImpl.java:535)
    at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:813)
    at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:781)
    at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624)
    at org.apache.kafka.common.network.SslTransportLayer.handshakeUnwrap(SslTransportLayer.java:468)
    at org.apache.kafka.common.network.SslTransportLayer.doHandshake(SslTransportLayer.java:331)
    at org.apache.kafka.common.network.SslTransportLayer.handshake(SslTransportLayer.java:258)
    at org.apache.kafka.common.network.KafkaChannel.prepare(KafkaChannel.java:125)
    at org.apache.kafka.common.network.Selector.pollSelectionKeys(Selector.java:487)
    at org.apache.kafka.common.network.Selector.poll(Selector.java:425)
    at org.apache.kafka.clients.NetworkClient.poll(NetworkClient.java:510)
    at org.apache.kafka.clients.NetworkClientUtils.awaitReady(NetworkClientUtils.java:73)
    at kafka.server.ReplicaFetcherBlockingSend.sendRequest(ReplicaFetcherBlockingSend.scala:91)
    at kafka.server.ReplicaFetcherThread.fetch(ReplicaFetcherThread.scala:240)
    at kafka.server.ReplicaFetcherThread.fetch(ReplicaFetcherThread.scala:43)
    at kafka.server.AbstractFetcherThread.processFetchRequest(AbstractFetcherThread.scala:149)
    at kafka.server.AbstractFetcherThread.doWork(AbstractFetcherThread.scala:114)
    at kafka.utils.ShutdownableThread.run(ShutdownableThread.scala:82)
Caused by: javax.net.ssl.SSLProtocolException: Handshake message sequence violation, 2
    at sun.security.ssl.ClientHandshaker.processMessage(ClientHandshaker.java:196)
    at sun.security.ssl.Handshaker.processLoop(Handshaker.java:1052)
    at sun.security.ssl.Handshaker$1.run(Handshaker.java:992)
    at sun.security.ssl.Handshaker$1.run(Handshaker.java:989)
    at java.security.AccessController.doPrivileged(Native Method)
    at sun.security.ssl.Handshaker$DelegatedTask.run(Handshaker.java:1467)
    at org.apache.kafka.common.network.SslTransportLayer.runDelegatedTasks(SslTransportLayer.java:393)
    at org.apache.kafka.common.network.SslTransportLayer.handshakeUnwrap(SslTransportLayer.java:473)
    ... 13 more

Issue Links

• relates to: KAFKA-7364 kafka periodically run into high cpu usage with high concurrent ssl writing