Uploaded image for project: 'JGroups'
  1. JGroups
  2. JGRP-2364

simply lock and unlock JGroups lock repeatedly will create chaos

    XMLWordPrintable

Details

    • Bug
    • Resolution: Done
    • Major
    • 4.1.2
    • 4.1.1
    • None
    • Hide

      Use attached unit test case org.jgroups.blocks.LockSimpleTest#testLockMultipleTimes to reproduce it:

          public void testLockMultipleTimes(Class<? extends Locking> locking_class) throws Exception {
        init(locking_class);
        final AtomicLong counter = new AtomicLong(0);
        final AtomicBoolean stop = new AtomicBoolean(false);
        ExecutorService executorService = createExecutorService();
        try {
            Runnable run = new Runnable() {
                @Override
                public void run() {
                    try {
                        while (!stop.get()) {
                            while (!tryLock(lock, 10000, LOCK)) {
                            }
                            try {
                                long c = counter.addAndGet(1);
                                if (c > 1)
                                    log_.error(String.format("Thread %s meet none exclusive access", Thread.currentThread().getId()));
                                counter.addAndGet(-1);
                            } finally {
                                unlock(lock, LOCK);
                            }
                        }
                    } catch (Throwable e) {
                        String msg = String.format("Exception happen in thread %s", Thread.currentThread().getId());
                        log_.error(msg, e);
                    }
                }
            };
            for (int i = 0; i < 1; i++) {
                executorService.submit(run);
            }
            sleep(90);
            stop.set(true);
            log_.warn(String.format("Final counter is: %s", counter.get()));
        } finally {
            destroyExecutorService(executorService);
        }
    }
      Show
      Use attached unit test case org.jgroups.blocks.LockSimpleTest#testLockMultipleTimes to reproduce it: public void testLockMultipleTimes( Class <? extends Locking> locking_class) throws Exception { init(locking_class); final AtomicLong counter = new AtomicLong(0); final AtomicBoolean stop = new AtomicBoolean( false ); ExecutorService executorService = createExecutorService(); try { Runnable run = new Runnable () { @Override public void run() { try { while (!stop.get()) { while (!tryLock(lock, 10000, LOCK)) { } try { long c = counter.addAndGet(1); if (c > 1) log_.error( String .format( " Thread %s meet none exclusive access" , Thread .currentThread().getId())); counter.addAndGet(-1); } finally { unlock(lock, LOCK); } } } catch (Throwable e) { String msg = String .format( "Exception happen in thread %s" , Thread .currentThread().getId()); log_.error(msg, e); } } }; for ( int i = 0; i < 1; i++) { executorService.submit(run); } sleep(90); stop.set( true ); log_.warn( String .format( "Final counter is: %s" , counter.get())); } finally { destroyExecutorService(executorService); } }

    Description

      I have one simple use case to reproduce the issue. In same thread, just lock/unlock the lock repeatedly. Turn the log level to TRACE, you will find the communication chaos between the client and the coordinate. JGroups unlock will return immediately after sending out RELEASE_LOCK currently. Why unlock don’t wait and only return after receiving the RELEASE_LOCK_OK response?

      • Current log: 
        16:56:40,399 TRACE [CENTRAL_LOCK] A --> A: GRANT_LOCK[sample-lock, lock_id=1, owner=A::31, trylock, timeout=10000]
16:56:40,404 TRACE [CENTRAL_LOCK] A <-- A: GRANT_LOCK[sample-lock, lock_id=1, owner=A::31, trylock, timeout=10000, sender=A]
16:56:40,410 TRACE [CENTRAL_LOCK] A --> A: LOCK_GRANTED[sample-lock, lock_id=1, owner=A::31]
16:56:40,411 TRACE [CENTRAL_LOCK] A <-- A: LOCK_GRANTED[sample-lock, lock_id=1, owner=A::31, sender=A]
16:56:40,413 TRACE [CENTRAL_LOCK] A --> A: RELEASE_LOCK[sample-lock, lock_id=1, owner=A::31]
16:56:40,414 TRACE [CENTRAL_LOCK] A <-- A: RELEASE_LOCK[sample-lock, lock_id=1, owner=A::31, sender=A]
16:56:40,414 TRACE [CENTRAL_LOCK] A --> A: RELEASE_LOCK[sample-lock, lock_id=1, owner=A::31]
16:56:40,415 TRACE [CENTRAL_LOCK] A --> A: RELEASE_LOCK_OK[sample-lock, lock_id=1, owner=A::31]
16:56:40,415 TRACE [CENTRAL_LOCK] A --> A: RELEASE_LOCK[sample-lock, lock_id=1, owner=A::31]
      • The expected log: 
        2019-07-24 17:01:52,849 TRACE [org.jgroups.protocols.CENTRAL_LOCK] [A] --> [A] GRANT_LOCK [sample-lock, lock_id=1, owner=A::63, trylock (timeout=10000)
2019-07-24 17:01:52,849 TRACE [org.jgroups.protocols.CENTRAL_LOCK] [A] <-- [A] GRANT_LOCK [sample-lock, lock_id=1, owner=A::63, trylock (timeout=10000)
2019-07-24 17:01:52,852 TRACE [org.jgroups.protocols.CENTRAL_LOCK] [A] --> [A] LOCK_GRANTED [sample-lock, lock_id=1, owner=A::63 ]
2019-07-24 17:01:52,852 TRACE [org.jgroups.protocols.CENTRAL_LOCK] [A] <-- [A] LOCK_GRANTED [sample-lock, lock_id=1, owner=A::63 ]
2019-07-24 17:01:52,853 TRACE [org.jgroups.protocols.CENTRAL_LOCK] [A] --> [A] RELEASE_LOCK [sample-lock, lock_id=1, owner=A::63 ]
2019-07-24 17:01:52,853 TRACE [org.jgroups.protocols.CENTRAL_LOCK] [A] <-- [A] RELEASE_LOCK [sample-lock, lock_id=1, owner=A::63 ]
2019-07-24 17:01:52,853 TRACE [org.jgroups.protocols.CENTRAL_LOCK] [A] --> [A] RELEASE_LOCK_OK [sample-lock, lock_id=1, owner=A::63 ]
2019-07-24 17:01:52,854 TRACE [org.jgroups.protocols.CENTRAL_LOCK] [A] <-- [A] RELEASE_LOCK_OK [sample-lock, lock_id=1, owner=A::63 ]

      Attachments

        Activity

          People

            rhn-engineering-bban Bela Ban
            deng2 deng Deng (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: