feat: add x-hs-latency header for application overhead measurement (#2486)

config/development.toml

@@ -437,4 +437,4 @@ apple_pay_merchant_cert_key = "APPLE_PAY_MERCHNAT_CERTIFICATE_KEY"
 
 [lock_settings]
 redis_lock_expiry_seconds = 180 # 3 * 60 seconds
-delay_between_retries_in_milliseconds = 500
+delay_between_retries_in_milliseconds = 500

crates/api_models/src/payments.rs

@@ -307,6 +307,7 @@ pub struct PaymentsRequest {
 #[derive(Default, Debug, Clone, Copy)]
 pub struct HeaderPayload {
     pub payment_confirm_source: Option<api_enums::PaymentSource>,
+    pub x_hs_latency: Option<bool>,
 }
 
 #[derive(

crates/common_utils/src/consts.rs

@@ -26,3 +26,6 @@ pub const PAYMENTS_LIST_MAX_LIMIT_V2: u32 = 20;
 
 /// surcharge percentage maximum precision length
 pub const SURCHARGE_PERCENTAGE_PRECISION_LENGTH: u8 = 2;
+
+/// Header Key for application overhead of a request
+pub const X_HS_LATENCY: &str = "x-hs-latency";

crates/router/src/compatibility/wrap.rs

@@ -85,7 +85,7 @@ where
             let response = S::try_from(response);
             match response {
                 Ok(response) => match serde_json::to_string(&response) {
-                    Ok(res) => api::http_response_json_with_headers(res, headers),
+                    Ok(res) => api::http_response_json_with_headers(res, headers, None),
                     Err(_) => api::http_response_err(
                         r#"{
                                 "error": {

crates/router/src/core/payments.rs

@@ -66,7 +66,13 @@ pub async fn payments_operation_core<F, Req, Op, FData, Ctx>(
     call_connector_action: CallConnectorAction,
     auth_flow: services::AuthFlow,
     header_payload: HeaderPayload,
-) -> RouterResult<(PaymentData<F>, Req, Option<domain::Customer>, Option<u16>)>
+) -> RouterResult<(
+    PaymentData<F>,
+    Req,
+    Option<domain::Customer>,
+    Option<u16>,
+    Option<u128>,
+)>
 where
     F: Send + Clone + Sync,
     Req: Authenticate,
@@ -158,7 +164,7 @@ where
     .await?;
 
     let mut connector_http_status_code = None;
-
+    let mut external_latency = None;
     if let Some(connector_details) = connector {
         payment_data = match connector_details {
             api::ConnectorCallType::Single(connector) => {
@@ -180,6 +186,7 @@ where
                 let operation = Box::new(PaymentResponse);
                 let db = &*state.store;
                 connector_http_status_code = router_data.connector_http_status_code;
+                external_latency = router_data.external_latency;
                 //add connector http status code metrics
                 add_connector_http_status_code_metrics(connector_http_status_code);
                 operation
@@ -237,7 +244,13 @@ where
             .await?;
     }
 
-    Ok((payment_data, req, customer, connector_http_status_code))
+    Ok((
+        payment_data,
+        req,
+        customer,
+        connector_http_status_code,
+        external_latency,
+    ))
 }
 
 #[allow(clippy::too_many_arguments)]
@@ -269,7 +282,7 @@ where
     // To perform router related operation for PaymentResponse
     PaymentResponse: Operation<F, FData, Ctx>,
 {
-    let (payment_data, req, customer, connector_http_status_code) =
+    let (payment_data, req, customer, connector_http_status_code, external_latency) =
         payments_operation_core::<_, _, _, _, Ctx>(
             &state,
             merchant_account,
@@ -291,6 +304,8 @@ where
         operation,
         &state.conf.connector_request_reference_id_config,
         connector_http_status_code,
+        external_latency,
+        header_payload.x_hs_latency,
     )
 }
 

crates/router/src/core/payments/helpers.rs

@@ -2657,6 +2657,7 @@ pub fn router_data_type_conversion<F1, F2, Req1, Req2, Res1, Res2>(
         test_mode: router_data.test_mode,
         connector_api_version: router_data.connector_api_version,
         connector_http_status_code: router_data.connector_http_status_code,
+        external_latency: router_data.external_latency,
         apple_pay_flow: router_data.apple_pay_flow,
     }
 }

crates/router/src/core/payments/transformers.rs

@@ -1,7 +1,7 @@
 use std::{fmt::Debug, marker::PhantomData, str::FromStr};
 
 use api_models::payments::FrmMessage;
-use common_utils::fp_utils;
+use common_utils::{consts::X_HS_LATENCY, fp_utils};
 use diesel_models::ephemeral_key;
 use error_stack::{IntoReport, ResultExt};
 use router_env::{instrument, tracing};
@@ -161,6 +161,7 @@ where
         payment_method_balance: None,
         connector_api_version,
         connector_http_status_code: None,
+        external_latency: None,
         apple_pay_flow,
     };
 
@@ -182,6 +183,8 @@ where
         operation: Op,
         connector_request_reference_id_config: &ConnectorRequestReferenceIdConfig,
         connector_http_status_code: Option<u16>,
+        external_latency: Option<u128>,
+        is_latency_header_enabled: Option<bool>,
     ) -> RouterResponse<Self>;
 }
 
@@ -200,6 +203,8 @@ where
         operation: Op,
         connector_request_reference_id_config: &ConnectorRequestReferenceIdConfig,
         connector_http_status_code: Option<u16>,
+        external_latency: Option<u128>,
+        is_latency_header_enabled: Option<bool>,
     ) -> RouterResponse<Self> {
         let captures =
             payment_data
@@ -229,6 +234,8 @@ where
             &operation,
             connector_request_reference_id_config,
             connector_http_status_code,
+            external_latency,
+            is_latency_header_enabled,
         )
     }
 }
@@ -249,6 +256,8 @@ where
         _operation: Op,
         _connector_request_reference_id_config: &ConnectorRequestReferenceIdConfig,
         _connector_http_status_code: Option<u16>,
+        _external_latency: Option<u128>,
+        _is_latency_header_enabled: Option<bool>,
     ) -> RouterResponse<Self> {
         Ok(services::ApplicationResponse::JsonWithHeaders((
             Self {
@@ -281,6 +290,8 @@ where
         _operation: Op,
         _connector_request_reference_id_config: &ConnectorRequestReferenceIdConfig,
         _connector_http_status_code: Option<u16>,
+        _external_latency: Option<u128>,
+        _is_latency_header_enabled: Option<bool>,
     ) -> RouterResponse<Self> {
         let additional_payment_method_data: Option<api_models::payments::AdditionalPaymentData> =
             data.payment_attempt
@@ -334,6 +345,8 @@ pub fn payments_to_payments_response<R, Op, F: Clone>(
     operation: &Op,
     connector_request_reference_id_config: &ConnectorRequestReferenceIdConfig,
     connector_http_status_code: Option<u16>,
+    external_latency: Option<u128>,
+    is_latency_header_enabled: Option<bool>,
 ) -> RouterResponse<api::PaymentsResponse>
 where
     Op: Debug,
@@ -430,7 +443,13 @@ where
             payment_confirm_source.to_string(),
         ))
     }
-
+    if Some(true) == is_latency_header_enabled {
+        headers.extend(
+            external_latency
+                .map(|latency| vec![(X_HS_LATENCY.to_string(), latency.to_string())])
+                .unwrap_or(vec![]),
+        );
+    }
     let output = Ok(match payment_request {
         Some(_request) => {
             if payments::is_start_pay(&operation)

crates/router/src/core/utils.rs

@@ -187,6 +187,7 @@ pub async fn construct_payout_router_data<'a, F>(
         payment_method_balance: None,
         connector_api_version: None,
         connector_http_status_code: None,
+        external_latency: None,
         apple_pay_flow: None,
     };
 
@@ -326,6 +327,7 @@ pub async fn construct_refund_router_data<'a, F>(
         payment_method_balance: None,
         connector_api_version,
         connector_http_status_code: None,
+        external_latency: None,
         apple_pay_flow: None,
     };
 
@@ -553,6 +555,7 @@ pub async fn construct_accept_dispute_router_data<'a>(
         payment_method_balance: None,
         connector_api_version: None,
         connector_http_status_code: None,
+        external_latency: None,
         apple_pay_flow: None,
     };
     Ok(router_data)
@@ -638,6 +641,7 @@ pub async fn construct_submit_evidence_router_data<'a>(
         test_mode,
         connector_api_version: None,
         connector_http_status_code: None,
+        external_latency: None,
         apple_pay_flow: None,
     };
     Ok(router_data)
@@ -728,6 +732,7 @@ pub async fn construct_upload_file_router_data<'a>(
         test_mode,
         connector_api_version: None,
         connector_http_status_code: None,
+        external_latency: None,
         apple_pay_flow: None,
     };
     Ok(router_data)
@@ -816,6 +821,7 @@ pub async fn construct_defend_dispute_router_data<'a>(
         test_mode,
         connector_api_version: None,
         connector_http_status_code: None,
+        external_latency: None,
         apple_pay_flow: None,
     };
     Ok(router_data)
@@ -897,6 +903,7 @@ pub async fn construct_retrieve_file_router_data<'a>(
         test_mode,
         connector_api_version: None,
         connector_http_status_code: None,
+        external_latency: None,
         apple_pay_flow: None,
     };
     Ok(router_data)

crates/router/src/core/webhooks/utils.rs

@@ -118,6 +118,7 @@ pub async fn construct_webhook_router_data<'a>(
         payment_method_balance: None,
         connector_api_version: None,
         connector_http_status_code: None,
+        external_latency: None,
         apple_pay_flow: None,
     };
     Ok(router_data)

crates/router/src/services/api.rs

@@ -13,8 +13,8 @@ use std::{
 use actix_web::{body, web, FromRequest, HttpRequest, HttpResponse, Responder, ResponseError};
 use api_models::enums::CaptureMethod;
 pub use client::{proxy_bypass_urls, ApiClient, MockApiClient, ProxyClient};
-use common_utils::errors::ReportSwitchExt;
 pub use common_utils::request::{ContentType, Method, Request, RequestBuilder};
+use common_utils::{consts::X_HS_LATENCY, errors::ReportSwitchExt};
 use error_stack::{report, IntoReport, Report, ResultExt};
 use masking::{ExposeOptionInterface, PeekInterface};
 use router_env::{instrument, tracing, tracing_actix_web::RequestId, Tag};
@@ -338,7 +338,9 @@ where
             match connector_request {
                 Some(request) => {
                     logger::debug!(connector_request=?request);
+                    let current_time = Instant::now();
                     let response = call_connector_api(state, request).await;
+                    let external_latency = current_time.elapsed().as_millis();
                     logger::debug!(connector_response=?response);
                     match response {
                         Ok(body) => {
@@ -363,10 +365,20 @@ where
                                             error
                                         })?;
                                     data.connector_http_status_code = connector_http_status_code;
+                                    // Add up multiple external latencies in case of multiple external calls within the same request.
+                                    data.external_latency = Some(
+                                        data.external_latency
+                                            .map_or(external_latency, |val| val + external_latency),
+                                    );
                                     data
                                 }
                                 Err(body) => {
                                     router_data.connector_http_status_code = Some(body.status_code);
+                                    router_data.external_latency = Some(
+                                        router_data
+                                            .external_latency
+                                            .map_or(external_latency, |val| val + external_latency),
+                                    );
                                     metrics::CONNECTOR_ERROR_RESPONSE_COUNT.add(
                                         &metrics::CONTEXT,
                                         1,
@@ -399,6 +411,11 @@ where
                                 };
                                 router_data.response = Err(error_response);
                                 router_data.connector_http_status_code = Some(504);
+                                router_data.external_latency = Some(
+                                    router_data
+                                        .external_latency
+                                        .map_or(external_latency, |val| val + external_latency),
+                                );
                                 Ok(router_data)
                             } else {
                                 Err(error.change_context(
@@ -559,6 +576,7 @@ async fn handle_response(
             logger::info!(?response);
             let status_code = response.status().as_u16();
             let headers = Some(response.headers().to_owned());
+
             match status_code {
                 200..=202 | 302 | 204 => {
                     logger::debug!(response=?response);
@@ -870,8 +888,15 @@ where
             .map_into_boxed_body()
         }
         Ok(ApplicationResponse::JsonWithHeaders((response, headers))) => {
+            let request_elapsed_time = request.headers().get(X_HS_LATENCY).and_then(|value| {
+                if value == "true" {
+                    Some(start_instant.elapsed())
+                } else {
+                    None
+                }
+            });
             match serde_json::to_string(&response) {
-                Ok(res) => http_response_json_with_headers(res, headers),
+                Ok(res) => http_response_json_with_headers(res, headers, request_elapsed_time),
                 Err(_) => http_response_err(
                     r#"{
                         "error": {
@@ -948,12 +973,23 @@ pub fn http_response_json<T: body::MessageBody + 'static>(response: T) -> HttpRe
 
 pub fn http_response_json_with_headers<T: body::MessageBody + 'static>(
     response: T,
-    headers: Vec<(String, String)>,
+    mut headers: Vec<(String, String)>,
+    request_duration: Option<Duration>,
 ) -> HttpResponse {
     let mut response_builder = HttpResponse::Ok();
-    for (name, value) in headers {
+
-        response_builder.append_header((name, value));
+    for (name, value) in headers.iter_mut() {
+        if name == X_HS_LATENCY {
+            if let Some(request_duration) = request_duration {
+                if let Ok(external_latency) = value.parse::<u128>() {
+                    let updated_duration = request_duration.as_millis() - external_latency;
+                    *value = updated_duration.to_string();
+                }
+            }
+        }
+        response_builder.append_header((name.clone(), value.clone()));
     }
+
     response_builder
         .content_type(mime::APPLICATION_JSON)
         .body(response)

crates/router/src/types.rs

@@ -289,7 +289,7 @@ pub struct RouterData<Flow, Request, Response> {
 
     pub test_mode: Option<bool>,
     pub connector_http_status_code: Option<u16>,
-
+    pub external_latency: Option<u128>,
     /// Contains apple pay flow type simplified or manual
     pub apple_pay_flow: Option<storage_enums::ApplePayFlow>,
 }
@@ -1117,6 +1117,7 @@ impl<F1, F2, T1, T2> From<(&RouterData<F1, T1, PaymentsResponseData>, T2)>
             payment_method_balance: data.payment_method_balance.clone(),
             connector_api_version: data.connector_api_version.clone(),
             connector_http_status_code: data.connector_http_status_code,
+            external_latency: data.external_latency,
             apple_pay_flow: data.apple_pay_flow.clone(),
         }
     }
@@ -1171,6 +1172,7 @@ impl<F1, F2>
             payment_method_balance: None,
             connector_api_version: None,
             connector_http_status_code: data.connector_http_status_code,
+            external_latency: data.external_latency,
             apple_pay_flow: None,
         }
     }

crates/router/src/types/transformers.rs

@@ -2,6 +2,7 @@
 use actix_web::http::header::HeaderMap;
 use api_models::{enums as api_enums, payments};
 use common_utils::{
+    consts::X_HS_LATENCY,
     crypto::Encryptable,
     ext_traits::{StringExt, ValueExt},
     pii,
@@ -787,8 +788,14 @@ impl ForeignTryFrom<&HeaderMap> for api_models::payments::HeaderPayload {
                         )
                 })
                 .transpose()?;
+
+        let x_hs_latency = get_header_value_by_key(X_HS_LATENCY.into(), headers)
+            .map(|value| value == Some("true"))
+            .unwrap_or(false);
+
         Ok(Self {
             payment_confirm_source,
+            x_hs_latency: Some(x_hs_latency),
         })
     }
 }

crates/router/src/utils.rs

@@ -730,6 +730,8 @@ where
             &operation,
             &state.conf.connector_request_reference_id_config,
             None,
+            None,
+            None,
         )?;
 
         let event_type: enums::EventType = status

crates/router/src/workflows/payment_sync.rs

@@ -60,7 +60,7 @@ impl ProcessTrackerWorkflow<AppState> for PaymentsSyncWorkflow {
             )
             .await?;
 
-        let (mut payment_data, _, customer, _) =
+        let (mut payment_data, _, customer, _, _) =
             payment_flows::payments_operation_core::<api::PSync, _, _, _, Oss>(
                 state,
                 merchant_account.clone(),

crates/router/tests/connectors/aci.rs

@@ -92,6 +92,7 @@ fn construct_payment_router_data() -> types::PaymentsAuthorizeRouterData {
         connector_api_version: None,
         connector_http_status_code: None,
         apple_pay_flow: None,
+        external_latency: None,
     }
 }
 
@@ -148,6 +149,7 @@ fn construct_refund_router_data<F>() -> types::RefundsRouterData<F> {
         connector_api_version: None,
         connector_http_status_code: None,
         apple_pay_flow: None,
+        external_latency: None,
     }
 }
 

crates/router/tests/connectors/utils.rs

@@ -514,6 +514,7 @@ pub trait ConnectorActions: Connector {
             connector_api_version: None,
             connector_http_status_code: None,
             apple_pay_flow: None,
+            external_latency: None,
         }
     }