[TEST] testTracerLog failing #40586

ywelsch · 2019-03-28T12:47:36Z

I've seen failures for both org.elasticsearch.xpack.security.transport.nio.SimpleSecurityNioTransportTests and org.elasticsearch.transport.nio.SimpleMockNioTransportTests, see e.g.
https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+artifactory/63/console
and
https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+intake/2750/console

Output:


1> [2019-03-27T06:17:03,889][TRACE][o.e.t.T.tracer           ] [TS_A] [4][internal:testError] sent to [{TS_B}{OA0DAXBZRXWAablhhFBeqA}{5obbkIyrSaCge6HKcNOD8g}{127.0.0.1}{127.0.0.1:36985}] (timeout: [null])
  1> 2019-03-27 06:17:03,890 elasticsearch[TS_B][transport_worker][T#5] ERROR An exception occurred processing Appender mock java.util.ConcurrentModificationException
  1> 	at java.util.ArrayList$Itr.checkForComodification(ArrayList.java:909)
  1> 	at java.util.ArrayList$Itr.next(ArrayList.java:859)
  1> 	at org.elasticsearch.test.MockLogAppender.append(MockLogAppender.java:54)
  1> 	at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)
  1> 	at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)
  1> 	at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120)
  1> 	at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
  1> 	at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:464)
  1> 	at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:448)
  1> 	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:431)
  1> 	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
  1> 	at org.apache.logging.log4j.core.config.DefaultReliabilityStrategy.log(DefaultReliabilityStrategy.java:49)
  1> 	at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:146)
  1> 	at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2170)
  1> 	at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2125)
  1> 	at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2108)
  1> 	at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2025)
  1> 	at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1898)
  1> 	at org.apache.logging.log4j.spi.AbstractLogger.trace(AbstractLogger.java:2432)
  1> 	at org.elasticsearch.transport.TransportService.onResponseSent(TransportService.java:908)
  1> 	at org.elasticsearch.transport.OutboundHandler.lambda$sendResponse$2(OutboundHandler.java:106)
  1> 	at org.elasticsearch.action.ActionListener.lambda$wrap$0(ActionListener.java:84)
  1> 	at org.elasticsearch.action.ActionListener$1.onResponse(ActionListener.java:62)
  1> 	at org.elasticsearch.transport.OutboundHandler$SendContext.lambda$innerOnResponse$0(OutboundHandler.java:216)
  1> 	at org.elasticsearch.core.internal.io.IOUtils.close(IOUtils.java:103)
  1> 	at org.elasticsearch.core.internal.io.IOUtils.close(IOUtils.java:85)
  1> 	at org.elasticsearch.common.lease.Releasables.close(Releasables.java:36)
  1> 	at org.elasticsearch.common.lease.Releasables.close(Releasables.java:46)
  1> 	at org.elasticsearch.common.lease.Releasables.close(Releasables.java:51)
  1> 	at org.elasticsearch.transport.OutboundHandler$SendContext.closeAndCallback(OutboundHandler.java:230)
  1> 	at org.elasticsearch.transport.OutboundHandler$SendContext.innerOnResponse(OutboundHandler.java:216)
  1> 	at org.elasticsearch.transport.OutboundHandler$SendContext.innerOnResponse(OutboundHandler.java:178)
  1> 	at org.elasticsearch.action.NotifyOnceListener.onResponse(NotifyOnceListener.java:40)
  1> 	at org.elasticsearch.action.ActionListener.lambda$toBiConsumer$3(ActionListener.java:112)
  1> 	at org.elasticsearch.nio.NioSelector.lambda$executeListener$1(NioSelector.java:360)
  1> 	at org.elasticsearch.nio.EventHandler.handleTask(EventHandler.java:158)
  1> 	at org.elasticsearch.nio.NioSelector.handleTask(NioSelector.java:274)
  1> 	at org.elasticsearch.nio.NioSelector.executeListener(NioSelector.java:360)
  1> 	at org.elasticsearch.nio.SocketChannelContext.currentFlushOperationComplete(SocketChannelContext.java:162)
  1> 	at org.elasticsearch.xpack.security.transport.nio.SSLChannelContext.flushChannel(SSLChannelContext.java:91)
  1> 	at org.elasticsearch.nio.EventHandler.handleWrite(EventHandler.java:139)
  1> 	at org.elasticsearch.nio.NioSelector.handleWrite(NioSelector.java:389)
  1> 	at org.elasticsearch.nio.NioSelector.writeToChannel(NioSelector.java:345)
  1> 	at org.elasticsearch.nio.SocketChannelContext.sendMessage(SocketChannelContext.java:143)
  1> 	at org.elasticsearch.transport.nio.NioTcpChannel.sendMessage(NioTcpChannel.java:42)
  1> 	at org.elasticsearch.transport.OutboundHandler.internalSend(OutboundHandler.java:134)
  1> 	at org.elasticsearch.transport.OutboundHandler.sendMessage(OutboundHandler.java:127)
  1> 	at org.elasticsearch.transport.OutboundHandler.sendResponse(OutboundHandler.java:107)
  1> 	at org.elasticsearch.transport.TcpTransportChannel.sendResponse(TcpTransportChannel.java:64)
  1> 	at org.elasticsearch.transport.TaskTransportChannel.sendResponse(TaskTransportChannel.java:54)
  1> 	at org.elasticsearch.transport.AbstractSimpleTransportTestCase.lambda$testTracerLog$15(AbstractSimpleTransportTestCase.java:997)
  1> 	at org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:63)
  1> 	at org.elasticsearch.transport.InboundHandler$RequestHandler.doRun(InboundHandler.java:267)
  1> 	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
  1> 	at org.elasticsearch.common.util.concurrent.EsExecutors$DirectExecutorService.execute(EsExecutors.java:192)
  1> 	at org.elasticsearch.transport.InboundHandler.handleRequest(InboundHandler.java:188)
  1> 	at org.elasticsearch.transport.InboundHandler.messageReceived(InboundHandler.java:121)
  1> 	at org.elasticsearch.transport.InboundHandler.inboundMessage(InboundHandler.java:105)
  1> 	at org.elasticsearch.transport.TcpTransport.inboundMessage(TcpTransport.java:644)
  1> 	at org.elasticsearch.transport.TcpTransport.consumeNetworkReads(TcpTransport.java:668)
  1> 	at org.elasticsearch.transport.nio.TcpReadWriteHandler.consumeReads(TcpReadWriteHandler.java:42)
  1> 	at org.elasticsearch.nio.SocketChannelContext.handleReadBytes(SocketChannelContext.java:213)
  1> 	at org.elasticsearch.xpack.security.transport.nio.SSLChannelContext.read(SSLChannelContext.java:145)
  1> 	at org.elasticsearch.nio.EventHandler.handleRead(EventHandler.java:119)
  1> 	at org.elasticsearch.nio.NioSelector.handleRead(NioSelector.java:397)
  1> 	at org.elasticsearch.nio.NioSelector.processKey(NioSelector.java:246)
  1> 	at org.elasticsearch.nio.NioSelector.singleLoop(NioSelector.java:172)
  1> 	at org.elasticsearch.nio.NioSelector.runLoop(NioSelector.java:129)
  1> 	at java.lang.Thread.run(Thread.java:748)
  1> [2019-03-27T06:17:03,888][TRACE][o.e.t.T.tracer           ] [TS_B] [3][internal:test] sent response
  1> [2019-03-27T06:17:03,895][TRACE][o.e.t.T.tracer           ] [TS_B] [4][internal:testError] received request
  1> [2019-03-27T06:17:03,896][TRACE][o.e.t.T.tracer           ] [TS_A] [4][internal:testError] received response from [{TS_B}{OA0DAXBZRXWAablhhFBeqA}{5obbkIyrSaCge6HKcNOD8g}{127.0.0.1}{127.0.0.1:36985}]
  1> [2019-03-27T06:17:03,897][TRACE][o.e.t.T.tracer           ] [TS_B] [4][internal:testError] sent error response
  1> java.lang.RuntimeException: 
  1> 	at org.elasticsearch.transport.AbstractSimpleTransportTestCase.lambda$testTracerLog$16(AbstractSimpleTransportTestCase.java:1002) ~[framework-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:63) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.transport.InboundHandler$RequestHandler.doRun(InboundHandler.java:267) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.common.util.concurrent.EsExecutors$DirectExecutorService.execute(EsExecutors.java:192) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.transport.InboundHandler.handleRequest(InboundHandler.java:188) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.transport.InboundHandler.messageReceived(InboundHandler.java:121) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.transport.InboundHandler.inboundMessage(InboundHandler.java:105) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.transport.TcpTransport.inboundMessage(TcpTransport.java:644) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.transport.TcpTransport.consumeNetworkReads(TcpTransport.java:668) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.transport.nio.TcpReadWriteHandler.consumeReads(TcpReadWriteHandler.java:42) ~[transport-nio-client-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.nio.SocketChannelContext.handleReadBytes(SocketChannelContext.java:213) ~[elasticsearch-nio-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.xpack.security.transport.nio.SSLChannelContext.read(SSLChannelContext.java:145) ~[main/:?]
  1> 	at org.elasticsearch.nio.EventHandler.handleRead(EventHandler.java:119) ~[elasticsearch-nio-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.nio.NioSelector.handleRead(NioSelector.java:397) ~[elasticsearch-nio-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.nio.NioSelector.processKey(NioSelector.java:246) ~[elasticsearch-nio-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.nio.NioSelector.singleLoop(NioSelector.java:172) ~[elasticsearch-nio-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.nio.NioSelector.runLoop(NioSelector.java:129) ~[elasticsearch-nio-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
  1> 	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_202]

java.lang.AssertionError: 
Expected: an empty collection
     but: <[An exception occurred processing Appender mock]>
	at __randomizedtesting.SeedInfo.seed([E1E5A1FAE4A24475:E2665C44E5AAEAA0]:0)
	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
	at org.junit.Assert.assertThat(Assert.java:956)
	at org.junit.Assert.assertThat(Assert.java:923)
	at org.elasticsearch.test.ESTestCase.checkStaticState(ESTestCase.java:484)
	at org.elasticsearch.test.ESTestCase.after(ESTestCase.java:360)
	at sun.reflect.GeneratedMethodAccessor7.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	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.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49)
	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
	at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
	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.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
	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 com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
	at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
	at java.lang.Thread.run(Thread.java:748)

The text was updated successfully, but these errors were encountered:

elasticmachine · 2019-03-28T12:47:37Z

Pinging @elastic/es-distributed

ywelsch · 2019-03-28T13:05:36Z

Muted on the various branches (see linked commits)

Relates to #40586

ywelsch · 2019-04-03T08:59:50Z

Can you have a look @andrershov?

andrershov · 2019-04-04T12:25:38Z

@ywelsch I'm looking at it and not sure what is going on here.
Unfortunately, none of the build logs is available.
I can not reproduce it locally.
Normally log looks like this:

[TS_A] [4][internal:testError] sent to [{TS_B}{TAaYTmWwTl-D7jENSU2Avw}{63ElMLsuStOTW1YzK9aa4g}{127.0.0.1}{127.0.0.1:51973}] (timeout: [null])
[TS_B] [4][internal:testError] received request
[TS_A] [4][internal:testError] received response from [{TS_B}{TAaYTmWwTl-D7jENSU2Avw}{63ElMLsuStOTW1YzK9aa4g}{127.0.0.1}{127.0.0.1:51973}]
[TS_B] [4][internal:testError] sent error response

But here we see just the following line before the exception:

[TS_A] [4][internal:testError] sent to [{TS_B}{OA0DAXBZRXWAablhhFBeqA}{5obbkIyrSaCge6HKcNOD8g}{127.0.0.1}{127.0.0.1:36985}] (timeout: [null])

Stacktrace is telling us that exception is happening when TS_B tries to log the following message (TransportService:908):

sent response

The unusual thing here is that we expect it to log sent error response and not sent response.
I don't know why it's happening. @tbrooks8 what do you think?

Tim-Brooks · 2019-04-04T15:40:43Z

I think it is just due to the concurrency. Expectations are being added throughout the test. But the network threads are asynchronous. So it is possible there is an attempt to add a new assertions while the network threads attempt to log.

We might need to create the MockAppenders, add assertion and then add it as a logging appender. Probably a new appender for each different scenario.

romseygeek · 2019-05-07T12:19:42Z

This just failed for SimpleSecurityNetty4ServerTransportTests.testTracerLog:

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+intake/3437/

A slightly different error message this time:

Expected: an empty collection
     but: <[Attempted to append to non-started appender mock]>
	at __randomizedtesting.SeedInfo.seed([BC7BFAA89193A0EF:BFF80716909B0E3A]:0)
	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:18)
	at org.junit.Assert.assertThat(Assert.java:956)
	at org.junit.Assert.assertThat(Assert.java:923)
	at org.elasticsearch.test.ESTestCase.checkStaticState(ESTestCase.java:484)
	at org.elasticsearch.test.ESTestCase.after(ESTestCase.java:360)

Reproduce line is:

./gradlew :x-pack:plugin:security:test --tests "org.elasticsearch.xpack.security.transport.netty4.SimpleSecurityNetty4ServerTransportTests.testTracerLog" -Dtests.seed=BC7BFAA89193A0EF -Dtests.security.manager=true -Dtests.locale=ta-MY -Dtests.timezone=Mexico/BajaSur -Dcompiler.java=12 -Druntime.java=11

matriv · 2019-05-07T12:35:21Z

Adding more of the log outcome in case it helps: https://gist.github.com/matriv/ab0a86f3251a291fcd9e7283964e6f73

jasontedor · 2019-05-07T12:44:37Z

In general can we have new issues for new failures? It makes it easier to track what is new and old, and gives a clean slate for new failures. I opened #41890.

ywelsch added :Distributed Coordination/Network Http and internode communication implementations >test-failure Triaged test failures from CI labels Mar 28, 2019

ywelsch added a commit that referenced this issue Mar 28, 2019

Mute testTracerLog

fea91c6

Relates to #40586

ywelsch added a commit that referenced this issue Mar 28, 2019

Mute testTracerLog

a423924

Relates to #40586

ywelsch assigned andrershov Apr 3, 2019

Tim-Brooks mentioned this issue Apr 22, 2019

org.elasticsearch.transport.netty4.ESLoggingHandlerIT.testLoggingHandler Failure #41415

Closed

jasontedor mentioned this issue Apr 22, 2019

Avoid concurrent modification in mock log appender #41424

Merged

jasontedor self-assigned this Apr 22, 2019

jasontedor closed this as completed in #41424 Apr 23, 2019

romseygeek reopened this May 7, 2019

jasontedor mentioned this issue May 7, 2019

SimpleSecurityNetty4ServerTransportTests.testTracerLog is failing with appends to non-started mock appender #41890

Closed

jasontedor closed this as completed May 7, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[TEST] testTracerLog failing #40586

[TEST] testTracerLog failing #40586

ywelsch commented Mar 28, 2019 •

edited

Loading

elasticmachine commented Mar 28, 2019

ywelsch commented Mar 28, 2019

ywelsch commented Apr 3, 2019

andrershov commented Apr 4, 2019

Tim-Brooks commented Apr 4, 2019

romseygeek commented May 7, 2019

matriv commented May 7, 2019

jasontedor commented May 7, 2019

[TEST] testTracerLog failing #40586

[TEST] testTracerLog failing #40586

Comments

ywelsch commented Mar 28, 2019 • edited Loading

elasticmachine commented Mar 28, 2019

ywelsch commented Mar 28, 2019

ywelsch commented Apr 3, 2019

andrershov commented Apr 4, 2019

Tim-Brooks commented Apr 4, 2019

romseygeek commented May 7, 2019

matriv commented May 7, 2019

jasontedor commented May 7, 2019

ywelsch commented Mar 28, 2019 •

edited

Loading