Previously I've reported it into kafkacat tracker but the issue has been closed as related to cyrus-sasl/krb5.
podman run --rm -it --name kafkacat-DEV \
-v$(pwd)/conf/integration:/conf -v$(pwd)/conf/integration/krb5.conf:/etc/krb5.conf \
localhost/kafkacat_gssapi:1 \
kafkacat \
-b kafka-int.example.com:9095 \
-Xssl.ca.location=/conf/kafka-int.ca.crt \
-Xsecurity.protocol=SASL_SSL \
-Xsasl.mechanisms=GSSAPI \
'-Xsasl.kerberos.kinit.cmd=cat /conf/paswd | /usr/bin/kinit [email protected]' \
-Xsasl.kerberos.service.name=kafka \
-m30 -L
Error:
Password for [email protected]:
%5|1620820968.991|LIBSASL|rdkafka#producer-1| [thrd:sasl_ssl://kafka-int.example.com:9095/bootstrap]: sasl_ssl://kafka-int.example.com:9095/bootstrap: GSSAPI client step 1
%2|1620820969.336|LIBSASL|rdkafka#producer-1| [thrd:sasl_ssl://kafka-int.example.com:9095/bootstrap]: sasl_ssl://kafka-int.example.com:9095/bootstrap: GSSAPI Error: Miscellaneous failure (see text) (Matching credential (kafka/[email protected]) not found)
%3|1620820969.336|FAIL|rdkafka#producer-1| [thrd:sasl_ssl://kafka-int.example.com:9095/bootstrap]: sasl_ssl://kafka-int.example.com:9095/bootstrap: Failed to initialize SASL authentication: SASL handshake failed (start (-1)): SASL(-1): generic failure: GSSAPI Error: Miscellaneous failure (see text) (Matching credential (kafka/[email protected]) not found) (after 345ms in state AUTH_REQ)
%5|1620820970.006|LIBSASL|rdkafka#producer-1| [thrd:sasl_ssl://kafka-int.example.com:9095/bootstrap]: sasl_ssl://kafka-int.example.com:9095/bootstrap: GSSAPI client step 1
%2|1620820970.137|LIBSASL|rdkafka#producer-1| [thrd:sasl_ssl://kafka-int.example.com:9095/bootstrap]: sasl_ssl://kafka-int.example.com:9095/bootstrap: GSSAPI Error: Miscellaneous failure (see text) (Matching credential (kafka/[email protected]) not found)
%3|1620820970.137|FAIL|rdkafka#producer-1| [thrd:sasl_ssl://kafka-int.example.com:9095/bootstrap]: sasl_ssl://kafka-int.example.com:9095/bootstrap: Failed to initialize SASL authentication: SASL handshake failed (start (-1)): SASL(-1): generic failure: GSSAPI Error: Miscellaneous failure (see text) (Matching credential (kafka/[email protected]) not found) (after 131ms in state AUTH_REQ, 1 identical error(s) suppressed)
%5|1620820971.431|LIBSASL|rdkafka#producer-1| [thrd:sasl_ssl://kafka-int.example.com:9095/bootstrap]: sasl_ssl://kafka-int.example.com:9095/bootstrap: GSSAPI client step 1
%2|1620820972.935|LIBSASL|rdkafka#producer-1| [thrd:sasl_ssl://kafka-int.example.com:9095/bootstrap]: sasl_ssl://kafka-int.example.com:9095/bootstrap: GSSAPI Error: Miscellaneous failure (see text) (Matching credential (kafka/[email protected]) not found)
%5|1620820976.319|LIBSASL|rdkafka#producer-1| [thrd:sasl_ssl://kafka-int.example.com:9095/bootstrap]: sasl_ssl://kafka-int.example.com:9095/bootstrap: GSSAPI client step 1
%2|1620820976.745|LIBSASL|rdkafka#producer-1| [thrd:sasl_ssl://kafka-int.example.com:9095/bootstrap]: sasl_ssl://kafka-int.example.com:9095/bootstrap: GSSAPI Error: Miscellaneous failure (see text) (Matching credential (kafka/[email protected]) not found)
%5|1620820987.183|LIBSASL|rdkafka#producer-1| [thrd:sasl_ssl://kafka-int.example.com:9095/bootstrap]: sasl_ssl://kafka-int.example.com:9095/bootstrap: GSSAPI client step 1
%2|1620820987.651|LIBSASL|rdkafka#producer-1| [thrd:sasl_ssl://kafka-int.example.com:9095/bootstrap]: sasl_ssl://kafka-int.example.com:9095/bootstrap: GSSAPI Error: Miscellaneous failure (see text) (Matching credential (kafka/[email protected]) not found)
%5|1620820998.114|LIBSASL|rdkafka#producer-1| [thrd:sasl_ssl://kafka-int.example.com:9095/bootstrap]: sasl_ssl://kafka-int.example.com:9095/bootstrap: GSSAPI client step 1
%2|1620820998.480|LIBSASL|rdkafka#producer-1| [thrd:sasl_ssl://kafka-int.example.com:9095/bootstrap]: sasl_ssl://kafka-int.example.com:9095/bootstrap: GSSAPI Error: Miscellaneous failure (see text) (Matching credential (kafka/[email protected]) not found)
% ERROR: Failed to acquire metadata: Local: Broker transport failure
Where localhost/kafkacat_gssapi:1 just built from Dockerfile:
FROM docker.io/edenhill/kafkacat:1.6.0
RUN apk add --no-cache cyrus-sasl cyrus-sasl-gssapiv2 krb5 openssl ca-certificates
$ podman run -it --rm localhost/kafkacat_gssapi:1 -V
kafkacat - Apache Kafka producer and consumer tool
https://github.com/edenhill/kafkacat
Copyright (c) 2014-2019, Magnus Edenhill
Version 1.6.0 (JSON, Avro, Transactions, librdkafka 1.5.0 builtin.features=gzip,snappy,ssl,sasl,regex,lz4,sasl_gssapi,sasl_plain,sasl_scram,plugins,zstd,sasl_oauthbearer)
Same run on Fedora 33:
kafkacat \
-b kafka-int.example.com:9095 \
-Xssl.ca.location=conf/integration/kafka-int.ca.crt \
-Xsecurity.protocol=SASL_SSL \
-Xsasl.mechanisms=GSSAPI \
'-Xsasl.kerberos.kinit.cmd=cat conf/paswd | /usr/bin/kinit [email protected]' \
-Xsasl.kerberos.service.name=kafka \
-m 30 \
-L
Password for [email protected]:
%5|1620821374.957|LIBSASL|rdkafka#producer-1| [thrd:sasl_ssl://kafka-int.example.com:9095/bootstrap]: sasl_ssl://kafka-int.example.com:9095/bootstrap: GSSAPI client step 1
%5|1620821384.957|LIBSASL|rdkafka#producer-1| [thrd:sasl_ssl://kafka-int.example.com:9095/bootstrap]: sasl_ssl://kafka-int.example.com:9095/bootstrap: GSSAPI client step 1
%5|1620821385.027|LIBSASL|rdkafka#producer-1| [thrd:sasl_ssl://kafka-int.example.com:9095/bootstrap]: sasl_ssl://kafka-int.example.com:9095/bootstrap: GSSAPI client step 2
Metadata for all topics (from broker -1: sasl_ssl://kafka-int.example.com:9095/bootstrap):
3 brokers:
broker 202 at ecsc00a09eab.example.com:9095
broker 201 at ecsc00a09eaa.example.com:9095 (controller)
broker 203 at ecsc00a09eac.example.com:9095
1440 topics:
topic "test-topic" with 1 partitions:
partition 0, leader 202, replicas: 202,203,201, isrs: 201,203,202
topic "datahub.....EffectiveFrom" with 1 partitions:
partition 0, leader 201, replicas: 201,203, isrs: 201,203
...
What interesting, if I run with KRB5_TRACE=/dev/stdout in direct working case I see (full log):
[2616356] 1620807906.324107: Sending DNS URI query for _kerberos.PETERSBURG.EXAMPLE.COM.
[2616356] 1620807906.324108: No URI records found
[2616356] 1620807906.324109: Sending DNS SRV query for _kerberos._tcp.PETERSBURG.EXAMPLE.COM.
[2616356] 1620807906.324110: SRV answer: 0 100 88 "evrupetsa0001.petersburg.example.com."
[2616356] 1620807906.324111: SRV answer: 0 100 88 "evrupetsa0007.petersburg.example.com."
[2616356] 1620807906.324112: SRV answer: 0 100 88 "evbyminsa0007.petersburg.example.com."
[2616356] 1620807906.324113: SRV answer: 0 100 88 "evusprisa0049.petersburg.example.com."
[2616356] 1620807906.324114: SRV answer: 0 100 88 "evhubudsa0001.petersburg.example.com."
[2616356] 1620807906.324115: Resolving hostname evrupetsa0001.petersburg.example.com.
[2616356] 1620807906.324116: Initiating TCP connection to stream 10.66.110.11:88
[2616356] 1620807906.324117: Sending TCP request to stream 10.66.110.11:88
[2616356] 1620807906.324118: Received answer (4491 bytes) from stream 10.66.110.11:88
[2616356] 1620807906.324119: Terminating TCP connection to stream 10.66.110.11:88
[2616356] 1620807906.324120: Sending DNS URI query for _kerberos.PETERSBURG.EXAMPLE.COM.
[2616356] 1620807906.324121: No URI records found
[2616356] 1620807906.324122: Sending DNS SRV query for _kerberos-master._tcp.PETERSBURG.EXAMPLE.COM.
[2616356] 1620807906.324123: No SRV records found
[2616356] 1620807906.324124: Response was not from master KDC
[2616356] 1620807906.324125: Processing preauth types: PA-ETYPE-INFO2 (19)
[2616356] 1620807906.324126: Selected etype info: etype aes256-cts, salt "PETERSBURG.EXAMPLE.COMPavel_Alexeev", params ""
[2616356] 1620807906.324127: Produced preauth for next request: (empty)
[2616356] 1620807906.324128: AS key determined by preauth: aes256-cts/83C9
[2616356] 1620807906.324129: Decrypted AS reply; session key is: aes256-cts/CCEB
[2616356] 1620807906.324130: FAST negotiation: unavailable
[2616356] 1620807906.324131: Initializing FILE:/tmp/krb5cc_1000 with default princ [email protected]
[2616356] 1620807906.324132: Storing [email protected] -> krbtgt/[email protected] in FILE:/tmp/krb5cc_1000
[2616356] 1620807906.324133: Storing config in FILE:/tmp/krb5cc_1000 for krbtgt/[email protected]: pa_type: 2
[2616356] 1620807906.324134: Storing [email protected] -> krb5_ccache_conf_data/pa_type/krbtgt\/PETERSBURG.EXAMPLE.COM\@PETERSBURG.EXAMPLE.COM@X-CACHECONF: in FILE:/tmp/krb5cc_1000
%5|1620807906.993|LIBSASL|rdkafka#producer-1| [thrd:sasl_ssl://kafka-int.example.com:9095/bootstrap]: sasl_ssl://kafka-int.example.com:9095/bootstrap: GSSAPI client step 1
[2616353] 1620807906.996539: ccselect can't find appropriate cache for server principal kafka/[email protected]
[2616353] 1620807906.996540: Getting credentials [email protected] -> kafka/[email protected] using ccache FILE:/tmp/krb5cc_1000
[2616353] 1620807906.996541: Retrieving [email protected] -> kafka/[email protected] from FILE:/tmp/krb5cc_1000 with result: -1765328243/Matching credential not found (filename: /tmp/krb5cc_1000)
[2616353] 1620807906.996542: Retrieving [email protected] -> krbtgt/[email protected] from FILE:/tmp/krb5cc_1000 with result: -1765328243/Matching credential not found (filename: /tmp/krb5cc_1000)
[2616353] 1620807906.996543: Retrieving [email protected] -> krbtgt/[email protected] from FILE:/tmp/krb5cc_1000 with result: 0/Success
[2616353] 1620807906.996544: Starting with TGT for client realm: [email protected] -> krbtgt/[email protected]
[2616353] 1620807906.996545: Retrieving [email protected] -> krbtgt/[email protected] from FILE:/tmp/krb5cc_1000 with result: -1765328243/Matching credential not found (filename: /tmp/krb5cc_1000)
[2616353] 1620807906.996546: Requesting TGT krbtgt/[email protected] using TGT krbtgt/[email protected]
[2616353] 1620807906.996547: Generated subkey for TGS request: aes256-cts/69EE
[2616353] 1620807906.996548: etypes requested in TGS request: aes256-cts, aes128-cts, aes256-sha2, aes128-sha2, rc4-hmac, camellia128-cts, camellia256-cts
[2616353] 1620807906.996550: Encoding request body and padata into FAST request
[2616353] 1620807906.996551: Sending request (4611 bytes) to PETERSBURG.EXAMPLE.COM
[2616353] 1620807906.996552: Sending DNS URI query for _kerberos.PETERSBURG.EXAMPLE.COM.
[2616353] 1620807907.003430: No URI records found
[2616353] 1620807907.003431: Sending DNS SRV query for _kerberos._udp.PETERSBURG.EXAMPLE.COM.
[2616353] 1620807907.003432: SRV answer: 0 100 88 "evrupetsa0007.petersburg.example.com."
[2616353] 1620807907.003433: SRV answer: 0 100 88 "evrupetsa0001.petersburg.example.com."
[2616353] 1620807907.003434: SRV answer: 0 100 88 "evusprisa0049.petersburg.example.com."
[2616353] 1620807907.003435: SRV answer: 0 100 88 "evhubudsa0001.petersburg.example.com."
[2616353] 1620807907.003436: SRV answer: 0 100 88 "evbyminsa0007.petersburg.example.com."
[2616353] 1620807907.003437: Sending DNS SRV query for _kerberos._tcp.PETERSBURG.EXAMPLE.COM.
[2616353] 1620807907.003438: SRV answer: 0 100 88 "evrupetsa0007.petersburg.example.com."
[2616353] 1620807907.003439: SRV answer: 0 100 88 "evbyminsa0007.petersburg.example.com."
[2616353] 1620807907.003440: SRV answer: 0 100 88 "evusprisa0049.petersburg.example.com."
[2616353] 1620807907.003441: SRV answer: 0 100 88 "evhubudsa0001.petersburg.example.com."
[2616353] 1620807907.003442: SRV answer: 0 100 88 "evrupetsa0001.petersburg.example.com."
[2616353] 1620807907.003443: Resolving hostname evrupetsa0007.petersburg.example.com.
[2616353] 1620807907.003444: Resolving hostname evrupetsa0001.petersburg.example.com.
[2616353] 1620807907.003445: Resolving hostname evusprisa0049.petersburg.example.com.
[2616353] 1620807907.003446: Resolving hostname evhubudsa0001.petersburg.example.com.
[2616353] 1620807907.003447: Resolving hostname evbyminsa0007.petersburg.example.com.
[2616353] 1620807907.003448: Resolving hostname evrupetsa0007.petersburg.example.com.
[2616353] 1620807907.003449: Initiating TCP connection to stream 10.66.110.17:88
[2616353] 1620807907.003450: Sending TCP request to stream 10.66.110.17:88
[2616353] 1620807907.003451: Received answer (4542 bytes) from stream 10.66.110.17:88
[2616353] 1620807907.003452: Terminating TCP connection to stream 10.66.110.17:88
[2616353] 1620807907.003453: Sending DNS URI query for _kerberos.PETERSBURG.EXAMPLE.COM.
[2616353] 1620807907.003454: No URI records found
[2616353] 1620807907.003455: Sending DNS SRV query for _kerberos-master._tcp.PETERSBURG.EXAMPLE.COM.
[2616353] 1620807907.003456: No SRV records found
[2616353] 1620807907.003457: Response was not from master KDC
[2616353] 1620807907.003458: Decoding FAST response
[2616353] 1620807907.003459: FAST reply key: aes256-cts/9007
[2616353] 1620807907.003460: TGS reply is for [email protected] -> krbtgt/[email protected] with session key rc4-hmac/7459
[2616353] 1620807907.003461: TGS request result: 0/Success
[2616353] 1620807907.003462: Storing [email protected] -> krbtgt/[email protected] in FILE:/tmp/krb5cc_1000
[2616353] 1620807907.003463: Received TGT for service realm: krbtgt/[email protected]
[2616353] 1620807907.003464: Requesting tickets for kafka/[email protected], referrals on
[2616353] 1620807907.003465: Generated subkey for TGS request: rc4-hmac/F9B4
[2616353] 1620807907.003466: etypes requested in TGS request: aes256-cts, aes128-cts, aes256-sha2, aes128-sha2, rc4-hmac, camellia128-cts, camellia256-cts
[2616353] 1620807907.003468: Encoding request body and padata into FAST request
[2616353] 1620807907.003469: Sending request (4615 bytes) to EXAMPLE.COM
[2616353] 1620807907.003470: Sending DNS URI query for _kerberos.EXAMPLE.COM.
[2616353] 1620807907.003471: No URI records found
[2616353] 1620807907.003472: Sending DNS SRV query for _kerberos._udp.EXAMPLE.COM.
[2616353] 1620807907.003473: SRV answer: 0 100 88 "evusbossa0000.example.com."
[2616353] 1620807907.003474: SRV answer: 0 100 88 "evkzastsa0000.example.com."
...
[2616353] 1620807907.003762: Resolving hostname EVUAVINSA0000.example.com.
[2616353] 1620807907.003763: Resolving hostname EVUSCONSA0000.example.com.
[2616353] 1620807907.003764: Initiating TCP connection to stream 10.22.128.2:88
[2616353] 1620807907.003765: Sending TCP request to stream 10.22.128.2:88
[2616353] 1620807908.732538: Received answer (4631 bytes) from stream 10.22.128.2:88
[2616353] 1620807908.732539: Terminating TCP connection to stream 10.22.128.2:88
[2616353] 1620807908.732540: Sending DNS URI query for _kerberos.EXAMPLE.COM.
[2616353] 1620807908.732541: No URI records found
[2616353] 1620807908.732542: Sending DNS SRV query for _kerberos-master._tcp.EXAMPLE.COM.
[2616353] 1620807908.732543: No SRV records found
[2616353] 1620807908.732544: Response was not from master KDC
[2616353] 1620807908.732545: Decoding FAST response
[2616353] 1620807908.732546: FAST reply key: rc4-hmac/2A6B
[2616353] 1620807908.732547: TGS reply is for [email protected] -> kafka/[email protected] with session key aes256-cts/F35A
[2616353] 1620807908.732548: TGS request result: 0/Success
[2616353] 1620807908.732549: Received creds for desired service kafka/[email protected]
[2616353] 1620807908.732550: Storing [email protected] -> kafka/[email protected] in FILE:/tmp/krb5cc_1000
[2616353] 1620807908.732552: Creating authenticator for [email protected] -> kafka/[email protected], seqnum 691537013, subkey aes256-cts/A6FD, session key aes256-cts/F35A
%5|1620807908.873|LIBSASL|rdkafka#producer-1| [thrd:sasl_ssl://kafka-int.example.com:9095/bootstrap]: sasl_ssl://kafka-int.example.com:9095/bootstrap: GSSAPI client step 1
In case of an error in the alpine container (full log):
[4] 1620808362.090471: Sending DNS URI query for _kerberos.PETERSBURG.EXAMPLE.COM.
[4] 1620808362.090472: No URI records found
[4] 1620808362.090473: Sending DNS SRV query for _kerberos._tcp.PETERSBURG.EXAMPLE.COM.
[4] 1620808362.090474: SRV answer: 0 100 88 "evusprisa0049.petersburg.example.com."
[4] 1620808362.090475: SRV answer: 0 100 88 "evhubudsa0001.petersburg.example.com."
[4] 1620808362.090476: SRV answer: 0 100 88 "evrupetsa0001.petersburg.example.com."
[4] 1620808362.090477: SRV answer: 0 100 88 "evrupetsa0007.petersburg.example.com."
[4] 1620808362.090478: SRV answer: 0 100 88 "evbyminsa0007.petersburg.example.com."
[4] 1620808362.090479: Resolving hostname evusprisa0049.petersburg.example.com.
[4] 1620808362.090480: Initiating TCP connection to stream 10.244.110.7:88
[4] 1620808362.090481: Sending TCP request to stream 10.244.110.7:88
[4] 1620808362.090482: Received answer (4491 bytes) from stream 10.244.110.7:88
[4] 1620808362.090483: Terminating TCP connection to stream 10.244.110.7:88
[4] 1620808362.090484: Sending DNS URI query for _kerberos.PETERSBURG.EXAMPLE.COM.
[4] 1620808362.090485: No URI records found
[4] 1620808362.090486: Sending DNS SRV query for _kerberos-master._tcp.PETERSBURG.EXAMPLE.COM.
[4] 1620808362.090487: No SRV records found
[4] 1620808362.090488: Response was not from master KDC
[4] 1620808362.090489: Processing preauth types: PA-ETYPE-INFO2 (19)
[4] 1620808362.090490: Selected etype info: etype aes256-cts, salt "PETERSBURG.EXAMPLE.COMPavel_Alexeev", params ""
[4] 1620808362.090491: Produced preauth for next request: (empty)
[4] 1620808362.090492: AS key determined by preauth: aes256-cts/83C9
[4] 1620808362.090493: Decrypted AS reply; session key is: aes256-cts/9506
[4] 1620808362.090494: FAST negotiation: unavailable
[4] 1620808362.090495: Initializing FILE:/tmp/krb5cc_0 with default princ [email protected]
[4] 1620808362.090496: Storing [email protected] -> krbtgt/[email protected] in FILE:/tmp/krb5cc_0
[4] 1620808362.090497: Storing config in FILE:/tmp/krb5cc_0 for krbtgt/[email protected]: pa_type: 2
[4] 1620808362.090498: Storing [email protected] -> krb5_ccache_conf_data/pa_type/krbtgt\/PETERSBURG.EXAMPLE.COM\@PETERSBURG.EXAMPLE.COM@X-CACHECONF: in FILE:/tmp/krb5cc_0
%5|1620808363.004|LIBSASL|rdkafka#producer-1| [thrd:sasl_ssl://kafka-int.example.com:9095/bootstrap]: sasl_ssl://kafka-int.example.com:9095/bootstrap: GSSAPI client step 1
%2|1620808363.250|LIBSASL|rdkafka#producer-1| [thrd:sasl_ssl://kafka-int.example.com:9095/bootstrap]: sasl_ssl://kafka-int.example.com:9095/bootstrap: GSSAPI Error: Miscellaneous failure (see text) (Matching credential (kafka/[email protected]) not found)
What also looks very interesting and strange to me, on host machine where all works just after kafkacat execution klist show me 3 tickets:
$ klist
Ticket cache: FILE:/tmp/krb5cc_1000
Default principal: [email protected]
Valid starting Expires Service principal
12/05/21 19:53:26 13/05/21 03:53:26 krbtgt/[email protected]
renew until 19/05/21 19:53:26
12/05/21 19:53:27 13/05/21 03:53:26 krbtgt/[email protected]
renew until 19/05/21 19:53:26
12/05/21 19:53:28 13/05/21 03:53:26 kafka/[email protected]
renew until 13/05/21 05:53:28
But in the same time, if I change parameter '-Xsasl.kerberos.kinit.cmd=/usr/bin/kinit --use-referrals --password-file=/conf/paswd [email protected]; klist' I see there only one ticket! For example:
$ podman run --rm -it --name kafkacat-DEV \
-v$(pwd)/conf/integration:/conf -v$(pwd)/conf/integration/krb5.conf:/etc/krb5.conf \
localhost/kafkacat_gssapi_heimdal:3 \
kafkacat \
-b kafka-int.example.com:9095 \
-Xssl.ca.location=/conf/kafka-int.ca.crt \
-Xsecurity.protocol=SASL_SSL \
-Xsasl.mechanisms=GSSAPI \
'-Xsasl.kerberos.kinit.cmd=/usr/bin/kinit --use-referrals --password-file=/conf/paswd [email protected]; klist' \
-Xsasl.kerberos.service.name=kafka \
-m30 -L
...
Credentials cache: FILE:/tmp/krb5cc_0
Principal: [email protected]
Issued Expires Principal
May 12 18:54:50 2021 May 13 02:54:49 2021 krbtgt/[email protected]
...
So I can't understand where 2 others come from
Listing after execute kafkacat in the container also show only a single principal.
Will appreciate any help.
P.S. Also report it as cyrus-sasl issue
Very strange issue, and honestly I can't say why, but adding into krb5.conf:
[libdefaults]
dns_canonicalize_hostname = false
solves the problem.
P.S. I've posted that as the solution because it starts work. But if someone may explain in comments why it is the solution and especially how that may be understandable from provided logs it will be very helpful.