feat(migration-canister): export a metric for the oldest request in flight and add endpoint for listing requests (#10978)

Adds the gauge `migration_canister_oldest_request_in_flight_age_seconds`
to the metrics served via `http_request`, reporting the age of the
migration request that has been in flight the longest. The gauge is not
set if there is no request in flight.

The age is derived from a new stable map `ACCEPTED_TIME` recording, for
every request in `REQUESTS`, the time at which it was accepted. The
timestamp is retained across state transitions (which remove and
re-insert the request) and dropped once the request leaves `REQUESTS`
for good, i.e., when the corresponding event is recorded in `HISTORY`
(both on success and on failure). Requests that were already in flight
before this bookkeeping was introduced are backfilled upon their next
state transition.

The motivation for adding the gauge is ability to introduce alerts for
request that are stuck for a long time.

---------

Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>

Author: mraszyk

rs/migration_canister/src/canister_state.rs

@@ -30,6 +30,15 @@ thread_local! {
     static REQUESTS: RefCell<BTreeMap<RequestState, (), Memory>> =
         RefCell::new(BTreeMap::init(MEMORY_MANAGER.with(|m| m.borrow().get(MemoryId::new(1)))));
 
+    /// Records for every request in `REQUESTS` the time (IC time in nanos since epoch)
+    /// at which it entered `REQUESTS`, i.e., when it was accepted.
+    /// An entry is added when a request is first inserted into `REQUESTS` and is
+    /// retained across state transitions (which remove and re-insert the request).
+    /// It is removed once the request leaves `REQUESTS` for good, i.e., when the
+    /// corresponding event is recorded in `HISTORY`.
+    static ACCEPTED_TIME: RefCell<BTreeMap<CanisterMigrationArgs, u64, Memory>> =
+        RefCell::new(BTreeMap::init(MEMORY_MANAGER.with(|m| m.borrow().get(MemoryId::new(5)))));
+
     /// Stores timestamps of all successful events in `HISTORY`
     /// that are within the last 24 hours.
     /// It can also store timestamps beyond the last 24 hours
@@ -53,6 +62,20 @@ thread_local! {
     // BTreeMap<(Request, Reqstate: String), (Counter: u64, FirstTs: Time, LastTs: Time)>
 }
 
+/// Returns the current IC time in nanos since epoch.
+///
+/// Unit tests do not run inside a canister, where `ic_cdk::api::time` traps,
+/// so we fall back to zero there.
+#[cfg(not(test))]
+fn now() -> u64 {
+    ic_cdk::api::time()
+}
+
+#[cfg(test)]
+fn now() -> u64 {
+    0
+}
+
 pub fn migrations_disabled() -> bool {
     DISABLED.with_borrow(|x| *x.get())
 }
@@ -86,16 +109,36 @@ pub mod privileged {
 pub mod requests {
     use candid::Principal;
 
-    use crate::{RequestState, canister_state::REQUESTS};
+    use crate::{
+        CanisterMigrationArgs, RequestState,
+        canister_state::{ACCEPTED_TIME, REQUESTS, now},
+    };
 
     pub fn num_requests() -> u64 {
         REQUESTS.with_borrow(|req| req.len())
     }
 
     pub fn insert_request(request: RequestState) {
+        let args = CanisterMigrationArgs::from(request.request());
+        // State transitions remove and re-insert a request, so we must only
+        // record the time at which the request was accepted, i.e., first inserted.
+        // Requests that were already in flight before this bookkeeping was
+        // introduced are backfilled upon their next state transition.
+        ACCEPTED_TIME.with_borrow_mut(|a| {
+            if !a.contains_key(&args) {
+                a.insert(args, now());
+            }
+        });
         REQUESTS.with_borrow_mut(|r| r.insert(request, ()));
     }
 
+    /// Returns the age in nanos of the request that has been in flight the longest,
+    /// or `None` if there is no request in flight.
+    pub fn oldest_request_age_nanos() -> Option<u64> {
+        let now = now();
+        ACCEPTED_TIME.with_borrow(|a| a.values().map(|time| now.saturating_sub(time)).max())
+    }
+
     pub fn remove_request(request: &RequestState) {
         let _ = REQUESTS.with_borrow_mut(|r| r.remove(request));
     }
@@ -134,12 +177,15 @@ pub mod requests {
 pub mod events {
     use crate::{
         CanisterMigrationArgs, Event, EventType,
-        canister_state::{HISTORY, LAST_EVENT, LIMITER},
+        canister_state::{ACCEPTED_TIME, HISTORY, LAST_EVENT, LIMITER},
     };
     use candid::Principal;
     use ic_cdk::api::time;
 
     pub fn insert_event(event: EventType) {
+        // Recording an event is the terminal step of a request, i.e., the request
+        // has just left `REQUESTS` and thus is not in flight anymore.
+        ACCEPTED_TIME.with_borrow_mut(|a| a.remove(&CanisterMigrationArgs::from(event.request())));
         let time = time();
         if let EventType::Succeeded { .. } = event {
             LIMITER.with_borrow_mut(|l| {

rs/migration_canister/src/migration_canister.rs

@@ -16,7 +16,7 @@ use crate::{
         events::{find_last_event, history_len},
         limiter::num_successes_in_past_24_h,
         migrations_disabled, num_validations,
-        requests::{find_request, insert_request, num_requests},
+        requests::{find_request, insert_request, num_requests, oldest_request_age_nanos},
         set_allowlist,
     },
     rate_limited, start_timers,
@@ -133,6 +133,15 @@ fn encode_metrics(w: &mut ic_metrics_encoder::MetricsEncoder<Vec<u8>>) -> std::i
         "Number of currently ongoing migration requests.",
     )?;
 
+    // This gauge is not set if there is no request in flight.
+    if let Some(age_nanos) = oldest_request_age_nanos() {
+        w.encode_gauge(
+            "migration_canister_oldest_request_in_flight_age_seconds",
+            age_nanos as f64 / 1_000_000_000_f64,
+            "Age in seconds of the migration request that has been in flight the longest.",
+        )?;
+    }
+
     w.encode_gauge(
         "migration_canister_num_successes_in_past_24_h",
         num_successes_in_past_24_h() as f64,

rs/migration_canister/tests/tests.rs

@@ -12,7 +12,7 @@ use ic_transport_types::EnvelopeContent::Call;
 use ic_universal_canister::{CallArgs, UNIVERSAL_CANISTER_WASM, wasm};
 use itertools::Itertools;
 use pocket_ic::{
-    CreateCanisterParams, CreateCanisterPlacement, PocketIcBuilder,
+    CreateCanisterParams, CreateCanisterPlacement, PocketIcBuilder, Time,
     common::rest::{
         CanisterCyclesCostSchedule, ExtendedSubnetConfigSet, IcpFeatures, IcpFeaturesConfig,
         SubnetSpec,
@@ -815,6 +815,154 @@ async fn metrics() {
         get_gauge(&metrics, "migration_canister_migrations_enabled"),
         1.0
     );
+
+    assert_eq!(
+        get_gauge(&metrics, "migration_canister_requests_in_flight"),
+        0.0
+    );
+
+    assert_eq!(oldest_request_age(&metrics), None);
+}
+
+const OLDEST_REQUEST_AGE_METRIC: &str = "migration_canister_oldest_request_in_flight_age_seconds";
+
+/// Reads the age (in seconds) of the oldest request in flight.
+/// Returns `None` if the metric is not set, i.e., if no request is in flight.
+fn oldest_request_age(metrics: &Scrape) -> Option<f64> {
+    let is_metric_set = metrics
+        .samples
+        .iter()
+        .any(|sample| sample.metric == OLDEST_REQUEST_AGE_METRIC);
+    if !is_metric_set {
+        return None;
+    }
+    Some(get_gauge(metrics, OLDEST_REQUEST_AGE_METRIC))
+}
+
+#[tokio::test]
+async fn oldest_request_in_flight_metric() {
+    let Setup {
+        pic,
+        migrated_canisters,
+        replaced_canisters,
+        migrated_canister_controllers,
+        ..
+    } = setup(Settings {
+        num_migrations: 2,
+        ..Default::default()
+    })
+    .await;
+    let sender = migrated_canister_controllers[0];
+    let first = MigrateCanisterArgs {
+        migrated_canister_id: migrated_canisters[0],
+        replaced_canister_id: replaced_canisters[0],
+    };
+    let second = MigrateCanisterArgs {
+        migrated_canister_id: migrated_canisters[1],
+        replaced_canister_id: replaced_canisters[1],
+    };
+
+    // Bump the time to 2022-01-01T00:00:00Z so that the requests are not
+    // accepted at the UNIX epoch and thus their age is not equal to the
+    // current IC time (which would make the assertions below vacuous).
+    pic.set_time(Time::from_nanos_since_unix_epoch(
+        1_640_995_200 * 1_000_000_000,
+    ))
+    .await;
+
+    // Without any request in flight, the metric is not set.
+    assert_eq!(oldest_request_age(&fetch_metrics(&pic).await), None);
+
+    migrate_canister(&pic, sender, &first).await.unwrap();
+    pic.advance_time(Duration::from_secs(10)).await;
+    pic.tick().await;
+
+    // The age of the (only) request in flight grows with time.
+    let metrics = fetch_metrics(&pic).await;
+    assert_eq!(
+        get_gauge(&metrics, "migration_canister_requests_in_flight"),
+        1.0
+    );
+    let age = oldest_request_age(&metrics).unwrap();
+    assert!((10.0..100.0).contains(&age), "unexpected age {age}");
+
+    // A second, younger request does not affect the metric:
+    // it keeps reporting the age of the first request.
+    migrate_canister(&pic, sender, &second).await.unwrap();
+    let metrics = fetch_metrics(&pic).await;
+    assert_eq!(
+        get_gauge(&metrics, "migration_canister_requests_in_flight"),
+        2.0
+    );
+    let age = oldest_request_age(&metrics).unwrap();
+    assert!((10.0..100.0).contains(&age), "unexpected age {age}");
+
+    // Drive both migrations to completion. We advance time by a lot so that
+    // the task waiting for 6 minutes can succeed quickly.
+    for _ in 0..100 {
+        pic.advance_time(Duration::from_secs(250)).await;
+        pic.tick().await;
+    }
+    for args in [&first, &second] {
+        assert!(matches!(
+            get_status(&pic, sender, args).await.unwrap(),
+            MigrationStatus::Succeeded { .. }
+        ));
+    }
+
+    // Successful requests are not in flight anymore.
+    let metrics = fetch_metrics(&pic).await;
+    assert_eq!(
+        get_gauge(&metrics, "migration_canister_requests_in_flight"),
+        0.0
+    );
+    assert_eq!(oldest_request_age(&metrics), None);
+}
+
+#[tokio::test]
+async fn oldest_request_in_flight_metric_reset_on_failure() {
+    let Setup {
+        pic,
+        migrated_canisters,
+        replaced_canisters,
+        migrated_canister_controllers,
+        ..
+    } = setup(Settings::default()).await;
+    let sender = migrated_canister_controllers[0];
+    let migrated_canister = migrated_canisters[0];
+    let args = MigrateCanisterArgs {
+        migrated_canister_id: migrated_canister,
+        replaced_canister_id: replaced_canisters[0],
+    };
+
+    migrate_canister(&pic, sender, &args).await.unwrap();
+
+    // The request has been accepted and thus its age is reported by the metric.
+    let metrics = fetch_metrics(&pic).await;
+    assert_eq!(
+        get_gauge(&metrics, "migration_canister_requests_in_flight"),
+        1.0
+    );
+    assert!(oldest_request_age(&metrics).is_some());
+
+    // Validation succeeded. Now we break migration by interfering.
+    pic.start_canister(migrated_canister, Some(sender))
+        .await
+        .unwrap();
+    for _ in 0..4 {
+        advance(&pic).await;
+    }
+    let MigrationStatus::Failed { .. } = get_status(&pic, sender, &args).await.unwrap() else {
+        panic!("expected the migration to fail")
+    };
+
+    // Failed requests are not in flight anymore either.
+    let metrics = fetch_metrics(&pic).await;
+    assert_eq!(
+        get_gauge(&metrics, "migration_canister_requests_in_flight"),
+        0.0
+    );
+    assert_eq!(oldest_request_age(&metrics), None);
 }
 
 async fn concurrent_migration(