Bug: Handle span closures after request completion or after consolidated log...



Currently some consolidated logs don't have the values propogated all the way to the top,

This seems to be a result of the way we handle the consolidated log & value propogation


In this case the consolidated log line is printed before the spans are closed resulting in values not being propogated at the top

<img width="1445" alt="image" src="https://github.com/juspay/hyperswitch/assets/21202349/fdbd4858-e432-4347-9a28-c28046566f38">

diff --git a/crates/router/src/middleware.rs b/crates/router/src/middleware.rs
index f1a3275ab21..2cab332a677 100644
--- a/crates/router/src/middleware.rs
+++ b/crates/router/src/middleware.rs
@@ -143,7 +143,7 @@ where
         Box::pin(
             async move {
                 let response = response_fut.await;
-                logger::info!(golden_log_line = true);
+                router_env::tracing::Span::current().record("golden_log_line", true);
                 response
             }
             .instrument(
@@ -153,7 +153,8 @@ where
                     merchant_id = Empty,
                     connector_name = Empty,
                     payment_method = Empty,
-                    flow = "UNKNOWN"
+                    flow = "UNKNOWN",
+                    golden_log_line = Empty
                 )
                 .or_current(),
             ),
diff --git a/crates/router_env/src/logger/config.rs b/crates/router_env/src/logger/config.rs
index 664c0d508f5..09d285a8628 100644
--- a/crates/router_env/src/logger/config.rs
+++ b/crates/router_env/src/logger/config.rs
@@ -107,13 +107,15 @@ pub struct LogTelemetry {
 
 /// Telemetry / tracing.
 #[derive(Default, Debug, Deserialize, Clone, PartialEq, Eq)]
-#[serde(rename_all = "lowercase")]
+#[serde(rename_all = "snake_case")]
 pub enum LogFormat {
     /// Default pretty log format
     Default,
     /// JSON based structured logging
     #[default]
     Json,
+    /// JSON based structured logging with pretty print
+    PrettyJson,
 }
 
 impl Config {
diff --git a/crates/router_env/src/logger/formatter.rs b/crates/router_env/src/logger/formatter.rs
index 4fd94c22163..472b917e746 100644
--- a/crates/router_env/src/logger/formatter.rs
+++ b/crates/router_env/src/logger/formatter.rs
@@ -10,7 +10,7 @@ use std::{
 
 use once_cell::sync::Lazy;
 use serde::ser::{SerializeMap, Serializer};
-use serde_json::Value;
+use serde_json::{ser::Formatter, Value};
 // use time::format_description::well_known::Rfc3339;
 use time::format_description::well_known::Iso8601;
 use tracing::{Event, Metadata, Subscriber};
@@ -121,9 +121,10 @@ impl fmt::Display for RecordType {
 /// `FormattingLayer` relies on the `tracing_bunyan_formatter::JsonStorageLayer` which is storage of entries.
 ///
 #[derive(Debug)]
-pub struct FormattingLayer<W>
+pub struct FormattingLayer<W, F>
 where
     W: for<'a> MakeWriter<'a> + 'static,
+    F: Formatter + Clone,
 {
     dst_writer: W,
     pid: u32,
@@ -135,11 +136,13 @@ where
     #[cfg(feature = "vergen")]
     build: String,
     default_fields: HashMap<String, Value>,
+    formatter: F,
 }
 
-impl<W> FormattingLayer<W>
+impl<W, F> FormattingLayer<W, F>
 where
     W: for<'a> MakeWriter<'a> + 'static,
+    F: Formatter + Clone,
 {
     ///
     /// Constructor of `FormattingLayer`.
@@ -149,11 +152,11 @@ where
     ///
     /// ## Example
     /// ```rust
-    /// let formatting_layer = router_env::FormattingLayer::new(router_env::service_name!(),std::io::stdout);
+    /// let formatting_layer = router_env::FormattingLayer::new(router_env::service_name!(),std::io::stdout, CompactFormatter);
     /// ```
     ///
-    pub fn new(service: &str, dst_writer: W) -> Self {
-        Self::new_with_implicit_entries(service, dst_writer, HashMap::new())
+    pub fn new(service: &str, dst_writer: W, formatter: F) -> Self {
+        Self::new_with_implicit_entries(service, dst_writer, HashMap::new(), formatter)
     }
 
     /// Construct of `FormattingLayer with implicit default entries.
@@ -161,6 +164,7 @@ where
         service: &str,
         dst_writer: W,
         default_fields: HashMap<String, Value>,
+        formatter: F,
     ) -> Self {
         let pid = std::process::id();
         let hostname = gethostname::gethostname().to_string_lossy().into_owned();
@@ -182,6 +186,7 @@ where
             #[cfg(feature = "vergen")]
             build,
             default_fields,
+            formatter,
         }
     }
 
@@ -287,7 +292,6 @@ where
     }
 
     /// Serialize entries of span.
-    #[cfg(feature = "log_active_span_json")]
     fn span_serialize<S>(
         &self,
         span: &SpanRef<'_, S>,
@@ -297,7 +301,8 @@ where
         S: Subscriber + for<'a> LookupSpan<'a>,
     {
         let mut buffer = Vec::new();
-        let mut serializer = serde_json::Serializer::new(&mut buffer);
+        let mut serializer =
+            serde_json::Serializer::with_formatter(&mut buffer, self.formatter.clone());
         let mut map_serializer = serializer.serialize_map(None)?;
         let message = Self::span_message(span, ty);
 
@@ -324,7 +329,8 @@ where
         S: Subscriber + for<'a> LookupSpan<'a>,
     {
         let mut buffer = Vec::new();
-        let mut serializer = serde_json::Serializer::new(&mut buffer);
+        let mut serializer =
+            serde_json::Serializer::with_formatter(&mut buffer, self.formatter.clone());
         let mut map_serializer = serializer.serialize_map(None)?;
 
         let mut storage = Storage::default();
@@ -398,10 +404,11 @@ where
 }
 
 #[allow(clippy::expect_used)]
-impl<S, W> Layer<S> for FormattingLayer<W>
+impl<S, W, F> Layer<S> for FormattingLayer<W, F>
 where
     S: Subscriber + for<'a> LookupSpan<'a>,
     W: for<'a> MakeWriter<'a> + 'static,
+    F: Formatter + Clone + 'static,
 {
     fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) {
         // Event could have no span.
@@ -421,6 +428,16 @@ where
         }
     }
 
+    #[cfg(not(feature = "log_active_span_json"))]
+    fn on_close(&self, id: tracing::Id, ctx: Context<'_, S>) {
+        let span = ctx.span(&id).expect("No span");
+        if span.parent().is_none() {
+            if let Ok(serialized) = self.span_serialize(&span, RecordType::ExitSpan) {
+                let _ = self.flush(serialized);
+            }
+        }
+    }
+
     #[cfg(feature = "log_active_span_json")]
     fn on_close(&self, id: tracing::Id, ctx: Context<'_, S>) {
         let span = ctx.span(&id).expect("No span");
diff --git a/crates/router_env/src/logger/setup.rs b/crates/router_env/src/logger/setup.rs
index 992de3e747e..af77991e804 100644
--- a/crates/router_env/src/logger/setup.rs
+++ b/crates/router_env/src/logger/setup.rs
@@ -16,6 +16,7 @@ use opentelemetry::{
     KeyValue,
 };
 use opentelemetry_otlp::{TonicExporterBuilder, WithExportConfig};
+use serde_json::ser::{CompactFormatter, PrettyFormatter};
 use tracing_appender::non_blocking::WorkerGuard;
 use tracing_subscriber::{fmt, prelude::*, util::SubscriberInitExt, EnvFilter, Layer};
 
@@ -69,7 +70,10 @@ pub fn setup(
         );
         println!("Using file logging filter: {file_filter}");
 
-        Some(FormattingLayer::new(service_name, file_writer).with_filter(file_filter))
+        Some(
+            FormattingLayer::new(service_name, file_writer, CompactFormatter)
+                .with_filter(file_filter),
+        )
     } else {
         None
     };
@@ -104,7 +108,15 @@ pub fn setup(
             config::LogFormat::Json => {
                 error_stack::Report::set_color_mode(error_stack::fmt::ColorMode::None);
                 let logging_layer =
-                    FormattingLayer::new(service_name, console_writer).with_filter(console_filter);
+                    FormattingLayer::new(service_name, console_writer, CompactFormatter)
+                        .with_filter(console_filter);
+                subscriber.with(logging_layer).init();
+            }
+            config::LogFormat::PrettyJson => {
+                error_stack::Report::set_color_mode(error_stack::fmt::ColorMode::None);
+                let logging_layer =
+                    FormattingLayer::new(service_name, console_writer, PrettyFormatter::new())
+                        .with_filter(console_filter);
                 subscriber.with(logging_layer).init();
             }
         }

## Type of Change
<!-- Put an `x` in the boxes that apply -->

- [x] Bugfix
- [ ] New feature
- [ ] Enhancement
- [ ] Refactoring
- [ ] Dependency updates
- [ ] Documentation
- [ ] CI/CD

## Description
<!-- Describe your changes in detail -->
- Add `pretty_json` log format for console logs
- Add span end log for root span close as the default behaviour
- move consolidated log from event to span close

### Additional Changes

- [ ] This PR modifies the API contract
- [ ] This PR modifies the database schema
- [ ] This PR modifies application configuration/environment variables

<!--
Provide links to the files with corresponding changes.

Following are the paths where you can find config files:
1. `config`
2. `crates/router/src/configs`
3. `loadtest/config`
-->


## Motivation and Context
<!--
Why is this change required? What problem does it solve?
If it fixes an open issue, please link to the issue here.

If you don't have an issue, we'd recommend starting with one first so the PR
can focus on the implementation (unless it is an obvious bug or documentation fix
that will have little conversation).
-->


## How did you test it?
<!--
Did you write an integration/unit/API test to verify the code changes?
Or did you test this change manually (provide relevant screenshots)?
-->

- running it locally check for the last log line after any request
```
curl --location 'http://localhost:8080/payments' \
--header 'Content-Type: application/json' \
--header 'Accept: application/json' \
--header 'api-key: dev_st84Q3ucbQSWWnUbPwQXAyefTD2w5gJsRN8GEQ0shegg1ZomnwsseEdJU3KjVoAp' \
--data-raw '{
  "amount": 6540,
  "currency": "USD",
  "confirm": true,
  "capture_method": "automatic",
  "capture_on": "2022-09-10T10:11:12Z",
  "amount_to_capture": 6540,
  "customer_id": "StripeCustomer",
  "email": "guest@example.com",
  "name": "John Doe",
  "phone": "999999999",
  "phone_country_code": "+1",
  "description": "Its my first payment request",
  "authentication_type": "no_three_ds",
  "return_url": "https://google.com",
  "payment_method": "card",
  "payment_method_type": "credit",
  "payment_method_data": {
    "card": {
      "card_number": "4242424242424242",
      "card_exp_month": "10",
      "card_exp_year": "25",
      "card_holder_name": "joseph Doe",
      "card_cvc": "123"
    }
  },
  "billing": {
    "address": {
      "line1": "1467",
      "line2": "Harrison Street",
      "line3": "Harrison Street",
      "city": "San Fransico",
      "state": "California",
      "zip": "94122",
      "country": "US",
      "first_name": "joseph",
      "last_name": "Doe"
    },
    "phone": {
      "number": "8056594427",
      "country_code": "+91"
    }
  },
  "shipping": {
    "address": {
      "line1": "1467",
      "line2": "Harrison Street",
      "line3": "Harrison Street",
      "city": "San Fransico",
      "state": "California",
      "zip": "94122",
      "country": "US",
      "first_name": "joseph",
      "last_name": "Doe"
    },
    "phone": {
      "number": "8056594427",
      "country_code": "+91"
    }
  },
  "statement_descriptor_name": "joseph",
  "statement_descriptor_suffix": "JS",
  "metadata": {
    "udf1": "value1",
    "new_customer": "true",
    "login_date": "2019-09-10T10:11:12Z"
  }
}'
```
- It should contain every field in consolidated log

<img width="463" alt="image" src="https://github.com/juspay/hyperswitch/assets/21202349/dc279a45-1b16-40d4-bb88-5433b458f0f3">

[grafana](https://grafana.staging.eu.juspay.net/explore?orgId=1&left=%7B%22datasource%22:%22x5WTfCG4k%22,%22queries%22:%5B%7B%22refId%22:%22A%22,%22expr%22:%22%7Bapp%3D%5C%22bach%5C%22,%20golden_log_line%3D%5C%22true%5C%22%7D%20%7C%3D%20%60%60%22,%22queryType%22:%22range%22,%22datasource%22:%7B%22type%22:%22loki%22,%22uid%22:%22x5WTfCG4k%22%7D,%22editorMode%22:%22builder%22%7D%5D,%22range%22:%7B%22from%22:%22now-1h%22,%22to%22:%22now%22%7D%7D)

```json
{
  "message": "[ROOT_SPAN - END]",
  "hostname": "sampraslopes-SERIAL.local",
  "pid": 3422,
  "env": "development",
  "level": "INFO",
  "target": "router::middleware",
  "service": "router",
  "line": 150,
  "file": "crates/router/src/middleware.rs",
  "fn": "ROOT_SPAN",
  "full_name": "router::middleware::ROOT_SPAN",
  "time": "2024-02-16T10:31:12.692105000Z",
  "flow": "PaymentsConfirm",
  "request_id": "018db178-5a8f-7a9d-ac46-218510ab655a",
  "merchant_id": "merchant_1707203569",
  "extra": {
    "connector_name": "stripe",
    "http.scheme": "http",
    "http.user_agent": "PostmanRuntime/7.33.0",
    "http.host": "localhost:8080",
    "http.target": "/payments/pay_tIvDNoPTya0pP7SiTJAU/confirm",
    "otel.name": "HTTP POST /payments/{payment_id}/confirm",
    "trace_id": "00000000000000000000000000000000",
    "payment_id": "pay_tIvDNoPTya0pP7SiTJAU",
    "payment_method": "card",
    "elapsed_milliseconds": 1443,
    "http.flavor": "1.1",
    "golden_log_line": true,
    "http.route": "/payments/{payment_id}/confirm",
    "http.method": "POST",
    "otel.kind": "server",
    "http.client_ip": "::1"
  }
}
```

## Checklist
<!-- Put an `x` in the boxes that apply -->

- [ ] I formatted the code `cargo +nightly fmt --all`
- [ ] I addressed lints thrown by `cargo clippy`
- [ ] I reviewed the submitted code
- [ ] I added unit tests for my changes where possible
- [ ] I added a [CHANGELOG](/CHANGELOG.md) entry if applicable
