Skip to main content

ferrum_cli/
observability_product.rs

1use chrono::{Duration, Utc};
2use clap::ValueEnum;
3use ferrum_types::{
4    FerrumError, FerrumObservabilityConfig, FerrumProfileEvent, MemorySnapshot,
5    ObservabilityProfileDetail, ProfileEntrypoint, ProfileError, ProfileEventKind, ProfileStatus,
6    ReplayReference, ResourceAction, ResourceTraceEvent, Result, SamplingParams,
7    DEFAULT_OBSERVABILITY_PROFILE_SAMPLE_RATE, OBSERVABILITY_PROFILE_SCHEMA_VERSION,
8};
9use serde_json::{json, Value};
10use sha2::{Digest, Sha256};
11use std::collections::BTreeMap;
12use std::fs;
13use std::ops::Deref;
14use std::path::{Path, PathBuf};
15use uuid::Uuid;
16
17const SYNTHETIC_MODEL: &str = "synthetic/no-weight";
18const SYNTHETIC_BACKEND: &str = "synthetic";
19
20#[derive(Clone, Copy, Debug, Default, PartialEq, Eq, ValueEnum)]
21pub enum ProfileDetailArg {
22    #[default]
23    Off,
24    Basic,
25    Resource,
26    Latency,
27    Kernel,
28    Debug,
29    Replay,
30    Verify,
31    Full,
32}
33
34impl ProfileDetailArg {
35    pub fn as_str(self) -> &'static str {
36        match self {
37            Self::Off => "off",
38            Self::Basic => "basic",
39            Self::Resource => "resource",
40            Self::Latency => "latency",
41            Self::Kernel => "kernel",
42            Self::Debug => "debug",
43            Self::Replay => "replay",
44            Self::Verify => "verify",
45            Self::Full => "full",
46        }
47    }
48}
49
50impl From<ProfileDetailArg> for ObservabilityProfileDetail {
51    fn from(value: ProfileDetailArg) -> Self {
52        match value {
53            ProfileDetailArg::Off => Self::Off,
54            ProfileDetailArg::Basic => Self::Basic,
55            ProfileDetailArg::Resource => Self::Resource,
56            ProfileDetailArg::Latency => Self::Latency,
57            ProfileDetailArg::Kernel => Self::Kernel,
58            ProfileDetailArg::Debug => Self::Debug,
59            ProfileDetailArg::Replay => Self::Replay,
60            ProfileDetailArg::Verify => Self::Verify,
61            ProfileDetailArg::Full => Self::Full,
62        }
63    }
64}
65
66#[derive(Clone, Debug)]
67pub struct ProductObservabilityConfig {
68    pub core: FerrumObservabilityConfig,
69}
70
71impl Deref for ProductObservabilityConfig {
72    type Target = FerrumObservabilityConfig;
73
74    fn deref(&self) -> &Self::Target {
75        &self.core
76    }
77}
78
79pub struct ActualRunObservation {
80    pub request_id: String,
81    pub duration_us: u64,
82    pub sampling_params: SamplingParams,
83    pub prompt_token_ids: Option<Vec<u32>>,
84    pub prompt_token_count: Option<usize>,
85    pub output_tokens: usize,
86    pub output_token_ids: Vec<u32>,
87    pub chunk_count: usize,
88    pub finish_reason: Option<String>,
89    pub prompt_chars: usize,
90    pub response_chars: usize,
91    pub response_text: String,
92    pub execution_evidence: Option<ferrum_types::InferenceExecutionEvidence>,
93    pub memory: Option<crate::memory_profile::ProcessMemoryObservation>,
94    pub memory_stages: Vec<ActualMemoryStageObservation>,
95}
96
97pub struct ActualRunFailureObservation {
98    pub request_id: String,
99    pub duration_us: u64,
100    pub sampling_params: SamplingParams,
101    pub prompt_token_ids: Option<Vec<u32>>,
102    pub prompt_token_count: Option<usize>,
103    pub prompt_chars: usize,
104    pub failure_kind: String,
105    pub error_kind: String,
106    pub error_message: String,
107    pub memory: Option<crate::memory_profile::ProcessMemoryObservation>,
108    pub memory_stages: Vec<ActualMemoryStageObservation>,
109}
110
111#[derive(Clone, Debug)]
112pub struct ActualMemoryStageObservation {
113    pub phase: String,
114    pub stage: String,
115    pub duration_us: Option<u64>,
116    pub memory: Option<crate::memory_profile::ProcessMemoryObservation>,
117    pub attributes: BTreeMap<String, Value>,
118}
119
120impl ActualMemoryStageObservation {
121    pub fn new(
122        phase: impl Into<String>,
123        stage: impl Into<String>,
124        duration_us: Option<u64>,
125        memory: Option<crate::memory_profile::ProcessMemoryObservation>,
126    ) -> Self {
127        Self {
128            phase: phase.into(),
129            stage: stage.into(),
130            duration_us,
131            memory,
132            attributes: BTreeMap::new(),
133        }
134    }
135
136    pub fn with_attribute(mut self, key: impl Into<String>, value: Value) -> Self {
137        self.attributes.insert(key.into(), value);
138        self
139    }
140
141    pub fn with_profile_run_status(
142        mut self,
143        executed: bool,
144        status: impl Into<String>,
145        source: impl Into<String>,
146    ) -> Self {
147        self.attributes.extend([
148            ("profile_run_executed".to_string(), json!(executed)),
149            ("profile_run_status".to_string(), json!(status.into())),
150            ("profile_run_source".to_string(), json!(source.into())),
151        ]);
152        self
153    }
154
155    pub fn with_engine_cache_status(mut self, status: &ferrum_types::EngineStatus) -> Self {
156        let memory = &status.memory_usage;
157        let dynamic_capacity_bytes = memory.cache_memory_bytes.saturating_add(memory.free_bytes);
158        self.attributes.extend([
159            (
160                "kv_cache_total_bytes".to_string(),
161                json!(dynamic_capacity_bytes),
162            ),
163            (
164                "kv_cache_used_bytes".to_string(),
165                json!(memory.cache_memory_bytes),
166            ),
167            ("kv_cache_free_bytes".to_string(), json!(memory.free_bytes)),
168            (
169                "cache_memory_bytes".to_string(),
170                json!(memory.cache_memory_bytes),
171            ),
172            (
173                "available_kv_or_state_bytes".to_string(),
174                json!(memory.free_bytes),
175            ),
176            (
177                "resource_total_bytes".to_string(),
178                json!(memory.total_bytes),
179            ),
180            ("resource_used_bytes".to_string(), json!(memory.used_bytes)),
181            ("resource_free_bytes".to_string(), json!(memory.free_bytes)),
182        ]);
183        self
184    }
185}
186
187impl ProductObservabilityConfig {
188    #[allow(clippy::too_many_arguments)]
189    pub fn new(
190        entrypoint: ProfileEntrypoint,
191        model: impl Into<String>,
192        profile_jsonl: Option<&PathBuf>,
193        profile_detail: ProfileDetailArg,
194        memory_profile_jsonl: Option<&PathBuf>,
195        scheduler_trace_jsonl: Option<&PathBuf>,
196        request_dump_dir: Option<&PathBuf>,
197        profile_sample_rate: f64,
198    ) -> Self {
199        Self {
200            core: FerrumObservabilityConfig::new(
201                entrypoint,
202                model,
203                profile_jsonl.cloned(),
204                profile_detail.into(),
205                memory_profile_jsonl.cloned(),
206                scheduler_trace_jsonl.cloned(),
207                request_dump_dir.cloned(),
208                profile_sample_rate,
209            ),
210        }
211    }
212
213    pub fn enabled(&self) -> bool {
214        self.core.enabled()
215    }
216
217    pub fn synthetic_no_weight_enabled(&self) -> bool {
218        self.core.synthetic_no_weight_enabled()
219    }
220
221    pub fn unified_product_profile_enabled(&self) -> bool {
222        self.core.unified_product_profile_enabled()
223    }
224
225    fn validate(&self) -> Result<()> {
226        self.core.validate().map_err(FerrumError::invalid_parameter)
227    }
228}
229
230pub fn default_profile_sample_rate() -> f64 {
231    DEFAULT_OBSERVABILITY_PROFILE_SAMPLE_RATE
232}
233
234pub fn write_synthetic_product_observability(
235    config: &ProductObservabilityConfig,
236) -> Result<Vec<PathBuf>> {
237    config.validate()?;
238    let request_id = format!(
239        "product-obs-{}-{}",
240        entrypoint_label(config.entrypoint),
241        Uuid::new_v4().simple()
242    );
243    let replay_command = replay_command(config);
244    let events = product_events(config, &request_id, &replay_command);
245    let mut written = write_profile_outputs(
246        config,
247        &events,
248        ferrum_bench_core::JsonlJournalOpenMode::Truncate,
249        true,
250        true,
251        true,
252    )?;
253    if let Some(dir) = &config.request_dump_dir {
254        fs_create_dir_all(dir)?;
255        written.extend(write_replay_bundle(
256            dir,
257            config,
258            &request_id,
259            &replay_command,
260            ReplayBundleData {
261                request: request_dump(config, &request_id, &replay_command),
262                prompt_token_ids: Some(vec![101, 202, 303, 404]),
263                prompt_token_count: Some(4),
264                prompt_token_unavailable_reason: None,
265                sampling_params: Some(SamplingParams::greedy()),
266                backend: SYNTHETIC_BACKEND,
267                actual_model_smoke: false,
268                output_token_ids: Some(vec![909, 808]),
269                output_text: Some("synthetic ok"),
270                finish_reason: Some("stop"),
271                failure_kind: None,
272                failure_diagnostics: None,
273            },
274        )?);
275    }
276    Ok(written)
277}
278
279pub fn write_actual_run_observability(
280    config: &ProductObservabilityConfig,
281    observation: &ActualRunObservation,
282) -> Result<Vec<PathBuf>> {
283    if !config.enabled() {
284        return Ok(Vec::new());
285    }
286    config.validate()?;
287    if let Some(timing) = observation
288        .execution_evidence
289        .as_ref()
290        .and_then(|evidence| evidence.engine_token_timing.as_ref())
291    {
292        timing
293            .validate(observation.output_tokens)
294            .map_err(FerrumError::invalid_parameter)?;
295    }
296    let replay_command = replay_command(config);
297    let events = actual_run_events(config, observation, &replay_command);
298    write_actual_run_artifacts(config, &events, observation, &replay_command)
299}
300
301pub fn write_actual_run_failure_observability(
302    config: &ProductObservabilityConfig,
303    observation: &ActualRunFailureObservation,
304) -> Result<Vec<PathBuf>> {
305    if !config.enabled() {
306        return Ok(Vec::new());
307    }
308    config.validate()?;
309    let replay_command = replay_command(config);
310    let events = actual_run_failure_events(config, observation, &replay_command);
311    write_actual_run_failure_artifacts(config, &events, observation, &replay_command)
312}
313
314pub fn write_actual_serve_startup_observability(
315    config: &ProductObservabilityConfig,
316    startup_duration_us: u64,
317    startup_memory: Option<crate::memory_profile::ProcessMemoryObservation>,
318    memory_stages: Vec<ActualMemoryStageObservation>,
319) -> Result<Vec<PathBuf>> {
320    if !config.unified_product_profile_enabled() {
321        return Ok(Vec::new());
322    }
323    config.validate()?;
324    let request_id = format!("serve-startup-{}", Uuid::new_v4().simple());
325    let replay_command = replay_command(config);
326    let events = actual_serve_startup_events(
327        config,
328        &request_id,
329        startup_duration_us,
330        startup_memory.as_ref(),
331        &memory_stages,
332        &replay_command,
333    );
334    write_actual_artifacts(config, &events, &request_id, &replay_command)
335}
336
337pub fn append_actual_serve_memory_stage_observability(
338    config: &ProductObservabilityConfig,
339    stage: ActualMemoryStageObservation,
340) -> Result<Vec<PathBuf>> {
341    if !config.unified_product_profile_enabled() {
342        return Ok(Vec::new());
343    }
344    config.validate()?;
345    let request_id = format!("serve-memory-{}", Uuid::new_v4().simple());
346    let events = actual_memory_stage_events(config, &request_id, &[stage], Utc::now());
347    write_profile_outputs(
348        config,
349        &events,
350        ferrum_bench_core::JsonlJournalOpenMode::Append,
351        true,
352        true,
353        false,
354    )
355}
356
357fn write_actual_run_artifacts(
358    config: &ProductObservabilityConfig,
359    events: &[FerrumProfileEvent],
360    observation: &ActualRunObservation,
361    replay_command: &str,
362) -> Result<Vec<PathBuf>> {
363    // Successful actual inference must prove its scheduler lifecycle at the engine boundary.
364    // Adding a product fallback here would duplicate real events or hide missing engine evidence.
365    let mut written = write_actual_artifacts_with_scheduler(
366        config,
367        events,
368        &observation.request_id,
369        replay_command,
370        false,
371    )?;
372    if let Some(dir) = &config.request_dump_dir {
373        written.extend(write_replay_bundle(
374            dir,
375            config,
376            &observation.request_id,
377            replay_command,
378            ReplayBundleData {
379                request: actual_request_dump(config, &observation.request_id, replay_command),
380                prompt_token_ids: observation.prompt_token_ids.clone(),
381                prompt_token_count: observation.prompt_token_count,
382                prompt_token_unavailable_reason: observation.prompt_token_ids.is_none().then_some(
383                    "rendered prompt token ids were unavailable for run one-shot observability",
384                ),
385                sampling_params: Some(observation.sampling_params.clone()),
386                backend: "actual",
387                actual_model_smoke: true,
388                output_token_ids: Some(observation.output_token_ids.clone()),
389                output_text: Some(&observation.response_text),
390                finish_reason: observation.finish_reason.as_deref(),
391                failure_kind: None,
392                failure_diagnostics: None,
393            },
394        )?);
395    }
396    Ok(written)
397}
398
399fn write_actual_run_failure_artifacts(
400    config: &ProductObservabilityConfig,
401    events: &[FerrumProfileEvent],
402    observation: &ActualRunFailureObservation,
403    replay_command: &str,
404) -> Result<Vec<PathBuf>> {
405    let mut written =
406        write_actual_artifacts(config, events, &observation.request_id, replay_command)?;
407    if let Some(dir) = &config.request_dump_dir {
408        written.extend(write_replay_bundle(
409            dir,
410            config,
411            &observation.request_id,
412            replay_command,
413            ReplayBundleData {
414                request: actual_request_dump(config, &observation.request_id, replay_command),
415                prompt_token_ids: observation.prompt_token_ids.clone(),
416                prompt_token_count: observation.prompt_token_count,
417                prompt_token_unavailable_reason: observation.prompt_token_ids.is_none().then_some(
418                    "rendered prompt token ids were unavailable for run failure observability",
419                ),
420                sampling_params: Some(observation.sampling_params.clone()),
421                backend: "actual",
422                actual_model_smoke: true,
423                output_token_ids: Some(Vec::new()),
424                output_text: Some(""),
425                finish_reason: Some("error"),
426                failure_kind: Some(observation.failure_kind.as_str()),
427                failure_diagnostics: Some(actual_run_failure_diagnostics(observation)),
428            },
429        )?);
430    }
431    Ok(written)
432}
433
434fn write_actual_artifacts(
435    config: &ProductObservabilityConfig,
436    events: &[FerrumProfileEvent],
437    request_id: &str,
438    replay_command: &str,
439) -> Result<Vec<PathBuf>> {
440    write_actual_artifacts_with_scheduler(config, events, request_id, replay_command, true)
441}
442
443fn write_actual_artifacts_with_scheduler(
444    config: &ProductObservabilityConfig,
445    events: &[FerrumProfileEvent],
446    request_id: &str,
447    replay_command: &str,
448    include_scheduler: bool,
449) -> Result<Vec<PathBuf>> {
450    let mut written = write_profile_outputs(
451        config,
452        events,
453        ferrum_bench_core::JsonlJournalOpenMode::Append,
454        true,
455        true,
456        include_scheduler,
457    )?;
458    if let Some(dir) = &config.request_dump_dir {
459        fs_create_dir_all(dir)?;
460        written.extend(write_replay_bundle(
461            dir,
462            config,
463            request_id,
464            replay_command,
465            ReplayBundleData {
466                request: actual_request_dump(config, request_id, replay_command),
467                prompt_token_ids: None,
468                prompt_token_count: None,
469                prompt_token_unavailable_reason: Some(
470                    "startup or non-run request has no rendered prompt token dump in WP9 L0",
471                ),
472                sampling_params: None,
473                backend: "actual",
474                actual_model_smoke: true,
475                output_token_ids: Some(Vec::new()),
476                output_text: None,
477                finish_reason: None,
478                failure_kind: None,
479                failure_diagnostics: None,
480            },
481        )?);
482    }
483    Ok(written)
484}
485
486#[derive(Clone, Copy, Default)]
487struct ProfileOutputRoles {
488    profile: bool,
489    memory: bool,
490    scheduler: bool,
491}
492
493fn add_profile_output_target(
494    targets: &mut BTreeMap<PathBuf, ProfileOutputRoles>,
495    path: Option<&PathBuf>,
496    role: fn(&mut ProfileOutputRoles) -> &mut bool,
497) -> Result<()> {
498    let Some(path) = path else {
499        return Ok(());
500    };
501    let normalized = ferrum_bench_core::normalize_jsonl_path(path).map_err(|error| {
502        FerrumError::io(format!(
503            "normalize observability JSONL path {}: {error}",
504            path.display()
505        ))
506    })?;
507    *role(targets.entry(normalized).or_default()) = true;
508    Ok(())
509}
510
511fn write_profile_outputs(
512    config: &ProductObservabilityConfig,
513    events: &[FerrumProfileEvent],
514    mode: ferrum_bench_core::JsonlJournalOpenMode,
515    include_profile: bool,
516    include_memory: bool,
517    include_scheduler: bool,
518) -> Result<Vec<PathBuf>> {
519    let mut targets = BTreeMap::<PathBuf, ProfileOutputRoles>::new();
520    if include_profile {
521        add_profile_output_target(&mut targets, config.profile_jsonl.as_ref(), |roles| {
522            &mut roles.profile
523        })?;
524    }
525    if include_memory {
526        add_profile_output_target(
527            &mut targets,
528            config.memory_profile_jsonl.as_ref(),
529            |roles| &mut roles.memory,
530        )?;
531    }
532    if include_scheduler {
533        add_profile_output_target(
534            &mut targets,
535            config.scheduler_trace_jsonl.as_ref(),
536            |roles| &mut roles.scheduler,
537        )?;
538    }
539
540    let mut written = Vec::with_capacity(targets.len());
541    for (path, roles) in targets {
542        let selected = events
543            .iter()
544            .filter(|event| {
545                roles.profile
546                    || (roles.memory && event.memory.is_some())
547                    || (roles.scheduler && event.resource.is_some())
548            })
549            .cloned()
550            .collect::<Vec<_>>();
551        if selected.is_empty() {
552            continue;
553        }
554        write_profile_events(&path, mode, &selected)?;
555        written.push(path);
556    }
557    Ok(written)
558}
559
560fn product_events(
561    config: &ProductObservabilityConfig,
562    request_id: &str,
563    replay_command: &str,
564) -> Vec<FerrumProfileEvent> {
565    let base = Utc::now();
566    let open = resource_event(
567        config,
568        request_id,
569        "request",
570        request_id,
571        "request_slot",
572        "request_open",
573        ResourceAction::RequestOpen,
574        base,
575        None,
576        None,
577        None,
578        Some(1),
579        None,
580    );
581    let reserve = resource_event(
582        config,
583        request_id,
584        "request",
585        request_id,
586        "request_slot",
587        "request_slot_reserve",
588        ResourceAction::Reserve,
589        base + Duration::microseconds(10),
590        Some(1),
591        Some(0),
592        Some(1),
593        Some(1),
594        None,
595    );
596    let commit = resource_event(
597        config,
598        request_id,
599        "request",
600        request_id,
601        "request_slot",
602        "request_slot_commit",
603        ResourceAction::Commit,
604        base + Duration::microseconds(20),
605        Some(1),
606        Some(0),
607        Some(1),
608        Some(1),
609        None,
610    );
611
612    let mut prefill = base_event(
613        config,
614        request_id,
615        "synthetic_prefill",
616        ProfileEventKind::TimedSpan,
617        base + Duration::microseconds(30),
618    );
619    prefill.duration_us = Some(160);
620    prefill.memory = Some(MemorySnapshot {
621        scope: "process".to_string(),
622        backend: Some(SYNTHETIC_BACKEND.to_string()),
623        before_bytes: Some(2048),
624        after_bytes: Some(2304),
625        current_bytes: Some(2304),
626        high_water_bytes: Some(2304),
627        available_bytes: Some(1024 * 1024),
628    });
629    prefill.attributes.extend(common_attrs(config));
630    prefill
631        .attributes
632        .insert("input_tokens".to_string(), json!(8));
633
634    let release = resource_event(
635        config,
636        request_id,
637        "request",
638        request_id,
639        "request_slot",
640        "request_slot_release",
641        ResourceAction::Release,
642        base + Duration::microseconds(180),
643        Some(1),
644        Some(1),
645        Some(0),
646        Some(1),
647        None,
648    );
649
650    let mut close = resource_event(
651        config,
652        request_id,
653        "request",
654        request_id,
655        "request_slot",
656        "request_close",
657        ResourceAction::RequestClose,
658        base + Duration::microseconds(190),
659        None,
660        None,
661        None,
662        Some(1),
663        None,
664    );
665    close.status = if config.profile_detail.diagnostic_only() {
666        ProfileStatus::DiagnosticOnly
667    } else {
668        ProfileStatus::Ok
669    };
670    close.replay = Some(ReplayReference {
671        command: replay_command.to_string(),
672        bundle_dir: config
673            .request_dump_dir
674            .as_ref()
675            .map(|path| path.to_string_lossy().to_string()),
676    });
677    close.attributes.extend(common_attrs(config));
678    close
679        .attributes
680        .insert("response_text".to_string(), json!("synthetic ok"));
681    vec![open, reserve, commit, prefill, release, close]
682}
683
684fn actual_run_events(
685    config: &ProductObservabilityConfig,
686    observation: &ActualRunObservation,
687    replay_command: &str,
688) -> Vec<FerrumProfileEvent> {
689    let base = Utc::now();
690    let shutdown_stage_index = observation
691        .memory_stages
692        .iter()
693        .position(|stage| stage.stage == "shutdown")
694        .unwrap_or(observation.memory_stages.len());
695    let mut events = actual_memory_stage_events(
696        config,
697        &observation.request_id,
698        &observation.memory_stages[..shutdown_stage_index],
699        base,
700    );
701    let open = actual_resource_event(
702        config,
703        &observation.request_id,
704        "request",
705        &observation.request_id,
706        "request_slot",
707        "request_open",
708        ResourceAction::RequestOpen,
709        base,
710        None,
711        None,
712        None,
713        Some(1),
714        None,
715    );
716    let reserve = actual_resource_event(
717        config,
718        &observation.request_id,
719        "request",
720        &observation.request_id,
721        "request_slot",
722        "request_slot_reserve",
723        ResourceAction::Reserve,
724        base + Duration::microseconds(5),
725        Some(1),
726        Some(0),
727        Some(1),
728        Some(1),
729        None,
730    );
731    let commit = actual_resource_event(
732        config,
733        &observation.request_id,
734        "request",
735        &observation.request_id,
736        "request_slot",
737        "request_slot_commit",
738        ResourceAction::Commit,
739        base + Duration::microseconds(10),
740        Some(1),
741        Some(0),
742        Some(1),
743        Some(1),
744        None,
745    );
746
747    let mut generation = actual_base_event(
748        config,
749        &observation.request_id,
750        "actual_run_generation",
751        ProfileEventKind::TimedSpan,
752        base + Duration::microseconds(20),
753    );
754    generation.duration_us = Some(observation.duration_us);
755    attach_process_memory(
756        &mut generation,
757        observation.memory.as_ref(),
758        "first_request_done",
759    );
760    generation.attributes.insert(
761        "output_tokens".to_string(),
762        json!(observation.output_tokens),
763    );
764    generation.attributes.insert(
765        "output_token_count".to_string(),
766        json!(observation.output_tokens),
767    );
768    generation.attributes.insert(
769        "completion_token_count".to_string(),
770        json!(observation.output_tokens),
771    );
772    generation.attributes.insert(
773        "e2e_duration_us".to_string(),
774        json!(observation.duration_us),
775    );
776    if let Some(prompt_token_count) = observation.prompt_token_count {
777        generation
778            .attributes
779            .insert("prompt_token_count".to_string(), json!(prompt_token_count));
780        generation.attributes.insert(
781            "total_token_count".to_string(),
782            json!(prompt_token_count.saturating_add(observation.output_tokens)),
783        );
784        generation.attributes.insert(
785            "token_count_source".to_string(),
786            json!("rendered_prompt_and_generated_tokens"),
787        );
788    } else {
789        generation.attributes.insert(
790            "total_token_count".to_string(),
791            json!(observation.output_tokens),
792        );
793        generation
794            .attributes
795            .insert("token_count_source".to_string(), json!("generated_tokens"));
796        generation.attributes.insert(
797            "prompt_token_unavailable_reason".to_string(),
798            json!("run rendered prompt token count was unavailable"),
799        );
800    }
801    generation
802        .attributes
803        .insert("chunk_count".to_string(), json!(observation.chunk_count));
804    generation.attributes.insert(
805        "finish_reason".to_string(),
806        json!(observation.finish_reason.as_deref().unwrap_or("unknown")),
807    );
808    if let Some(timing) = observation
809        .execution_evidence
810        .as_ref()
811        .and_then(|evidence| evidence.engine_token_timing.as_ref())
812    {
813        generation
814            .attributes
815            .extend(ferrum_types::engine_token_timing_profile_attributes(timing));
816    }
817
818    let release = actual_resource_event(
819        config,
820        &observation.request_id,
821        "request",
822        &observation.request_id,
823        "request_slot",
824        "request_slot_release",
825        ResourceAction::Release,
826        base + Duration::microseconds(30),
827        Some(1),
828        Some(1),
829        Some(0),
830        Some(1),
831        None,
832    );
833
834    let mut close = actual_resource_event(
835        config,
836        &observation.request_id,
837        "request",
838        &observation.request_id,
839        "request_slot",
840        "request_close",
841        ResourceAction::RequestClose,
842        base + Duration::microseconds(40),
843        None,
844        None,
845        None,
846        Some(1),
847        None,
848    );
849    close.replay = Some(ReplayReference {
850        command: replay_command.to_string(),
851        bundle_dir: config
852            .request_dump_dir
853            .as_ref()
854            .map(|path| path.to_string_lossy().to_string()),
855    });
856    close
857        .attributes
858        .insert("prompt_chars".to_string(), json!(observation.prompt_chars));
859    close.attributes.insert(
860        "response_chars".to_string(),
861        json!(observation.response_chars),
862    );
863    events.extend([open, reserve, commit, generation, release, close]);
864    events.extend(actual_memory_stage_events(
865        config,
866        &observation.request_id,
867        &observation.memory_stages[shutdown_stage_index..],
868        base + Duration::microseconds(50),
869    ));
870    events
871}
872
873fn actual_run_failure_events(
874    config: &ProductObservabilityConfig,
875    observation: &ActualRunFailureObservation,
876    replay_command: &str,
877) -> Vec<FerrumProfileEvent> {
878    let base = Utc::now();
879    let shutdown_stage_index = observation
880        .memory_stages
881        .iter()
882        .position(|stage| stage.stage == "shutdown")
883        .unwrap_or(observation.memory_stages.len());
884    let mut events = actual_memory_stage_events(
885        config,
886        &observation.request_id,
887        &observation.memory_stages[..shutdown_stage_index],
888        base,
889    );
890    let open = actual_resource_event(
891        config,
892        &observation.request_id,
893        "request",
894        &observation.request_id,
895        "request_slot",
896        "request_open",
897        ResourceAction::RequestOpen,
898        base,
899        None,
900        None,
901        None,
902        Some(1),
903        None,
904    );
905    let reserve = actual_resource_event(
906        config,
907        &observation.request_id,
908        "request",
909        &observation.request_id,
910        "request_slot",
911        "request_slot_reserve",
912        ResourceAction::Reserve,
913        base + Duration::microseconds(5),
914        Some(1),
915        Some(0),
916        Some(1),
917        Some(1),
918        None,
919    );
920    let commit = actual_resource_event(
921        config,
922        &observation.request_id,
923        "request",
924        &observation.request_id,
925        "request_slot",
926        "request_slot_commit",
927        ResourceAction::Commit,
928        base + Duration::microseconds(10),
929        Some(1),
930        Some(0),
931        Some(1),
932        Some(1),
933        None,
934    );
935
936    let mut failure = actual_base_event(
937        config,
938        &observation.request_id,
939        "actual_run_generation_failed",
940        ProfileEventKind::TimedSpan,
941        base + Duration::microseconds(20),
942    );
943    failure.status = ProfileStatus::Failure;
944    failure.duration_us = Some(observation.duration_us);
945    failure.error = Some(ProfileError {
946        kind: observation.error_kind.clone(),
947        message: observation.error_message.clone(),
948        blocking: false,
949    });
950    failure.replay = Some(ReplayReference {
951        command: replay_command.to_string(),
952        bundle_dir: config
953            .request_dump_dir
954            .as_ref()
955            .map(|path| path.to_string_lossy().to_string()),
956    });
957    attach_process_memory(
958        &mut failure,
959        observation.memory.as_ref(),
960        "first_request_failed",
961    );
962    failure
963        .attributes
964        .insert("terminal_failure_event".to_string(), json!(true));
965    failure
966        .attributes
967        .insert("prompt_chars".to_string(), json!(observation.prompt_chars));
968
969    let release = actual_resource_event(
970        config,
971        &observation.request_id,
972        "request",
973        &observation.request_id,
974        "request_slot",
975        "request_slot_release",
976        ResourceAction::Release,
977        base + Duration::microseconds(30),
978        Some(1),
979        Some(1),
980        Some(0),
981        Some(1),
982        None,
983    );
984
985    let mut close = actual_resource_event(
986        config,
987        &observation.request_id,
988        "request",
989        &observation.request_id,
990        "request_slot",
991        "request_close",
992        ResourceAction::RequestClose,
993        base + Duration::microseconds(40),
994        None,
995        None,
996        None,
997        Some(1),
998        None,
999    );
1000    close.replay = Some(ReplayReference {
1001        command: replay_command.to_string(),
1002        bundle_dir: config
1003            .request_dump_dir
1004            .as_ref()
1005            .map(|path| path.to_string_lossy().to_string()),
1006    });
1007    events.extend([open, reserve, commit, failure, release, close]);
1008    events.extend(actual_memory_stage_events(
1009        config,
1010        &observation.request_id,
1011        &observation.memory_stages[shutdown_stage_index..],
1012        base + Duration::microseconds(50),
1013    ));
1014    events
1015}
1016
1017fn actual_memory_stage_events(
1018    config: &ProductObservabilityConfig,
1019    request_id: &str,
1020    stages: &[ActualMemoryStageObservation],
1021    base: chrono::DateTime<Utc>,
1022) -> Vec<FerrumProfileEvent> {
1023    stages
1024        .iter()
1025        .enumerate()
1026        .map(|(index, stage)| {
1027            let mut event = actual_base_event(
1028                config,
1029                request_id,
1030                &stage.phase,
1031                ProfileEventKind::Memory,
1032                base + Duration::microseconds(index as i64),
1033            );
1034            event.duration_us = stage.duration_us;
1035            attach_process_memory(&mut event, stage.memory.as_ref(), &stage.stage);
1036            event.attributes.extend(stage.attributes.clone());
1037            event
1038        })
1039        .collect()
1040}
1041
1042fn actual_serve_startup_events(
1043    config: &ProductObservabilityConfig,
1044    request_id: &str,
1045    startup_duration_us: u64,
1046    startup_memory: Option<&crate::memory_profile::ProcessMemoryObservation>,
1047    memory_stages: &[ActualMemoryStageObservation],
1048    replay_command: &str,
1049) -> Vec<FerrumProfileEvent> {
1050    let base = Utc::now();
1051    let post_model_loaded_index = memory_stages
1052        .iter()
1053        .position(|stage| matches!(stage.stage.as_str(), "profile_run_done" | "cache_allocated"))
1054        .unwrap_or(memory_stages.len());
1055    let mut events = actual_memory_stage_events(
1056        config,
1057        request_id,
1058        &memory_stages[..post_model_loaded_index],
1059        base,
1060    );
1061    let open = actual_resource_event(
1062        config,
1063        request_id,
1064        "server",
1065        request_id,
1066        "startup_slot",
1067        "server_startup_open",
1068        ResourceAction::RequestOpen,
1069        base,
1070        None,
1071        None,
1072        None,
1073        Some(1),
1074        None,
1075    );
1076    let reserve = actual_resource_event(
1077        config,
1078        request_id,
1079        "server",
1080        request_id,
1081        "startup_slot",
1082        "server_startup_reserve",
1083        ResourceAction::Reserve,
1084        base + Duration::microseconds(5),
1085        Some(1),
1086        Some(0),
1087        Some(1),
1088        Some(1),
1089        None,
1090    );
1091    let commit = actual_resource_event(
1092        config,
1093        request_id,
1094        "server",
1095        request_id,
1096        "startup_slot",
1097        "server_startup_commit",
1098        ResourceAction::Commit,
1099        base + Duration::microseconds(10),
1100        Some(1),
1101        Some(0),
1102        Some(1),
1103        Some(1),
1104        None,
1105    );
1106    let mut startup = actual_base_event(
1107        config,
1108        request_id,
1109        "actual_serve_startup",
1110        ProfileEventKind::TimedSpan,
1111        base + Duration::microseconds(20),
1112    );
1113    startup.duration_us = Some(startup_duration_us);
1114    attach_process_memory(&mut startup, startup_memory, "model_loaded");
1115    events.extend([open, reserve, commit, startup]);
1116    events.extend(actual_memory_stage_events(
1117        config,
1118        request_id,
1119        &memory_stages[post_model_loaded_index..],
1120        base + Duration::microseconds(21),
1121    ));
1122
1123    let release = actual_resource_event(
1124        config,
1125        request_id,
1126        "server",
1127        request_id,
1128        "startup_slot",
1129        "server_startup_release",
1130        ResourceAction::Release,
1131        base + Duration::microseconds(30),
1132        Some(1),
1133        Some(1),
1134        Some(0),
1135        Some(1),
1136        None,
1137    );
1138    let mut ready = actual_resource_event(
1139        config,
1140        request_id,
1141        "server",
1142        request_id,
1143        "startup_slot",
1144        "server_ready_for_requests",
1145        ResourceAction::RequestClose,
1146        base + Duration::microseconds(40),
1147        None,
1148        None,
1149        None,
1150        Some(1),
1151        None,
1152    );
1153    ready.replay = Some(ReplayReference {
1154        command: replay_command.to_string(),
1155        bundle_dir: config
1156            .request_dump_dir
1157            .as_ref()
1158            .map(|path| path.to_string_lossy().to_string()),
1159    });
1160    events.extend([release, ready]);
1161    events
1162}
1163
1164fn base_event(
1165    config: &ProductObservabilityConfig,
1166    request_id: &str,
1167    phase: &str,
1168    event_kind: ProfileEventKind,
1169    timestamp: chrono::DateTime<Utc>,
1170) -> FerrumProfileEvent {
1171    FerrumProfileEvent {
1172        schema_version: OBSERVABILITY_PROFILE_SCHEMA_VERSION,
1173        ts_unix_nanos: timestamp
1174            .timestamp_nanos_opt()
1175            .unwrap_or_else(|| timestamp.timestamp_micros() * 1_000),
1176        event_id: format!(
1177            "evt-product-{}-{phase}",
1178            entrypoint_label(config.entrypoint)
1179        ),
1180        request_id: request_id.to_string(),
1181        correlation_id: Some(format!(
1182            "corr-product-{}",
1183            entrypoint_label(config.entrypoint)
1184        )),
1185        entrypoint: config.entrypoint,
1186        backend: SYNTHETIC_BACKEND.to_string(),
1187        runtime_preset_hash: runtime_preset_hash(config),
1188        phase: phase.to_string(),
1189        event_kind,
1190        timestamp,
1191        status: ProfileStatus::Ok,
1192        model: Some(config.model.clone()),
1193        duration_us: None,
1194        memory: None,
1195        resource: None,
1196        error: None,
1197        replay: None,
1198        shape: default_event_shape(),
1199        backend_detail: None,
1200        attributes: common_attrs(config),
1201    }
1202}
1203
1204fn actual_base_event(
1205    config: &ProductObservabilityConfig,
1206    request_id: &str,
1207    phase: &str,
1208    event_kind: ProfileEventKind,
1209    timestamp: chrono::DateTime<Utc>,
1210) -> FerrumProfileEvent {
1211    let mut event = base_event(config, request_id, phase, event_kind, timestamp);
1212    event.backend = "actual".to_string();
1213    event.attributes = actual_attrs(config);
1214    event.attributes.insert(
1215        "execution_request_id".to_string(),
1216        json!(format!("request.product.{request_id}")),
1217    );
1218    event
1219}
1220
1221fn runtime_preset_hash(config: &ProductObservabilityConfig) -> String {
1222    let mut hasher = Sha256::new();
1223    hasher.update(config.entrypoint.as_str().as_bytes());
1224    hasher.update(b"\0");
1225    hasher.update(config.model.as_bytes());
1226    hasher.update(b"\0");
1227    hasher.update(config.profile_detail.as_str().as_bytes());
1228    hasher.update(b"\0");
1229    hasher.update(config.profile_sample_rate.to_string().as_bytes());
1230    format!("sha256:{:x}", hasher.finalize())
1231}
1232
1233fn default_event_shape() -> BTreeMap<String, Value> {
1234    BTreeMap::from([("batch_size".to_string(), json!(1))])
1235}
1236
1237#[allow(clippy::too_many_arguments)]
1238fn resource_event(
1239    config: &ProductObservabilityConfig,
1240    request_id: &str,
1241    owner_kind: &str,
1242    owner_id: &str,
1243    resource_kind: &str,
1244    phase: &str,
1245    action: ResourceAction,
1246    timestamp: chrono::DateTime<Utc>,
1247    amount: Option<i64>,
1248    before: Option<i64>,
1249    after: Option<i64>,
1250    capacity: Option<i64>,
1251    reason: Option<&str>,
1252) -> FerrumProfileEvent {
1253    let mut event = base_event(
1254        config,
1255        request_id,
1256        phase,
1257        ProfileEventKind::Resource,
1258        timestamp,
1259    );
1260    event.resource = Some(ResourceTraceEvent {
1261        owner_kind: owner_kind.to_string(),
1262        owner_id: owner_id.to_string(),
1263        resource_kind: resource_kind.to_string(),
1264        action,
1265        amount,
1266        before,
1267        after,
1268        capacity,
1269        underflow_amount: match (action, amount, before) {
1270            (ResourceAction::Release | ResourceAction::Rollback, Some(amount), Some(before))
1271                if amount > before =>
1272            {
1273                Some(amount.saturating_sub(before))
1274            }
1275            _ => None,
1276        },
1277        reason: reason.map(str::to_string),
1278        error_kind: None,
1279        message: None,
1280        resource_error_kind: None,
1281    });
1282    event
1283}
1284
1285#[allow(clippy::too_many_arguments)]
1286fn actual_resource_event(
1287    config: &ProductObservabilityConfig,
1288    request_id: &str,
1289    owner_kind: &str,
1290    owner_id: &str,
1291    resource_kind: &str,
1292    phase: &str,
1293    action: ResourceAction,
1294    timestamp: chrono::DateTime<Utc>,
1295    amount: Option<i64>,
1296    before: Option<i64>,
1297    after: Option<i64>,
1298    capacity: Option<i64>,
1299    reason: Option<&str>,
1300) -> FerrumProfileEvent {
1301    let mut event = resource_event(
1302        config,
1303        request_id,
1304        owner_kind,
1305        owner_id,
1306        resource_kind,
1307        phase,
1308        action,
1309        timestamp,
1310        amount,
1311        before,
1312        after,
1313        capacity,
1314        reason,
1315    );
1316    event.backend = "actual".to_string();
1317    event.attributes = actual_attrs(config);
1318    event
1319}
1320
1321fn attach_process_memory(
1322    event: &mut FerrumProfileEvent,
1323    observation: Option<&crate::memory_profile::ProcessMemoryObservation>,
1324    stage: &str,
1325) {
1326    if let Some(observation) = observation {
1327        event.memory = Some(observation.to_snapshot("process", Some("actual")));
1328        event
1329            .attributes
1330            .insert("memory_measurement".to_string(), json!("process_rss"));
1331        event
1332            .attributes
1333            .insert("memory_stage".to_string(), json!(stage));
1334        event.attributes.insert(
1335            "process_memory_source".to_string(),
1336            json!(observation.source),
1337        );
1338    } else {
1339        event.memory = Some(MemorySnapshot {
1340            scope: "process".to_string(),
1341            backend: Some("actual".to_string()),
1342            before_bytes: Some(0),
1343            after_bytes: Some(0),
1344            current_bytes: Some(0),
1345            high_water_bytes: Some(0),
1346            available_bytes: None,
1347        });
1348        event
1349            .attributes
1350            .insert("memory_measurement".to_string(), json!("not_collected"));
1351        event
1352            .attributes
1353            .insert("memory_stage".to_string(), json!(stage));
1354    }
1355}
1356
1357fn common_attrs(config: &ProductObservabilityConfig) -> BTreeMap<String, Value> {
1358    BTreeMap::from([
1359        (
1360            "profile_detail".to_string(),
1361            json!(config.profile_detail.as_str()),
1362        ),
1363        (
1364            "profile_sample_rate".to_string(),
1365            json!(config.profile_sample_rate),
1366        ),
1367        (
1368            "diagnostic_only".to_string(),
1369            json!(config.profile_detail.diagnostic_only()),
1370        ),
1371        ("l0_only".to_string(), json!(true)),
1372    ])
1373}
1374
1375fn actual_attrs(config: &ProductObservabilityConfig) -> BTreeMap<String, Value> {
1376    BTreeMap::from([
1377        (
1378            "profile_detail".to_string(),
1379            json!(config.profile_detail.as_str()),
1380        ),
1381        (
1382            "profile_sample_rate".to_string(),
1383            json!(config.profile_sample_rate),
1384        ),
1385        (
1386            "diagnostic_only".to_string(),
1387            json!(config.profile_detail.diagnostic_only()),
1388        ),
1389        ("l0_only".to_string(), json!(false)),
1390        ("actual_model_smoke".to_string(), json!(true)),
1391    ])
1392}
1393
1394struct ReplayBundleData<'a> {
1395    request: serde_json::Value,
1396    prompt_token_ids: Option<Vec<u32>>,
1397    prompt_token_count: Option<usize>,
1398    prompt_token_unavailable_reason: Option<&'a str>,
1399    sampling_params: Option<SamplingParams>,
1400    backend: &'a str,
1401    actual_model_smoke: bool,
1402    output_token_ids: Option<Vec<u32>>,
1403    output_text: Option<&'a str>,
1404    finish_reason: Option<&'a str>,
1405    failure_kind: Option<&'a str>,
1406    failure_diagnostics: Option<serde_json::Value>,
1407}
1408
1409fn write_replay_bundle(
1410    root: &Path,
1411    config: &ProductObservabilityConfig,
1412    request_id: &str,
1413    replay_command: &str,
1414    data: ReplayBundleData<'_>,
1415) -> Result<Vec<PathBuf>> {
1416    fs_create_dir_all(root)?;
1417    let bundle_dir = root.join(request_id);
1418    fs_create_dir_all(&bundle_dir)?;
1419    let mut written = Vec::new();
1420
1421    let request_path = root.join("request.json");
1422    let replay_path = root.join("replay_command.txt");
1423    write_json(&request_path, &data.request)?;
1424    fs_write(&replay_path, format!("{replay_command}\n"))?;
1425    written.push(request_path);
1426    written.push(replay_path);
1427
1428    let prompt_token_count = data
1429        .prompt_token_count
1430        .or_else(|| data.prompt_token_ids.as_ref().map(Vec::len));
1431    let output_token_count = data.output_token_ids.as_ref().map(Vec::len).unwrap_or(0);
1432    let prompt_tokens = json!({
1433        "schema_version": OBSERVABILITY_PROFILE_SCHEMA_VERSION,
1434        "request_id": request_id,
1435        "model": config.model,
1436        "tokenizer_or_model": config.model,
1437        "token_ids": data.prompt_token_ids,
1438        "token_count": prompt_token_count,
1439        "unavailable_reason": data.prompt_token_unavailable_reason,
1440        "sanitized": true
1441    });
1442    let output_text = data.output_text.unwrap_or("");
1443    let sampling_unavailable_reason = if data.sampling_params.is_some() {
1444        Value::Null
1445    } else {
1446        json!("sampling params unavailable for this replay bundle kind in WP9 L0")
1447    };
1448    let output_text_body = if data.actual_model_smoke && config.model != SYNTHETIC_MODEL {
1449        format!(
1450            "[redacted actual output]\nsha256={}\nchars={}\n",
1451            sha256_hex(output_text.as_bytes()),
1452            output_text.chars().count()
1453        )
1454    } else {
1455        format!("{output_text}\n")
1456    };
1457    let output_scan = bad_output_scan(
1458        request_id,
1459        output_text,
1460        data.failure_kind,
1461        output_text_body.as_bytes(),
1462    );
1463    let engine_replay_args = engine_replay_command_args(&bundle_dir);
1464    let engine_replay_command = replay_command_from_args(&engine_replay_args);
1465    let files = [
1466        ("request.json", data.request),
1467        ("prompt_token_ids.json", prompt_tokens),
1468        (
1469            "sampling_params.json",
1470            json!({
1471                "schema_version": OBSERVABILITY_PROFILE_SCHEMA_VERSION,
1472                "request_id": request_id,
1473                "sampling_params": data.sampling_params,
1474                "unavailable_reason": sampling_unavailable_reason
1475            }),
1476        ),
1477        (
1478            "runtime_effective_config.json",
1479            json!({
1480                "schema_version": OBSERVABILITY_PROFILE_SCHEMA_VERSION,
1481                "request_id": request_id,
1482                "entrypoint": entrypoint_label(config.entrypoint),
1483                "profile_detail": config.profile_detail.as_str(),
1484                "profile_sample_rate": config.profile_sample_rate,
1485                "profile_jsonl": config.profile_jsonl.as_ref().map(|path| path.to_string_lossy().to_string()),
1486                "memory_profile_jsonl": config.memory_profile_jsonl.as_ref().map(|path| path.to_string_lossy().to_string()),
1487                "scheduler_trace_jsonl": config.scheduler_trace_jsonl.as_ref().map(|path| path.to_string_lossy().to_string()),
1488                "request_dump_dir": Some(root.to_string_lossy().to_string()),
1489                "sanitized": true
1490            }),
1491        ),
1492        (
1493            "backend_selection.json",
1494            json!({
1495                "schema_version": OBSERVABILITY_PROFILE_SCHEMA_VERSION,
1496                "request_id": request_id,
1497                "backend": data.backend,
1498                "model": config.model,
1499                "actual_model_smoke": data.actual_model_smoke
1500            }),
1501        ),
1502        (
1503            "output_token_ids.json",
1504            json!({
1505                "schema_version": OBSERVABILITY_PROFILE_SCHEMA_VERSION,
1506                "request_id": request_id,
1507                "token_ids": data.output_token_ids.unwrap_or_default(),
1508                "token_count": output_token_count,
1509                "finish_reason": data.finish_reason
1510            }),
1511        ),
1512        ("bad_output_scan.json", output_scan),
1513        (
1514            "replay.command.json",
1515            json!({
1516                "schema_version": OBSERVABILITY_PROFILE_SCHEMA_VERSION,
1517                "request_id": request_id,
1518                "entrypoint": entrypoint_label(config.entrypoint),
1519                "command": replay_command,
1520                "argv": replay_command_args(config),
1521                "bundle_dir": bundle_dir.to_string_lossy(),
1522                "engine_replay": {
1523                    "mode": "bundle_offline",
1524                    "requires_http_server": false,
1525                    "command": engine_replay_command,
1526                    "argv": engine_replay_args
1527                },
1528                "sanitized": true
1529            }),
1530        ),
1531    ];
1532    for (name, value) in files {
1533        let path = bundle_dir.join(name);
1534        write_json(&path, &value)?;
1535        written.push(path);
1536    }
1537    if let Some(diagnostics) = data.failure_diagnostics {
1538        let path = bundle_dir.join("failure_diagnostics.json");
1539        write_json(&path, &diagnostics)?;
1540        written.push(path);
1541    }
1542    let output_text_path = bundle_dir.join("output_text.txt");
1543    fs_write(&output_text_path, output_text_body)?;
1544    written.push(output_text_path);
1545    Ok(written)
1546}
1547
1548fn actual_run_failure_diagnostics(observation: &ActualRunFailureObservation) -> serde_json::Value {
1549    if resource_failure_kind(&observation.failure_kind) {
1550        return actual_run_resource_failure_diagnostics(observation);
1551    }
1552    json!({
1553        "schema_version": OBSERVABILITY_PROFILE_SCHEMA_VERSION,
1554        "request_id": observation.request_id,
1555        "failure_kind": observation.failure_kind,
1556        "first_failure_event": {
1557            "phase": "actual_run_generation_failed",
1558            "error_kind": observation.error_kind,
1559            "message": observation.error_message
1560        },
1561        "nearest_request_id": observation.request_id,
1562        "log_excerpt": observation.error_message
1563    })
1564}
1565
1566fn actual_run_resource_failure_diagnostics(
1567    observation: &ActualRunFailureObservation,
1568) -> serde_json::Value {
1569    let memory_current = observation
1570        .memory
1571        .as_ref()
1572        .map(|memory| memory.current_bytes as i64)
1573        .unwrap_or(0)
1574        .max(0);
1575    let memory_high_water = observation
1576        .memory
1577        .as_ref()
1578        .map(|memory| memory.high_water_bytes as i64)
1579        .unwrap_or(memory_current);
1580    let resource_kind = resource_kind_for_failure(&observation.failure_kind);
1581    let needed = if resource_kind == "device_memory" {
1582        memory_current.saturating_add(1).max(1)
1583    } else {
1584        observation
1585            .prompt_token_count
1586            .and_then(|tokens| i64::try_from(tokens).ok())
1587            .unwrap_or(1)
1588            .max(1)
1589    };
1590    let capacity = if resource_kind == "device_memory" {
1591        memory_high_water.max(memory_current)
1592    } else {
1593        0
1594    };
1595    json!({
1596        "schema_version": OBSERVABILITY_PROFILE_SCHEMA_VERSION,
1597        "request_id": observation.request_id,
1598        "failure_kind": observation.failure_kind,
1599        "first_failure_event": {
1600            "phase": "actual_run_generation_failed",
1601            "error_kind": observation.error_kind,
1602            "message": observation.error_message
1603        },
1604        "nearest_request_id": observation.request_id,
1605        "log_excerpt": observation.error_message,
1606        "capacity": {
1607            "resource_kind": resource_kind,
1608            "needed": needed,
1609            "available": 0,
1610            "capacity": capacity,
1611            "reason": observation.error_message
1612        },
1613        "nearest_resource_event": {
1614            "owner_kind": "request",
1615            "owner_id": observation.request_id,
1616            "resource_kind": resource_kind,
1617            "action": "reject",
1618            "amount": needed,
1619            "before": 0,
1620            "after": 0,
1621            "capacity": capacity,
1622            "reason": observation.error_message
1623        },
1624        "nearest_memory_snapshot": {
1625            "scope": "actual_run_failure",
1626            "backend": "process",
1627            "current_bytes": memory_current,
1628            "high_water_bytes": memory_high_water.max(memory_current),
1629            "source": observation.memory.as_ref().map(|memory| memory.source).unwrap_or("not_collected")
1630        }
1631    })
1632}
1633
1634fn resource_failure_kind(failure_kind: &str) -> bool {
1635    matches!(
1636        failure_kind,
1637        "oom" | "prevented_oom" | "admission" | "admission_reject" | "oom_admission"
1638    )
1639}
1640
1641fn resource_kind_for_failure(failure_kind: &str) -> &'static str {
1642    match failure_kind {
1643        "oom" | "prevented_oom" => "device_memory",
1644        _ => "admission_capacity",
1645    }
1646}
1647
1648fn bad_output_scan(
1649    request_id: &str,
1650    text: &str,
1651    failure_kind: Option<&str>,
1652    output_artifact_bytes: &[u8],
1653) -> serde_json::Value {
1654    let mut reasons = Vec::new();
1655    let mut first_span: Option<serde_json::Value> = None;
1656    for (needle, reason) in [
1657        ("<unk>", "reserved_token"),
1658        ("[PAD", "reserved_token"),
1659        ("<pad>", "reserved_token"),
1660        ("<|endoftext|>", "reserved_token"),
1661        ("<|im_start|>", "reserved_token"),
1662        ("<|im_end|>", "reserved_token"),
1663        ("<|reserved_special_token", "reserved_token"),
1664    ] {
1665        if let Some(index) = text.find(needle) {
1666            reasons.push(reason);
1667            first_span.get_or_insert_with(|| {
1668                json!({
1669                    "byte_start": index,
1670                    "byte_end": index + needle.len(),
1671                    "text": needle,
1672                    "reason": reason
1673                })
1674            });
1675        }
1676    }
1677    if let Some(index) = first_mojibake_index(text) {
1678        reasons.push("mojibake");
1679        first_span.get_or_insert_with(|| {
1680            json!({
1681                "byte_start": index,
1682                "byte_end": index + 1,
1683                "reason": "mojibake"
1684            })
1685        });
1686    }
1687    reasons.sort_unstable();
1688    reasons.dedup();
1689    let bad_output = !reasons.is_empty();
1690    json!({
1691        "schema_version": OBSERVABILITY_PROFILE_SCHEMA_VERSION,
1692        "request_id": request_id,
1693        "bad_output": bad_output,
1694        "bad_text_count": if bad_output { 1 } else { 0 },
1695        "reasons": reasons,
1696        "first_bad_text_span": first_span,
1697        "failure_kind": failure_kind,
1698        "output_chars": text.chars().count(),
1699        "classified_output_sha256": sha256_hex(text.as_bytes()),
1700        "output_sha256": sha256_hex(output_artifact_bytes)
1701    })
1702}
1703
1704fn first_mojibake_index(text: &str) -> Option<usize> {
1705    ["\u{00c3}\u{00a9}", "\u{00c2}\u{00a9}", "\u{00e2}\u{20ac}"]
1706        .iter()
1707        .filter_map(|needle| text.find(needle))
1708        .min()
1709}
1710
1711fn sha256_hex(bytes: &[u8]) -> String {
1712    let mut hasher = Sha256::new();
1713    hasher.update(bytes);
1714    format!("{:x}", hasher.finalize())
1715}
1716
1717fn request_dump(
1718    config: &ProductObservabilityConfig,
1719    request_id: &str,
1720    replay_command: &str,
1721) -> serde_json::Value {
1722    let entrypoint = entrypoint_label(config.entrypoint);
1723    match config.entrypoint {
1724        ProfileEntrypoint::Run => json!({
1725            "schema_version": OBSERVABILITY_PROFILE_SCHEMA_VERSION,
1726            "entrypoint": entrypoint,
1727            "request_id": request_id,
1728            "model": config.model,
1729            "backend": SYNTHETIC_BACKEND,
1730            "profile_detail": config.profile_detail.as_str(),
1731            "profile_sample_rate": config.profile_sample_rate,
1732            "l0_only": true,
1733            "sanitized": true,
1734            "prompt": "product observability wiring",
1735            "replay_command": replay_command
1736        }),
1737        ProfileEntrypoint::Serve => json!({
1738            "schema_version": OBSERVABILITY_PROFILE_SCHEMA_VERSION,
1739            "entrypoint": entrypoint,
1740            "request_id": request_id,
1741            "model": config.model,
1742            "backend": SYNTHETIC_BACKEND,
1743            "profile_detail": config.profile_detail.as_str(),
1744            "profile_sample_rate": config.profile_sample_rate,
1745            "l0_only": true,
1746            "sanitized": true,
1747            "http": {
1748                "method": "POST",
1749                "path": "/v1/chat/completions",
1750                "body": {
1751                    "model": config.model,
1752                    "messages": [{"role": "user", "content": "product observability wiring"}],
1753                    "stream": false
1754                }
1755            },
1756            "replay_command": replay_command
1757        }),
1758        other => json!({
1759            "schema_version": OBSERVABILITY_PROFILE_SCHEMA_VERSION,
1760            "entrypoint": entrypoint_label(other),
1761            "request_id": request_id,
1762            "model": config.model,
1763            "backend": SYNTHETIC_BACKEND,
1764            "profile_detail": config.profile_detail.as_str(),
1765            "profile_sample_rate": config.profile_sample_rate,
1766            "l0_only": true,
1767            "sanitized": true,
1768            "replay_command": replay_command
1769        }),
1770    }
1771}
1772
1773fn actual_request_dump(
1774    config: &ProductObservabilityConfig,
1775    request_id: &str,
1776    replay_command: &str,
1777) -> serde_json::Value {
1778    json!({
1779        "schema_version": OBSERVABILITY_PROFILE_SCHEMA_VERSION,
1780        "entrypoint": entrypoint_label(config.entrypoint),
1781        "request_id": request_id,
1782        "model": config.model,
1783        "backend": "actual",
1784        "profile_detail": config.profile_detail.as_str(),
1785        "profile_sample_rate": config.profile_sample_rate,
1786        "l0_only": false,
1787        "actual_model_smoke": true,
1788        "sanitized": true,
1789        "replay_command": replay_command
1790    })
1791}
1792
1793fn replay_command(config: &ProductObservabilityConfig) -> String {
1794    replay_command_from_args(&replay_command_args(config))
1795}
1796
1797fn replay_command_from_args(args: &[String]) -> String {
1798    args.iter()
1799        .map(|part| shell_quote(part))
1800        .collect::<Vec<_>>()
1801        .join(" ")
1802}
1803
1804fn replay_command_args(config: &ProductObservabilityConfig) -> Vec<String> {
1805    let mut parts = vec![
1806        "cargo".to_string(),
1807        "run".to_string(),
1808        "-p".to_string(),
1809        "ferrum-cli".to_string(),
1810        "--".to_string(),
1811        entrypoint_label(config.entrypoint).to_string(),
1812        SYNTHETIC_MODEL.to_string(),
1813        "--profile-detail".to_string(),
1814        config.profile_detail.as_str().to_string(),
1815        "--profile-sample-rate".to_string(),
1816        config.profile_sample_rate.to_string(),
1817    ];
1818    push_path_arg(&mut parts, "--profile-jsonl", config.profile_jsonl.as_ref());
1819    push_path_arg(
1820        &mut parts,
1821        "--memory-profile-jsonl",
1822        config.memory_profile_jsonl.as_ref(),
1823    );
1824    push_path_arg(
1825        &mut parts,
1826        "--scheduler-trace-jsonl",
1827        config.scheduler_trace_jsonl.as_ref(),
1828    );
1829    push_path_arg(
1830        &mut parts,
1831        "--request-dump-dir",
1832        config.request_dump_dir.as_ref(),
1833    );
1834    parts
1835}
1836
1837fn engine_replay_command_args(bundle_dir: &Path) -> Vec<String> {
1838    vec![
1839        "cargo".to_string(),
1840        "run".to_string(),
1841        "-p".to_string(),
1842        "ferrum-cli".to_string(),
1843        "--".to_string(),
1844        "replay-bundle".to_string(),
1845        bundle_dir.to_string_lossy().to_string(),
1846        "--out".to_string(),
1847        bundle_dir
1848            .join("engine_replay")
1849            .to_string_lossy()
1850            .to_string(),
1851        "--json".to_string(),
1852    ]
1853}
1854
1855fn push_path_arg(parts: &mut Vec<String>, flag: &str, path: Option<&PathBuf>) {
1856    if let Some(path) = path {
1857        parts.push(flag.to_string());
1858        parts.push(path.to_string_lossy().to_string());
1859    }
1860}
1861
1862#[cfg(test)]
1863fn write_profile_jsonl(path: &Path, events: &[FerrumProfileEvent]) -> Result<()> {
1864    write_profile_events(
1865        path,
1866        ferrum_bench_core::JsonlJournalOpenMode::Truncate,
1867        events,
1868    )
1869}
1870
1871#[cfg(test)]
1872fn append_profile_jsonl(path: &Path, events: &[FerrumProfileEvent]) -> Result<()> {
1873    write_profile_events(
1874        path,
1875        ferrum_bench_core::JsonlJournalOpenMode::Append,
1876        events,
1877    )
1878}
1879
1880fn write_profile_events(
1881    path: &Path,
1882    mode: ferrum_bench_core::JsonlJournalOpenMode,
1883    events: &[FerrumProfileEvent],
1884) -> Result<()> {
1885    if events.is_empty() {
1886        return Err(FerrumError::internal("profile event set must be non-empty"));
1887    }
1888    for event in events {
1889        event.validate().map_err(|err| {
1890            FerrumError::internal(format!("invalid product observability event: {err}"))
1891        })?;
1892    }
1893    ferrum_bench_core::write_jsonl_records(path, mode, events)
1894        .map_err(|error| FerrumError::io(error.to_string()))
1895}
1896
1897fn write_json(path: &Path, value: &serde_json::Value) -> Result<()> {
1898    let body = serde_json::to_string_pretty(value)
1899        .map_err(|err| FerrumError::serialization(format!("failed to serialize JSON: {err}")))?;
1900    fs_write(path, format!("{body}\n"))
1901}
1902
1903fn fs_create_dir_all(path: &Path) -> Result<()> {
1904    fs::create_dir_all(path)
1905        .map_err(|err| FerrumError::io(format!("failed to create {}: {err}", path.display())))
1906}
1907
1908fn fs_write(path: &Path, content: impl AsRef<[u8]>) -> Result<()> {
1909    if let Some(parent) = path.parent() {
1910        fs_create_dir_all(parent)?;
1911    }
1912    fs::write(path, content)
1913        .map_err(|err| FerrumError::io(format!("failed to write {}: {err}", path.display())))
1914}
1915
1916fn entrypoint_label(entrypoint: ProfileEntrypoint) -> &'static str {
1917    match entrypoint {
1918        ProfileEntrypoint::Run => "run",
1919        ProfileEntrypoint::Serve => "serve",
1920        ProfileEntrypoint::BenchServe => "bench_serve",
1921        ProfileEntrypoint::Synthetic => "synthetic",
1922    }
1923}
1924
1925fn shell_quote(value: &str) -> String {
1926    if value
1927        .chars()
1928        .all(|ch| ch.is_ascii_alphanumeric() || "-_./:".contains(ch))
1929    {
1930        return value.to_string();
1931    }
1932    format!("'{}'", value.replace('\'', "'\\''"))
1933}
1934
1935#[cfg(test)]
1936mod tests {
1937    use super::*;
1938
1939    #[test]
1940    fn engine_cache_observation_does_not_report_static_weights_as_kv() {
1941        let status = ferrum_types::EngineStatus {
1942            is_ready: true,
1943            loaded_models: vec![ferrum_types::ModelId::from("test-model")],
1944            active_requests: 0,
1945            queued_requests: 0,
1946            memory_usage: ferrum_types::MemoryUsage {
1947                total_bytes: 900,
1948                used_bytes: 500,
1949                free_bytes: 400,
1950                gpu_memory_bytes: Some(500),
1951                cpu_memory_bytes: None,
1952                cache_memory_bytes: 100,
1953                utilization_percent: 500.0 / 9.0,
1954            },
1955            uptime_seconds: 0,
1956            last_heartbeat: chrono::Utc::now(),
1957            version: "test".to_string(),
1958        };
1959
1960        let observation = ActualMemoryStageObservation::new("test", "cache_allocated", None, None)
1961            .with_engine_cache_status(&status);
1962
1963        assert_eq!(observation.attributes["kv_cache_total_bytes"], 500);
1964        assert_eq!(observation.attributes["kv_cache_used_bytes"], 100);
1965        assert_eq!(observation.attributes["resource_total_bytes"], 900);
1966        assert_eq!(observation.attributes["resource_used_bytes"], 500);
1967    }
1968
1969    #[test]
1970    fn synthetic_product_observability_writes_profile_paths() {
1971        let root = std::env::temp_dir().join(format!(
1972            "ferrum-product-observability-{}",
1973            Uuid::new_v4().simple()
1974        ));
1975        let config = ProductObservabilityConfig::new(
1976            ProfileEntrypoint::Run,
1977            SYNTHETIC_MODEL,
1978            Some(&root.join("profile.jsonl")),
1979            ProfileDetailArg::Basic,
1980            Some(&root.join("memory.jsonl")),
1981            Some(&root.join("scheduler.jsonl")),
1982            Some(&root.join("request_dump")),
1983            1.0,
1984        );
1985        let written = write_synthetic_product_observability(&config).unwrap();
1986        assert!(written.len() >= 14);
1987        assert!(root.join("profile.jsonl").is_file());
1988        assert!(root.join("memory.jsonl").is_file());
1989        assert!(root.join("scheduler.jsonl").is_file());
1990        assert!(root.join("request_dump/request.json").is_file());
1991        assert!(root.join("request_dump/replay_command.txt").is_file());
1992        let request_dump_root = root.join("request_dump");
1993        let bundle_dir = fs::read_dir(&request_dump_root)
1994            .unwrap()
1995            .flatten()
1996            .find_map(|entry| entry.path().is_dir().then_some(entry.path()))
1997            .expect("request-id replay bundle directory should exist");
1998        assert!(bundle_dir.join("prompt_token_ids.json").is_file());
1999        assert!(bundle_dir.join("sampling_params.json").is_file());
2000        assert!(bundle_dir.join("runtime_effective_config.json").is_file());
2001        assert!(bundle_dir.join("backend_selection.json").is_file());
2002        assert!(bundle_dir.join("output_token_ids.json").is_file());
2003        assert!(bundle_dir.join("output_text.txt").is_file());
2004        assert!(bundle_dir.join("bad_output_scan.json").is_file());
2005        assert!(bundle_dir.join("replay.command.json").is_file());
2006        let replay: serde_json::Value = serde_json::from_str(
2007            &fs::read_to_string(bundle_dir.join("replay.command.json")).unwrap(),
2008        )
2009        .unwrap();
2010        let engine_argv = replay["engine_replay"]["argv"].as_array().unwrap();
2011        assert!(engine_argv.iter().any(|item| item == "replay-bundle"));
2012        assert_eq!(replay["engine_replay"]["requires_http_server"], false);
2013        fs::remove_dir_all(root).ok();
2014    }
2015
2016    #[test]
2017    fn aliased_profile_roles_write_each_event_once() {
2018        let root = std::env::temp_dir().join(format!(
2019            "ferrum-product-observability-alias-{}",
2020            Uuid::new_v4().simple()
2021        ));
2022        let combined = root.join("combined.jsonl");
2023        let memory_alias = root.join(".").join("combined.jsonl");
2024        let scheduler_alias = root.join("not-created").join("..").join("combined.jsonl");
2025        let config = ProductObservabilityConfig::new(
2026            ProfileEntrypoint::Run,
2027            SYNTHETIC_MODEL,
2028            Some(&combined),
2029            ProfileDetailArg::Resource,
2030            Some(&memory_alias),
2031            Some(&scheduler_alias),
2032            None,
2033            1.0,
2034        );
2035
2036        let written = write_synthetic_product_observability(&config).unwrap();
2037        assert_eq!(written.len(), 1);
2038        let events = fs::read_to_string(&combined)
2039            .unwrap()
2040            .lines()
2041            .map(|line| serde_json::from_str::<serde_json::Value>(line).unwrap())
2042            .collect::<Vec<_>>();
2043        assert_eq!(
2044            events.len(),
2045            6,
2046            "aliased roles duplicated events: {events:#?}"
2047        );
2048        assert_eq!(
2049            events
2050                .iter()
2051                .filter_map(|event| event["event_id"].as_str())
2052                .collect::<std::collections::BTreeSet<_>>()
2053                .len(),
2054            6
2055        );
2056        fs::remove_dir_all(root).ok();
2057    }
2058
2059    #[test]
2060    fn actual_serve_memory_stage_observability_appends_shutdown() {
2061        let root = std::env::temp_dir().join(format!(
2062            "ferrum-serve-memory-observability-{}",
2063            Uuid::new_v4().simple()
2064        ));
2065        let config = ProductObservabilityConfig::new(
2066            ProfileEntrypoint::Serve,
2067            "Qwen/Qwen3-0.6B",
2068            Some(&root.join("profile.jsonl")),
2069            ProfileDetailArg::Basic,
2070            Some(&root.join("memory.jsonl")),
2071            Some(&root.join("scheduler.jsonl")),
2072            Some(&root.join("request_dump")),
2073            1.0,
2074        );
2075        let memory = crate::memory_profile::ProcessMemoryObservation {
2076            before_bytes: 100,
2077            after_bytes: 200,
2078            current_bytes: 200,
2079            high_water_bytes: 240,
2080            source: "test",
2081        };
2082        write_actual_serve_startup_observability(
2083            &config,
2084            42,
2085            Some(memory.clone()),
2086            vec![
2087                ActualMemoryStageObservation::new(
2088                    "actual_serve_process_start",
2089                    "process_start",
2090                    None,
2091                    Some(memory.clone()),
2092                ),
2093                ActualMemoryStageObservation::new(
2094                    "actual_serve_backend_initialized",
2095                    "backend_initialized",
2096                    None,
2097                    Some(memory.clone()),
2098                ),
2099            ],
2100        )
2101        .unwrap();
2102        append_actual_serve_memory_stage_observability(
2103            &config,
2104            ActualMemoryStageObservation::new(
2105                "actual_serve_shutdown",
2106                "shutdown",
2107                None,
2108                Some(memory),
2109            ),
2110        )
2111        .unwrap();
2112        let profile = fs::read_to_string(root.join("profile.jsonl")).unwrap();
2113        assert!(profile.contains("\"phase\":\"actual_serve_startup\""));
2114        assert!(profile.contains("\"phase\":\"actual_serve_shutdown\""));
2115        let memory_profile = fs::read_to_string(root.join("memory.jsonl")).unwrap();
2116        let memory_stages = memory_profile
2117            .lines()
2118            .filter(|line| !line.trim().is_empty())
2119            .map(|line| serde_json::from_str::<serde_json::Value>(line).unwrap())
2120            .filter_map(|event| {
2121                event["attributes"]["memory_stage"]
2122                    .as_str()
2123                    .map(str::to_string)
2124            })
2125            .collect::<Vec<_>>();
2126        assert!(memory_stages.contains(&"process_start".to_string()));
2127        assert!(memory_stages.contains(&"backend_initialized".to_string()));
2128        assert!(memory_stages.contains(&"model_loaded".to_string()));
2129        assert!(memory_stages.contains(&"shutdown".to_string()));
2130        fs::remove_dir_all(root).ok();
2131    }
2132
2133    #[test]
2134    fn profile_jsonl_append_is_parseable_under_concurrent_writers() {
2135        let root = std::env::temp_dir().join(format!(
2136            "ferrum-profile-concurrent-append-{}",
2137            Uuid::new_v4().simple()
2138        ));
2139        let path = root.join("profile.jsonl");
2140        let config = ProductObservabilityConfig::new(
2141            ProfileEntrypoint::Serve,
2142            "Qwen/Qwen3-0.6B",
2143            Some(&path),
2144            ProfileDetailArg::Basic,
2145            None,
2146            None,
2147            Some(&root.join("request_dump")),
2148            1.0,
2149        );
2150
2151        let mut handles = Vec::new();
2152        for writer in 0..8 {
2153            let path = path.clone();
2154            let config = config.clone();
2155            handles.push(std::thread::spawn(move || {
2156                for seq in 0..32 {
2157                    let request_id = format!("req-{writer}-{seq}");
2158                    let mut event = actual_base_event(
2159                        &config,
2160                        &request_id,
2161                        "chat_completions_sync_complete",
2162                        ProfileEventKind::TimedSpan,
2163                        Utc::now(),
2164                    );
2165                    event.event_id = format!("evt-{writer}-{seq}");
2166                    event.correlation_id = Some(format!("corr-{writer}-{seq}"));
2167                    event.duration_us = Some(1);
2168                    event.attributes.insert("writer".to_string(), json!(writer));
2169                    event.attributes.insert("seq".to_string(), json!(seq));
2170                    append_profile_jsonl(&path, &[event]).unwrap();
2171                }
2172            }));
2173        }
2174
2175        for handle in handles {
2176            handle.join().unwrap();
2177        }
2178
2179        let profile = fs::read_to_string(&path).unwrap();
2180        let mut parsed = 0usize;
2181        for line in profile.lines().filter(|line| !line.trim().is_empty()) {
2182            serde_json::from_str::<serde_json::Value>(line).unwrap();
2183            parsed += 1;
2184        }
2185        assert_eq!(parsed, 8 * 32);
2186        fs::remove_dir_all(root).ok();
2187    }
2188
2189    #[test]
2190    fn actual_serve_startup_memory_orders_model_profile_and_cache_stages() {
2191        let root = std::env::temp_dir().join(format!(
2192            "ferrum-serve-memory-order-{}",
2193            Uuid::new_v4().simple()
2194        ));
2195        let config = ProductObservabilityConfig::new(
2196            ProfileEntrypoint::Serve,
2197            "Qwen/Qwen3-0.6B",
2198            Some(&root.join("profile.jsonl")),
2199            ProfileDetailArg::Basic,
2200            Some(&root.join("memory.jsonl")),
2201            Some(&root.join("scheduler.jsonl")),
2202            Some(&root.join("request_dump")),
2203            1.0,
2204        );
2205        let memory = crate::memory_profile::ProcessMemoryObservation {
2206            before_bytes: 100,
2207            after_bytes: 200,
2208            current_bytes: 200,
2209            high_water_bytes: 240,
2210            source: "test",
2211        };
2212        write_actual_serve_startup_observability(
2213            &config,
2214            42,
2215            Some(memory.clone()),
2216            vec![
2217                ActualMemoryStageObservation::new(
2218                    "actual_serve_process_start",
2219                    "process_start",
2220                    None,
2221                    Some(memory.clone()),
2222                ),
2223                ActualMemoryStageObservation::new(
2224                    "actual_serve_backend_initialized",
2225                    "backend_initialized",
2226                    None,
2227                    Some(memory.clone()),
2228                ),
2229                ActualMemoryStageObservation::new(
2230                    "actual_serve_profile_run_done",
2231                    "profile_run_done",
2232                    None,
2233                    Some(memory.clone()),
2234                )
2235                .with_profile_run_status(false, "not_configured", "test"),
2236                ActualMemoryStageObservation::new(
2237                    "actual_serve_cache_allocated",
2238                    "cache_allocated",
2239                    None,
2240                    Some(memory),
2241                )
2242                .with_attribute("available_kv_or_state_bytes", json!(0)),
2243            ],
2244        )
2245        .unwrap();
2246        let memory_profile = fs::read_to_string(root.join("memory.jsonl")).unwrap();
2247        let memory_stages = memory_profile
2248            .lines()
2249            .filter(|line| !line.trim().is_empty())
2250            .map(|line| serde_json::from_str::<serde_json::Value>(line).unwrap())
2251            .filter_map(|event| {
2252                event["attributes"]["memory_stage"]
2253                    .as_str()
2254                    .map(str::to_string)
2255            })
2256            .collect::<Vec<_>>();
2257        assert_eq!(
2258            memory_stages,
2259            vec![
2260                "process_start",
2261                "backend_initialized",
2262                "model_loaded",
2263                "profile_run_done",
2264                "cache_allocated"
2265            ]
2266        );
2267        fs::remove_dir_all(root).ok();
2268    }
2269
2270    #[test]
2271    fn actual_run_failure_observability_writes_diagnostics_bundle() {
2272        let root = std::env::temp_dir().join(format!(
2273            "ferrum-run-failure-observability-{}",
2274            Uuid::new_v4().simple()
2275        ));
2276        let config = ProductObservabilityConfig::new(
2277            ProfileEntrypoint::Run,
2278            "Qwen/Qwen3-0.6B",
2279            Some(&root.join("profile.jsonl")),
2280            ProfileDetailArg::Basic,
2281            Some(&root.join("memory.jsonl")),
2282            Some(&root.join("scheduler.jsonl")),
2283            Some(&root.join("request_dump")),
2284            1.0,
2285        );
2286        let request_id = "req-failure-test".to_string();
2287        write_actual_run_failure_observability(
2288            &config,
2289            &ActualRunFailureObservation {
2290                request_id: request_id.clone(),
2291                duration_us: 42,
2292                sampling_params: SamplingParams::greedy(),
2293                prompt_token_ids: Some(vec![11, 22, 33]),
2294                prompt_token_count: Some(3),
2295                prompt_chars: 12,
2296                failure_kind: "error".to_string(),
2297                error_kind: "error".to_string(),
2298                error_message: "synthetic failure".to_string(),
2299                memory: None,
2300                memory_stages: Vec::new(),
2301            },
2302        )
2303        .unwrap();
2304        let profile = fs::read_to_string(root.join("profile.jsonl")).unwrap();
2305        let failure = profile
2306            .lines()
2307            .map(|line| serde_json::from_str::<serde_json::Value>(line).unwrap())
2308            .find(|event| event["phase"] == "actual_run_generation_failed")
2309            .expect("run failure profile event");
2310        assert_eq!(failure["event_kind"], "timed_span");
2311        assert_eq!(failure["status"], "failure");
2312        assert_eq!(failure["duration_us"], 42);
2313        assert_eq!(failure["attributes"]["terminal_failure_event"], true);
2314        assert!(failure["attributes"]["first_failure_event"].is_null());
2315        let bundle_dir = root.join("request_dump").join(&request_id);
2316        assert!(bundle_dir.join("failure_diagnostics.json").is_file());
2317        let scan: serde_json::Value = serde_json::from_str(
2318            &fs::read_to_string(bundle_dir.join("bad_output_scan.json")).unwrap(),
2319        )
2320        .unwrap();
2321        assert_eq!(scan["failure_kind"], "error");
2322        let diagnostics: serde_json::Value = serde_json::from_str(
2323            &fs::read_to_string(bundle_dir.join("failure_diagnostics.json")).unwrap(),
2324        )
2325        .unwrap();
2326        assert_eq!(diagnostics["failure_kind"], "error");
2327        assert_eq!(
2328            diagnostics["first_failure_event"]["phase"],
2329            "actual_run_generation_failed"
2330        );
2331        fs::remove_dir_all(root).ok();
2332    }
2333
2334    #[test]
2335    fn actual_run_observability_writes_prompt_token_ids() {
2336        let root = std::env::temp_dir().join(format!(
2337            "ferrum-run-observability-{}",
2338            Uuid::new_v4().simple()
2339        ));
2340        let config = ProductObservabilityConfig::new(
2341            ProfileEntrypoint::Run,
2342            "Qwen/Qwen3-0.6B",
2343            Some(&root.join("profile.jsonl")),
2344            ProfileDetailArg::Latency,
2345            Some(&root.join("memory.jsonl")),
2346            Some(&root.join("scheduler.jsonl")),
2347            Some(&root.join("request_dump")),
2348            1.0,
2349        );
2350        let request_id = "req-run-test".to_string();
2351        let native_event = actual_base_event(
2352            &config,
2353            &request_id,
2354            "vnext.request_accepted",
2355            ProfileEventKind::Instant,
2356            Utc::now(),
2357        );
2358        write_profile_jsonl(&root.join("profile.jsonl"), &[native_event]).unwrap();
2359        write_actual_run_observability(
2360            &config,
2361            &ActualRunObservation {
2362                request_id: request_id.clone(),
2363                duration_us: 42,
2364                sampling_params: SamplingParams::greedy(),
2365                prompt_token_ids: Some(vec![7, 8, 9]),
2366                prompt_token_count: Some(3),
2367                output_tokens: 2,
2368                output_token_ids: vec![10, 11],
2369                chunk_count: 1,
2370                finish_reason: Some("stop".to_string()),
2371                prompt_chars: 12,
2372                response_chars: 2,
2373                response_text: "OK".to_string(),
2374                execution_evidence: Some(ferrum_types::InferenceExecutionEvidence {
2375                    prompt_token_ids: vec![
2376                        ferrum_types::TokenId::new(7),
2377                        ferrum_types::TokenId::new(8),
2378                        ferrum_types::TokenId::new(9),
2379                    ],
2380                    output_token_ids: vec![
2381                        ferrum_types::TokenId::new(10),
2382                        ferrum_types::TokenId::new(11),
2383                    ],
2384                    engine_token_timing: Some(ferrum_types::EngineTokenTimingEvidence {
2385                        clock_source: "rust_std_instant".to_string(),
2386                        wall_anchor_unix_nanos: 1_700_000_000_000_000_000,
2387                        wall_anchor_max_error_nanos: 500,
2388                        decode_ready_nanos_since_request_start: Some(1_000_000),
2389                        token_commit_nanos_since_request_start: vec![2_000_000, 4_000_000],
2390                        decode_stage_intervals: Vec::new(),
2391                    }),
2392                }),
2393                memory: None,
2394                memory_stages: vec![
2395                    ActualMemoryStageObservation::new(
2396                        "actual_run_process_start",
2397                        "process_start",
2398                        None,
2399                        Some(crate::memory_profile::ProcessMemoryObservation {
2400                            before_bytes: 100,
2401                            after_bytes: 100,
2402                            current_bytes: 100,
2403                            high_water_bytes: 120,
2404                            source: "test",
2405                        }),
2406                    ),
2407                    ActualMemoryStageObservation::new(
2408                        "actual_run_shutdown",
2409                        "shutdown",
2410                        None,
2411                        Some(crate::memory_profile::ProcessMemoryObservation {
2412                            before_bytes: 200,
2413                            after_bytes: 220,
2414                            current_bytes: 220,
2415                            high_water_bytes: 240,
2416                            source: "test",
2417                        }),
2418                    ),
2419                ],
2420            },
2421        )
2422        .unwrap();
2423        let bundle_dir = root.join("request_dump").join(&request_id);
2424        let prompt_tokens: serde_json::Value = serde_json::from_str(
2425            &fs::read_to_string(bundle_dir.join("prompt_token_ids.json")).unwrap(),
2426        )
2427        .unwrap();
2428        assert_eq!(prompt_tokens["token_ids"], serde_json::json!([7, 8, 9]));
2429        assert_eq!(prompt_tokens["token_count"], 3);
2430        assert!(prompt_tokens["unavailable_reason"].is_null());
2431        let output_text_bytes = fs::read(bundle_dir.join("output_text.txt")).unwrap();
2432        let output_text = String::from_utf8(output_text_bytes.clone()).unwrap();
2433        assert!(output_text.starts_with("[redacted actual output]\n"));
2434        let scan: serde_json::Value = serde_json::from_str(
2435            &fs::read_to_string(bundle_dir.join("bad_output_scan.json")).unwrap(),
2436        )
2437        .unwrap();
2438        assert_eq!(
2439            scan["output_sha256"],
2440            sha256_hex(output_text_bytes.as_slice())
2441        );
2442        assert_eq!(scan["classified_output_sha256"], sha256_hex(b"OK"));
2443        let profile = fs::read_to_string(root.join("profile.jsonl")).unwrap();
2444        assert!(profile.lines().any(|line| {
2445            serde_json::from_str::<serde_json::Value>(line)
2446                .is_ok_and(|event| event["phase"] == "vnext.request_accepted")
2447        }));
2448        let generation = profile
2449            .lines()
2450            .filter(|line| !line.trim().is_empty())
2451            .map(|line| serde_json::from_str::<serde_json::Value>(line).unwrap())
2452            .find(|event| event["phase"] == "actual_run_generation")
2453            .expect("actual run generation event");
2454        assert_eq!(generation["attributes"]["prompt_token_count"], 3);
2455        assert_eq!(generation["attributes"]["completion_token_count"], 2);
2456        assert_eq!(generation["attributes"]["output_token_count"], 2);
2457        assert_eq!(generation["attributes"]["total_token_count"], 5);
2458        assert_eq!(
2459            generation["attributes"]["token_count_source"],
2460            "rendered_prompt_and_generated_tokens"
2461        );
2462        assert_eq!(generation["attributes"]["e2e_duration_us"], 42);
2463        assert_eq!(generation["attributes"]["profile_detail"], "latency");
2464        assert_eq!(
2465            generation["attributes"]["engine_token_commit_nanos_since_request_start"],
2466            serde_json::json!([2_000_000, 4_000_000])
2467        );
2468        assert_eq!(generation["attributes"]["engine_token_commit_count"], 2);
2469        assert_eq!(
2470            generation["attributes"]["itl_source"],
2471            "engine_token_commit"
2472        );
2473        assert_eq!(
2474            generation["attributes"]["itl_nanos"],
2475            serde_json::json!([2_000_000])
2476        );
2477        assert_eq!(generation["attributes"]["ttft_us"], 2_000);
2478        assert_eq!(generation["attributes"]["itl_us_avg"], 2_000);
2479        assert_eq!(
2480            generation["attributes"]["engine_decode_ready_nanos_since_request_start"],
2481            1_000_000
2482        );
2483        assert_eq!(
2484            generation["attributes"]["engine_decode_wall_nanos"],
2485            3_000_000
2486        );
2487        assert_eq!(generation["attributes"]["clock_conversion_error_ppm"], 166);
2488        assert_eq!(
2489            generation["attributes"]["decode_wall_timing_eligible"],
2490            true
2491        );
2492        let memory_profile = fs::read_to_string(root.join("memory.jsonl")).unwrap();
2493        let memory_stages = memory_profile
2494            .lines()
2495            .filter(|line| !line.trim().is_empty())
2496            .map(|line| serde_json::from_str::<serde_json::Value>(line).unwrap())
2497            .filter_map(|event| {
2498                event["attributes"]["memory_stage"]
2499                    .as_str()
2500                    .map(str::to_string)
2501            })
2502            .collect::<Vec<_>>();
2503        assert!(memory_stages.contains(&"process_start".to_string()));
2504        assert!(memory_stages.contains(&"first_request_done".to_string()));
2505        let first_request_index = memory_stages
2506            .iter()
2507            .position(|stage| stage == "first_request_done")
2508            .expect("first_request_done stage");
2509        let shutdown_index = memory_stages
2510            .iter()
2511            .position(|stage| stage == "shutdown")
2512            .expect("shutdown stage");
2513        assert!(first_request_index < shutdown_index);
2514        assert!(
2515            !root.join("scheduler.jsonl").exists(),
2516            "the engine owns successful actual-run scheduler lifecycles"
2517        );
2518        fs::remove_dir_all(root).ok();
2519    }
2520
2521    #[test]
2522    fn actual_run_resource_failure_observability_writes_resource_diagnostics() {
2523        let root = std::env::temp_dir().join(format!(
2524            "ferrum-observability-resource-failure-{}",
2525            uuid::Uuid::new_v4()
2526        ));
2527        fs::create_dir_all(&root).unwrap();
2528        let config = ProductObservabilityConfig::new(
2529            ProfileEntrypoint::Run,
2530            "Qwen/Qwen3-0.6B",
2531            Some(&root.join("profile.jsonl")),
2532            ProfileDetailArg::Basic,
2533            Some(&root.join("memory.jsonl")),
2534            Some(&root.join("scheduler.jsonl")),
2535            Some(&root.join("request_dump")),
2536            1.0,
2537        );
2538        let request_id = "req-resource-failure-test".to_string();
2539        write_actual_run_failure_observability(
2540            &config,
2541            &ActualRunFailureObservation {
2542                request_id: request_id.clone(),
2543                duration_us: 42,
2544                sampling_params: SamplingParams::greedy(),
2545                prompt_token_ids: Some(vec![1, 2, 3, 4]),
2546                prompt_token_count: Some(4),
2547                prompt_chars: 128,
2548                failure_kind: "oom_admission".to_string(),
2549                error_kind: "resource_exhausted".to_string(),
2550                error_message: "Resource exhausted: recurrent state capacity exhausted".to_string(),
2551                memory: Some(crate::memory_profile::ProcessMemoryObservation {
2552                    before_bytes: 1024,
2553                    after_bytes: 2048,
2554                    current_bytes: 2048,
2555                    high_water_bytes: 4096,
2556                    source: "test",
2557                }),
2558                memory_stages: Vec::new(),
2559            },
2560        )
2561        .unwrap();
2562        let bundle_dir = root.join("request_dump").join(&request_id);
2563        let scan: serde_json::Value = serde_json::from_str(
2564            &fs::read_to_string(bundle_dir.join("bad_output_scan.json")).unwrap(),
2565        )
2566        .unwrap();
2567        assert_eq!(scan["failure_kind"], "oom_admission");
2568        let diagnostics: serde_json::Value = serde_json::from_str(
2569            &fs::read_to_string(bundle_dir.join("failure_diagnostics.json")).unwrap(),
2570        )
2571        .unwrap();
2572        assert_eq!(diagnostics["failure_kind"], "oom_admission");
2573        assert_eq!(
2574            diagnostics["capacity"]["resource_kind"],
2575            "admission_capacity"
2576        );
2577        assert_eq!(diagnostics["nearest_resource_event"]["action"], "reject");
2578        assert_eq!(
2579            diagnostics["nearest_memory_snapshot"]["current_bytes"],
2580            2048
2581        );
2582        fs::remove_dir_all(root).ok();
2583    }
2584}