[AMQ-2916] Kaha persistence adapter not closing opend file after lock check in secondery server: shared file system mode

• Type: Bug
• Status: Closed
• Priority: Critical
• Resolution: Cannot Reproduce
• Affects Version/s: 5.3.0
• Component/s: Broker

Environment

Mac os x 10.6 which NFS file system for shared file system

• Assignee: Unassigned
• Reporter: Madhu krishna
• Created: 13/Sep/10 19:53
• Updated: 30/Sep/11 14:56
• Resolved: 30/Sep/11 14:56

Description

This For KahaDb store.
From the logs it looks like activeMq shared file system broker has a leak in RandomAccessfile lock check. On a lock fail it is not closing the opened files. This is causing the secondary server to run out of number of open files set in the OS.
Current OS is Set to 1024 max open files.

I have been running some tests to validate this and the following is the observations.
1. Log from secondary server:
2010-09-10 06:36:12,157 [MQ-BROKER-SERVICE] INFO (KahaStore.java:463) - Kaha Store using data directory /nfs/soleta/gdvt/activeMq
2010-09-10 06:36:12,157 [MQ-BROKER-SERVICE] INFO (KahaPersistenceAdapter.java:180) - Store is locked... waiting 10 seconds for the Store to be unlocked.
2010-09-10 06:36:22,159 [MQ-BROKER-SERVICE] INFO (KahaStore.java:463) - Kaha Store using data directory /nfs/soleta/gdvt/activeMq
2010-09-10 06:36:22,161 [MQ-BROKER-SERVICE] INFO (KahaPersistenceAdapter.java:180) - Store is locked... waiting 10 seconds for the Store to be unlocked.
2010-09-10 06:36:32,161 [MQ-BROKER-SERVICE] INFO (KahaStore.java:463) - Kaha Store using data directory /nfs/soleta/gdvt/activeMq
2010-09-10 06:36:32,162 [MQ-BROKER-SERVICE] INFO (KahaPersistenceAdapter.java:180) - Store is locked... waiting 10 seconds for the Store to be unlocked.
2010-09-10 06:36:42,162 [MQ-BROKER-SERVICE] INFO (KahaStore.java:463) - Kaha Store using data directory /nfs/soleta/gdvt/activeMq
2010-09-10 06:36:42,174 [MQ-BROKER-SERVICE] INFO (KahaPersistenceAdapter.java:180) - Store is locked... waiting 10 seconds for the Store to be unlocked.
2010-09-10 06:36:52,175 [MQ-BROKER-SERVICE] INFO (KahaStore.java:463) - Kaha Store using data directory /nfs/soleta/gdvt/activeMq
2010-09-10 06:36:52,175 [MQ-BROKER-SERVICE] INFO (KahaPersistenceAdapter.java:180) - Store is locked... waiting 10 seconds for the Store to be unlocked.
2010-09-10 06:37:02,175 [MQ-BROKER-SERVICE] INFO (KahaStore.java:463) - Kaha Store using data directory /nfs/soleta/gdvt/activeMq
2010-09-10 06:37:02,176 [MQ-BROKER-SERVICE] INFO (KahaPersistenceAdapter.java:180) - Store is locked... waiting 10 seconds for the Store to be unlocked.
2010-09-10 06:37:12,177 [MQ-BROKER-SERVICE] INFO (KahaStore.java:463) - Kaha Store using data directory /nfs/soleta/gdvt/activeMq
2010-09-10 06:37:12,178 [MQ-BROKER-SERVICE] INFO (KahaPersistenceAdapter.java:180) - Store is locked... waiting 10 seconds for the Store to be unlocked.
Note: As you can see that the secondary server is trying to get the lock on /nfs/soleta/gdvt/activeMq file, it fails as the file has been locked by the primary server. So it tries to get the lock very 10 seconds.
2. Log from lsof | grep activeMq
java 13855 madhu 84u REG 14,2 0 7519799 /nfs/soleta/gdvt/activeMq/lock
java 13855 madhu 85u REG 14,2 0 7519799 /nfs/soleta/gdvt/activeMq/lock
java 13855 madhu 86u REG 14,2 0 7519799 /nfs/soleta/gdvt/activeMq/lock
java 13855 madhu 87u REG 14,2 0 7519799 /nfs/soleta/gdvt/activeMq/lock
java 13855 madhu 94u REG 14,2 0 7519799 /nfs/soleta/gdvt/activeMq/lock
java 13855 madhu 95u REG 14,2 0 7519799 /nfs/soleta/gdvt/activeMq/lock
java 13855 madhu 96u REG 14,2 0 7519799 /nfs/soleta/gdvt/activeMq/lock
java 13855 madhu 97u REG 14,2 0 7519799 /nfs/soleta/gdvt/activeMq/lock
You can see that the file used for the lock is not getting closed.
3. Log from lsof | grep activeMq | wc -l
The above cmd will give us the total number of open files for " /nfs/soleta/gdvt/activeMq/lock" .
et3-tk:~ madhu$ lsof | grep activeMq | wc -l
56
et3-tk:~ madhu$ lsof | grep activeMq | wc -l
57
et3-tk:~ madhu$ lsof | grep activeMq | wc -l
58
et3-tk:~ madhu$ lsof | grep activeMq | wc -l
62

As you can see that the open files are increasing on "/nfs/soleta/gdvt/activeMq/lock" and the count doesn't come down.

Note: The below changes were done only for learning purpose.
I was able to resolve this issue by changing version 5.3.0 activeMq-core
org.apache.activemq.kaha.impl.KahaStore line no 465
I replace line 465 with the following code
try

{ lock(); }

catch(StoreLockedExcpetion e)

{ LOG.error("Got error locking file",e); lockFile.getChannel().close(); lockFile.close(); throw new StoreLockedExcpetion("Kaha Store " + directory.getName() + " is already opened by another application"); }