Open thecoop opened 10 months ago
Pinging @elastic/es-data-management (Team:Data Management)
Here's the formatted version of that returned stack trace:
i [index] returned [400 Bad Request] [{"error":{"root_cause":[{"type":"document_parsing_exception","reason":"[1:83] failed to parse: data stream timestamp field [@timestamp] is missing","stack_trace":"org.elasticsearch.index.mapper.DocumentParsingException: [1:83] failed to parse: data stream timestamp field [@timestamp] is missing
at org.elasticsearch.index.mapper.DocumentParser.wrapInDocumentParsingException(DocumentParser.java:246)
at org.elasticsearch.index.mapper.DocumentParser.internalParseDocument(DocumentParser.java:153)
at org.elasticsearch.index.mapper.DocumentParser.parseDocument(DocumentParser.java:96)
at org.elasticsearch.index.mapper.DocumentMapper.parse(DocumentMapper.java:92)
at org.elasticsearch.index.shard.IndexShard.prepareIndex(IndexShard.java:1012)
at org.elasticsearch.index.shard.IndexShard.applyIndexOperation(IndexShard.java:960)
at org.elasticsearch.index.shard.IndexShard.applyIndexOperationOnPrimary(IndexShard.java:904)
at org.elasticsearch.action.bulk.TransportShardBulkAction.executeBulkItemRequest(TransportShardBulkAction.java:360)
at org.elasticsearch.action.bulk.TransportShardBulkAction$2.doRun(TransportShardBulkAction.java:224)
at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:26)
at org.elasticsearch.action.bulk.TransportShardBulkAction.performOnPrimary(TransportShardBulkAction.java:291)
at org.elasticsearch.action.bulk.TransportShardBulkAction.dispatchedShardOperationOnPrimary(TransportShardBulkAction.java:142)
at org.elasticsearch.action.bulk.TransportShardBulkAction.dispatchedShardOperationOnPrimary(TransportShardBulkAction.java:74)
at org.elasticsearch.action.support.replication.TransportWriteAction$1.doRun(TransportWriteAction.java:216)
at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:26)
at org.elasticsearch.common.util.concurrent.TimedRunnable.doRun(TimedRunnable.java:33)
at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:983)
at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:26)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
at java.lang.Thread.run(Thread.java:1583)
Caused by: java.lang.IllegalArgumentException: data stream timestamp field [@timestamp] is missing
at org.elasticsearch.index.mapper.DataStreamTimestampFieldMapper.postParse(DataStreamTimestampFieldMapper.java:218)
at org.elasticsearch.index.mapper.DocumentParser.internalParseDocument(DocumentParser.java:150)
... 19 more
"}],"type":"document_parsing_exception","reason":"[1:83] failed to parse: data stream timestamp field [@timestamp] is missing","caused_by":{"type":"illegal_argument_exception","reason":"data stream timestamp field [@timestamp] is missing","stack_trace":"java.lang.IllegalArgumentException: data stream timestamp field [@timestamp] is missing
at org.elasticsearch.index.mapper.DataStreamTimestampFieldMapper.postParse(DataStreamTimestampFieldMapper.java:218)
at org.elasticsearch.index.mapper.DocumentParser.internalParseDocument(DocumentParser.java:150)
at org.elasticsearch.index.mapper.DocumentParser.parseDocument(DocumentParser.java:96)
at org.elasticsearch.index.mapper.DocumentMapper.parse(DocumentMapper.java:92)
at org.elasticsearch.index.shard.IndexShard.prepareIndex(IndexShard.java:1012)
at org.elasticsearch.index.shard.IndexShard.applyIndexOperation(IndexShard.java:960)
at org.elasticsearch.index.shard.IndexShard.applyIndexOperationOnPrimary(IndexShard.java:904)
at org.elasticsearch.action.bulk.TransportShardBulkAction.executeBulkItemRequest(TransportShardBulkAction.java:360)
at org.elasticsearch.action.bulk.TransportShardBulkAction$2.doRun(TransportShardBulkAction.java:224)
at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:26)
at org.elasticsearch.action.bulk.TransportShardBulkAction.performOnPrimary(TransportShardBulkAction.java:291)
at org.elasticsearch.action.bulk.TransportShardBulkAction.dispatchedShardOperationOnPrimary(TransportShardBulkAction.java:142)
at org.elasticsearch.action.bulk.TransportShardBulkAction.dispatchedShardOperationOnPrimary(TransportShardBulkAction.java:74)
at org.elasticsearch.action.support.replication.TransportWriteAction$1.doRun(TransportWriteAction.java:216)
at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:26)
at org.elasticsearch.common.util.concurrent.TimedRunnable.doRun(TimedRunnable.java:33)
at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:983)
at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:26)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
at java.lang.Thread.run(Thread.java:1583)
"},"stack_trace":"org.elasticsearch.index.mapper.DocumentParsingException: [1:83] failed to parse: data stream timestamp field [@timestamp] is missing
at org.elasticsearch.index.mapper.DocumentParser.wrapInDocumentParsingException(DocumentParser.java:246)
at org.elasticsearch.index.mapper.DocumentParser.internalParseDocument(DocumentParser.java:153)
at org.elasticsearch.index.mapper.DocumentParser.parseDocument(DocumentParser.java:96)
at org.elasticsearch.index.mapper.DocumentMapper.parse(DocumentMapper.java:92)
at org.elasticsearch.index.shard.IndexShard.prepareIndex(IndexShard.java:1012)
at org.elasticsearch.index.shard.IndexShard.applyIndexOperation(IndexShard.java:960)
at org.elasticsearch.index.shard.IndexShard.applyIndexOperationOnPrimary(IndexShard.java:904)
at org.elasticsearch.action.bulk.TransportShardBulkAction.executeBulkItemRequest(TransportShardBulkAction.java:360)
at org.elasticsearch.action.bulk.TransportShardBulkAction$2.doRun(TransportShardBulkAction.java:224)
at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:26)
at org.elasticsearch.action.bulk.TransportShardBulkAction.performOnPrimary(TransportShardBulkAction.java:291)
at org.elasticsearch.action.bulk.TransportShardBulkAction.dispatchedShardOperationOnPrimary(TransportShardBulkAction.java:142)
at org.elasticsearch.action.bulk.TransportShardBulkAction.dispatchedShardOperationOnPrimary(TransportShardBulkAction.java:74)
at org.elasticsearch.action.support.replication.TransportWriteAction$1.doRun(TransportWriteAction.java:216)
at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:26)
at org.elasticsearch.common.util.concurrent.TimedRunnable.doRun(TimedRunnable.java:33)
at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:983)
at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:26)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
at java.lang.Thread.run(Thread.java:1583)
Caused by: java.lang.IllegalArgumentException: data stream timestamp field [@timestamp] is missing
at org.elasticsearch.index.mapper.DataStreamTimestampFieldMapper.postParse(DataStreamTimestampFieldMapper.java:218)
at org.elasticsearch.index.mapper.DocumentParser.internalParseDocument(DocumentParser.java:150)
... 19 more
"},"status":400}]
Here is what this test is supposed to be doing, assuming that the template in logs@template.json
has been loaded in time (sometimes it hasn't been, and so the flow is a little different. But in this case since we're seeing datastream validation we can be sure it has been):
It ingests a simple document into the index logs-generic-default
using the pipeline pipeline-with-two-data-stream-processors
defined in the test. That pipeline has a reroute processor that reroutes it to an index called logs-first-default
. That index matches the logs
template from logs@template.json
. So it has a default pipeline defined in logs@default-pipeline.json
, referenced from logs@settings.json
, loaded as part of the logs
template. That default pipeline has a set processor that sets @timestamp
:
"set": {
"description": "If '@timestamp' is missing, set it with the ingest timestamp",
"field": "@timestamp",
"override": false,
"copy_from": "_ingest.timestamp"
}
In this case, something is going wrong. I can see from the logs that logs-first-default
is matches the logs
template. And I can see that logs@template.json
, logs@settings.json
, and logs@default-pipeline.json
have all been loaded. But somehow either that set processor is not executing, or _ingest.timestamp
is null. Maybe a race condition where the logs@default-pipeline.json
pipeline is not yet in the cluster state on the ingest node?
From my comment above "But somehow either that set processor is not executing, or _ingest.timestamp is null". I don't think it is possible for _ingest.timestamp to be null, because it is set to ZonedDateTime.now(ZoneOffset.UTC)
in IngestDocument's constructor, and is never altered or removed. So it does seem most likely that the set processor is just not being executed, meaning that logs@default-pipeline
is somehow not there.
Actually my last comment was wrong. I can reproduce this if I remove just the set processor from logs@default-pipeline.json. But if I don't load that pipeline at all, the test passes because DataStreamTimestampFieldMapper.enabled
is false
, so it doesn't check for the existence of @timestamp
. It also doesn't fail in this way if _ingest.timestamp
does not exist when the set processor runs -- it fails in a different way. The only way I've been able to get it to fail is to not run the set processor. That doesn't seem possible though. But I also don't know how _ingest.timestamp
could be null though. So I'm stumped on this one.
One last note for myself (because I'm putting this ticket aside again for a little while). I had to put a Thread.sleep() call into ESClientYamlSuiteTestCase.test() so that all templates are loaded before the test runs, so that the data stream gets created (which is what happened in the failure). The fact that the server is available before all templates have been loaded is a known issues tracked elsewhere, and is not directly related to the bug reported here.
Build scan: https://gradle-enterprise.elastic.co/s/taoppoclp6vds/tests/:modules:ingest-common:yamlRestTest/org.elasticsearch.ingest.common.IngestCommonClientYamlTestSuiteIT/test%20%7Byaml=ingest%2F310_reroute_processor%2FTest%20first%20matching%20router%20terminates%20pipeline%7D Reproduction line:
Applicable branches: main
Reproduces locally?: No
Failure history: https://gradle-enterprise.elastic.co/scans/tests?tests.container=org.elasticsearch.ingest.common.IngestCommonClientYamlTestSuiteIT&tests.test=test%20%7Byaml%3Dingest/310_reroute_processor/Test%20first%20matching%20router%20terminates%20pipeline%7D
Failure excerpt: