Uploaded image for project: 'Kafka'
  1. Kafka
  2. KAFKA-3131

Inappropriate logging level for SSL Problem

    XMLWordPrintableJSON

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Minor
    • Resolution: Duplicate
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: clients
    • Labels:
      None

      Description

      I didn't have my truststore set up correctly. The Kafka producer waited until the connection timed out (60 seconds in my case) and then threw this exception:

      Exception in thread "main" java.util.concurrent.ExecutionException: org.apache.kafka.common.errors.TimeoutException: Failed to update metadata after 60000 ms.
      	at org.apache.kafka.clients.producer.KafkaProducer$FutureFailure.<init>(KafkaProducer.java:706)
      	at org.apache.kafka.clients.producer.KafkaProducer.send(KafkaProducer.java:453)
      	at org.apache.kafka.clients.producer.KafkaProducer.send(KafkaProducer.java:339)
      

      I changed my log level to DEBUG and found this, less than two seconds after startup:

      [DEBUG] @ 2016-01-22 10:10:34,095 
      [User: ; Server: ; Client: ; URL: ; ChangeGroup: ]
       org.apache.kafka.common.network.Selector  - Connection with kafka02/10.0.0.2 disconnected 
      
      javax.net.ssl.SSLHandshakeException: General SSLEngine problem
      	at sun.security.ssl.Handshaker.checkThrown(Handshaker.java:1364)
      	at sun.security.ssl.SSLEngineImpl.checkTaskThrown(SSLEngineImpl.java:529)
      	at sun.security.ssl.SSLEngineImpl.writeAppRecord(SSLEngineImpl.java:1194)
      	at sun.security.ssl.SSLEngineImpl.wrap(SSLEngineImpl.java:1166)
      	at javax.net.ssl.SSLEngine.wrap(SSLEngine.java:469)
      	at org.apache.kafka.common.network.SslTransportLayer.handshakeWrap(SslTransportLayer.java:377)
      	at org.apache.kafka.common.network.SslTransportLayer.handshake(SslTransportLayer.java:242)
      	at org.apache.kafka.common.network.KafkaChannel.prepare(KafkaChannel.java:68)
      	at org.apache.kafka.common.network.Selector.poll(Selector.java:281)
      	at org.apache.kafka.clients.NetworkClient.poll(NetworkClient.java:270)
      	at org.apache.kafka.clients.producer.internals.Sender.run(Sender.java:216)
      	at org.apache.kafka.clients.producer.internals.Sender.run(Sender.java:128)
      	at java.lang.Thread.run(Thread.java:745)
      Caused by: javax.net.ssl.SSLHandshakeException: General SSLEngine problem
      	at sun.security.ssl.Alerts.getSSLException(Alerts.java:192)
      	at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1708)
      	at sun.security.ssl.Handshaker.fatalSE(Handshaker.java:303)
      	at sun.security.ssl.Handshaker.fatalSE(Handshaker.java:295)
      	at sun.security.ssl.ClientHandshaker.serverCertificate(ClientHandshaker.java:1369)
      	at sun.security.ssl.ClientHandshaker.processMessage(ClientHandshaker.java:156)
      	at sun.security.ssl.Handshaker.processLoop(Handshaker.java:925)
      	at sun.security.ssl.Handshaker$1.run(Handshaker.java:865)
      	at sun.security.ssl.Handshaker$1.run(Handshaker.java:862)
      	at java.security.AccessController.doPrivileged(Native Method)
      	at sun.security.ssl.Handshaker$DelegatedTask.run(Handshaker.java:1302)
      	at org.apache.kafka.common.network.SslTransportLayer.runDelegatedTasks(SslTransportLayer.java:335)
      	at org.apache.kafka.common.network.SslTransportLayer.handshakeUnwrap(SslTransportLayer.java:413)
      	at org.apache.kafka.common.network.SslTransportLayer.handshake(SslTransportLayer.java:269)
      	... 6 more
      Caused by: sun.security.validator.ValidatorException: PKIX path building failed: sun.security.provider.certpath.SunCertPathBuilderException: unable to find valid certification path to requested target
      	at sun.security.validator.PKIXValidator.doBuild(PKIXValidator.java:387)
      	at sun.security.validator.PKIXValidator.engineValidate(PKIXValidator.java:292)
      	at sun.security.validator.Validator.validate(Validator.java:260)
      	at sun.security.ssl.X509TrustManagerImpl.validate(X509TrustManagerImpl.java:324)
      	at sun.security.ssl.X509TrustManagerImpl.checkTrusted(X509TrustManagerImpl.java:281)
      	at sun.security.ssl.X509TrustManagerImpl.checkServerTrusted(X509TrustManagerImpl.java:136)
      	at sun.security.ssl.ClientHandshaker.serverCertificate(ClientHandshaker.java:1356)
      	... 15 more
      Caused by: sun.security.provider.certpath.SunCertPathBuilderException: unable to find valid certification path to requested target
      	at sun.security.provider.certpath.SunCertPathBuilder.build(SunCertPathBuilder.java:145)
      	at sun.security.provider.certpath.SunCertPathBuilder.engineBuild(SunCertPathBuilder.java:131)
      	at java.security.cert.CertPathBuilder.build(CertPathBuilder.java:280)
      	at sun.security.validator.PKIXValidator.doBuild(PKIXValidator.java:382)
      	... 21 more
      

      There are two problems here:
      1. The log level should be ERROR if the Kafka producer cannot connect because of an SSL handshake problem, as this error is not likely to be intermittent or recoverable without intervention, and the thrown exception completely obscures the real problem.
      2. Ideally, I would think that the producer's call to send should throw an exception immediately rather than waiting for the full timeout.

      I'm not sure if it will help, but the full DEBUG output of my Kafka producer's session is attached.

        Attachments

        1. kafka-ssl-error-debug-log.txt
          878 kB
          Jake Robb

          Issue Links

            Activity

              People

              • Assignee:
                sriharsha Harsha
                Reporter:
                jakerobb Jake Robb
              • Votes:
                1 Vote for this issue
                Watchers:
                3 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: