[
https://issues.apache.org/jira/browse/HBASE-28366?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17817531#comment-17817531
]
Viraj Jasani commented on HBASE-28366:
--------------------------------------
{quote}I’ve seen many times that if the znode goes away (delete or expire), the
master will throw YouAreDeadException the next time the RS checks in
{quote}
Yes, you are correct, however it seems we have possibility of edge case here.
Without TRACE log, report regionserver rpc calls are hard to track but it seems
that beyond the dead server check (which throws YouAreDeadException), the
region report went ahead, then SCP removed the server entry from
AssignmentManager's rsReports map, but by that time, regionServerReport()
validation was already completed and the master went ahead with
reportOnlineRegions() call and that eventually added the rsReports map entry
again.
One more surprising observation is that the old server (start code:
1706541866103)'s regionServerReport() was again served by master when new
server on the same host (start code: 1706547696987) was already online and
registered to master:
{code:java}
2024-01-29 17:02:17,315 INFO
[iority.RWQ.Fifo.write.handler=2,queue=0,port=61000] master.ServerManager -
Server serverName=server1-114.xyz,61020,1706541866103 rejected; we already have
server1-114.xyz,61020,1706547696987 registered with same hostname and port
2024-01-29 17:02:17,315 INFO
[iority.RWQ.Fifo.write.handler=2,queue=0,port=61000] master.ServerManager -
RegionServerReport ignored, could not record the server:
server1-114.xyz,61020,1706541866103 {code}
New server was brought online at 17:01:35. Perhaps the master handler was able
to serve old server's regionServerReport() rpc call with some delay.
> Mis-order of SCP and regionServerReport results into region inconsistencies
> ---------------------------------------------------------------------------
>
> Key: HBASE-28366
> URL: https://issues.apache.org/jira/browse/HBASE-28366
> Project: HBase
> Issue Type: Bug
> Affects Versions: 2.4.17, 3.0.0-beta-1, 2.5.7
> Reporter: Viraj Jasani
> Assignee: Viraj Jasani
> Priority: Major
>
> If the regionserver is online but due to network issue, if it's rs ephemeral
> node gets deleted in zookeeper, active master schedules the SCP. However, if
> the regionserver is alive, it can still send regionServerReport to active
> master. In the case where SCP assigns regions to other regionserver that were
> previously hosted on the old regionserver (which is still alive), the old rs
> can continue to sent regionServerReport to active master.
> Eventually this results into region inconsistencies because region is alive
> on two regionservers at the same time (though it's temporary state because
> the rs will be aborted soon). While old regionserver can have zookeeper
> connectivity issues, it can still make rpc calls to active master.
> Logs:
> SCP:
> {code:java}
> 2024-01-29 16:50:33,956 INFO [RegionServerTracker-0]
> assignment.AssignmentManager - Scheduled ServerCrashProcedure pid=9812440 for
> server1-114.xyz,61020,1706541866103 (carryingMeta=false)
> server1-114.xyz,61020,1706541866103/CRASHED/regionCount=364/lock=java.util.concurrent.locks.ReentrantReadWriteLock@5d5fc31[Write
> locks = 1, Read locks = 0], oldState=ONLINE.
> 2024-01-29 16:50:33,956 DEBUG [RegionServerTracker-0]
> procedure2.ProcedureExecutor - Stored pid=9812440,
> state=RUNNABLE:SERVER_CRASH_START; ServerCrashProcedure
> server1-114.xyz,61020,1706541866103, splitWal=true, meta=false
> 2024-01-29 16:50:33,973 INFO [PEWorker-36] procedure.ServerCrashProcedure -
> Splitting WALs pid=9812440, state=RUNNABLE:SERVER_CRASH_SPLIT_LOGS,
> locked=true; ServerCrashProcedure server1-114.xyz,61020,1706541866103,
> splitWal=true, meta=false, isMeta: false
> {code}
> As part of SCP, d743ace9f70d55f55ba1ecc6dc49a5cb was assigned to another
> server:
>
> {code:java}
> 2024-01-29 16:50:42,656 INFO [PEWorker-24] procedure.MasterProcedureScheduler
> - Took xlock for pid=9818494, ppid=9812440,
> state=RUNNABLE:REGION_STATE_TRANSITION_GET_ASSIGN_CANDIDATE;
> TransitRegionStateProcedure
> table=PLATFORM_ENTITY.PLATFORM_IMMUTABLE_ENTITY_DATA,
> region=d743ace9f70d55f55ba1ecc6dc49a5cb, ASSIGN
> 2024-01-29 16:50:43,106 INFO [PEWorker-23] assignment.RegionStateStore -
> pid=9818494 updating hbase:meta row=d743ace9f70d55f55ba1ecc6dc49a5cb,
> regionState=OPEN, repBarrier=12867482, openSeqNum=12867482,
> regionLocation=server1-65.xyz,61020,1706165574050
> {code}
>
> rs abort, after ~5 min:
> {code:java}
> 2024-01-29 16:54:27,235 ERROR [regionserver/server1-114:61020]
> regionserver.HRegionServer - ***** ABORTING region server
> server1-114.xyz,61020,1706541866103: Unexpected exception handling getData
> *****
> org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode
> = ConnectionLoss for /hbase/master
> at org.apache.zookeeper.KeeperException.create(KeeperException.java:102)
> at org.apache.zookeeper.KeeperException.create(KeeperException.java:54)
> at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1229)
> at
> org.apache.hadoop.hbase.zookeeper.RecoverableZooKeeper.getData(RecoverableZooKeeper.java:414)
> at
> org.apache.hadoop.hbase.zookeeper.ZKUtil.getDataInternal(ZKUtil.java:403)
> at
> org.apache.hadoop.hbase.zookeeper.ZKUtil.getDataAndWatch(ZKUtil.java:367)
> at
> org.apache.hadoop.hbase.zookeeper.ZKNodeTracker.getData(ZKNodeTracker.java:180)
> at
> org.apache.hadoop.hbase.zookeeper.MasterAddressTracker.getMasterAddress(MasterAddressTracker.java:152)
> at
> org.apache.hadoop.hbase.regionserver.HRegionServer.createRegionServerStatusStub(HRegionServer.java:2892)
> at
> org.apache.hadoop.hbase.regionserver.HRegionServer.tryRegionServerReport(HRegionServer.java:1352)
> at
> org.apache.hadoop.hbase.regionserver.HRegionServer.run(HRegionServer.java:1142)
> {code}
>
> Several region transition failure report logs:
> {code:java}
> 2024-01-29 16:55:13,029 INFO [_REGION-regionserver/server1-114:61020-0]
> regionserver.HRegionServer - Failed report transition server { host_name:
> "server1-114.xyz" port: 61020 start_code: 1706541866103 } transition {
> transition_code: CLOSED region_info { region_id: 1671555604277 table_name {
> namespace: "default" qualifier: "TABLE1" } start_key: "abc" end_key: "xyz"
> offline: false split: false replica_id: 0 } proc_id: -1 }; retry (#0)
> immediately.
> java.net.UnknownHostException: Call to address=master-server1.xyz:61000
> failed on local exception: java.net.UnknownHostException:
> master-server1.xyz:61000 could not be resolved
> at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
> at
> sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
> at
> sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
> at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
> at org.apache.hadoop.hbase.ipc.IPCUtil.wrapException(IPCUtil.java:239)
> at
> org.apache.hadoop.hbase.ipc.AbstractRpcClient.onCallFinished(AbstractRpcClient.java:391)
> at
> org.apache.hadoop.hbase.ipc.AbstractRpcClient.access$100(AbstractRpcClient.java:92)
> at
> org.apache.hadoop.hbase.ipc.AbstractRpcClient$3.run(AbstractRpcClient.java:425)
> at
> org.apache.hadoop.hbase.ipc.AbstractRpcClient$3.run(AbstractRpcClient.java:420)
> at org.apache.hadoop.hbase.ipc.Call.callComplete(Call.java:114)
> at org.apache.hadoop.hbase.ipc.Call.setException(Call.java:129)
> at
> org.apache.hadoop.hbase.ipc.NettyRpcConnection.lambda$sendRequest$4(NettyRpcConnection.java:365)
> at
> org.apache.hbase.thirdparty.io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:174)
> at
> org.apache.hbase.thirdparty.io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:167)
> at
> org.apache.hbase.thirdparty.io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470)
> at
> org.apache.hbase.thirdparty.io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:403)
> at
> org.apache.hbase.thirdparty.io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
> at
> org.apache.hbase.thirdparty.io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
> at
> org.apache.hbase.thirdparty.io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
> at java.lang.Thread.run(Thread.java:750)
> Caused by: java.net.UnknownHostException: master-server1.xyz:61000 could not
> be resolved
> at
> org.apache.hadoop.hbase.ipc.RpcConnection.getRemoteInetAddress(RpcConnection.java:192)
> at
> org.apache.hadoop.hbase.ipc.NettyRpcConnection.connect(NettyRpcConnection.java:280)
> at
> org.apache.hadoop.hbase.ipc.NettyRpcConnection.access$900(NettyRpcConnection.java:79)
> at
> org.apache.hadoop.hbase.ipc.NettyRpcConnection$5.run(NettyRpcConnection.java:340)
> at
> org.apache.hadoop.hbase.ipc.HBaseRpcControllerImpl.notifyOnCancel(HBaseRpcControllerImpl.java:259)
> at
> org.apache.hadoop.hbase.ipc.NettyRpcConnection.sendRequest0(NettyRpcConnection.java:323)
> at
> org.apache.hadoop.hbase.ipc.NettyRpcConnection.lambda$sendRequest$4(NettyRpcConnection.java:363)
> ... 8 more
> {code}
>
> The server is later started after sometime:
> {code:java}
> Mon Jan 29 17:01:35 UTC 2024 Starting regionserver on server1-114.xyz
> core file size (blocks, -c) unlimited
> ...
> ... {code}
>
> In order to avoid region inconsistencies, we should clear regionserver ->
> region reported map from active master. We can do it in two ways:
> # Active: master should throw error while serving regionServerReport call if
> the server is already considered dead due to deletion of ephemeral znode.
> # Passive: run a chore that can compare the regionserver -> region map
> generated from the regionserver reports with the actual live servers based on
> the zk tracking, and remove any rs report that is no longer valid.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
