logging: Always run crate tests

Ensure the tests in the local `logging` crate are run for all consumers
of it.

Additionally, add a new test which checks that output is generated by a
range of different log level `slog` macros. This is designed to ensure
debug level output is always available for the consumers of the
`logging` crate.

Fixes: #2969.

Signed-off-by: James O. D. Hunt <james.o.hunt@intel.com>

Makefile

@@ -19,7 +19,10 @@ STANDARD_TARGETS = build check clean install test vendor
 
 default: all
 
-all: build
+all: logging-crate-tests build
+
+logging-crate-tests:
+	make -C pkg/logging
 
 include utils.mk
 include ./tools/packaging/kata-deploy/local-build/Makefile
@@ -36,4 +39,10 @@ generate-protocols:
 static-checks: build
 	bash ci/static-checks.sh
 
-.PHONY: all default static-checks binary-tarball install-binary-tarball
+.PHONY: \
+	all \
+	binary-tarball \
+	default \
+	install-binary-tarball \
+	logging-crate-tests \
+	static-checks

pkg/logging/Makefile

@@ -0,0 +1,18 @@
+# Copyright (c) 2021 Intel Corporation
+#
+# SPDX-License-Identifier: Apache-2.0
+#
+
+# It is not necessary to have a build target as this crate is built
+# automatically by the consumers of it.
+#
+# However, it is essential that the crate be tested.
+default: test
+
+# It is essential to run these tests using *both* build profiles.
+# See the `test_logger_levels()` test for further information.
+test:
+	@echo "INFO: testing log levels for development build"
+	@cargo test
+	@echo "INFO: testing log levels for release build"
+	@cargo test --release

pkg/logging/src/lib.rs

@@ -20,6 +20,8 @@ const LOG_LEVELS: &[(&str, slog::Level)] = &[
     ("critical", slog::Level::Critical),
 ];
 
+const DEFAULT_SUBSYSTEM: &str = "root";
+
 // XXX: 'writer' param used to make testing possible.
 pub fn create_logger<W>(
     name: &str,
@@ -50,7 +52,7 @@ where
     let logger = slog::Logger::root(
         async_drain.fuse(),
         o!("version" => env!("CARGO_PKG_VERSION"),
-            "subsystem" => "root",
+            "subsystem" => DEFAULT_SUBSYSTEM,
             "pid" => process::id().to_string(),
             "name" => name.to_string(),
             "source" => source.to_string()),
@@ -216,8 +218,8 @@ where
 #[cfg(test)]
 mod tests {
     use super::*;
-    use serde_json::Value;
-    use slog::info;
+    use serde_json::{json, Value};
+    use slog::{crit, debug, error, info, warn, Logger};
     use std::io::prelude::*;
     use tempfile::NamedTempFile;
 
@@ -295,15 +297,15 @@ mod tests {
                 let result_level = result.unwrap();
                 let expected_level = d.result.unwrap();
 
-                assert!(result_level == expected_level, msg);
+                assert!(result_level == expected_level, "{}", msg);
                 continue;
             } else {
-                assert!(result.is_err(), msg);
+                assert!(result.is_err(), "{}", msg);
             }
 
-            let expected_error = format!("{}", d.result.as_ref().unwrap_err());
-            let actual_error = format!("{}", result.unwrap_err());
-            assert!(actual_error == expected_error, msg);
+            let expected_error = d.result.as_ref().unwrap_err();
+            let actual_error = result.unwrap_err();
+            assert!(&actual_error == expected_error, "{}", msg);
         }
     }
 
@@ -350,13 +352,13 @@ mod tests {
             let msg = format!("{}, result: {:?}", msg, result);
 
             if d.result.is_ok() {
-                assert!(result == d.result, msg);
+                assert!(result == d.result, "{}", msg);
                 continue;
             }
 
-            let expected_error = format!("{}", d.result.as_ref().unwrap_err());
-            let actual_error = format!("{}", result.unwrap_err());
-            assert!(actual_error == expected_error, msg);
+            let expected_error = d.result.as_ref().unwrap_err();
+            let actual_error = result.unwrap_err();
+            assert!(&actual_error == expected_error, "{}", msg);
         }
     }
 
@@ -376,14 +378,17 @@ mod tests {
         let record_key = "record-key-1";
         let record_value = "record-key-2";
 
-        let logger = create_logger(name, source, level, writer);
+        let (logger, guard) = create_logger(name, source, level, writer);
 
         let msg = "foo, bar, baz";
 
         // Call the logger (which calls the drain)
-        info!(logger, "{}", msg; "subsystem" => record_subsystem, record_key => record_value);
+        // Note: This "mid level" log level should be available in debug or
+        // release builds.
+        info!(&logger, "{}", msg; "subsystem" => record_subsystem, record_key => record_value);
 
         // Force temp file to be flushed
+        drop(guard);
         drop(logger);
 
         let mut contents = String::new();
@@ -430,4 +435,168 @@ mod tests {
             .expect("failed to find record key field");
         assert_eq!(field_record_value, record_value);
     }
+
+    #[test]
+    fn test_logger_levels() {
+        let name = "name";
+        let source = "source";
+
+        let debug_msg = "a debug log level message";
+        let info_msg = "an info log level message";
+        let warn_msg = "a warn log level message";
+        let error_msg = "an error log level message";
+        let critical_msg = "a critical log level message";
+
+        // The slog crate will *remove* macro calls for log levels "above" the
+        // configured log level.lock
+        //
+        // At the time of writing, the default slog log
+        // level is "info", but this crate overrides that using the magic
+        // "*max_level*" features in the "Cargo.toml" manifest.
+
+        // However, there are two log levels:
+        //
+        // - max_level_${level}
+        //
+        //   This is the log level for normal "cargo build" (development/debug)
+        //   builds.
+        //
+        // - release_max_level_${level}
+        //
+        //   This is the log level for "cargo install" and
+        //   "cargo build --release" (release) builds.
+        //
+        // This crate sets them to different values, which is sensible and
+        // standard practice. However, that causes a problem: there is
+        // currently no clean way for this test code to detect _which_
+        // profile the test is being built for (development or release),
+        // meaning we cannot know which macros are expected to produce output
+        // and which aren't ;(
+        //
+        // The best we can do is test the following log levels which
+        // are expected to work in all build profiles.
+
+        let debug_closure = |logger: &Logger, msg: String| debug!(logger, "{}", msg);
+        let info_closure = |logger: &Logger, msg: String| info!(logger, "{}", msg);
+        let warn_closure = |logger: &Logger, msg: String| warn!(logger, "{}", msg);
+        let error_closure = |logger: &Logger, msg: String| error!(logger, "{}", msg);
+        let critical_closure = |logger: &Logger, msg: String| crit!(logger, "{}", msg);
+
+        struct TestData<'a> {
+            slog_level: slog::Level,
+            slog_level_tag: &'a str,
+            msg: String,
+            closure: Box<dyn Fn(&Logger, String)>,
+        }
+
+        let tests = &[
+            TestData {
+                slog_level: slog::Level::Debug,
+                // Looks like a typo but tragically it isn't! ;(
+                slog_level_tag: "DEBG",
+                msg: debug_msg.into(),
+                closure: Box::new(debug_closure),
+            },
+            TestData {
+                slog_level: slog::Level::Info,
+                slog_level_tag: "INFO",
+                msg: info_msg.into(),
+                closure: Box::new(info_closure),
+            },
+            TestData {
+                slog_level: slog::Level::Warning,
+                slog_level_tag: "WARN",
+                msg: warn_msg.into(),
+                closure: Box::new(warn_closure),
+            },
+            TestData {
+                slog_level: slog::Level::Error,
+                // Another language tragedy
+                slog_level_tag: "ERRO",
+                msg: error_msg.into(),
+                closure: Box::new(error_closure),
+            },
+            TestData {
+                slog_level: slog::Level::Critical,
+                slog_level_tag: "CRIT",
+                msg: critical_msg.into(),
+                closure: Box::new(critical_closure),
+            },
+        ];
+
+        for (i, d) in tests.iter().enumerate() {
+            let msg = format!("test[{}]", i);
+
+            // Create a writer for the logger drain to use
+            let writer =
+                NamedTempFile::new().expect(&format!("{:}: failed to create tempfile", msg));
+
+            // Used to check file contents before the temp file is unlinked
+            let mut writer_ref = writer
+                .reopen()
+                .expect(&format!("{:?}: failed to clone tempfile", msg));
+
+            let (logger, logger_guard) = create_logger(name, source, d.slog_level, writer);
+
+            // Call the logger (which calls the drain)
+            (d.closure)(&logger, d.msg.to_owned());
+
+            // Force temp file to be flushed
+            drop(logger_guard);
+            drop(logger);
+
+            let mut contents = String::new();
+            writer_ref
+                .read_to_string(&mut contents)
+                .expect(&format!("{:?}: failed to read tempfile contents", msg));
+
+            // Convert file to JSON
+            let fields: Value = serde_json::from_str(&contents)
+                .expect(&format!("{:?}: failed to convert logfile to json", msg));
+
+            // Check the expected JSON fields
+
+            let field_ts = fields
+                .get("ts")
+                .expect(&format!("{:?}: failed to find timestamp field", msg));
+            assert_ne!(field_ts, "", "{}", msg);
+
+            let field_version = fields
+                .get("version")
+                .expect(&format!("{:?}: failed to find version field", msg));
+            assert_eq!(field_version, env!("CARGO_PKG_VERSION"), "{}", msg);
+
+            let field_pid = fields
+                .get("pid")
+                .expect(&format!("{:?}: failed to find pid field", msg));
+            assert_ne!(field_pid, "", "{}", msg);
+
+            let field_level = fields
+                .get("level")
+                .expect(&format!("{:?}: failed to find level field", msg));
+            assert_eq!(field_level, d.slog_level_tag, "{}", msg);
+
+            let field_msg = fields
+                .get("msg")
+                .expect(&format!("{:?}: failed to find msg field", msg));
+            assert_eq!(field_msg, &json!(d.msg), "{}", msg);
+
+            let field_name = fields
+                .get("name")
+                .expect(&format!("{:?}: failed to find name field", msg));
+            assert_eq!(field_name, name, "{}", msg);
+
+            let field_source = fields
+                .get("source")
+                .expect(&format!("{:?}: failed to find source field", msg));
+            assert_eq!(field_source, source, "{}", msg);
+
+            let field_subsystem = fields
+                .get("subsystem")
+                .expect(&format!("{:?}: failed to find subsystem field", msg));
+
+            // No explicit subsystem, so should be the default
+            assert_eq!(field_subsystem, &json!(DEFAULT_SUBSYSTEM), "{}", msg);
+        }
+    }
 }

src/agent/Makefile

@@ -101,7 +101,10 @@ endef
 ##TARGET default: build code
 default: $(TARGET) show-header
 
-$(TARGET): $(GENERATED_CODE) $(TARGET_PATH)
+$(TARGET): $(GENERATED_CODE) logging-crate-tests $(TARGET_PATH)
+
+logging-crate-tests:
+	make -C $(CWD)/../../pkg/logging
 
 $(TARGET_PATH): $(SOURCES) | show-summary
 	@RUSTFLAGS="$(EXTRA_RUSTFLAGS) --deny warnings" cargo build --target $(TRIPLE) --$(BUILD_TYPE) $(EXTRA_RUSTFEATURES)
@@ -205,9 +208,10 @@ codecov-html: check_tarpaulin
 
 .PHONY: \
 	help \
+	logging-crate-tests \
+	optimize \
 	show-header \
 	show-summary \
-	optimize \
 	vendor
 
 ##TARGET generate-protocols: generate/update grpc agent protocols

src/trace-forwarder/Makefile

@@ -7,9 +7,12 @@ include ../../utils.mk
 
 default: build
 
-build:
+build: logging-crate-tests
 	@RUSTFLAGS="$(EXTRA_RUSTFLAGS) --deny warnings" cargo build --target $(TRIPLE) --$(BUILD_TYPE)
 
+logging-crate-tests:
+	make -C $(CWD)/../../pkg/logging
+
 clean:
 	cargo clean
 
@@ -25,8 +28,9 @@ check:
 
 .PHONY: \
 	build \
-	test \
 	check \
-	install \
 	clean \
+	install \
+	logging-crate-tests \
+	test \
 	vendor

tools/agent-ctl/Makefile

@@ -7,9 +7,12 @@ include ../../utils.mk
 
 default: build
 
-build:
+build: logging-crate-tests
 	@RUSTFLAGS="$(EXTRA_RUSTFLAGS) --deny warnings" cargo build --target $(TRIPLE) --$(BUILD_TYPE)
 
+logging-crate-tests:
+	make -C $(CWD)/../../pkg/logging
+
 clean:
 	cargo clean
 
@@ -25,8 +28,9 @@ check:
 
 .PHONY: \
 	build \
-	test \
 	check \
-	install \
 	clean \
+	install \
+	logging-crate-tests \
+	test \
 	vendor

utils.mk

@@ -143,3 +143,5 @@ ifeq ($(ARCH), aarch64)
 endif
 
 TRIPLE = $(ARCH)-unknown-linux-$(LIBC)
+
+CWD := $(shell dirname $(realpath $(firstword $(MAKEFILE_LIST))))