Can't seem to intercept tracing - ends up in global default instead of overridden subscriber

[vlovich]

xitca is an internal implementation detail within my library and I want to redirect its logs to my own tracing subscriber. So in my app I have something like:

#[tokio::main]
async fn main() {
   tracing_subscriber::register().with(tracing_subscriber::fmt::layer()).init();
   let lib_handle = my_lib::init().await.unwrap();
   tokio::signal::ctrl_c().await().unwrap();
}

In my my_lib::init() fn I have something that simplifies to:

async fn init() -> Result<Handle> {
    let dispatcher = Dispatch::new(tracing_subscriber::Register::default().with(tracing_subscriber::filter::LevelFilter::OFF));
    std::thread::spawn(move || {
        tracing::dispatcher::with_default(&dispatcher, move || {
            let rt= tokio::runtime::Builder::new()
                .on_thread_start(move || /*TRACE_TLS_GUARD = tracing::dispatcher::set_default(&dispatcher)*/)
                .on_thread_stop(move ||  */TRACE_TLS_GUARD.reset() */)
           }),enable_all().build();
           let run_app_server = async move {
               tokio::App::new()./*...*/.listen(...).unwrap().run().with_subscriber(dispatcher.clone()).await.unwrap();
           };
           rt.block_on(run_app_server).unwrap();
   });
}

However when I run my executable, I get messages like:

2025-01-29T00:36:34.536074Z  INFO xitca_server::net: Started Tcp listening on: Some(127.0.0.1:8000)
API ready on http://127.0.0.1:8000
2025-01-29T00:36:34.537768Z  INFO xitca_server::worker: Started xitca-server-worker-0
2025-01-29T00:36:34.538002Z  INFO xitca_server::worker: Started xitca-server-worker-1

Obviously my goal isn't to actually turn off the messages. I want them to be silently redirected to my logging endpoint instead rather than bubbling all the way up. I'm just using the "off" as a simple way to verify my subscriber is the one receiving the messages instead of the global default. Any tips on what I'm doing wrong would be appreciated.

Apologies if the example code contains typos - I was trying to reduce it to the smallest possible example without having to build an entirely new working project.

[fakeshadow]

From what I see xitca-server is using your subscriber already. It does not spawn any subscriber on it's own and tracing-subscriber
is not even a dependency of it.

I guess what you want is to move xitca-server's log into your tracing span like:
INFO your_app: xitca_server::net: event
This is usually achieved through span and instrument macros where you can find referencing doc here:
https://docs.rs/tracing/latest/tracing/#spans

That said it's still not as easy as just set up a span. xitca-server is an application spawning it's own threads and runtimes where the context of your span is neither known nor accessible. I'll see what I can do to improve the span handling between server thread boundary but for now it would be better if you customize your subscriber filter event from xitca-server and add a manual span before it.

[vlovich]

I don't think it's using my subscriber because traces within my subscriber don't go to stdout. Only the global default subscriber is set to redirect to stdout.

It feels like there's a manual thread (or maybe even multiple) being spawned somewhere (ie outside tokio) and if so that would be the problem because the default subscriber takes over and I'd need hooks similar to tokio runtime where I get notified of thread start and stop (or alternatively can inject a hook that is given the body of the thread to run within a scope). This would make sense since a bunch of threads are named after xitca.

I don't think it's an issue around scope/instrument macros which I believe simply relate traces together vs change where they're sent.

[joelwurtz]

The server create a specific runtime to spawn worker thread, that's certainly why it goes to the default global subscriber instead of your own,

However there is a on_worker_start method in builder that allows you to run custom code when xitca creates its worker thread https://github.com/HFQR/xitca-web/blob/main/server/src/builder.rs#L119

Maybe you can set your specific subscriber there.

[vlovich]

Nope, installing a subscriber doesn't seem to do anything to the output. I don't think it's the worker threads. I think the logs are coming from a thread that xitca is spawning to do the main work. I put a log message when I install the thread local storage. As you can see on_worker_start is working as expected. However you can see "Got INFO log from xitca at default subscriber" is followed by "xitca_server::net: Started Tcp listening" which indicates that that message is from some other thread. A similar effect is observed for

xitca_server::worker: Started xitca-server-worker-0
xitca_server::worker: Started xitca-server-worker-1
xitca_server::server::future: Signal Int received
xitca_server::worker::shutdown: Graceful stopped xitca-server-worker-0
xitca_server::worker::shutdown: Graceful stopped xitca-server-worker-1

Here's the full log from my test case

MY_APP: Installed thread-local subscriber in Some("tokio-runtime-worker") (thread ThreadId(36))
MY_APP: Installed thread-local subscriber in Some("tokio-runtime-worker") (thread ThreadId(37))
MY_APP: Installed thread-local subscriber in Some("tokio-runtime-worker") (thread ThreadId(38))
<snip>
MY_APP: Installed thread-local subscriber in Some("tokio-runtime-worker") (thread ThreadId(64))
MY_APP: Installed thread-local subscriber in Some("tokio-runtime-worker") (thread ThreadId(65))
MY_APP: Installed thread-local subscriber in Some("tokio-runtime-worker") (thread ThreadId(66))
MY_APP: Installed thread-local subscriber in Some("tokio-runtime-worker") (thread ThreadId(67))
MY_APP: Got INFO log from xitca at DEFAULT SUBSCRIBER
2025-01-30T20:14:06.086935Z  INFO xitca_server::net: Started Tcp listening on: Some(127.0.0.1:8000)
MY_APP: Installed thread-local subscriber in Some("xitca-server-worker-0") (thread ThreadId(71))
MY_APP: Installed thread-local subscriber in Some("xitca-server-worker-1") (thread ThreadId(72))
Got INFO log from xitca at default subscriber
2025-01-30T20:14:06.088850Z  INFO xitca_server::worker: Started xitca-server-worker-0
2025-01-30T20:14:06.089142Z  INFO xitca_server::worker: Started xitca-server-worker-1
^CGot INFO log from xitca at DEFAULT SUBSCRIBER
2025-01-30T20:14:22.453955Z  INFO xitca_server::server::future: Signal Int received.
Got INFO log from xitca at DEFAULT SUBSCRIBER
Got INFO log from xitca at DEFAULT SUBSCRIBER
2025-01-30T20:14:22.454720Z  INFO xitca_server::worker::shutdown: Graceful stopped xitca-server-worker-0
2025-01-30T20:14:22.454753Z  INFO xitca_server::worker::shutdown: Graceful stopped xitca-server-worker-1

[vlovich]

The problem is this line:

        let listeners = thread::scope(|s| s.spawn(|| rt.block_on(fut)).join()).unwrap()?;

There's no mechanism to intercept that. Maybe I can hack it by giving a custom AsListener to .listen that installs the subscriber before giving back a listener.

[fakeshadow]

Interesting. Would removing the scoped thread make thing work?

[vlovich]

Not sure. I would think so but I also took a stab at plumbing through a bunch of callbacks that would let me install the span and that didn't seem to work (didn't debug it too thoroughly so not sure)

[fakeshadow]

I would look into how the scope thread can be removed so tokio's call track won't be broken by it.