Repository: oli-obk/cargo_metadata
Pull request #106 (2020-04-04 09:58:08)

Robust message parsing
would appreciate a release with this one!

matklad: See also upstream issue: https://github.com/serde-rs/json/issues/647

Though, because cargo guarantees [ndjson](http://ndjson.org/) format, I feel like this lines-based impl is actually more proper. 
ehuss: See also https://github.com/oli-obk/cargo_metadata/issues/102#issuecomment-596264704 for a discussion about this.  I personally think it is better to check if the line starts with `{` and pass-through all others.  Unfortunately Cargo doesn't say when to stop parsing, so things like `cargo test` and `cargo run` can be tricky, though fixing that would be easy.  Also, Cargo itself doesn't emit json errors (something I've wanted to fix for a long time), so mapping to a `io::Error` means you lose the actual message, which is probably not a pattern I would want to encourage.
matklad: >so mapping to a io::Error means you lose the actual message, which is probably not a pattern I would want to encourage.

I believe the message is preserved, and that the original serde error can be recovered via downcasting as well:

```rust
Err(err) => {
    eprintln!("err = {:?}", err);
    eprintln!("err = {}", err);
    let err = err.get_ref().unwrap().downcast_ref::<serde_json::Error>();
    eprintln!("err = {:?}", err);
    bad += 1
},
-------
running 1 test
err = Custom { kind: InvalidData, error: Error("expected value", line: 1, column: 1) }
err = expected value at line 1 column 1
err = Some(Error("expected value", line: 1, column: 1))
test parse_stream_is_robust ... ok
```

This does sound like a perfect use-case for `io::ErrorKind::InvalidData`. 

Checking for `{` is only optimization I think? Like, proc macro can print `{}`, and we'd still fail to deserialize it as `Message`. So i'd rather just lean of serde's error reporting here. 

Separating messages from other output properly is an interesting, hard problem, which I think doesn't have a perfect solution. Like, you can't even assume utf-8 encoding. So I'd rather keep this API as the ideal solution for dealing with `cargo check` /  `cargo build`, and, for anything more complex, leave the implementation to the consumer. They probably will need a really complicated machinery for full generality, like the infamous read2 copy. 
matklad: More specifically, I can imagine a tad more general interface, which returns an `io::Result<Either<Message, String>>`, but I believe that:

* it will make check & build cases more complicated without any benefit
* it won't solve the run case, as, for run, you'd need to handle stderr (and non-utf8 output).
* it won't be a part of perfect solution for the run case, as that involves `read2` to drain both stdout and stderr, and read2 interface (and, in general, the whole posix-style IO) doesn't compose well with blocking iterators
ehuss: Checking for `{` is a convenience to differentiate between "this is definitely not JSON" and "this is maybe JSON, but didn't parse correctly", where in the former case should just be displayed as-is to the user, whereas the later you may want to show an error.

I don't see how to get the original line from the error object.

I'm not sure why it needs to be particularly complex or specialized.  It just needs to return a message or a string.  I think rustc's bootstrap is a good use case example ([code](https://github.com/rust-lang/rust/blob/e129923b7e4d58a92c8a0530cd6eaa5be548342d/src/bootstrap/compile.rs#L959-L970)), and shows the code doesn't need to be too complex.

BTW, I posted https://github.com/rust-lang/cargo/pull/8069 as a solution to know when to stop parsing the output.  Would appreciate if you have any comments on it.

matklad: >I don't see how to get the original line from the error object.

Ah, sorry, I've completely misunderstood what do you mean by " you lose the actual message", I was thinking about serde's error message. 

> It just needs to return a message or a string.

Hm, what Item type do you envision for the Iterator then? I think it has to be `io::Result<Something>`, as we need to report the outer reader errors. For something, we need to handle three possibilities: 

1. It's definitelly not a JSON message
2. It's a JSON message
3. It looks like JSON message, but fails to parse.

And in the last case we can't re-use serde_json::Error as is, as it doesn't contain the original string.  That gives us something like this:

```rust
io::Result<Result<Message, (String, Option<serde_json::Error>)>>
```

I don't see nice ways to simplify that substantionaly. It seems like just writing the loop manually as is done in the rustc's bootstrap code might actually be more readable.

Writing this all down, I am not actually sure if this streamp-parsing functionality even should exist in this crate, but, if it does, I think it should use the line splitting approach. 
roblabla: What's the motivation for this? Does cargo ever send us non-JSON output? Shouldn't that be considered a cargo bug and fixed there, instead of awkwardly worked around here?
matklad: https://github.com/oli-obk/cargo_metadata/pull/106/commits/1a3220f578db2774b9a800bf0341610a59f54271#diff-8294540e38a75a7ad333709397296910R480-R481

We hit this in real world with rust-analyzer
oli-obk: I'm sorry, I'm not sure I get what's going on in this discussion. I seem to be missing information from other places.

@ehuss @roblabla do you have any concerns about this impl that will be problematic for us in the future? If so, do you have any concrete modification suggestions to this PR?

ehuss: Yea, sorry, I've been meaning to respond.  I'll try to come up with a concrete suggestion soon. 
roblabla: I've been thinking about this for a bit. I think this PR is fine for inclusion as-is. There are two separate problems with `cargo-metadata` and JSON parsing that it helps with:

1. During the cargo build, there will sometimes be non-JSON output interspersed in `stdout`, despite using `message-format=json`. IMO this is a cargo/rustc bug - when `--message-format=json` is passed to cargo, `stdout` shouldn't have any non-JSON output at least during the build. I opened a cargo issue, https://github.com/rust-lang/cargo/issues/8179

    Still, even though it's a cargo bug, having this PR in is a good idea: it allows us to gracefully recover when a stray print happens. It work on cargo as it exists today, it avoids problems if cargo regresses later, and it allows `cargo-metadata` to work on outdated cargo versions when the problem is fixed.

    The current PR doesn't provide a mechanism to recover the message that failed to parse as JSON. IMO this is fine, since ultimately this is caused by a cargo bug that needs to be fixed upstream. I don't think the lost message will cause all that much problem - I'm highly doubtful there's any tools relying on the stdout output of proc-macros.

2. After the build is done, there isn't any guarantee that the stdout will contain JSON, e.g. when doing `cargo run`. At this point, the rest of the data can be just about anything. This is linked to #102.

    In this use-case, this PR avoids a crash, but it doesn't provide a mechanism to recover the data that failed to parse to JSON, which might be necessary for some tools to parse. For instance, the rest of the data could be another JSON stream (for instance, when running `cargo test -- --format json`) or it could be binary data/invalid utf8, etc...

    Attempting to recover the "lost" message in the error type here doesn't make sense. The output might not be a line, it might be of arbitrary size, it might be invalid utf8. 

    To help deal with this, ehuss added a `build-finished` message type to cargo (https://github.com/rust-lang/cargo/pull/8069), signaling the end of a cargo build and the rest of the output stream is arbitrary. IMO, the ideal solution would be for `cargo-metadata` to stop deserializing messages after the marker, and allow the user to extract the `std::io::Read` instance passed to `parse_stream`. The user would then be free to do what they need to do with the `std::io::Read` (write the rest of the stream to disk, parse it, etc...).

    This PR lays some groundwork for this. First of all, `parse_stream` introduces its own type that can have arbitrary logic, so it allows us to add some logic to stop parsing messages after the `build-finished` marker is reached, and adding our own functions to recover the `BufRead` after iteration is done, without introducing a breaking change.

So, no, I don't think this PR is problematic.
ehuss: Taking another look at this, what do you think about just adding another variant to `Message` that indicates a raw stdout message?  That can be used if the line is not valid JSON.

matklad: @ehuss I like your solution, implemented it!

The drawback is that we now can in theory mask a serde error, but this bug seems unlikely in practice, and, given that we control both producer and consumer of messages here, shouldn't be hard to fix. 

Patch:
diff --git a/Cargo.toml b/Cargo.toml
index 36f7005..d878a92 100644
--- a/Cargo.toml
+++ b/Cargo.toml
@@ -9,7 +9,7 @@ readme = "README.md"
 
 [dependencies]
 serde = "1.0.79"
-serde_derive = "1.0.79"
+serde_derive = "1.0.107"
 serde_json = "1.0.1"
 
 [dependencies.semver]
diff --git a/src/lib.rs b/src/lib.rs
index 8a204cd..62676ed 100644
--- a/src/lib.rs
+++ b/src/lib.rs
@@ -56,7 +56,8 @@
 //!     .spawn()
 //!     .unwrap();
 //!
-//! for message in cargo_metadata::parse_messages(command.stdout.take().unwrap()) {
+//! let reader = std::io::BufReader::new(command.stdout.take().unwrap());
+//! for message in cargo_metadata::Message::parse_stream(reader) {
 //!     match message.unwrap() {
 //!         Message::CompilerMessage(msg) => {
 //!             println!("{:?}", msg);
@@ -96,8 +97,10 @@ pub use dependency::{Dependency, DependencyKind};
 use diagnostic::Diagnostic;
 pub use errors::{Error, Result};
 pub use messages::{
-    parse_messages, Artifact, ArtifactProfile, BuildFinished, BuildScript, CompilerMessage, Message,
+    Artifact, ArtifactProfile, BuildFinished, BuildScript, CompilerMessage, Message, MessageIter
 };
+#[allow(deprecated)]
+pub use messages::parse_messages;
 
 mod dependency;
 pub mod diagnostic;
diff --git a/src/messages.rs b/src/messages.rs
index a5bc161..11df302 100644
--- a/src/messages.rs
+++ b/src/messages.rs
@@ -1,7 +1,7 @@
 use super::{Diagnostic, PackageId, Target};
 use serde_json;
 use std::fmt;
-use std::io::Read;
+use std::io::{self, BufRead, Lines, Read};
 use std::path::PathBuf;
 
 /// Profile settings used to determine which compiler flags to use for a
@@ -110,23 +110,52 @@ pub enum Message {
     /// This is emitted at the end of the build as the last message.
     /// Added in Rust 1.44.
     BuildFinished(BuildFinished),
+    /// A line of text which isn't a cargo or compiler message.
+    /// Line separator is not included
+    #[serde(skip)]
+    TextLine(String),
     #[doc(hidden)]
     #[serde(other)]
     Unknown,
 }
 
+impl Message {
+    /// Creates an iterator of Message from a Read outputting a stream of JSON
+    /// messages. For usage information, look at the top-level documentation.
+    pub fn parse_stream<R: BufRead>(input: R) -> MessageIter<R> {
+        MessageIter {
+            lines: input.lines(),
+        }
+    }
+}
+
 impl fmt::Display for CompilerMessage {
     fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
         write!(f, "{}", self.message)
     }
 }
 
+/// An iterator of Messages.
+pub struct MessageIter<R> {
+    lines: Lines<R>,
+}
+
+impl<R: BufRead> Iterator for MessageIter<R> {
+    type Item = io::Result<Message>;
+    fn next(&mut self) -> Option<Self::Item> {
+        let line = self.lines.next()?;
+        let message = line.map(|it| serde_json::from_str(&it).unwrap_or(Message::TextLine(it)));
+        Some(message)
+    }
+}
+
 /// An iterator of Message.
 type MessageIterator<R> =
     serde_json::StreamDeserializer<'static, serde_json::de::IoRead<R>, Message>;
 
 /// Creates an iterator of Message from a Read outputting a stream of JSON
 /// messages. For usage information, look at the top-level documentation.
+#[deprecated(note = "Use Message::parse_stream instead")]
 pub fn parse_messages<R: Read>(input: R) -> MessageIterator<R> {
     serde_json::Deserializer::from_reader(input).into_iter::<Message>()
 }


Test patch:
diff --git a/tests/test_samples.rs b/tests/test_samples.rs
index 3ba730c..e4c6e19 100644
--- a/tests/test_samples.rs
+++ b/tests/test_samples.rs
@@ -474,3 +474,24 @@ fn current_dir() {
     let namedep = meta.packages.iter().find(|p| p.name == "namedep").unwrap();
     assert!(namedep.name.starts_with("namedep"));
 }
+
+#[test]
+fn parse_stream_is_robust() {
+    // Proc macros can print stuff to stdout, which naturally breaks JSON messages.
+    // Let's check that we don't die horribly in this case, and report an error.
+    let json_output = r##"{"reason":"compiler-artifact","package_id":"chatty 0.1.0 (path+file:///chatty-macro/chatty)","target":{"kind":["proc-macro"],"crate_types":["proc-macro"],"name":"chatty","src_path":"/chatty-macro/chatty/src/lib.rs","edition":"2018","doctest":true},"profile":{"opt_level":"0","debuginfo":2,"debug_assertions":true,"overflow_checks":true,"test":false},"features":[],"filenames":["/chatty-macro/target/debug/deps/libchatty-f2adcff24cdf3bb2.so"],"executable":null,"fresh":false}
+Evil proc macro was here!
+{"reason":"compiler-artifact","package_id":"chatty-macro 0.1.0 (path+file:///chatty-macro)","target":{"kind":["lib"],"crate_types":["lib"],"name":"chatty-macro","src_path":"/chatty-macro/src/lib.rs","edition":"2018","doctest":true},"profile":{"opt_level":"0","debuginfo":2,"debug_assertions":true,"overflow_checks":true,"test":false},"features":[],"filenames":["/chatty-macro/target/debug/libchatty_macro.rlib","/chatty-macro/target/debug/deps/libchatty_macro-cb5956ed52a11fb6.rmeta"],"executable":null,"fresh":false}
+"##;
+    let mut n_messages = 0;
+    let mut text = String::new();
+    for message in cargo_metadata::Message::parse_stream(json_output.as_bytes()) {
+        let message = message.unwrap();
+        match message {
+            cargo_metadata::Message::TextLine(line) => text = line,
+            _ => n_messages += 1,
+        }
+    }
+    assert_eq!(n_messages, 2);
+    assert_eq!(text, "Evil proc macro was here!");
+}