search

quickwit-oss / quickwit

Cloud-native search engine for observability. An open-source alternative to Datadog, Elasticsearch, Loki, and Tempo.
https://quickwit.io
Other
8.29k stars 339 forks source link

precondition failed for splits #5431

Open sergeyignatov opened 2 months ago

sergeyignatov commented 2 months ago

Hi, We have 4 indexes in quickwit, all indexes are in GCS, quickwit version 0.8.2. Recently started issue with the biggest index fluentbit-logs-2024-09-12 when splits older 1h is automatically removed. Other indexes are ok. The issue is not gone after the index recreation.

The affected index has way more Staged splits than other indexes. 

select count(*), split_state, index_uid from splits  group by index_uid, split_state order by index_uid;
 count |    split_state    |                          index_uid
-------+-------------------+--------------------------------------------------------------

  1941 | Staged            | fluentbit-logs-2024-09-12:01J7MNHZMJSJJ80B2JN40CE12J
   485 | Published         | fluentbit-logs-2024-09-12:01J7MNHZMJSJJ80B2JN40CE12J
  9851 | MarkedForDeletion | fluentbit-logs-2024-09-12:01J7MNHZMJSJJ80B2JN40CE12J
  8349 | MarkedForDeletion | fluentbit-logs-connect-2024-02-05:01HSA1Z6D9N74GPZ0DX9B3RVYV
   902 | Published         | fluentbit-logs-connect-2024-02-05:01HSA1Z6D9N74GPZ0DX9B3RVYV
    16 | Staged            | fluentbit-logs-connect-2024-02-05:01HSA1Z6D9N74GPZ0DX9B3RVYV
  9156 | MarkedForDeletion | fluentbit-logs-sk-2024-01-30:01HNDX8JAKT5A6A06BFVZF8TC2
  1020 | Published         | fluentbit-logs-sk-2024-01-30:01HNDX8JAKT5A6A06BFVZF8TC2
    15 | Staged            | fluentbit-logs-sk-2024-01-30:01HNDX8JAKT5A6A06BFVZF8TC2

In the indexer logs the only errors:

2024-09-16T07:13:19Z 2024-09-16T07:13:19.603Z DEBUG merge{merge_split_id=01J7WTQKDHE1DSZJCC8HZZBM6V split_ids=["01J7WTQ9BFBHCHRXT9MXZ265DA", "01J7WTKJSX9DZ5GACD8GGK3E5T", "01J7WTFVCS7S8NBTFRCN0ZNWAB", "01J7WTCEM5PXZ6BCCN8CP9YG2B", "01J7WT8X7M3YNXWTYB5SVQM6X9", "01J7WT5NG5PNZ571V6PGBMH5TZ", "01J7WT2D80WANG4V0EN4FVZHKF", "01J7WSZ07FDD1DB8SE1M8ZX2ZT", "01J7WSVJXY8G25A2Y99V580GNC", "01J7WSQS4WYMB8V98SJSA89BP4"] typ=Merge}:uploader:upload{split=01J7WTQ
KDHE1DSZJCC8HZZBM6V}:store_split: quickwit_indexing::split_store::indexing_split_store: store-split-remote-success split_size_in_megabytes=2336.5374 num_docs=5074840 elapsed_secs=34.93994 throughput_mb_s=66.87296 is_mature=false
2024-09-16T07:13:19Z 2024-09-16T07:13:19.603Z DEBUG merge{merge_split_id=01J7WTQKDHE1DSZJCC8HZZBM6V split_ids=["01J7WTQ9BFBHCHRXT9MXZ265DA", "01J7WTKJSX9DZ5GACD8GGK3E5T", "01J7WTFVCS7S8NBTFRCN0ZNWAB", "01J7WTCEM5PXZ6BCCN8CP9YG2B", "01J7WT8X7M3YNXWTYB5SVQM6X9", "01J7WT5NG5PNZ571V6PGBMH5TZ", "01J7WT2D80WANG4V0EN4FVZHKF", "01J7WSZ07FDD1DB8SE1M8ZX2ZT", "01J7WSVJXY8G25A2Y99V580GNC", "01J7WSQS4WYMB8V98SJSA89BP4"] typ=Merge}:uploader:upload{split=01J7WTQ
KDHE1DSZJCC8HZZBM6V}:store_split: quickwit_indexing::split_store::indexing_split_store: store-in-cache
2024-09-16T07:13:19Z 2024-09-16T07:13:19.604Z DEBUG merge{merge_split_id=01J7WTQKDHE1DSZJCC8HZZBM6V split_ids=["01J7WTQ9BFBHCHRXT9MXZ265DA", "01J7WTKJSX9DZ5GACD8GGK3E5T", "01J7WTFVCS7S8NBTFRCN0ZNWAB", "01J7WTCEM5PXZ6BCCN8CP9YG2B", "01J7WT8X7M3YNXWTYB5SVQM6X9", "01J7WT5NG5PNZ571V6PGBMH5TZ", "01J7WT2D80WANG4V0EN4FVZHKF", "01J7WSZ07FDD1DB8SE1M8ZX2ZT", "01J7WSVJXY8G25A2Y99V580GNC", "01J7WSQS4WYMB8V98SJSA89BP4"] typ=Merge}:uploader: quickwit_actors::ac
tor_context: from=MergeUploader-ancient-MtKx send=MergePublisher-cold-XqZ7 msg=SplitsUpdate { index_id: "fluentbit-logs-2024-09-12", new_splits: "01J7WTQKDHE1DSZJCC8HZZBM6V", checkpoint_delta: None }
2024-09-16T07:13:19Z 2024-09-16T07:13:19.635Z ERROR quickwit_actors::spawn_builder: actor-failure cause=failed to publish splits
2024-09-16T07:13:19Z
2024-09-16T07:13:19Z Caused by:
2024-09-16T07:13:19Z precondition failed for splits `01J7WT2D80WANG4V0EN4FVZHKF, 01J7WSQS4WYMB8V98SJSA89BP4, 01J7WSVJXY8G25A2Y99V580GNC, 01J7WSZ07FDD1DB8SE1M8ZX2ZT`: splits are not marked for deletion exit_status=Failure(failed to publish splits
2024-09-16T07:13:19Z
2024-09-16T07:13:19Z Caused by:
2024-09-16T07:13:19Z precondition failed for splits `01J7WT2D80WANG4V0EN4FVZHKF, 01J7WSQS4WYMB8V98SJSA89BP4, 01J7WSVJXY8G25A2Y99V580GNC, 01J7WSZ07FDD1DB8SE1M8ZX2ZT`: splits are not marked for deletion)
2024-09-16T07:13:19Z 2024-09-16T07:13:19.635Z  INFO quickwit_actors::spawn_builder: actor-exit actor_id=MergePublisher-cold-XqZ7 exit_status=failure(cause=failed to publish splits
2024-09-16T07:13:19Z
2024-09-16T07:13:19Z Caused by:
2024-09-16T07:13:19Z precondition failed for splits `01J7WT2D80WANG4V0EN4FVZHKF, 01J7WSQS4WYMB8V98SJSA89BP4, 01J7WSVJXY8G25A2Y99V580GNC, 01J7WSZ07FDD1DB8SE1M8ZX2ZT`: splits are not marked for deletion)
2024-09-16T07:13:19Z 2024-09-16T07:13:19.635Z ERROR quickwit_actors::actor_context: exit activating-kill-switch actor=MergePublisher-cold-XqZ7 exit_status=Failure(failed to publish splits
2024-09-16T07:13:19Z
2024-09-16T07:13:19Z Caused by:
2024-09-16T07:13:19Z precondition failed for splits `01J7WT2D80WANG4V0EN4FVZHKF, 01J7WSQS4WYMB8V98SJSA89BP4, 01J7WSVJXY8G25A2Y99V580GNC, 01J7WSZ07FDD1DB8SE1M8ZX2ZT`: splits are not marked for deletion)
2024-09-16T07:13:19Z 2024-09-16T07:13:19.635Z DEBUG quickwit_common::kill_switch: kill-switch-activated
2024-09-16T07:13:19Z 2024-09-16T07:13:19.813Z DEBUG quickwit_indexing::actors::merge_pipeline: Merge pipeline running. pipeline_id=IndexingPipelineId { node_id: "quickwit-indexer-27", index_uid: IndexUid { index_id: "otel-logs-v0_7", incarnation_id: Ulid(2063959136266216495463690505829921250) }, source_id: "_ingest-api-source", pipeline_uid: Pipeline(01J7WN5H0HPQKHF24X7WR6ZCWG) } generation=1 healthy_actors=["MergePlanner-spring-SN2A", "MergeSplitDownloader-throbbing-dUH8", "MergeExecutor-dawn-pAvm", "MergePackager-twilight-VTk7", "MergeUploader-black-JdUK", "MergePublisher-old-iQPj"] failed_or_unhealthy_actors=[] success_actors=[]
2024-09-16T07:13:19Z 2024-09-16T07:13:19.813Z DEBUG quickwit_indexing::actors::merge_pipeline: Merge pipeline running. pipeline_id=IndexingPipelineId { node_id: "quickwit-indexer-27", index_uid: IndexUid { index_id: "query-log-2024-06-17", incarnation_id: Ulid(2077716558178011118253688979804328215) }, source_id: "_ingest-api-source", pipeline_uid: Pipeline(01J7WN5H0HD2FE5DTTAE559ZNY) } generation=1 healthy_actors=["MergePlanner-broken-d4ur", "MergeSplitDownloader-black-YjDS", "MergeExecutor-nameless-ti3k", "MergePackager-ancient-RdhO", "MergeUploader-sparkling-RbOn", "MergePublisher-falling-k4Ls"] failed_or_unhealthy_actors=[] success_actors=[]

index config 

 - version: 0.8
    index_id: fluentbit-logs-2024-09-12
    doc_mapping:
      mode: dynamic
      field_mappings:
      - name: timestamp
        type: datetime
        input_formats:
        - iso8601
        output_format: unix_timestamp_millis
        precision: milliseconds
        fast: true
      - name: message
        type: text
        tokenizer: default
        record: position
        stored: true
      - name: log
        type: text
        tokenizer: default
        record: position
        stored: true

      timestamp_field: timestamp
    indexing_settings:
      commit_timeout_secs: 10
    search_settings:
      default_search_fields:
      - message
      - log
    retention:
      period: 5 days
      schedule: hourly
fulmicoton commented 2 months ago

@trinity-1686a any idea what happened here?

trinity-1686a commented 2 months ago

the error message is a bit misleading. iiuc, this error happens when a split was expected to be Published and is actually not. The only situation where i can imagine a split being Staged according to the metastore, but a merge candidate for an indexer, is if the metastore was rolled back. That can happen easily with the S3/GCS metastore (if multiple metastores are running and they fight each other), not so much on postgres. The more likely scenario is the splits are already MarkedForDeletion, which could happen due to the same kind of issues, but also other reasons. The only persistent issue that comes to mind would be that two indexers have the same node_id, so they try to merge splits from each others.

Do you know if some of your indexes have the same node_id? (either explicitly configured, or same short hostname)? If you search for 01J7WT2D80WANG4V0EN4FVZHKF in all your logs, do you get logs for more than one indexer?

sergeyignatov commented 2 months ago

The split 01J7WT2D80WANG4V0EN4FVZHKF is present only in the quickwit-indexer-27 and metastore logs.


2024-09-16 07:13:19.5342024-09-16T07:13:19.533Z  INFO stage_splits{split_ids="[\"01J7WTV5YEJ4KCD5B27SZ2XMXS\"]"}: quickwit_metastore::metastore::postgres::metastore: staged `1` splits successfully index_id=fluentbit-logs-2024-09-122024-09-16 07:13:19.5342024-09-16T07:13:19.534Z  INFO stage_splits{split_ids="[\"01J7WTV5JQ2HW1XD7XEWB5CBFG\"]"}: quickwit_metastore::metastore::postgres::metastore: staged `1` splits successfully index_id=fluentbit-logs-2024-09-12 | 2024-09-16 07:13:19.534 | 2024-09-16T07:13:19.533Z  INFO stage_splits{split_ids="[\"01J7WTV5YEJ4KCD5B27SZ2XMXS\"]"}: quickwit_metastore::metastore::postgres::metastore: staged `1` splits successfully index_id=fluentbit-logs-2024-09-12

2024-09-16 07:13:19.534 | 2024-09-16T07:13:19.534Z  INFO stage_splits{split_ids="[\"01J7WTV5JQ2HW1XD7XEWB5CBFG\"]"}: quickwit_metastore::metastore::postgres::metastore: staged `1` splits successfully index_id=fluentbit-logs-2024-09-12 
2024-09-16 07:13:19.534 | 2024-09-16T07:13:19.533Z  INFO stage_splits{split_ids="[\"01J7WTV5YEJ4KCD5B27SZ2XMXS\"]"}: quickwit_metastore::metastore::postgres::metastore: staged `1` splits successfully index_id=fluentbit-logs-2024-09-12
2024-09-16 07:13:19.534 | 2024-09-16T07:13:19.534Z  INFO stage_splits{split_ids="[\"01J7WTV5JQ2HW1XD7XEWB5CBFG\"]"}: quickwit_metastore::metastore::postgres::metastore: staged `1` splits successfully index_id=fluentbit-logs-2024-09-12 

2024-09-16 07:13:19.638 | 2024-09-16T07:13:19.634Z  WARN publish_splits{request=PublishSplitsRequest { index_uid: Some(IndexUid { index_id: "fluentbit-logs-2024-09-12", incarnation_id: Ulid(2086843892575080035060981602672116818) }), staged_split_ids: ["01J7WTQKDHE1DSZJCC8HZZBM6V"], replaced_split_ids: ["01J7WSVJXY8G25A2Y99V580GNC", "01J7WT2D80WANG4V0EN4FVZHKF", "01J7WT5NG5PNZ571V6PGBMH5TZ", "01J7WTQ9BFBHCHRXT9MXZ265DA", "01J7WTKJSX9DZ5GACD8GGK3E5T", "01J7WTCEM5PXZ6BCCN8CP9YG2B", "01J7WSQS4WYMB8V98SJSA89BP4", "01J7WT8X7M3YNXWTYB5SVQM6X9", "01J7WTFVCS7S8NBTFRCN0ZNWAB", "01J7WSZ07FDD1DB8SE1M8ZX2ZT"], index_checkpoint_delta_json_opt: None, publish_token_opt: None }}: quickwit_metastore::metastore::postgres::metastore: rollback

2024-09-16 07:13:19.638 | 2024-09-16T07:13:19.636Z  INFO publish_splits{request=PublishSplitsRequest { index_uid: Some(IndexUid { index_id: "fluentbit-logs-connect-2024-02-05", incarnation_id: Ulid(2068240375732922833404597870727557083) }), staged_split_ids: ["01J7WTV646WZ63XE6NXYJVYVD1"], replaced_split_ids: [], index_checkpoint_delta_json_opt: Some("{\"source_id\":\"_ingest-api-source\",\"source_delta\":{\"per_partition\":{\"ingest_partition_01J7WNDBAVYDR8BBZB14NBGMA4\":{\"from\":\"00000000000000449363\",\"to\":\"00000000000000458417\"}}}}"), publish_token_opt: None }}: quickwit_metastore::metastore::postgres::metastore: published 1 splits and marked 0 for deletion successfully index_id=fluentbit-logs-connect-2024-02-052024-09-16 07:13:19.7572024-09-16T07:13:19.755Z  INFO stage_splits{split_ids="[\"01J7WTV66RWB63VWTKNGH999D4\"]"}: quickwit_metastore::metastore::postgres::metastore: staged `1` splits successfully index_id=fluentbit-logs-2024-09-12 

2024-09-16 07:13:19.638 | 2024-09-16T07:13:19.636Z  INFO publish_splits{request=PublishSplitsRequest { index_uid: Some(IndexUid { index_id: "fluentbit-logs-connect-2024-02-05", incarnation_id: Ulid(2068240375732922833404597870727557083) }), staged_split_ids: ["01J7WTV646WZ63XE6NXYJVYVD1"], replaced_split_ids: [], index_checkpoint_delta_json_opt: Some("{\"source_id\":\"_ingest-api-source\",\"source_delta\":{\"per_partition\":{\"ingest_partition_01J7WNDBAVYDR8BBZB14NBGMA4\":{\"from\":\"00000000000000449363\",\"to\":\"00000000000000458417\"}}}}"), publish_token_opt: None }}: quickwit_metastore::metastore::postgres::metastore: published 1 splits and marked 0 for deletion successfully index_id=fluentbit-logs-connect-2024-02-05

2024-09-16 07:13:19.757 | 2024-09-16T07:13:19.755Z  INFO stage_splits{split_ids="[\"01J7WTV66RWB63VWTKNGH999D4\"]"}: quickwit_metastore::metastore::postgres::metastore: staged `1` splits successfully index_id=fluentbit-logs-2024-09-12
2024-09-16 07:13:19.638 | 2024-09-16T07:13:19.636Z  INFO publish_splits{request=PublishSplitsRequest { index_uid: Some(IndexUid { index_id: "fluentbit-logs-connect-2024-02-05", incarnation_id: Ulid(2068240375732922833404597870727557083) }), staged_split_ids: ["01J7WTV646WZ63XE6NXYJVYVD1"], replaced_split_ids: [], index_checkpoint_delta_json_opt: Some("{\"source_id\":\"_ingest-api-source\",\"source_delta\":{\"per_partition\":{\"ingest_partition_01J7WNDBAVYDR8BBZB14NBGMA4\":{\"from\":\"00000000000000449363\",\"to\":\"00000000000000458417\"}}}}"), publish_token_opt: None }}: quickwit_metastore::metastore::postgres::metastore: published 1 splits and marked 0 for deletion successfully index_id=fluentbit-logs-connect-2024-02-05
2024-09-16 07:13:19.757 | 2024-09-16T07:13:19.755Z  INFO stage_splits{split_ids="[\"01J7WTV66RWB63VWTKNGH999D4\"]"}: quickwit_metastore::metastore::postgres::metastore: staged `1` splits successfully index_id=fluentbit-logs-2024-09-12
sergeyignatov commented 2 months ago

Also in the affected index the "timestamp range start" not equal to "Timestamp range end " - retention 

General Information
 --------------------------------------------+-------------------------------------------------------------------------------------
  Index ID                                   | fluentbit-logs-2024-09-12
  Number of published documents              | 357.045612 M (357,045,612)
  Size of published documents (uncompressed) | 499.8 GB
  Number of published splits                 | 822
  Size of published splits                   | 149.7 GB
  Timestamp field                            | "timestamp"
  Timestamp range start                      | 2024-09-06 06:11:43 (Timestamp: 1725603103)
  Timestamp range end                        | 2024-09-17 18:15:21 (Timestamp: 1726596921)
sergeyignatov commented 2 months ago

How likely a logs with the timestamp older than now() - "retention days" may break the retention logic ?

trinity-1686a commented 2 months ago

the retention logic looks at the timestamp range end (of individual splits). If quickwit receives a batch of documents that are retention days old, and make a split only of that (with no recent document), the retention policy will mark the split for deletion on the next round. If the indexer tries to merge it after that, it will probably get the error you're getting

sergeyignatov commented 2 months ago

we started to drop logs with timestamp in the far past on the fluent-bit side and the issue has been resolved.
It would be good to have such protection on the quickwit ingestion side.

hardfornamesohard commented 1 month ago

i got the same error log， it occurs when a reaching retention period split is deleted ，does this situation affect the incomming ingested data？i wonder know if the incomming data will lost or not？ @trinity-1686a

trinity-1686a commented 1 month ago

when a precondition fails on a merge, the splits used in the merge stay in the same state. They don't get marked for deletion until the merge succeeded. This may result in sub-optimal search (it's faster to search a single large split than a dozen smaller ones), but this doesn't cause loss or duplication of data