containers
containers copied to clipboard
Published
20 hours ago •
bitnami
bitnami
SSL Handshake Failure from kafka-console-producer.sh
Name and Version
bitnami/kafka:3.6
What architecture are you using?
amd64
What steps will reproduce the bug?
Using this docker-compose.yml:
version: "3"
services:
kafka:
image: 'bitnami/kafka:3.6'
ports:
- '9092:9092'
volumes:
- ./server.properties:/bitnami/kafka/config/server.properties
- ./internal_client.properties:/bitnami/kafka/config/producer.properties
- ./internal_client.properties:/bitnami/kafka/config/consumer.properties
- ./keystore.pem:/opt/bitnami/kafka/config/certs/keystore.pem:ro
- ./CA.pem:/opt/bitnami/kafka/config/certs/CA.pem:ro
which uses the following server.properties:
# Kraft settings
process.roles=broker,controller
node.id=1
controller.quorum.voters=1@localhost:9093
# Listener settings
listeners=SSL://:9092,CONTROLLER://:9093
#inter.broker.listener.name=SSL
advertised.listeners=SSL://localhost:9092
controller.listener.names=CONTROLLER
listener.security.protocol.map=CONTROLLER:PLAINTEXT,PLAINTEXT:PLAINTEXT,SSL:SSL,SASL_PLAINTEXT:SASL_PLAINTEXT,SASL_SSL:SASL_SSL
# TLS/SSL settings
security.protocol=SSL
security.inter.broker.protocol=SSL
ssl.keystore.type=PEM
ssl.keystore.location=/opt/bitnami/kafka/config/certs/keystore.pem
ssl.key.password=<hidden>
ssl.truststore.type=PEM
ssl.truststore.location=/opt/bitnami/kafka/config/certs/CA.pem
ssl.client.auth=none
ssl.endpoint.identification.algorithm=
producer.ssl.endpoint.identification.algorithm=
consumer.ssl.endpoint.identification.algorithm=
# Performance settings
num.network.threads=3
num.io.threads=8
socket.send.buffer.bytes=102400
socket.receive.buffer.bytes=102400
socket.request.max.bytes=104857600
log.dirs=/tmp/kraft-combined-logs
num.partitions=1
num.recovery.threads.per.data.dir=1
# Replication factor settings
offsets.topic.replication.factor=1
transaction.state.log.replication.factor=1
transaction.state.log.min.isr=1
# Log retention settings
log.retention.hours=168
log.segment.bytes=1073741824
log.retention.check.interval.ms=300000
The producer and consumer properties are set in internal_client.properties:
security.protocol=SSL
ssl.keystore.type=PEM
ssl.keystore.location=/opt/bitnami/kafka/config/certs/keystore.pem
ssl.key.password=<hidden>
ssl.truststore.type=PEM
ssl.truststore.location=/opt/bitnami/kafka/config/certs/CA.pem
In this case keystore.pem contains the server certificate and private key. This was signed by my organisation's CA, the trust chain for which is present in CA.pem.
What is the expected behavior?
Docker container starts up ok, and I can use kafka-console-producer.sh and kafka-console-consumer.sh inside the container with the above producer.properties and consumer.properties to interact with topics on the command line.
What do you see instead?
The container starts up ok. When I try to run kafka-console-producer.sh I get an error:
$ kafka-console-producer.sh --bootstrap-server localhost:9092 --topic test-tls --producer.config /opt/bitnami/kafka/config/producer.properties
>[2024-03-01 10:54:25,231] ERROR [Producer clientId=console-producer] Connection to node -1 (localhost/127.0.0.1:9092) failed authentication due to: SSL handshake failed (org.apache.kafka.clients.NetworkClient)
[2024-03-01 10:54:25,232] WARN [Producer clientId=console-producer] Bootstrap broker localhost:9092 (id: -1 rack: null) disconnected (org.apache.kafka.clients.NetworkClient)
[2024-03-01 10:54:25,366] ERROR [Producer clientId=console-producer] Connection to node -1 (localhost/127.0.0.1:9092) failed authentication due to: SSL handshake failed (org.apache.kafka.clients.NetworkClient)
^C
Accompanied by errors in the container logs:
[2024-03-01 10:54:25,228] INFO [SocketServer listenerType=BROKER, nodeId=1] Failed authentication with /127.0.0.1 (channelId=127.0.0.1:9092-127.0.0.1:53984-0) (SSL handshake failed) (org.apache.kafka.common.network.Selector)
[2024-03-01 10:54:25,387] INFO [SocketServer listenerType=BROKER, nodeId=1] Failed authentication with /127.0.0.1 (channelId=127.0.0.1:9092-127.0.0.1:53998-0) (SSL handshake failed) (org.apache.kafka.common.network.Selector)
[2024-03-01 10:54:25,805] INFO [SocketServer listenerType=BROKER, nodeId=1] Failed authentication with /127.0.0.1 (channelId=127.0.0.1:9092-127.0.0.1:54010-0) (SSL handshake failed) (org.apache.kafka.common.network.Selector)
Which doesn't tell me the root cause of the problem, like a problem with my certificates, or my configuration, only that the SSL handshake failed.
Additional information
If I run a connection test with openssl s_client -cert keystore.pem -CAfile CA.pem -debug -connect localhost:9092, I get the following in the response, as well as the server certificate and other outputs:
SSL handshake has read 1701 bytes and written 377 bytes
Verification: OK
---
Verify return code: 0 (ok)
The full container logs are as follows:
kafka 10:30:48.89 INFO ==>
kafka 10:30:48.89 INFO ==> Welcome to the Bitnami kafka container
kafka 10:30:48.89 INFO ==> Subscribe to project updates by watching https://github.com/bitnami/containers
kafka 10:30:48.89 INFO ==> Submit issues and feature requests at https://github.com/bitnami/containers/issues
kafka 10:30:48.89 INFO ==>
kafka 10:30:48.89 INFO ==> ** Starting Kafka setup **
kafka 10:30:48.94 INFO ==> Initializing KRaft storage metadata
kafka 10:30:48.94 WARN ==> KAFKA_KRAFT_CLUSTER_ID not set - If using multiple nodes then you must use the same Cluster ID for each one
kafka 10:30:50.01 INFO ==> Generated Kafka cluster ID 'Yt-D0rsjQnaOh3r6COffgQ'
kafka 10:30:50.01 INFO ==> Formatting storage directories to add metadata...
All of the log directories are already formatted.
kafka 10:30:51.30 INFO ==> ** Kafka setup finished! **
kafka 10:30:51.31 INFO ==> ** Starting Kafka **
[2024-03-01 10:30:51,929] INFO Registered kafka:type=kafka.Log4jController MBean (kafka.utils.Log4jControllerRegistration$)
[2024-03-01 10:30:52,181] INFO Setting -D jdk.tls.rejectClientInitiatedRenegotiation=true to disable client-initiated TLS renegotiation (org.apache.zookeeper.common.X509Util)
[2024-03-01 10:30:52,306] INFO Registered signal handlers for TERM, INT, HUP (org.apache.kafka.common.utils.LoggingSignalHandler)
[2024-03-01 10:30:52,308] INFO [ControllerServer id=1] Starting controller (kafka.server.ControllerServer)
[2024-03-01 10:30:52,326] INFO authorizerStart completed for endpoint CONTROLLER. Endpoint is now READY. (org.apache.kafka.server.network.EndpointReadyFutures)
[2024-03-01 10:30:52,656] INFO Updated connection-accept-rate max connection creation rate to 2147483647 (kafka.network.ConnectionQuotas)
[2024-03-01 10:30:52,692] INFO [SocketServer listenerType=CONTROLLER, nodeId=1] Created data-plane acceptor and processors for endpoint : ListenerName(CONTROLLER) (kafka.network.SocketServer)
[2024-03-01 10:30:52,694] INFO [SharedServer id=1] Starting SharedServer (kafka.server.SharedServer)
[2024-03-01 10:30:52,742] INFO [LogLoader partition=__cluster_metadata-0, dir=/tmp/kraft-combined-logs] Recovering unflushed segment 0. 0/1 recovered for __cluster_metadata-0. (kafka.log.LogLoader)
[2024-03-01 10:30:52,743] INFO [LogLoader partition=__cluster_metadata-0, dir=/tmp/kraft-combined-logs] Loading producer state till offset 0 with message format version 2 (kafka.log.UnifiedLog$)
[2024-03-01 10:30:52,744] INFO [LogLoader partition=__cluster_metadata-0, dir=/tmp/kraft-combined-logs] Reloading from producer snapshot and rebuilding producer state from offset 0 (kafka.log.UnifiedLog$)
[2024-03-01 10:30:52,744] INFO Deleted producer state snapshot /tmp/kraft-combined-logs/__cluster_metadata-0/00000000000000000017.snapshot (org.apache.kafka.storage.internals.log.SnapshotFile)
[2024-03-01 10:30:52,744] INFO [LogLoader partition=__cluster_metadata-0, dir=/tmp/kraft-combined-logs] Producer state recovery took 0ms for snapshot load and 0ms for segment recovery from offset 0 (kafka.log.UnifiedLog$)
[2024-03-01 10:30:52,766] INFO [ProducerStateManager partition=__cluster_metadata-0]Wrote producer snapshot at offset 17 with 0 producer ids in 4 ms. (org.apache.kafka.storage.internals.log.ProducerStateManager)
[2024-03-01 10:30:52,777] INFO [LogLoader partition=__cluster_metadata-0, dir=/tmp/kraft-combined-logs] Loading producer state till offset 17 with message format version 2 (kafka.log.UnifiedLog$)
[2024-03-01 10:30:52,777] INFO [LogLoader partition=__cluster_metadata-0, dir=/tmp/kraft-combined-logs] Reloading from producer snapshot and rebuilding producer state from offset 17 (kafka.log.UnifiedLog$)
[2024-03-01 10:30:52,777] INFO [ProducerStateManager partition=__cluster_metadata-0]Loading producer state from snapshot file 'SnapshotFile(offset=17, file=/tmp/kraft-combined-logs/__cluster_metadata-0/00000000000000000017.snapshot)' (org.apache.kafka.storage.internals.log.ProducerStateManager)
[2024-03-01 10:30:52,778] INFO [LogLoader partition=__cluster_metadata-0, dir=/tmp/kraft-combined-logs] Producer state recovery took 1ms for snapshot load and 0ms for segment recovery from offset 17 (kafka.log.UnifiedLog$)
[2024-03-01 10:30:52,808] INFO Initialized snapshots with IDs Set() from /tmp/kraft-combined-logs/__cluster_metadata-0 (kafka.raft.KafkaMetadataLog$)
[2024-03-01 10:30:52,827] INFO [raft-expiration-reaper]: Starting (kafka.raft.TimingWheelExpirationService$ExpiredOperationReaper)
[2024-03-01 10:30:52,972] INFO [RaftManager id=1] Completed transition to ResignedState(localId=1, epoch=1, voters=[1], electionTimeoutMs=1567, unackedVoters=[], preferredSuccessors=[]) from null (org.apache.kafka.raft.QuorumState)
[2024-03-01 10:30:52,975] INFO [RaftManager id=1] Completed transition to CandidateState(localId=1, epoch=2, retries=1, voteStates={1=GRANTED}, highWatermark=Optional.empty, electionTimeoutMs=1776) from ResignedState(localId=1, epoch=1, voters=[1], electionTimeoutMs=1567, unackedVoters=[], preferredSuccessors=[]) (org.apache.kafka.raft.QuorumState)
[2024-03-01 10:30:52,979] INFO [RaftManager id=1] Completed transition to Leader(localId=1, epoch=2, epochStartOffset=17, highWatermark=Optional.empty, voterStates={1=ReplicaState(nodeId=1, endOffset=Optional.empty, lastFetchTimestamp=-1, lastCaughtUpTimestamp=-1, hasAcknowledgedLeader=true)}) from CandidateState(localId=1, epoch=2, retries=1, voteStates={1=GRANTED}, highWatermark=Optional.empty, electionTimeoutMs=1776) (org.apache.kafka.raft.QuorumState)
[2024-03-01 10:30:52,990] INFO [kafka-1-raft-outbound-request-thread]: Starting (kafka.raft.RaftSendThread)
[2024-03-01 10:30:52,990] INFO [kafka-1-raft-io-thread]: Starting (kafka.raft.KafkaRaftManager$RaftIoThread)
[2024-03-01 10:30:53,013] INFO [RaftManager id=1] High watermark set to LogOffsetMetadata(offset=18, metadata=Optional[(segmentBaseOffset=0,relativePositionInSegment=1237)]) for the first time for epoch 2 based on indexOfHw 0 and voters [ReplicaState(nodeId=1, endOffset=Optional[LogOffsetMetadata(offset=18, metadata=Optional[(segmentBaseOffset=0,relativePositionInSegment=1237)])], lastFetchTimestamp=-1, lastCaughtUpTimestamp=-1, hasAcknowledgedLeader=true)] (org.apache.kafka.raft.LeaderState)
[2024-03-01 10:30:53,014] INFO [MetadataLoader id=1] initializeNewPublishers: The loader is still catching up because we have loaded up to offset -1, but the high water mark is 18 (org.apache.kafka.image.loader.MetadataLoader)
[2024-03-01 10:30:53,015] INFO [ControllerServer id=1] Waiting for controller quorum voters future (kafka.server.ControllerServer)
[2024-03-01 10:30:53,016] INFO [ControllerServer id=1] Finished waiting for controller quorum voters future (kafka.server.ControllerServer)
[2024-03-01 10:30:53,026] INFO [RaftManager id=1] Registered the listener org.apache.kafka.image.loader.MetadataLoader@1516470837 (org.apache.kafka.raft.KafkaRaftClient)
[2024-03-01 10:30:53,034] INFO [MetadataLoader id=1] maybePublishMetadata(LOG_DELTA): The loader is still catching up because we have loaded up to offset 0, but the high water mark is 18 (org.apache.kafka.image.loader.MetadataLoader)
[2024-03-01 10:30:53,045] INFO [MetadataLoader id=1] maybePublishMetadata(LOG_DELTA): The loader finished catching up to the current high water mark of 18 (org.apache.kafka.image.loader.MetadataLoader)
[2024-03-01 10:30:53,048] INFO [QuorumController id=1] Creating new QuorumController with clusterId uz_bu6KaRriLjudbKZTsaQ. (org.apache.kafka.controller.QuorumController)
[2024-03-01 10:30:53,049] INFO [RaftManager id=1] Registered the listener org.apache.kafka.controller.QuorumController$QuorumMetaLogListener@1201137727 (org.apache.kafka.raft.KafkaRaftClient)
[2024-03-01 10:30:53,051] INFO [QuorumController id=1] Replayed BeginTransactionRecord(name='Bootstrap records') at offset 1. (org.apache.kafka.controller.OffsetControlManager)
[2024-03-01 10:30:53,051] INFO [QuorumController id=1] Replayed a FeatureLevelRecord setting metadata version to 3.6-IV2 (org.apache.kafka.controller.FeatureControlManager)
[2024-03-01 10:30:53,051] INFO [QuorumController id=1] Replayed EndTransactionRecord() at offset 4. (org.apache.kafka.controller.OffsetControlManager)
[2024-03-01 10:30:53,053] INFO [QuorumController id=1] Replayed initial RegisterBrokerRecord for broker 1: RegisterBrokerRecord(brokerId=1, isMigratingZkBroker=false, incarnationId=gS6KIxlJTvWKMY8IdGLXfg, brokerEpoch=6, endPoints=[BrokerEndpoint(name='SSL', host='localhost', port=9092, securityProtocol=1)], features=[BrokerFeature(name='metadata.version', minSupportedVersion=1, maxSupportedVersion=14)], rack=null, fenced=true, inControlledShutdown=false) (org.apache.kafka.controller.ClusterControlManager)
[2024-03-01 10:30:53,053] INFO [QuorumController id=1] Replayed BrokerRegistrationChangeRecord modifying the registration for broker 1: BrokerRegistrationChangeRecord(brokerId=1, brokerEpoch=6, fenced=-1, inControlledShutdown=0) (org.apache.kafka.controller.ClusterControlManager)
[2024-03-01 10:30:53,054] INFO [controller-1-ThrottledChannelReaper-Fetch]: Starting (kafka.server.ClientQuotaManager$ThrottledChannelReaper)
[2024-03-01 10:30:53,055] INFO [QuorumController id=1] Replayed BrokerRegistrationChangeRecord modifying the registration for broker 1: BrokerRegistrationChangeRecord(brokerId=1, brokerEpoch=6, fenced=1, inControlledShutdown=0) (org.apache.kafka.controller.ClusterControlManager)
[2024-03-01 10:30:53,055] INFO [QuorumController id=1] Becoming the active controller at epoch 2, next write offset 18. (org.apache.kafka.controller.QuorumController)
[2024-03-01 10:30:53,055] INFO [controller-1-ThrottledChannelReaper-Produce]: Starting (kafka.server.ClientQuotaManager$ThrottledChannelReaper)
[2024-03-01 10:30:53,056] INFO [controller-1-ThrottledChannelReaper-Request]: Starting (kafka.server.ClientQuotaManager$ThrottledChannelReaper)
[2024-03-01 10:30:53,057] INFO [controller-1-ThrottledChannelReaper-ControllerMutation]: Starting (kafka.server.ClientQuotaManager$ThrottledChannelReaper)
[2024-03-01 10:30:53,059] WARN [QuorumController id=1] Performing controller activation. Loaded ZK migration state of NONE. (org.apache.kafka.controller.QuorumController)
[2024-03-01 10:30:53,072] INFO [ExpirationReaper-1-AlterAcls]: Starting (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper)
[2024-03-01 10:30:53,079] INFO [ControllerServer id=1] Waiting for the controller metadata publishers to be installed (kafka.server.ControllerServer)
[2024-03-01 10:30:53,079] INFO [ControllerServer id=1] Finished waiting for the controller metadata publishers to be installed (kafka.server.ControllerServer)
[2024-03-01 10:30:53,080] INFO [SocketServer listenerType=CONTROLLER, nodeId=1] Enabling request processing. (kafka.network.SocketServer)
[2024-03-01 10:30:53,082] INFO [MetadataLoader id=1] InitializeNewPublishers: initializing SnapshotGenerator with a snapshot at offset 17 (org.apache.kafka.image.loader.MetadataLoader)
[2024-03-01 10:30:53,082] INFO [MetadataLoader id=1] InitializeNewPublishers: initializing FeaturesPublisher with a snapshot at offset 17 (org.apache.kafka.image.loader.MetadataLoader)
[2024-03-01 10:30:53,083] INFO Awaiting socket connections on 0.0.0.0:9093. (kafka.network.DataPlaneAcceptor)
[2024-03-01 10:30:53,087] INFO [MetadataLoader id=1] InitializeNewPublishers: initializing DynamicConfigPublisher controller id=1 with a snapshot at offset 17 (org.apache.kafka.image.loader.MetadataLoader)
[2024-03-01 10:30:53,090] INFO [MetadataLoader id=1] InitializeNewPublishers: initializing DynamicClientQuotaPublisher controller id=1 with a snapshot at offset 17 (org.apache.kafka.image.loader.MetadataLoader)
[2024-03-01 10:30:53,091] INFO [MetadataLoader id=1] InitializeNewPublishers: initializing ScramPublisher controller id=1 with a snapshot at offset 17 (org.apache.kafka.image.loader.MetadataLoader)
[2024-03-01 10:30:53,092] INFO [MetadataLoader id=1] InitializeNewPublishers: initializing DelegationTokenPublisher controller id=1 with a snapshot at offset 17 (org.apache.kafka.image.loader.MetadataLoader)
[2024-03-01 10:30:53,093] INFO [MetadataLoader id=1] InitializeNewPublishers: initializing ControllerMetadataMetricsPublisher with a snapshot at offset 17 (org.apache.kafka.image.loader.MetadataLoader)
[2024-03-01 10:30:53,093] INFO [MetadataLoader id=1] InitializeNewPublishers: initializing AclPublisher controller id=1 with a snapshot at offset 17 (org.apache.kafka.image.loader.MetadataLoader)
[2024-03-01 10:30:53,098] INFO [ControllerServer id=1] Waiting for all of the authorizer futures to be completed (kafka.server.ControllerServer)
[2024-03-01 10:30:53,098] INFO [ControllerServer id=1] Finished waiting for all of the authorizer futures to be completed (kafka.server.ControllerServer)
[2024-03-01 10:30:53,098] INFO [ControllerServer id=1] Waiting for all of the SocketServer Acceptors to be started (kafka.server.ControllerServer)
[2024-03-01 10:30:53,098] INFO [ControllerServer id=1] Finished waiting for all of the SocketServer Acceptors to be started (kafka.server.ControllerServer)
[2024-03-01 10:30:53,100] INFO [BrokerServer id=1] Transition from SHUTDOWN to STARTING (kafka.server.BrokerServer)
[2024-03-01 10:30:53,100] INFO [BrokerServer id=1] Starting broker (kafka.server.BrokerServer)
[2024-03-01 10:30:53,109] INFO [broker-1-ThrottledChannelReaper-Fetch]: Starting (kafka.server.ClientQuotaManager$ThrottledChannelReaper)
[2024-03-01 10:30:53,109] INFO [broker-1-ThrottledChannelReaper-Produce]: Starting (kafka.server.ClientQuotaManager$ThrottledChannelReaper)
[2024-03-01 10:30:53,109] INFO [broker-1-ThrottledChannelReaper-Request]: Starting (kafka.server.ClientQuotaManager$ThrottledChannelReaper)
[2024-03-01 10:30:53,110] INFO [broker-1-ThrottledChannelReaper-ControllerMutation]: Starting (kafka.server.ClientQuotaManager$ThrottledChannelReaper)
[2024-03-01 10:30:53,123] INFO [BrokerServer id=1] Waiting for controller quorum voters future (kafka.server.BrokerServer)
[2024-03-01 10:30:53,123] INFO [BrokerServer id=1] Finished waiting for controller quorum voters future (kafka.server.BrokerServer)
[2024-03-01 10:30:53,128] INFO [broker-1-to-controller-forwarding-channel-manager]: Starting (kafka.server.BrokerToControllerRequestThread)
[2024-03-01 10:30:53,129] INFO [broker-1-to-controller-forwarding-channel-manager]: Recorded new controller, from now on will use node localhost:9093 (id: 1 rack: null) (kafka.server.BrokerToControllerRequestThread)
[2024-03-01 10:30:53,169] INFO Updated connection-accept-rate max connection creation rate to 2147483647 (kafka.network.ConnectionQuotas)
[2024-03-01 10:30:53,675] INFO [SocketServer listenerType=BROKER, nodeId=1] Created data-plane acceptor and processors for endpoint : ListenerName(SSL) (kafka.network.SocketServer)
[2024-03-01 10:30:53,680] INFO [broker-1-to-controller-alter-partition-channel-manager]: Starting (kafka.server.BrokerToControllerRequestThread)
[2024-03-01 10:30:53,680] INFO [broker-1-to-controller-alter-partition-channel-manager]: Recorded new controller, from now on will use node localhost:9093 (id: 1 rack: null) (kafka.server.BrokerToControllerRequestThread)
[2024-03-01 10:30:53,711] INFO [ExpirationReaper-1-Produce]: Starting (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper)
[2024-03-01 10:30:53,723] INFO [ExpirationReaper-1-Fetch]: Starting (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper)
[2024-03-01 10:30:53,723] INFO [ExpirationReaper-1-DeleteRecords]: Starting (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper)
[2024-03-01 10:30:53,745] INFO [ExpirationReaper-1-RemoteFetch]: Starting (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper)
[2024-03-01 10:30:53,755] INFO [ExpirationReaper-1-ElectLeader]: Starting (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper)
[2024-03-01 10:30:53,759] INFO [ExpirationReaper-1-Heartbeat]: Starting (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper)
[2024-03-01 10:30:53,760] INFO [ExpirationReaper-1-Rebalance]: Starting (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper)
[2024-03-01 10:30:53,802] INFO [BrokerLifecycleManager id=1] Incarnation aXlqUkpZRcW174tUagHgHQ of broker 1 in cluster uz_bu6KaRriLjudbKZTsaQ is now STARTING. (kafka.server.BrokerLifecycleManager)
[2024-03-01 10:30:53,803] INFO [broker-1-to-controller-heartbeat-channel-manager]: Starting (kafka.server.BrokerToControllerRequestThread)
[2024-03-01 10:30:53,803] INFO [broker-1-to-controller-heartbeat-channel-manager]: Recorded new controller, from now on will use node localhost:9093 (id: 1 rack: null) (kafka.server.BrokerToControllerRequestThread)
[2024-03-01 10:30:53,832] INFO [ExpirationReaper-1-AlterAcls]: Starting (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper)
[2024-03-01 10:30:53,881] INFO [QuorumController id=1] Replayed RegisterBrokerRecord establishing a new incarnation of broker 1: RegisterBrokerRecord(brokerId=1, isMigratingZkBroker=false, incarnationId=aXlqUkpZRcW174tUagHgHQ, brokerEpoch=19, endPoints=[BrokerEndpoint(name='SSL', host='localhost', port=9092, securityProtocol=1)], features=[BrokerFeature(name='metadata.version', minSupportedVersion=1, maxSupportedVersion=14)], rack=null, fenced=true, inControlledShutdown=false) (org.apache.kafka.controller.ClusterControlManager)
[2024-03-01 10:30:53,882] INFO [BrokerServer id=1] Waiting for the broker metadata publishers to be installed (kafka.server.BrokerServer)
[2024-03-01 10:30:53,883] INFO [BrokerServer id=1] Finished waiting for the broker metadata publishers to be installed (kafka.server.BrokerServer)
[2024-03-01 10:30:53,883] INFO [BrokerServer id=1] Waiting for the controller to acknowledge that we are caught up (kafka.server.BrokerServer)
[2024-03-01 10:30:53,883] INFO [MetadataLoader id=1] InitializeNewPublishers: initializing BrokerMetadataPublisher with a snapshot at offset 18 (org.apache.kafka.image.loader.MetadataLoader)
[2024-03-01 10:30:53,884] INFO [BrokerMetadataPublisher id=1] Publishing initial metadata at offset OffsetAndEpoch(offset=18, epoch=2) with metadata.version 3.6-IV2. (kafka.server.metadata.BrokerMetadataPublisher)
[2024-03-01 10:30:53,884] INFO Loading logs from log dirs ArrayBuffer(/tmp/kraft-combined-logs) (kafka.log.LogManager)
[2024-03-01 10:30:53,888] INFO No logs found to be loaded in /tmp/kraft-combined-logs (kafka.log.LogManager)
[2024-03-01 10:30:53,899] INFO Loaded 0 logs in 14ms (kafka.log.LogManager)
[2024-03-01 10:30:53,899] INFO Starting log cleanup with a period of 300000 ms. (kafka.log.LogManager)
[2024-03-01 10:30:53,900] INFO Starting log flusher with a default period of 9223372036854775807 ms. (kafka.log.LogManager)
[2024-03-01 10:30:53,915] INFO [BrokerLifecycleManager id=1] Successfully registered broker 1 with broker epoch 19 (kafka.server.BrokerLifecycleManager)
[2024-03-01 10:30:53,922] INFO Starting the log cleaner (kafka.log.LogCleaner)
[2024-03-01 10:30:53,943] INFO [kafka-log-cleaner-thread-0]: Starting (kafka.log.LogCleaner$CleanerThread)
[2024-03-01 10:30:53,947] INFO [LogDirFailureHandler]: Starting (kafka.server.ReplicaManager$LogDirFailureHandler)
[2024-03-01 10:30:53,948] INFO [GroupCoordinator 1]: Starting up. (kafka.coordinator.group.GroupCoordinator)
[2024-03-01 10:30:53,949] INFO [AddPartitionsToTxnSenderThread-1]: Starting (kafka.server.AddPartitionsToTxnManager)
[2024-03-01 10:30:53,950] INFO [GroupCoordinator 1]: Startup complete. (kafka.coordinator.group.GroupCoordinator)
[2024-03-01 10:30:53,951] INFO [TransactionCoordinator id=1] Starting up. (kafka.coordinator.transaction.TransactionCoordinator)
[2024-03-01 10:30:53,953] INFO [TxnMarkerSenderThread-1]: Starting (kafka.coordinator.transaction.TransactionMarkerChannelManager)
[2024-03-01 10:30:53,953] INFO [TransactionCoordinator id=1] Startup complete. (kafka.coordinator.transaction.TransactionCoordinator)
[2024-03-01 10:30:53,954] INFO [BrokerMetadataPublisher id=1] Updating metadata.version to 14 at offset OffsetAndEpoch(offset=18, epoch=2). (kafka.server.metadata.BrokerMetadataPublisher)
[2024-03-01 10:30:53,982] INFO [BrokerLifecycleManager id=1] The broker has caught up. Transitioning from STARTING to RECOVERY. (kafka.server.BrokerLifecycleManager)
[2024-03-01 10:30:53,982] INFO [BrokerServer id=1] Finished waiting for the controller to acknowledge that we are caught up (kafka.server.BrokerServer)
[2024-03-01 10:30:53,982] INFO [BrokerServer id=1] Waiting for the initial broker metadata update to be published (kafka.server.BrokerServer)
[2024-03-01 10:30:53,982] INFO [BrokerServer id=1] Finished waiting for the initial broker metadata update to be published (kafka.server.BrokerServer)
[2024-03-01 10:30:53,984] INFO KafkaConfig values:
advertised.listeners = SSL://localhost:9092
alter.config.policy.class.name = null
alter.log.dirs.replication.quota.window.num = 11
alter.log.dirs.replication.quota.window.size.seconds = 1
authorizer.class.name =
auto.create.topics.enable = true
auto.include.jmx.reporter = true
auto.leader.rebalance.enable = true
background.threads = 10
broker.heartbeat.interval.ms = 2000
broker.id = 1
broker.id.generation.enable = true
broker.rack = null
broker.session.timeout.ms = 9000
client.quota.callback.class = null
compression.type = producer
connection.failed.authentication.delay.ms = 100
connections.max.idle.ms = 600000
connections.max.reauth.ms = 0
control.plane.listener.name = null
controlled.shutdown.enable = true
controlled.shutdown.max.retries = 3
controlled.shutdown.retry.backoff.ms = 5000
controller.listener.names = CONTROLLER
controller.quorum.append.linger.ms = 25
controller.quorum.election.backoff.max.ms = 1000
controller.quorum.election.timeout.ms = 1000
controller.quorum.fetch.timeout.ms = 2000
controller.quorum.request.timeout.ms = 2000
controller.quorum.retry.backoff.ms = 20
controller.quorum.voters = [1@localhost:9093]
controller.quota.window.num = 11
controller.quota.window.size.seconds = 1
controller.socket.timeout.ms = 30000
create.topic.policy.class.name = null
default.replication.factor = 1
delegation.token.expiry.check.interval.ms = 3600000
delegation.token.expiry.time.ms = 86400000
delegation.token.master.key = null
delegation.token.max.lifetime.ms = 604800000
delegation.token.secret.key = null
delete.records.purgatory.purge.interval.requests = 1
delete.topic.enable = true
early.start.listeners = null
fetch.max.bytes = 57671680
fetch.purgatory.purge.interval.requests = 1000
group.consumer.assignors = [org.apache.kafka.coordinator.group.assignor.RangeAssignor]
group.consumer.heartbeat.interval.ms = 5000
group.consumer.max.heartbeat.interval.ms = 15000
group.consumer.max.session.timeout.ms = 60000
group.consumer.max.size = 2147483647
group.consumer.min.heartbeat.interval.ms = 5000
group.consumer.min.session.timeout.ms = 45000
group.consumer.session.timeout.ms = 45000
group.coordinator.new.enable = false
group.coordinator.threads = 1
group.initial.rebalance.delay.ms = 3000
group.max.session.timeout.ms = 1800000
group.max.size = 2147483647
group.min.session.timeout.ms = 6000
initial.broker.registration.timeout.ms = 60000
inter.broker.listener.name = null
inter.broker.protocol.version = 3.6-IV2
kafka.metrics.polling.interval.secs = 10
kafka.metrics.reporters = []
leader.imbalance.check.interval.seconds = 300
leader.imbalance.per.broker.percentage = 10
listener.security.protocol.map = CONTROLLER:PLAINTEXT,PLAINTEXT:PLAINTEXT,SSL:SSL,SASL_PLAINTEXT:SASL_PLAINTEXT,SASL_SSL:SASL_SSL
listeners = SSL://:9092,CONTROLLER://:9093
log.cleaner.backoff.ms = 15000
log.cleaner.dedupe.buffer.size = 134217728
log.cleaner.delete.retention.ms = 86400000
log.cleaner.enable = true
log.cleaner.io.buffer.load.factor = 0.9
log.cleaner.io.buffer.size = 524288
log.cleaner.io.max.bytes.per.second = 1.7976931348623157E308
log.cleaner.max.compaction.lag.ms = 9223372036854775807
log.cleaner.min.cleanable.ratio = 0.5
log.cleaner.min.compaction.lag.ms = 0
log.cleaner.threads = 1
log.cleanup.policy = [delete]
log.dir = /tmp/kafka-logs
log.dirs = /tmp/kraft-combined-logs
log.flush.interval.messages = 9223372036854775807
log.flush.interval.ms = null
log.flush.offset.checkpoint.interval.ms = 60000
log.flush.scheduler.interval.ms = 9223372036854775807
log.flush.start.offset.checkpoint.interval.ms = 60000
log.index.interval.bytes = 4096
log.index.size.max.bytes = 10485760
log.local.retention.bytes = -2
log.local.retention.ms = -2
log.message.downconversion.enable = true
log.message.format.version = 3.0-IV1
log.message.timestamp.after.max.ms = 9223372036854775807
log.message.timestamp.before.max.ms = 9223372036854775807
log.message.timestamp.difference.max.ms = 9223372036854775807
log.message.timestamp.type = CreateTime
log.preallocate = false
log.retention.bytes = -1
log.retention.check.interval.ms = 300000
log.retention.hours = 168
log.retention.minutes = null
log.retention.ms = null
log.roll.hours = 168
log.roll.jitter.hours = 0
log.roll.jitter.ms = null
log.roll.ms = null
log.segment.bytes = 1073741824
log.segment.delete.delay.ms = 60000
max.connection.creation.rate = 2147483647
max.connections = 2147483647
max.connections.per.ip = 2147483647
max.connections.per.ip.overrides =
max.incremental.fetch.session.cache.slots = 1000
message.max.bytes = 1048588
metadata.log.dir = null
metadata.log.max.record.bytes.between.snapshots = 20971520
metadata.log.max.snapshot.interval.ms = 3600000
metadata.log.segment.bytes = 1073741824
metadata.log.segment.min.bytes = 8388608
metadata.log.segment.ms = 604800000
metadata.max.idle.interval.ms = 500
metadata.max.retention.bytes = 104857600
metadata.max.retention.ms = 604800000
metric.reporters = []
metrics.num.samples = 2
metrics.recording.level = INFO
metrics.sample.window.ms = 30000
min.insync.replicas = 1
node.id = 1
num.io.threads = 8
num.network.threads = 3
num.partitions = 1
num.recovery.threads.per.data.dir = 1
num.replica.alter.log.dirs.threads = null
num.replica.fetchers = 1
offset.metadata.max.bytes = 4096
offsets.commit.required.acks = -1
offsets.commit.timeout.ms = 5000
offsets.load.buffer.size = 5242880
offsets.retention.check.interval.ms = 600000
offsets.retention.minutes = 10080
offsets.topic.compression.codec = 0
offsets.topic.num.partitions = 50
offsets.topic.replication.factor = 1
offsets.topic.segment.bytes = 104857600
password.encoder.cipher.algorithm = AES/CBC/PKCS5Padding
password.encoder.iterations = 4096
password.encoder.key.length = 128
password.encoder.keyfactory.algorithm = null
password.encoder.old.secret = null
password.encoder.secret = null
principal.builder.class = class org.apache.kafka.common.security.authenticator.DefaultKafkaPrincipalBuilder
process.roles = [broker, controller]
producer.id.expiration.check.interval.ms = 600000
producer.id.expiration.ms = 86400000
producer.purgatory.purge.interval.requests = 1000
queued.max.request.bytes = -1
queued.max.requests = 500
quota.window.num = 11
quota.window.size.seconds = 1
remote.log.index.file.cache.total.size.bytes = 1073741824
remote.log.manager.task.interval.ms = 30000
remote.log.manager.task.retry.backoff.max.ms = 30000
remote.log.manager.task.retry.backoff.ms = 500
remote.log.manager.task.retry.jitter = 0.2
remote.log.manager.thread.pool.size = 10
remote.log.metadata.custom.metadata.max.bytes = 128
remote.log.metadata.manager.class.name = org.apache.kafka.server.log.remote.metadata.storage.TopicBasedRemoteLogMetadataManager
remote.log.metadata.manager.class.path = null
remote.log.metadata.manager.impl.prefix = rlmm.config.
remote.log.metadata.manager.listener.name = null
remote.log.reader.max.pending.tasks = 100
remote.log.reader.threads = 10
remote.log.storage.manager.class.name = null
remote.log.storage.manager.class.path = null
remote.log.storage.manager.impl.prefix = rsm.config.
remote.log.storage.system.enable = false
replica.fetch.backoff.ms = 1000
replica.fetch.max.bytes = 1048576
replica.fetch.min.bytes = 1
replica.fetch.response.max.bytes = 10485760
replica.fetch.wait.max.ms = 500
replica.high.watermark.checkpoint.interval.ms = 5000
replica.lag.time.max.ms = 30000
replica.selector.class = null
replica.socket.receive.buffer.bytes = 65536
replica.socket.timeout.ms = 30000
replication.quota.window.num = 11
replication.quota.window.size.seconds = 1
request.timeout.ms = 30000
reserved.broker.max.id = 1000
sasl.client.callback.handler.class = null
sasl.enabled.mechanisms = [GSSAPI]
sasl.jaas.config = null
sasl.kerberos.kinit.cmd = /usr/bin/kinit
sasl.kerberos.min.time.before.relogin = 60000
sasl.kerberos.principal.to.local.rules = [DEFAULT]
sasl.kerberos.service.name = null
sasl.kerberos.ticket.renew.jitter = 0.05
sasl.kerberos.ticket.renew.window.factor = 0.8
sasl.login.callback.handler.class = null
sasl.login.class = null
sasl.login.connect.timeout.ms = null
sasl.login.read.timeout.ms = null
sasl.login.refresh.buffer.seconds = 300
sasl.login.refresh.min.period.seconds = 60
sasl.login.refresh.window.factor = 0.8
sasl.login.refresh.window.jitter = 0.05
sasl.login.retry.backoff.max.ms = 10000
sasl.login.retry.backoff.ms = 100
sasl.mechanism.controller.protocol = GSSAPI
sasl.mechanism.inter.broker.protocol = GSSAPI
sasl.oauthbearer.clock.skew.seconds = 30
sasl.oauthbearer.expected.audience = null
sasl.oauthbearer.expected.issuer = null
sasl.oauthbearer.jwks.endpoint.refresh.ms = 3600000
sasl.oauthbearer.jwks.endpoint.retry.backoff.max.ms = 10000
sasl.oauthbearer.jwks.endpoint.retry.backoff.ms = 100
sasl.oauthbearer.jwks.endpoint.url = null
sasl.oauthbearer.scope.claim.name = scope
sasl.oauthbearer.sub.claim.name = sub
sasl.oauthbearer.token.endpoint.url = null
sasl.server.callback.handler.class = null
sasl.server.max.receive.size = 524288
security.inter.broker.protocol = SSL
security.providers = null
server.max.startup.time.ms = 9223372036854775807
socket.connection.setup.timeout.max.ms = 30000
socket.connection.setup.timeout.ms = 10000
socket.listen.backlog.size = 50
socket.receive.buffer.bytes = 102400
socket.request.max.bytes = 104857600
socket.send.buffer.bytes = 102400
ssl.cipher.suites = []
ssl.client.auth = none
ssl.enabled.protocols = [TLSv1.2, TLSv1.3]
ssl.endpoint.identification.algorithm =
ssl.engine.factory.class = null
ssl.key.password = [hidden]
ssl.keymanager.algorithm = SunX509
ssl.keystore.certificate.chain = null
ssl.keystore.key = null
ssl.keystore.location = /opt/bitnami/kafka/config/certs/keystore.pem
ssl.keystore.password = null
ssl.keystore.type = PEM
ssl.principal.mapping.rules = DEFAULT
ssl.protocol = TLSv1.3
ssl.provider = null
ssl.secure.random.implementation = null
ssl.trustmanager.algorithm = PKIX
ssl.truststore.certificates = null
ssl.truststore.location = /opt/bitnami/kafka/config/certs/CA.pem
ssl.truststore.password = null
ssl.truststore.type = PEM
transaction.abort.timed.out.transaction.cleanup.interval.ms = 10000
transaction.max.timeout.ms = 900000
transaction.partition.verification.enable = true
transaction.remove.expired.transaction.cleanup.interval.ms = 3600000
transaction.state.log.load.buffer.size = 5242880
transaction.state.log.min.isr = 1
transaction.state.log.num.partitions = 50
transaction.state.log.replication.factor = 1
transaction.state.log.segment.bytes = 104857600
transactional.id.expiration.ms = 604800000
unclean.leader.election.enable = false
unstable.api.versions.enable = false
zookeeper.clientCnxnSocket = null
zookeeper.connect = null
zookeeper.connection.timeout.ms = null
zookeeper.max.in.flight.requests = 10
zookeeper.metadata.migration.enable = false
zookeeper.session.timeout.ms = 18000
zookeeper.set.acl = false
zookeeper.ssl.cipher.suites = null
zookeeper.ssl.client.enable = false
zookeeper.ssl.crl.enable = false
zookeeper.ssl.enabled.protocols = null
zookeeper.ssl.endpoint.identification.algorithm = HTTPS
zookeeper.ssl.keystore.location = null
zookeeper.ssl.keystore.password = null
zookeeper.ssl.keystore.type = null
zookeeper.ssl.ocsp.enable = false
zookeeper.ssl.protocol = TLSv1.2
zookeeper.ssl.truststore.location = null
zookeeper.ssl.truststore.password = null
zookeeper.ssl.truststore.type = null
(kafka.server.KafkaConfig)
[2024-03-01 10:30:53,990] INFO [BrokerServer id=1] Waiting for the broker to be unfenced (kafka.server.BrokerServer)
[2024-03-01 10:30:53,991] INFO [QuorumController id=1] The request from broker 1 to unfence has been granted because it has caught up with the offset of its register broker record 19. (org.apache.kafka.controller.BrokerHeartbeatManager)
[2024-03-01 10:30:53,993] INFO [QuorumController id=1] Replayed BrokerRegistrationChangeRecord modifying the registration for broker 1: BrokerRegistrationChangeRecord(brokerId=1, brokerEpoch=19, fenced=-1, inControlledShutdown=0) (org.apache.kafka.controller.ClusterControlManager)
[2024-03-01 10:30:54,021] INFO [BrokerLifecycleManager id=1] The broker has been unfenced. Transitioning from RECOVERY to RUNNING. (kafka.server.BrokerLifecycleManager)
[2024-03-01 10:30:54,021] INFO [BrokerServer id=1] Finished waiting for the broker to be unfenced (kafka.server.BrokerServer)
[2024-03-01 10:30:54,022] INFO authorizerStart completed for endpoint SSL. Endpoint is now READY. (org.apache.kafka.server.network.EndpointReadyFutures)
[2024-03-01 10:30:54,022] INFO [SocketServer listenerType=BROKER, nodeId=1] Enabling request processing. (kafka.network.SocketServer)
[2024-03-01 10:30:54,022] INFO Awaiting socket connections on 0.0.0.0:9092. (kafka.network.DataPlaneAcceptor)
[2024-03-01 10:30:54,023] INFO [BrokerServer id=1] Waiting for all of the authorizer futures to be completed (kafka.server.BrokerServer)
[2024-03-01 10:30:54,023] INFO [BrokerServer id=1] Finished waiting for all of the authorizer futures to be completed (kafka.server.BrokerServer)
[2024-03-01 10:30:54,023] INFO [BrokerServer id=1] Waiting for all of the SocketServer Acceptors to be started (kafka.server.BrokerServer)
[2024-03-01 10:30:54,023] INFO [BrokerServer id=1] Finished waiting for all of the SocketServer Acceptors to be started (kafka.server.BrokerServer)
[2024-03-01 10:30:54,023] INFO [BrokerServer id=1] Transition from STARTING to STARTED (kafka.server.BrokerServer)
[2024-03-01 10:30:54,024] INFO Kafka version: 3.6.1 (org.apache.kafka.common.utils.AppInfoParser)
[2024-03-01 10:30:54,024] INFO Kafka commitId: 5e3c2b738d253ff5 (org.apache.kafka.common.utils.AppInfoParser)
[2024-03-01 10:30:54,024] INFO Kafka startTimeMs: 1709289054023 (org.apache.kafka.common.utils.AppInfoParser)
[2024-03-01 10:30:54,025] INFO [KafkaRaftServer nodeId=1] Kafka Server started (kafka.server.KafkaRaftServer)
[2024-03-01 10:54:25,228] INFO [SocketServer listenerType=BROKER, nodeId=1] Failed authentication with /127.0.0.1 (channelId=127.0.0.1:9092-127.0.0.1:53984-0) (SSL handshake failed) (org.apache.kafka.common.network.Selector)
[2024-03-01 10:54:25,387] INFO [SocketServer listenerType=BROKER, nodeId=1] Failed authentication with /127.0.0.1 (channelId=127.0.0.1:9092-127.0.0.1:53998-0) (SSL handshake failed) (org.apache.kafka.common.network.Selector)
[2024-03-01 10:54:25,805] INFO [SocketServer listenerType=BROKER, nodeId=1] Failed authentication with /127.0.0.1 (channelId=127.0.0.1:9092-127.0.0.1:54010-0) (SSL handshake failed) (org.apache.kafka.common.network.Selector)
