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

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.

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