Unfortunate error message when missing ACLs

[paneq]

When the producer uses ruby-kafka and it is not authorized to publish messages to a certain topic (because of Kafka's ACLs) the Kafka::TopicAuthorizationFailed exception is raised:

Traceback (most recent call last):
	4: from produce_sasl.rb:16:in `<main>'
	3: from /Users/rupert/.rbenv/versions/2.5.5/lib/ruby/gems/2.5.0/gems/ruby-kafka-0.7.9/lib/kafka/client.rb:152:in `deliver_message'
	2: from /Users/rupert/.rbenv/versions/2.5.5/lib/ruby/gems/2.5.0/gems/ruby-kafka-0.7.9/lib/kafka/cluster.rb:145:in `partitions_for'
	1: from /Users/rupert/.rbenv/versions/2.5.5/lib/ruby/gems/2.5.0/gems/ruby-kafka-0.7.9/lib/kafka/protocol/metadata_response.rb:134:in `partitions_for'
/Users/rupert/.rbenv/versions/2.5.5/lib/ruby/gems/2.5.0/gems/ruby-kafka-0.7.9/lib/kafka/protocol.rb:160:in `handle_error': Kafka::TopicAuthorizationFailed (Kafka::TopicAuthorizationFailed)

However when using waterdrop we get Kafka::DeliveryFailed with the message such as Failed to assign partitions to 1 messages in test-topic exception which hides the real reason behind the failure:

E, [2019-10-01T17:00:44.672771 #35917] ERROR -- : Failed to assign partitions to 1 messages in e2
W, [2019-10-01T17:00:44.672910 #35917]  WARN -- : Failed to send all messages to ; attempting retry 1 of 2 after 1s
E, [2019-10-01T17:00:45.687680 #35917] ERROR -- : Failed to assign partitions to 1 messages in e2
W, [2019-10-01T17:00:45.687861 #35917]  WARN -- : Failed to send all messages to ; attempting retry 2 of 2 after 1s
E, [2019-10-01T17:00:46.705185 #35917] ERROR -- : Failed to assign partitions to 1 messages in e2
E, [2019-10-01T17:00:46.705252 #35917] ERROR -- : Failed to send all messages to ; keeping remaining messages in buffer
E, [2019-10-01T17:00:46.720882 #35917] ERROR -- : Failed to assign partitions to 1 messages in e2
W, [2019-10-01T17:00:46.720940 #35917]  WARN -- : Failed to send all messages to ; attempting retry 1 of 2 after 1s
E, [2019-10-01T17:00:47.736301 #35917] ERROR -- : Failed to assign partitions to 1 messages in e2
W, [2019-10-01T17:00:47.736369 #35917]  WARN -- : Failed to send all messages to ; attempting retry 2 of 2 after 1s
E, [2019-10-01T17:00:48.750387 #35917] ERROR -- : Failed to assign partitions to 1 messages in e2
E, [2019-10-01T17:00:48.750574 #35917] ERROR -- : Failed to send all messages to ; keeping remaining messages in buffer
E, [2019-10-01T17:00:48.762185 #35917] ERROR -- : Failed to assign partitions to 1 messages in e2
W, [2019-10-01T17:00:48.762278 #35917]  WARN -- : Failed to send all messages to ; attempting retry 1 of 2 after 1s
E, [2019-10-01T17:00:49.785085 #35917] ERROR -- : Failed to assign partitions to 1 messages in e2
W, [2019-10-01T17:00:49.785191 #35917]  WARN -- : Failed to send all messages to ; attempting retry 2 of 2 after 1s
E, [2019-10-01T17:00:50.810873 #35917] ERROR -- : Failed to assign partitions to 1 messages in e2
E, [2019-10-01T17:00:50.811024 #35917] ERROR -- : Failed to send all messages to ; keeping remaining messages in buffer
Traceback (most recent call last):
	7: from produce_sasl_waterdrop.rb:28:in `<main>'
	6: from /Users/rupert/.rbenv/versions/2.5.5/lib/ruby/gems/2.5.0/bundler/gems/waterdrop-74b2c35bdd82/lib/water_drop/sync_producer.rb:19:in `call'
	5: from /Users/rupert/.rbenv/versions/2.5.5/lib/ruby/gems/2.5.0/bundler/gems/delivery_boy-d875e1e791cc/lib/delivery_boy.rb:28:in `deliver'
	4: from /Users/rupert/.rbenv/versions/2.5.5/lib/ruby/gems/2.5.0/bundler/gems/delivery_boy-d875e1e791cc/lib/delivery_boy/instance.rb:14:in `deliver'
	3: from /Users/rupert/.rbenv/versions/2.5.5/lib/ruby/gems/2.5.0/gems/ruby-kafka-0.7.10/lib/kafka/producer.rb:246:in `deliver_messages'
	2: from /Users/rupert/.rbenv/versions/2.5.5/lib/ruby/gems/2.5.0/gems/ruby-kafka-0.7.10/lib/kafka/instrumenter.rb:23:in `instrument'
	1: from /Users/rupert/.rbenv/versions/2.5.5/lib/ruby/gems/2.5.0/gems/ruby-kafka-0.7.10/lib/kafka/producer.rb:253:in `block in deliver_messages'
/Users/rupert/.rbenv/versions/2.5.5/lib/ruby/gems/2.5.0/gems/ruby-kafka-0.7.10/lib/kafka/producer.rb:426:in `deliver_messages_with_retries': Failed to assign partitions to 1 messages (Kafka::DeliveryFailed)

I reproduced this issue locally on confluentinc/cp-kafka:5.1.2 after configuring SASL and ACLs as well as on Confluent Cloud Enterprise cluster.

[mensfeld]

Async or sync publishing?

[ronin]

Sync

[mensfeld]

@paneq p e.cause - this should contain the raw details on why wasn't delivered. Does it work?

[paneq]

@mensfeld

Unfortunately, it does not. e.cause is nil.

[paneq]

Replication procedure:

• clone https://github.com/paneq/kafka_docker_sasl_plain
• run docker-compose -f test.yml up
• execute:

WaterDrop.setup do |config|
  config.deliver = true
  config.client_id = "my-app-waterdrop"
  config.kafka.seed_brokers = ["kafka://127.0.0.1:9092"]

  config.kafka.ssl_ca_certs_from_system = false
  config.kafka.sasl_over_ssl = false
  config.kafka.sasl_plain_username = "edward"
  config.kafka.sasl_plain_password = "edward"
end


WaterDrop::SyncProducer.call('message', topic: 'unexisting')
# => Failed to assign partitions to 1 messages (Kafka::DeliveryFailed)

compare that with:

kafka = Kafka.new(
	["127.0.0.1:9092"], 
	client_id: "my-application",
	sasl_plain_username: 'edward',
        sasl_plain_password: 'edward',
	sasl_over_ssl: false,
)

kafka.deliver_message("message", topic: "unexisting")
# => Kafka::TopicAuthorizationFailed

and that should suffice.

FYI: Authentication and authorization is configured here: https://github.com/paneq/kafka_docker_sasl_plain/blob/master/test.yml#L23L36

If something does not work, let me know.

[mensfeld]

I can confirm. Investigating and fixing...

[mensfeld]

This is a mismatch in between how delivery boy works and how ruby-kafka client works. It won't be fixed due to #106

For rdkafka there's a issue reported: karafka/rdkafka-ruby#92

[mensfeld]

I will close it. This should be fixed in librdkafka and we're moving out from ruby-kafka.