Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

IsAcquired not getting the lock sometimes #32

Closed
bpp9614 opened this issue Dec 27, 2017 · 11 comments
Closed

IsAcquired not getting the lock sometimes #32

bpp9614 opened this issue Dec 27, 2017 · 11 comments

Comments

@bpp9614
Copy link

bpp9614 commented Dec 27, 2017

We are using Redis Windows version (latest). We are using Redlock.NET to lock the DBs. Everyday, for about 30mnts to 2 hours no one gets the lock. This is not very consistent. Works most of the time, expect when those 30mnts to 2 hour.

I don't see any issues with Redis on logfiles.

We have the lock expiry set to 1 mnt, but the lock doesn't seem to be expiring.
Settings:
Expiry: 60 sec, Retry: 1 sec, Wait: 20 sec

Redlock.NET version: 1.7.5
StackExchange.Redis: 1.2.6.0

Code:

 using (var redisLock = redislockFactory.Create(redisKeyToLock, redisExpiry, redisWait, redisRetry))
                        {
                            if (redisLock.IsAcquired) // make sure we got the lock
                            {
                               //Business Logic to update the cache
                               
                            }
                      }
redisLock.Dispose(); // release redis lock by explicitly disposing it

Logs in descending order:

id	CreatedDate	LogLevel	LogMessage
146237812	2017-12-26 11:54:40.000	Debug	Could not acquire quorum after 3 attempts, giving up: myKey (6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5)
146237465	2017-12-26 11:54:39.000	Debug	Lock attempt 1/3: myKey (6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5), expiry: 00:01:00
146237466	2017-12-26 11:54:39.000	Trace	LockInstance enter xxxxxxx:6379 (master): redlock-myKey, 6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5, 00:01:00
146237469	2017-12-26 11:54:39.000	Trace	LockInstance exit xxxxxxx:6379 (master): redlock-myKey, 6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5, False
146237471	2017-12-26 11:54:39.000	Debug	Acquired locks for myKey (6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5) in 0/1 instances, quorum: 1, validityTicks: 593978099
146237472	2017-12-26 11:54:39.000	Trace	UnlockInstance enter xxxxxxx:6379 (master): redlock-myKey, 6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5
146237475	2017-12-26 11:54:39.000	Trace	UnlockInstance exit xxxxxxx:6379 (master): redlock-myKey, 6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5, False
146237522	2017-12-26 11:54:39.000	Debug	Lock attempt 2/3: myKey (6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5), expiry: 00:01:00
146237523	2017-12-26 11:54:39.000	Trace	LockInstance enter xxxxxxx:6379 (master): redlock-myKey, 6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5, 00:01:00
146237524	2017-12-26 11:54:39.000	Trace	LockInstance exit xxxxxxx:6379 (master): redlock-myKey, 6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5, False
146237525	2017-12-26 11:54:39.000	Debug	Acquired locks for myKey (6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5) in 0/1 instances, quorum: 1, validityTicks: 593978121
146237526	2017-12-26 11:54:39.000	Trace	UnlockInstance enter xxxxxxx:6379 (master): redlock-myKey, 6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5
146237527	2017-12-26 11:54:39.000	Trace	UnlockInstance exit xxxxxxx:6379 (master): redlock-myKey, 6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5, False
146237544	2017-12-26 11:54:39.000	Debug	Lock attempt 3/3: myKey (6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5), expiry: 00:01:00
146237546	2017-12-26 11:54:39.000	Trace	LockInstance enter xxxxxxx:6379 (master): redlock-myKey, 6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5, 00:01:00
146237549	2017-12-26 11:54:39.000	Trace	LockInstance exit xxxxxxx:6379 (master): redlock-myKey, 6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5, False
146237551	2017-12-26 11:54:39.000	Debug	Acquired locks for myKey (6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5) in 0/1 instances, quorum: 1, validityTicks: 593977454
146237552	2017-12-26 11:54:39.000	Trace	UnlockInstance enter xxxxxxx:6379 (master): redlock-myKey, 6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5
146237556	2017-12-26 11:54:39.000	Trace	UnlockInstance exit xxxxxxx:6379 (master): redlock-myKey, 6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5, False
146237558	2017-12-26 11:54:39.000	Debug	Could not acquire quorum after 3 attempts, giving up: myKey (6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5)
146237213	2017-12-26 11:54:38.000	Debug	Lock attempt 3/3: myKey (6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5), expiry: 00:01:00
146237214	2017-12-26 11:54:38.000	Trace	LockInstance enter xxxxxxx:6379 (master): redlock-myKey, 6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5, 00:01:00
146237217	2017-12-26 11:54:38.000	Trace	LockInstance exit xxxxxxx:6379 (master): redlock-myKey, 6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5, False
146237218	2017-12-26 11:54:38.000	Debug	Acquired locks for myKey (6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5) in 0/1 instances, quorum: 1, validityTicks: 593977102
146237220	2017-12-26 11:54:38.000	Trace	UnlockInstance enter xxxxxxx:6379 (master): redlock-myKey, 6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5
146237223	2017-12-26 11:54:38.000	Trace	UnlockInstance exit xxxxxxx:6379 (master): redlock-myKey, 6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5, False
146237225	2017-12-26 11:54:38.000	Debug	Could not acquire quorum after 3 attempts, giving up: myKey (6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5)
146237170	2017-12-26 11:54:37.000	Debug	Lock attempt 2/3: myKey (6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5), expiry: 00:01:00
146237171	2017-12-26 11:54:37.000	Trace	LockInstance enter xxxxxxx:6379 (master): redlock-myKey, 6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5, 00:01:00
146237172	2017-12-26 11:54:37.000	Trace	LockInstance exit xxxxxxx:6379 (master): redlock-myKey, 6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5, False
146237173	2017-12-26 11:54:37.000	Debug	Acquired locks for myKey (6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5) in 0/1 instances, quorum: 1, validityTicks: 593977542
146237174	2017-12-26 11:54:37.000	Trace	UnlockInstance enter xxxxxxx:6379 (master): redlock-myKey, 6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5
146237175	2017-12-26 11:54:37.000	Trace	UnlockInstance exit xxxxxxx:6379 (master): redlock-myKey, 6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5, False
146237063	2017-12-26 11:54:37.000	Debug	Lock attempt 1/3: myKey (6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5), expiry: 00:01:00
146237064	2017-12-26 11:54:37.000	Trace	LockInstance enter xxxxxxx:6379 (master): redlock-myKey, 6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5, 00:01:00
146237068	2017-12-26 11:54:37.000	Trace	LockInstance exit xxxxxxx:6379 (master): redlock-myKey, 6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5, False

More Logs of not acquiring locks

Could not acquire quorum after 3 attempts, giving up: myKey (ffe47df8-ccc4-4fba-a04b-8ae22381492e)
Could not acquire quorum after 3 attempts, giving up: myKey (073c0f12-84a2-42d5-ac43-77aeefab502a)
Could not acquire quorum after 3 attempts, giving up: myKey (f282c0a7-cc2d-4edd-9a88-1526b89c5f2e)
Could not acquire quorum after 3 attempts, giving up: myKey (b245e22f-a3ad-4b0e-9569-b56040152f7e)
Could not acquire quorum after 3 attempts, giving up: myKey (5dd6f49d-6fd6-4780-8f7b-e4c929e8eb19)
Could not acquire quorum after 3 attempts, giving up: myKey (5723a48b-27f5-48dd-a4d3-8f22812ae53f)
Could not acquire quorum after 3 attempts, giving up: myKey (d68d61c4-e7f3-4c08-8e36-958bfd2d6f83)
Could not acquire quorum after 3 attempts, giving up: myKey (6bd279c5-b094-4962-a225-eb89b825f688)
Could not acquire quorum after 3 attempts, giving up: myKey (5c499083-5b4b-4312-a410-f39af7f6ed05)
Could not acquire quorum after 3 attempts, giving up: myKey (6bd279c5-b094-4962-a225-eb89b825f688)
Could not acquire quorum after 3 attempts, giving up: myKey (5c499083-5b4b-4312-a410-f39af7f6ed05)
Could not acquire quorum after 3 attempts, giving up: myKey (d68d61c4-e7f3-4c08-8e36-958bfd2d6f83)
Could not acquire quorum after 3 attempts, giving up: myKey (d68d61c4-e7f3-4c08-8e36-958bfd2d6f83)
Could not acquire quorum after 3 attempts, giving up: myKey (5ffded6f-ffdb-4661-8192-7d8dfeff44ae)
Could not acquire quorum after 3 attempts, giving up: myKey (1578e26d-0d28-4da5-8e47-e2c3fe3477ca)
@samcook
Copy link
Owner

samcook commented Dec 29, 2017

That's odd - are you able to check redis while this is occurring and see:

  • the value of the redlock key (e.g. GET redlock-myKey) - this should be a GUID that is generated by redlock. If a key exists with a value that doesn't match the current lock's value then it's assumed that another process owns the lock. For the lock in your logs above it was 6fd7eb8c-2a92-4520-a1fe-105f6b49e9f5. If there is a key with another value, you could try searching through your logs to see if it was previous one that was set.
  • the TTL remaining (e.g. PTTL redlock-myKey) - this should be, at most, the expiry time (so 60,000 if your expiry is 60 seconds).

If the key doesn't exist, but redlock fails to get a lock, that would possibly indicate a communication or timeout issue with redis, although you should see something in the logs if you're logging at debug level.

Given that the lock is unavailable for 20 mins to 2 hours, it seems likely that either another process is holding the lock during that period (if it was an abandoned lock it should expire after the timeout - 60 seconds in your case).

Also, you don't need to explicitly dispose the redis lock after the using block, it will automatically be disposed as it goes out of scope.

@bpp9614
Copy link
Author

bpp9614 commented Jan 2, 2018

Is there a way to know programatically who is holding the lock. If so, is there a way to force release the lock?

@samcook
Copy link
Owner

samcook commented Jan 2, 2018

There isn't currently a way to programmatically know who has the lock (although I suppose RedLock could be altered to include some identifying information in the lock value).

And there isn't a way to programatically force release a lock from within RedLock (because that's generally a bad idea). You could just delete the redis key though (however, if it exists then presumably something created it, or is keeping it alive, so it would probably be best to try and figure out why it's still there).

@bpp9614
Copy link
Author

bpp9614 commented Jan 16, 2018

I did a trace for a lockid 06935f4d-e327-467a-9924-e648ef74e279. Even if the key is acquired on the 1st attempt, redlock is trying again to get it and finally giving up. I am puzzled why it should do so if it acquires the lock on 1st attempt?

CreatedDate	LogLevel	LogMessage
2018-01-16 09:32:45.000	Debug	Lock attempt 1/3: myKey (06935f4d-e327-467a-9924-e648ef74e279), expiry: 00:00:01
2018-01-16 09:32:45.000	Trace	LockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, 00:00:01
2018-01-16 09:32:45.000	Trace	LockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, True
2018-01-16 09:32:45.000	Debug	Acquired locks for myKey (06935f4d-e327-467a-9924-e648ef74e279) in 1/1 instances, quorum: 1, validityTicks: 9878031
2018-01-16 09:32:45.000	Info	Acquired lock: myKey (06935f4d-e327-467a-9924-e648ef74e279)
2018-01-16 09:32:45.000	Debug	Disposing myKey (06935f4d-e327-467a-9924-e648ef74e279)
2018-01-16 09:32:45.000	Trace	UnlockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279
2018-01-16 09:32:45.000	Trace	UnlockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, True
2018-01-16 09:32:44.000	Debug	Lock attempt 1/3: myKey (06935f4d-e327-467a-9924-e648ef74e279), expiry: 00:00:01
2018-01-16 09:32:44.000	Trace	LockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, 00:00:01
2018-01-16 09:32:44.000	Trace	LockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:44.000	Debug	Acquired locks for myKey (06935f4d-e327-467a-9924-e648ef74e279) in 0/1 instances, quorum: 1, validityTicks: 9877658
2018-01-16 09:32:44.000	Trace	UnlockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279
2018-01-16 09:32:44.000	Trace	UnlockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:44.000	Debug	Lock attempt 2/3: myKey (06935f4d-e327-467a-9924-e648ef74e279), expiry: 00:00:01
2018-01-16 09:32:44.000	Trace	LockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, 00:00:01
2018-01-16 09:32:44.000	Trace	LockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:44.000	Debug	Acquired locks for myKey (06935f4d-e327-467a-9924-e648ef74e279) in 0/1 instances, quorum: 1, validityTicks: 9877660
2018-01-16 09:32:44.000	Trace	UnlockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279
2018-01-16 09:32:44.000	Trace	UnlockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:44.000	Debug	Lock attempt 3/3: myKey (06935f4d-e327-467a-9924-e648ef74e279), expiry: 00:00:01
2018-01-16 09:32:44.000	Trace	LockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, 00:00:01
2018-01-16 09:32:44.000	Trace	LockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:44.000	Debug	Acquired locks for myKey (06935f4d-e327-467a-9924-e648ef74e279) in 0/1 instances, quorum: 1, validityTicks: 9878252
2018-01-16 09:32:44.000	Trace	UnlockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279
2018-01-16 09:32:44.000	Trace	UnlockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:44.000	Debug	Could not acquire quorum after 3 attempts, giving up: myKey (06935f4d-e327-467a-9924-e648ef74e279)
2018-01-16 09:32:43.000	Debug	Lock attempt 3/3: myKey (06935f4d-e327-467a-9924-e648ef74e279), expiry: 00:00:01
2018-01-16 09:32:43.000	Trace	LockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, 00:00:01
2018-01-16 09:32:43.000	Trace	LockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:43.000	Debug	Acquired locks for myKey (06935f4d-e327-467a-9924-e648ef74e279) in 0/1 instances, quorum: 1, validityTicks: 9878047
2018-01-16 09:32:43.000	Trace	UnlockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279
2018-01-16 09:32:43.000	Trace	UnlockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:43.000	Debug	Could not acquire quorum after 3 attempts, giving up: myKey (06935f4d-e327-467a-9924-e648ef74e279)
2018-01-16 09:32:42.000	Debug	Lock attempt 1/3: myKey (06935f4d-e327-467a-9924-e648ef74e279), expiry: 00:00:01
2018-01-16 09:32:42.000	Trace	LockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, 00:00:01
2018-01-16 09:32:42.000	Trace	LockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:42.000	Debug	Acquired locks for myKey (06935f4d-e327-467a-9924-e648ef74e279) in 0/1 instances, quorum: 1, validityTicks: 9878227
2018-01-16 09:32:42.000	Trace	UnlockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279
2018-01-16 09:32:42.000	Trace	UnlockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:42.000	Debug	Lock attempt 2/3: myKey (06935f4d-e327-467a-9924-e648ef74e279), expiry: 00:00:01
2018-01-16 09:32:42.000	Trace	LockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, 00:00:01
2018-01-16 09:32:42.000	Trace	LockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:42.000	Debug	Acquired locks for myKey (06935f4d-e327-467a-9924-e648ef74e279) in 0/1 instances, quorum: 1, validityTicks: 9878590
2018-01-16 09:32:42.000	Trace	UnlockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279
2018-01-16 09:32:42.000	Trace	UnlockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:41.000	Debug	Lock attempt 1/3: myKey (06935f4d-e327-467a-9924-e648ef74e279), expiry: 00:00:01
2018-01-16 09:32:41.000	Trace	LockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, 00:00:01
2018-01-16 09:32:41.000	Trace	LockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:41.000	Debug	Acquired locks for myKey (06935f4d-e327-467a-9924-e648ef74e279) in 0/1 instances, quorum: 1, validityTicks: 9878463
2018-01-16 09:32:41.000	Trace	UnlockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279
2018-01-16 09:32:41.000	Trace	UnlockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:41.000	Debug	Lock attempt 2/3: myKey (06935f4d-e327-467a-9924-e648ef74e279), expiry: 00:00:01
2018-01-16 09:32:41.000	Trace	LockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, 00:00:01
2018-01-16 09:32:41.000	Trace	LockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:41.000	Debug	Acquired locks for myKey (06935f4d-e327-467a-9924-e648ef74e279) in 0/1 instances, quorum: 1, validityTicks: 9878305
2018-01-16 09:32:41.000	Trace	UnlockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279
2018-01-16 09:32:41.000	Trace	UnlockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:41.000	Debug	Lock attempt 3/3: myKey (06935f4d-e327-467a-9924-e648ef74e279), expiry: 00:00:01
2018-01-16 09:32:41.000	Trace	LockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, 00:00:01
2018-01-16 09:32:41.000	Trace	LockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:41.000	Debug	Acquired locks for myKey (06935f4d-e327-467a-9924-e648ef74e279) in 0/1 instances, quorum: 1, validityTicks: 9878408
2018-01-16 09:32:41.000	Trace	UnlockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279
2018-01-16 09:32:41.000	Trace	UnlockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:41.000	Debug	Could not acquire quorum after 3 attempts, giving up: myKey (06935f4d-e327-467a-9924-e648ef74e279)
2018-01-16 09:32:40.000	Trace	UnlockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279
2018-01-16 09:32:40.000	Trace	UnlockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:40.000	Debug	Lock attempt 3/3: myKey (06935f4d-e327-467a-9924-e648ef74e279), expiry: 00:00:01
2018-01-16 09:32:40.000	Trace	LockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, 00:00:01
2018-01-16 09:32:40.000	Trace	LockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:40.000	Debug	Acquired locks for myKey (06935f4d-e327-467a-9924-e648ef74e279) in 0/1 instances, quorum: 1, validityTicks: 9878669
2018-01-16 09:32:40.000	Trace	UnlockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279
2018-01-16 09:32:40.000	Trace	UnlockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:40.000	Debug	Could not acquire quorum after 3 attempts, giving up: myKey (06935f4d-e327-467a-9924-e648ef74e279)
2018-01-16 09:32:40.000	Debug	Lock attempt 2/3: myKey (06935f4d-e327-467a-9924-e648ef74e279), expiry: 00:00:01
2018-01-16 09:32:40.000	Trace	LockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, 00:00:01
2018-01-16 09:32:40.000	Trace	LockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:40.000	Debug	Acquired locks for myKey (06935f4d-e327-467a-9924-e648ef74e279) in 0/1 instances, quorum: 1, validityTicks: 9878582
2018-01-16 09:32:39.000	Debug	Lock attempt 1/3: myKey (06935f4d-e327-467a-9924-e648ef74e279), expiry: 00:00:01
2018-01-16 09:32:39.000	Trace	LockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, 00:00:01
2018-01-16 09:32:39.000	Trace	LockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:39.000	Debug	Acquired locks for myKey (06935f4d-e327-467a-9924-e648ef74e279) in 0/1 instances, quorum: 1, validityTicks: 9878078
2018-01-16 09:32:39.000	Trace	UnlockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279
2018-01-16 09:32:39.000	Trace	UnlockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:38.000	Debug	Lock attempt 1/3: myKey (06935f4d-e327-467a-9924-e648ef74e279), expiry: 00:00:01
2018-01-16 09:32:38.000	Trace	LockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, 00:00:01
2018-01-16 09:32:38.000	Trace	LockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:38.000	Debug	Acquired locks for myKey (06935f4d-e327-467a-9924-e648ef74e279) in 0/1 instances, quorum: 1, validityTicks: 9878035
2018-01-16 09:32:38.000	Trace	UnlockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279
2018-01-16 09:32:38.000	Trace	UnlockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:38.000	Debug	Lock attempt 2/3: myKey (06935f4d-e327-467a-9924-e648ef74e279), expiry: 00:00:01
2018-01-16 09:32:38.000	Trace	LockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, 00:00:01
2018-01-16 09:32:38.000	Trace	LockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:38.000	Debug	Acquired locks for myKey (06935f4d-e327-467a-9924-e648ef74e279) in 0/1 instances, quorum: 1, validityTicks: 9878338
2018-01-16 09:32:38.000	Trace	UnlockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279
2018-01-16 09:32:38.000	Trace	UnlockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:38.000	Debug	Lock attempt 3/3: myKey (06935f4d-e327-467a-9924-e648ef74e279), expiry: 00:00:01
2018-01-16 09:32:38.000	Trace	LockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, 00:00:01
2018-01-16 09:32:38.000	Trace	LockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:38.000	Debug	Acquired locks for myKey (06935f4d-e327-467a-9924-e648ef74e279) in 0/1 instances, quorum: 1, validityTicks: 9878680
2018-01-16 09:32:38.000	Trace	UnlockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279
2018-01-16 09:32:38.000	Trace	UnlockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:38.000	Debug	Could not acquire quorum after 3 attempts, giving up: myKey (06935f4d-e327-467a-9924-e648ef74e279)
2018-01-16 09:32:37.000	Debug	Lock attempt 1/3: myKey (06935f4d-e327-467a-9924-e648ef74e279), expiry: 00:00:01
2018-01-16 09:32:37.000	Trace	LockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, 00:00:01
2018-01-16 09:32:37.000	Trace	LockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:37.000	Debug	Acquired locks for myKey (06935f4d-e327-467a-9924-e648ef74e279) in 0/1 instances, quorum: 1, validityTicks: 9878040
2018-01-16 09:32:37.000	Trace	UnlockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279
2018-01-16 09:32:37.000	Trace	UnlockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:37.000	Debug	Lock attempt 2/3: myKey (06935f4d-e327-467a-9924-e648ef74e279), expiry: 00:00:01
2018-01-16 09:32:37.000	Trace	LockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, 00:00:01
2018-01-16 09:32:37.000	Trace	LockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:37.000	Debug	Acquired locks for myKey (06935f4d-e327-467a-9924-e648ef74e279) in 0/1 instances, quorum: 1, validityTicks: 9878198
2018-01-16 09:32:37.000	Trace	UnlockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279
2018-01-16 09:32:37.000	Trace	UnlockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:37.000	Debug	Lock attempt 3/3: myKey (06935f4d-e327-467a-9924-e648ef74e279), expiry: 00:00:01
2018-01-16 09:32:37.000	Trace	LockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, 00:00:01
2018-01-16 09:32:37.000	Trace	LockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:37.000	Debug	Acquired locks for myKey (06935f4d-e327-467a-9924-e648ef74e279) in 0/1 instances, quorum: 1, validityTicks: 9878275
2018-01-16 09:32:37.000	Trace	UnlockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279
2018-01-16 09:32:37.000	Trace	UnlockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:37.000	Debug	Could not acquire quorum after 3 attempts, giving up: myKey (06935f4d-e327-467a-9924-e648ef74e279)
2018-01-16 09:32:36.000	Debug	Lock attempt 3/3: myKey (06935f4d-e327-467a-9924-e648ef74e279), expiry: 00:00:01
2018-01-16 09:32:36.000	Trace	LockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, 00:00:01
2018-01-16 09:32:36.000	Trace	LockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:36.000	Debug	Acquired locks for myKey (06935f4d-e327-467a-9924-e648ef74e279) in 0/1 instances, quorum: 1, validityTicks: 9877916
2018-01-16 09:32:36.000	Trace	UnlockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279
2018-01-16 09:32:36.000	Trace	UnlockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:36.000	Debug	Could not acquire quorum after 3 attempts, giving up: myKey (06935f4d-e327-467a-9924-e648ef74e279)
2018-01-16 09:32:35.000	Debug	Lock attempt 1/3: myKey (06935f4d-e327-467a-9924-e648ef74e279), expiry: 00:00:01
2018-01-16 09:32:35.000	Trace	LockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, 00:00:01
2018-01-16 09:32:35.000	Trace	LockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:35.000	Debug	Acquired locks for myKey (06935f4d-e327-467a-9924-e648ef74e279) in 0/1 instances, quorum: 1, validityTicks: 9877921
2018-01-16 09:32:35.000	Trace	UnlockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279
2018-01-16 09:32:35.000	Trace	UnlockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:35.000	Debug	Lock attempt 2/3: myKey (06935f4d-e327-467a-9924-e648ef74e279), expiry: 00:00:01
2018-01-16 09:32:35.000	Trace	LockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, 00:00:01
2018-01-16 09:32:35.000	Trace	LockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False
2018-01-16 09:32:35.000	Debug	Acquired locks for myKey (06935f4d-e327-467a-9924-e648ef74e279) in 0/1 instances, quorum: 1, validityTicks: 9878443
2018-01-16 09:32:35.000	Trace	UnlockInstance enter xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279
2018-01-16 09:32:35.000	Trace	UnlockInstance exit xxx-xxxxx:6379 (master): redlock-myKey, 06935f4d-e327-467a-9924-e648ef74e279, False

@samcook
Copy link
Owner

samcook commented Jan 16, 2018

Those logs seem to be ordered quite strange - descending by timestamp, but in ascending blocks for each second?

At any rate, if I'm reading them correctly it appears that it tries repeatedly (but fails) to get a lock until eventually it managed to do so at 09:32:45.000 (Acquired locks for myKey (06935f4d-e327-467a-9924-e648ef74e279) in 1/1 instances, quorum: 1, validityTicks: 9878031), after which is it immediately disposed of.

Do you know whether the redis server was available during the time it was failing, and if so, whether there was already an existing key redlock-myKey?

Are you able to supply some code that reliably reproduces the problem?

@bpp9614
Copy link
Author

bpp9614 commented Jan 16, 2018

Yes, Redis is available all the time. This is our prod environment and I can never reproduce in Test or Dev. The logs are just in descending order. Yes, there is a key myKey in Redis, which the application acquires to lock Redis to perform cache manipulation.

@samcook
Copy link
Owner

samcook commented Jan 17, 2018

Those logs appear to be consistent with the key in redis already existing when the attempt to acquire the lock occurs.

When you call redlockFactory.Create("myKey", expiry, wait, retry), it attempts to set a string key in redis named redlock-myKey, if it does not already exist.

If a key with that name does already exist, it will retry up to two more times with a small random sleep in between (to avoid two processes racing for the same lock continually blocking each other), before declaring that it was not able to acquire the lock.

Since you're doing a blocking wait in this case (wait and retry have been passed to the Create method), it will then sleep for retry seconds (1 second) before trying again, repeating until either a lock is acquired, or wait seconds (20 seconds) have passed.

The key value (lock id) that it uses (e.g. 06935f4d-e327-467a-9924-e648ef74e279) will remain the same for this entire process.

In order to solve this I think you need to find out what is holding the redis key during the time that you aren't able to acquire the lock.

Some possibilities:

  • another process running RedLock using the same key currently has the lock held.
  • a process had a lock, but crashed or quit unexpectedly without releasing the lock first (the key should automatically expire after the specified timeout, in this case 60 seconds).
  • something non-RedLock related setting a key in Redis with the same name that RedLock uses.

@samcook
Copy link
Owner

samcook commented Feb 13, 2018

If you're still having trouble with this, I've pushed a pre-release package version 2.1.0-pre1 to nuget which includes changes that give more detail about why locks failed to acquire.

See #24 for more details.

@samcook samcook closed this as completed Sep 5, 2018
@Nadav-Revuze
Copy link

In order to solve this I think you need to find out what is holding the redis key during the time that you aren't able to acquire the lock.

doesnt it suppose to lock the same key i want to write to from another process ?

from on process i read from key and do some work, from another process i write to the same key

@samcook
Copy link
Owner

samcook commented Apr 23, 2020

The key is used to lock a particular resource for one process only. If one process holds the lock key in redis, another process attempting to acquire a lock with the same key will fail (or be blocked until it is available).

@karthickgw
Copy link

Hi @samcook
I was getting IsAquired always false. Could you please verify the attached screenshot.
The RedLock.net version is 2.0.0. .Net Version 4.6
image

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants