[
https://issues.apache.org/jira/browse/KAFKA-17254?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Krishna V Reddy resolved KAFKA-17254.
-------------------------------------
Assignee: Krishna V Reddy
Resolution: Not A Problem
> Kafka Server/CLI no longer respects log4j.properties/tools-log4j.properties
> file
> --------------------------------------------------------------------------------
>
> Key: KAFKA-17254
> URL: https://issues.apache.org/jira/browse/KAFKA-17254
> Project: Kafka
> Issue Type: Bug
> Components: admin, logging, tools
> Affects Versions: 3.8.0, 3.7.1
> Reporter: Krishna V Reddy
> Assignee: Krishna V Reddy
> Priority: Major
> Attachments: 螢幕快照 2024-08-05 10-55-02.png
>
>
> Kafka CLI tools and Kafka server for that matter no longer seem to respect
> *KAFKA_LOG4J_OPTS* environment variable starting from v3.7.1 in Kraft mode
> and seems to always log data to console. This regression only started
> happening from 3.7.1 as rolling back to 3.7.0 fixes this issue.
> Here's an example where we list kafka topics using kafka CLI tool in v3.7.1:
> {code:java}
> bash-4.4$ bin/kafka-topics.sh --list --bootstrap-server localhost:21503
> --command-config /tmp/kafka/config/kraft/client.properties
> 00:11:29.415 [main] INFO org.apache.kafka.clients.admin.AdminClientConfig --
> AdminClientConfig values:
> auto.include.jmx.reporter = true
> bootstrap.controllers = []
> bootstrap.servers = [localhost:21503]
> ...
> hello-world # Actual topic output
> 00:11:29.960 [main] DEBUG org.apache.kafka.clients.admin.KafkaAdminClient --
> [AdminClient clientId=adminclient-1] Initiating close operation.
> 00:11:29.960 [main] DEBUG org.apache.kafka.clients.admin.KafkaAdminClient --
> [AdminClient clientId=adminclient-1] Waiting for the I/O thread to exit. Hard
> shutdown in 31536000000 ms.
> 00:11:29.961 [kafka-admin-client-thread | adminclient-1] INFO
> org.apache.kafka.common.utils.AppInfoParser -- App info kafka.admin.client
> for adminclient-1 unregistered
> 00:11:29.967 [kafka-admin-client-thread | adminclient-1] INFO
> org.apache.kafka.common.metrics.Metrics -- Metrics scheduler closed
> 00:11:29.967 [kafka-admin-client-thread | adminclient-1] INFO
> org.apache.kafka.common.metrics.Metrics -- Closing reporter
> org.apache.kafka.common.metrics.JmxReporter
> 00:11:29.967 [kafka-admin-client-thread | adminclient-1] INFO
> org.apache.kafka.common.metrics.Metrics -- Metrics reporters closed
> 00:11:29.967 [kafka-admin-client-thread | adminclient-1] DEBUG
> org.apache.kafka.clients.admin.KafkaAdminClient -- [AdminClient
> clientId=adminclient-1] Exiting AdminClientRunnable thread.
> 00:11:29.968 [main] DEBUG org.apache.kafka.clients.admin.KafkaAdminClient --
> [AdminClient clientId=adminclient-1] Kafka admin client closed. {code}
> Running the same command in v3.7.0 gets us:
> {code:java}
> bash-4.4$ bin/kafka-topics.sh --list --bootstrap-server localhost:21503
> --command-config /tmp/kafka/config/kraft/client.properties
> hello-world{code}
> I added logging in *kafka-run-class.sh* to make sure the correct log4j
> properties file is being selected and sure enough the default pre-packaged
> *config/tools-log4j.properties* is selected by this script and the
> environment variable *KAFKA_LOG4J_OPTS* is set with this properties file:
> {code:java}
> # Log4j settings
> if [ -z "$KAFKA_LOG4J_OPTS" ]; then
> # Log to console. This is a tool.
> LOG4J_DIR="$base_dir/config/tools-log4j.properties"
> # If Cygwin is detected, LOG4J_DIR is converted to Windows format.
> (( WINDOWS_OS_FORMAT )) && LOG4J_DIR=$(cygpath --path --mixed
> "${LOG4J_DIR}")
> KAFKA_LOG4J_OPTS="-Dlog4j.configuration=file:${LOG4J_DIR}"
> else
> # create logs directory
> if [ ! -d "$LOG_DIR" ]; then
> mkdir -p "$LOG_DIR"
> fi
> fi{code}
> The *config/tools-log4j.properties* used in both 3.7.0 and 3.7.1 is the same
> and contains the following contents(Kafka set defaults):
> {code:java}
> log4j.rootLogger=WARN, stderr
> log4j.appender.stderr=org.apache.log4j.ConsoleAppender
> log4j.appender.stderr.layout=org.apache.log4j.PatternLayout
> log4j.appender.stderr.layout.ConversionPattern=[%d] %p %m (%c)%n
> log4j.appender.stderr.Target=System.err
> # for connect-plugin-path
> log4j.logger.org.reflections=ERROR{code}
> This is a very bizarre bug since nothing changed from our end other than
> either upgrading to 3.7.1. We also tried upgrading to 3.8.0 to see if it goes
> away but it doesn't. What makes this worse is that the same issue also
> happens with Kafka server. Kafka server starting from 3.7.1 only seems to add
> logs to console and no longer respects *kafka.logs.dir* system property nor
> does it seem to be reading our log4j configuration file that we set like so:
> {code:java}
> export
> KAFKA_LOG4J_OPTS="-Dlog4j.configuration=file:${KAFKA_CONFIG_DIRECTORY}/log4j.properties"
> {code}
> Our log4j properties file for our server looks like so:
> {code:java}
> log4j.rootLogger=INFO, stdout, kafkaAppender
> log4j.appender.stdout=org.apache.log4j.ConsoleAppender
> log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
> log4j.appender.stdout.layout.ConversionPattern=[%d] %p %m (%c)%n
> log4j.appender.kafkaAppender=org.apache.log4j.RollingFileAppender
> log4j.appender.kafkaAppender.MaxFileSize=1GB
> log4j.appender.kafkaAppender.MaxBackupIndex=10
> log4j.appender.kafkaAppender.File=${kafka.logs.dir}/server.log
> log4j.appender.kafkaAppender.layout=org.apache.log4j.PatternLayout
> log4j.appender.kafkaAppender.layout.ConversionPattern=[%d] %p %m (%c)%n
> log4j.appender.stateChangeAppender=org.apache.log4j.RollingFileAppender
> log4j.appender.stateChangeAppender.MaxFileSize=1GB
> log4j.appender.stateChangeAppender.MaxBackupIndex=10
> log4j.appender.stateChangeAppender.File=${kafka.logs.dir}/state-change.log
> log4j.appender.stateChangeAppender.layout=org.apache.log4j.PatternLayout
> log4j.appender.stateChangeAppender.layout.ConversionPattern=[%d] %p %m (%c)%n
> log4j.appender.requestAppender=org.apache.log4j.RollingFileAppender
> log4j.appender.requestAppender.MaxFileSize=1GBlog4j.appender.requestAppender.MaxBackupIndex=10
> log4j.appender.requestAppender.File=${kafka.logs.dir}/kafka-request.log
> log4j.appender.requestAppender.layout=org.apache.log4j.PatternLayout
> log4j.appender.requestAppender.layout.ConversionPattern=[%d] %p %m (%c)%n
> log4j.appender.cleanerAppender=org.apache.log4j.RollingFileAppender
> log4j.appender.cleanerAppender.MaxFileSize=1GB
> log4j.appender.cleanerAppender.MaxBackupIndex=10
> log4j.appender.cleanerAppender.File=${kafka.logs.dir}/log-cleaner.log
> log4j.appender.cleanerAppender.layout=org.apache.log4j.PatternLayout
> log4j.appender.cleanerAppender.layout.ConversionPattern=[%d] %p %m (%c)%n
> log4j.appender.controllerAppender=org.apache.log4j.RollingFileAppender
> log4j.appender.controllerAppender.MaxFileSize=1GB
> log4j.appender.controllerAppender.MaxBackupIndex=10log4j.appender.controllerAppender.File=${kafka.logs.dir}/controller.log
> log4j.appender.controllerAppender.layout=org.apache.log4j.PatternLayoutlog4j.appender.controllerAppender.layout.ConversionPattern=[%d]
> %p %m (%c)%n
> log4j.appender.authorizerAppender=org.apache.log4j.RollingFileAppender
> log4j.appender.authorizerAppender.MaxFileSize=1GB
> log4j.appender.authorizerAppender.MaxBackupIndex=10
> log4j.appender.authorizerAppender.File=${kafka.logs.dir}/kafka-authorizer.loglog4j.appender.authorizerAppender.layout=org.apache.log4j.PatternLayout
> log4j.appender.authorizerAppender.layout.ConversionPattern=[%d] %p %m (%c)%n
> # Change the line below to adjust ZK client
> logginglog4j.logger.org.apache.zookeeper=INFO
> # Change the two lines below to adjust the general broker logging level
> (output to server.log and
> stdout)log4j.logger.kafka=INFOlog4j.logger.org.apache.kafka=INFO
> # Change to DEBUG or TRACE to enable request logging
> log4j.logger.kafka.request.logger=OFF, requestAppender
> log4j.additivity.kafka.request.logger=false
> # Uncomment the lines below and change
> log4j.logger.kafka.network.RequestChannel$ to TRACE for additional output
> # related to the handling of
> requests#log4j.logger.kafka.network.Processor=TRACE, requestAppender
> #log4j.logger.kafka.server.KafkaApis=TRACE, requestAppender
> #log4j.additivity.kafka.server.KafkaApis=false
> log4j.logger.kafka.network.RequestChannel$=WARN, requestAppender
> log4j.additivity.kafka.network.RequestChannel$=false
> # Change the line below to adjust KRaft mode controller
> logginglog4j.logger.org.apache.kafka.controller=INFO, controllerAppender
> log4j.additivity.org.apache.kafka.controller=false
> # Change the line below to adjust ZK mode controller logging
> log4j.logger.kafka.controller=TRACE, controllerAppender
> log4j.additivity.kafka.controller=false
> log4j.logger.kafka.log.LogCleaner=INFO, cleanerAppender
> log4j.additivity.kafka.log.LogCleaner=false
> log4j.logger.state.change.logger=TRACE, stateChangeAppender
> log4j.additivity.state.change.logger=false
> # Access denials are logged at INFO level, change to DEBUG to also log
> allowed accesses
> log4j.logger.kafka.authorizer.logger=INFO, authorizerAppender
> log4j.additivity.kafka.authorizer.logger=false {code}
> And here's how we initialize the appropriate log4j environment variables in
> our Kafka startup script:
> {code:java}
> export KAFKA_CONFIG_DIRECTORY="/tmp/kafka/kraft/config"
> export
> KAFKA_LOG4J_OPTS="-Dlog4j.configuration=file:${KAFKA_CONFIG_DIRECTORY}/log4j.properties"
> export LOG_DIR="/logs/kafka/"
> ...
> bin/kafka-server-start.sh
> ${KAFKA_CONFIG_DIRECTORY}/kraft/broker.properties{code}
> Again nothing changed here. It's the same code we have used since v3.5.0. Any
> ideas what's going wrong? Did 3.7.1 upgrade introduce any regressions or
> changes to Kafka logging?
> Here's an example of what the Kafka broker logs(emitted to console) look like
> after upgrading to 3.7.1+
> {code:java}
> 2024-08-04_00:35:13.89138 00:35:13.891 [kafka-2-raft-io-thread] DEBUG
> org.apache.kafka.raft.KafkaRaftClient -- [RaftManager id=2] Follower high
> watermark updated to 455399
> 2024-08-04_00:35:13.89159 00:35:13.891 [kafka-2-raft-io-thread] DEBUG
> org.apache.kafka.raft.KafkaRaftClient -- [RaftManager id=2] Notifying
> listener org.apache.kafka.image.loader.MetadataLoader@670337647 of batch for
> baseOffset 455398 and lastOffset OptionalLong.empty
> 2024-08-04_00:35:13.89169 00:35:13.891 [kafka-2-raft-outbound-request-thread]
> DEBUG org.apache.kafka.clients.NetworkClient -- [RaftManager id=2] Sending
> FETCH request with header RequestHeader(apiKey=FETCH, apiVersion=16,
> clientId=raft-client-2, correlationId=4602, headerVersion=2) and timeout 2000
> to node 3: FetchRequestData(clusterId='_EMgkMHpTcKhrGEMNo01zA', replicaId=-1,
> replicaState=ReplicaState(replicaId=2, replicaEpoch=-1), maxWaitMs=500,
> minBytes=0, maxBytes=8388608, isolationLevel=0, sessionId=0, sessionEpoch=-1,
> topics=[FetchTopic(topic='__cluster_metadata',
> topicId=AAAAAAAAAAAAAAAAAAAAAQ, partitions=[FetchPartition(partition=0,
> currentLeaderEpoch=82, fetchOffset=455400, lastFetchedEpoch=82,
> logStartOffset=-1, partitionMaxBytes=0)])], forgottenTopicsData=[], rackId='')
> 2024-08-04_00:35:13.89177 00:35:13.891
> [kafka-2-metadata-loader-event-handler] DEBUG
> org.apache.kafka.image.loader.MetadataBatchLoader -- [MetadataLoader id=2]
> handleCommit: Generated a metadata delta between 455397 and 455398 from 1
> batch(es) in 0 us.
> 2024-08-04_00:35:13.89182 00:35:13.891
> [kafka-2-metadata-loader-event-handler] DEBUG
> org.apache.kafka.image.loader.MetadataLoader -- [MetadataLoader id=2]
> handleCommit: publishing new image with provenance
> MetadataProvenance(lastContainedOffset=455398, lastContainedEpoch=82,
> lastContainedLogTimeMs=1722731713365).{code}
> P.S Our Kafka jars are directly downloaded from
> [https://kafka.apache.org/downloads] with no modifications to the binaries
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
