Not working with spawn_blocking() tasks

[op8867555]

Bug Report

Version

tracing-otlp-mre v0.1.0
│   │       │   │   │   │   └── tracing v0.1.40
│   │       │   │   │   │       ├── tracing-attributes v0.1.27 (proc-macro)
│   │       │   │   │   │       └── tracing-core v0.1.32
│   │       │   │   │   └── tracing v0.1.40 (*)
│   │       │   │   ├── tracing v0.1.40 (*)
│   │       │   │   └── tracing v0.1.40 (*)
│   │       └── tracing v0.1.40 (*)
├── tracing v0.1.40 (*)
├── tracing-opentelemetry v0.23.0
│   ├── tracing v0.1.40 (*)
│   ├── tracing-core v0.1.32 (*)
│   ├── tracing-log v0.2.0
│   │   └── tracing-core v0.1.32 (*)
│   └── tracing-subscriber v0.3.18
│       ├── tracing v0.1.40 (*)
│       ├── tracing-core v0.1.32 (*)
│       └── tracing-log v0.2.0 (*)
└── tracing-subscriber v0.3.18 (*)

[dependencies]
tokio = { version = "1.37", features = ["full"] }
opentelemetry = "0.22"
opentelemetry_sdk = { version = "0.22", features = ["rt-tokio"]}
opentelemetry-otlp = { version = "0.15.0", features = ["grpc-tonic"]}
tracing = "0.1"
tracing-opentelemetry = "0.23"
tracing-subscriber = {version = "0.3", features = ["env-filter"]}

Platform

Linux x1c5galexlu 6.8.2-arch2-1 #1 SMP PREEMPT_DYNAMIC Thu, 28 Mar 2024 17:06:35 +0000 x86_64 GNU/Linux

Description

I tried this code:

use opentelemetry_sdk::runtime;
use tracing_opentelemetry::OpenTelemetryLayer;
use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt};

#[tokio::main]
async fn main() {
    let tracer = opentelemetry_otlp::new_pipeline()
        .tracing()
        .with_exporter(opentelemetry_otlp::new_exporter().tonic())
        .install_batch(runtime::Tokio)
        .unwrap();
    let telemetry = OpenTelemetryLayer::new(tracer);

    tracing_subscriber::registry()
        .with(telemetry)
        .with(tracing_subscriber::fmt::layer())
        .with(tracing_subscriber::EnvFilter::from_default_env())
        .init();

    tracing::info!("start");
    tokio::task::spawn_blocking(test).await.unwrap();
    opentelemetry::global::shutdown_tracer_provider();

}

#[tracing::instrument]
fn test() {
    tracing::info!("start");
    loop {
        std::thread::sleep(std::time::Duration::from_secs(5));
        tracing::info!("test")
    }
}

I expected to see this happen:

• traces info should be send to otel-collector
• with RUST_LOG=trace, there should be some h2/tonic logs
  But none of them happens, it only output my application logs:

2024-04-25T05:36:06.781995Z  INFO tracing_otlp_mre: start
2024-04-25T05:36:06.782370Z  INFO test: tracing_otlp_mre: start
2024-04-25T05:36:11.782632Z  INFO test: tracing_otlp_mre: test

[mladedav]

Your span never finishes so it can never be sent. Try creating a spans inside the loop.

[op8867555]

Sorry I didn't make it clear, I'm actually doing a busy loop:

#[tracing::instrument]
fn test() {
   loop {
       read();
   }
}
#[tracing::instrument]
fn read() {
   while ptr.read_volatile() == 0 {}
   info!("some log")
}

[mladedav]

And when you try with spawm instead of spawn_blocking, then it works?

I'll try to take a look when I have some time, just trying to rule out as much as possible beforehand.

[op8867555]

Just tried that, It seems the issue happens with spawn as well.

[xuxiaocheng0201]

spawn:

use tracing::Instrument;
tokio::spawn(async {
      // something
}.in_current_span())

spawn_blocking:

#[allow(unused_mut)]
let mut block = ; // something
let span = tracing::span::Span::current();
tokio::task::spawn_blocking(move || {
      let _enter = span.enter();
      block()
})