Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

HBASE-28413 Fix race condition in TestCleanerChore.retriesIOExceptionInStatus #5735

Open
wants to merge 2 commits into
base: master
Choose a base branch
from

Conversation

ndimiduk
Copy link
Member

@ndimiduk ndimiduk commented Mar 1, 2024

We occasionally get a test failure in TestCleanerChore.retriesIOExceptionInStatus. For example, from a recent PR build 0 on branch-2.6,

java.util.concurrent.ExecutionException: java.io.IOException: whomp whomp.
	at java.base/java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:395)
	at java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1999)
	at org.apache.hadoop.hbase.master.cleaner.TestCleanerChore.retriesIOExceptionInStatus(TestCleanerChore.java:163)
...
Caused by: java.io.IOException: whomp whomp.
	at org.apache.hadoop.hbase.master.cleaner.TestCleanerChore$1.listStatus(TestCleanerChore.java:134)
	at org.apache.hadoop.hbase.master.cleaner.CleanerChore.traverseAndDelete(CleanerChore.java:475)
	at org.apache.hadoop.hbase.master.cleaner.CleanerChore.lambda$chore$0(CleanerChore.java:258)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	... 1 more

This looks like a race condition where the chore manages an entire execution between when the flag is flipped and when the test thread gets back around to continuing execution. Make the test a little more pessimistic about its view of the world.

…InStatus

We occasionally get a test failure in TestCleanerChore.retriesIOExceptionInStatus. For example,
from a recent PR build [0] on branch-2.6,

```
java.util.concurrent.ExecutionException: java.io.IOException: whomp whomp.
	at java.base/java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:395)
	at java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1999)
	at org.apache.hadoop.hbase.master.cleaner.TestCleanerChore.retriesIOExceptionInStatus(TestCleanerChore.java:163)
...
Caused by: java.io.IOException: whomp whomp.
	at org.apache.hadoop.hbase.master.cleaner.TestCleanerChore$1.listStatus(TestCleanerChore.java:134)
	at org.apache.hadoop.hbase.master.cleaner.CleanerChore.traverseAndDelete(CleanerChore.java:475)
	at org.apache.hadoop.hbase.master.cleaner.CleanerChore.lambda$chore$0(CleanerChore.java:258)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	... 1 more
```

This looks like a race condition where the chore manages an entire execution between when the flag
is flipped and when the test thread gets back around to continuing execution. Make the test a
little more pessimistic about its view of the world.

[0]: https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-5725/1/testReport/org.apache.hadoop.hbase.master.cleaner/TestCleanerChore/precommit_checks___yetus_jdk11_hadoop3_checks___retriesIOExceptionInStatus/
@ndimiduk
Copy link
Member Author

ndimiduk commented Mar 1, 2024

Relates to test change introduced in #4730.

@ndimiduk ndimiduk requested a review from Apache9 March 1, 2024 07:04
@Apache-HBase

This comment was marked as outdated.

@Apache-HBase

This comment was marked as outdated.

@Apache-HBase

This comment was marked as outdated.

@Apache-HBase

This comment was marked as outdated.

@Apache-HBase
Copy link

🎊 +1 overall

Vote Subsystem Runtime Comment
+0 🆗 reexec 0m 28s Docker mode activated.
_ Prechecks _
+1 💚 dupname 0m 0s No case conflicting files found.
+1 💚 hbaseanti 0m 0s Patch does not have any anti-patterns.
+1 💚 @author 0m 0s The patch does not contain any @author tags.
_ master Compile Tests _
+1 💚 mvninstall 2m 55s master passed
+1 💚 compile 2m 33s master passed
+1 💚 checkstyle 0m 35s master passed
+1 💚 spotless 0m 42s branch has no errors when running spotless:check.
+1 💚 spotbugs 1m 29s master passed
_ Patch Compile Tests _
+1 💚 mvninstall 2m 55s the patch passed
+1 💚 compile 2m 33s the patch passed
+1 💚 javac 2m 33s the patch passed
+1 💚 checkstyle 0m 35s the patch passed
+1 💚 whitespace 0m 0s The patch has no whitespace issues.
+1 💚 hadoopcheck 5m 28s Patch does not cause any errors with Hadoop 3.3.6.
+1 💚 spotless 0m 43s patch has no errors when running spotless:check.
+1 💚 spotbugs 1m 44s the patch passed
_ Other Tests _
+1 💚 asflicense 0m 9s The patch does not generate ASF License warnings.
29m 46s
Subsystem Report/Notes
Docker ClientAPI=1.43 ServerAPI=1.43 base: https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-5735/2/artifact/yetus-general-check/output/Dockerfile
GITHUB PR #5735
Optional Tests dupname asflicense javac spotbugs hadoopcheck hbaseanti spotless checkstyle compile
uname Linux d3170c72a1b5 5.4.0-1103-aws #111~18.04.1-Ubuntu SMP Tue May 23 20:04:10 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux
Build tool maven
Personality dev-support/hbase-personality.sh
git revision master / ede4ccd
Default Java Eclipse Adoptium-11.0.17+8
Max. process+thread count 79 (vs. ulimit of 30000)
modules C: hbase-server U: hbase-server
Console output https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-5735/2/console
versions git=2.34.1 maven=3.8.6 spotbugs=4.7.3
Powered by Apache Yetus 0.12.0 https://yetus.apache.org

This message was automatically generated.

@Apache-HBase
Copy link

💔 -1 overall

Vote Subsystem Runtime Comment
+0 🆗 reexec 0m 37s Docker mode activated.
-0 ⚠️ yetus 0m 3s Unprocessed flag(s): --brief-report-file --spotbugs-strict-precheck --whitespace-eol-ignore-list --whitespace-tabs-ignore-list --quick-hadoopcheck
_ Prechecks _
_ master Compile Tests _
+1 💚 mvninstall 3m 4s master passed
+1 💚 compile 0m 55s master passed
+1 💚 shadedjars 5m 13s branch has no errors when building our shaded downstream artifacts.
+1 💚 javadoc 0m 30s master passed
_ Patch Compile Tests _
+1 💚 mvninstall 2m 51s the patch passed
+1 💚 compile 0m 55s the patch passed
+1 💚 javac 0m 55s the patch passed
+1 💚 shadedjars 5m 12s patch has no errors when building our shaded downstream artifacts.
+1 💚 javadoc 0m 29s the patch passed
_ Other Tests _
-1 ❌ unit 31m 38s hbase-server in the patch failed.
53m 15s
Subsystem Report/Notes
Docker ClientAPI=1.44 ServerAPI=1.44 base: https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-5735/2/artifact/yetus-jdk17-hadoop3-check/output/Dockerfile
GITHUB PR #5735
Optional Tests javac javadoc unit shadedjars compile
uname Linux ac8a42036405 5.4.0-163-generic #180-Ubuntu SMP Tue Sep 5 13:21:23 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux
Build tool maven
Personality dev-support/hbase-personality.sh
git revision master / ede4ccd
Default Java Eclipse Adoptium-17.0.10+7
unit https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-5735/2/artifact/yetus-jdk17-hadoop3-check/output/patch-unit-hbase-server.txt
Test Results https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-5735/2/testReport/
Max. process+thread count 1740 (vs. ulimit of 30000)
modules C: hbase-server U: hbase-server
Console output https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-5735/2/console
versions git=2.34.1 maven=3.8.6
Powered by Apache Yetus 0.12.0 https://yetus.apache.org

This message was automatically generated.

@Apache-HBase
Copy link

🎊 +1 overall

Vote Subsystem Runtime Comment
+0 🆗 reexec 0m 26s Docker mode activated.
-0 ⚠️ yetus 0m 2s Unprocessed flag(s): --brief-report-file --spotbugs-strict-precheck --whitespace-eol-ignore-list --whitespace-tabs-ignore-list --quick-hadoopcheck
_ Prechecks _
_ master Compile Tests _
+1 💚 mvninstall 2m 43s master passed
+1 💚 compile 0m 37s master passed
+1 💚 shadedjars 5m 29s branch has no errors when building our shaded downstream artifacts.
+1 💚 javadoc 0m 23s master passed
_ Patch Compile Tests _
+1 💚 mvninstall 2m 26s the patch passed
+1 💚 compile 0m 39s the patch passed
+1 💚 javac 0m 39s the patch passed
+1 💚 shadedjars 5m 28s patch has no errors when building our shaded downstream artifacts.
+1 💚 javadoc 0m 21s the patch passed
_ Other Tests _
+1 💚 unit 224m 47s hbase-server in the patch passed.
247m 32s
Subsystem Report/Notes
Docker ClientAPI=1.43 ServerAPI=1.43 base: https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-5735/2/artifact/yetus-jdk8-hadoop3-check/output/Dockerfile
GITHUB PR #5735
Optional Tests javac javadoc unit shadedjars compile
uname Linux b57bb5079e58 5.4.0-1103-aws #111~18.04.1-Ubuntu SMP Tue May 23 20:04:10 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux
Build tool maven
Personality dev-support/hbase-personality.sh
git revision master / ede4ccd
Default Java Temurin-1.8.0_352-b08
Test Results https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-5735/2/testReport/
Max. process+thread count 5216 (vs. ulimit of 30000)
modules C: hbase-server U: hbase-server
Console output https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-5735/2/console
versions git=2.34.1 maven=3.8.6
Powered by Apache Yetus 0.12.0 https://yetus.apache.org

This message was automatically generated.

@Apache-HBase
Copy link

🎊 +1 overall

Vote Subsystem Runtime Comment
+0 🆗 reexec 0m 13s Docker mode activated.
-0 ⚠️ yetus 0m 2s Unprocessed flag(s): --brief-report-file --spotbugs-strict-precheck --whitespace-eol-ignore-list --whitespace-tabs-ignore-list --quick-hadoopcheck
_ Prechecks _
_ master Compile Tests _
+1 💚 mvninstall 3m 6s master passed
+1 💚 compile 0m 49s master passed
+1 💚 shadedjars 5m 10s branch has no errors when building our shaded downstream artifacts.
+1 💚 javadoc 0m 27s master passed
_ Patch Compile Tests _
+1 💚 mvninstall 2m 48s the patch passed
+1 💚 compile 0m 49s the patch passed
+1 💚 javac 0m 49s the patch passed
+1 💚 shadedjars 5m 12s patch has no errors when building our shaded downstream artifacts.
+1 💚 javadoc 0m 26s the patch passed
_ Other Tests _
+1 💚 unit 224m 59s hbase-server in the patch passed.
248m 24s
Subsystem Report/Notes
Docker ClientAPI=1.44 ServerAPI=1.44 base: https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-5735/2/artifact/yetus-jdk11-hadoop3-check/output/Dockerfile
GITHUB PR #5735
Optional Tests javac javadoc unit shadedjars compile
uname Linux b62a25c5d62a 5.4.0-172-generic #190-Ubuntu SMP Fri Feb 2 23:24:22 UTC 2024 x86_64 x86_64 x86_64 GNU/Linux
Build tool maven
Personality dev-support/hbase-personality.sh
git revision master / ede4ccd
Default Java Eclipse Adoptium-11.0.17+8
Test Results https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-5735/2/testReport/
Max. process+thread count 5136 (vs. ulimit of 30000)
modules C: hbase-server U: hbase-server
Console output https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-5735/2/console
versions git=2.34.1 maven=3.8.6
Powered by Apache Yetus 0.12.0 https://yetus.apache.org

This message was automatically generated.

@Apache9
Copy link
Contributor

Apache9 commented Mar 2, 2024

The test is failing in jdk17 build?

@ndimiduk
Copy link
Member Author

ndimiduk commented Mar 3, 2024

I think that my fix is incomplete. Or there's something else disrupting the test harness. The test was terminated, interrupting the chore thread, while the waiter loop had only sat for 5 seconds.

2024-03-01T16:16:45,537 INFO  [Time-limited test {}] hbase.Waiter(181): Waiting up to [180,000] milli-secs(wait.for.ratio=[1])
2024-03-01T16:16:50,538 INFO  [cleaner.Chore.2 {}] cleaner.CleanerChore(265): Failed to traverse and delete the dir: /home/jenkins/jenkins-home/workspace/Base-PreCommit-GitHub-PR_PR-5735/yetus-jdk17-hadoop3-check/src/hbase-server/target/test-data/c58d0e04-c6be-93cf-6ca5-040d0c598291
java.lang.InterruptedException: null
...
2024-03-01T16:16:50,555 INFO  [Time-limited test {}] hbase.ResourceChecker(175): after: master.cleaner.TestCleanerChore#retriesIOExceptionInStatus Thread=19 (was 12)
...

@ndimiduk
Copy link
Member Author

ndimiduk commented Mar 3, 2024

In fact, jenkins doesn't tell us which of these failed runs is the output we have in the unit test summary.

[ERROR] Errors: 
[ERROR] org.apache.hadoop.hbase.master.cleaner.TestCleanerChore.null
[ERROR]   Run 1: TestCleanerChore.retriesIOExceptionInStatus:171 » TestTimedOut test timed out after 780 seconds
[ERROR]   Run 2: TestCleanerChore.retriesIOExceptionInStatus:171 » TestTimedOut test timed out after 780 seconds
[INFO] 
[ERROR] org.apache.hadoop.hbase.master.cleaner.TestCleanerChore.retriesIOExceptionInStatus
[ERROR]   Run 1: TestCleanerChore.retriesIOExceptionInStatus:220 » Execution java.io.IOException: whomp whomp.
[ERROR]   Run 2: TestCleanerChore.retriesIOExceptionInStatus:171 » Interrupted
[ERROR]   Run 3: TestCleanerChore.retriesIOExceptionInStatus:171 » Interrupted
[INFO] 
[INFO] 
[ERROR] Tests run: 1227, Failures: 0, Errors: 2, Skipped: 4

@ndimiduk
Copy link
Member Author

ndimiduk commented Mar 3, 2024

There is still a race.

[ERROR] org.apache.hadoop.hbase.master.cleaner.TestCleanerChore  Time elapsed: 779.999 s  <<< ERROR!
org.junit.runners.model.TestTimedOutException: test timed out after 780 seconds
	at [email protected]/jdk.internal.misc.Unsafe.park(Native Method)
	at [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:211)
	at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:715)
	at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1047)
	at [email protected]/java.util.concurrent.CountDownLatch.await(CountDownLatch.java:230)
	at app//org.apache.hadoop.hbase.master.cleaner.TestCleanerChore.retriesIOExceptionInStatus(TestCleanerChore.java:171)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants