[
https://issues.apache.org/jira/browse/KAFKA-17254?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17870872#comment-17870872
]
Krishna V Reddy commented on KAFKA-17254:
-----------------------------------------
[~chia7712] There are two issues here. Both the Kafka CLI and Kafka server are
not respecting their respective log4j properties file. Kafka CLI is not
respecting config/tools-log4j.properties and Kafka server is not respecting
config/log4j.properties. The mention of *kafka.logs.dir* in the above issue was
in regards to Kafka server not Kafka CLI but that is secondary. The issue it
seems is that both Kafka CLI and Kafka server are not reading the log4
properties file {*}at all{*}. That's the primary issue.
> 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
> Priority: Major
>
> 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 instead of writing logs to directory
> set in system property *kafka.logs.dir.* 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)
