ActiveMQ
  1. ActiveMQ
  2. AMQ-2916

Kaha persistence adapter not closing opend file after lock check in secondery server: shared file system mode

    Details

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

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

      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"); }

        Activity

        Hide
        Timothy Bish added a comment -

        Workaround available. No feedback from user on results of using the workaround.

        Show
        Timothy Bish added a comment - Workaround available. No feedback from user on results of using the workaround.
        Hide
        Gary Tully added a comment -

        workaround, try KahaDB or AMQ store as alternatives.

        Show
        Gary Tully added a comment - workaround, try KahaDB or AMQ store as alternatives.

          People

          • Assignee:
            Unassigned
            Reporter:
            Madhu krishna
          • Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development