diff --git a/Cargo.lock b/Cargo.lock index 46ea436c..0b7eedc6 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1734,6 +1734,8 @@ dependencies = [ "serde", "serde_json", "serde_yml", + "slog", + "slog-json", "sqlite", "sqlite3-sys", "subplot-build", @@ -2182,6 +2184,24 @@ version = "1.0.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "56199f7ddabf13fe5074ce809e7d3f42b42ae711800501b5b16ea82ad029c39d" +[[package]] +name = "slog" +version = "2.7.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8347046d4ebd943127157b94d63abb990fcf729dc4e9978927fdf4ac3c998d06" + +[[package]] +name = "slog-json" +version = "2.6.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3e1e53f61af1e3c8b852eef0a9dee29008f55d6dd63794f3f12cef786cf0f219" +dependencies = [ + "serde", + "serde_json", + "slog", + "time", +] + [[package]] name = "slug" version = "0.1.5" diff --git a/Cargo.toml b/Cargo.toml index 4d9d4b76..bcc1ec92 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -22,6 +22,8 @@ regex = "1.10.5" serde = { version = "1.0.204", features = ["derive"] } serde_json = "1.0.121" serde_yml = "0.0.11" +slog = "2.7.0" +slog-json = "2.6.1" sqlite = "0.32.0" sqlite3-sys = "0.15.0" subplotlib = "0.10.0" diff --git a/ci-broker.md b/ci-broker.md index b030ea04..06f9b64f 100644 --- a/ci-broker.md +++ b/ci-broker.md @@ -991,3 +991,81 @@ when I run cibtool --db x.db run show x then stdout contains ""state": "finished"" then stdout contains ""result": "failure"" ~~~ + +# Acceptance criteria for logging + +The CI broker writes log messages to its standard error output +(stderr), which the node operator can capture to a suitable persistent +location. The logs are structured: each line is a JSON object. The +structured logs are meant to be easier to process by programs, for +example to extract information for monitoring, and alerting the node +operator about problems. + +An example log message might look like below (here formatted on +multiple lines for human consumption): + +~~~json +{ + "msg": "CI broker starts", + "level": "INFO", + "ts": "2024-08-14T13:38:36.733953135Z", +} +~~~ + +Because logs are crucial for managing a system, we record acceptance +criteria for the minimum logging that the CI broker needs to do. + +## Logs start and successful end + +_What:_ `cib` logs a message when it starts and ends. + +_Why:_ The program starting to run can be important information, for +example, to know when it's not running. It's also important to know if +the CI broker terminates successfully. + +_Who:_ `cib-dev`. + +We verify this by starting `cib` in a mode where it processes any +events already in the event queue, and then terminates. We don't add +any events, so `cib` just terminates at once. All of this will work, +when properly set up. + +~~~scenario +given file radenv.sh +given file setup-node.sh +when I run bash radenv.sh bash setup-node.sh + +given file adapter.sh from dummy.sh +when I run chmod +x adapter.sh + +given an installed cib + +given file broker.yaml +when I run bash radenv.sh cib --config broker.yaml queued + +then stderr contains "CI broker starts" +then stderr contains "CI broker ends successfully" +~~~ + +## Logs termination due to error + +_What:_ `cib` logs a message when it ends due to an unrecoverable +error. + +_Why:_ It's quite important to know this. Note that a recoverable +error does not terminate the CI broker. + +_Who:_ `cib-dev`. + +We check this by running the CI broker without a local node. This +is an error it can't recover from. + +~~~scenario +given an installed cib + +given file broker.yaml +when I try to run cib --config broker.yaml queued + +then stderr contains "CI broker starts" +then stderr contains "CI broker ends in unrecoverable error" +~~~ diff --git a/ci-broker.subplot b/ci-broker.subplot index 07971ece..25a30c19 100644 --- a/ci-broker.subplot +++ b/ci-broker.subplot @@ -12,3 +12,5 @@ bindings: impls: rust: - src/subplot.rs +classes: + - json diff --git a/src/bin/cib.rs b/src/bin/cib.rs index bfd8af67..c21dd538 100644 --- a/src/bin/cib.rs +++ b/src/bin/cib.rs @@ -19,6 +19,7 @@ use radicle_ci_broker::{ broker::{Broker, BrokerError}, config::{Config, ConfigError}, db::{Db, DbError}, + logger::Logger, notif::NotificationChannel, pages::{PageBuilder, PageError}, queueadd::{AdderError, QueueAdderBuilder}, @@ -26,6 +27,9 @@ use radicle_ci_broker::{ }; fn main() { + let logger = Logger::default(); + logger.start_cib(); + if let Err(e) = fallible_main() { error!("ERROR: {}", e); let mut e = e.source(); @@ -33,8 +37,11 @@ fn main() { error!("caused by: {}", source); e = source.source(); } + logger.end_cib_in_error(); exit(1); } + + logger.end_cib_successfully(); } fn fallible_main() -> Result<(), CibError> { diff --git a/src/lib.rs b/src/lib.rs index d07efc87..65ac0d61 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -10,6 +10,7 @@ pub mod broker; pub mod config; pub mod db; pub mod event; +pub mod logger; pub mod msg; pub mod notif; pub mod pages; diff --git a/src/logger.rs b/src/logger.rs new file mode 100644 index 00000000..04a89b98 --- /dev/null +++ b/src/logger.rs @@ -0,0 +1,34 @@ +//! A logger abstraction for the CI broker. + +use std::sync::Mutex; + +use slog::{info, o, Drain}; + +pub struct Logger { + root: slog::Logger, +} + +impl Default for Logger { + fn default() -> Self { + Self { + root: slog::Logger::root( + Mutex::new(slog_json::Json::default(std::io::stderr())).map(slog::Fuse), + o!(), + ), + } + } +} + +impl Logger { + pub fn start_cib(&self) { + info!(&self.root, "CI broker starts"); + } + + pub fn end_cib_successfully(&self) { + info!(&self.root, "CI broker ends successfully"); + } + + pub fn end_cib_in_error(&self) { + info!(&self.root, "CI broker ends in unrecoverable error"); + } +}