[ https://issues.apache.org/jira/browse/HBASE-13084?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14341246#comment-14341246 ]
zhangduo commented on HBASE-13084: ---------------------------------- https://builds.apache.org/job/HBase-TRUNK/6180/testReport/junit/org.apache.hadoop.hbase.client/TestReplicationShell/org_apache_hadoop_hbase_client_TestReplicationShell/ {noformat} 2015-02-28 02:28:36,085 WARN [main] mortbay.log (Slf4jLog.java:warn(76)) - failed SelectChannelConnector@0.0.0.0:16010: java.net.BindException: Address already in use 2015-02-28 02:28:36,085 WARN [main] mortbay.log (Slf4jLog.java:warn(76)) - failed Server@5de44bb4: java.net.BindException: Address already in use 2015-02-28 02:28:36,086 ERROR [main] hbase.MiniHBaseCluster (MiniHBaseCluster.java:init(229)) - Error starting cluster java.lang.RuntimeException: Failed construction of Master: class org.apache.hadoop.hbase.master.HMasterAddress already in use at org.apache.hadoop.hbase.util.JVMClusterUtil.createMasterThread(JVMClusterUtil.java:143) at org.apache.hadoop.hbase.LocalHBaseCluster.addMaster(LocalHBaseCluster.java:216) at org.apache.hadoop.hbase.LocalHBaseCluster.<init>(LocalHBaseCluster.java:154) at org.apache.hadoop.hbase.MiniHBaseCluster.init(MiniHBaseCluster.java:213) at org.apache.hadoop.hbase.MiniHBaseCluster.<init>(MiniHBaseCluster.java:93) at org.apache.hadoop.hbase.HBaseTestingUtility.startMiniHBaseCluster(HBaseTestingUtility.java:996) at org.apache.hadoop.hbase.HBaseTestingUtility.startMiniCluster(HBaseTestingUtility.java:956) at org.apache.hadoop.hbase.HBaseTestingUtility.startMiniCluster(HBaseTestingUtility.java:830) at org.apache.hadoop.hbase.HBaseTestingUtility.startMiniCluster(HBaseTestingUtility.java:824) at org.apache.hadoop.hbase.HBaseTestingUtility.startMiniCluster(HBaseTestingUtility.java:768) at org.apache.hadoop.hbase.client.AbstractTestShell.setUpBeforeClass(AbstractTestShell.java:50) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:606) at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47) at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44) at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:24) at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27) at org.junit.runners.ParentRunner.run(ParentRunner.java:309) at org.junit.runners.Suite.runChild(Suite.java:127) at org.junit.runners.Suite.runChild(Suite.java:26) at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238) at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63) at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236) at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53) at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229) at org.junit.runners.ParentRunner.run(ParentRunner.java:309) at org.junit.runner.JUnitCore.run(JUnitCore.java:160) at org.junit.runner.JUnitCore.run(JUnitCore.java:138) at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.createRequestAndRun(JUnitCoreWrapper.java:107) at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.executeEager(JUnitCoreWrapper.java:77) at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:53) at org.apache.maven.surefire.junitcore.JUnitCoreProvider.invoke(JUnitCoreProvider.java:144) at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:203) at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:155) at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103) Caused by: java.io.IOException: Failed to start redirecting jetty server at org.apache.hadoop.hbase.master.HMaster.putUpJettyServer(HMaster.java:428) at org.apache.hadoop.hbase.master.HMaster.<init>(HMaster.java:391) at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) at java.lang.reflect.Constructor.newInstance(Constructor.java:526) at org.apache.hadoop.hbase.util.JVMClusterUtil.createMasterThread(JVMClusterUtil.java:139) ... 37 more Caused by: java.net.BindException: Address already in use at sun.nio.ch.Net.bind0(Native Method) at sun.nio.ch.Net.bind(Net.java:444) at sun.nio.ch.Net.bind(Net.java:436) at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:214) at sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:74) at org.mortbay.jetty.nio.SelectChannelConnector.open(SelectChannelConnector.java:216) at org.mortbay.jetty.nio.SelectChannelConnector.doStart(SelectChannelConnector.java:315) at org.mortbay.component.AbstractLifeCycle.start(AbstractLifeCycle.java:50) at org.mortbay.jetty.Server.doStart(Server.java:235) at org.mortbay.component.AbstractLifeCycle.start(AbstractLifeCycle.java:50) at org.apache.hadoop.hbase.master.HMaster.putUpJettyServer(HMaster.java:426) ... 43 more {noformat} 16010 seems to be the default info port, but I think we set all ports to 0 in unit tests? Let me check again. > Add labels to VisibilityLabelsCache asynchronously causes TestShell flakey > -------------------------------------------------------------------------- > > Key: HBASE-13084 > URL: https://issues.apache.org/jira/browse/HBASE-13084 > Project: HBase > Issue Type: Bug > Components: test > Reporter: zhangduo > Assignee: zhangduo > Fix For: 2.0.0, 1.1.0 > > Attachments: HBASE-13084-addendum.patch, HBASE-13084.patch, > HBASE-13084_1.patch, HBASE-13084_2.patch, HBASE-13084_2.patch, > HBASE-13084_2.patch, HBASE-13084_2.patch, HBASE-13084_2_disable_test.patch > > > As discussed in HBASE-12953, we found this error in PreCommit log > https://builds.apache.org/job/PreCommit-HBASE-Build/12918/artifact/hbase-shell/target/surefire-reports/org.apache.hadoop.hbase.client.TestShell-output.txt > {noformat} > 1) Error: > test_The_get/put_methods_should_work_for_data_written_with_Visibility(Hbase::VisibilityLabelsAdminMethodsTest): > ArgumentError: org.apache.hadoop.hbase.DoNotRetryIOException: > org.apache.hadoop.hbase.security.visibility.InvalidLabelException: Label > 'TEST_VISIBILITY' doesn't exists > at > org.apache.hadoop.hbase.security.visibility.VisibilityController.setAuths(VisibilityController.java:808) > at > org.apache.hadoop.hbase.protobuf.generated.VisibilityLabelsProtos$VisibilityLabelsService$1.setAuths(VisibilityLabelsProtos.java:6036) > at > org.apache.hadoop.hbase.protobuf.generated.VisibilityLabelsProtos$VisibilityLabelsService.callMethod(VisibilityLabelsProtos.java:6219) > at > org.apache.hadoop.hbase.regionserver.HRegion.execService(HRegion.java:6867) > at > org.apache.hadoop.hbase.regionserver.RSRpcServices.execServiceOnRegion(RSRpcServices.java:1707) > at > org.apache.hadoop.hbase.regionserver.RSRpcServices.execService(RSRpcServices.java:1689) > at > org.apache.hadoop.hbase.protobuf.generated.ClientProtos$ClientService$2.callBlockingMethod(ClientProtos.java:31309) > at org.apache.hadoop.hbase.ipc.RpcServer.call(RpcServer.java:2038) > at org.apache.hadoop.hbase.ipc.CallRunner.run(CallRunner.java:107) > at > org.apache.hadoop.hbase.ipc.RpcExecutor.consumerLoop(RpcExecutor.java:130) > at org.apache.hadoop.hbase.ipc.RpcExecutor$1.run(RpcExecutor.java:107) > at java.lang.Thread.run(Thread.java:744) > > /home/jenkins/jenkins-slave/workspace/PreCommit-HBASE-Build/hbase-shell/src/main/ruby/hbase/visibility_labels.rb:84:in > `set_auths' > ./src/test/ruby/hbase/visibility_labels_admin_test.rb:77:in > `test_The_get/put_methods_should_work_for_data_written_with_Visibility' > org/jruby/RubyProc.java:270:in `call' > org/jruby/RubyKernel.java:2105:in `send' > org/jruby/RubyArray.java:1620:in `each' > org/jruby/RubyArray.java:1620:in `each' > 2) Error: > test_The_set/clear_methods_should_work_with_authorizations(Hbase::VisibilityLabelsAdminMethodsTest): > ArgumentError: No authentication set for the given user jenkins > > /home/jenkins/jenkins-slave/workspace/PreCommit-HBASE-Build/hbase-shell/src/main/ruby/hbase/visibility_labels.rb:97:in > `get_auths' > ./src/test/ruby/hbase/visibility_labels_admin_test.rb:57:in > `test_The_set/clear_methods_should_work_with_authorizations' > org/jruby/RubyProc.java:270:in `call' > org/jruby/RubyKernel.java:2105:in `send' > org/jruby/RubyArray.java:1620:in `each' > org/jruby/RubyArray.java:1620:in `each' > {noformat} > This is the test code > {code:title=visibility_labels_admin_test.rb} > label = 'TEST_VISIBILITY' > user = org.apache.hadoop.hbase.security.User.getCurrent().getName(); > visibility_admin.add_labels(label) > visibility_admin.set_auths(user, label) > {code} > It says 'label does not exists' when calling set_auths. > Then I add some ugly logs in DefaultVisibilityLabelServiceImpl and > VisibilityLabelsCache. > {code:title=DefaultVisibilityLabelServiceImpl.java} > public OperationStatus[] addLabels(List<byte[]> labels) throws IOException { > ... > if (mutateLabelsRegion(puts, finalOpStatus)) { > updateZk(true); > } > for (byte[] label : labels) { > String labelStr = Bytes.toString(label); > LOG.info(labelStr + "=====" + > this.labelsCache.getLabelOrdinal(labelStr)); > } > ... > } > {code} > {code:title=VisibilityLabelsCache.java} > public void refreshLabelsCache(byte[] data) throws IOException { > LOG.info("========refresh", new Exception()); > ... > } > {code} > And I modified TestVisibilityLabelsWithCustomVisLabService to use > DefaultVisibilityLabelServiceImpl, then collected the logs of setupBeforeClass > {noformat} > 2015-02-21 20:39:16,362 INFO > [B.defaultRpcServer.handler=0,queue=0,port=42678] > visibility.DefaultVisibilityLabelServiceImpl(236): secret=====0 > 2015-02-21 20:39:16,362 INFO > [B.defaultRpcServer.handler=0,queue=0,port=42678] > visibility.DefaultVisibilityLabelServiceImpl(236): topsecret=====0 > 2015-02-21 20:39:16,362 INFO > [B.defaultRpcServer.handler=0,queue=0,port=42678] > visibility.DefaultVisibilityLabelServiceImpl(236): confidential=====0 > 2015-02-21 20:39:16,362 INFO > [B.defaultRpcServer.handler=0,queue=0,port=42678] > visibility.DefaultVisibilityLabelServiceImpl(236): public=====0 > 2015-02-21 20:39:16,362 INFO > [B.defaultRpcServer.handler=0,queue=0,port=42678] > visibility.DefaultVisibilityLabelServiceImpl(236): private=====0 > 2015-02-21 20:39:16,362 INFO > [B.defaultRpcServer.handler=0,queue=0,port=42678] > visibility.DefaultVisibilityLabelServiceImpl(236): ©ABC=====0 > 2015-02-21 20:39:16,362 INFO > [B.defaultRpcServer.handler=0,queue=0,port=42678] > visibility.DefaultVisibilityLabelServiceImpl(236): ु=====0 > 2015-02-21 20:39:16,362 INFO > [B.defaultRpcServer.handler=0,queue=0,port=42678] > visibility.DefaultVisibilityLabelServiceImpl(236): ©ABC"ु\secret"'&\=====0 > 2015-02-21 20:39:16,363 INFO > [B.defaultRpcServer.handler=0,queue=0,port=42678] > visibility.DefaultVisibilityLabelServiceImpl(236): '"+=====0 > 2015-02-21 20:39:16,363 INFO > [B.defaultRpcServer.handler=0,queue=0,port=42678] > visibility.DefaultVisibilityLabelServiceImpl(236): -?=====0 > 2015-02-21 20:39:16,363 INFO [main-EventThread] > visibility.VisibilityLabelsCache(115): ========refresh > java.lang.Exception > at > org.apache.hadoop.hbase.security.visibility.VisibilityLabelsCache.refreshLabelsCache(VisibilityLabelsCache.java:115) > at > org.apache.hadoop.hbase.security.visibility.ZKVisibilityLabelWatcher.refreshVisibilityLabelsCache(ZKVisibilityLabelWatcher.java:76) > at > org.apache.hadoop.hbase.security.visibility.ZKVisibilityLabelWatcher.nodeDataChanged(ZKVisibilityLabelWatcher.java:115) > at > org.apache.hadoop.hbase.zookeeper.ZooKeeperWatcher.process(ZooKeeperWatcher.java:412) > at > org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:522) > at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:498) > {noformat} > We can see that, refresh is triggered from a background zk watcher, and it is > possible that the labels are not in labelsCache after addLabels being called. -- This message was sent by Atlassian JIRA (v6.3.4#6332)