[HDFS-6533] TestBPOfferService#testBasicFunctionalitytest fails intermittently

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 2.4.0
• Fix Version/s: 2.8.0, 3.0.0-alpha1
• Component/s: datanode, hdfs-client
• Hadoop Flags: Reviewed
• Assignee: Wei-Chiu Chuang
• Reporter: Yongjun Zhang
• Created: 14/Jun/14 16:15
• Updated: 02/Oct/19 17:15
• Resolved: 01/Dec/15 21:37

Description

Per https://builds.apache.org/job/Hadoop-Hdfs-trunk/1774/testReport, the following test failed. However, local rerun is successful.

org.apache.hadoop.hdfs.server.datanode.TestBPOfferService.testBasicFunctionality

Error Message

Wanted but not invoked:
datanodeProtocolClientSideTranslatorPB.registerDatanode(
    <any>
);
-> at org.apache.hadoop.hdfs.server.datanode.TestBPOfferService.testBasicFunctionality(TestBPOfferService.java:175)
Actually, there were zero interactions with this mock.
Stacktrace

org.mockito.exceptions.verification.WantedButNotInvoked: 
Wanted but not invoked:
datanodeProtocolClientSideTranslatorPB.registerDatanode(
    <any>
);
-> at org.apache.hadoop.hdfs.server.datanode.TestBPOfferService.testBasicFunctionality(TestBPOfferService.java:175)
Actually, there were zero interactions with this mock.

	at org.apache.hadoop.hdfs.server.datanode.TestBPOfferService.testBasicFunctionality(TestBPOfferService.java:175)
Standard Output

2014-06-14 12:42:08,723 INFO  datanode.DataNode (SimulatedFSDataset.java:registerMBean(968)) - Registered FSDatasetState MBean
2014-06-14 12:42:08,730 INFO  datanode.DataNode (BPServiceActor.java:run(805)) - Block pool <registering> (Datanode Uuid unassigned) service to 0.0.0.0/0.0.0.0:0 starting to offer service
2014-06-14 12:42:08,730 DEBUG datanode.DataNode (BPServiceActor.java:retrieveNamespaceInfo(170)) - Block pool <registering> (Datanode Uuid unassigned) service to 0.0.0.0/0.0.0.0:0 received versionRequest response: lv=-57;cid=fake cluster;nsid=1;c=0;bpid=fake bpid
2014-06-14 12:42:08,731 INFO  datanode.DataNode (BPServiceActor.java:register(765)) - Block pool fake bpid (Datanode Uuid null) service to 0.0.0.0/0.0.0.0:0 beginning handshake with NN
2014-06-14 12:42:08,731 INFO  datanode.DataNode (BPServiceActor.java:register(778)) - Block pool Block pool fake bpid (Datanode Uuid null) service to 0.0.0.0/0.0.0.0:0 successfully registered with NN
2014-06-14 12:42:08,732 INFO  datanode.DataNode (BPServiceActor.java:offerService(637)) - For namenode 0.0.0.0/0.0.0.0:0 using DELETEREPORT_INTERVAL of 300000 msec  BLOCKREPORT_INTERVAL of 21600000msec CACHEREPORT_INTERVAL of 10000msec Initial delay: 0msec; heartBeatInterval=3000
2014-06-14 12:42:08,732 DEBUG datanode.DataNode (BPServiceActor.java:sendHeartBeat(562)) - Sending heartbeat with 1 storage reports from service actor: Block pool fake bpid (Datanode Uuid null) service to 0.0.0.0/0.0.0.0:0
2014-06-14 12:42:08,734 INFO  datanode.DataNode (BPServiceActor.java:blockReport(498)) - Sent 1 blockreports 0 blocks total. Took 1 msec to generate and 0 msecs for RPC and NN processing.  Got back commands none
2014-06-14 12:42:08,738 INFO  datanode.DataNode (BPServiceActor.java:run(805)) - Block pool fake bpid (Datanode Uuid null) service to 0.0.0.0/0.0.0.0:1 starting to offer service
2014-06-14 12:42:08,739 DEBUG datanode.DataNode (BPServiceActor.java:retrieveNamespaceInfo(170)) - Block pool fake bpid (Datanode Uuid null) service to 0.0.0.0/0.0.0.0:1 received versionRequest response: lv=-57;cid=fake cluster;nsid=1;c=0;bpid=fake bpid
2014-06-14 12:42:08,739 INFO  datanode.DataNode (BPServiceActor.java:register(765)) - Block pool fake bpid (Datanode Uuid null) service to 0.0.0.0/0.0.0.0:1 beginning handshake with NN
2014-06-14 12:42:08,740 INFO  datanode.DataNode (BPServiceActor.java:register(778)) - Block pool Block pool fake bpid (Datanode Uuid null) service to 0.0.0.0/0.0.0.0:1 successfully registered with NN