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

On 10/23/2017 02:50 PM, Questions/problems related to using JGroups wrote:
> So if we look at the server locks only for  server locks only for lock 'writelock/regular/instance_2_1/', we can see that the lock is held by node 40388 with thread-id=369 (shortened node names):
>
>     writelock/regular/instance_2_1/:
>         40388::369,
>             queue:
>                 L(writelock/regular/instance_2_1/,40388::373)
> TL(writelock/regular/instance_2_1/,45507::413,20000)
>
> Thread 373 on the same node has also issued a lock() and is waiting in the queue for the lock to be released by 369.

I don't think this is correct but I could be wrong. I don't call lock() on the JGroups lock, all attempts to aqcuire a lock are done using tryLock(..)

>
> The client locks show that the lock is owned by 369
>    my locks:
>         writelock/regular/instance_2_1/
>         (40388::369, 40388::373, unlocked)
>
>
> Now thread 369 calls unlock() [I assume?].

To be honest, I don't know. I can't find a trace of thread id 369 acquiring a lock on 'writelock/regular/instance_2_1/'. The only traces I can find of a thread with that ID acquiring locks are these, but thats a different lock:

10-18 09:32:30.093 1965454074 [RxCachedThreadScheduler-38] DEBUG ... Thread (369) RxCachedThreadScheduler-38 acquired writelock/regular/virtual_machine_stats_1_1/

The thread id's should match, this is the log statement in my code:

log.debug(LOCK_MARKER, track + " Thread (" + Thread.currentThread().getId() + ") " + Thread.currentThread().getName() + " acquired " + name);

>
> The server locks are correctly changed:
>
>     server locks:
>     writelock/regular/instance_2_1/:     40388::373
>
> We can see that 369 has released the lock and the next thread in the queue (373) has acquired the lock. There are no pending lock requests, as 413 timed out on its tryLock().
>
> However, the client side lock table is incorrect:
>
>     my locks:
>        writelock/regular/instance_2_1/ (40388::369, 40388::373, 40388::45, unlocked),
>
> We can see that 369 has not yet been removed (it should have!) and yet 373 does hold the lock (no 'unlocked' shown)!
>
> I need to investigate further. Questions:
>
> #1 What's your configuration? I assume you don't use FORK do you?

No FORK. We basically use https://github.com/belaban/JGroups/blob/master/conf/tcp-nio.xml with the CENTRAL_LOCK and Counter: https://pastebin.com/YjWCqsBB

>
> #2 I assume use_thread_id_for_lock_owner has not been set to false (default: true)?

Should be default.

>
> #3 How does 369 release its lock? Obviously 40388::369 and 40388::373 are 2 threads running in the same member (node), so it must be a Lock.unlock()? I'm unsure because you mentioned 'the old coordinator left', but in this case, both 369 *and* 373 would have been released...

I don't know. I can't figure it out despite all the logging I do. To be clear: the old coordinator was node 1. I suspect that taking over control over the locking (by node 2) causes these problems (node 2 was the new coordinator), but again I'm not sure.

>
>
> On 19/10/17 08:29, 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