[HBASE-21646] Flakey TestTableSnapshotInputFormat; DisableTable not completing...

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 2.0.3
• Fix Version/s: 3.0.0-alpha-1, 2.2.0, 2.1.2, 2.0.4
• Component/s: test
• Assignee: Michael Stack
• Reporter: Michael Stack
• Created: 27/Dec/18 05:26
• Updated: 04/Mar/19 08:57
• Resolved: 28/Dec/18 22:49

Description

Fails about 50% of time in the GCE builds... https://builds.apache.org/view/H-L/view/HBase/job/HBase-Find-Flaky-Tests/job/branch-2.0/lastSuccessfulBuild/artifact/dashboard.html

We are disabling table to delete at end of test when multi regions and we don't complete... pid=21:

 2018-12-26 20:52:17,179 DEBUG [RpcServer.default.FPBQ.Fifo.handler=2,queue=0,port=55246] assignment.RegionTransitionProcedure(297): Received report CLOSED seqId=-1, pid=27, ppid=21, state=RUNNABLE:REGION_TRANSITION_DISPATCH, locked=true; UnassignProcedure                      table=testWithMapReduce, region=b66d77b9dd3eaed5b4f8c89872bb56ca, server=192.168.1.51,55250,1545886322135; rit=CLOSING, location=192.168.1.51,55250,1545886322135
 2018-12-26 20:52:17,179 DEBUG [RpcServer.default.FPBQ.Fifo.handler=2,queue=0,port=55246] procedure.MasterProcedureScheduler(339): Add TableQueue(testWithMapReduce, xlock=false sharedLock=8 size=1) to run queue because: pid=27, ppid=21, state=RUNNABLE:                          REGION_TRANSITION_FINISH, locked=true; UnassignProcedure table=testWithMapReduce, region=b66d77b9dd3eaed5b4f8c89872bb56ca, server=192.168.1.51,55250,1545886322135 has lock
 2018-12-26 20:52:17,179 DEBUG [RpcServer.default.FPBQ.Fifo.handler=1,queue=0,port=55246] assignment.RegionTransitionProcedure(297): Received report CLOSED seqId=-1, pid=26, ppid=21, state=RUNNABLE:REGION_TRANSITION_DISPATCH, locked=true; UnassignProcedure                      table=testWithMapReduce, region=71231f8d1e9b8d4dc83519a6b2b0602a, server=192.168.1.51,55250,1545886322135; rit=CLOSING, location=192.168.1.51,55250,1545886322135
 2018-12-26 20:52:17,179 DEBUG [PEWorker-1] procedure.MasterProcedureScheduler(349): Remove TableQueue(testWithMapReduce, xlock=false sharedLock=8 size=0) from run queue because: queue is empty after polling out pid=27, ppid=21, state=RUNNABLE:REGION_TRANSITION_FINISH,         locked=true; UnassignProcedure table=testWithMapReduce, region=b66d77b9dd3eaed5b4f8c89872bb56ca, server=192.168.1.51,55250,1545886322135
 2018-12-26 20:52:17,179 DEBUG [PEWorker-1] assignment.RegionTransitionProcedure(394): Finishing pid=27, ppid=21, state=RUNNABLE:REGION_TRANSITION_FINISH, locked=true; UnassignProcedure table=testWithMapReduce, region=b66d77b9dd3eaed5b4f8c89872bb56ca, server=192.168.1.51,      55250,1545886322135; rit=CLOSING, location=192.168.1.51,55250,1545886322135
 2018-12-26 20:52:17,179 DEBUG [RpcServer.default.FPBQ.Fifo.handler=1,queue=0,port=55246] procedure.MasterProcedureScheduler(339): Add TableQueue(testWithMapReduce, xlock=false sharedLock=8 size=1) to run queue because: pid=26, ppid=21, state=RUNNABLE:                          REGION_TRANSITION_FINISH, locked=true; UnassignProcedure table=testWithMapReduce, region=71231f8d1e9b8d4dc83519a6b2b0602a, server=192.168.1.51,55250,1545886322135 has lock
 2018-12-26 20:52:17,180 DEBUG [PEWorker-14] procedure.MasterProcedureScheduler(349): Remove TableQueue(testWithMapReduce, xlock=false sharedLock=8 size=0) from run queue because: queue is empty after polling out pid=26, ppid=21, state=RUNNABLE:REGION_TRANSITION_FINISH,        locked=true; UnassignProcedure table=testWithMapReduce, region=71231f8d1e9b8d4dc83519a6b2b0602a, server=192.168.1.51,55250,1545886322135
 2018-12-26 20:52:17,180 DEBUG [PEWorker-14] assignment.RegionTransitionProcedure(394): Finishing pid=26, ppid=21, state=RUNNABLE:REGION_TRANSITION_FINISH, locked=true; UnassignProcedure table=testWithMapReduce, region=71231f8d1e9b8d4dc83519a6b2b0602a, server=192.168.1.51,     55250,1545886322135; rit=CLOSING, location=192.168.1.51,55250,1545886322135
 2018-12-26 20:52:17,405 DEBUG [RpcServer.default.FPBQ.Fifo.handler=2,queue=0,port=55246] master.MasterRpcServices(1152): Checking to see if procedure is done pid=21
 2018-12-26 20:52:17,911 DEBUG [RpcServer.default.FPBQ.Fifo.handler=2,queue=0,port=55246] master.MasterRpcServices(1152): Checking to see if procedure is done pid=21
 2018-12-26 20:52:18,917 DEBUG [RpcServer.default.FPBQ.Fifo.handler=2,queue=0,port=55246] master.MasterRpcServices(1152): Checking to see if procedure is done pid=21
 2018-12-26 20:52:20,922 DEBUG [RpcServer.default.FPBQ.Fifo.handler=2,queue=0,port=55246] master.MasterRpcServices(1152): Checking to see if procedure is done pid=21
 2018-12-26 20:52:24,928 DEBUG [RpcServer.default.FPBQ.Fifo.handler=2,queue=0,port=55246] master.MasterRpcServices(1152): Checking to see if procedure is done pid=21
 2018-12-26 20:52:34,932 DEBUG [RpcServer.default.FPBQ.Fifo.handler=2,queue=0,port=55246] master.MasterRpcServices(1152): Checking to see if procedure is done pid=21
 2018-12-26 20:52:44,934 DEBUG [RpcServer.default.FPBQ.Fifo.handler=2,queue=0,port=55246] master.MasterRpcServices(1152): Checking to see if procedure is done pid=21
 2018-12-26 20:52:54,938 DEBUG [RpcServer.default.FPBQ.Fifo.handler=2,queue=0,port=55246] master.MasterRpcServices(1152): Checking to see if procedure is done pid=21
 2018-12-26 20:53:04,944 DEBUG [RpcServer.default.FPBQ.Fifo.handler=2,queue=0,port=55246] master.MasterRpcServices(1152): Checking to see if procedure is done pid=21

This happens about time of fail of last few pid=21 subprocs:

 ***** ABORTING region server 192.168.1.51,55250,1545886322135: Caught throwable while processing event M_RS_CLOSE_REGION *****
 Cause:
 java.lang.RuntimeException: java.io.IOException: The new max sequence id 6 is less than the old max sequence id 7
   at org.apache.hadoop.hbase.regionserver.handler.CloseRegionHandler.process(CloseRegionHandler.java:116)
   at org.apache.hadoop.hbase.executor.EventHandler.run(EventHandler.java:104)
   at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1135)
   at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
   at java.base/java.lang.Thread.run(Thread.java:844)
 Caused by: java.io.IOException: The new max sequence id 6 is less than the old max sequence id 7
   at org.apache.hadoop.hbase.wal.WALSplitter.writeRegionSequenceIdFile(WALSplitter.java:684)
   at org.apache.hadoop.hbase.regionserver.HRegion.writeRegionCloseMarker(HRegion.java:1134)
   at org.apache.hadoop.hbase.regionserver.HRegion.doClose(HRegion.java:1662)
   at org.apache.hadoop.hbase.regionserver.HRegion.close(HRegion.java:1479)
   at org.apache.hadoop.hbase.regionserver.handler.CloseRegionHandler.process(CloseRegionHandler.java:104)
   ... 4 more

Fails for me locally.

Issue Links

• is duplicated by: HBASE-21571 The TestTableSnapshotInputFormat is flaky
• links to: Review Board (branch-2.0)

Sub-Tasks

• Break up TestTableSnapshotInputFormat into smaller pieces, figure why testWithMapReduceMultipleMappersPerRegion fails in mapred project fairly frequently: Open