kata-ctl: Switch to slog logging; add --log-level, --json-logging args

Fixes: #5401, #6654

- Switch kata-ctl from eprintln!()/println!() to structured logging via
  the logging library which uses slog.
- Adds a new create_term_logger() library call which enables printing
  log messages to the terminal via a less verbose / more human readable
  terminal format with colors.
- Adds --log-level argument to select the minimum log level of printed messages.
- Adds --json-logging argument to switch to logging in JSON format.

Co-authored-by: Byron Marohn <byron.marohn@intel.com>
Co-authored-by: Luke Phillips <lucas.phillips@intel.com>
Signed-off-by: Jayant Singh <jayant.singh@intel.com>
Signed-off-by: Byron Marohn <byron.marohn@intel.com>
Signed-off-by: Luke Phillips <lucas.phillips@intel.com>
Signed-off-by: Kelby Madal-Hellmuth <kelby.madal-hellmuth@intel.com>
Signed-off-by: Liz Lawrens <liz.lawrens@intel.com>
This commit is contained in:
Jayant Singh 2023-04-28 23:54:49 +00:00 committed by Byron Marohn
parent 465f5a5ced
commit 77519fd120
14 changed files with 321 additions and 39 deletions

59
src/agent/Cargo.lock generated
View File

@ -422,6 +422,16 @@ dependencies = [
"dirs-sys",
]
[[package]]
name = "dirs-next"
version = "2.0.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "b98cf8ebf19c3d1b223e151f99a4f9f0690dca41414773390fc824184ac833e1"
dependencies = [
"cfg-if 1.0.0",
"dirs-sys-next",
]
[[package]]
name = "dirs-sys"
version = "0.3.7"
@ -433,6 +443,17 @@ dependencies = [
"winapi",
]
[[package]]
name = "dirs-sys-next"
version = "0.1.2"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "4ebda144c4fe02d1f7ea1a7d9641b6fc6b580adcfa024ae48797ecdeb6825b4d"
dependencies = [
"libc",
"redox_users",
"winapi",
]
[[package]]
name = "either"
version = "1.6.1"
@ -949,6 +970,7 @@ dependencies = [
"slog-async",
"slog-json",
"slog-scope",
"slog-term",
]
[[package]]
@ -1762,6 +1784,12 @@ dependencies = [
"zbus",
]
[[package]]
name = "rustversion"
version = "1.0.12"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "4f3208ce4d8448b3f3e7d168a73f5e0c43a61e32930de3bceeccedb388b6bf06"
[[package]]
name = "ryu"
version = "1.0.10"
@ -1951,6 +1979,19 @@ dependencies = [
"slog-scope",
]
[[package]]
name = "slog-term"
version = "2.9.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "87d29185c55b7b258b4f120eab00f48557d4d9bc814f41713f449d35b0f8977c"
dependencies = [
"atty",
"slog",
"term",
"thread_local",
"time 0.3.11",
]
[[package]]
name = "smallvec"
version = "1.8.0"
@ -2031,6 +2072,17 @@ dependencies = [
"winapi",
]
[[package]]
name = "term"
version = "0.7.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "c59df8ac95d96ff9bede18eb7300b0fda5e5d8d90960e76f8e14ae765eedbf1f"
dependencies = [
"dirs-next",
"rustversion",
"winapi",
]
[[package]]
name = "termcolor"
version = "1.1.3"
@ -2102,8 +2154,15 @@ dependencies = [
"itoa",
"libc",
"num_threads",
"time-macros",
]
[[package]]
name = "time-macros"
version = "0.2.4"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "42657b1a6f4d817cda8e7a0ace261fe0cc946cf3a80314390b22cc61ae080792"
[[package]]
name = "tokio"
version = "1.28.1"

View File

@ -15,6 +15,7 @@ serde_json = "1.0.73"
# (by stopping the compiler from removing log calls).
slog = { version = "2.5.2", features = ["dynamic-keys", "max_level_trace", "release_max_level_debug"] }
slog-json = "2.4.0"
slog-term = "2.9.0"
slog-async = "2.7.0"
slog-scope = "4.4.0"

View File

@ -39,6 +39,28 @@ const LOG_LEVELS: &[(&str, slog::Level)] = &[
const DEFAULT_SUBSYSTEM: &str = "root";
// Creates a logger which prints output as human readable text to the terminal
pub fn create_term_logger(level: slog::Level) -> (slog::Logger, slog_async::AsyncGuard) {
let term_drain = slog_term::term_compact().fuse();
// Ensure only a unique set of key/value fields is logged
let unique_drain = UniqueDrain::new(term_drain).fuse();
// Allow runtime filtering of records by log level
let filter_drain = RuntimeLevelFilter::new(unique_drain, level).fuse();
// Ensure the logger is thread-safe
let (async_drain, guard) = slog_async::Async::new(filter_drain)
.thread_name("slog-async-logger".into())
.build_with_guard();
// Add some "standard" fields
let logger = slog::Logger::root(async_drain.fuse(), o!("subsystem" => DEFAULT_SUBSYSTEM));
(logger, guard)
}
// Creates a logger which prints output as JSON
// XXX: 'writer' param used to make testing possible.
pub fn create_logger<W>(
name: &str,

View File

@ -96,6 +96,17 @@ dependencies = [
"syn 1.0.107",
]
[[package]]
name = "atty"
version = "0.2.14"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "d9b39be18770d11421cdb1b9947a45dd3f37e93092cbf377614828a319d5fee8"
dependencies = [
"hermit-abi 0.1.19",
"libc",
"winapi",
]
[[package]]
name = "autocfg"
version = "1.1.0"
@ -280,6 +291,27 @@ dependencies = [
"syn 1.0.107",
]
[[package]]
name = "dirs-next"
version = "2.0.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "b98cf8ebf19c3d1b223e151f99a4f9f0690dca41414773390fc824184ac833e1"
dependencies = [
"cfg-if",
"dirs-sys-next",
]
[[package]]
name = "dirs-sys-next"
version = "0.1.2"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "4ebda144c4fe02d1f7ea1a7d9641b6fc6b580adcfa024ae48797ecdeb6825b4d"
dependencies = [
"libc",
"redox_users",
"winapi",
]
[[package]]
name = "either"
version = "1.8.1"
@ -460,6 +492,17 @@ dependencies = [
"slab",
]
[[package]]
name = "getrandom"
version = "0.2.9"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "c85e1d9ab2eadba7e5040d4e09cbd6d072b76a557ad64e797c2cb9d4da21d7e4"
dependencies = [
"cfg-if",
"libc",
"wasi",
]
[[package]]
name = "glob"
version = "0.3.1"
@ -506,6 +549,15 @@ version = "0.4.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "95505c38b4572b2d910cecb0281560f54b440a19336cbbcb27bf6ce6adc6f5a8"
[[package]]
name = "hermit-abi"
version = "0.1.19"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "62b467343b94ba476dcb2500d242dadbb39557df889310ac77c5d99100aaac33"
dependencies = [
"libc",
]
[[package]]
name = "hermit-abi"
version = "0.2.6"
@ -728,6 +780,7 @@ dependencies = [
"hyper",
"kata-types",
"libc",
"logging",
"micro_http",
"nix 0.25.1",
"privdrop",
@ -821,6 +874,7 @@ dependencies = [
"slog-async",
"slog-json",
"slog-scope",
"slog-term",
]
[[package]]
@ -961,6 +1015,15 @@ dependencies = [
"libc",
]
[[package]]
name = "num_threads"
version = "0.1.6"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "2819ce041d2ee131036f4fc9d6ae7ae125a3a40e97ba64d04fe799ad9dabbb44"
dependencies = [
"libc",
]
[[package]]
name = "oci"
version = "0.1.0"
@ -1284,6 +1347,17 @@ dependencies = [
"bitflags",
]
[[package]]
name = "redox_users"
version = "0.4.3"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "b033d837a7cf162d7993aded9304e30a83213c648b6e389db233191f891e5c2b"
dependencies = [
"getrandom",
"redox_syscall",
"thiserror",
]
[[package]]
name = "regex"
version = "1.7.1"
@ -1600,6 +1674,19 @@ dependencies = [
"slog",
]
[[package]]
name = "slog-term"
version = "2.9.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "87d29185c55b7b258b4f120eab00f48557d4d9bc814f41713f449d35b0f8977c"
dependencies = [
"atty",
"slog",
"term",
"thread_local",
"time",
]
[[package]]
name = "smallvec"
version = "1.10.0"
@ -1705,6 +1792,17 @@ dependencies = [
"winapi",
]
[[package]]
name = "term"
version = "0.7.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "c59df8ac95d96ff9bede18eb7300b0fda5e5d8d90960e76f8e14ae765eedbf1f"
dependencies = [
"dirs-next",
"rustversion",
"winapi",
]
[[package]]
name = "test-utils"
version = "0.1.0"
@ -1749,6 +1847,8 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "a561bf4617eebd33bca6434b988f39ed798e527f51a1e797d0ee4f61c0a38376"
dependencies = [
"itoa",
"libc",
"num_threads",
"serde",
"time-core",
"time-macros",

View File

@ -36,6 +36,10 @@ serial_test = "0.5.1"
vmm-sys-util = "0.11.0"
epoll = "4.0.1"
libc = "0.2.138"
# Note: this crate sets the slog 'max_*' features which allows the log level
# to be modified at runtime.
logging = { path = "../../libs/logging" }
slog = "2.7.0"
slog-scope = "4.4.0"
hyper = "0.14.20"

View File

@ -11,6 +11,7 @@ mod arch_specific {
use crate::types::*;
use crate::utils;
use anyhow::Result;
use slog::{info, o, warn};
use std::path::Path;
const KVM_DEV: &str = "/dev/kvm";
@ -19,6 +20,12 @@ mod arch_specific {
#[allow(dead_code)]
pub const ARCH_CPU_MODEL_FIELD: &str = "CPU architecture";
macro_rules! sl {
() => {
slog_scope::logger().new(o!("subsystem" => "aarch64"))
};
}
// List of check functions
static CHECK_LIST: &[CheckItem] = &[CheckItem {
name: CheckType::Cpu,
@ -28,11 +35,14 @@ mod arch_specific {
}];
pub fn check(_args: &str) -> Result<()> {
println!("INFO: check: aarch64");
info!(sl!(), "check: aarch64");
if Path::new(KVM_DEV).exists() {
println!("Kata Containers can run on this host\n");
info!(sl!(), "Kata Containers can run on this host\n");
} else {
eprintln!("WARNING: Kata Containers can't run on this host as lack of virtulization support\n");
warn!(
sl!(),
"Kata Containers can't run on this host as lack of virtulization support\n"
);
}
Ok(())

View File

@ -13,6 +13,7 @@ mod arch_specific {
use crate::utils;
use anyhow::{anyhow, Result};
use nix::unistd::Uid;
use slog::{info, o, warn};
use std::collections::HashMap;
use std::io::BufRead;
use std::io::BufReader;
@ -21,6 +22,12 @@ mod arch_specific {
const CPUINFO_FEATURES_TAG: &str = "features";
const CPU_FEATURES_REQ: &[&str] = &["sie"];
macro_rules! sl {
() => {
slog_scope::logger().new(o!("subsystem" => "s390x"))
};
}
#[allow(dead_code)]
pub const ARCH_CPU_VENDOR_FIELD: &str = check::GENERIC_CPU_VENDOR_FIELD;
#[allow(dead_code)]
@ -28,7 +35,7 @@ mod arch_specific {
// check cpu
fn check_cpu() -> Result<()> {
println!("INFO: check CPU: s390x");
info!(sl!(), "check CPU: s390x");
let cpu_info = check::get_single_cpu_info(check::PROC_CPUINFO, CPUINFO_DELIMITER)?;
@ -42,14 +49,14 @@ mod arch_specific {
let missing_cpu_features = check::check_cpu_flags(&cpu_features, CPU_FEATURES_REQ)?;
if !missing_cpu_features.is_empty() {
eprintln!("WARNING: Missing CPU flags {:?}", missing_cpu_features);
warn!(sl!(), "Missing CPU flags {:?}", missing_cpu_features);
}
Ok(())
}
pub fn check(_args: &str) -> Result<()> {
println!("INFO: check: s390x");
info!(sl!(), "check: s390x");
let _cpu_result = check_cpu();

View File

@ -15,6 +15,7 @@ mod arch_specific {
use crate::utils;
use anyhow::{anyhow, Context, Result};
use nix::unistd::Uid;
use slog::{info, o, warn};
use std::fs;
use std::path::Path;
@ -27,6 +28,12 @@ mod arch_specific {
pub const ARCH_CPU_VENDOR_FIELD: &str = check::GENERIC_CPU_VENDOR_FIELD;
pub const ARCH_CPU_MODEL_FIELD: &str = check::GENERIC_CPU_MODEL_FIELD;
macro_rules! sl {
() => {
slog_scope::logger().new(o!("subsystem" => "x86_64"))
};
}
// List of check functions
static CHECK_LIST: &[CheckItem] = &[
CheckItem {
@ -72,7 +79,7 @@ mod arch_specific {
// check cpu
fn check_cpu(_args: &str) -> Result<()> {
println!("INFO: check CPU: x86_64");
info!(sl!(), "check CPU: x86_64");
let cpu_info = check::get_single_cpu_info(check::PROC_CPUINFO, CPUINFO_DELIMITER)?;
@ -89,14 +96,11 @@ mod arch_specific {
// TODO: Add more information to output (see kata-check in go tool); adjust formatting
let missing_cpu_attributes = check::check_cpu_attribs(&cpu_info, CPU_ATTRIBS_INTEL)?;
if !missing_cpu_attributes.is_empty() {
eprintln!(
"WARNING: Missing CPU attributes {:?}",
missing_cpu_attributes
);
warn!(sl!(), "Missing CPU attributes {:?}", missing_cpu_attributes);
}
let missing_cpu_flags = check::check_cpu_flags(&cpu_flags, CPU_FLAGS_INTEL)?;
if !missing_cpu_flags.is_empty() {
eprintln!("WARNING: Missing CPU flags {:?}", missing_cpu_flags);
warn!(sl!(), "Missing CPU flags {:?}", missing_cpu_flags);
}
Ok(())
@ -122,7 +126,7 @@ mod arch_specific {
// check if kvm is usable
fn check_kvm_is_usable(_args: &str) -> Result<()> {
println!("INFO: check if kvm is usable: x86_64");
info!(sl!(), "check if kvm is usable: x86_64");
let result = check::check_kvm_is_usable_generic();
@ -275,7 +279,7 @@ mod arch_specific {
}
fn check_kernel_modules(_args: &str) -> Result<()> {
println!("INFO: check kernel modules for: x86_64");
info!(sl!(), "check kernel modules for: x86_64");
for module in MODULE_LIST {
let module_loaded =
@ -291,12 +295,12 @@ mod arch_specific {
);
match parameter_check {
Ok(_v) => println!("{} Ok", module.name),
Ok(_v) => info!(sl!(), "{} Ok", module.name),
Err(e) => return Err(e),
}
}
Err(err) => {
eprintln!("WARNING {:}", err.replace('\n', ""))
warn!(sl!(), "{:}", err.replace('\n', ""))
}
}
}

View File

@ -12,6 +12,25 @@ use thiserror::Error;
pub struct KataCtlCli {
#[clap(subcommand)]
pub command: Commands,
#[clap(short, long, value_enum, value_parser = parse_log_level)]
/// Sets the minimum log level required for log messages to be displayed. Default is 'info'.
/// Valid values are: trace, debug, info, warning, error, critical
pub log_level: Option<slog::Level>,
#[clap(short, long, action)]
/// If enabled, log messages will be JSON formatted for easier machine parsing
pub json_logging: bool,
}
fn parse_log_level(arg: &str) -> Result<slog::Level, String> {
match arg {
"trace" => Ok(slog::Level::Trace),
"debug" => Ok(slog::Level::Debug),
"info" => Ok(slog::Level::Info),
"warning" => Ok(slog::Level::Warning),
"error" => Ok(slog::Level::Error),
"critical" => Ok(slog::Level::Critical),
_ => Err("Must be one of [trace, debug, info, warning, error, critical]".to_string()),
}
}
#[derive(Debug, Subcommand)]

View File

@ -12,6 +12,7 @@ use nix::unistd::close;
use nix::{ioctl_write_int_bad, request_code_none};
use reqwest::header::{CONTENT_TYPE, USER_AGENT};
use serde::{Deserialize, Serialize};
use slog::{info, o};
use std::fmt;
use thiserror::Error;
@ -51,6 +52,12 @@ pub const GENERIC_CPU_MODEL_FIELD: &str = "model name";
#[allow(dead_code)]
pub const PROC_CPUINFO: &str = "/proc/cpuinfo";
macro_rules! sl {
() => {
slog_scope::logger().new(o!("subsystem" => "check"))
};
}
fn read_file_contents(file_path: &str) -> Result<String> {
let contents = std::fs::read_to_string(file_path)?;
Ok(contents)
@ -276,14 +283,20 @@ pub fn check_all_releases() -> Result<()> {
for release in releases {
if !release.prerelease {
println!(
info!(
sl!(),
"Official : Release {:15}; created {} ; {}",
release.tag_name, release.created_at, release.tarball_url
release.tag_name,
release.created_at,
release.tarball_url
);
} else {
println!(
info!(
sl!(),
"PreRelease: Release {:15}; created {} ; {}",
release.tag_name, release.created_at, release.tarball_url
release.tag_name,
release.created_at,
release.tarball_url
);
}
}
@ -294,12 +307,15 @@ pub fn check_official_releases() -> Result<()> {
let releases: Vec<Release> =
get_kata_all_releases_by_url(KATA_GITHUB_RELEASE_URL).map_err(handle_reqwest_error)?;
println!("Official Releases...");
info!(sl!(), "Official Releases...");
for release in releases {
if !release.prerelease {
println!(
info!(
sl!(),
"Release {:15}; created {} ; {}",
release.tag_name, release.created_at, release.tarball_url
release.tag_name,
release.created_at,
release.tarball_url
);
}
}
@ -392,6 +408,7 @@ pub fn check_kernel_module_loaded(module: &str, parameter: &str) -> Result<Strin
mod tests {
use super::*;
use semver::Version;
use slog::warn;
use std::fs;
use std::io::Write;
use tempfile::tempdir;
@ -573,8 +590,9 @@ mod tests {
// sometime in GitHub action accessing to github.com API may fail
// we can skip this test to prevent the whole test fail.
if releases.is_err() {
println!(
"WARNING!!!\nget kata version failed({:?}), this maybe a temporary error, just skip the test.",
warn!(
sl!(),
"get kata version failed({:?}), this maybe a temporary error, just skip the test.",
releases.unwrap_err()
);
return;

View File

@ -11,7 +11,8 @@ mod types;
mod utils;
use anyhow::Result;
use clap::Parser;
use clap::{crate_name, Parser};
use std::io;
use std::process::exit;
use args::{Commands, KataCtlCli};
@ -22,11 +23,28 @@ use ops::check_ops::{
use ops::env_ops::handle_env;
use ops::exec_ops::handle_exec;
use ops::volume_ops::handle_direct_volume;
use slog::{error, o};
macro_rules! sl {
() => {
slog_scope::logger().new(o!("subsystem" => "kata-ctl_main"))
};
}
fn real_main() -> Result<()> {
let args = KataCtlCli::parse();
match args.command {
let log_level = args.log_level.unwrap_or(slog::Level::Info);
let (logger, _guard) = if args.json_logging {
logging::create_logger(crate_name!(), crate_name!(), log_level, io::stdout())
} else {
logging::create_term_logger(log_level)
};
let _guard = slog_scope::set_global_logger(logger);
let res = match args.command {
Commands::Check(args) => handle_check(args),
Commands::DirectVolume(args) => handle_direct_volume(args),
Commands::Exec(args) => handle_exec(args),
@ -35,12 +53,19 @@ fn real_main() -> Result<()> {
Commands::Iptables(args) => handle_iptables(args),
Commands::Metrics(args) => handle_metrics(args),
Commands::Version => handle_version(),
};
// Log errors here, then let the logger go out of scope in main() to ensure
// the asynchronous drain flushes all messages before exit()
if let Err(e) = &res {
error!(sl!(), "{:#?}", e);
}
res
}
fn main() {
if let Err(e) = real_main() {
eprintln!("ERROR: {:#?}", e);
if let Err(_e) = real_main() {
exit(1);
}
}

View File

@ -15,8 +15,16 @@ use crate::types::*;
use anyhow::{anyhow, Result};
use slog::{info, o, warn};
const NAME: &str = "kata-ctl";
macro_rules! sl {
() => {
slog_scope::logger().new(o!("subsystem" => "check_ops"))
};
}
// This function retrieves the cmd function passes as argument
fn get_builtin_check_func(name: CheckType) -> Result<BuiltinCmdFp> {
if let Some(check_list) = get_checks() {
@ -55,14 +63,12 @@ fn print_check_list() -> Result<()> {
let cmds = get_client_cmd_details();
if cmds.is_empty() {
println!("Checks not found!\n");
warn!(sl!(), "Checks not found!\n");
return Ok(());
}
cmds.iter().for_each(|n| println!(" - {}", n));
println!();
cmds.iter().for_each(|n| info!(sl!(), " - {}", n));
Ok(())
}
@ -125,6 +131,6 @@ pub fn handle_metrics(_args: MetricsCommand) -> Result<()> {
pub fn handle_version() -> Result<()> {
let version = version::get().unwrap();
println!("{} version {:?} (type: rust)", NAME, version);
info!(sl!(), "{} version {:?} (type: rust)", NAME, version);
Ok(())
}

View File

@ -19,7 +19,7 @@ use std::{
use anyhow::{anyhow, Context};
use nix::sys::socket::{connect, socket, AddressFamily, SockFlag, SockType, VsockAddr};
use reqwest::StatusCode;
use slog::debug;
use slog::{debug, error, o};
use vmm_sys_util::terminal::Terminal;
use crate::args::ExecArguments;
@ -40,7 +40,7 @@ type Result<T> = std::result::Result<T, Error>;
#[macro_export]
macro_rules! sl {
() => {
slog_scope::logger()
slog_scope::logger().new(o!("subsystem" => "exec_ops"))
};
}
@ -142,7 +142,7 @@ impl EpollContext {
return Ok(());
}
Err(e) => {
println!("error with errno {:?} while reading stdin", e);
error!(sl!(), "errno {:?} while reading stdin", e);
return Ok(());
}
Ok(count) => {
@ -159,7 +159,7 @@ impl EpollContext {
return Ok(());
}
Err(e) => {
println!("error with errno {:?} while reading server", e);
error!(sl!(), "errno {:?} while reading server", e);
return Ok(());
}
Ok(count) => {

View File

@ -13,6 +13,7 @@ use kata_types::mount::{
};
use nix;
use reqwest::StatusCode;
use slog::{info, o};
use std::{fs, time::Duration};
use url;
@ -25,6 +26,12 @@ use shim_interface::shim_mgmt::{
const TIMEOUT: Duration = Duration::from_millis(2000);
const CONTENT_TYPE_JSON: &str = "application/json";
macro_rules! sl {
() => {
slog_scope::logger().new(o!("subsystem" => "volume_ops"))
};
}
pub fn handle_direct_volume(vol_cmd: DirectVolumeCommand) -> Result<()> {
if !nix::unistd::Uid::effective().is_root() {
return Err(anyhow!(
@ -41,7 +48,7 @@ pub fn handle_direct_volume(vol_cmd: DirectVolumeCommand) -> Result<()> {
}
};
if let Some(cmd_result) = cmd_result {
println!("{:?}", cmd_result);
info!(sl!(), "{:?}", cmd_result);
}
Ok(())