[HELP] Adding custom fields to all logs without propagating them to `log` usages?

[nerodono]

I want to turn off and on logs in the same module selectively (some part of code should have logs, some other part don't) and add custom fields to each log without propagating those fields to log::{warn,info,debug, ...} usages. Intuitively, fastrace integration should do this, however:

let span = Span::root("root", SpanContext::random()).with_property(|| ("component", "database"));
async move {
    log::info!("Test");
}.in_span(span).await;

Doesn't report component=database. How can I achieve that properly? I can't use Metadata::target (can I? As far as I can see, target represents crate name), since everything occurs in the same crate.

And logforth lacks some explanations, as an example:

Metadata::target
Get the target

What's the target?

[tisonkun]

Doesn't report component=database

Yes. The current FastraceDiagnostic only provides:

logforth/diagnostics/fastrace/src/lib.rs

Lines 50 to 54 in 4118fd3

	if let Some(span) = fastrace::collector::SpanContext::current_local_parent() {
	visitor.visit(Key::new("trace_id"), Value::from_u128(span.trace_id.0))?;
	visitor.visit(Key::new("span_id"), Value::from_u64(span.span_id.0))?;
	visitor.visit(Key::new("sampled"), Value::from_bool(span.sampled))?;
	}

@andylokandy is there some way we can fetch the current span and its properties to populate the diags?

What's the target?

target is a field that you can set by log::warn!(target: "input_events", "App received warning: {warn_description}");. It's default to module_path!.

I agree that we can enrich the document with some examples.

[tisonkun]

In ScopeDB, we use target to filter different code path no matter what their module is, like:

log::info!(
    target: "ingest",
    method:% = request.method(),
    uri:% = request.uri(),
    format:% = req.data.format(),
    ty:? = req.ty,
    size:% = humansize::format_size(req.data.data_size(), humansize::BINARY);
    "{:?}", req.statement
);

And in specific instance, we use the filter info,ingest=error to disable warn, info, debug, and trace logs on ingest target.

[nerodono]

Hmm, I guess I can work-around that the same way it done in FastraceDiagnostic (propagate context through thread locals, so logger will know which component is currently speaking).

---

target is a field that you can set by log::warn!(target: "input_events", "App received warning: {warn_description}");. It's default to module_path!.

Sadly, looks like there's no way to provide target from outside, without propagating it topdown, so that's not applicable in my use-case :(. Precisely, use-case is — spawning multiple tasks in tokio's JoinSet, each task is component of the system (http server, websocket server, cron jobs, ...). HTTP and WebSocket servers are just presentation layers for custom logic.
So, desired outcome is:

1. When HTTP server task logs something, it'll have field component=http
2. When websocket server task logs something, it'll have field component=ws
3. When backend (logic which is called by presentations, not a task, but a library) logs something, it'll have component=backend

Thus providing target by hand is not something enjoyable.

[tisonkun]

propagate context through thread locals, so logger will know which component is currently speaking

Yeah logforth provides a ThreadLocalDiagnostic to populate thread-local state as context.

But IIRC tokio's task doesn't always run in the same thread so you'd prepare for an opaque task scheule. Anyway, you can give it a try and welcome to send the feedback.

Another possible approach is using different logger for different component, which is supported starting from log 0.4.27 (rust-lang/log#664) and you can see an example here.

Now I understand your requirement to populate context per span and propagate it to log context. If you can share a minimal repro or the whole logic of your logics, we can investiagte it together better.

[nerodono]

But IIRC tokio's task doesn't always run in the same thread so you'd prepare for an opaque task scheule. Anyway, you can give it a try and welcome to send the feedback.

Yeah, tokio tasks are usually not pinned to threads, so it'd require me to do something like .in_span(..) does, like so:

impl<F: Future> Future for FutureInScope<F> {
    type Output = F::Output;

    fn poll(self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll<Self::Output> {
        let this = self.project();

        SCOPE.with_borrow_mut(|opt| match opt {
            Some(arc) => {
                if !Arc::ptr_eq(arc, &*this.scope) {
                    *arc = Arc::clone(&*this.scope);
                }
            }
            None => *opt = Some(Arc::clone(&this.scope)),
        });

        this.fut.poll(cx)
    }
}

And

#[derive(Debug)]
struct ComponentDiagnostics {}

impl logforth::Diagnostic for ComponentDiagnostics {
    fn visit(&self, visitor: &mut dyn logforth::kv::Visitor) -> Result<(), logforth::Error> {
        use logforth::kv::{Key, Value};

        if let Some(r) = supervisor::scope::with(|scope| {
            visitor.visit(Key::new("component"), Value::from_str(scope.component()))
        }) {
            r
        } else {
            Ok(())
        }
    }
}

Works for me. Should I keep issue open? IMO populating properties from the current span sounds like useful addition.

UPD: made a typo, not "something like .in_scope(..)", but "something like .in_span(..)". Edited this message.

[tisonkun]

Should I keep issue open

Sure. Let's wait for @andylokandy 's reply on fastrace side.

in_scope

Could you elaborate a bit about this method? Does it come from some open-source projects? I'd like to see if I can borrow it as a completement to logforth.

[nerodono]

Sorry, made a typo here

so it'd require me to do something like .in_scope(..) does

Edited original message.

---

Actually, I meant "like in_span(..) does". .in_scope(..) is similar extension method for the Future which I wrote myself. They're similar in algorithm - both set some thread local when Future is polled. I doubt you can borrow that, since fastrace::future::FutureExt::in_span already works the same way.

[nerodono]

As for logforth completement, maybe it's worth mentioning - tokio has task_local. elfo actor framework uses it to propagate trace_id down the stack - https://github.com/elfo-rs/elfo/blob/6fe7570580b9d5bcd3063043a0408bceb4954bb0/elfo-core/src/scope.rs#L24.

[tisonkun]

#187 implements a task local diagnostic that you can attach context task local.