use crate::common;
use crate::common::inbox::{NoopHandler, message};
use std::fmt::Write as _;
use std::sync::{Arc, Mutex};
use reliar_core::MessageId;
use reliar_inbox::{InboxDeadLetters, InboxScope, InboxStore};
use reliar_store_postgres::{PostgresInboxSettings, PostgresInboxStore};
use tracing::field::{Field, Visit};
use tracing_subscriber::layer::{Context, SubscriberExt};
const SECRET_ERROR_MARKER: &str = "RELIAR_LAST_ERROR_MUST_NEVER_APPEAR_IN_A_SPAN";
#[derive(Debug)]
struct SecretError;
impl std::fmt::Display for SecretError {
fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
write!(f, "{SECRET_ERROR_MARKER}")
}
}
impl std::error::Error for SecretError {}
struct TranscriptVisitor<'a>(&'a mut String);
impl Visit for TranscriptVisitor<'_> {
fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) {
let _ = write!(self.0, "{}={value:?} ", field.name());
}
}
#[derive(Default, Clone)]
struct Transcript(Arc<Mutex<String>>);
impl Transcript {
fn text(&self) -> String {
self.0.lock().unwrap().clone()
}
}
struct Recorder(Transcript);
impl<S> tracing_subscriber::Layer<S> for Recorder
where
S: tracing::Subscriber + for<'lookup> tracing_subscriber::registry::LookupSpan<'lookup>,
{
fn on_new_span(
&self,
attrs: &tracing::span::Attributes<'_>,
_id: &tracing::span::Id,
_ctx: Context<'_, S>,
) {
let mut line = format!("SPAN_OPEN {}{{ ", attrs.metadata().name());
attrs.record(&mut TranscriptVisitor(&mut line));
line.push_str("}\n");
self.0.0.lock().unwrap().push_str(&line);
}
fn on_record(
&self,
_id: &tracing::span::Id,
values: &tracing::span::Record<'_>,
_ctx: Context<'_, S>,
) {
let mut line = "SPAN_RECORD ".to_string();
values.record(&mut TranscriptVisitor(&mut line));
line.push('\n');
self.0.0.lock().unwrap().push_str(&line);
}
}
fn install_recorder() -> (Transcript, tracing::subscriber::DefaultGuard) {
let transcript = Transcript::default();
let subscriber = tracing_subscriber::registry().with(Recorder(transcript.clone()));
let guard = common::install_recording_subscriber(subscriber);
(transcript, guard)
}
async fn claim_span_carries_entry_and_dead_outcome_fields() {
let pool = common::fresh_db().await;
let settings = PostgresInboxSettings::default().max_attempts(1);
let store = PostgresInboxStore::with_settings(pool.clone(), settings).unwrap();
let scope = InboxScope::new("orders-projection").unwrap();
let id = MessageId::new();
let failure = store.fail(&scope, message(id), &SecretError).await.unwrap();
let dead_record_id = match failure {
reliar_inbox::InboxFailure::Dead { id, .. } => id,
other => panic!("expected Dead, got {other:?}"),
};
let (transcript, _guard) = install_recorder();
let mut tx = pool.begin().await.unwrap();
let claim = store.claim(&mut tx, &scope, message(id)).await.unwrap();
tx.rollback().await.unwrap();
assert!(matches!(claim, reliar_inbox::InboxClaim::Dead { .. }));
let text = transcript.text();
assert_eq!(
text.matches("SPAN_OPEN reliar.inbox.claim{").count(),
1,
"expected exactly one claim span:\n{text}"
);
assert!(text.contains(&format!("message.id={id}")), "{text}");
assert!(text.contains("message.type=orders.created"), "{text}");
assert!(text.contains("inbox.scope=orders-projection"), "{text}");
assert!(text.contains("inbox.outcome=\"dead\""), "{text}");
assert!(
text.contains(&format!("inbox.record_id={dead_record_id}")),
"expected the dead row's id on the claim span:\n{text}"
);
assert!(
!text.contains(SECRET_ERROR_MARKER),
"last_error must never reach a span:\n{text}"
);
}
async fn claim_span_records_claimed_outcome_with_singular_attempt() {
let pool = common::fresh_db().await;
let store =
PostgresInboxStore::with_settings(pool.clone(), PostgresInboxSettings::default()).unwrap();
let scope = InboxScope::new("orders-projection").unwrap();
let id = MessageId::new();
let (transcript, _guard) = install_recorder();
let mut tx = pool.begin().await.unwrap();
let claim = store.claim(&mut tx, &scope, message(id)).await.unwrap();
tx.rollback().await.unwrap();
assert_eq!(claim, reliar_inbox::InboxClaim::Claimed { attempt: 1 });
let text = transcript.text();
assert!(text.contains("inbox.outcome=\"claimed\""), "{text}");
assert!(
text.contains("inbox.attempt=1"),
"expected the singular inbox.attempt field:\n{text}"
);
assert!(
!text.contains("inbox.attempts=1") && !text.contains("inbox.attempts=\"1\""),
"inbox.attempts (plural) must not be recorded on a claimed outcome:\n{text}"
);
}
async fn claim_span_records_already_completed_outcome() {
let pool = common::fresh_db().await;
let store =
PostgresInboxStore::with_settings(pool.clone(), PostgresInboxSettings::default()).unwrap();
let scope = InboxScope::new("orders-projection").unwrap();
let id = MessageId::new();
let mut tx = pool.begin().await.unwrap();
store.claim(&mut tx, &scope, message(id)).await.unwrap();
store.complete(&mut tx, &scope, id).await.unwrap();
tx.commit().await.unwrap();
let (transcript, _guard) = install_recorder();
let mut tx = pool.begin().await.unwrap();
let claim = store.claim(&mut tx, &scope, message(id)).await.unwrap();
tx.rollback().await.unwrap();
assert!(matches!(
claim,
reliar_inbox::InboxClaim::AlreadyCompleted { .. }
));
let text = transcript.text();
assert!(
text.contains("inbox.outcome=\"already_completed\""),
"{text}"
);
}
async fn claim_span_records_in_progress_outcome() {
let pool = common::fresh_db().await;
let store =
PostgresInboxStore::with_settings(pool.clone(), PostgresInboxSettings::default()).unwrap();
let scope = InboxScope::new("orders-projection").unwrap();
let id = MessageId::new();
let mut tx_a = pool.begin().await.unwrap();
store.claim(&mut tx_a, &scope, message(id)).await.unwrap();
let (transcript, _guard) = install_recorder();
let mut tx_b = pool.begin().await.unwrap();
let claim_b = tokio::time::timeout(
std::time::Duration::from_millis(500),
store.claim(&mut tx_b, &scope, message(id)),
)
.await
.expect("claim must return within 500ms instead of blocking on the advisory lock")
.unwrap();
tx_b.rollback().await.unwrap();
tx_a.rollback().await.unwrap();
assert_eq!(claim_b, reliar_inbox::InboxClaim::InProgress);
let text = transcript.text();
assert!(text.contains("inbox.outcome=\"in_progress\""), "{text}");
}
async fn fail_span_carries_entry_and_dead_outcome_fields() {
let pool = common::fresh_db().await;
let settings = PostgresInboxSettings::default().max_attempts(1);
let store = PostgresInboxStore::with_settings(pool.clone(), settings).unwrap();
let scope = InboxScope::new("orders-projection").unwrap();
let id = MessageId::new();
let (transcript, _guard) = install_recorder();
let failure = store.fail(&scope, message(id), &SecretError).await.unwrap();
let dead_record_id = match failure {
reliar_inbox::InboxFailure::Dead { id, .. } => id,
other => panic!("expected Dead at max_attempts(1), got {other:?}"),
};
let text = transcript.text();
assert_eq!(
text.matches("SPAN_OPEN reliar.inbox.fail{").count(),
1,
"expected exactly one fail span:\n{text}"
);
assert!(text.contains(&format!("message.id={id}")), "{text}");
assert!(text.contains("message.type=orders.created"), "{text}");
assert!(text.contains("inbox.outcome=\"dead\""), "{text}");
assert!(text.contains("inbox.attempts=1"), "{text}");
assert!(
text.contains(&format!("inbox.record_id={dead_record_id}")),
"expected the dead row's id on the fail span:\n{text}"
);
assert!(
!text.contains(SECRET_ERROR_MARKER),
"last_error must never reach a span, even though it caused the transition:\n{text}"
);
}
async fn fail_span_records_recorded_outcome() {
let pool = common::fresh_db().await;
let settings = PostgresInboxSettings::default().max_attempts(2);
let store = PostgresInboxStore::with_settings(pool.clone(), settings).unwrap();
let scope = InboxScope::new("orders-projection").unwrap();
let id = MessageId::new();
let (transcript, _guard) = install_recorder();
let failure = store.fail(&scope, message(id), &SecretError).await.unwrap();
assert_eq!(
failure,
reliar_inbox::InboxFailure::Recorded { attempts: 1 }
);
let text = transcript.text();
assert!(text.contains("inbox.outcome=\"recorded\""), "{text}");
assert!(text.contains("inbox.attempts=1"), "{text}");
assert!(
!text.contains("inbox.record_id="),
"inbox.record_id must not be recorded on a non-dead outcome:\n{text}"
);
}
async fn fail_span_records_already_completed_outcome() {
let pool = common::fresh_db().await;
let store =
PostgresInboxStore::with_settings(pool.clone(), PostgresInboxSettings::default()).unwrap();
let scope = InboxScope::new("orders-projection").unwrap();
let id = MessageId::new();
let mut tx = pool.begin().await.unwrap();
store.claim(&mut tx, &scope, message(id)).await.unwrap();
store.complete(&mut tx, &scope, id).await.unwrap();
tx.commit().await.unwrap();
let (transcript, _guard) = install_recorder();
let failure = store.fail(&scope, message(id), &SecretError).await.unwrap();
assert_eq!(failure, reliar_inbox::InboxFailure::AlreadyCompleted);
let text = transcript.text();
assert!(
text.contains("inbox.outcome=\"already_completed\""),
"{text}"
);
assert!(
!text.contains("inbox.attempts=") && !text.contains("inbox.record_id="),
"neither attempts nor record_id is recorded on already_completed:\n{text}"
);
}
async fn complete_span_carries_entry_fields_only() {
let pool = common::fresh_db().await;
let store =
PostgresInboxStore::with_settings(pool.clone(), PostgresInboxSettings::default()).unwrap();
let scope = InboxScope::new("orders-projection").unwrap();
let id = MessageId::new();
let mut tx = pool.begin().await.unwrap();
store.claim(&mut tx, &scope, message(id)).await.unwrap();
let (transcript, _guard) = install_recorder();
store.complete(&mut tx, &scope, id).await.unwrap();
tx.commit().await.unwrap();
let text = transcript.text();
assert_eq!(
text.matches("SPAN_OPEN reliar.inbox.complete{").count(),
1,
"expected exactly one complete span:\n{text}"
);
assert!(text.contains(&format!("message.id={id}")), "{text}");
assert!(text.contains("inbox.scope=orders-projection"), "{text}");
}
async fn purge_span_carries_exit_counts() {
let pool = common::fresh_db().await;
let store =
PostgresInboxStore::with_settings(pool.clone(), PostgresInboxSettings::default()).unwrap();
let scope = InboxScope::new("orders-projection").unwrap();
let id = MessageId::new();
let mut tx = pool.begin().await.unwrap();
store.claim(&mut tx, &scope, message(id)).await.unwrap();
store.complete(&mut tx, &scope, id).await.unwrap();
tx.commit().await.unwrap();
let (transcript, _guard) = install_recorder();
let report = store
.purge(
reliar_inbox::InboxPurgeRequest::default()
.completed_retention(Some(std::time::Duration::ZERO)),
)
.await
.unwrap();
assert_eq!(report.completed_deleted, 1);
let text = transcript.text();
assert_eq!(
text.matches("SPAN_OPEN reliar.inbox.purge{").count(),
1,
"expected exactly one purge span:\n{text}"
);
assert!(text.contains("inbox.completed_deleted=1"), "{text}");
assert!(text.contains("inbox.incomplete_deleted=0"), "{text}");
assert!(text.contains("inbox.dead_deleted=0"), "{text}");
}
async fn dead_letter_spans_carry_entry_and_exit_fields() {
let pool = common::fresh_db().await;
let settings = PostgresInboxSettings::default().max_attempts(1);
let store = PostgresInboxStore::with_settings(pool.clone(), settings).unwrap();
let scope = InboxScope::new("orders-projection").unwrap();
let id = MessageId::new();
store.fail(&scope, message(id), &SecretError).await.unwrap();
let record = store.find(&scope, id).await.unwrap().unwrap();
let (transcript, _guard) = install_recorder();
let page = store
.list_dead(
reliar_inbox::InboxDeadQuery::default()
.scope(scope.clone())
.limit(u32::MAX),
)
.await
.unwrap();
assert_eq!(page.len(), 1);
let affected = store.retry_dead(&[record.id]).await.unwrap();
assert_eq!(affected, 1);
let text = transcript.text();
assert_eq!(
text.matches("SPAN_OPEN reliar.inbox.list_dead{").count(),
1,
"expected exactly one list_dead span:\n{text}"
);
assert!(text.contains("inbox.scope=\"orders-projection\""), "{text}");
assert!(text.contains("inbox.limit=1000"), "{text}");
assert!(text.contains("inbox.returned=1"), "{text}");
assert_eq!(
text.matches("SPAN_OPEN reliar.inbox.retry_dead{").count(),
1,
"expected exactly one retry_dead span:\n{text}"
);
assert!(text.contains("inbox.requested=1"), "{text}");
assert!(text.contains("inbox.affected=1"), "{text}");
assert!(
!text.contains(SECRET_ERROR_MARKER),
"last_error must never reach a span:\n{text}"
);
}
async fn purge_dead_span_carries_entry_and_exit_fields() {
let pool = common::fresh_db().await;
let settings = PostgresInboxSettings::default().max_attempts(1);
let store = PostgresInboxStore::with_settings(pool.clone(), settings).unwrap();
let scope = InboxScope::new("orders-projection").unwrap();
let id = MessageId::new();
store.fail(&scope, message(id), &SecretError).await.unwrap();
let record = store.find(&scope, id).await.unwrap().unwrap();
let (transcript, _guard) = install_recorder();
let affected = store.purge_dead(&[record.id]).await.unwrap();
assert_eq!(affected, 1);
let text = transcript.text();
assert_eq!(
text.matches("SPAN_OPEN reliar.inbox.purge_dead{").count(),
1,
"expected exactly one purge_dead span:\n{text}"
);
assert!(text.contains("inbox.requested=1"), "{text}");
assert!(text.contains("inbox.affected=1"), "{text}");
assert!(
!text.contains(SECRET_ERROR_MARKER),
"last_error must never reach a span:\n{text}"
);
}
async fn process_span_emits_one_span_with_processed_outcome() {
let pool = common::fresh_db().await;
let store =
PostgresInboxStore::with_settings(pool.clone(), PostgresInboxSettings::default()).unwrap();
let scope = InboxScope::new("orders-projection").unwrap();
let id = MessageId::new();
let (transcript, _guard) = install_recorder();
let mut tx = pool.begin().await.unwrap();
let outcome = store
.process(&mut tx, &scope, message(id), &NoopHandler)
.await
.unwrap();
tx.commit().await.unwrap();
assert_eq!(outcome, reliar_inbox::InboxOutcome::Processed(()));
let text = transcript.text();
assert_eq!(
text.matches("SPAN_OPEN reliar.inbox.process{").count(),
1,
"expected exactly one process span:\n{text}"
);
assert!(text.contains(&format!("message.id={id}")), "{text}");
assert!(text.contains("message.type=orders.created"), "{text}");
assert!(text.contains("inbox.scope=orders-projection"), "{text}");
assert!(text.contains("inbox.outcome=\"processed\""), "{text}");
}
async fn process_span_records_already_completed_outcome() {
let pool = common::fresh_db().await;
let store =
PostgresInboxStore::with_settings(pool.clone(), PostgresInboxSettings::default()).unwrap();
let scope = InboxScope::new("orders-projection").unwrap();
let id = MessageId::new();
let mut tx = pool.begin().await.unwrap();
store
.process(&mut tx, &scope, message(id), &NoopHandler)
.await
.unwrap();
tx.commit().await.unwrap();
let (transcript, _guard) = install_recorder();
let mut tx2 = pool.begin().await.unwrap();
let outcome = store
.process(&mut tx2, &scope, message(id), &NoopHandler)
.await
.unwrap();
tx2.rollback().await.unwrap();
assert!(matches!(
outcome,
reliar_inbox::InboxOutcome::AlreadyCompleted { .. }
));
let text = transcript.text();
assert!(
text.contains("inbox.outcome=\"already_completed\""),
"{text}"
);
}
async fn process_span_records_in_progress_outcome() {
let pool = common::fresh_db().await;
let store =
PostgresInboxStore::with_settings(pool.clone(), PostgresInboxSettings::default()).unwrap();
let scope = InboxScope::new("orders-projection").unwrap();
let id = MessageId::new();
let mut tx_a = pool.begin().await.unwrap();
store.claim(&mut tx_a, &scope, message(id)).await.unwrap();
let (transcript, _guard) = install_recorder();
let mut tx_b = pool.begin().await.unwrap();
let outcome = tokio::time::timeout(
std::time::Duration::from_millis(500),
store.process(&mut tx_b, &scope, message(id), &NoopHandler),
)
.await
.expect("process must return within 500ms instead of blocking on the advisory lock")
.unwrap();
tx_b.rollback().await.unwrap();
tx_a.rollback().await.unwrap();
assert_eq!(outcome, reliar_inbox::InboxOutcome::InProgress);
let text = transcript.text();
assert!(text.contains("inbox.outcome=\"in_progress\""), "{text}");
}
async fn process_span_records_dead_outcome_and_record_id() {
let pool = common::fresh_db().await;
let settings = PostgresInboxSettings::default().max_attempts(1);
let store = PostgresInboxStore::with_settings(pool.clone(), settings).unwrap();
let scope = InboxScope::new("orders-projection").unwrap();
let id = MessageId::new();
let failure = store.fail(&scope, message(id), &SecretError).await.unwrap();
let dead_record_id = match failure {
reliar_inbox::InboxFailure::Dead { id, .. } => id,
other => panic!("expected Dead, got {other:?}"),
};
let (transcript, _guard) = install_recorder();
let mut tx = pool.begin().await.unwrap();
let outcome = store
.process(&mut tx, &scope, message(id), &NoopHandler)
.await
.unwrap();
tx.rollback().await.unwrap();
assert!(matches!(outcome, reliar_inbox::InboxOutcome::Dead { .. }));
let text = transcript.text();
assert!(text.contains("inbox.outcome=\"dead\""), "{text}");
assert!(
text.contains(&format!("inbox.record_id={dead_record_id}")),
"expected the dead row's id on the process span:\n{text}"
);
assert!(
!text.contains(SECRET_ERROR_MARKER),
"last_error must never reach a span:\n{text}"
);
}
#[allow(
clippy::too_many_lines,
reason = "one Trial per scenario function above; splitting the list would scatter it with no reuse"
)]
pub(crate) fn recorder_trials(rt: &'static tokio::runtime::Runtime) -> Vec<libtest_mimic::Trial> {
vec![
libtest_mimic::Trial::test(
"inbox_spans::claim_span_carries_entry_and_dead_outcome_fields",
move || {
rt.block_on(claim_span_carries_entry_and_dead_outcome_fields());
Ok(())
},
),
libtest_mimic::Trial::test(
"inbox_spans::claim_span_records_claimed_outcome_with_singular_attempt",
move || {
rt.block_on(claim_span_records_claimed_outcome_with_singular_attempt());
Ok(())
},
),
libtest_mimic::Trial::test(
"inbox_spans::claim_span_records_already_completed_outcome",
move || {
rt.block_on(claim_span_records_already_completed_outcome());
Ok(())
},
),
libtest_mimic::Trial::test(
"inbox_spans::claim_span_records_in_progress_outcome",
move || {
rt.block_on(claim_span_records_in_progress_outcome());
Ok(())
},
),
libtest_mimic::Trial::test(
"inbox_spans::fail_span_carries_entry_and_dead_outcome_fields",
move || {
rt.block_on(fail_span_carries_entry_and_dead_outcome_fields());
Ok(())
},
),
libtest_mimic::Trial::test(
"inbox_spans::fail_span_records_recorded_outcome",
move || {
rt.block_on(fail_span_records_recorded_outcome());
Ok(())
},
),
libtest_mimic::Trial::test(
"inbox_spans::fail_span_records_already_completed_outcome",
move || {
rt.block_on(fail_span_records_already_completed_outcome());
Ok(())
},
),
libtest_mimic::Trial::test(
"inbox_spans::complete_span_carries_entry_fields_only",
move || {
rt.block_on(complete_span_carries_entry_fields_only());
Ok(())
},
),
libtest_mimic::Trial::test("inbox_spans::purge_span_carries_exit_counts", move || {
rt.block_on(purge_span_carries_exit_counts());
Ok(())
}),
libtest_mimic::Trial::test(
"inbox_spans::dead_letter_spans_carry_entry_and_exit_fields",
move || {
rt.block_on(dead_letter_spans_carry_entry_and_exit_fields());
Ok(())
},
),
libtest_mimic::Trial::test(
"inbox_spans::purge_dead_span_carries_entry_and_exit_fields",
move || {
rt.block_on(purge_dead_span_carries_entry_and_exit_fields());
Ok(())
},
),
libtest_mimic::Trial::test(
"inbox_spans::process_span_emits_one_span_with_processed_outcome",
move || {
rt.block_on(process_span_emits_one_span_with_processed_outcome());
Ok(())
},
),
libtest_mimic::Trial::test(
"inbox_spans::process_span_records_already_completed_outcome",
move || {
rt.block_on(process_span_records_already_completed_outcome());
Ok(())
},
),
libtest_mimic::Trial::test(
"inbox_spans::process_span_records_in_progress_outcome",
move || {
rt.block_on(process_span_records_in_progress_outcome());
Ok(())
},
),
libtest_mimic::Trial::test(
"inbox_spans::process_span_records_dead_outcome_and_record_id",
move || {
rt.block_on(process_span_records_dead_outcome_and_record_id());
Ok(())
},
),
]
}