609e33c feat: log adapter stderr output — radicle-ci-broker

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 wast 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() {