[KAFKA-3131] Inappropriate logging level for SSL Problem

• Type: Bug
• Status: Resolved
• Priority: Minor
• Resolution: Duplicate
• Component/s: clients
• Assignee: Harsha
• Reporter: Jake Robb
• Created: 22/Jan/16 15:25
• Updated: 20/Sep/17 09:04
• Resolved: 20/Sep/17 09:03

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.

Issue Links

• is duplicated by: KAFKA-5920 Handle SSL authentication failures as non-retriable exceptions in clients
• links to: GitHub Pull Request #3758