Universe created with accelerated_time can lead to indexing pipeline failure.

When using accelerated_time for tests test_indexing_pipeline_simple or test_indexing_pipeline_retry_1 are failing as mentioned in #2865.

This can be explained by the fact that with accelerated time, the indexing pipeline actor executes two supervise calls in 2 consecutively in less than 2 milliseconds. This leads to 2 calls registered_activity_since_last_call , on the second, the packager or indexer will timeout.

Note that I never had the chance to reproduce the bug locally, it only happened on the CI (with nextest or cargo test, it doesn't matter).

Here are logs from the CI.

2023-02-22T08:55:22.7618585Z [2023-02-22T08:55:22.749Z DEBUG quickwit_actors::actor_context] from=Packager-shy-wzPd send=IndexUploader-broken-5yhp msg=PackagedSplitBatch { parent_span: Span { name: "index_batch", level: Level(Info), target: "quickwit-indexing", disabled: true, module_path: "quickwit_indexing::actors::indexer", line: 166, file: "quickwit-indexing/src/actors/indexer.rs" }, splits: [PackagedSplit { split_attrs: SplitAttrs { split_id: "01GSW5B7T8V05X87EWQPWNR4K3", partition_id: 0, replaced_split_ids: [], time_range: Some(1375457457..=1375457457), uncompressed_docs_size_in_bytes: 1030, num_docs: 4, num_merge_ops: 0 }, split_scratch_directory: ScratchDirectory { dir: "/tmp/.tmpYgTX3C/split-01GSW5B7T8V05X87EWQPWNR4K3-tWLssX" }, tags: {"owner!", "owner:"}, split_files: ["/tmp/.tmpYgTX3C/split-01GSW5B7T8V05X87EWQPWNR4K3-tWLssX/23c75f702437454c950da2874f37f8db.fast", "/tmp/.tmpYgTX3C/split-01GSW5B7T8V05X87EWQPWNR4K3-tWLssX/23c75f702437454c950da2874f37f8db.fieldnorm", "/tmp/.tmpYgTX3C/split-01GSW5B7T8V05X87EWQPWNR4K3-tWLssX/23c75f702437454c950da2874f37f8db.idx", "/tmp/.tmpYgTX3C/split-01GSW5B7T8V05X87EWQPWNR4K3-tWLssX/23c75f702437454c950da2874f37f8db.pos", "/tmp/.tmpYgTX3C/split-01GSW5B7T8V05X87EWQPWNR4K3-tWLssX/23c75f702437454c950da2874f37f8db.store", "/tmp/.tmpYgTX3C/split-01GSW5B7T8V05X87EWQPWNR4K3-tWLssX/23c75f702437454c950da2874f37f8db.term", "/tmp/.tmpYgTX3C/split-01GSW5B7T8V05X87EWQPWNR4K3-tWLssX/meta.json"] }], checkpoint_delta_opt: Some(test-source:∆(/__w/quickwit/quickwit/quickwit/quickwit-indexing/data/test_corpus.json:(00000000000000000000..00000000000000001030])), merge_operation: None, publish_lock: PublishLock { is_alive: true } }
2023-02-22T08:55:22.7621827Z [2023-02-22T08:55:22.749Z INFO  tracing::span] uploader;
2023-02-22T08:55:22.7622780Z [2023-02-22T08:55:22.749Z DEBUG quickwit_actors::actor_context] from=IndexUploader-broken-5yhp send=quickwit_indexing::actors::sequencer::Sequencer<quickwit_indexing::actors::publisher::Publisher>-restless-20OR msg=Receiver { inner: Some(Inner { state: State { is_complete: false, is_closed: false, is_rx_task_set: false, is_tx_task_set: false } }) }
2023-02-22T08:55:22.7623690Z [2023-02-22T08:55:22.749Z INFO  quickwit_indexing::actors::uploader] start-stage-and-store-splits split_ids=["01GSW5B7T8V05X87EWQPWNR4K3"]
2023-02-22T08:55:22.7625435Z [2023-02-22T08:55:22.750Z INFO  quickwit_indexing::actors::uploader] upload; split=01GSW5B7T8V05X87EWQPWNR4K3
2023-02-22T08:55:22.7625877Z [2023-02-22T08:55:22.750Z INFO  tracing::span] store_split;
2023-02-22T08:55:22.7626481Z [2023-02-22T08:55:22.750Z INFO  quickwit_indexing::split_store::indexing_split_store] store_split_in_remote_storage; split="01GSW5B7T8V05X87EWQPWNR4K3" is_mature=true num_bytes=14459
2023-02-22T08:55:22.7629689Z [2023-02-22T08:55:22.752Z INFO  quickwit_indexing::split_store::indexing_split_store] store-split-remote-success split_size_in_megabytes=0.014459 num_docs=4 elapsed_secs=0.001808481 throughput_mb_s=7.995107 is_mature=true
2023-02-22T08:55:22.7630973Z [2023-02-22T08:55:22.753Z DEBUG quickwit_actors::actor_context] from=quickwit_indexing::actors::sequencer::Sequencer<quickwit_indexing::actors::publisher::Publisher>-restless-20OR send=Publisher-falling-RXTC msg=SplitsUpdate { index_id: "test-index", new_splits: "01GSW5B7T8V05X87EWQPWNR4K3", checkpoint_delta: Some(test-source:∆(/__w/quickwit/quickwit/quickwit/quickwit-indexing/data/test_corpus.json:(00000000000000000000..00000000000000001030])) }actor_name="quickwit_indexing::actors::sequencer::Sequencer<quickwit_indexing::actors::publisher::Publisher>"actor_name="quickwit_indexing::actors::sequencer::Sequencer<quickwit_indexing::actors::publisher::Publisher>"
actor_name="quickwit_indexing::actors::sequencer::Sequencer<quickwit_indexing::actors::publisher::Publisher>"
2023-02-22T08:55:22.7635193Z [2023-02-22T08:55:22.753Z INFO  quickwit_actors::spawn_builder] is_last_mailbox actor_name="quickwit_indexing::actors::sequencer::Sequencer<quickwit_indexing::actors::publisher::Publisher>"
2023-02-22T08:55:22.7636190Z [2023-02-22T08:55:22.754Z INFO  quickwit_indexing::actors::publisher] publisher; split_update=SplitsUpdate { index_id: "test-index", new_splits: "01GSW5B7T8V05X87EWQPWNR4K3", checkpoint_delta: Some(test-source:∆(/__w/quickwit/quickwit/quickwit/quickwit-indexing/data/test_corpus.json:(00000000000000000000..00000000000000001030])) }
2023-02-22T08:55:22.7637257Z [2023-02-22T08:55:22.754Z INFO  quickwit_indexing::actors::publisher] publish-new-splits new_splits=["01GSW5B7T8V05X87EWQPWNR4K3"] checkpoint_delta=Some(test-source:∆(/__w/quickwit/quickwit/quickwit/quickwit-indexing/data/test_corpus.json:(00000000000000000000..00000000000000001030]))
2023-02-22T08:55:22.7638123Z [2023-02-22T08:55:22.754Z INFO  quickwit_metastore::checkpoint] delta=∆(/__w/quickwit/quickwit/quickwit/quickwit-indexing/data/test_corpus.json:(00000000000000000000..00000000000000001030]) checkpoint=Ckpt()
2023-02-22T08:55:22.7639025Z [2023-02-22T08:55:22.754Z DEBUG quickwit_actors::actor_context] from=Publisher-falling-RXTC send=SourceActor-wandering-J5tt msg=SuggestTruncate(Ckpt(/__w/quickwit/quickwit/quickwit/quickwit-indexing/data/test_corpus.json:00000000000000001030))
2023-02-22T08:55:22.7640467Z [2023-02-22T08:55:22.754Z DEBUG quickwit_actors::actor_context] from=Publisher-falling-RXTC send=test-mailbox-throbbing-mB6t msg=NewSplits { new_splits: [SplitMetadata { split_id: "01GSW5B7T8V05X87EWQPWNR4K3", index_id: "test-index", partition_id: 0, source_id: "test-source", node_id: "test-node", num_docs: 4, uncompressed_docs_size_in_bytes: 1030, time_range: Some(1375457457..=1375457457), create_timestamp: 1677056122, tags: {"owner!", "owner:"}, footer_offsets: 6213..14459, delete_opstamp: 10, num_merge_ops: 0 }] }
2023-02-22T08:55:22.7656058Z [2023-02-22T08:55:22.756Z DEBUG quickwit_indexing::actors::indexing_pipeline] Indexing pipeline running. pipeline_id=IndexingPipelineId { index_id: "test-index", source_id: "test-source", node_id: "test-node", pipeline_ord: 0 } generation=1 healthy_actors=["quickwit_indexing::actors::index_serializer::IndexSerializer-bitter-fvQ3", "Packager-misty-DpPy", "IndexUploader-white-XxX0", "quickwit_indexing::actors::sequencer::Sequencer<quickwit_indexing::actors::publisher::Publisher>-empty-Pl21", "Publisher-late-X1ME"] failed_or_unhealthy_actors=[] success_actors=["SourceActor-snowy-FAmA", "quickwit_indexing::actors::doc_processor::DocProcessor-solitary-PKI9", "Indexer-aged-1s2b"]
2023-02-22T08:55:22.7670402Z [2023-02-22T08:55:22.756Z DEBUG quickwit_indexing::actors::indexing_pipeline] Indexing pipeline running. pipeline_id=IndexingPipelineId { index_id: "test-index", source_id: "test-source", node_id: "test-node", pipeline_ord: 0 } generation=1 healthy_actors=["quickwit_indexing::actors::index_serializer::IndexSerializer-misty-Pkv3", "Packager-shy-wzPd", "IndexUploader-broken-5yhp", "quickwit_indexing::actors::sequencer::Sequencer<quickwit_indexing::actors::publisher::Publisher>-restless-20OR", "Publisher-falling-RXTC"] failed_or_unhealthy_actors=[] success_actors=["SourceActor-wandering-J5tt", "quickwit_indexing::actors::doc_processor::DocProcessor-restless-psxC", "Indexer-autumn-OtWN"]
2023-02-22T08:55:22.7673935Z [2023-02-22T08:55:22.756Z DEBUG quickwit_indexing::actors::indexing_pipeline] Indexing pipeline running. pipeline_id=IndexingPipelineId { index_id: "test-index", source_id: "test-source", node_id: "test-node", pipeline_ord: 0 } generation=1 healthy_actors=["quickwit_indexing::actors::index_serializer::IndexSerializer-bitter-fvQ3", "Packager-misty-DpPy", "IndexUploader-white-XxX0", "quickwit_indexing::actors::sequencer::Sequencer<quickwit_indexing::actors::publisher::Publisher>-empty-Pl21", "Publisher-late-X1ME"] failed_or_unhealthy_actors=[] success_actors=["SourceActor-snowy-FAmA", "quickwit_indexing::actors::doc_processor::DocProcessor-solitary-PKI9", "Indexer-aged-1s2b"]
2023-02-22T08:55:22.7695838Z [2023-02-22T08:55:22.757Z ERROR quickwit_actors::actor_handle] actor-timeout actor="Packager-shy-wzPd"
2023-02-22T08:55:22.7697907Z [2023-02-22T08:55:22.757Z ERROR quickwit_indexing::actors::indexing_pipeline] Indexing pipeline failure. pipeline_id=IndexingPipelineId { index_id: "test-index", source_id: "test-source", node_id: "test-node", pipeline_ord: 0 } generation=1 healthy_actors=["quickwit_indexing::actors::index_serializer::IndexSerializer-misty-Pkv3", "IndexUploader-broken-5yhp", "quickwit_indexing::actors::sequencer::Sequencer<quickwit_indexing::actors::publisher::Publisher>-restless-20OR", "Publisher-falling-RXTC"] failed_or_unhealthy_actors=["Packager-shy-wzPd"] success_actors=["SourceActor-wandering-J5tt", "quickwit_indexing::actors::doc_processor::DocProcessor-restless-psxC", "Indexer-autumn-OtWN"]
2023-02-22T08:55:22.7699190Z [2023-02-22T08:55:22.757Z DEBUG quickwit_common::kill_switch] kill-switch-activated
2023-02-22T08:55:22.7699771Z [2023-02-22T08:55:22.757Z DEBUG quickwit_common::kill_switch] kill-switch-activated
2023-02-22T08:55:22.7703469Z [2023-02-22T08:55:22.757Z DEBUG quickwit_common::kill_switch] kill-switch-activated
2023-02-22T08:55:22.7706416Z [2023-02-22T08:55:22.757Z DEBUG quickwit_common::kill_switch] kill-switch-activated
2023-02-22T08:55:22.7707065Z [2023-02-22T08:55:22.757Z INFO  quickwit_actors::spawn_builder] actor-exit actor_id=quickwit_indexing::actors::index_serializer::IndexSerializer-bitter-fvQ3 exit_status=Success
2023-02-22T08:55:22.7707640Z [2023-02-22T08:55:22.757Z DEBUG quickwit_common::kill_switch] kill-switch-activated
2023-02-22T08:55:22.7708839Z [2023-02-22T08:55:22.757Z DEBUG quickwit_common::kill_switch] kill-switch-activated
2023-02-22T08:55:22.7709914Z [2023-02-22T08:55:22.757Z INFO  quickwit_actors::spawn_builder] actor-exit actor_id=IndexUploader-broken-5yhp exit_status=Killed
2023-02-22T08:55:22.7713431Z [2023-02-22T08:55:22.757Z INFO  quickwit_actors::spawn_builder] actor-exit actor_id=Packager-shy-wzPd exit_status=Killed
2023-02-22T08:55:22.7715285Z [2023-02-22T08:55:22.757Z INFO  quickwit_actors::spawn_builder] actor-exit actor_id=Publisher-falling-RXTC exit_status=Killed
2023-02-22T08:55:22.7723561Z [2023-02-22T08:55:22.757Z INFO  quickwit_actors::spawn_builder] actor-exit actor_id=quickwit_indexing::actors::index_serializer::IndexSerializer-misty-Pkv3 exit_status=Success
2023-02-22T08:55:22.7731940Z [2023-02-22T08:55:22.757Z INFO  quickwit_actors::spawn_builder] actor-exit actor_id=quickwit_indexing::actors::sequencer::Sequencer<quickwit_indexing::actors::publisher::Publisher>-restless-20OR exit_status=Killed
2023-02-22T08:55:22.7738150Z [2023-02-22T08:55:22.757Z INFO  quickwit_actors::spawn_builder] actor-exit actor_id=Packager-misty-DpPy exit_status=Success
2023-02-22T08:55:22.7742810Z [2023-02-22T08:55:22.758Z INFO  quickwit_indexing::actors::indexing_pipeline] spawn_pipeline; index=test-index gen=1
2023-02-22T08:55:22.7745280Z [2023-02-22T08:55:22.758Z DEBUG quickwit_indexing::actors::indexing_pipeline] Indexing pipeline running. pipeline_id=IndexingPipelineId { index_id: "test-index", source_id: "test-source", node_id: "test-node", pipeline_ord: 0 } generation=1 healthy_actors=["IndexUploader-white-XxX0", "quickwit_indexing::actors::sequencer::Sequencer<quickwit_indexing::actors::publisher::Publisher>-empty-Pl21", "Publisher-late-X1ME"] failed_or_unhealthy_actors=[] success_actors=["SourceActor-snowy-FAmA", "quickwit_indexing::actors::doc_processor::DocProcessor-solitary-PKI9", "Indexer-aged-1s2b", "quickwit_indexing::actors::index_serializer::IndexSerializer-bitter-fvQ3", "Packager-misty-DpPy"]
2023-02-22T08:55:22.7748713Z [2023-02-22T08:55:22.758Z INFO  quickwit_indexing::actors::indexing_pipeline] Spawning indexing pipeline. index_id=test-index source_id=test-source pipeline_ord=0 root_dir=/tmp/.tmpYgTX3C

Start with the test cases test_indexing_pipeline_simple and test_indexing_pipeline_retry_1, then inspect the indexing pipeline actor around supervise and registered_activity_since_last_call. Run the tests with accelerated_time and verify that the packager and indexer no longer time out or cause pipeline failure.