[ci] Fixes for cli_integration. Debugging for websocket tests (#2453)

.github/workflows/ci.yml

@@ -172,6 +172,16 @@ jobs:
           command: make
           args: ci-cli-integration
       
+      - name: Debug info
+        if: always()
+        run: |
+          set -x
+          free -m
+          df -h
+          ps auxf
+          cat /tmp/surrealdb.log || true
+          
+
   http-server:
     name: HTTP integration tests
     runs-on: ubuntu-latest
@@ -326,6 +336,15 @@ jobs:
           command: make
           args: ci-api-integration-ws
 
+      - name: Debug info
+        if: always()
+        run: |
+          set -x
+          free -m
+          df -h
+          ps auxf
+          cat /tmp/surrealdb.log || true
+
   http-engine:
     name: HTTP engine
     runs-on: ubuntu-latest
@@ -363,6 +382,15 @@ jobs:
           command: make
           args: ci-api-integration-http
 
+      - name: Debug info
+        if: always()
+        run: |
+          set -x
+          free -m
+          df -h
+          ps auxf
+          cat /tmp/surrealdb.log || true
+
   any-engine:
     name: Any engine
     runs-on: ubuntu-latest
@@ -400,6 +428,15 @@ jobs:
           command: make
           args: ci-api-integration-any
 
+      - name: Debug info
+        if: always()
+        run: |
+          set -x
+          free -m
+          df -h
+          ps auxf
+          cat /tmp/surrealdb.log || true
+
   mem-engine:
     name: Memory engine
     runs-on: ubuntu-latest
@@ -549,6 +586,15 @@ jobs:
           command: make
           args: ci-api-integration-tikv
 
+      - name: Debug info
+        if: always()
+        run: |
+          set -x
+          free -m
+          df -h
+          ps auxf
+          cat /tmp/surrealdb.log || true
+
   fdb-engine:
     name: FoundationDB engine
     runs-on: ubuntu-latest
@@ -581,3 +627,12 @@ jobs:
         with:
           command: make
           args: ci-api-integration-fdb
+
+      - name: Debug info
+        if: always()
+        run: |
+          set -x
+          free -m
+          df -h
+          ps auxf
+          cat /tmp/surrealdb.log || true

.github/workflows/nightly.yml

@@ -57,6 +57,15 @@ jobs:
           command: make
           args: ci-workspace-coverage
 
+      - name: Debug info
+        if: always()
+        run: |
+          set -x
+          free -m
+          df -h
+          ps auxf
+          cat /tmp/surrealdb.log || true
+
       - name: Upload coverage report
         uses: actions/upload-artifact@v3
         with:

.github/workflows/release.yml

@@ -57,6 +57,15 @@ jobs:
           command: make
           args: ci-workspace-coverage-complete
 
+      - name: Debug info
+        if: always()
+        run: |
+          set -x
+          free -m
+          df -h
+          ps auxf
+          cat /tmp/surrealdb.log || true
+
       - name: Upload coverage report
         uses: actions/upload-artifact@v3
         with:

Makefile.ci.toml

@@ -143,7 +143,7 @@ run_task = { name = ["start-tikv", "ci-api-integration-tikv-tests", "stop-tikv"]
 category = "CI - SERVICES"
 dependencies = ["build-surrealdb"]
 script = """
-   #!/bin/bash
+   #!/bin/bash -ex
 
    target/debug/surreal start ${_START_SURREALDB_PATH} &>/tmp/surrealdb.log &
 
@@ -163,19 +163,21 @@ script = """
 
 [tasks.stop-surrealdb]
 category = "CI - SERVICES"
-script = "kill $(cat /tmp/surreal.pid) || true"
+script = """
+        kill $(cat /tmp/surreal.pid) || true
+        sleep 5
+        kill -9 $(cat /tmp/surreal.pid) || true
+"""
 
 [tasks.start-tikv]
 category = "CI - SERVICES"
 script = """
-   #!/bin/bash
+   #!/bin/bash -ex
 
    ${HOME}/.tiup/bin/tiup install pd tikv playground
 
    ${HOME}/.tiup/bin/tiup playground --mode tikv-slim --kv 3 --without-monitor &>/tmp/tiup.log &
 
-   ${HOME}/.tiup/bin/tiup clean --all
-
    echo $! > /tmp/tiup.pid
 
    set +e

flake.lock

@@ -32,11 +32,11 @@
         "rust-analyzer-src": "rust-analyzer-src"
       },
       "locked": {
-        "lastModified": 1690179764,
+        "lastModified": 1692253212,
-        "narHash": "sha256-Sgszrn/3KnemTBYHnJBwdCcY/u6Gc8FMGHAB+VpPH6I=",
+        "narHash": "sha256-vLwYUD/TjjVx9dkuQMIL0la+VpuqwFohzGFn+3AGq+k=",
         "owner": "nix-community",
         "repo": "fenix",
-        "rev": "dce10f32abcc7740e5090e021b2c83a6b2ddb614",
+        "rev": "5d85dc369f8ee47f1cef83999d0de4bb18def5d2",
         "type": "github"
       },
       "original": {
@@ -113,11 +113,11 @@
     },
     "nixpkgs": {
       "locked": {
-        "lastModified": 1690176526,
+        "lastModified": 1692232013,
-        "narHash": "sha256-SHdHTRu1RMLhIkTlFMSSyUJYsPNWw50Ky9W6znxGN9A=",
+        "narHash": "sha256-a5hct9pN+RSxLclPBsWCg9zOCG9c0Uf1cq3XlntQpDQ=",
         "owner": "NixOS",
         "repo": "nixpkgs",
-        "rev": "a58eb89c7fcb703554aa53b4d25b50bd62e16786",
+        "rev": "edf586f399ddb6aef26edc2df3aa843e97a2ddc1",
         "type": "github"
       },
       "original": {
@@ -139,11 +139,11 @@
     "rust-analyzer-src": {
       "flake": false,
       "locked": {
-        "lastModified": 1690057540,
+        "lastModified": 1692173342,
-        "narHash": "sha256-MKGhZsFTpJH3Sq+9dGFGqOje3A6PD6fKGO92tM23zuY=",
+        "narHash": "sha256-0JgH5lhg0AaUYeEqVAfWnVJPwOFu0dbvDVGIb0F9kUA=",
         "owner": "rust-lang",
         "repo": "rust-analyzer",
-        "rev": "99718d0c8bc5aadd993acdcabc1778fc7b5cc572",
+        "rev": "e69b96bd40a47d7919894e3220f9d43698888a84",
         "type": "github"
       },
       "original": {

tests/cli_integration.rs

@@ -175,13 +175,6 @@ async fn all_commands() {
 
 #[test(tokio::test)]
 async fn start_tls() {
-	// Capute the server's stdout/stderr
-	temp_env::async_with_vars(
-		[
-			("SURREAL_TEST_SERVER_STDOUT", Some("piped")),
-			("SURREAL_TEST_SERVER_STDERR", Some("piped")),
-		],
-		async {
 	let (_, server) = common::start_server(StartServerArguments {
 		auth: false,
 		tls: true,
@@ -196,9 +189,6 @@ async fn start_tls() {
 
 	// Test the crt/key args but the keys are self signed so don't actually connect.
 	assert!(output.contains("Started web server"), "couldn't start web server: {output}");
-		},
-	)
-	.await;
 }
 
 #[test(tokio::test)]

tests/common/mod.rs

@@ -24,6 +24,8 @@ pub const PASS: &str = "root";
 /// Child is a (maybe running) CLI process. It can be killed by dropping it
 pub struct Child {
 	inner: Option<std::process::Child>,
+	stdout_path: String,
+	stderr_path: String,
 }
 
 impl Child {
@@ -43,12 +45,19 @@ impl Child {
 	/// Read the child's stdout concatenated with its stderr. Returns Ok if the child
 	/// returns successfully, Err otherwise.
 	pub fn output(mut self) -> Result<String, String> {
-		let output = self.inner.take().unwrap().wait_with_output().unwrap();
+		let status = self.inner.take().unwrap().wait().unwrap();
 
-		let mut buf = String::from_utf8(output.stdout).unwrap();
+		let mut buf =
-		buf.push_str(&String::from_utf8(output.stderr).unwrap());
+			std::fs::read_to_string(&self.stdout_path).expect("Failed to read the stdout file");
+		buf.push_str(
+			&std::fs::read_to_string(&self.stderr_path).expect("Failed to read the stderr file"),
+		);
 
-		if output.status.success() {
+		// Cleanup files after reading them
+		std::fs::remove_file(self.stdout_path.as_str()).unwrap();
+		std::fs::remove_file(self.stderr_path.as_str()).unwrap();
+
+		if status.success() {
 			Ok(buf)
 		} else {
 			Err(buf)
@@ -64,12 +73,7 @@ impl Drop for Child {
 	}
 }
 
-pub fn run_internal<P: AsRef<Path>>(
+pub fn run_internal<P: AsRef<Path>>(args: &str, current_dir: Option<P>) -> Child {
-	args: &str,
-	current_dir: Option<P>,
-	stdout: Stdio,
-	stderr: Stdio,
-) -> Child {
 	let mut path = std::env::current_exe().unwrap();
 	assert!(path.pop());
 	if path.ends_with("deps") {
@@ -83,24 +87,35 @@ pub fn run_internal<P: AsRef<Path>>(
 	if let Some(dir) = current_dir {
 		cmd.current_dir(&dir);
 	}
+
+	// Use local files instead of pipes to avoid deadlocks. See https://github.com/rust-lang/rust/issues/45572
+	let stdout_path = tmp_file(format!("server-stdout-{}.log", rand::random::<u32>()).as_str());
+	let stderr_path = tmp_file(format!("server-stderr-{}.log", rand::random::<u32>()).as_str());
+	debug!("Logging server output to: ({}, {})", stdout_path, stderr_path);
+	let stdout = Stdio::from(File::create(&stdout_path).unwrap());
+	let stderr = Stdio::from(File::create(&stderr_path).unwrap());
+
 	cmd.env_clear();
 	cmd.stdin(Stdio::piped());
 	cmd.stdout(stdout);
 	cmd.stderr(stderr);
 	cmd.args(args.split_ascii_whitespace());
+
 	Child {
 		inner: Some(cmd.spawn().unwrap()),
+		stdout_path,
+		stderr_path,
 	}
 }
 
 /// Run the CLI with the given args
 pub fn run(args: &str) -> Child {
-	run_internal::<String>(args, None, Stdio::piped(), Stdio::piped())
+	run_internal::<String>(args, None)
 }
 
 /// Run the CLI with the given args inside a temporary directory
 pub fn run_in_dir<P: AsRef<Path>>(args: &str, current_dir: P) -> Child {
-	run_internal(args, Some(current_dir), Stdio::piped(), Stdio::piped())
+	run_internal(args, Some(current_dir))
 }
 
 pub fn tmp_file(name: &str) -> String {
@@ -108,19 +123,6 @@ pub fn tmp_file(name: &str) -> String {
 	path.to_string_lossy().into_owned()
 }
 
-fn parse_server_stdio_from_var(var: &str) -> Result<Stdio, Box<dyn Error>> {
-	match env::var(var).as_deref() {
-		Ok("inherit") => Ok(Stdio::inherit()),
-		Ok("null") => Ok(Stdio::null()),
-		Ok("piped") => Ok(Stdio::piped()),
-		Ok(val) if val.starts_with("file://") => {
-			Ok(Stdio::from(File::create(val.trim_start_matches("file://"))?))
-		}
-		Ok(val) => Err(format!("Unsupported stdio value: {val:?}").into()),
-		_ => Ok(Stdio::null()),
-	}
-}
-
 pub struct StartServerArguments {
 	pub auth: bool,
 	pub tls: bool,
@@ -191,9 +193,7 @@ pub async fn start_server(
 	info!("starting server with args: {start_args}");
 
 	// Configure where the logs go when running the test
-	let stdout = parse_server_stdio_from_var("SURREAL_TEST_SERVER_STDOUT")?;
+	let server = run_internal::<String>(&start_args, None);
-	let stderr = parse_server_stdio_from_var("SURREAL_TEST_SERVER_STDERR")?;
-	let server = run_internal::<String>(&start_args, None, stdout, stderr);
 
 	if !wait_is_ready {
 		return Ok((addr, server));
@@ -328,9 +328,16 @@ pub async fn ws_signin(
 		Some(obj) if obj.keys().all(|k| ["id", "error"].contains(&k.as_str())) => {
 			Err(format!("unexpected error from query request: {:?}", obj.get("error")).into())
 		}
-		Some(obj) if obj.keys().all(|k| ["id", "result"].contains(&k.as_str())) => {
+		Some(obj) if obj.keys().all(|k| ["id", "result"].contains(&k.as_str())) => Ok(obj
-			Ok(obj.get("result").unwrap().as_str().unwrap_or_default().to_owned())
+			.get("result")
-		}
+			.ok_or(TestError::AssertionError {
+				message: format!("expected a result from the received object, got this instead: {:?}", obj),
+			})?
+			.as_str()
+			.ok_or(TestError::AssertionError {
+				message: format!("expected the result object to be a string for the received ws message, got this instead: {:?}", obj.get("result")).to_string(),
+			})?
+			.to_owned()),
 		_ => {
 			error!("{:?}", msg.as_object().unwrap().keys().collect::<Vec<_>>());
 			Err(format!("unexpected response: {:?}", msg).into())
@@ -358,12 +365,11 @@ pub async fn ws_query(
 		Some(obj) if obj.keys().all(|k| ["id", "result"].contains(&k.as_str())) => Ok(obj
 			.get("result")
 			.ok_or(TestError::AssertionError {
-				message: "expected a result from the received object".to_string(),
+				message: format!("expected a result from the received object, got this instead: {:?}", obj),
 			})?
 			.as_array()
 			.ok_or(TestError::AssertionError {
-				message: "expected the result object to be an array for the received ws message"
+				message: format!("expected the result object to be an array for the received ws message, got this instead: {:?}", obj.get("result")).to_string(),
-					.to_string(),
 			})?
 			.to_owned()),
 		_ => {
@@ -393,9 +399,15 @@ pub async fn ws_use(
 		Some(obj) if obj.keys().all(|k| ["id", "error"].contains(&k.as_str())) => {
 			Err(format!("unexpected error from query request: {:?}", obj.get("error")).into())
 		}
-		Some(obj) if obj.keys().all(|k| ["id", "result"].contains(&k.as_str())) => {
+		Some(obj) if obj.keys().all(|k| ["id", "result"].contains(&k.as_str())) => Ok(obj
-			Ok(obj.get("result").unwrap().to_owned())
+			.get("result")
-		}
+			.ok_or(TestError::AssertionError {
+				message: format!(
+					"expected a result from the received object, got this instead: {:?}",
+					obj
+				),
+			})?
+			.to_owned()),
 		_ => {
 			error!("{:?}", msg.as_object().unwrap().keys().collect::<Vec<_>>());
 			Err(format!("unexpected response: {:?}", msg).into())