Radish alpha
r
rad:zwTxygwuz5LDGBq255RA2CbNGrz8
Radicle CI broker
Radicle
Git
feat: log adapter stderr output
Merged liw opened 1 year ago

The CI broker now logs the standard error output of the adapter, and the adapter exit status, to the broker’s own log. The log messages look like this:

{“msg”:“adapter exit code”,“level”:“DEBG”,“ts”:“2024-08-27T17:38:26.762222386Z”,“exit_code”:1} {“msg”:“adapter stderr”,“level”:“DEBG”,“ts”:“2024-08-27T17:38:26.762289242Z”,“stderr”:“woe be me\n”}

4 files changed +61 -12 dd043e01 58ceb336
modified ci-broker.md
@@ -73,11 +73,17 @@ filters:

This adapter does nothing, just reports a run ID and a successful run.

+
Note that this adapter always outputs a message to its standard error
+
output, even though it doesn't fail. This is useful for verifying that
+
the CI broker logs adapter error output, and doesn't harm other uses
+
of the adapter.
+

~~~{#dummy.sh .file .sh}
#!/bin/bash
set -euo pipefail
echo '{"response":"triggered","run_id":{"id":"xyzzy"}}'
echo '{"response":"finished","result":"success"}'
+
echo "This is an adapter error: Mordor" 1>&2
~~~

## A `refsFetched` node event
@@ -474,6 +480,35 @@ then file reports/index.html contains "testy"
This doesn't check that there is a per-repository HTML file, because
we have not convenient way to know the repository ID.

+
## Logs adapter stderr output
+

+
_What:_ The CI broker should log, to its own log output, the adapter's
+
stderr output.
+

+
_Why:_ This allows the adapter to output its own log to its standard
+
error output. This makes it easier to debug adapter problems.
+

+
_Who:_ `adapter-devs`, `node-ops`
+

+
~~~scenario
+
given file radenv.sh
+
given file setup-node.sh
+
when I run bash radenv.sh bash setup-node.sh
+

+
given an installed cibtool
+
when I run bash radenv.sh cibtool --db ci-broker.db trigger --repo testy --ref main --commit HEAD
+
when I run bash radenv.sh cibtool --db ci-broker.db event list --json
+

+
given an installed cib
+
given file broker.yaml
+
given a directory reports
+
given file adapter.sh from dummy.sh
+
when I run chmod +x adapter.sh
+

+
when I run bash radenv.sh cib --config broker.yaml queued
+
then stderr contains "Mordor"
+
~~~
+

# Acceptance criteria for test tooling

The event synthesizer is a helper to feed the CI broker node events in
modified src/adapter.rs
@@ -130,19 +130,21 @@ impl Adapter {
        }

        let wait = child.wait().map_err(AdapterError::Wait)?;
+

+
        let mut stderr = child.stderr.take().ok_or(AdapterError::StderrHandle)?;
+
        let mut buf = vec![];
+
        stderr
+
            .read_to_end(&mut buf)
+
            .map_err(AdapterError::ReadStderr)?;
+
        let stderr = String::from_utf8_lossy(&buf);
+
        logger::adapter_result(wait.code(), &stderr);
+

        if let Some(exit) = wait.code() {
            if exit != 0 {
-
                let mut stderr = child.stderr.take().ok_or(AdapterError::StderrHandle)?;
-
                let mut buf = vec![];
-
                stderr
-
                    .read_to_end(&mut buf)
-
                    .map_err(AdapterError::ReadStderr)?;
-
                let stderr = String::from_utf8_lossy(&buf);
-
                logger::adapter_result(exit, &stderr.to_string());
                return Err(AdapterError::Failed(exit));
            }
        } else {
-
            logger::adapter_did_not_exit_voluntarioly();
+
            logger::adapter_did_not_exit_voluntarily();
            return Err(AdapterError::Failed(NOT_EXITED));
        }

modified src/logger.rs
@@ -86,6 +86,10 @@ pub fn queueproc_channel_disconnect() {
    );
}

+
pub fn queueproc_picked_event(id: &QueueId) {
+
    info!(slog_scope::logger(), "picked event from queue: {id}");
+
}
+

pub fn queueproc_remove_event(id: &QueueId) {
    info!(slog_scope::logger(), "remove event from queue: {id}");
}
@@ -197,12 +201,18 @@ pub fn adapter_too_many_responses() {
    error!(slog_scope::logger(), "too many response messages");
}

-
pub fn adapter_result(exit: i32, stderr: &String) {
-
    debug!(slog_scope::logger(), "adapter exit code: {exit}");
-
    debug!(slog_scope::logger(), "adapter stderr: {stderr}");
+
pub fn adapter_result(exit: Option<i32>, stderr: &str) {
+
    if let Some(exit) = exit {
+
        debug!(slog_scope::logger(), "adapter exit code"; "exit_code" => exit);
+
    } else {
+
        debug!(slog_scope::logger(), "adapter was terminated by signal");
+
    }
+
    for line in stderr.lines() {
+
        debug!(slog_scope::logger(), "adapter stderr"; "stderr" => line);
+
    }
}

-
pub fn adapter_did_not_exit_voluntarioly() {
+
pub fn adapter_did_not_exit_voluntarily() {
    warn!(slog_scope::logger(), "adapter did not exit voluntarily");
}

modified src/queueproc.rs
@@ -79,6 +79,7 @@ impl QueueProcessor {
        let mut done = false;
        while !done {
            while let Some(qe) = self.pick_event()? {
+
                logger::queueproc_picked_event(qe.id());
                done = self.process_event(qe.event())?;
                self.drop_event(qe.id())?;
                self.run_tx.send(()).map_err(|_| QueueError::NotifyRun)?;
@@ -99,6 +100,7 @@ impl QueueProcessor {

    fn pick_event(&self) -> Result<Option<QueuedEvent>, QueueError> {
        let ids = self.db.queued_events().map_err(QueueError::db)?;
+
        logger::debug2(format!("queue in db has {} events", ids.len()));

        let mut queue = vec![];
        for id in ids.iter() {