feat(router): allow to customize access log message by plugin system (#1379)

Author: dotansimha

.changeset/expose-summary-message-to-plugin-system.md

@@ -0,0 +1,11 @@
+---
+hive-router-internal: minor
+hive-router: minor
+hive-router-plan-executor: patch
+---
+
+# Expose the summary message to the plugin system
+
+Plugins can now override the request summary log line's message via `hive_router::set_summary_message(message)`, callable from any hook.
+
+Fixes https://github.com/graphql-hive/router/issues/1378

bin/router/src/lib.rs

@@ -143,13 +143,26 @@ pub fn set_summary_attribute(key: impl Into<String>, value: impl Into<sonic_rs::
     summary::record(|s| s.set_custom(key, value));
 }
 
+/// Returns the current request log summary for the current request, if one exists.
+pub fn get_current_summary() -> Option<Arc<summary::RequestSummary>> {
+    summary::current_summary()
+}
+
 /// Lets plugins attach a custom correlation to every log line of the current request (not
-/// just the summary), e.g. a tenant or project id extracted from the URL. Setting the same
-/// key again overwrites the previous value. A no-op outside a request.
+/// just the summary), e.g. a tenant or project id extracted from the URL.
+/// Setting the same key again overwrites the previous value. A no-op outside a request.
 pub fn set_log_correlation(key: impl Into<String>, value: impl std::fmt::Display) {
     request_id::set_correlation(key, value);
 }
 
+/// Lets plugins override the request summary log line's message.
+/// This can be called only once per request, and only during the request's lifetime.
+/// Calling it more than once, for the same request is a no-op.
+/// Calling it outside of a request is a no-op.
+pub fn set_summary_message(message: impl Into<std::borrow::Cow<'static, str>>) {
+    summary::record(|s| s.set_message(message));
+}
+
 #[inline]
 fn obtain_header_value<'a>(
     header_map: &'a ntex::http::HeaderMap,
@@ -225,11 +238,14 @@ async fn graphql_endpoint_handler(
     }
     .await;
 
-    // for streamed responses the summary must be emitted when the stream ends, not now
-    // we do that by attaching the summary guard to the response body, so it will be emitted
-    // when the stream terminates (or the client disconnects)
     if response_mode.can_stream() {
+        // Streamed responses must defer printing until the stream ends (or disconnects), not
+        // now - attaching the guard to the response body achieves that.
         response = summary_guard.attach_to_response(response);
+    } else {
+        // Store the guard in the response's own extensions instead of allowing it to drop now.
+        // This allows us to emit the summary log line only after the response really completes sending
+        response.extensions_mut().insert(summary_guard);
     }
 
     let graphql_operation = read_graphql_operation_metric_identity(&request);

e2e/src/telemetry/logging.rs

@@ -11,7 +11,7 @@ use hive_router::{
     plugins::hooks::on_http_request::{OnHttpRequestHookPayload, OnHttpRequestHookResult},
     plugins::hooks::on_plugin_init::{OnPluginInitPayload, OnPluginInitResult},
     plugins::plugin_trait::{RouterPlugin, StartHookPayload},
-    set_summary_attribute,
+    set_summary_attribute, set_summary_message,
 };
 use hive_router_internal::telemetry::logging::targets;
 use http::{HeaderMap, HeaderName, HeaderValue};
@@ -702,6 +702,7 @@ impl RouterPlugin for TestDebugLogPlugin {
         payload: OnHttpRequestHookPayload<'req>,
     ) -> OnHttpRequestHookResult<'req> {
         debug!("i'm just a test");
+        set_summary_message("custom summary message from plugin");
         set_summary_attribute("test_debug_log.simple", "hello-from-plugin");
         set_summary_attribute(
             "test_debug_log.nested",
@@ -808,3 +809,32 @@ plugins:
         })
     );
 }
+
+#[ntex::test]
+async fn plugin_can_customize_summary_message() {
+    let (_subgraphs, router) = setup_router(
+        router_with_telemetry(
+            "\
+log:
+  level: info
+  format: json
+plugins:
+  test_debug_log:
+    enabled: true
+",
+        )
+        .register_plugin::<TestDebugLogPlugin>(),
+    )
+    .await;
+
+    let stdout_log = router
+        .send_graphql_request(TEST_QUERY, None, None)
+        .capture_stdout_json()
+        .await;
+
+    let req_summary = log_line_by_target(&stdout_log, targets::SUMMARY);
+    assert_eq!(
+        find_attr(req_summary, "message"),
+        Some("custom summary message from plugin".to_string())
+    );
+}

lib/internal/src/telemetry/logging/summary.rs

@@ -1,3 +1,4 @@
+use std::borrow::Cow;
 use std::collections::{BTreeMap, HashSet};
 use std::error::Error;
 use std::future::Future;
@@ -37,6 +38,7 @@ pub struct RequestSummary {
     pub duration_ms: AtomicU64,
     pub supergraph_identifier: AtomicU64,
     pub custom: Mutex<BTreeMap<String, sonic_rs::Value>>,
+    pub message: OnceLock<Cow<'static, str>>,
 }
 
 impl RequestSummary {
@@ -94,6 +96,11 @@ impl RequestSummary {
         }
     }
 
+    /// Overrides the summary log line's message. First call wins; later calls are no-ops.
+    pub fn set_message(&self, message: impl Into<Cow<'static, str>>) {
+        let _ = self.message.set(message.into());
+    }
+
     pub fn record_subgraph(&self, name: &str) {
         self.subgraph_requests.fetch_add(1, Relaxed);
         if let Ok(mut subgraphs) = self.involved_subgraphs.lock() {
@@ -116,6 +123,7 @@ impl RequestSummary {
 
         info!(
             target: targets::SUMMARY,
+            message = self.message.get().map(Cow::as_ref),
             client_name = self.client_name.get().map(String::as_str),
             client_version = self.client_version.get().map(String::as_str),
             operation_name = self.operation_name.get().map(String::as_str),
@@ -160,6 +168,10 @@ pub fn record(f: impl FnOnce(&RequestSummary)) {
     let _ = REQUEST_SUMMARY.try_with(|summary| f(summary));
 }
 
+pub fn current_summary() -> Option<Arc<RequestSummary>> {
+    REQUEST_SUMMARY.try_with(|summary| summary.clone()).ok()
+}
+
 pub fn emit() {
     if !is_enabled() {
         return;
@@ -242,10 +254,15 @@ impl Drop for SummaryOnDrop {
         };
         summary.set_duration(self.started_at.elapsed());
 
-        match self.request_ids.take() {
-            Some(ids) => REQUEST_IDENTIFIERS.sync_scope(ids, || summary.emit()),
-            None => summary.emit(),
-        }
+        // Re-enter both task-locals before emitting: by now (especially for responses whose
+        // body outlives the original request future) they may no longer be ambiently scoped,
+        // but the formatters look up `custom`/`correlations` independently via their own
+        // `try_with` at format time, so both must be active for that lookup to succeed.
+        let request_ids = self.request_ids.take();
+        REQUEST_SUMMARY.sync_scope(summary, || match request_ids {
+            Some(ids) => REQUEST_IDENTIFIERS.sync_scope(ids, emit),
+            None => emit(),
+        });
     }
 }
 

plugin_examples/Cargo.lock

@@ -2,13 +2,18 @@ use hive_router::plugins::hooks::on_http_request::{
     OnHttpRequestHookPayload, OnHttpRequestHookResult,
 };
 use hive_router::plugins::hooks::on_plugin_init::{OnPluginInitPayload, OnPluginInitResult};
-use hive_router::plugins::plugin_trait::{RouterPlugin, StartHookPayload};
-use hive_router::{set_log_correlation, tracing};
+use hive_router::plugins::plugin_trait::{EndHookPayload, RouterPlugin, StartHookPayload};
+use hive_router::{
+    async_trait, get_current_summary, set_log_correlation, set_summary_message, tracing,
+};
+use std::sync::atomic::Ordering::Relaxed;
+use std::time::Instant;
 
 pub struct CustomLoggerCorrelationPlugin;
 
 const PROJECT_ID_KEY: &str = "project_id";
 
+#[async_trait]
 impl RouterPlugin for CustomLoggerCorrelationPlugin {
     type Config = ();
 
@@ -33,12 +38,37 @@ impl RouterPlugin for CustomLoggerCorrelationPlugin {
             .unwrap_or("unknown_project")
             .to_string();
 
+        let started_at = Instant::now();
+
         // Attach it as soon as we know it, so every log line for the rest of this
         // request - including this plugin's own - carries the same correlation.
         set_log_correlation(PROJECT_ID_KEY, project_id);
 
         tracing::debug!(target: "custom_logger_correlation", "on_http_request called");
 
-        payload.proceed()
+        let method = payload.router_http_request.method().to_string();
+        let path = payload.router_http_request.path().to_string();
+
+        payload.on_end(move |end_payload| {
+            let current_summary = if let Some(summary) = get_current_summary() {
+                summary
+            } else {
+                return end_payload.proceed();
+            };
+
+            let operation_name = current_summary.operation_name.get().cloned();
+            let status_code = current_summary.status_code.load(Relaxed);
+
+            set_summary_message(format!(
+                "[status={}] [{}ms] {} {} {}",
+                status_code,
+                started_at.elapsed().as_millis(),
+                method,
+                path,
+                operation_name.as_deref().unwrap_or("-")
+            ));
+
+            end_payload.proceed()
+        })
     }
 }

plugin_examples/custom_logger_correlation/src/plugin.rs

@@ -49,5 +49,28 @@ mod custom_logger_correlation_tests {
                 .and_then(serde_json::Value::as_str),
             Some("test")
         );
+
+        // The request summary line's message was customized by the plugin, using data
+        // (status code, duration, operation name) only known once the request is done.
+        let summary_line = stdout_log
+            .lines_json
+            .iter()
+            .find(|line| {
+                line.get("target").and_then(serde_json::Value::as_str) == Some("router::request")
+            })
+            .expect("missing request summary line");
+        let message = summary_line
+            .get("message")
+            .and_then(serde_json::Value::as_str)
+            .expect("missing summary message");
+        assert!(
+            message.starts_with("[status=200] ["),
+            "unexpected summary message: {message}"
+        );
+        // the query is anonymous, so the operation name falls back to "-"
+        assert!(
+            message.ends_with("] POST /test/graphql -"),
+            "unexpected summary message: {message}"
+        );
     }
 }