Skip to content

improve s3 retry log #6609

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
PSeitz wants to merge 1 commit into
base: main
Choose a base branch
from
Open

improve s3 retry log #6609

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions quickwit/Cargo.lock
View file
Open in desktop

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

7 changes: 6 additions & 1 deletion quickwit/quickwit-aws/src/retry.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -62,13 +62,18 @@ where E: AwsRetryable
}
}

pub async fn aws_retry<U, E, Fut>(retry_params: &RetryParams, f: impl Fn() -> Fut) -> Result<U, E>
pub async fn aws_retry<U, E, Fut>(
request_name: &'static str,
retry_params: &RetryParams,
f: impl Fn() -> Fut,
) -> Result<U, E>
where
Fut: Future<Output = Result<U, E>>,
E: AwsRetryable + Debug + 'static,
{
retry_with_mockable_sleep(
retry_params,
request_name,
|| f().map_err(AwsRetryableWrapper),
TokioSleep,
)
Expand Down
1 change: 1 addition & 0 deletions quickwit/quickwit-common/Cargo.toml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -73,3 +73,4 @@ serde_json = { workspace = true }
serial_test = { workspace = true }
tempfile = { workspace = true }
tokio = { workspace = true, features = ["test-util"] }
tracing-subscriber = { workspace = true }
58 changes: 54 additions & 4 deletions quickwit/quickwit-common/src/retry.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -142,6 +142,7 @@ impl MockableSleep for TokioSleep {

pub async fn retry_with_mockable_sleep<U, E, Fut>(
retry_params: &RetryParams,
request_name: &'static str,
f: impl Fn() -> Fut,
mockable_sleep: impl MockableSleep,
) -> Result<U, E>
Expand All @@ -167,8 +168,10 @@ where

if num_attempts >= retry_params.max_attempts {
warn!(
request=%request_name,
num_attempts=%num_attempts,
"request failed"
error=?error,
"request failed after exhausting retries"
);
return Err(error);
}
Expand All @@ -177,6 +180,7 @@ where
None => retry_params.compute_delay(num_attempts),
};
debug!(
request=%request_name,
num_attempts=%num_attempts,
delay_ms=%delay.as_millis(),
error=?error,
Expand All @@ -186,17 +190,22 @@ where
}
}

pub async fn retry<U, E, Fut>(retry_params: &RetryParams, f: impl Fn() -> Fut) -> Result<U, E>
pub async fn retry<U, E, Fut>(
request_name: &'static str,
retry_params: &RetryParams,
f: impl Fn() -> Fut,
) -> Result<U, E>
where
Fut: Future<Output = Result<U, E>>,
E: Retryable + Debug + 'static,
{
retry_with_mockable_sleep(retry_params, f, TokioSleep).await
retry_with_mockable_sleep(retry_params, request_name, f, TokioSleep).await

@fulmicoton fulmicoton Jul 16, 2026 •
edited
Loading

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

are there cases where we don't know which method had a problem?

I thought it was mostly:
searcher -> GET
indexer -> PUT

@PSeitz PSeitz Jul 16, 2026

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

for search it should be GET, for indexing is should be PUT, for merge it could be either. But would be good to be sure from the logs

@PSeitz PSeitz Jul 17, 2026

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The log currently just logs request failed, without more context you don't know it's S3

}

#[cfg(test)]
mod tests {
use std::sync::RwLock;
use std::io::Write;
use std::sync::{Arc, Mutex, RwLock};
use std::time::Duration;

use futures::future::ready;
Expand All @@ -220,6 +229,19 @@ mod tests {

struct NoopSleep;

struct TestWriter(Arc<Mutex<Vec<u8>>>);

impl Write for TestWriter {
fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
self.0.lock().unwrap().extend_from_slice(buf);
Ok(buf.len())
}

fn flush(&mut self) -> std::io::Result<()> {
Ok(())
}
}

#[async_trait::async_trait]
impl MockableSleep for NoopSleep {
async fn sleep(&self, _duration: Duration) {
Expand All @@ -236,6 +258,7 @@ mod tests {
max_delay: Duration::from_millis(2),
max_attempts: 30,
},
"test.retry",
|| ready(values_it.write().unwrap().next().unwrap()),
noop_mock,
)
Expand Down Expand Up @@ -284,6 +307,33 @@ mod tests {
assert_eq!(simulate_retries(retry_sequence).await, Ok(()));
}

#[tokio::test(flavor = "current_thread")]
async fn test_retry_failure_log_includes_request_name_and_error() {
let output = Arc::new(Mutex::new(Vec::new()));
let writer_output = output.clone();
let subscriber = tracing_subscriber::fmt()
.with_ansi(false)
.without_time()
.with_writer(move || TestWriter(writer_output.clone()))
.finish();
let _subscriber_guard = tracing::subscriber::set_default(subscriber);

let result: Result<(), Retry<usize>> = retry_with_mockable_sleep(
&RetryParams::no_retries(),
"s3.get_object",
|| ready(Err(Retry::Transient(42))),
NoopSleep,
)
.await;

assert_eq!(result, Err(Retry::Transient(42)));
let logs = String::from_utf8(output.lock().unwrap().clone()).unwrap();
assert!(logs.contains("request failed after exhausting retries"));
assert!(logs.contains("request=s3.get_object"));
assert!(logs.contains("error=Transient(42)"));
assert!(logs.contains("num_attempts=1"));
}

fn test_retry_delay_does_not_overflow_aux(retry_params: RetryParams) {
for i in 1..100 {
let delay = retry_params.compute_delay(i);
Expand Down
18 changes: 9 additions & 9 deletions quickwit/quickwit-indexing/src/source/kinesis/api.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -27,7 +27,7 @@ pub(crate) async fn get_records(
) -> anyhow::Result<GetRecordsOutput> {
// TODO: Return an error other than `anyhow::Error` so that expired shard iterators can be
// handled properly.
let response = aws_retry(retry_params, || async {
let response = aws_retry("kinesis.get_records", retry_params, || async {
kinesis_client
.get_records()
.shard_iterator(shard_iterator.clone())
Expand Down Expand Up @@ -59,7 +59,7 @@ pub(crate) async fn get_shard_iterator(
ShardIteratorType::TrimHorizon
};

let response = aws_retry(retry_params, || async {
let response = aws_retry("kinesis.get_shard_iterator", retry_params, || async {
kinesis_client
.get_shard_iterator()
.stream_name(stream_name)
Expand Down Expand Up @@ -93,7 +93,7 @@ pub(crate) async fn list_shards(
None
};
let limit_per_request = limit_per_request.map(|limit| limit as i32);
let response = aws_retry(retry_params, || async {
let response = aws_retry("kinesis.list_shards", retry_params, || async {
kinesis_client
.list_shards()
.set_stream_name(stream_name.clone())
Expand Down Expand Up @@ -132,7 +132,7 @@ pub(crate) mod tests {
stream_name: &str,
num_shards: usize,
) -> anyhow::Result<()> {
aws_retry(&DEFAULT_RETRY_PARAMS, || async {
aws_retry("kinesis.create_stream", &DEFAULT_RETRY_PARAMS, || async {
kinesis_client
.create_stream()
.stream_name(stream_name)
Expand All @@ -151,7 +151,7 @@ pub(crate) mod tests {
kinesis_client: &KinesisClient,
stream_name: &str,
) -> anyhow::Result<()> {
aws_retry(&DEFAULT_RETRY_PARAMS, || async {
aws_retry("kinesis.delete_stream", &DEFAULT_RETRY_PARAMS, || async {
kinesis_client
.delete_stream()
.stream_name(stream_name.to_string())
Expand All @@ -169,7 +169,7 @@ pub(crate) mod tests {
kinesis_client: &KinesisClient,
stream_name: &str,
) -> anyhow::Result<StreamDescription> {
let response = aws_retry(&DEFAULT_RETRY_PARAMS, || async {
let response = aws_retry("kinesis.describe_stream", &DEFAULT_RETRY_PARAMS, || async {
kinesis_client
.describe_stream()
.stream_name(stream_name.to_string())
Expand All @@ -193,7 +193,7 @@ pub(crate) mod tests {
let mut has_more_streams = true;
let limit_per_request = limit_per_request.map(|limit| limit as i32);
while has_more_streams {
let response = aws_retry(&DEFAULT_RETRY_PARAMS, || async {
let response = aws_retry("kinesis.list_streams", &DEFAULT_RETRY_PARAMS, || async {
kinesis_client
.list_streams()
.set_exclusive_start_stream_name(exclusive_start_stream_name.clone())
Expand All @@ -218,7 +218,7 @@ pub(crate) mod tests {
shard_id: &str,
adjacent_shard_id: &str,
) -> anyhow::Result<()> {
aws_retry(&DEFAULT_RETRY_PARAMS, || async {
aws_retry("kinesis.merge_shards", &DEFAULT_RETRY_PARAMS, || async {
kinesis_client
.merge_shards()
.stream_name(stream_name)
Expand All @@ -240,7 +240,7 @@ pub(crate) mod tests {
shard_id: &str,
starting_hash_key: &str,
) -> anyhow::Result<()> {
aws_retry(&DEFAULT_RETRY_PARAMS, || async {
aws_retry("kinesis.split_shard", &DEFAULT_RETRY_PARAMS, || async {
kinesis_client
.split_shard()
.stream_name(stream_name)
Expand Down
40 changes: 24 additions & 16 deletions quickwit/quickwit-indexing/src/source/queue_sources/sqs_queue.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -67,7 +67,7 @@ impl Queue for SqsQueue {
// state that it starts when the message is returned.
let initial_deadline = Instant::now() + suggested_deadline;
let clamped_max_messages = std::cmp::min(max_messages, 10) as i32;
let receive_output = aws_retry(&self.receive_retries, || async {
let receive_output = aws_retry("sqs.receive_message", &self.receive_retries, || async {
self.sqs_client
.receive_message()
.queue_url(&self.queue_url)
Expand Down Expand Up @@ -133,13 +133,17 @@ impl Queue for SqsQueue {
let mut batch_errors = Vec::new();
let mut message_errors = Vec::new();
for batch in entry_batches {
let res = aws_retry(&self.acknowledge_retries, || {
self.sqs_client
.delete_message_batch()
.queue_url(&self.queue_url)
.set_entries(Some(batch.clone()))
.send()
})
let res = aws_retry(
"sqs.delete_message_batch",
&self.acknowledge_retries,
|| {
self.sqs_client
.delete_message_batch()
.queue_url(&self.queue_url)
.set_entries(Some(batch.clone()))
.send()
},
)
.await;
match res {
Ok(res) => {
Expand Down Expand Up @@ -187,14 +191,18 @@ impl Queue for SqsQueue {
) -> anyhow::Result<Instant> {
let visibility_timeout = std::cmp::min(suggested_deadline.as_secs() as i32, 43200);
let new_deadline = Instant::now() + suggested_deadline;
aws_retry(&self.modify_deadline_retries, || {
self.sqs_client
.change_message_visibility()
.queue_url(&self.queue_url)
.visibility_timeout(visibility_timeout)
.receipt_handle(ack_id)
.send()
})
aws_retry(
"sqs.change_message_visibility",
&self.modify_deadline_retries,
|| {
self.sqs_client
.change_message_visibility()
.queue_url(&self.queue_url)
.visibility_timeout(visibility_timeout)
.receipt_handle(ack_id)
.send()
},
)
.await?;
Ok(new_deadline)
}
Expand Down
8 changes: 4 additions & 4 deletions quickwit/quickwit-storage/src/object_storage/azure_blob_storage.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -215,7 +215,7 @@ impl AzureBlobStorage {
) -> StorageResult<Bytes> {
let name = self.blob_name(path);
let capacity = range_opt.as_ref().map(Range::len).unwrap_or(0);
retry(&self.retry_params, || async {
retry("azure.get", &self.retry_params, || async {
let _timer = HistogramTimer::new(&crate::metrics::OBJECT_STORAGE_GET_OBJECT_DURATION);
let (mut response_stream, _in_flight_guards) = if let Some(range) = range_opt.as_ref() {
let stream = self
Expand Down Expand Up @@ -247,7 +247,7 @@ impl AzureBlobStorage {
crate::metrics::OBJECT_STORAGE_PUT_PARTS.inc();
crate::metrics::OBJECT_STORAGE_UPLOAD_NUM_BYTES.inc_by(payload.len());
let _timer = HistogramTimer::new(&crate::metrics::OBJECT_STORAGE_PUT_OBJECT_DURATION);
retry(&self.retry_params, || async {
retry("azure.put", &self.retry_params, || async {
let data = Bytes::from(payload.read_all().await?.to_vec());
let hash = azure_storage_blobs::prelude::Hash::from(md5::compute(&data[..]).0);
self.container_client
Expand Down Expand Up @@ -284,7 +284,7 @@ impl AzureBlobStorage {
async move {
let _timer =
HistogramTimer::new(&crate::metrics::OBJECT_STORAGE_UPLOAD_PART_DURATION);
retry(&self.retry_params, || async {
retry("azure.put", &self.retry_params, || async {
// zero pad block ids to make them sortable as strings
let block_id = format!("block:{:05}", num);
let (data, hash_digest) =
Expand Down Expand Up @@ -469,7 +469,7 @@ impl Storage for AzureBlobStorage {
path: &Path,
range: Range<usize>,
) -> StorageResult<Box<dyn AsyncRead + Send + Unpin>> {
retry(&self.retry_params, || async {
retry("azure.get", &self.retry_params, || async {
let range = range.clone();
let name = self.blob_name(path);
let page_stream = self
Expand Down
Loading
Loading