[CI] SearchQueryIT testDateRangeInQueryStringWithTimeZone_7880 "Fields resolved to two different dates"

[droberts195]

org.elasticsearch.search.query.SearchQueryIT testDateRangeInQueryStringWithTimeZone_7880 failed in https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+multijob-unix-compatibility/os=fedora/200/console with this error:

23:48:26    > Throwable #1: MapperParsingException[failed to parse field [past] of type [date]]; nested: IllegalArgumentException[failed to parse date field [2019-01-23T23:48:15.384GMT0] with format [strict_date_optional_time||epoch_millis]]; nested: NotSerializableExceptionWrapper[date_time_parse_exception: Text '2019-01-23T23:48:15.384GMT0' could not be parsed: Conflict found: Fields resolved to two different dates: 2019-01-23 1970-01-01]; nested: NotSerializableExceptionWrapper[date_time_exception: Conflict found: Fields resolved to two different dates: 2019-01-23 1970-01-01];
23:48:26    > 	at __randomizedtesting.SeedInfo.seed([2F507404F3AD10FE:3BF7715B9238CEBB]:0)
23:48:26    > 	at org.elasticsearch.index.mapper.FieldMapper.parse(FieldMapper.java:280)
23:48:26    > 	at org.elasticsearch.index.mapper.DocumentParser.parseObjectOrField(DocumentParser.java:468)
23:48:26    > 	at org.elasticsearch.index.mapper.DocumentParser.parseValue(DocumentParser.java:596)
23:48:26    > 	at org.elasticsearch.index.mapper.DocumentParser.innerParseObject(DocumentParser.java:407)
23:48:26    > 	at org.elasticsearch.index.mapper.DocumentParser.parseObjectOrNested(DocumentParser.java:381)
23:48:26    > 	at org.elasticsearch.index.mapper.DocumentParser.internalParseDocument(DocumentParser.java:98)
23:48:26    > 	at org.elasticsearch.index.mapper.DocumentParser.parseDocument(DocumentParser.java:71)
23:48:26    > 	at org.elasticsearch.index.mapper.DocumentMapper.parse(DocumentMapper.java:264)
23:48:26    > 	at org.elasticsearch.index.shard.IndexShard.prepareIndex(IndexShard.java:755)
23:48:26    > 	at org.elasticsearch.index.shard.IndexShard.applyIndexOperation(IndexShard.java:732)
23:48:26    > 	at org.elasticsearch.index.shard.IndexShard.applyIndexOperationOnPrimary(IndexShard.java:704)
23:48:26    > 	at org.elasticsearch.action.bulk.TransportShardBulkAction.lambda$executeIndexRequestOnPrimary$3(TransportShardBulkAction.java:461)
23:48:26    > 	at org.elasticsearch.action.bulk.TransportShardBulkAction.executeOnPrimaryWhileHandlingMappingUpdates(TransportShardBulkAction.java:484)
23:48:26    > 	at org.elasticsearch.action.bulk.TransportShardBulkAction.executeIndexRequestOnPrimary(TransportShardBulkAction.java:459)
23:48:26    > 	at org.elasticsearch.action.bulk.TransportShardBulkAction.executeBulkItemRequest(TransportShardBulkAction.java:218)
23:48:26    > 	at org.elasticsearch.action.bulk.TransportShardBulkAction.performOnPrimary(TransportShardBulkAction.java:161)
23:48:26    > 	at org.elasticsearch.action.bulk.TransportShardBulkAction.performOnPrimary(TransportShardBulkAction.java:153)
23:48:26    > 	at org.elasticsearch.action.bulk.TransportShardBulkAction.shardOperationOnPrimary(TransportShardBulkAction.java:141)
23:48:26    > 	at org.elasticsearch.action.bulk.TransportShardBulkAction.shardOperationOnPrimary(TransportShardBulkAction.java:79)
23:48:26    > 	at org.elasticsearch.action.support.replication.TransportReplicationAction$PrimaryShardReference.perform(TransportReplicationAction.java:1034)
23:48:26    > 	at org.elasticsearch.action.support.replication.TransportReplicationAction$PrimaryShardReference.perform(TransportReplicationAction.java:1012)
23:48:26    > 	at org.elasticsearch.action.support.replication.ReplicationOperation.execute(ReplicationOperation.java:102)
23:48:26    > 	at org.elasticsearch.action.support.replication.TransportReplicationAction$AsyncPrimaryAction.runWithPrimaryShardReference(TransportReplicationAction.java:414)
23:48:26    > 	at org.elasticsearch.action.support.replication.TransportReplicationAction$AsyncPrimaryAction.lambda$doRun$0(TransportReplicationAction.java:360)
23:48:26    > 	at org.elasticsearch.action.ActionListener$1.onResponse(ActionListener.java:61)
23:48:26    > 	at org.elasticsearch.index.shard.IndexShardOperationPermits.acquire(IndexShardOperationPermits.java:269)
23:48:26    > 	at org.elasticsearch.index.shard.IndexShardOperationPermits.acquire(IndexShardOperationPermits.java:236)
23:48:26    > 	at org.elasticsearch.index.shard.IndexShard.acquirePrimaryOperationPermit(IndexShard.java:2355)
23:48:26    > 	at org.elasticsearch.action.support.replication.TransportReplicationAction.acquirePrimaryOperationPermit(TransportReplicationAction.java:971)
23:48:26    > 	at org.elasticsearch.action.support.replication.TransportReplicationAction$AsyncPrimaryAction.doRun(TransportReplicationAction.java:359)
23:48:26    > 	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
23:48:26    > 	at org.elasticsearch.action.support.replication.TransportReplicationAction$PrimaryOperationTransportHandler.messageReceived(TransportReplicationAction.java:314)
23:48:26    > 	at org.elasticsearch.action.support.replication.TransportReplicationAction$PrimaryOperationTransportHandler.messageReceived(TransportReplicationAction.java:306)
23:48:26    > 	at org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:63)
23:48:26    > 	at org.elasticsearch.transport.TransportService$7.doRun(TransportService.java:687)
23:48:26    > 	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:732)
23:48:26    > 	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
23:48:26    > 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
23:48:26    > 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
23:48:26    > 	at java.lang.Thread.run(Thread.java:748)
23:48:26    > Caused by: java.lang.IllegalArgumentException: failed to parse date field [2019-01-23T23:48:15.384GMT0] with format [strict_date_optional_time||epoch_millis]
23:48:26    > 	at org.elasticsearch.common.time.JavaDateFormatter.parse(JavaDateFormatter.java:127)
23:48:26    > 	at org.elasticsearch.index.mapper.DateFieldMapper$DateFieldType.parse(DateFieldMapper.java:250)
23:48:26    > 	at org.elasticsearch.index.mapper.DateFieldMapper.parseCreateField(DateFieldMapper.java:454)
23:48:26    > 	at org.elasticsearch.index.mapper.FieldMapper.parse(FieldMapper.java:274)
23:48:26    > 	... 39 more
23:48:26    > Caused by: NotSerializableExceptionWrapper[date_time_parse_exception: Text '2019-01-23T23:48:15.384GMT0' could not be parsed: Conflict found: Fields resolved to two different dates: 2019-01-23 1970-01-01]; nested: NotSerializableExceptionWrapper[date_time_exception: Conflict found: Fields resolved to two different dates: 2019-01-23 1970-01-01];
23:48:26    > 	at java.time.format.DateTimeFormatter.createError(DateTimeFormatter.java:1920)
23:48:26    > 	at java.time.format.DateTimeFormatter.parse(DateTimeFormatter.java:1781)
23:48:26    > 	at org.elasticsearch.common.time.JavaDateFormatter.parse(JavaDateFormatter.java:125)
23:48:26    > 	... 42 more
23:48:26    > Caused by: NotSerializableExceptionWrapper[date_time_exception: Conflict found: Fields resolved to two different dates: 2019-01-23 1970-01-01]
23:48:26    > 	at java.time.format.Parsed.updateCheckConflict(Parsed.java:357)
23:48:26    > 	at java.time.format.Parsed.resolveInstantFields0(Parsed.java:345)
23:48:26    > 	at java.time.format.Parsed.resolveInstantFields(Parsed.java:331)
23:48:26    > 	at java.time.format.Parsed.resolveFields(Parsed.java:310)
23:48:26    > 	at java.time.format.Parsed.resolve(Parsed.java:244)
23:48:26    > 	at java.time.format.DateTimeParseContext.toResolved(DateTimeParseContext.java:331)
23:48:26    > 	at java.time.format.DateTimeFormatter.parseResolved0(DateTimeFormatter.java:1955)
23:48:26    > 	at java.time.format.DateTimeFormatter.parse(DateTimeFormatter.java:1777)
23:48:26    > 	... 43 more

I thought this would reproduce easily, but it didn't reproduce on my Mac nor on a Linux machine running CentOS 7 using:

./gradlew :server:integTest \
  -Dtests.seed=2F507404F3AD10FE \
  -Dtests.class=org.elasticsearch.search.query.SearchQueryIT \
  -Dtests.method="testDateRangeInQueryStringWithTimeZone_7880" \
  -Dtests.security.manager=true \
  -Dtests.locale=no \
  -Dtests.timezone=GMT0 \
  -Dcompiler.java=11 \
  -Druntime.java=8

So I guess there must be something environmental about the failure. Maybe the fact that it ran close to midnight UTC, so resolved to a different date in the server timezone and the timezone specified in the date string. Or maybe something related to the OS being Fedora 28.

[javanna]

This one reproduces for me with the following seed, I am running on Fedora 28:

REPRODUCE WITH: ./gradlew :server:integTest -Dtests.seed=85FA1B5E67DEAE8C -Dtests.class=org.elasticsearch.search.query.SearchQueryIT -Dtests.method="testDateRangeInQueryStringWithTimeZone_7880" -Dtests.security.manager=true -Dtests.locale=ru -Dtests.timezone=Europe/Riga -Dcompiler.java=11 -Druntime.java=8

ERROR   3.61s | SearchQueryIT.testDateRangeInQueryStringWithTimeZone_7880 <<< FAILURES!
   > Throwable #1: MapperParsingException[failed to parse field [past] of type [date]]; nested: IllegalArgumentException[failed to parse date field [2019-01-28T12:33:28.264GMT0] with format [strict_date_optional_time||epoch_millis]]; nested: NotSerializableExceptionWrapper[date_time_parse_exception: Text '2019-01-28T12:33:28.264GMT0' could not be parsed: Conflict found: Fields resolved to two different dates: 2019-01-28 1970-01-01]; nested: NotSerializableExceptionWrapper[date_time_exception: Conflict found: Fields resolved to two different dates: 2019-01-28 1970-01-01];
   >    at __randomizedtesting.SeedInfo.seed([85FA1B5E67DEAE8C:915D1E01064B70C9]:0)
   >    at org.elasticsearch.index.mapper.FieldMapper.parse(FieldMapper.java:280)
   >    at org.elasticsearch.index.mapper.DocumentParser.parseObjectOrField(DocumentParser.java:468)
   >    at org.elasticsearch.index.mapper.DocumentParser.parseValue(DocumentParser.java:596)
   >    at org.elasticsearch.index.mapper.DocumentParser.innerParseObject(DocumentParser.java:407)
   >    at org.elasticsearch.index.mapper.DocumentParser.parseObjectOrNested(DocumentParser.java:381)
   >    at org.elasticsearch.index.mapper.DocumentParser.internalParseDocument(DocumentParser.java:98)
   >    at org.elasticsearch.index.mapper.DocumentParser.parseDocument(DocumentParser.java:71)
   >    at org.elasticsearch.index.mapper.DocumentMapper.parse(DocumentMapper.java:264)
   >    at org.elasticsearch.index.shard.IndexShard.prepareIndex(IndexShard.java:758)
   >    at org.elasticsearch.index.shard.IndexShard.applyIndexOperation(IndexShard.java:735)
   >    at org.elasticsearch.index.shard.IndexShard.applyIndexOperationOnPrimary(IndexShard.java:707)
   >    at org.elasticsearch.action.bulk.TransportShardBulkAction.lambda$executeIndexRequestOnPrimary$3(TransportShardBulkAction.java:461)
   >    at org.elasticsearch.action.bulk.TransportShardBulkAction.executeOnPrimaryWhileHandlingMappingUpdates(TransportShardBulkAction.java:484)
   >    at org.elasticsearch.action.bulk.TransportShardBulkAction.executeIndexRequestOnPrimary(TransportShardBulkAction.java:459)
   >    at org.elasticsearch.action.bulk.TransportShardBulkAction.executeBulkItemRequest(TransportShardBulkAction.java:218)
   >    at org.elasticsearch.action.bulk.TransportShardBulkAction.performOnPrimary(TransportShardBulkAction.java:161)
   >    at org.elasticsearch.action.bulk.TransportShardBulkAction.performOnPrimary(TransportShardBulkAction.java:153)
   >    at org.elasticsearch.action.bulk.TransportShardBulkAction.shardOperationOnPrimary(TransportShardBulkAction.java:141)
   >    at org.elasticsearch.action.bulk.TransportShardBulkAction.shardOperationOnPrimary(TransportShardBulkAction.java:79)
   >    at org.elasticsearch.action.support.replication.TransportReplicationAction$PrimaryShardReference.perform(TransportReplicationAction.java:1034)
   >    at org.elasticsearch.action.support.replication.TransportReplicationAction$PrimaryShardReference.perform(TransportReplicationAction.java:1012)
   >    at org.elasticsearch.action.support.replication.ReplicationOperation.execute(ReplicationOperation.java:102)
   >    at org.elasticsearch.action.support.replication.TransportReplicationAction$AsyncPrimaryAction.runWithPrimaryShardReference(TransportReplicationAction.java:414)
   >    at org.elasticsearch.action.support.replication.TransportReplicationAction$AsyncPrimaryAction.lambda$doRun$0(TransportReplicationAction.java:360)
   >    at org.elasticsearch.action.ActionListener$1.onResponse(ActionListener.java:61)
   >    at org.elasticsearch.index.shard.IndexShardOperationPermits.acquire(IndexShardOperationPermits.java:269)
   >    at org.elasticsearch.index.shard.IndexShardOperationPermits.acquire(IndexShardOperationPermits.java:236)
   >    at org.elasticsearch.index.shard.IndexShard.acquirePrimaryOperationPermit(IndexShard.java:2401)
   >    at org.elasticsearch.action.support.replication.TransportReplicationAction.acquirePrimaryOperationPermit(TransportReplicationAction.java:971)
   >    at org.elasticsearch.action.support.replication.TransportReplicationAction$AsyncPrimaryAction.doRun(TransportReplicationAction.java:359)
   >    at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
   >    at org.elasticsearch.action.support.replication.TransportReplicationAction$PrimaryOperationTransportHandler.messageReceived(TransportReplicationAction.java:314)
   >    at org.elasticsearch.action.support.replication.TransportReplicationAction$PrimaryOperationTransportHandler.messageReceived(TransportReplicationAction.java:306)
   >    at org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:63)
   >    at org.elasticsearch.transport.TransportService$7.doRun(TransportService.java:687)
   >    at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:751)
   >    at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
   >    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
   >    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
   >    at java.lang.Thread.run(Thread.java:748)
   > Caused by: java.lang.IllegalArgumentException: failed to parse date field [2019-01-28T12:33:28.264GMT0] with format [strict_date_optional_time||epoch_millis]
   >    at org.elasticsearch.common.time.JavaDateFormatter.parse(JavaDateFormatter.java:127)
   >    at org.elasticsearch.index.mapper.DateFieldMapper$DateFieldType.parse(DateFieldMapper.java:250)
   >    at org.elasticsearch.index.mapper.DateFieldMapper.parseCreateField(DateFieldMapper.java:454)
   >    at org.elasticsearch.index.mapper.FieldMapper.parse(FieldMapper.java:274)
   >    ... 39 more
   > Caused by: NotSerializableExceptionWrapper[date_time_parse_exception: Text '2019-01-28T12:33:28.264GMT0' could not be parsed: Conflict found: Fields resolved to two different dates: 2019-01-28 1970-01-01]; nested: NotSerializableExceptionWrapper[date_time_exception: Conflict found: Fields resolved to two different dates: 2019-01-28 1970-01-01];
   >    at java.time.format.DateTimeFormatter.createError(DateTimeFormatter.java:1920)
   >    at java.time.format.DateTimeFormatter.parse(DateTimeFormatter.java:1781)
   >    at org.elasticsearch.common.time.JavaDateFormatter.parse(JavaDateFormatter.java:125)
   >    ... 42 more
   > Caused by: NotSerializableExceptionWrapper[date_time_exception: Conflict found: Fields resolved to two different dates: 2019-01-28 1970-01-01]
   >    at java.time.format.Parsed.updateCheckConflict(Parsed.java:357)
   >    at java.time.format.Parsed.resolveInstantFields0(Parsed.java:345)
   >    at java.time.format.Parsed.resolveInstantFields(Parsed.java:331)
   >    at java.time.format.Parsed.resolveFields(Parsed.java:310)
   >    at java.time.format.Parsed.resolve(Parsed.java:244)
   >    at java.time.format.DateTimeParseContext.toResolved(DateTimeParseContext.java:331)
   >    at java.time.format.DateTimeFormatter.parseResolved0(DateTimeFormatter.java:1955)
   >    at java.time.format.DateTimeFormatter.parse(DateTimeFormatter.java:1777)
   >    ... 43 more

[javanna]

I have muted this test on master

[spinscale]

I found the reason for this. The timezone GMT0 in is wrongly parsed in java8.

One can reproduce the behaviour with a test like this

    public void testGMT0Zone() {
        ZoneId timeZone = ZoneId.of("GMT0");
        logger.info("zone [{}], normalized [{}]", timeZone, timeZone.normalized());
        DateFormatter dateFormatter = DateFormatter.forPattern("strict_date_optional_time");
        String now = dateFormatter.format(Instant.now().atZone(timeZone));
        dateFormatter.parse(now);
    }

This one works on java10 and fails on java8, as the GMT0 timezone cannot get properly be parsed under java 8.

This has been fixed in java9 and above but remains broken in java8. The JDK bug is at https://bugs.openjdk.java.net/browse/JDK-8138664 and the fix at http://hg.openjdk.java.net/jdk9/dev/jdk/rev/de39f994d657

I am inclined to ignore GMT0 as a timezone in this test to make the test work for now.