Re: [jgroups-users] Locks get locked forever after a cluster members leaves

On 10/23/2017 02:54 PM, Questions/problems related to using JGroups wrote:
>
>
> On 19/10/17 09:45, Questions/problems related to using JGroups via javagroups-users wrote:
>> For extra info, this is how the wrapping of the locks works. I only use our own lock service to fetch lock instances, there are no other code paths that use regular locking on the JGroups lock. What I see in my own logs is that there is a lock queue that indicates ' L(writelock/regular/instance_2_1/,NodeAddress-2_node2-40388::373)' is a regular lock. This is the lock that causes the dead lock (if I'm correct) but I'm not sure why that lock is in the queue as a regular lock.
>
>
> What do you mean? You must have called Lock.lock(), right? Below you mention that all lock() calls are changed into corresponding tryLock() calls, but the output you showed clearly indicate that the queue has a regular lock() request by 373 pending, followed by a tryLock() request...

I need some more time to reply to your first response but this one is easy. I *never* use a regular lock() call on the JGroups lock (I wrap them, see example), the only calls done on the JGroups lock are tryLock(..) calls. What I saw in the source code of JGroups is that the is_trylock flag of a ClientLock is reset to false in some situations (like a call to _unlock).

I saw this too in the logs and tripple checked to make sure all of the calls on the JGroups lock are tryLock calls and they are.

>
>> public class OurLockService {
>>      class LoggingLock implements Lock {
>>          private Lock actualLock;
>>
>>          public LoggingLock(Lock actualLock) {
>>              this.actualLock = actualLock;
>>          }
>>          /*
>>           * This locks logs every call to lock() etc
>>           */
>>      }
>>
>>      class TryLockLock implements Lock {
>>          private Lock actualLock;
>>
>>          public TryLockLock(Lock actualLock) {
>>              this.actualLock = actualLock;
>>          }
>>          /*
>>           * This locks changes all calls to lock() into a tryLock with a time out
>>           * of 20 seconds and throws an unchecked exception when the tryLock()
>>           * call times out
>>           */
>>      }
>>
>>      private org.jgroups.blocks.locking.LockService jgLockService;
>>
>>      public Lock getLock(String name) {
>>          Lock jgLock = jgLockService.getLock(name);
>>          Lock loggingLock = new LoggingLock(jgLock);
>>          Lock tryLockLock = new TryLockLock(loggingLock);
>>
>>          return tryLockLock;
>>      }
>> }
>>
>> Met vriendelijke groet / Kind regards,
>> Bram Klein Gunnewiek | Shock Media B.V.
>>
>> Tel: +31 (0)546 - 714360
>> Fax: +31 (0)546 - 714361
>> Web:https://www.shockmedia.nl/
>>
>> On 10/19/2017 08:29 AM, Questions/problems related to using JGroups via javagroups-users wrote:
>>>
>>> I use the central locking protocol extensively (> 10 locks requests per second isn't unusual) in our application thats currently running with 5 cluster members (nodes). I have dead lock issues (e.g. locks that are never released) and I think this is a bug / race condition in the protocol *somewhere*. I did a lot of debugging but can't pinpoint the error so I need some help ;-). The protocol configuration looks like the default TCP nio configuration with central locking configured like this:
>>>
>>>     <CENTRAL_LOCK num_backups="2" />
>>>
>>>     <COUNTER bypass_bundling="true"
>>>              num_backups="9999"/>
>>>
>>> I currently use JGroups 4.0.4.Final but I've seen this is other versions too.
>>>
>>> It looks like I have these problems when the coordinator of the cluster leaves (gracefully). When that happens and a new view is installed I see that some locks stay (or get?) locked forever. All locks I use are wrapped in what I call a 'logging try lock'. I never use regular lock() calls, it's always a trylock with a timeout of 20 seconds. I log *every* trylock request (and the result) and unlock() call. Because of that I should be able to tell if a lock is acquired but never released. Thats not te case so I suspect it has something to do with taking over the coordination of the locks.
>>>
>>> I have some logs of a situation where node1 (old coördinator) stops and node2 becomes the new coördinator. Right after that cluster members fail to acquire the lock 'writelock/regular/instance_2_1/' because it doesn't get locked within 20 seconds.
>>>
>>> Node2 installing a new view after node1 leaves:
>>>
>>>     10-18 09:44:36.840 1966180821 [jgroups-25500,yy,NodeAddress-2_node2-40388] DEBUG org.jgroups.protocols.pbcast.GMS - NodeAddress-2_node2-40388: installing view [NodeAddress-2_node2-40388|43] (4) [NodeAddress-2_node2-40388, NodeAddress-3_node3-45507, NodeAddress-6_node4-63954, NodeAddress-7_node5-32742]
>>>     10-18 09:44:36.841 1966180822 [jgroups-25500,yy,NodeAddress-2_node2-40388] DEBUG org.jgroups.protocols.pbcast.STABLE - resuming message garbage collection
>>>     10-18 09:44:36.841 1966180822 [jgroups-25500,yy,NodeAddress-2_node2-40388] DEBUG o.jgroups.protocols.pbcast.NAKACK2 - NodeAddress-2_node2-40388: removed NodeAddress-1_node1-3442 from xmit_table (not member anymore)
>>>     10-18 09:44:36.849 1966180830 [jgroups-25500,yy,NodeAddress-2_node2-40388] DEBUG nl.x.jgroups.c.i.a - handling local view change: [NodeAddress-2_node2-40388|43] (4) [NodeAddress-2_node2-40388, NodeAddress-3_node3-45507, NodeAddress-6_node4-63954, NodeAddress-7_node5-32742]
>>>     ...
>>>     10-18 09:44:36.884 1966180865 [jgroups-25500,yy,NodeAddress-2_node2-40388] DEBUG org.jgroups.protocols.CENTRAL_LOCK - view=[NodeAddress-2_node2-40388|43] (4) [NodeAddress-2_node2-40388, NodeAddress-3_node3-45507, NodeAddress-6_node4-63954, NodeAddress-7_node5-32742]
>>>     10-18 09:44:36.884 1966180865 [jgroups-25500,yy,NodeAddress-2_node2-40388] DEBUG org.jgroups.protocols.CENTRAL_LOCK - local_addr=NodeAddress-2_node2-40388, coord=NodeAddress-2_node2-40388, is_coord=true
>>>     10-18 09:44:36.909 1966180890 [jgroups-25500,yy,NodeAddress-2_node2-40388] DEBUG org.jgroups.protocols.COUNTER - view=[NodeAddress-2_node2-40388|43] (4) [NodeAddress-2_node2-40388, NodeAddress-3_node3-45507, NodeAddress-6_node4-63954, NodeAddress-7_node5-32742]
>>>     10-18 09:44:36.947 1966180928 [pool-1-thread-514351] WARN nl.x.jgroups.b.c - Detected new view!
>>>     10-18 09:44:36.950 1966180931 [pool-1-thread-514351] WARN nl.x.jgroups.b.c - Node NodeAddress-1_node1-3442 left, cancelling any pending requests to that node ...
>>>
>>> Node2 last lock on 'writelock/regular/instance_2_1/':
>>>
>>>     10-18 09:44:01.282 1966145263 [pool-2-thread-7] DEBUG nl.x.util.c.k - -2114432549 Thread (84) pool-2-thread-7 acquired writelock/regular/instance_2_1/
>>>     10-18 09:44:01.285 1966145266 [pool-2-thread-7] DEBUG nl.x.util.c.k - -2114432549 Thread (84) pool-2-thread-7 is releasing writelock/regular/instance_2_1/
>>>     10-18 09:44:01.285 1966145266 [pool-2-thread-7] DEBUG nl.x.util.c.k - -2114432549 Thread (84) pool-2-thread-7 has released writelock/regular/instance_2_1/
>>>
>>> Node2 first time lock on 'writelock/regular/instance_2_1/' fails:
>>>
>>>     10-18 09:45:21.113 1966225094 [pool-2-thread-5] ERROR nl.shockmedia.dds.cluster.jgroups.b - Failed aquiring lock Logging lock for: writelock/regular/instance_2_1/ [unlocked]. Current lock table:
>>>
>>>     server locks:
>>>     writelock/regular/instance_2_1/:
>>>         NodeAddress-2_node2-40388::369,
>>>             queue:
>>> L(writelock/regular/instance_2_1/,NodeAddress-2_node2-40388::373)
>>> TL(writelock/regular/instance_2_1/,NodeAddress-3_node3-45507::413,20000)
>>>
>>>     writelock/regular/instance_2_1/31:
>>>         NodeAddress-2_node2-40388::369,
>>>         queue:
>>> L(writelock/regular/instance_2_1/31,NodeAddress-2_node2-40388::373)
>>>
>>>     writelock/regular/instance_2_1/3635: NodeAddress-3_node3-45507::413
>>>     writelock/regular/instance_2_1/32: NodeAddress-2_node2-40388::46
>>>
>>>     my locks:
>>>         writelock/regular/instance_2_1/
>>>         (NodeAddress-2_node2-40388::369, NodeAddress-2_node2-40388::373, unlocked),
>>>
>>>         writelock/regular/instance_2_1/31
>>>         (NodeAddress-2_node2-40388::369, NodeAddress-2_node2-40388::373, unlocked),
>>>
>>>         writelock/regular/instance_2_1/32
>>>         (NodeAddress-2_node2-40388::46)
>>>
>>> There is no trace anywhere in the logs where node2 acquires a lock on 'writelock/regular/instance_2_1/' and never releases that lock. However if I'm correct the log output says that the lock 'writelock/regular/instance_2_1/' is currently locked by 'NodeAddress-2_node2-40388::369'. This stays like this forever (right?), the only solution is to stop all cluster members and start them again. This is the output of a failed trylock (not locked within 20 seconds) > 1 hour later:
>>>
>>>     10-18 10:54:16.682 1970360663 [RxCachedThreadScheduler-3] ERROR nl.shockmedia.dds.cluster.jgroups.b - Failed aquiring lock Logging lock for: writelock/regular/instance_2_1/ [unlocked]. Current lock table:
>>>     server locks:
>>>     writelock/regular/instance_2_1/: NodeAddress-2_node2-40388::373
>>>     writelock/regular/instance_2_1/3230: NodeAddress-1_node1-6233::120
>>>     writelock/regular/instance_2_1/3434: NodeAddress-2_node2-40388::93
>>>     writelock/regular/instance_2_1/3138: NodeAddress-2_node2-40388::45
>>>     writelock/regular/instance_2_1/31: NodeAddress-2_node2-40388::373
>>>     writelock/regular/instance_2_1/3635: NodeAddress-3_node3-45507::349
>>>     writelock/regular/instance_2_1/3937: NodeAddress-3_node3-45507::95
>>>
>>>     my locks: writelock/regular/instance_2_1/ (NodeAddress-2_node2-40388::369, NodeAddress-2_node2-40388::373, NodeAddress-2_node2-40388::45, unlocked), writelock/regular/instance_2_1/3434 (NodeAddress-2_node2-40388::93), writelock/regular/instance_2_1/3138 (NodeAddress-2_node2-40388::45), writelock/regular/instance_2_1/31 (NodeAddress-2_node2-40388::369, NodeAddress-2_node2-40388::373)
>>>
>>> I need some help in debugging this issue. Its not easy to reproduce, I don't have this problem everytime I shut-down a node, it happens every now and then. Any suggestions?
>>>
>>> -- 
>>> Met vriendelijke groet / Kind regards,
>>> Bram Klein Gunnewiek | Shock Media B.V.
>>>
>>> Tel: +31 (0)546 - 714360
>>> Fax: +31 (0)546 - 714361
>>> Web:https://www.shockmedia.nl/
>>>
>>>
>>> ------------------------------------------------------------------------------
>>> Check out the vibrant tech community on one of the world's most
>>> engaging tech sites, Slashdot.org!http://sdm.link/slashdot
>>>
>>>
>>> _______________________________________________
>>> javagroups-users mailing list
>>> [email protected]
>>> https://lists.sourceforge.net/lists/listinfo/javagroups-users
>>
>>
>>
>> ------------------------------------------------------------------------------
>> Check out the vibrant tech community on one of the world's most
>> engaging tech sites, Slashdot.org! http://sdm.link/slashdot
>>
>>
>>
>> _______________________________________________
>> javagroups-users mailing list
>> [email protected]
>> https://lists.sourceforge.net/lists/listinfo/javagroups-users
>>
>

------------------------------------------------------------------------------
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot

_______________________________________________
javagroups-users mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/javagroups-users