Reply
Explorer
Posts: 10
Registered: ‎07-17-2017
Accepted Solution

Apache Kafka Failing To Start For First Time

I have a kerberized CDH 5.9 cluster which has been running fine for a month now since securing it. I installed Kafka through Parcels, and then went to add the service to CM, and I've been running into an error while starting the brokers. All three broker nodes are complaining because they cannot access /var/run/scm-cloudera-agent/process/*-kafka-KAFKA_BROKER/supervisor.conf, but the start script seems to create a new folder with supervisor.conf in it every time. The file is set to 600 permissions with the owner as root, so its no wonder permission is denied, but I don't understand how this is supposed to work or what I'm missing that is causing it to not work in this case. I'm including a snippet of the stderr log (the whole log was too long to fit in this post) from one of the brokers below. Note that the permissions error comes up 4 times on each broker's log.

 

+ for i in '`seq 1 $COUNT`'
+ SCRIPT=/opt/cloudera/parcels/KAFKA-2.2.0-1.2.2.0.p0.68/meta/kafka_env.sh
+ PARCEL_DIRNAME=KAFKA-2.2.0-1.2.2.0.p0.68
+ . /opt/cloudera/parcels/KAFKA-2.2.0-1.2.2.0.p0.68/meta/kafka_env.sh
++ KAFKA_DIRNAME=KAFKA-2.2.0-1.2.2.0.p0.68
++ export KAFKA_HOME=/opt/cloudera/parcels/KAFKA-2.2.0-1.2.2.0.p0.68/lib/kafka
++ KAFKA_HOME=/opt/cloudera/parcels/KAFKA-2.2.0-1.2.2.0.p0.68/lib/kafka
+ echo 'Using /var/run/cloudera-scm-agent/process/1464-kafka-KAFKA_BROKER as conf dir'
+ echo 'Using scripts/control.sh as process script'
+ replace_conf_dir
+ find /var/run/cloudera-scm-agent/process/1464-kafka-KAFKA_BROKER -type f '!' -path '/var/run/cloudera-scm-agent/process/1464-kafka-KAFKA_BROKER/logs/*' '!' -name '*.log' '!' -name '*.keytab' '!' -name '*jceks' -exec perl -pi -e 's#{{CMF_CONF_DIR}}#/var/run/cloudera-scm-agent/process/1464-kafka-KAFKA_BROKER#g' '{}' ';'
Can't open /var/run/cloudera-scm-agent/process/1464-kafka-KAFKA_BROKER/supervisor.conf: Permission denied.
+ make_scripts_executable
+ find /var/run/cloudera-scm-agent/process/1464-kafka-KAFKA_BROKER -regex '.*\.\(py\|sh\)$' -exec chmod u+x '{}' ';'
+ export COMMON_SCRIPT=/usr/lib64/cmf/service/common/cloudera-config.sh
+ COMMON_SCRIPT=/usr/lib64/cmf/service/common/cloudera-config.sh
+ chmod u+x /var/run/cloudera-scm-agent/process/1464-kafka-KAFKA_BROKER/scripts/control.sh
+ exec /var/run/cloudera-scm-agent/process/1464-kafka-KAFKA_BROKER/scripts/control.sh start
+ DEFAULT_KAFKA_HOME=/usr/lib/kafka
+ KAFKA_HOME=/opt/cloudera/parcels/KAFKA-2.2.0-1.2.2.0.p0.68/lib/kafka
+ MIN_KAFKA_MAJOR_VERSION_WITH_SSL=2
Posts: 630
Topics: 3
Kudos: 102
Solutions: 66
Registered: ‎08-16-2016

Re: Apache Kafka Failing To Start For First Time

All services log that message about the supervisor.conf (not 100% is this is after kerberization or not). You can safely ignore it.

Check the stderr as well as the stdout, also see if there are logs under /var/log/*kafka* on the hosts running the Kafka brokers. That may contain more information and some exceptions and/or errors.

Did you do any config changes to Kafka after you installed it?
Explorer
Posts: 10
Registered: ‎07-17-2017

Re: Apache Kafka Failing To Start For First Time

[ Edited ]

I've not seen anything else in either stdout or stderr. I'm attaching the entirety of stdout here for posterity. The stderr can be found at the link below:

 

 

 

https://pastebin.com/CguhWiqh

 

Mon Jul 17 14:32:38 CDT 2017
JAVA_HOME=/usr/java/jdk1.7.0_67-cloudera
Using -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/tmp/kafka_kafka-KAFKA_BROKER-c1b2741bf1f3e232c6c549ec045bcb79_pid41162.hprof -XX:OnOutOfMemoryError=/usr/lib64/cmf/service/common/killparent.sh as CSD_JAVA_OPTS
Using /var/run/cloudera-scm-agent/process/1464-kafka-KAFKA_BROKER as conf dir
Using scripts/control.sh as process script

Date: Mon Jul 17 14:32:38 CDT 2017
Host: svd0hdatn03.XXXX.corp
Pwd: /var/run/cloudera-scm-agent/process/1464-kafka-KAFKA_BROKER
CONF_DIR: /var/run/cloudera-scm-agent/process/1464-kafka-KAFKA_BROKER
KAFKA_HOME: /opt/cloudera/parcels/KAFKA-2.2.0-1.2.2.0.p0.68/lib/kafka
Zookeeper Quorum: svd0hdatn01.XXXX.corp:2181,svd0hmstn01.XXXX.corp:2181,svd0hmstn02.XXXX.corp:2181
Zookeeper Chroot: 
PORT: 9092
JMX_PORT: 9393
SSL_PORT: 9093
ENABLE_MONITORING: true
METRIC_REPORTERS: nl.techop.kafka.KafkaHttpMetricsReporter
BROKER_HEAP_SIZE: 1024
BROKER_JAVA_OPTS: -server -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled -XX:+CMSScavengeBeforeRemark -XX:+DisableExplicitGC -Djava.awt.headless=true
BROKER_SSL_ENABLED: false
KERBEROS_AUTH_ENABLED: false
KAFKA_PRINCIPAL: kafka/svd0hdatn03.XXXX.corp@XXXX.CORP
SECURITY_INTER_BROKER_PROTOCOL: INFERRED
AUTHENTICATE_ZOOKEEPER_CONNECTION: true
SUPER_USERS: kafka
Kafka version found: 0.10.2-kafka2.2.0
ZK_PRINCIPAL_NAME: zookeeper
Final Zookeeper Quorum is svd0hdatn01.XXXX.corp:2181,svd0hmstn01.XXXX.corp:2181,svd0hmstn02.XXXX.corp:2181
security.inter.broker.protocol inferred as PLAINTEXT
LISTENERS=listeners=PLAINTEXT://svd0hdatn03.XXXX.corp:9092,
Mon Jul 17 14:32:43 CDT 2017
JAVA_HOME=/usr/java/jdk1.7.0_67-cloudera
Using -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/tmp/kafka_kafka-KAFKA_BROKER-c1b2741bf1f3e232c6c549ec045bcb79_pid41853.hprof -XX:OnOutOfMemoryError=/usr/lib64/cmf/service/common/killparent.sh as CSD_JAVA_OPTS
Using /var/run/cloudera-scm-agent/process/1464-kafka-KAFKA_BROKER as conf dir
Using scripts/control.sh as process script

Date: Mon Jul 17 14:32:43 CDT 2017
Host: svd0hdatn03.XXXX.corp
Pwd: /var/run/cloudera-scm-agent/process/1464-kafka-KAFKA_BROKER
CONF_DIR: /var/run/cloudera-scm-agent/process/1464-kafka-KAFKA_BROKER
KAFKA_HOME: /opt/cloudera/parcels/KAFKA-2.2.0-1.2.2.0.p0.68/lib/kafka
Zookeeper Quorum: svd0hdatn01.XXXX.corp:2181,svd0hmstn01.XXXX.corp:2181,svd0hmstn02.XXXX.corp:2181
Zookeeper Chroot: 
PORT: 9092
JMX_PORT: 9393
SSL_PORT: 9093
ENABLE_MONITORING: true
METRIC_REPORTERS: nl.techop.kafka.KafkaHttpMetricsReporter
BROKER_HEAP_SIZE: 1024
BROKER_JAVA_OPTS: -server -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled -XX:+CMSScavengeBeforeRemark -XX:+DisableExplicitGC -Djava.awt.headless=true
BROKER_SSL_ENABLED: false
KERBEROS_AUTH_ENABLED: false
KAFKA_PRINCIPAL: kafka/svd0hdatn03.XXXX.corp@XXXX.CORP
SECURITY_INTER_BROKER_PROTOCOL: INFERRED
AUTHENTICATE_ZOOKEEPER_CONNECTION: true
SUPER_USERS: kafka
Kafka version found: 0.10.2-kafka2.2.0
ZK_PRINCIPAL_NAME: zookeeper
Final Zookeeper Quorum is svd0hdatn01.XXXX.corp:2181,svd0hmstn01.XXXX.corp:2181,svd0hmstn02.XXXX.corp:2181
security.inter.broker.protocol inferred as PLAINTEXT
LISTENERS=listeners=PLAINTEXT://svd0hdatn03.XXXX.corp:9092,
Mon Jul 17 14:32:49 CDT 2017
JAVA_HOME=/usr/java/jdk1.7.0_67-cloudera
Using -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/tmp/kafka_kafka-KAFKA_BROKER-c1b2741bf1f3e232c6c549ec045bcb79_pid42550.hprof -XX:OnOutOfMemoryError=/usr/lib64/cmf/service/common/killparent.sh as CSD_JAVA_OPTS
Using /var/run/cloudera-scm-agent/process/1464-kafka-KAFKA_BROKER as conf dir
Using scripts/control.sh as process script

Date: Mon Jul 17 14:32:49 CDT 2017
Host: svd0hdatn03.XXXX.corp
Pwd: /var/run/cloudera-scm-agent/process/1464-kafka-KAFKA_BROKER
CONF_DIR: /var/run/cloudera-scm-agent/process/1464-kafka-KAFKA_BROKER
KAFKA_HOME: /opt/cloudera/parcels/KAFKA-2.2.0-1.2.2.0.p0.68/lib/kafka
Zookeeper Quorum: svd0hdatn01.XXXX.corp:2181,svd0hmstn01.XXXX.corp:2181,svd0hmstn02.XXXX.corp:2181
Zookeeper Chroot: 
PORT: 9092
JMX_PORT: 9393
SSL_PORT: 9093
ENABLE_MONITORING: true
METRIC_REPORTERS: nl.techop.kafka.KafkaHttpMetricsReporter
BROKER_HEAP_SIZE: 1024
BROKER_JAVA_OPTS: -server -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled -XX:+CMSScavengeBeforeRemark -XX:+DisableExplicitGC -Djava.awt.headless=true
BROKER_SSL_ENABLED: false
KERBEROS_AUTH_ENABLED: false
KAFKA_PRINCIPAL: kafka/svd0hdatn03.XXXX.corp@XXXX.CORP
SECURITY_INTER_BROKER_PROTOCOL: INFERRED
AUTHENTICATE_ZOOKEEPER_CONNECTION: true
SUPER_USERS: kafka
Kafka version found: 0.10.2-kafka2.2.0
ZK_PRINCIPAL_NAME: zookeeper
Final Zookeeper Quorum is svd0hdatn01.XXXX.corp:2181,svd0hmstn01.XXXX.corp:2181,svd0hmstn02.XXXX.corp:2181
security.inter.broker.protocol inferred as PLAINTEXT
LISTENERS=listeners=PLAINTEXT://svd0hdatn03.XXXX.corp:9092,
Mon Jul 17 14:32:57 CDT 2017
JAVA_HOME=/usr/java/jdk1.7.0_67-cloudera
Using -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/tmp/kafka_kafka-KAFKA_BROKER-c1b2741bf1f3e232c6c549ec045bcb79_pid43296.hprof -XX:OnOutOfMemoryError=/usr/lib64/cmf/service/common/killparent.sh as CSD_JAVA_OPTS
Using /var/run/cloudera-scm-agent/process/1464-kafka-KAFKA_BROKER as conf dir
Using scripts/control.sh as process script

Date: Mon Jul 17 14:32:57 CDT 2017
Host: svd0hdatn03.XXXX.corp
Pwd: /var/run/cloudera-scm-agent/process/1464-kafka-KAFKA_BROKER
CONF_DIR: /var/run/cloudera-scm-agent/process/1464-kafka-KAFKA_BROKER
KAFKA_HOME: /opt/cloudera/parcels/KAFKA-2.2.0-1.2.2.0.p0.68/lib/kafka
Zookeeper Quorum: svd0hdatn01.XXXX.corp:2181,svd0hmstn01.XXXX.corp:2181,svd0hmstn02.XXXX.corp:2181
Zookeeper Chroot: 
PORT: 9092
JMX_PORT: 9393
SSL_PORT: 9093
ENABLE_MONITORING: true
METRIC_REPORTERS: nl.techop.kafka.KafkaHttpMetricsReporter
BROKER_HEAP_SIZE: 1024
BROKER_JAVA_OPTS: -server -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled -XX:+CMSScavengeBeforeRemark -XX:+DisableExplicitGC -Djava.awt.headless=true
BROKER_SSL_ENABLED: false
KERBEROS_AUTH_ENABLED: false
KAFKA_PRINCIPAL: kafka/svd0hdatn03.XXXX.corp@XXXX.CORP
SECURITY_INTER_BROKER_PROTOCOL: INFERRED
AUTHENTICATE_ZOOKEEPER_CONNECTION: true
SUPER_USERS: kafka
Kafka version found: 0.10.2-kafka2.2.0
ZK_PRINCIPAL_NAME: zookeeper
Final Zookeeper Quorum is svd0hdatn01.XXXX.corp:2181,svd0hmstn01.XXXX.corp:2181,svd0hmstn02.XXXX.corp:2181
security.inter.broker.protocol inferred as PLAINTEXT
LISTENERS=listeners=PLAINTEXT://svd0hdatn03.XXXX.corp:9092,

 

Highlighted
Explorer
Posts: 10
Registered: ‎07-17-2017

Re: Apache Kafka Failing To Start For First Time

Found the issue. In /var/log/*kafka*, there was a log file that had an exception logged in it that I've included below. After I went back and enabled Kerberos authorization for Kafka (I had not enabled it thinking I could do that later), everything started successfully. Thanks for pointing me to that log file!

 

java.lang.RuntimeException: Unable to create KafkaAuthBinding: keytabFile required because kerberos is enabled
        at org.apache.sentry.kafka.binding.KafkaAuthBindingSingleton.configure(KafkaAuthBindingSingleton.java:67)
        at org.apache.sentry.kafka.authorizer.SentryKafkaAuthorizer.configure(SentryKafkaAuthorizer.java:120)
        at kafka.server.KafkaServer$$anonfun$startup$4.apply(KafkaServer.scala:236)
        at kafka.server.KafkaServer$$anonfun$startup$4.apply(KafkaServer.scala:234)
        at scala.Option.map(Option.scala:146)
        at kafka.server.KafkaServer.startup(KafkaServer.scala:234)
        at kafka.server.KafkaServerStartable.startup(KafkaServerStartable.scala:39)
        at kafka.Kafka$.main(Kafka.scala:67)
        at com.cloudera.kafka.wrap.Kafka$.main(Kafka.scala:76)
        at com.cloudera.kafka.wrap.Kafka.main(Kafka.scala)
Caused by: java.lang.IllegalArgumentException: keytabFile required because kerberos is enabled
        at org.apache.sentry.kafka.binding.KafkaAuthBinding.initKerberos(KafkaAuthBinding.java:561)
        at org.apache.sentry.kafka.binding.KafkaAuthBinding.createAuthProvider(KafkaAuthBinding.java:142)
        at org.apache.sentry.kafka.binding.KafkaAuthBinding.<init>(KafkaAuthBinding.java:97)
        at org.apache.sentry.kafka.binding.KafkaAuthBindingSingleton.configure(KafkaAuthBindingSingleton.java:63)
        ... 9 more
Announcements