You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@hbase.apache.org by "Viraj Jasani (Jira)" <ji...@apache.org> on 2022/12/01 06:13:00 UTC
[jira] [Comment Edited] (HBASE-27502) Regionservers aborted as mvcc read point is less than max seq id derived from .seqid files
[ https://issues.apache.org/jira/browse/HBASE-27502?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17637558#comment-17637558 ]
Viraj Jasani edited comment on HBASE-27502 at 12/1/22 6:12 AM:
---------------------------------------------------------------
After looking into multiple regions that went through the above mentioned sequence of events (leading to regionserver aborting), here is _*the common pattern*_ among the regions:
Table snapshot is created. Hence, regions of the table go through snapshot process (snapshot type = {_}*SKIPFLUSH*{_}).
FlushSnapshotSubprocedure is completed soon.
Logs:
{code:java}
2022-11-21 01:04:07,006 DEBUG [375)-snapshot-pool-1] snapshot.SnapshotManifest - Adding snapshot references for [hdfs://c01/hbase/data/default/TABLE01/34621c450d2a5e35f82dd1e8a278f9e2/0/19f0375e15b94f829027142628366206] hfiles
2022-11-21 01:04:07,006 DEBUG [375)-snapshot-pool-1] snapshot.SnapshotManifest - Adding reference for file (1/1): hdfs://c01/hbase/data/default/TABLE01/34621c450d2a5e35f82dd1e8a278f9e2/0/19f0375e15b94f829027142628366206 for snapshot=SNAPSHOT_TABLE01_1668992404010_1668992453610_0
2022-11-21 01:04:07,006 DEBUG [375)-snapshot-pool-1] snapshot.SnapshotManifest - Storing 'TABLE01,00DZ000000NAH0x000000000000000005Z0000005O3lcU\x000000000000000008\xFD\xBD\xF3\xC9\xE7\xAE\xFF\xCF\xBB\xCA\xA5\xCF\xCF\xCF\xCF\xCF\xCF\x8F\xCD\xA5\x97\xBA,1663467811966.34621c450d2a5e35f82dd1e8a278f9e2.' region-info for snapshot=SNAPSHOT_TABLE01_1668992404010_1668992453610_0
2022-11-21 01:04:07,006 DEBUG [375)-snapshot-pool-1] snapshot.FlushSnapshotSubprocedure - Starting snapshot operation on TABLE01,00DZ000000NAH0x000000000000000005Z0000005O3lcU\x000000000000000008\xFD\xBD\xF3\xC9\xE7\xAE\xFF\xCF\xBB\xCA\xA5\xCF\xCF\xCF\xCF\xCF\xCF\x8F\xCD\xA5\x97\xBA,1663467811966.34621c450d2a5e35f82dd1e8a278f9e2.
2022-11-21 01:04:07,161 DEBUG [375)-snapshot-pool-1] snapshot.FlushSnapshotSubprocedure - Closing snapshot operation on TABLE01,00DZ000000NAH0x000000000000000005Z0000005O3lcU\x000000000000000008\xFD\xBD\xF3\xC9\xE7\xAE\xFF\xCF\xBB\xCA\xA5\xCF\xCF\xCF\xCF\xCF\xCF\x8F\xCD\xA5\x97\xBA,1663467811966.34621c450d2a5e35f82dd1e8a278f9e2.
2022-11-21 01:04:07,161 DEBUG [375)-snapshot-pool-1] snapshot.FlushSnapshotSubprocedure - ... SkipFlush Snapshotting region TABLE01,00DZ000000NAH0x000000000000000005Z0000005O3lcU\x000000000000000008\xFD\xBD\xF3\xC9\xE7\xAE\xFF\xCF\xBB\xCA\xA5\xCF\xCF\xCF\xCF\xCF\xCF\x8F\xCD\xA5\x97\xBA,1663467811966.34621c450d2a5e35f82dd1e8a278f9e2. completed.{code}
After some time, as per HDFS audit logs, new seqid file is created:
{code:java}
2022-11-20 01:14:11,549 INFO [on default port 8020] FSNamesystem.audit - allowed=true ugi=hbase/c01-mabc2-1-xyz.abcxyz@c01-xyz.abcxyz (auth:TOKEN) ip=/{ip} cmd=create src=/hbase/data/default/TABLE01/34621c450d2a5e35f82dd1e8a278f9e2/recovered.edits/6123331.seqid dst=null perm=abc:supergroup:rw-r--r-- proto=rpc
2022-11-21 01:15:58,426 INFO [on default port 8020] FSNamesystem.audit - allowed=true ugi=hbase/c01-mabc2-1-xyz.abcxyz@c01-xyz.abcxyz (auth:TOKEN) ip=/10.220.160.86 cmd=getfileinfo src=/hbase/data/default/TABLE01/34621c450d2a5e35f82dd1e8a278f9e2/recovered.edits/6123331.seqid dst=null perm=null proto=rpc
2022-11-21 01:15:58,450 INFO [on default port 8020] FSNamesystem.audit - allowed=true ugi=hbase/c01-mabc2-1-xyz.abcxyz@c01-xyz.abcxyz (auth:TOKEN) ip=/10.220.160.86 cmd=getfileinfo src=/hbase/data/default/TABLE01/34621c450d2a5e35f82dd1e8a278f9e2/recovered.edits/6123332.seqid dst=null perm=null proto=rpc
2022-11-21 01:15:58,464 INFO [on default port 8020] FSNamesystem.audit - allowed=true ugi=hbase/c01-mabc2-1-xyz.abcxyz@c01-xyz.abcxyz (auth:TOKEN) ip=/10.220.160.86 cmd=create src=/hbase/data/default/TABLE01/34621c450d2a5e35f82dd1e8a278f9e2/recovered.edits/6123332.seqid dst=null perm=abc:supergroup:rw-r--r-- proto=rpc
2022-11-21 01:15:58,483 INFO [on default port 8020] FSNamesystem.audit - allowed=true ugi=hbase/c01-mabc2-1-xyz.abcxyz@c01-xyz.abcxyz (auth:TOKEN) ip=/10.220.160.86 cmd=delete src=/hbase/data/default/TABLE01/34621c450d2a5e35f82dd1e8a278f9e2/recovered.edits/6123331.seqid dst=null perm=null proto=rpc
2022-11-21 01:15:58,479 INFO [on default port 8020] hdfs.StateChange - DIR* completeFile: /hbase/data/default/TABLE01/34621c450d2a5e35f82dd1e8a278f9e2/recovered.edits/6123332.seqid is closed by DFSClient_attempt_1668068715963_11371_m_000057_0_-589973827_1{code}
After long enough time, region goes through MOVE transition as per balancer plan. When the region closes, mvcc read point is somehow not latest one (less than max seqid file created as per above logs).
{code:java}
2022-11-21 01:57:14,728 INFO [-dabc3-2-xyz:61020-0] handler.UnassignRegionHandler - Close 34621c450d2a5e35f82dd1e8a278f9e2
2022-11-21 01:57:14,728 INFO [-dabc3-2-xyz:61020-0] regionserver.HRegion - Closing region
2022-11-21 01:57:14,737 WARN [-dabc3-2-xyz:61020-0] handler.UnassignRegionHandler - Fatal error occurred while closing region 34621c450d2a5e35f82dd1e8a278f9e2, aborting...
java.io.IOException: The new max sequence id 6123331 is less than the old max sequence id 6123332
at org.apache.hadoop.hbase.wal.WALSplitUtil.writeRegionSequenceIdFile(WALSplitUtil.java:397)
at org.apache.hadoop.hbase.regionserver.HRegion.writeRegionCloseMarker(HRegion.java:1217)
at org.apache.hadoop.hbase.regionserver.HRegion.doClose(HRegion.java:1816)
at org.apache.hadoop.hbase.regionserver.HRegion.close(HRegion.java:1552)
at org.apache.hadoop.hbase.regionserver.handler.UnassignRegionHandler.process(UnassignRegionHandler.java:118)
at org.apache.hadoop.hbase.executor.EventHandler.run(EventHandler.java:98)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:750)
2022-11-21 01:57:14,749 ERROR [-dabc3-2-xyz:61020-0] regionserver.HRegionServer - ***** ABORTING region server c01-dabc3-2-xyz.abcxyz,61020,1668598527375: Failed to close region 34621c450d2a5e35f82dd1e8a278f9e2 and can not recover *****
java.io.IOException: The new max sequence id 6123331 is less than the old max sequence id 6123332
at org.apache.hadoop.hbase.wal.WALSplitUtil.writeRegionSequenceIdFile(WALSplitUtil.java:397)
at org.apache.hadoop.hbase.regionserver.HRegion.writeRegionCloseMarker(HRegion.java:1217)
at org.apache.hadoop.hbase.regionserver.HRegion.doClose(HRegion.java:1816)
at org.apache.hadoop.hbase.regionserver.HRegion.close(HRegion.java:1552)
at org.apache.hadoop.hbase.regionserver.handler.UnassignRegionHandler.process(UnassignRegionHandler.java:118)
at org.apache.hadoop.hbase.executor.EventHandler.run(EventHandler.java:98)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:750)
2022-11-21 01:57:14,795 INFO [-dabc3-2-xyz:61020-0] regionserver.HRegionServer - STOPPED: Failed to close region 34621c450d2a5e35f82dd1e8a278f9e2 and can not recover
{code}
What is really interesting here is that mvcc read point is not updated even after ~42 min of a new seqid being created under the recovered.edits. As part of the region close, _doFullMarkerAppendTransaction()_ should have advanced mvcc read point (while completing the write entry).
And yet, even after ~42 min of new max seqid presence in recovered edits, followed by region close is not enough to advance mvcc read point, which eventually results in incorrect comparison i.e. (mvcc read point) < (max seq id available).
This would make us wonder perhaps we have some issue with skip flush snapshot type? Though how it relates to mvcc read point not being updated with latest seq id is an interesting scenario to dig in.
was (Author: vjasani):
After looking into multiple regions that went through the above mentioned sequence of events (leading to regionserver aborting), here is _*the common pattern*_ among the regions:
Table snapshot is created. Hence, regions of the table go through snapshot process (snapshot type = {_}*SKIPFLUSH*{_}).
FlushSnapshotSubprocedure is completed soon.
Logs:
{code:java}
2022-11-21 01:04:07,006 DEBUG [375)-snapshot-pool-1] snapshot.SnapshotManifest - Adding snapshot references for [hdfs://c01/hbase/data/default/TABLE01/34621c450d2a5e35f82dd1e8a278f9e2/0/19f0375e15b94f829027142628366206] hfiles
2022-11-21 01:04:07,006 DEBUG [375)-snapshot-pool-1] snapshot.SnapshotManifest - Adding reference for file (1/1): hdfs://c01/hbase/data/default/TABLE01/34621c450d2a5e35f82dd1e8a278f9e2/0/19f0375e15b94f829027142628366206 for snapshot=SNAPSHOT_TABLE01_1668992404010_1668992453610_0
2022-11-21 01:04:07,006 DEBUG [375)-snapshot-pool-1] snapshot.SnapshotManifest - Storing 'TABLE01,00DZ000000NAH0x000000000000000005Z0000005O3lcU\x000000000000000008\xFD\xBD\xF3\xC9\xE7\xAE\xFF\xCF\xBB\xCA\xA5\xCF\xCF\xCF\xCF\xCF\xCF\x8F\xCD\xA5\x97\xBA,1663467811966.34621c450d2a5e35f82dd1e8a278f9e2.' region-info for snapshot=SNAPSHOT_TABLE01_1668992404010_1668992453610_0
2022-11-21 01:04:07,006 DEBUG [375)-snapshot-pool-1] snapshot.FlushSnapshotSubprocedure - Starting snapshot operation on TABLE01,00DZ000000NAH0x000000000000000005Z0000005O3lcU\x000000000000000008\xFD\xBD\xF3\xC9\xE7\xAE\xFF\xCF\xBB\xCA\xA5\xCF\xCF\xCF\xCF\xCF\xCF\x8F\xCD\xA5\x97\xBA,1663467811966.34621c450d2a5e35f82dd1e8a278f9e2.
2022-11-21 01:04:07,161 DEBUG [375)-snapshot-pool-1] snapshot.FlushSnapshotSubprocedure - Closing snapshot operation on TABLE01,00DZ000000NAH0x000000000000000005Z0000005O3lcU\x000000000000000008\xFD\xBD\xF3\xC9\xE7\xAE\xFF\xCF\xBB\xCA\xA5\xCF\xCF\xCF\xCF\xCF\xCF\x8F\xCD\xA5\x97\xBA,1663467811966.34621c450d2a5e35f82dd1e8a278f9e2.
2022-11-21 01:04:07,161 DEBUG [375)-snapshot-pool-1] snapshot.FlushSnapshotSubprocedure - ... SkipFlush Snapshotting region TABLE01,00DZ000000NAH0x000000000000000005Z0000005O3lcU\x000000000000000008\xFD\xBD\xF3\xC9\xE7\xAE\xFF\xCF\xBB\xCA\xA5\xCF\xCF\xCF\xCF\xCF\xCF\x8F\xCD\xA5\x97\xBA,1663467811966.34621c450d2a5e35f82dd1e8a278f9e2. completed.{code}
After some time, as per HDFS audit logs, new seqid file is created:
{code:java}
2022-11-21 01:15:58,426 INFO [on default port 8020] FSNamesystem.audit - allowed=true ugi=hbase/c01-mabc2-1-xyz.abcxyz@c01-xyz.abcxyz (auth:TOKEN) ip=/10.220.160.86 cmd=getfileinfo src=/hbase/data/default/TABLE01/34621c450d2a5e35f82dd1e8a278f9e2/recovered.edits/6123331.seqid dst=null perm=null proto=rpc
2022-11-21 01:15:58,450 INFO [on default port 8020] FSNamesystem.audit - allowed=true ugi=hbase/c01-mabc2-1-xyz.abcxyz@c01-xyz.abcxyz (auth:TOKEN) ip=/10.220.160.86 cmd=getfileinfo src=/hbase/data/default/TABLE01/34621c450d2a5e35f82dd1e8a278f9e2/recovered.edits/6123332.seqid dst=null perm=null proto=rpc
2022-11-21 01:15:58,464 INFO [on default port 8020] FSNamesystem.audit - allowed=true ugi=hbase/c01-mabc2-1-xyz.abcxyz@c01-xyz.abcxyz (auth:TOKEN) ip=/10.220.160.86 cmd=create src=/hbase/data/default/TABLE01/34621c450d2a5e35f82dd1e8a278f9e2/recovered.edits/6123332.seqid dst=null perm=abc:supergroup:rw-r--r-- proto=rpc
2022-11-21 01:15:58,483 INFO [on default port 8020] FSNamesystem.audit - allowed=true ugi=hbase/c01-mabc2-1-xyz.abcxyz@c01-xyz.abcxyz (auth:TOKEN) ip=/10.220.160.86 cmd=delete src=/hbase/data/default/TABLE01/34621c450d2a5e35f82dd1e8a278f9e2/recovered.edits/6123331.seqid dst=null perm=null proto=rpc
2022-11-21 01:15:58,479 INFO [on default port 8020] hdfs.StateChange - DIR* completeFile: /hbase/data/default/TABLE01/34621c450d2a5e35f82dd1e8a278f9e2/recovered.edits/6123332.seqid is closed by DFSClient_attempt_1668068715963_11371_m_000057_0_-589973827_1{code}
After long enough time, region goes through MOVE transition as per balancer plan. When the region closes, mvcc read point is somehow not latest one (less than max seqid file created as per above logs).
{code:java}
2022-11-21 01:57:14,728 INFO [-dabc3-2-xyz:61020-0] handler.UnassignRegionHandler - Close 34621c450d2a5e35f82dd1e8a278f9e2
2022-11-21 01:57:14,728 INFO [-dabc3-2-xyz:61020-0] regionserver.HRegion - Closing region
2022-11-21 01:57:14,737 WARN [-dabc3-2-xyz:61020-0] handler.UnassignRegionHandler - Fatal error occurred while closing region 34621c450d2a5e35f82dd1e8a278f9e2, aborting...
java.io.IOException: The new max sequence id 6123331 is less than the old max sequence id 6123332
at org.apache.hadoop.hbase.wal.WALSplitUtil.writeRegionSequenceIdFile(WALSplitUtil.java:397)
at org.apache.hadoop.hbase.regionserver.HRegion.writeRegionCloseMarker(HRegion.java:1217)
at org.apache.hadoop.hbase.regionserver.HRegion.doClose(HRegion.java:1816)
at org.apache.hadoop.hbase.regionserver.HRegion.close(HRegion.java:1552)
at org.apache.hadoop.hbase.regionserver.handler.UnassignRegionHandler.process(UnassignRegionHandler.java:118)
at org.apache.hadoop.hbase.executor.EventHandler.run(EventHandler.java:98)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:750)
2022-11-21 01:57:14,749 ERROR [-dabc3-2-xyz:61020-0] regionserver.HRegionServer - ***** ABORTING region server c01-dabc3-2-xyz.abcxyz,61020,1668598527375: Failed to close region 34621c450d2a5e35f82dd1e8a278f9e2 and can not recover *****
java.io.IOException: The new max sequence id 6123331 is less than the old max sequence id 6123332
at org.apache.hadoop.hbase.wal.WALSplitUtil.writeRegionSequenceIdFile(WALSplitUtil.java:397)
at org.apache.hadoop.hbase.regionserver.HRegion.writeRegionCloseMarker(HRegion.java:1217)
at org.apache.hadoop.hbase.regionserver.HRegion.doClose(HRegion.java:1816)
at org.apache.hadoop.hbase.regionserver.HRegion.close(HRegion.java:1552)
at org.apache.hadoop.hbase.regionserver.handler.UnassignRegionHandler.process(UnassignRegionHandler.java:118)
at org.apache.hadoop.hbase.executor.EventHandler.run(EventHandler.java:98)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:750)
2022-11-21 01:57:14,795 INFO [-dabc3-2-xyz:61020-0] regionserver.HRegionServer - STOPPED: Failed to close region 34621c450d2a5e35f82dd1e8a278f9e2 and can not recover
{code}
What is really interesting here is that mvcc read point is not updated even after ~42 min of a new seqid being created under the recovered.edits. As part of the region close, _doFullMarkerAppendTransaction()_ should have advanced mvcc read point (while completing the write entry).
And yet, even after ~42 min of new max seqid presence in recovered edits, followed by region close is not enough to advance mvcc read point, which eventually results in incorrect comparison i.e. (mvcc read point) < (max seq id available).
This would make us wonder perhaps we have some issue with skip flush snapshot type? Though how it relates to mvcc read point not being updated with latest seq id is an interesting scenario to dig in.
> Regionservers aborted as mvcc read point is less than max seq id derived from .seqid files
> ------------------------------------------------------------------------------------------
>
> Key: HBASE-27502
> URL: https://issues.apache.org/jira/browse/HBASE-27502
> Project: HBase
> Issue Type: Bug
> Components: wal
> Affects Versions: 2.4.15
> Reporter: Viraj Jasani
> Priority: Major
>
> HBase cluster is upgraded from 1.6 to 2.4.14/15 version recently. The cluster doesn't have much traffic. After 4-5 days of this upgrade, suddenly 144 out of ~150 regionservers were aborted with {*}java.io.IOException: The new max sequence id {} is less than the old max sequence id {}{*}.
> After starting regionservers, things were normal.
>
> Sequence of events for the first regionserver that was aborted:
> Table snapshot was created, hence region went through snapshot subprocedure.
> {code:java}
> 2022-11-16 01:03:11,504 DEBUG [532)-snapshot-pool-0] snapshot.SnapshotManifest - Storing 'TABLE01,00DJ0000003PwkV000000000000000005J000000681gsU\x000000000000000008\xFD\xCC\xDC\x9C\xB7\xA4\xFF\xCF\xBB\xCA\xB5\xCF\xCF\xCF\xCF\xCF\xCF\x8A\xAE\xB3\xA7\x9D,1658067025381.d773829ad7e76202cccac6fbc314091b.' region-info for snapshot=SNAPSHOT_TABLE01_1668560404026_1668560447300_0
> 2022-11-16 01:03:11,504 DEBUG [532)-snapshot-pool-0] snapshot.FlushSnapshotSubprocedure - Starting snapshot operation on TABLE01,00DJ0000003PwkV000000000000000005J000000681gsU\x000000000000000008\xFD\xCC\xDC\x9C\xB7\xA4\xFF\xCF\xBB\xCA\xB5\xCF\xCF\xCF\xCF\xCF\xCF\x8A\xAE\xB3\xA7\x9D,1658067025381.d773829ad7e76202cccac6fbc314091b.
> 2022-11-16 01:03:11,504 DEBUG [532)-snapshot-pool-0] snapshot.SnapshotManifest - Adding snapshot references for [hdfs://c01/hbase/data/default/TABLE01/d773829ad7e76202cccac6fbc314091b/0/ea13e8a1f56843efb1243d5ba108e63a] hfiles
> 2022-11-16 01:03:11,504 DEBUG [532)-snapshot-pool-0] snapshot.SnapshotManifest - Adding reference for file (1/1): hdfs://c01/hbase/data/default/TABLE01/d773829ad7e76202cccac6fbc314091b/0/ea13e8a1f56843efb1243d5ba108e63a for snapshot=SNAPSHOT_TABLE01_1668560404026_1668560447300_0
> 2022-11-16 01:03:11,562 DEBUG [532)-snapshot-pool-0] snapshot.FlushSnapshotSubprocedure - Closing snapshot operation on TABLE01,00DJ0000003PwkV000000000000000005J000000681gsU\x000000000000000008\xFD\xCC\xDC\x9C\xB7\xA4\xFF\xCF\xBB\xCA\xB5\xCF\xCF\xCF\xCF\xCF\xCF\x8A\xAE\xB3\xA7\x9D,1658067025381.d773829ad7e76202cccac6fbc314091b.
> 2022-11-16 01:03:11,562 DEBUG [532)-snapshot-pool-0] snapshot.FlushSnapshotSubprocedure - ... SkipFlush Snapshotting region TABLE01,00DJ0000003PwkV000000000000000005J000000681gsU\x000000000000000008\xFD\xCC\xDC\x9C\xB7\xA4\xFF\xCF\xBB\xCA\xB5\xCF\xCF\xCF\xCF\xCF\xCF\x8A\xAE\xB3\xA7\x9D,1658067025381.d773829ad7e76202cccac6fbc314091b. completed.
> {code}
>
> After 6+ hr, major compaction of the table was triggered.
> Logs from RS c01-dabc11-12-xyz.abcxyz:
> {code:java}
> 2022-11-16 07:36:34,978 INFO [0-shortCompactions-0] regionserver.HStore - Starting compaction of [hdfs://c01/hbase/data/default/TABLE01/d773829ad7e76202cccac6fbc314091b/0/ea13e8a1f56843efb1243d5ba108e63a] into tmpdir=hdfs://c01/hbase/data/default/TABLE01/d773829ad7e76202cccac6fbc314091b/.tmp, totalSize=939.0 M
> 2022-11-16 07:36:34,978 INFO [0-shortCompactions-0] regionserver.HRegion - Starting compaction of d773829ad7e76202cccac6fbc314091b/0 in TABLE01,00DJ0000003PwkV000000000000000005J000000681gsU\x000000000000000008\xFD\xCC\xDC\x9C\xB7\xA4\xFF\xCF\xBB\xCA\xB5\xCF\xCF\xCF\xCF\xCF\xCF\x8A\xAE\xB3\xA7\x9D,1658067025381.d773829ad7e76202cccac6fbc314091b.
> {code}
>
>
> Region split is triggered by CompactSplit.
> Logs from RS c01-dabc11-12-xyz.abcxyz:
> {code:java}
> 2022-11-16 07:38:03,570 DEBUG [0-shortCompactions-0] regionserver.CompactSplit - Splitting TABLE01,00DJ0000003PwkV000000000000000005J000000681gsU\x000000000000000008\xFD\xCC\xDC\x9C\xB7\xA4\xFF\xCF\xBB\xCA\xB5\xCF\xCF\xCF\xCF\xCF\xCF\x8A\xAE\xB3\xA7\x9D,1658067025381.d773829ad7e76202cccac6fbc314091b., compactionQueue=(longCompactions=0:shortCompactions=0), splitQueue=0
> 2022-11-16 07:38:03,848 INFO [abc11-12-xyz:61020-0] regionserver.HRegion - Closing region TABLE01,00DJ0000003PwkV000000000000000005J000000681gsU\x000000000000000008\xFD\xCC\xDC\x9C\xB7\xA4\xFF\xCF\xBB\xCA\xB5\xCF\xCF\xCF\xCF\xCF\xCF\x8A\xAE\xB3\xA7\x9D,1658067025381.d773829ad7e76202cccac6fbc314091b.
> 2022-11-16 07:38:03,860 DEBUG [2cccac6fbc314091b.-1] backup.HFileArchiver - Archived from FileableStoreFile, hdfs://c01/hbase/data/default/TABLE01/d773829ad7e76202cccac6fbc314091b/0/ea13e8a1f56843efb1243d5ba108e63a to hdfs://c01/hbase/archive/data/default/TABLE01/d773829ad7e76202cccac6fbc314091b/0/ea13e8a1f56843efb1243d5ba108e63a
> 2022-11-16 07:38:03,881 DEBUG [abc11-12-xyz:61020-0] regionserver.HRegion - Region close journal for d773829ad7e76202cccac6fbc314091b:
> Waiting for close lock at 1668584283848Running coprocessor pre-close hooks at 1668584283848Disabling compacts and flushes for region at 1668584283848Disabling writes for close at 1668584283848Writing region close event to WAL at 1668584283876 (+28 ms)
> 2022-11-16 07:38:03,881 WARN [abc11-12-xyz:61020-0] handler.UnassignRegionHandler - Fatal error occurred while closing region d773829ad7e76202cccac6fbc314091b, aborting...
> java.io.IOException: The new max sequence id 1963762 is less than the old max sequence id 1963764
> at org.apache.hadoop.hbase.wal.WALSplitUtil.writeRegionSequenceIdFile(WALSplitUtil.java:397)
> at org.apache.hadoop.hbase.regionserver.HRegion.writeRegionCloseMarker(HRegion.java:1217)
> at org.apache.hadoop.hbase.regionserver.HRegion.doClose(HRegion.java:1816)
> at org.apache.hadoop.hbase.regionserver.HRegion.close(HRegion.java:1552)
> at org.apache.hadoop.hbase.regionserver.handler.UnassignRegionHandler.process(UnassignRegionHandler.java:118)
> at org.apache.hadoop.hbase.executor.EventHandler.run(EventHandler.java:98)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at java.lang.Thread.run(Thread.java:750)
> {code}
> Leading to RS abort:
> {code:java}
> 2022-11-16 07:38:03,889 ERROR [abc11-12-xyz:61020-0] regionserver.HRegionServer - ***** ABORTING region server c01-dabc11-12-xyz.abcxyz,61020,1668064189532: Failed to close region d773829ad7e76202cccac6fbc314091b and can not recover *****
> java.io.IOException: The new max sequence id 1963762 is less than the old max sequence id 1963764
> at org.apache.hadoop.hbase.wal.WALSplitUtil.writeRegionSequenceIdFile(WALSplitUtil.java:397)
> at org.apache.hadoop.hbase.regionserver.HRegion.writeRegionCloseMarker(HRegion.java:1217)
> at org.apache.hadoop.hbase.regionserver.HRegion.doClose(HRegion.java:1816)
> at org.apache.hadoop.hbase.regionserver.HRegion.close(HRegion.java:1552)
> at org.apache.hadoop.hbase.regionserver.handler.UnassignRegionHandler.process(UnassignRegionHandler.java:118)
> at org.apache.hadoop.hbase.executor.EventHandler.run(EventHandler.java:98)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at java.lang.Thread.run(Thread.java:750)
> {code}
>
>
> Master tries to open the region on other RS.
> master logs:
> {code:java}
> 2022-11-16 07:38:08,840 INFO [PEWorker-60] assignment.RegionStateStore - pid=58195 updating hbase:meta row=d773829ad7e76202cccac6fbc314091b, regionState=ABNORMALLY_CLOSED
> 2022-11-16 07:38:08,883 INFO [PEWorker-32] assignment.RegionStateStore - pid=58195 updating hbase:meta row=d773829ad7e76202cccac6fbc314091b, regionState=OPENING, regionLocation=c01-dabc6-10-xyz.abcxyz,61020,1668058690832
> 2022-11-16 07:38:08,883 DEBUG [PEWorker-32] hbase.META - Put {"totalColumns":3,"row":"TABLE01,00DJ0000003PwkV000000000000000005J000000681gsU\\x000000000000000008\\xFD\\xCC\\xDC\\x9C\\xB7\\xA4\\xFF\\xCF\\xBB\\xCA\\xB5\\xCF\\xCF\\xCF\\xCF\\xCF\\xCF\\x8A\\xAE\\xB3\\xA7\\x9D,1658067025381.d773829ad7e76202cccac6fbc314091b.","families":{"info":[{"qualifier":"regioninfo","vlen":245,"tag":[],"timestamp":"1668584288883"},{"qualifier":"sn","vlen":53,"tag":[],"timestamp":"1668584288883"},{"qualifier":"state","vlen":7,"tag":[],"timestamp":"1668584288883"}]},"ts":"1668584288883"}
> 2022-11-16 07:38:08,888 INFO [PEWorker-32] procedure2.ProcedureExecutor - Initialized subprocedures=[{pid=58794, ppid=58195, state=RUNNABLE; OpenRegionProcedure d773829ad7e76202cccac6fbc314091b, server=c01-dabc6-10-xyz.abcxyz,61020,1668058690832}]
> 2022-11-16 07:38:09,398 INFO [PEWorker-55] assignment.RegionStateStore - pid=58195 updating hbase:meta row=d773829ad7e76202cccac6fbc314091b, regionState=OPEN, repBarrier=1963765, openSeqNum=1963765, regionLocation=c01-dabc6-10-xyz.abcxyz,61020,1668058690832
> {code}
>
>
>
> On the new RS, region is opened, recovered, closed (as part of compact split), compacted and successfully archived.
> Logs from new RS c01-dabc6-10-xyz.abcxyz:
> {code:java}
> 2022-11-16 07:38:09,168 INFO [dabc6-10-xyz:61020-0] handler.AssignRegionHandler - Open TABLE01,00DJ0000003PwkV000000000000000005J000000681gsU\x000000000000000008\xFD\xCC\xDC\x9C\xB7\xA4\xFF\xCF\xBB\xCA\xB5\xCF\xCF\xCF\xCF\xCF\xCF\x8A\xAE\xB3\xA7\x9D,1658067025381.d773829ad7e76202cccac6fbc314091b.
> 2022-11-16 07:38:09,235 DEBUG [dabc6-10-xyz:61020-0] regionserver.HRegion - Instantiated TABLE01,00DJ0000003PwkV000000000000000005J000000681gsU\x000000000000000008\xFD\xCC\xDC\x9C\xB7\xA4\xFF\xCF\xBB\xCA\xB5\xCF\xCF\xCF\xCF\xCF\xCF\x8A\xAE\xB3\xA7\x9D,1658067025381.d773829ad7e76202cccac6fbc314091b.; StoreHotnessProtector, parallelPutToStoreThreadLimit=10 ; minColumnNum=100 ; preparePutThreadLimit=20 ; hotProtect now enable
> 2022-11-16 07:38:09,318 DEBUG [dabc6-10-xyz:61020-0] regionserver.HRegion - Found 0 recovered edits file(s) under hdfs://c01/hbase/data/default/TABLE01/d773829ad7e76202cccac6fbc314091b
> 2022-11-16 07:38:09,330 DEBUG [dabc6-10-xyz:61020-0] regionserver.HRegion - Found 1 recovered edits file(s) under hdfs://c01/hbase/data/default/TABLE01/d773829ad7e76202cccac6fbc314091b
> 2022-11-16 07:38:09,334 INFO [dabc6-10-xyz:61020-0] regionserver.HRegion - Replaying edits from hdfs://c01/hbase/data/default/TABLE01/d773829ad7e76202cccac6fbc314091b/recovered.edits/0000000000001963761
> 2022-11-16 07:38:09,365 DEBUG [dabc6-10-xyz:61020-0] regionserver.HRegion - Applied 0, skipped 1, firstSequenceIdInLog=1963761, maxSequenceIdInLog=1963761, path=hdfs://c01/hbase/data/default/TABLE01/d773829ad7e76202cccac6fbc314091b/recovered.edits/0000000000001963761
> 2022-11-16 07:38:09,365 DEBUG [dabc6-10-xyz:61020-0] regionserver.HRegion - d773829ad7e76202cccac6fbc314091b : Replaying compaction marker table_name: "TABLE01" encoded_region_name: "d773829ad7e76202cccac6fbc314091b" family_name: "0" compaction_input: "ea13e8a1f56843efb1243d5ba108e63a" compaction_output: "e629d75027ed4da79fd962e645c7a3b4" store_home_dir: "0" region_name: "TABLE01,00DJ0000003PwkV000000000000000005J000000681gsU\0000000000000000008\375\314\334\234\267\244\377\317\273\312\265\317\317\317\317\317\317\212\256\263\247\235,1658067025381.d773829ad7e76202cccac6fbc314091b." with seqId=9223372036854775807 and lastReplayedOpenRegionSeqId=-1
> 2022-11-16 07:38:09,367 DEBUG [dabc6-10-xyz:61020-0] regionserver.HRegion - Deleted recovered.edits file=hdfs://c01/hbase/data/default/TABLE01/d773829ad7e76202cccac6fbc314091b/recovered.edits/0000000000001963761
> 2022-11-16 07:38:09,372 DEBUG [dabc6-10-xyz:61020-0] regionserver.HRegion - writing seq id for d773829ad7e76202cccac6fbc314091b
> 2022-11-16 07:38:09,373 INFO [dabc6-10-xyz:61020-0] regionserver.HRegion - Opened d773829ad7e76202cccac6fbc314091b; next sequenceid=1963765; SteppingSplitPolicysuper{IncreasingToUpperBoundRegionSplitPolicy{initialSize=536870912, ConstantSizeRegionSplitPolicy{desiredMaxFileSize=9917293600, jitterRate=-0.07638005912303925}}}, FlushLargeStoresPolicy{flushSizeLowerBound=-1}
> 2022-11-16 07:38:09,581 INFO [dabc6-10-xyz:61020-2] regionserver.HRegion - Closing region TABLE01,00DJ0000003PwkV000000000000000005J000000681gsU\x000000000000000008\xFD\xCC\xDC\x9C\xB7\xA4\xFF\xCF\xBB\xCA\xB5\xCF\xCF\xCF\xCF\xCF\xCF\x8A\xAE\xB3\xA7\x9D,1658067025381.d773829ad7e76202cccac6fbc314091b.
> 2022-11-16 07:38:09,597 DEBUG [dabc6-10-xyz:61020-2] wal.WALSplitUtil - Wrote file=hdfs://c01/hbase/data/default/TABLE01/d773829ad7e76202cccac6fbc314091b/recovered.edits/1963767.seqid, newMaxSeqId=1963767, maxSeqId=1963764
> 2022-11-16 07:38:09,601 INFO [dabc6-10-xyz:61020-2] handler.UnassignRegionHandler - Closed d773829ad7e76202cccac6fbc314091b
> 2022-11-16 07:38:10,340 INFO [0-shortCompactions-0] regionserver.HStore - Starting compaction of [hdfs://c01/hbase/data/default/TABLE01/2eaab01e9bd001727475abf7a4f73053/0/e629d75027ed4da79fd962e645c7a3b4.d773829ad7e76202cccac6fbc314091b->hdfs://c01/hbase/data/default/TABLE01/d773829ad7e76202cccac6fbc314091b/0/e629d75027ed4da79fd962e645c7a3b4-top] into tmpdir=hdfs://c01/hbase/data/default/TABLE01/2eaab01e9bd001727475abf7a4f73053/.tmp, totalSize=939.0 M
> 2022-11-16 07:38:10,340 DEBUG [0-shortCompactions-0] compactions.Compactor - Compacting e629d75027ed4da79fd962e645c7a3b4.d773829ad7e76202cccac6fbc314091b, keycount=18319191, bloomtype=NONE, size=939.0 M, encoding=FAST_DIFF, compression=NONE, seqNum=1963665, earliestPutTs=1637575074953
> 2022-11-16 07:38:10,349 DEBUG [0-shortCompactions-1] compactions.Compactor - Compacting e629d75027ed4da79fd962e645c7a3b4.d773829ad7e76202cccac6fbc314091b, keycount=18319191, bloomtype=NONE, size=939.0 M, encoding=FAST_DIFF, compression=NONE, seqNum=1963664, earliestPutTs=1637575074953
> 2022-11-16 07:40:15,455 DEBUG [dabc6-10-xyz:61020-8] backup.HFileArchiver - Archived from FileableStoreFile, hdfs://c01/hbase/data/default/TABLE01/d188c0c23b5826973511da243e8c892a/0/e629d75027ed4da79fd962e645c7a3b4.d773829ad7e76202cccac6fbc314091b to hdfs://c01/hbase/archive/data/default/TABLE01/d188c0c23b5826973511da243e8c892a/0/e629d75027ed4da79fd962e645c7a3b4.d773829ad7e76202cccac6fbc314091b {code}
>
--
This message was sent by Atlassian Jira
(v8.20.10#820010)