Skip to content

Commit ccba344

Browse files
authored
feat(protocol): drop the telemetry queue when the portal toggle is off (#437)
* feat(protocol): drop the telemetry queue when the portal toggle is off The uploader treated every 401 and 403 alike: keep the refused batch, halt until the next enable_telemetry, keep queuing. Right for a bad key, which the developer fixes and re-enables through. Wrong for the application's telemetry toggle in the developer portal: once it came back on, a relaunch resent up to six days of the off period, the backfill the toggle promises not to make. The ingest now answers that refusal with the error code telemetry_disabled. On a 403 carrying it the uploader drops the refused batch and everything queued behind it, halts, and reports it to the pipe, which discards the ring at every later cycle instead of cutting batches until the next enable_telemetry. The flag is read on the cycle, never on the emit path. Every other 401 or 403, and a 403 from an ingest that predates the code, keeps the queue as before. * test(protocol): make the toggle scenario prove its store was adopted The telemetry_disabled scenario ends by building a fresh pipe over the same sealed store and asserting that nothing is resent. That is a negative assertion, and it passes just as happily when the fresh pipe never adopted the store and quietly ran in memory. An empty in-memory queue has nothing to backfill either. So the day someone breaks release-then-adopt, this test keeps saying "no backfill" for entirely the wrong reason. Assert the fresh pipe is durable before trusting the count. The bad-key sibling never needed this, because its assertion is positive: the refused batch shows up again, which it can only do from the store. * refactor(protocol): match the ingest error code without cloning it Classifying a 403 parsed the body, cloned the error code into a fresh String, and compared that against a constant. The String existed only to be compared and thrown away. Ask the question directly instead: does the body name this code. Same parse, and junk or a missing field still lands on the ordinary halt. It only runs on a 403, so this is tidiness, not a hot-path win, and I won't pretend otherwise. * docs: stop promising the telemetry queue waits for re-enable The telemetry_disabled change updated the uploader's answer table and added an errors row, and left three other places describing the old world. The stats table listed four sources for dropped, the privacy page named three things that clear the queue, and the threat model said persisted batches are kept for a later enable. All three are wrong for an app whose portal toggle is off. Say it in each place. dropped also counts what was queued or collected after the ingest reported the toggle off, and the queue is cleared when that happens rather than held for the toggle coming back. The privacy page is the one integrators quote to their users, so it is not the place to be out of date. While at it, document the one sharp edge. The ingest caches a rejection for 30 seconds, so a launch just after the toggle is turned back on can still be refused, and that process then keeps nothing until its next enableTelemetry. Before this change the next launch would have backfilled it. Now it doesn't, which is the whole point, but a developer checking the dashboard right after flipping the switch deserves to know why that launch went missing. * fix(protocol): drop a queue adopted after the telemetry_disabled halt The telemetry_disabled halt promised that nothing from the off period is left on disk for a later pipe to resend. It kept that promise only for a pipe that was already durable when the refusal arrived. It turns out the engine never starts one that way. enable_telemetry starts every pipe in memory and hands the protocol-state store over for the worker to adopt, which on the mobile bindings means after initialize_mls. A flush that reaches the ingest first takes the halt with an empty in-memory queue. Adoption then loads whatever an earlier launch persisted, and nothing touches it again: the cycle has stopped cutting batches, and the halted uploader returns before it reads the queue. A re-enable that waits for the old pipe to let go of the queue gets there the same way. So the next enable_telemetry, with the toggle back on, sends the off period. Which is exactly the backfill this change exists to prevent. Sweep the store at adoption when the flag is set. Adoption is the one way a batch can still enter the store after the refusal, so the check belongs there rather than in the uploader, which both a battery-deferred cycle and the worker's adoption-only wake skip. The swept batches count as dropped, in events, like the rest of the halt. The new scenario runs three launches over one store and fails with the sweep removed. * test(protocol): pin the telemetry_disabled drop on the final flush stop() runs the same cycle as any other flush, so a toggle-off refusal on the final flush already drops the queue. Nothing pinned it, though, and a batch left on disk there would be resent by the next enable_telemetry like any other. Pin it: a sealed pipe whose only send is the final flush, then a fresh pipe over the same store with nothing to resend. * docs(bindings): list the toggle-off discard among telemetry drops The telemetry_disabled change taught the Rust doc and docs/telemetry.md that dropped also counts what the pipe discards once the ingest reports the portal toggle off. The same sentence is hand-copied into four more places: the UDL, the TypeScript type and method docs, and the Python wrapper. All four still listed the old sources. Say it in all four. The UDL edit is a plain comment, which uniffi-bindgen ignores: regenerating all three bindings from it changes no generated file, so there is nothing to regenerate here.
1 parent 5fdc3e4 commit ccba344

13 files changed

Lines changed: 392 additions & 20 deletions

File tree

CHANGELOG.md

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -132,6 +132,15 @@ the client's answers were wrong on a device rather than merely different:
132132
through, and the queue now waits for a good one. `telemetryStats().dropped`
133133
counts events and only events, so a queued batch that cannot be opened on
134134
load is warned about rather than added to it in a different unit.
135+
- **A 403 `telemetry_disabled` drops the queue.** The ingest answers with that
136+
`error` code, rather than the `forbidden` a bad key draws, while the
137+
application's telemetry toggle is off in the developer portal. The pipe
138+
drops the refused batch and everything queued behind it, discards what it
139+
collects afterwards instead of queuing it, and sends nothing more until the
140+
next `enableTelemetry`, so a toggled-off stretch stays a gap on the
141+
dashboard rather than filling in from the device's queue once the toggle
142+
comes back. Every other 401 or 403 keeps its queue as above, and so does a
143+
403 from an ingest that predates the code, which answers `forbidden`.
135144
- **Telemetry session boundaries follow the process on Android**, through the
136145
set of started activities rather than `onHostPause`. `onHostPause` is
137146
`Activity.onPause`, which fires for a runtime permission dialog (including

bindings/python/offline_protocol_sdk/protocol_manager.py

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -527,8 +527,10 @@ def telemetry_stats(self) -> TelemetryStats | None:
527527
528528
``accepted_events`` is what the ingest reported accepting, which is
529529
what an invoice is reconciled against; ``dropped`` counts events
530-
lost to the ring buffer, the queue caps, the six-day expiry or a
531-
permanent rejection; ``last_error`` is the most recent send failure.
530+
lost to the ring buffer, the queue caps, the six-day expiry, a
531+
permanent rejection, or everything queued or collected after the
532+
ingest reported the application's telemetry toggle off;
533+
``last_error`` is the most recent send failure.
532534
"""
533535
return self._protocol.telemetry_stats()
534536

bindings/react-native/src/index.ts

Lines changed: 5 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -1955,10 +1955,11 @@ export class OfflineProtocol {
19551955
* The telemetry pipe's counters, or `null` while telemetry is not
19561956
* enabled. `acceptedEvents` is what the ingest reported accepting, which
19571957
* is what an invoice is reconciled against; `dropped` counts events lost
1958-
* to the ring buffer, the durable queue's caps, the six-day expiry, or a
1959-
* permanent rejection; `lastError` is the most recent send failure, and
1960-
* clears once a batch is accepted, so it reports the current state rather
1961-
* than the high-water mark of a recovered outage.
1958+
* to the ring buffer, the durable queue's caps, the six-day expiry, a
1959+
* permanent rejection, or everything queued or collected after the ingest
1960+
* reported the application's telemetry toggle off; `lastError` is the most
1961+
* recent send failure, and clears once a batch is accepted, so it reports
1962+
* the current state rather than the high-water mark of a recovered outage.
19621963
*/
19631964
async telemetryStats(): Promise<TelemetryStats | null> {
19641965
const stats = await OfflineProtocolNativeModule.telemetryStats();

bindings/react-native/src/types.ts

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -3081,8 +3081,10 @@ export interface TelemetryConfig {
30813081
* `sentEvents` counts events in batches the ingest answered 2xx;
30823082
* `acceptedEvents` sums the `accepted` count the ingest reported, which is
30833083
* what an invoice is reconciled against. `dropped` counts events lost to
3084-
* the ring buffer, the durable queue's caps, the six-day expiry, or a
3085-
* permanent rejection. `lastFlushAtMs` is when a batch was last accepted.
3084+
* the ring buffer, the durable queue's caps, the six-day expiry, a
3085+
* permanent rejection, or everything queued or collected after the ingest
3086+
* reported the application's telemetry toggle off. `lastFlushAtMs` is when
3087+
* a batch was last accepted.
30863088
*/
30873089
export interface TelemetryStats {
30883090
buffered: number;

crates/offline-protocol-uniffi/src/offline_protocol.udl

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -934,7 +934,8 @@ dictionary TelemetryConfig {
934934
// in batches the ingest answered 2xx; `accepted_events` sums the `accepted`
935935
// count the ingest reported, which is what an invoice is reconciled against.
936936
// `dropped` counts events lost to the ring buffer, the durable queue's caps,
937-
// the six-day expiry, or a permanent rejection.
937+
// the six-day expiry, a permanent rejection, or everything queued or
938+
// collected after the ingest reported the application's telemetry toggle off.
938939
dictionary TelemetryStats {
939940
u64 buffered;
940941
u64 sent_events;

crates/offline-protocol/src/telemetry/pipe/mod.rs

Lines changed: 44 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -118,7 +118,9 @@ pub struct TelemetryStats {
118118
/// Events the ingest reported accepted (the `accepted` count of each
119119
/// 202 body, summed; a replay counts nothing new).
120120
pub accepted_events: u64,
121-
/// Events lost: ring overflow, queue caps, TTL expiry, permanent 4xx.
121+
/// Events lost: ring overflow, queue caps, TTL expiry, permanent 4xx,
122+
/// and everything queued or collected once the developer portal switched
123+
/// telemetry off for the application.
122124
///
123125
/// Events, never records. This number is what reconciles an invoice
124126
/// against the device, so it counts in the unit the ingest meters. A
@@ -188,6 +190,16 @@ pub(crate) struct PipeShared {
188190
/// `-1` until a batch has been accepted.
189191
last_flush_at_ms: AtomicI64,
190192
last_error: Mutex<Option<String>>,
193+
/// Set once the ingest has answered `telemetry_disabled`: the
194+
/// application's toggle is off in the developer portal. From then on the
195+
/// ring is emptied into nothing at every cycle rather than cut into
196+
/// batches, and a durable queue adopted afterwards is emptied as it is
197+
/// adopted, so nothing the pipe holds or adopts is left on disk for a
198+
/// later pipe to send, and the gap the toggle promises holds at the
199+
/// device. Read on the cycle and at adoption, never on the emit path,
200+
/// which keeps its one atomic load. Cleared only by a fresh pipe, which is
201+
/// what the next `enable_telemetry` builds.
202+
server_disabled: AtomicBool,
191203
}
192204

193205
fn lock<T>(mutex: &Mutex<T>) -> MutexGuard<'_, T> {
@@ -229,7 +241,13 @@ impl PipeShared {
229241
self.adopt_pending_backend();
230242

231243
let drained = lock(&self.pipeline).drain();
232-
if !drained.is_empty() {
244+
if self.server_disabled.load(Ordering::Relaxed) {
245+
// Counted as dropped, in events, the unit the rest of `dropped`
246+
// uses: the toggle is off, and these are the events it says are
247+
// not kept.
248+
self.uploader_dropped
249+
.fetch_add(drained.len() as u64, Ordering::Relaxed);
250+
} else if !drained.is_empty() {
233251
let device_id = if self.include_device_id {
234252
lock(&self.device_id).clone()
235253
} else {
@@ -280,6 +298,15 @@ impl PipeShared {
280298
if report.batches_sent > 0 {
281299
self.last_flush_at_ms.store(now, Ordering::Relaxed);
282300
}
301+
if report.disabled && !self.server_disabled.swap(true, Ordering::Relaxed) {
302+
tracing::warn!(
303+
target: PIPE_LOG_TARGET,
304+
dropped_events = report.dropped_events,
305+
"hosted telemetry is switched off for this application in the developer \
306+
portal; the queue was dropped and nothing more is collected until \
307+
enable_telemetry"
308+
);
309+
}
283310
// Mirrored, not accumulated: the uploader clears its own error when a
284311
// batch is accepted, and a stats reader asking "is telemetry working"
285312
// after a recovered outage must not still be shown the outage. A
@@ -305,6 +332,20 @@ impl PipeShared {
305332
Attach::Busy(backend) => Some((backend, true)),
306333
Attach::Failed(backend) => Some((backend, false)),
307334
};
335+
if refused.is_none() && self.server_disabled.load(Ordering::Relaxed) {
336+
// The toggle is off, and adoption is the one way a batch can still
337+
// enter the store: the cycle no longer cuts any, but adopting
338+
// loads whatever the queue on that storage already holds, an
339+
// earlier launch's batches included. The halted uploader returns
340+
// before it reads the queue, so a batch kept here would sit on
341+
// disk until the next `enable_telemetry` resent it, which is the
342+
// backfill the toggle promises not to make.
343+
let mut dropped = 0u64;
344+
while let Some(batch) = store.pop_front() {
345+
dropped += u64::from(batch.event_count);
346+
}
347+
self.uploader_dropped.fetch_add(dropped, Ordering::Relaxed);
348+
}
308349
store.flush_index();
309350
self.durable.store(store.is_durable(), Ordering::Relaxed);
310351
self.store_dropped
@@ -606,6 +647,7 @@ impl TelemetryPipe {
606647
store_dropped: AtomicU64::new(0),
607648
last_flush_at_ms: AtomicI64::new(-1),
608649
last_error: Mutex::new(None),
650+
server_disabled: AtomicBool::new(false),
609651
});
610652
// The host's state at enable time, recorded rather than reported:
611653
// there is no session to close yet, and the seed exists so that a

crates/offline-protocol/src/telemetry/pipe/tests/mod.rs

Lines changed: 17 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -38,18 +38,22 @@ impl FakeClock {
3838
}
3939
}
4040

41-
/// A client that captures every body and answers with a fixed status.
41+
/// A client that captures every body and answers with a fixed status. A 2xx
42+
/// carries the ingest's accepted count; anything else carries the ingest's
43+
/// error shape, with `error_code` as the code (`forbidden` when unset).
4244
#[derive(Clone)]
4345
pub(crate) struct CapturingClient {
4446
pub(crate) bodies: Arc<Mutex<Vec<String>>>,
4547
pub(crate) status: Arc<AtomicI64>,
48+
pub(crate) error_code: Arc<Mutex<Option<String>>>,
4649
}
4750

4851
impl CapturingClient {
4952
pub(crate) fn accepting() -> Self {
5053
Self {
5154
bodies: Arc::default(),
5255
status: Arc::new(AtomicI64::new(202)),
56+
error_code: Arc::default(),
5357
}
5458
}
5559

@@ -74,10 +78,21 @@ impl HttpClient for CapturingClient {
7478
.ok()
7579
.and_then(|v| v["events"].as_array().map(|e| e.len()))
7680
.unwrap_or(0);
81+
let body = if (200..300).contains(&status) {
82+
format!(r#"{{"accepted":{accepted},"rejected":0,"rejected_reasons":[]}}"#)
83+
} else {
84+
let code = self
85+
.error_code
86+
.lock()
87+
.unwrap()
88+
.clone()
89+
.unwrap_or_else(|| "forbidden".to_string());
90+
format!(r#"{{"error":"{code}","message":"{code}"}}"#)
91+
};
7792
Ok(Response {
7893
status: status as u16,
7994
retry_after: None,
80-
body: format!(r#"{{"accepted":{accepted},"rejected":0,"rejected_reasons":[]}}"#),
95+
body,
8196
})
8297
}
8398
}

crates/offline-protocol/src/telemetry/pipe/tests/scenarios.rs

Lines changed: 171 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -556,3 +556,174 @@ fn a_detached_worker_finishing_an_upload_cannot_orphan_its_replacements_batch()
556556
"the batch the ingest accepted was queued again: {sessions:?}"
557557
);
558558
}
559+
560+
/// The toggle's gap holds at the device. A `403` whose `error` code is
561+
/// `telemetry_disabled` drops the refused batch and everything queued behind
562+
/// it, what is collected afterwards is discarded rather than queued, and a
563+
/// fresh pipe over the same store has nothing from the off period to resend.
564+
/// Contrast `a_batch_refused_for_a_bad_key_is_still_there_when_the_key_is_fixed`:
565+
/// a bad key keeps its queue, because that is a fault the developer fixes.
566+
#[test]
567+
fn a_403_telemetry_disabled_drops_the_queue_and_discards_what_follows() {
568+
let clock = FakeClock::at(1_000);
569+
let storage = Arc::new(MemoryStorage::default());
570+
let client = CapturingClient::accepting();
571+
client.status.store(0, Ordering::SeqCst); // offline, so two batches queue up
572+
let pipe = inline_pipe(&test_config(), &clock, client.clone(), sealed(&storage));
573+
emit_failed(&pipe, 1);
574+
pipe.flush();
575+
clock.set(1_500); // inside the backoff: the second batch is cut, not sent
576+
emit_failed(&pipe, 2);
577+
pipe.flush();
578+
let queued = |pipe: &TelemetryPipe| crate::telemetry::pipe::lock(&pipe.shared().store).len();
579+
assert_eq!(queued(&pipe), 2);
580+
assert!(client.bodies.lock().unwrap().is_empty());
581+
582+
// The developer switches the toggle off in the portal.
583+
client.status.store(403, Ordering::SeqCst);
584+
*client.error_code.lock().unwrap() = Some("telemetry_disabled".into());
585+
clock.set(3_000);
586+
pipe.flush();
587+
assert_eq!(client.bodies.lock().unwrap().len(), 1, "one attempt");
588+
assert_eq!(
589+
pipe.stats().last_error.as_deref(),
590+
Some("ingest responded 403 (telemetry_disabled)")
591+
);
592+
assert_eq!(
593+
queued(&pipe),
594+
0,
595+
"the refused batch and the one queued behind it are gone"
596+
);
597+
assert_eq!(pipe.stats().dropped, 2);
598+
599+
// Collected while off: discarded at the next flush, never queued or sent.
600+
emit_failed(&pipe, 3);
601+
clock.set(4_000);
602+
pipe.flush();
603+
assert_eq!(queued(&pipe), 0);
604+
assert_eq!(pipe.stats().dropped, 3);
605+
assert_eq!(
606+
client.bodies.lock().unwrap().len(),
607+
1,
608+
"nothing more is sent"
609+
);
610+
pipe.stop(FINAL_FLUSH_BUDGET);
611+
612+
// The toggle comes back on and the app relaunches: a fresh pipe over the
613+
// same protocol-state store has nothing from the off period to resend.
614+
client.status.store(202, Ordering::SeqCst);
615+
*client.error_code.lock().unwrap() = None;
616+
let again = inline_pipe(&test_config(), &clock, client.clone(), sealed(&storage));
617+
// Without this, a fresh pipe that failed to adopt the store would run in
618+
// memory, and "no backfill" below would hold with nothing proven.
619+
assert!(
620+
again.is_durable(),
621+
"the fresh pipe adopted the durable queue"
622+
);
623+
again.flush();
624+
assert_eq!(client.bodies.lock().unwrap().len(), 1, "no backfill");
625+
emit_failed(&again, 4);
626+
again.flush();
627+
let bodies = client.bodies.lock().unwrap();
628+
assert_eq!(bodies.len(), 2, "and new events flow again");
629+
assert!(
630+
bodies[1].contains("protocol.message.failed"),
631+
"{}",
632+
bodies[1]
633+
);
634+
}
635+
636+
/// A queue adopted after the refusal is emptied as it is adopted. The engine
637+
/// starts every pipe in memory and hands the protocol-state store over once
638+
/// `initialize_mls` has it, so a flush can reach the ingest first. The halted
639+
/// uploader never reads the queue again, so without the sweep at adoption the
640+
/// batches an earlier launch left on disk would stay there until the next
641+
/// `enable_telemetry` resent them.
642+
#[test]
643+
fn a_queue_adopted_after_a_telemetry_disabled_refusal_is_dropped_too() {
644+
let clock = FakeClock::at(1_000);
645+
let storage = Arc::new(MemoryStorage::default());
646+
let client = CapturingClient::accepting();
647+
648+
// An earlier launch, offline throughout, leaves one batch on disk.
649+
client.status.store(0, Ordering::SeqCst);
650+
let earlier = inline_pipe(&test_config(), &clock, client.clone(), sealed(&storage));
651+
emit_failed(&earlier, 1);
652+
earlier.flush();
653+
earlier.stop(FINAL_FLUSH_BUDGET);
654+
assert!(client.bodies.lock().unwrap().is_empty());
655+
656+
// This launch starts in memory, as `enable_telemetry` does, and reaches
657+
// the ingest before storage attaches. The toggle is off.
658+
client.status.store(403, Ordering::SeqCst);
659+
*client.error_code.lock().unwrap() = Some("telemetry_disabled".into());
660+
let pipe = inline_pipe(&test_config(), &clock, client.clone(), Backend::Memory);
661+
emit_failed(&pipe, 2);
662+
pipe.flush();
663+
assert_eq!(client.bodies.lock().unwrap().len(), 1, "one attempt");
664+
assert_eq!(pipe.stats().dropped, 1);
665+
666+
// `initialize_mls` attaches the store, and the pipe adopts the queue the
667+
// earlier launch left there.
668+
let Backend::Sealed {
669+
storage: backing,
670+
cipher,
671+
} = sealed(&storage)
672+
else {
673+
unreachable!("sealed() builds a sealed backend");
674+
};
675+
pipe.attach_storage(backing, cipher);
676+
// Without this, an adoption that never happened would leave the store
677+
// empty too, and the assertions below would hold with nothing proven.
678+
assert!(pipe.is_durable(), "the queue on disk was adopted");
679+
let queued = crate::telemetry::pipe::lock(&pipe.shared().store).len();
680+
assert_eq!(queued, 0, "and emptied as it was adopted");
681+
assert_eq!(
682+
pipe.stats().dropped,
683+
2,
684+
"the adopted batch counts as dropped"
685+
);
686+
pipe.stop(FINAL_FLUSH_BUDGET);
687+
688+
// The toggle comes back on: the next launch has nothing to resend.
689+
client.status.store(202, Ordering::SeqCst);
690+
*client.error_code.lock().unwrap() = None;
691+
let again = inline_pipe(&test_config(), &clock, client.clone(), sealed(&storage));
692+
assert!(
693+
again.is_durable(),
694+
"the fresh pipe adopted the durable queue"
695+
);
696+
again.flush();
697+
assert_eq!(client.bodies.lock().unwrap().len(), 1, "no backfill");
698+
}
699+
700+
/// A refusal on the final flush drops the queue the same way. `stop` runs the
701+
/// same cycle, and a batch it left on disk would be resent by the next
702+
/// `enable_telemetry`.
703+
#[test]
704+
fn a_telemetry_disabled_refusal_on_the_final_flush_drops_the_queue_too() {
705+
let clock = FakeClock::at(1_000);
706+
let storage = Arc::new(MemoryStorage::default());
707+
let client = CapturingClient::accepting();
708+
client.status.store(403, Ordering::SeqCst);
709+
*client.error_code.lock().unwrap() = Some("telemetry_disabled".into());
710+
let pipe = inline_pipe(&test_config(), &clock, client.clone(), sealed(&storage));
711+
emit_failed(&pipe, 1);
712+
pipe.stop(FINAL_FLUSH_BUDGET);
713+
assert_eq!(
714+
client.bodies.lock().unwrap().len(),
715+
1,
716+
"the final flush reached the ingest"
717+
);
718+
assert_eq!(pipe.stats().dropped, 1);
719+
720+
client.status.store(202, Ordering::SeqCst);
721+
*client.error_code.lock().unwrap() = None;
722+
let again = inline_pipe(&test_config(), &clock, client.clone(), sealed(&storage));
723+
assert!(
724+
again.is_durable(),
725+
"the fresh pipe adopted the durable queue"
726+
);
727+
again.flush();
728+
assert_eq!(client.bodies.lock().unwrap().len(), 1, "no backfill");
729+
}

0 commit comments

Comments
 (0)