feat(ads-client): add telemetry with tracing

Author: Almaju

Cargo.lock

@@ -12,6 +12,7 @@ default = []
 chrono = "0.4"
 context_id = { path = "../context_id" }
 error-support = { path = "../support/error" }
+once_cell = "1.5"
 parking_lot = "0.12"
 rusqlite = { version = "0.37.0", features = [
   "functions",
@@ -21,13 +22,17 @@ rusqlite = { version = "0.37.0", features = [
 ] }
 serde = "1"
 serde_json = "1"
+sql-support = { path = "../support/sql" }
 thiserror = "2"
-once_cell = "1.5"
+tracing = "0.1"
+tracing-subscriber = { version = "0.3", default-features = false, features = [
+  "registry",
+  "std",
+] }
 uniffi = { version = "0.29.0" }
 url = { version = "2", features = ["serde"] }
 uuid = { version = "1.3", features = ["v4"] }
 viaduct = { path = "../viaduct" }
-sql-support = { path = "../support/sql" }
 
 [dev-dependencies]
 mockall = "0.12"

components/ads-client/Cargo.toml

@@ -10,6 +10,8 @@ use serde::{Deserialize, Serialize};
 use std::collections::{HashMap, HashSet};
 use url::Url;
 
+use tracing::error;
+
 #[derive(Debug, Deserialize, PartialEq, uniffi::Record, Serialize)]
 pub struct AdResponse {
     #[serde(deserialize_with = "AdResponse::deserialize_ad_response", flatten)]
@@ -33,12 +35,7 @@ impl AdResponse {
                     if let Ok(ad) = serde_json::from_value::<MozAd>(item) {
                         ads.push(ad);
                     } else {
-                        #[cfg(not(test))]
-                        {
-                            use crate::instrument::{emit_telemetry_event, TelemetryEvent};
-                            // TODO: improve the telemetry event (should we include the invalid URL?)
-                            let _ = emit_telemetry_event(Some(TelemetryEvent::InvalidUrlError));
-                        }
+                        error!(target: "ads_client::telemetry", "InvalidUrlError");
                     }
                 }
                 if !ads.is_empty() {

components/ads-client/src/client/ad_response.rs

@@ -3,7 +3,7 @@
 * file, You can obtain one at http://mozilla.org/MPL/2.0/.
 */
 
-use error_support::{error, ErrorHandling, GetErrorHandling};
+use error_support::{ErrorHandling, GetErrorHandling};
 use viaduct::Response;
 
 pub type AdsClientApiResult<T> = std::result::Result<T, AdsClientApiError>;
@@ -92,21 +92,6 @@ pub enum FetchAdsError {
     HTTPError(#[from] HTTPError),
 }
 
-#[derive(Debug, thiserror::Error)]
-pub enum EmitTelemetryError {
-    #[error("URL parse error: {0}")]
-    UrlParse(#[from] url::ParseError),
-
-    #[error("Error sending request: {0}")]
-    Request(#[from] viaduct::ViaductError),
-
-    #[error("JSON error: {0}")]
-    Json(#[from] serde_json::Error),
-
-    #[error("Could not fetch ads, MARS responded with: {0}")]
-    HTTPError(#[from] HTTPError),
-}
-
 #[derive(Debug, thiserror::Error)]
 pub enum CallbackRequestError {
     #[error("Could not fetch ads, MARS responded with: {0}")]

components/ads-client/src/error.rs

@@ -3,63 +3,141 @@
 * file, You can obtain one at http://mozilla.org/MPL/2.0/.
 */
 
-use std::sync::LazyLock;
-
-use crate::error::{ComponentError, EmitTelemetryError};
-use parking_lot::RwLock;
-use serde::{Deserialize, Serialize};
+use once_cell::sync::Lazy;
+use serde_json::json;
+use tracing::field::{Field, Visit};
+use tracing_subscriber::layer::Context;
+use tracing_subscriber::Layer;
 use url::Url;
 use viaduct::Request;
 
-static DEFAULT_TELEMETRY_ENDPOINT: &str = "https://ads.mozilla.org/v1/log";
-static TELEMETRY_ENDPONT: LazyLock<RwLock<String>> =
-    LazyLock::new(|| RwLock::new(DEFAULT_TELEMETRY_ENDPOINT.to_string()));
+static TELEMETRY_ENDPOINT: Lazy<Url> = Lazy::new(|| {
+    Url::parse("https://ads.mozilla.org/v1/log")
+        .expect("hardcoded telemetry endpoint URL must be valid")
+});
 
-fn get_telemetry_endpoint() -> String {
-    TELEMETRY_ENDPONT.read().clone()
+pub fn telemetry_layer<S>() -> impl Layer<S>
+where
+    S: tracing::Subscriber + for<'a> tracing_subscriber::registry::LookupSpan<'a>,
+{
+    TelemetryLayer {
+        endpoint: TELEMETRY_ENDPOINT.clone(),
+    }
+    .with_filter(TelemetryFilter)
 }
 
-#[derive(Debug, Deserialize, Serialize)]
-#[serde(rename_all = "snake_case")]
-pub enum TelemetryEvent {
-    Init,
-    RenderError,
-    AdLoadError,
-    FetchError,
-    InvalidUrlError,
+struct TelemetryLayer {
+    endpoint: Url,
 }
 
-pub trait TrackError<T, ComponentError> {
-    fn emit_telemetry_if_error(self) -> Self;
-}
+impl<S> Layer<S> for TelemetryLayer
+where
+    S: tracing::Subscriber,
+{
+    fn on_event(&self, event: &tracing::Event<'_>, _ctx: Context<'_, S>) {
+        let mut visitor = EventVisitor::default();
+        event.record(&mut visitor);
+
+        let event_message = visitor
+            .fields
+            .get("message")
+            .unwrap_or_default()
+            .as_str()
+            .unwrap_or_default();
 
-impl<T> TrackError<T, ComponentError> for Result<T, ComponentError> {
-    /// Attempts to emit a telemetry event if the Error type can map to an event type.
-    fn emit_telemetry_if_error(self) -> Self {
-        if let Err(ref err) = self {
-            let error_type = map_error_to_event_type(err);
-            let _ = emit_telemetry_event(error_type);
+        let mut url = self.endpoint.clone();
+        url.set_query(Some(&format!("event={event_message}")));
+
+        if let Err(e) = Request::get(url).send() {
+            eprintln!("[TELEMETRY] Failed to send event: {}", e);
         }
-        self
     }
 }
 
-fn map_error_to_event_type(err: &ComponentError) -> Option<TelemetryEvent> {
-    match err {
-        ComponentError::RequestAds(_) => Some(TelemetryEvent::FetchError),
-        ComponentError::RecordImpression(_) => Some(TelemetryEvent::InvalidUrlError),
-        ComponentError::RecordClick(_) => Some(TelemetryEvent::InvalidUrlError),
-        ComponentError::ReportAd(_) => Some(TelemetryEvent::InvalidUrlError),
+struct TelemetryFilter;
+
+impl<S> tracing_subscriber::layer::Filter<S> for TelemetryFilter
+where
+    S: tracing::Subscriber,
+{
+    fn enabled(
+        &self,
+        meta: &tracing::Metadata<'_>,
+        _cx: &tracing_subscriber::layer::Context<'_, S>,
+    ) -> bool {
+        meta.target() == "ads_client::telemetry"
+    }
+}
+
+#[derive(Default)]
+struct EventVisitor {
+    fields: serde_json::Map<String, serde_json::Value>,
+}
+
+impl Visit for EventVisitor {
+    fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) {
+        self.fields.insert(
+            field.name().to_string(),
+            serde_json::Value::String(format!("{:?}", value)),
+        );
+    }
+
+    fn record_str(&mut self, field: &Field, value: &str) {
+        self.fields.insert(field.name().to_string(), json!(value));
+    }
+
+    fn record_i64(&mut self, field: &Field, value: i64) {
+        self.fields.insert(field.name().to_string(), json!(value));
+    }
+
+    fn record_u64(&mut self, field: &Field, value: u64) {
+        self.fields.insert(field.name().to_string(), json!(value));
+    }
+
+    fn record_bool(&mut self, field: &Field, value: bool) {
+        self.fields.insert(field.name().to_string(), json!(value));
     }
 }
 
-pub fn emit_telemetry_event(event_type: Option<TelemetryEvent>) -> Result<(), EmitTelemetryError> {
-    let endpoint = get_telemetry_endpoint();
-    let mut url = Url::parse(&endpoint)?;
-    if let Some(event) = event_type {
-        let event_string = serde_json::to_string(&event)?;
-        url.set_query(Some(&format!("event={}", event_string)));
-        Request::get(url).send()?;
+#[cfg(test)]
+mod tests {
+    use super::*;
+    use mockito::mock;
+    use tracing::error;
+    use tracing_subscriber::prelude::*;
+
+    #[test]
+    fn test_telemetry_layer() {
+        let subscriber = tracing_subscriber::registry::Registry::default().with(telemetry_layer());
+        tracing::subscriber::with_default(subscriber, || {});
+    }
+
+    #[test]
+    fn test_telemetry_sends_to_mock_server() {
+        viaduct_dev::init_backend_dev();
+
+        let mock_server_url = mockito::server_url();
+        let telemetry_url = Url::parse(&format!("{}/v1/log", mock_server_url)).unwrap();
+
+        let mock_endpoint = mock("GET", "/v1/log")
+            .with_status(200)
+            .match_query(mockito::Matcher::Regex(
+                r#"event=test%20telemetry%20error"#.to_string(),
+            ))
+            .expect(1)
+            .create();
+
+        let telemetry_layer = TelemetryLayer {
+            endpoint: telemetry_url,
+        }
+        .with_filter(TelemetryFilter);
+        let subscriber = tracing_subscriber::registry::Registry::default().with(telemetry_layer);
+
+        tracing::subscriber::with_default(subscriber, || {
+            error!(target: "ads_client::telemetry", message = "test telemetry error");
+            error!(target: "ads_client::not_telemetry", message = "non-telemetry event");
+        });
+
+        mock_endpoint.assert();
     }
-    Ok(())
 }

components/ads-client/src/instrument.rs

@@ -9,12 +9,12 @@ use error::AdsClientApiResult;
 use error::ComponentError;
 use error_support::handle_error;
 use parking_lot::Mutex;
+use tracing::error;
 use url::Url as AdsClientUrl;
 
 use client::MozAdsClientInner;
 use error::AdsClientApiError;
 use http_cache::{CacheMode, RequestCachePolicy};
-use instrument::TrackError;
 
 use crate::client::ad_request::AdContentCategory;
 use crate::client::ad_request::AdPlacementRequest;
@@ -25,7 +25,7 @@ use crate::client::config::MozAdsClientConfig;
 mod client;
 mod error;
 pub mod http_cache;
-mod instrument;
+pub mod instrument;
 mod mars;
 
 #[cfg(test)]
@@ -93,28 +93,37 @@ impl MozAdsClient {
     #[handle_error(ComponentError)]
     pub fn record_impression(&self, placement: MozAd) -> AdsClientApiResult<()> {
         let inner = self.inner.lock();
-        inner
+        let result = inner
             .record_impression(&placement)
-            .map_err(ComponentError::RecordImpression)
-            .emit_telemetry_if_error()
+            .map_err(ComponentError::RecordImpression);
+        if result.is_err() {
+            error!(target: "ads_client::telemetry", "InvalidUrlError");
+        }
+        result
     }
 
     #[handle_error(ComponentError)]
     pub fn record_click(&self, placement: MozAd) -> AdsClientApiResult<()> {
         let inner = self.inner.lock();
-        inner
+        let result = inner
             .record_click(&placement)
-            .map_err(ComponentError::RecordClick)
-            .emit_telemetry_if_error()
+            .map_err(ComponentError::RecordClick);
+        if result.is_err() {
+            error!(target: "ads_client::telemetry", "InvalidUrlError");
+        }
+        result
     }
 
     #[handle_error(ComponentError)]
     pub fn report_ad(&self, placement: MozAd) -> AdsClientApiResult<()> {
         let inner = self.inner.lock();
-        inner
+        let result = inner
             .report_ad(&placement)
-            .map_err(ComponentError::ReportAd)
-            .emit_telemetry_if_error()
+            .map_err(ComponentError::ReportAd);
+        if result.is_err() {
+            error!(target: "ads_client::telemetry", "InvalidUrlError");
+        }
+        result
     }
 
     pub fn cycle_context_id(&self) -> AdsClientApiResult<String> {

components/ads-client/src/lib.rs

@@ -7,13 +7,19 @@ license = "MPL-2.0"
 exclude = ["/android", "/ios"]
 
 [dependencies]
+ads-client = { path = "../../ads-client" }
 uniffi = { version = "0.29.0" }
-error-support = { path = "../error", default-features = false, features = ["tracing-logging"] }
-tracing-subscriber = { version = "0.3", default-features = false, features = ["fmt", "std"] }
+error-support = { path = "../error", default-features = false, features = [
+    "tracing-logging",
+] }
+tracing-subscriber = { version = "0.3", default-features = false, features = [
+    "fmt",
+    "std",
+] }
 tracing-support = { path = "../tracing" }
 
 [dev-dependencies]
 tracing = "0.1"
 
 [build-dependencies]
-uniffi = { version = "0.29.0", features=["build"]}
+uniffi = { version = "0.29.0", features = ["build"] }

components/support/rust-log-forwarder/Cargo.toml

@@ -66,6 +66,7 @@ pub fn set_logger(logger: Option<Box<dyn AppServicesLogger>>) {
         use tracing_subscriber::prelude::*;
         tracing_subscriber::registry()
             .with(tracing_support::simple_event_layer())
+            .with(ads_client::instrument::telemetry_layer())
             .init();
     });