[CI] EvilLoggerTests.testDeprecatedSettings failure

[jkakavas]

./gradlew :qa:evil-tests:test \
  -Dtests.seed=63408A35B5B91EC \
  -Dtests.class=org.elasticsearch.common.logging.EvilLoggerTests \
  -Dtests.method="testDeprecatedSettings" \
  -Dtests.security.manager=false \
  -Dtests.locale=ar-OM \
  -Dtests.timezone=Africa/Mbabane \
  -Dcompiler.java=11 \
  -Druntime.java=8

This failed in https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.x+multijob-darwin-compatibility/84/console but doesn't reproduce locally.

This looks suspiciously like #25680. It hasn't failed in the recent past, I'll be monitoring

[jasontedor]

Capturing the logging output for future investigation:

FAILURE 0.46s J4 | EvilLoggerTests.testDeprecatedSettings <<< FAILURES!
   > Throwable #1: java.lang.AssertionError: 
   > Expected: <1>
   >      but: was <0>
   > 	at __randomizedtesting.SeedInfo.seed([63408A35B5B91EC:664DF37970B48763]:0)
   > 	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
   > 	at org.elasticsearch.common.logging.EvilLoggerTests.testDeprecatedSettings(EvilLoggerTests.java:275)
   > 	at java.lang.Thread.run(Thread.java:748)
  1> [2018-11-28T12:26:10,763][INFO ][o.e.c.l.EvilLoggerTests  ] [testLocationInfoTest] before test
  2> NOTE: leaving temporary files on disk at: /private/var/lib/jenkins/workspace/elastic+elasticsearch+6.x+multijob-darwin-compatibility/qa/evil-tests/build/testrun/test/J4/temp/org.elasticsearch.common.logging.EvilLoggerTests_63408A35B5B91EC-001
  1> [2018-11-28T12:26:10,770][ERROR][test                     ] [testLocationInfoTest] This is an error message
  1> [2018-11-28T12:26:10,770][WARN ][test                     ] [testLocationInfoTest] This is a warning message
  2> NOTE: test params are: codec=Asserting(Lucene70): {}, docValues:{}, maxPointsInLeafNode=360, maxMBSortInHeap=6.7207523771409825, sim=RandomSimilarity(queryNorm=true): {}, locale=ar-OM, timezone=Africa/Mbabane
  1> [2018-11-28T12:26:10,770][INFO ][test                     ] [testLocationInfoTest] This is an info message
  1> [2018-11-28T12:26:10,771][DEBUG][test                     ] [testLocationInfoTest] This is a debug message
  1> [2018-11-28T12:26:10,771][TRACE][test                     ] [testLocationInfoTest] This is a trace message
  1> [2018-11-28T12:26:10,771][INFO ][org.elasticsearch.common.logging.EvilLoggerTests] [testLocationInfoTest] after test
  1> [2018-11-28T12:26:10,777][INFO ][o.e.c.l.EvilLoggerTests  ] [testConcurrentDeprecationLogger] before test
  2> NOTE: Mac OS X 10.13.3 x86_64/Oracle Corporation 1.8.0_192 (64-bit)/cpus=12,threads=1,free=252368448,total=477626368
  1> [2018-11-28T12:26:12,199][INFO ][org.elasticsearch.common.logging.EvilLoggerTests] [testConcurrentDeprecationLogger] after test
  2> NOTE: All tests run in this JVM: [TribeUnitTests, EvilSecurityTests, EvilLoggerTests]
  1> [2018-11-28T12:26:12,207][INFO ][o.e.c.l.EvilLoggerTests  ] [testNoNodeNameInPatternWarning] before test
  1> [2018-11-28T12:26:12,214][WARN ][org.elasticsearch.common.logging.LogConfigurator] [unknown] Some logging configurations have %marker but don't have %node_name. We will automatically add %node_name to the pattern to ease the migration for users who customize log4j2.properties but will stop this behavior in 7.0. You should manually replace `%node_name` with `[%node_name]%marker ` in these locations:
  1>   /private/var/lib/jenkins/workspace/elastic+elasticsearch+6.x+multijob-darwin-compatibility/qa/evil-tests/build/resources/test/org/elasticsearch/common/logging/no_node_name/log4j2.properties
  1> [2018-11-28T12:26:12,216][INFO ][org.elasticsearch.common.logging.EvilLoggerTests] [unknown] after test
  1> [2018-11-28T12:26:12,222][INFO ][o.e.c.l.EvilLoggerTests  ] [testPrefixLogger] before test
  1> [2018-11-28T12:26:12,256][INFO ][prefix_test              ] [testPrefixLogger]MAqilEqJYxClRItU test
  1> [2018-11-28T12:26:12,256][INFO ][prefix_test              ] [testPrefixLogger]MAqilEqJYxClRItU test
  1> [2018-11-28T12:26:12,258][INFO ][prefix_test              ] [testPrefixLogger]MAqilEqJYxClRItU test
  1> java.lang.Exception: exception
  1> 	at org.elasticsearch.common.logging.EvilLoggerTests.testPrefixLogger(EvilLoggerTests.java:306) [test/:6.6.0-SNAPSHOT]
  1> 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_192]
  1> 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_192]
  1> 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_192]
  1> 	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_192]
  1> 	at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1750) [randomizedtesting-runner-2.7.0.jar:?]
  1> 	at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:938) [randomizedtesting-runner-2.7.0.jar:?]
  1> 	at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:974) [randomizedtesting-runner-2.7.0.jar:?]
  1> 	at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:988) [randomizedtesting-runner-2.7.0.jar:?]
  1> 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) [randomizedtesting-runner-2.7.0.jar:?]
  1> 	at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49) [lucene-test-framework-7.6.0-snapshot-36ca27c36e.jar:7.6.0-snapshot-36ca27c36e 36ca27c36e90e33abbae8b6ce5359c7655c898c5 - nknize - 2018-11-09 16:17:17]
  1> 	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45) [lucene-test-framework-7.6.0-snapshot-36ca27c36e.jar:7.6.0-snapshot-36ca27c36e 36ca27c36e90e33abbae8b6ce5359c7655c898c5 - nknize - 2018-11-09 16:17:17]
  1> 	at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48) [lucene-test-framework-7.6.0-snapshot-36ca27c36e.jar:7.6.0-snapshot-36ca27c36e 36ca27c36e90e33abbae8b6ce5359c7655c898c5 - nknize - 2018-11-09 16:17:17]
  1> 	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64) [lucene-test-framework-7.6.0-snapshot-36ca27c36e.jar:7.6.0-snapshot-36ca27c36e 36ca27c36e90e33abbae8b6ce5359c7655c898c5 - nknize - 2018-11-09 16:17:17]
  1> 	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47) [lucene-test-framework-7.6.0-snapshot-36ca27c36e.jar:7.6.0-snapshot-36ca27c36e 36ca27c36e90e33abbae8b6ce5359c7655c898c5 - nknize - 2018-11-09 16:17:17]
  1> 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) [randomizedtesting-runner-2.7.0.jar:?]
  1> 	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368) [randomizedtesting-runner-2.7.0.jar:?]
  1> 	at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817) [randomizedtesting-runner-2.7.0.jar:?]
  1> 	at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468) [randomizedtesting-runner-2.7.0.jar:?]
  1> 	at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:947) [randomizedtesting-runner-2.7.0.jar:?]
  1> 	at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:832) [randomizedtesting-runner-2.7.0.jar:?]
  1> 	at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:883) [randomizedtesting-runner-2.7.0.jar:?]
  1> 	at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:894) [randomizedtesting-runner-2.7.0.jar:?]
  1> 	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45) [lucene-test-framework-7.6.0-snapshot-36ca27c36e.jar:7.6.0-snapshot-36ca27c36e 36ca27c36e90e33abbae8b6ce5359c7655c898c5 - nknize - 2018-11-09 16:17:17]
  1> 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) [randomizedtesting-runner-2.7.0.jar:?]
  1> 	at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41) [lucene-test-framework-7.6.0-snapshot-36ca27c36e.jar:7.6.0-snapshot-36ca27c36e 36ca27c36e90e33abbae8b6ce5359c7655c898c5 - nknize - 2018-11-09 16:17:17]
  1> 	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40) [randomizedtesting-runner-2.7.0.jar:?]
  1> 	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40) [randomizedtesting-runner-2.7.0.jar:?]
  1> 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) [randomizedtesting-runner-2.7.0.jar:?]
  1> 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) [randomizedtesting-runner-2.7.0.jar:?]
  1> 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) [randomizedtesting-runner-2.7.0.jar:?]
  1> 	at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53) [lucene-test-framework-7.6.0-snapshot-36ca27c36e.jar:7.6.0-snapshot-36ca27c36e 36ca27c36e90e33abbae8b6ce5359c7655c898c5 - nknize - 2018-11-09 16:17:17]
  1> 	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47) [lucene-test-framework-7.6.0-snapshot-36ca27c36e.jar:7.6.0-snapshot-36ca27c36e 36ca27c36e90e33abbae8b6ce5359c7655c898c5 - nknize - 2018-11-09 16:17:17]
  1> 	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64) [lucene-test-framework-7.6.0-snapshot-36ca27c36e.jar:7.6.0-snapshot-36ca27c36e 36ca27c36e90e33abbae8b6ce5359c7655c898c5 - nknize - 2018-11-09 16:17:17]
  1> 	at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54) [lucene-test-framework-7.6.0-snapshot-36ca27c36e.jar:7.6.0-snapshot-36ca27c36e 36ca27c36e90e33abbae8b6ce5359c7655c898c5 - nknize - 2018-11-09 16:17:17]
  1> 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) [randomizedtesting-runner-2.7.0.jar:?]
  1> 	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368) [randomizedtesting-runner-2.7.0.jar:?]
  1> 	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_192]
  1> [2018-11-28T12:26:12,263][INFO ][org.elasticsearch.common.logging.EvilLoggerTests] [testPrefixLogger] after test
Completed [17/17] on J4 in 6.68s, 10 tests, 1 failure <<< FAILURES!

[elasticmachine]

Pinging @elastic/es-core-infra

[andyb-elastic]

Another one, does not reproduce locally on my mac

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.x+multijob-darwin-compatibility/95/console

build-darwin-95.txt.zip

[andyb-elastic]

Muted on 6.x - 6cf5c84

Looks like this has failed about once a day on darwin on 6.x since 28 November

[gwbrown]

Failed again today: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.7+multijob-darwin-compatibility/46/console

consoleText.txt

[dimitris-athanasiou]

And another here: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.7+multijob-darwin-compatibility/54/console

These are enough to conclude the test is still problematic. I'll follow up to mute it.

[dimitris-athanasiou]

Re-muted in 6.7 in be10934