Auto merge of #109729 - fortanix:raoul/bugfix_libtest_json_synchroniz…

…ation, r=pietroalbini

Ensure test library issues json string line-by-line

#108659 introduces a custom test display implementation. It does so by using libtest to output json. The stdout is read line by line and parsed. The code trims the line read and checks whether it starts with a `{` and ends with a `}`.

Unfortunately, there is a race condition in how json data is written to stdout. The `write_message` function calls `self.out.write_all` repeatedly to write a buffer that contains (partial) json data, or a new line. There is no lock around the `self.out.write_all` functions. Similarly, the `write_message` function itself is called with only partial json data. As these functions are called from concurrent threads, this may result in json data ending up on the same stdout line. This PR avoids this by buffering the complete json data before issuing a single `self.out.write_all`.

(#109484 implemented a partial fix for this issue; it only avoids that failed json parsing would result in a panic.)

cc: `@jethrogb,` `@pietroalbini`

library/test/src/formatters/json.rs

@@ -18,14 +18,10 @@ impl<T: Write> JsonFormatter<T> {
     }
 
     fn writeln_message(&mut self, s: &str) -> io::Result<()> {
-        assert!(!s.contains('\n'));
-
-        self.out.write_all(s.as_ref())?;
-        self.out.write_all(b"\n")
-    }
-
-    fn write_message(&mut self, s: &str) -> io::Result<()> {
-        assert!(!s.contains('\n'));
+        // self.out will take a lock, but that lock is released when write_all returns. This
+        // results in a race condition and json output may not end with a new line. We avoid this
+        // by issuing `write_all` calls line-by-line.
+        assert_eq!(s.chars().last(), Some('\n'));
 
         self.out.write_all(s.as_ref())
     }
@@ -34,34 +30,35 @@ impl<T: Write> JsonFormatter<T> {
         &mut self,
         ty: &str,
         name: &str,
-        evt: &str,
+        event: &str,
         exec_time: Option<&time::TestExecTime>,
         stdout: Option<Cow<'_, str>>,
         extra: Option<&str>,
     ) -> io::Result<()> {
         // A doc test's name includes a filename which must be escaped for correct json.
-        self.write_message(&format!(
-            r#"{{ "type": "{}", "name": "{}", "event": "{}""#,
-            ty,
-            EscapedString(name),
-            evt
-        ))?;
-        if let Some(exec_time) = exec_time {
-            self.write_message(&format!(r#", "exec_time": {}"#, exec_time.0.as_secs_f64()))?;
-        }
-        if let Some(stdout) = stdout {
-            self.write_message(&format!(r#", "stdout": "{}""#, EscapedString(stdout)))?;
-        }
-        if let Some(extra) = extra {
-            self.write_message(&format!(r#", {extra}"#))?;
-        }
-        self.writeln_message(" }")
+        let name = EscapedString(name);
+        let exec_time_json = if let Some(exec_time) = exec_time {
+            format!(r#", "exec_time": {}"#, exec_time.0.as_secs_f64())
+        } else {
+            String::from("")
+        };
+        let stdout_json = if let Some(stdout) = stdout {
+            format!(r#", "stdout": "{}""#, EscapedString(stdout))
+        } else {
+            String::from("")
+        };
+        let extra_json =
+            if let Some(extra) = extra { format!(r#", {extra}"#) } else { String::from("") };
+        let newline = "\n";
+
+        self.writeln_message(&format!(
+                r#"{{ "type": "{ty}", "name": "{name}", "event": "{event}"{exec_time_json}{stdout_json}{extra_json} }}{newline}"#))
     }
 }
 
 impl<T: Write> OutputFormatter for JsonFormatter<T> {
     fn write_discovery_start(&mut self) -> io::Result<()> {
-        self.writeln_message(&format!(r#"{{ "type": "suite", "event": "discovery" }}"#))
+        self.writeln_message(concat!(r#"{ "type": "suite", "event": "discovery" }"#, "\n"))
     }
 
     fn write_test_discovered(&mut self, desc: &TestDesc, test_type: &str) -> io::Result<()> {
@@ -77,21 +74,24 @@ impl<T: Write> OutputFormatter for JsonFormatter<T> {
             ..
         } = desc;
 
+        let name = EscapedString(name.as_slice());
+        let ignore_message = ignore_message.unwrap_or("");
+        let source_path = EscapedString(source_file);
+        let newline = "\n";
+
         self.writeln_message(&format!(
-            r#"{{ "type": "{test_type}", "event": "discovered", "name": "{}", "ignore": {ignore}, "ignore_message": "{}", "source_path": "{}", "start_line": {start_line}, "start_col": {start_col}, "end_line": {end_line}, "end_col": {end_col} }}"#,
-            EscapedString(name.as_slice()),
-            ignore_message.unwrap_or(""),
-            EscapedString(source_file),
+            r#"{{ "type": "{test_type}", "event": "discovered", "name": "{name}", "ignore": {ignore}, "ignore_message": "{ignore_message}", "source_path": "{source_path}", "start_line": {start_line}, "start_col": {start_col}, "end_line": {end_line}, "end_col": {end_col} }}{newline}"#
         ))
     }
 
     fn write_discovery_finish(&mut self, state: &ConsoleTestDiscoveryState) -> io::Result<()> {
         let ConsoleTestDiscoveryState { tests, benchmarks, ignored, .. } = state;
 
         let total = tests + benchmarks;
+        let newline = "\n";
         self.writeln_message(&format!(
-            r#"{{ "type": "suite", "event": "completed", "tests": {tests}, "benchmarks": {benchmarks}, "total": {total}, "ignored": {ignored} }}"#
-        ))
+            r#"{{ "type": "suite", "event": "completed", "tests": {tests}, "benchmarks": {benchmarks}, "total": {total}, "ignored": {ignored} }}{newline}"#
+            ))
     }
 
     fn write_run_start(&mut self, test_count: usize, shuffle_seed: Option<u64>) -> io::Result<()> {
@@ -100,15 +100,17 @@ impl<T: Write> OutputFormatter for JsonFormatter<T> {
         } else {
             String::new()
         };
+        let newline = "\n";
         self.writeln_message(&format!(
-            r#"{{ "type": "suite", "event": "started", "test_count": {test_count}{shuffle_seed_json} }}"#
-        ))
+            r#"{{ "type": "suite", "event": "started", "test_count": {test_count}{shuffle_seed_json} }}{newline}"#
+            ))
     }
 
     fn write_test_start(&mut self, desc: &TestDesc) -> io::Result<()> {
+        let name = EscapedString(desc.name.as_slice());
+        let newline = "\n";
         self.writeln_message(&format!(
-            r#"{{ "type": "test", "event": "started", "name": "{}" }}"#,
-            EscapedString(desc.name.as_slice())
+            r#"{{ "type": "test", "event": "started", "name": "{name}" }}{newline}"#
         ))
     }
 
@@ -173,53 +175,43 @@ impl<T: Write> OutputFormatter for JsonFormatter<T> {
                 } else {
                     format!(r#", "mib_per_second": {}"#, bs.mb_s)
                 };
+                let name = EscapedString(desc.name.as_slice());
 
-                let line = format!(
+                self.writeln_message(&format!(
                     "{{ \"type\": \"bench\", \
-                     \"name\": \"{}\", \
-                     \"median\": {}, \
-                     \"deviation\": {}{} }}",
-                    EscapedString(desc.name.as_slice()),
-                    median,
-                    deviation,
-                    mbps
-                );
-
-                self.writeln_message(&line)
+                     \"name\": \"{name}\", \
+                     \"median\": {median}, \
+                     \"deviation\": {deviation}{mbps} }}\n",
+                ))
             }
         }
     }
 
     fn write_timeout(&mut self, desc: &TestDesc) -> io::Result<()> {
+        let name = EscapedString(desc.name.as_slice());
+        let newline = "\n";
         self.writeln_message(&format!(
-            r#"{{ "type": "test", "event": "timeout", "name": "{}" }}"#,
-            EscapedString(desc.name.as_slice())
+            r#"{{ "type": "test", "event": "timeout", "name": "{name}" }}{newline}"#,
         ))
     }
 
     fn write_run_finish(&mut self, state: &ConsoleTestState) -> io::Result<bool> {
-        self.write_message(&format!(
-            "{{ \"type\": \"suite\", \
-             \"event\": \"{}\", \
-             \"passed\": {}, \
-             \"failed\": {}, \
-             \"ignored\": {}, \
-             \"measured\": {}, \
-             \"filtered_out\": {}",
-            if state.failed == 0 { "ok" } else { "failed" },
-            state.passed,
-            state.failed,
-            state.ignored,
-            state.measured,
-            state.filtered_out,
-        ))?;
-
-        if let Some(ref exec_time) = state.exec_time {
-            let time_str = format!(", \"exec_time\": {}", exec_time.0.as_secs_f64());
-            self.write_message(&time_str)?;
-        }
+        let event = if state.failed == 0 { "ok" } else { "failed" };
+        let passed = state.passed;
+        let failed = state.failed;
+        let ignored = state.ignored;
+        let measured = state.measured;
+        let filtered_out = state.filtered_out;
+        let exec_time_json = if let Some(ref exec_time) = state.exec_time {
+            format!(r#", "exec_time": {}"#, exec_time.0.as_secs_f64())
+        } else {
+            String::from("")
+        };
+        let newline = "\n";
 
-        self.writeln_message(" }")?;
+        self.writeln_message(&format!(
+            r#"{{ "type": "suite", "event": "{event}", "passed": {passed}, "failed": {failed}, "ignored": {ignored}, "measured": {measured}, "filtered_out": {filtered_out}{exec_time_json} }}{newline}"#
+        ))?;
 
         Ok(state.failed == 0)
     }