fix(logs): remove logs to avoid circular logging

robertohuertasm · robertohuertasm · commit 8fb522e58e77 · 2023-01-30T21:29:11.000+01:00
diff --git a/dd-tracing-layer/Cargo.toml b/dd-tracing-layer/Cargo.toml
@@ -1,6 +1,6 @@
 [package]
 name = "dd-tracing-layer"
-version = "0.1.1"
+version = "0.1.2"
 authors = ["Roberto Huertas <roberto.huertas@outlook.com>"]
 description = "Send your logs to Datadog"
 edition = "2021"
@@ -24,9 +24,7 @@ serde_json = "1"
 chrono = "0.4"
 async-trait = "0.1"
 async-recursion = "1.0"
-log = "0.4"
 
 [dev-dependencies]
 tracing-subscriber = { version = "0.3.16", features = ["json", "registry"] }
 httpmock = "0.6.7"
-simple_logger = "4.0.0"
diff --git a/dd-tracing-layer/src/datadog_ingestor.rs b/dd-tracing-layer/src/datadog_ingestor.rs
@@ -7,7 +7,7 @@ use std::{collections::VecDeque, sync::Arc};
 use tokio::sync::RwLock;
 
 const DD_SOURCE: &str = "dd-tracing-layer";
-const DD_TAGS: &str = "version:0.1.0";
+const DD_TAGS: &str = "version:0.1.2";
 const MAX_BATCH_SIZE: usize = 1000;
 const MAX_BATCH_DURATION_SECS: i64 = 5;
 const MAX_RETRIES: u8 = 3;
@@ -99,13 +99,10 @@ impl DatadogLogIngestor {
     #[async_recursion]
     async fn send_logs(&self, logs: &[Log], retries: u8) {
         if retries > MAX_RETRIES {
-            log::error!("Failed to send logs after {} retries", retries);
+            eprintln!("Failed to send logs after {} retries", retries);
         }
 
-        let retry = || {
-            log::info!("Retrying...");
-            self.send_logs(logs, retries + 1)
-        };
+        let retry = || self.send_logs(logs, retries + 1);
 
         // https://docs.datadoghq.com/api/latest/logs/?code-lang=typescript
         match self
@@ -119,23 +116,23 @@ impl DatadogLogIngestor {
         {
             Ok(res) => match res.status().as_u16() {
                 202 => {
-                    log::info!("Accepted: the request has been accepted for processing");
+                    //println!("Accepted: the request has been accepted for processing");
                 }
                 400 => {
-                    log::error!("Bad request (likely an issue in the payload formatting)");
+                    eprintln!("Bad request (likely an issue in the payload formatting)");
                 }
                 401 => {
-                    log::error!("Unauthorized (likely a missing API Key)");
+                    eprintln!("Unauthorized (likely a missing API Key)");
                 }
                 403 => {
-                    log::error!("Permission issue (likely using an invalid API Key)");
+                    eprintln!("Permission issue (likely using an invalid API Key)");
                 }
                 408 => {
-                    log::error!("Request Timeout, request should be retried after some time");
+                    eprintln!("Request Timeout, request should be retried after some time");
                     retry().await;
                 }
                 413 => {
-                    log::error!("Payload too large (batch is above 5MB uncompressed)");
+                    eprintln!("Payload too large (batch is above 5MB uncompressed)");
                     // split batch
                     let logs_len = logs.len();
                     let half = logs_len / 2;
@@ -144,36 +141,34 @@ impl DatadogLogIngestor {
                     self.send_logs(right, retries + 1).await;
                 }
                 429 => {
-                    log::error!("Too Many Requests, request should be retried after some time");
+                    eprintln!("Too Many Requests, request should be retried after some time");
                     retry().await;
                 }
                 500 => {
-                    log::error!("Internal Server Error, the server encountered an unexpected condition that prevented it from fulfilling the request, request should be retried after some time");
+                    eprintln!("Internal Server Error, the server encountered an unexpected condition that prevented it from fulfilling the request, request should be retried after some time");
                     retry().await;
                 }
                 503 => {
-                    log::error!("Service Unavailable, the server is not ready to handle the request probably because it is overloaded, request should be retried after some time");
+                    eprintln!("Service Unavailable, the server is not ready to handle the request probably because it is overloaded, request should be retried after some time");
                     retry().await;
                 }
                 _ => {
-                    log::error!("Unknown error, try again later");
+                    eprintln!("Unknown error, try again later");
                     retry().await;
                 }
             },
             Err(e) => {
-                log::error!("Failed to send logs to Datadog: {:?}", e);
+                eprintln!("Failed to send logs to Datadog: {:?}", e);
             }
         }
     }
 
     #[async_recursion]
     async fn try_send(&mut self, is_flush: bool) {
-        log::info!("Flushing...");
         {
             // send current logs to datadog if there are any
             let queue = self.queue.read().await;
             if queue.is_empty() {
-                log::info!("Queue is empty, skipping flush");
                 return;
             }
             if !is_flush {
@@ -182,7 +177,6 @@ impl DatadogLogIngestor {
                 let now = Utc::now();
                 let diff = now - last_log.received_at;
                 if diff < Duration::seconds(MAX_BATCH_DURATION_SECS) {
-                    log::info!("Last log is too recent, skipping flush: {:?}", diff);
                     return;
                 }
             }
@@ -198,7 +192,6 @@ impl DatadogLogIngestor {
 
         // send them (retries if it fails)
         self.send_logs(&logs, 0).await;
-        log::info!("Flushed {} logs", logs.len());
 
         // check if the queue is empty and flush again if it's not
         let is_queue_empty = { self.queue.read().await.is_empty() };
diff --git a/dd-tracing-layer/tests/datadog.rs b/dd-tracing-layer/tests/datadog.rs
@@ -18,16 +18,6 @@ mod tests {
 
     #[test]
     fn datadog_works() {
-        simple_logger::SimpleLogger::new()
-            .with_level(log::LevelFilter::Info)
-            .with_module_level("log_tracing_layer::layer", log::LevelFilter::Debug)
-            .with_module_level(
-                "dd_tracing_layer::datadog_ingestor",
-                log::LevelFilter::Debug,
-            )
-            .without_timestamps()
-            .init()
-            .unwrap();
         let server = httpmock::MockServer::start();
         let _mock = server.mock(|when, then| {
             when.any_request();
diff --git a/log-tracing-layer/Cargo.toml b/log-tracing-layer/Cargo.toml
@@ -1,6 +1,6 @@
 [package]
 name = "log-tracing-layer"
-version = "0.1.1"
+version = "0.1.2"
 authors = ["Roberto Huertas <roberto.huertas@outlook.com>"]
 description = "Build your own custom tracing layer."
 edition = "2021"
diff --git a/log-tracing-layer/src/layer.rs b/log-tracing-layer/src/layer.rs
@@ -32,7 +32,7 @@ impl LogLayer {
                     .build()
                 {
                     Err(e) => {
-                        log::error!("Runtime creation failure: {:?}", e);
+                        eprintln!("Runtime creation failure: {:?}", e);
                         return;
                     }
                     Ok(r) => r,
@@ -41,13 +41,10 @@ impl LogLayer {
                 rt.block_on(async move {
                     ingestor.start();
                     while let Some(log) = rx.recv().await {
-                        log::info!("LAYER: Adding log to ingestor");
                         ingestor.ingest(log).await;
                     }
-                    log::info!("LAYER: Done sending logs");
                     ingestor.flush().await;
                 });
-                log::info!("LAYER: Dropping runtime");
                 drop(rt);
             })
             .expect("Something went wrong spawning the thread");
@@ -76,10 +73,11 @@ impl LogLayer {
             }
         }
 
-        // there will be one for sure. We use that to get the span
-        let last = spans.last().unwrap();
-        log.insert("span".to_string(), json!(last));
-        log.insert("spans".to_string(), json!(spans));
+        // if no last span, it means there are no spans at all
+        if let Some(last) = spans.last() {
+            log.insert("span".to_string(), json!(last));
+            log.insert("spans".to_string(), json!(spans));
+        }
 
         log.insert(
             "level".to_string(),
@@ -106,7 +104,6 @@ impl LogLayer {
             json!(chrono::Utc::now().to_rfc3339()),
         );
 
-        log::debug!("LAYER: log = {:#?}", log);
         log
     }
 }
@@ -121,7 +118,6 @@ impl Drop for LogLayer {
         if let Some(handle) = self.handle.take() {
             let _result = handle.join();
         }
-        log::info!("LAYER: Dropped!");
     }
 }
 
@@ -146,10 +142,11 @@ where
 
     fn on_event(&self, event: &tracing::Event<'_>, ctx: tracing_subscriber::layer::Context<'_, S>) {
         // send to the channel
-        log::info!("LAYER: Sending to ingestor");
         if let Some(tx) = &self.tx {
             let log = Self::create_log(event, &ctx);
-            tx.send(log).unwrap();
+            if let Err(e) = tx.send(log) {
+                eprintln!("LAYER: Error sending log to ingestor: {:?}", e);
+            }
         }
     }
 }

Original file line number	Diff line number	Diff line change
`@@ -32,7 +32,7 @@ impl LogLayer {`
`32`	`32`	`.build()`
`33`	`33`	`{`
`34`	`34`	`Err(e) => {`
`35`		`- log::error!("Runtime creation failure: {:?}", e);`
	`35`	`+ eprintln!("Runtime creation failure: {:?}", e);`
`36`	`36`	`return;`
`37`	`37`	`}`
`38`	`38`	`Ok(r) => r,`
`@@ -41,13 +41,10 @@ impl LogLayer {`
`41`	`41`	`rt.block_on(async move {`
`42`	`42`	`ingestor.start();`
`43`	`43`	`while let Some(log) = rx.recv().await {`
`44`		`- log::info!("LAYER: Adding log to ingestor");`
`45`	`44`	`ingestor.ingest(log).await;`
`46`	`45`	`}`
`47`		`- log::info!("LAYER: Done sending logs");`
`48`	`46`	`ingestor.flush().await;`
`49`	`47`	`});`
`50`		`- log::info!("LAYER: Dropping runtime");`
`51`	`48`	`drop(rt);`
`52`	`49`	`})`
`53`	`50`	`.expect("Something went wrong spawning the thread");`
`@@ -76,10 +73,11 @@ impl LogLayer {`
`76`	`73`	`}`
`77`	`74`	`}`
`78`	`75`
`79`		`- // there will be one for sure. We use that to get the span`
`80`		`- let last = spans.last().unwrap();`
`81`		`- log.insert("span".to_string(), json!(last));`
`82`		`- log.insert("spans".to_string(), json!(spans));`
	`76`	`+ // if no last span, it means there are no spans at all`
	`77`	`+ if let Some(last) = spans.last() {`
	`78`	`+ log.insert("span".to_string(), json!(last));`
	`79`	`+ log.insert("spans".to_string(), json!(spans));`
	`80`	`+ }`
`83`	`81`
`84`	`82`	`log.insert(`
`85`	`83`	`"level".to_string(),`
`@@ -106,7 +104,6 @@ impl LogLayer {`
`106`	`104`	`json!(chrono::Utc::now().to_rfc3339()),`
`107`	`105`	`);`
`108`	`106`
`109`		`- log::debug!("LAYER: log = {:#?}", log);`
`110`	`107`	`log`
`111`	`108`	`}`
`112`	`109`	`}`
`@@ -121,7 +118,6 @@ impl Drop for LogLayer {`
`121`	`118`	`if let Some(handle) = self.handle.take() {`
`122`	`119`	`let _result = handle.join();`
`123`	`120`	`}`
`124`		`- log::info!("LAYER: Dropped!");`
`125`	`121`	`}`
`126`	`122`	`}`
`127`	`123`
`@@ -146,10 +142,11 @@ where`
`146`	`142`
`147`	`143`	`fn on_event(&self, event: &tracing::Event<'_>, ctx: tracing_subscriber::layer::Context<'_, S>) {`
`148`	`144`	`// send to the channel`
`149`		`- log::info!("LAYER: Sending to ingestor");`
`150`	`145`	`if let Some(tx) = &self.tx {`
`151`	`146`	`let log = Self::create_log(event, &ctx);`
`152`		`- tx.send(log).unwrap();`
	`147`	`+ if let Err(e) = tx.send(log) {`
	`148`	`+ eprintln!("LAYER: Error sending log to ingestor: {:?}", e);`
	`149`	`+ }`
`153`	`150`	`}`
`154`	`151`	`}`
`155`	`152`	`}`