[
https://issues.apache.org/jira/browse/KAFKA-20829?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Souquières Adam updated KAFKA-20829:
------------------------------------
Description:
When a Streams application triggers an app-wide shutdown (e.g., a
{{StreamsUncaughtExceptionHandler}} returning {{{}SHUTDOWN_APPLICATION{}}}),
every {{StreamThread}} running the classic rebalance protocol spams the logs
with {{Request joining group due to: Shutdown requested}} — once per run-loop
iteration, at CPU speed.
*Root cause:* {{StreamThread.maybeSendShutdown()}} executes on every loop pass.
KAFKA-19054 throttled the {{log.warn(...)}} call to once per 10s, but left the
{{mainConsumer.enforceRebalance("Shutdown requested")}} call unthrottled. That
call reaches the unguarded {{{}AbstractCoordinator.requestRejoin{}}}, which
unconditionally logs at info level ({{{}Request joining group due to:
{}{{}}}}). Since the shutdown rebalance's {{pollPhase()}} polls non-blocking
({{{}Duration.ZERO{}}}), the loop free-spins and re-triggers the log line on
every pass.
*Scope:* Classic protocol only. KIP-1071, which signals shutdown via the
heartbeat, is unaffected.
*Fix:* Apply the same 10s throttle guarding the warn to the
{{enforceRebalance}} call as well. The first occurrence still fires
immediately, so shutdown latency is unaffected, and the periodic re-assertion
remains in place as a retry safety net.
*Workaround:*
log4j.logger.org.apache.kafka.clients.consumer.internals.AbstractCoordinator=WARN
was:
When a Streams application triggers an app-wide shutdown (e.g., a
{{StreamsUncaughtExceptionHandler}} returning {{{}SHUTDOWN_APPLICATION{}}}),
every {{StreamThread}} running the classic rebalance protocol spams the logs
with {{Request joining group due to: Shutdown requested}} — once per run-loop
iteration, at CPU speed.
*Root cause:* {{StreamThread.maybeSendShutdown()}} executes on every loop pass.
KAFKA-19054 throttled the {{log.warn(...)}} call to once per 10s, but left the
{{mainConsumer.enforceRebalance("Shutdown requested")}} call unthrottled. That
call reaches the unguarded {{{}AbstractCoordinator.requestRejoin{}}}, which
unconditionally logs at info level ({{{}Request joining group due to: {}{}}}).
Since the shutdown rebalance's {{pollPhase()}} polls non-blocking
({{{}Duration.ZERO{}}}), the loop free-spins and re-triggers the log line on
every pass.
*Scope:* Classic protocol only. KIP-1071, which signals shutdown via the
heartbeat, is unaffected.
*Fix:* Apply the same 10s throttle guarding the warn to the
{{enforceRebalance}} call as well. The first occurrence still fires
immediately, so shutdown latency is unaffected, and the periodic re-assertion
remains in place as a retry safety net.
> StreamThread floods logs with "Request joining group due to: Shutdown
> requested" during ▎ SHUTDOWN_APPLICATION under the classic
> protocol
> -------------------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: KAFKA-20829
> URL: https://issues.apache.org/jira/browse/KAFKA-20829
> Project: Kafka
> Issue Type: Bug
> Components: streams
> Affects Versions: 4.2.1, 4.3.1
> Reporter: Souquières Adam
> Assignee: Souquières Adam
> Priority: Minor
>
> When a Streams application triggers an app-wide shutdown (e.g., a
> {{StreamsUncaughtExceptionHandler}} returning {{{}SHUTDOWN_APPLICATION{}}}),
> every {{StreamThread}} running the classic rebalance protocol spams the logs
> with {{Request joining group due to: Shutdown requested}} — once per run-loop
> iteration, at CPU speed.
> *Root cause:* {{StreamThread.maybeSendShutdown()}} executes on every loop
> pass. KAFKA-19054 throttled the {{log.warn(...)}} call to once per 10s, but
> left the {{mainConsumer.enforceRebalance("Shutdown requested")}} call
> unthrottled. That call reaches the unguarded
> {{{}AbstractCoordinator.requestRejoin{}}}, which unconditionally logs at info
> level ({{{}Request joining group due to: {}{{}}}}). Since the shutdown
> rebalance's {{pollPhase()}} polls non-blocking ({{{}Duration.ZERO{}}}), the
> loop free-spins and re-triggers the log line on every pass.
> *Scope:* Classic protocol only. KIP-1071, which signals shutdown via the
> heartbeat, is unaffected.
> *Fix:* Apply the same 10s throttle guarding the warn to the
> {{enforceRebalance}} call as well. The first occurrence still fires
> immediately, so shutdown latency is unaffected, and the periodic re-assertion
> remains in place as a retry safety net.
> *Workaround:*
> log4j.logger.org.apache.kafka.clients.consumer.internals.AbstractCoordinator=WARN
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
