NPE on Locking.handleDeleteLockRequest -------------------------------------- Key: JGRP-1621 URL: https://issues.jboss.org/browse/JGRP-1621 Project: JGroups Issue Type: Bug Affects Versions: 2.12.1 Reporter: freeliuade freeliuade Assignee: Bela Ban Fix For: 3.3 meet NPE on Locking.handleDeleteLockRequest, this NPE seems happens on the network full bandwidth. and it seems this exception will result in a lock can't be unlock. I'm pretty sure a locker has called unlock, but using LockService.printLocks() still can find the locker is be holding by a thread. below is the log: 03:00:00,881 WARN [GMS] hyliuds2-8321: not member of view [hyliuds1-33648|2] [hyliuds1-33648]; discarding it 03:00:00,890 WARN [GMS] hyliuds2-30414: not member of view [hyliuds1-3567|4] [hyliuds1-3567, node2-9324, node2-33852]; discarding it 03:00:00,886 WARN [GMS] hyliuds2-13134: not member of view [hyliuds1-13050|4] [hyliuds1-13050, node2-62142, node2-26805]; discarding it 03:00:00,924 WARN [GMS] hyliuds2-10154: not member of view [hyliuds1-51819|4] [hyliuds1-51819, node2-14763, node2-26168]; discarding it 03:00:01,264 WARN [GMS] jnp://10.101.7.172:1100: not member of view [jnp://10.101.7.24:1100|2] [jnp://10.101.7.24:1100]; discarding it 03:00:02,368 WARN [VIEW_SYNC] discarding view as I (hyliuds2-30414) am not member of view ([hyliuds1-3567|4] [hyliuds1-3567, node2-9324, node2-33852]) 03:00:03,659 WARN [GMS] hyliuds2-13134: failed to collect all ACKs (expected=4) for view MergeView::[node2-62142|5] [node2-62142, hyliuds2-13134, node2-26805, hyliuds1-13050], subgroups=[[hyliuds1-13050|4] [hyliuds1-13050, node2-62142, node2-26805], [hyliuds2-13134|3] [hyliuds2-13134]] after 2000ms, missing ACKs from [node2-62142, node2-26805] 03:00:06,019 INFO [DomainManager] Installing App sla in domain DefaultDomain. 03:00:06,021 INFO [DomainManager] App sla is installed in domain DefaultDomain. 03:00:19,321 INFO [StateCache] Accept a new Node list "[jnp://10.101.7.24:1100, jnp://10.101.7.172:1100]" 03:00:33,586 WARN [VIEW_SYNC] discarding view as I (hyliuds2-30414) am not member of view ([hyliuds1-3567|4] [hyliuds1-3567, node2-9324, node2-33852]) 03:00:50,634 INFO [StateCache] Accept a new Node list "[jnp://10.101.7.24:1100, jnp://10.101.7.172:1100]" 03:01:03,585 WARN [VIEW_SYNC] discarding view as I (hyliuds2-30414) am not member of view ([hyliuds1-3567|4] [hyliuds1-3567, node2-9324, node2-33852]) 03:01:30,951 INFO [DomainManager] Installing App dojoclient in domain DefaultDomain. 03:01:30,971 INFO [DomainManager] App dojoclient is installed in domain DefaultDomain. 03:01:41,450 WARN [VIEW_SYNC] discarding view as I (hyliuds2-10154) am not member of view ([hyliuds1-51819|4] [hyliuds1-51819, node2-14763, node2-26168]) 03:01:49,799 WARN [VIEW_SYNC] discarding view as I (hyliuds2-30414) am not member of view ([hyliuds1-3567|4] [hyliuds1-3567, node2-9324, node2-33852]) 03:02:02,298 WARN [VIEW_SYNC] discarding view as I (hyliuds2-10154) am not member of view ([hyliuds1-51819|4] [hyliuds1-51819, node2-14763, node2-26168]) 03:03:33,370 WARN [VIEW_SYNC] discarding view as I (hyliuds2-10154) am not member of view ([hyliuds1-51819|4] [hyliuds1-51819, node2-14763, node2-26168]) 03:04:26,623 WARN [GMS] hyliuds2-8321: not member of view [hyliuds1-33648|4] [hyliuds1-33648]; discarding it 03:04:35,922 WARN [NAKACK] hyliuds2-8321: dropped message from hyliuds1-33648 (not in table [hyliuds2-8321]), view=[hyliuds2-8321|5] [hyliuds2-8321] 03:04:35,922 WARN [NAKACK] hyliuds2-8321: dropped message from hyliuds1-33648 (not in table [hyliuds2-8321]), view=[hyliuds2-8321|5] [hyliuds2-8321] 03:04:37,106 WARN [NAKACK] hyliuds2-8321: dropped message from hyliuds1-33648 (not in table [hyliuds2-8321]), view=[hyliuds2-8321|5] [hyliuds2-8321] 03:04:53,227 WARN [NAKACK] hyliuds2-8321: dropped message from hyliuds1-33648 (not in table [hyliuds2-8321]), view=[hyliuds2-8321|5] [hyliuds2-8321] 03:04:53,227 WARN [NAKACK] hyliuds2-8321: dropped message from hyliuds1-33648 (not in table [hyliuds2-8321]), view=[hyliuds2-8321|5] [hyliuds2-8321] 03:04:53,227 WARN [NAKACK] hyliuds2-8321: dropped message from hyliuds1-33648 (not in table [hyliuds2-8321]), view=[hyliuds2-8321|5] [hyliuds2-8321] 03:04:53,228 WARN [NAKACK] hyliuds2-8321: dropped message from hyliuds1-33648 (not in table [hyliuds2-8321]), view=[hyliuds2-8321|5] [hyliuds2-8321] 03:04:53,228 WARN [NAKACK] hyliuds2-8321: dropped message from hyliuds1-33648 (not in table [hyliuds2-8321]), view=[hyliuds2-8321|5] [hyliuds2-8321] 03:04:53,527 WARN [NAKACK] hyliuds2-8321: dropped message from hyliuds1-33648 (not in table [hyliuds2-8321]), view=[hyliuds2-8321|5] [hyliuds2-8321] 03:04:54,460 INFO [DomainManager] Deploying project "/apps/sla/projects/SLAAppletProject$Deployment" with release tag "TipOfTrunk" and deployment configuration "Deployment". The overwrite flag is true. The required Runtime Server is "DefaultPool/". The required Feed Server is "auto". The required Data Source for Runtime Server is "auto". The required Data Source for Feed Server is "auto". 03:04:54,837 INFO [DomainManager] Project "/apps/sla/projects/SLAAppletProject$Deployment" has been dispatched with Runtime Server "DefaultPool/rs2", Feed Server "fs", Runtime Server Data Source "/vitria/m3o/datasource/DefaultDomain/datasource", Feed Server Data Source "/vitria/m3o/datasource/DefaultDomain/datasource". 03:04:54,986 WARN [NAKACK] hyliuds2-8321: dropped message from hyliuds1-33648 (not in table [hyliuds2-8321]), view=[hyliuds2-8321|5] [hyliuds2-8321] 03:04:54,987 WARN [NAKACK] hyliuds2-8321: dropped message from hyliuds1-33648 (not in table [hyliuds2-8321]), view=[hyliuds2-8321|5] [hyliuds2-8321] 03:04:56,972 WARN [NAKACK] hyliuds2-8321: dropped message from hyliuds1-33648 (not in table [hyliuds2-8321]), view=[hyliuds2-8321|5] [hyliuds2-8321] 03:05:03,650 INFO [DomainManager] Data Source "/vitria/m3o/datasource/DefaultDomain/datasource" was deployed to RuntimeServer "DefaultPool/rs2". 03:05:03,692 WARN [NAKACK] hyliuds2-8321: dropped message from hyliuds1-33648 (not in table [hyliuds2-8321]), view=[hyliuds2-8321|5] [hyliuds2-8321] 03:05:03,692 WARN [NAKACK] hyliuds2-8321: dropped message from hyliuds1-33648 (not in table [hyliuds2-8321]), view=[hyliuds2-8321|5] [hyliuds2-8321] 03:05:04,387 INFO [DomainManager] Data Source "/vitria/m3o/datasource/DefaultDomain/datasource" was deployed to FeedServer "fs". 03:05:04,956 INFO [DomainManager] Feed "/apps/sla/projects/SLAAppletProject$Deployment/Vitria/Feed/EventSourceExceptionFeed" was deployed to FeedServer "fs". 03:05:05,000 WARN [NAKACK] hyliuds2-8321: dropped message from hyliuds1-33648 (not in table [hyliuds2-8321]), view=[hyliuds2-8321|5] [hyliuds2-8321] 03:05:05,001 WARN [NAKACK] hyliuds2-8321: dropped message from hyliuds1-33648 (not in table [hyliuds2-8321]), view=[hyliuds2-8321|5] [hyliuds2-8321] 03:05:05,994 INFO [DomainManager] Feed "/apps/sla/projects/SLAAppletProject$Deployment/Feeds/KPINotifications" was deployed to FeedServer "fs". 03:05:06,991 WARN [NAKACK] hyliuds2-8321: dropped message from hyliuds1-33648 (not in table [hyliuds2-8321]), view=[hyliuds2-8321|5] [hyliuds2-8321] 03:05:11,047 WARN [NAKACK] hyliuds2-8321: dropped message from hyliuds1-33648 (not in table [hyliuds2-8321]), view=[hyliuds2-8321|5] [hyliuds2-8321] 03:05:13,003 INFO [DomainManager] Project "/apps/sla/projects/SLAAppletProject$Deployment" successfully deployed on server "DefaultPool/rs2". 03:05:13,007 INFO [DomainManager] Notify an event with type "Deploy". 04:57:15,746 WARN [NAKACK] hyliuds2-10154: dropped message from hyliuds1-51819 (not in table [node2-14763, node2-26168, hyliuds2-10154]), view=[node2-14763|6] [node2-14763, hyliuds2-10154, node2-26168] 04:57:15,785 WARN [NAKACK] hyliuds2-10154: dropped message from hyliuds1-51819 (not in table [node2-14763, node2-26168, hyliuds2-10154]), view=[node2-14763|6] [node2-14763, hyliuds2-10154, node2-26168] 04:57:19,956 WARN [NAKACK] hyliuds2-8321: dropped message from hyliuds1-33648 (not in table [hyliuds2-8321]), view=[hyliuds2-8321|7] [hyliuds2-8321] 04:57:35,009 WARN [NAKACK] hyliuds2-8321: dropped message from hyliuds1-33648 (not in table [hyliuds2-8321]), view=[hyliuds2-8321|7] [hyliuds2-8321] 04:57:43,024 ERROR [UNICAST] couldn't deliver message [dst: hyliuds2-8321, src: hyliuds1-33648 (3 headers), size=95 bytes, flags=DONT_BUNDLE] java.lang.NullPointerException at org.jgroups.protocols.Locking.handleDeleteLockRequest(Locking.java:505) at org.jgroups.protocols.Locking.up(Locking.java:243) at org.jgroups.protocols.pbcast.STATE_TRANSFER.up(STATE_TRANSFER.java:150) at org.jgroups.protocols.FRAG2.up(FRAG2.java:189) at org.jgroups.protocols.FlowControl.up(FlowControl.java:418) at org.jgroups.protocols.FlowControl.up(FlowControl.java:400) at org.jgroups.protocols.pbcast.GMS.up(GMS.java:891) at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:246) at org.jgroups.protocols.VIEW_SYNC.up(VIEW_SYNC.java:170) at org.jgroups.protocols.UNICAST.handleDataReceived(UNICAST.java:613) at org.jgroups.protocols.UNICAST.up(UNICAST.java:294) at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:703) at org.jgroups.protocols.BARRIER.up(BARRIER.java:119) at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:133) at org.jgroups.protocols.FD_ALL.up(FD_ALL.java:177) at org.jgroups.protocols.FD.up(FD.java:275) at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:275) at org.jgroups.protocols.MERGE2.up(MERGE2.java:209) at org.jgroups.protocols.Discovery.up(Discovery.java:293) at org.jgroups.protocols.PING.up(PING.java:69) at org.jgroups.protocols.TP.passMessageUp(TP.java:1109) at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1665) at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1647) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) at java.lang.Thread.run(Thread.java:722)