Kafka service fails to start on VMWare appliance, appliance console hangs starting server

[mschmitt-nasuni]

Issue

When trying to start the ManageIQ server from the appliance_console, it hangs indefinitely. Looking at the cockpit interface, we can see that the kafka service fails to start.

Steps to Reproduce

1. deploy a fresh ManageIQ appliance from the manageiq-vsphere-quinteros-1.ova OVA
2. run appliance_console
3. enter number 5 when prompted
4. set up the appliance as default
5. when it finishes the setup, and tries to start the server, the console hangs indefinitely

Environment

• Version: Quinteros-1
• Environment:
  • VMWare appliance

kafka logs:

[root@itmiq001 ~]# journalctl -u kafka --no-pager
-- Logs begin at Wed 2024-08-14 12:42:01 EDT, end at Wed 2024-08-14 13:12:35 EDT. --
Aug 14 12:45:31 itmiq001.domain.com systemd[1]: Started kafka service.
Aug 14 12:45:32 itmiq001.domain.com kafka-server-start.sh[7509]: [2024-08-14 12:45:32,733] INFO Registered kafka:type=kafka.Log4jController MBean (kafka.utils.Log4jControllerRegistration$)
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]: [2024-08-14 12:45:33,021] INFO Setting -D jdk.tls.rejectClientInitiatedRenegotiation=true to disable client-initiated TLS renegotiation (org.apache.zookeeper.common.X509Util)
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]: [2024-08-14 12:45:33,114] ERROR Exiting Kafka due to fatal exception (kafka.Kafka$)
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]: org.apache.kafka.common.KafkaException: Exception while loading Zookeeper JAAS login context [java.security.auth.login.config=/opt/kafka/config/kafka_server_jaas.conf, zookeeper.sasl.client=default:true, zookeeper.sasl.clientconfig=default:Client]
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]:         at org.apache.kafka.common.security.JaasUtils.isZkSaslEnabled(JaasUtils.java:67)
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]:         at kafka.server.KafkaServer$.zkClientConfigFromKafkaConfig(KafkaServer.scala:80)
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]:         at kafka.server.KafkaServer.<init>(KafkaServer.scala:150)
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]:         at kafka.Kafka$.buildServer(Kafka.scala:73)
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]:         at kafka.Kafka$.main(Kafka.scala:87)
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]:         at kafka.Kafka.main(Kafka.scala)
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]: Caused by: java.lang.SecurityException: java.io.IOException: Configuration Error:
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]:         Line 4: expected [option key], found [null]
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]:         at sun.security.provider.ConfigFile$Spi.<init>(ConfigFile.java:137)
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]:         at sun.security.provider.ConfigFile.<init>(ConfigFile.java:102)
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]:         at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]:         at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]:         at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]:         at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]:         at java.lang.Class.newInstance(Class.java:442)
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]:         at javax.security.auth.login.Configuration$2.run(Configuration.java:255)
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]:         at javax.security.auth.login.Configuration$2.run(Configuration.java:247)
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]:         at java.security.AccessController.doPrivileged(Native Method)
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]:         at javax.security.auth.login.Configuration.getConfiguration(Configuration.java:246)
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]:         at org.apache.kafka.common.security.JaasUtils.isZkSaslEnabled(JaasUtils.java:63)
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]:         ... 5 more
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]: Caused by: java.io.IOException: Configuration Error:
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]:         Line 4: expected [option key], found [null]
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]:         at sun.security.provider.ConfigFile$Spi.ioException(ConfigFile.java:666)
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]:         at sun.security.provider.ConfigFile$Spi.match(ConfigFile.java:579)
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]:         at sun.security.provider.ConfigFile$Spi.parseLoginEntry(ConfigFile.java:477)
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]:         at sun.security.provider.ConfigFile$Spi.readConfig(ConfigFile.java:427)
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]:         at sun.security.provider.ConfigFile$Spi.init(ConfigFile.java:329)
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]:         at sun.security.provider.ConfigFile$Spi.init(ConfigFile.java:271)
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]:         at sun.security.provider.ConfigFile$Spi.<init>(ConfigFile.java:135)
Aug 14 12:45:33 itmiq001.domain.com kafka-server-start.sh[7509]:         ... 16 more
Aug 14 12:45:33 itmiq001.domain.com systemd[1]: kafka.service: Main process exited, code=exited, status=1/FAILURE
Aug 14 12:45:33 itmiq001.domain.com systemd[1]: kafka.service: Failed with result 'exit-code'.
Aug 14 12:45:33 itmiq001.domain.com systemd[1]: kafka.service: Service RestartSec=100ms expired, scheduling restart.
Aug 14 12:45:33 itmiq001.domain.com systemd[1]: kafka.service: Scheduled restart job, restart counter is at 1.
Aug 14 12:45:33 itmiq001.domain.com systemd[1]: Stopped kafka service.
...
Aug 14 12:45:41 itmiq001.domain.com systemd[1]: kafka.service: Start request repeated too quickly.
Aug 14 12:45:41 itmiq001.domain.com systemd[1]: kafka.service: Failed with result 'exit-code'.
Aug 14 12:45:41 itmiq001.domain.com systemd[1]: Failed to start kafka service.

kafka config file

[root@itmiq001 ~]# cat /var/www/miq/vmdb/config/messaging.yml 
---
base:
  host: localhost
  port: 9092
  protocol: Kafka
  encoding: json
  username: admin
  password: smartvm
development:
  host: localhost
  port: 9092
  protocol: Kafka
  encoding: json
  username: admin
  password: smartvm
production:
  host: itmiq001.REDACTED.com
  port: 9093
  protocol: Kafka
  encoding: json
  username: admin
  password: v2:{REDACTED}
  ssl: true
  ca_file: "/opt/kafka/config/keystore/ca-cert"
test:
  host: localhost
  port: 9092
  protocol: Kafka
  encoding: json
  username: admin
  password: smartvm

[bdunne]

Is this a duplicate of https://github.com/orgs/ManageIQ/discussions/23131 ?

[mschmitt-nasuni]

Could be.. though I understood that forum to be for technical support, while this appears to be a bug. If it is a duplicate, or should be directed to that forum instead, we can close this.

[bdunne]

I'll let @nasark handle that part, but I wanted to at least link them together.

[miq-bot]

This issue has been automatically marked as stale because it has not been updated for at least 3 months.

If you can still reproduce this issue on the current release or on master, please reply with all of the information you have about it in order to keep the issue open.