java.lang.IllegalMonitorStateException: Current thread is not owner of the lock! -> <not-locked> in hazelcast 3.1.2 (Test included)

[rites...@gaikai.com]

Seeing this error in hazelcast server log:

java.lang.IllegalMonitorStateException: Current thread is not owner of the lock! -> <not-locked>
        at com.hazelcast.concurrent.lock.UnlockOperation.run(UnlockOperation.java:51)
        at com.hazelcast.spi.impl.OperationServiceImpl.doRunOperation(OperationServiceImpl.java:274)
        at com.hazelcast.spi.impl.OperationServiceImpl.access$800(OperationServiceImpl.java:52)
        at com.hazelcast.spi.impl.OperationServiceImpl$LocalOperationProcessor.run(OperationServiceImpl.java:710)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:744)
                                                


I can reproduce this with following test , though not sure if this is what we are facing, but we do use lease lock as shown in the test.

The test starts two threads both try to acquire a lease lock for 10 seconds and one gets in and other waits. The threads who gets the lock waits for waits for 120 seconds before doing anything and thread that does not should just wait for lock to be available.
what happens is that after 100 second somehow the thread which is waiting for lock gets the lock even though the other thread has not released it. so later when one of the thread tries to release the lock it gets exception regarding "java.lang.IllegalMonitorStateException: Current thread is not owner of the lock!"

Here is what is printed:


INFO: [10.0.30.26]:5701 [dev] Address[10.0.30.26]:5701 is STARTED
thread1 started at: Thu Dec 05 19:58:04 PST 2013
thread2 started at: Thu Dec 05 19:58:04 PST 2013
Dec 05, 2013 7:58:05 PM com.hazelcast.partition.PartitionService
INFO: [10.0.30.26]:5701 [dev] Initializing cluster partition table first arrangement...
thread 1 acquired lock and now sleeping, time it waited to acquire lock: 70 ms
thread 2 acquired lock and now sleeping, time it waited to acquire lock: 100072 ms
thread 1 interrupted
thread 2 interrupted
Dec 05, 2013 8:00:04 PM com.hazelcast.concurrent.lock.UnlockOperation
SEVERE: [10.0.30.26]:5701 [dev] Current thread is not owner of the lock! -> Owner: 77570aea-49f9-4922-bbee-f24fb572a743, thread-id: 32
java.lang.IllegalMonitorStateException: Current thread is not owner of the lock! -> Owner: 77570aea-49f9-4922-bbee-f24fb572a743, thread-id: 32



Test:


@Test
    public void testThreadNotOwnerOfLock() throws Exception {
        final HazelcastInstance hazelcastInstance =  Hazelcast.newHazelcastInstance();
       
        Runnable run1 = new Runnable() {
           
            @Override
            public void run() {
                Date sDate = new Date();
                long startTime = sDate.getTime();
                System.out.println("thread1 started at: "+ sDate);
               
               
                ILock lock = hazelcastInstance.getLock("a");
                TransactionContext tx =  hazelcastInstance.newTransactionContext();
                try {
                    lock.lock(100000, TimeUnit.MILLISECONDS);
                   
                    try {
                       
                            tx.beginTransaction();
                            long endTime = System.currentTimeMillis();
                            long tt = endTime - startTime;
                            System.out.println("thread 1 acquired lock and now sleeping, time it waited to acquire lock: " + tt + " ms");
                            Thread.sleep(120000);
                           
                            TransactionalMap<String, String>  test = tx.getMap("test");
                            test.put("a", "1");
                            tx.commitTransaction();
                            Thread.sleep(100);
                       
                    } catch(InterruptedException ex) {
                        System.out.println("thread 1 interrupted ");
                    } catch (Exception ex) {
                        ex.printStackTrace();
                        tx.rollbackTransaction();
                    } finally {
                        try {
                            lock.unlock();
                            Date eDate = new Date();
                            long endTime = eDate.getTime();
                            long tt = endTime - startTime;
                            System.out.println("thread1 released lock at : "+ eDate + " total time tokk: "+ tt + " ms");
                        } catch(Exception ex) {
                            ex.printStackTrace();
                        }
                       
                       
                    }
                } catch(Exception ex) {
                    ex.printStackTrace();
                }
               
            }
        };
       
       
        Runnable run2 = new Runnable() {
           
            @Override
            public void run() {
                Date sDate = new Date();
                long startTime = sDate.getTime();
                System.out.println("thread2 started at: "+ sDate);
                ILock lock = hazelcastInstance.getLock("a");
                TransactionContext tx =  hazelcastInstance.newTransactionContext();
                try {
                    try {
                       
                        lock.lock(100000, TimeUnit.MILLISECONDS);
                            tx.beginTransaction();
                            long endTime = System.currentTimeMillis();
                            long tt = endTime - startTime;
                            System.out.println("thread 2 acquired lock and now sleeping, time it waited to acquire lock: " + tt + " ms");
                           
                            Thread.sleep(120000);
                            TransactionalMap<String, String>  test = tx.getMap("test");
                            String val = test.get("a");
                            System.out.println(" val: "+ val);
                            tx.commitTransaction();
                            Thread.sleep(100);
                       
                    } catch(InterruptedException ex) {
                        System.out.println("thread 2 interrupted ");
                    } catch (Exception ex) {
                        ex.printStackTrace();
                        tx.rollbackTransaction();
                    } finally {
                        try {
                            lock.unlock();
                            Date eDate = new Date();
                            long endTime = eDate.getTime();
                            long tt = endTime - startTime;
                            System.out.println("thread 2 released lock at : "+ eDate + " total time tokk: "+ tt + " ms");
                        } catch(Exception ex) {
                            ex.printStackTrace();
                        }
                       
                    }
               
                } catch(Exception ex) {
                    ex.printStackTrace();
                }
               
               
            }
        };
       
       
        Thread thread1 = new Thread(run1);
        thread1.start();
       
        Thread thread2 = new Thread(run2);
        thread2.start();
       
        Thread.sleep(120000);
       
        thread1.interrupt();
        thread2.interrupt();
       
       
        Thread.sleep(1000);
    }