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

classic Classic list List threaded Threaded
6 messages Options
Reply | Threaded
Open this post in threaded view
|

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

Marcel Gutsche
Hi,


I have a hard time troubleshooting an error. I posted the issue
already here (https://github.com/edenhill/librdkafka/issues/1630) and
here (https://github.com/cyrusimap/cyrus-sasl/issues/501), but to no
avail.


In short:


I try to access a KafkaServer which uses Kerberos for authentication.
The setup librdkafka works from my local machine running Ubuntu 16.04.
It also works from my CentOS VM, when I use the java application (not
librdkafka) for contacting the Kafka Server.  It does not work when I
try to use librdkafka from frm the VM. Details and logs can be found
in the link above. Maybe you have any idea for troubleshooting?


Kind regards,

Marcel
________________________________________________
Kerberos mailing list           [hidden email]
https://mailman.mit.edu/mailman/listinfo/kerberos
Reply | Threaded
Open this post in threaded view
|

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

Ken Hornstein
>I have a hard time troubleshooting an error. I posted the issue
>already here (https://github.com/edenhill/librdkafka/issues/1630) and
>here (https://github.com/cyrusimap/cyrus-sasl/issues/501), but to no
>avail.

It might be helpful to describe what the underlying Kerberos implementation
is on the server side.  The key error is "Matching credential not found";
you can ignore everything else.

I know nothing about kafka, in terms of who is a client or server, but ...
you posted this config file snippet:

'sasl.kerberos.service.name': 'kafka',
'sasl.kerberos.principal': 'user@principal,
'sasl.kerberos.keytab': keytab_file,

Are you sure 'user@principal' is correct?  If that's on the server side,
that would strike me as unlikely (not knowing the details of Kafka).

--Ken
________________________________________________
Kerberos mailing list           [hidden email]
https://mailman.mit.edu/mailman/listinfo/kerberos
Reply | Threaded
Open this post in threaded view
|

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

Greg Hudson
In reply to this post by Marcel Gutsche
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           [hidden email]
https://mailman.mit.edu/mailman/listinfo/kerberos
Reply | Threaded
Open this post in threaded view
|

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

Fabiano Tarlao
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" <[hidden email]> 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           [hidden email]
> https://mailman.mit.edu/mailman/listinfo/kerberos
>
________________________________________________
Kerberos mailing list           [hidden email]
https://mailman.mit.edu/mailman/listinfo/kerberos
Reply | Threaded
Open this post in threaded view
|

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

Marcel Gutsche
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@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@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@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@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@PRINCIPAL"
@ "(null)": returning "user@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@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 <[hidden email]>:

> 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" <[hidden email]> 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           [hidden email]
>> https://mailman.mit.edu/mailman/listinfo/kerberos
>>
>
________________________________________________
Kerberos mailing list           [hidden email]
https://mailman.mit.edu/mailman/listinfo/kerberos
Reply | Threaded
Open this post in threaded view
|

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

Marcel Gutsche
Ah I still had a bug, not pointing to the correct keytab_file. Also
discussed here https://github.com/edenhill/librdkafka/issues/1630 and here
https://github.com/cyrusimap/cyrus-sasl/issues/501
It now hangs at an GSSAPI step 1.

```

Using python-kafka: ('0.11.0', 720896) and librdkafka
('0.11.1-109-g6f0750', 721407)
%7|1516023480.330|SASL|rdkafka#consumer-1| [thrd:app]: Selected
provider Cyrus for SASL mechanism GSSAPI
%7|1516023480.330|MEMBERID|rdkafka#consumer-1| [thrd:app]: Group
"user-cctv_python_rhel": updating member id "(not-set)" -> ""
%7|1516023480.332|BRKREASSIGN|rdkafka#consumer-1| [thrd:main]: Group
"user-cctv_python_rhel" management reassigned from broker (none) to
:0/internal
%7|1516023480.332|CGRPSTATE|rdkafka#consumer-1| [thrd:main]: Group
"user-cctv_python_rhel" changed state init -> wait-broker (v1,
join-state init)
%7|1516023480.332|BRKASSIGN|rdkafka#consumer-1| [thrd:main]: Group
"user-cctv_python_rhel" management assigned to broker :0/internal
%7|1516023480.332|CGRPOP|rdkafka#consumer-1| [thrd:main]: Group
"user-cctv_python_rhel" received op SUBSCRIBE (v0) in state
wait-broker (join state init, v1 vs 0)
%7|1516023480.332|SUBSCRIBE|rdkafka#consumer-1| [thrd:main]: Group
"user-cctv_python_rhel": subscribe to new subscription of 1 topics
(join state init)
%7|1516023480.332|UNSUBSCRIBE|rdkafka#consumer-1| [thrd:main]: Group
"user-cctv_python_rhel": unsubscribe from current unset subscription
of 0 topics (leave group=no, join state init, v1)
%7|1516023480.332|GRPLEADER|rdkafka#consumer-1| [thrd:main]: Group
"user-cctv_python_rhel": resetting group leader info: unsubscribe
%7|1516023480.332|CGRPJOINSTATE|rdkafka#consumer-1| [thrd:main]: Group
"user-cctv_python_rhel" changed join state init -> wait-unassign (v1,
state wait-broker)
%7|1516023480.332|UNASSIGN|rdkafka#consumer-1| [thrd:main]: Group
"user-cctv_python_rhel": unassign done in state wait-broker (join
state wait-unassign): without new assignment: unassign (no previous
assignment)
%7|1516023480.332|CGRPJOINSTATE|rdkafka#consumer-1| [thrd:main]: Group
"user-cctv_python_rhel" changed join state wait-unassign -> init (v1,
state wait-broker)
%7|1516023480.332|CGRPQUERY|rdkafka#consumer-1| [thrd:main]: Group
"user-cctv_python_rhel": no broker available for coordinator query:
intervaled in state wait-broker
%7|1516023480.385|CONNECTED|rdkafka#consumer-1|
[thrd:sasl_plaintext://host2:9092/bootstrap]:
sasl_plaintext://host2:9092/bootstrap: Connected (#1)
%7|1516023480.385|BROKERFAIL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host1:9092/bootstrap]:
sasl_plaintext://host1:9092/bootstrap: failed: err: Local: Broker
transport failure: (errno: Connection refused)
%7|1516023480.385|CONNECTED|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: Connected (#1)
%7|1516023480.385|FEATURE|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: Updated enabled protocol
features +ApiVersion to ApiVersion
%3|1516023480.385|FAIL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host1:9092/bootstrap]:
sasl_plaintext://host1:9092/bootstrap: Connect to
ipv4#XXX.XXX.XXX.237:9092 failed: Connection refused
%3|1516023480.385|ERROR|rdkafka#consumer-1|
[thrd:sasl_plaintext://host1:9092/bootstrap]:
sasl_plaintext://host1:9092/bootstrap: Connect to
ipv4#XXX.XXX.XXX.237:9092 failed: Connection refused
%7|1516023480.385|FEATURE|rdkafka#consumer-1|
[thrd:sasl_plaintext://host2:9092/bootstrap]:
sasl_plaintext://host2:9092/bootstrap: Updated enabled protocol
features +ApiVersion to ApiVersion
%7|1516023480.385|SEND|rdkafka#consumer-1|
[thrd:sasl_plaintext://host2:9092/bootstrap]:
sasl_plaintext://host2:9092/bootstrap: Sent ApiVersionRequest (v0, 25
bytes @ 0, CorrId 1)
%7|1516023480.385|SEND|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: Sent ApiVersionRequest (v0, 25
bytes @ 0, CorrId 1)
%7|1516023480.433|RECV|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: Received ApiVersionResponse
(v0, 132 bytes, CorrId 1, rtt 47.80ms)
%7|1516023480.433|AUTH|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: Auth in state APIVERSION_QUERY
(handshake supported)
%7|1516023480.433|RECV|rdkafka#consumer-1|
[thrd:sasl_plaintext://host2:9092/bootstrap]:
sasl_plaintext://host2:9092/bootstrap: Received ApiVersionResponse
(v0, 132 bytes, CorrId 1, rtt 47.92ms)
%7|1516023480.433|AUTH|rdkafka#consumer-1|
[thrd:sasl_plaintext://host2:9092/bootstrap]:
sasl_plaintext://host2:9092/bootstrap: Auth in state APIVERSION_QUERY
(handshake supported)
%7|1516023480.433|SEND|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: Sent SaslHandshakeRequest (v0,
29 bytes @ 0, CorrId 2)
%7|1516023480.433|SEND|rdkafka#consumer-1|
[thrd:sasl_plaintext://host2:9092/bootstrap]:
sasl_plaintext://host2:9092/bootstrap: Sent SaslHandshakeRequest (v0,
29 bytes @ 0, CorrId 2)
%7|1516023480.481|RECV|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: Received SaslHandshakeResponse
(v0, 14 bytes, CorrId 2, rtt 47.78ms)
%7|1516023480.481|RECV|rdkafka#consumer-1|
[thrd:sasl_plaintext://host2:9092/bootstrap]:
sasl_plaintext://host2:9092/bootstrap: Received SaslHandshakeResponse
(v0, 14 bytes, CorrId 2, rtt 47.75ms)
%7|1516023480.481|SASLMECHS|rdkafka#consumer-1|
[thrd:sasl_plaintext://host2:9092/bootstrap]:
sasl_plaintext://host2:9092/bootstrap: Broker supported SASL
mechanisms: GSSAPI
%7|1516023480.481|AUTH|rdkafka#consumer-1|
[thrd:sasl_plaintext://host2:9092/bootstrap]:
sasl_plaintext://host2:9092/bootstrap: Auth in state AUTH_HANDSHAKE
(handshake supported)
%7|1516023480.481|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|1516023480.481|SASLREFRESH|rdkafka#consumer-1|
[thrd:sasl_plaintext://host2:9092/bootstrap]:
sasl_plaintext://host2:9092/bootstrap: Refreshing SASL keys with
command: KRB5_TRACE=/dev/stdout kinit  -kt /root/user.keytab
user@PRINCIPAL
%7|1516023480.481|SASLMECHS|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: Broker supported SASL
mechanisms: GSSAPI
%7|1516023480.481|AUTH|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: Auth in state AUTH_HANDSHAKE
(handshake supported)
%7|1516023480.481|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|1516023480.481|SASLREFRESH|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: Refreshing SASL keys with
command: KRB5_TRACE=/dev/stdout kinit  -kt /root/user.keytab
user@PRINCIPAL
[24032] 1516023480.505296: Getting initial credentials for user@PRINCIPAL
[24032] 1516023480.511157: Looked up etypes in keytab: aes256-cts,
rc4-hmac, des3-cbc-sha1, des-cbc-crc
[24032] 1516023480.511341: Sending request (176 bytes) to PRINCIPAL
[24032] 1516023480.511883: Resolving hostname XXX.XXX.XXX.168
[24032] 1516023480.512229: Sending initial UDP request to dgram
XXX.XXX.XXX.168:88
[24032] 1516023480.560726: Received answer (327 bytes) from dgram
XXX.XXX.XXX.168:88
[24032] 1516023480.560830: Response was not from master KDC
[24032] 1516023480.560927: Received error from KDC:
-1765328359/Additional pre-authentication required
[24032] 1516023480.561108: Processing preauth types: 136, 19, 2, 133
[24032] 1516023480.561134: Selected etype info: etype aes256-cts, salt
"PRINCIPALuser", params ""
[24032] 1516023480.561145: Received cookie: MIT
[24032] 1516023480.561298: Retrieving user@PRINCIPAL from
FILE:/root/user.keytab (vno 0, enctype aes256-cts) with result:
0/Success
[24032] 1516023480.561357: AS key obtained for encrypted timestamp:
aes256-cts/114F
[24032] 1516023480.561566: Encrypted timestamp (for
1516023524.856095): plain 301AA011180xxxxxxxxxx, encrypted
C9AF43C25442F3xxxxxxxxxx
[24032] 1516023480.561754: Preauth module encrypted_timestamp (2)
(real) returned: 0/Success
[24032] 1516023480.561766: Produced preauth for next request: 133, 2
[24032] 1516023480.561811: Sending request (271 bytes) to PRINCIPAL
[24032] 1516023480.561861: Resolving hostname XXX.XXX.XXX.168
[24032] 1516023480.562076: Sending initial UDP request to dgram
XXX.XXX.XXX.168:88
[24032] 1516023480.662874: Received answer (765 bytes) from dgram
XXX.XXX.XXX.168:88
[24032] 1516023480.663083: Response was not from master KDC
[24032] 1516023480.663143: Processing preauth types: 19
[24032] 1516023480.663161: Selected etype info: etype aes256-cts, salt
"PRINCIPALuser", params ""
[24032] 1516023480.663175: Produced preauth for next request: (empty)
[24032] 1516023480.663195: AS key determined by preauth: aes256-cts/114F
[24032] 1516023480.663319: Decrypted AS reply; session key is: aes256-cts/38D6
[24032] 1516023480.663361: FAST negotiation: available
[24032] 1516023480.663411: Initializing FILE:/tmp/krb5cc_0 with
default princ user@PRINCIPAL
[24032] 1516023480.664114: Storing user@PRINCIPAL ->
krbtgt/PRINCIPAL@PRINCIPAL in FILE:/tmp/krb5cc_0
[24032] 1516023480.664252: Storing config in FILE:/tmp/krb5cc_0 for
krbtgt/PRINCIPAL@PRINCIPAL: fast_avail: yes
[24032] 1516023480.664332: Storing user@PRINCIPAL ->
krb5_ccache_conf_data/fast_avail/krbtgt\/PRINCIPAL\@PRINCIPAL@X-CACHECONF:
in FILE:/tmp/krb5cc_0
[24032] 1516023480.664402: Storing config in FILE:/tmp/krb5cc_0 for
krbtgt/PRINCIPAL@PRINCIPAL: pa_type: 2
[24032] 1516023480.664459: Storing user@PRINCIPAL ->
krb5_ccache_conf_data/pa_type/krbtgt\/PRINCIPAL\@PRINCIPAL@X-CACHECONF:
in FILE:/tmp/krb5cc_0
%7|1516023480.665|SASLREFRESH|rdkafka#consumer-1|
[thrd:sasl_plaintext://host2:9092/bootstrap]:
sasl_plaintext://host2:9092/bootstrap: SASL key refreshed
%7|1516023480.666|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|1516023480.667|LIBSASL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host2:9092/bootstrap]:
sasl_plaintext://host2:9092/bootstrap: GSSAPI client step 1
[24033] 1516023480.682361: Getting initial credentials for user@PRINCIPAL
[24033] 1516023480.687733: Looked up etypes in keytab: aes256-cts,
rc4-hmac, des3-cbc-sha1, des-cbc-crc
[24033] 1516023480.687910: Sending request (176 bytes) to PRINCIPAL
[24033] 1516023480.688224: Resolving hostname XXX.XXX.XXX.168
[24033] 1516023480.688563: Sending initial UDP request to dgram
XXX.XXX.XXX.168:88
[24033] 1516023480.737062: Received answer (326 bytes) from dgram
XXX.XXX.XXX.168:88
[24033] 1516023480.737149: Response was not from master KDC
[24033] 1516023480.737245: Received error from KDC:
-1765328359/Additional pre-authentication required
[24033] 1516023480.737326: Processing preauth types: 136, 19, 2, 133
[24033] 1516023480.737346: Selected etype info: etype aes256-cts, salt
"PRINCIPALuser", params ""
[24033] 1516023480.737358: Received cookie: MIT
[24033] 1516023480.737471: Retrieving user@PRINCIPAL from
FILE:/root/user.keytab (vno 0, enctype aes256-cts) with result:
0/Success
[24033] 1516023480.737518: AS key obtained for encrypted timestamp:
aes256-cts/114F
[24033] 1516023480.737640: Encrypted timestamp (for 1516023525.32174):
plain 3019A01118xx, encrypted 32A7BD9DDA3xxx
[24033] 1516023480.737665: Preauth module encrypted_timestamp (2)
(real) returned: 0/Success
[24033] 1516023480.737674: Produced preauth for next request: 133, 2
[24033] 1516023480.737705: Sending request (270 bytes) to PRINCIPAL
[24033] 1516023480.737736: Resolving hostname XXX.XXX.XXX.168
[24033] 1516023480.737929: Sending initial UDP request to dgram
XXX.XXX.XXX.168:88
[24033] 1516023480.830272: Received answer (765 bytes) from dgram
XXX.XXX.XXX.168:88
[24033] 1516023480.830434: Response was not from master KDC
[24033] 1516023480.830492: Processing preauth types: 19
[24033] 1516023480.830509: Selected etype info: etype aes256-cts, salt
"PRINCIPALuser", params ""
[24033] 1516023480.830523: Produced preauth for next request: (empty)
[24033] 1516023480.830541: AS key determined by preauth: aes256-cts/114F
[24033] 1516023480.830666: Decrypted AS reply; session key is: aes256-cts/05B5
[24033] 1516023480.830711: FAST negotiation: available
[24033] 1516023480.830760: Initializing FILE:/tmp/krb5cc_0 with
default princ user@PRINCIPAL
[24033] 1516023480.831344: Storing user@PRINCIPAL ->
krbtgt/PRINCIPAL@PRINCIPAL in FILE:/tmp/krb5cc_0
[24033] 1516023480.831551: Storing config in FILE:/tmp/krb5cc_0 for
krbtgt/PRINCIPAL@PRINCIPAL: fast_avail: yes
[24033] 1516023480.831636: Storing user@PRINCIPAL ->
krb5_ccache_conf_data/fast_avail/krbtgt\/PRINCIPAL\@PRINCIPAL@X-CACHECONF:
in FILE:/tmp/krb5cc_0
[24033] 1516023480.831708: Storing config in FILE:/tmp/krb5cc_0 for
krbtgt/PRINCIPAL@PRINCIPAL: pa_type: 2
[24033] 1516023480.831766: Storing user@PRINCIPAL ->
krb5_ccache_conf_data/pa_type/krbtgt\/PRINCIPAL\@PRINCIPAL@X-CACHECONF:
in FILE:/tmp/krb5cc_0
%7|1516023480.832|SASLREFRESH|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: SASL key refreshed
%7|1516023480.832|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|1516023480.832|LIBSASL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: GSSAPI client step 1
%7|1516023480.894|LIBSASL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: CB_CANON: flags 0x3,
"user@PRINCIPAL" @ "(null)": returning "user@PRINCIPAL"
%7|1516023480.894|SASL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: Selected SASL mechanism: GSSAPI
(wanted GSSAPI)
%7|1516023480.894|SASL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: Send SASL frame to broker (605
bytes)
%7|1516023480.943|SASL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: Received SASL frame from broker
(36 bytes)
%5|1516023480.943|LIBSASL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: GSSAPI client step 2
%7|1516023480.943|SASL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: Send SASL frame to broker (32
bytes)
%7|1516023480.944|SASL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: Authenticated as user@PRINCIPAL
using GSSAPI (gssapiv2)
%7|1516023480.944|SEND|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: Sent MetadataRequest (v2, 25
bytes @ 0, CorrId 3)
%7|1516023481.076|RECV|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/bootstrap: Received MetadataResponse (v2,
80 bytes, CorrId 3, rtt 132.29ms)
%7|1516023481.076|SUBSCRIPTION|rdkafka#consumer-1| [thrd:main]: Group
"user-cctv_python_rhel": no topics in metadata matched subscription
%7|1516023481.076|BRKREASSIGN|rdkafka#consumer-1| [thrd:main]: Group
"user-cctv_python_rhel" management reassigned from broker :0/internal
to sasl_plaintext://host3:9092/bootstrap
%7|1516023481.076|BRKUNASSIGN|rdkafka#consumer-1| [thrd:main]: Group
"user-cctv_python_rhel" management unassigned from broker handle
:0/internal
%7|1516023481.076|BRKASSIGN|rdkafka#consumer-1| [thrd:main]: Group
"user-cctv_python_rhel" management assigned to broker
sasl_plaintext://host3:9092/bootstrap
%7|1516023481.076|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/bootstrap: Group "user-cctv_python_rhel":
querying for coordinator: intervaled in state wait-broker
%7|1516023481.077|SEND|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Sent GroupCoordinatorRequest (v0, 46
bytes @ 0, CorrId 4)
%7|1516023481.125|RECV|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Received GroupCoordinatorResponse (v0,
22 bytes, CorrId 4, rtt 48.33ms)
%7|1516023481.125|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel"
coordinator is host2:9092 id 2
%7|1516023481.125|CGRPCOORD|rdkafka#consumer-1| [thrd:main]: Group
"user-cctv_python_rhel" changing coordinator -1 -> 2
%7|1516023481.435|BROKERFAIL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host1:9092/bootstrap]:
sasl_plaintext://host1:9092/bootstrap: failed: err: Local: Broker
transport failure: (errno: Connection refused)
%7|1516023482.331|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel": querying
for coordinator: intervaled in state wait-broker
%7|1516023482.331|SEND|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Sent GroupCoordinatorRequest (v0, 46
bytes @ 0, CorrId 5)
%7|1516023482.379|RECV|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Received GroupCoordinatorResponse (v0,
22 bytes, CorrId 5, rtt 48.04ms)
%7|1516023482.379|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel"
coordinator is host2:9092 id 2
%7|1516023482.483|BROKERFAIL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host1:9092/bootstrap]:
sasl_plaintext://host1:9092/bootstrap: failed: err: Local: Broker
transport failure: (errno: Connection refused)
%7|1516023483.332|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel": querying
for coordinator: intervaled in state wait-broker
%7|1516023483.332|SEND|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Sent GroupCoordinatorRequest (v0, 46
bytes @ 0, CorrId 6)
%7|1516023483.380|RECV|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Received GroupCoordinatorResponse (v0,
22 bytes, CorrId 6, rtt 47.82ms)
%7|1516023483.380|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel"
coordinator is host2:9092 id 2
%7|1516023483.531|BROKERFAIL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host1:9092/bootstrap]:
sasl_plaintext://host1:9092/bootstrap: failed: err: Local: Broker
transport failure: (errno: Connection refused)
%7|1516023484.332|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel": querying
for coordinator: intervaled in state wait-broker
%7|1516023484.332|SEND|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Sent GroupCoordinatorRequest (v0, 46
bytes @ 0, CorrId 7)
%7|1516023484.380|RECV|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Received GroupCoordinatorResponse (v0,
22 bytes, CorrId 7, rtt 47.90ms)
%7|1516023484.380|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel"
coordinator is host2:9092 id 2
%7|1516023484.579|BROKERFAIL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host1:9092/bootstrap]:
sasl_plaintext://host1:9092/bootstrap: failed: err: Local: Broker
transport failure: (errno: Connection refused)
%7|1516023485.330|COMMIT|rdkafka#consumer-1| [thrd:main]: OffsetCommit
internal error: Local: No offset stored
%7|1516023485.330|COMMIT|rdkafka#consumer-1| [thrd:main]: OffsetCommit
for -1 partition(s): cgrp auto commit timer: returned: Local: No
offset stored
%7|1516023485.330|UNASSIGN|rdkafka#consumer-1| [thrd:main]: Group
"user-cctv_python_rhel": unassign done in state wait-broker (join
state init): without new assignment: OffsetCommit done (__NO_OFFSET)
%7|1516023485.332|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel": querying
for coordinator: intervaled in state wait-broker
%7|1516023485.332|SEND|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Sent GroupCoordinatorRequest (v0, 46
bytes @ 0, CorrId 8)
%7|1516023485.380|RECV|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Received GroupCoordinatorResponse (v0,
22 bytes, CorrId 8, rtt 47.95ms)
%7|1516023485.380|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel"
coordinator is host2:9092 id 2
%7|1516023485.627|BROKERFAIL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host1:9092/bootstrap]:
sasl_plaintext://host1:9092/bootstrap: failed: err: Local: Broker
transport failure: (errno: Connection refused)
%7|1516023486.332|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel": querying
for coordinator: intervaled in state wait-broker
%7|1516023486.332|SEND|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Sent GroupCoordinatorRequest (v0, 46
bytes @ 0, CorrId 9)
%7|1516023486.380|RECV|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Received GroupCoordinatorResponse (v0,
22 bytes, CorrId 9, rtt 48.03ms)
%7|1516023486.380|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel"
coordinator is host2:9092 id 2
%7|1516023486.675|BROKERFAIL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host1:9092/bootstrap]:
sasl_plaintext://host1:9092/bootstrap: failed: err: Local: Broker
transport failure: (errno: Connection refused)
%7|1516023487.332|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel": querying
for coordinator: intervaled in state wait-broker
%7|1516023487.332|SEND|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Sent GroupCoordinatorRequest (v0, 46
bytes @ 0, CorrId 10)
%7|1516023487.380|RECV|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Received GroupCoordinatorResponse (v0,
22 bytes, CorrId 10, rtt 47.92ms)
%7|1516023487.380|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel"
coordinator is host2:9092 id 2
%7|1516023487.723|BROKERFAIL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host1:9092/bootstrap]:
sasl_plaintext://host1:9092/bootstrap: failed: err: Local: Broker
transport failure: (errno: Connection refused)
%7|1516023488.332|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel": querying
for coordinator: intervaled in state wait-broker
%7|1516023488.332|SEND|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Sent GroupCoordinatorRequest (v0, 46
bytes @ 0, CorrId 11)
%7|1516023488.380|RECV|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Received GroupCoordinatorResponse (v0,
22 bytes, CorrId 11, rtt 47.85ms)
%7|1516023488.380|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel"
coordinator is host2:9092 id 2
%7|1516023488.770|BROKERFAIL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host1:9092/bootstrap]:
sasl_plaintext://host1:9092/bootstrap: failed: err: Local: Broker
transport failure: (errno: Connection refused)
%7|1516023489.332|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel": querying
for coordinator: intervaled in state wait-broker
%7|1516023489.332|SEND|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Sent GroupCoordinatorRequest (v0, 46
bytes @ 0, CorrId 12)
%7|1516023489.380|RECV|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Received GroupCoordinatorResponse (v0,
22 bytes, CorrId 12, rtt 48.05ms)
%7|1516023489.380|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel"
coordinator is host2:9092 id 2
%7|1516023489.818|BROKERFAIL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host1:9092/bootstrap]:
sasl_plaintext://host1:9092/bootstrap: failed: err: Local: Broker
transport failure: (errno: Connection refused)
%7|1516023490.330|COMMIT|rdkafka#consumer-1| [thrd:main]: OffsetCommit
internal error: Local: No offset stored
%7|1516023490.331|COMMIT|rdkafka#consumer-1| [thrd:main]: OffsetCommit
for -1 partition(s): cgrp auto commit timer: returned: Local: No
offset stored
%7|1516023490.331|UNASSIGN|rdkafka#consumer-1| [thrd:main]: Group
"user-cctv_python_rhel": unassign done in state wait-broker (join
state init): without new assignment: OffsetCommit done (__NO_OFFSET)
%7|1516023490.332|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel": querying
for coordinator: intervaled in state wait-broker
%7|1516023490.332|SEND|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Sent GroupCoordinatorRequest (v0, 46
bytes @ 0, CorrId 13)
%7|1516023490.380|RECV|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Received GroupCoordinatorResponse (v0,
22 bytes, CorrId 13, rtt 47.85ms)
%7|1516023490.380|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel"
coordinator is host2:9092 id 2
%7|1516023490.866|BROKERFAIL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host1:9092/bootstrap]:
sasl_plaintext://host1:9092/bootstrap: failed: err: Local: Broker
transport failure: (errno: Connection refused)
%7|1516023491.332|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel": querying
for coordinator: intervaled in state wait-broker
%7|1516023491.332|SEND|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Sent GroupCoordinatorRequest (v0, 46
bytes @ 0, CorrId 14)
%7|1516023491.380|RECV|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Received GroupCoordinatorResponse (v0,
22 bytes, CorrId 14, rtt 47.97ms)
%7|1516023491.380|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel"
coordinator is host2:9092 id 2
%7|1516023491.913|BROKERFAIL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host1:9092/bootstrap]:
sasl_plaintext://host1:9092/bootstrap: failed: err: Local: Broker
transport failure: (errno: Connection refused)
%7|1516023492.332|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel": querying
for coordinator: intervaled in state wait-broker
%7|1516023492.332|SEND|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Sent GroupCoordinatorRequest (v0, 46
bytes @ 0, CorrId 15)
%7|1516023492.380|RECV|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Received GroupCoordinatorResponse (v0,
22 bytes, CorrId 15, rtt 48.20ms)
%7|1516023492.380|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel"
coordinator is host2:9092 id 2
%7|1516023492.961|BROKERFAIL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host1:9092/bootstrap]:
sasl_plaintext://host1:9092/bootstrap: failed: err: Local: Broker
transport failure: (errno: Connection refused)
%7|1516023493.332|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel": querying
for coordinator: intervaled in state wait-broker
%7|1516023493.332|SEND|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Sent GroupCoordinatorRequest (v0, 46
bytes @ 0, CorrId 16)
%7|1516023493.380|RECV|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Received GroupCoordinatorResponse (v0,
22 bytes, CorrId 16, rtt 47.94ms)
%7|1516023493.380|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel"
coordinator is host2:9092 id 2
%7|1516023494.009|BROKERFAIL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host1:9092/bootstrap]:
sasl_plaintext://host1:9092/bootstrap: failed: err: Local: Broker
transport failure: (errno: Connection refused)
%7|1516023494.332|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel": querying
for coordinator: intervaled in state wait-broker
%7|1516023494.332|SEND|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Sent GroupCoordinatorRequest (v0, 46
bytes @ 0, CorrId 17)
%7|1516023494.380|RECV|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Received GroupCoordinatorResponse (v0,
22 bytes, CorrId 17, rtt 48.04ms)
%7|1516023494.380|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel"
coordinator is host2:9092 id 2
%7|1516023495.056|BROKERFAIL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host1:9092/bootstrap]:
sasl_plaintext://host1:9092/bootstrap: failed: err: Local: Broker
transport failure: (errno: Connection refused)
%7|1516023495.331|COMMIT|rdkafka#consumer-1| [thrd:main]: OffsetCommit
internal error: Local: No offset stored
%7|1516023495.331|COMMIT|rdkafka#consumer-1| [thrd:main]: OffsetCommit
for -1 partition(s): cgrp auto commit timer: returned: Local: No
offset stored
%7|1516023495.331|UNASSIGN|rdkafka#consumer-1| [thrd:main]: Group
"user-cctv_python_rhel": unassign done in state wait-broker (join
state init): without new assignment: OffsetCommit done (__NO_OFFSET)
%7|1516023495.332|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel": querying
for coordinator: intervaled in state wait-broker
%7|1516023495.332|SEND|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Sent GroupCoordinatorRequest (v0, 46
bytes @ 0, CorrId 18)
%7|1516023495.380|RECV|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Received GroupCoordinatorResponse (v0,
22 bytes, CorrId 18, rtt 47.87ms)
%7|1516023495.380|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel"
coordinator is host2:9092 id 2
^C%7|1516023496.105|BROKERFAIL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host1:9092/bootstrap]:
sasl_plaintext://host1:9092/bootstrap: failed: err: Local: Broker
transport failure: (errno: Connection refused)
^C^C%7|1516023496.332|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel": querying
for coordinator: intervaled in state wait-broker
%7|1516023496.332|SEND|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Sent GroupCoordinatorRequest (v0, 46
bytes @ 0, CorrId 19)
%7|1516023496.380|RECV|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Received GroupCoordinatorResponse (v0,
22 bytes, CorrId 19, rtt 47.91ms)
%7|1516023496.380|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel"
coordinator is host2:9092 id 2
^C%7|1516023497.152|BROKERFAIL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host1:9092/bootstrap]:
sasl_plaintext://host1:9092/bootstrap: failed: err: Local: Broker
transport failure: (errno: Connection refused)
%7|1516023497.332|CGRPQUERY|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel": querying
for coordinator: intervaled in state wait-broker
%7|1516023497.332|SEND|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Sent GroupCoordinatorRequest (v0, 46
bytes @ 0, CorrId 20)
%7|1516023497.380|RECV|rdkafka#consumer-1|
[thrd:sasl_plaintext://host3:9092/bootstrap]:
sasl_plaintext://host3:9092/3: Received GroupCoordinatorResponse (v0,
22 bytes, CorrId 20, rtt 47.98ms)
%7|1516023497.380|CGRPCOORD|rdkafka#consumer-1| [thrd:main]:
sasl_plaintext://host3:9092/3: Group "user-cctv_python_rhel"
coordinator is host2:9092 id 2
%7|1516023498.200|BROKERFAIL|rdkafka#consumer-1|
[thrd:sasl_plaintext://host1:9092/bootstrap]:
sasl_plaintext://host1:9092/bootstrap: failed: err: Local: Broker
transport failure: (errno: Connection refused)
Terminated

```



2018-01-15 11:06 GMT+01:00 Marcel Gutsche <[hidden email]>:

> 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@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@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@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@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@PRINCIPAL" @ "(null)": returning
> "user@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@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 <[hidden email]>:
>
>> 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" <[hidden email]> 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           [hidden email]
>>> https://mailman.mit.edu/mailman/listinfo/kerberos
>>>
>>
>
________________________________________________
Kerberos mailing list           [hidden email]
https://mailman.mit.edu/mailman/listinfo/kerberos