[HDFS-13723] Occasional "Should be different group" error in TestRefreshUserMappings#testGroupMappingRefresh

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 3.0.0
• Fix Version/s: 3.2.0, 3.1.1, 3.0.4, 2.10.2
• Component/s: security, test
• Target Version/s: 3.0.0
• Assignee: Siyao Meng
• Reporter: Siyao Meng
• Created: 05/Jul/18 23:07
• Updated: 21/Jan/21 19:33
• Resolved: 11/Jul/18 17:03

Description

In some occasions, the user-group mapping refresh timeout test assertion would fail due to the mapping didn't refresh in time, reporting "Should be different group".

 

Trace:

java.lang.AssertionError: Should be different group 
at org.apache.hadoop.security.TestRefreshUserMappings.testGroupMappingRefresh(TestRefreshUserMappings.java:153)
:
:
2018-07-04 19:35:21,073 [BP-1412052829-172.26.17.254-1530758120647 heartbeating to localhost/127.0.0.1:39524] INFO datanode.DataNode (BPOfferService.java:processCommandFromActive(759)) - Got finalize command for block pool BP-1412052829-172.26.17.254-1530758120647
Getting groups in MockUnixGroupsMapping
2018-07-04 19:35:21,090 [IPC Server handler 6 on 39524] INFO FSNamesystem.audit (FSNamesystem.java:logAuditMessage(7805)) - allowed=true	ugi=jenkins (auth:SIMPLE)	ip=/127.0.0.1 cmd=datanodeReport	src=null	dst=null	perm=null	proto=rpc
2018-07-04 19:35:21,092 [main] INFO hdfs.MiniDFSCluster (MiniDFSCluster.java:waitActive(2629)) - Cluster is active
2018-07-04 19:35:21,095 [IPC Server handler 7 on 39524] INFO FSNamesystem.audit (FSNamesystem.java:logAuditMessage(7805)) - allowed=true	ugi=jenkins (auth:SIMPLE)	ip=/127.0.0.1 cmd=datanodeReport	src=null	dst=null	perm=null	proto=rpc
2018-07-04 19:35:21,096 [main] INFO hdfs.MiniDFSCluster (MiniDFSCluster.java:waitActive(2629)) - Cluster is active
first attempt:
[jenkins11, jenkins12]
second attempt, should be same:
[jenkins11, jenkins12]
2018-07-04 19:35:21,101 [IPC Server handler 5 on 39524] INFO namenode.NameNode (NameNodeRpcServer.java:refreshUserToGroupsMappings(1648)) - Refreshing all user-to-groups mappings. Requested by user: jenkins
2018-07-04 19:35:21,101 [IPC Server handler 5 on 39524] INFO security.Groups (Groups.java:refresh(401)) - clearing userToGroupsMap cache
Refreshing groups in MockUnixGroupsMapping
2018-07-04 19:35:21,102 [IPC Server handler 5 on 39524] INFO FSNamesystem.audit (FSNamesystem.java:logAuditMessage(7805)) - allowed=true	ugi=jenkins (auth:SIMPLE)	ip=/127.0.0.1 cmd=refreshUserToGroupsMappings	src=null	dst=null	perm=null	proto=rpc
Refresh user to groups mapping successful
third attempt(after refresh command), should be different:
Getting groups in MockUnixGroupsMapping
[jenkins21, jenkins22]
fourth attempt(after timeout), should be different:
[jenkins21, jenkins22]
Getting groups in MockUnixGroupsMapping
2018-07-04 19:35:22,204 [main] INFO hdfs.MiniDFSCluster (MiniDFSCluster.java:shutdown(1965)) - Shutting down the Mini HDFS Cluster

 

Solution:

Increase the timeout slightly, and place debugging message in load() and reload() methods in class GroupCacheLoader.