feat(api): prometheus metrics

services/api/Cargo.toml

@@ -11,6 +11,7 @@ http = "0.2.8"
 hyper-reverse-proxy = "0.5.1"
 lazy_static = "1.4.0"
 libpk = { path = "../../lib/libpk" }
+metrics = "0.20.1"
 tokio = { workspace = true }
 tower = "0.4.13"
 tracing = { workspace = true }

services/api/src/main.rs

@@ -12,6 +12,7 @@ mod util;
 #[tokio::main]
 async fn main() -> anyhow::Result<()> {
     libpk::init_logging("api")?;
+    libpk::init_metrics()?;
     info!("hello world");
 
     // processed upside down (???) so we have to put middleware at the end
@@ -69,8 +70,8 @@ async fn main() -> anyhow::Result<()> {
         .route("/v2/members/:member_id/oembed.json", get(util::rproxy))
         .route("/v2/groups/:group_id/oembed.json", get(util::rproxy))
 
-        .layer(middleware::ratelimit::ratelimiter(middleware::ratelimit::do_request_ratelimited)) // this sucks
         .layer(axum::middleware::from_fn(middleware::logger))
+        .layer(middleware::ratelimit::ratelimiter(middleware::ratelimit::do_request_ratelimited)) // this sucks
         .layer(axum::middleware::from_fn(middleware::ignore_invalid_routes))
         .layer(axum::middleware::from_fn(middleware::cors))
 

services/api/src/middleware/logger.rs

@@ -1,10 +1,15 @@
 use std::time::Instant;
 
 use axum::{extract::MatchedPath, http::Request, middleware::Next, response::Response};
-use tracing::{info, span, Instrument, Level};
+use metrics::histogram;
+use tracing::{info, span, warn, Instrument, Level};
 
 use crate::util::header_or_unknown;
 
+// log any requests that take longer than 2 seconds
+// todo: change as necessary
+const MIN_LOG_TIME: u128 = 2_000;
+
 pub async fn logger<B>(request: Request<B>, next: Next<B>) -> Response {
     let method = request.method().clone();
 
@@ -12,14 +17,14 @@ pub async fn logger<B>(request: Request<B>, next: Next<B>) -> Response {
     let remote_ip = header_or_unknown(request.headers().get("Fly-Client-IP"));
     let user_agent = header_or_unknown(request.headers().get("User-Agent"));
 
-    let path = request
+    let endpoint = request
         .extensions()
         .get::<MatchedPath>()
         .cloned()
         .map(|v| v.as_str().to_string())
         .unwrap_or("unknown".to_string());
 
-    // todo: prometheus metrics
+    let uri = request.uri().clone();
 
     let request_id_span = span!(
         Level::INFO,
@@ -27,7 +32,7 @@ pub async fn logger<B>(request: Request<B>, next: Next<B>) -> Response {
         request_id,
         remote_ip,
         method = method.as_str(),
-        path,
+        endpoint = endpoint.clone(),
         user_agent
     );
 
@@ -35,7 +40,21 @@ pub async fn logger<B>(request: Request<B>, next: Next<B>) -> Response {
     let response = next.run(request).instrument(request_id_span).await;
     let elapsed = start.elapsed().as_millis();
 
-    info!("handled request for {} {} in {}ms", method, path, elapsed);
+    info!(
+        "handled request for {} {} in {}ms",
+        method, endpoint, elapsed
+    );
+    histogram!("pk_http_requests", (elapsed as f64) / 1_000_f64, "method" => method.to_string(), "endpoint" => endpoint.clone());
+
+    if elapsed > MIN_LOG_TIME {
+        warn!(
+            "request to {} full path {} (endpoint {}) took a long time ({}ms)!",
+            method,
+            uri.path(),
+            endpoint,
+            elapsed
+        )
+    }
 
     response
 }

services/api/src/middleware/ratelimit.rs

@@ -8,7 +8,8 @@ use axum::{
 };
 use fred::{pool::RedisPool, prelude::LuaInterface, types::ReconnectPolicy, util::sha1_hash};
 use http::{HeaderValue, StatusCode};
-use tracing::{error, info, warn};
+use metrics::increment_counter;
+use tracing::{debug, error, info, warn};
 
 use crate::util::{header_or_unknown, json_err};
 
@@ -107,13 +108,13 @@ pub async fn do_request_ratelimited<B>(
                 let mut response = if remaining > 0 {
                     next.run(request).await
                 } else {
-                    println!("{}", reset_after);
+                    let retry_after = (retry_after * 1_000_f64).ceil() as u64;
+                    debug!("ratelimited request from {rl_key}, retry_after={retry_after}");
+                    increment_counter!("pk_http_requests_ratelimited");
                     json_err(
                         StatusCode::TOO_MANY_REQUESTS,
                         format!(
-                            // todo: the retry_after is horribly wrong
-                            r#"{{"message":"429: too many requests","retry_after":{},"code":0}}"#,
-                            (retry_after * 1_000_f64).ceil() as u64
+                            r#"{{"message":"429: too many requests","retry_after":{retry_after},"code":0}}"#,
                         ),
                     )
                 };