move to using tracing instead of log (Azure#1579)

In order to move towards supporting OpenTelemetry, we need to move the
underlying logging implementation to use `tracing`.

This does _not_ start exposing spans or tracing state yet.

ref: https://azure.github.io/azure-sdk/general_implementation.html

Author: demoray

sdk/core/Cargo.toml

@@ -20,7 +20,7 @@ bytes = "1.0"
 dyn-clone = "1.0"
 futures = "0.3"
 http-types = { version = "2.12", default-features = false }
-log = "0.4"
+tracing = "0.1.40"
 rand = "0.8"
 reqwest = { version = "0.11.14", features = [
   "stream",
@@ -48,7 +48,7 @@ getrandom = { version = "0.2", features = ["js"] }
 rustc_version = "0.4"
 
 [dev-dependencies]
-env_logger = "0.10"
+tracing-subscriber = "0.3"
 tokio = { version = "1.0", features = ["default", "macros", "rt", "time"] }
 thiserror = "1.0"
 

sdk/core/src/headers/utilities.rs

@@ -80,7 +80,7 @@ pub fn delete_type_permanent_from_headers(headers: &Headers) -> crate::Result<bo
     if result.is_ok() {
         result
     } else {
-        log::warn!("Error receiving delete type permanent.  returning false");
+        tracing::warn!("Error receiving delete type permanent.  returning false");
         Ok(false)
     }
 }

sdk/core/src/http_client/reqwest.rs

@@ -5,10 +5,11 @@ use crate::{
 use async_trait::async_trait;
 use futures::TryStreamExt;
 use std::{collections::HashMap, str::FromStr, sync::Arc};
+use tracing::{debug, warn};
 
 /// Construct a new `HttpClient` with the `reqwest` backend.
 pub fn new_reqwest_client() -> Arc<dyn HttpClient> {
-    log::debug!("instantiating an http client using the reqwest backend");
+    debug!("instantiating an http client using the reqwest backend");
 
     // set `pool_max_idle_per_host` to `0` to avoid an issue in the underlying
     // `hyper` library that causes the `reqwest` client to hang in some cases.
@@ -53,7 +54,7 @@ impl HttpClient for ::reqwest::Client {
         }
         .context(ErrorKind::Other, "failed to build `reqwest` request")?;
 
-        log::debug!("performing request {method} '{url}' with `reqwest`");
+        debug!("performing request {method} '{url}' with `reqwest`");
         let rsp = self
             .execute(reqwest_request)
             .await
@@ -89,7 +90,7 @@ fn to_headers(map: &::reqwest::header::HeaderMap) -> crate::headers::Headers {
                     crate::headers::HeaderValue::from(value.to_owned()),
                 ))
             } else {
-                log::warn!("header value for `{key}` is not utf8");
+                warn!("header value for `{key}` is not utf8");
                 None
             }
         })

sdk/core/src/parsing.rs

@@ -49,7 +49,7 @@ pub fn from_azure_time(s: &str) -> crate::Result<time::OffsetDateTime> {
     if let Ok(dt) = date::parse_rfc1123(s) {
         Ok(dt)
     } else {
-        log::warn!("Received an invalid date: {}, returning now()", s);
+        tracing::warn!("Received an invalid date: {}, returning now()", s);
         Ok(time::OffsetDateTime::now_utc())
     }
 }

sdk/core/src/policies/custom_headers_policy.rs

@@ -1,7 +1,10 @@
-use crate::headers::Headers;
-use crate::policies::{Policy, PolicyResult};
-use crate::{Context, Request};
+use crate::{
+    headers::Headers,
+    policies::{Policy, PolicyResult},
+    Context, Request,
+};
 use std::sync::Arc;
+use tracing::trace;
 
 #[derive(Debug, Clone)]
 pub struct CustomHeaders(Headers);
@@ -28,7 +31,7 @@ impl Policy for CustomHeadersPolicy {
             custom_headers
                 .iter()
                 .for_each(|(header_name, header_value)| {
-                    log::trace!(
+                    trace!(
                         "injecting custom context header {:?} with value {:?}",
                         header_name,
                         header_value

sdk/core/src/policies/retry_policies/retry_policy.rs

@@ -1,15 +1,15 @@
-use crate::date;
-use crate::error::{Error, ErrorKind, HttpError, ResultExt};
-use crate::headers::{Headers, RETRY_AFTER, RETRY_AFTER_MS, X_MS_RETRY_AFTER_MS};
-use crate::policies::{Policy, PolicyResult, Request};
-use crate::sleep::sleep;
-use crate::{Context, StatusCode};
-
+use crate::{
+    date,
+    error::{Error, ErrorKind, HttpError, ResultExt},
+    headers::{Headers, RETRY_AFTER, RETRY_AFTER_MS, X_MS_RETRY_AFTER_MS},
+    policies::{Policy, PolicyResult, Request},
+    sleep::sleep,
+    Context, StatusCode,
+};
 use async_trait::async_trait;
+use std::{sync::Arc, time::Duration};
 use time::OffsetDateTime;
-
-use std::sync::Arc;
-use std::time::Duration;
+use tracing::{debug, trace};
 
 /// Attempts to parse the supplied string as an HTTP date, of the form defined by RFC 1123 (e.g. `Fri, 01 Jan 2021 00:00:00 GMT`).
 /// Returns `None` if the string is not a valid HTTP date.
@@ -122,7 +122,7 @@ where
             let start = start.get_or_insert_with(OffsetDateTime::now_utc);
             let (last_error, retry_after) = match result {
                 Ok(response) if response.status().is_success() => {
-                    log::trace!(
+                    trace!(
                         "Successful response. Request={:?} response={:?}",
                         request,
                         response
@@ -151,7 +151,7 @@ where
                     );
 
                     if !RETRY_STATUSES.contains(&status) {
-                        log::debug!(
+                        debug!(
                             "server returned error status which will not be retried: {}",
                             status
                         );
@@ -165,15 +165,15 @@ where
                         );
                         return Err(error);
                     }
-                    log::debug!(
+                    debug!(
                         "server returned error status which requires retry: {}",
                         status
                     );
                     (Error::new(error_kind, http_error), retry_after)
                 }
                 Err(error) => {
                     if error.kind() == &ErrorKind::Io {
-                        log::debug!(
+                        debug!(
                             "io error occurred when making request which will be retried: {}",
                             error
                         );

sdk/core/src/policies/transport.rs

@@ -1,8 +1,10 @@
-use crate::policies::{Policy, PolicyResult};
-use crate::TransportOptions;
-use crate::{Context, Request};
+use crate::{
+    policies::{Policy, PolicyResult},
+    Context, Request, TransportOptions,
+};
 use async_trait::async_trait;
 use std::sync::Arc;
+use tracing::debug;
 
 #[derive(Debug, Clone)]
 pub struct TransportPolicy {
@@ -27,7 +29,7 @@ impl Policy for TransportPolicy {
         // there must be no more policies
         assert_eq!(0, next.len());
 
-        log::debug!("the following request will be passed to the transport policy: {request:#?}");
+        debug!("the following request will be passed to the transport policy: {request:#?}");
         let response = { self.transport_options.send(ctx, request) };
 
         response.await

sdk/core/src/tokio/fs.rs

@@ -4,13 +4,13 @@ use crate::{
     setters,
 };
 use futures::{task::Poll, Future};
-use log::debug;
 use std::{cmp::min, io::SeekFrom, pin::Pin, sync::Arc, task::Context};
 use tokio::{
     fs::File,
     io::{AsyncReadExt, AsyncSeekExt, Take},
     sync::Mutex,
 };
+use tracing::debug;
 
 #[derive(Debug)]
 pub struct FileStreamBuilder {

sdk/data_cosmos/Cargo.toml

@@ -17,7 +17,7 @@ async-trait = "0.1"
 azure_core = { path = "../core", version = "0.19" }
 time = "0.3.10"
 futures = "0.3"
-log = "0.4"
+tracing = "0.1.40"
 serde = { version = "1.0", features = ["derive"] }
 serde_json = "1.0"
 url = "2.2"
@@ -26,7 +26,7 @@ thiserror = "1.0"
 bytes = "1.0"
 
 [dev-dependencies]
-env_logger = "0.10"
+tracing-subscriber = "0.3"
 tokio = { version = "1", features = ["macros", "rt-multi-thread"] }
 clap = { version = "4.0.2", features = ["derive", "env"] }
 reqwest = "0.11.0"

sdk/data_cosmos/examples/cancellation.rs

@@ -16,7 +16,7 @@ struct Args {
 
 #[tokio::main]
 async fn main() -> azure_core::Result<()> {
-    env_logger::init();
+    tracing_subscriber::fmt().init();
     // First we retrieve the account name and access key from environment variables, and
     // create an authorization token.
     let args = Args::parse();

sdk/data_cosmos/src/authorization_policy.rs

@@ -1,11 +1,13 @@
-use crate::resources::permission::AuthorizationToken;
-use crate::resources::ResourceType;
-use azure_core::headers::{HeaderValue, AUTHORIZATION, MS_DATE, VERSION};
-use azure_core::hmac::hmac_sha256;
-use azure_core::{date, Context, Policy, PolicyResult, Request, Url};
-use std::borrow::Cow;
-use std::sync::Arc;
+use crate::{resources::permission::AuthorizationToken, resources::ResourceType};
+use azure_core::{
+    date,
+    headers::{HeaderValue, AUTHORIZATION, MS_DATE, VERSION},
+    hmac::hmac_sha256,
+    Context, Policy, PolicyResult, Request, Url,
+};
+use std::{borrow::Cow, sync::Arc};
 use time::OffsetDateTime;
+use tracing::trace;
 use url::form_urlencoded;
 
 const AZURE_VERSION: &str = "2018-12-31";

sdk/data_cosmos/src/lib.rs

@@ -87,8 +87,6 @@ async fn main() -> azure_core::Result<()> {
 #![deny(missing_docs)]
 #![recursion_limit = "256"]
 #[macro_use]
-extern crate log;
-#[macro_use]
 extern crate serde;
 #[macro_use]
 extern crate azure_core;

sdk/data_cosmos/src/operations/query_documents.rs

@@ -16,6 +16,7 @@ use azure_core::{
 use serde::de::DeserializeOwned;
 use serde_json::Value;
 use time::OffsetDateTime;
+use tracing::warn;
 
 operation! {
     #[stream]

sdk/data_cosmos/src/resource_quota.rs

@@ -1,4 +1,5 @@
 use azure_core::error::{Error, ErrorKind};
+use tracing::{debug, trace};
 
 /// A resource quota for the given resource kind
 ///

sdk/data_cosmos/src/resources/permission/authorization_token.rs

@@ -1,7 +1,7 @@
 use super::PermissionToken;
 use azure_core::auth::{Secret, TokenCredential};
-use std::fmt;
-use std::sync::Arc;
+use std::{fmt, sync::Arc};
+use tracing::trace;
 
 /// Authorization tokens for accessing Cosmos.
 ///

sdk/data_cosmos/src/resources/permission/permission_token.rs

@@ -1,5 +1,6 @@
 use super::AuthorizationToken;
 use azure_core::{auth::Secret, base64};
+use tracing::trace;
 
 const PERMISSION_TYPE_PREFIX: &str = "type=";
 const VERSION_PREFIX: &str = "ver=";

sdk/data_cosmos/tests/collection_operations.rs

@@ -1,31 +1,32 @@
 use azure_data_cosmos::resources::collection::*;
 use futures::StreamExt;
+use tracing::{debug, info};
 
 mod setup_mock;
 
 #[tokio::test]
 async fn collection_operations() -> azure_core::Result<()> {
-    env_logger::init();
+    tracing_subscriber::fmt().init();
 
     let client = setup_mock::initialize("collection_operations")?;
     let database_name = "test-collection-operations";
 
-    log::info!("Creating a database with name '{}'...", database_name);
+    info!("Creating a database with name '{}'...", database_name);
     client.create_database(database_name).await?;
-    log::info!("Successfully created a database");
+    info!("Successfully created a database");
 
     // create collection!
     let database = client.database_client(database_name);
 
     let collection_name = "sample_collection";
-    log::info!("Creating a collection with name '{}'...", collection_name);
+    info!("Creating a collection with name '{}'...", collection_name);
 
     let create_collection_response = database.create_collection(collection_name, "/id").await?;
 
     assert_eq!(create_collection_response.collection.id, collection_name);
 
-    log::info!("Successfully created a collection");
-    log::debug!(
+    info!("Successfully created a collection");
+    debug!(
         "The create_collection response: {:#?}",
         create_collection_response
     );
@@ -37,8 +38,8 @@ async fn collection_operations() -> azure_core::Result<()> {
 
     assert_eq!(get_collection.collection.id, collection_name);
 
-    log::info!("Successfully got a collection");
-    log::debug!("The get_collection response: {:#?}", get_collection);
+    info!("Successfully got a collection");
+    debug!("The get_collection response: {:#?}", get_collection);
 
     let collections = database
         .list_collections()
@@ -99,24 +100,24 @@ async fn collection_operations() -> azure_core::Result<()> {
         "/\"excludeme\"/?"
     );
 
-    log::info!("Successfully replaced collection");
-    log::debug!(
+    info!("Successfully replaced collection");
+    debug!(
         "The replace_collection response: {:#?}",
         replace_collection_response
     );
 
     // delete collection!
     let delete_collection_response = collection.delete_collection().await?;
 
-    log::info!("Successfully deleted collection");
-    log::debug!(
+    info!("Successfully deleted collection");
+    debug!(
         "The delete_collection response: {:#?}",
         delete_collection_response
     );
 
     // delete database
     database.delete_database().await?;
-    log::info!("Successfully deleted database");
+    info!("Successfully deleted database");
 
     Ok(())
 }