feat: Enable/Disable logging in tests via RUST_LOG environment variable (#793)

* feat: Enable/Disable logging in tests via RUST_LOG environment variable

* docs: Add section to contributing

* docs: tweak readme

* fix: Use same logging system in tests as in influxdb_ioxd

CONTRIBUTING.md

@@ -99,6 +99,25 @@ The `cargo` build tool runs tests as well. Run:
 cargo test --workspace
 ```
 
+### Enabling logging in tests
+
+To enable logging to stderr during a run of `cargo test` set the Rust
+`RUST_LOG` environment varable. For example, to see all INFO messages:
+
+```shell
+RUST_LOG=info cargo test --workspace
+```
+
+Since this feature uses
+[`EnvFilter`](https://docs.rs/tracing-subscriber/0.2.15/tracing_subscriber/filter/struct.EnvFilter.html) internally, you
+can use all the features of that crate. For example, to disable the
+(somewhat noisy) logs in some h2 modules, you can use a value of
+`RUST_LOG` such as:
+
+```shell
+RUST_LOG=debug,hyper::proto::h1=info,h2=info cargo test --workspace
+```
+
 ## Running `rustfmt` and `clippy`
 
 CI will check the code formatting with [`rustfmt`] and Rust best practices with [`clippy`].

Cargo.lock

@@ -3536,9 +3536,9 @@ name = "test_helpers"
 version = "0.1.0"
 dependencies = [
  "dotenv",
- "env_logger 0.7.1",
  "tempfile",
  "tracing",
+ "tracing-subscriber",
 ]
 
 [[package]]

server/src/query_tests/sql.rs

@@ -13,7 +13,7 @@ use query::{exec::Executor, frontend::sql::SQLQueryPlanner};
 /// output
 macro_rules! run_sql_test_case {
     ($DB_SETUP:expr, $SQL:expr, $EXPECTED_LINES:expr) => {
-        //test_helpers::enable_logging();
+        test_helpers::maybe_start_logging();
         let sql = $SQL.to_string();
         for scenario in $DB_SETUP.make().await {
             let DBScenario { scenario_name, db } = scenario;

server/src/query_tests/table_schema.rs

@@ -13,6 +13,7 @@ use super::scenarios::*;
 /// output
 macro_rules! run_table_schema_test_case {
     ($DB_SETUP:expr, $SELECTION:expr, $TABLE_NAME:expr, $EXPECTED_SCHEMA:expr) => {
+        test_helpers::maybe_start_logging();
         let selection = $SELECTION;
         let table_name = $TABLE_NAME;
         let expected_schema = $EXPECTED_SCHEMA;

test_helpers/Cargo.toml

@@ -6,7 +6,6 @@ edition = "2018"
 
 [dependencies] # In alphabetical order
 dotenv = "0.15.0"
-env_logger = "0.7.1"
 tempfile = "3.1.0"
 tracing = "0.1"
-
+tracing-subscriber = "0.2.15"

test_helpers/src/lib.rs

@@ -85,17 +85,37 @@ pub fn tag_key_bytes_to_strings(bytes: Vec<u8>) -> String {
 
 static LOG_SETUP: Once = Once::new();
 
-/// Enables debug logging. This function can be called more than once
-pub fn enable_logging() {
+/// Enables debug logging regardless of the value of RUST_LOG
+/// environment variable. If RUST_LOG isn't specifies, defaults to
+/// "debug"
+pub fn start_logging() {
     // ensure the global has been initialized
     LOG_SETUP.call_once(|| {
-        // TODO honor any existing RUST_LOG level (and maybe not start
-        // logging unless it is set??)
+        // honor any existing RUST_LOG level
+        if std::env::var("RUST_LOG").is_err() {
             std::env::set_var("RUST_LOG", "debug");
-        env_logger::init();
+        }
+        // Configure the logger to write to stderr and install it
+        let output_stream = std::io::stderr;
+
+        use tracing_subscriber::{prelude::*, EnvFilter};
+
+        tracing_subscriber::registry()
+            .with(EnvFilter::from_default_env())
+            .with(tracing_subscriber::fmt::layer().with_writer(output_stream))
+            .init();
     })
 }
 
+/// Enables debug logging if the RUST_LOG environment variable is
+/// set. Does nothing if RUST_LOG is not set. If enable_logging has
+/// been set previously, does nothing
+pub fn maybe_start_logging() {
+    if std::env::var("RUST_LOG").is_ok() {
+        start_logging()
+    }
+}
+
 #[macro_export]
 /// A macro to assert that one string is contained within another with
 /// a nice error message if they are not.