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

Use try-with-resources with MockLogAppender #1595

Merged
merged 1 commit into from
Dec 21, 2021

Conversation

andrross
Copy link
Member

@andrross andrross commented Nov 20, 2021

The context of this change is that some unit and integration tests make assertions about
the logging behavior of the code under test by adding a MockLogAppender to the
static (i.e. global) logging system to collect logging events. On top of this, the base
test class OpenSearchTestCase has an @After method that asserts that the logging
system itself did not emit any errors indicating a problem with the logging setup. A
problem occurs if a MockLogAppender is added to a logger before it is started or is
stopped before it is removed. A non-started appender can cause the logger to emit and
fail therefore fail a test. The specific error I've observed is "Attempted to append to non-started
appender mock". When running a single test in isolation, there will not be a problem
regardless of the start/add/remove/stop order of the appender, because there is nothing
else going on inside the JVM to trigger a logging event. However, if tests are being run
concurrently inside a JVM, then if a non-started appender is added to a logger then there
exists a race condition that if a particular logging event were to fire then it could cause an
error before the mock appender was started. These errors are quite difficult to chase down
as the tests that interfere with each other are otherwise entirely unrelated. The change here
is to handle the lifecycle management of MockLogAppender via try-with-resources so it
is handled correctly be default and it is not so easy to introduce a potential race condition.

Concretely, this is what the code looked like before:

final MockLogAppender appender = new MockLogAppender();
appender.start();
Loggers.addAppender(logger, appender); // <- Must be done after start()

.. test logic ...

Loggers.removeAppender(logger, appender); // <- Must be done before stop()
appender.stop();

and this is what it looks like after the change in this PR:

try (MockLogAppender appender = MockLogAppender.createForLoggers(logger)) {
... test logic ...
}

The try-with-resources construct does the start/add/remove/stop logic in the correct order
and the developer doesn't need to think about it.


I previously added a helper that started a MockLogAppender to ensure it
was never added to a Logger before it was started. I subsequently found
the opposite case in RolloverIT.java where the appender was stopped
before it was closed, therefore creating a race where a concurrently
running test in the same JVM could cause a logging failure. This seems
like a really easy mistake to make when writing a test or introduce when
refactoring a test. I've made a change to use try-with-resources to
ensure that proper setup and teardown is done. This should make it much
harder to introduce this particular test bug in the future.
Unfortunately, it did involve touching a lot of files. The changes here
are purely structural to leverage try-with-resources; no testing logic
has been changed.

Description

Fixes a potential race conditions in tests that lead to intermittent failures

Issues Resolved

None

Check List

  • New functionality includes testing.
    • All tests pass
  • New functionality has been documented.
    • New functionality has javadoc added
  • Commits are signed per the DCO using --signoff

By submitting this pull request, I confirm that my contribution is made under the terms of the Apache 2.0 license.
For more information on following Developer Certificate of Origin and signing off your commits, please check here.

@andrross andrross requested a review from a team as a code owner November 20, 2021 00:33
@opensearch-ci-bot
Copy link
Collaborator

Can one of the admins verify this patch?

@opensearch-ci-bot
Copy link
Collaborator

✅   Gradle Wrapper Validation success c753dca7220e943d21550ebe73e779baa8d114fc

@opensearch-ci-bot
Copy link
Collaborator

✅   Gradle Precommit success c753dca7220e943d21550ebe73e779baa8d114fc

@opensearch-ci-bot
Copy link
Collaborator

❌   Gradle Check failure c753dca7220e943d21550ebe73e779baa8d114fc
Log 1156

Reports 1156

@andrross
Copy link
Member Author

start gradle check

@andrross
Copy link
Member Author

Test failed with a pretty generic timeout and cannot be reproduced:

REPRODUCE WITH: ./gradlew ':server:internalClusterTest' --tests "org.opensearch.search.geo.GeoShapeIntegrationIT.testOrientationPersistence" -Dtests.seed=3547E4E7785AD6D0 -Dtests.security.manager=true -Dtests.jvm.argline="-XX:TieredStopAtLevel=1 -XX:ReservedCodeCacheSize=64m" -Dtests.locale=en-ZA -Dtests.timezone=SystemV/CST6CDT -Druntime.java=17

org.opensearch.search.geo.GeoShapeIntegrationIT > testOrientationPersistence FAILED
    java.lang.AssertionError: timed out waiting for green state
        at __randomizedtesting.SeedInfo.seed([3547E4E7785AD6D0:6498346FC69C3338]:0)
        at org.junit.Assert.fail(Assert.java:88)
        at org.opensearch.test.OpenSearchIntegTestCase.ensureColor(OpenSearchIntegTestCase.java:1019)
        at org.opensearch.test.OpenSearchIntegTestCase.ensureGreen(OpenSearchIntegTestCase.java:958)
        at org.opensearch.test.OpenSearchIntegTestCase.ensureGreen(OpenSearchIntegTestCase.java:947)
        at org.opensearch.search.geo.GeoShapeIntegrationIT.testOrientationPersistence(GeoShapeIntegrationIT.java:111)

@opensearch-ci-bot
Copy link
Collaborator

✅   Gradle Check success c753dca7220e943d21550ebe73e779baa8d114fc
Log 1175

Reports 1175

@opensearch-ci-bot
Copy link
Collaborator

❌   Gradle Check failure 85b8adac39cdfac639db4e7fe21bd6b20398e23e
Log 1447

Reports 1447

@andrross
Copy link
Member Author

start gradle check

@opensearch-ci-bot
Copy link
Collaborator

✅   Gradle Check success 85b8adac39cdfac639db4e7fe21bd6b20398e23e
Log 1448

Reports 1448

@opensearch-ci-bot
Copy link
Collaborator

❌   Gradle Check failure bae1339936c4137ab02aa4a1c8390154092938ed
Log 1609

Reports 1609

I previously added a helper that started a MockLogAppender to ensure it
was never added to a Logger before it was started. I subsequently found
the opposite case in RolloverIT.java where the appender was stopped
before it was closed, therefore creating a race where a concurrently
running test in the same JVM could cause a logging failure. This seems
like a really easy mistake to make when writing a test or introduce when
refactoring a test. I've made a change to use try-with-resources to
ensure that proper setup and teardown is done. This should make it much
harder to introduce this particular test bug in the future.
Unfortunately, it did involve touching a lot of files. The changes here
are purely structural to leverage try-with-resources; no testing logic
has been changed.

Signed-off-by: Andrew Ross <andrross@amazon.com>
@opensearch-ci-bot
Copy link
Collaborator

✅   Gradle Check success 61cc582
Log 1610

Reports 1610

@andrross andrross merged commit 96d5596 into opensearch-project:main Dec 21, 2021
@andrross andrross added backport 1.x pending backport Identifies an issue or PR that still needs to be backported and removed backport 1.x labels Dec 21, 2021
andrross added a commit to andrross/OpenSearch that referenced this pull request Dec 21, 2021
I previously added a helper that started a MockLogAppender to ensure it
was never added to a Logger before it was started. I subsequently found
the opposite case in RolloverIT.java where the appender was stopped
before it was closed, therefore creating a race where a concurrently
running test in the same JVM could cause a logging failure. This seems
like a really easy mistake to make when writing a test or introduce when
refactoring a test. I've made a change to use try-with-resources to
ensure that proper setup and teardown is done. This should make it much
harder to introduce this particular test bug in the future.
Unfortunately, it did involve touching a lot of files. The changes here
are purely structural to leverage try-with-resources; no testing logic
has been changed.

Signed-off-by: Andrew Ross <andrross@amazon.com>
adnapibar pushed a commit that referenced this pull request Dec 22, 2021
I previously added a helper that started a MockLogAppender to ensure it
was never added to a Logger before it was started. I subsequently found
the opposite case in RolloverIT.java where the appender was stopped
before it was closed, therefore creating a race where a concurrently
running test in the same JVM could cause a logging failure. This seems
like a really easy mistake to make when writing a test or introduce when
refactoring a test. I've made a change to use try-with-resources to
ensure that proper setup and teardown is done. This should make it much
harder to introduce this particular test bug in the future.
Unfortunately, it did involve touching a lot of files. The changes here
are purely structural to leverage try-with-resources; no testing logic
has been changed.

Signed-off-by: Andrew Ross <andrross@amazon.com>
@andrross andrross deleted the mock-appender-twr branch December 22, 2021 16:28
@andrross andrross removed the pending backport Identifies an issue or PR that still needs to be backported label Jan 26, 2022
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.

3 participants