Logging and panics can interleave on same line in output about materialize

[guswynn]

I need to think about how best to handle this; the default hook writes to stderr, and is fairly complex (it has to handle things like capturing output in tests and what not, and double-panics); recreating it with tracing is probably impossible, but we may be able to instead use a simpler version as long as we do not use it in tests...

[guswynn]

For posterity, when I get to this, there IS a way to check if there is a no (global or thread-local) subscriber, but its slightly weird:

fn main() {
    eprintln!("before setting:");
    tracing::dispatcher::get_default(|d| {
        assert!(dbg!(d.is::<tracing::subscriber::NoSubscriber>()));
    });

    tracing_subscriber::fmt().init();

    eprintln!("after setting:");
    tracing::dispatcher::get_default(|d| {
        assert!(!dbg!(d.is::<tracing::subscriber::NoSubscriber>()));
    });
}

[guswynn]

@def- I thought about this quite a bit, and did some research, and I am convinced there is no satisfying way to fix this:

Logs (through tracing) and the panic message both currently write to stderr. To prevent interleaving, the panic handle specifically must lock it (https://doc.rust-lang.org/std/io/struct.Stderr.html#method.lock). It is insufficient for tracing to lock stderr (it currently doesn't, but a vast majority of messages are single-line so we dont see problems), as the panic handler itself is the one buffering lines into stderr.

We could write our own panic handler that DOES lock stderr, but there are 2 reasons not too:

• the default panic handler (the one that currently prints out panics) has an immense number of features that we cannot replicate as we don't have nightly features (things like, capturing output for tests, the exact semantics of backtrace formatting, etc). We could make it so we override this handler only in mzcompose/zippy tests so that we lock stderr, but:
• rust-lang/rust#96706 suggests that locking stderr as part of panic handling comes with the risk of deadlock; its unclear to me how this occurs, but its makes me quite scared

I think the only feasible alternative we have is having logging go to stdout in mzcompose (a bit against our philosophy, I know: https://materializeinc.slack.com/archives/C0246GEHL8N/p1704759822272049), and have the error-checking software check the fd's separately. However, my understanding is that docker does NOT make this easy, especially if we want stdout and stderr in one log file in buildkite?

[def-]

Yes, this is quite annoying indeed. I don't see a good solution either.

[def-]

Actually, how about we make a custom panic handler and just print the panic on one line again like it used to be? That would at least be easy.

[guswynn]

@def- as in before: https://blog.rust-lang.org/2023/10/05/Rust-1.73.0.html#cleaner-panic-messages

we can do that, but we will have to copy/recreate the backtrace printing that the default panic handler does

[def-]

Yes. But actually it doesn't solve the problem fully since we can have interleaving even on the same line still I guess. Somehow we didn't have this issue before Rust 1.73.0 (or I never noticed)

[guswynn]

@def- perhaps we were just getting lucky? I do think that logging to stdout and tee-ing stderr and stdout to files for ci to inspect...but also i think this is pretty annoying to do: docker/compose#8098