You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@hbase.apache.org by "Duo Zhang (JIRA)" <ji...@apache.org> on 2018/06/12 10:38:00 UTC
[jira] [Commented] (HBASE-19998) Flakey
TestVisibilityLabelsWithDefaultVisLabelService
[ https://issues.apache.org/jira/browse/HBASE-19998?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16509474#comment-16509474 ]
Duo Zhang commented on HBASE-19998:
-----------------------------------
OK, arrive here when implementing HBASE-20708. I wonder when will we call nodeCreated? I think nodeCreated will only be called when you call exists on an inexistent path on zk. But here, for RegionServerTracker, we will only set watchers on the existent children. And obviously, we can not know what is the node name for a new RS, so it is impossible to get a server added notification through nodeCreated...
> Flakey TestVisibilityLabelsWithDefaultVisLabelService
> -----------------------------------------------------
>
> Key: HBASE-19998
> URL: https://issues.apache.org/jira/browse/HBASE-19998
> Project: HBase
> Issue Type: Bug
> Components: flakey, test
> Reporter: stack
> Assignee: stack
> Priority: Major
> Fix For: 2.0.0-beta-2, 2.0.0
>
> Attachments: HBASE-19998.master.001.patch, hbase-19988.master.001.patch
>
>
> This is a good one. Its a timeout and though it has lots of test methods, the problem is one of them gets stuck. The test method kills a RegionServers then starts a new one. Usually all works out fine but the odd time there is this unexplained MOVE that gets interjected just as ServerCrashProcedure starts up. hbase:meta gets stuck (perhaps this is what is being referred to here: https://issues.apache.org/jira/browse/HBASE-19929?focusedCommentId=16356906&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-16356906). It is trying to run the MOVE by first unassigning from the server that has just crashed. It never succeeds. Need to fix this. Need to figure where these Move operations are coming from too. Let me add some debug.
> See here how we are well into ServerCrashProcedure... and then two MOVEs cut-in... for hbase:meta and for namespace:
> {code}
> ....
> 2018-02-14 02:35:19,806 DEBUG [PEWorker-6] procedure.ServerCrashProcedure(192): pid=10, state=RUNNABLE:SERVER_CRASH_PROCESS_META; ServerCrashProcedure server=asf903.gq1.ygridcore.net,59608,1518575711969, splitWal=true, meta=true; Processing hbase:meta that was on asf903.gq1.ygridcore.net,59608,1518575711969
> 2018-02-14 02:35:19,807 INFO [PEWorker-6] procedure2.ProcedureExecutor(1498): Initialized subprocedures=[{pid=12, ppid=10, state=RUNNABLE:RECOVER_META_SPLIT_LOGS; RecoverMetaProcedure failedMetaServer=asf903.gq1.ygridcore.net,59608,1518575711969, splitWal=true}]
> 2018-02-14 02:35:19,811 DEBUG [Thread-214] procedure2.ProcedureExecutor(868): Stored pid=11, state=RUNNABLE:MOVE_REGION_UNASSIGN; MoveRegionProcedure hri=hbase:meta,,1.1588230740, source=asf903.gq1.ygridcore.net,59608,1518575711969, destination=
> 2018-02-14 02:35:19,813 INFO [PEWorker-8] procedure.MasterProcedureScheduler(813): pid=11, state=RUNNABLE:MOVE_REGION_UNASSIGN; MoveRegionProcedure hri=hbase:meta,,1.1588230740, source=asf903.gq1.ygridcore.net,59608,1518575711969, destination= hbase:meta hbase:meta,,1.1588230740
> 2018-02-14 02:35:19,814 INFO [PEWorker-8] procedure2.ProcedureExecutor(1498): Initialized subprocedures=[{pid=14, ppid=11, state=RUNNABLE:REGION_TRANSITION_DISPATCH; UnassignProcedure table=hbase:meta, region=1588230740, server=asf903.gq1.ygridcore.net,59608,1518575711969}]
> 2018-02-14 02:35:19,831 DEBUG [Thread-214] procedure2.ProcedureExecutor(868): Stored pid=13, state=RUNNABLE:MOVE_REGION_UNASSIGN; MoveRegionProcedure hri=hbase:namespace,,1518575716296.e52a160b3f3a57ab50d710eba62d9b15., source=asf903.gq1.ygridcore.net,59608,1518575711969, destination=
> 2018-02-14 02:35:19,833 INFO [PEWorker-10] procedure.MasterProcedureScheduler(813): pid=13, state=RUNNABLE:MOVE_REGION_UNASSIGN; MoveRegionProcedure hri=hbase:namespace,,1518575716296.e52a160b3f3a57ab50d710eba62d9b15., source=asf903.gq1.ygridcore.net,59608,1518575711969, destination= hbase:namespace hbase:namespace,,1518575716296.e52a160b3f3a57ab50d710eba62d9b15.
> 2018-02-14 02:35:19,837 INFO [PEWorker-10] procedure2.ProcedureExecutor(1498): Initialized subprocedures=[{pid=15, ppid=13, state=RUNNABLE:REGION_TRANSITION_DISPATCH; UnassignProcedure table=hbase:namespace, region=e52a160b3f3a57ab50d710eba62d9b15, server=asf903.gq1.ygridcore.net,59608,1518575711969}]
> ....
> {code}
> Here is the failure of the unassign:
> {code}
> 2018-02-14 02:35:19,944 WARN [PEWorker-8] assignment.RegionTransitionProcedure(187): Remote call failed pid=14, ppid=11, state=RUNNABLE:REGION_TRANSITION_DISPATCH; UnassignProcedure table=hbase:meta, region=1588230740, server=asf903.gq1.ygridcore.net,59608,1518575711969; rit=CLOSING, location=asf903.gq1.ygridcore.net,59608,1518575711969; exception=pid=14, ppid=11, state=RUNNABLE:REGION_TRANSITION_DISPATCH; UnassignProcedure table=hbase:meta, region=1588230740, server=asf903.gq1.ygridcore.net,59608,1518575711969 to asf903.gq1.ygridcore.net,59608,1518575711969
> 2018-02-14 02:35:19,945 WARN [PEWorker-8] assignment.UnassignProcedure(245): Expiring server pid=14, ppid=11, state=RUNNABLE:REGION_TRANSITION_DISPATCH; UnassignProcedure table=hbase:meta, region=1588230740, server=asf903.gq1.ygridcore.net,59608,1518575711969; rit=CLOSING, location=asf903.gq1.ygridcore.net,59608,1518575711969, exception=org.apache.hadoop.hbase.master.assignment.FailedRemoteDispatchException: pid=14, ppid=11, state=RUNNABLE:REGION_TRANSITION_DISPATCH; UnassignProcedure table=hbase:meta, region=1588230740, server=asf903.gq1.ygridcore.net,59608,1518575711969 to asf903.gq1.ygridcore.net,59608,1518575711969
> 2018-02-14 02:35:19,945 WARN [PEWorker-8] master.ServerManager(579): Expiration of asf903.gq1.ygridcore.net,59608,1518575711969 but server shutdown already in progress
> 2018-02-14 02:35:19,949 DEBUG [RS-EventLoopGroup-4-22] ipc.FailedServers(56): Added failed server with address asf903.gq1.ygridcore.net/67.195.81.147:59608 to list caused by org.apache.hbase.thirdparty.io.netty.channel.AbstractChannel$AnnotatedConnectException: syscall:getsockopt(..) failed: Connection refused: asf903.gq1.ygridcore.net/67.195.81.147:59608
> 2018-02-14 02:35:20,064 DEBUG [MultiHConnection-shared--pool8-t5] ipc.AbstractRpcClient(349): Not trying to connect to asf903.gq1.ygridcore.net/67.195.81.147:59608 this server is in the failed servers list
> ...
> {code}
> ... and we keep trying:
> {code}
> 2018-02-14 02:35:22,093 INFO [MultiHConnection-shared--pool8-t5] client.AsyncRequestFutureImpl(767): id=6, table=hbase:meta, attempt=6/46 failed=1ops, last exception=java.net.ConnectException: Call to asf903.gq1.ygridcore.net/67.195.81.147:59608 failed on connection exception: org.apache.hbase.thirdparty.io.netty.channel.AbstractChannel$AnnotatedConnectException: syscall:getsockopt(..) failed: Connection refused: asf903.gq1.ygridcore.net/67.195.81.147:59608 on asf903.gq1.ygridcore.net,59608,1518575711969, tracking started null, retrying after=2000ms, replay=1ops
> 2018-02-14 02:35:24,095 DEBUG [MultiHConnection-shared--pool8-t5] ipc.NettyRpcConnection(254): Connecting to asf903.gq1.ygridcore.net/67.195.81.147:59608
> 2018-02-14 02:35:24,110 DEBUG [RS-EventLoopGroup-4-24] ipc.FailedServers(56): Added failed server with address asf903.gq1.ygridcore.net/67.195.81.147:59608 to list caused by org.apache.hbase.thirdparty.io.netty.channel.AbstractChannel$AnnotatedConnectException: syscall:getsockopt(..) failed: Connection refused: asf903.gq1.ygridcore.net/67.195.81.147:59608
> 2018-02-14 02:35:24,112 INFO [MultiHConnection-shared--pool8-t5] client.AsyncRequestFutureImpl(767): id=6, table=hbase:meta, attempt=7/46 failed=1ops, last exception=java.net.ConnectException: Call to asf903.gq1.ygridcore.net/67.195.81.147:59608 failed on connection exception: org.apache.hbase.thirdparty.io.netty.channel.AbstractChannel$AnnotatedConnectException: syscall:getsockopt(..) failed: Connection refused: asf903.gq1.ygridcore.net/67.195.81.147:59608 on asf903.gq1.ygridcore.net,59608,1518575711969, tracking started null, retrying after=4005ms, replay=1ops
> 2018-02-14 02:35:28,120 DEBUG [MultiHConnection-shared--pool8-t5] ipc.NettyRpcConnection(254): Connecting to asf903.gq1.ygridcore.net/67.195.81.147:59608
> {code}
> Test set: org.apache.hadoop.hbase.security.visibility.TestVisibilityLabelsWithDefaultVisLabelService
> -------------------------------------------------------------------------------
> Tests run: 2, Failures: 0, Errors: 2, Skipped: 0, Time elapsed: 600.83 s <<< FAILURE! - in org.apache.hadoop.hbase.security.visibility.TestVisibilityLabelsWithDefaultVisLabelService
> org.apache.hadoop.hbase.security.visibility.TestVisibilityLabelsWithDefaultVisLabelService Time elapsed: 583.188 s <<< ERROR!
> org.junit.runners.model.TestTimedOutException: test timed out after 600 seconds
> at org.apache.hadoop.hbase.security.visibility.TestVisibilityLabelsWithDefaultVisLabelService.testAddVisibilityLabelsOnRSRestart(TestVisibilityLabelsWithDefaultVisLabelService.java:126)
> org.apache.hadoop.hbase.security.visibility.TestVisibilityLabelsWithDefaultVisLabelService Time elapsed: 583.227 s <<< ERROR!
> java.lang.Exception: Appears to be stuck in thread RS-EventLoopGroup-7-2
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)