Librdkafka: Kafka Consumer GSSAPI Error on CentOS VM
Description
I have trouble getting a consumer running on a virtual machine with CentOS with SASL_PLAIN authentication. Almost the same setup works on my local Ubuntu machine. kinit -kt
Output on VM CentOS 7.4.1708
Using python-kafka: ('0.11.0', 720896) and librdkafka ('0.11.1', 721407)
%7|1515506815.490|SASLREFRESH|rdkafka#consumer-1| [thrd:sasl_plaintext://remote_server:9092/bootstrap]: sasl_plaintext://remote_server:9092/bootstrap: SASL key refreshed
%7|1515506815.492|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://remote_server:9092/bootstrap]: sasl_plaintext://remote_server:9092/bootstrap: My supported SASL mechanisms: GSS-SPNEGO GSSAPI EXTERNAL LOGIN PLAIN ANONYMOUS
%2|1515506815.494|LIBSASL|rdkafka#consumer-1| [thrd:sasl_plaintext://remote_server:9092/bootstrap]: sasl_plaintext://remote_server:9092/bootstrap: GSSAPI Error: Unspecified GSS failure. Minor code may provide more information (Matching credential not found)
Output on Local Ubuntu 16.04
Using python-kafka: ('0.11.0', 720896) and librdkafka ('0.11.0', 721151)
%7|1515506844.422|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://remote_server:9092/bootstrap]: sasl_plaintext://remote_server:9092/bootstrap: My supported SASL mechanisms: SCRAM-SHA-1 GS2-IAKERB GS2-KRB5 GSS-SPNEGO GSSAPI DIGEST-MD5 EXTERNAL CRAM-MD5 NTLM PLAIN LOGIN ANONYMOUS
%7|1515506844.423|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://remote_server:9092/bootstrap]: sasl_plaintext://remote_server:9092/bootstrap: Send SASL frame to broker (605 bytes)
%7|1515506844.472|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://remote_server:9092/bootstrap]: sasl_plaintext://remote_server:9092/bootstrap: Received SASL frame from broker (112 bytes)
%7|1515506844.472|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://remote_server:9092/bootstrap]: sasl_plaintext://remote_server:9092/bootstrap: Send SASL frame to broker (0 bytes)
%7|1515506844.520|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://remote_server:9092/bootstrap]: sasl_plaintext://remote_server:9092/bootstrap: Received SASL frame from broker (36 bytes)
%7|1515506844.520|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://remote_server:9092/bootstrap]: sasl_plaintext://remote_server:9092/bootstrap: Send SASL frame to broker (32 bytes)
%7|1515506844.520|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://remote_server:9092/bootstrap]: sasl_plaintext://remote_server:9092/bootstrap: Authenticated as [email protected] using GSSAPI (gssapiv2)
Apache Kafka version: 0.10.1`
Config:
'auto.offset.reset': 'smallest',
'default.topic.config': {'auto.offset.reset': 'smallest'},
'broker.version.fallback': '0.9.0',
'security.protocol': 'sasl_plaintext',
'socket.keepalive.enable': True,
'sasl.mechanisms': 'GSSAPI',
'sasl.kerberos.service.name': 'kafka',
'sasl.kerberos.principal': 'user@principal,
'sasl.kerberos.keytab': keytab_file,
Checklist
Please provide the following information:
- [x] librdkafka version (release number or git tag): see above
- [x] Apache Kafka version: 0.10.1`
- [x] librdkafka client configuration:
<REPLACE with e.g., message.timeout.ms=123, auto.reset.offset=earliest, ..> - [x] Operating system:
<REPLACE with e.g., Centos 5 (x64)> - [x] Provide logs (with
debug=..as necessary) from librdkafka - [x] Provide broker log excerpts; Does not show in logs
- [?] Critical issue
mmgutsche
All 26 comments
librdkafka relies on libsasl2/cyrus-sasl for the Kerberos authentication client and it is possible that Ubuntu and CentOS has different default configuration for things like krb5.
Use 'debug': 'security' on the client to see what kinit command is being issued and then try to work it out in the console. When you get it working there you can configure sasl.kerberos.kinit.cmd appropriately.
edenhill
on 9 Jan 2018
Thanks for that fast response. I already tried working it out in the console, the issue is, that it works there. Maybe there are some additional hidden environment setting I have to take care of?
The kinit command used by CentOS is the following
kinit -S "kafka/host" -k -t "/home/user/user.keytab" user@PRINCIPAL
Running in the shell
KRB5_TRACE=/dev/stdout kinit -S "kafka/host" -k -t "/home/user/user.keytab" user@PRINCIPAL
[22302] 1515511326.69147: Getting initial credentials for user@PRINCIPAL
[22302] 1515511326.74618: Setting initial creds service to kafka/host
[22302] 1515511326.74908: Looked up etypes in keytab: aes256-cts, rc4-hmac, des3-cbc-sha1, des-cbc-crc
[22302] 1515511326.75318: Sending request (191 bytes) to PRINCIPAL
[22302] 1515511326.75584: Resolving hostname 195.134.67.168
[22302] 1515511326.76002: Sending initial UDP request to dgram XXX.XXX.XXX.XXX:PPPP
[22302] 1515511326.125011: Received answer (323 bytes) from dgram XXX.XXX.XXX.XXX:PPPP
[22302] 1515511326.125125: Response was not from master KDC
[22302] 1515511326.125225: Received error from KDC: -1765328359/Additional pre-authentication required
[22302] 1515511326.125300: Processing preauth types: 136, 19, 2, 133
[22302] 1515511326.125320: Selected etype info: etype aes256-cts, salt "PRINCIPALuser", params ""
[22302] 1515511326.125331: Received cookie: MIT
[22302] 1515511326.125456: Retrieving user@PRINCIPAL from FILE:/root/user.keytab (vno 0, enctype aes256-cts) with result: 0/Success
[22302] 1515511326.125511: AS key obtained for encrypted timestamp: aes256-cts/114F
[22302] 1515511326.125676: Encrypted timestamp (for 1515511361.943780): plain 301AA011XXXXXXXXXXXXXXXXXXXXXX, encrypted EEB3D340332XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
[22302] 1515511326.125723: Preauth module encrypted_timestamp (2) (real) returned: 0/Success
[22302] 1515511326.125739: Produced preauth for next request: 133, 2
[22302] 1515511326.125783: Sending request (286 bytes) to PRINCIPAL
[22302] 1515511326.125817: Resolving hostname 195.134.67.168
[22302] 1515511326.126103: Sending initial UDP request to dgram XXX.XXX.XXX.XXX:PPPP
[22302] 1515511326.211769: Received answer (756 bytes) from dgram XXX.XXX.XXX.XXX:PPPP
[22302] 1515511326.211903: Response was not from master KDC
[22302] 1515511326.212052: Processing preauth types: 19
[22302] 1515511326.212073: Selected etype info: etype aes256-cts, salt "PRINCIPALuser", params ""
[22302] 1515511326.212089: Produced preauth for next request: (empty)
[22302] 1515511326.212108: AS key determined by preauth: aes256-cts/114F
[22302] 1515511326.212237: Decrypted AS reply; session key is: aes256-cts/52B6
[22302] 1515511326.212279: FAST negotiation: available
[22302] 1515511326.212330: Initializing KEYRING:persistent:0:0 with default princ user@PRINCIPAL
[22302] 1515511326.212418: Storing user@PRINCIPAL -> kafka/host@PRINCIPAL in KEYRING:persistent:0:0
[22302] 1515511326.212509: Storing config in KEYRING:persistent:0:0 for kafka/host@PRINCIPAL: fast_avail: yes
[22302] 1515511326.212541: Storing user@PRINCIPAL -> krb5_ccache_conf_data/fast_avail/kafka\/host\@PRINCIPAL@X-CACHECONF: in KEYRING:persistent:0:0
[22302] 1515511326.212635: Storing config in KEYRING:persistent:0:0 for kafka/host@PRINCIPAL: pa_type: 2
[22302] 1515511326.212667: Storing user@PRINCIPAL -> krb5_ccache_conf_data/pa_type/kafka\/host\@PRINCIPAL@X-CACHECONF: in KEYRING:persistent:0:0
and it just works fine from the console. But not when called from librdkafka.
%7|1515508030.142|AUTH|rdkafka#consumer-1| [thrd:sasl_plaintext://host:9092/bootstrap]: sasl_plaintext://host:9092/2: Auth in state APIVERSION_QUERY (handshake supported)
%7|1515508030.190|SASLMECHS|rdkafka#consumer-1| [thrd:sasl_plaintext://host:9092/bootstrap]: sasl_plaintext://host:9092/2: Broker supported SASL mechanisms: GSSAPI
%7|1515508030.190|AUTH|rdkafka#consumer-1| [thrd:sasl_plaintext://host:9092/bootstrap]: sasl_plaintext://host:9092/2: Auth in state AUTH_HANDSHAKE (handshake supported)
%7|1515508030.190|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host:9092/bootstrap]: sasl_plaintext://host:9092/2: Initializing SASL client: service name kafka, hostname host, mechanisms GSSAPI, provider Cyrus
%7|1515508030.190|SASLREFRESH|rdkafka#consumer-1| [thrd:sasl_plaintext://host:9092/bootstrap]: sasl_plaintext://host:9092/2: Refreshing SASL keys with command: kinit -S "kafka/host" -k -t "/home/user/user.keytab" user@PRINCIPAL
%7|1515508030.346|SASLREFRESH|rdkafka#consumer-1| [thrd:sasl_plaintext://host:9092/bootstrap]: sasl_plaintext://host:9092/2: SASL key refreshed
%7|1515508030.346|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host:9092/bootstrap]: sasl_plaintext://host:9092/2: My supported SASL mechanisms: GSS-SPNEGO GSSAPI EXTERNAL LOGIN PLAIN ANONYMOUS
%2|1515508030.347|LIBSASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host:9092/bootstrap]: sasl_plaintext://host:9092/2: GSSAPI Error: Unspecified GSS failure. Minor code may provide more information (Matching credential not found)
%3|1515508030.347|FAIL|rdkafka#consumer-1| [thrd:sasl_plaintext://host:9092/bootstrap]: sasl_plaintext://host:9092/2: Failed to initialize SASL authentication: SASL handshake failed (start (-1)): SASL(-1): generic failure: GSSAPI Error: Unspecified GSS failure. Minor code may provide more information (Matching credential not found)
%3|1515508030.347|ERROR|rdkafka#consumer-1| [thrd:sasl_plaintext://host:9092/bootstrap]: sasl_plaintext://host:9092/2: Failed to initialize SASL authentication: SASL handshake failed (start (-1)): SASL(-1): generic failure: GSSAPI Error: Unspecified GSS failure. Minor code may provide more information (Matching credential not found)
Can you run the kafka client with KRB5_TRACE=/dev/stdout as well?
edenhill
on 9 Jan 2018
Good idea. Interestingly, it also outputs success. The question is, why is an GSSAPI Error raised then?
%7|1515512677.876|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 -S "kafka/host2" -k -t "/root/user.keytab" user@PRINCIPAL
[22344] 1515512677.891584: Getting initial credentials for user@PRINCIPAL
[22344] 1515512677.896651: Setting initial creds service to kafka/host2
[22344] 1515512677.896818: Looked up etypes in keytab: aes256-cts, rc4-hmac, des3-cbc-sha1, des-cbc-crc
[22344] 1515512677.897015: Sending request (191 bytes) to PRINCIPAL
[22344] 1515512677.897241: Resolving hostname 195.134.67.168
[22344] 1515512677.897537: Sending initial UDP request to dgram 1XXX.XXX.XXX.XXX:PPPP
[22344] 1515512677.946246: Received answer (323 bytes) from dgram 1XXX.XXX.XXX.XXX:PPPP
[22344] 1515512677.946360: Response was not from master KDC
[22344] 1515512677.946460: Received error from KDC: -1765328359/Additional pre-authentication required
[22344] 1515512677.946534: Processing preauth types: 136, 19, 2, 133
[22344] 1515512677.946555: Selected etype info: etype aes256-cts, salt "PRINCIPALuser", params ""
[22344] 1515512677.946567: Received cookie: MIT
[22344] 1515512677.946691: Retrieving user@PRINCIPAL from FILE:/home/user/user.keytab (vno 0, enctype aes256-cts) with result: 0/Success
[22344] 1515512677.946746: AS key obtained for encrypted timestamp: aes256-cts/114F
[22344] 1515512677.946906: Encrypted timestamp (for 1515512713.788216): plain 301AA011..........., encrypted 1B0122BF...............
[22344] 1515512677.947079: Preauth module encrypted_timestamp (2) (real) returned: 0/Success
[22344] 1515512677.947099: Produced preauth for next request: 133, 2
[22344] 1515512677.947137: Sending request (286 bytes) to PRINCIPAL
[22344] 1515512677.947172: Resolving hostname 195.134.67.168
[22344] 1515512677.947362: Sending initial UDP request to dgram 1XXX.XXX.XXX.XXX:PPPP
[22344] 1515512678.39285: Received answer (756 bytes) from dgram 1XXX.XXX.XXX.XXX:PPPP
[22344] 1515512678.39413: Response was not from master KDC
[22344] 1515512678.39471: Processing preauth types: 19
[22344] 1515512678.39488: Selected etype info: etype aes256-cts, salt "PRINCIPALuser", params ""
[22344] 1515512678.39507: Produced preauth for next request: (empty)
[22344] 1515512678.39565: AS key determined by preauth: aes256-cts/114F
[22344] 1515512678.39744: Decrypted AS reply; session key is: aes256-cts/3ADC
[22344] 1515512678.39805: FAST negotiation: available
[22344] 1515512678.39880: Initializing KEYRING:persistent:0:0 with default princ user@PRINCIPAL
[22344] 1515512678.40048: Storing user@PRINCIPAL -> kafka/host2@PRINCIPAL in KEYRING:persistent:0:0
[22344] 1515512678.40180: Storing config in KEYRING:persistent:0:0 for kafka/host2@PRINCIPAL: fast_avail: yes
[22344] 1515512678.40219: Storing user@PRINCIPAL -> krb5_ccache_conf_data/fast_avail/kafka\/host2\@PRINCIPAL@X-CACHECONF: in KEYRING:persistent:0:0
[22344] 1515512678.40287: Storing config in KEYRING:persistent:0:0 for kafka/host2@PRINCIPAL: pa_type: 2
[22344] 1515512678.40311: Storing user@PRINCIPAL -> krb5_ccache_conf_data/pa_type/kafka\/host2\@PRINCIPAL@X-CACHECONF: in KEYRING:persistent:0:0
Can you include all output up to (Matching credential not found)?
edenhill
on 9 Jan 2018
I think it is the same as before, but for completeness here we go:
%7|1515512677.713|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 -S "kafka/host2" -k -t "/home/useruser.keytab" user@PRINCIPAL
[22343] 1515512677.729998: Getting initial credentials for user@PRINCIPAL
[22343] 1515512677.735640: Setting initial creds service to kafka/host2
[22343] 1515512677.735870: Looked up etypes in keytab: aes256-cts, rc4-hmac, des3-cbc-sha1, des-cbc-crc
[22343] 1515512677.736097: Sending request (191 bytes) to PRINCIPAL
[22343] 1515512677.736369: Resolving hostname 195.134.67.168
[22343] 1515512677.736732: Sending initial UDP request to dgram XXX.XXX.XXX.XXX:PPPP
[22343] 1515512677.785395: Received answer (323 bytes) from dgram XXX.XXX.XXX.XXX:PPPP
[22343] 1515512677.785543: Response was not from master KDC
[22343] 1515512677.785678: Received error from KDC: -1765328359/Additional pre-authentication required
[22343] 1515512677.785760: Processing preauth types: 136, 19, 2, 133
[22343] 1515512677.785782: Selected etype info: etype aes256-cts, salt "PRINCIPALuser", params ""
[22343] 1515512677.785793: Received cookie: MIT
[22343] 1515512677.785923: Retrieving user@PRINCIPAL from FILE:/home/useruser.keytab (vno 0, enctype aes256-cts) with result: 0/Success
[22343] 1515512677.786101: AS key obtained for encrypted timestamp: aes256-cts/114F
[22343] 1515512677.786260: Encrypted timestamp (for 1515512713.627509): plain 301AA011..................., encrypted FEBD44DA4FF57......................
[22343] 1515512677.786311: Preauth module encrypted_timestamp (2) (real) returned: 0/Success
[22343] 1515512677.786326: Produced preauth for next request: 133, 2
[22343] 1515512677.786378: Sending request (286 bytes) to PRINCIPAL
[22343] 1515512677.786429: Resolving hostname 195.134.67.168
[22343] 1515512677.786629: Sending initial UDP request to dgram XXX.XXX.XXX.XXX:PPPP
%7|1515512677.828|AUTH|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Auth in state APIVERSION_QUERY (handshake supported)
[22343] 1515512677.872203: Received answer (756 bytes) from dgram XXX.XXX.XXX.XXX:PPPP
[22343] 1515512677.872348: Response was not from master KDC
[22343] 1515512677.872409: Processing preauth types: 19
[22343] 1515512677.872426: Selected etype info: etype aes256-cts, salt "PRINCIPALuser", params ""
[22343] 1515512677.872440: Produced preauth for next request: (empty)
[22343] 1515512677.872459: AS key determined by preauth: aes256-cts/114F
[22343] 1515512677.872606: Decrypted AS reply; session key is: aes256-cts/5970
[22343] 1515512677.872653: FAST negotiation: available
[22343] 1515512677.872705: Initializing KEYRING:persistent:0:0 with default princ user@PRINCIPAL
[22343] 1515512677.872775: Storing user@PRINCIPAL -> kafka/host2@PRINCIPAL in KEYRING:persistent:0:0
[22343] 1515512677.872860: Storing config in KEYRING:persistent:0:0 for kafka/host2@PRINCIPAL: fast_avail: yes
[22343] 1515512677.872893: Storing user@PRINCIPAL -> krb5_ccache_conf_data/fast_avail/kafka\/host2\@PRINCIPAL@X-CACHECONF: in KEYRING:persistent:0:0
[22343] 1515512677.873034: Storing config in KEYRING:persistent:0:0 for kafka/host2@PRINCIPAL: pa_type: 2
[22343] 1515512677.873066: Storing user@PRINCIPAL -> krb5_ccache_conf_data/pa_type/kafka\/host2\@PRINCIPAL@X-CACHECONF: in KEYRING:persistent:0:0
%7|1515512677.874|SASLREFRESH|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: SASL key refreshed
%7|1515512677.874|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: My supported SASL mechanisms: GSS-SPNEGO GSSAPI EXTERNAL LOGIN PLAIN ANONYMOUS
%2|1515512677.875|LIBSASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: GSSAPI Error: Unspecified GSS failure. Minor code may provide more information (Matching credential not found)
%3|1515512677.875|FAIL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Failed to initialize SASL authentication: SASL handshake failed (start (-1)): SASL(-1): generic failure: GSSAPI Error: Unspecified GSS failure. Minor code may provide more information (Matching credential not found)
%3|1515512677.875|ERROR|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Failed to initialize SASL authentication: SASL handshake failed (start (-1)): SASL(-1): generic failure: GSSAPI Error: Unspecified GSS failure. Minor code may provide more information (Matching credential not found)
%7|1515512677.876|SASLMECHS|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Broker supported SASL mechanisms: GSSAPI
%7|1515512677.876|AUTH|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Auth in state AUTH_HANDSHAKE (handshake supported)
%7|1515512677.876|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|1515512677.876|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 -S "kafka/host2" -k -t "/home/useruser.keytab" user@PRINCIPAL
Sorry to say I'm no expert on Kerberos or the inner workings of krb5 and libsasl2 :(
edenhill
on 9 Jan 2018
So it's either a configuration error or a bug on libsasl2 side...? I'll try to get in touch with the libsasl2 developers. Thanks anyway for your support!
mmgutsche
on 9 Jan 2018
Yes, or an interaction issue between krb5, libsasl2 and librdkafka.
Lots of moving parts in this.
edenhill
on 9 Jan 2018
https://github.com/cyrusimap/cyrus-sasl/issues/501
So I got an answer from the cyrus-sasl people.
CentOS 7.4 has already the patch for "correct" SPNEGO, which makes it fail against the old implementations of SPNEGO in cyrus-sasl:
https://git.centos.org/blob/rpms!cyrus-sasl.git/c7/SPECS!cyrus-sasl.spec#L443
This is probably the main difference from Ubuntu.
There is similar discussion bug for Fedora, which got also this patch.
A quick fix is to configure your tools to not offer GSS-SPNEGO or fix the SPNEGO the same way also in the other tool you are talking to.
A follow up question now would be, where do I configure this setting? As an SASL mechanism I'm only able to switch between GSSAPI, PLAIN, SCRAM-SHA-256 and SCRAM-SHA-512.
mmgutsche
on 10 Jan 2018
Following the advice in that cyrus-sasl issue we need to add some debugging to get the selected mechanism from the sasl connection.
If I added this printout to librdkafka master could you give it a spin on both your systems to see the difference?
edenhill
on 10 Jan 2018
Sure!
Am 10.01.2018 19:31 schrieb "Magnus Edenhill" notifications@github.com:
Following the advice in that cyrus-sasl issue we need to add some
debugging to get the selected mechanism from the sasl connection.If I added this printout to librdkafka master could you give it a spin on
both your systems to see the difference?—
You are receiving this because you authored the thread.
Reply to this email directly, view it on GitHub
https://github.com/edenhill/librdkafka/issues/1630#issuecomment-356693577,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AgQ1dUZQSink8HOfots-GSxnuhiPv5toks5tJQH3gaJpZM4RX6ng
.
mmgutsche
on 10 Jan 2018
Great! Please pull and build the sasl_faildbg branch, re-run your application with debug=security and it should tell give a better auth failure error message (hopefully) and also tell you what mechanism it selected.
edenhill
on 10 Jan 2018
So thanks for your support, here is the output. But I can still not really see what the problem is...
CentOS
Using python-kafka: ('0.11.0', 720896) and librdkafka ('0.11.1-109-g6f0750', 721407)
%7|1515659471.742|SASL|rdkafka#consumer-1| [thrd:app]: Selected provider Cyrus for SASL mechanism GSSAPI
%3|1515659471.795|FAIL|rdkafka#consumer-1| [thrd:sasl_plaintext://host1:9092/bootstrap]: sasl_plaintext://host1:9092/bootstrap: Connect to ipv4#19X.1XX.6X.2XX:9PPP failed: Connection refused
%3|1515659471.795|ERROR|rdkafka#consumer-1| [thrd:sasl_plaintext://host1:9092/bootstrap]: sasl_plaintext://host1:9092/bootstrap: Connect to ipv4#19X.1XX.6X.2XX:9PPP failed: Connection refused
%7|1515659471.843|AUTH|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Auth in state APIVERSION_QUERY (handshake supported)
%7|1515659471.843|AUTH|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Auth in state APIVERSION_QUERY (handshake supported)
%7|1515659471.891|SASLMECHS|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Broker supported SASL mechanisms: GSSAPI
%7|1515659471.891|AUTH|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Auth in state AUTH_HANDSHAKE (handshake supported)
%7|1515659471.891|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|1515659471.891|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 -S "kafka/host2" -k -t "/root/user.keytab" user@PRINCIPAL
%7|1515659471.891|SASLMECHS|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Broker supported SASL mechanisms: GSSAPI
%7|1515659471.891|AUTH|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Auth in state AUTH_HANDSHAKE (handshake supported)
%7|1515659471.891|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|1515659471.891|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 -S "kafka/host2" -k -t "/root/user.keytab" user@PRINCIPAL
[29725] 1515659471.910709: Getting initial credentials for user@PRINCIPAL
[29725] 1515659471.916453: Setting initial creds service to kafka/host2
[29725] 1515659471.917224: Looked up etypes in keytab: aes256-cts, rc4-hmac, des3-cbc-sha1, des-cbc-crc
[29725] 1515659471.917397: Sending request (172 bytes) to PRINCIPAL
[29725] 1515659471.917711: Resolving hostname 19X.1XX.6X.2XX:9PPP
[29725] 1515659471.918038: Sending initial UDP request to dgram 19X.1XX.6X.2XX:9PPP:88
[29725] 1515659471.967103: Received answer (323 bytes) from dgram 19X.1XX.6X.2XX:9PPP:88
[29725] 1515659471.967209: Response was not from master KDC
[29725] 1515659471.967302: Received error from KDC: -1765328359/Additional pre-authentication required
[29725] 1515659471.967376: Processing preauth types: 136, 19, 2, 133
[29725] 1515659471.967405: Selected etype info: etype aes256-cts, salt "PRINCIPALuser", params ""
[29725] 1515659471.967424: Received cookie: MIT
[29725] 1515659471.967593: Retrieving user@PRINCIPAL from FILE:/root/user.keytab (vno 0, enctype aes256-cts) with result: 0/Success
[29725] 1515659471.967754: AS key obtained for encrypted timestamp: aes256-cts/114F
[29725] 1515659471.968095: Encrypted timestamp (for 1515659510.236257): plain 301AA0XXXXXXXXXXX....., encrypted 9BF3XXXXXXXXX.....
[29725] 1515659471.968141: Preauth module encrypted_timestamp (2) (real) returned: 0/Success
[29725] 1515659471.968151: Produced preauth for next request: 133, 2
[29725] 1515659471.968185: Sending request (267 bytes) to PRINCIPAL
[29725] 1515659471.968218: Resolving hostname 19X.1XX.6X.2XX:9PPP
[29725] 1515659471.968395: Sending initial UDP request to dgram 19X.1XX.6X.2XX:9PPP:88
[29725] 1515659472.67470: Received answer (756 bytes) from dgram 19X.1XX.6X.2XX:9PPP:88
[29725] 1515659472.67611: Response was not from master KDC
[29725] 1515659472.67676: Processing preauth types: 19
[29725] 1515659472.67694: Selected etype info: etype aes256-cts, salt "PRINCIPALuser", params ""
[29725] 1515659472.67709: Produced preauth for next request: (empty)
[29725] 1515659472.67727: AS key determined by preauth: aes256-cts/114F
[29725] 1515659472.67877: Decrypted AS reply; session key is: aes256-cts/07A1
[29725] 1515659472.67921: FAST negotiation: available
[29725] 1515659472.68073: Initializing FILE:/tmp/krb5cc_0 with default princ user@PRINCIPAL
[29725] 1515659472.68709: Storing user@PRINCIPAL -> kafka/host2@PRINCIPAL in FILE:/tmp/krb5cc_0
[29725] 1515659472.68836: Storing config in FILE:/tmp/krb5cc_0 for kafka/host2@PRINCIPAL: fast_avail: yes
[29725] 1515659472.68915: Storing user@PRINCIPAL -> krb5_ccache_conf_data/fast_avail/kafka\/host2\@PRINCIPAL@X-CACHECONF: in FILE:/tmp/krb5cc_0
[29725] 1515659472.69028: Storing config in FILE:/tmp/krb5cc_0 for kafka/host2@PRINCIPAL: pa_type: 2
[29725] 1515659472.69101: Storing user@PRINCIPAL -> krb5_ccache_conf_data/pa_type/kafka\/host2\@PRINCIPAL@X-CACHECONF: in FILE:/tmp/krb5cc_0
%7|1515659472.070|SASLREFRESH|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: SASL key refreshed
%7|1515659472.071|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: My supported SASL mechanisms: GSS-SPNEGO GSSAPI EXTERNAL LOGIN PLAIN ANONYMOUS
%2|1515659472.074|LIBSASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: GSSAPI Error: Unspecified GSS failure. Minor code may provide more information (Matching credential not found (filename: /tmp/krb5cc_0))
%7|1515659472.074|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Selected SASL mechanism: GSSAPI (wanted GSSAPI)
%3|1515659472.075|FAIL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Failed to initialize SASL authentication: SASL handshake start failed for (unknown) using mechanism GSSAPI (gssapiv2): SASL(-6): can't request information until later in exchange: Information that was requested is not yet available.
%3|1515659472.075|ERROR|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Failed to initialize SASL authentication: SASL handshake start failed for (unknown) using mechanism GSSAPI (gssapiv2): SASL(-6): can't request information until later in exchange: Information that was requested is not yet available.
[29726] 1515659472.85982: Getting initial credentials for user@PRINCIPAL
[29726] 1515659472.91124: Setting initial creds service to kafka/host2
[29726] 1515659472.91273: Looked up etypes in keytab: aes256-cts, rc4-hmac, des3-cbc-sha1, des-cbc-crc
[29726] 1515659472.91461: Sending request (172 bytes) to PRINCIPAL
[29726] 1515659472.91698: Resolving hostname 19X.1XX.6X.2XX:9PPP
[29726] 1515659472.92027: Sending initial UDP request to dgram 19X.1XX.6X.2XX:9PPP:88
[29726] 1515659472.140471: Received answer (323 bytes) from dgram 19X.1XX.6X.2XX:9PPP:88
[29726] 1515659472.140591: Response was not from master KDC
[29726] 1515659472.140687: Received error from KDC: -1765328359/Additional pre-authentication required
[29726] 1515659472.140760: Processing preauth types: 136, 19, 2, 133
[29726] 1515659472.140781: Selected etype info: etype aes256-cts, salt "PRINCIPALuser", params ""
[29726] 1515659472.140792: Received cookie: MIT
[29726] 1515659472.140917: Retrieving user@PRINCIPAL from FILE:/root/user.keytab (vno 0, enctype aes256-cts) with result: 0/Success
[29726] 1515659472.141067: AS key obtained for encrypted timestamp: aes256-cts/114F
[29726] 1515659472.141229: Encrypted timestamp (for 1515659510.409886): plain 301AA0xxxxxxxxxxxxxxxxxxxxx, encrypted 4A22xxxxxxxxxxxxxxxx
[29726] 1515659472.141265: Preauth module encrypted_timestamp (2) (real) returned: 0/Success
[29726] 1515659472.141274: Produced preauth for next request: 133, 2
[29726] 1515659472.141305: Sending request (267 bytes) to PRINCIPAL
[29726] 1515659472.141348: Resolving hostname 19X.1XX.6X.2XX:9PPP
[29726] 1515659472.141550: Sending initial UDP request to dgram 19X.1XX.6X.2XX:9PPP:88
[29726] 1515659472.226355: Received answer (756 bytes) from dgram 19X.1XX.6X.2XX:9PPP:88
[29726] 1515659472.226469: Response was not from master KDC
[29726] 1515659472.226522: Processing preauth types: 19
[29726] 1515659472.226538: Selected etype info: etype aes256-cts, salt "PRINCIPALuser", params ""
[29726] 1515659472.226553: Produced preauth for next request: (empty)
[29726] 1515659472.226571: AS key determined by preauth: aes256-cts/114F
[29726] 1515659472.226695: Decrypted AS reply; session key is: aes256-cts/0A60
[29726] 1515659472.226738: FAST negotiation: available
[29726] 1515659472.226785: Initializing FILE:/tmp/krb5cc_0 with default princ user@PRINCIPAL
[29726] 1515659472.227320: Storing user@PRINCIPAL -> kafka/host2@PRINCIPAL in FILE:/tmp/krb5cc_0
[29726] 1515659472.227468: Storing config in FILE:/tmp/krb5cc_0 for kafka/host2@PRINCIPAL: fast_avail: yes
[29726] 1515659472.227549: Storing user@PRINCIPAL -> krb5_ccache_conf_data/fast_avail/kafka\/host2\@PRINCIPAL@X-CACHECONF: in FILE:/tmp/krb5cc_0
[29726] 1515659472.227622: Storing config in FILE:/tmp/krb5cc_0 for kafka/host2@PRINCIPAL: pa_type: 2
[29726] 1515659472.227679: Storing user@PRINCIPAL -> krb5_ccache_conf_data/pa_type/kafka\/host2\@PRINCIPAL@X-CACHECONF: in FILE:/tmp/krb5cc_0
%7|1515659472.228|SASLREFRESH|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: SASL key refreshed
%7|1515659472.228|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: My supported SASL mechanisms: GSS-SPNEGO GSSAPI EXTERNAL LOGIN PLAIN ANONYMOUS
Output from Ubuntu
Using python-kafka: ('0.11.0', 720896) and librdkafka ('0.11.1-109-g6f0750', 721407)
%7|1515659816.268|SASL|rdkafka#consumer-1| [thrd:app]: Selected provider Cyrus for SASL mechanism GSSAPI
%3|1515659816.318|FAIL|rdkafka#consumer-1| [thrd:sasl_plaintext://host1:9092/bootstrap]: sasl_plaintext://host1:9092/bootstrap: Connect to ipv4#195.134.67.237:9092 failed: Connection refused
%3|1515659816.318|ERROR|rdkafka#consumer-1| [thrd:sasl_plaintext://host1:9092/bootstrap]: sasl_plaintext://host1:9092/bootstrap: Connect to ipv4#195.134.67.237:9092 failed: Connection refused
%7|1515659816.366|AUTH|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Auth in state APIVERSION_QUERY (handshake supported)
%7|1515659816.366|AUTH|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Auth in state APIVERSION_QUERY (handshake supported)
%7|1515659816.413|SASLMECHS|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Broker supported SASL mechanisms: GSSAPI
%7|1515659816.413|AUTH|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Auth in state AUTH_HANDSHAKE (handshake supported)
%7|1515659816.413|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|1515659816.413|SASLMECHS|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Broker supported SASL mechanisms: GSSAPI
%7|1515659816.413|SASLREFRESH|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Refreshing SASL keys with command: kinit -S "kafka/host3" -k -t "/home/mgutsche/software_projects/KafkaServerPy/user.keytab" user@PRINCIPAL
%7|1515659816.413|AUTH|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Auth in state AUTH_HANDSHAKE (handshake supported)
%7|1515659816.413|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|1515659816.413|SASLREFRESH|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Refreshing SASL keys with command: kinit -S "kafka/host2" -k -t "/home/mgutsche/software_projects/KafkaServerPy/user.keytab" user@PRINCIPAL
%7|1515659816.562|SASLREFRESH|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: SASL key refreshed
%7|1515659816.562|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: My supported SASL mechanisms: SCRAM-SHA-1 GS2-IAKERB GS2-KRB5 GSS-SPNEGO GSSAPI DIGEST-MD5 EXTERNAL CRAM-MD5 NTLM PLAIN LOGIN ANONYMOUS
%7|1515659816.563|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Selected SASL mechanism: GSSAPI (wanted GSSAPI)
%7|1515659816.563|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Send SASL frame to broker (605 bytes)
%7|1515659816.633|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Received SASL frame from broker (112 bytes)
%7|1515659816.633|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|1515659816.633|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Send SASL frame to broker (0 bytes)
%7|1515659816.681|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Received SASL frame from broker (36 bytes)
%7|1515659816.681|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Send SASL frame to broker (32 bytes)
%7|1515659816.681|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Authenticated as user@PRINCIPAL using GSSAPI (gssapiv2)
%7|1515659816.720|SASLREFRESH|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: SASL key refreshed
%7|1515659816.720|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: My supported SASL mechanisms: SCRAM-SHA-1 GS2-IAKERB GS2-KRB5 GSS-SPNEGO GSSAPI DIGEST-MD5 EXTERNAL CRAM-MD5 NTLM PLAIN LOGIN ANONYMOUS
%7|1515659816.721|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Selected SASL mechanism: GSSAPI (wanted GSSAPI)
%7|1515659816.721|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Send SASL frame to broker (605 bytes)
%7|1515659816.769|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Received SASL frame from broker (112 bytes)
%7|1515659816.770|LIBSASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: CB_CANON: flags 0x3, "user@PRINCIPAL" @ "(null)": returning "user@PRINCIPAL"
%7|1515659816.770|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Send SASL frame to broker (0 bytes)
%7|1515659816.817|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/2: Received SASL frame from broker (36 bytes)
%7|1515659816.817|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/2: Send SASL frame to broker (32 bytes)
%7|1515659816.817|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/2: Authenticated as user@PRINCIPAL using GSSAPI (gssapiv2)
So it seems we're not actually hitting the SPNEGO issue because it does indeed select GSSAPI:
%7|1515659472.074|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Selected SASL mechanism: GSSAPI (wanted GSSAPI)
%3|1515659472.075|FAIL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Failed to initialize SASL authentication: SASL handshake start failed for (unknown) using mechanism GSSAPI (gssapiv2): SASL(-6): can't request information until later in exchange: Information that was requested is not yet available.
The error message can't request information until later in exchange: Information that was requested is not yet available. can be ignored, that's a bug with yesterday's patch, I'll fix that to show the proper error (which is what you saw previously).
So I guess we're back at square one..
edenhill
on 11 Jan 2018
Edit: Maybe I spotted something, which I missed in the logs before.
I tried the version without patch, and now I see that it is complaining about a non matching credential..
%2|1515683353.636|LIBSASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: GSSAPI Error: Unspecified GSS failure. Minor code may provide more information (Matching credential not found (filename: /tmp/krb5cc_0))
But when I call klist
Ticket cache: FILE:/tmp/krb5cc_0
Default principal: user@PRINCIPAL
Valid starting Expires Service principal
12.01.2018 09:47:31 12.01.2018 19:47:31 kafka/host2@PRINCIPAL
renew until 13.01.2018 09:47:31
Here the full log
%7|1515683353.474|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|1515683353.474|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 -S "kafka/host2" -k -t "/root/user.keytab" user@PRINCIPAL
[13964] 1515683353.490424: Getting initial credentials for user@PRINCIPAL
[13964] 1515683353.495702: Setting initial creds service to kafka/host2
[13964] 1515683353.495865: Looked up etypes in keytab: aes256-cts, rc4-hmac, des3-cbc-sha1, des-cbc-crc
[13964] 1515683353.496088: Sending request (172 bytes) to PRINCIPAL
[13964] 1515683353.496341: Resolving hostname XXX.XXX.XXX.168
[13964] 1515683353.496652: Sending initial UDP request to dgram XXX.XXX.XXX.XXX.PPP
[13964] 1515683353.545446: Received answer (323 bytes) from dgram XXX.XXX.XXX.XXX.PPP
[13964] 1515683353.545587: Response was not from master KDC
[13964] 1515683353.545692: Received error from KDC: -1765328359/Additional pre-authentication required
[13964] 1515683353.545767: Processing preauth types: 136, 19, 2, 133
[13964] 1515683353.545789: Selected etype info: etype aes256-cts, salt "PRINCIPALuser", params ""
[13964] 1515683353.545801: Received cookie: MIT
[13964] 1515683353.545928: Retrieving user@PRINCIPAL from FILE:/root/user.keytab (vno 0, enctype aes256-cts) with result: 0/Success
[13964] 1515683353.546069: AS key obtained for encrypted timestamp: aes256-cts/114F
[13964] 1515683353.546213: Encrypted timestamp (for 1515683392.207303): plain 301AA011180F.., encrypted 8237B9430A48..
[13964] 1515683353.546250: Preauth module encrypted_timestamp (2) (real) returned: 0/Success
[13964] 1515683353.546259: Produced preauth for next request: 133, 2
[13964] 1515683353.546291: Sending request (267 bytes) to PRINCIPAL
[13964] 1515683353.546328: Resolving hostname XXX.XXX.XXX.168
[13964] 1515683353.546517: Sending initial UDP request to dgram XXX.XXX.XXX.XXX.PPP
[13964] 1515683353.632101: Received answer (756 bytes) from dgram XXX.XXX.XXX.XXX.PPP
[13964] 1515683353.632229: Response was not from master KDC
[13964] 1515683353.632287: Processing preauth types: 19
[13964] 1515683353.632304: Selected etype info: etype aes256-cts, salt "PRINCIPALuser", params ""
[13964] 1515683353.632319: Produced preauth for next request: (empty)
[13964] 1515683353.632338: AS key determined by preauth: aes256-cts/114F
[13964] 1515683353.632467: Decrypted AS reply; session key is: aes256-cts/EA6D
[13964] 1515683353.632512: FAST negotiation: available
[13964] 1515683353.632561: Initializing FILE:/tmp/krb5cc_0 with default princ user@PRINCIPAL
[13964] 1515683353.633096: Storing user@PRINCIPAL -> kafka/host2@PRINCIPAL in FILE:/tmp/krb5cc_0
[13964] 1515683353.633335: Storing config in FILE:/tmp/krb5cc_0 for kafka/host2@PRINCIPAL: fast_avail: yes
[13964] 1515683353.633427: Storing user@PRINCIPAL -> krb5_ccache_conf_data/fast_avail/kafka\/host2\@PRINCIPAL@X-CACHECONF: in FILE:/tmp/krb5cc_0
[13964] 1515683353.633507: Storing config in FILE:/tmp/krb5cc_0 for kafka/host2@PRINCIPAL: pa_type: 2
[13964] 1515683353.633579: Storing user@PRINCIPAL -> krb5_ccache_conf_data/pa_type/kafka\/host2\@PRINCIPAL@X-CACHECONF: in FILE:/tmp/krb5cc_0
%7|1515683353.634|SASLREFRESH|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: SASL key refreshed
%7|1515683353.634|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|1515683353.634|LIBSASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: GSSAPI client step 1
%2|1515683353.636|LIBSASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: GSSAPI Error: Unspecified GSS failure. Minor code may provide more information (Matching credential not found (filename: /tmp/krb5cc_0))
%7|1515683353.636|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Selected SASL mechanism: GSSAPI (wanted GSSAPI)
%3|1515683353.636|FAIL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Failed to initialize SASL authentication: SASL handshake start failed for (unknown) using mechanism GSSAPI (gssapiv2): SASL(-6): can't request information until later in exchange: Information that was requested is not yet available.
%3|1515683353.636|ERROR|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Failed to initialize SASL authentication: SASL handshake start failed for (unknown) using mechanism GSSAPI (gssapiv2): SASL(-6): can't request information until later in exchange: Information that was requested is not yet available.
%3|1515683353.636|ERROR|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: 3/3 brokers are down
Terminated
So I got rid of the credential not found error, by removing the -S kafka/host line. But I am still stuck and I can not retrieve the messages. Maybe the authorization is not completely finished, but the logs do not indicate such a thing.
I also added the krb5.conf and the /etc/hosts for possible name clashes.
%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
Add protocol to your debug list to see if the broker connection is usable, we can't really tell from the group-coordinator query logs: that might as well be no group coordinator being available (typically due to under-replicated __consumer_offsets topic).
edenhill
on 15 Jan 2018
I added protocol to the debug information. In the previous log I had an error in the keytab location. So just ignore the previous log.
%7|1516012892.489|SASL|rdkafka#consumer-1| [thrd:app]: Selected provider Cyrus for SASL mechanism GSSAPI
%7|1516012892.489|MEMBERID|rdkafka#consumer-1| [thrd:app]: Group "user_python_rhel": updating member id "(not-set)" -> ""
%7|1516012892.491|BRKREASSIGN|rdkafka#consumer-1| [thrd:main]: Group "user_python_rhel" management reassigned from broker (none) to :0/internal
%7|1516012892.491|CGRPSTATE|rdkafka#consumer-1| [thrd:main]: Group "user_python_rhel" changed state init -> wait-broker (v1, join-state init)
%7|1516012892.491|BRKASSIGN|rdkafka#consumer-1| [thrd:main]: Group "user_python_rhel" management assigned to broker :0/internal
%7|1516012892.492|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|1516012892.492|SUBSCRIBE|rdkafka#consumer-1| [thrd:main]: Group "user_python_rhel": subscribe to new subscription of 1 topics (join state init)
%7|1516012892.492|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|1516012892.492|GRPLEADER|rdkafka#consumer-1| [thrd:main]: Group "user_python_rhel": resetting group leader info: unsubscribe
%7|1516012892.492|CGRPJOINSTATE|rdkafka#consumer-1| [thrd:main]: Group "user_python_rhel" changed join state init -> wait-unassign (v1, state wait-broker)
%7|1516012892.492|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|1516012892.492|CGRPJOINSTATE|rdkafka#consumer-1| [thrd:main]: Group "user_python_rhel" changed join state wait-unassign -> init (v1, state wait-broker)
%7|1516012892.492|CGRPQUERY|rdkafka#consumer-1| [thrd:main]: Group "user_python_rhel": no broker available for coordinator query: intervaled in state wait-broker
%7|1516012892.540|CONNECTED|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Connected (#1)
%7|1516012892.540|FEATURE|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Updated enabled protocol features +ApiVersion to ApiVersion
%7|1516012892.541|SEND|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Sent ApiVersionRequest (v0, 25 bytes @ 0, CorrId 1)
%7|1516012892.541|CONNECTED|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Connected (#1)
%7|1516012892.541|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|1516012892.541|FEATURE|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Updated enabled protocol features +ApiVersion to ApiVersion
%3|1516012892.541|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|1516012892.541|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|1516012892.541|SEND|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Sent ApiVersionRequest (v0, 25 bytes @ 0, CorrId 1)
%7|1516012892.588|RECV|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Received ApiVersionResponse (v0, 132 bytes, CorrId 1, rtt 47.76ms)
%7|1516012892.588|AUTH|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Auth in state APIVERSION_QUERY (handshake supported)
%7|1516012892.589|SEND|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Sent SaslHandshakeRequest (v0, 29 bytes @ 0, CorrId 2)
%7|1516012892.589|RECV|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Received ApiVersionResponse (v0, 132 bytes, CorrId 1, rtt 47.76ms)
%7|1516012892.589|AUTH|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Auth in state APIVERSION_QUERY (handshake supported)
%7|1516012892.589|SEND|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Sent SaslHandshakeRequest (v0, 29 bytes @ 0, CorrId 2)
%7|1516012892.636|RECV|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Received SaslHandshakeResponse (v0, 14 bytes, CorrId 2, rtt 47.58ms)
%7|1516012892.636|SASLMECHS|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Broker supported SASL mechanisms: GSSAPI
%7|1516012892.636|AUTH|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Auth in state AUTH_HANDSHAKE (handshake supported)
%7|1516012892.636|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|1516012892.636|RECV|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Received SaslHandshakeResponse (v0, 14 bytes, CorrId 2, rtt 47.58ms)
%7|1516012892.637|SASLMECHS|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Broker supported SASL mechanisms: GSSAPI
%7|1516012892.637|AUTH|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Auth in state AUTH_HANDSHAKE (handshake supported)
%7|1516012892.636|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 user.keytab user@PRINCIPAL
%7|1516012892.637|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|1516012892.637|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 user.keytab user@PRINCIPAL
[23729] 1516012892.654094: Getting initial credentials for user@PRINCIPAL
[23729] 1516012892.660045: Looked up etypes in keytab: aes256-cts, rc4-hmac, des3-cbc-sha1, des-cbc-crc
[23729] 1516012892.660281: Sending request (176 bytes) to PRINCIPAL
[23729] 1516012892.660529: Resolving hostname XXX.XXX.XXX.168
[23729] 1516012892.660894: Sending initial UDP request to dgram XXX.XXX.XXX.168:88
[23729] 1516012892.709553: Received answer (327 bytes) from dgram XXX.XXX.XXX.168:88
[23729] 1516012892.709674: Response was not from master KDC
[23729] 1516012892.709794: Received error from KDC: -1765328359/Additional pre-authentication required
[23729] 1516012892.709919: Processing preauth types: 136, 19, 2, 133
[23729] 1516012892.709945: Selected etype info: etype aes256-cts, salt "PRINCIPALuser", params ""
[23729] 1516012892.710049: Received cookie: MIT
[23729] 1516012892.710203: Retrieving user@PRINCIPAL from FILE:user.keytab (vno 0, enctype aes256-cts) with result: 0/Success
[23729] 1516012892.710289: AS key obtained for encrypted timestamp: aes256-cts/114F
[23729] 1516012892.710454: Encrypted timestamp (for 1516012936.830025): plain 301AAxxxx, encrypted 3098B47BA0xxxxx
[23729] 1516012892.710494: Preauth module encrypted_timestamp (2) (real) returned: 0/Success
[23729] 1516012892.710503: Produced preauth for next request: 133, 2
[23729] 1516012892.710536: Sending request (271 bytes) to PRINCIPAL
[23729] 1516012892.710569: Resolving hostname XXX.XXX.XXX.168
[23729] 1516012892.710809: Sending initial UDP request to dgram XXX.XXX.XXX.168:88
[23729] 1516012892.796197: Received answer (765 bytes) from dgram XXX.XXX.XXX.168:88
[23729] 1516012892.796372: Response was not from master KDC
[23729] 1516012892.796429: Processing preauth types: 19
[23729] 1516012892.796446: Selected etype info: etype aes256-cts, salt "PRINCIPALuser", params ""
[23729] 1516012892.796462: Produced preauth for next request: (empty)
[23729] 1516012892.796481: AS key determined by preauth: aes256-cts/114F
[23729] 1516012892.796608: Decrypted AS reply; session key is: aes256-cts/B201
[23729] 1516012892.796652: FAST negotiation: available
[23729] 1516012892.796702: Initializing FILE:/tmp/krb5cc_0 with default princ user@PRINCIPAL
[23729] 1516012892.797337: Storing user@PRINCIPAL -> krbtgt/PRINCIPAL@PRINCIPAL in FILE:/tmp/krb5cc_0
[23729] 1516012892.797502: Storing config in FILE:/tmp/krb5cc_0 for krbtgt/PRINCIPAL@PRINCIPAL: fast_avail: yes
[23729] 1516012892.797619: Storing user@PRINCIPAL -> krb5_ccache_conf_data/fast_avail/krbtgt\/PRINCIPAL\@PRINCIPAL@X-CACHECONF: in FILE:/tmp/krb5cc_0
[23729] 1516012892.797808: Storing config in FILE:/tmp/krb5cc_0 for krbtgt/PRINCIPAL@PRINCIPAL: pa_type: 2
[23729] 1516012892.797914: Storing user@PRINCIPAL -> krb5_ccache_conf_data/pa_type/krbtgt\/PRINCIPAL\@PRINCIPAL@X-CACHECONF: in FILE:/tmp/krb5cc_0
%7|1516012892.799|SASLREFRESH|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: SASL key refreshed
%7|1516012892.801|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|1516012892.801|LIBSASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: GSSAPI client step 1
[23730] 1516012892.816281: Getting initial credentials for user@PRINCIPAL
[23730] 1516012892.822247: Looked up etypes in keytab: aes256-cts, rc4-hmac, des3-cbc-sha1, des-cbc-crc
[23730] 1516012892.822485: Sending request (176 bytes) to PRINCIPAL
[23730] 1516012892.822803: Resolving hostname XXX.XXX.XXX.168
[23730] 1516012892.823401: Sending initial UDP request to dgram XXX.XXX.XXX.168:88
[23730] 1516012892.871986: Received answer (327 bytes) from dgram XXX.XXX.XXX.168:88
[23730] 1516012892.872107: Response was not from master KDC
[23730] 1516012892.872274: Received error from KDC: -1765328359/Additional pre-authentication required
[23730] 1516012892.872367: Processing preauth types: 136, 19, 2, 133
[23730] 1516012892.872388: Selected etype info: etype aes256-cts, salt "PRINCIPALuser", params ""
[23730] 1516012892.872400: Received cookie: MIT
[23730] 1516012892.872514: Retrieving user@PRINCIPAL from FILE:user.keytab (vno 0, enctype aes256-cts) with result: 0/Success
[23730] 1516012892.872564: AS key obtained for encrypted timestamp: aes256-cts/114F
[23730] 1516012892.872692: Encrypted timestamp (for 1516012936.992269): plain 301AA011180F3xxxx, encrypted 2D9C95FB09588F2Bxxxxxxx
[23730] 1516012892.872725: Preauth module encrypted_timestamp (2) (real) returned: 0/Success
[23730] 1516012892.872734: Produced preauth for next request: 133, 2
[23730] 1516012892.872766: Sending request (271 bytes) to PRINCIPAL
[23730] 1516012892.872799: Resolving hostname XXX.XXX.XXX.168
[23730] 1516012892.873041: Sending initial UDP request to dgram XXX.XXX.XXX.168:88
[23730] 1516012893.188843: Received answer (765 bytes) from dgram XXX.XXX.XXX.168:88
[23730] 1516012893.189066: Response was not from master KDC
[23730] 1516012893.189126: Processing preauth types: 19
[23730] 1516012893.189144: Selected etype info: etype aes256-cts, salt "PRINCIPALuser", params ""
[23730] 1516012893.189158: Produced preauth for next request: (empty)
[23730] 1516012893.189176: AS key determined by preauth: aes256-cts/114F
[23730] 1516012893.189302: Decrypted AS reply; session key is: aes256-cts/04D7
[23730] 1516012893.189345: FAST negotiation: available
[23730] 1516012893.189394: Initializing FILE:/tmp/krb5cc_0 with default princ user@PRINCIPAL
[23730] 1516012893.189835: Storing user@PRINCIPAL -> krbtgt/PRINCIPAL@PRINCIPAL in FILE:/tmp/krb5cc_0
[23730] 1516012893.190021: Storing config in FILE:/tmp/krb5cc_0 for krbtgt/PRINCIPAL@PRINCIPAL: fast_avail: yes
[23730] 1516012893.190130: Storing user@PRINCIPAL -> krb5_ccache_conf_data/fast_avail/krbtgt\/PRINCIPAL\@PRINCIPAL@X-CACHECONF: in FILE:/tmp/krb5cc_0
[23730] 1516012893.190247: Storing config in FILE:/tmp/krb5cc_0 for krbtgt/PRINCIPAL@PRINCIPAL: pa_type: 2
[23730] 1516012893.190351: Storing user@PRINCIPAL -> krb5_ccache_conf_data/pa_type/krbtgt\/PRINCIPAL\@PRINCIPAL@X-CACHECONF: in FILE:/tmp/krb5cc_0
%7|1516012893.191|SASLREFRESH|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: SASL key refreshed
%7|1516012893.191|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|1516012893.191|LIBSASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: GSSAPI client step 1
%7|1516012893.243|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|1516012893.243|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Selected SASL mechanism: GSSAPI (wanted GSSAPI)
%7|1516012893.243|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Send SASL frame to broker (605 bytes)
%7|1516012893.292|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Received SASL frame from broker (36 bytes)
%5|1516012893.293|LIBSASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: GSSAPI client step 2
%7|1516012893.293|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Send SASL frame to broker (32 bytes)
%7|1516012893.293|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Authenticated as user@PRINCIPAL using GSSAPI (gssapiv2)
%7|1516012893.293|SEND|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Sent MetadataRequest (v2, 25 bytes @ 0, CorrId 3)
%7|1516012893.426|RECV|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Received MetadataResponse (v2, 80 bytes, CorrId 3, rtt 133.37ms)
%7|1516012893.427|SUBSCRIPTION|rdkafka#consumer-1| [thrd:main]: Group "user_python_rhel": no topics in metadata matched subscription
%7|1516012893.427|BRKREASSIGN|rdkafka#consumer-1| [thrd:main]: Group "user_python_rhel" management reassigned from broker :0/internal to sasl_plaintext://host3:9092/bootstrap
%7|1516012893.427|BRKUNASSIGN|rdkafka#consumer-1| [thrd:main]: Group "user_python_rhel" management unassigned from broker handle :0/internal
%7|1516012893.427|BRKASSIGN|rdkafka#consumer-1| [thrd:main]: Group "user_python_rhel" management assigned to broker sasl_plaintext://host3:9092/bootstrap
%7|1516012893.427|CGRPQUERY|rdkafka#consumer-1| [thrd:main]: sasl_plaintext://host3:9092/3: Group "user_python_rhel": querying for coordinator: intervaled in state wait-broker
%7|1516012893.427|SEND|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/3: Sent GroupCoordinatorRequest (v0, 46 bytes @ 0, CorrId 4)
%7|1516012893.475|RECV|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/3: Received GroupCoordinatorResponse (v0, 22 bytes, CorrId 4, rtt 47.81ms)
%7|1516012893.475|CGRPCOORD|rdkafka#consumer-1| [thrd:main]: sasl_plaintext://host3:9092/3: Group "user_python_rhel" coordinator is host2:9092 id 2
%7|1516012893.475|CGRPCOORD|rdkafka#consumer-1| [thrd:main]: Group "user_python_rhel" changing coordinator -1 -> 2
%7|1516012893.589|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|1516012894.490|CGRPQUERY|rdkafka#consumer-1| [thrd:main]: sasl_plaintext://host3:9092/3: Group "user_python_rhel": querying for coordinator: intervaled in state wait-broker
%7|1516012894.491|SEND|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/3: Sent GroupCoordinatorRequest (v0, 46 bytes @ 0, CorrId 5)
%7|1516012894.539|RECV|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/3: Received GroupCoordinatorResponse (v0, 22 bytes, CorrId 5, rtt 48.08ms)
%7|1516012894.539|CGRPCOORD|rdkafka#consumer-1| [thrd:main]: sasl_plaintext://host3:9092/3: Group "user_python_rhel" coordinator is host2:9092 id 2
%7|1516012894.637|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|1516012895.491|CGRPQUERY|rdkafka#consumer-1| [thrd:main]: sasl_plaintext://host3:9092/3: Group "user_python_rhel": querying for coordinator: intervaled in state wait-broker
%7|1516012895.491|SEND|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/3: Sent GroupCoordinatorRequest (v0, 46 bytes @ 0, CorrId 6)
%7|1516012895.540|RECV|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/3: Received GroupCoordinatorResponse (v0, 22 bytes, CorrId 6, rtt 48.10ms)
%7|1516012895.540|CGRPCOORD|rdkafka#consumer-1| [thrd:main]: sasl_plaintext://host3:9092/3: Group "user_python_rhel" coordinator is host2:9092 id 2
%7|1516012895.685|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|1516012896.491|CGRPQUERY|rdkafka#consumer-1| [thrd:main]: sasl_plaintext://host3:9092/3: Group "user_python_rhel": querying for coordinator: intervaled in state wait-broker
%7|1516012896.491|SEND|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/3: Sent GroupCoordinatorRequest (v0, 46 bytes @ 0, CorrId 7)
%7|1516012896.539|RECV|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/3: Received GroupCoordinatorResponse (v0, 22 bytes, CorrId 7, rtt 48.10ms)
%7|1516012896.539|CGRPCOORD|rdkafka#consumer-1| [thrd:main]: sasl_plaintext://host3:9092/3: Group "user_python_rhel" coordinator is host2:9092 id 2
%7|1516012896.732|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|1516012897.489|COMMIT|rdkafka#consumer-1| [thrd:main]: OffsetCommit internal error: Local: No offset stored
%7|1516012897.490|COMMIT|rdkafka#consumer-1| [thrd:main]: OffsetCommit for -1 partition(s): cgrp auto commit timer: returned: Local: No offset stored
%7|1516012897.490|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|1516012897.491|CGRPQUERY|rdkafka#consumer-1| [thrd:main]: sasl_plaintext://host3:9092/3: Group "user_python_rhel": querying for coordinator: intervaled in state wait-broker
%7|1516012897.491|SEND|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/3: Sent GroupCoordinatorRequest (v0, 46 bytes @ 0, CorrId 8)
%7|1516012897.540|RECV|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/3: Received GroupCoordinatorResponse (v0, 22 bytes, CorrId 8, rtt 48.04ms)
%7|1516012897.540|CGRPCOORD|rdkafka#consumer-1| [thrd:main]: sasl_plaintext://host3:9092/3: Group "user_python_rhel" coordinator is host2:9092 id 2
%7|1516012897.780|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|1516012898.491|CGRPQUERY|rdkafka#consumer-1| [thrd:main]: sasl_plaintext://host3:9092/3: Group "user_python_rhel": querying for coordinator: intervaled in state wait-broker
%7|1516012898.491|SEND|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/3: Sent GroupCoordinatorRequest (v0, 46 bytes @ 0, CorrId 9)
%7|1516012898.540|RECV|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/3: Received GroupCoordinatorResponse (v0, 22 bytes, CorrId 9, rtt 48.15ms)
%7|1516012898.540|CGRPCOORD|rdkafka#consumer-1| [thrd:main]: sasl_plaintext://host3:9092/3: Group "user_python_rhel" coordinator is host2:9092 id 2
%7|1516012898.827|BROKERFAIL|rdkafka#consumer-1| [thrd:sasl_plaintext://host1:9092/bootstrap]: sasl_plaintext://host1:9092/bootstrap: failed: err: Local: Broker transport failure: (errno: Connection refused)
Everything is looking good, except for failure to connect to one of the brokers:
%7|1516012894.637|BROKERFAIL|rdkafka#consumer-1| [thrd:sasl_plaintext://host1:9092/bootstrap]: sasl_plaintext://host1:9092/bootstrap: failed: err: Local: Broker transport failure: (errno: Connection refused)
edenhill
on 15 Jan 2018
Any idea on how to investigate this further? On my ubuntu machine I do not get this error. Also not when I am using the JavaConsumer on the VM.
mmgutsche
on 15 Jan 2018
What is the problem exactly?
edenhill
on 15 Jan 2018
Thanks for your patience. The problem is, that I still do not get any messages from the Kafka Server when I start the librdkafka consumer from my VM on CentOS. The JavaConsumer works on the VM.
And librdkafka also works on my local Ubuntu installation. On the VM librdkafka seems to be stuck here
%7|1516023831.360|BROKERFAIL|rdkafka#consumer-1| [thrd:sasl_plaintext://kddlab-pc1:9092/bootstrap]: sasl_plaintext://kddlab-pc1:9092/bootstrap: failed: err: Local: Broker transport failure: (errno: Connection refused)
while on the local machine it recovers quite quickly from it.
CentOS VM
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
Ubuntu local
Using python-kafka: ('0.11.0', 720896) and librdkafka ('0.11.1-109-g6f0750', 721407)
%7|1516023762.012|SASL|rdkafka#consumer-1| [thrd:app]: Selected provider Cyrus for SASL mechanism GSSAPI
%7|1516023762.012|MEMBERID|rdkafka#consumer-1| [thrd:app]: Group "user-cctv_python_ubuntu": updating member id "(not-set)" -> ""
%7|1516023762.012|BRKREASSIGN|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu" management reassigned from broker (none) to :0/internal
%7|1516023762.012|CGRPSTATE|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu" changed state init -> wait-broker (v1, join-state init)
%7|1516023762.012|BRKASSIGN|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu" management assigned to broker :0/internal
%7|1516023762.012|CGRPOP|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu" received op SUBSCRIBE (v0) in state wait-broker (join state init, v1 vs 0)
%7|1516023762.012|SUBSCRIBE|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu": subscribe to new subscription of 1 topics (join state init)
%7|1516023762.012|UNSUBSCRIBE|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu": unsubscribe from current unset subscription of 0 topics (leave group=no, join state init, v1)
%7|1516023762.012|GRPLEADER|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu": resetting group leader info: unsubscribe
%7|1516023762.012|CGRPJOINSTATE|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu" changed join state init -> wait-unassign (v1, state wait-broker)
%7|1516023762.012|UNASSIGN|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu": unassign done in state wait-broker (join state wait-unassign): without new assignment: unassign (no previous assignment)
%7|1516023762.012|CGRPJOINSTATE|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu" changed join state wait-unassign -> init (v1, state wait-broker)
%7|1516023762.012|CGRPQUERY|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu": no broker available for coordinator query: intervaled in state wait-broker
%7|1516023762.060|CONNECTED|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Connected (#1)
%7|1516023762.060|FEATURE|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Updated enabled protocol features +ApiVersion to ApiVersion
%7|1516023762.060|SEND|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Sent ApiVersionRequest (v0, 25 bytes @ 0, CorrId 1)
%7|1516023762.060|CONNECTED|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Connected (#1)
%7|1516023762.060|FEATURE|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Updated enabled protocol features +ApiVersion to ApiVersion
%7|1516023762.060|SEND|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Sent ApiVersionRequest (v0, 25 bytes @ 0, CorrId 1)
%7|1516023762.060|BROKERFAIL|rdkafka#consumer-1| [thrd:sasl_plaintext://host1:9092/bootstrap]: sasl_plaintext://host1:9092/bootstrap: failed: err: Local: Broker transport failure: (errno: Connection refused)
%3|1516023762.060|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|1516023762.060|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|1516023762.108|RECV|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Received ApiVersionResponse (v0, 132 bytes, CorrId 1, rtt 47.91ms)
%7|1516023762.108|AUTH|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Auth in state APIVERSION_QUERY (handshake supported)
%7|1516023762.108|SEND|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Sent SaslHandshakeRequest (v0, 29 bytes @ 0, CorrId 2)
%7|1516023762.109|RECV|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Received ApiVersionResponse (v0, 132 bytes, CorrId 1, rtt 48.15ms)
%7|1516023762.109|AUTH|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Auth in state APIVERSION_QUERY (handshake supported)
%7|1516023762.109|SEND|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Sent SaslHandshakeRequest (v0, 29 bytes @ 0, CorrId 2)
%7|1516023762.156|RECV|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Received SaslHandshakeResponse (v0, 14 bytes, CorrId 2, rtt 47.66ms)
%7|1516023762.156|SASLMECHS|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Broker supported SASL mechanisms: GSSAPI
%7|1516023762.156|AUTH|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Auth in state AUTH_HANDSHAKE (handshake supported)
%7|1516023762.156|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|1516023762.156|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 /home/user/software_projects/KafkaServerPy/user.keytab user@PRINCIPAL
%7|1516023762.157|RECV|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Received SaslHandshakeResponse (v0, 14 bytes, CorrId 2, rtt 48.32ms)
%7|1516023762.157|SASLMECHS|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Broker supported SASL mechanisms: GSSAPI
%7|1516023762.157|AUTH|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Auth in state AUTH_HANDSHAKE (handshake supported)
%7|1516023762.157|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|1516023762.157|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 /home/user/software_projects/KafkaServerPy/user.keytab user@PRINCIPAL
[25670] 1516023762.160745: Getting initial credentials for user@PRINCIPAL
[25670] 1516023762.160972: Looked up etypes in keytab: aes256-cts, rc4-hmac, des3-cbc-sha1, des-cbc-crc
[25670] 1516023762.161044: Sending request (170 bytes) to PRINCIPAL
[25670] 1516023762.161073: Resolving hostname XXX.XXX.XXX.168
[25670] 1516023762.161191: Sending initial UDP request to dgram XXX.XXX.XXX.168:88
[25670] 1516023762.209539: Received answer (327 bytes) from dgram XXX.XXX.XXX.168:88
[25670] 1516023762.209571: Response was not from master KDC
[25670] 1516023762.209604: Received error from KDC: -1765328359/Additional pre-authentication required
[25670] 1516023762.209648: Processing preauth types: 136, 19, 2, 133
[25670] 1516023762.209663: Selected etype info: etype aes256-cts, salt "PRINCIPALuser", params ""
[25670] 1516023762.209672: Received cookie: MIT
[25670] 1516023762.209739: Retrieving user@PRINCIPAL from FILE:/home/user/software_projects/KafkaServerPy/user.keytab (vno 0, enctype aes256-cts) with result: 0/Success
[25670] 1516023762.209759: AS key obtained for encrypted timestamp: aes256-cts/114F
[25670] 1516023762.209827: Encrypted timestamp (for 1516023762.182178): plain 301AA011180F32303138303131353133343234325AA105020302C7A2, encrypted 0F3685A1DB893A12ED2FA239A4967E67136F1DEA2FAE2B778FE9DD1E288CD59A8174C5C4071582EF53BDAABFA967327D01A564993E8BD692
[25670] 1516023762.209846: Preauth module encrypted_timestamp (2) (real) returned: 0/Success
[25670] 1516023762.209854: Produced preauth for next request: 133, 2
[25670] 1516023762.209876: Sending request (265 bytes) to PRINCIPAL
[25670] 1516023762.209897: Resolving hostname XXX.XXX.XXX.168
[25670] 1516023762.209974: Sending initial UDP request to dgram XXX.XXX.XXX.168:88
[25670] 1516023762.335681: Received answer (765 bytes) from dgram XXX.XXX.XXX.168:88
[25670] 1516023762.335720: Response was not from master KDC
[25670] 1516023762.335752: Processing preauth types: 19
[25670] 1516023762.335763: Selected etype info: etype aes256-cts, salt "PRINCIPALuser", params ""
[25670] 1516023762.335772: Produced preauth for next request: (empty)
[25670] 1516023762.335785: AS key determined by preauth: aes256-cts/114F
[25670] 1516023762.335855: Decrypted AS reply; session key is: aes256-cts/B626
[25670] 1516023762.335879: FAST negotiation: available
[25670] 1516023762.335899: Initializing FILE:/tmp/krb5cc_1001 with default princ user@PRINCIPAL
[25670] 1516023762.336032: Storing user@PRINCIPAL -> krbtgt/PRINCIPAL@PRINCIPAL in FILE:/tmp/krb5cc_1001
[25670] 1516023762.336069: Storing config in FILE:/tmp/krb5cc_1001 for krbtgt/PRINCIPAL@PRINCIPAL: fast_avail: yes
[25670] 1516023762.336107: Storing user@PRINCIPAL -> krb5_ccache_conf_data/fast_avail/krbtgt\/PRINCIPAL\@PRINCIPAL@X-CACHECONF: in FILE:/tmp/krb5cc_1001
[25670] 1516023762.336143: Storing config in FILE:/tmp/krb5cc_1001 for krbtgt/PRINCIPAL@PRINCIPAL: pa_type: 2
[25670] 1516023762.336176: Storing user@PRINCIPAL -> krb5_ccache_conf_data/pa_type/krbtgt\/PRINCIPAL\@PRINCIPAL@X-CACHECONF: in FILE:/tmp/krb5cc_1001
%7|1516023762.336|SASLREFRESH|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: SASL key refreshed
%7|1516023762.337|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: My supported SASL mechanisms: SCRAM-SHA-1 GS2-IAKERB GS2-KRB5 GSS-SPNEGO GSSAPI DIGEST-MD5 EXTERNAL CRAM-MD5 NTLM PLAIN LOGIN ANONYMOUS
[25681] 1516023762.339948: Getting initial credentials for user@PRINCIPAL
[25681] 1516023762.340111: Looked up etypes in keytab: aes256-cts, rc4-hmac, des3-cbc-sha1, des-cbc-crc
[25681] 1516023762.340162: Sending request (170 bytes) to PRINCIPAL
[25681] 1516023762.340187: Resolving hostname XXX.XXX.XXX.168
[25681] 1516023762.340265: Sending initial UDP request to dgram XXX.XXX.XXX.168:88
%7|1516023762.387|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Selected SASL mechanism: GSSAPI (wanted GSSAPI)
%7|1516023762.387|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Send SASL frame to broker (605 bytes)
[25681] 1516023762.388666: Received answer (327 bytes) from dgram XXX.XXX.XXX.168:88
[25681] 1516023762.388692: Response was not from master KDC
[25681] 1516023762.388719: Received error from KDC: -1765328359/Additional pre-authentication required
[25681] 1516023762.388751: Processing preauth types: 136, 19, 2, 133
[25681] 1516023762.388762: Selected etype info: etype aes256-cts, salt "PRINCIPALuser", params ""
[25681] 1516023762.388769: Received cookie: MIT
[25681] 1516023762.388825: Retrieving user@PRINCIPAL from FILE:/home/user/software_projects/KafkaServerPy/user.keytab (vno 0, enctype aes256-cts) with result: 0/Success
[25681] 1516023762.388843: AS key obtained for encrypted timestamp: aes256-cts/114F
[25681] 1516023762.388900: Encrypted timestamp (for 1516023762.361113): plain 301AA011180F32303138303131353133343234325AA1050203058299, encrypted 0DEF2B93813C7150A4EEF14450E65DB56EAECDF54641BB2758FEC6938DEE88BAC5CAB1A6772965F453ACD5B9CA5FB507456AE4AE0695C2E4
[25681] 1516023762.388922: Preauth module encrypted_timestamp (2) (real) returned: 0/Success
[25681] 1516023762.388927: Produced preauth for next request: 133, 2
[25681] 1516023762.388947: Sending request (265 bytes) to PRINCIPAL
[25681] 1516023762.388965: Resolving hostname XXX.XXX.XXX.168
[25681] 1516023762.389051: Sending initial UDP request to dgram XXX.XXX.XXX.168:88
%7|1516023762.436|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Received SASL frame from broker (112 bytes)
%7|1516023762.436|LIBSASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: CB_CANON: flags 0x3, "user@PRINCIPAL" @ "(null)": returning "user@PRINCIPAL"
%7|1516023762.436|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Send SASL frame to broker (0 bytes)
[25681] 1516023762.477968: Received answer (765 bytes) from dgram XXX.XXX.XXX.168:88
[25681] 1516023762.478002: Response was not from master KDC
[25681] 1516023762.478030: Processing preauth types: 19
[25681] 1516023762.478041: Selected etype info: etype aes256-cts, salt "PRINCIPALuser", params ""
[25681] 1516023762.478051: Produced preauth for next request: (empty)
[25681] 1516023762.478067: AS key determined by preauth: aes256-cts/114F
[25681] 1516023762.478121: Decrypted AS reply; session key is: aes256-cts/326D
[25681] 1516023762.478143: FAST negotiation: available
[25681] 1516023762.478160: Initializing FILE:/tmp/krb5cc_1001 with default princ user@PRINCIPAL
[25681] 1516023762.478278: Storing user@PRINCIPAL -> krbtgt/PRINCIPAL@PRINCIPAL in FILE:/tmp/krb5cc_1001
[25681] 1516023762.478314: Storing config in FILE:/tmp/krb5cc_1001 for krbtgt/PRINCIPAL@PRINCIPAL: fast_avail: yes
[25681] 1516023762.478344: Storing user@PRINCIPAL -> krb5_ccache_conf_data/fast_avail/krbtgt\/PRINCIPAL\@PRINCIPAL@X-CACHECONF: in FILE:/tmp/krb5cc_1001
[25681] 1516023762.478372: Storing config in FILE:/tmp/krb5cc_1001 for krbtgt/PRINCIPAL@PRINCIPAL: pa_type: 2
[25681] 1516023762.478397: Storing user@PRINCIPAL -> krb5_ccache_conf_data/pa_type/krbtgt\/PRINCIPAL\@PRINCIPAL@X-CACHECONF: in FILE:/tmp/krb5cc_1001
%7|1516023762.478|SASLREFRESH|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: SASL key refreshed
%7|1516023762.479|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: My supported SASL mechanisms: SCRAM-SHA-1 GS2-IAKERB GS2-KRB5 GSS-SPNEGO GSSAPI DIGEST-MD5 EXTERNAL CRAM-MD5 NTLM PLAIN LOGIN ANONYMOUS
%7|1516023762.484|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Received SASL frame from broker (36 bytes)
%7|1516023762.484|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Send SASL frame to broker (32 bytes)
%7|1516023762.484|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Authenticated as user@PRINCIPAL using GSSAPI (gssapiv2)
%7|1516023762.484|SEND|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Sent MetadataRequest (v2, 25 bytes @ 0, CorrId 3)
%7|1516023762.529|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Selected SASL mechanism: GSSAPI (wanted GSSAPI)
%7|1516023762.529|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Send SASL frame to broker (605 bytes)
%7|1516023762.578|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Received SASL frame from broker (112 bytes)
%7|1516023762.578|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|1516023762.578|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/bootstrap: Send SASL frame to broker (0 bytes)
%7|1516023762.620|RECV|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: Received MetadataResponse (v2, 80 bytes, CorrId 3, rtt 135.23ms)
%7|1516023762.620|SUBSCRIPTION|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu": no topics in metadata matched subscription
%7|1516023762.620|BRKREASSIGN|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu" management reassigned from broker :0/internal to sasl_plaintext://host2:9092/bootstrap
%7|1516023762.620|BRKUNASSIGN|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu" management unassigned from broker handle :0/internal
%7|1516023762.620|BRKASSIGN|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu" management assigned to broker sasl_plaintext://host2:9092/bootstrap
%7|1516023762.620|CGRPQUERY|rdkafka#consumer-1| [thrd:main]: sasl_plaintext://host2:9092/bootstrap: Group "user-cctv_python_ubuntu": querying for coordinator: intervaled in state wait-broker
%7|1516023762.620|SEND|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/2: Sent GroupCoordinatorRequest (v0, 48 bytes @ 0, CorrId 4)
%7|1516023762.626|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/3: Received SASL frame from broker (36 bytes)
%7|1516023762.626|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/3: Send SASL frame to broker (32 bytes)
%7|1516023762.626|SASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/3: Authenticated as user@PRINCIPAL using GSSAPI (gssapiv2)
%7|1516023762.626|SEND|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/3: Sent MetadataRequest (v2, 25 bytes @ 0, CorrId 3)
%7|1516023762.668|RECV|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/2: Received GroupCoordinatorResponse (v0, 22 bytes, CorrId 4, rtt 47.84ms)
%7|1516023762.668|CGRPCOORD|rdkafka#consumer-1| [thrd:main]: sasl_plaintext://host2:9092/2: Group "user-cctv_python_ubuntu" coordinator is host2:9092 id 2
%7|1516023762.668|CGRPCOORD|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu" changing coordinator -1 -> 2
%7|1516023762.668|CGRPSTATE|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu" changed state wait-broker -> wait-broker-transport (v1, join-state init)
%7|1516023762.668|CGRPSTATE|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu" changed state wait-broker-transport -> up (v1, join-state init)
%7|1516023762.668|JOIN|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu": join with 0 (1) subscribed topic(s)
%7|1516023762.668|CGRPMETADATA|rdkafka#consumer-1| [thrd:main]: consumer join: metadata for subscription only available for 0/1 topics (-1ms old)
%7|1516023762.668|JOIN|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu": postponing join until up-to-date metadata is available
%7|1516023762.668|SEND|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/3: Sent MetadataRequest (v2, 45 bytes @ 0, CorrId 4)
%7|1516023762.759|RECV|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/3: Received MetadataResponse (v2, 80 bytes, CorrId 3, rtt 133.01ms)
%7|1516023762.759|SUBSCRIPTION|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu": no topics in metadata matched subscription
%7|1516023762.759|RECV|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/3: Received MetadataResponse (v2, 137 bytes, CorrId 4, rtt 91.50ms)
%7|1516023762.759|SUBSCRIPTION|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu": effective subscription list changed from 0 to 1 topic(s):
%7|1516023762.759|SUBSCRIPTION|rdkafka#consumer-1| [thrd:main]: Topic DCC-Traffic-Images with 1 partition(s)
%7|1516023762.759|REJOIN|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu": subscription updated from metadata change: rejoining group
%7|1516023762.759|GRPLEADER|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu": resetting group leader info: Group rejoin
%7|1516023762.759|REJOIN|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu" rejoining in join-state init without an assignment
%7|1516023762.759|JOIN|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu": join with 1 (1) subscribed topic(s)
%7|1516023762.759|CGRPMETADATA|rdkafka#consumer-1| [thrd:main]: consumer join: metadata for subscription is up to date (0ms old)
%7|1516023762.759|CGRPJOINSTATE|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu" changed join state init -> wait-join (v1, state up)
%7|1516023762.759|SEND|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/2: Sent JoinGroupRequest (v0, 155 bytes @ 0, CorrId 5)
%7|1516023763.109|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|1516023764.156|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|1516023765.204|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|1516023766.252|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|1516023767.012|COMMIT|rdkafka#consumer-1| [thrd:main]: OffsetCommit internal error: Local: No offset stored
%7|1516023767.012|COMMIT|rdkafka#consumer-1| [thrd:main]: OffsetCommit for -1 partition(s): cgrp auto commit timer: returned: Local: No offset stored
%7|1516023767.012|UNASSIGN|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu": unassign done in state up (join state wait-join): without new assignment: OffsetCommit done (__NO_OFFSET)
%7|1516023767.315|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|1516023768.364|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|1516023769.412|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|1516023770.460|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|1516023771.508|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|1516023772.012|COMMIT|rdkafka#consumer-1| [thrd:main]: OffsetCommit internal error: Local: No offset stored
%7|1516023772.012|COMMIT|rdkafka#consumer-1| [thrd:main]: OffsetCommit for -1 partition(s): cgrp auto commit timer: returned: Local: No offset stored
%7|1516023772.012|UNASSIGN|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu": unassign done in state up (join state wait-join): without new assignment: OffsetCommit done (__NO_OFFSET)
%7|1516023772.556|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|1516023773.603|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|1516023774.651|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|1516023775.698|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|1516023776.746|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|1516023777.012|COMMIT|rdkafka#consumer-1| [thrd:main]: OffsetCommit internal error: Local: No offset stored
%7|1516023777.012|COMMIT|rdkafka#consumer-1| [thrd:main]: OffsetCommit for -1 partition(s): cgrp auto commit timer: returned: Local: No offset stored
%7|1516023777.012|UNASSIGN|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu": unassign done in state up (join state wait-join): without new assignment: OffsetCommit done (__NO_OFFSET)
%7|1516023777.814|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|1516023778.862|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|1516023779.910|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|1516023780.958|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|1516023781.921|RECV|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/2: Received JoinGroupResponse (v0, 189 bytes, CorrId 5, rtt 19161.68ms)
%7|1516023781.921|JOINGROUP|rdkafka#consumer-1| [thrd:main]: JoinGroup response: GenerationId 16, Protocol range, LeaderId rdkafka-a635696e-aaad-41ee-8061-93b94919022b (me), my MemberId rdkafka-a635696e-aaad-41ee-8061-93b94919022b, 1 members in group: (no error)
%7|1516023781.921|MEMBERID|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu": updating member id "" -> "rdkafka-a635696e-aaad-41ee-8061-93b94919022b"
%7|1516023781.921|JOINGROUP|rdkafka#consumer-1| [thrd:main]: Elected leader for group "user-cctv_python_ubuntu" with 1 member(s)
%7|1516023781.921|GRPLEADER|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu": resetting group leader info: JoinGroup response clean-up
%7|1516023781.921|CGRPJOINSTATE|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu" changed join state wait-join -> wait-metadata (v1, state up)
%7|1516023781.921|SEND|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/2: Sent MetadataRequest (v2, 45 bytes @ 0, CorrId 6)
%7|1516023781.969|RECV|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/2: Received MetadataResponse (v2, 137 bytes, CorrId 6, rtt 47.89ms)
%7|1516023781.969|ASSIGN|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu" running range assignment for 1 member(s):
%7|1516023781.969|ASSIGN|rdkafka#consumer-1| [thrd:main]: Member "rdkafka-a635696e-aaad-41ee-8061-93b94919022b" (me) with 1 subscription(s):
%7|1516023781.969|ASSIGN|rdkafka#consumer-1| [thrd:main]: DCC-Traffic-Images [-1]
%7|1516023781.969|ASSIGN|rdkafka#consumer-1| [thrd:main]: range: Topic DCC-Traffic-Images with 1 partition(s) and 1 subscribing member(s)
%7|1516023781.969|ASSIGN|rdkafka#consumer-1| [thrd:main]: range: Member "rdkafka-a635696e-aaad-41ee-8061-93b94919022b": assigned topic DCC-Traffic-Images partitions 0..0
%7|1516023781.969|ASSIGN|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu" range assignment for 1 member(s) finished in 0.023ms:
%7|1516023781.969|ASSIGN|rdkafka#consumer-1| [thrd:main]: Member "rdkafka-a635696e-aaad-41ee-8061-93b94919022b" (me) assigned 1 partition(s):
%7|1516023781.969|ASSIGN|rdkafka#consumer-1| [thrd:main]: DCC-Traffic-Images [0]
%7|1516023781.969|ASSIGNOR|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu": "range" assignor run for 1 member(s)
%7|1516023781.969|CGRPJOINSTATE|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu" changed join state wait-metadata -> wait-sync (v1, state up)
%7|1516023781.969|SEND|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/2: Sent SyncGroupRequest (v0, 190 bytes @ 0, CorrId 7)
%7|1516023782.006|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|1516023782.012|COMMIT|rdkafka#consumer-1| [thrd:main]: OffsetCommit internal error: Local: No offset stored
%7|1516023782.012|COMMIT|rdkafka#consumer-1| [thrd:main]: OffsetCommit for -1 partition(s): cgrp auto commit timer: returned: Local: No offset stored
%7|1516023782.012|UNASSIGN|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu": unassign done in state up (join state wait-sync): without new assignment: OffsetCommit done (__NO_OFFSET)
%7|1516023782.018|RECV|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/2: Received SyncGroupResponse (v0, 44 bytes, CorrId 7, rtt 48.15ms)
%7|1516023782.018|SYNCGROUP|rdkafka#consumer-1| [thrd:main]: SyncGroup response: Success (38 bytes of MemberState data)
%7|1516023782.018|ASSIGN|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu": delegating assign of 1 partition(s) to application rebalance callback on queue rd_kafka_cgrp_new: new assignment
%7|1516023782.018|CGRPJOINSTATE|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu" changed join state wait-sync -> wait-assign-rebalance_cb (v1, state up)
%7|1516023782.018|HEARTBEAT|rdkafka#consumer-1| [thrd:main]: sasl_plaintext://host2:9092/2: Heartbeat for group "user-cctv_python_ubuntu" generation id 16
%7|1516023782.018|CGRPOP|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu" received op ASSIGN (v0) in state up (join state wait-assign-rebalance_cb, v1 vs 0)
%7|1516023782.018|ASSIGN|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu": new assignment of 1 partition(s) in join state wait-assign-rebalance_cb
%7|1516023782.018|SEND|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/2: Sent HeartbeatRequest (v0, 98 bytes @ 0, CorrId 8)
%7|1516023782.018|BARRIER|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu": rd_kafka_cgrp_assign:2284: new version barrier v2
%7|1516023782.018|ASSIGN|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu": assigning 1 partition(s) in join state wait-assign-rebalance_cb
%7|1516023782.018|CGRPJOINSTATE|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu" changed join state wait-assign-rebalance_cb -> assigned (v2, state up)
%7|1516023782.018|BARRIER|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu": rd_kafka_cgrp_partitions_fetch_start0:1632: new version barrier v3
%7|1516023782.018|FETCHSTART|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu": starting fetchers for 1 assigned partition(s) in join-state assigned (usable_offsets=no, v3, line 2329)
%7|1516023782.018|FETCHSTART|rdkafka#consumer-1| [thrd:main]: List with 1 partition(s):
%7|1516023782.018|FETCHSTART|rdkafka#consumer-1| [thrd:main]: DCC-Traffic-Images [0] offset INVALID
%7|1516023782.018|OFFSET|rdkafka#consumer-1| [thrd:main]: sasl_plaintext://host2:9092/2: Fetch committed offsets for 1/1 partition(s)
%7|1516023782.018|SEND|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/2: Sent OffsetFetchRequest (v1, 80 bytes @ 0, CorrId 9)
%7|1516023782.081|RECV|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/2: Received HeartbeatResponse (v0, 2 bytes, CorrId 8, rtt 63.17ms)
%7|1516023782.129|RECV|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/2: Received OffsetFetchResponse (v1, 44 bytes, CorrId 9, rtt 111.16ms)
%7|1516023782.129|OFFSETFETCH|rdkafka#consumer-1| [thrd:main]: List with 1 partition(s):
%7|1516023782.129|OFFSETFETCH|rdkafka#consumer-1| [thrd:main]: DCC-Traffic-Images [0] offset INVALID
%7|1516023782.129|OFFSET|rdkafka#consumer-1| [thrd:main]: Topic DCC-Traffic-Images [0]: setting default offset INVALID
%7|1516023782.129|BARRIER|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu": rd_kafka_cgrp_partitions_fetch_start0:1632: new version barrier v4
%7|1516023782.129|FETCHSTART|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu": starting fetchers for 1 assigned partition(s) in join-state assigned (usable_offsets=yes, v4, line 1564)
%7|1516023782.129|FETCHSTART|rdkafka#consumer-1| [thrd:main]: List with 1 partition(s):
%7|1516023782.129|FETCHSTART|rdkafka#consumer-1| [thrd:main]: DCC-Traffic-Images [0] offset 25206854
%7|1516023782.129|CGRPJOINSTATE|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu" changed join state assigned -> started (v4, state up)
%7|1516023782.129|CGRPOP|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu" received op PARTITION_JOIN in state up (join state started, v4) for DCC-Traffic-Images [0]
%7|1516023782.129|PARTADD|rdkafka#consumer-1| [thrd:main]: Group "user-cctv_python_ubuntu": add DCC-Traffic-Images [0]
%7|1516023782.129|SEND|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/3: Sent FetchRequest (v2, 77 bytes @ 0, CorrId 5)
%7|1516023782.570|RECV|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/3: Received FetchResponse (v2, 1048626 bytes, CorrId 5, rtt 441.24ms)
%7|1516023782.570|PROTOUFLOW|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/3: Protocol read buffer underflow at 1040737/1048626 (rd_kafka_msgset_reader_msg_v0_1:484): expected 60370 bytes > 7889 remaining bytes (truncated response from broker (ok))
%7|1516023782.570|SEND|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/3: Sent FetchRequest (v2, 77 bytes @ 0, CorrId 6)
Received msg: ..............
.............................
%7|1516023782.861|RECV|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/3: Received FetchResponse (v2, 1048626 bytes, CorrId 6, rtt 290.78ms)
%7|1516023782.861|PROTOUFLOW|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/3: Protocol read buffer underflow at 859650/1048626 (rd_kafka_msgset_reader_msg_v0_1:484): expected 281548 bytes > 188976 remaining bytes (truncated response from broker (ok))
%7|1516023782.861|SEND|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/3: Sent FetchRequest (v2, 77 bytes @ 0, CorrId 7)
Received msg: ..............
.............................
Received msg: ..............
.............................
%7|1516023783.054|BROKERFAIL|rdkafka#consumer-1| [thrd:sasl_plaintext://host1:9092/bootstrap]: sasl_plaintext://host1:9092/bootstrap: failed: err: Local: Broker transport failure: (errno: Connection refused)
Received msg: ..............
.............................
%7|1516023783.112|RECV|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/3: Received FetchResponse (v2, 1048626 bytes, CorrId 7, rtt 250.72ms)
%7|1516023783.112|PROTOUFLOW|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/3: Protocol read buffer underflow at 759915/1048626 (rd_kafka_msgset_reader_msg_v0_1:484): expected 319784 bytes > 288711 remaining bytes (truncated response from broker (ok))
%7|1516023783.112|SEND|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/3: Sent FetchRequest (v2, 77 bytes @ 0, CorrId 8)
Received msg: ..............
.............................
%7|1516023783.365|RECV|rdkafka#consumer-1| [thrd:sasl_plaintext://host3:9092/bootstrap]: sasl_plaintext://host3:9092/3: Received FetchResponse (v2, 1048626 bytes, CorrId 8, rtt 253.22ms)
mmgutsche
on 15 Jan 2018
Stlll seems to be an issue with libsasl2, it never appears to return from sasl_client_start() in the CentOS case.
After this log (which is from libsasl2) we don't see any more output for broker2:
%5|1516023480.667|LIBSASL|rdkafka#consumer-1| [thrd:sasl_plaintext://host2:9092/bootstrap]: sasl_plaintext://host2:9092/bootstrap: GSSAPI client step 1
edenhill
on 15 Jan 2018
So, this one was a pain. I finally fixed it. It was not related to cyrus-sasl, not related to librdkafka and not related to kerberos. Or somehow related to all of them, because the debug information was sometimes misleading. I updated to the latest version on CentOS and changed my /etc/hosts.
Here I had
127.0.0.1 localhost localhost.localdomain localhost4 localhost4.localdomain4
::1 localhost localhost.localdomain localhost6 localhost6.localdomain6
xxx.xxx.xxx.237 host1
xxx.xxx.xxx.184 host3
xxx.xxx.xxx.168 PRINCIPAL.COM principal.com host2
The last line caused some hickup in the kerberos credential cache. Changing it to
xxx.xxx.xxx.168 host2 principal.com PRINCIPAL.COM
Fixed the issue. I am still not 100% sure why, but happy that it is solved.
mmgutsche
on 17 Jan 2018
Happy to hear that! Thanks for sharing the problem/solution for the next poor soul to struggle with Kerberos
edenhill
on 17 Jan 2018
Related issues
dblia
·
5Comments
vahidhashemian
·
6Comments
winbatch
·
5Comments
QueryCity
·
7Comments
blandings
·
4Comments