Fwd: Authentication issues using cyrus-sasl from librdkafka on CentOSVM with Kerberos

Marcel Gutsche mail at marcelgutsche.de
Mon Jan 15 05:06:03 EST 2018


Thanks for all the suggestions.
I got rid of the "-S kafka/host" part, which also removed the credential
not found error. But I still cannot connect to the KafkaServer using the
VM. Maybe someone of you knows if the following log relates to a finally
successful authorization, or if there is still something missing.

```
%7|1516010149.485|SASL|rdkafka#consumer-1| [thrd:app]: Selected provider
Cyrus for SASL mechanism GSSAPI
%7|1516010149.485|MEMBERID|rdkafka#consumer-1| [thrd:app]: Group
"user_python_rhel": updating member id "(not-set)" -> ""
%7|1516010149.485|BRKREASSIGN|rdkafka#consumer-1| [thrd:main]: Group
"user_python_rhel" management reassigned from broker (none) to :0/internal
%7|1516010149.485|CGRPSTATE|rdkafka#consumer-1| [thrd:main]: Group
"user_python_rhel" changed state init -> wait-broker (v1, join-state init)
%7|1516010149.485|BRKASSIGN|rdkafka#consumer-1| [thrd:main]: Group
"user_python_rhel" management assigned to broker :0/internal
%7|1516010149.486|CGRPOP|rdkafka#consumer-1| [thrd:main]: Group
"user_python_rhel" received op SUBSCRIBE (v0) in state wait-broker (join
state init, v1 vs 0)
%7|1516010149.486|SUBSCRIBE|rdkafka#consumer-1| [thrd:main]: Group
"user_python_rhel": subscribe to new subscription of 1 topics (join state
init)
%7|1516010149.486|UNSUBSCRIBE|rdkafka#consumer-1| [thrd:main]: Group
"user_python_rhel": unsubscribe from current unset subscription of 0 topics
(leave group=no, join state init, v1)
%7|1516010149.486|GRPLEADER|rdkafka#consumer-1| [thrd:main]: Group
"user_python_rhel": resetting group leader info: unsubscribe
%7|1516010149.486|CGRPJOINSTATE|rdkafka#consumer-1| [thrd:main]: Group
"user_python_rhel" changed join state init -> wait-unassign (v1, state
wait-broker)
%7|1516010149.486|UNASSIGN|rdkafka#consumer-1| [thrd:main]: Group
"user_python_rhel": unassign done in state wait-broker (join state
wait-unassign): without new assignment: unassign (no previous assignment)
%7|1516010149.486|CGRPJOINSTATE|rdkafka#consumer-1| [thrd:main]: Group
"user_python_rhel" changed join state wait-unassign -> init (v1, state
wait-broker)
%7|1516010149.486|CGRPQUERY|rdkafka#consumer-1| [thrd:main]: Group
"user_python_rhel": no broker available for coordinator query: intervaled
in state wait-broker
%3|1516010149.537|FAIL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host1:9092/bootstrap]:
sasl_plaintext://host1:9092/bootstrap: Connect to ipv4#XXX.XXX.XXX.XXX:PPPP
failed: Connection refused
%3|1516010149.537|ERROR|rdkafka#consumer-1|
[thrd:sasl_plaintext://host1:9092/bootstrap]:
sasl_plaintext://host1:9092/bootstrap: Connect to ipv4#XXX.XXX.XXX.XXX:PPPP
failed: Connection refused
%7|1516010149.585|AUTH|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: Auth in state APIVERSION_QUERY
(handshake supported)
%7|1516010149.585|AUTH|rdkafka#consumer-1|
[thrd:sasl_plaintext://host2:9092/bootstrap]:
sasl_plaintext://host2:9092/bootstrap: Auth in state APIVERSION_QUERY
(handshake supported)
%7|1516010149.633|SASLMECHS|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: Broker supported SASL mechanisms:
GSSAPI
%7|1516010149.634|AUTH|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: Auth in state AUTH_HANDSHAKE
(handshake supported)
%7|1516010149.634|SASLMECHS|rdkafka#consumer-1|
[thrd:sasl_plaintext://host2:9092/bootstrap]:
sasl_plaintext://host2:9092/bootstrap: Broker supported SASL mechanisms:
GSSAPI
%7|1516010149.634|AUTH|rdkafka#consumer-1|
[thrd:sasl_plaintext://host2:9092/bootstrap]:
sasl_plaintext://host2:9092/bootstrap: Auth in state AUTH_HANDSHAKE
(handshake supported)
%7|1516010149.634|SASL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host2:9092/bootstrap]:
sasl_plaintext://host2:9092/bootstrap: Initializing SASL client: service
name kafka, hostname host2, mechanisms GSSAPI, provider Cyrus
%7|1516010149.634|SASLREFRESH|rdkafka#consumer-1|
[thrd:sasl_plaintext://host2:9092/bootstrap]:
sasl_plaintext://host2:9092/bootstrap: Refreshing SASL keys with command:
kinit  -kt {} user at PRINCIPAL
%7|1516010149.634|SASL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: Initializing SASL client: service
name kafka, hostname host3, mechanisms GSSAPI, provider Cyrus
%7|1516010149.634|SASLREFRESH|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: Refreshing SASL keys with command:
kinit  -kt {} user at PRINCIPAL
kinit: Pre-authentication failed: Key table file '{}' not found while
getting initial credentials
%3|1516010149.700|SASLREFRESH|rdkafka#consumer-1|
[thrd:sasl_plaintext://host2:9092/bootstrap]:
sasl_plaintext://host2:9092/bootstrap: SASL key refresh failed: kinit  -kt
{} user at PRINCIPAL: exited with code 1
%7|1516010149.701|SASL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host2:9092/bootstrap]:
sasl_plaintext://host2:9092/bootstrap: My supported SASL mechanisms:
GS2-IAKERB GS2-KRB5 SCRAM-SHA-1 GSSAPI GSS-SPNEGO DIGEST-MD5 EXTERNAL OTP
CRAM-MD5 PLAIN ANONYMOUS
%5|1516010149.701|LIBSASL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host2:9092/bootstrap]:
sasl_plaintext://host2:9092/bootstrap: GSSAPI client step 1
kinit: Pre-authentication failed: Key table file '{}' not found while
getting initial credentials
%3|1516010149.764|SASLREFRESH|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: SASL key refresh failed: kinit  -kt
{} user at PRINCIPAL: exited with code 1
%7|1516010149.764|SASL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: My supported SASL mechanisms:
GS2-IAKERB GS2-KRB5 SCRAM-SHA-1 GSSAPI GSS-SPNEGO DIGEST-MD5 EXTERNAL OTP
CRAM-MD5 PLAIN ANONYMOUS
%5|1516010149.764|LIBSASL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: GSSAPI client step 1
%7|1516010149.816|LIBSASL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: CB_CANON: flags 0x3, "user at PRINCIPAL"
@ "(null)": returning "user at PRINCIPAL"
%7|1516010149.816|SASL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: Selected SASL mechanism: GSSAPI
(wanted GSSAPI)
%7|1516010149.816|SASL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: Send SASL frame to broker (624 bytes)
%7|1516010149.865|SASL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: Received SASL frame from broker (36
bytes)
%5|1516010149.865|LIBSASL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: GSSAPI client step 2
%7|1516010149.865|SASL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: Send SASL frame to broker (32 bytes)
%7|1516010149.865|SASL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: Authenticated as user at PRINCIPAL
using GSSAPI (gssapiv2)
%7|1516010149.999|SUBSCRIPTION|rdkafka#consumer-1| [thrd:main]: Group
"user_python_rhel": no topics in metadata matched subscription
%7|1516010149.999|BRKREASSIGN|rdkafka#consumer-1| [thrd:main]: Group
"user_python_rhel" management reassigned from broker :0/internal to
sasl_plaintext://host3:9092/3
%7|1516010149.999|BRKUNASSIGN|rdkafka#consumer-1| [thrd:main]: Group
"user_python_rhel" management unassigned from broker handle :0/internal
%7|1516010149.999|BRKASSIGN|rdkafka#consumer-1| [thrd:main]: Group
"user_python_rhel" management assigned to broker
sasl_plaintext://host3:9092/3
%7|1516010149.999|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user_python_rhel": querying for
coordinator: intervaled in state wait-broker
%7|1516010150.048|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user_python_rhel" coordinator is
host2:9092 id 2
%7|1516010150.048|CGRPCOORD|rdkafka#consumer-1| [thrd:main]: Group
"user_python_rhel" changing coordinator -1 -> 2
%7|1516010151.484|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user_python_rhel": querying for
coordinator: intervaled in state wait-broker
%7|1516010151.533|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user_python_rhel" coordinator is
host2:9092 id 2
%7|1516010152.485|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user_python_rhel": querying for
coordinator: intervaled in state wait-broker
%7|1516010152.533|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user_python_rhel" coordinator is
host2:9092 id 2
%7|1516010153.485|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user_python_rhel": querying for
coordinator: intervaled in state wait-broker
%7|1516010153.533|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user_python_rhel" coordinator is
host2:9092 id 2
%7|1516010154.485|COMMIT|rdkafka#consumer-1| [thrd:main]: OffsetCommit
internal error: Local: No offset stored
%7|1516010154.485|COMMIT|rdkafka#consumer-1| [thrd:main]: OffsetCommit for
-1 partition(s): cgrp auto commit timer: returned: Local: No offset stored
%7|1516010154.485|UNASSIGN|rdkafka#consumer-1| [thrd:main]: Group
"user_python_rhel": unassign done in state wait-broker (join state init):
without new assignment: OffsetCommit done (__NO_OFFSET)
%7|1516010154.485|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user_python_rhel": querying for
coordinator: intervaled in state wait-broker
%7|1516010154.533|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user_python_rhel" coordinator is
host2:9092 id 2
%7|1516010155.485|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user_python_rhel": querying for
coordinator: intervaled in state wait-broker
%7|1516010155.534|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user_python_rhel" coordinator is
host2:9092 id 2
%7|1516010156.485|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user_python_rhel": querying for
coordinator: intervaled in state wait-broker
%7|1516010156.534|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user_python_rhel" coordinator is
host2:9092 id 2
%7|1516010157.485|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user_python_rhel": querying for
coordinator: intervaled in state wait-broker
%7|1516010157.534|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user_python_rhel" coordinator is
host2:9092 id 2
%7|1516010158.485|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user_python_rhel": querying for
coordinator: intervaled in state wait-broker
%7|1516010158.534|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user_python_rhel" coordinator is
host2:9092 id 2
%7|1516010159.485|COMMIT|rdkafka#consumer-1| [thrd:main]: OffsetCommit
internal error: Local: No offset stored
%7|1516010159.485|COMMIT|rdkafka#consumer-1| [thrd:main]: OffsetCommit for
-1 partition(s): cgrp auto commit timer: returned: Local: No offset stored
%7|1516010159.485|UNASSIGN|rdkafka#consumer-1| [thrd:main]: Group
"user_python_rhel": unassign done in state wait-broker (join state init):
without new assignment: OffsetCommit done (__NO_OFFSET)
%7|1516010159.485|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user_python_rhel": querying for
coordinator: intervaled in state wait-broker
%7|1516010159.533|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user_python_rhel" coordinator is
host2:9092 id 2
%7|1516010160.485|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user_python_rhel": querying for
coordinator: intervaled in state wait-broker
%7|1516010160.534|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user_python_rhel" coordinator is
host2:9092 id 2
%7|1516010161.485|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user_python_rhel": querying for
coordinator: intervaled in state wait-broker
%7|1516010161.534|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user_python_rhel" coordinator is
host2:9092 id 2
%7|1516010162.485|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user_python_rhel": querying for
coordinator: intervaled in state wait-broker
%7|1516010162.534|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user_python_rhel" coordinator is
host2:9092 id 2
^C^C%7|1516010163.485|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user_python_rhel": querying for
coordinator: intervaled in state wait-broker
%7|1516010163.534|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user_python_rhel" coordinator is
host2:9092 id 2
^C^C%7|1516010164.485|COMMIT|rdkafka#consumer-1| [thrd:main]: OffsetCommit
internal error: Local: No offset stored
%7|1516010164.485|COMMIT|rdkafka#consumer-1| [thrd:main]: OffsetCommit for
-1 partition(s): cgrp auto commit timer: returned: Local: No offset stored
%7|1516010164.485|UNASSIGN|rdkafka#consumer-1| [thrd:main]: Group
"user_python_rhel": unassign done in state wait-broker (join state init):
without new assignment: OffsetCommit done (__NO_OFFSET)
%7|1516010164.485|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user_python_rhel": querying for
coordinator: intervaled in state wait-broker
%7|1516010164.534|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user_python_rhel" coordinator is
host2:9092 id 2
```

As you can see I am still stuck and waiting for the broker, but that might
be unrelated to the kerberos authorization process. To lift the confusion
about DNS and PRINCIPAL and hosts I also add my /etc/hosts and my krb5.conf
file:

/etc/hosts

```
127.0.0.1   localhost localhost.localdomain localhost4
localhost4.localdomain4
::1         localhost localhost.localdomain localhost6
localhost6.localdomain6
XXX.XXX.67.237 host1
XXX.XXX.67.168 principal host2 PRINCIPAL
XXX.XXX.67.184 host3
```
krb5.conf
```
[libdefaults]
default_realm = PRINCIPAL
dns_lookup_kdc = false


[realms]
KDDLAB.KRB.GR = {
kdc = XXX.XXX.67.168
admin_server = XXX.XXX.67.168
}

[domain_realm]

[logging]
kdc = SYSLOG:INFO
admin_server = FILE=/var/log/kadm5.log

```

2018-01-14 9:43 GMT+01:00 Fabiano Tarlao <ftarlao at gmail.com>:

> I'm a newbie and had a similar issue, in order to find out the right
> principal for a service, I executed Wireshark on client or server node in a
> test env... Wireshark kerberos dissector works quite well and tuo can see
> details of requests, principals too. Perhaps this ke obvious but.. Not for
> me :-(
>
> Il 13 gen 2018 17:46, "Greg Hudson" <ghudson at mit.edu> ha scritto:
>
>> My best guess is that there is a disagreement between the server
>> principal name passed to kinit -S ("kafka/host") and the server
>> principal name chosen by SASL GSSAPI.  At least, that's the most obvious
>> way I can find to get a "Matching credential not found" error message
>> from MIT krb5's GSSAPI library.  It's hard for me to be sure since I'm
>> not seeing any krb5 trace logs resulting from the SASL operation, only
>> from the kinit operation.  (I would expect to see at least trace logs
>> like "Getting credentials <clientprinc> -> <serverprinc> using ccache
>> <ccache>" and "Retrieving <clientprinc> -> <serverprinc> from <ccache>
>> with result: ...")
>>
>> If you can configure rdkafka to acquire a TGT from the keytab instead of
>> directly acquiring a service ticket (by removing "-S kafka/host" from
>> the kinit command line), you could verify that this is the problem and
>> to determine (using klist) what service ticket is acquired during
>> authentication.
>>
>> ________________________________________________
>> Kerberos mailing list           Kerberos at mit.edu
>> https://mailman.mit.edu/mailman/listinfo/kerberos
>>
>


More information about the Kerberos mailing list