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

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...

> 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
> 

-- 
Bela Ban | http://www.jgroups.org


------------------------------------------------------------------------------
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