feat: start adding structured logging to cib

This is the smallest useful change to add structured logging. It adds
little useful logging, but builds a foundation for adding more useful
logging later, and for converging existing log messages to structured
one later.

Add some acceptance criteria for structured logging so that we do not
accidentally change the log messages we really, really care about.

Add dependencies on the slog and slog-json crates, which exist
precisely for structured logging.

Signed-off-by: Lars Wirzenius <liw@liw.fi>

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"

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"

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"
+~~~

ci-broker.subplot

@@ -12,3 +12,5 @@ bindings:
 impls:
   rust:
     - src/subplot.rs
+classes:
+  - json

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> {

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;

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");
+    }
+}