Auto merge of rust-lang#115706 - RalfJung:compiletest-truncation, r=wesleywiser

Make compiletest output truncation less disruptive

When the test output becomes too large, compiletest stops recording all of it. However:
- this can lead to invalid JSON, which then causes compiletest itself to throw further errors
- the note that output was truncated is in the middle of the output, with >100kb of text on each side; that makes it almost impossible to actually see that note in the terminal

So assuming that we do need to keep the output truncation, I propose that we only ever do a cut at the end, so that it is very clear by looking at the end of the log that truncation happened. I added a message at the beginning of the output as well. Also I added some logic to make it less likely that we'll cut things off in the middle of a JSON record. (I tested that successfully by reducing the output limit to something very low and running a few ui tests.) Furthermore I increased the max buffer size to 512KB; that's really not a lot of memory compared to how much RAM it takes to build rustc (it's ~25% more than the previous maximum HEAD+TAIL length). And finally, the information that things got truncated is now propagated to the higher levels, so that we can fail the test instead of comparing the truncated output with the reference.

Fixes rust-lang#115675
Fixes rust-lang#96229
Fixes rust-lang#94322
Fixes rust-lang#92211

Author: bors

src/tools/compiletest/src/read2.rs

@@ -9,7 +9,16 @@ use std::io::{self, Write};
 use std::mem::replace;
 use std::process::{Child, Output};
 
-pub fn read2_abbreviated(mut child: Child, filter_paths_from_len: &[String]) -> io::Result<Output> {
+#[derive(Copy, Clone, Debug)]
+pub enum Truncated {
+    Yes,
+    No,
+}
+
+pub fn read2_abbreviated(
+    mut child: Child,
+    filter_paths_from_len: &[String],
+) -> io::Result<(Output, Truncated)> {
     let mut stdout = ProcOutput::new();
     let mut stderr = ProcOutput::new();
 
@@ -24,11 +33,12 @@ pub fn read2_abbreviated(mut child: Child, filter_paths_from_len: &[String]) ->
     )?;
     let status = child.wait()?;
 
-    Ok(Output { status, stdout: stdout.into_bytes(), stderr: stderr.into_bytes() })
+    let truncated =
+        if stdout.truncated() || stderr.truncated() { Truncated::Yes } else { Truncated::No };
+    Ok((Output { status, stdout: stdout.into_bytes(), stderr: stderr.into_bytes() }, truncated))
 }
 
-const HEAD_LEN: usize = 160 * 1024;
-const TAIL_LEN: usize = 256 * 1024;
+const MAX_OUT_LEN: usize = 512 * 1024;
 
 // Whenever a path is filtered when counting the length of the output, we need to add some
 // placeholder length to ensure a compiler emitting only filtered paths doesn't cause a OOM.
@@ -39,14 +49,18 @@ const FILTERED_PATHS_PLACEHOLDER_LEN: usize = 32;
 
 enum ProcOutput {
     Full { bytes: Vec<u8>, filtered_len: usize },
-    Abbreviated { head: Vec<u8>, skipped: usize, tail: Box<[u8]> },
+    Abbreviated { head: Vec<u8>, skipped: usize },
 }
 
 impl ProcOutput {
     fn new() -> Self {
         ProcOutput::Full { bytes: Vec::new(), filtered_len: 0 }
     }
 
+    fn truncated(&self) -> bool {
+        matches!(self, Self::Abbreviated { .. })
+    }
+
     fn extend(&mut self, data: &[u8], filter_paths_from_len: &[String]) {
         let new_self = match *self {
             ProcOutput::Full { ref mut bytes, ref mut filtered_len } => {
@@ -83,24 +97,21 @@ impl ProcOutput {
                 }
 
                 let new_len = bytes.len();
-                if (*filtered_len).min(new_len) <= HEAD_LEN + TAIL_LEN {
+                if (*filtered_len).min(new_len) <= MAX_OUT_LEN {
                     return;
                 }
 
                 let mut head = replace(bytes, Vec::new());
-                let mut middle = head.split_off(HEAD_LEN);
-                let tail = middle.split_off(middle.len() - TAIL_LEN).into_boxed_slice();
-                let skipped = new_len - HEAD_LEN - TAIL_LEN;
-                ProcOutput::Abbreviated { head, skipped, tail }
+                // Don't truncate if this as a whole line.
+                // That should make it less likely that we cut a JSON line in half.
+                if head.last() != Some(&('\n' as u8)) {
+                    head.truncate(MAX_OUT_LEN);
+                }
+                let skipped = new_len - head.len();
+                ProcOutput::Abbreviated { head, skipped }
             }
-            ProcOutput::Abbreviated { ref mut skipped, ref mut tail, .. } => {
+            ProcOutput::Abbreviated { ref mut skipped, .. } => {
                 *skipped += data.len();
-                if data.len() <= TAIL_LEN {
-                    tail[..data.len()].copy_from_slice(data);
-                    tail.rotate_left(data.len());
-                } else {
-                    tail.copy_from_slice(&data[(data.len() - TAIL_LEN)..]);
-                }
                 return;
             }
         };
@@ -110,18 +121,12 @@ impl ProcOutput {
     fn into_bytes(self) -> Vec<u8> {
         match self {
             ProcOutput::Full { bytes, .. } => bytes,
-            ProcOutput::Abbreviated { mut head, mut skipped, tail } => {
-                let mut tail = &*tail;
-
-                // Skip over '{' at the start of the tail, so we don't later wrongfully consider this as json.
-                // See <https://rust-lang.zulipchat.com/#narrow/stream/182449-t-compiler.2Fhelp/topic/Weird.20CI.20failure/near/321797811>
-                while tail.get(0) == Some(&b'{') {
-                    tail = &tail[1..];
-                    skipped += 1;
-                }
-
-                write!(&mut head, "\n\n<<<<<< SKIPPED {} BYTES >>>>>>\n\n", skipped).unwrap();
-                head.extend_from_slice(tail);
+            ProcOutput::Abbreviated { mut head, skipped } => {
+                let head_note =
+                    format!("<<<<<< TRUNCATED, SHOWING THE FIRST {} BYTES >>>>>>\n\n", head.len());
+                head.splice(0..0, head_note.into_bytes());
+                write!(&mut head, "\n\n<<<<<< TRUNCATED, DROPPED {} BYTES >>>>>>", skipped)
+                    .unwrap();
                 head
             }
         }

src/tools/compiletest/src/read2/tests.rs

@@ -1,4 +1,6 @@
-use crate::read2::{ProcOutput, FILTERED_PATHS_PLACEHOLDER_LEN, HEAD_LEN, TAIL_LEN};
+use std::io::Write;
+
+use crate::read2::{ProcOutput, FILTERED_PATHS_PLACEHOLDER_LEN, MAX_OUT_LEN};
 
 #[test]
 fn test_abbreviate_short_string() {
@@ -21,35 +23,13 @@ fn test_abbreviate_short_string_multiple_steps() {
 fn test_abbreviate_long_string() {
     let mut out = ProcOutput::new();
 
-    let data = vec![b'.'; HEAD_LEN + TAIL_LEN + 16];
+    let data = vec![b'.'; MAX_OUT_LEN + 16];
     out.extend(&data, &[]);
 
-    let mut expected = vec![b'.'; HEAD_LEN];
-    expected.extend_from_slice(b"\n\n<<<<<< SKIPPED 16 BYTES >>>>>>\n\n");
-    expected.extend_from_slice(&vec![b'.'; TAIL_LEN]);
-
-    // We first check the length to avoid endless terminal output if the length differs, since
-    // `out` is hundreds of KBs in size.
-    let out = out.into_bytes();
-    assert_eq!(expected.len(), out.len());
-    assert_eq!(expected, out);
-}
-
-#[test]
-fn test_abbreviate_long_string_multiple_steps() {
-    let mut out = ProcOutput::new();
-
-    out.extend(&vec![b'.'; HEAD_LEN], &[]);
-    out.extend(&vec![b'.'; TAIL_LEN], &[]);
-    // Also test whether the rotation works
-    out.extend(&vec![b'!'; 16], &[]);
-    out.extend(&vec![b'?'; 16], &[]);
-
-    let mut expected = vec![b'.'; HEAD_LEN];
-    expected.extend_from_slice(b"\n\n<<<<<< SKIPPED 32 BYTES >>>>>>\n\n");
-    expected.extend_from_slice(&vec![b'.'; TAIL_LEN - 32]);
-    expected.extend_from_slice(&vec![b'!'; 16]);
-    expected.extend_from_slice(&vec![b'?'; 16]);
+    let mut expected = Vec::new();
+    write!(expected, "<<<<<< TRUNCATED, SHOWING THE FIRST {MAX_OUT_LEN} BYTES >>>>>>\n\n").unwrap();
+    expected.extend_from_slice(&[b'.'; MAX_OUT_LEN]);
+    expected.extend_from_slice(b"\n\n<<<<<< TRUNCATED, DROPPED 16 BYTES >>>>>>");
 
     // We first check the length to avoid endless terminal output if the length differs, since
     // `out` is hundreds of KBs in size.
@@ -86,9 +66,8 @@ fn test_abbreviate_filters_avoid_abbreviations() {
     let mut out = ProcOutput::new();
     let filters = &[std::iter::repeat('a').take(64).collect::<String>()];
 
-    let mut expected = vec![b'.'; HEAD_LEN - FILTERED_PATHS_PLACEHOLDER_LEN as usize];
+    let mut expected = vec![b'.'; MAX_OUT_LEN - FILTERED_PATHS_PLACEHOLDER_LEN as usize];
     expected.extend_from_slice(filters[0].as_bytes());
-    expected.extend_from_slice(&vec![b'.'; TAIL_LEN]);
 
     out.extend(&expected, filters);
 
@@ -104,14 +83,13 @@ fn test_abbreviate_filters_can_still_cause_abbreviations() {
     let mut out = ProcOutput::new();
     let filters = &[std::iter::repeat('a').take(64).collect::<String>()];
 
-    let mut input = vec![b'.'; HEAD_LEN];
-    input.extend_from_slice(&vec![b'.'; TAIL_LEN]);
+    let mut input = vec![b'.'; MAX_OUT_LEN];
     input.extend_from_slice(filters[0].as_bytes());
 
-    let mut expected = vec![b'.'; HEAD_LEN];
-    expected.extend_from_slice(b"\n\n<<<<<< SKIPPED 64 BYTES >>>>>>\n\n");
-    expected.extend_from_slice(&vec![b'.'; TAIL_LEN - 64]);
-    expected.extend_from_slice(&vec![b'a'; 64]);
+    let mut expected = Vec::new();
+    write!(expected, "<<<<<< TRUNCATED, SHOWING THE FIRST {MAX_OUT_LEN} BYTES >>>>>>\n\n").unwrap();
+    expected.extend_from_slice(&[b'.'; MAX_OUT_LEN]);
+    expected.extend_from_slice(b"\n\n<<<<<< TRUNCATED, DROPPED 64 BYTES >>>>>>");
 
     out.extend(&input, filters);
 

src/tools/compiletest/src/runtest.rs

@@ -12,7 +12,7 @@ use crate::compute_diff::{write_diff, write_filtered_diff};
 use crate::errors::{self, Error, ErrorKind};
 use crate::header::TestProps;
 use crate::json;
-use crate::read2::read2_abbreviated;
+use crate::read2::{read2_abbreviated, Truncated};
 use crate::util::{add_dylib_path, dylib_env_var, logv, PathBufExt};
 use crate::ColorConfig;
 use regex::{Captures, Regex};
@@ -701,6 +701,7 @@ impl<'test> TestCx<'test> {
             status: output.status,
             stdout: String::from_utf8(output.stdout).unwrap(),
             stderr: String::from_utf8(output.stderr).unwrap(),
+            truncated: Truncated::No,
             cmdline: format!("{cmd:?}"),
         };
         self.dump_output(&proc_res.stdout, &proc_res.stderr);
@@ -1275,6 +1276,7 @@ impl<'test> TestCx<'test> {
                 status,
                 stdout: String::from_utf8(stdout).unwrap(),
                 stderr: String::from_utf8(stderr).unwrap(),
+                truncated: Truncated::No,
                 cmdline,
             };
             if adb.kill().is_err() {
@@ -1566,7 +1568,13 @@ impl<'test> TestCx<'test> {
         };
 
         self.dump_output(&out, &err);
-        ProcRes { status, stdout: out, stderr: err, cmdline: format!("{:?}", cmd) }
+        ProcRes {
+            status,
+            stdout: out,
+            stderr: err,
+            truncated: Truncated::No,
+            cmdline: format!("{:?}", cmd),
+        }
     }
 
     fn cleanup_debug_info_options(&self, options: &Vec<String>) -> Vec<String> {
@@ -2227,7 +2235,7 @@ impl<'test> TestCx<'test> {
         dylib
     }
 
-    fn read2_abbreviated(&self, child: Child) -> Output {
+    fn read2_abbreviated(&self, child: Child) -> (Output, Truncated) {
         let mut filter_paths_from_len = Vec::new();
         let mut add_path = |path: &Path| {
             let path = path.display().to_string();
@@ -2274,12 +2282,13 @@ impl<'test> TestCx<'test> {
             child.stdin.as_mut().unwrap().write_all(input.as_bytes()).unwrap();
         }
 
-        let Output { status, stdout, stderr } = self.read2_abbreviated(child);
+        let (Output { status, stdout, stderr }, truncated) = self.read2_abbreviated(child);
 
         let result = ProcRes {
             status,
             stdout: String::from_utf8_lossy(&stdout).into_owned(),
             stderr: String::from_utf8_lossy(&stderr).into_owned(),
+            truncated,
             cmdline,
         };
 
@@ -3610,12 +3619,14 @@ impl<'test> TestCx<'test> {
             }
         }
 
-        let output = self.read2_abbreviated(cmd.spawn().expect("failed to spawn `make`"));
+        let (output, truncated) =
+            self.read2_abbreviated(cmd.spawn().expect("failed to spawn `make`"));
         if !output.status.success() {
             let res = ProcRes {
                 status: output.status,
                 stdout: String::from_utf8_lossy(&output.stdout).into_owned(),
                 stderr: String::from_utf8_lossy(&output.stderr).into_owned(),
+                truncated,
                 cmdline: format!("{:?}", cmd),
             };
             self.fatal_proc_rec("make failed", &res);
@@ -3777,6 +3788,15 @@ impl<'test> TestCx<'test> {
         let emit_metadata = self.should_emit_metadata(pm);
         let proc_res = self.compile_test(should_run, emit_metadata);
         self.check_if_test_should_compile(&proc_res, pm);
+        if matches!(proc_res.truncated, Truncated::Yes)
+            && !self.props.dont_check_compiler_stdout
+            && !self.props.dont_check_compiler_stderr
+        {
+            self.fatal_proc_rec(
+                &format!("compiler output got truncated, cannot compare with reference file"),
+                &proc_res,
+            );
+        }
 
         // if the user specified a format in the ui test
         // print the output to the stderr file, otherwise extract
@@ -4468,6 +4488,7 @@ pub struct ProcRes {
     status: ExitStatus,
     stdout: String,
     stderr: String,
+    truncated: Truncated,
     cmdline: String,
 }