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

Fix race condition in testTracerLog #12139

Conversation

andrross
Copy link
Member

@andrross andrross commented Feb 1, 2024

The test currently blocks on receiving a response to the request for the "internal:testNotSeen" action. However, that response is sent from TransportService before the trace logger writes its log message. Since the test was not polling for this "sent response" log message to appear that meant it was possible for the test to remove/stop the mock log appender concurrently with the logging of that final message. The fix is to include this final log message as an expectation, so the test will poll until this message appears and the logger should be quiescent when the appender is removed and stopped.

Related Issues

Resolves #10799

Check List

  • New functionality includes testing.
    • All tests pass
  • New functionality has been documented.
    • New functionality has javadoc added
  • Failing checks are inspected and point to the corresponding known issue(s) (See: Troubleshooting Failing Builds)
  • Commits are signed per the DCO using --signoff
  • Commit changes are listed out in CHANGELOG.md file (See: Changelog)
  • Public documentation issue/PR created

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.

The test currently blocks on receiving a response to the request for the
"internal:testNotSeen" action. However, that response is sent from
TransportService before the trace logger [writes its log message][1].
Since the test was not polling for this "sent response" log message to
appear that meant it was possible for the test to remove/stop the mock
log appender concurrently with the logging of that final message. The
fix is to include this final log message as an expectation, so the test
will poll until this message appears and the logger should be quiescent
when the appender is removed and stopped.

[1]: https://github.com/opensearch-project/OpenSearch/blob/71f1fabe149fd0777edf44502ace4a8f0911feeb/server/src/main/java/org/opensearch/transport/TransportService.java#L1273

Signed-off-by: Andrew Ross <andrross@amazon.com>
@andrross
Copy link
Member Author

andrross commented Feb 1, 2024

@reta I think I may have my white whale here but please do tell me if this doesn't make sense :)

@andrross andrross added the backport 2.x Backport to 2.x branch label Feb 1, 2024
Copy link
Contributor

github-actions bot commented Feb 1, 2024

Compatibility status:

Checks if related components are compatible with change 3ed46df

Incompatible components

Incompatible components: [https://github.com/opensearch-project/cross-cluster-replication.git, https://github.com/opensearch-project/performance-analyzer.git, https://github.com/opensearch-project/performance-analyzer-rca.git]

Skipped components

Compatible components

Compatible components: [https://github.com/opensearch-project/security-analytics.git, https://github.com/opensearch-project/observability.git, https://github.com/opensearch-project/opensearch-oci-object-storage.git, https://github.com/opensearch-project/job-scheduler.git, https://github.com/opensearch-project/custom-codecs.git, https://github.com/opensearch-project/sql.git, https://github.com/opensearch-project/ml-commons.git, https://github.com/opensearch-project/notifications.git, https://github.com/opensearch-project/security.git, https://github.com/opensearch-project/asynchronous-search.git, https://github.com/opensearch-project/index-management.git, https://github.com/opensearch-project/neural-search.git, https://github.com/opensearch-project/reporting.git, https://github.com/opensearch-project/geospatial.git, https://github.com/opensearch-project/k-nn.git, https://github.com/opensearch-project/common-utils.git, https://github.com/opensearch-project/anomaly-detection.git, https://github.com/opensearch-project/alerting.git]

@andrross andrross changed the title Fix race condition in SimpleNioTransportTests.testTracerLog Fix race condition in testTracerLog Feb 2, 2024
Copy link
Contributor

github-actions bot commented Feb 2, 2024

❕ Gradle check result for 3ed46df: UNSTABLE

  • TEST FAILURES:
      1 org.opensearch.remotestore.RemoteIndexPrimaryRelocationIT.testPrimaryRelocationWhileIndexing

Please review all flaky tests that succeeded after retry and create an issue if one does not already exist to track the flaky failure.

Copy link

codecov bot commented Feb 2, 2024

Codecov Report

All modified and coverable lines are covered by tests ✅

Comparison is base (3c07461) 71.40% compared to head (3ed46df) 71.34%.
Report is 2 commits behind head on main.

Additional details and impacted files
@@             Coverage Diff              @@
##               main   #12139      +/-   ##
============================================
- Coverage     71.40%   71.34%   -0.06%     
+ Complexity    59505    59491      -14     
============================================
  Files          4925     4925              
  Lines        279540   279540              
  Branches      40646    40646              
============================================
- Hits         199594   199445     -149     
- Misses        63314    63490     +176     
+ Partials      16632    16605      -27     

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

@reta
Copy link
Collaborator

reta commented Feb 2, 2024

@reta I think I may have my white whale here but please do tell me if this doesn't make sense :)

I think it does make sense in scope of the test scaffolding we have, thanks a lot @andrross !

@andrross andrross merged commit f55b9e0 into opensearch-project:main Feb 2, 2024
86 of 111 checks passed
opensearch-trigger-bot bot pushed a commit that referenced this pull request Feb 2, 2024
The test currently blocks on receiving a response to the request for the
"internal:testNotSeen" action. However, that response is sent from
TransportService before the trace logger [writes its log message][1].
Since the test was not polling for this "sent response" log message to
appear that meant it was possible for the test to remove/stop the mock
log appender concurrently with the logging of that final message. The
fix is to include this final log message as an expectation, so the test
will poll until this message appears and the logger should be quiescent
when the appender is removed and stopped.

[1]: https://github.com/opensearch-project/OpenSearch/blob/71f1fabe149fd0777edf44502ace4a8f0911feeb/server/src/main/java/org/opensearch/transport/TransportService.java#L1273

Signed-off-by: Andrew Ross <andrross@amazon.com>
(cherry picked from commit f55b9e0)
Signed-off-by: github-actions[bot] <github-actions[bot]@users.noreply.github.com>
reta pushed a commit that referenced this pull request Feb 5, 2024
…12145)

The test currently blocks on receiving a response to the request for the
"internal:testNotSeen" action. However, that response is sent from
TransportService before the trace logger [writes its log message][1].
Since the test was not polling for this "sent response" log message to
appear that meant it was possible for the test to remove/stop the mock
log appender concurrently with the logging of that final message. The
fix is to include this final log message as an expectation, so the test
will poll until this message appears and the logger should be quiescent
when the appender is removed and stopped.

[1]: https://github.com/opensearch-project/OpenSearch/blob/71f1fabe149fd0777edf44502ace4a8f0911feeb/server/src/main/java/org/opensearch/transport/TransportService.java#L1273


(cherry picked from commit f55b9e0)

Signed-off-by: Andrew Ross <andrross@amazon.com>
Signed-off-by: github-actions[bot] <github-actions[bot]@users.noreply.github.com>
Co-authored-by: github-actions[bot] <github-actions[bot]@users.noreply.github.com>
@andrross andrross deleted the AbstractSimpleTransportTestCase-race branch February 8, 2024 19:46
peteralfonsi pushed a commit to peteralfonsi/OpenSearch that referenced this pull request Mar 1, 2024
…ch-project#12139)

The test currently blocks on receiving a response to the request for the
"internal:testNotSeen" action. However, that response is sent from
TransportService before the trace logger [writes its log message][1].
Since the test was not polling for this "sent response" log message to
appear that meant it was possible for the test to remove/stop the mock
log appender concurrently with the logging of that final message. The
fix is to include this final log message as an expectation, so the test
will poll until this message appears and the logger should be quiescent
when the appender is removed and stopped.

[1]: https://github.com/opensearch-project/OpenSearch/blob/71f1fabe149fd0777edf44502ace4a8f0911feeb/server/src/main/java/org/opensearch/transport/TransportService.java#L1273

Signed-off-by: Andrew Ross <andrross@amazon.com>
rayshrey pushed a commit to rayshrey/OpenSearch that referenced this pull request Mar 18, 2024
…ch-project#12139)

The test currently blocks on receiving a response to the request for the
"internal:testNotSeen" action. However, that response is sent from
TransportService before the trace logger [writes its log message][1].
Since the test was not polling for this "sent response" log message to
appear that meant it was possible for the test to remove/stop the mock
log appender concurrently with the logging of that final message. The
fix is to include this final log message as an expectation, so the test
will poll until this message appears and the logger should be quiescent
when the appender is removed and stopped.

[1]: https://github.com/opensearch-project/OpenSearch/blob/71f1fabe149fd0777edf44502ace4a8f0911feeb/server/src/main/java/org/opensearch/transport/TransportService.java#L1273

Signed-off-by: Andrew Ross <andrross@amazon.com>
shiv0408 pushed a commit to Gaurav614/OpenSearch that referenced this pull request Apr 25, 2024
…ch-project#12139)

The test currently blocks on receiving a response to the request for the
"internal:testNotSeen" action. However, that response is sent from
TransportService before the trace logger [writes its log message][1].
Since the test was not polling for this "sent response" log message to
appear that meant it was possible for the test to remove/stop the mock
log appender concurrently with the logging of that final message. The
fix is to include this final log message as an expectation, so the test
will poll until this message appears and the logger should be quiescent
when the appender is removed and stopped.

[1]: https://github.com/opensearch-project/OpenSearch/blob/71f1fabe149fd0777edf44502ace4a8f0911feeb/server/src/main/java/org/opensearch/transport/TransportService.java#L1273

Signed-off-by: Andrew Ross <andrross@amazon.com>
Signed-off-by: Shivansh Arora <hishiv@amazon.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
backport 2.x Backport to 2.x branch bug Something isn't working flaky-test Random test failure that succeeds on second run Other skip-changelog
Projects
None yet
Development

Successfully merging this pull request may close these issues.

[BUG] MockLogAppender appended to after stopping
2 participants