[CI] org.elasticsearch.backwards.MixedClusterClientYamlTestSuiteIT.test fails on Test Index and Search locale dependent mappings / dates

[dliappis]

Since #48703 we are seeing failures like: https://gradle-enterprise.elastic.co/s/m64s5k5k3pbn6/tests/qiq773hxdcg7e-2pri752okzdby

Failure:

expected [2xx] status code but api [indices.create] returned [500 Internal Server Error] [{"error":{"root_cause":[{"type":"remote_transport_exception","reason":"[v6.8.3-2][127.0.0.1:36768][indices:admin/create]","stack_trace":"[[v6.8.3-2][127.0.0.1:36768][indices:admin/create]]; nested: RemoteTransportException[[v6.8.3-2][127.0.0.1:36768][indices:admin/create]]; nested: IllegalStateException[DocumentMapper serialization result is different from source. \n--> Source [{\"_doc\":{\"properties\":{\"date_field\":{\"type\":\"date\",\"format\":\"88E, d MMM uuuu HH:mm:ss Z\",\"locale\":\"de\"}}}}]\n--> Result [{\"_doc\":{\"properties\":{\"date_field\":{\"type\":\"date\",\"format\":\"888E, d MMM uuuu HH:mm:ss Z\",\"locale\":\"de\"}}}}]];\n\tat org.elasticsearch.ElasticsearchException.guessRootCauses(ElasticsearchException.java:644)\n\tat org.elasticsearch.ElasticsearchException.generateFailureXContent(ElasticsearchException.java:572)\n\tat org.elasticsearch.rest.BytesRestResponse.build(BytesRestResponse.java:138)\n\tat org.elasticsearch.rest.BytesRestResponse.<init>(BytesRestResponse.java:96)\n\tat org.elasticsearch.rest.BytesRestResponse.<init>(BytesRestResponse.java:91)\n\tat org.elasticsearch.rest.action.RestActionListener.onFailure(RestActionListener.java:58)\n\tat org.elasticsearch.action.support.TransportAction$1.onFailure(TransportAction.java:79)\n\tat org.elasticsearch.action.support.master.TransportMasterNodeAction$AsyncSingleAction$1.handleException(TransportMasterNodeAction.java:190)\n\tat org.elasticsearch.transport.TransportService$ContextRestoreResponseHandler.handleException(TransportService.java:1119)\n\tat org.elasticsearch.transport.InboundHandler.lambda$handleException$2(InboundHandler.java:243)\n\tat org.elasticsearch.common.util.concurrent.EsExecutors$DirectExecutorService.execute(EsExecutors.java:225)\n\tat org.elasticsearch.transport.InboundHandler.handleException(InboundHandler.java:241)\n\tat org.elasticsearch.transport.InboundHandler.handlerResponseError(InboundHandler.java:233)\n\tat org.elasticsearch.transport.InboundHandler.messageReceived(InboundHandler.java:136)\n\tat org.elasticsearch.transport.InboundHandler.inboundMessage(InboundHandler.java:102)\n\tat org.elasticsearch.transport.TcpTransport.inboundMessage(TcpTransport.java:673)\n\tat org.elasticsearch.transport.netty4.Netty4MessageChannelHandler.channelRead(Netty4MessageChannelHandler.java:62)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)\n\tat io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352)\n\tat io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:326)\n\tat io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:300)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)\n\tat io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352)\n\tat io.netty.handler.logging.LoggingHandler.channelRead(LoggingHandler.java:241)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)\n\tat io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352)\n\tat io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1422)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)\n\tat io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:931)\n\tat io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163)\n\tat io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:700)\n\tat io.netty.channel.nio.NioEventLoop.processSelectedKeysPlain(NioEventLoop.java:600)\n\tat io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:554)\n\tat io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:514)\n\tat io.netty.util.concurrent.SingleThreadEventExecutor$6.run(SingleThreadEventExecutor.java:1050)\n\tat io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)\n\tat java.lang.Thread.run(Thread.java:748)\nCaused by: RemoteTransportException[[v6.8.3-2][127.0.0.1:36768][indices:admin/create]]; nested: IllegalStateException[DocumentMapper serialization result is different from source. \n--> Source [{\"_doc\":{\"properties\":{\"date_field\":{\"type\":\"date\",\"format\":\"88E, d MMM uuuu HH:mm:ss Z\",\"locale\":\"de\"}}}}]\n--> Result [{\"_doc\":{\"properties\":{\"date_field\":{\"type\":\"date\",\"format\":\"888E, d MMM uuuu HH:mm:ss Z\",\"locale\":\"de\"}}}}]];\nCaused by: java.lang.IllegalStateException: DocumentMapper serialization result is different from source. \n--> Source [{\"_doc\":{\"properties\":{\"date_field\":{\"type\":\"date\",\"format\":\"88E, d MMM uuuu HH:mm:ss Z\",\"locale\":\"de\"}}}}]\n--> Result [{\"_doc\":{\"properties\":{\"date_field\":{\"type\":\"date\",\"format\":\"888E, d MMM uuuu HH:mm:ss Z\",\"locale\":\"de\"}}}}]\n\tat org.elasticsearch.index.mapper.MapperService.assertSerialization(MapperService.java:617)\n\tat java.util.stream.MatchOps$1MatchSink.accept(MatchOps.java:90)\n\tat java.util.Spliterators$IteratorSpliterator.tryAdvance(Spliterators.java:1812)\n\tat java.util.stream.ReferencePipeline.forEachWithCancel(ReferencePipeline.java:126)\n\tat java.util.stream.AbstractPipeline.copyIntoWithCancel(AbstractPipeline.java:499)\n\tat java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:486)\n\tat java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:472)\n\tat java.util.stream.MatchOps$MatchOp.evaluateSequential(MatchOps.java:230)\n\tat java.util.stream.MatchOps$MatchOp.evaluateSequential(MatchOps.java:196)\n\tat java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)\n\tat java.util.stream.ReferencePipeline.allMatch(ReferencePipeline.java:454)\n\tat org.elasticsearch.index.mapper.MapperService.internalMerge(MapperService.java:592)\n\tat org.elasticsearch.index.mapper.MapperService.internalMerge(MapperService.java:403)\n\tat org.elasticsearch.index.mapper.MapperService.merge(MapperService.java:330)\n\tat org.elasticsearch.cluster.metadata.MetaDataCreateIndexService$IndexCreationTask.execute(MetaDataCreateIndexService.java:481)\n\tat org.elasticsearch.cluster.ClusterStateUpdateTask.execute(ClusterStateUpdateTask.java:47)\n\tat org.elasticsearch.cluster.service.MasterService.executeTasks(MasterService.java:643)\n\tat org.elasticsearch.cluster.service.MasterService.calculateTaskOutputs(MasterService.java:270)\n\tat org.elasticsearch.cluster.service.MasterService.runTasks(MasterService.java:200)\n\tat org.elasticsearch.cluster.service.MasterService$Batcher.run(MasterService.java:135)\n\tat org.elasticsearch.cluster.service.TaskBatcher.runIfNotProcessed(TaskBatcher.java:150)\n\tat org.elasticsearch.cluster.service.TaskBatcher$BatchedTask.run(TaskBatcher.java:188)\n\tat org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:681)\n\tat org.elasticsearch.common.util.concurrent.PrioritizedEsThreadPoolExecutor$TieBreakingPrioritizedRunnable.runAndClean(PrioritizedEsThreadPoolExecutor.java:252)\n\tat org.elasticsearch.common.util.concurrent.PrioritizedEsThreadPoolExecutor$TieBreakingPrioritizedRunnable.run(PrioritizedEsThreadPoolExecutor.java:215)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)\n\tat java.lang.Thread.run(Thread.java:748)\n"}],"type":"illegal_state_exception","reason":"DocumentMapper serialization result is different from source. \n--> Source [{\"_doc\":{\"properties\":{\"date_field\":{\"type\":\"date\",\"format\":\"88E, d MMM uuuu HH:mm:ss Z\",\"locale\":\"de\"}}}}]\n--> Result [{\"_doc\":{\"properties\":{\"date_field\":{\"type\":\"date\",\"format\":\"888E, d MMM uuuu HH:mm:ss Z\",\"locale\":\"de\"}}}}]","stack_trace":"java.lang.IllegalStateException: DocumentMapper serialization result is different from source. \n--> Source [{\"_doc\":{\"properties\":{\"date_field\":{\"type\":\"date\",\"format\":\"88E, d MMM uuuu HH:mm:ss Z\",\"locale\":\"de\"}}}}]\n--> Result [{\"_doc\":{\"properties\":{\"date_field\":{\"type\":\"date\",\"format\":\"888E, d MMM uuuu HH:mm:ss Z\",\"locale\":\"de\"}}}}]\n\tat org.elasticsearch.index.mapper.MapperService.assertSerialization(MapperService.java:617)\n\tat java.util.stream.MatchOps$1MatchSink.accept(MatchOps.java:90)\n\tat java.util.Spliterators$IteratorSpliterator.tryAdvance(Spliterators.java:1812)\n\tat java.util.stream.ReferencePipeline.forEachWithCancel(ReferencePipeline.java:126)\n\tat java.util.stream.AbstractPipeline.copyIntoWithCancel(AbstractPipeline.java:499)\n\tat java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:486)\n\tat java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:472)\n\tat java.util.stream.MatchOps$MatchOp.evaluateSequential(MatchOps.java:230)\n\tat java.util.stream.MatchOps$MatchOp.evaluateSequential(MatchOps.java:196)\n\tat java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)\n\tat java.util.stream.ReferencePipeline.allMatch(ReferencePipeline.java:454)\n\tat org.elasticsearch.index.mapper.MapperService.internalMerge(MapperService.java:592)\n\tat org.elasticsearch.index.mapper.MapperService.internalMerge(MapperService.java:403)\n\tat org.elasticsearch.index.mapper.MapperService.merge(MapperService.java:330)\n\tat org.elasticsearch.cluster.metadata.MetaDataCreateIndexService$IndexCreationTask.execute(MetaDataCreateIndexService.java:481)\n\tat org.elasticsearch.cluster.ClusterStateUpdateTask.execute(ClusterStateUpdateTask.java:47)\n\tat org.elasticsearch.cluster.service.MasterService.executeTasks(MasterService.java:643)\n\tat org.elasticsearch.cluster.service.MasterService.calculateTaskOutputs(MasterService.java:270)\n\tat org.elasticsearch.cluster.service.MasterService.runTasks(MasterService.java:200)\n\tat org.elasticsearch.cluster.service.MasterService$Batcher.run(MasterService.java:135)\n\tat org.elasticsearch.cluster.service.TaskBatcher.runIfNotProcessed(TaskBatcher.java:150)\n\tat org.elasticsearch.cluster.service.TaskBatcher$BatchedTask.run(TaskBatcher.java:188)\n\tat org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:681)\n\tat org.elasticsearch.common.util.concurrent.PrioritizedEsThreadPoolExecutor$TieBreakingPrioritizedRunnable.runAndClean(PrioritizedEsThreadPoolExecutor.java:252)\n\tat org.elasticsearch.common.util.concurrent.PrioritizedEsThreadPoolExecutor$TieBreakingPrioritizedRunnable.run(PrioritizedEsThreadPoolExecutor.java:215)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)\n\tat java.lang.Thread.run(Thread.java:748)\n"},"status":500}]Open stacktrace
[2019-11-29T08:03:40,087][INFO ][o.e.b.MixedClusterClientYamlTestSuiteIT] [test] [p0=search/180_locale_dependent_mapping/Test Index and Search locale dependent mappings / dates] before test
11 29, 2019 8:03:40 午前 org.elasticsearch.client.RestClient logResponse
警告: request [PUT http://[::1]:34553/test_index?include_type_name=false&error_trace=true] returned 1 warnings: [299 Elasticsearch-7.6.0-SNAPSHOT-90e9d61f2b75aa2962685175ea1bd92b8bb7c223 "[types removal] Using include_type_name in create index requests is deprecated. The parameter will be removed in the next major version."]
[2019-11-29T08:03:40,108][INFO ][o.e.b.MixedClusterClientYamlTestSuiteIT] [test] Stash dump on test failure [{
  "stash" : {
    "body" : {
      "error" : {
        "root_cause" : [
          {
            "type" : "remote_transport_exception",
            "reason" : "[v6.8.3-2][127.0.0.1:36768][indices:admin/create]",
            "stack_trace" : "[[v6.8.3-2][127.0.0.1:36768][indices:admin/create]]; nested: RemoteTransportException[[v6.8.3-2][127.0.0.1:36768][indices:admin/create]]; nested: IllegalStateException[DocumentMapper serialization result is different from source. 
--> Source [{\"_doc\":{\"properties\":{\"date_field\":{\"type\":\"date\",\"format\":\"88E, d MMM uuuu HH:mm:ss Z\",\"locale\":\"de\"}}}}]
--> Result [{\"_doc\":{\"properties\":{\"date_field\":{\"type\":\"date\",\"format\":\"888E, d MMM uuuu HH:mm:ss Z\",\"locale\":\"de\"}}}}]];

So we see the difference here is an additional 8 in the date_field format.

[elasticmachine]

Pinging @elastic/es-core-infra (:Core/Infra/Core)

[dliappis]

For now raised #49721 to mute the test.

[jaymode]

Fixed in #49724. @pgomulka note that GitHub will not automatically close an issue when a fix is merged to a branch other than master.

[droberts195]

#49724 skips the tests against versions older than 6.8.5, but I think more versions need to be skipped (or other fixes are required), as this same test caused a problem when 7.x was BWC tested against 7.1.0.

The failing build was https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+7.x+default-distro+bwc/BWC_VERSION=7.1.0,nodes=centos-7&&immutable/363/console

One of the nodes in the cluster died with an assertion failure while running search/180_locale_dependent_mapping/Test Index and Search locale dependent mappings / dates. The assertion failure stack trace is in v7.1.0-2/logs/v7.1.0.log in the server side logs:

[2019-12-06T03:05:48,389][DEBUG][o.e.c.c.PublicationTransportHandler] [v7.1.0-2] received diff cluster state version [7527] with uuid [HQ07hpYkQpuP-zai32NBew], diff size [396]
[2019-12-06T03:05:48,394][ERROR][o.e.b.ElasticsearchUncaughtExceptionHandler] [v7.1.0-2] fatal error in thread [elasticsearch[v7.1.0-2][clusterApplierService#updateTask][T#1]], exiting
java.lang.AssertionError: {_doc=org.elasticsearch.index.mapper.DocumentMapper@c732ec4}
    at org.elasticsearch.index.mapper.MapperService.assertMappingVersion(MapperService.java:264) ~[elasticsearch-7.1.0.jar:7.1.0]
    at org.elasticsearch.index.mapper.MapperService.updateMapping(MapperService.java:218) ~[elasticsearch-7.1.0.jar:7.1.0]
    at org.elasticsearch.index.IndexService.updateMapping(IndexService.java:551) ~[elasticsearch-7.1.0.jar:7.1.0]
    at org.elasticsearch.indices.cluster.IndicesClusterStateService.updateIndices(IndicesClusterStateService.java:533) ~[elasticsearch-7.1.0.jar:7.1.0]
    at org.elasticsearch.indices.cluster.IndicesClusterStateService.applyClusterState(IndicesClusterStateService.java:266) ~[elasticsearch-7.1.0.jar:7.1.0]
    at org.elasticsearch.cluster.service.ClusterApplierService.lambda$callClusterStateAppliers$5(ClusterApplierService.java:478) ~[elasticsearch-7.1.0.jar:7.1.0]
    at java.lang.Iterable.forEach(Iterable.java:75) ~[?:1.8.0_231]
    at org.elasticsearch.cluster.service.ClusterApplierService.callClusterStateAppliers(ClusterApplierService.java:476) ~[elasticsearch-7.1.0.jar:7.1.0]
    at org.elasticsearch.cluster.service.ClusterApplierService.applyChanges(ClusterApplierService.java:459) ~[elasticsearch-7.1.0.jar:7.1.0]
    at org.elasticsearch.cluster.service.ClusterApplierService.runTask(ClusterApplierService.java:413) ~[elasticsearch-7.1.0.jar:7.1.0]
    at org.elasticsearch.cluster.service.ClusterApplierService$UpdateTask.run(ClusterApplierService.java:164) ~[elasticsearch-7.1.0.jar:7.1.0]
    at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:681) ~[elasticsearch-7.1.0.jar:7.1.0]
    at org.elasticsearch.common.util.concurrent.PrioritizedEsThreadPoolExecutor$TieBreakingPrioritizedRunnable.runAndClean(PrioritizedEsThreadPoolExecutor.java:252) ~[elasticsearch-7.1.0.jar:7.1.0]
    at org.elasticsearch.common.util.concurrent.PrioritizedEsThreadPoolExecutor$TieBreakingPrioritizedRunnable.run(PrioritizedEsThreadPoolExecutor.java:215) ~[elasticsearch-7.1.0.jar:7.1.0]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_231]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_231]
    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_231]

The corresponding client side log (extracted from https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+7.x+default-distro+bwc/BWC_VERSION=7.1.0,nodes=centos-7&&immutable/363/consoleText) is:

  1> [2019-12-06T00:05:48,356][INFO ][o.e.b.MixedClusterClientYamlTestSuiteIT] [test] [p0=search/180_locale_dependent_mapping/Test Index and Search locale dependent mappings / dates] before test
  1> [2019-12-06T00:06:48,621][INFO ][o.e.b.MixedClusterClientYamlTestSuiteIT] [test] Stash dump on test failure [{
  1>   "stash" : {
  1>     "body" : {
  1>       "error" : {
  1>         "root_cause" : [ ],
  1>         "type" : "search_phase_execution_exception",
  1>         "reason" : "all shards failed",
  1>         "phase" : "query",
  1>         "grouped" : true,
  1>         "failed_shards" : [ ],
  1>         "stack_trace" : "Failed to execute phase [query], all shards failed
  1> 	at org.elasticsearch.action.search.AbstractSearchAsyncAction.onPhaseFailure(AbstractSearchAsyncAction.java:296)
  1> 	at org.elasticsearch.action.search.AbstractSearchAsyncAction.executeNextPhase(AbstractSearchAsyncAction.java:139)
  1> 	at org.elasticsearch.action.search.AbstractSearchAsyncAction.onPhaseDone(AbstractSearchAsyncAction.java:259)
  1> 	at org.elasticsearch.action.search.InitialSearchPhase.onShardFailure(InitialSearchPhase.java:105)
  1> 	at org.elasticsearch.action.search.InitialSearchPhase.lambda$performPhaseOnShard$1(InitialSearchPhase.java:251)
  1> 	at org.elasticsearch.action.search.InitialSearchPhase$1.doRun(InitialSearchPhase.java:172)
  1> 	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
  1> 	at org.elasticsearch.common.util.concurrent.TimedRunnable.doRun(TimedRunnable.java:41)
  1> 	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:751)
  1> 	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
  1> 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
  1> 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
  1> 	at java.lang.Thread.run(Thread.java:748)
  1> "
  1>       },
  1>       "status" : 503
  1>     }
  1>   }
  1> }]

I could not reproduce locally using:

./gradlew ':qa:mixed-cluster:v7.1.0#mixedClusterTest' --tests "org.elasticsearch.backwards.MixedClusterClientYamlTestSuiteIT.test {p0=search/180_locale_dependent_mapping/Test Index and Search locale dependent mappings / dates}" \
  -Dtests.seed=FFEEF395D279E9FB \
  -Dtests.security.manager=true \
  -Dtests.locale=lt \
  -Dtests.timezone=America/Rosario \
  -Dtests.distribution=default \
  -Dcompiler.java=12 \
  -Druntime.java=8

So the problem may well depend on whether the master node is 7.1 or 7.6 and whether some request is sent direct to master or via a non-master coordinating node.