|
| 1 | +# Synthetic Time Testing Guide |
| 2 | + |
| 3 | +How to write deterministic, fast tests for time-dependent logic in the Terraphim ADF crates. |
| 4 | + |
| 5 | +--- |
| 6 | + |
| 7 | +## The Problem |
| 8 | + |
| 9 | +Three ADF crates make scheduling decisions based on elapsed time: stall detection, message expiry, retry eligibility, restart intensity windows. Before this change, all functions called `Utc::now()` internally, making tests either non-deterministic (race conditions at boundaries) or slow (real `sleep()` calls). |
| 10 | + |
| 11 | +## The Solution |
| 12 | + |
| 13 | +Two complementary techniques, zero new dependencies: |
| 14 | + |
| 15 | +1. **Parameter injection** -- Logic-critical functions accept `now: DateTime<Utc>` instead of calling `Utc::now()` internally. Production code passes `Utc::now()` at the call site; tests pass explicit timestamps. |
| 16 | + |
| 17 | +2. **`tokio::time::pause`** -- For tests involving tokio timers (sleep, interval, timeout), use the built-in tokio test infrastructure to freeze and advance time. |
| 18 | + |
| 19 | +--- |
| 20 | + |
| 21 | +## Technique 1: Parameter Injection (Wall-Clock Decisions) |
| 22 | + |
| 23 | +### Pattern |
| 24 | + |
| 25 | +```rust |
| 26 | +// BEFORE: untestable at boundaries |
| 27 | +pub fn check_stall(started_at: DateTime<Utc>, timeout_ms: i64) -> bool { |
| 28 | + let elapsed = (Utc::now() - started_at).num_milliseconds(); |
| 29 | + elapsed > timeout_ms |
| 30 | +} |
| 31 | + |
| 32 | +// AFTER: deterministically testable |
| 33 | +pub fn check_stall(started_at: DateTime<Utc>, timeout_ms: i64, now: DateTime<Utc>) -> bool { |
| 34 | + let elapsed = (now - started_at).num_milliseconds(); |
| 35 | + elapsed > timeout_ms |
| 36 | +} |
| 37 | +``` |
| 38 | + |
| 39 | +Production call site unchanged in intent: |
| 40 | +```rust |
| 41 | +let stalled = check_stall(entry.started_at, timeout, Utc::now()); |
| 42 | +``` |
| 43 | + |
| 44 | +Test with exact boundary control: |
| 45 | +```rust |
| 46 | +#[test] |
| 47 | +fn no_stall_at_exact_boundary() { |
| 48 | + let started = Utc::now(); |
| 49 | + let now = started + chrono::Duration::milliseconds(300_000); |
| 50 | + assert!(!check_stall(started, 300_000, now)); // elapsed == timeout, not > |
| 51 | +} |
| 52 | + |
| 53 | +#[test] |
| 54 | +fn stall_one_ms_over_boundary() { |
| 55 | + let started = Utc::now(); |
| 56 | + let now = started + chrono::Duration::milliseconds(300_001); |
| 57 | + assert!(check_stall(started, 300_000, now)); |
| 58 | +} |
| 59 | +``` |
| 60 | + |
| 61 | +### Available Functions |
| 62 | + |
| 63 | +#### Symphony -- Stall Detection |
| 64 | + |
| 65 | +```rust |
| 66 | +// crates/terraphim_symphony/src/orchestrator/reconcile.rs |
| 67 | + |
| 68 | +/// Check a single running entry for stall. |
| 69 | +pub fn check_stall( |
| 70 | + last_event_timestamp: Option<DateTime<Utc>>, |
| 71 | + started_at: DateTime<Utc>, |
| 72 | + stall_timeout_ms: i64, |
| 73 | + now: DateTime<Utc>, // <-- injected |
| 74 | +) -> Option<ReconcileAction> |
| 75 | + |
| 76 | +/// Collect stalled issue IDs from the runtime state. |
| 77 | +pub fn find_stalled_issues( |
| 78 | + state: &OrchestratorRuntimeState, |
| 79 | + stall_timeout_ms: i64, |
| 80 | + now: DateTime<Utc>, // <-- injected |
| 81 | +) -> Vec<String> |
| 82 | +``` |
| 83 | + |
| 84 | +Example test: |
| 85 | +```rust |
| 86 | +use chrono::Utc; |
| 87 | +use crate::orchestrator::reconcile::{check_stall, ReconcileAction}; |
| 88 | + |
| 89 | +#[test] |
| 90 | +fn stall_uses_last_event_timestamp_when_present() { |
| 91 | + let started = Utc::now(); |
| 92 | + let last_event = started + chrono::Duration::seconds(100); |
| 93 | + let now = last_event + chrono::Duration::seconds(200); |
| 94 | + // 200s since last event, within 300s timeout |
| 95 | + let result = check_stall(Some(last_event), started, 300_000, now); |
| 96 | + assert!(result.is_none()); |
| 97 | +} |
| 98 | + |
| 99 | +#[test] |
| 100 | +fn stall_falls_back_to_started_at_when_no_events() { |
| 101 | + let started = Utc::now(); |
| 102 | + let now = started + chrono::Duration::milliseconds(300_001); |
| 103 | + let result = check_stall(None, started, 300_000, now); |
| 104 | + assert!(matches!(result, Some(ReconcileAction::StallDetected))); |
| 105 | +} |
| 106 | +``` |
| 107 | + |
| 108 | +#### Symphony -- State Snapshot |
| 109 | + |
| 110 | +```rust |
| 111 | +// crates/terraphim_symphony/src/orchestrator/state.rs |
| 112 | + |
| 113 | +/// Create a snapshot of the current state for observability. |
| 114 | +pub fn snapshot(&self, now: DateTime<Utc>) -> StateSnapshot |
| 115 | +``` |
| 116 | + |
| 117 | +Example test: |
| 118 | +```rust |
| 119 | +#[test] |
| 120 | +fn snapshot_calculates_elapsed_from_injected_now() { |
| 121 | + let mut state = OrchestratorRuntimeState::new(30_000, 10); |
| 122 | + // ... add a running entry with known started_at ... |
| 123 | + let now = entry_started_at + chrono::Duration::seconds(120); |
| 124 | + let snap = state.snapshot(now); |
| 125 | + // Verify elapsed calculation uses injected time |
| 126 | + assert!(snap.codex_totals.seconds_running >= 120.0); |
| 127 | +} |
| 128 | +``` |
| 129 | + |
| 130 | +#### Messaging -- Message Expiry |
| 131 | + |
| 132 | +```rust |
| 133 | +// crates/terraphim_agent_messaging/src/message.rs |
| 134 | + |
| 135 | +/// Check if message has expired. |
| 136 | +pub fn is_expired(&self, now: DateTime<Utc>) -> bool |
| 137 | +``` |
| 138 | + |
| 139 | +Example test: |
| 140 | +```rust |
| 141 | +use std::time::Duration; |
| 142 | + |
| 143 | +#[test] |
| 144 | +fn message_expires_after_timeout() { |
| 145 | + let options = DeliveryOptions { |
| 146 | + timeout: Duration::from_secs(30), |
| 147 | + ..Default::default() |
| 148 | + }; |
| 149 | + let envelope = MessageEnvelope::new( |
| 150 | + AgentPid::new(), |
| 151 | + "test".to_string(), |
| 152 | + serde_json::Value::String("payload".to_string()), |
| 153 | + options, |
| 154 | + ); |
| 155 | + |
| 156 | + // Not expired at 29s |
| 157 | + let before = envelope.created_at + chrono::Duration::seconds(29); |
| 158 | + assert!(!envelope.is_expired(before)); |
| 159 | + |
| 160 | + // Expired at 30s + 1ms |
| 161 | + let after = envelope.created_at + chrono::Duration::milliseconds(30_001); |
| 162 | + assert!(envelope.is_expired(after)); |
| 163 | +} |
| 164 | +``` |
| 165 | + |
| 166 | +#### Messaging -- Retry Eligibility |
| 167 | + |
| 168 | +```rust |
| 169 | +// crates/terraphim_agent_messaging/src/delivery.rs |
| 170 | + |
| 171 | +/// Check if a message should be retried. |
| 172 | +fn should_retry(&self, record: &DeliveryRecord, now: DateTime<Utc>) -> bool |
| 173 | +``` |
| 174 | + |
| 175 | +This is a private method. Test it indirectly through `get_retry_candidates()`, or write tests within the `delivery.rs` module. |
| 176 | + |
| 177 | +#### Supervisor -- Agent Uptime |
| 178 | + |
| 179 | +```rust |
| 180 | +// crates/terraphim_agent_supervisor/src/agent.rs |
| 181 | + |
| 182 | +/// Get uptime duration. |
| 183 | +pub fn uptime(&self, now: DateTime<Utc>) -> chrono::Duration |
| 184 | +``` |
| 185 | + |
| 186 | +Example test: |
| 187 | +```rust |
| 188 | +#[test] |
| 189 | +fn uptime_calculation() { |
| 190 | + let info = SupervisedAgentInfo::new(/* ... */); |
| 191 | + let now = info.start_time + chrono::Duration::hours(2); |
| 192 | + assert_eq!(info.uptime(now).num_hours(), 2); |
| 193 | +} |
| 194 | +``` |
| 195 | + |
| 196 | +#### Supervisor -- Restart Window |
| 197 | + |
| 198 | +```rust |
| 199 | +// crates/terraphim_agent_supervisor/src/supervisor.rs |
| 200 | + |
| 201 | +/// Check if agent should be restarted based on policy. |
| 202 | +async fn should_restart( |
| 203 | + &self, |
| 204 | + agent_id: &AgentPid, |
| 205 | + reason: &ExitReason, |
| 206 | + now: DateTime<Utc>, // <-- injected |
| 207 | +) -> SupervisionResult<bool> |
| 208 | +``` |
| 209 | + |
| 210 | +The `RestartIntensity::is_restart_allowed()` already accepts `time_since_first_restart: Duration` as a parameter, so it is directly testable without the async wrapper: |
| 211 | + |
| 212 | +```rust |
| 213 | +use std::time::Duration; |
| 214 | + |
| 215 | +#[test] |
| 216 | +fn restart_window_resets_after_time_window() { |
| 217 | + let intensity = RestartIntensity::new(3, Duration::from_secs(60)); |
| 218 | + |
| 219 | + // At max restarts within window: denied |
| 220 | + assert!(!intensity.is_restart_allowed(3, Duration::from_secs(30))); |
| 221 | + |
| 222 | + // Exactly at window boundary: still denied (> not >=) |
| 223 | + assert!(!intensity.is_restart_allowed(3, Duration::from_secs(60))); |
| 224 | + |
| 225 | + // One second past window: counter resets, allowed |
| 226 | + assert!(intensity.is_restart_allowed(3, Duration::from_secs(61))); |
| 227 | +} |
| 228 | +``` |
| 229 | + |
| 230 | +--- |
| 231 | + |
| 232 | +## Technique 2: tokio::time::pause (Async Timers) |
| 233 | + |
| 234 | +For tests that need to exercise `tokio::time::sleep`, `tokio::time::interval`, or `tokio::time::timeout` without real delays. |
| 235 | + |
| 236 | +### Pattern |
| 237 | + |
| 238 | +```rust |
| 239 | +#[tokio::test(start_paused = true)] |
| 240 | +async fn retry_timer_fires_after_backoff() { |
| 241 | + // Time is frozen at test start. |
| 242 | + // tokio::time::sleep/interval/timeout will NOT resolve |
| 243 | + // until we explicitly advance time. |
| 244 | + |
| 245 | + let retry_delay = Duration::from_secs(10); |
| 246 | + let timer = tokio::time::sleep(retry_delay); |
| 247 | + tokio::pin!(timer); |
| 248 | + |
| 249 | + // Timer has not fired yet |
| 250 | + assert!(futures::poll!(&mut timer).is_pending()); |
| 251 | + |
| 252 | + // Advance time by 10 seconds |
| 253 | + tokio::time::advance(Duration::from_secs(10)).await; |
| 254 | + |
| 255 | + // Timer has now fired |
| 256 | + assert!(futures::poll!(&mut timer).is_ready()); |
| 257 | +} |
| 258 | +``` |
| 259 | + |
| 260 | +### What it controls |
| 261 | + |
| 262 | +| Primitive | Controlled by pause/advance? | |
| 263 | +|-----------|------------------------------| |
| 264 | +| `tokio::time::sleep()` | Yes | |
| 265 | +| `tokio::time::interval()` | Yes | |
| 266 | +| `tokio::time::timeout()` | Yes | |
| 267 | +| `tokio::time::Instant::now()` | Yes | |
| 268 | +| `chrono::Utc::now()` | **No** -- use parameter injection | |
| 269 | +| `std::time::Instant::now()` | **No** -- not used in logic decisions | |
| 270 | + |
| 271 | +### When to use which technique |
| 272 | + |
| 273 | +| Decision type | Technique | Example | |
| 274 | +|--------------|-----------|---------| |
| 275 | +| "Has N milliseconds elapsed since X?" | Parameter injection (`now`) | Stall detection, message expiry, restart windows | |
| 276 | +| "Fire after a tokio sleep/interval" | `tokio::time::pause` | Retry timer, health check loop, poll interval | |
| 277 | +| Both | Combine both | Test that a stalled session triggers a retry timer | |
| 278 | + |
| 279 | +### Combined example |
| 280 | + |
| 281 | +```rust |
| 282 | +#[tokio::test(start_paused = true)] |
| 283 | +async fn stalled_session_triggers_retry_after_backoff() { |
| 284 | + // Setup orchestrator with known start time |
| 285 | + let started_at = Utc::now(); |
| 286 | + |
| 287 | + // Advance tokio time past stall threshold |
| 288 | + tokio::time::advance(Duration::from_secs(301)).await; |
| 289 | + |
| 290 | + // Check stall with injected wall-clock time |
| 291 | + let now = started_at + chrono::Duration::seconds(301); |
| 292 | + let result = check_stall(None, started_at, 300_000, now); |
| 293 | + assert!(matches!(result, Some(ReconcileAction::StallDetected))); |
| 294 | + |
| 295 | + // Retry timer (tokio sleep) resolves because time is paused+advanced |
| 296 | + let backoff = Duration::from_secs(10); |
| 297 | + tokio::time::sleep(backoff).await; // resolves instantly with paused time |
| 298 | +} |
| 299 | +``` |
| 300 | + |
| 301 | +--- |
| 302 | + |
| 303 | +## Boundary Testing Conventions |
| 304 | + |
| 305 | +All time comparisons in the codebase use **strict greater-than** (`>`), not greater-than-or-equal (`>=`). This means: |
| 306 | + |
| 307 | +| Condition | Result | |
| 308 | +|-----------|--------| |
| 309 | +| `elapsed < threshold` | No action | |
| 310 | +| `elapsed == threshold` | No action | |
| 311 | +| `elapsed > threshold` | Action triggered | |
| 312 | + |
| 313 | +Always test three points: |
| 314 | +1. **Below threshold** -- verify no action |
| 315 | +2. **At exact threshold** -- verify no action (the `==` case) |
| 316 | +3. **One unit above threshold** -- verify action triggers |
| 317 | + |
| 318 | +```rust |
| 319 | +#[test] |
| 320 | +fn boundary_below() { |
| 321 | + let now = started + chrono::Duration::milliseconds(threshold - 1); |
| 322 | + assert!(result.is_none()); |
| 323 | +} |
| 324 | + |
| 325 | +#[test] |
| 326 | +fn boundary_exact() { |
| 327 | + let now = started + chrono::Duration::milliseconds(threshold); |
| 328 | + assert!(result.is_none()); // > not >= |
| 329 | +} |
| 330 | + |
| 331 | +#[test] |
| 332 | +fn boundary_above() { |
| 333 | + let now = started + chrono::Duration::milliseconds(threshold + 1); |
| 334 | + assert!(result.is_some()); |
| 335 | +} |
| 336 | +``` |
| 337 | + |
| 338 | +--- |
| 339 | + |
| 340 | +## Running Tests |
| 341 | + |
| 342 | +```bash |
| 343 | +# All three ADF crates |
| 344 | +cd crates/terraphim_symphony && cargo test --lib |
| 345 | +cd crates/terraphim_agent_supervisor && cargo test |
| 346 | +cd crates/terraphim_agent_messaging && cargo test |
| 347 | + |
| 348 | +# Specific boundary tests |
| 349 | +cargo test -p terraphim_symphony stall_boundary |
| 350 | +cargo test -p terraphim_agent_messaging message_expired |
| 351 | +cargo test -p terraphim_agent_messaging message_not_expired |
| 352 | +cargo test -p terraphim_agent_supervisor restart_window_boundary |
| 353 | +``` |
| 354 | + |
| 355 | +--- |
| 356 | + |
| 357 | +## Adding Synthetic Time to New Functions |
| 358 | + |
| 359 | +When writing a new function that makes decisions based on elapsed time: |
| 360 | + |
| 361 | +1. **Add `now: DateTime<Utc>` as the last parameter** |
| 362 | +2. **Replace `Utc::now()` with `now`** in the function body |
| 363 | +3. **Pass `Utc::now()` at the call site** in production code |
| 364 | +4. **Write three boundary tests** (below, at, above threshold) |
| 365 | +5. **Do not change timestamp-recording calls** (`created_at`, `started_at`, etc.) -- only decision-making comparisons need the parameter |
| 366 | + |
| 367 | +```rust |
| 368 | +// Good: decision function parameterised |
| 369 | +pub fn is_overdue(&self, now: DateTime<Utc>) -> bool { |
| 370 | + (now - self.deadline).num_seconds() > 0 |
| 371 | +} |
| 372 | + |
| 373 | +// Good: recording function keeps Utc::now() |
| 374 | +pub fn record_start(&mut self) { |
| 375 | + self.started_at = Utc::now(); // this is fine |
| 376 | +} |
| 377 | +``` |
0 commit comments