DINO-1164: add observability to new LAS on the rust server side & the main backend side (via @Timed)

README.md

@@ -51,7 +51,7 @@ This repository is a monorepo that contains many different pieces of Codebloom,
 - Our public task board on [Notion](https://www.notion.so/) which is used to define a relationship between tasks and PRs
   - [View public taskboard](https://codebloom.notion.site/)
   - [Goto `.github/scripts/notion/index.ts` to view custom PR/commit check validation implementation](./.github/scripts/notion/index.ts)
-- Our backend which is written in [Java 25](https://dev.java/) and [Spring Boot 3](https://spring.io/projects/spring-boot). The backend interfaces with our database via [pgJDBC](https://jdbc.postgresql.org/), Discord via [JDA](https://jda.wiki/), [leetcode.com](https://leetcode.com) via a custom abstraction over their [GraphQL](https://graphql.org/) API as well as [Playwright](https://playwright.dev/java/) to obtain credentials to [leetcode.com](https://leetcode.com) via [GitHub OAuth](https://github.com).
+- Our backend which is written in [Java 25](https://dev.java/) and [Spring Boot 3](https://spring.io/projects/spring-boot). The backend interfaces with our database via [pgJDBC](https://jdbc.postgresql.org/), Discord via [JDA](https://jda.wiki/), and [leetcode.com](https://leetcode.com) via a custom abstraction over their [GraphQL](https://graphql.org/) API, using credentials from [`leetcode-auth-service`](./internal/leetcode-auth-service/README.md).
   - [Goto `src/`](./src/)
   - [View detailed documentation](./src/README.md)
   - [View OpenAPI schema](https://codebloom.patinanetwork.org/swagger-ui/index.html)

example.env

@@ -44,9 +44,7 @@ SECRET_KEY=<changeme>
 
 # Server URL, pretty self explanatory.
 # Why is this port 5173? Vite will forward api
-# requests to the backend if needed. We also
-# load some frontend URLs via Playwright so it
-# needs to go through the frontend.
+# requests to the backend if needed.
 SERVER_URL=http://localhost:5173
 
 # read by leetcode-auth-service

exclusions.ts

@@ -9,7 +9,6 @@ const frontendBaseDir = "js/src";
 export const backendExclusions = [
   `${backendBaseDir}/common/dto/**`,
   `${backendBaseDir}/config/**`,
-  `${backendBaseDir}/playwright/PlaywrightProvider.java`,
   `${backendBaseDir}/CodebloomApplication.java`,
 ];
 export const frontendExclusions = [

internal/leetcode-auth-service/Cargo.toml

@@ -26,6 +26,7 @@ tracing = "0.1.44"
 tracing-subscriber = { version = "0.3.23", features = ["json", "env-filter"] }
 chrono = { version = "0.4.45", default-features = false, features = ["std", "clock"] }
 redis = { version = "1.8.1", default-features = false, features = ["tokio-comp", "connection-manager", "script"] }
+strum = { version = "0.28.0", features = ["derive"] }
 
 [dev-dependencies]
 parking_lot = "0.12"

internal/leetcode-auth-service/README.md

@@ -60,7 +60,13 @@ Zero or unparsable durations fall back to the default.
 
 - `/livez`: always `ok`.
 - `/readyz`: `503` when Redis does not answer `PING` within 3 seconds, so the pod is taken out of the Service until Redis is back. The pod starts and stays alive while Redis is down; the Redis connection opens on first use and reconnects on its own.
-- `/metrics`: Prometheus, including `grpc_requests_total`, `grpc_request_duration_seconds` and `leetcode_auth_refresh_total{result="stored|lass_failed|store_failed"}`.
+- `/metrics`: Prometheus. Besides process metrics, `grpc_requests_total` and `grpc_request_duration_seconds`:
+  - `leetcode_auth_refresh_total{result="stored|lass_failed|store_failed"}`: finished refreshes.
+  - `leetcode_auth_refresh_requests_total{source="rpc|schedule",result="started|locked|lock_error"}`: refresh requests. `locked` means another refresh held the lock and the request was ignored.
+  - `leetcode_auth_refresh_in_progress`: refreshes running in this pod.
+  - `leetcode_auth_lass_request_duration_seconds{status}`: LASS `Authenticate` latency by gRPC status, with buckets from 1s to 240s.
+  - `leetcode_auth_scheduled_checks_total{result="fresh|stale|missing|read_error"}`: scheduled staleness checks.
+  - `leetcode_auth_credentials_stored_timestamp_seconds`: when the stored credentials were written, as last seen by this pod. Credential age is `time() - max(leetcode_auth_credentials_stored_timestamp_seconds)`.
 - `/version`: `VERSION` env var.
 
 ## Code layout

internal/leetcode-auth-service/src/config.rs

@@ -66,9 +66,8 @@ impl Config {
                     .filter(|v| !v.is_empty())
                     .unwrap_or_else(|| "localhost:50051".to_string());
                 let tls = var("GRPC_LASS_TLS")
-                    .map(|b| b.parse::<bool>().ok())
-                    .flatten()
-                    .unwrap_or_else(|| false);
+                    .and_then(|b| b.parse::<bool>().ok())
+                    .unwrap_or(false);
 
                 format!("{}{host}", if tls { "https://" } else { "http://" })
             },

internal/leetcode-auth-service/src/grpc/auth.rs

@@ -7,7 +7,7 @@ use crate::{
         GetTokenRequest, GetTokenResponse, RefreshTokenRequest, RefreshTokenResponse,
         leetcode_auth_service_server,
     },
-    service::refresh::TokenManager,
+    service::refresh::{RefreshSource, TokenManager},
 };
 
 pub use leetcode_auth_service_server::LeetcodeAuthServiceServer;
@@ -55,7 +55,7 @@ impl<R: AuthRepository, A: LASS> leetcode_auth_service_server::LeetcodeAuthServi
     ) -> Result<Response<RefreshTokenResponse>, Status> {
         let started = self
             .token_manager
-            .trigger()
+            .trigger(RefreshSource::Rpc)
             .await
             .map_err(redis_status)?
             .is_some();

internal/leetcode-auth-service/src/grpc/metrics.rs

@@ -83,6 +83,28 @@ fn status_code_from(headers: &HeaderMap) -> Option<&'static str> {
         })
 }
 
+pub fn code_name(code: tonic::Code) -> &'static str {
+    match code {
+        tonic::Code::Ok => "OK",
+        tonic::Code::Cancelled => "CANCELLED",
+        tonic::Code::Unknown => "UNKNOWN",
+        tonic::Code::InvalidArgument => "INVALID_ARGUMENT",
+        tonic::Code::DeadlineExceeded => "DEADLINE_EXCEEDED",
+        tonic::Code::NotFound => "NOT_FOUND",
+        tonic::Code::AlreadyExists => "ALREADY_EXISTS",
+        tonic::Code::PermissionDenied => "PERMISSION_DENIED",
+        tonic::Code::ResourceExhausted => "RESOURCE_EXHAUSTED",
+        tonic::Code::FailedPrecondition => "FAILED_PRECONDITION",
+        tonic::Code::Aborted => "ABORTED",
+        tonic::Code::OutOfRange => "OUT_OF_RANGE",
+        tonic::Code::Unimplemented => "UNIMPLEMENTED",
+        tonic::Code::Internal => "INTERNAL",
+        tonic::Code::Unavailable => "UNAVAILABLE",
+        tonic::Code::DataLoss => "DATA_LOSS",
+        tonic::Code::Unauthenticated => "UNAUTHENTICATED",
+    }
+}
+
 fn record_grpc_request_metrics(grpc_method: Arc<str>, status: &'static str, start: Instant) {
     // Unknown services and methods answer UNIMPLEMENTED. Their paths come from the client, so
     // collapse them into one label value to keep the series count bounded.
@@ -160,25 +182,7 @@ impl http_body::Body for ObservedGrpcBody {
                 Poll::Ready(Some(Ok(frame)))
             }
             Poll::Ready(Some(Err(status))) => {
-                let code = match status.code() {
-                    tonic::Code::Ok => "OK",
-                    tonic::Code::Cancelled => "CANCELLED",
-                    tonic::Code::Unknown => "UNKNOWN",
-                    tonic::Code::InvalidArgument => "INVALID_ARGUMENT",
-                    tonic::Code::DeadlineExceeded => "DEADLINE_EXCEEDED",
-                    tonic::Code::NotFound => "NOT_FOUND",
-                    tonic::Code::AlreadyExists => "ALREADY_EXISTS",
-                    tonic::Code::PermissionDenied => "PERMISSION_DENIED",
-                    tonic::Code::ResourceExhausted => "RESOURCE_EXHAUSTED",
-                    tonic::Code::FailedPrecondition => "FAILED_PRECONDITION",
-                    tonic::Code::Aborted => "ABORTED",
-                    tonic::Code::OutOfRange => "OUT_OF_RANGE",
-                    tonic::Code::Unimplemented => "UNIMPLEMENTED",
-                    tonic::Code::Internal => "INTERNAL",
-                    tonic::Code::Unavailable => "UNAVAILABLE",
-                    tonic::Code::DataLoss => "DATA_LOSS",
-                    tonic::Code::Unauthenticated => "UNAUTHENTICATED",
-                };
+                let code = code_name(status.code());
 
                 this.recorder.record(code);
 

internal/leetcode-auth-service/src/lib.rs

@@ -3,5 +3,6 @@ pub mod db;
 pub mod domain;
 pub mod grpc;
 pub mod http;
+pub mod observe;
 pub mod proto;
 pub mod service;

internal/leetcode-auth-service/src/main.rs

@@ -15,7 +15,7 @@ use leetcode_auth_service::{
         metrics::GrpcRequestMetricsMiddleware,
     },
     http::{router, state::AppState},
-    proto,
+    observe, proto,
     service::refresh::TokenManager,
 };
 
@@ -44,9 +44,11 @@ fn init_tracing() {
 async fn main() -> anyhow::Result<()> {
     init_tracing();
 
-    let prom_handle = PrometheusBuilder::new()
+    let prom_handle = observe::configure(PrometheusBuilder::new())
+        .context("failed to configure Prometheus histogram buckets")?
         .install_recorder()
         .context("failed to install Prometheus recorder")?;
+    observe::describe();
     let sys_collector = metrics_process::Collector::default();
     sys_collector.describe();
 

internal/leetcode-auth-service/src/observe.rs

@@ -0,0 +1,130 @@
+use std::time::Instant;
+
+use chrono::{DateTime, Utc};
+use metrics::{
+    Unit, counter, describe_counter, describe_gauge, describe_histogram, gauge, histogram,
+};
+use metrics_exporter_prometheus::{BuildError, Matcher, PrometheusBuilder};
+use strum::IntoStaticStr;
+use tonic::Status;
+
+use crate::{
+    grpc::metrics::code_name,
+    service::refresh::{RefreshOutcome, RefreshSource},
+};
+
+const REFRESH_TOTAL: &str = "leetcode_auth_refresh_total";
+const REFRESH_REQUESTS: &str = "leetcode_auth_refresh_requests_total";
+const REFRESH_IN_PROGRESS: &str = "leetcode_auth_refresh_in_progress";
+const LASS_DURATION: &str = "leetcode_auth_lass_request_duration_seconds";
+const SCHEDULED_CHECKS: &str = "leetcode_auth_scheduled_checks_total";
+const CREDENTIALS_STORED_AT: &str = "leetcode_auth_credentials_stored_timestamp_seconds";
+
+/// A LASS login drives a browser and may run until `GRPC_LASS_TIMEOUT_SECONDS` (180s by default).
+const LASS_BUCKETS: &[f64] = &[
+    1.0, 5.0, 10.0, 20.0, 30.0, 45.0, 60.0, 90.0, 120.0, 180.0, 240.0,
+];
+
+/// Whether a refresh request took the lock.
+#[derive(Debug, Clone, Copy, PartialEq, Eq, IntoStaticStr)]
+#[strum(serialize_all = "snake_case")]
+pub enum RefreshRequestResult {
+    Started,
+    /// Another refresh holds the lock, so the request was ignored.
+    Locked,
+    LockError,
+}
+
+/// What a scheduled staleness check found.
+#[derive(Debug, Clone, Copy, PartialEq, Eq, IntoStaticStr)]
+#[strum(serialize_all = "snake_case")]
+pub enum ScheduledCheck {
+    Fresh,
+    Stale,
+    Missing,
+    ReadError,
+}
+
+pub fn configure(builder: PrometheusBuilder) -> Result<PrometheusBuilder, BuildError> {
+    builder.set_buckets_for_metric(Matcher::Full(LASS_DURATION.to_string()), LASS_BUCKETS)
+}
+
+pub fn describe() {
+    describe_counter!(
+        REFRESH_TOTAL,
+        "Finished refreshes by result: stored, lass_failed or store_failed."
+    );
+    describe_counter!(
+        REFRESH_REQUESTS,
+        "Refresh requests by source (rpc or schedule) and result: started, locked (another refresh holds the lock) or lock_error."
+    );
+    describe_gauge!(
+        REFRESH_IN_PROGRESS,
+        "Refreshes currently running in this pod."
+    );
+    describe_histogram!(
+        LASS_DURATION,
+        Unit::Seconds,
+        "Duration of LASS Authenticate calls by gRPC status."
+    );
+    describe_counter!(
+        SCHEDULED_CHECKS,
+        "Scheduled staleness checks by result: fresh, stale, missing or read_error."
+    );
+    describe_gauge!(
+        CREDENTIALS_STORED_AT,
+        Unit::Seconds,
+        "Unix time the stored credentials were written, as last seen by this pod."
+    );
+}
+
+pub fn record_refresh(outcome: RefreshOutcome) {
+    let result: &'static str = outcome.into();
+    counter!(REFRESH_TOTAL, "result" => result).increment(1);
+}
+
+pub fn record_refresh_request(source: RefreshSource, result: RefreshRequestResult) {
+    let source: &'static str = source.into();
+    let result: &'static str = result.into();
+    counter!(REFRESH_REQUESTS, "source" => source, "result" => result).increment(1);
+}
+
+pub fn record_scheduled_check(result: ScheduledCheck) {
+    let result: &'static str = result.into();
+    counter!(SCHEDULED_CHECKS, "result" => result).increment(1);
+}
+
+pub fn record_credentials_stored_at(date_stored: DateTime<Utc>) {
+    gauge!(CREDENTIALS_STORED_AT).set(date_stored.timestamp_millis() as f64 / 1000.0);
+}
+
+pub async fn time_lass_call<T>(call: impl Future<Output = Result<T, Status>>) -> Result<T, Status> {
+    let start = Instant::now();
+    let result = call.await;
+    let status = match &result {
+        Ok(_) => "OK",
+        Err(status) => code_name(status.code()),
+    };
+    histogram!(LASS_DURATION, "status" => status).record(start.elapsed().as_secs_f64());
+    result
+}
+
+pub async fn track_refresh<T>(refresh: impl Future<Output = T>) -> T {
+    let _in_progress = InProgress::start();
+    refresh.await
+}
+
+struct InProgress;
+
+impl InProgress {
+    fn start() -> Self {
+        gauge!(REFRESH_IN_PROGRESS).increment(1.0);
+        Self
+    }
+}
+
+impl Drop for InProgress {
+    fn drop(&mut self) {
+        gauge!(REFRESH_IN_PROGRESS).decrement(1.0);
+    }
+}