Issue in locking on key in concurrency

[savanpatel]

In my project, I have a servlet, that call a utility class.
Utility class calls a wrapper class that I have implemented over redisson lock.
Wrapper class holds RLock object for a thread and provides lock and unlock methods that call RLock's lock and unlock method
But while running a apache ab-test tool for concurrency, Following exception occurs.
Can you tell me if I am missing something over here?

java.lang.IllegalMonitorStateException: Attempt to unlock lock, not locked by current id: 286dad3d-dd4b-434e-bca7-30c35eec01eb thread-id: 158
at org.redisson.RedissonLock$4.execute(RedissonLock.java:416)
at org.redisson.RedissonLock$4.execute(RedissonLock.java:1)
at org.redisson.connection.MasterSlaveConnectionManager.write(MasterSlaveConnectionManager.java:272)
at org.redisson.connection.MasterSlaveConnectionManager.write(MasterSlaveConnectionManager.java:261)
at org.redisson.RedissonLock.unlock(RedissonLock.java:402)
at com.sokrati.redisClient.JedisConnection.unlock(JedisConnection.java:431)
at com.sokrati.throttlingService.operations.RedisOperations.unlock(RedisOperations.java:112)
at com.sokrati.throttlingService.utils.ThrottlerUtil.checkKeyBlocked(ThrottlerUtil.java:135)
at com.sokrati.throttlingService.servlets.Throttler.fetch(Throttler.java:70)
at sun.reflect.GeneratedMethodAccessor29.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.sokrati.restCommunicator.RestCommunicator.invokeServiceMethod(RestCommunicator.java:308)

[mrniko]

hi!

you should unlock the lock in the same thread it has been locked

[savanpatel]

I am unloking thread from same thread still the same exception happens

[erdem-aslan]

Would you mind sharing the code snippet where you lock and unlock ?

[savanpatel]

public static BlockageDetails checkKeyBlocked(String key,
RedisConnection rc)
throws UnableToGetConnection, UnableToGetCredentials
{
BlockageDetails blockageDetails = new BlockageDetails(key, 0L);
BaseOperations baseOperations = BaseOperations.getInstance(rc);
String blockKey = getBlockKey(key);

    Locker lock = baseOperations.lock(ThrottlerUtil.getLockKey(key));
    if (baseOperations.isExists(blockKey))
    {
        String expiryTime = baseOperations.getValue(blockKey);
        if(Long.parseLong(expiryTime) > new Date().getTime())
        {
            blockageDetails =
                new BlockageDetails(
                    key,
                    baseOperations.getRemainingTime(blockKey)
                );
        }
    }
    baseOperations.unlock(lock);
    baseOperations.disconnect();
    return blockageDetails;
}

this is function that my servlet calls

On Tue, Jun 9, 2015 at 5:04 PM, Gladmir notifications@github.com wrote:

Would you mind sharing the code snippet where you lock and unlock ?

—
Reply to this email directly or view it on GitHub
#171 (comment).

[savanpatel]

public static BlockageDetails checkKeyBlocked(String key,
RedisConnection rc)
throws UnableToGetConnection, UnableToGetCredentials
{
BlockageDetails blockageDetails = new BlockageDetails(key, 0L);
BaseOperations baseOperations = BaseOperations.getInstance(rc);
String blockKey = getBlockKey(key);

    Locker lock = baseOperations.lock(ThrottlerUtil.getLockKey(key));
    if (baseOperations.isExists(blockKey))
    {
        String expiryTime = baseOperations.getValue(blockKey);
        if(Long.parseLong(expiryTime) > new Date().getTime())
        {
            blockageDetails = 
                new BlockageDetails(
                    key,
                    baseOperations.getRemainingTime(blockKey)
                );
        }
    }
    baseOperations.unlock(lock);
    baseOperations.disconnect();
    return blockageDetails;
}

Class Locker holds object of RLock
this is function that my servlet calls

[erdem-aslan]

Since I can't see the related underlying implementation of yours, my wild guess would be; You have a possible race condition with your getBlockKey and/or ThrottlerUtil.getLockKey method accessors.

Are those synchronised ? Are you sure that you are generating/returning correct keys per Servlet (per Servlet Container Thread) request?

You can easily debug it via checking the thread id just before and after you acquired the lock and also compare the ids with your RLock wrapper object.

RLock object is being serialised to Redis with a JVM wide unique UUID and thread id, you can double check with Redis also (if you are using default Jackson Serialiser).

[savanpatel]

But when I call this:
Locker lock = baseOperations.lock(ThrottlerUtil.getLockKey(key));
It returns Locker object (Wrapper over RLcok) containing RLock object for key after locking.
So doesn't redisson takes care of these race conditions?

[erdem-aslan]

So you are calling tryLock after you get the RLock impl. object and you are sure you acquired the lock (within baseOperations.lock (...) call ) ?

Could you share baseOperations.lock call's code?

Also a simple test would pin point the bug origin, please check the threadId of the current running thread and compare with the acquired lock's threadId. If they are same, at that point the problem would be within redisson.

[savanpatel]

/*
* Locks on the given key.
*/
@OverRide
public Locker lock(String key)
{
RLock lock = redisson.getLock(key);
lock.lock(leaseTimeMs, TimeUnit.MILLISECONDS);
return new Locker(lock);
}

And redisson is
private Redisson redisson;

[erdem-aslan]

Please check the threadId like I mentioned earlier, your lock (String key) method seems clear.

Edit: One last comment on the "leaseTimeMs". By the time you call unlock, lock may be unlocked due to lease timeout and acquired by another thread with the same key. So when you call unlock, you "may" encounter the the related exception.

[savanpatel]

I monitored on redis and every time on new lock request, it over writes the lock value.

"SET" "amplelock" "{"@Class":"org.redisson.RedissonLock$LockValue","counter":1,"id":"2596c222-404c-4827-a33c-728eb8c35378","threadId":321}" "px" "5000" "nx"
1433853958.412589 [0 176.9.155.232:37491] "SET" "amplelock" "{"@Class":"org.redisson.RedissonLock$LockValue","counter":1,"id":"c0741619-0037-4453-adb8-4b1757895bae","threadId":451}" "px" "5000" "nx"
1433853958.412837 [0 144.76.139.52:35420] "SET" "amplelock" "{"@Class":"org.redisson.RedissonLock$LockValue","counter":1,"id":"2596c222-404c-4827-a33c-728eb8c35378","threadId":337}" "px" "5000" "nx"
1433853958.412906 [0 176.9.155.232:37503] "SET" "amplelock" "{"@Class":"org.redisson.RedissonLock$LockValue","counter":1,"id":"c0741619-0037-4453-adb8-4b1757895bae","threadId":787}" "px" "5000" "nx"
1433853958.412960 [0 144.76.139.52:35435] "SET" "amplelock" "{"@Class":"org.redisson.RedissonLock$LockValue","counter":1,"id":"2596c222-404c-4827-a33c-728eb8c35378","threadId":370}" "px" "5000" "nx"
1433853958.413274 [0 176.9.155.232:37486] "SET" "amplelock" "{"@Class":"org.redisson.RedissonLock$LockValue","counter":1,"id":"c0741619-0037-4453-adb8-4b1757895bae","threadId":782}" "px" "5000" "nx"
1433853958.413369 [0 176.9.155.232:37488] "SET" "amplelock" "{"@Class":"org.redisson.RedissonLock$LockValue","counter":1,"id":"c0741619-0037-4453-adb8-4b1757895bae","threadId":813}" "px" "5000" "nx"
1433853958.413440 [0 176.9.155.232:37528] "SET" "amplelock" "{"@Class":"org.redisson.RedissonLock$LockValue","counter":1,"id":"c0741619-0037-4453-adb8-4b1757895bae","threadId":797}" "px" "5000" "nx"

Have a look at screen shot

Edit: ON "leaseTimeMs", my leasTimeMs is high 5seconds. I also tried with 50seconds and then 5mins. But still the problem persists.
Note: I am running service on two servers, these service uses redisson independently within them.

[erdem-aslan]

Whats your redisson version? I want to check the source code of it.

[savanpatel]

redisson-1.2.0

#Note: My service is deployed on two server boxes that fires request to redis master

[erdem-aslan]

Tried with 100 threads, 5 ms waits between lock/unlock calls per thread and couldn't generated your case.

First of all, please upgrade your redisson version to latest 1.2.1 and check your redis monitor log for the SETNX command instead of SET command. Also make sure to use at least Redis 3.0.1, just be sure.

Your monitor output should be like;

1434091509.343215 [0 127.0.0.1:50802] "SETNX" "someLock" "{"@Class":"org.redisson.RedissonLock$LockValue","counter":1,"id":"f6a8c65b-8d3d-4042-9dd3-c0e5a2afa70b","threadId":97}"
1434091509.343416 [0 127.0.0.1:50829] "SETNX" "someLock" "{"@Class":"org.redisson.RedissonLock$LockValue","counter":1,"id":"f6a8c65b-8d3d-4042-9dd3-c0e5a2afa70b","threadId":61}"
1434091509.343721 [0 127.0.0.1:50767] "SETNX" "someLock" "{"@Class":"org.redisson.RedissonLock$LockValue","counter":1,"id":"f6a8c65b-8d3d-4042-9dd3-c0e5a2afa70b","threadId":50}"
1434091509.344046 [0 127.0.0.1:50765] "SETNX" "someLock" "{"@Class":"org.redisson.RedissonLock$LockValue","counter":1,"id":"f6a8c65b-8d3d-4042-9dd3-c0e5a2afa70b","threadId":58}"
1434091509.344412 [0 127.0.0.1:50764] "SETNX" "someLock" "{"@Class":"org.redisson.RedissonLock$LockValue","counter":1,"id":"f6a8c65b-8d3d-4042-9dd3-c0e5a2afa70b","threadId":49}"
1434091509.345077 [0 127.0.0.1:50851] "SETNX" "someLock" "{"@Class":"org.redisson.RedissonLock$LockValue","counter":1,"id":"f6a8c65b-8d3d-4042-9dd3-c0e5a2afa70b","threadId":55}"
1434091509.345137 [0 127.0.0.1:50814] "SETNX" "someLock" "{"@Class":"org.redisson.RedissonLock$LockValue","counter":1,"id":"f6a8c65b-8d3d-4042-9dd3-c0e5a2afa70b","threadId":102}"
1434091509.345192 [0 127.0.0.1:50827] "SETNX" "someLock" "{"@Class":"org.redisson.RedissonLock$LockValue","counter":1,"id":"f6a8c65b-8d3d-4042-9dd3-c0e5a2afa70b","threadId":45}"
1434091509.345244 [0 127.0.0.1:50810] "SETNX" "someLock" "{"@Class":"org.redisson.RedissonLock$LockValue","counter":1,"id":"f6a8c65b-8d3d-4042-9dd3-c0e5a2afa70b","threadId":84}"
1434091509.345297 [0 127.0.0.1:50849] "SETNX" "someLock" "{"@Class":"org.redisson.RedissonLock$LockValue","counter":1,"id":"f6a8c65b-8d3d-4042-9dd3-c0e5a2afa70b","threadId":94}"
1434091509.345349 [0 127.0.0.1:50812] "SETNX" "someLock" "{"@Class":"org.redisson.RedissonLock$LockValue","counter":1,"id":"f6a8c65b-8d3d-4042-9dd3-c0e5a2afa70b","threadId":87}"
1434091509.345404 [0 127.0.0.1:50854] "SETNX" "someLock" "{"@Class":"org.redisson.RedissonLock$LockValue","counter":1,"id":"f6a8c65b-8d3d-4042-9dd3-c0e5a2afa70b","threadId":106}"

Since the command SETNX only updates/sets if the key is missing and Redis's embedded atomicity support, running the same test with multiple independent redisson instances and/or JVMs should not change or break the Lock contract.