From dc9b6fa1b02371339af581d46dadbbb45d0b1204 Mon Sep 17 00:00:00 2001
From: bmc-msft <41130664+bmc-msft@users.noreply.github.com>
Date: Fri, 26 Mar 2021 18:45:36 -0400
Subject: [PATCH] address telemetry log message locality (#736)

---
 .../onefuzz-agent/src/tasks/stats/common.rs   |  4 +-
 src/agent/onefuzz-telemetry/src/lib.rs        | 38 +++++++++++--------
 src/proxy-manager/Cargo.lock                  |  1 +
 src/proxy-manager/Cargo.toml                  |  3 +-
 4 files changed, 27 insertions(+), 19 deletions(-)

diff --git a/src/agent/onefuzz-agent/src/tasks/stats/common.rs b/src/agent/onefuzz-agent/src/tasks/stats/common.rs
index 962940ca1..1859ced30 100644
--- a/src/agent/onefuzz-agent/src/tasks/stats/common.rs
+++ b/src/agent/onefuzz-agent/src/tasks/stats/common.rs
@@ -4,7 +4,7 @@
 use super::afl;
 use anyhow::{Error, Result};
 use onefuzz::jitter::delay_with_jitter;
-use onefuzz_telemetry::{track_event, Event::runtime_stats};
+use onefuzz_telemetry::Event::runtime_stats;
 use serde::Deserialize;
 pub const STATS_DELAY: std::time::Duration = std::time::Duration::from_secs(30);
 
@@ -21,7 +21,7 @@ pub async fn monitor_stats(path: Option<String>, format: Option<StatsFormat>) ->
                     StatsFormat::AFL => afl::read_stats(&path).await,
                 };
                 if let Ok(stats) = stats {
-                    track_event(runtime_stats, stats);
+                    log_events!(runtime_stats; stats);
                 }
                 delay_with_jitter(STATS_DELAY).await;
             }
diff --git a/src/agent/onefuzz-telemetry/src/lib.rs b/src/agent/onefuzz-telemetry/src/lib.rs
index 63cfd83a6..86e6c824c 100644
--- a/src/agent/onefuzz-telemetry/src/lib.rs
+++ b/src/agent/onefuzz-telemetry/src/lib.rs
@@ -492,23 +492,22 @@ pub fn set_property(entry: EventData) {
     }
 }
 
-fn local_log_event(event: &Event, properties: &[EventData]) {
-    let as_values = properties
+pub fn format_events(events: &[EventData]) -> String {
+    events
         .iter()
         .map(|x| x.as_values())
         .map(|(x, y)| format!("{}:{}", x, y))
         .collect::<Vec<String>>()
-        .join(" ");
-    log::log!(log::Level::Info, "{} {}", event.as_str(), as_values);
+        .join(" ")
 }
 
-pub fn track_event(event: Event, properties: Vec<EventData>) {
+pub fn track_event(event: &Event, properties: &[EventData]) {
     use appinsights::telemetry::Telemetry;
 
     if let Some(client) = client(ClientType::Instance) {
         let mut evt = appinsights::telemetry::EventTelemetry::new(event.as_str());
         let props = evt.properties_mut();
-        for property in &properties {
+        for property in properties {
             let (name, val) = property.as_values();
             props.insert(name.to_string(), val);
         }
@@ -519,7 +518,7 @@ pub fn track_event(event: Event, properties: Vec<EventData>) {
         let mut evt = appinsights::telemetry::EventTelemetry::new(event.as_str());
         let props = evt.properties_mut();
 
-        for property in &properties {
+        for property in properties {
             if property.can_share_with_microsoft() {
                 let (name, val) = property.as_values();
                 props.insert(name.to_string(), val);
@@ -527,7 +526,6 @@ pub fn track_event(event: Event, properties: Vec<EventData>) {
         }
         client.track(evt);
     }
-    local_log_event(&event, &properties);
 }
 
 pub fn to_log_level(level: &appinsights::telemetry::SeverityLevel) -> log::Level {
@@ -540,18 +538,24 @@ pub fn to_log_level(level: &appinsights::telemetry::SeverityLevel) -> log::Level
     }
 }
 
-pub fn should_log(level: &appinsights::telemetry::SeverityLevel) -> bool {
-    to_log_level(level) <= log::max_level()
-}
-
 pub fn log_message(level: appinsights::telemetry::SeverityLevel, msg: String) {
-    let log_level = to_log_level(&level);
-    log::log!(log_level, "{}", msg);
     if let Some(client) = client(ClientType::Instance) {
         client.track_trace(msg, level);
     }
 }
 
+#[macro_export]
+macro_rules! log_events {
+    ($name: expr; $events: expr) => {{
+        onefuzz_telemetry::track_event(&$name, &$events);
+        log::info!(
+            "{} {}",
+            $name.as_str(),
+            onefuzz_telemetry::format_events(&$events)
+        );
+    }};
+}
+
 #[macro_export]
 macro_rules! event {
     ($name: expr ; $($k: path = $v: expr),*) => {{
@@ -562,15 +566,17 @@ macro_rules! event {
 
         })*;
 
-        onefuzz_telemetry::track_event($name, events);
+        log_events!($name; events);
     }};
 }
 
 #[macro_export]
 macro_rules! log {
     ($level: expr, $($arg: tt)+) => {{
-        if onefuzz_telemetry::should_log(&$level) {
+        let log_level = onefuzz_telemetry::to_log_level(&$level);
+        if log_level <= log::max_level() {
             let msg = format!("{}", format_args!($($arg)+));
+            log::log!(log_level, "{}", msg);
             onefuzz_telemetry::log_message($level, msg.to_string());
         }
     }};
diff --git a/src/proxy-manager/Cargo.lock b/src/proxy-manager/Cargo.lock
index 225f70df2..be5293591 100644
--- a/src/proxy-manager/Cargo.lock
+++ b/src/proxy-manager/Cargo.lock
@@ -1165,6 +1165,7 @@ dependencies = [
  "clap",
  "env_logger",
  "futures",
+ "log",
  "onefuzz-telemetry",
  "reqwest",
  "reqwest-retry",
diff --git a/src/proxy-manager/Cargo.toml b/src/proxy-manager/Cargo.toml
index eeff07775..e1d556d4a 100644
--- a/src/proxy-manager/Cargo.toml
+++ b/src/proxy-manager/Cargo.toml
@@ -20,4 +20,5 @@ tokio = { version = "0.2", features = ["macros", "rt-threaded", "fs", "process"]
 url = { version = "2.2", features = ["serde"] }
 reqwest-retry = { path = "../agent/reqwest-retry"}
 onefuzz-telemetry = { path = "../agent/onefuzz-telemetry" }
-uuid = "0.8"
\ No newline at end of file
+uuid = "0.8"
+log = "0.4"