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.

Sign up for GitHub

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

Jump to bottom

[BUG] MockLogAppender appended to after stopping #10799

Closed
andrross opened this issue Oct 20, 2023 · 3 comments · Fixed by #11866 or #12139
Closed

[BUG] MockLogAppender appended to after stopping #10799

andrross opened this issue Oct 20, 2023 · 3 comments · Fixed by #11866 or #12139
Assignees
@andrross
Labels
bug Something isn't working flaky-test Random test failure that succeeds on second run Other untriaged

Comments

@andrross
Copy link
Member

See test failure here: https://build.ci.opensearch.org/job/gradle-check/28539/consoleText

org.opensearch.transport.netty4.SimpleNetty4TransportTests > testTracerLog FAILED
    java.lang.AssertionError: 
    Expected: an empty collection
         but: <[Attempted to append to non-started appender mock]>
        at __randomizedtesting.SeedInfo.seed([C98A4BF58C821570:CA09B64B8D8ABBA5]:0)
        at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:18)
        at org.junit.Assert.assertThat(Assert.java:964)
        at org.junit.Assert.assertThat(Assert.java:930)
        at org.opensearch.test.OpenSearchTestCase.checkStaticState(OpenSearchTestCase.java:638)
        at org.opensearch.test.OpenSearchTestCase.after(OpenSearchTestCase.java:428)
        at java.****/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
        at java.****/java.lang.reflect.Method.invoke(Method.java:578)
        at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1750)
        at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:996)
        at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
        at org.junit.rules.RunRules.evaluate(RunRules.java:20)
        at org.apache.lucene.tests.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:48)
        at org.apache.lucene.tests.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:43)
        at org.apache.lucene.tests.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:45)
        at org.apache.lucene.tests.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:60)
        at org.apache.lucene.tests.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:44)
        at org.junit.rules.RunRules.evaluate(RunRules.java:20)
        at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
        at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
        at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817)
        at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468)
        at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:947)
        at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:832)
        at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:883)
        at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:894)
        at org.apache.lucene.tests.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:43)
        at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
        at org.apache.lucene.tests.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:38)
        at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
        at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
        at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
        at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
        at org.apache.lucene.tests.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
        at org.apache.lucene.tests.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:43)
        at org.apache.lucene.tests.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:44)
        at org.apache.lucene.tests.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:60)
        at org.apache.lucene.tests.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:47)
        at org.junit.rules.RunRules.evaluate(RunRules.java:20)
        at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
        at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
        at java.****/java.lang.Thread.run(Thread.java:1623)

I thought I fixed this problem in #1595. After glancing at the code I don't see where the problem is so this remains a mystery.
@andrross andrross added bug Something isn't working untriaged flaky-test Random test failure that succeeds on second run labels Oct 20, 2023
@andrross andrross mentioned this issue Oct 20, 2023
Merged
7 tasks
andrross added a commit to andrross/OpenSearch that referenced this issue Jan 12, 2024
@andrross
Fix log appender in InsecureSettingTests
47a6261 
The appender was being added to the logger before the appender was
started. This can lead to logger errors with concurrently running tests
because the logger is static state shared across the JVM. See opensearch-project#10799.

I've also added a removeAppender call that was missing from
LoggersTests, but that is mostly hygiene and would not lead to failures.

Signed-off-by: Andrew Ross <[email protected]>
@andrross andrross mentioned this issue Jan 12, 2024
Merged
8 tasks
andrross added a commit that referenced this issue Jan 12, 2024
@andrross
Fix log appender in InsecureSettingTests (#11866)
c8ae7f0 
The appender was being added to the logger before the appender was
started. This can lead to logger errors with concurrently running tests
because the logger is static state shared across the JVM. See #10799.

I've also added a removeAppender call that was missing from
LoggersTests, but that is mostly hygiene and would not lead to failures.

Signed-off-by: Andrew Ross <[email protected]>
opensearch-trigger-bot bot pushed a commit that referenced this issue Jan 12, 2024
@github-actions
Fix log appender in InsecureSettingTests (#11866)
f0e2ee5 
The appender was being added to the logger before the appender was
started. This can lead to logger errors with concurrently running tests
because the logger is static state shared across the JVM. See #10799.

I've also added a removeAppender call that was missing from
LoggersTests, but that is mostly hygiene and would not lead to failures.

Signed-off-by: Andrew Ross <[email protected]>
(cherry picked from commit c8ae7f0)
Signed-off-by: github-actions[bot] <github-actions[bot]@users.noreply.github.com>
kotwanikunal pushed a commit that referenced this issue Jan 13, 2024
@opensearch-trigger-bot @github-actions
Fix log appender in InsecureSettingTests (#11866) (#11879)
e93425d 
The appender was being added to the logger before the appender was
started. This can lead to logger errors with concurrently running tests
because the logger is static state shared across the JVM. See #10799.

I've also added a removeAppender call that was missing from
LoggersTests, but that is mostly hygiene and would not lead to failures.


(cherry picked from commit c8ae7f0)

Signed-off-by: Andrew Ross <[email protected]>
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>
@reta reta reopened this Jan 23, 2024
@reta
Copy link
Collaborator

reta commented Jan 23, 2024

Sadly came back here: #12000

@reta reta mentioned this issue Jan 23, 2024
Merged
8 tasks
andrross added a commit to andrross/OpenSearch that referenced this issue Jan 24, 2024
@andrross
Add calling class name to mock log appender
02820d4 
Issue opensearch-project#10799 is caused by a stopped or unstarted appender still being
present in the static logger state. I have not been able to find the
improper usage of the log appender that would cause this error. To help
debug, this commit adds the calling class name to the mock log appender.
Any future occurrence should result in an error message with the class
name that incorrected configured the logger.

I've also added an override to the `stop()` method to force that callers
use the close() method that properly cleans up the logger state as
opposed to stopping the appender directly.

Signed-off-by: Andrew Ross <[email protected]>
andrross added a commit to andrross/OpenSearch that referenced this issue Jan 24, 2024
@andrross
Add calling class name to mock log appender
7e3b6de 
Issue opensearch-project#10799 is caused by a stopped or unstarted appender still being
present in the static logger state. I have not been able to find the
improper usage of the log appender that would cause this error. To help
debug, this commit adds the calling class name to the mock log appender.
Any future occurrence should result in an error message with the class
name that incorrected configured the logger.

I've also added an override to the `stop()` method to force that callers
use the close() method that properly cleans up the logger state as
opposed to stopping the appender directly.

Signed-off-by: Andrew Ross <[email protected]>
@andrross andrross mentioned this issue Jan 24, 2024
Merged
8 tasks
andrross added a commit to andrross/OpenSearch that referenced this issue Jan 24, 2024
@andrross
Add calling class name to mock log appender
a11754c 
Issue opensearch-project#10799 is caused by a stopped or unstarted appender still being
present in the static logger state. I have not been able to find the
improper usage of the log appender that would cause this error. To help
debug, this commit adds the calling class name to the mock log appender.
Any future occurrence should result in an error message with the class
name that incorrected configured the logger.

I've also added an override to the `stop()` method to force that callers
use the close() method that properly cleans up the logger state as
opposed to stopping the appender directly.

Signed-off-by: Andrew Ross <[email protected]>
reta pushed a commit that referenced this issue Jan 25, 2024
@andrross
Add calling class name to mock log appender (#12013)
b4306b6 
Issue #10799 is caused by a stopped or unstarted appender still being
present in the static logger state. I have not been able to find the
improper usage of the log appender that would cause this error. To help
debug, this commit adds the calling class name to the mock log appender.
Any future occurrence should result in an error message with the class
name that incorrected configured the logger.

I've also added an override to the `stop()` method to force that callers
use the close() method that properly cleans up the logger state as
opposed to stopping the appender directly.

Signed-off-by: Andrew Ross <[email protected]>
opensearch-trigger-bot bot pushed a commit that referenced this issue Jan 25, 2024
@github-actions
Add calling class name to mock log appender (#12013)
0c9a598 
Issue #10799 is caused by a stopped or unstarted appender still being
present in the static logger state. I have not been able to find the
improper usage of the log appender that would cause this error. To help
debug, this commit adds the calling class name to the mock log appender.
Any future occurrence should result in an error message with the class
name that incorrected configured the logger.

I've also added an override to the `stop()` method to force that callers
use the close() method that properly cleans up the logger state as
opposed to stopping the appender directly.

Signed-off-by: Andrew Ross <[email protected]>
(cherry picked from commit b4306b6)
Signed-off-by: github-actions[bot] <github-actions[bot]@users.noreply.github.com>
andrross pushed a commit that referenced this issue Jan 25, 2024
@opensearch-trigger-bot @github-actions
Add calling class name to mock log appender (#12013) (#12017)
13a1038 
Issue #10799 is caused by a stopped or unstarted appender still being
present in the static logger state. I have not been able to find the
improper usage of the log appender that would cause this error. To help
debug, this commit adds the calling class name to the mock log appender.
Any future occurrence should result in an error message with the class
name that incorrected configured the logger.

I've also added an override to the `stop()` method to force that callers
use the close() method that properly cleans up the logger state as
opposed to stopping the appender directly.


(cherry picked from commit b4306b6)

Signed-off-by: Andrew Ross <[email protected]>
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>
@reta reta mentioned this issue Jan 29, 2024
Merged
@andrross
Copy link
Member Author

From this failure:

REPRODUCE WITH: ./gradlew ':plugins:transport-nio:test' --tests "org.opensearch.transport.nio.SimpleNioTransportTests.testTracerLog" -Dtests.seed=25BED9B96E9788F7 -Dtests.security.manager=true -Dtests.jvm.argline="-XX:TieredStopAtLevel=1 -XX:ReservedCodeCacheSize=64m" -Dtests.locale=nl-BE -Dtests.timezone=US/Mountain -Druntime.java=21

org.opensearch.transport.nio.SimpleNioTransportTests > testTracerLog FAILED
    java.lang.AssertionError: 
    Expected: an empty collection
         but: <[Attempted to append to non-started appender org.opensearch.transport.AbstractSimpleTransportTestCase-mock-log-appender]>

The new logging suggests AbstractSimpleTransportTestCase is the culprit...

@andrross
Copy link
Member Author

With the added logging, I believe the code is correct and not a simple start/add/remove/stop ordering issue of the logging appender. I think this could be a concurrency issue in org.apache.logging.log4j.core.config.LoggerConfig in that we remove the appender and then stop it, but an on-going logging event still has an older reference of AppenderControlArraySet (which has similar semantics to CopyOnWriteArraySet according to the documentation) that holds a reference to the now-stopped appender.

This was referenced Feb 1, 2024
Closed
Merged
peteralfonsi pushed a commit to peteralfonsi/OpenSearch that referenced this issue Mar 1, 2024
@andrross
Fix log appender in InsecureSettingTests (opensearch-project#11866)
03ac29f 
The appender was being added to the logger before the appender was
started. This can lead to logger errors with concurrently running tests
because the logger is static state shared across the JVM. See opensearch-project#10799.

I've also added a removeAppender call that was missing from
LoggersTests, but that is mostly hygiene and would not lead to failures.

Signed-off-by: Andrew Ross <[email protected]>
peteralfonsi pushed a commit to peteralfonsi/OpenSearch that referenced this issue Mar 1, 2024
@andrross
Add calling class name to mock log appender (opensearch-project#12013)
28a8329 
Issue opensearch-project#10799 is caused by a stopped or unstarted appender still being
present in the static logger state. I have not been able to find the
improper usage of the log appender that would cause this error. To help
debug, this commit adds the calling class name to the mock log appender.
Any future occurrence should result in an error message with the class
name that incorrected configured the logger.

I've also added an override to the `stop()` method to force that callers
use the close() method that properly cleans up the logger state as
opposed to stopping the appender directly.

Signed-off-by: Andrew Ross <[email protected]>
rayshrey pushed a commit to rayshrey/OpenSearch that referenced this issue Mar 18, 2024
@andrross @rayshrey
Fix log appender in InsecureSettingTests (opensearch-project#11866)
64f1a2c 
The appender was being added to the logger before the appender was
started. This can lead to logger errors with concurrently running tests
because the logger is static state shared across the JVM. See opensearch-project#10799.

I've also added a removeAppender call that was missing from
LoggersTests, but that is mostly hygiene and would not lead to failures.

Signed-off-by: Andrew Ross <[email protected]>
rayshrey pushed a commit to rayshrey/OpenSearch that referenced this issue Mar 18, 2024
@andrross @rayshrey
Add calling class name to mock log appender (opensearch-project#12013)
fa332f0 
Issue opensearch-project#10799 is caused by a stopped or unstarted appender still being
present in the static logger state. I have not been able to find the
improper usage of the log appender that would cause this error. To help
debug, this commit adds the calling class name to the mock log appender.
Any future occurrence should result in an error message with the class
name that incorrected configured the logger.

I've also added an override to the `stop()` method to force that callers
use the close() method that properly cleans up the logger state as
opposed to stopping the appender directly.

Signed-off-by: Andrew Ross <[email protected]>
shiv0408 pushed a commit to Gaurav614/OpenSearch that referenced this issue Apr 25, 2024
@andrross @shiv0408
Fix log appender in InsecureSettingTests (opensearch-project#11866)
bc90112 
The appender was being added to the logger before the appender was
started. This can lead to logger errors with concurrently running tests
because the logger is static state shared across the JVM. See opensearch-project#10799.

I've also added a removeAppender call that was missing from
LoggersTests, but that is mostly hygiene and would not lead to failures.

Signed-off-by: Andrew Ross <[email protected]>
Signed-off-by: Shivansh Arora <[email protected]>
shiv0408 pushed a commit to Gaurav614/OpenSearch that referenced this issue Apr 25, 2024
@andrross @shiv0408
Add calling class name to mock log appender (opensearch-project#12013)
bf3ec17 
Issue opensearch-project#10799 is caused by a stopped or unstarted appender still being
present in the static logger state. I have not been able to find the
improper usage of the log appender that would cause this error. To help
debug, this commit adds the calling class name to the mock log appender.
Any future occurrence should result in an error message with the class
name that incorrected configured the logger.

I've also added an override to the `stop()` method to force that callers
use the close() method that properly cleans up the logger state as
opposed to stopping the appender directly.

Signed-off-by: Andrew Ross <[email protected]>
Signed-off-by: Shivansh Arora <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@andrross andrross

Labels
bug Something isn't working flaky-test Random test failure that succeeds on second run Other untriaged
Projects
None yet
Milestone
No milestone
4 participants
@reta @andrross @anasalkouz @ticheng-aws