tracing::span! missing fields

[immno]

Bug Report

When I used the salvo web framework, I found that the logs were always missing. Through debugging, I found that it was not a salvo problem, but a tracing problem.

#[derive(Debug)]
pub struct TraceLogger;

#[async_trait::async_trait]
impl Handler for TraceLogger {
    async fn handle(&self, req: &mut Request, depot: &mut Depot, res: &mut Response, ctrl: &mut FlowCtrl) {
        let trace = Uuid::new_v4().as_simple().to_string();
        let traces = trace.clone();
        let span = tracing::span!(Level::INFO, "", %trace);
        depot.insert(REQUEST_ID_NAME, trace);

        let url = format!("{}{}", req.remote_addr(), req.uri().path());

        async move {
            let now = Instant::now();
            ctrl.call_next(req, depot, res).await;
            let duration = now.elapsed();

            let span = Span::current().clone();
            let n = span.is_none();
            let d = span.is_disabled();
            let f = span.has_field("trace");
            tracing::info!(url = %url, duration = ?duration, traces2 = traces, n = n, d = d, f = f);
        }
            .instrument(span)
            .await
    }
}

But printing logs sometimes loses trace=xxx information:

2024-05-12 12:06:30.636  INFO  main-5 url=socket://127.0.0.1:65534/doc.html duration=75.1µs traces2="d7b3aefd3891488eb3d222cb69ab87e6" n=false d=false f=true
2024-05-12 12:06:30.955  INFO  main-0 url=socket://127.0.0.1:65534/openapi-doc/api-reference.js duration=234.7598ms traces2="183708168def40e286b5e7866836e31c" n=false d=false f=true
2024-05-12 12:06:31.219  INFO  main-0 {trace=9b15f21ad56e4dfbb03685a94d61a53f}: url=socket://127.0.0.1:65534/server-api-doc/openapi.json duration=6.4085ms traces2="9b15f21ad56e4dfbb03685a94d61a53f" n=false d=false f=true
2024-05-12 12:06:34.296  INFO  main-4 {trace=330a8fe4905f46838cc0d3115630a325}: url=socket://127.0.0.1:65534/doc.html duration=35.3µs traces2="330a8fe4905f46838cc0d3115630a325" n=false d=false f=true
2024-05-12 12:06:34.547  INFO  main-4 {trace=0b99a33afcc6400db2d3f50d331a4c0e}: url=socket://127.0.0.1:65534/openapi-doc/api-reference.js duration=227.3619ms traces2="0b99a33afcc6400db2d3f50d331a4c0e" n=false d=false f=true
2024-05-12 12:06:34.939  INFO  main-3 url=socket://127.0.0.1:65534/server-api-doc/openapi.json duration=5.8706ms traces2="de720b6275494edd9889ba4495862b83" n=false d=false f=true
2024-05-12 12:06:41.228  INFO  main-5 {trace=751b6400f3744662b42a64fb27e46fe2}: url=socket://127.0.0.1:65534/doc.html duration=39.1µs traces2="751b6400f3744662b42a64fb27e46fe2" n=false d=false f=true
2024-05-12 12:06:41.487  INFO  main-5 {trace=5a84b641d58a42339f8b2c5be562cb8b}: url=socket://127.0.0.1:65534/openapi-doc/api-reference.js duration=228.3182ms traces2="5a84b641d58a42339f8b2c5be562cb8b" n=false d=false f=true
2024-05-12 12:06:41.749  INFO  main-0 {trace=e1e5c09570dd4f5bad1b33f0f0907958}: url=socket://127.0.0.1:65534/server-api-doc/openapi.json duration=6.1977ms traces2="e1e5c09570dd4f5bad1b33f0f0907958" n=false d=false f=true
2024-05-12 12:06:44.040  INFO  main-1 url=socket://127.0.0.1:65534/doc.html duration=33.7µs traces2="15618ecc58aa48cda5646da18da3408b" n=false d=false f=true
2024-05-12 12:06:44.285  INFO  main-1 {trace=3a71bf30498c439d847e6a936e333435}: url=socket://127.0.0.1:65534/openapi-doc/api-reference.js duration=222.4668ms traces2="3a71bf30498c439d847e6a936e333435" n=false d=false f=true
2024-05-12 12:06:44.541  INFO  main-3 {trace=c18677ea66db4134b9859c59d778ca98}: url=socket://127.0.0.1:65534/server-api-doc/openapi.json duration=6.2009ms traces2="c18677ea66db4134b9859c59d778ca98" n=false d=false f=true
2024-05-12 12:06:46.787  INFO  main-3 {trace=7597a6535d7643a4ba5b05ef870ac010}: url=socket://127.0.0.1:65534/doc.html duration=40.7µs traces2="7597a6535d7643a4ba5b05ef870ac010" n=false d=false f=true
2024-05-12 12:06:47.044  INFO  main-5 {trace=699c0939653846e997c85f5be4ea6965}: url=socket://127.0.0.1:65534/openapi-doc/api-reference.js duration=231.4573ms traces2="699c0939653846e997c85f5be4ea6965" n=false d=false f=true
2024-05-12 12:06:47.415  INFO  main-3 {trace=a6a0f65841444639b8ce5d3dd9615f98}: url=socket://127.0.0.1:65534/server-api-doc/openapi.json duration=6.3899ms traces2="a6a0f65841444639b8ce5d3dd9615f98" n=false d=false f=true
2024-05-12 12:06:52.234  INFO  main-1 {trace=23998bc1b1ab48edab33fc5e396646ce}: url=socket://127.0.0.1:65534/doc.html duration=34.3µs traces2="23998bc1b1ab48edab33fc5e396646ce" n=false d=false f=true
2024-05-12 12:06:52.481  INFO  main-1 {trace=4a3afcf28eb24c09a3ce7350acbe19aa}: url=socket://127.0.0.1:65534/openapi-doc/api-reference.js duration=221.2977ms traces2="4a3afcf28eb24c09a3ce7350acbe19aa" n=false d=false f=true
2024-05-12 12:06:52.745  INFO  main-5 {trace=dd6b9a77eefb4956a3fc1e3f82dea0fb}: url=socket://127.0.0.1:65534/server-api-doc/openapi.json duration=5.739ms traces2="dd6b9a77eefb4956a3fc1e3f82dea0fb" n=false d=false f=true
2024-05-12 12:06:55.107  INFO  main-4 {trace=c92ccdf5fa2045a4a7afa3c0fca3ef2a}: url=socket://127.0.0.1:65534/doc.html duration=58.6µs traces2="c92ccdf5fa2045a4a7afa3c0fca3ef2a" n=false d=false f=true
2024-05-12 12:06:55.357  INFO  main-4 {trace=f1c43281609545f79760e38db348cbaa}: url=socket://127.0.0.1:65534/openapi-doc/api-reference.js duration=226.6668ms traces2="f1c43281609545f79760e38db348cbaa" n=false d=false f=true
2024-05-12 12:06:55.627  INFO  main-0 {trace=ae6f436f284a4cb88965d7ca975f38f6}: url=socket://127.0.0.1:65534/server-api-doc/openapi.json duration=5.6639ms traces2="ae6f436f284a4cb88965d7ca975f38f6" n=false d=false f=true

I can't understand why it happens.

Version

mno@DESKTOP-A7EFBS7 MINGW64 /d/RustroverProjects/tagflow-rs/tagflow-application (master)
$ cargo tree | grep tracing
│       └── 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 v0.1.40 (*)
│   │   └── tracing v0.1.40 (*)
│   │   ├── tracing v0.1.40 (*)
│   │   └── tracing v0.1.40 (*)
│   │   │   │   ├── tracing v0.1.40 (*)
│   │   │   │   │   │   ├── tracing v0.1.40 (*)
│   │   │       ├── tracing v0.1.40 (*)
│   ├── tracing v0.1.40 (*)
│   │   │   │       │   │   └── tracing v0.1.40 (*)
│   │   │   │       ├── tracing v0.1.40 (*)
│   │   │   │       └── tracing-futures v0.2.5
│   │   │   │           └── tracing v0.1.40 (*)
│   │       └── tracing v0.1.40 (*)
│   │   ├── tracing v0.1.40 (*)
│   ├── tracing v0.1.40 (*)
│   ├── tracing-test v0.2.4
│   │   ├── 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-core v0.1.32 (*)
│   │   └── tracing-test-macro v0.2.4 (proc-macro)
│   │   ├── tracing v0.1.40 (*)
│   │   ├── tracing-subscriber v0.3.18 (*)
│   └── tracing v0.1.40 (*)
├── tracing v0.1.40 (*)
├── tracing-appender v0.2.3
│   └── tracing-subscriber v0.3.18 (*)
├── tracing-subscriber v0.3.18 (*)
├── tracing-test v0.2.4 (*)

Platform

My local development environment (Windows 10: 19045.4291) will also appear, and online (Linux 3.10.0-1160.76.1.el7.x86_64 #1 SMP Wed Aug 10 16:21:17 UTC 2022 x86_64 GNU/Linux) will also appear.

Description

Already mentioned above.

[immno]

I have been troubleshooting this issue until now. We used the tokio-cron-scheduler crate, which caused this problem. After we removed tokio-cron-scheduler, it finally worked properly without omissions and misalignment. Thanks to tracing, it works great!