diff --git a/hil/src/commands/flash.rs b/hil/src/commands/flash.rs index b792911a2..079326b8b 100644 --- a/hil/src/commands/flash.rs +++ b/hil/src/commands/flash.rs @@ -1,15 +1,22 @@ use camino::Utf8PathBuf; +use chrono::{DateTime, SecondsFormat, Utc}; use clap::Parser; use color_eyre::{ - eyre::{bail, ensure, WrapErr}, + eyre::{bail, ensure, ContextCompat, WrapErr}, Result, }; -use std::env; +use std::{ + env, + path::PathBuf, + time::{Duration, Instant}, +}; +use tokio_serial::SerialPortBuilderExt as _; +use tracing::{info, warn}; use crate::OrbConfig; use orb_s3_helpers::{ExistingFileBehavior, S3Uri}; use rand::{rngs::StdRng, SeedableRng}; -use tracing::info; +use serde_json::json; use crate::{current_dir, rts::FlashVariant}; @@ -44,6 +51,13 @@ pub struct Flash { } impl Flash { + fn get_serial_path(orb_config: &OrbConfig) -> Result<&PathBuf> { + orb_config + .serial_path + .as_ref() + .wrap_err("serial-path must be specified") + } + pub async fn run(self, orb_config: &OrbConfig) -> Result<()> { let args = self; let existing_file_behavior = if args.overwrite_existing { @@ -98,6 +112,7 @@ impl Flash { let orb_id = orb_config.orb_id.as_deref()?; Some(Utf8PathBuf::from(format!("{home}/persistent-{orb_id}"))) }); + let flash_started = Instant::now(); crate::rts::flash( variant, &rts_path, @@ -106,7 +121,93 @@ impl Flash { ) .await .wrap_err("error while flashing")?; + let flash_duration_seconds = flash_started.elapsed().as_secs(); + let flash_completed_at = Utc::now(); + + if args.ci { + Self::emit_ci_metrics( + orb_config, + flash_duration_seconds, + flash_completed_at, + ) + .await; + } Ok(()) } + + async fn emit_ci_metrics( + orb_config: &OrbConfig, + flash_duration_seconds: u64, + flash_completed_at: DateTime, + ) { + let login_prompt_detected_at = + match Self::wait_for_login_prompt(orb_config, Duration::from_secs(15 * 60)) + .await + { + Ok(timestamp) => Some(timestamp), + Err(error) => { + warn!("failed to wait for login prompt after flash: {error:?}"); + None + } + }; + + let boot_to_login_prompt_duration_seconds = + login_prompt_detected_at.and_then(|timestamp| { + (timestamp - flash_completed_at) + .to_std() + .ok() + .map(|d| d.as_secs()) + }); + + let metrics = json!({ + "event": "hil_flash_metrics", + "flash_duration_seconds": flash_duration_seconds, + "flash_completed_at": flash_completed_at.to_rfc3339_opts(SecondsFormat::Secs, true), + "boot_to_login_prompt_duration_seconds": boot_to_login_prompt_duration_seconds, + "login_prompt_detected_at": login_prompt_detected_at.map(|timestamp| timestamp.to_rfc3339_opts(SecondsFormat::Secs, true)), + }); + + println!("{metrics}"); + } + + async fn wait_for_login_prompt( + orb_config: &OrbConfig, + timeout: Duration, + ) -> Result> { + let serial_path = Self::get_serial_path(orb_config)?; + let serial = tokio_serial::new( + serial_path.to_string_lossy(), + crate::serial::ORB_BAUD_RATE, + ) + .open_native_async() + .wrap_err_with(|| { + format!("failed to open serial port {}", serial_path.display()) + })?; + + let (serial_reader, _) = tokio::io::split(serial); + let (serial_output_tx, serial_output_rx) = tokio::sync::broadcast::channel(64); + let (reader_task, kill_tx) = + crate::serial::spawn_serial_reader_task(serial_reader, serial_output_tx); + + info!("waiting for login prompt after flash"); + let login_wait_result = tokio::time::timeout( + timeout, + crate::serial::wait_for_pattern( + crate::serial::LOGIN_PROMPT_PATTERN.as_bytes().to_vec(), + tokio_stream::wrappers::BroadcastStream::new(serial_output_rx), + ), + ) + .await + .wrap_err("timed out while waiting for login prompt after flash")? + .wrap_err("failed while waiting for login prompt after flash"); + + let _ = kill_tx.send(()); + reader_task + .await + .wrap_err("serial reader task panicked")??; + + login_wait_result?; + Ok(Utc::now()) + } }