std: avoid tearing dbg! prints

[joboet]

Fixes #136703.

This is an alternative to #149859. Instead of formatting everything into a string, this PR makes multi-expression dbg! expand into multiple nested matches, with the final match containing a single eprint!. By using macro recursion and relying on hygiene, this allows naming every bound value in that eprint!.

CC @orlp

r? libs

[orlp]

Neat solution :) I wasn't sure if we could use helper macros.

[rustbot]

Some changes occurred in src/tools/clippy

cc @rust-lang/clippy

[joboet]

I'm not sure whether this is really necessary, I just copied this from above.

[samueltardieu]

I don't think this is needed here. You can probably use match arm.body.kind { and add this extra test line to src/tools/clippy/tests/ui/dbg_macro/dbg_macro.rs (and bless the results with ./x test clippy --bless):

        takes_async_fn(async move |val| { dbg!(val, val + 1); val });
        //~^ dbg_macro

[orlp]

Is it allowed to change those error messages to leak those internal details?

[orlp]

An alternative is to stuff the helper macro into the main macro with some kind of marker that would otherwise never be legal, e.g. starting with the tokens => __internal_recursion:

macro_rules! foo {
    (=> __internal_recursion $x:expr) => {
        // ...
    };
    
    ($x:expr) => {
        foo!(=> __internal_recursion $x);
    };
}

[joboet]

Is it allowed to change those error messages to leak those internal details?

I don't think there's currently a way to tell the compiler to hide them unfortunately. But yes, this is fine, or at least there is precedent – the same happens for thread_local!: If you try

thread_local! {
    #[rustc_align_static(42)]
    static LOCAL: i32 = 42;
}

(playground) on stable, the error message will reference $crate::thread::local_impl::thread_local_inner.

An alternative is to stuff the helper macro into the main macro with some kind of marker that would otherwise never be legal, e.g. starting with the tokens => __internal_recursion:

macro_rules! foo {
    (=> __internal_recursion $x:expr) => {
        // ...
    };
    
    ($x:expr) => {
        foo!(=> __internal_recursion $x);
    };
}

It would be legal to write these tokens in macro invocations in user code, so this would be an even worse leak of implementation details. I'm sure there is a way to abuse #[allow_internal_unstable] to make some macro arms unusable from stable, but I don't think its worth the hassle.

[orlp]

It would be legal to write these tokens in macro invocations in user code, so this would be an even worse leak of implementation details.

It would also be legal to directly write std::macros::dbg_internal!, no? So I don't see how it's better/worse in that regard.

[rustbot]

The Miri subtree was changed

cc @rust-lang/miri

[joboet]

It would be legal to write these tokens in macro invocations in user code, so this would be an even worse leak of implementation details.

It would also be legal to directly write std::macros::dbg_internal!, no? So I don't see how it's better/worse in that regard.

No, since the macro is perma-unstable 😏

[orlp]

How does that work once the macro expands? Does it not expand in the user's context? Or is this just stdlib magic sprinkles?

[joboet]

How does that work once the macro expands? Does it not expand in the user's context? Or is this just stdlib magic sprinkles?

dbg! is marked with #[allow_internal_unstable(std_internals)] which allows dbg_internal! to be used from code generated by the macro (but not in spans passed to the macro) despite it being an unstable feature. We use the same trick for thread_local!, since it too needs to invoke unstable helper macros, which need to use unstable features like #[thread_local] themselves.

Edit: So yes, essentially just stdlib magic sprinkles 😄

[bors]

☔ The latest upstream changes (presumably #150068) made this pull request unmergeable. Please resolve the merge conflicts.

[Mark-Simulacrum]

How does this actually help avoid tearing?

$ cat t.rs
fn main() {
        let a = 1;
        let b = 1;
        eprintln!("a {} b {}", a, b);
}
$ rustc t.rs && strace -o strace.log ./t 2>/dev/null; rg write strace.log
65:write(2, "a ", 2)                       = 2
66:write(2, "1", 1)                        = 1
67:write(2, " b ", 3)                      = 3
68:write(2, "1", 1)                        = 1
69:write(2, "\n", 1)                       = 1

So we should expect this to lower to a series of writes to stderr, i.e., it will in fact tear if there's concurrency. We'd need to add a buffer somewhere to avoid that.

[Mark-Simulacrum]

Ah, I see, we're taking a lock in fmt::Write for Stderr before calling write_fmt.

Should we avoid the matches and just make dbg! expand to write!(std::io::stderr().lock(), ...) then? That seems simpler and achieves the same goal, right? I guess it'd need to inline the capturing (print_to_buffer_if_capture_used)...

[orlp]

@Mark-Simulacrum What would you propose would go in that ...? That's precisely what the recursive matches generate.

[Mark-Simulacrum]

Today, we expand dbg!(a, b, c) to:

    (match a {
            tmp => {
                {
                    ::std::io::_eprint(format_args!("[{0}:{1}:{2}] {3} = {4:#?}\n",
                            "src/main.rs", 2u32, 5u32, "a",
                            &&tmp as &dyn ::std::fmt::Debug));
                };
                tmp
            }
        },
        match b {
            tmp => {
                {
                    ::std::io::_eprint(format_args!("[{0}:{1}:{2}] {3} = {4:#?}\n",
                            "src/main.rs", 2u32, 5u32, "b",
                            &&tmp as &dyn ::std::fmt::Debug));
                };
                tmp
            }
        },
        match c {
            tmp => {
                {
                    ::std::io::_eprint(format_args!("[{0}:{1}:{2}] {3} = {4:#?}\n",
                            "src/main.rs", 2u32, 5u32, "c",
                            &&tmp as &dyn ::std::fmt::Debug));
                };
                tmp
            }
        });

That causes tearing because eprintln! ends up calling global_s().write_fmt(args), which is just std::io::stderr().write_fmt(args), i.e., we take the stderr lock three times.

It seems to me that we ought to be able to ensure unique lock ownership if we added a wrapping:

match std::io::stderr().lock() {
    _guard => {
        // existing desugaring
    }
}

because the stderr lock is re-entrant, so it's fine to take it twice on the same thread (as this would be doing), we just need to prevent other threads from acquiring it while printing our dbg! parts.

I think this seems simpler than the PR's implementation -- at the very least it's less nesting, and presumably no change in diagnostics / error messages? It does mean we don't get this benefit for the libtest output capture, but that seems OK to me, and if we wanted it we could replace locking stderr with a dedicated lock_acquire() function of some kind.

[orlp]

As I mentioned in my original PR this approach leads to deadlocks and is unacceptable. The "we just need to prevent other threads from acquiring it while printing our dbg!" part is impossible. For example when you write dbg!(f()) then f() may block until another thread does some task (e.g. could be as simple and innocent as dbg!("foo", chan.recv())) . And that other task may also call dbg!, at which point you've deadlocked.

[Mark-Simulacrum]

I guess that's true, though that's already the case for the formatting itself (Debug impls using dbg! can lead to deadlocks today), right? In order to avoid it we'd need to serialize to a temporary buffer before writing to stderr (perhaps optionally -- if locking fails -- but still).

That also implies a change in behavior if we land this PR: today dbg!("foo", chan.recv()) prints foo and then waits, whereas with this PR we'd only print foo after both are complete, right? I'm not sure that's an improvement, i.e., it's not obvious that we should fix the issue. Do we have a T-libs-api decision somewhere on what the behavior of multi-expression dbg! should be with regards to concurrency?

[orlp]

Debug impls using dbg! can lead to deadlocks today

Only if the Debug impl causes dbg! to be called on another thread, which is rather unusual, but in theory yes. But I don't think it's a fair comparison at all, the situation you describe is incredibly niche, whereas my example can be trivially caused if for example you use rayon to parallelize some computation you're debugging.

That also implies a change in behavior if we land this PR: today dbg!("foo", chan.recv()) prints foo and then waits, whereas with this PR we'd only print foo after both are complete, right?

Yes. I honestly think the old behavior is more surprising than this new behavior, and trivial to fix if undesirable. On the other hand torn multi-expression dbg! statements can be very confusing, and it is 'impossible' to fix (you can wrap the entire thing in a tuple but that also changes the output, or write your own macro of course which defeats the point of quick debugging).

Do we have a T-libs-api decision somewhere on what the behavior of multi-expression dbg! should be with regards to concurrency?

Not that I'm aware of. You can nominate the issue if you feel this change is controversial.