From 402d58eea0e854ae84a67e01b458ce49c67bc20d Mon Sep 17 00:00:00 2001
From: Lars Wirzenius <liw@liw.fi>
Date: Wed, 14 Aug 2024 17:45:21 +0300
Subject: [PATCH] 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        | 20 ++++++++++++
 Cargo.toml        |  2 ++
 ci-broker.md      | 78 +++++++++++++++++++++++++++++++++++++++++++++++
 ci-broker.subplot |  2 ++
 src/bin/cib.rs    |  7 +++++
 src/lib.rs        |  1 +
 src/logger.rs     | 34 +++++++++++++++++++++
 7 files changed, 144 insertions(+)
 create mode 100644 src/logger.rs

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