Added JSON output to libtest.

libtest: Json format now outputs failed tests' stdouts.

libtest: Json format now outputs failed tests' stdouts.

libtest: Json formatter now spews individiual events, not as an array

libtest: JSON fixes

libtest: Better JSON escaping

libtest: Test start event is printed on time

2 files changed, 312 insertions, 50 deletions

diff --git a/src/libtest/formatters.rs b/src/libtest/formatters.rs
index 4454e7ed115..08d87b90978 100644
--- a/src/libtest/formatters.rs
+++ b/src/libtest/formatters.rs
@@ -12,12 +12,12 @@ use super::*;
 
 pub(crate) trait OutputFormatter {
     fn write_run_start(&mut self, len: usize) -> io::Result<()>;
-    fn write_test_start(&mut self,
-        test: &TestDesc,
-        align: NamePadding,
-        max_name_len: usize) -> io::Result<()>;
+    fn write_test_start(&mut self, test: &TestDesc) -> io::Result<()>;
     fn write_timeout(&mut self, desc: &TestDesc) -> io::Result<()>;
-    fn write_result(&mut self, result: &TestResult) -> io::Result<()>;
+    fn write_result(&mut self,
+                    desc: &TestDesc,
+                    result: &TestResult,
+                    stdout: &[u8]) -> io::Result<()>;
     fn write_run_finish(&mut self, state: &ConsoleTestState) -> io::Result<bool>;
 }
 
@@ -26,15 +26,17 @@ pub(crate) struct HumanFormatter<T> {
     terse: bool,
     use_color: bool,
     test_count: usize,
+    max_name_len: usize, // number of columns to fill when aligning names
 }
 
 impl<T: Write> HumanFormatter<T> {
-    pub fn new(out: OutputLocation<T>, use_color: bool, terse: bool) -> Self {
+    pub fn new(out: OutputLocation<T>, use_color: bool, terse: bool, max_name_len: usize) -> Self {
         HumanFormatter {
             out,
             terse,
             use_color,
             test_count: 0,
+            max_name_len,
         }
     }
 
@@ -73,7 +75,7 @@ impl<T: Write> HumanFormatter<T> {
                 // `stamp` in the rust CI).
                 self.write_plain("\n")?;
             }
-            
+
             self.test_count += 1;
             Ok(())
         } else {
@@ -170,20 +172,18 @@ impl<T: Write> OutputFormatter for HumanFormatter<T> {
         self.write_plain(&format!("\nrunning {} {}\n", len, noun))
     }
 
-    fn write_test_start(&mut self,
-                        test: &TestDesc,
-                        align: NamePadding,
-                        max_name_len: usize) -> io::Result<()> {
-        if self.terse && align != PadOnRight {
-            Ok(())
-        }
-        else {
-            let name = test.padded_name(max_name_len, align);
-            self.write_plain(&format!("test {} ... ", name))
-        }
+    fn write_test_start(&mut self, _desc: &TestDesc) -> io::Result<()> {
+        // Do not print header, as priting it at this point will result in
+        // an unreadable output when running tests concurrently.
+        Ok(())
     }
 
-    fn write_result(&mut self, result: &TestResult) -> io::Result<()> {
+    fn write_result(&mut self, desc: &TestDesc, result: &TestResult, _: &[u8]) -> io::Result<()> {
+        if !(self.terse && desc.name.padding() != PadOnRight) {
+            let name = desc.padded_name(self.max_name_len, desc.name.padding());
+            self.write_plain(&format!("test {} ... ", name))?;
+        }
+
         match *result {
             TrOk => self.write_ok(),
             TrFailed | TrFailedMsg(_) => self.write_failed(),
@@ -244,3 +244,203 @@ impl<T: Write> OutputFormatter for HumanFormatter<T> {
         Ok(success)
     }
 }
+
+pub(crate) struct JsonFormatter<T> {
+    out: OutputLocation<T>
+}
+
+impl<T: Write> JsonFormatter<T> {
+    pub fn new(out: OutputLocation<T>) -> Self {
+        Self {
+            out,        }
+    }
+
+    fn write_str<S: AsRef<str>>(&mut self, s: S) -> io::Result<()> {
+        self.out.write_all(s.as_ref().as_ref())?;
+        self.out.write_all("\n".as_ref())
+    }
+
+    fn write_event(&mut self,
+                    ty: &str,
+                    name: &str,
+                    evt: &str,
+                    extra: Option<String>) -> io::Result<()> {
+        if let Some(extras) = extra {
+            self.write_str(&*format!(r#"{{ "type": "{}", "name": "{}", "event": "{}", {} }}"#,
+                                    ty,
+                                    name,
+                                    evt,
+                                    extras))
+        }
+        else {
+            self.write_str(&*format!(r#"{{ "type": "{}", "name": "{}", "event": "{}" }}"#,
+                                    ty,
+                                    name,
+                                    evt))
+        }
+    }
+}
+
+impl<T: Write> OutputFormatter for JsonFormatter<T> {
+    fn write_run_start(&mut self, len: usize) -> io::Result<()> {
+        self.write_str(
+            &*format!(r#"{{ "type": "suite", "event": "started", "test_count": "{}" }}"#, len))
+    }
+
+    fn write_test_start(&mut self, desc: &TestDesc) -> io::Result<()> {
+        self.write_str(&*format!(r#"{{ "type": "test", "event": "started", "name": "{}" }}"#,
+                                desc.name))
+    }
+
+    fn write_result(&mut self,
+                        desc: &TestDesc,
+                        result: &TestResult,
+                        stdout: &[u8]) -> io::Result<()> {
+        match *result {
+            TrOk => {
+                self.write_event("test", desc.name.as_slice(), "ok", None)
+            },
+
+            TrFailed => {
+                let extra_data = if stdout.len() > 0 {
+                    Some(format!(r#""stdout": "{}""#,
+                        EscapedString(String::from_utf8_lossy(stdout))))
+                }
+                else {
+                    None
+                };
+
+                self.write_event("test", desc.name.as_slice(), "failed", extra_data)
+            },
+
+            TrFailedMsg(ref m) => {
+                self.write_event("test",
+                                    desc.name.as_slice(),
+                                    "failed",
+                                    Some(format!(r#""message": "{}""#, EscapedString(m))))
+            },
+
+            TrIgnored => {
+                self.write_event("test", desc.name.as_slice(), "ignored", None)
+            },
+
+            TrAllowedFail => {
+                self.write_event("test", desc.name.as_slice(), "allowed_failure", None)
+            },
+
+            TrBench(ref bs) => {
+                let median = bs.ns_iter_summ.median as usize;
+                let deviation = (bs.ns_iter_summ.max - bs.ns_iter_summ.min) as usize;
+
+                let mbps = if bs.mb_s == 0 {
+                    "".into()
+                }
+                else {
+                    format!(r#", "mib_per_second": {}"#, bs.mb_s)
+                };
+
+                let line = format!("{{ \"type\": \"bench\", \
+                                \"name\": \"{}\", \
+                                \"median\": {}, \
+                                \"deviation\": {}{} }}",
+                        desc.name,
+                        median,
+                        deviation,
+                        mbps);
+
+                self.write_str(&*line)
+            },
+        }
+    }
+
+    fn write_timeout(&mut self, desc: &TestDesc) -> io::Result<()> {
+        self.write_str(&*format!(r#"{{ "type": "test", "event": "timeout", "name": "{}" }}"#,
+                        desc.name))
+    }
+
+    fn write_run_finish(&mut self, state: &ConsoleTestState) -> io::Result<bool> {
+
+        self.write_str(&*format!("{{ \"type\": \"suite\", \
+            \"event\": \"{}\", \
+            \"passed\": {}, \
+            \"failed\": {}, \
+            \"allowed_fail\": {}, \
+            \"ignored\": {}, \
+            \"measured\": {}, \
+            \"filtered_out\": \"{}\" }}",
+            if state.failed == 0 { "ok" } else { "failed" },
+            state.passed,
+            state.failed + state.allowed_fail,
+            state.allowed_fail,
+            state.ignored,
+            state.measured,
+            state.filtered_out))?;
+
+        Ok(state.failed == 0)
+    }
+}
+
+/// A formatting utility used to print strings with characters in need of escaping.
+/// Base code taken form `libserialize::json::escape_str`
+struct EscapedString<S: AsRef<str>>(S);
+
+impl<S: AsRef<str>> ::std::fmt::Display for EscapedString<S> {
+    fn fmt(&self, f: &mut ::std::fmt::Formatter) -> ::std::fmt::Result {
+        let mut start = 0;
+
+        for (i, byte) in self.0.as_ref().bytes().enumerate() {
+            let escaped = match byte {
+                b'"' => "\\\"",
+                b'\\' => "\\\\",
+                b'\x00' => "\\u0000",
+                b'\x01' => "\\u0001",
+                b'\x02' => "\\u0002",
+                b'\x03' => "\\u0003",
+                b'\x04' => "\\u0004",
+                b'\x05' => "\\u0005",
+                b'\x06' => "\\u0006",
+                b'\x07' => "\\u0007",
+                b'\x08' => "\\b",
+                b'\t' => "\\t",
+                b'\n' => "\\n",
+                b'\x0b' => "\\u000b",
+                b'\x0c' => "\\f",
+                b'\r' => "\\r",
+                b'\x0e' => "\\u000e",
+                b'\x0f' => "\\u000f",
+                b'\x10' => "\\u0010",
+                b'\x11' => "\\u0011",
+                b'\x12' => "\\u0012",
+                b'\x13' => "\\u0013",
+                b'\x14' => "\\u0014",
+                b'\x15' => "\\u0015",
+                b'\x16' => "\\u0016",
+                b'\x17' => "\\u0017",
+                b'\x18' => "\\u0018",
+                b'\x19' => "\\u0019",
+                b'\x1a' => "\\u001a",
+                b'\x1b' => "\\u001b",
+                b'\x1c' => "\\u001c",
+                b'\x1d' => "\\u001d",
+                b'\x1e' => "\\u001e",
+                b'\x1f' => "\\u001f",
+                b'\x7f' => "\\u007f",
+                _ => { continue; }
+            };
+
+            if start < i {
+                f.write_str(&self.0.as_ref()[start..i])?;
+            }
+
+            f.write_str(escaped)?;
+
+            start = i + 1;
+        }
+
+        if start != self.0.as_ref().len() {
+            f.write_str(&self.0.as_ref()[start..])?;
+        }
+
+        Ok(())
+    }
+}
diff --git a/src/libtest/lib.rs b/src/libtest/lib.rs
index 2fb62c832f8..b11f783770f 100644
--- a/src/libtest/lib.rs
+++ b/src/libtest/lib.rs
@@ -71,6 +71,7 @@ use std::sync::mpsc::{channel, Sender};
 use std::sync::{Arc, Mutex};
 use std::thread;
 use std::time::{Instant, Duration};
+use std::borrow::Cow;
 
 const TEST_WARN_TIMEOUT_S: u64 = 60;
 const QUIET_MODE_MAX_COLUMN: usize = 100; // insert a '\n' after 100 tests in quiet mode
@@ -97,14 +98,33 @@ use formatters::*;
 pub enum TestName {
     StaticTestName(&'static str),
     DynTestName(String),
+    AlignedTestName(Cow<'static, str>, NamePadding),
 }
 impl TestName {
     fn as_slice(&self) -> &str {
         match *self {
             StaticTestName(s) => s,
             DynTestName(ref s) => s,
+            AlignedTestName(ref s, _) => &*s,
         }
     }
+
+    fn padding(&self) -> NamePadding {
+        match self {
+            &AlignedTestName(_, p) => p,
+            _ => PadNone,
+        }
+    }
+
+    fn with_padding(&self, padding: NamePadding) -> TestName {
+        let name = match self {
+            &TestName::StaticTestName(name) => Cow::Borrowed(name),
+            &TestName::DynTestName(ref name) => Cow::Owned(name.clone()),
+            &TestName::AlignedTestName(ref name, _) => name.clone(),
+        };
+
+        TestName::AlignedTestName(name, padding)
+    }
 }
 impl fmt::Display for TestName {
     fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
@@ -112,7 +132,7 @@ impl fmt::Display for TestName {
     }
 }
 
-#[derive(Clone, Copy, PartialEq, Eq)]
+#[derive(Clone, Copy, PartialEq, Eq, Hash, Debug)]
 pub enum NamePadding {
     PadNone,
     PadOnRight,
@@ -306,6 +326,13 @@ pub enum ColorConfig {
     NeverColor,
 }
 
+#[derive(Copy, Clone, Debug, PartialEq, Eq)]
+pub enum OutputFormat {
+    Pretty,
+    Terse,
+    Json
+}
+
 #[derive(Debug)]
 pub struct TestOpts {
     pub list: bool,
@@ -317,7 +344,7 @@ pub struct TestOpts {
     pub logfile: Option<PathBuf>,
     pub nocapture: bool,
     pub color: ColorConfig,
-    pub quiet: bool,
+    pub format: OutputFormat,
     pub test_threads: Option<usize>,
     pub skip: Vec<String>,
     pub options: Options,
@@ -336,7 +363,7 @@ impl TestOpts {
             logfile: None,
             nocapture: false,
             color: AutoColor,
-            quiet: false,
+            format: OutputFormat::Pretty,
             test_threads: None,
             skip: vec![],
             options: Options::new(),
@@ -362,13 +389,17 @@ fn optgroups() -> getopts::Options {
                                      in parallel", "n_threads")
         .optmulti("", "skip", "Skip tests whose names contain FILTER (this flag can \
                                be used multiple times)","FILTER")
-        .optflag("q", "quiet", "Display one character per test instead of one line.\
-                                Equivalent to --format=terse")
+        .optflag("q", "quiet", "Display one character per test instead of one line. \
+                                Alias to --format=terse")
         .optflag("", "exact", "Exactly match filters rather than by substring")
         .optopt("", "color", "Configure coloring of output:
             auto   = colorize if stdout is a tty and tests are run on serially (default);
             always = always colorize output;
-            never  = never colorize output;", "auto|always|never");
+            never  = never colorize output;", "auto|always|never")
+        .optopt("", "format", "Configure formatting of output:
+            pretty = Print verbose output;
+            terse  = Display one character per test;
+            json   = Output a json document", "pretty|terse|json");
     return opts
 }
 
@@ -469,6 +500,19 @@ pub fn parse_opts(args: &[String]) -> Option<OptRes> {
         }
     };
 
+    let format = match matches.opt_str("format").as_ref().map(|s| &**s) {
+        None if quiet => OutputFormat::Terse,
+        Some("pretty") | None => OutputFormat::Pretty,
+        Some("terse") => OutputFormat::Terse,
+        Some("json") => OutputFormat::Json,
+
+        Some(v) => {
+            return Some(Err(format!("argument for --format must be pretty, terse, or json (was \
+                                     {})",
+                                    v)))
+        }
+    };
+
     let test_opts = TestOpts {
         list,
         filter,
@@ -479,7 +523,7 @@ pub fn parse_opts(args: &[String]) -> Option<OptRes> {
         logfile,
         nocapture,
         color,
-        quiet,
+        format,
         test_threads,
         skip: matches.opt_strs("skip"),
         options: Options::new(),
@@ -539,7 +583,6 @@ struct ConsoleTestState {
     metrics: MetricMap,
     failures: Vec<(TestDesc, Vec<u8>)>,
     not_failures: Vec<(TestDesc, Vec<u8>)>,
-    max_name_len: usize, // number of columns to fill when aligning names
     options: Options,
 }
 
@@ -562,7 +605,6 @@ impl ConsoleTestState {
             metrics: MetricMap::new(),
             failures: Vec::new(),
             not_failures: Vec::new(),
-            max_name_len: 0,
             options: opts.options,
         })
     }
@@ -641,7 +683,9 @@ pub fn list_tests_console(opts: &TestOpts, tests: Vec<TestDescAndFn>) -> io::Res
         None => Raw(io::stdout()),
         Some(t) => Pretty(t),
     };
-    let mut out = HumanFormatter::new(output, use_color(opts), opts.quiet);
+
+    let quiet = opts.format == OutputFormat::Terse;
+    let mut out = HumanFormatter::new(output, use_color(opts), quiet, 0);
     let mut st = ConsoleTestState::new(opts)?;
 
     let mut ntest = 0;
@@ -668,11 +712,11 @@ pub fn list_tests_console(opts: &TestOpts, tests: Vec<TestDescAndFn>) -> io::Res
         }
     }
 
-    if !opts.quiet {
+    if !quiet {
         if ntest != 0 || nbench != 0 {
-            st.write_plain("\n")?;
+            out.write_plain("\n")?;
         }
-        st.write_plain(format!("{}, {}\n",
+        out.write_plain(format!("{}, {}\n",
             plural(ntest, "test"),
             plural(nbench, "benchmark")))?;
     }
@@ -682,6 +726,14 @@ pub fn list_tests_console(opts: &TestOpts, tests: Vec<TestDescAndFn>) -> io::Res
 
 // A simple console test runner
 pub fn run_tests_console(opts: &TestOpts, tests: Vec<TestDescAndFn>) -> io::Result<bool> {
+    let tests = {
+        let mut tests = tests;
+        for test in tests.iter_mut() {
+            test.desc.name = test.desc.name.with_padding(test.testfn.padding());
+        }
+
+        tests
+    };
 
     fn callback(event: &TestEvent,
                 st: &mut ConsoleTestState,
@@ -693,11 +745,11 @@ pub fn run_tests_console(opts: &TestOpts, tests: Vec<TestDescAndFn>) -> io::Resu
                 out.write_run_start(filtered_tests.len())
             },
             TeFilteredOut(filtered_out) => Ok(st.filtered_out = filtered_out),
-            TeWait(ref test, padding) => out.write_test_start(test, padding, st.max_name_len),
+            TeWait(ref test) => out.write_test_start(test),
             TeTimeout(ref test) => out.write_timeout(test),
             TeResult(test, result, stdout) => {
                 st.write_log_result(&test, &result)?;
-                out.write_result(&result)?;
+                out.write_result(&test, &result, &*stdout)?;
                 match result {
                     TrOk => {
                         st.passed += 1;
@@ -734,8 +786,25 @@ pub fn run_tests_console(opts: &TestOpts, tests: Vec<TestDescAndFn>) -> io::Resu
         Some(t) => Pretty(t),
     };
 
-    let mut out = HumanFormatter::new(output, use_color(opts), opts.quiet);
+    let max_name_len = if let Some(t) = tests.iter().max_by_key(|t| len_if_padded(*t)) {
+        let n = t.desc.name.as_slice();
+        n.len()
+    }
+    else {
+        0
+    };
 
+    let mut out: Box<OutputFormatter> = match opts.format {
+        OutputFormat::Pretty => Box::new(HumanFormatter::new(output,
+                                                                use_color(opts),
+                                                                false,
+                                                                max_name_len)),
+        OutputFormat::Terse => Box::new(HumanFormatter::new(output,
+                                                                use_color(opts),
+                                                                true,
+                                                                max_name_len)),
+        OutputFormat::Json => Box::new(JsonFormatter::new(output)),
+    };
     let mut st = ConsoleTestState::new(opts)?;
     fn len_if_padded(t: &TestDescAndFn) -> usize {
         match t.testfn.padding() {
@@ -743,11 +812,8 @@ pub fn run_tests_console(opts: &TestOpts, tests: Vec<TestDescAndFn>) -> io::Resu
             PadOnRight => t.desc.name.as_slice().len(),
         }
     }
-    if let Some(t) = tests.iter().max_by_key(|t| len_if_padded(*t)) {
-        let n = t.desc.name.as_slice();
-        st.max_name_len = n.len();
-    }
-    run_tests(opts, tests, |x| callback(&x, &mut st, &mut out))?;
+
+    run_tests(opts, tests, |x| callback(&x, &mut st, &mut *out))?;
 
     assert!(st.current_test_count() == st.total);
 
@@ -770,7 +836,7 @@ fn should_sort_failures_before_printing_them() {
         allow_fail: false,
     };
 
-    let mut out = HumanFormatter::new(Raw(Vec::new()), false, false);
+    let mut out = HumanFormatter::new(Raw(Vec::new()), false, false, 10);
 
     let st = ConsoleTestState {
         log_out: None,
@@ -781,7 +847,6 @@ fn should_sort_failures_before_printing_them() {
         allowed_fail: 0,
         filtered_out: 0,
         measured: 0,
-        max_name_len: 10,
         metrics: MetricMap::new(),
         failures: vec![(test_b, Vec::new()), (test_a, Vec::new())],
         options: Options::new(),
@@ -839,7 +904,7 @@ fn stdout_isatty() -> bool {
 #[derive(Clone)]
 pub enum TestEvent {
     TeFiltered(Vec<TestDesc>),
-    TeWait(TestDesc, NamePadding),
+    TeWait(TestDesc),
     TeResult(TestDesc, TestResult, Vec<u8>),
     TeTimeout(TestDesc),
     TeFilteredOut(usize),
@@ -915,7 +980,7 @@ pub fn run_tests<F>(opts: &TestOpts, tests: Vec<TestDescAndFn>, mut callback: F)
     if concurrency == 1 {
         while !remaining.is_empty() {
             let test = remaining.pop().unwrap();
-            callback(TeWait(test.desc.clone(), test.testfn.padding()))?;
+            callback(TeWait(test.desc.clone()))?;
             run_test(opts, !opts.run_tests, test, tx.clone());
             let (test, result, stdout) = rx.recv().unwrap();
             callback(TeResult(test, result, stdout))?;
@@ -926,6 +991,7 @@ pub fn run_tests<F>(opts: &TestOpts, tests: Vec<TestDescAndFn>, mut callback: F)
                 let test = remaining.pop().unwrap();
                 let timeout = Instant::now() + Duration::from_secs(TEST_WARN_TIMEOUT_S);
                 running_tests.insert(test.desc.clone(), timeout);
+                callback(TeWait(test.desc.clone()))?; //here no pad
                 run_test(opts, !opts.run_tests, test, tx.clone());
                 pending += 1;
             }
@@ -949,7 +1015,6 @@ pub fn run_tests<F>(opts: &TestOpts, tests: Vec<TestDescAndFn>, mut callback: F)
             let (desc, result, stdout) = res.unwrap();
             running_tests.remove(&desc);
 
-            callback(TeWait(desc.clone(), PadNone))?;
             callback(TeResult(desc, result, stdout))?;
             pending -= 1;
         }
@@ -958,7 +1023,7 @@ pub fn run_tests<F>(opts: &TestOpts, tests: Vec<TestDescAndFn>, mut callback: F)
     if opts.bench_benchmarks {
         // All benchmarks run at the end, in serial.
         for b in filtered_benchs {
-            callback(TeWait(b.desc.clone(), b.testfn.padding()))?;
+            callback(TeWait(b.desc.clone()))?;
             run_test(opts, false, b, tx.clone());
             let (test, result, stdout) = rx.recv().unwrap();
             callback(TeResult(test, result, stdout))?;
@@ -1239,10 +1304,7 @@ pub fn run_test(opts: &TestOpts,
             !cfg!(target_os = "emscripten") &&
             !cfg!(target_arch = "wasm32");
         if supports_threads {
-            let cfg = thread::Builder::new().name(match name {
-                DynTestName(ref name) => name.clone(),
-                StaticTestName(name) => name.to_owned(),
-            });
+            let cfg = thread::Builder::new().name(name.as_slice().to_owned());
             cfg.spawn(runtest).unwrap();
         } else {
             runtest();