Using `tracing` crate #3960

link2xt · 2023-01-16T13:57:11Z

No description provided.

flub · 2023-01-16T20:54:36Z

Oh, I've wanted this for a while :)

link2xt · 2023-01-17T13:28:08Z

There are three main tasks in setting up the tracing crate:

Adding context ID spans to context methods, so it is possible to identify which context emitted an event.
Emitting tracing events instead of Delta Chat INFO/WARNING/ERROR events.
Setting up a subscriber to catch tracing events, convert them into Delta Chat events and push into the event channel.

Subscriber is already implemented in this PR as an EventLayer layer and Events.to_layer() method, so it is easy to construct a subscriber, but it is not obvious where to set it up.

One option is to instrument all Context and Accounts calls.
This option does not introduce any API changes,
but makes it impossible for library users to setup other advanced subscribers to collect traces instead of collecting all tracing events to the Delta Chat event emitter.

I am currently considering not setting up the subscriber from the deltachat crate at all, so it is up to the user whether they want to get logs in the form of Delta Chat events or using their own subscriber.

Instead:

Rust programs, such as REPL, examples and bots will set up their own subscriber manually. They don't need tracing events to be converted into Delta Chat events in most cases.
deltachat-rpc-server may convert all tracing events into JSON-RPC notifications itself, using its own subscriber.
deltachat-ffi will set up subscribers on every FFI call for compatibility, using with_subscriber on the future before passing it into block_on() or .awaiting it. This affects non-async python bindings and node module. Python tests need this, because they set up many independent contexts with independent event channels and rely on INFO events being emitted from the corresponding channel.

flub · 2023-01-17T19:31:14Z

Subscriber is already implemented in this PR as an EventLayer layer and Events.to_layer() method, so it is easy to construct a subscriber, but it is not obvious where to set it up.

This layer should be part of the Rust public API.

1. Rust programs, such as REPL, examples and bots will set up their own subscriber manually. They don't need `tracing` events to be converted into Delta Chat events in most cases.

2. `deltachat-rpc-server` may convert all tracing events into JSON-RPC notifications itself, using its own subscriber.

3. `deltachat-ffi` will set up subscribers on every FFI call for compatibility, using [with_subscriber](https://docs.rs/tracing-futures/latest/tracing_futures/trait.WithSubscriber.html) on the future before passing it into `block_on()` or `.await`ing it. This affects non-async python bindings and node module. Python tests need this, because they set up many independent contexts with independent event channels and rely on INFO events being emitted from the corresponding channel.

Yes, I agree this is the right approach.

link2xt · 2023-01-18T13:13:35Z

src/events.rs

+        let &level = event.metadata().level();
+
+        // FIXME
+        let context_id = 0;


It's still a question where to get this context_id from.

It should be possible to set it from Accounts.start_io() for every account.start_io() future.
I am currently considering looking for context_id field on the current span. If current span has no context ID field, then set it to 0. The problem is that some library called by delta chat core may set up a span too, then context_id will become invisible, but at least all delta chat events will have proper context ID. We can also try to walk the span tree if needed.

Could we require a subscriber per context and insert the context id into the subscriber at creation time?

I thought about this, but this means account manager will have to create subscribers, and these subscribers will catch all the tracing events, converting them to Delta Chat events. For Rust programs like repl and Rust bots these subscribers are not needed, they might want to subscribe to all events directly from main() and account manager creating its own subscribers will interfere.

hpk42 · 2023-01-19T15:21:34Z

On Wed, Jan 18, 2023 at 11:00 -0800, link2xt wrote: @link2xt commented on this pull request. + // FIXME + let context_id = 0; I thought about this, but this means account manager will have to create subscribers, and these subscribers will catch all the `tracing` events, converting them to Delta Chat events. For Rust programs like `repl` and Rust bots these subscribers are not needed, they might want to subscribe to all events directly from `main()` and account manager creating its own subscribers will interfere.

Repl and Rust bots are not a strong argument against floris' suggestion i think. If it works for jsonrpc-desktop/android/ios usage and python/js bots then repl/rust can maybe just live with it or do something in addition to work-around if it's an issue?

flub · 2023-01-19T19:27:53Z

On Thu 19 Jan 2023 at 07:21 -0800, holger krekel wrote: On Wed, Jan 18, 2023 at 11:00 -0800, link2xt wrote: > @link2xt commented on this pull request. > + // FIXME > + let context_id = 0; > > I thought about this, but this means account manager will have to create subscribers, and these subscribers will catch all the `tracing` events, converting them to Delta Chat events. For Rust programs like `repl` and Rust bots these subscribers are not needed, they might want to subscribe to all events directly from `main()` and account manager creating its own subscribers will interfere. Repl and Rust bots are not a strong argument against floris' suggestion i think. If it works for jsonrpc-desktop/android/ios usage and python/js bots then repl/rust can maybe just live with it or do something in addition to work-around if it's an issue?

I'm not really sure anymore if my suggestion would really work out. The subscriber is global and you still need to support multiple accounts. So I fear that somehow the context id needs to be in the span otherwise the subscriber doesn't know which account an event is from. I guess a standard span name of `context` with an `id` field would work this, rather than searching any span for a matching id (or context_id) field. The trickier bit will be to activate that span in the right places.

src/accounts.rs

iequidoo · 2023-01-26T16:55:56Z

I guess a standard span name of context with an id field would work this, rather than searching any span for a matching id (or context_id) field. The trickier bit will be to activate that span in the right places.

Took a glance at tracing crate, but don't see any way for looking for a particular span, even for getting a parent one. Only Span::current() function. Can't you point me to the proper API?

link2xt · 2023-01-26T18:25:38Z

Took a glance at tracing crate, but don't see any way for looking for a particular span, even for getting a parent one. Only Span::current() function. Can't you point me to the proper API?

See events.rs, it's already implemented. When span is created, layer is notified and records "context_id" field of a span into "extension", which can then be looked up when event arrives. It already works and is tested by python tests.

link2xt · 2023-01-26T18:26:56Z

The PR is ready for review, it only needs rebasing and maybe repl/README updates to make it usable. But applications and bots built with this will already work.

src/events.rs

iequidoo · 2023-01-27T14:37:04Z

src/events.rs

+                if let Some(span_context_id) = span.extensions().get::<EventContextId>() {
+                    context_id = *span_context_id;
+                    if context_id.0 > 0 {
+                        break;


Can't we also set here EventContextId for the original span so that we don't need to loop again on subsequent events?

Also i'd prefer to have a span id in the log instead of a context id (which is per-account afaiu). So, when an event occurs, and it's the first event in its span, we, say, first log that there's a new span (in the context of its parent span), i.e. send a fake event "span created" from its parent span (which propagate up if needed), and then process the original event. This way logs would be more structured. And also spans w/o "real" events wouldn't produce any logs

Can't we also set here EventContextId for the original span so that we don't need to loop again on subsequent events?

I am not sure such microoptimization makes things better. If there is only one event emitted in this span, then it's an additional memory write for no gain.

Also i'd prefer to have a span id in the log instead of a context id (which is per-account afaiu).

Context ID inside event indicates which account received an event when account manager is used and there is only a single event emitter for multiple accounts. I do not see how span ID helps with this, it only indicates part of the code which emitted an event, but there is no way to tell if it's the current account or another account running in the background.

I am not sure such microoptimization makes things better. If there is only one event emitted in this span, then it's an additional memory write for no gain.

Yes, but i personally prefer things that scale better in questional situations. Anyway, it's not critical here.

Context ID inside event indicates which account received an event when account manager is used and there is only a single event emitter for multiple accounts. I do not see how span ID helps with this, it only indicates part of the code which emitted an event, but there is no way to tell if it's the current account or another account running in the background.

I suppose we have different root spans for accounts and thus can learn from logs which account an event belongs to. Anyway, i don't suggest to implement this now as it changes the structure of logs. Just to think how we could make logs more structured and also get rid of such loops searching for EventContextId

iequidoo · 2023-01-27T15:04:09Z

deltachat-rpc-server/src/bin/deltachat-rpc-server/main.rs

@@ -11,18 +11,24 @@ use deltachat_jsonrpc::api::{Accounts, CommandApi};
 use futures_lite::stream::StreamExt;
 use tokio::io::{self, AsyncBufReadExt, BufReader};
 use tokio::task::JoinHandle;
+use tracing::{info, trace};


Maybe we can reexport all such macros somewhere in our crate to just write smth like use crate::tracing::macros::*? Because if we need, say, info, we also need other macros too and it's not convenient to constantly fix these use statements

There is an upstream proposal to implement use tracing::prelude::*: tokio-rs/tracing#167 . Wildcard import of modules not called prelude is generally a bad style, clippy will complain.

We can of course add our own internal prelude module, but this seems better suited for upstream or at least a separate crate.

Btw, for now we can use tracing as log; and this commit will be smaller and we don't need to list all necessary macros explicitly.

We can also define our own private module deltachat::prelude and include deltachat::prelude::* everywhere.

iequidoo

Looks good to me but maybe somebody with more experience with logging/tracing in Rust should take a look also

link2xt · 2023-03-14T13:50:28Z

I removed all the #[instrument] macros and implemented .bind_context_id() instead.

link2xt · 2023-03-15T13:57:18Z

It is unclear now how to set the context/account ID when JSON-RPC requests are made. In dc_jsonrpc_request we spawn a request handler, but have no universal way to attribute an account ID to the request. For some requests it is a positional argument, but not for all of them.

iequidoo · 2023-03-27T15:03:22Z

src/log.rs

@@ -50,13 +50,13 @@ impl Context {
    /// Set last error string.
    /// Implemented as blocking as used from macros in different, not always async blocks.
    pub fn set_last_error(&self, error: &str) {
-        let mut last_error = self.last_error.write().unwrap();
+        let mut last_error = self.events.last_error.write().unwrap();
        *last_error = error.to_string();


Again, maybe call to_string() before taking lock?

Hocuri · 2023-04-02T09:22:23Z

src/log.rs

-}
-
-#[macro_export]
-macro_rules! warn {


Since the new warn! macro doesn't take a context anymore, would be nice to adapt log_err() and so on, too, maybe by just letting it use the warn! macro. After rebasing though, because it'll create a merge conflict otherwise, and it's not urgent either.

dignifiedquire · 2024-05-18T10:58:51Z

@link2xt what happened to this?

link2xt · 2024-05-18T16:01:22Z

Was probably closed when we renamed master to main and deleted master.

But the problem is that every caller has to set an account_id and if someone uses deltachat crate directly they have to do it as well - currently it is not needed.

link2xt · 2025-06-23T23:51:39Z

This is now replaced with a much simpler approach #6919

link2xt force-pushed the link2xt/tracing branch 2 times, most recently from 7c8626e to d137f9e Compare January 16, 2023 15:22

link2xt force-pushed the link2xt/tracing branch from 0913923 to 8ff2a79 Compare January 16, 2023 22:13

link2xt force-pushed the link2xt/tracing branch from f5f2710 to d6e5bfd Compare January 17, 2023 16:20

link2xt force-pushed the link2xt/tracing branch from 967cc85 to d089e5b Compare January 17, 2023 19:58

link2xt mentioned this pull request Jan 18, 2023

Mergeable fails on PRs without description #3024

Closed

link2xt commented Jan 18, 2023

View reviewed changes

dignifiedquire reviewed Jan 19, 2023

View reviewed changes

src/accounts.rs Outdated Show resolved Hide resolved

link2xt force-pushed the link2xt/tracing branch 7 times, most recently from f2bedff to ad03ac7 Compare January 23, 2023 00:04

link2xt marked this pull request as ready for review January 23, 2023 01:54

iequidoo reviewed Jan 27, 2023

View reviewed changes

src/events.rs Show resolved Hide resolved

iequidoo reviewed Jan 27, 2023

View reviewed changes

iequidoo self-requested a review January 27, 2023 16:24

iequidoo approved these changes Jan 27, 2023

View reviewed changes

link2xt force-pushed the link2xt/tracing branch 2 times, most recently from c14a00e to a85b988 Compare January 30, 2023 11:28

link2xt force-pushed the link2xt/tracing branch from 7ff5ce1 to e0e9caa Compare March 14, 2023 13:47

link2xt marked this pull request as ready for review March 14, 2023 13:49

link2xt requested a review from flub March 14, 2023 13:49

link2xt requested a review from iequidoo March 14, 2023 13:55

iequidoo approved these changes Mar 15, 2023

View reviewed changes

link2xt force-pushed the link2xt/tracing branch 2 times, most recently from d24dc3a to 75b4100 Compare March 15, 2023 13:50

link2xt marked this pull request as draft March 15, 2023 13:55

link2xt marked this pull request as ready for review March 15, 2023 15:25

link2xt force-pushed the link2xt/tracing branch from 2d3cdb1 to ff9a7c9 Compare March 15, 2023 22:41

link2xt added 3 commits March 25, 2023 12:38

Move last_error from Context to Events

dab2889

Explicitly emit INFO events in stop_io()

8c660ad

lockfile

381af52

link2xt force-pushed the link2xt/tracing branch from ff9a7c9 to 0db7386 Compare March 25, 2023 16:01

Use tracing crate for logging

4f364f0

link2xt force-pushed the link2xt/tracing branch from 0db7386 to 4f364f0 Compare March 25, 2023 17:36

iequidoo reviewed Mar 27, 2023

View reviewed changes

Hocuri reviewed Apr 2, 2023

View reviewed changes

link2xt force-pushed the master branch from cfacebb to 514074d Compare April 22, 2023 16:43

link2xt force-pushed the master branch from a1cc433 to 5b435d1 Compare June 1, 2023 12:31

link2xt deleted the branch master October 25, 2023 21:22

link2xt closed this Oct 25, 2023

link2xt reopened this Oct 25, 2023

link2xt deleted the branch master December 17, 2023 17:58

link2xt closed this Dec 17, 2023

Uh oh!

Using tracing crate #3960

Using tracing crate #3960

Uh oh!

Conversation

link2xt commented Jan 16, 2023

Uh oh!

flub commented Jan 16, 2023

Uh oh!

link2xt commented Jan 17, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

flub commented Jan 17, 2023

Uh oh!

Choose a reason for hiding this comment

Uh oh!

flub Jan 18, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

hpk42 commented Jan 19, 2023 via email

Uh oh!

flub commented Jan 19, 2023 via email

Uh oh!

Uh oh!

iequidoo commented Jan 26, 2023

Uh oh!

link2xt commented Jan 26, 2023

Uh oh!

link2xt commented Jan 26, 2023

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

iequidoo left a comment

Choose a reason for hiding this comment

Uh oh!

link2xt commented Mar 14, 2023

Uh oh!

link2xt commented Mar 15, 2023

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

dignifiedquire commented May 18, 2024

Uh oh!

link2xt commented May 18, 2024

Uh oh!

link2xt commented Jun 23, 2025

Uh oh!

Uh oh!

Using `tracing` crate #3960

Using `tracing` crate #3960

link2xt commented Jan 17, 2023 •

edited

Loading

flub Jan 18, 2023 •

edited

Loading