[jira] [Created] (KAFKA-19960) Spurious failure to close StateDirectory due to some task directories still locked

["Mikael Carlstedt (Jira)" <ji...@apache.org>]

Mikael Carlstedt created KAFKA-19960:
----------------------------------------

             Summary: Spurious failure to close StateDirectory due to some task directories still locked
                 Key: KAFKA-19960
                 URL: https://issues.apache.org/jira/browse/KAFKA-19960
             Project: Kafka
          Issue Type: Bug
          Components: streams
    Affects Versions: 3.8.1
            Reporter: Mikael Carlstedt


We are seeing random failures to close state directories while closing a kafka-streams application in a test environment.

*Preconditions:*
 * Two state stores
 * Three input partitions
 * Stand-by replication enabled (NB: we have not been able to reproduce without stand-by replication)
 * Two instances running on a single host with different state directory.

The application instances are started before each test case is executed, and then closed when the test case has completed. Most of the time it works well without any errors logged, but sometimes we see this error message when closing an application instance:

 
{noformat}
25-12-04T13:01:18.711 ERROR o.a.k.s.p.i.StateDirectory:397 - Some task directories still locked while closing state, this indicates unclean shutdown: {0_2=	StreamsThread threadId: messages.nobill.campaigns.delay-queue-78f61f55-4863-4c4f-913c-bd398eceed0e-StreamThread-1
TaskManager
	MetadataState:
	Tasks:
, 0_0=	StreamsThread threadId: messages.nobill.campaigns.delay-queue-78f61f55-4863-4c4f-913c-bd398eceed0e-StreamThread-1
TaskManager
	MetadataState:
	Tasks:
}{noformat}
 
 * is has a knock-on effect on all of the following test cases, which fail with this error message:

 
{noformat}
25-12-04T13:01:28.684 ERROR s.s.n.k.k.i.KafkaClient:179 - Unhandled exception in Kafka streams application messages.nobill.campaigns.delay-queue
org.apache.kafka.streams.errors.ProcessorStateException: Error opening store rate-limiterpriority-chronological-store-0 at location /tmp/node2/messages.nobill.campaigns.delay-queue/0_2/rocksdb/rate-limiterpriority-chronological-store-0
	at org.apache.kafka.streams.state.internals.RocksDBStore.openRocksDB(RocksDBStore.java:330)

...

Caused by: org.rocksdb.RocksDBException: lock hold by current process, acquire time 1764849665 acquiring thread 14274883584: /tmp/node2/messages.nobill.campaigns.delay-queue/0_2/rocksdb/rate-limiterpriority-chronological-store-0/LOCK: No locks available
	at org.rocksdb.RocksDB.open(Native Method)
	at org.rocksdb.RocksDB.open(RocksDB.java:307)
	at org.apache.kafka.streams.state.internals.RocksDBStore.openRocksDB(RocksDBStore.java:324)
	... 19 common frames omitted{noformat}
*Observation:*

 
 * Prior to the error, the two stand-by tasks that fail to release their locks are "closed and recycled":

{noformat}
25-12-04T13:01:18.080  INFO o.a.k.s.p.i.StandbyTask:149 - stream-thread [messages.nobill.campaigns.delay-queue-78f61f55-4863-4c4f-913c-bd398eceed0e-StreamThread-1] standby-task [0_2] Suspended running
25-12-04T13:01:18.080 DEBUG o.a.k.s.p.i.ProcessorStateManager:633 - stream-thread [messages.nobill.campaigns.delay-queue-78f61f55-4863-4c4f-913c-bd398eceed0e-StreamThread-1] standby-task [0_2] Recycling state for STANDBY task 0_2.
25-12-04T13:01:18.080 DEBUG o.a.k.s.p.i.ProcessorStateManager:644 - stream-thread [messages.nobill.campaigns.delay-queue-78f61f55-4863-4c4f-913c-bd398eceed0e-StreamThread-1] standby-task [0_2] Clearing all store caches registered in the state manager: ...
25-12-04T13:01:18.080  INFO o.a.k.s.p.i.StandbyTask:254 - stream-thread [messages.nobill.campaigns.delay-queue-78f61f55-4863-4c4f-913c-bd398eceed0e-StreamThread-1] standby-task [0_2] Closed and recycled state{noformat}

 * By comparison, the third task is "closed clean":

{noformat}
25-12-04T13:01:17.024  INFO o.a.k.s.p.i.StandbyTask:149 - stream-thread [messages.nobill.campaigns.delay-queue-bff50025-9296-45b7-ab1a-43480aee6f66-StreamThread-1] standby-task [0_1] Suspended running
25-12-04T13:01:17.024 DEBUG o.a.k.s.p.i.ProcessorStateManager:585 - stream-thread [messages.nobill.campaigns.delay-queue-bff50025-9296-45b7-ab1a-43480aee6f66-StreamThread-1] standby-task [0_1] Closing its state manager and all the registered state stores: ...
25-12-04T13:01:17.028 DEBUG o.a.k.s.p.i.StateDirectory:377 - stream-thread [messages.nobill.campaigns.delay-queue-bff50025-9296-45b7-ab1a-43480aee6f66-StreamThread-1] Released state dir lock for task 0_1
25-12-04T13:01:17.028  INFO o.a.k.s.p.i.StandbyTask:232 - stream-thread [messages.nobill.campaigns.delay-queue-bff50025-9296-45b7-ab1a-43480aee6f66-StreamThread-1] standby-task [0_1] Closed clean{noformat}

What is it that triggers this "recycling" of stand-by tasks?



--
This message was sent by Atlassian Jira
(v8.20.10#820010)