From a030828619b51badcd6711a3a9ce1105e2504fa1 Mon Sep 17 00:00:00 2001 From: Chris Olszewski Date: Fri, 9 Feb 2024 11:29:19 -0800 Subject: [PATCH 1/5] fix: avoid grouping logs from tasks which ended in error --- .../turborepo-lib/src/task_graph/visitor.rs | 5 ++++- crates/turborepo-ui/src/output.rs | 22 +++++++++---------- .../tests/run-logging/log-order-github.t | 2 -- 3 files changed, 15 insertions(+), 14 deletions(-) diff --git a/crates/turborepo-lib/src/task_graph/visitor.rs b/crates/turborepo-lib/src/task_graph/visitor.rs index 092dca519a709..0acb084453de4 100644 --- a/crates/turborepo-lib/src/task_graph/visitor.rs +++ b/crates/turborepo-lib/src/task_graph/visitor.rs @@ -690,7 +690,10 @@ impl ExecContext { .instrument(span) .await; - let logs = match output_client.finish() { + // If the task resulted in an error, do not group in order to better highlight + // the error. + let keep_group = matches!(result, ExecOutcome::Success(_)); + let logs = match output_client.finish(keep_group) { Ok(logs) => logs, Err(e) => { telemetry.track_error(TrackedErrors::DaemonFailedToMarkOutputsAsCached); diff --git a/crates/turborepo-ui/src/output.rs b/crates/turborepo-ui/src/output.rs index 837c11041aa40..02bafa22b8130 100644 --- a/crates/turborepo-ui/src/output.rs +++ b/crates/turborepo-ui/src/output.rs @@ -116,7 +116,7 @@ impl OutputClient { /// Consume the client and flush any bytes to the underlying sink if /// necessary - pub fn finish(self) -> io::Result>> { + pub fn finish(self, keep_group: bool) -> io::Result>> { let Self { behavior, buffer, @@ -133,7 +133,7 @@ impl OutputClient { // We hold the mutex until we write all of the bytes associated for the client // to ensure that the bytes aren't interspersed. let mut writers = writers.lock().expect("lock poisoned"); - if let Some(prefix) = header { + if let Some(prefix) = keep_group.then_some(header).flatten() { writers.out.write_all(prefix.as_bytes())?; } for SinkBytes { @@ -147,7 +147,7 @@ impl OutputClient { }; writer.write_all(buffer)?; } - if let Some(suffix) = footer { + if let Some(suffix) = keep_group.then_some(footer).flatten() { writers.out.write_all(suffix.as_bytes())?; } } @@ -253,7 +253,7 @@ mod test { let mut err = pass_thru_logger.stderr(); writeln!(&mut out, "task 1: out").unwrap(); writeln!(&mut err, "task 1: err").unwrap(); - assert!(pass_thru_logger.finish().unwrap().is_none()); + assert!(pass_thru_logger.finish(true).unwrap().is_none()); }); s.spawn(move || { let mut out = buffer_logger.stdout(); @@ -261,7 +261,7 @@ mod test { writeln!(&mut out, "task 2: out").unwrap(); writeln!(&mut err, "task 2: err").unwrap(); assert_eq!( - buffer_logger.finish().unwrap().unwrap(), + buffer_logger.finish(true).unwrap().unwrap(), b"task 2: out\ntask 2: err\n" ); }); @@ -291,7 +291,7 @@ mod test { "pass thru should end up in sink immediately" ); assert!( - logger.finish()?.is_none(), + logger.finish(true)?.is_none(), "pass through logs shouldn't keep a buffer" ); assert_eq!( @@ -317,7 +317,7 @@ mod test { "buffer should end up in sink immediately" ); assert_eq!( - logger.finish()?.unwrap(), + logger.finish(true)?.unwrap(), b"output for 1\n", "buffer should return buffer" ); @@ -343,11 +343,11 @@ mod test { writeln!(&mut group2_out, "output for 2")?; writeln!(&mut group1_out, "output for 1")?; let group1_logs = group1_logger - .finish()? + .finish(true)? .expect("grouped logs should have buffer"); writeln!(&mut group2_err, "warning for 2")?; let group2_logs = group2_logger - .finish()? + .finish(true)? .expect("grouped logs should have buffer"); assert_eq!(group1_logs, b"output for 1\n"); @@ -374,14 +374,14 @@ mod test { write!(&mut out, "task 1:").unwrap(); b1.wait(); writeln!(&mut out, " echo building").unwrap(); - assert!(logger1.finish().unwrap().is_none()); + assert!(logger1.finish(true).unwrap().is_none()); }); s.spawn(move || { let mut out = logger2.stdout(); write!(&mut out, "task 2:").unwrap(); b2.wait(); writeln!(&mut out, " echo failing").unwrap(); - assert!(logger2.finish().unwrap().is_none(),); + assert!(logger2.finish(true).unwrap().is_none(),); }); }); let SinkWriters { out, .. } = Arc::into_inner(sink.writers).unwrap().into_inner().unwrap(); diff --git a/turborepo-tests/integration/tests/run-logging/log-order-github.t b/turborepo-tests/integration/tests/run-logging/log-order-github.t index f7a282a2953ef..e5dd8ce8078ad 100644 --- a/turborepo-tests/integration/tests/run-logging/log-order-github.t +++ b/turborepo-tests/integration/tests/run-logging/log-order-github.t @@ -56,7 +56,6 @@ Verify that errors are grouped properly \xe2\x80\xa2 Packages in scope: my-app, util (esc) \xe2\x80\xa2 Running fail in 2 packages (esc) \xe2\x80\xa2 Remote caching disabled (esc) - ::group::util:fail cache miss, executing 122cca10fdcda4f0 \> fail (re) @@ -68,7 +67,6 @@ Verify that errors are grouped properly npm ERR! in workspace: util npm ERR\! at location: (.*)(\/|\\)packages(\/|\\)util (re) \[ERROR\] command finished with error: command \((.*)(\/|\\)packages(\/|\\)util\) (.*)npm(?:\.cmd)? run fail exited \(1\) (re) - ::endgroup:: ::error::util#fail: command \(.*(\/|\\)packages(\/|\\)util\) (.*)npm(?:\.cmd)? run fail exited \(1\) (re) Tasks: 0 successful, 1 total From bb377241acf4899775c0d202c255a4ed0330ae53 Mon Sep 17 00:00:00 2001 From: Chris Olszewski Date: Fri, 9 Feb 2024 16:58:08 -0800 Subject: [PATCH 2/5] fix: update test to use new api --- crates/turborepo-ui/tests/threads.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/crates/turborepo-ui/tests/threads.rs b/crates/turborepo-ui/tests/threads.rs index 1fd2b8304ee0a..a3099975209ab 100644 --- a/crates/turborepo-ui/tests/threads.rs +++ b/crates/turborepo-ui/tests/threads.rs @@ -104,7 +104,7 @@ fn echo_task( } process.wait()?; - client.finish()?; + client.finish(true)?; Ok(()) } From a78024455805bac9ebf4d9e4aaf3f8c1269c0e55 Mon Sep 17 00:00:00 2001 From: Chris Olszewski Date: Tue, 13 Feb 2024 16:25:58 -0800 Subject: [PATCH 3/5] fix: keep red task id on failure in github CI --- crates/turborepo-ci/src/vendor_behavior.rs | 19 +++++++++ crates/turborepo-ci/src/vendors.rs | 42 ++++++++++--------- .../turborepo-lib/src/task_graph/visitor.rs | 10 ++++- crates/turborepo-ui/src/output.rs | 35 ++++++++++++---- .../tests/run-logging/log-order-github.t | 1 + 5 files changed, 76 insertions(+), 31 deletions(-) diff --git a/crates/turborepo-ci/src/vendor_behavior.rs b/crates/turborepo-ci/src/vendor_behavior.rs index e737743fb5d39..396e81a8dc269 100644 --- a/crates/turborepo-ci/src/vendor_behavior.rs +++ b/crates/turborepo-ci/src/vendor_behavior.rs @@ -4,4 +4,23 @@ type GroupPrefixFn = fn(group_name: &str) -> String; pub struct VendorBehavior { pub group_prefix: GroupPrefixFn, pub group_suffix: GroupPrefixFn, + pub error_group_prefix: Option, + pub error_group_suffix: Option, +} + +impl VendorBehavior { + pub fn new(prefix: GroupPrefixFn, suffix: GroupPrefixFn) -> Self { + Self { + group_prefix: prefix, + group_suffix: suffix, + error_group_prefix: None, + error_group_suffix: None, + } + } + + pub fn with_error(mut self, prefix: GroupPrefixFn, suffix: GroupPrefixFn) -> Self { + self.error_group_prefix = Some(prefix); + self.error_group_suffix = Some(suffix); + self + } } diff --git a/crates/turborepo-ci/src/vendors.rs b/crates/turborepo-ci/src/vendors.rs index 9dc8483c0fd4e..0f061b0c0c775 100644 --- a/crates/turborepo-ci/src/vendors.rs +++ b/crates/turborepo-ci/src/vendors.rs @@ -77,10 +77,10 @@ pub(crate) fn get_vendors() -> &'static [Vendor] { sha_env_var: None, branch_env_var: None, username_env_var: None, - behavior: Some(VendorBehavior { - group_prefix: |group_name| format!("##[group]{group_name}\r\n"), - group_suffix: |_| String::from("##[endgroup]\r\n"), - }), + behavior: Some(VendorBehavior::new( + |group_name| format!("##[group]{group_name}\r\n"), + |_| String::from("##[endgroup]\r\n"), + )), }, Vendor { name: "Bamboo", @@ -266,10 +266,16 @@ pub(crate) fn get_vendors() -> &'static [Vendor] { sha_env_var: Some("GITHUB_SHA"), branch_env_var: Some("GITHUB_REF_NAME"), username_env_var: Some("GITHUB_ACTOR"), - behavior: Some(VendorBehavior { - group_prefix: |group_name| format!("::group::{group_name}\n"), - group_suffix: |_| String::from("::endgroup::\n"), - }), + behavior: Some( + VendorBehavior::new( + |group_name| format!("::group::{group_name}\n"), + |_| String::from("::endgroup::\n"), + ) + .with_error( + |group_name| format!("\x1B[;31m{group_name}\x1B[;0m\n"), + |_| String::new(), + ), + ), }, Vendor { name: "GitLab CI", @@ -546,14 +552,10 @@ pub(crate) fn get_vendors() -> &'static [Vendor] { sha_env_var: None, branch_env_var: None, username_env_var: None, - behavior: Some(VendorBehavior { - group_prefix: |group_name| { - format!("##teamcity[blockOpened name='{group_name}']") - }, - group_suffix: |group_name| { - format!("##teamcity[blockClosed name='{group_name}']") - }, - }), + behavior: Some(VendorBehavior::new( + |group_name| format!("##teamcity[blockOpened name='{group_name}']"), + |group_name| format!("##teamcity[blockClosed name='{group_name}']"), + )), }, Vendor { name: "Travis CI", @@ -566,10 +568,10 @@ pub(crate) fn get_vendors() -> &'static [Vendor] { sha_env_var: None, branch_env_var: None, username_env_var: None, - behavior: Some(VendorBehavior { - group_prefix: |group_name| format!("travis_fold:start:{group_name}\r\n"), - group_suffix: |group_name| format!("travis_fold:end:{group_name}\r\n"), - }), + behavior: Some(VendorBehavior::new( + |group_name| format!("travis_fold:start:{group_name}\r\n"), + |group_name| format!("travis_fold:end:{group_name}\r\n"), + )), }, Vendor { name: "Vercel", diff --git a/crates/turborepo-lib/src/task_graph/visitor.rs b/crates/turborepo-lib/src/task_graph/visitor.rs index 0acb084453de4..fc208f0156bb0 100644 --- a/crates/turborepo-lib/src/task_graph/visitor.rs +++ b/crates/turborepo-lib/src/task_graph/visitor.rs @@ -392,6 +392,12 @@ impl<'a> Visitor<'a> { (vendor_behavior.group_suffix)(&group_name), ); logger.with_header_footer(Some(header), Some(footer)); + + let (error_header, error_footer) = ( + vendor_behavior.error_group_prefix.map(|f| f(&group_name)), + vendor_behavior.error_group_suffix.map(|f| f(&group_name)), + ); + logger.with_error_header_footer(error_header, error_footer); } logger } @@ -692,8 +698,8 @@ impl ExecContext { // If the task resulted in an error, do not group in order to better highlight // the error. - let keep_group = matches!(result, ExecOutcome::Success(_)); - let logs = match output_client.finish(keep_group) { + let is_error = matches!(result, ExecOutcome::Task { .. }); + let logs = match output_client.finish(is_error) { Ok(logs) => logs, Err(e) => { telemetry.track_error(TrackedErrors::DaemonFailedToMarkOutputsAsCached); diff --git a/crates/turborepo-ui/src/output.rs b/crates/turborepo-ui/src/output.rs index 02bafa22b8130..80ddf868e8ebd 100644 --- a/crates/turborepo-ui/src/output.rs +++ b/crates/turborepo-ui/src/output.rs @@ -22,6 +22,12 @@ pub struct OutputClient { // Any locals held across an await must implement Sync and RwLock lets us achieve this buffer: Option>>>, writers: Arc>>, + primary: Marginals, + error: Marginals, +} + +#[derive(Default)] +struct Marginals { header: Option, footer: Option, } @@ -82,16 +88,19 @@ impl OutputSink { behavior, buffer, writers, - header: None, - footer: None, + primary: Default::default(), + error: Default::default(), } } } impl OutputClient { pub fn with_header_footer(&mut self, header: Option, footer: Option) { - self.header = header; - self.footer = footer; + self.primary = Marginals { header, footer }; + } + + pub fn with_error_header_footer(&mut self, header: Option, footer: Option) { + self.error = Marginals { header, footer }; } /// A writer that will write to the underlying sink's out writer according @@ -116,15 +125,23 @@ impl OutputClient { /// Consume the client and flush any bytes to the underlying sink if /// necessary - pub fn finish(self, keep_group: bool) -> io::Result>> { + pub fn finish(self, use_error: bool) -> io::Result>> { let Self { behavior, buffer, writers, - header, - footer, + primary, + error, } = self; let buffers = buffer.map(|cell| cell.into_inner().expect("lock poisoned")); + let header = use_error + .then_some(error.header) + .flatten() + .or(primary.header); + let footer = use_error + .then_some(error.footer) + .flatten() + .or(primary.footer); if matches!(behavior, OutputClientBehavior::Grouped) { let buffers = buffers @@ -133,7 +150,7 @@ impl OutputClient { // We hold the mutex until we write all of the bytes associated for the client // to ensure that the bytes aren't interspersed. let mut writers = writers.lock().expect("lock poisoned"); - if let Some(prefix) = keep_group.then_some(header).flatten() { + if let Some(prefix) = header { writers.out.write_all(prefix.as_bytes())?; } for SinkBytes { @@ -147,7 +164,7 @@ impl OutputClient { }; writer.write_all(buffer)?; } - if let Some(suffix) = keep_group.then_some(footer).flatten() { + if let Some(suffix) = footer { writers.out.write_all(suffix.as_bytes())?; } } diff --git a/turborepo-tests/integration/tests/run-logging/log-order-github.t b/turborepo-tests/integration/tests/run-logging/log-order-github.t index e5dd8ce8078ad..96c17cfb3977a 100644 --- a/turborepo-tests/integration/tests/run-logging/log-order-github.t +++ b/turborepo-tests/integration/tests/run-logging/log-order-github.t @@ -56,6 +56,7 @@ Verify that errors are grouped properly \xe2\x80\xa2 Packages in scope: my-app, util (esc) \xe2\x80\xa2 Running fail in 2 packages (esc) \xe2\x80\xa2 Remote caching disabled (esc) + \x1b[;31mutil:fail\x1b[;0m (esc) cache miss, executing 122cca10fdcda4f0 \> fail (re) From 7777ffbaef747e15f7d4753285b5d3ffd4a284f9 Mon Sep 17 00:00:00 2001 From: Chris Olszewski Date: Tue, 13 Feb 2024 16:44:00 -0800 Subject: [PATCH 4/5] chore: add unit test for marginals choice --- crates/turborepo-ui/src/output.rs | 38 +++++++++++++++++++++++++++++++ 1 file changed, 38 insertions(+) diff --git a/crates/turborepo-ui/src/output.rs b/crates/turborepo-ui/src/output.rs index 80ddf868e8ebd..86895d84a191d 100644 --- a/crates/turborepo-ui/src/output.rs +++ b/crates/turborepo-ui/src/output.rs @@ -377,6 +377,44 @@ mod test { Ok(()) } + #[test] + fn test_marginals() -> io::Result<()> { + let sink = OutputSink::new(Vec::new(), Vec::new()); + let mut group1_logger = sink.logger(OutputClientBehavior::Grouped); + group1_logger + .with_header_footer(Some("good header\n".into()), Some("good footer\n".into())); + group1_logger + .with_error_header_footer(Some("bad header\n".into()), Some("bad footer\n".into())); + let mut group2_logger = sink.logger(OutputClientBehavior::Grouped); + group2_logger + .with_header_footer(Some("good header\n".into()), Some("good footer\n".into())); + + let mut group1_out = group1_logger.stdout(); + let mut group2_out = group2_logger.stdout(); + + writeln!(&mut group2_out, "output for 2")?; + writeln!(&mut group1_out, "output for 1")?; + let group1_logs = group1_logger + .finish(true)? + .expect("grouped logs should have buffer"); + let group2_logs = group2_logger + .finish(true)? + .expect("grouped logs should have buffer"); + + assert_eq!(group1_logs, b"output for 1\n"); + assert_eq!(group2_logs, b"output for 2\n"); + + let SinkWriters { out, .. } = Arc::into_inner(sink.writers).unwrap().into_inner().unwrap(); + // Error marginals used when present, primary ones used if errors aren't + // provided + assert_eq!( + out, + b"bad header\noutput for 1\nbad footer\ngood header\noutput for 2\ngood header\n" + ); + + Ok(()) + } + #[test] fn test_loggers_wait_for_newline() { let b1 = Arc::new(Barrier::new(2)); From d7bca55eaeec6935f8b55bbaad8c4f7f2149ad75 Mon Sep 17 00:00:00 2001 From: Chris Olszewski Date: Tue, 13 Feb 2024 17:41:29 -0800 Subject: [PATCH 5/5] chore: fix expected test output --- crates/turborepo-ui/src/output.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/crates/turborepo-ui/src/output.rs b/crates/turborepo-ui/src/output.rs index 86895d84a191d..2fcedd35e30c8 100644 --- a/crates/turborepo-ui/src/output.rs +++ b/crates/turborepo-ui/src/output.rs @@ -409,7 +409,7 @@ mod test { // provided assert_eq!( out, - b"bad header\noutput for 1\nbad footer\ngood header\noutput for 2\ngood header\n" + b"bad header\noutput for 1\nbad footer\ngood header\noutput for 2\ngood footer\n" ); Ok(())