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

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