diag: instrument jmap_push to log what Stalwart actually sends
The P0 push-delivery problem is stuck on an unresolvable contradiction:
push:subscription:b is confirmed in Redis (TTL=-1) and a manual curl
{"pushSubscriptionId":"b"} returns 204, yet Stalwart's real event push
gets 401 from the same dedup_exists check.
Reconstructing the timeline from email-arrival timestamps is unreliable.
Instead, add diagnostic logging so the next real push produces evidence:
- Entry log: subscription_id, account_id, email_id, has_verification_code
- dedup_exists outcome: which key was queried and whether it hit
- verify-branch outcome: when a verification request rewrites the key
- enqueue success: when an event is accepted for delivery
A single request_id is minted at entry and threaded through push_401 so
the request_id in Stalwart's 401 response matches the entry/branch logs
(previously error_response minted a fresh random id per call, making
correlation impossible).
No delivery logic, TTL, key-writing, limiter ordering, or routes changed.
All info! lines are temporary diagnostics, removed after root cause found.
GATE-P0: 106 passed / 0 failed / 4 ignored
GATE-DOCS: 6/6 PASS
Co-Authored-By: Claude Code <noreply@anthropic.com>
This commit is contained in:
parent
3f8fbb7bdc
commit
ffa53b5bbb
|
|
@ -1293,9 +1293,21 @@ async fn jmap_push(State(app): State<AppState>, body: Bytes) -> Response {
|
||||||
let Ok(push) = serde_json::from_slice::<JmapPush>(&body) else {
|
let Ok(push) = serde_json::from_slice::<JmapPush>(&body) else {
|
||||||
return error_response(StatusCode::BAD_REQUEST, "invalid_request", false);
|
return error_response(StatusCode::BAD_REQUEST, "invalid_request", false);
|
||||||
};
|
};
|
||||||
|
// Diagnostic request_id minted once here so every push 401 response and
|
||||||
|
// branch log line in this handler carries the same correlation id as the
|
||||||
|
// entry log. The verification_code value is never logged (AGENTS.md §3.2).
|
||||||
|
let request_id = reconcile_lock_owner();
|
||||||
|
tracing::info!(
|
||||||
|
request_id = %request_id,
|
||||||
|
subscription_id = ?push.subscription_id,
|
||||||
|
account_id = ?push.account_id,
|
||||||
|
email_id = ?push.email_id,
|
||||||
|
has_verification_code = push.verification_code.is_some(),
|
||||||
|
"jmap_push request received"
|
||||||
|
);
|
||||||
// subscription_id is required on every request (RFC 8620 §7.2/§7.3).
|
// subscription_id is required on every request (RFC 8620 §7.2/§7.3).
|
||||||
let Some(subscription) = push.subscription_id.as_deref() else {
|
let Some(subscription) = push.subscription_id.as_deref() else {
|
||||||
return error_response(StatusCode::UNAUTHORIZED, "unauthorized", false);
|
return push_401(request_id);
|
||||||
};
|
};
|
||||||
if let Some(code) = push.verification_code.as_deref() {
|
if let Some(code) = push.verification_code.as_deref() {
|
||||||
// Verification request (RFC 8620 §7.2): carries verificationCode.
|
// Verification request (RFC 8620 §7.2): carries verificationCode.
|
||||||
|
|
@ -1352,17 +1364,33 @@ async fn jmap_push(State(app): State<AppState>, body: Bytes) -> Response {
|
||||||
"push verify API call failed; continuing (RFC 8620 §7.2 verification is via callback response)");
|
"push verify API call failed; continuing (RFC 8620 §7.2 verification is via callback response)");
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
// Diagnostic: a verification request rewrites push:subscription:{id}.
|
||||||
|
// If a concurrent event push 401s, this line tells us a verification
|
||||||
|
// raced it (key rewritten mid-window). The code value is not logged.
|
||||||
|
tracing::info!(
|
||||||
|
request_id = %request_id,
|
||||||
|
subscription = %subscription,
|
||||||
|
"jmap_push verification branch wrote key"
|
||||||
|
);
|
||||||
}
|
}
|
||||||
} else {
|
} else {
|
||||||
// Event push (RFC 8620 §7.3): no verificationCode; the subscription
|
// Event push (RFC 8620 §7.3): no verificationCode; the subscription
|
||||||
// must have been verified during the initial handshake.
|
// must have been verified during the initial handshake.
|
||||||
if !matches!(
|
let push_key = format!("push:subscription:{subscription}");
|
||||||
app.state
|
let exists = matches!(app.state.dedup_exists(&push_key).await, Ok(true));
|
||||||
.dedup_exists(&format!("push:subscription:{subscription}"))
|
// Diagnostic: this is the line that decides the 401. If subscription is
|
||||||
.await,
|
// "b" and exists is false here while a CLI probe shows the key present,
|
||||||
Ok(true)
|
// the key was deleted/rewritten in the window (see the verify-branch
|
||||||
) {
|
// log). If subscription is not "b", Stalwart sent a different id than
|
||||||
return error_response(StatusCode::UNAUTHORIZED, "unauthorized", false);
|
// our stored push:subscription:id pointer — the contradiction's root.
|
||||||
|
tracing::info!(
|
||||||
|
request_id = %request_id,
|
||||||
|
key = %push_key,
|
||||||
|
exists,
|
||||||
|
"jmap_push event dedup_exists check"
|
||||||
|
);
|
||||||
|
if !exists {
|
||||||
|
return push_401(request_id);
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
if push.account_id.is_none() && push.email_id.is_none() {
|
if push.account_id.is_none() && push.email_id.is_none() {
|
||||||
|
|
@ -1388,6 +1416,15 @@ async fn jmap_push(State(app): State<AppState>, body: Bytes) -> Response {
|
||||||
.await
|
.await
|
||||||
{
|
{
|
||||||
Ok(message_id) => {
|
Ok(message_id) => {
|
||||||
|
// Diagnostic: the event push was accepted and queued for
|
||||||
|
// delivery. If Telegram still doesn't arrive after this line,
|
||||||
|
// the failure is downstream (worker.process / Telegram), not
|
||||||
|
// in the push 401 path.
|
||||||
|
tracing::info!(
|
||||||
|
request_id = %request_id,
|
||||||
|
%message_id,
|
||||||
|
"jmap_push event enqueued"
|
||||||
|
);
|
||||||
// Claim in-flight lease so the cron-triggered worker() drain
|
// Claim in-flight lease so the cron-triggered worker() drain
|
||||||
// skips this message while we process it immediately.
|
// skips this message while we process it immediately.
|
||||||
let inflight_key = format!("delivery:inflight:stalwart:jmap:{message_id}");
|
let inflight_key = format!("delivery:inflight:stalwart:jmap:{message_id}");
|
||||||
|
|
@ -1863,6 +1900,19 @@ fn error_response_with_id(status: StatusCode, code: &'static str, request_id: St
|
||||||
.into_response()
|
.into_response()
|
||||||
}
|
}
|
||||||
|
|
||||||
|
// 401 for the push inbound path. Identical body to `error_response` with
|
||||||
|
// `retry=false`, but the request_id is the one minted at jmap_push entry so
|
||||||
|
// Stalwart's logged request_id matches the diagnostic entry/branch logs. No
|
||||||
|
// Retry-After header (401 is not retryable). Diagnostic instrumentation: this
|
||||||
|
// helper exists only so the push 401 sites stay correlated to the entry log.
|
||||||
|
fn push_401(request_id: String) -> Response {
|
||||||
|
(
|
||||||
|
StatusCode::UNAUTHORIZED,
|
||||||
|
axum::Json(serde_json::json!({"error": "unauthorized", "request_id": request_id})),
|
||||||
|
)
|
||||||
|
.into_response()
|
||||||
|
}
|
||||||
|
|
||||||
#[derive(serde::Deserialize)]
|
#[derive(serde::Deserialize)]
|
||||||
struct TelegramUpdate {
|
struct TelegramUpdate {
|
||||||
update_id: u64,
|
update_id: u64,
|
||||||
|
|
|
||||||
Loading…
Reference in New Issue