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

fix: Avoid other output between contents when printing #786

Merged
merged 3 commits into from
Feb 23, 2023

Conversation

flub
Copy link
Contributor

@flub flub commented Feb 22, 2023

This makes sure the OutWriter writes the newline as part of the same
buffer as the output. This makes it less likely that the output will
be interrupted between the content and the newline. E.g. without this
and enabling logging, log messages will be injected between the
content and the newline, making the output garbled.

Unfortunately this isn't entirely correct and is more of a heuristic
because most of our output is small enough that they fit in a single
write. In the blocking world you'd lock Stderr while printing the
messages, in the tokio world however I don't know how to safely do
this.

This makes sure the OutWriter writes the newline as part of the same
buffer as the output.  This makes it less likely that the output will
be interrupted between the content and the newline.  E.g. without this
and enabling logging, log messages will be injected between the
content and the newline, making the output garbled.

Unfortunately this isn't entirely correct and is more of a heuristic
because most of our output is small enough that they fit in a single
write.  In the blocking world you'd lock Stderr while printing the
messages, in the tokio world however I don't know how to safely do
this.
src/main.rs Outdated
@@ -99,8 +99,9 @@ impl OutWriter {
impl OutWriter {
pub async fn println(&self, content: impl AsRef<[u8]>) {
let stderr = &mut *self.stderr.lock().await;
stderr.write_all(content.as_ref()).await.unwrap();
stderr.write_all(b"\n").await.unwrap();
let mut buf: Vec<u8> = content.as_ref().to_vec();
Copy link
Contributor

Choose a reason for hiding this comment

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

much allocations :(

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Yeah, agreed. But this isn't very critical. We don't output much.

Copy link
Contributor

Choose a reason for hiding this comment

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

Actually, I think you could the signature to take a String and just extend that.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

that's nicer indeed. done

@dignifiedquire
Copy link
Contributor

This makes it less likely that the output will be interrupted between the content and the newline

All logging is already to stderr with the content going to stdout, so I am not really convinced this is something we need to be concerned with.

@flub
Copy link
Contributor Author

flub commented Feb 22, 2023

This makes it less likely that the output will be interrupted between the content and the newline

All logging is already to stderr with the content going to stdout, so I am not really convinced this is something we need to be concerned with.

Yes, this is purely user experience: both our logging and tracing logging interact currently. E.g.

[sc]flub@fredriksen ~/n/iroh git (flub/proto-request-id|✔)
> RUST_LOG=iroh=trace cargo run -- provide README.md                                                 1ms
   Compiling iroh v0.2.0 (/home/flub/n0/iroh)
    Finished dev [unoptimized + debuginfo] target(s) in 2.08s
     Running `target/debug/iroh provide README.md`
Reading README.md
Collection: bafkr4icn6xqy7qerkq3q3zpwmvrmdfjkwh5asnw6ghjtijyab3egjo7vwe

- README.md: 1735 bytes

PeerID: qg8jlQMG0f8jWHGhltnKNWs7tR-slUc49n3WQl8uh-s
Auth token: gsCbGh7Mb6M0v-wxQAz6qgv4DavYnybqh8oI3hA2598
All-in-one ticket: IE314Y_AkVQ3DeX2ZWLBlSqx-gk23jHTNCcADshku_WxIKoPI5UDBtH_I1hxoZbZyjVrO7UfrJVHOPZ91kJfLofrAH8AAAHRIoLAmxoezG-jNL_sMUAM-qoL-A2r2J8m6ofKCN4QNuff2023-02-22T15:08:52.799327Z DEBUG iroh::provider:

listening at: 127.0.0.1:4433

Notice how the ticket and the tracing output just run into each other. Some users will not realise where one stops and the other starts. That's what I'm trying to fix. With this fix you get:

All-in-one ticket: IOWSYHkZ263lx89FERoXPawukQdfSmdD2FbzYbbhImIQIJrkCUKHJRMMdN120Z5WyDDng5x7JUqmckIML790Z6ZWAH8AAAHRIjbePF7iYRmzGCuzEypA0HWn9-IZiUOPR20P7Mly5QKn
2023-02-22T16:01:01.768570Z DEBUG iroh::provider:
listening at: 127.0.0.1:4433

Which is a lot better.

@dignifiedquire
Copy link
Contributor

looking at this the ticket and other info should go to stdout I think

@flub
Copy link
Contributor Author

flub commented Feb 23, 2023

I think that's orthogonal though, it still is printed to the same terminal by default so it still can end up mangled in the output without locking or otherwise figuring out how to sequence these writes.

Allocations still depends on how format! allocates
@flub
Copy link
Contributor Author

flub commented Feb 23, 2023

Why do we have this OutWriter struct at all btw? Seems like we should be able to use eprintln!() directly?

@flub flub merged commit 9076443 into main Feb 23, 2023
@flub flub deleted the flub/output-ordering branch February 23, 2023 18:45
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants