problems when using kerberos with invalid keytab and principal

[shenxingwuying]

I am working for duplicating kudu records to kafka. I use librdkafka.

When I support kerberos in librdkafka according to this page:https://github.com/edenhill/librdkafka/wiki/Using-SASL-with-librdkafka.

I am adding some unit tests for this. Serveral tests:

1. If the "security.protocol" not match as kafka cluster. Producer cannot write record to kafka.
2. If the "sasl.kerberos.service.name" does not match as kafka cluster. Producer cannot write record to kafka.
3. If the "sasl.kerberos.keytab" is invalid (no such keytab file) . Producer cannot write record to kafka.
4. If the "sasl.kerberos.principal" is invalid (no such principal). Producer cannot write record to kafka.
5. If the "sasl.kerberos.keytab" and "sasl.kerberos.principal" are both invalid. Producer cannot write record to kafka.

1, 2 test case is passed. But 3, 4, 5 is failed, although the keytab and principal is invalid, producer write records to kafka success. It's very confused.

Some logs represent 'kinit' commands are failed. But it does not prevent write request to kafka, and kafka receive these records!

I0724 16:41:59.925408 1388917 pending_rounds.cc:171] T 1f39d4455b0a4264acc3d66bd28779f6 P 85e68941416a4322873ddf008ea747b9: Last triggered apply was: 1.4 Starting to apply from log index: 5 kinit: Cannot find KDC for realm "KRBTEST.COMinvalid" while getting initial credentials kinit: Cannot find KDC for realm "KRBTEST.COMinvalid" while getting initial credentials %3|1690188119.931|SASLREFRESH|rdkafka#producer-1| [thrd:main]: Kerberos ticket refresh failed: kinit -R -t "/tmp/kudutest-0/duplication_with_kerberos_kafka-itest.DuplicationWithKerberosKafkaITest.TestInvaildKeytab.1690188107547701-1386211/krb5kdc/[email protected]" -k kafka/[email protected] || kinit -t "/tmp/kudutest-0/duplication_with_kerberos_kafka-itest.DuplicationWithKerberosKafkaITest.TestInvaildKeytab.1690188107547701-1386211/krb5kdc/[email protected]" -k kafka/[email protected]: exited with code 1

I use a simple method to solve this problem. This patch can make 3,4,5 unit tests success.
#4371

I need some help to make sure this problem. If I am correct, I can continue this patch and provide some tests.
If I am not correct, you can help me some usage or other ideas.

[rolandyoung]

If your broker cluster accepts a connection without requiring valid Kerberos credentials, that is an issue with the broker configuration, not with the client. (You cannot prevent a bad actor from, for example, using librdkafka in the configuration you regard as "failing", so it is the responsibility of the server to enforce valid credentials.)

Steps you should take

1. Confirm that the records you are writing in your "fail" scenarios are actually readable from the cluster. Remember that rd_kafka_produce is asynchronous, so the call can succeed even if no connection has been made. Until you get a delivery receipt callback, you do not know that the message has been delivered.
2. If the messages really are being delivered, check that you have configured Kerberos authentication correctly at the broker. If you need help with this, you should ask for it in the Kafka server support forums, or on another Q&A site.

[shenxingwuying]

You say:
"1. Confirm that the records you are writing in your "fail" scenarios are actually readable from the cluster. Remember that rd_kafka_produce is asynchronous, so the call can succeed even if no connection has been made. Until you get a delivery receipt callback, you do not know that the message has been delivered."

I can provide more logs including what I have provided:
I0724 16:41:59.925379 1388920 log_cache.cc:412] T 1f39d4455b0a4264acc3d66bd28779f6 P 85e68941416a4322873ddf008ea747b9: Evicting log cache: after state: Pinned index: 6, LogCacheStats(num_ops=1, bytes=1032) I0724 16:41:59.925408 1388917 pending_rounds.cc:171] T 1f39d4455b0a4264acc3d66bd28779f6 P 85e68941416a4322873ddf008ea747b9: Last triggered apply was: 1.4 Starting to apply from log index: 5 kinit: Cannot find KDC for realm "KRBTEST.COMinvalid" while getting initial credentials kinit: Cannot find KDC for realm "KRBTEST.COMinvalid" while getting initial credentials %3|1690188119.931|SASLREFRESH|rdkafka#producer-1| [thrd:main]: Kerberos ticket refresh failed: kinit -R -t "/tmp/kudutest-0/duplication_with_kerberos_kafka-itest.DuplicationWithKerberosKafkaITest.TestInvaildKeytab.1690188107547701-1386211/krb5kdc/[email protected]" -k kafka/[email protected] || kinit -t "/tmp/kudutest-0/duplication_with_kerberos_kafka-itest.DuplicationWithKerberosKafkaITest.TestInvaildKeytab.1690188107547701-1386211/krb5kdc/[email protected]" -k kafka/[email protected]: exited with code 1 I0724 16:41:59.938171 1386829 kafka_connector.cc:185] kafka producer init succeed! With kerberos_options: type: KAFKA, name: kudu_profile_record_stream, uri: localhost:9104, options: , security_protocol: SASL_PLAINTEXT, service_name: kafka, keytab: /tmp/kudutest-0/duplication_with_kerberos_kafka-itest.DuplicationWithKerberosKafkaITest.TestInvaildKeytab.1690188107547701-1386211/krb5kdc/[email protected], principal: kafka/[email protected] I0724 16:41:59.938318 1386829 log_reader.cc:134] Reading wal from path:/tmp/kudutest-0/duplication_with_kerberos_kafka-itest.DuplicationWithKerberosKafkaITest.TestInvaildKeytab.1690188107547701-1386211/minicluster-data/ts-3/wal/wals/1f39d4455b0a4264acc3d66bd28779f6 I0724 16:41:59.938333 1386829 log_reader.cc:140] Parsing segments from path: /tmp/kudutest-0/duplication_with_kerberos_kafka-itest.DuplicationWithKerberosKafkaITest.TestInvaildKeytab.1690188107547701-1386211/minicluster-data/ts-3/wal/wals/1f39d4455b0a4264acc3d66bd28779f6 I0724 16:41:59.938357 1386829 log_util.cc:265] Parsing wal segment: /tmp/kudutest-0/duplication_with_kerberos_kafka-itest.DuplicationWithKerberosKafkaITest.TestInvaildKeytab.1690188107547701-1386211/minicluster-data/ts-3/wal/wals/1f39d4455b0a4264acc3d66bd28779f6/wal-000000001 I0724 16:41:59.938455 1386829 log_util.cc:343] Log segment /tmp/kudutest-0/duplication_with_kerberos_kafka-itest.DuplicationWithKerberosKafkaITest.TestInvaildKeytab.1690188107547701-1386211/minicluster-data/ts-3/wal/wals/1f39d4455b0a4264acc3d66bd28779f6/wal-000000001 has no footer. This segment was likely being written when the server previously shut down. I0724 16:41:59.938463 1386829 log_reader.cc:170] Log segment /tmp/kudutest-0/duplication_with_kerberos_kafka-itest.DuplicationWithKerberosKafkaITest.TestInvaildKeytab.1690188107547701-1386211/minicluster-data/ts-3/wal/wals/1f39d4455b0a4264acc3d66bd28779f6/wal-000000001 was likely left in-progress after a previous crash. Will try to rebuild footer by scanning data. I0724 16:41:59.938511 1386829 log_util.cc:126] Reading segment entries from /tmp/kudutest-0/duplication_with_kerberos_kafka-itest.DuplicationWithKerberosKafkaITest.TestInvaildKeytab.1690188107547701-1386211/minicluster-data/ts-3/wal/wals/1f39d4455b0a4264acc3d66bd28779f6/wal-000000001: offset=128 file_size=1048576 readable_to_offset=1048576 I0724 16:41:59.939011 1386829 log_util.cc:589] Scanning /tmp/kudutest-0/duplication_with_kerberos_kafka-itest.DuplicationWithKerberosKafkaITest.TestInvaildKeytab.1690188107547701-1386211/minicluster-data/ts-3/wal/wals/1f39d4455b0a4264acc3d66bd28779f6/wal-000000001 for valid entry headers following offset 1637... I0724 16:41:59.939674 1386829 log_util.cc:626] Found no log entry headers I0724 16:41:59.939680 1386829 log_util.cc:228] Reached preallocated space while reading log segment /tmp/kudutest-0/duplication_with_kerberos_kafka-itest.DuplicationWithKerberosKafkaITest.TestInvaildKeytab.1690188107547701-1386211/minicluster-data/ts-3/wal/wals/1f39d4455b0a4264acc3d66bd28779f6/wal-000000001 I0724 16:41:59.939692 1386829 log_util.cc:406] Successfully rebuilt footer for segment: /tmp/kudutest-0/duplication_with_kerberos_kafka-itest.DuplicationWithKerberosKafkaITest.TestInvaildKeytab.1690188107547701-1386211/minicluster-data/ts-3/wal/wals/1f39d4455b0a4264acc3d66bd28779f6/wal-000000001 (valid entries through byte offset 1621) I0724 16:41:59.939738 1386829 log_reader.cc:189] Log Reader Indexed: num_entries: 9 min_replicate_index: 1 max_replicate_index: 5 I0724 16:41:59.939811 1386829 log_util.cc:126] Reading segment entries from /tmp/kudutest-0/duplication_with_kerberos_kafka-itest.DuplicationWithKerberosKafkaITest.TestInvaildKeytab.1690188107547701-1386211/minicluster-data/ts-3/wal/wals/1f39d4455b0a4264acc3d66bd28779f6/wal-000000001: offset=128 file_size=1048576 readable_to_offset=1621 W0724 16:41:59.940018 1386829 duplicator.cc:114] duplicator info: confirmed opid term: 0 index: 0, queue latest opid , tablet id 1f39d4455b0a4264acc3d66bd28779f6, peer uuid 85e68941416a4322873ddf008ea747b9, duplication_mode: WAL_DUPLICATION not find start point, replay all wals, status: Not found: not found start point, should replay all, tablet id 1f39d4455b0a4264acc3d66bd28779f6, peer uuid 85e68941416a4322873ddf008ea747b9 I0724 16:41:59.940091 1386829 tablet_replica.cc:354] T 1f39d4455b0a4264acc3d66bd28779f6 P 85e68941416a4322873ddf008ea747b9: start duplicator success. I0724 16:41:59.940114 1386828 duplication_replay.cc:163] tablet id 1f39d4455b0a4264acc3d66bd28779f6, peer uuid 85e68941416a4322873ddf008ea747b9 Replay start, replay start point: I0724 16:41:59.940151 1386828 log_reader.cc:134] Reading wal from path:/tmp/kudutest-0/duplication_with_kerberos_kafka-itest.DuplicationWithKerberosKafkaITest.TestInvaildKeytab.1690188107547701-1386211/minicluster-data/ts-3/wal/wals/1f39d4455b0a4264acc3d66bd28779f6 I0724 16:41:59.940163 1386828 log_reader.cc:140] Parsing segments from path: /tmp/kudutest-0/duplication_with_kerberos_kafka-itest.DuplicationWithKerberosKafkaITest.TestInvaildKeytab.1690188107547701-1386211/minicluster-data/ts-3/wal/wals/1f39d4455b0a4264acc3d66bd28779f6 I0724 16:41:59.940181 1386828 log_util.cc:265] Parsing wal segment: /tmp/kudutest-0/duplication_with_kerberos_kafka-itest.DuplicationWithKerberosKafkaITest.TestInvaildKeytab.1690188107547701-1386211/minicluster-data/ts-3/wal/wals/1f39d4455b0a4264acc3d66bd28779f6/wal-000000001 I0724 16:41:59.940204 1386828 log_util.cc:343] Log segment /tmp/kudutest-0/duplication_with_kerberos_kafka-itest.DuplicationWithKerberosKafkaITest.TestInvaildKeytab.1690188107547701-1386211/minicluster-data/ts-3/wal/wals/1f39d4455b0a4264acc3d66bd28779f6/wal-000000001 has no footer. This segment was likely being written when the server previously shut down. I0724 16:41:59.940208 1386828 log_reader.cc:170] Log segment /tmp/kudutest-0/duplication_with_kerberos_kafka-itest.DuplicationWithKerberosKafkaITest.TestInvaildKeytab.1690188107547701-1386211/minicluster-data/ts-3/wal/wals/1f39d4455b0a4264acc3d66bd28779f6/wal-000000001 was likely left in-progress after a previous crash. Will try to rebuild footer by scanning data. I0724 16:41:59.940212 1386828 log_util.cc:126] Reading segment entries from /tmp/kudutest-0/duplication_with_kerberos_kafka-itest.DuplicationWithKerberosKafkaITest.TestInvaildKeytab.1690188107547701-1386211/minicluster-data/ts-3/wal/wals/1f39d4455b0a4264acc3d66bd28779f6/wal-000000001: offset=128 file_size=1048576 readable_to_offset=1048576 I0724 16:41:59.940378 1386828 log_util.cc:589] Scanning /tmp/kudutest-0/duplication_with_kerberos_kafka-itest.DuplicationWithKerberosKafkaITest.TestInvaildKeytab.1690188107547701-1386211/minicluster-data/ts-3/wal/wals/1f39d4455b0a4264acc3d66bd28779f6/wal-000000001 for valid entry headers following offset 1637... I0724 16:41:59.940618 1388924 result_tracker.cc:260] 0xa66000 kudu.tserver.TabletServerService: Sending RPC success response for Call kudu.tserver.TabletServerService.Write from 127.0.0.1:46566 (ReqId={client: 5118b3cbcd36474484af366ae08f07ec, seq_no=1, attempt_no=0}): timestamp: 6923010539213680640 I0724 16:41:59.940727 1386828 log_util.cc:626] Found no log entry headers I0724 16:41:59.940737 1386828 log_util.cc:228] Reached preallocated space while reading log segment /tmp/kudutest-0/duplication_with_kerberos_kafka-itest.DuplicationWithKerberosKafkaITest.TestInvaildKeytab.1690188107547701-1386211/minicluster-data/ts-3/wal/wals/1f39d4455b0a4264acc3d66bd28779f6/wal-000000001 I0724 16:41:59.940742 1386828 log_util.cc:406] Successfully rebuilt footer for segment: /tmp/kudutest-0/duplication_with_kerberos_kafka-itest.DuplicationWithKerberosKafkaITest.TestInvaildKeytab.1690188107547701-1386211/minicluster-data/ts-3/wal/wals/1f39d4455b0a4264acc3d66bd28779f6/wal-000000001 (valid entries through byte offset 1621) I0724 16:41:59.940752 1386828 log_reader.cc:189] Log Reader Indexed: num_entries: 9 min_replicate_index: 1 max_replicate_index: 5 I0724 16:41:59.940790 1386828 log_util.cc:126] Reading segment entries from /tmp/kudutest-0/duplication_with_kerberos_kafka-itest.DuplicationWithKerberosKafkaITest.TestInvaildKeytab.1690188107547701-1386211/minicluster-data/ts-3/wal/wals/1f39d4455b0a4264acc3d66bd28779f6/wal-000000001: offset=128 file_size=1048576 readable_to_offset=1621 I0724 16:41:59.941237 1386828 duplication_replay.cc:279] tablet id 1f39d4455b0a4264acc3d66bd28779f6, peer uuid 85e68941416a4322873ddf008ea747b9 segment replicate count: 5, replay write count: 2, ops size: 2 I0724 16:41:59.941264 1386828 duplicator.cc:329] duplicator info: confirmed opid term: 1 index: 4, queue latest opid term: 1 index: 5, tablet id 1f39d4455b0a4264acc3d66bd28779f6, peer uuid 85e68941416a4322873ddf008ea747b9, duplication_mode: WAL_DUPLICATION_FINISH switch mode from WAL_DUPLICATION to WAL_DUPLICATION_FINISH I0724 16:41:59.941191 1386816 kafka_connector.cc:215] produce record: properties { name: "key" value: "0" primary_key_column: true } properties { name: "int_val" value: "0" } properties { name: "string_val" value: "0" } table_name: "DuplicationWithInvalidKerberosOptionsInvaildKeytab" operation_type: SET I0724 16:41:59.941282 1386828 duplicator.cc:418] duplicator info: confirmed opid term: 1 index: 4, queue latest opid term: 1 index: 5, tablet id 1f39d4455b0a4264acc3d66bd28779f6, peer uuid 85e68941416a4322873ddf008ea747b9, duplication_mode: REALTIME_DUPLICATION top_op_id term: 1 index: 5, queue_latest_opid term: 1 index: 5, switch mode from WAL_DUPLICATION_FINISH to REALTIME_DUPLICATION, need_replay_again_: false, switch_success: true I0724 16:41:59.941300 1386828 duplication_replay.cc:292] tablet id 1f39d4455b0a4264acc3d66bd28779f6, peer uuid 85e68941416a4322873ddf008ea747b9 Replay finish, next start point: term: 1 index: 5 I0724 16:41:59.966032 1386816 kafka_connector.cc:289] DeliveryReport succeed, key: 0 I0724 16:41:59.966279 1386816 kafka_connector.cc:215] produce record: properties { name: "key" value: "2" primary_key_column: true } properties { name: "int_val" value: "2" } properties { name: "string_val" value: "4" } table_name: "DuplicationWithInvalidKerberosOptionsInvaildKeytab" operation_type: SET I0724 16:41:59.966323 1386816 kafka_connector.cc:215] produce record: properties { name: "key" value: "2" primary_key_column: true } properties { name: "int_val" value: "2" } properties { name: "string_val" value: "4" } table_name: "DuplicationWithInvalidKerberosOptionsInvaildKeytab" operation_type: SET I0724 16:41:59.967137 1386816 kafka_connector.cc:289] DeliveryReport succeed, key: 2 I0724 16:41:59.967152 1386816 kafka_connector.cc:289] DeliveryReport succeed, key: 2 I0724 16:42:00.032724 1386939 tablet.cc:2202] T 1f39d4455b0a4264acc3d66bd28779f6 P 85e68941416a4322873ddf008ea747b9: Best compaction for 1f39d4455b0a4264acc3d66bd28779f6: 0 I0724 16:42:00.080933 1386326 builtin_ntp.cc:404] NTP from 127.73.184.212:37445 (127.73.184.212:37445): 1688438908694150 +/- 12us I0724 16:42:00.168959 1386482 builtin_ntp.cc:404] NTP from 127.73.184.212:37445 (127.73.184.212:37445): 1688438908694151 +/- 12us

We can see several 'DeliveryReport succeed' logs. And I use a consumer in the test to get these record, I have 3 record, this matches the 'DeliveryReport succeed' count.
I0724 16:42:23.933780 1388925 duplication_with_kerberos_kafka-itest.cc:278] consume record size: 3, count: 3, last message size: 0 /builds/sensors-analytics/kudu/src/kudu/integration-tests/duplication_with_kerberos_kafka-itest.cc:773: Failure Expected: 0 To be equal to: kafka_key_set.size() Which is: 2

you say:
'
2. If the messages really are being delivered, check that you have configured Kerberos authentication correctly at the broker. If you need help with this, you should ask for it in the Kafka server support forums, or on another Q&A site.
'

Yes, it's responsibility kafka server side(brokers) to prevent it.

1. One is brokers' configuration is not correct. Yes, it feels a high probability event. I have try to configure this brokers' configure and the case 1 and case 2 is as my expect. kafka is connected with the kdc? or I takes much time to config this and make this broker start success, So Kerberos authentication correctly? The test is in this:

2. The other maybe kafka has a bug.

This need some time to study.

[rolandyoung]

OK, so you have confirmed that the records are actually being written. So this means that your issue is not a problem with the client (librdkafka), but with the server. This is not the right place for such a question!

It is can be very hard to configure Kerberos authentication, so you are not alone in this, although usually the problem is that clients fail to authenticate and cannot connect. Your problem - broker fails to require authentication - is more unusual.

I would strongly recommend that you first try to test authentication using the Java command line clients. You need to get your broker configuration so that a Java client cannot write or read records if it does not authenticate using Kerberos and can read and write if it does authenticate. If you cannot do this, seek help in the support forums for server-side Kafka.

When you have got the Java clients working as expected, then test using kafkacat, so that you find out what librdkafka config is required. Finally, you can apply that config to the application you are developing using librdkafka.

[marlowa]

I also get similar kinit errors blatted to the console, despite me having callback for the generic event, which includes a log event. Sometimes my callback gets the text as well and sometimes it doesn't. This means that when there kerberos problem I cannot always find it in the application log. This seems like a tricky area - I mean, do I chase the kerberos people or the librdkafka people?

[rolandyoung]

There are three possible cases:

• Errors using Java command line tools ( kafka-topics.sh, etc ) - chase the Kerberos (or Kafka) people
• Success using Java, but issues with kcat - check that you understand the librdkafka config settings, then chase librdkafka people, showing them the Java client config that works and the kcat settings that don't
• Success using kcat but not using your program - check your code, then chase librdkafka people showing kcat output that behaves as you expect and your logs that don't