From 7c4966dfcf01486f79bc256b2e80584019f81df4 Mon Sep 17 00:00:00 2001 From: Lucas Kent Date: Thu, 8 Dec 2022 14:16:57 +1100 Subject: [PATCH] DockerCompose: wait logic inspect yaml (#917) --- Cargo.lock | 23 ++- test-helpers/Cargo.toml | 2 + test-helpers/src/docker_compose.rs | 216 ++++++++++++++++++++--------- 3 files changed, 172 insertions(+), 69 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 9a28daba3..b3931437e 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2768,6 +2768,19 @@ dependencies = [ "yaml-rust", ] +[[package]] +name = "serde_yaml" +version = "0.9.14" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6d232d893b10de3eb7258ff01974d6ee20663d8e833263c99409d4b13a0209da" +dependencies = [ + "indexmap", + "itoa 1.0.4", + "ryu", + "serde", + "unsafe-libyaml", +] + [[package]] name = "serial_test" version = "0.9.0" @@ -2883,7 +2896,7 @@ dependencies = [ "scylla", "serde", "serde_json", - "serde_yaml", + "serde_yaml 0.8.26", "serial_test", "split-iter", "strum_macros 0.24.3", @@ -3073,6 +3086,8 @@ dependencies = [ "anyhow", "nix", "rcgen", + "regex", + "serde_yaml 0.9.14", "subprocess", "tracing", ] @@ -3450,6 +3465,12 @@ dependencies = [ "subtle", ] +[[package]] +name = "unsafe-libyaml" +version = "0.2.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "c1e5fa573d8ac5f1a856f8d7be41d390ee973daf97c806b2c1a465e4e1406e68" + [[package]] name = "untrusted" version = "0.7.1" diff --git a/test-helpers/Cargo.toml b/test-helpers/Cargo.toml index 62f534824..924dfae04 100644 --- a/test-helpers/Cargo.toml +++ b/test-helpers/Cargo.toml @@ -13,3 +13,5 @@ subprocess = "0.2.7" anyhow = "1.0.42" nix = "0.25.0" rcgen = "0.10.0" +serde_yaml = "0.9.0" +regex = "1.7.0" diff --git a/test-helpers/src/docker_compose.rs b/test-helpers/src/docker_compose.rs index 7f29b4226..225e62048 100644 --- a/test-helpers/src/docker_compose.rs +++ b/test-helpers/src/docker_compose.rs @@ -1,4 +1,8 @@ use anyhow::{anyhow, Result}; +use regex::Regex; +use serde_yaml::Value; +use std::collections::HashMap; +use std::fmt::Write; use std::io::ErrorKind; use std::process::Command; use std::time::{self, Duration}; @@ -44,9 +48,9 @@ impl DockerCompose { /// Creates a new DockerCompose object by submitting a file to the underlying docker-compose /// system. Executes `docker-compose -f [file_path] up -d` /// - /// Will spin until it detects all the containers have started up. - /// This logic is implemented internally per docker-compose file. - /// If a docker-compose file is used that hasnt had this logic implemented for it yet + /// Will spin until it detects all the containers have started up by inspecting the logs for a magic string. + /// This logic is implemented internally per docker image name. + /// If a service uses an image that hasnt had this logic implemented for it yet /// a panic will occur instructing the developer to implement this logic. /// /// # Arguments @@ -54,7 +58,6 @@ impl DockerCompose { /// /// # Panics /// * Will panic if docker-compose is not installed - /// pub fn new(file_path: &str) -> Self { if let Err(ErrorKind::NotFound) = Command::new("docker-compose") .output() @@ -118,65 +121,104 @@ impl DockerCompose { } fn wait_for_containers_to_startup(&self) { - match self.file_path.as_ref() { - "tests/transforms/docker-compose-moto.yaml" => { - self.wait_for_log("Press CTRL+C to quit", 1) - } - "example-configs/redis-passthrough/docker-compose.yaml" - | "example-configs/redis-tls/docker-compose.yaml" => { - self.wait_for_log("Ready to accept connections", 1) - } - "example-configs/redis-multi/docker-compose.yaml" => { - self.wait_for_log("Ready to accept connections", 3) - } - "tests/test-configs/redis-cluster-ports-rewrite/docker-compose.yaml" - | "tests/test-configs/redis-cluster-auth/docker-compose.yaml" - | "example-configs/redis-cluster-handling/docker-compose.yaml" - | "example-configs/redis-cluster-hiding/docker-compose.yaml" - | "example-configs/redis-cluster-tls/docker-compose.yaml" - | "example-configs/redis-cluster-tls/docker-compose-with-key.yaml" => { - self.wait_for_log("Cluster state changed", 6) - } - "example-configs/redis-cluster-dr/docker-compose.yaml" => { - self.wait_for_log("Cluster state changed", 12) - } - "example-configs/cassandra-passthrough/docker-compose.yaml" - | "example-configs/cassandra-tls/docker-compose.yaml" - | "example-configs/cassandra-redis-cache/docker-compose.yaml" - | "example-configs/cassandra-protect-local/docker-compose.yaml" - | "example-configs/cassandra-protect-aws/docker-compose.yaml" - | "example-configs/cassandra-request-throttling/docker-compose.yaml" - | "tests/test-configs/cassandra-passthrough-parse-request/docker-compose.yaml" - | "tests/test-configs/cassandra-passthrough-parse-response/docker-compose.yaml" => { - self.wait_for_log("Startup complete", 1) - } - "tests/test-configs/cassandra-peers-rewrite/docker-compose-4.0-cassandra.yaml" - | "tests/test-configs/cassandra-peers-rewrite/docker-compose-3.11-cassandra.yaml" => { - self.wait_for_log("Startup complete", 2) - } - "example-configs-docker/cassandra-peers-rewrite/docker-compose.yaml" - | "example-configs/cassandra-cluster-v4/docker-compose.yaml" - | "example-configs/cassandra-cluster-v3/docker-compose.yaml" - | "example-configs/cassandra-cluster-multi-rack/docker-compose.yaml" - | "example-configs/cassandra-cluster-tls/docker-compose.yaml" => { - self.wait_for_log("Startup complete", 3) - } - path => unimplemented!( - "Unknown compose file `{path}` Please implement waiting logic for it here.", - ), + let images = [ + Image { + name: "shotover/shotover-proxy", + log_regex_to_wait_for: r"accepting inbound connections", + }, + Image { + name: "motoserver/moto", + log_regex_to_wait_for: r"Press CTRL\+C to quit", + }, + Image { + name: "library/redis:5.0.9", + log_regex_to_wait_for: r"Ready to accept connections", + }, + Image { + name: "library/redis:6.2.5", + log_regex_to_wait_for: r"Ready to accept connections", + }, + Image { + name: "docker.io/bitnami/redis-cluster:6.0-debian-10", + log_regex_to_wait_for: r"Cluster state changed|Cluster correctly created", + }, + Image { + name: "bitnami/redis-cluster:6.0-debian-10", + //`Cluster state changed` is created by the node services + //`Cluster correctly created` is created by the init service + log_regex_to_wait_for: r"Cluster state changed|Cluster correctly created", + }, + Image { + name: "bitnami/cassandra:4.0.6", + log_regex_to_wait_for: r"Startup complete", + }, + Image { + name: "shotover-int-tests/cassandra:4.0.6", + log_regex_to_wait_for: r"Startup complete", + }, + Image { + name: "shotover-int-tests/cassandra-tls:4.0.6", + log_regex_to_wait_for: r"Startup complete", + }, + Image { + name: "shotover-int-tests/cassandra:3.11.13", + log_regex_to_wait_for: r"Startup complete", + }, + ]; + + let services: Vec = self + .get_service_to_image() + .into_iter() + .map( + |(service_name, image_name)| match images.iter().find(|image| image.name == image_name) { + Some(image) => Service { + name: service_name, + log_to_wait_for: Regex::new(image.log_regex_to_wait_for).unwrap(), + }, + None => panic!("DockerCompose does not yet know about the image {image_name}, please add it to the list above."), + }, + ) + .collect(); + + self.wait_for_logs(&services); + } + + fn get_service_to_image(&self) -> HashMap { + // If we got this far then docker-compose already succesfully parsed the docker-compose.yaml, + // so our error reporting only has to be good enough to debug issues in our implementation. + let compose_yaml: Value = + serde_yaml::from_str(&std::fs::read_to_string(&self.file_path).unwrap()).unwrap(); + let mut result = HashMap::new(); + match compose_yaml { + Value::Mapping(root) => match root.get("services").unwrap() { + Value::Mapping(services) => { + for (service_name, service) in services { + let service_name = match service_name { + Value::String(service_name) => service_name, + service_name => panic!("Unexpected service_name {service_name:?}"), + }; + match service { + Value::Mapping(service) => { + let image = match service.get("image").unwrap() { + Value::String(image) => image, + image => panic!("Unexpected image {image:?}"), + }; + result.insert(service_name.clone(), image.clone()); + } + service => panic!("Unexpected service {service:?}"), + } + } + } + services => panic!("Unexpected services {services:?}"), + }, + root => panic!("Unexpected root {root:?}"), } + result } - /// Waits for a string to appear in the docker-compose log output `count` times within `time` seconds. - /// - /// # Arguments - /// * `log_to_wait_for` - A regular expression defining the text to find in the docker-container log - /// output. - /// * `count` - The number of times the regular expression should be found. - /// - /// # Panics - /// * If `count` occurrences of `log_text` is not found in the log within 120 seconds. - fn wait_for_log(&self, log_to_wait_for: &str, count: usize) { + /// Wait until the requirements in every Service is met. + /// Will panic if a timeout occurs. + fn wait_for_logs(&self, services: &[Service]) { let timeout = Duration::from_secs(120); // TODO: remove this check once CI docker-compose is updated (probably ubuntu 22.04) @@ -187,24 +229,52 @@ impl DockerCompose { let instant = time::Instant::now(); loop { - // check if the service is completely ready - let full_log = run_command("docker-compose", &["-f", &self.file_path, "logs"]).unwrap(); - let current_count = full_log.matches(log_to_wait_for).count(); - if current_count >= count { + // check if every service is completely ready + if services.iter().all(|service| { + let log = run_command( + "docker-compose", + &["-f", &self.file_path, "logs", &service.name], + ) + .unwrap(); + service.log_to_wait_for.is_match(&log) + }) { return; } + let all_logs = run_command("docker-compose", &["-f", &self.file_path, "logs"]).unwrap(); + // check if the service has failed in some way // this allows us to report the failure to the developer a lot sooner than just relying on the timeout if can_use_status_flag { - self.assert_no_containers_in_service_with_status("exited", &full_log); - self.assert_no_containers_in_service_with_status("dead", &full_log); - self.assert_no_containers_in_service_with_status("removing", &full_log); + self.assert_no_containers_in_service_with_status("exited", &all_logs); + self.assert_no_containers_in_service_with_status("dead", &all_logs); + self.assert_no_containers_in_service_with_status("removing", &all_logs); } // if all else fails timeout the wait if instant.elapsed() > timeout { - panic!("wait_for_log {timeout:?} timer expired. Found {current_count}/{count} instances of '{log_to_wait_for}' in the log\n{full_log}"); + let mut results = "".to_owned(); + for service in services { + let log = run_command( + "docker-compose", + &["-f", &self.file_path, "logs", &service.name], + ) + .unwrap(); + let found = if service.log_to_wait_for.is_match(&log) { + "Found" + } else { + "Missing" + }; + + writeln!( + results, + "* Service {}, searched for '{}', was {}", + service.name, service.log_to_wait_for, found + ) + .unwrap(); + } + + panic!("wait_for_log {timeout:?} timer expired. Results:\n{results}\nLogs:\n{all_logs}"); } } } @@ -276,6 +346,16 @@ impl DockerCompose { } } +struct Image<'a> { + name: &'a str, + log_regex_to_wait_for: &'a str, +} + +struct Service { + name: String, + log_to_wait_for: Regex, +} + impl Drop for DockerCompose { fn drop(&mut self) { if std::thread::panicking() {