HBase
  1. HBase
  2. HBASE-7468

TestSplitTransactionOnCluster hangs frequently

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 0.94.3
    • Fix Version/s: 0.94.5
    • Component/s: None
    • Labels:
      None

      Description

      This what I saw once in a local build.

      java.lang.Thread.State: TIMED_WAITING (sleeping)
              at java.lang.Thread.sleep(Native Method)
              at org.apache.hadoop.hbase.client.HBaseAdmin.disableTable(HBaseAdmin.java:831)
              at org.apache.hadoop.hbase.regionserver.TestSplitTransactionOnCluster.testShouldClearRITWhenNodeFoundInSplittingState(TestSplitTransactionOnCluster.java:650)
      
      1. TestSplitTransactionOnCluster-jstack.txt
        172 kB
        Lars Hofhansl
      2. 7468-jstack.txt
        173 kB
        Lars Hofhansl
      3. 7468-output.zip
        102 kB
        Lars Hofhansl
      4. 7468-0.94.txt
        11 kB
        Lars Hofhansl
      5. 7468-0.94-v2.txt
        11 kB
        Lars Hofhansl
      6. TEST-org.apache.hadoop.hbase.regionserver.TestSplitTransactionOnCluster.xml
        28 kB
        Lars Hofhansl
      7. HBASE-7468v3.patch
        12 kB
        ramkrishna.s.vasudevan
      8. TEST-org.apache.hadoop.hbase.regionserver.TestSplitTransactionOnCluster.xml
        28 kB
        Lars Hofhansl
      9. 7468-0.94-v4.txt
        11 kB
        Lars Hofhansl
      10. TEST-org.apache.hadoop.hbase.regionserver.TestSplitTransactionOnCluster.xml
        31 kB
        Lars Hofhansl

        Activity

        Hide
        Hudson added a comment -

        Integrated in HBase-0.94-security-on-Hadoop-23 #11 (See https://builds.apache.org/job/HBase-0.94-security-on-Hadoop-23/11/)
        HBASE-7468 TestSplitTransactionOnCluster hangs frequently (Revision 1432808)

        Result = FAILURE
        larsh :
        Files :

        • /hbase/branches/0.94/src/test/java/org/apache/hadoop/hbase/regionserver/TestSplitTransactionOnCluster.java
        Show
        Hudson added a comment - Integrated in HBase-0.94-security-on-Hadoop-23 #11 (See https://builds.apache.org/job/HBase-0.94-security-on-Hadoop-23/11/ ) HBASE-7468 TestSplitTransactionOnCluster hangs frequently (Revision 1432808) Result = FAILURE larsh : Files : /hbase/branches/0.94/src/test/java/org/apache/hadoop/hbase/regionserver/TestSplitTransactionOnCluster.java
        Hide
        Hudson added a comment -

        Integrated in HBase-0.94-security #95 (See https://builds.apache.org/job/HBase-0.94-security/95/)
        HBASE-7468 TestSplitTransactionOnCluster hangs frequently (Revision 1432808)

        Result = SUCCESS
        larsh :
        Files :

        • /hbase/branches/0.94/src/test/java/org/apache/hadoop/hbase/regionserver/TestSplitTransactionOnCluster.java
        Show
        Hudson added a comment - Integrated in HBase-0.94-security #95 (See https://builds.apache.org/job/HBase-0.94-security/95/ ) HBASE-7468 TestSplitTransactionOnCluster hangs frequently (Revision 1432808) Result = SUCCESS larsh : Files : /hbase/branches/0.94/src/test/java/org/apache/hadoop/hbase/regionserver/TestSplitTransactionOnCluster.java
        Hide
        ramkrishna.s.vasudevan added a comment -

        Raised https://issues.apache.org/jira/browse/HBASE-7551.
        We can close this and work on the new one Lars. Thanks.

        Show
        ramkrishna.s.vasudevan added a comment - Raised https://issues.apache.org/jira/browse/HBASE-7551 . We can close this and work on the new one Lars. Thanks.
        Hide
        ramkrishna.s.vasudevan added a comment -

        Ideally the nodeChildrenChange event iterates thro the list of new znodes on the /hbase/assignment nodes. And then creates a watcher on that. One reason could be there are more than one znode and so the watch setting operation takes time. The order of execution is different when we try running from eclipse and when we run mvn tests.
        My conclusion is that the testcase actually reveals the problem but the same can happen in any case where the SPLITTING event can get missed out. May be some of the SPLIT related bugs that were raised is due to this? Need to analyse.

        Any suggestions welcome. We should ensure that the transition from SPLITTING to SPLITTING should happen only after the master has set the watch on the znode and we should be sure of that.

        Show
        ramkrishna.s.vasudevan added a comment - Ideally the nodeChildrenChange event iterates thro the list of new znodes on the /hbase/assignment nodes. And then creates a watcher on that. One reason could be there are more than one znode and so the watch setting operation takes time. The order of execution is different when we try running from eclipse and when we run mvn tests. My conclusion is that the testcase actually reveals the problem but the same can happen in any case where the SPLITTING event can get missed out. May be some of the SPLIT related bugs that were raised is due to this? Need to analyse. Any suggestions welcome. We should ensure that the transition from SPLITTING to SPLITTING should happen only after the master has set the watch on the znode and we should be sure of that.
        Hide
        ramkrishna.s.vasudevan added a comment -

        I got the issue. I am able to reproduce this
        See the logs

        2013-01-14 14:37:21,760 INFO  [main] regionserver.SplitTransaction(216): Starting split of region testShouldClearRITWhenNodeFoundInSplittingState,,1358154439514.a9e57d09c58b3ef3b949d602232fb2c2.
        
        2013-01-14 14:37:21,760 DEBUG [main] regionserver.SplitTransaction(871): regionserver:61665-0x13c384e4e4f0002 Creating ephemeral node for a9e57d09c58b3ef3b949d602232fb2c2 in SPLITTING state
        
        2013-01-14 14:37:21,844 DEBUG [main] zookeeper.ZKAssign(757): regionserver:61665-0x13c384e4e4f0002 Attempting to transition node a9e57d09c58b3ef3b949d602232fb2c2 from RS_ZK_REGION_SPLITTING to RS_ZK_REGION_SPLITTING
        
        2013-01-14 14:37:21,849 DEBUG [Thread-873-EventThread] zookeeper.ZooKeeperWatcher(277): master:62334-0x13c384e4e4f001b Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/unassigned
        
        2013-01-14 14:37:21,853 DEBUG [main] zookeeper.ZKUtil(1565): regionserver:61665-0x13c384e4e4f0002 Retrieved 140 byte(s) of data from znode /hbase/unassigned/a9e57d09c58b3ef3b949d602232fb2c2; data=region=testShouldClearRITWhenNodeFoundInSplittingState,,1358154439514.a9e57d09c58b3ef3b949d602232fb2c2., origin=Ram.Home,61665,1358154325430, state=RS_ZK_REGION_SPLITTING
        
        2013-01-14 14:37:21,918 DEBUG [main] zookeeper.ZKAssign(820): regionserver:61665-0x13c384e4e4f0002 Successfully transitioned node a9e57d09c58b3ef3b949d602232fb2c2 from RS_ZK_REGION_SPLITTING to RS_ZK_REGION_SPLITTING
        
        2013-01-14 14:37:21,919 DEBUG [Thread-873-EventThread] zookeeper.ZKUtil(417): master:62334-0x13c384e4e4f001b Set watcher on existing znode /hbase/unassigned/a9e57d09c58b3ef3b949d602232fb2c2
        

        Here we can observe that the SPLITTING node was first created. Then we transit it to SPLITTING to SPLITTING so that AM can have the nodeDataChange event. But for the nodeDataChange event to happen first nodeChildrenChange event should happen so that the master can set a watcher on the node.

        Now when this hang happens, we can see that after the transition happens only then the watcher is set by nodeChildrenChange event and so the SPLITTING to SPLITTING event itself is missed or skipped.

        Show
        ramkrishna.s.vasudevan added a comment - I got the issue. I am able to reproduce this See the logs 2013-01-14 14:37:21,760 INFO [main] regionserver.SplitTransaction(216): Starting split of region testShouldClearRITWhenNodeFoundInSplittingState,,1358154439514.a9e57d09c58b3ef3b949d602232fb2c2. 2013-01-14 14:37:21,760 DEBUG [main] regionserver.SplitTransaction(871): regionserver:61665-0x13c384e4e4f0002 Creating ephemeral node for a9e57d09c58b3ef3b949d602232fb2c2 in SPLITTING state 2013-01-14 14:37:21,844 DEBUG [main] zookeeper.ZKAssign(757): regionserver:61665-0x13c384e4e4f0002 Attempting to transition node a9e57d09c58b3ef3b949d602232fb2c2 from RS_ZK_REGION_SPLITTING to RS_ZK_REGION_SPLITTING 2013-01-14 14:37:21,849 DEBUG [ Thread -873-EventThread] zookeeper.ZooKeeperWatcher(277): master:62334-0x13c384e4e4f001b Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/unassigned 2013-01-14 14:37:21,853 DEBUG [main] zookeeper.ZKUtil(1565): regionserver:61665-0x13c384e4e4f0002 Retrieved 140 byte (s) of data from znode /hbase/unassigned/a9e57d09c58b3ef3b949d602232fb2c2; data=region=testShouldClearRITWhenNodeFoundInSplittingState,,1358154439514.a9e57d09c58b3ef3b949d602232fb2c2., origin=Ram.Home,61665,1358154325430, state=RS_ZK_REGION_SPLITTING 2013-01-14 14:37:21,918 DEBUG [main] zookeeper.ZKAssign(820): regionserver:61665-0x13c384e4e4f0002 Successfully transitioned node a9e57d09c58b3ef3b949d602232fb2c2 from RS_ZK_REGION_SPLITTING to RS_ZK_REGION_SPLITTING 2013-01-14 14:37:21,919 DEBUG [ Thread -873-EventThread] zookeeper.ZKUtil(417): master:62334-0x13c384e4e4f001b Set watcher on existing znode /hbase/unassigned/a9e57d09c58b3ef3b949d602232fb2c2 Here we can observe that the SPLITTING node was first created. Then we transit it to SPLITTING to SPLITTING so that AM can have the nodeDataChange event. But for the nodeDataChange event to happen first nodeChildrenChange event should happen so that the master can set a watcher on the node. Now when this hang happens, we can see that after the transition happens only then the watcher is set by nodeChildrenChange event and so the SPLITTING to SPLITTING event itself is missed or skipped.
        Hide
        Hudson added a comment -

        Integrated in HBase-0.94 #729 (See https://builds.apache.org/job/HBase-0.94/729/)
        HBASE-7468 TestSplitTransactionOnCluster hangs frequently (Revision 1432808)

        Result = FAILURE
        larsh :
        Files :

        • /hbase/branches/0.94/src/test/java/org/apache/hadoop/hbase/regionserver/TestSplitTransactionOnCluster.java
        Show
        Hudson added a comment - Integrated in HBase-0.94 #729 (See https://builds.apache.org/job/HBase-0.94/729/ ) HBASE-7468 TestSplitTransactionOnCluster hangs frequently (Revision 1432808) Result = FAILURE larsh : Files : /hbase/branches/0.94/src/test/java/org/apache/hadoop/hbase/regionserver/TestSplitTransactionOnCluster.java
        Hide
        Lars Hofhansl added a comment -

        Thanks Ram.

        Should we close this issue (since the hangs are now gone) and continue with the specific failures in another jira?

        Show
        Lars Hofhansl added a comment - Thanks Ram. Should we close this issue (since the hangs are now gone) and continue with the specific failures in another jira?
        Hide
        ramkrishna.s.vasudevan added a comment -

        The output log file that you have attached on 7th Jan is the full log i suppose. There you can see a ZK expiry log coming.
        Will look into it once again.

        Show
        ramkrishna.s.vasudevan added a comment - The output log file that you have attached on 7th Jan is the full log i suppose. There you can see a ZK expiry log coming. Will look into it once again.
        Hide
        Lars Hofhansl added a comment -

        In any case, the attached patch will turn hanging tests into proper assertion failures, and also make failures less likely. So I am going to commit this to 0.94.
        Then we can investigate further why the assert mentioned above fails sometimes.

        Show
        Lars Hofhansl added a comment - In any case, the attached patch will turn hanging tests into proper assertion failures, and also make failures less likely. So I am going to commit this to 0.94. Then we can investigate further why the assert mentioned above fails sometimes.
        Hide
        Lars Hofhansl added a comment -

        One more log, this time with the ZK expired exception I was mentioning.
        Interestingly, if I loop testShouldClearRITWhenNodeFoundInSplittingState by itself, I can run it forever and it won't fail (well after HBASE-7550 that is).
        So this failure has some relation to the other tests running either previously or concurrently.

        Show
        Lars Hofhansl added a comment - One more log, this time with the ZK expired exception I was mentioning. Interestingly, if I loop testShouldClearRITWhenNodeFoundInSplittingState by itself, I can run it forever and it won't fail (well after HBASE-7550 that is). So this failure has some relation to the other tests running either previously or concurrently.
        Hide
        Lars Hofhansl added a comment -

        This test is quite a bit different in trunk (why is that?)
        Removing the 0.96 target.

        Show
        Lars Hofhansl added a comment - This test is quite a bit different in trunk (why is that?) Removing the 0.96 target.
        Hide
        Lars Hofhansl added a comment -

        Slightly improved patch that also fixes another problem where we did not give the ZK watcher enough time to learn of the change.

        Show
        Lars Hofhansl added a comment - Slightly improved patch that also fixes another problem where we did not give the ZK watcher enough time to learn of the change.
        Hide
        Lars Hofhansl added a comment -

        Here's a failed run with the timeout increased to 20s.
        Something it seems is preventing the node from being set.
        (I tried with 40s timeout as well, as saw the same problem as well).

        Show
        Lars Hofhansl added a comment - Here's a failed run with the timeout increased to 20s. Something it seems is preventing the node from being set. (I tried with 40s timeout as well, as saw the same problem as well).
        Hide
        Lars Hofhansl added a comment -

        In one test run I actually got a session expired from the Master's ZK watcher.

        Show
        Lars Hofhansl added a comment - In one test run I actually got a session expired from the Master's ZK watcher.
        Hide
        Lars Hofhansl added a comment -

        As per my comment above I tried that.
        Did not help unfortunately. I set that timeout to 20s, and it would still happen.

        Show
        Lars Hofhansl added a comment - As per my comment above I tried that. Did not help unfortunately. I set that timeout to 20s, and it would still happen.
        Hide
        ramkrishna.s.vasudevan added a comment -

        Increased the timeout before

        assertTrue("region is not in transition",
                  am.getRegionsInTransition().containsKey(regions.get(0).getRegionInfo().getEncodedName()));
        

        Here too we should have sufficient timeout. Because only after transitioning the znode to SPLITTING we will get the callback. That may take some time.

        Show
        ramkrishna.s.vasudevan added a comment - Increased the timeout before assertTrue( "region is not in transition" , am.getRegionsInTransition().containsKey(regions.get(0).getRegionInfo().getEncodedName())); Here too we should have sufficient timeout. Because only after transitioning the znode to SPLITTING we will get the callback. That may take some time.
        Hide
        Lars Hofhansl added a comment - - edited

        Here's the log of the failing test, which failed here:

        testShouldClearRITWhenNodeFoundInSplittingState(org.apache.hadoop.hbase.regionserver.TestSplitTransactionOnCluster)  Time elapsed: 3.19 sec  <<< FAILURE!
        java.lang.AssertionError: region is not in transition
                at org.junit.Assert.fail(Assert.java:93)
                at org.junit.Assert.assertTrue(Assert.java:43)
                at org.apache.hadoop.hbase.regionserver.TestSplitTransactionOnCluster.testShouldClearRITWhenNodeFoundInSplittingState(TestSplitTransactionOnCluster.java:630)
        
        Show
        Lars Hofhansl added a comment - - edited Here's the log of the failing test, which failed here: testShouldClearRITWhenNodeFoundInSplittingState(org.apache.hadoop.hbase.regionserver.TestSplitTransactionOnCluster) Time elapsed: 3.19 sec <<< FAILURE! java.lang.AssertionError: region is not in transition at org.junit.Assert.fail(Assert.java:93) at org.junit.Assert.assertTrue(Assert.java:43) at org.apache.hadoop.hbase.regionserver.TestSplitTransactionOnCluster.testShouldClearRITWhenNodeFoundInSplittingState(TestSplitTransactionOnCluster.java:630)
        Hide
        ramkrishna.s.vasudevan added a comment -

        Lars Hofhansl
        If the test fails once again with timeout increased, pls attach the logs. Am not able to run the testcases as i don have an env with me.
        I will debug and fix the issue. Lets see if there is a problem with the split and disable scenario also. Thanks Lars. Appreciate your time.

        Show
        ramkrishna.s.vasudevan added a comment - Lars Hofhansl If the test fails once again with timeout increased, pls attach the logs. Am not able to run the testcases as i don have an env with me. I will debug and fix the issue. Lets see if there is a problem with the split and disable scenario also. Thanks Lars. Appreciate your time.
        Hide
        Lars Hofhansl added a comment -

        Same patch with timeout increased.

        Show
        Lars Hofhansl added a comment - Same patch with timeout increased.
        Hide
        Lars Hofhansl added a comment -

        The 2nd increase did not help. Times out after 20s now.

        Show
        Lars Hofhansl added a comment - The 2nd increase did not help. Times out after 20s now.
        Hide
        Lars Hofhansl added a comment -

        Sorry for the span, after 50mins or so I saw another failure. This time it failed here:

         assertTrue("region is not in transition",
                  am.getRegionsInTransition().containsKey(regions.get(0).getRegionInfo().getEncodedName()));
        

        The wait here was also only 2s, I increased that to 20s. Let's see what happens.

        Show
        Lars Hofhansl added a comment - Sorry for the span, after 50mins or so I saw another failure. This time it failed here: assertTrue( "region is not in transition" , am.getRegionsInTransition().containsKey(regions.get(0).getRegionInfo().getEncodedName())); The wait here was also only 2s, I increased that to 20s. Let's see what happens.
        Hide
        Lars Hofhansl added a comment -

        Increased the timeout to 20s.
        Have been running the test in a loop now for 40min, did not fail once - before this was easily reproducible after a few minutes.
        I am going to commit this (with the timeout for a SPLIT increased to 20s).

        Show
        Lars Hofhansl added a comment - Increased the timeout to 20s. Have been running the test in a loop now for 40min, did not fail once - before this was easily reproducible after a few minutes. I am going to commit this (with the timeout for a SPLIT increased to 20s).
        Hide
        Lars Hofhansl added a comment -

        Indeed when I run the test in a loop now, I see the assertion fail that Ram mentioned.
        I increased the timeout and am running the test in a loop again.

        Show
        Lars Hofhansl added a comment - Indeed when I run the test in a loop now, I see the assertion fail that Ram mentioned. I increased the timeout and am running the test in a loop again.
        Hide
        Lars Hofhansl added a comment -

        Right now it wait for 2s for the SPLITTING znode to be removed. Could wait up to 20s instead.

        Show
        Lars Hofhansl added a comment - Right now it wait for 2s for the SPLITTING znode to be removed. Could wait up to 20s instead.
        Hide
        Lars Hofhansl added a comment -

        Do you think we should also wait longer to for the split to happen?

        Show
        Lars Hofhansl added a comment - Do you think we should also wait longer to for the split to happen?
        Hide
        ramkrishna.s.vasudevan added a comment -

        Ok Lars. This is fine. +1.
        We will see if this helps us out.

        Show
        ramkrishna.s.vasudevan added a comment - Ok Lars. This is fine. +1. We will see if this helps us out.
        Hide
        Lars Hofhansl added a comment -

        Here's a 0.94 patch that exactly that.

        Show
        Lars Hofhansl added a comment - Here's a 0.94 patch that exactly that.
        Hide
        Lars Hofhansl added a comment -

        I think the first step should be to remove the try/finally blocks for disabling the tables. In most cases that just hides the problem.

        Show
        Lars Hofhansl added a comment - I think the first step should be to remove the try/finally blocks for disabling the tables. In most cases that just hides the problem.
        Hide
        Lars Hofhansl added a comment -

        Are you saying we should put the infinite timeouts back? These hangs did happens before I removed them (in an attempt to pinpoint where it actually hangs).

        Is this a split racing with a disable of the table?
        It seems like the main problem is disabling the table in a finally clause, which would try to disable it even when some of the assertions fail.
        We could just remove the try/finally and cleanup the table only after successful test execution... At least that would not hide the problem as it does now.

        Show
        Lars Hofhansl added a comment - Are you saying we should put the infinite timeouts back? These hangs did happens before I removed them (in an attempt to pinpoint where it actually hangs). Is this a split racing with a disable of the table? It seems like the main problem is disabling the table in a finally clause, which would try to disable it even when some of the assertions fail. We could just remove the try/finally and cleanup the table only after successful test execution... At least that would not hide the problem as it does now.
        Hide
        ramkrishna.s.vasudevan added a comment -

        The way RIT is populated for SPLITTING in 0.94 is not there in trunk after the AM related changes.
        The logs does not clearly tell the reason why is it taking a while but currently the testcase waits for 2 sec for it to happen.

        Waiting should remove the znode i feel. Need to run the tests repeatedly to see if there is any other reason for it.

        Show
        ramkrishna.s.vasudevan added a comment - The way RIT is populated for SPLITTING in 0.94 is not there in trunk after the AM related changes. The logs does not clearly tell the reason why is it taking a while but currently the testcase waits for 2 sec for it to happen. Waiting should remove the znode i feel. Need to run the tests repeatedly to see if there is any other reason for it.
        Hide
        stack added a comment -

        ...we need to wait till the RIT is removed for the SPLITTING znode...

        Or can we just block until it is removed (with a timeout on the test) rather than have a timer? Will it get removed if we wait long enough? Why is it taking a while?

        Why is this test not in trunk, do you know Ram?

        Thanks for taking a looksee.

        Show
        stack added a comment - ...we need to wait till the RIT is removed for the SPLITTING znode... Or can we just block until it is removed (with a timeout on the test) rather than have a timer? Will it get removed if we wait long enough? Why is it taking a while? Why is this test not in trunk, do you know Ram? Thanks for taking a looksee.
        Hide
        ramkrishna.s.vasudevan added a comment -

        So found the reason. As stated in the above comment after rollback we need to delete the znode. Only after the znode deletion happens it is possible to remove from RIT. Only then the disable will be successful.
        In the previous commit, the infinite loops were removed and changed to finite loops. So basically here the

               assertFalse("region is still in transition",
                    am.getRegionsInTransition().containsKey(regions.get(0).getRegionInfo().getEncodedName()));
        

        assertion has failed and it has tried to disable the table which did not happen.
        But in the output file attached by Lars the thing is the node deleted event never happened at all and i doubt it is because of the session expiry error that has come just after the rollback

        2013-01-06 21:49:35,500 WARN  [Master:0;bunnypig,51009,1357537755267-EventThread] zookeeper.ZKUtil(423): hconnection-0x13c138da85b0019 Unable to set watcher on znode /hbase/master
        org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /hbase/master
        	at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
        	at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
        	at org.apache.zookeeper.ZooKeeper.exists(ZooKeeper.java:1041)
        	at org.apache.hadoop.hbase.zookeeper.RecoverableZooKeeper.exists(RecoverableZooKeeper.java:172)
        	at org.apache.hadoop.hbase.zookeeper.ZKUtil.watchAndCheckExists(ZKUtil.java:414)
        	at org.apache.hadoop.hbase.zookeeper.ZooKeeperNodeTracker.nodeDeleted(ZooKeeperNodeTracker.java:188)
        	at org.apache.hadoop.hbase.zookeeper.ZooKeeperWatcher.process(ZooKeeperWatcher.java:301)
        

        So my suggestion would be we need to wait till the RIT is removed for the SPLITTING znode that happens thro AM.nodeDeleted(). And we should introdue a timeout for the test which is missing. The same testcase does not exist in Trunk.
        @Lars
        Pls provide your thoughts.

        Show
        ramkrishna.s.vasudevan added a comment - So found the reason. As stated in the above comment after rollback we need to delete the znode. Only after the znode deletion happens it is possible to remove from RIT. Only then the disable will be successful. In the previous commit, the infinite loops were removed and changed to finite loops. So basically here the assertFalse( "region is still in transition" , am.getRegionsInTransition().containsKey(regions.get(0).getRegionInfo().getEncodedName())); assertion has failed and it has tried to disable the table which did not happen. But in the output file attached by Lars the thing is the node deleted event never happened at all and i doubt it is because of the session expiry error that has come just after the rollback 2013-01-06 21:49:35,500 WARN [Master:0;bunnypig,51009,1357537755267-EventThread] zookeeper.ZKUtil(423): hconnection-0x13c138da85b0019 Unable to set watcher on znode /hbase/master org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /hbase/master at org.apache.zookeeper.KeeperException.create(KeeperException.java:127) at org.apache.zookeeper.KeeperException.create(KeeperException.java:51) at org.apache.zookeeper.ZooKeeper.exists(ZooKeeper.java:1041) at org.apache.hadoop.hbase.zookeeper.RecoverableZooKeeper.exists(RecoverableZooKeeper.java:172) at org.apache.hadoop.hbase.zookeeper.ZKUtil.watchAndCheckExists(ZKUtil.java:414) at org.apache.hadoop.hbase.zookeeper.ZooKeeperNodeTracker.nodeDeleted(ZooKeeperNodeTracker.java:188) at org.apache.hadoop.hbase.zookeeper.ZooKeeperWatcher.process(ZooKeeperWatcher.java:301) So my suggestion would be we need to wait till the RIT is removed for the SPLITTING znode that happens thro AM.nodeDeleted(). And we should introdue a timeout for the test which is missing. The same testcase does not exist in Trunk. @Lars Pls provide your thoughts.
        Hide
        ramkrishna.s.vasudevan added a comment -

        Started with this. What i could see is that the testShouldClearRITWhenNodeFoundInSplittingState() has failed to delete the znode on rollback of SPLIT. So this has made the disable not to happen due to this

        2013-01-06 21:49:33,509 DEBUG [bunnypig,36944,1357537761566-org.apache.hadoop.hbase.master.handler.DisableTableHandler$BulkDisabler-0] master.AssignmentManager(2063): /hbase/unassigned/5f308eaff51750dae5c8327ad015a20a is SPLIT or SPLITTING; skipping unassign because region no longer exists -- its split 
        

        Also some of the other testcases need some clean up. Will investigate further and keep posted. But that is for tomorrow. Hope to close this off sooner and make it run fine.

        Show
        ramkrishna.s.vasudevan added a comment - Started with this. What i could see is that the testShouldClearRITWhenNodeFoundInSplittingState() has failed to delete the znode on rollback of SPLIT. So this has made the disable not to happen due to this 2013-01-06 21:49:33,509 DEBUG [bunnypig,36944,1357537761566-org.apache.hadoop.hbase.master.handler.DisableTableHandler$BulkDisabler-0] master.AssignmentManager(2063): /hbase/unassigned/5f308eaff51750dae5c8327ad015a20a is SPLIT or SPLITTING; skipping unassign because region no longer exists -- its split Also some of the other testcases need some clean up. Will investigate further and keep posted. But that is for tomorrow. Hope to close this off sooner and make it run fine.
        Hide
        ramkrishna.s.vasudevan added a comment -

        Thanks Lars. I will look into this tomorrow and see if i can find something. Good on you.

        Show
        ramkrishna.s.vasudevan added a comment - Thanks Lars. I will look into this tomorrow and see if i can find something. Good on you.
        Hide
        Lars Hofhansl added a comment -

        Just produced this again. jstack and the test-output.

        Show
        Lars Hofhansl added a comment - Just produced this again. jstack and the test-output.
        Hide
        Lars Hofhansl added a comment -

        To reproduce a failing scenario I just run the test in a loop like this:

        while mvn test -PlocalTests -Dtest=TestSplitTransactionOnCluster | grep "BUILD SUCCESS"; do echo "OK"; done
        
        Show
        Lars Hofhansl added a comment - To reproduce a failing scenario I just run the test in a loop like this: while mvn test -PlocalTests -Dtest=TestSplitTransactionOnCluster | grep "BUILD SUCCESS" ; do echo "OK" ; done
        Hide
        Lars Hofhansl added a comment -

        another case:

        "Thread-1301" prio=10 tid=0x00007f19f0b41000 nid=0x1794 waiting on condition [0x
        00007f19d8e3d000]
           java.lang.Thread.State: TIMED_WAITING (sleeping)
                at java.lang.Thread.sleep(Native Method)
                at org.apache.hadoop.hbase.client.HBaseAdmin.createTable(HBaseAdmin.java
        :446)
                at org.apache.hadoop.hbase.client.HBaseAdmin.createTable(HBaseAdmin.java
        :335)
                at org.apache.hadoop.hbase.regionserver.TestSplitTransactionOnCluster.testShouldFailSplitIfZNodeDoesNotExistDueToPrevRollBack(TestSplitTransactionOnCluster.java:666)
        
        Show
        Lars Hofhansl added a comment - another case: " Thread -1301" prio=10 tid=0x00007f19f0b41000 nid=0x1794 waiting on condition [0x 00007f19d8e3d000] java.lang. Thread .State: TIMED_WAITING (sleeping) at java.lang. Thread .sleep(Native Method) at org.apache.hadoop.hbase.client.HBaseAdmin.createTable(HBaseAdmin.java :446) at org.apache.hadoop.hbase.client.HBaseAdmin.createTable(HBaseAdmin.java :335) at org.apache.hadoop.hbase.regionserver.TestSplitTransactionOnCluster.testShouldFailSplitIfZNodeDoesNotExistDueToPrevRollBack(TestSplitTransactionOnCluster.java:666)
        Hide
        Lars Hofhansl added a comment -

        It happens when I run TestSplitTransactionOnCluster in a loop, after a dozen times or so.
        I'll try to reproduce later today.

        Show
        Lars Hofhansl added a comment - It happens when I run TestSplitTransactionOnCluster in a loop, after a dozen times or so. I'll try to reproduce later today.
        Hide
        ramkrishna.s.vasudevan added a comment -

        Any logs possible when this happened. I am not able to reproduce this

        Show
        ramkrishna.s.vasudevan added a comment - Any logs possible when this happened. I am not able to reproduce this
        Hide
        Ted Yu added a comment -

        I checked open region handler threads. They were all waiting with stack similar to the following:

           java.lang.Thread.State: WAITING (parking)
          at sun.misc.Unsafe.park(Native Method)
          - parking to wait for  <0x00000007ec7f14a0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
          at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
          at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
          at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
        
        Show
        Ted Yu added a comment - I checked open region handler threads. They were all waiting with stack similar to the following: java.lang. Thread .State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000007ec7f14a0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043) at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
        Hide
        Lars Hofhansl added a comment -

        This is the other interesting part:

        "MASTER_TABLE_OPERATIONS-bunnypig,53142,1356935902274-0" prio=10 tid=0x00007ff44403c800 nid=0x7004 waiting on condition [0x00007ff46be6d000]
           java.lang.Thread.State: TIMED_WAITING (sleeping)
        	at java.lang.Thread.sleep(Native Method)
        	at org.apache.hadoop.hbase.master.handler.DisableTableHandler$BulkDisabler.waitUntilDone(DisableTableHandler.java:171)
        	at org.apache.hadoop.hbase.master.BulkAssigner.bulkAssign(BulkAssigner.java:105)
        	at org.apache.hadoop.hbase.master.BulkAssigner.bulkAssign(BulkAssigner.java:79)
        	at org.apache.hadoop.hbase.master.handler.DisableTableHandler.handleDisableTable(DisableTableHandler.java:124)
        	at org.apache.hadoop.hbase.master.handler.DisableTableHandler.process(DisableTableHandler.java:98)
        	at org.apache.hadoop.hbase.executor.EventHandler.run(EventHandler.java:169)
        	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
        	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
        	at java.lang.Thread.run(Thread.java:722)
        
        Show
        Lars Hofhansl added a comment - This is the other interesting part: "MASTER_TABLE_OPERATIONS-bunnypig,53142,1356935902274-0" prio=10 tid=0x00007ff44403c800 nid=0x7004 waiting on condition [0x00007ff46be6d000] java.lang. Thread .State: TIMED_WAITING (sleeping) at java.lang. Thread .sleep(Native Method) at org.apache.hadoop.hbase.master.handler.DisableTableHandler$BulkDisabler.waitUntilDone(DisableTableHandler.java:171) at org.apache.hadoop.hbase.master.BulkAssigner.bulkAssign(BulkAssigner.java:105) at org.apache.hadoop.hbase.master.BulkAssigner.bulkAssign(BulkAssigner.java:79) at org.apache.hadoop.hbase.master.handler.DisableTableHandler.handleDisableTable(DisableTableHandler.java:124) at org.apache.hadoop.hbase.master.handler.DisableTableHandler.process(DisableTableHandler.java:98) at org.apache.hadoop.hbase.executor.EventHandler.run(EventHandler.java:169) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) at java.lang. Thread .run( Thread .java:722)
        Hide
        Lars Hofhansl added a comment -

        Just ran it in a loop and after 10 attempts (or so) it happened again:

        "main" prio=10 tid=0x00007ff480008000 nid=0x69ee waiting on condition [0x00007ff
        487e9b000]
           java.lang.Thread.State: TIMED_WAITING (sleeping)
                at java.lang.Thread.sleep(Native Method)
                at org.apache.hadoop.hbase.client.HBaseAdmin.disableTable(HBaseAdmin.jav
        a:831)
                at org.apache.hadoop.hbase.regionserver.TestSplitTransactionOnCluster.te
        stShouldClearRITWhenNodeFoundInSplittingState(TestSplitTransactionOnCluster.java
        :650)
        

        Will attach the fill jstack.

        Show
        Lars Hofhansl added a comment - Just ran it in a loop and after 10 attempts (or so) it happened again: "main" prio=10 tid=0x00007ff480008000 nid=0x69ee waiting on condition [0x00007ff 487e9b000] java.lang. Thread .State: TIMED_WAITING (sleeping) at java.lang. Thread .sleep(Native Method) at org.apache.hadoop.hbase.client.HBaseAdmin.disableTable(HBaseAdmin.jav a:831) at org.apache.hadoop.hbase.regionserver.TestSplitTransactionOnCluster.te stShouldClearRITWhenNodeFoundInSplittingState(TestSplitTransactionOnCluster.java :650) Will attach the fill jstack.
        Hide
        Lars Hofhansl added a comment -

        I've seen this in HBASE-7432. It turned out the the new MasterObserver code (HBASE-7331) was missing a null check. But that is since fixed (and it happened 100% of the time).

        I also only observed the hang above once.

        Show
        Lars Hofhansl added a comment - I've seen this in HBASE-7432 . It turned out the the new MasterObserver code ( HBASE-7331 ) was missing a null check. But that is since fixed (and it happened 100% of the time). I also only observed the hang above once.
        Hide
        Ted Yu added a comment -

        There appear to be both active open and close handlers in the master going on at the same time

        Let me guess: open handler for daughter region, close handler for parent ?

        Show
        Ted Yu added a comment - There appear to be both active open and close handlers in the master going on at the same time Let me guess: open handler for daughter region, close handler for parent ?
        Hide
        Andrew Purtell added a comment -

        With a 0.94 branch updated this morning, this is the result of running TestSplitTransactionOnCluster locally:

        Tests run: 11, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 110.065 sec <<< FAILURE!
        testShouldClearRITWhenNodeFoundInSplittingState(org.apache.hadoop.hbase.regionserver.TestSplitTransactionOnCluster)  Time elapsed: 3.722 sec  <<< FAILURE!
        java.lang.AssertionError
        	at org.junit.Assert.fail(Assert.java:92)
        	at org.junit.Assert.assertTrue(Assert.java:43)
        	at org.junit.Assert.assertFalse(Assert.java:68)
        	at org.junit.Assert.assertFalse(Assert.java:79)
        	at org.apache.hadoop.hbase.regionserver.TestSplitTransactionOnCluster.testShouldClearRITWhenNodeFoundInSplittingState(TestSplitTransactionOnCluster.java:627)
        	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:616)
        	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:45)
        	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
        	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:42)
        	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
        	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
        	at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:47)
        	at org.junit.rules.RunRules.evaluate(RunRules.java:18)
        	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:263)
        	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:68)
        	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:47)
        	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231)
        	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:60)
        	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:229)
        	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:50)
        	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:222)
        	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
        	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:30)
        	at org.junit.runners.ParentRunner.run(ParentRunner.java:300)
        	at org.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:53)
        	at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:123)
        	at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:104)
        	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:616)
        	at org.apache.maven.surefire.util.ReflectionUtils.invokeMethodWithArray(ReflectionUtils.java:164)
        	at org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy.invoke(ProviderFactory.java:110)
        	at org.apache.maven.surefire.booter.SurefireStarter.invokeProvider(SurefireStarter.java:175)
        	at org.apache.maven.surefire.booter.SurefireStarter.runSuitesInProcessWhenForked(SurefireStarter.java:81)
        	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:68)
        
        Show
        Andrew Purtell added a comment - With a 0.94 branch updated this morning, this is the result of running TestSplitTransactionOnCluster locally: Tests run: 11, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 110.065 sec <<< FAILURE! testShouldClearRITWhenNodeFoundInSplittingState(org.apache.hadoop.hbase.regionserver.TestSplitTransactionOnCluster) Time elapsed: 3.722 sec <<< FAILURE! java.lang.AssertionError at org.junit.Assert.fail(Assert.java:92) at org.junit.Assert.assertTrue(Assert.java:43) at org.junit.Assert.assertFalse(Assert.java:68) at org.junit.Assert.assertFalse(Assert.java:79) at org.apache.hadoop.hbase.regionserver.TestSplitTransactionOnCluster.testShouldClearRITWhenNodeFoundInSplittingState(TestSplitTransactionOnCluster.java:627) 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:616) at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:45) at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15) at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:42) at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20) at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28) at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:47) at org.junit.rules.RunRules.evaluate(RunRules.java:18) at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:263) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:68) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:47) at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231) at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:60) at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:229) at org.junit.runners.ParentRunner.access$000(ParentRunner.java:50) at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:222) at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28) at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:30) at org.junit.runners.ParentRunner.run(ParentRunner.java:300) at org.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:53) at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:123) at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:104) 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:616) at org.apache.maven.surefire.util.ReflectionUtils.invokeMethodWithArray(ReflectionUtils.java:164) at org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy.invoke(ProviderFactory.java:110) at org.apache.maven.surefire.booter.SurefireStarter.invokeProvider(SurefireStarter.java:175) at org.apache.maven.surefire.booter.SurefireStarter.runSuitesInProcessWhenForked(SurefireStarter.java:81) at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:68)
        Hide
        Andrew Purtell added a comment -

        I've seen this in jstacks too recently, hanging in disableTable. There appear to be both active open and close handlers in the master going on at the same time. Like Ram I'm not in a position to dig in until next week.

        Show
        Andrew Purtell added a comment - I've seen this in jstacks too recently, hanging in disableTable. There appear to be both active open and close handlers in the master going on at the same time. Like Ram I'm not in a position to dig in until next week.
        Hide
        Lars Hofhansl added a comment -

        Thanks Ram, that would be awesome!
        Interestingly the code where it hangs is here.

            } finally {
              if (admin.isTableAvailable(tableName) && admin.isTableEnabled(tableName)) {
        -->     admin.disableTable(tableName);
                admin.deleteTable(tableName);
                admin.close();
              }
            }
        

        So the table is available and enabled.

        Show
        Lars Hofhansl added a comment - Thanks Ram, that would be awesome! Interestingly the code where it hangs is here. } finally { if (admin.isTableAvailable(tableName) && admin.isTableEnabled(tableName)) { --> admin.disableTable(tableName); admin.deleteTable(tableName); admin.close(); } } So the table is available and enabled.
        Hide
        ramkrishna.s.vasudevan added a comment -

        Lars may be i can check this out. But am currently out of station. Can i check this out on wednesday if the time permits?
        I see you have spent good amount of your time on this. So thought i can help you out on this.

        Show
        ramkrishna.s.vasudevan added a comment - Lars may be i can check this out. But am currently out of station. Can i check this out on wednesday if the time permits? I see you have spent good amount of your time on this. So thought i can help you out on this.
        Hide
        Lars Hofhansl added a comment -

        With the defaults HBaseAdmin.disableTable can close to an hour.

        Show
        Lars Hofhansl added a comment - With the defaults HBaseAdmin.disableTable can close to an hour.

          People

          • Assignee:
            ramkrishna.s.vasudevan
            Reporter:
            Lars Hofhansl
          • Votes:
            0 Vote for this issue
            Watchers:
            9 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development