Adding parent span id to tracing json in Rust

Cargo.toml

[package]
name = "foo"
edition = "2021"
version = "0.1.0"
authors = ["Steve Vermeulen <sfvermeulen@gmail.com>"]

# See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html

[dependencies]
tracing = "0.1.40"
tracing-subscriber = {version = "0.3.18", features = ["env-filter"]}
backtrace = "0.3.69"
serde_json = "1.0.108"

LICENSE

MIT License

Copyright (c) 2024 Steve Vermeulen

Permission is hereby granted, free of charge, to any person obtaining a copy
of this software and associated documentation files (the "Software"), to deal
in the Software without restriction, including without limitation the rights
to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
copies of the Software, and to permit persons to whom the Software is
furnished to do so, subject to the following conditions:

The above copyright notice and this permission notice shall be included in all
copies or substantial portions of the Software.

THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
SOFTWARE.

main.rs

use serde_json::{json, Value};
use std::{
    collections::HashMap,
    sync::Mutex,
    thread,
    time::{Duration, SystemTime, UNIX_EPOCH}, fs::{OpenOptions, File}, io::LineWriter
};
use tracing::{
    field::{Field, Visit},
    span::Id,
    Event, Level, Metadata, Subscriber,
};
use tracing_subscriber::{layer::Context, prelude::*, registry::LookupSpan, EnvFilter, Layer};
use std::io::Write;

#[macro_use]
extern crate tracing;

struct JsonVisitor {
    pub fields: HashMap<String, Value>,
}

impl JsonVisitor {
    fn new() -> Self {
        JsonVisitor {
            fields: HashMap::new(),
        }
    }
}

impl Visit for JsonVisitor {
    fn record_i64(&mut self, field: &Field, value: i64) {
        self.fields.insert(field.name().to_string(), json!(value));
    }

    fn record_u64(&mut self, field: &Field, value: u64) {
        self.fields.insert(field.name().to_string(), json!(value));
    }

    fn record_str(&mut self, field: &Field, value: &str) {
        self.fields.insert(field.name().to_string(), json!(value));
    }

    fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) {
        self.fields
            .insert(field.name().to_string(), json!(format!("{:?}", value)));
    }
}

fn get_unix_timestamp() -> u128 {
    SystemTime::now()
        .duration_since(UNIX_EPOCH)
        .unwrap()
        .as_millis()
}

struct SpanInfo {
    start_time: SystemTime,
}

impl SpanInfo {
    pub fn new(start_time: SystemTime) -> Self {
        Self { start_time }
    }
}

struct CustomLayer {
    span_infos: Mutex<HashMap<u64, SpanInfo>>,
    log_file: Mutex<LineWriter<File>>,
}

fn add_common_metadata(fields: &mut HashMap<String, Value>, metadata: &Metadata<'_>) {
    fields.insert("timestamp".to_string(), json!(get_unix_timestamp()));
    fields.insert("target".to_string(), json!(metadata.target()));
    fields.insert("level".to_string(), json!(metadata.level().to_string()));

    let file = metadata.file();
    let line = metadata.line();

    if file.is_some() || line.is_some() {
        let mut source_fields = HashMap::new();

        if let Some(file) = metadata.file() {
            source_fields.insert("file".to_string(), json!(file));
        }

        if let Some(line) = metadata.line() {
            source_fields.insert("line".to_string(), json!(line));
        }

        fields.insert("source".to_string(), json!(source_fields));
    }
}

impl CustomLayer {
    fn new() -> Self {
        let file = OpenOptions::new()
            .write(true)      // Allow writing to the file
            .create(true)     // Create the file if it does not exist
            .truncate(true)   // Truncate the file if it already exists
            .open("log.json")
            .expect("Unable to open log file");

        CustomLayer {
            span_infos: Mutex::new(HashMap::new()),
            log_file: Mutex::new(LineWriter::new(file)),
        }
    }

    fn output_trace_entry(&self, fields: &HashMap<String, Value>) {
        let Ok(log_line) = serde_json::to_string(fields) else { return; };

        let mut log_file = self.log_file.lock().unwrap();
        let _ = writeln!(*log_file, "{log_line}");
    }
}

impl<S> Layer<S> for CustomLayer
where
    S: Subscriber + for<'a> LookupSpan<'a>,
{
    fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) {
        let span_id = if let Some(span) = ctx.lookup_current() {
            span.id().into_u64()
        } else {
            0 // No current span
        };

        let mut visitor = JsonVisitor::new();
        event.record(&mut visitor);

        let metadata = event.metadata();
        add_common_metadata(&mut visitor.fields, metadata);
        visitor.fields.insert("span_id".to_string(), json!(span_id));

        self.output_trace_entry(&visitor.fields);
    }

    fn on_new_span(&self, attrs: &tracing::span::Attributes<'_>, id: &Id, ctx: Context<'_, S>) {
        let Some(span_ref) = ctx.span(id) else {
            return;
        };

        self.span_infos
            .lock()
            .unwrap()
            .insert(id.into_u64(), SpanInfo::new(SystemTime::now()));

        let mut visitor = JsonVisitor::new();
        attrs.record(&mut visitor);

        let metadata = span_ref.metadata();
        add_common_metadata(&mut visitor.fields, metadata);

        let span_id = span_ref.id().into_u64();
        visitor.fields.insert("span_id".to_string(), json!(span_id));
        visitor
            .fields
            .insert("span_name".to_string(), json!(metadata.name()));
        visitor
            .fields
            .insert("span_event".to_string(), json!("span_open".to_string()));

        let parent_span_id = span_ref.parent().map_or(0, |p| p.id().into_u64());
        visitor
            .fields
            .insert("parent_span_id".to_string(), json!(parent_span_id));

        self.output_trace_entry(&visitor.fields);
    }

    fn on_close(&self, id: Id, ctx: Context<'_, S>) {
        let Some(span_ref) = ctx.span(&id) else {
            return;
        };

        let span_id = span_ref.id().into_u64();

        let start_time = {
            let mut span_infos = self.span_infos.lock().unwrap();
            let info = span_infos.remove(&span_id).unwrap();
            info.start_time
        };

        let metadata = span_ref.metadata();

        let mut fields = HashMap::new();
        add_common_metadata(&mut fields, metadata);

        fields.insert("span_id".to_string(), json!(span_id));
        fields.insert("span_event".to_string(), json!("span_close".to_string()));

        let duration = start_time.elapsed().unwrap_or(Duration::from_secs(0));
        fields.insert("span_duration_ms".to_string(), json!(duration.as_millis()));

        self.output_trace_entry(&fields);
    }
}

fn main() {
    let subscriber = tracing_subscriber::registry()
        .with(EnvFilter::new("debug"))
        .with(CustomLayer::new());

    tracing::subscriber::set_global_default(subscriber).expect("Setting default subscriber failed");

    tracing::info!("entry point");

    let root_span = span!(Level::INFO, "root_span", qux = 42);
    let _enter = root_span.enter();

    tracing::info!("starting up");
    thread::sleep(Duration::from_millis(10));

    {
        let child_span = span!(Level::INFO, "child_span");
        let _child_enter = child_span.enter();
        tracing::info!(line = 19, "This is a test log message.");
        thread::sleep(Duration::from_millis(20));

        {
            let child_span = span!(Level::INFO, "another_child_span");
            let _child_enter = child_span.enter();
            thread::sleep(Duration::from_millis(30));
            tracing::info!("another log");
        }
    }

    tracing::info!("program complete");
}

This is some sample code showing how to change the rust tracing crate to output parent span information