Matthias J. Sax created KAFKA-18498:
---------------------------------------
Summary: Kafka Streams main thread does not release lock
Key: KAFKA-18498
URL: https://issues.apache.org/jira/browse/KAFKA-18498
Project: Kafka
Issue Type: Bug
Components: streams
Reporter: Matthias J. Sax
We merged [https://github.com/apache/kafka/pull/16922] which seems to introduce
a regression bug, not releasing a lock properly.
We saw a failing system test (timed out) with the following (relevant logs)
{code:java}
[2024-12-19 02:45:29,637] DEBUG stream-thread [main] standby-task [1_0]
Acquired state directory lock
(org.apache.kafka.streams.processor.internals.StandbyTask)
[2024-12-19 02:45:29,655] INFO Opening store
KSTREAM-AGGREGATE-STATE-STORE-0000000014 in regular mode
(org.apache.kafka.streams.state.internals.RocksDBTimestampedStore)
[2024-12-19 02:45:29,656] DEBUG [RocksDB Metrics Recorder for
KSTREAM-AGGREGATE-STATE-STORE-0000000014] Adding metrics recorder of task 1_0
to metrics recording trigger
(org.apache.kafka.streams.state.internals.metrics.RocksDBMetricsRecorder)
[2024-12-19 02:45:29,656] DEBUG [RocksDB Metrics Recorder for
KSTREAM-AGGREGATE-STATE-STORE-0000000014] Adding value providers for store
KSTREAM-AGGREGATE-STATE-STORE-0000000014 of task 1_0
(org.apache.kafka.streams.state.internals.metrics.RocksDBMetricsRecorder)
[2024-12-19 02:45:29,656] DEBUG stream-client
[EosTest-6cef0eeb-642f-446b-ada7-35c3d7f7121c] Registered state store
KSTREAM-AGGREGATE-STATE-STORE-0000000014 to its state manager
(org.apache.kafka.streams.processor.internals.ProcessorStateManager)
[2024-12-19 02:45:29,675] INFO Opening store
KSTREAM-AGGREGATE-STATE-STORE-0000000018 in regular mode
(org.apache.kafka.streams.state.internals.RocksDBTimestampedStore)
[2024-12-19 02:45:29,675] DEBUG [RocksDB Metrics Recorder for
KSTREAM-AGGREGATE-STATE-STORE-0000000018] Adding metrics recorder of task 1_0
to metrics recording trigger
(org.apache.kafka.streams.state.internals.metrics.RocksDBMetricsRecorder)
[2024-12-19 02:45:29,675] DEBUG [RocksDB Metrics Recorder for
KSTREAM-AGGREGATE-STATE-STORE-0000000018] Adding value providers for store
KSTREAM-AGGREGATE-STATE-STORE-0000000018 of task 1_0
(org.apache.kafka.streams.state.internals.metrics.RocksDBMetricsRecorder)
[2024-12-19 02:45:29,676] DEBUG stream-client
[EosTest-6cef0eeb-642f-446b-ada7-35c3d7f7121c] Registered state store
KSTREAM-AGGREGATE-STATE-STORE-0000000018 to its state manager
(org.apache.kafka.streams.processor.internals.ProcessorStateManager)
[2024-12-19 02:45:29,676] DEBUG stream-thread [main] standby-task [1_0]
Registered state stores
(org.apache.kafka.streams.processor.internals.StandbyTask)
[2024-12-19 02:45:29,676] INFO stream-client
[EosTest-6cef0eeb-642f-446b-ada7-35c3d7f7121c] State store
KSTREAM-AGGREGATE-STATE-STORE-0000000014 initialized from checkpoint with
offset null at changelog
EosTest-KSTREAM-AGGREGATE-STATE-STORE-0000000014-changelog-0
(org.apache.kafka.streams.processor.internals.ProcessorStateManager)
[2024-12-19 02:45:29,676] INFO stream-client
[EosTest-6cef0eeb-642f-446b-ada7-35c3d7f7121c] State store
KSTREAM-AGGREGATE-STATE-STORE-0000000018 initialized from checkpoint with
offset null at changelog
EosTest-KSTREAM-AGGREGATE-STATE-STORE-0000000018-changelog-0
(org.apache.kafka.streams.processor.internals.ProcessorStateManager)
[2024-12-19 02:45:29,676] DEBUG stream-thread [main] standby-task [1_0]
Initialized state stores
(org.apache.kafka.streams.processor.internals.StandbyTask)
[2024-12-19 02:45:29,676] INFO stream-thread [main] standby-task [1_0]
Initialized (org.apache.kafka.streams.processor.internals.StandbyTask)
[...]
[2024-12-19 02:45:32,328] INFO stream-thread [main] standby-task [1_0]
Suspended running (org.apache.kafka.streams.processor.internals.StandbyTask)
[2024-12-19 02:45:32,328] ERROR stream-thread [main] standby-task [1_0] Failed
to acquire lock while closing the state store for STANDBY task 1_0
(org.apache.kafka.streams.processor.internals.StandbyTask)
[2024-12-19 02:45:32,328] INFO stream-thread [main] standby-task [1_0] Closed
clean (org.apache.kafka.streams.processor.internals.StandbyTask)
[...]
[2024-12-19 02:45:32,374] INFO stream-thread
[EosTest-6cef0eeb-642f-446b-ada7-35c3d7f7121c-StreamThread-1] Handle new
assignment with:
New active tasks: [1_0, 1_3, 0_2]
New standby tasks: [0_4, 1_4, 0_3, 0_1, 1_2, 1_1, 0_0]
Existing active tasks: []
Existing standby tasks: [0_4, 1_4, 0_3, 0_1, 1_2, 0_0, 1_1]
(org.apache.kafka.streams.processor.internals.TaskManager)
[2024-12-19 02:45:32,376] DEBUG stream-thread
[EosTest-6cef0eeb-642f-446b-ada7-35c3d7f7121c-StreamThread-1] stream-task [1_0]
Created state store manager for task 1_0
(org.apache.kafka.streams.processor.internals.ProcessorStateManager)
[...]
[2024-12-19 02:45:32,562] INFO stream-thread
[EosTest-6cef0eeb-642f-446b-ada7-35c3d7f7121c-StreamThread-1] Encountered lock
exception. Reattempting locking the state in the next iteration. Error message
was: stream-thread
[EosTest-6cef0eeb-642f-446b-ada7-35c3d7f7121c-StreamThread-1] task [1_0] Failed
to lock the state directory for task 1_0
(org.apache.kafka.streams.processor.internals.TaskManager) {code}
The last log line keeps repeating...
I am going to revert the PR for 4.0 release, and we should fix forward on
`trunk`.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
