diff --git a/Makefile b/Makefile index aa8ee4816d..8afdee2f7c 100644 --- a/Makefile +++ b/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 diff --git a/pkg/logging/Makefile b/pkg/logging/Makefile new file mode 100644 index 0000000000..74c917ab88 --- /dev/null +++ b/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 diff --git a/pkg/logging/src/lib.rs b/pkg/logging/src/lib.rs index af6a1738f3..5d92acabff 100644 --- a/pkg/logging/src/lib.rs +++ b/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( 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, + } + + 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); + } + } } diff --git a/src/agent/Makefile b/src/agent/Makefile index 24a98e34b8..8078bb9df3 100644 --- a/src/agent/Makefile +++ b/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 diff --git a/src/trace-forwarder/Makefile b/src/trace-forwarder/Makefile index 6cc28568ed..b0e1e41f4f 100644 --- a/src/trace-forwarder/Makefile +++ b/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 diff --git a/tools/agent-ctl/Makefile b/tools/agent-ctl/Makefile index 930b522017..ff115a305e 100644 --- a/tools/agent-ctl/Makefile +++ b/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 diff --git a/utils.mk b/utils.mk index 7ace929745..0b4af421b5 100644 --- a/utils.mk +++ b/utils.mk @@ -143,3 +143,5 @@ ifeq ($(ARCH), aarch64) endif TRIPLE = $(ARCH)-unknown-linux-$(LIBC) + +CWD := $(shell dirname $(realpath $(firstword $(MAKEFILE_LIST))))