Feature request: Tracing spans/logs

[Altair-Bueno]

Context

tracing has become the de-facto standard for logging and tracing in Rust, not only in async code but also in sync code. It is compatible with the log facade, which means it would work well with any logging consumer out there. The advantage of using tracing over log are spans and events, which you can learn more on docs.rs.

Expected behavior

A cargo feature flag (for dbus and dbus-crossroads) and a generator option (for dbus-codegen) that allows the library to emit tracing logs and spans. These would be useful for end users to see how the client/server is behaving.

Current behavior

To my knowledge, there is no instrumentation available on either dbus dbus-crossroads or dbus-codegen available

Further considerations

• This isn't a breaking change, as it would be an additive feature flag/generator option

Alternatives

• Using the log crate instead of tracing

[diwic]

Hi and thanks for submitting this feature request!

Two questions:

1. Is it possible to make the tracing/log dependency an optional feature, and
2. If I say yes, will you start writing PR(s) for this?

[AldanTanneo]

Is it possible to make the tracing/log dependency an optional feature

One idea would be to have wrapping macros that call the actual macro when a feature is enabled? Although most libraries depend on tracing unconditionally, as the events are only logged when a subscriber is present.

If I say yes, will you start writing PR(s) for this?

I can help too :)

[diwic]

Two of tracing's biggest consumers are tokio and hyper. For both, the dependency is optional, probably that is for a reason. So, I'm not sure that "most libraries depend on tracing unconditionally", but maybe we can do things the same way hyper/tokio does things to make the feature optional?

[AldanTanneo]

Yeah in Hyper they use what I thought, they redefine macros in a top level trace module to use throughout the crate:

macro_rules! info {
    ($($arg:tt)*) => {
        #[cfg(feature = "tracing")]
        {
            tracing::info!($($arg)+);
        }
    }
}

[Altair-Bueno]

Sorry for the delayed response. Currently working on non-dbus stuff at Altra. Indeed, I can submit a PR, but unfortunately I cannot give you an ETA for the feature. It's something of a low priority right now.

Also, as @AldanTanneo noted, it should be an optional feature as tracing can easily increase the final binary size. It should be up to the developer to enable it.

Before doing anything, what would be the most useful things to instrument?

For example. at Altra, we are doing the following for D-Bus crossroads:

//! Blocking implementation of [org.bluez.GattService1](https://github.com/bluez/bluez/blob/2ee08ffd4d469781dc627fa50b4a015d9ad68007/doc/org.bluez.GattService.rst)

use dbus::MethodErr;
use dbus_crossroads::Crossroads;
use dbus_crossroads::PropContext;

/// Defines the blocking D-Bus interface for [org.bluez.GattService1](https://github.com/bluez/bluez/blob/2ee08ffd4d469781dc627fa50b4a015d9ad68007/doc/org.bluez.GattService.rst)
///
/// GATT local/server and remote/client services share the same high-level D-Bus API.
/// Local/Server refers to GATT based service exported by a plugin or an external application.
///
/// Remote/Client refers to GATT services exported by the peer.
pub trait GattService1 {
    const INTERFACE_NAME: &'static str = "org.bluez.GattService1";
    /// 128-bit service UUID.
    fn get_uuid(&mut self, context: &mut PropContext) -> Result<String, MethodErr>;
    /// Indicates whether or not this GATT service is a primary service. If false, the service is secondary.
    fn is_primary(&mut self, context: &mut PropContext) -> Result<bool, MethodErr>;
    fn get_characteristics(
        &mut self,
        context: &mut PropContext,
    ) -> Result<Vec<dbus::Path<'static>>, MethodErr>;
    /// Array of object paths representing the included services of this service.
    fn get_includes(
        &mut self,
        context: &mut PropContext,
    ) -> Result<Vec<dbus::Path<'static>>, MethodErr> {
        Err(MethodErr::no_property(context.name()))
    }
    /// Service handle. When available in the server it would attempt to use to allocate into the database which may fail, to auto allocate the value 0x0000 shall be used which will cause the allocated handle to be set once registered.
    fn get_handle(&mut self, context: &mut PropContext) -> Result<u16, MethodErr> {
        Err(MethodErr::no_property(context.name()))
    }
    /// Service handle. When available in the server it would attempt to use to allocate into the database which may fail, to auto allocate the value 0x0000 shall be used which will cause the allocated handle to be set once registered.
    fn set_handle(&mut self, context: &mut PropContext, _value: u16) -> Result<u16, MethodErr> {
        Err(MethodErr::no_property(context.name()))
    }
}

/// Extension trait for [`GattService1`] to register the interface with a blocking [`Crossroads`] instance.
pub trait GattService1Interface
where
    Self: Send + Sized,
{
    fn interface(crossroads: &mut Crossroads) -> dbus_crossroads::IfaceToken<Self>;
}

impl<A> GattService1Interface for A
where
    A: Send + Sized + GattService1,
{
    fn interface(crossroads: &mut Crossroads) -> dbus_crossroads::IfaceToken<Self> {
        crossroads.register(Self::INTERFACE_NAME, |builder| {
            builder.property("Primary").get(|context, this: &mut Self| {
                tracing::info_span!(
                    "Get",
                    property = context.name(),
                    interface = Self::INTERFACE_NAME
                )
                .in_scope(move || {
                    tracing::trace!("Processing D-Bus request");
                    this.is_primary(context)
                        .inspect_err(|e| tracing::error!("{e}"))
                })
            });

            builder.property("UUID").get(|context, this: &mut Self| {
                tracing::info_span!(
                    "Get",
                    property = context.name(),
                    interface = Self::INTERFACE_NAME
                )
                .in_scope(move || {
                    tracing::trace!("Processing D-Bus request");
                    this.get_uuid(context)
                        .inspect_err(|e| tracing::error!("{e}"))
                })
            });

            builder
                .property("Characteristics")
                .get(|context, this: &mut Self| {
                    tracing::info_span!(
                        "Get",
                        property = context.name(),
                        interface = Self::INTERFACE_NAME
                    )
                    .in_scope(move || {
                        tracing::trace!("Processing D-Bus request");
                        this.get_characteristics(context)
                            .inspect_err(|e| tracing::error!("{e}"))
                    })
                });

            builder
                .property("Includes")
                .get(|context, this: &mut Self| {
                    tracing::info_span!(
                        "Get",
                        property = context.name(),
                        interface = Self::INTERFACE_NAME
                    )
                    .in_scope(move || {
                        tracing::trace!("Processing D-Bus request");
                        this.get_includes(context)
                            .inspect_err(|e| tracing::error!("{e}"))
                    })
                });

            builder
                .property("Handle")
                .get(|context, this: &mut Self| {
                    tracing::info_span!(
                        "Get",
                        property = context.name(),
                        interface = Self::INTERFACE_NAME
                    )
                    .in_scope(move || {
                        tracing::trace!("Processing D-Bus request");
                        this.get_handle(context)
                            .inspect_err(|e| tracing::error!("{e}"))
                    })
                })
                .set(|context, this: &mut Self, value: u16| {
                    tracing::info_span!(
                        "Set",
                        property = context.name(),
                        interface = Self::INTERFACE_NAME
                    )
                    .in_scope(move || {
                        tracing::trace!("Processing D-Bus request");
                        this.set_handle(context, value)
                            .map(Some)
                            .inspect_err(|e| tracing::error!("{e}"))
                    })
                });
        })
    }
}

Notice that we are creating a span for each method invocation, property and signal. Ideally, crossroads should be the one creating those and entering them (minus the tracing::error! log).

Similarly, sending D-Bus messages should log (at trace level), the signature, sender and interface. Maybe something like the total byte size too may be useful.

This is behaviour similar to what xtra does. I think this is a good example, as D-Bus is basically an actor system mailbox.

[diwic]

You have more experience with tracing/spans than I have, so maybe we have to iterate this a bit. And start with one crate, dbus-tokio or dbus-crossroads and see how things work there before adding it everywhere. Does that make sense?

[Altair-Bueno]

Ideally, we should be able to pull this off from dbus and dbus-crossroads, with zero modifications for dbus-tokio and others. Maybe the dbus-generator tool, but I don't think it will be necessary.

While I believe the implementation is straightforward on the dbus-crossroads side (just adding the spans and sprinkling some logs on dbus_crossroads::IfaceBuilder), I'm not sure on how we should instrument the dbus crate tho. Is there any callback or similar where all requests and responses go through? In such case, instrumenting only that function would be sufficient.

Additionally, if the libdbus library provides logging callback functions, we should emit those too. (Judging from the generated bindings and the C API it doesn't seem to have any kind of internal logging, but it might be worthwhile to double-check)

[diwic]

Let's start with dbus-crossroads then and see how that works out before approaching other crates. Dbus-tokio is also a good crate to start with because tokio (optionally) depends on tracing itself.