From 953b99f6b93e857c38276582e0056cfd81922aa5 Mon Sep 17 00:00:00 2001 From: John Gallagher Date: Wed, 8 Jan 2025 12:52:51 -0500 Subject: [PATCH] [reconfigurator-cli] Customize log outputs * Dump them to stdout instead of stderr * Omit timestamps (which should fix the test failure on #7307, where our expectorate tests don't know how to redact slog timestamps) --- Cargo.lock | 3 +- dev-tools/reconfigurator-cli/Cargo.toml | 3 +- .../reconfigurator-cli/src/log_capture.rs | 131 ++++++++++++++++++ dev-tools/reconfigurator-cli/src/main.rs | 24 ++-- 4 files changed, 151 insertions(+), 10 deletions(-) create mode 100644 dev-tools/reconfigurator-cli/src/log_capture.rs diff --git a/Cargo.lock b/Cargo.lock index ea34752d1a..7c4f36da46 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -9442,7 +9442,7 @@ dependencies = [ "camino-tempfile", "chrono", "clap", - "dropshot 0.13.0", + "colored", "expectorate", "humantime", "indent_write", @@ -9469,6 +9469,7 @@ dependencies = [ "serde_json", "slog", "slog-error-chain", + "slog-term", "subprocess", "swrite", "tabled", diff --git a/dev-tools/reconfigurator-cli/Cargo.toml b/dev-tools/reconfigurator-cli/Cargo.toml index 0e3bf009a1..0f8afd7b76 100644 --- a/dev-tools/reconfigurator-cli/Cargo.toml +++ b/dev-tools/reconfigurator-cli/Cargo.toml @@ -16,7 +16,7 @@ assert_matches.workspace = true camino.workspace = true chrono.workspace = true clap.workspace = true -dropshot.workspace = true +colored.workspace = true humantime.workspace = true indent_write.workspace = true internal-dns-types.workspace = true @@ -32,6 +32,7 @@ pq-sys = "*" reedline.workspace = true serde_json.workspace = true slog-error-chain.workspace = true +slog-term.workspace = true slog.workspace = true swrite.workspace = true tabled.workspace = true diff --git a/dev-tools/reconfigurator-cli/src/log_capture.rs b/dev-tools/reconfigurator-cli/src/log_capture.rs new file mode 100644 index 0000000000..6216fa5d78 --- /dev/null +++ b/dev-tools/reconfigurator-cli/src/log_capture.rs @@ -0,0 +1,131 @@ +// This Source Code Form is subject to the terms of the Mozilla Public +// License, v. 2.0. If a copy of the MPL was not distributed with this +// file, You can obtain one at https://mozilla.org/MPL/2.0/. + +//! in-memory slog drain + +use colored::Color; +use colored::Colorize; +use slog::Drain; +use slog::Level; +use slog::LevelFilter; +use slog::Logger; +use slog::KV as _; +use slog_term::Decorator; +use slog_term::PlainSyncDecorator; +use slog_term::Serializer; +use std::io; +use std::mem; +use std::sync::Arc; +use std::sync::Mutex; + +/// `LogCapture` creates a `slog::Logger` where log lines are buffered in memory +/// and can be fetched when desired via [`LogCapture::take_log_lines()`]. +pub struct LogCapture { + lines: Arc>>, +} + +impl LogCapture { + /// Create a new [`Logger`] that emits to the returned `LogCapture`. + pub fn new(colorize: bool) -> (Self, Logger) { + let lines = Arc::default(); + let slf = LogCapture { lines }; + + let line_buf = LineBuf::default(); + let drain = LogCaptureDrain { + colorize, + lines: Arc::clone(&slf.lines), + line_buf: line_buf.clone(), + decorator: PlainSyncDecorator::new(line_buf), + }; + + let drain = slog::Fuse(LevelFilter::new(drain, Level::Info)); + let logger = Logger::root(drain, slog::o!()); + + (slf, logger) + } + + /// Take all buffered log lines out of the `LogCapture`. + /// + /// Additional logs emitted after this is called will continue to be + /// buffered and can be fetched by subsequent calls to `take_log_lines()`. + pub fn take_log_lines(&self) -> Vec { + mem::take(&mut *self.lines.lock().unwrap()) + } +} + +struct LogCaptureDrain { + colorize: bool, + lines: Arc>>, + line_buf: LineBuf, + decorator: PlainSyncDecorator, +} + +impl Drain for LogCaptureDrain { + type Ok = (); + type Err = io::Error; + + fn log( + &self, + record: &slog::Record, + values: &slog::OwnedKVList, + ) -> Result { + self.decorator.with_record(record, values, |d| { + // This is heavily derived from `slog_term::print_msg_header()`, but + // we omit some options we don't care about and intentionally omit + // any kind of timestamp (so expectorate-based reconfigurator-cli + // tests don't have to deal with redacting log timestamps). + d.start_level()?; + let level = record.level(); + if self.colorize { + let color = match level { + Level::Critical => Color::Magenta, + Level::Error => Color::Red, + Level::Warning => Color::Yellow, + Level::Info => Color::Green, + Level::Debug => Color::Cyan, + Level::Trace => Color::Blue, + }; + write!(d, "{}", level.as_short_str().color(color))?; + } else { + write!(d, "{}", level.as_short_str())?; + } + + d.start_whitespace()?; + write!(d, " ")?; + + d.start_msg()?; + write!(d, "{}", record.msg())?; + + let mut serializer = Serializer::new(d, true, true); + record.kv().serialize(record, &mut serializer)?; + values.serialize(record, &mut serializer)?; + serializer.finish()?; + d.flush() + })?; + let line = self.line_buf.take_as_string()?; + self.lines.lock().unwrap().push(line); + Ok(()) + } +} + +#[derive(Clone, Default)] +struct LineBuf(Arc>>); + +impl LineBuf { + fn take_as_string(&self) -> io::Result { + let contents = mem::take(&mut *self.0.lock().unwrap()); + String::from_utf8(contents) + .map_err(|err| io::Error::new(io::ErrorKind::Other, err)) + } +} + +impl io::Write for LineBuf { + fn write(&mut self, buf: &[u8]) -> io::Result { + self.0.lock().unwrap().write(buf) + } + + fn flush(&mut self) -> io::Result<()> { + self.0.lock().unwrap().flush() + } +} diff --git a/dev-tools/reconfigurator-cli/src/main.rs b/dev-tools/reconfigurator-cli/src/main.rs index 7da8a05043..7842535c7f 100644 --- a/dev-tools/reconfigurator-cli/src/main.rs +++ b/dev-tools/reconfigurator-cli/src/main.rs @@ -12,6 +12,7 @@ use clap::ValueEnum; use clap::{Args, Parser, Subcommand}; use indent_write::fmt::IndentWriter; use internal_dns_types::diff::DnsDiff; +use log_capture::LogCapture; use nexus_inventory::CollectionBuilder; use nexus_reconfigurator_planning::blueprint_builder::BlueprintBuilder; use nexus_reconfigurator_planning::example::ExampleSystemBuilder; @@ -42,10 +43,13 @@ use std::borrow::Cow; use std::collections::BTreeMap; use std::fmt::Write; use std::io::BufRead; +use std::io::IsTerminal; use swrite::{swriteln, SWrite}; use tabled::Tabled; use uuid::Uuid; +mod log_capture; + /// REPL state #[derive(Debug)] struct ReconfiguratorSim { @@ -157,11 +161,7 @@ struct CmdReconfiguratorSim { fn main() -> anyhow::Result<()> { let cmd = CmdReconfiguratorSim::parse(); - let log = dropshot::ConfigLogging::StderrTerminal { - level: dropshot::ConfigLoggingLevel::Info, - } - .to_logger("reconfigurator-sim") - .context("creating logger")?; + let (log_capture, log) = LogCapture::new(std::io::stdout().is_terminal()); let seed_provided = cmd.seed.is_some(); let mut sim = ReconfiguratorSim::new(log, cmd.seed); @@ -179,7 +179,7 @@ fn main() -> anyhow::Result<()> { let buffer = maybe_buffer .with_context(|| format!("read {:?}", &input_file))?; println!("> {}", buffer); - match process_entry(&mut sim, buffer) { + match process_entry(&mut sim, buffer, &log_capture) { LoopResult::Continue => (), LoopResult::Bail(error) => return Err(error), } @@ -194,7 +194,7 @@ fn main() -> anyhow::Result<()> { loop { match ed.read_line(&prompt) { Ok(Signal::Success(buffer)) => { - match process_entry(&mut sim, buffer) { + match process_entry(&mut sim, buffer, &log_capture) { LoopResult::Continue => (), LoopResult::Bail(error) => return Err(error), } @@ -225,7 +225,11 @@ enum LoopResult { } /// Processes one "line" of user input. -fn process_entry(sim: &mut ReconfiguratorSim, entry: String) -> LoopResult { +fn process_entry( + sim: &mut ReconfiguratorSim, + entry: String, + logs: &LogCapture, +) -> LoopResult { // If no input was provided, take another lap (print the prompt and accept // another line). This gets handled specially because otherwise clap would // treat this as a usage error and print a help message, which isn't what we @@ -289,6 +293,10 @@ fn process_entry(sim: &mut ReconfiguratorSim, entry: String) -> LoopResult { Commands::Wipe(args) => cmd_wipe(sim, args), }; + for line in logs.take_log_lines() { + println!("{line}"); + } + match cmd_result { Err(error) => println!("error: {:#}", error), Ok(Some(s)) => println!("{}", s),