Skip to content

GCP Pub/Sub source timeout can drop acknowledged messages before checkpoint publication #6607

Description

@YZL0v3ZZ

Describe the bug

At audited commit 82168d5d6fd6554a0b0be8589267ccbeea7a7986, the GCP Pub/Sub source can acknowledge a pulled message before that message has crossed Quickwit's checkpointed handoff boundary.

The relevant path is GcpPubSubSource::emit_batches -> pull_message_batch:

  • emit_batches races pull_message_batch(&mut batch_builder) against EMIT_BATCHES_TIMEOUT with tokio::select!.
  • pull_message_batch acknowledges each Pub/Sub message inside a loop, then updates in-memory counters and adds the document to BatchBuilder.
  • The checkpoint delta is recorded only after the whole pulled-message loop completes.
  • emit_batches sends a RawDocBatch only when batch_builder.checkpoint_delta is non-empty.

This creates a cancellation window:

ACK M1 succeeds in Pub/Sub
-> M1's bytes are added to the in-memory BatchBuilder
-> the source awaits ACK for M2
-> the emit_batches deadline branch wins
-> tokio::select! drops the pull_message_batch future
-> record_partition_delta has not run
-> checkpoint_delta is still empty
-> emit_batches skips send_raw_doc_batch
-> M1's in-memory document bytes are dropped

At that point, Pub/Sub has accepted the ACK for M1, while Quickwit has not sent M1 to the downstream DocProcessor and has not recorded a checkpoint delta for it. Pub/Sub documents that acknowledging a message tells the service that the message was processed and need not be delivered again, and the ACK API can remove the relevant messages from the subscription.

Source anchors:

  • GCP Pub/Sub emit_batches timeout and checkpoint-gated send:
    async fn emit_batches(
    &mut self,
    source_sink: &SourceSink,
    ctx: &SourceContext,
    ) -> Result<Duration, ActorExitStatus> {
    let now = Instant::now();
    let mut batch_builder = BatchBuilder::new(SourceType::PubSub);
    let deadline = time::sleep(*EMIT_BATCHES_TIMEOUT);
    tokio::pin!(deadline);
    // TODO: ensure we ACK the message after being commit: at least once
    // TODO: ensure we increase_ack_deadline for the items
    loop {
    tokio::select! {
    resp = self.pull_message_batch(&mut batch_builder) => {
    if let Err(err) = resp {
    warn!("failed to pull messages from subscription `{}`: {:?}", self.subscription_name, err);
    }
    if batch_builder.num_bytes >= BATCH_NUM_BYTES_LIMIT {
    break;
    }
    }
    _ = &mut deadline => {
    break;
    }
    }
    ctx.record_progress();
    }
    if batch_builder.num_bytes > 0 {
    self.state.num_consecutive_empty_batches = 0
    } else {
    self.state.num_consecutive_empty_batches += 1
    }
    // TODO: need to wait for all the id to be ack for at_least_once
    if self.should_exit() {
    info!(subscription=%self.subscription_name, "reached end of subscription");
    source_sink.send_exit_with_success(ctx).await?;
    return Err(ActorExitStatus::Success);
    }
    if !batch_builder.checkpoint_delta.is_empty() {
    debug!(
    num_bytes=%batch_builder.num_bytes,
    num_docs=%batch_builder.docs.len(),
    num_millis=%now.elapsed().as_millis(),
    "Sending doc batch to indexer.");
    let message = batch_builder.build();
    source_sink.send_raw_doc_batch(message, ctx).await?;
  • GCP Pub/Sub ACK-before-checkpoint loop:
    async fn pull_message_batch(&mut self, batch: &mut BatchBuilder) -> anyhow::Result<()> {
    let messages = self
    .subscription
    .pull(self.max_messages_per_pull, None)
    .await
    .context("failed to pull messages from subscription")?;
    let Some(last_message) = messages.last() else {
    return Ok(());
    };
    let message_id = last_message.message.message_id.clone();
    let publish_timestamp_millis = last_message
    .message
    .publish_time
    .as_ref()
    .map(|timestamp| timestamp.seconds * 1_000 + (timestamp.nanos as i64 / 1_000_000))
    .unwrap_or(0); // TODO: Replace with now UTC millis.
    for message in messages {
    message.ack().await?; // TODO: remove ACK here when doing at least once
    self.state.num_messages_processed += 1;
    self.state.num_bytes_processed += message.message.data.len() as u64;
    let doc: Bytes = Bytes::from(message.message.data);
    if doc.is_empty() {
    self.state.num_invalid_messages += 1;
    } else {
    batch.add_doc(doc);
    }
    }
    let to_position = Position::from(format!(
    "{}:{message_id}:{publish_timestamp_millis}",
    self.state.num_messages_processed
    ));
    let from_position = mem::replace(&mut self.state.current_position, to_position.clone());
    batch
    .checkpoint_delta
    .record_partition_delta(self.partition_id.clone(), from_position, to_position)
    .context("failed to record partition delta")?;
    Ok(())
  • Source checkpoint/exactly-once model:
    //! # Checkpoints and exactly-once semantics
    //!
    //! Quickwit is designed to offer exactly-once semantics whenever possible using the following
    //! strategy, using checkpoints.
    //!
    //! Messages are split into partitions, and within a partition messages are totally ordered: they
    //! are marked by a unique position within this partition.
    //!
    //! Sources are required to emit messages in a way that respects this partial order.
    //! If two message belong 2 different partitions, they can be emitted in any order.
    //! If two message belong to the same partition, they are required to be emitted in the order of
    //! their position.
    //!
    //! The set of documents processed by a source can then be expressed entirely as Checkpoint, that is
    //! simply a mapping `(PartitionId -> Position)`.
    //!
    //! This checkpoint is used in Quickwit to implement exactly-once semantics.
    //! When a new split is published, it is atomically published with an update of the last indexed
    //! checkpoint.
    //!
    //! If the indexing pipeline is restarted, the source will simply be recreated with that checkpoint.
  • EMIT_BATCHES_TIMEOUT:
    static EMIT_BATCHES_TIMEOUT: LazyLock<Duration> = LazyLock::new(|| {
    if cfg!(any(test, feature = "testsuite")) {
    let timeout = Duration::from_millis(100);
    assert!(timeout < *quickwit_actors::HEARTBEAT);
    timeout
    } else {
    let timeout = Duration::from_millis(1_000);
    if *quickwit_actors::HEARTBEAT < timeout {
    error!("QW_ACTOR_HEARTBEAT_SECS smaller than batch timeout");
    }
    timeout
    }
    });
  • BatchBuilder::add_doc / BatchBuilder::build:
    pub fn add_doc(&mut self, doc: Bytes) {
    let num_bytes = doc.len();
    self.docs.push(doc);
    self.num_bytes += num_bytes as u64;
    self.gauge_guard.increment(num_bytes as f64);
    }
    pub fn force_commit(&mut self) {
    self.force_commit = true;
    }
    pub fn build(self) -> RawDocBatch {
    RawDocBatch::new(self.docs, self.checkpoint_delta, self.force_commit)
  • RawDocBatch carries both docs and checkpoint delta:
    pub struct RawDocBatch {
    // Do not directly append documents to this vector; otherwise, in-flight metrics will be
    // incorrect.
    pub docs: Vec<Bytes>,
    pub checkpoint_delta: SourceCheckpointDelta,
    pub force_commit: bool,
    _gauge_guard: GaugeGuard,
    }
    impl RawDocBatch {
    pub fn new(
    docs: Vec<Bytes>,
    checkpoint_delta: SourceCheckpointDelta,
    force_commit: bool,
    ) -> Self {
    let delta = docs.iter().map(|doc| doc.len() as i64).sum::<i64>();
    let gauge_guard = GaugeGuard::new(&IN_FLIGHT_DOC_PROCESSOR_MAILBOX, delta as f64);
    Self {
    docs,
    checkpoint_delta,
    force_commit,
  • Tokio select! cancellation semantics: https://docs.rs/tokio/latest/tokio/macro.select.html
  • Tokio timeout cancellation semantics: https://docs.rs/tokio/latest/tokio/time/fn.timeout.html
  • Pub/Sub ACK API: https://cloud.google.com/pubsub/docs/reference/rest/v1/projects.subscriptions/acknowledge
  • Pub/Sub pull workflow: https://cloud.google.com/pubsub/docs/pull

The timeout is only the trigger. The correctness issue is that the source performs an external irreversible ACK before the corresponding local document/checkpoint handoff is cancellation-clean.

Steps to reproduce (if applicable)

This can be reproduced deterministically with a whitebox test. The test does not require a real GCP Pub/Sub subscription or emulator; it isolates the exact state transition in pull_message_batch using gated fake messages.

  1. Add the following test module to quickwit-indexing/src/source/gcp_pubsub_source.rs, just before the existing gcp_pubsub_emulator_tests module.
  2. Run:
cargo test -p quickwit-indexing --lib --features gcp-pubsub test_pubsub_deadline_after_ack_leaves_doc_without_checkpoint_delta -- --nocapture
  1. The current implementation passes the test:
Finished `test` profile [unoptimized] target(s) in 0.57s
Running unittests src/lib.rs (target/debug/deps/quickwit_indexing-1774c6987a924a8a)

running 1 test
test source::gcp_pubsub_source::gcp_pubsub_cancellation_tests::test_pubsub_deadline_after_ack_leaves_doc_without_checkpoint_delta ... ok

test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 172 filtered out; finished in 0.00s

The passing result is intentional: this is a bug-existence test. It asserts the current bad state after cancellation:

  • the first message has been acknowledged;
  • the first document has been added to BatchBuilder;
  • the second ACK wait is cancelled by tokio::select!;
  • current_position is still Position::Beginning;
  • checkpoint_delta is still empty;
  • the production emit_batches guard would skip send_raw_doc_batch and drop the document.
Whitebox test module
#[cfg(test)]
mod gcp_pubsub_cancellation_tests {
    use std::sync::Arc;
    use std::sync::atomic::{AtomicBool, Ordering};

    use tokio::sync::oneshot;

    use super::*;

    const FIRST_DOC: &[u8] = b"acked-before-timeout";
    const SECOND_DOC: &[u8] = b"blocked-until-after-timeout";

    struct TestPubSubMessage {
        message_id: &'static str,
        data: Bytes,
        ack_rx: oneshot::Receiver<()>,
        acked: Arc<AtomicBool>,
    }

    impl TestPubSubMessage {
        fn new(
            message_id: &'static str,
            data: &'static [u8],
            ack_rx: oneshot::Receiver<()>,
            acked: Arc<AtomicBool>,
        ) -> Self {
            Self {
                message_id,
                data: Bytes::from_static(data),
                ack_rx,
                acked,
            }
        }

        async fn ack_and_take_doc(self) -> Bytes {
            self.ack_rx.await.expect("test ACK gate should be released");
            self.acked.store(true, Ordering::SeqCst);
            self.data
        }
    }

    async fn pull_test_messages_until_checkpoint(
        state: &mut GcpPubSubSourceState,
        partition_id: &PartitionId,
        messages: Vec<TestPubSubMessage>,
        batch: &mut BatchBuilder,
        mut make_deadline_ready_after_first_doc: Option<oneshot::Sender<()>>,
    ) -> anyhow::Result<()> {
        let last_message_id = messages
            .last()
            .expect("test needs at least one message")
            .message_id;
        let publish_timestamp_millis = 0;
        let mut num_messages_in_pull = 0;

        for message in messages {
            let doc = message.ack_and_take_doc().await;
            state.num_messages_processed += 1;
            state.num_bytes_processed += doc.len() as u64;
            if doc.is_empty() {
                state.num_invalid_messages += 1;
            } else {
                batch.add_doc(doc);
            }
            num_messages_in_pull += 1;

            if num_messages_in_pull == 1
                && let Some(deadline_tx) = make_deadline_ready_after_first_doc.take()
            {
                let _ = deadline_tx.send(());
            }
        }

        let to_position = Position::from(format!(
            "{}:{last_message_id}:{publish_timestamp_millis}",
            state.num_messages_processed
        ));
        let from_position = mem::replace(&mut state.current_position, to_position.clone());
        batch
            .checkpoint_delta
            .record_partition_delta(partition_id.clone(), from_position, to_position)
            .expect("test checkpoint delta should record");
        Ok(())
    }

    #[tokio::test]
    async fn test_pubsub_deadline_after_ack_leaves_doc_without_checkpoint_delta() {
        let mut state = GcpPubSubSourceState::default();
        let mut batch_builder = BatchBuilder::new(SourceType::PubSub);
        let partition_id = PartitionId::from("test-pubsub-partition");

        let first_acked = Arc::new(AtomicBool::new(false));
        let second_acked = Arc::new(AtomicBool::new(false));
        let (release_first_ack_tx, release_first_ack_rx) = oneshot::channel();
        let (release_second_ack_tx, release_second_ack_rx) = oneshot::channel();
        let (deadline_tx, deadline_rx) = oneshot::channel();

        let messages = vec![
            TestPubSubMessage::new(
                "message-1",
                FIRST_DOC,
                release_first_ack_rx,
                first_acked.clone(),
            ),
            TestPubSubMessage::new(
                "message-2",
                SECOND_DOC,
                release_second_ack_rx,
                second_acked.clone(),
            ),
        ];
        release_first_ack_tx
            .send(())
            .expect("first ACK gate should have a receiver");

        let deadline_won = tokio::select! {
            result = pull_test_messages_until_checkpoint(
                &mut state,
                &partition_id,
                messages,
                &mut batch_builder,
                Some(deadline_tx),
            ) => {
                result.expect("test pull should not fail");
                false
            }
            _ = deadline_rx => true,
        };

        assert!(
            deadline_won,
            "the test deadline must cancel the in-progress pull before checkpoint recording"
        );
        assert!(
            release_second_ack_tx.send(()).is_err(),
            "the pending ACK receiver should be dropped when select cancels the pull branch"
        );
        assert!(first_acked.load(Ordering::SeqCst));
        assert!(!second_acked.load(Ordering::SeqCst));
        assert_eq!(state.num_messages_processed, 1);
        assert_eq!(state.num_bytes_processed, FIRST_DOC.len() as u64);
        assert_eq!(state.current_position, Position::Beginning);
        assert_eq!(batch_builder.docs, vec![Bytes::from_static(FIRST_DOC)]);
        assert_eq!(batch_builder.num_bytes, FIRST_DOC.len() as u64);
        assert!(batch_builder.checkpoint_delta.is_empty());
        assert!(
            batch_builder.num_bytes > 0 && batch_builder.checkpoint_delta.is_empty(),
            "the production emit_batches guard would skip send_raw_doc_batch and drop the doc"
        );
    }
}

The important gate is after the first ACK and document append, but before checkpoint recording. That avoids wall-clock timing and proves the timeout branch can observe a non-empty document batch with an empty checkpoint delta.

Expected behavior

Once a Pub/Sub ACK succeeds, Quickwit should not be able to lose the corresponding document on a caller-side timeout or select! cancellation.

The source should guarantee one of the following:

  1. Delay Pub/Sub ACK until the document has reached a durable Quickwit handoff and the corresponding checkpoint can be published.
  2. Store ACK IDs with the batch and perform ACK from suggest_truncate after the indexed checkpoint is published.
  3. If ACK remains inside batch construction, record per-message checkpoint progress and make any partially acknowledged batch cancellation-clean before awaiting the next ACK.
  4. If the deadline fires after partial external progress, return or complete an explicit partial-progress state instead of treating it as an empty/no-progress batch.

In short, emit_batches should not return successfully after acknowledging a message while skipping send_raw_doc_batch for that same message.

After a fix, the whitebox test above should no longer pass in its current form. It should be inverted to assert the corrected invariant: an acknowledged non-empty document is either emitted with a checkpoint delta, retained in a retryable handoff state, or not acknowledged yet.

Configuration

Please provide:

  1. Output of quickwit --version

    I did not rely on a Quickwit binary for this reproduction. The audited source checkout is commit 82168d5d6fd6554a0b0be8589267ccbeea7a7986, with workspace crate version 0.8.0.

  2. The index_config.yaml

    Not required for the whitebox reproduction. The issue is in the generic GCP Pub/Sub source batch construction path and is exercised without starting an index or a Pub/Sub emulator.

Additional reproduction details:

  • Package: quickwit-indexing
  • Feature: gcp-pubsub
  • Test command:
cargo test -p quickwit-indexing --lib --features gcp-pubsub test_pubsub_deadline_after_ack_leaves_doc_without_checkpoint_delta -- --nocapture

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't working

    Type

    No type

    Fields

    No fields configured for issues without a type.

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions