[HUDI-3394] Fail to release in-process lock due to IllegalMonitorStateException

• Type: Bug
• Status: Closed
• Priority: Blocker
• Resolution: Fixed
• Fix Version/s: 0.11.0
• Component/s: writer-core
• Labels: HUDI-bug pull-request-available
• Story Points: 0
• Epic Link: Metadata Table for File Listing & Query Planning
• Assignee: Yue Zhang
• Reporter: Ethan Guo
• Created: 08/Feb/22 20:17
• Updated: 21/Feb/22 14:19
• Resolved: 17/Feb/22 02:34

Description

Environment: Deltastreamer continuous mode writing MOR table with upserts, with async Compaction, and Cleaner, archival and metadata table enabled.  InProcessLockProvider is used.

hoodie.write.concurrency.mode=optimistic_concurrency_control
hoodie.cleaner.policy.failed.writes=LAZY
hoodie.write.lock.provider=org.apache.hudi.client.transaction.lock.InProcessLockProvider 

Root cause: one thread writing deltacommit is holding the lock.  The async cleaner fails to grab the lock in a minute or so due to the ongoing deltacommit, and then tries to unlock which throws IllegalMonitorStateException.

Full logs and stacktrace:

 

java.util.concurrent.ExecutionException: org.apache.hudi.exception.HoodieRollbackException: Failed to rollback /Users/ethan/Work/data/hudi/metadata_test_ds_mor_continuous_4 commits 20220207234228129
	at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:357)
	at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1908)
	at org.apache.hudi.async.HoodieAsyncService.waitForShutdown(HoodieAsyncService.java:89)
	at org.apache.hudi.client.AsyncCleanerService.waitForCompletion(AsyncCleanerService.java:71)
	at org.apache.hudi.client.BaseHoodieWriteClient.autoCleanOnCommit(BaseHoodieWriteClient.java:523)
	at org.apache.hudi.client.BaseHoodieWriteClient.postCommit(BaseHoodieWriteClient.java:462)
	at org.apache.hudi.client.BaseHoodieWriteClient.commitStats(BaseHoodieWriteClient.java:200)
	at org.apache.hudi.client.SparkRDDWriteClient.commit(SparkRDDWriteClient.java:127)
	at org.apache.hudi.utilities.deltastreamer.DeltaSync.writeToSink(DeltaSync.java:578)
	at org.apache.hudi.utilities.deltastreamer.DeltaSync.syncOnce(DeltaSync.java:323)
	at org.apache.hudi.utilities.deltastreamer.HoodieDeltaStreamer$DeltaSyncService.lambda$startService$0(HoodieDeltaStreamer.java:643)
	at java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1604)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
Caused by: org.apache.hudi.exception.HoodieRollbackException: Failed to rollback /Users/ethan/Work/data/hudi/metadata_test_ds_mor_continuous_4 commits 20220207234228129
	at org.apache.hudi.client.BaseHoodieWriteClient.rollback(BaseHoodieWriteClient.java:666)
	at org.apache.hudi.client.BaseHoodieWriteClient.rollbackFailedWrites(BaseHoodieWriteClient.java:971)
	at org.apache.hudi.client.BaseHoodieWriteClient.rollbackFailedWrites(BaseHoodieWriteClient.java:954)
	at org.apache.hudi.client.BaseHoodieWriteClient.lambda$clean$33796fd2$1(BaseHoodieWriteClient.java:736)
	at org.apache.hudi.common.util.CleanerUtils.rollbackFailedWrites(CleanerUtils.java:135)
	at org.apache.hudi.client.BaseHoodieWriteClient.clean(BaseHoodieWriteClient.java:735)
	at org.apache.hudi.client.BaseHoodieWriteClient.clean(BaseHoodieWriteClient.java:703)
	at org.apache.hudi.client.AsyncCleanerService.lambda$startService$0(AsyncCleanerService.java:51)
	... 4 more
Caused by: org.apache.hudi.exception.HoodieLockException: Thread pool-26-thread-1 FAILED_TO_RELEASE in-process lock.
	at org.apache.hudi.client.transaction.lock.InProcessLockProvider.unlock(InProcessLockProvider.java:97)
	at org.apache.hudi.client.transaction.lock.LockManager.unlock(LockManager.java:88)
	at org.apache.hudi.client.transaction.TransactionManager.endTransaction(TransactionManager.java:80)
	at org.apache.hudi.table.action.rollback.BaseRollbackActionExecutor.finishRollback(BaseRollbackActionExecutor.java:252)
	at org.apache.hudi.table.action.rollback.BaseRollbackActionExecutor.runRollback(BaseRollbackActionExecutor.java:122)
	at org.apache.hudi.table.action.rollback.BaseRollbackActionExecutor.execute(BaseRollbackActionExecutor.java:144)
	at org.apache.hudi.table.HoodieSparkMergeOnReadTable.rollback(HoodieSparkMergeOnReadTable.java:170)
	at org.apache.hudi.client.BaseHoodieWriteClient.rollback(BaseHoodieWriteClient.java:651)
	... 11 more
Caused by: java.lang.IllegalMonitorStateException
	at java.util.concurrent.locks.ReentrantReadWriteLock$Sync.tryRelease(ReentrantReadWriteLock.java:371)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.release(AbstractQueuedSynchronizer.java:1261)
	at java.util.concurrent.locks.ReentrantReadWriteLock$WriteLock.unlock(ReentrantReadWriteLock.java:1131)
	at org.apache.hudi.client.transaction.lock.InProcessLockProvider.unlock(InProcessLockProvider.java:95)
	... 18 more 

 

 

https://gist.github.com/yihua/c391601e859c8f828dc2678330dce793

Issue Links

• relates to: HUDI-3462 List of fixes to Metadata table after 0.10.1
• links to: GitHub Pull Request #4819