[
https://issues.apache.org/jira/browse/KAFKA-3131?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Jake Robb updated KAFKA-3131:
-----------------------------
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:
{code}
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)
{code}
I changed my log level to DEBUG and found this, less than two seconds after
startup:
{code}
[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
{code}
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.
was:
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:
{code}
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)
{code}
I changed my log level to DEBUG and found this, less than two seconds after
startup:
{code}
[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
{code}
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.
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.
> Inappropriate logging level for SSL Problem
> -------------------------------------------
>
> Key: KAFKA-3131
> URL: https://issues.apache.org/jira/browse/KAFKA-3131
> Project: Kafka
> Issue Type: Bug
> Components: clients
> Reporter: Jake Robb
> Assignee: Sriharsha Chintalapani
> Priority: Minor
> Attachments: kafka-ssl-error-debug-log.txt
>
>
> 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:
> {code}
> 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)
> {code}
> I changed my log level to DEBUG and found this, less than two seconds after
> startup:
> {code}
> [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
> {code}
> 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.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
