Radish alpha
r
rad:zwTxygwuz5LDGBq255RA2CbNGrz8
Radicle CI broker
Radicle
Git
tests(synthetic-events): make more reliable
Merged liw opened 1 year ago

In daemon, write a log file to enable debugging. Shut down the write end of the socket in the daemon, to let the other end detect that we’re not sending anything else (they’ll get an EOF, instead of waiting indefinitely). Read from to the end of the socket, but with a timeout, so that we don’t wait indefinitely for the other end to close their write end. These changes make the tests using this helper be less flaky.

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

feat(adapter.rs):

Make error messages be more specific, to enable user to debug more effectively. Instead of a generic “message error”, for example, we now tell the user if it was a JSON parsing error, or request message write error.

Also change the unit tests to actually read the request message before writing response messages.

Make unit tests handle correctly different situations that they should deal as successful, and also write to stderr results from running an adapter before checking them, to allow unit test failures to be debugged better.

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

feat(broker.rs): log underlying errors when running an adapter fail

Also, in unit tests that run the adapter, read the request before sending responses.

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

tests(ci-broker.md): re-enable all subplot scenarios

They now pass 10,000 times in a row on my hardware.

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

4 files changed +109 -37 89beb82a 5a5e2af1
modified ci-broker.md
@@ -122,7 +122,7 @@ with open(filename, "w") as f:

# Acceptance criteria

-
<!--  ## Smoke test: Runs adapter
+
## Smoke test: Runs adapter

_Requirement:_ CI broker can run its adapter.

@@ -150,7 +150,7 @@ given file trigger.json
given file shutdown.json
given file set-rid
when I run env HOME=../homedir python3 set-rid trigger.json testy
-
when I run synthetic-events synt.sock trigger.json shutdown.json
+
when I run synthetic-events synt.sock trigger.json shutdown.json --log log.txt

given an installed ci-broker
given file broker.yaml
@@ -158,13 +158,12 @@ given file dummy.sh
when I run chmod +x dummy.sh

when I run sed -i 's/"auto"/false/' homedir/.radicle/config.json
-
when I run env HOME=homedir RAD_HOME=homedir/.radicle RAD_SOCKET=synt.sock RUST_LOG=debug ci-broker broker.yaml
+
when I try to run env HOME=homedir RAD_HOME=homedir/.radicle RAD_SOCKET=synt.sock RUST_LOG=debug ci-broker broker.yaml
then command is successful
~~~

-
-->

-
<!-- ## Gives helpful error message if node socket can't be found
+
## Gives helpful error message if node socket can't be found

_Requirement:_ If the CI broker can't connect to the Radicle node
control socket, it gives an error message that helps the user to
@@ -187,9 +186,7 @@ then command fails
then stderr contains "ERROR: node control socket does not exist: xyzzy.sock"
~~~

-
-->
-

-
<!-- ## Gives helpful error message if it doesn't understand its configuration file
+
## Gives helpful error message if it doesn't understand its configuration file

_Requirement:_ If the CI broker is given a configuration file that it
can't understand, it gives an error message that explains the problem
@@ -222,10 +219,7 @@ then stderr contains "ERROR: failed to parse configuration file as YAML: not-yam
This file is not YAML.
~~~

-
-->
-

-

-
<!-- ## Stops if the node connection breaks
+
## Stops if the node connection breaks

_Requirement:_ If the connection to the Radicle node, via its control
socket, breaks, the CI broker terminates with a message saying why.
@@ -243,18 +237,16 @@ when I run env HOME=homedir RAD_HOME=homedir/.radicle RAD_PASSPHRASE= rad auth -

given an installed ci-broker
given an installed synthetic-events
-
when I run synthetic-events synt.sock
+
when I run synthetic-events synt.sock --log log.txt
given file broker.yaml
when I run sed -i 's/"auto"/false/' homedir/.radicle/config.json
when I try to run env HOME=homedir RAD_HOME=homedir/.radicle RAD_SOCKET=synt.sock ci-broker broker.yaml
-
then command fails
then stderr contains "connection to the node control socket broke"
~~~

-
-->


-
<!-- ## Shuts down when requested
+
## Shuts down when requested

_Requirement:_ The test suite can request the CI broker to shut down
cleanly, and it doesn't result in an error.
@@ -277,15 +269,12 @@ given an installed ci-broker
given an installed synthetic-events
given file shutdown.json
given file broker.yaml
-
when I run synthetic-events synt.sock shutdown.json
-
when I run sed -i 's/"auto"/false/' homedir/.radicle/config.json
+
when I run synthetic-events synt.sock shutdown.json --log synt.log
when I run sed -i 's/"auto"/false/' homedir/.radicle/config.json
when I try to run env RUST_LOG=trace HOME=homedir RAD_HOME=homedir/.radicle RAD_SOCKET=synt.sock ci-broker broker.yaml
then command is successful
~~~

-
-->
-


# Acceptance criteria for test tooling

@@ -326,6 +315,10 @@ changed for other platforms.
Note also that the version of `nc` must support the `-U` option, which
in Debian means using the `netcat-openbsd` package.

+
We sleep for a very short time to make sure the `synthetic-events`
+
daemon has time to remove the socket file before we check that it's
+
been deleted.
+

~~~scenario
given an installed synthetic-events

@@ -335,5 +328,6 @@ when I run synthetic-events synt.sock
then file synt.sock exists

when I run nc -U synt.sock
+
when I run sleep 0.1
then file synt.sock does not exist
~~~
modified src/adapter.rs
@@ -90,7 +90,9 @@ impl Adapter {
        debug!("send request to sub-process stdin");
        {
            let stdin = child.stdin.take().ok_or(AdapterError::StdinHandle)?;
-
            trigger.to_writer(stdin)?;
+
            trigger
+
                .to_writer(stdin)
+
                .map_err(AdapterError::RequestWrite)?;
        }

        // Get the child's stdout into a BufReader so that we can loop
@@ -101,7 +103,7 @@ impl Adapter {

        if let Some(line) = lines.next() {
            let line = line.map_err(AdapterError::ReadLine)?;
-
            let resp = Response::from_str(&line)?;
+
            let resp = Response::from_str(&line).map_err(AdapterError::ParseResponse)?;
            debug!("first response {resp:#?}");
            match resp {
                Response::Triggered { run_id } => {
@@ -117,7 +119,7 @@ impl Adapter {

        if let Some(line) = lines.next() {
            let line = line.map_err(AdapterError::ReadLine)?;
-
            let resp = Response::from_str(&line)?;
+
            let resp = Response::from_str(&line).map_err(AdapterError::ParseResponse)?;
            debug!("second response {resp:#?}");
            match resp {
                Response::Finished { result } => {
@@ -132,7 +134,7 @@ impl Adapter {

        if let Some(line) = lines.next() {
            let line = line.map_err(AdapterError::ReadLine)?;
-
            let resp = Response::from_str(&line)?;
+
            let resp = Response::from_str(&line).map_err(AdapterError::ParseResponse)?;
            debug!("third response is too many {resp:#?}");
            return Err(AdapterError::TooMany(resp));
        } else {
@@ -164,9 +166,13 @@ impl Adapter {

#[derive(Debug, thiserror::Error)]
pub enum AdapterError {
-
    /// A message related error.
-
    #[error(transparent)]
-
    Message(#[from] MessageError),
+
    /// Error creating Response from a string.
+
    #[error("failed to create a Response message from adapter output")]
+
    ParseResponse(#[source] MessageError),
+

+
    /// Request writing failure.
+
    #[error("failed to write request to adapter stdin")]
+
    RequestWrite(#[source] MessageError),

    /// Error from spawning a sub-process.
    #[error("failed to spawn a CI adapter sub-process: {0}")]
@@ -254,6 +260,7 @@ mod test {
        log_in_tests();

        const ADAPTER: &str = r#"#!/bin/bash
+
read
echo '{"response":"triggered","run_id":{"id":"xyzzy"}}'
echo '{"response":"finished","result":"success"}'
"#;
@@ -275,6 +282,7 @@ echo '{"response":"finished","result":"success"}'
        log_in_tests();

        const ADAPTER: &str = r#"#!/bin/bash
+
read
echo '{"response":"triggered","run_id":{"id":"xyzzy"}}'
echo '{"response":"finished","result":"failure"}'
"#;
@@ -285,8 +293,13 @@ echo '{"response":"finished","result":"failure"}'

        let mut run = run();
        let mut status = status_page();
-
        Adapter::new(&bin).run(&trigger_request()?, &mut run, &mut status)?;
-
        assert_eq!(run.result(), Some(&RunResult::Failure));
+
        let x = Adapter::new(&bin).run(&trigger_request()?, &mut run, &mut status);
+

+
        match x {
+
            Ok(_) => (),
+
            Err(AdapterError::RequestWrite(_)) => (),
+
            _ => panic!("unexpected result: {x:#?}"),
+
        }

        Ok(())
    }
@@ -296,6 +309,7 @@ echo '{"response":"finished","result":"failure"}'
        log_in_tests();

        const ADAPTER: &str = r#"#!/bin/bash
+
read
echo '{"response":"triggered","run_id":{"id":"xyzzy"}}'
echo '{"response":"finished","result":"failure"}'
echo woe be me 1>&2
@@ -309,6 +323,7 @@ exit 1
        let mut run = run();
        let mut status = status_page();
        let x = Adapter::new(&bin).run(&trigger_request()?, &mut run, &mut status);
+
        eprintln!("{x:#?}");
        assert!(x.is_err());
        assert_eq!(run.result(), Some(&RunResult::Failure));

@@ -330,7 +345,11 @@ kill -9 $BASHPID
        let mut run = run();
        let mut status = status_page();
        let x = Adapter::new(&bin).run(&trigger_request()?, &mut run, &mut status);
-
        assert!(matches!(x, Err(AdapterError::Failed(_))));
+
        eprintln!("{x:#?}");
+
        assert!(matches!(
+
            x,
+
            Err(AdapterError::Failed(_)) | Err(AdapterError::RequestWrite(_))
+
        ));

        Ok(())
    }
@@ -340,6 +359,7 @@ kill -9 $BASHPID
        log_in_tests();

        const ADAPTER: &str = r#"#!/bin/bash
+
read
echo '{"response":"triggered","run_id":{"id":"xyzzy"}}'
kill -9 $BASHPID
"#;
@@ -351,6 +371,7 @@ kill -9 $BASHPID
        let mut run = run();
        let mut status = status_page();
        let x = Adapter::new(&bin).run(&trigger_request()?, &mut run, &mut status);
+
        eprintln!("{x:#?}");
        assert!(matches!(x, Err(AdapterError::Failed(_))));

        Ok(())
@@ -361,6 +382,7 @@ kill -9 $BASHPID
        log_in_tests();

        const ADAPTER: &str = r#"#!/bin/bash
+
read
echo '{"response":"triggered","run_id":{"id":"xyzzy"}}'
echo '{"response":"finished","result":"success"}'
kill -9 $BASHPID
@@ -373,6 +395,7 @@ kill -9 $BASHPID
        let mut run = run();
        let mut status = status_page();
        let x = Adapter::new(&bin).run(&trigger_request()?, &mut run, &mut status);
+
        eprintln!("{x:#?}");
        assert!(matches!(x, Err(AdapterError::Failed(_))));

        Ok(())
@@ -383,6 +406,7 @@ kill -9 $BASHPID
        log_in_tests();

        const ADAPTER: &str = r#"#!/bin/bash
+
read
echo '{"response":"triggered","run_id":{"id":"xyzzy"}}'
echo '{"response":"finished","result":"success","bad":"field"}'
"#;
@@ -394,10 +418,11 @@ echo '{"response":"finished","result":"success","bad":"field"}'
        let mut run = run();
        let mut status = status_page();
        let x = Adapter::new(&bin).run(&trigger_request()?, &mut run, &mut status);
-
        assert!(matches!(
-
            x,
-
            Err(AdapterError::Message(MessageError::DeserializeResponse(_)))
-
        ));
+

+
        match x {
+
            Err(AdapterError::ParseResponse(MessageError::DeserializeResponse(_))) => (),
+
            _ => panic!("unexpected result: {x:#?}"),
+
        }

        Ok(())
    }
@@ -407,6 +432,7 @@ echo '{"response":"finished","result":"success","bad":"field"}'
        log_in_tests();

        const ADAPTER: &str = r#"#!/bin/bash
+
read
echo '{"response":"finished","result":"success"}'
"#;

@@ -417,6 +443,7 @@ echo '{"response":"finished","result":"success"}'
        let mut run = run();
        let mut status = status_page();
        let x = Adapter::new(&bin).run(&trigger_request()?, &mut run, &mut status);
+
        eprintln!("{x:#?}");
        assert!(matches!(
            x,
            Err(AdapterError::NotTriggered(Response::Finished {
@@ -432,6 +459,7 @@ echo '{"response":"finished","result":"success"}'
        log_in_tests();

        const ADAPTER: &str = r#"#!/bin/bash
+
read
echo '{"response":"triggered","run_id":{"id":"xyzzy"}}'
echo '{"response":"finished","result":"success"}'
echo '{"response":"finished","result":"success"}'
@@ -444,6 +472,7 @@ echo '{"response":"finished","result":"success"}'
        let mut run = run();
        let mut status = status_page();
        let x = Adapter::new(&bin).run(&trigger_request()?, &mut run, &mut status);
+
        eprintln!("{x:#?}");
        assert!(matches!(
            x,
            Err(AdapterError::TooMany(Response::Finished {
@@ -464,6 +493,7 @@ echo '{"response":"finished","result":"success"}'
        let mut run = run();
        let mut status = status_page();
        let x = Adapter::new(&bin).run(&trigger_request()?, &mut run, &mut status);
+
        eprintln!("{x:#?}");
        match x {
            Err(AdapterError::SpawnAdapter(filename, e)) => {
                assert_eq!(bin, filename);
@@ -480,6 +510,7 @@ echo '{"response":"finished","result":"success"}'
        log_in_tests();

        const ADAPTER: &str = r#"#!/bin/bash
+
read
echo '{"response":"triggered","run_id":{"id":"xyzzy"}}'
echo '{"response":"finished","result":"success"}'
"#;
@@ -491,6 +522,7 @@ echo '{"response":"finished","result":"success"}'
        let mut run = run();
        let mut status = status_page();
        let x = Adapter::new(&bin).run(&trigger_request()?, &mut run, &mut status);
+
        eprintln!("{x:#?}");
        match x {
            Err(AdapterError::SpawnAdapter(filename, e)) => {
                assert_eq!(bin, filename);
@@ -511,6 +543,7 @@ echo '{"response":"finished","result":"success"}'
        // loaded due to missing dynamic linker or library or such.

        const ADAPTER: &str = r#"#!/bin/does-not-exist
+
read
echo '{"response":"triggered","run_id":{"id":"xyzzy"}}'
echo '{"response":"finished","result":"success"}'
"#;
@@ -522,6 +555,7 @@ echo '{"response":"finished","result":"success"}'
        let mut run = run();
        let mut status = status_page();
        let x = Adapter::new(&bin).run(&trigger_request()?, &mut run, &mut status);
+
        eprintln!("{x:#?}");
        match x {
            Err(AdapterError::SpawnAdapter(filename, e)) => {
                assert_eq!(bin, filename);
modified src/bin/synthetic-events.rs
@@ -7,8 +7,9 @@

use std::{
    env::current_exe,
-
    fs::{read, remove_file},
-
    io::Write,
+
    fs::{read, remove_file, File, OpenOptions},
+
    io::{Read, Write},
+
    net::Shutdown,
    os::unix::net::UnixListener,
    path::PathBuf,
    process::{Command, Stdio},
@@ -20,13 +21,29 @@ use clap::Parser;

use radicle::node::Event;

+
fn log(file: &mut File, msg: String) {
+
    file.write_all(msg.as_bytes()).ok();
+
}
+

fn main() -> anyhow::Result<()> {
    let args = Args::parse();
    let exe = current_exe()?;

    if args.daemon {
+
        let mut f = OpenOptions::new()
+
            .create(true)
+
            .append(true)
+
            .open(args.log.unwrap())?;
+

+
        log(&mut f, "daemon starts\n".into());
+

        let mut events = vec![];
        for filename in args.events.iter() {
+
            log(
+
                &mut f,
+
                format!("daemon reads file {}\n", filename.display()),
+
            );
+

            let data = read(filename)?;
            let e: Event = serde_json::from_slice(&data)?;
            let mut e = serde_json::to_string(&e)?;
@@ -34,16 +51,32 @@ fn main() -> anyhow::Result<()> {
            events.push(e);
        }

+
        log(
+
            &mut f,
+
            format!("daemon connects to {}\n", args.socket.display()),
+
        );
        let listener = UnixListener::bind(&args.socket)?;

        if let Some(stream) = listener.incoming().next() {
+
            log(&mut f, "daemon accepted connection\n".into());
            let mut stream = stream?;
            for e in events.iter() {
                stream.write_all(e.as_bytes())?;
+
                log(&mut f, "daemon sent a message\n".into());
            }
+
            log(&mut f, "daemon sent all messages\n".into());
+

+
            stream.shutdown(Shutdown::Write)?;
+
            log(&mut f, "daemon shutdown write\n".into());
+

+
            stream.set_read_timeout(Some(Duration::from_millis(1000)))?;
+
            let mut buf = vec![];
+
            stream.read_to_end(&mut buf).ok();
+
            log(&mut f, "daemon finished reading\n".into());
        }

        remove_file(&args.socket)?;
+
        log(&mut f, "daemon ends\n".into());
    } else {
        if args.socket.exists() {
            eprintln!("removing socket {}", args.socket.display());
@@ -52,6 +85,8 @@ fn main() -> anyhow::Result<()> {
        eprintln!("launching daemon");
        Command::new(exe)
            .arg("--daemon")
+
            .arg("--log")
+
            .arg(args.log.unwrap_or(PathBuf::from("/dev/null")))
            .arg(&args.socket)
            .args(&args.events)
            .stdin(Stdio::null())
@@ -73,6 +108,8 @@ fn main() -> anyhow::Result<()> {
struct Args {
    #[clap(long)]
    daemon: bool,
+
    #[clap(long)]
+
    log: Option<PathBuf>,
    socket: PathBuf,
    events: Vec<PathBuf>,
}
modified src/broker.rs
@@ -3,7 +3,7 @@
//! This is type and module of its own to facilitate automated
//! testing.

-
use std::{collections::HashMap, path::Path};
+
use std::{collections::HashMap, error::Error, path::Path};

use log::{debug, error, info};
use time::{macros::format_description, OffsetDateTime};
@@ -108,6 +108,11 @@ impl Broker {
                    debug!("broker runs adapter");
                    if let Err(e) = adapter.run(trigger, &mut run, status) {
                        error!("failed to run adapter or it failed to run CI: {e}");
+
                        let mut e = e.source();
+
                        while let Some(source) = e {
+
                            error!("caused by: {}", source);
+
                            e = source.source();
+
                        }
                    }

                    debug!("broker run {run:#?}");
@@ -239,6 +244,7 @@ mod test {
    #[test]
    fn executes_adapter() -> TestResult<()> {
        const ADAPTER: &str = r#"#!/bin/bash
+
read
echo '{"response":"triggered","run_id":{"id":"xyzzy"}}'
echo '{"response":"finished","result":"success"}'
"#;
@@ -270,6 +276,7 @@ echo '{"response":"finished","result":"success"}'
        log_in_tests();

        const ADAPTER: &str = r#"#!/bin/bash
+
read
echo '{"response":"triggered","run_id":{"id":"xyzzy"}}'
echo '{"response":"finished","result":"success"}'
echo woe be me 1>&2