Merge pull request #197 from influxdata/alamb/log-requests

feat: Log gRPC calls using trace crate, allow custom log levels

Cargo.lock

@@ -662,6 +662,8 @@ dependencies = [
  "tempfile",
  "tokio",
  "tonic 0.2.1",
+ "tracing",
+ "tracing-futures",
 ]
 
 [[package]]

Cargo.toml

@@ -57,6 +57,9 @@ num_cpus = "1.11.1"
 tonic = "0.2.0"
 prost = "0.6.1"
 prost-types = "0.6.1"
+tracing = "0.1"
+tracing-futures="0.2.4"
+
 
 crc32fast = "1.2.0"
 num = "0.2.1"

src/main.rs

@@ -36,6 +36,9 @@ Examples:
     # Run the Delorean server with extra verbose logging
     delorean -v
 
+    # Run delorean with full debug logging specified with RUST_LOG
+    RUST_LOG=debug delorean
+
     # converts line protocol formatted data in temperature.lp to out.parquet
     delorean convert temperature.lp out.parquet
 
@@ -97,20 +100,13 @@ Examples:
                 ),
         )
         .subcommand(SubCommand::with_name("server").about("Runs in server mode (default)"))
-        .arg(
-            Arg::with_name("verbose")
-                .short("v")
-                .long("verbose")
-                .help("Enables verbose output"),
-        )
+        .arg(Arg::with_name("verbose").short("v").long("verbose").help(
+            "Enables verbose logging. You can also set log level via \
+                       the environment variable RUST_LOG=<value>",
+        ))
         .get_matches();
 
-    if matches.is_present("verbose") {
-        std::env::set_var("RUST_LOG", "delorean=debug,hyper=info");
-    } else {
-        std::env::set_var("RUST_LOG", "delorean=info,hyper=info");
-    }
-    env_logger::init();
+    setup_logging(matches.is_present("verbose"));
 
     match matches.subcommand() {
         ("convert", Some(sub_matches)) => {
@@ -158,3 +154,38 @@ Examples:
         }
     }
 }
+
+/// Default debug level is debug for everything except
+/// some especially noisy low level libraries
+const DEFAULT_DEBUG_LOG_LEVEL: &str = "debug,h2=info";
+
+// Default log level is info level for all components
+const DEFAULT_LOG_LEVEL: &str = "info";
+
+/// Configures logging in the following precedence:
+///
+/// 1. If RUST_LOG environment variable is set, use that value
+/// 2. if `verbose_requested`, use DEFAULT_DEBUG_LOG_LEVEL
+/// 3. otherwise, use DEFAULT_LOG_LEVEL
+fn setup_logging(verbose_requested: bool) {
+    let rust_log_env = std::env::var("RUST_LOG");
+
+    if verbose_requested {
+        match rust_log_env {
+            Ok(lvl) => {
+                eprintln!(
+                    "WARNING: Using RUST_LOG='{}' environment, ignoring request for -v",
+                    lvl
+                );
+            }
+            Err(_) => std::env::set_var("RUST_LOG", DEFAULT_DEBUG_LOG_LEVEL),
+        }
+    } else {
+        match rust_log_env {
+            Ok(_) => {}
+            Err(_) => std::env::set_var("RUST_LOG", DEFAULT_LOG_LEVEL),
+        }
+    }
+
+    env_logger::init();
+}

src/rpc.rs

@@ -1,3 +1,9 @@
+//! This module contains gRPC service implementatations
+
+// Something about how `tracing::instrument` works triggers a clippy
+// warning about complex types
+#![allow(clippy::type_complexity)]
+
 use delorean::generated_types::{
     delorean_server::Delorean,
     measurement_fields_response::MessageField,
@@ -26,12 +32,14 @@ use tonic::Status;
 
 use crate::server::App;
 
+#[derive(Debug)]
 pub struct GrpcServer {
     pub app: Arc<App>,
 }
 
 #[tonic::async_trait]
 impl Delorean for GrpcServer {
+    #[tracing::instrument(level = "debug")]
     async fn create_bucket(
         &self,
         req: tonic::Request<CreateBucketRequest>,
@@ -55,6 +63,9 @@ impl Delorean for GrpcServer {
         Ok(tonic::Response::new(CreateBucketResponse {}))
     }
 
+    // Something in instrument is causing lint warnings about unused braces
+    #[allow(unused_braces)]
+    #[tracing::instrument(level = "debug")]
     async fn delete_bucket(
         &self,
         _req: tonic::Request<DeleteBucketRequest>,
@@ -62,6 +73,7 @@ impl Delorean for GrpcServer {
         Ok(tonic::Response::new(DeleteBucketResponse {}))
     }
 
+    #[tracing::instrument(level = "debug")]
     async fn get_buckets(
         &self,
         req: tonic::Request<Organization>,
@@ -174,6 +186,7 @@ impl GrpcInputs for MeasurementFieldsRequest {
 impl Storage for GrpcServer {
     type ReadFilterStream = mpsc::Receiver<Result<ReadResponse, Status>>;
 
+    #[tracing::instrument(level = "debug")]
     async fn read_filter(
         &self,
         req: tonic::Request<ReadFilterRequest>,
@@ -210,6 +223,7 @@ impl Storage for GrpcServer {
 
     type ReadGroupStream = mpsc::Receiver<Result<ReadResponse, Status>>;
 
+    #[tracing::instrument(level = "debug")]
     async fn read_group(
         &self,
         req: tonic::Request<ReadGroupRequest>,
@@ -256,6 +270,7 @@ impl Storage for GrpcServer {
 
     type TagKeysStream = mpsc::Receiver<Result<StringValuesResponse, Status>>;
 
+    #[tracing::instrument(level = "debug")]
     async fn tag_keys(
         &self,
         req: tonic::Request<TagKeysRequest>,
@@ -306,6 +321,7 @@ impl Storage for GrpcServer {
 
     type TagValuesStream = mpsc::Receiver<Result<StringValuesResponse, Status>>;
 
+    #[tracing::instrument(level = "debug")]
     async fn tag_values(
         &self,
         req: tonic::Request<TagValuesRequest>,
@@ -360,15 +376,19 @@ impl Storage for GrpcServer {
         Ok(tonic::Response::new(rx))
     }
 
+    // Something in instrument is causing lint warnings about unused braces
+    #[allow(unused_braces)]
+    #[tracing::instrument(level = "debug")]
     async fn capabilities(
         &self,
-        _: tonic::Request<()>,
+        req: tonic::Request<()>,
     ) -> Result<tonic::Response<CapabilitiesResponse>, Status> {
         Err(Status::unimplemented("Not yet implemented"))
     }
 
     type MeasurementNamesStream = mpsc::Receiver<Result<StringValuesResponse, Status>>;
 
+    #[tracing::instrument(level = "debug")]
     async fn measurement_names(
         &self,
         req: tonic::Request<MeasurementNamesRequest>,
@@ -422,6 +442,7 @@ impl Storage for GrpcServer {
 
     type MeasurementTagKeysStream = mpsc::Receiver<Result<StringValuesResponse, Status>>;
 
+    #[tracing::instrument(level = "debug")]
     async fn measurement_tag_keys(
         &self,
         req: tonic::Request<MeasurementTagKeysRequest>,
@@ -483,6 +504,7 @@ impl Storage for GrpcServer {
 
     type MeasurementTagValuesStream = mpsc::Receiver<Result<StringValuesResponse, Status>>;
 
+    #[tracing::instrument(level = "debug")]
     async fn measurement_tag_values(
         &self,
         req: tonic::Request<MeasurementTagValuesRequest>,
@@ -546,6 +568,7 @@ impl Storage for GrpcServer {
 
     type MeasurementFieldsStream = mpsc::Receiver<Result<MeasurementFieldsResponse, Status>>;
 
+    #[tracing::instrument(level = "debug")]
     async fn measurement_fields(
         &self,
         req: tonic::Request<MeasurementFieldsRequest>,
@@ -617,6 +640,7 @@ impl Storage for GrpcServer {
     }
 }
 
+#[tracing::instrument(level = "debug")]
 async fn send_series_filters(
     mut tx: mpsc::Sender<Result<ReadResponse, Status>>,
     app: Arc<App>,
@@ -681,6 +705,7 @@ async fn send_series_filters(
     Ok(())
 }
 
+#[tracing::instrument(level = "debug")]
 async fn send_groups(
     mut tx: mpsc::Sender<Result<ReadResponse, Status>>,
     app: Arc<App>,

src/server.rs

@@ -1,6 +1,6 @@
 #![deny(rust_2018_idioms)]
 
-use log::{debug, info, warn};
+use tracing::{debug, info, warn};
 
 use delorean::generated_types::{
     delorean_server::DeloreanServer, storage_server::StorageServer, Bucket, TimestampRange,
@@ -29,6 +29,7 @@ use serde::Deserialize;
 
 use crate::rpc::GrpcServer;
 
+#[derive(Debug)]
 pub struct App {
     pub db: Database,
 }