How to extract message from tracing `Event`, in custom impl of `Layer` trait

help
1
Here's my code: 
use colored::*;
use tracing::error;
use tracing::event;
use tracing::level_filters::LevelFilter;
use tracing::Level;
use tracing::Subscriber;
use tracing_subscriber::fmt;
use tracing_subscriber::layer::Layer;
use tracing_subscriber::prelude::*;
use tracing_subscriber::EnvFilter;

fn main() {
    tracing_configuration();
    error!("table");
    println!("tower");
}

pub fn tracing_configuration() {
    tracing_subscriber::registry()
        .with(fmt::layer().without_time())
        .with(CustomLayer {})
        .with(
            EnvFilter::builder()
                .with_default_directive(LevelFilter::INFO.into())
                .from_env()
                .unwrap_or(EnvFilter::from_default_env()),
        )
        .init();
}
#[derive(Clone, Debug, Default)]
pub struct CustomLayer {}

impl<S> Layer<S> for CustomLayer
where
    S: Subscriber,
{
    fn on_event(&self, event: &event::Event<'_>, ctx: tracing_subscriber::layer::Context<'_, S>) {
        let metadata = event.metadata();
        let file = metadata.file().unwrap();
        let formatted_file = file.replace('/', "::").replace("src::", "");
        let trimmed_file = formatted_file.trim_end_matches(".rs");

        let line = metadata.line().unwrap().to_string();
        let level = metadata.level();

        if *level == Level::ERROR {
            println!(
                "{} {}{} {}{}",
                "ERROR".red(),
                trimmed_file.black(),
                ":".black(),
                line.black(),
                ": ".black(),
            );
        }

        dbg!(&event);
        let callsite = event.fields().map(|field| field.callsite());
        dbg!(&callsite);
        let name = event.fields().map(|field| field.name());
        dbg!(&name);
        let metadata = event.metadata();
        dbg!(&metadata);
        let parent = event.parent();
        dbg!(&parent);

        panic!();
    }
}
`event` contains the following: 
[src/main.rs:57:9] &event = Event {
    fields: ValueSet {
        message: table,
        callsite: Identifier(0x633812807010),
    },
    metadata: Metadata {
        name: "event src/main.rs:14",
        target: "nice",
        level: Level(
            Error,
        ),
        module_path: "nice",
        location: src/main.rs:14,
        fields: {message},
        callsite: Identifier(0x633812807010),
        kind: Kind(EVENT),
    },
    parent: Current,
}

I'm trying to get the message (in this case "table") from the event. I tried all the methods I could find on the Event, but each of them seems to exclude the message I'm trying to get. How do I extract the message (in this case "table") into a variable?

2

What output does this show? You're printing an iterator that has not been iterated, so you're probably just getting a debug string describing the iterator, not the values in the iterator. To get the values and print them, collect them into a vec or at least call next on the iterator to get the first value.

3

I collected all the iters to a vec, and here is the full debug output in the CLI:

dbg!() output in CLI 
[src/main.rs:58:9] &event = Event {
    fields: ValueSet {
        message: table,
        callsite: Identifier(0x62d25e2ca010),
    },
    metadata: Metadata {
        name: "event src/main.rs:15",
        target: "nice",
        level: Level(
            Error,
        ),
        module_path: "nice",
        location: src/main.rs:15,
        fields: {message},
        callsite: Identifier(0x62d25e2ca010),
        kind: Kind(EVENT),
    },
    parent: Current,
}
[src/main.rs:60:9] &callsite = [
    Identifier(0x62d25e2ca010),
]
[src/main.rs:62:9] &name = [
    "message",
]
[src/main.rs:64:9] &metadata = Metadata {
    name: "event src/main.rs:15",
    target: "nice",
    level: Level(
        Error,
    ),
    module_path: "nice",
    location: src/main.rs:15,
    fields: {message},
    callsite: Identifier(0x62d25e2ca010),
    kind: Kind(EVENT),
}
[src/main.rs:66:9] &parent = None

I have the full source code shown in the original post. If you want, you can copy-paste it into a cargo new:ed project and cargo add the dependencies and then it should be easy to run it and play around with it!

4

Sorry I have to go now, but I think the info you're looking for is here. You probably want the value of the field, not the name, so one easy thing to try is to remove the .map(|field| field.name() for the fields iterator.

5

Here's what I get with just fields without name:

``` let fields = event.fields().collect_vec(); dbg!(&fields); ``` 
[src/main.rs:69:9] &fields = [
    Field {
        i: 0,
        fields: FieldSet {
            names: [
                "message",
            ],
            callsite: Identifier(0x5b1e375a9010),
        },
    },
]

I'll check out the link u sent!

6

I'm just getting back to this and you may have already resolved it. As described in the link I sent, it looks like you have to iterate over values with a visitor. I added the following to the end of your debug output:

pub struct MyVisitor;
impl Visit for MyVisitor {
    fn record_debug(
        &mut self,
        field: &Field,
        value: &dyn std::fmt::Debug,
    ) {
        dbg!(field.name(), value);
    }
}
let mut visitor = MyVisitor;
event.record(&mut visitor);

And it produced this output:

[src/lib.rs:104:25] field.name() = "message"
[src/lib.rs:104:25] value = table

There are other methods you can implement in the Visit trait to get values of specific types.

2 Likes
7

the formatted message is implicitly translated into a field named "message" with str type. the solution by @jumpnbrownweasel using the visitor pattern is how you access the fields (including the message field) of an Event (and also Span, for that matter).

an Event in tracing is not just a simple text log line, it is adhoc defined (i.e. field names and value types are potentially different for each single instance), structured data, similar to Record type or Object type, and the subscriber (potentially defined in layers) determines how to interprete/process the data (e.g. print to console, save to file, or send to a server, etc)

for example, this line of code:

error!(session_id=12345678, path="/foo/bar/page.html", method = Method::POST, "access denied: {}", error_code);

is shorthand for:

(note: for illustration purpose only, read the source code if you want to learn how exactly the macro is expanded):

event!(Level:ERROR,
    session_id=12345678,
    path="/foo/bar/page.html",
    method = Method::POST,
    message = format!("access denied: {}", error_code)
);

this, you can think of it like this (conceptual pseudo code)

get_registered_subscriber().event(
    Event {
        file: file!(),
        line: line!(),
        level: Level::ERROR,
        session_id: 12345678,
        path: "/foo/bar/page.html",
        method: Method::POST,
        message: access denied: {}", error_code));
    }
);

in the real implementation, some of the information are static/constant, and these are represented by a Metadata type so they don't have runtime overhead; and the Event is represented as a slice of (field_name, field_value) pairs where field_name is of type Field and can be enumerated, but the type of field_value is erased (Option<&dyn Value>, the Option is so you can declare a field name before hand to generate correct metadata, and record the field value later) and must be accessed using the "visitor pattern".

obviously, the same concepts can be implemented in alternative ways, but why they are implemented like this? I don't really know, but I guess part of the consideration is to avoid allocation and to support no_std, and maybe also to preserve the order of the fields, so a slice of (key,value) pairs is used (instead of, say, a HashMap). as for why the visitor pattern (i.e. trait Value as opposed to enum Value) is used, I've absolute no idea.

as mentioned above, it is the Subscribers who decides how to process the information of an Event. for example the default fmt layer will convert the fields of an event to different representation according to the configured formatter.

note: some formatter might need to handle the message field as a special case, like the Pretty formatter; but other formatter just treat the message field like a normal field, like the Json formatter. below is how the PrettyVisitor handles the message field:

1 Like
8

This topic was automatically closed 90 days after the last reply. We invite you to open a new topic if you have further questions or comments.