Kafka Kerberos Debug

I’ve spent a lot of time with Kerberos recently.

If you are debugging kerberos and kafka, try this before starting Kafka add -Dsun.security.krb5.debug=true to the KAFKA_HEAP_OPTS.

export KAFKA_HEAP_OPTS="-Xmx1G -Xms1G -Djava.security.auth.login.config=/opt/kafka/security/kafka_server_jaas.conf -Djava.security.krb5.conf=/etc/krb5.conf -Dlog4j.properties=file:///opt/kafka/config/log4j.properties -Dsun.security.krb5.debug=true"

/opt/kafka/bin/kafka-server-start.sh /opt/kafka/config/server.properties

You get a rich log file

 

root@broker:/# cat zookeeper.log
[2017-05-20 20:25:33,482] INFO Reading configuration from: /opt/kafka/config/zookeeper.properties (org.apache.zookeeper.server.quorum.QuorumPeerConfig)
[2017-05-20 20:25:33,495] INFO Resolved hostname: 0.0.0.0 to address: /0.0.0.0 (org.apache.zookeeper.server.quorum.QuorumPeer)
[2017-05-20 20:25:33,495] ERROR Invalid configuration, only one server specified (ignoring) (org.apache.zookeeper.server.quorum.QuorumPeerConfig)
[2017-05-20 20:25:33,497] INFO autopurge.snapRetainCount set to 3 (org.apache.zookeeper.server.DatadirCleanupManager)
[2017-05-20 20:25:33,497] INFO autopurge.purgeInterval set to 0 (org.apache.zookeeper.server.DatadirCleanupManager)
[2017-05-20 20:25:33,497] INFO Purge task is not scheduled. (org.apache.zookeeper.server.DatadirCleanupManager)
[2017-05-20 20:25:33,497] WARN Either no config or no quorum defined in config, running in standalone mode (org.apache.zookeeper.server.quorum.QuorumPeerMain)
[2017-05-20 20:25:33,512] INFO Reading configuration from: /opt/kafka/config/zookeeper.properties (org.apache.zookeeper.server.quorum.QuorumPeerConfig)
[2017-05-20 20:25:33,512] INFO Resolved hostname: 0.0.0.0 to address: /0.0.0.0 (org.apache.zookeeper.server.quorum.QuorumPeer)
[2017-05-20 20:25:33,513] ERROR Invalid configuration, only one server specified (ignoring) (org.apache.zookeeper.server.quorum.QuorumPeerConfig)
[2017-05-20 20:25:33,513] INFO Starting server (org.apache.zookeeper.server.ZooKeeperServerMain)
[2017-05-20 20:25:33,520] INFO Server environment:zookeeper.version=3.4.8--1, built on 02/06/2016 03:18 GMT (org.apache.zookeeper.server.ZooKeeperServer)
[2017-05-20 20:25:33,520] INFO Server environment:host.name=broker.example.local (org.apache.zookeeper.server.ZooKeeperServer)
[2017-05-20 20:25:33,520] INFO Server environment:java.version=1.8.0_131 (org.apache.zookeeper.server.ZooKeeperServer)
[2017-05-20 20:25:33,520] INFO Server environment:java.vendor=Oracle Corporation (org.apache.zookeeper.server.ZooKeeperServer)
[2017-05-20 20:25:33,520] INFO Server environment:java.home=/usr/lib/jvm/java-8-openjdk-amd64/jre (org.apache.zookeeper.server.ZooKeeperServer)
[2017-05-20 20:25:33,520] INFO Server environment:java.class.path=:/opt/kafka/bin/../libs/aopalliance-repackaged-2.4.0-b34.jar:/opt/kafka/bin/../libs/argparse4j-0.5.0.jar:/opt/kafka/bin/../libs/connect-api-0.10.1.0.jar:/opt/kafka/bin/../libs/connect-file-0.10.1.0.jar:/opt/kafka/bin/../libs/connect-json-0.10.1.0.jar:/opt/kafka/bin/../libs/connect-runtime-0.10.1.0.jar:/opt/kafka/bin/../libs/guava-18.0.jar:/opt/kafka/bin/../libs/hk2-api-2.4.0-b34.jar:/opt/kafka/bin/../libs/hk2-locator-2.4.0-b34.jar:/opt/kafka/bin/../libs/hk2-utils-2.4.0-b34.jar:/opt/kafka/bin/../libs/jackson-annotations-2.6.0.jar:/opt/kafka/bin/../libs/jackson-core-2.6.3.jar:/opt/kafka/bin/../libs/jackson-databind-2.6.3.jar:/opt/kafka/bin/../libs/jackson-jaxrs-base-2.6.3.jar:/opt/kafka/bin/../libs/jackson-jaxrs-json-provider-2.6.3.jar:/opt/kafka/bin/../libs/jackson-module-jaxb-annotations-2.6.3.jar:/opt/kafka/bin/../libs/javassist-3.18.2-GA.jar:/opt/kafka/bin/../libs/javax.annotation-api-1.2.jar:/opt/kafka/bin/../libs/javax.inject-1.jar:/opt/kafka/bin/../libs/javax.inject-2.4.0-b34.jar:/opt/kafka/bin/../libs/javax.servlet-api-3.1.0.jar:/opt/kafka/bin/../libs/javax.ws.rs-api-2.0.1.jar:/opt/kafka/bin/../libs/jersey-client-2.22.2.jar:/opt/kafka/bin/../libs/jersey-common-2.22.2.jar:/opt/kafka/bin/../libs/jersey-container-servlet-2.22.2.jar:/opt/kafka/bin/../libs/jersey-container-servlet-core-2.22.2.jar:/opt/kafka/bin/../libs/jersey-guava-2.22.2.jar:/opt/kafka/bin/../libs/jersey-media-jaxb-2.22.2.jar:/opt/kafka/bin/../libs/jersey-server-2.22.2.jar:/opt/kafka/bin/../libs/jetty-continuation-9.2.15.v20160210.jar:/opt/kafka/bin/../libs/jetty-http-9.2.15.v20160210.jar:/opt/kafka/bin/../libs/jetty-io-9.2.15.v20160210.jar:/opt/kafka/bin/../libs/jetty-security-9.2.15.v20160210.jar:/opt/kafka/bin/../libs/jetty-server-9.2.15.v20160210.jar:/opt/kafka/bin/../libs/jetty-servlet-9.2.15.v20160210.jar:/opt/kafka/bin/../libs/jetty-servlets-9.2.15.v20160210.jar:/opt/kafka/bin/../libs/jetty-util-9.2.15.v20160210.jar:/opt/kafka/bin/../libs/jopt-simple-4.9.jar:/opt/kafka/bin/../libs/kafka-clients-0.10.1.0.jar:/opt/kafka/bin/../libs/kafka-log4j-appender-0.10.1.0.jar:/opt/kafka/bin/../libs/kafka-streams-0.10.1.0.jar:/opt/kafka/bin/../libs/kafka-streams-examples-0.10.1.0.jar:/opt/kafka/bin/../libs/kafka-tools-0.10.1.0.jar:/opt/kafka/bin/../libs/kafka_2.11-0.10.1.0-sources.jar:/opt/kafka/bin/../libs/kafka_2.11-0.10.1.0-test-sources.jar:/opt/kafka/bin/../libs/kafka_2.11-0.10.1.0.jar:/opt/kafka/bin/../libs/log4j-1.2.17.jar:/opt/kafka/bin/../libs/lz4-1.3.0.jar:/opt/kafka/bin/../libs/metrics-core-2.2.0.jar:/opt/kafka/bin/../libs/osgi-resource-locator-1.0.1.jar:/opt/kafka/bin/../libs/reflections-0.9.10.jar:/opt/kafka/bin/../libs/rocksdbjni-4.9.0.jar:/opt/kafka/bin/../libs/scala-library-2.11.8.jar:/opt/kafka/bin/../libs/scala-parser-combinators_2.11-1.0.4.jar:/opt/kafka/bin/../libs/slf4j-api-1.7.21.jar:/opt/kafka/bin/../libs/slf4j-log4j12-1.7.21.jar:/opt/kafka/bin/../libs/snappy-java-1.1.2.6.jar:/opt/kafka/bin/../libs/validation-api-1.1.0.Final.jar:/opt/kafka/bin/../libs/zkclient-0.9.jar:/opt/kafka/bin/../libs/zookeeper-3.4.8.jar (org.apache.zookeeper.server.ZooKeeperServer)
[2017-05-20 20:25:33,520] INFO Server environment:java.library.path=/usr/java/packages/lib/amd64:/usr/lib/x86_64-linux-gnu/jni:/lib/x86_64-linux-gnu:/usr/lib/x86_64-linux-gnu:/usr/lib/jni:/lib:/usr/lib (org.apache.zookeeper.server.ZooKeeperServer)
[2017-05-20 20:25:33,520] INFO Server environment:java.io.tmpdir=/tmp (org.apache.zookeeper.server.ZooKeeperServer)
[2017-05-20 20:25:33,520] INFO Server environment:java.compiler= (org.apache.zookeeper.server.ZooKeeperServer)
[2017-05-20 20:25:33,520] INFO Server environment:os.name=Linux (org.apache.zookeeper.server.ZooKeeperServer)
[2017-05-20 20:25:33,520] INFO Server environment:os.arch=amd64 (org.apache.zookeeper.server.ZooKeeperServer)
[2017-05-20 20:25:33,520] INFO Server environment:os.version=4.9.27-moby (org.apache.zookeeper.server.ZooKeeperServer)
[2017-05-20 20:25:33,520] INFO Server environment:user.name=root (org.apache.zookeeper.server.ZooKeeperServer)
[2017-05-20 20:25:33,520] INFO Server environment:user.home=/root (org.apache.zookeeper.server.ZooKeeperServer)
[2017-05-20 20:25:33,520] INFO Server environment:user.dir=/ (org.apache.zookeeper.server.ZooKeeperServer)
[2017-05-20 20:25:33,527] INFO tickTime set to 3000 (org.apache.zookeeper.server.ZooKeeperServer)
[2017-05-20 20:25:33,527] INFO minSessionTimeout set to -1 (org.apache.zookeeper.server.ZooKeeperServer)
[2017-05-20 20:25:33,527] INFO maxSessionTimeout set to -1 (org.apache.zookeeper.server.ZooKeeperServer)
Debug is true storeKey true useTicketCache false useKeyTab true doNotPrompt true ticketCache is null isInitiator true KeyTab is /etc/security/keytabs/zookeeper.keytab refreshKrb5Config is true principal is zookeeper/broker.example.local@example.LOCAL tryFirstPass is false useFirstPass is true storePass is false clearPass is false
Refreshing Kerberos configuration
Java config name: /etc/krb5.conf
Loaded from Java config

KdcAccessibility: reset
KdcAccessibility: reset
KeyTabInputStream, readName(): example.LOCAL
KeyTabInputStream, readName(): zookeeper
KeyTabInputStream, readName(): broker.example.local
KeyTab: load() entry length: 107; type: 18
KeyTabInputStream, readName(): example.LOCAL
KeyTabInputStream, readName(): zookeeper
KeyTabInputStream, readName(): broker.example.local
KeyTab: load() entry length: 91; type: 17
KeyTabInputStream, readName(): example.LOCAL
KeyTabInputStream, readName(): zookeeper
KeyTabInputStream, readName(): broker.example.local
KeyTab: load() entry length: 99; type: 16
KeyTabInputStream, readName(): example.LOCAL
KeyTabInputStream, readName(): zookeeper
KeyTabInputStream, readName(): broker.example.local
KeyTab: load() entry length: 91; type: 23
KeyTabInputStream, readName(): example.LOCAL
KeyTabInputStream, readName(): zookeeper
KeyTabInputStream, readName(): broker.example.local
KeyTab: load() entry length: 107; type: 18
KeyTabInputStream, readName(): example.LOCAL
KeyTabInputStream, readName(): zookeeper
KeyTabInputStream, readName(): broker.example.local
KeyTab: load() entry length: 91; type: 17
KeyTabInputStream, readName(): example.LOCAL
KeyTabInputStream, readName(): zookeeper
KeyTabInputStream, readName(): broker.example.local
KeyTab: load() entry length: 99; type: 16
KeyTabInputStream, readName(): example.LOCAL
KeyTabInputStream, readName(): zookeeper
KeyTabInputStream, readName(): broker.example.local
KeyTab: load() entry length: 91; type: 23
Looking for keys for: zookeeper/broker.example.local@example.LOCAL
Added key: 23version: 2
Added key: 16version: 2
Added key: 17version: 2
Added key: 18version: 2
Added key: 23version: 1
Added key: 16version: 1
Added key: 17version: 1
Added key: 18version: 1
Looking for keys for: zookeeper/broker.example.local@example.LOCAL
Added key: 23version: 2
Added key: 16version: 2
Added key: 17version: 2
Added key: 18version: 2
Added key: 23version: 1
Added key: 16version: 1
Added key: 17version: 1
Added key: 18version: 1
default etypes for default_tkt_enctypes: 18 17 16.
KrbAsReq creating message
KrbKdcReq send: kdc=broker.example.local UDP:88, timeout=30000, number of retries =3, #bytes=188
KDCCommunication: kdc=broker.example.local UDP:88, timeout=30000,Attempt =1, #bytes=188
KrbKdcReq send: #bytes read=804
KdcAccessibility: remove broker.example.local
Looking for keys for: zookeeper/broker.example.local@example.LOCAL
Added key: 23version: 2
Added key: 16version: 2
Added key: 17version: 2
Added key: 18version: 2
Added key: 23version: 1
Added key: 16version: 1
Added key: 17version: 1
Added key: 18version: 1
EType: sun.security.krb5.internal.crypto.Aes256CtsHmacSha1EType
KrbAsRep cons in KrbAsReq.getReply zookeeper/broker.example.local
principal is zookeeper/broker.example.local@example.LOCAL
Will use keytab
Commit Succeeded

[2017-05-20 20:25:33,649] INFO successfully logged in. (org.apache.zookeeper.Login)
[2017-05-20 20:25:33,651] INFO TGT refresh thread started. (org.apache.zookeeper.Login)
[2017-05-20 20:25:33,656] INFO binding to port 0.0.0.0/0.0.0.0:2181 (org.apache.zookeeper.server.NIOServerCnxnFactory)
[2017-05-20 20:25:33,666] INFO TGT valid starting at: Sat May 20 20:25:33 UTC 2017 (org.apache.zookeeper.Login)
[2017-05-20 20:25:33,666] INFO TGT expires: Sun May 21 20:25:33 UTC 2017 (org.apache.zookeeper.Login)
[2017-05-20 20:25:33,666] INFO TGT refresh sleeping until: Sun May 21 16:02:45 UTC 2017 (org.apache.zookeeper.Login)
root@broker:/#