Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Consistently use crate::display_error on errors during drain #10394

Merged
merged 2 commits into from
Mar 21, 2022
Merged
Show file tree
Hide file tree
Changes from 1 commit
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
60 changes: 32 additions & 28 deletions src/cargo/core/compiler/job_queue.rs
Original file line number Diff line number Diff line change
Expand Up @@ -77,6 +77,7 @@ use crate::core::compiler::future_incompat::{
use crate::core::resolver::ResolveBehavior;
use crate::core::{PackageId, Shell, TargetKind};
use crate::util::diagnostic_server::{self, DiagnosticPrinter};
use crate::util::errors::AlreadyPrintedError;
use crate::util::machine_message::{self, Message as _};
use crate::util::CargoResult;
use crate::util::{self, internal, profile};
Expand Down Expand Up @@ -169,6 +170,10 @@ struct DrainState<'cfg> {
per_package_future_incompat_reports: Vec<FutureIncompatReportPackage>,
}

pub struct ErrorsDuringDrain {
pub count: usize,
}

#[derive(Debug, Copy, Clone, PartialEq, Eq, Hash, PartialOrd, Ord)]
pub struct JobId(pub u32);

Expand Down Expand Up @@ -786,14 +791,14 @@ impl<'cfg> DrainState<'cfg> {
// After a job has finished we update our internal state if it was
// successful and otherwise wait for pending work to finish if it failed
// and then immediately return.
let mut error = None;
let mut errors = ErrorsDuringDrain { count: 0 };
// CAUTION! Do not use `?` or break out of the loop early. Every error
// must be handled in such a way that the loop is still allowed to
// drain event messages.
loop {
if error.is_none() {
if errors.count == 0 {
if let Err(e) = self.spawn_work_if_possible(cx, jobserver_helper, scope) {
self.handle_error(&mut cx.bcx.config.shell(), &mut error, e);
self.handle_error(&mut cx.bcx.config.shell(), &mut errors, e);
}
}

Expand All @@ -804,7 +809,7 @@ impl<'cfg> DrainState<'cfg> {
}

if let Err(e) = self.grant_rustc_token_requests() {
self.handle_error(&mut cx.bcx.config.shell(), &mut error, e);
self.handle_error(&mut cx.bcx.config.shell(), &mut errors, e);
}

// And finally, before we block waiting for the next event, drop any
Expand All @@ -814,7 +819,7 @@ impl<'cfg> DrainState<'cfg> {
// to the jobserver itself.
for event in self.wait_for_events() {
if let Err(event_err) = self.handle_event(cx, jobserver_helper, plan, event) {
self.handle_error(&mut cx.bcx.config.shell(), &mut error, event_err);
self.handle_error(&mut cx.bcx.config.shell(), &mut errors, event_err);
}
}
}
Expand All @@ -839,30 +844,24 @@ impl<'cfg> DrainState<'cfg> {
}

let time_elapsed = util::elapsed(cx.bcx.config.creation_time().elapsed());
if let Err(e) = self.timings.finished(cx, &error) {
if error.is_some() {
crate::display_error(&e, &mut cx.bcx.config.shell());
} else {
return Some(e);
}
if let Err(e) = self.timings.finished(cx, &errors.to_error()) {
self.handle_error(&mut cx.bcx.config.shell(), &mut errors, e);
}
Comment on lines -842 to 883
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In response to:

I'm finding it a bit confusing to follow why above cases use handle_error but self.timings.finished and the writeln! below both use different custom logic. I think, however, that it should be fine to use handle_error in both cases?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yea, I think it should be fine. It's been a while, but I think my thought process was that "if something has gone wrong, might as well exit right away". The consequence is that you might end up with multiple errors displayed.

if cx.bcx.build_config.emit_json() {
let mut shell = cx.bcx.config.shell();
let msg = machine_message::BuildFinished {
success: error.is_none(),
success: errors.count == 0,
}
.to_json_string();
if let Err(e) = writeln!(shell.out(), "{}", msg) {
if error.is_some() {
crate::display_error(&e.into(), &mut shell);
} else {
return Some(e.into());
}
self.handle_error(&mut shell, &mut errors, e.into());
}
}

if let Some(e) = error {
Some(e)
if let Some(error) = errors.to_error() {
// Any errors up to this point have already been printed via the
// `display_error` inside `handle_error`.
Some(anyhow::Error::new(AlreadyPrintedError::new(error)))
} else if self.queue.is_empty() && self.pending_queue.is_empty() {
let message = format!(
"{} [{}] target(s) in {}",
Expand All @@ -887,19 +886,14 @@ impl<'cfg> DrainState<'cfg> {
fn handle_error(
&self,
shell: &mut Shell,
err_state: &mut Option<anyhow::Error>,
err_state: &mut ErrorsDuringDrain,
new_err: anyhow::Error,
) {
if err_state.is_some() {
// Already encountered one error.
log::warn!("{:?}", new_err);
} else if !self.active.is_empty() {
crate::display_error(&new_err, shell);
crate::display_error(&new_err, shell);
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't fully understand why, but this breaks build::close_output in the test suite.

The failure looks like:

---- build::close_output stdout ----
thread 'build::close_output' panicked at 'called `Result::unwrap()` on an `Err` value: Expected lines did not match (ignoring order):
0   100002     Compiling foo v0.1.0 (/home/runner/work/cargo/cargo/target/tmp/cit/t231/foo)
1   0     hello stderr!
2   0     error: Broken pipe (os error 32)
3   99999  warning: build failed, waiting for other jobs to finish...
4   0     error: Broken pipe (os error 32)
    5    +error: Broken pipe (os error 32)
    6    +error: Broken pipe (os error 32)
    7    +error: Broken pipe (os error 32)
    8    +error: Broken pipe (os error 32)
    9    +error: Broken pipe (os error 32)
    10   +error: Broken pipe (os error 32)
    11   +error: Broken pipe (os error 32)
    12   +error: Broken pipe (os error 32)
    13   +error: Broken pipe (os error 32)
    14   +error: Broken pipe (os error 32)
    15   +error: Broken pipe (os error 32)
    16   +error: Broken pipe (os error 32)
    17   +error: Broken pipe (os error 32)
    18   +error: Broken pipe (os error 32)
    19   +error: Broken pipe (os error 32)
    20   +error: Broken pipe (os error 32)
[...]
    99989 +error: Broken pipe (os error 32)
    99990 +error: Broken pipe (os error 32)
    99991 +error: Broken pipe (os error 32)
    99992 +error: Broken pipe (os error 32)
    99993 +error: Broken pipe (os error 32)
    99994 +error: Broken pipe (os error 32)
    99995 +error: Broken pipe (os error 32)
    99996 +error: Broken pipe (os error 32)
    99997 +error: Broken pipe (os error 32)
    99998 +error: Broken pipe (os error 32)
    99999 +error: Broken pipe (os error 32)
    100000 +error: Broken pipe (os error 32)
    100001 +error: Broken pipe (os error 32)
    100002 +error: Broken pipe (os error 32)

', tests/testsuite/build.rs:5680:6
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace


failures:
    build::close_output

test result: FAILED. 2298 passed; 1 failed; 6 ignored; 0 measured; 0 filtered out; finished in 506.90s

The test involves a proc macro where we close its stdout and then execute println! 100,000 times from the macro. I believe println is supposed to panic on io error so I am confused how the macro keeps going and prints 99,999 more times after the first println has failed.

The test passes after the following diff:

-         crate::display_error(&new_err, shell);
+         if err_state.count > 1 {
+             log::warn!("{:?}", new_err);
+         } else {
+             crate::display_error(&new_err, shell);
+         }

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I believe the reason for this is that the main loop here gets one-line-at-a-time from the proc-macro, which is 100k prints. Each print fails because of a broken pipe, so Cargo tries to handle the error 100k times.

Short of specifically handling broken pipe errors here I'm not entirely sure what to do. We don't want to drop errors on the floor, especially with your future PR of continuing on error, so they need to be handled somehow I think?

Copy link
Contributor

@ehuss ehuss Mar 2, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm a little concerned specifically about this change (and I realize it is the crux of this PR). It was pretty intentional to not show any errors after the first due to scenarios like this, where Cargo could just spew a bunch of error messages, but only one is really relevant.

Perhaps it is possible to put errors into two categories, one which is "important" and should be shown no matter what, and the other where it should only be shown if no other error has been shown? I think the only error that fits the former category is this one, which is the "could not compile foo…" error. The rest of the errors are all things like failed to write to stdout or other internal errors that aren't too critical to display if something else has gone wrong. Would it be possible to wrap that error up in such a way that it will only show duplicates for that?

That will still result in more errors being display (imagine there are 16 crates building in parallel and they all fail), but I think that's probably fine (and maybe even preferred?).

There still would be some risk that some relevant error would get elided, but at the moment I don't see any that really matter (and wouldn't be any worse than it is today).

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I have update the PR to revert to log::warn! instead of crate::display_error for errors after the first, except for the Message::Finish error that you flagged as important.

if !self.active.is_empty() && err_state.count == 0 {
drop(shell.warn("build failed, waiting for other jobs to finish..."));
*err_state = Some(anyhow::format_err!("build failed"));
} else {
*err_state = Some(new_err);
}
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In response to:

I believe the original intention of this code was, when possible, to return upwards the error we encountered during compilation if only one was encountered. That being said, however, I don't believe we can reliably return upwards an error so I think it would be better to unconditionally, for any errors encountered during the build, to use crate::display_error and print them here. That way there's much less juggling of trying to preserve some "main" error to return while also ensuring that all other errors are printed.

err_state.count += 1;
}

// This also records CPU usage and marks concurrency; we roughly want to do
Expand Down Expand Up @@ -1216,3 +1210,13 @@ feature resolver. Try updating to diesel 1.4.8 to fix this error.
Ok(())
}
}

impl ErrorsDuringDrain {
fn to_error(&self) -> Option<anyhow::Error> {
match self.count {
0 => None,
1 => Some(format_err!("1 job failed")),
n => Some(format_err!("{} jobs failed", n)),
}
}
}
42 changes: 19 additions & 23 deletions src/cargo/lib.rs
Original file line number Diff line number Diff line change
Expand Up @@ -13,7 +13,7 @@ use crate::core::Shell;
use anyhow::Error;
use log::debug;

pub use crate::util::errors::{InternalError, VerboseError};
pub use crate::util::errors::{AlreadyPrintedError, InternalError, VerboseError};
pub use crate::util::{indented_lines, CargoResult, CliError, CliResult, Config};
pub use crate::version::version;

Expand Down Expand Up @@ -76,31 +76,27 @@ pub fn display_warning_with_error(warning: &str, err: &Error, shell: &mut Shell)
}

fn _display_error(err: &Error, shell: &mut Shell, as_err: bool) -> bool {
let verbosity = shell.verbosity();
let is_verbose = |e: &(dyn std::error::Error + 'static)| -> bool {
verbosity != Verbose && e.downcast_ref::<VerboseError>().is_some()
};
// Generally the top error shouldn't be verbose, but check it anyways.
if is_verbose(err.as_ref()) {
return true;
}
if as_err {
drop(shell.error(&err));
} else {
drop(writeln!(shell.err(), "{}", err));
}
for cause in err.chain().skip(1) {
// If we're not in verbose mode then print remaining errors until one
for (i, err) in err.chain().enumerate() {
// If we're not in verbose mode then only print cause chain until one
// marked as `VerboseError` appears.
if is_verbose(cause) {
//
// Generally the top error shouldn't be verbose, but check it anyways.
if shell.verbosity() != Verbose && err.is::<VerboseError>() {
return true;
}
drop(writeln!(shell.err(), "\nCaused by:"));
drop(write!(
shell.err(),
"{}",
indented_lines(&cause.to_string())
));
if err.is::<AlreadyPrintedError>() {
break;
}
if i == 0 {
if as_err {
drop(shell.error(&err));
} else {
drop(writeln!(shell.err(), "{}", err));
}
} else {
drop(writeln!(shell.err(), "\nCaused by:"));
drop(write!(shell.err(), "{}", indented_lines(&err.to_string())));
}
}
false
}
33 changes: 33 additions & 0 deletions src/cargo/util/errors.rs
Original file line number Diff line number Diff line change
Expand Up @@ -99,6 +99,39 @@ impl fmt::Display for InternalError {
}
}

// =============================================================================
// Already printed error

/// An error that does not need to be printed because it does not add any new
/// information to what has already been printed.
pub struct AlreadyPrintedError {
inner: Error,
}

impl AlreadyPrintedError {
pub fn new(inner: Error) -> Self {
AlreadyPrintedError { inner }
}
}

impl std::error::Error for AlreadyPrintedError {
fn source(&self) -> Option<&(dyn std::error::Error + 'static)> {
self.inner.source()
}
}

impl fmt::Debug for AlreadyPrintedError {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
self.inner.fmt(f)
}
}

impl fmt::Display for AlreadyPrintedError {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
self.inner.fmt(f)
}
}

// =============================================================================
// Manifest error

Expand Down
4 changes: 1 addition & 3 deletions tests/testsuite/install.rs
Original file line number Diff line number Diff line change
Expand Up @@ -879,11 +879,9 @@ fn compile_failure() {
.with_status(101)
.with_stderr_contains(
"\
[ERROR] could not compile `foo` due to previous error
[ERROR] failed to compile `foo v0.0.1 ([..])`, intermediate artifacts can be \
found at `[..]target`

Caused by:
could not compile `foo` due to previous error
",
)
.run();
Expand Down