Potential deadlock when using `console_subscriber` about console HOT 10 CLOSED

Hmmm, interesting. I notice that your code is creating its own tokio::task span, in addition to the span generated by tokio::spawn itself when RUSTFLAGS="--cfg tokio_unstable" is set...are you also setting that cfg? it's possible that having two task spans is breaking something, although that seems somewhat surprising...

from console.

Yes, this was really just to capture all the diagnostics in the same place – I'll try changing the target and see if that helps. The tokio_unstable flag is set when running this, so there will be two tokio::task spans at once.

from console.

After removing that target, I can't seem to get any of the spans to get captured by the subscriber (or at least, they don't appear in the console view). Am I chasing the wrong use-case by trying to capture spans outside of tokio internals?

from console.

After removing that target, I can't seem to get any of the spans to get captured by the subscriber (or at least, they don't appear in the console view).

Yeah, that part is expected --- but, if you set the level filter to tokio=trace, with your span disabled, do you still see the deadlock?

Am I chasing the wrong use-case by trying to capture spans outside of tokio internals?

Right now, the console has only been tested using tokio's internal instrumentation as the source for task spans, but the goal for the future is definitely to support consuming task spans from other sources as well. However, this isn't something we've put much work into supporting yet.

Currently, the TasksLayer type only cares about a single metadata callsite for task spans, and it will simply decide to track whatever the first metadata it sees with the target tokio::task and the name task:

We could probably change this behavior and allow multiple span callsites to be tracked as tasks --- we could track any callsite with the tokio::task target, for example. This would allow spans in user code or from other executors to be tracked...and would simplify the code for tracking tasks from both tokio::spawn and tokio::spawn_blocking. However, we would probably want some way to ensure that if you spawn a future with a user-defined tokio::task span, and then tokio adds its own tokio::task span to the spawned future, we don't treat those as two separate tasks...

Regardless, I'm very surprised this is causing an apparent deadlock --- I can't really immediately imagine why that would happen.

from console.

Ah, thanks for talking through that. I've taken a look into the code and thought that was the case, but I'm not quite familiar enough with tracing or spans to have really grasped it on first glance...I suppose it would all be much easier if we didn't spawn all our tasks on the same line, since the only real need for us to use another span is to be able to record the caller location in the fields.

I have just tried changing the filter back to tokio=trace and disabling the instrumentation, and the deadlock still seems to be there, unfortunately – sitting completely still at 0% CPU usage. It's only when not constructing the TasksLayer that it seems to go away...

from console.

I observe the same total freez and CPU at 0% when trying latest main branch of console on http://github.com/njasm/blunt on the echo or chat examples. (tested on the trait_redo branch)

As soon as I start to open connections to any of the examples the program just stops responding (not even accepting more connections. I've notice it cos i'm locally running artillery to load test the library

EDIT:

• I did commented out all Instrument attribute #[tracing::instrument(...)] found in 4 or 5 methods on that branch.
• Also the two calls to tracing future intrument method (.instrument(trace_span!("..."))) found https://github.com/njasm/blunt/blob/7c30881a6919f382e39a922c843a7d95da68c145/src/websocket.rs#L63 and here https://github.com/njasm/blunt/blob/7c30881a6919f382e39a922c843a7d95da68c145/src/websocket.rs#L82

And the deadlock still occurred.

code used to register console_subscriber (compiled with RUSTFLAGS=--cfg tokio_unstable)

    let filter = EnvFilter::from_default_env()
        .add_directive("tokio=trace".parse().unwrap());

    let (console, server) = console_subscriber::TasksLayer::builder()
        .with_default_env()
        .build();

    use tracing_subscriber::layer::SubscriberExt;
    use tracing_subscriber::util::SubscriberInitExt;
    tracing_subscriber::registry()
        .with(filter)
        .with(console)
        .init();

    tokio::task::spawn(server.serve());
`

from console.

@njasm hmm, thanks for the report! out of interest, what happens if the console server task is spawned on a separate tokio runtime, in the background?

from console.

@hawkw If I understand you correctly, I've change the code to this.

    //tokio::task::spawn(server.serve());

    let _handle = std::thread::spawn(move || {
        let rt = tokio::runtime::Builder::new_multi_thread()
            .enable_all()
            .build()
            .unwrap();
        rt.block_on(server.serve())
    });

and it also deadlocks. With the single threaded runtime too. (Builder::new_current_thread())

If I miss understood your question feel free to provide me with the code snippet you want to try it out.

from console.

Okay @njasm and @Adam-Gleave, I believe #95 should fix this. Let me know if you still see issues with the latest version from main?

from console.

@hawkw regarding the reported deadlock, I don't see it anymore with latest main. Its fixed for me!

thanks!

from console.