Return-Path: X-Original-To: apmail-hbase-issues-archive@www.apache.org Delivered-To: apmail-hbase-issues-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id AB01510BBA for ; Wed, 25 Feb 2015 06:48:06 +0000 (UTC) Received: (qmail 2525 invoked by uid 500); 25 Feb 2015 06:48:06 -0000 Delivered-To: apmail-hbase-issues-archive@hbase.apache.org Received: (qmail 2486 invoked by uid 500); 25 Feb 2015 06:48:06 -0000 Mailing-List: contact issues-help@hbase.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Delivered-To: mailing list issues@hbase.apache.org Received: (qmail 2473 invoked by uid 99); 25 Feb 2015 06:48:06 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 25 Feb 2015 06:48:06 +0000 Date: Wed, 25 Feb 2015 06:48:06 +0000 (UTC) From: "zhangduo (JIRA)" To: issues@hbase.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Commented] (HBASE-13084) Add labels to VisibilityLabelsCache asynchronously causes TestShell flakey MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/HBASE-13084?page=3Dcom.atlassia= n.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=3D143= 36105#comment-14336105 ]=20 zhangduo commented on HBASE-13084: ---------------------------------- listLabels fetches label from labelRegion, and setAuths check label from la= belsCache, so listLabels is success does not mean setAuths can also be succ= ess... > Add labels to VisibilityLabelsCache asynchronously causes TestShell flake= y > -------------------------------------------------------------------------= - > > 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.patch, HBASE-13084_1.patch, HBASE-13084_= 2.patch, HBASE-13084_2.patch, HBASE-13084_2.patch, HBASE-13084_2.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-outp= ut.txt > {noformat} > 1) Error: > test_The_get/put_methods_should_work_for_data_written_with_Visibility(Hba= se::VisibilityLabelsAdminMethodsTest): > ArgumentError: org.apache.hadoop.hbase.DoNotRetryIOException: org.apache.= hadoop.hbase.security.visibility.InvalidLabelException: Label 'TEST_VISIBIL= ITY' doesn't exists > =09at org.apache.hadoop.hbase.security.visibility.VisibilityController.se= tAuths(VisibilityController.java:808) > =09at org.apache.hadoop.hbase.protobuf.generated.VisibilityLabelsProtos$V= isibilityLabelsService$1.setAuths(VisibilityLabelsProtos.java:6036) > =09at org.apache.hadoop.hbase.protobuf.generated.VisibilityLabelsProtos$V= isibilityLabelsService.callMethod(VisibilityLabelsProtos.java:6219) > =09at org.apache.hadoop.hbase.regionserver.HRegion.execService(HRegion.ja= va:6867) > =09at org.apache.hadoop.hbase.regionserver.RSRpcServices.execServiceOnReg= ion(RSRpcServices.java:1707) > =09at org.apache.hadoop.hbase.regionserver.RSRpcServices.execService(RSRp= cServices.java:1689) > =09at org.apache.hadoop.hbase.protobuf.generated.ClientProtos$ClientServi= ce$2.callBlockingMethod(ClientProtos.java:31309) > =09at org.apache.hadoop.hbase.ipc.RpcServer.call(RpcServer.java:2038) > =09at org.apache.hadoop.hbase.ipc.CallRunner.run(CallRunner.java:107) > =09at org.apache.hadoop.hbase.ipc.RpcExecutor.consumerLoop(RpcExecutor.ja= va:130) > =09at org.apache.hadoop.hbase.ipc.RpcExecutor$1.run(RpcExecutor.java:107) > =09at java.lang.Thread.run(Thread.java:744) > /home/jenkins/jenkins-slave/workspace/PreCommit-HBASE-Build/hbase-she= ll/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::Visibil= ityLabelsAdminMethodsTest): > ArgumentError: No authentication set for the given user jenkins > /home/jenkins/jenkins-slave/workspace/PreCommit-HBASE-Build/hbase-she= ll/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=3Dvisibility_labels_admin_test.rb} > label =3D 'TEST_VISIBILITY' > user =3D 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 Visib= ilityLabelsCache. > {code:title=3DDefaultVisibilityLabelServiceImpl.java} > public OperationStatus[] addLabels(List labels) throws IOExcept= ion { > ... > if (mutateLabelsRegion(puts, finalOpStatus)) { > updateZk(true); > } > for (byte[] label : labels) { > String labelStr =3D Bytes.toString(label); > LOG.info(labelStr + "=3D=3D=3D=3D=3D" + this.labelsCache.getLabelOr= dinal(labelStr)); > } > ... > } > {code} > {code:title=3DVisibilityLabelsCache.java} > public void refreshLabelsCache(byte[] data) throws IOException { > LOG.info("=3D=3D=3D=3D=3D=3D=3D=3Drefresh", new Exception()); > ... > } > {code} > And I modified TestVisibilityLabelsWithCustomVisLabService to use Default= VisibilityLabelServiceImpl, then collected the logs of setupBeforeClass > {noformat} > 2015-02-21 20:39:16,362 INFO [B.defaultRpcServer.handler=3D0,queue=3D0,p= ort=3D42678] visibility.DefaultVisibilityLabelServiceImpl(236): secret=3D= =3D=3D=3D=3D0 > 2015-02-21 20:39:16,362 INFO [B.defaultRpcServer.handler=3D0,queue=3D0,p= ort=3D42678] visibility.DefaultVisibilityLabelServiceImpl(236): topsecret= =3D=3D=3D=3D=3D0 > 2015-02-21 20:39:16,362 INFO [B.defaultRpcServer.handler=3D0,queue=3D0,p= ort=3D42678] visibility.DefaultVisibilityLabelServiceImpl(236): confidentia= l=3D=3D=3D=3D=3D0 > 2015-02-21 20:39:16,362 INFO [B.defaultRpcServer.handler=3D0,queue=3D0,p= ort=3D42678] visibility.DefaultVisibilityLabelServiceImpl(236): public=3D= =3D=3D=3D=3D0 > 2015-02-21 20:39:16,362 INFO [B.defaultRpcServer.handler=3D0,queue=3D0,p= ort=3D42678] visibility.DefaultVisibilityLabelServiceImpl(236): private=3D= =3D=3D=3D=3D0 > 2015-02-21 20:39:16,362 INFO [B.defaultRpcServer.handler=3D0,queue=3D0,p= ort=3D42678] visibility.DefaultVisibilityLabelServiceImpl(236): =C2=A9ABC= =3D=3D=3D=3D=3D0 > 2015-02-21 20:39:16,362 INFO [B.defaultRpcServer.handler=3D0,queue=3D0,p= ort=3D42678] visibility.DefaultVisibilityLabelServiceImpl(236): =E0=A5=81= =3D=3D=3D=3D=3D0 > 2015-02-21 20:39:16,362 INFO [B.defaultRpcServer.handler=3D0,queue=3D0,p= ort=3D42678] visibility.DefaultVisibilityLabelServiceImpl(236): =C2=A9ABC"= =E0=A5=81\secret"'&\=3D=3D=3D=3D=3D0 > 2015-02-21 20:39:16,363 INFO [B.defaultRpcServer.handler=3D0,queue=3D0,p= ort=3D42678] visibility.DefaultVisibilityLabelServiceImpl(236): '"+=3D=3D= =3D=3D=3D0 > 2015-02-21 20:39:16,363 INFO [B.defaultRpcServer.handler=3D0,queue=3D0,p= ort=3D42678] visibility.DefaultVisibilityLabelServiceImpl(236): -?=3D=3D=3D= =3D=3D0 > 2015-02-21 20:39:16,363 INFO [main-EventThread] visibility.VisibilityLab= elsCache(115): =3D=3D=3D=3D=3D=3D=3D=3Drefresh > java.lang.Exception > =09at org.apache.hadoop.hbase.security.visibility.VisibilityLabelsCache.r= efreshLabelsCache(VisibilityLabelsCache.java:115) > =09at org.apache.hadoop.hbase.security.visibility.ZKVisibilityLabelWatche= r.refreshVisibilityLabelsCache(ZKVisibilityLabelWatcher.java:76) > =09at org.apache.hadoop.hbase.security.visibility.ZKVisibilityLabelWatche= r.nodeDataChanged(ZKVisibilityLabelWatcher.java:115) > =09at org.apache.hadoop.hbase.zookeeper.ZooKeeperWatcher.process(ZooKeepe= rWatcher.java:412) > =09at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn= .java:522) > =09at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:498= ) > {noformat} > We can see that, refresh is triggered from a background zk watcher, and i= t is possible that the labels are not in labelsCache after addLabels being = called. -- This message was sent by Atlassian JIRA (v6.3.4#6332)