♻️ zb: Make tracing an optional dependency #712

REALERvolker1 · 2024-04-09T04:56:00Z

Hey all

I'm here to fix #331. It took me a bit to get to it, I have been pretty busy as of late.

Anyways, I'm pretty sure everything works. I ran the tests on all features, I documented the new macros themselves, changed some of the code structure to better support instrumented futures, and more.

I am using stable-x86_64-unknown-linux-gnu, so I don't know 100% if everything works on Windows (I didn't even know Windows had dbus!). I followed the contributor guidelines, so I'm pretty confident with this pr.

I hope my macros make this much easier to maintain in the future.

zeenix

Thanks so much for taking this on and I realize it wasn't an easy task. Overall, the approach looks good to me. Also, thanks for following the commit message rules (somehow everyone misses that at first 😆).

Apart from the inline comments, kindly squash the fixups commits into the relevant commits as per the guidelines (see the very last bullet point here).

Ideally this should be 3 commits but I'm fine with putting it all in one commit.

zeenix · 2024-04-09T10:07:18Z

zbus/src/connection/socket_reader.rs

+                            #[cfg(not(feature = "tracing"))]
+                            Err(_e) => continue,
+                            #[cfg(feature = "tracing")]


This turned out to be more intrusive than I was hoping for. Why do we need feature gating in the rest of the code, if you created the macros for both cases (feature enabled and disabled)? 🤔

zeenix · 2024-04-09T10:07:49Z

zbus/src/connection/socket_reader.rs

@@ -72,6 +80,7 @@ impl SocketReader {
                    }
                }

+                #[allow(unused_variables)]


We shouldn't need these either. The macros should take care of this.

zeenix · 2024-04-09T10:09:10Z

zbus/Cargo.toml

 ] }
-tracing = "0.1.40"
+# FIXME: We should only enable process feature for Mac OS. See comment on async-process below for why we can't.


This comment is for tokio dep so pretty sure this is a mistake.

zeenix · 2024-04-09T10:18:28Z

so I don't know 100% if everything works on Windows (I didn't even know Windows had dbus!)

Don't worry about it. The CI will take care of that. :)

REALERvolker1 · 2024-04-09T19:09:33Z

Firstly, I am sorry for the number of commits. I usually make numerous small commits on projects that I am working on on my machine, and I simply did not know that the repo style favors larger commits. I usually do multiple, smaller commits because then it is easier to detect when changes were made and by who. I will learn how to use these tools to merge the commits.

Second, the macros that I created for the cases where tracing is not enabled simply expand to (), the return type of println!["{}", var]. Following the contributor guide, I wanted to remove clippy lints related to dead code, and minimize variable creation when possible. I realize how it bloated the codebase, and I will do my best to minimize the impact of this.

Third, I am sorry about the tokio comment. I have both VSCodium and Neovim set to autoformat, so I am pretty sure that's what happened there. I will move that back where it belongs.

I am still pretty new to contributing to OSS, so thanks for considering my pull request! 🎉

REALERvolker1 · 2024-04-09T20:28:47Z

I couldn't figure out how to integrate #[allow(unused_variables)] into the logging macros, I got the error attributes on expressions are experimental, but besides that, I think I cleaned up pretty well. What do you think?

zeenix · 2024-04-09T20:39:00Z

Firstly, I am sorry for the number of commits. I usually make numerous small commits on projects that I am working on on my machine, and I simply did not know that the repo style favors larger commits.

I'm sorry to give you the wrong idea. We very much prefer atomic commits (which typically but not always imply smaller commits). The criteria is one logical change per commit (ideally) that has its own summary and rationale in the commit log. Since the point is to keep the commits atomic, rather than keeping the history linear, git has (I think from the very beginning) the concept of fixup commits, which means that if you've an unmerged (to the main tree) commit that needs fixing, fixup allows you to fix that commit (together with a rebase), instead of creating an additional commit for it. This is documented in the contribution guidelines I pointed to in my previous comment.

Most projects, unfortunately just squash all commits when merging but we don't, because we want commits to remain atomic.

Third, I am sorry about the tokio comment. I have both VSCodium and Neovim set to autoformat, so I am pretty sure that's what happened there. I will move that back where it belongs.

You don't have to appologize. We all make mistakes. This is what the review process is for. :) Having said that, if you're not already doing so, I would suggest that you review your changes yourself before/after pushing.

I am still pretty new to contributing to OSS, so thanks for considering my pull request! 🎉

You're doing pretty great for someone new to OSS. Trust me, I was doing much worse when I started off. :)

I couldn't figure out how to integrate #[allow(unused_variables)] into the logging macros, I got the error attributes on expressions are experimental

Perhaps you can instead tell the compiler to ignore the unused variables instead?

let _ = the_variable_to_ignore;

REALERvolker1 · 2024-04-10T01:43:19Z

Perhaps you can instead tell the compiler to ignore the unused variables instead?
let _ = the_variable_to_ignore;

The problem with this is that clippy does ignore those variables while the tracing feature is disabled, but when it is enabled, those variables are used, which breaks naming convention. Another solution would be to remove the #[allow(unused_variables)] markers and introduce clippy warnings into the codebase (which you forbid in CONTRIBUTING.md). The idea I lean towards is breaking variable naming convention with underscore-prefixed names, because that is probably the least burdensome in terms of maintenance.

As for atomic commits, I read the blog post and commit guidelines again, and I think the best course of action would be to manually copy over what I have written into a local copy of the repository. I would be able to succinctly describe what everything does. The problem with this is that we lose the logs of trial and error I dealt with, but I think that it is probably for the best (And in this situation, it seems way easier than dealing with git).

REALERvolker1 · 2024-04-10T18:35:46Z

Oh! Another annoyance I had with zbus is that it sends tracing messages at info level. I often use info! for my own purposes, and I think that by default zbus should use trace. (Unless there's an important warning or error).

I added several macros related to logging. This is intended to replace the direct usage of tracing macros (which is what my pull request addresses). These do not support all of the syntax of the standard format_args macro, but I feel that they should still be comfortable to work with, while remaining easy to understand and maintain. I have inquired about the usage of info! because I personally prefer not to have libraries using this more "general" log level directly, and I will remove the info macro if I am allowed to do so.

Adds feature "tracing" to the crate. In addition to making the tracing dependency optional, this makes the tracing feature of tokio optional. This does not remove the dev-dependency tracing-subscriber, but as that is a dev dependency, it is not used in the final binary anyway.

This is a very large commit that touches many files in the zbus codebase. However, it is minimally invasive. There are many clippy warnings about unused variables, which will be addressed next. This commit also changes the logging level of the instrumented functions and futures to 'trace', notably excluding test functions. I added a custom debug macro in e2e.rs because the zbus logging macros are not public.

In CONTRIBUTING.md, it is stated that clippy must not find anything wrong in the code, and that contributors may allow clippy to ignore warnings. In a discussion I had with zeenix in pull request dbus2#712, we discussed possible ways to allow unused variables. I decided that instead of littering the codebase with the `#[allow(unused_variables)]` annotation, I would instead prefix variables that have to do with logging with an underscore. I have some misgivings about this, namely that it breaks clippy's lint, but it is more maintainable this way. In conclusion, I have no idea if this even *should* be allowed, but it gets the job done and I'm not complaining!

REALERvolker1 · 2024-04-11T04:04:31Z

Alright, I recommitted everything. What do you think?

zeenix · 2024-04-11T14:58:42Z

Perhaps you can instead tell the compiler to ignore the unused variables instead?
let _ = the_variable_to_ignore;

The problem with this is that clippy does ignore those variables while the tracing feature is disabled, but when it is enabled, those variables are used, which breaks naming convention.

Just to be clear, I didn't propose that you prefix the parameters/names with _ unconditionally but rather tell the compiler to ignore the variable in the macro for feature = "tracing". Something like we do here.

As for atomic commits, I read the blog post and commit guidelines again

👍

I think the best course of action would be to manually copy over what I have written into a local copy of the repository.

Well that's one way but you can also make use of rebase, reset, and commit --amend. That way you'll also gain some very important git skills, which really should be considered essential but unfortunately are not. :( I don't mind either way, as long as the end result is the same for me as the reviewer. :)

The problem with this is that we lose the logs of trial and error I dealt with, but I think that it is probably for the best

I know it feels bad that the rest of the world doesn't see your struggles and only the end result, but it's not helpful to have that recorded in the git log. E.g if one of your changes turn out to be problematic and need to be reverted later, with atomic commits, it'll hopefully be just a revert of a specific commit(s).

Oh! Another annoyance I had with zbus is that it sends tracing messages at info level.

Does it? I only see one use of tracing::info! in all the code. In either case, best we deal with this in a separate issue+PR (perhaps after this one is merged).

Alright, I recommitted everything. What do you think?

Awesome. I see only 4 commits so I'm sure it's definitely much closer to the target already (maybe already there). I'll review the commits soon.

zeenix · 2024-04-15T12:18:00Z

@REALERvolker1
Merge branch 'dbus2:main' into main

Please don't merge main but rather rebase on it and force push. Otherwise, we get unrelated changes/commits in the PR.

In CONTRIBUTING.md, it is stated that clippy must not find anything wrong in the code, and that contributors may allow clippy to ignore warnings. In a discussion I had with zeenix in pull request dbus2#712, we discussed possible ways to allow unused variables. This is an edited commit -- my original method used underscore-prefixed variable names to "fix" clippy lints. Now, I feature-gate the `#[allow(unused_variables)]` with cfg_attr so it only takes effect if the tracing feature is enabled. I also feature-gated some logic that only makes sense to run if the tracing feature is enabled.

REALERvolker1 · 2024-04-16T00:10:26Z

If the number of botched commits bothers you, don't worry I have 3 different backups locally

zeenix · 2024-04-16T12:54:10Z

zbus/src/connection/mod.rs

-                                Err(e) => {
-                                    warning!("Failed to parse `NameAcquired` signal: {}", e)
+                                Err(_e) => {
+                                    warning!("Failed to parse `NameAcquired` signal: {}", _e)


The task is to not have to do this at all. The caller of the macros, should not need to worry about the variables being unused.

zeenix · 2024-04-16T13:00:32Z

If the number of botched commits bothers you, don't worry I have 3 different backups locally

That's good and it's good to keep branches around with different approaches (branches are cheap in git). However, in case you didn't know already, git also keeps a cache of last 3 months of changes, which you can access through git reflog. I'd suggest using a tool like tig to access it though, so it's easy and quick to see which changes are there.

My main suggestion/request is still pending btw. If you are having trouble making the changes, I can have a look and see if I can get it to work. It's very much a requirement though, since having to add _ prefixes to variables just to use them with the macros, is not nice at all. The task of an abstraction is to abstract their user from the underlying details.

In CONTRIBUTING.md, it is stated that clippy must not find anything wrong in the code, and that contributors may allow clippy to ignore warnings. In a discussion I had with zeenix in pull request dbus2#712, we discussed possible ways to allow unused variables. Feeding these variables to the format_args macro inside of a block is a cheap way to use these variables without forcing the user of the macros to worry about unused variable clippy lints.

REALERvolker1 · 2024-04-17T20:33:55Z

Will the compiler optimize away spurious calls to format_args? I replaced the () in the logging macros with

{
   format_args!($stuff);
}

From what I know, it constructs those at compile-time. I basically don't want to impact runtime performance at all (except removing tracing macros probably makes it faster).

zeenix · 2024-04-18T13:42:14Z

Will the compiler optimize away spurious calls to format_args?

I would think so but it's a bit strange to make a needless call. Did you try my suggestion?

REALERvolker1 · 2024-04-18T15:34:09Z

For some reason I only just now realized what you meant by let _ = ... 😅

I tried out what you suggested, but the clippy warnings do not go away.

macro_rules! warning {
    ($first:literal $(, $arg:expr)+$(,)?) => {
        {
            let _ = (&$first $(, &$arg)+);
        }
    };
    ($only:literal) => {
        {
            let _ = &$only;
        }
    };
}

If I remove the borrows, the variables are used, but moved into the _ variable, which breaks things.

REALERvolker1 · 2024-04-18T15:36:46Z

Also I realized an optimization I can do is to replace the + symbols with * and it works without the $only branch, but I can do that after resolving this issue.

zeenix · 2024-04-18T16:28:05Z

If I remove the borrows, the variables are used, but moved into the _ variable, which breaks things.

I just checked it locally. The borrow actually works when the variables are passed separately from the literal string. It fails only when the variables are used in the literal string (e.g {e}). This will be an issue even if you don't borrow (but you don't get to this warning because there are errors because of the move elsewhere).

Hm.. this is tricky. @bilelmoussaoui since you requested this, do you have some ideas on how to nicely resolve this problem?

zeenix · 2024-04-18T16:31:28Z

One not-so-bad solution that comes to mind is that we require separate arguments to be always passed by reference. IMO the inlined style (debug!("inlining {e} here")) should be preferred anyway.

zeenix · 2024-04-18T16:32:44Z

BTW,

    ($only:literal) => {
        {
            let _ = &$only;
        }
    };

You don't need to do anything for the literal case. It can just be ().

REALERvolker1 · 2024-04-18T17:52:11Z

We could overengineer a solution with zbus_macros

I tried out the format_args call in the playground and with release optimizations, it generates the same asm as if I didn't even have the statement. https://play.rust-lang.org/?version=stable&mode=release&edition=2021&code=fn+main%28%29+%7B%0A++++let+foo+%3D+%22Hello%21%22%3B%0A++++%2F%2F+%7B%0A++++%2F%2F+++++format_args%21%28%22variable+%7Bfoo%7D%22%29%3B%0A++++%2F%2F+%7D%0A%7D

REALERvolker1 · 2024-04-18T19:41:10Z

The format_args macro is const in nightly too afaik

zeenix · 2024-04-18T21:24:09Z

We could overengineer a solution with zbus_macros

This needs to be internal only, sorry. Also it doesn't really fit in zbus_macros.

I tried out the format_args call in the playground and with release optimizations, it generates the same asm as if I didn't even have the statement. https://play.rust-lang.org/?version=stable&mode=release&edition=2021&code=fn+main%28%29+%7B%0A++++let+foo+%3D+%22Hello%21%22%3B%0A++++%2F%2F+%7B%0A++++%2F%2F+++++format_args%21%28%22variable+%7Bfoo%7D%22%29%3B%0A++++%2F%2F+%7D%0A%7D

Well, yet another reason it's not a good idea. We also can't rely on the fact that it will never gain #[must_use] attribute.

zeenix · 2024-04-18T21:26:00Z

One not-so-bad solution that comes to mind is that we require separate arguments to be always passed by reference. IMO the inlined style (debug!("inlining {e} here")) should be preferred anyway.

Just in case it wasn't clear, by this I meant that we can use let _ = .. solution but use the args by value. The tracing macros can take references as well.

In CONTRIBUTING.md, it is stated that clippy must not find anything wrong in the code, and that contributors may allow clippy to ignore warnings. In a discussion I had with zeenix in pull request dbus2#712, we discussed possible ways to allow unused variables. Feeding these variables to an underscore ident inside of a block is a cheap way to use these variables without forcing the user of the macros to worry about unused variable clippy lints. This does require people to pass in arguments themselves for the variables to be properly used.

REALERvolker1 · 2024-04-25T20:45:58Z

Hey sorry for the late reply, I was busy. As for variables, I assign everything in tuples into an underscore, and put in #[allow(unused_variables)] for good measure.

This does require us to use the args by value, but war is hell

zeenix

Sorry but still some way to go IMO. Apart from inline comments, you'll need to rebase against the latest git main (to resolve the conflicts) and please squash commits and update the commit log accordingly.

Don't give up though! Despite all that, you've made a lot of progress on this and I'm really looking forward to merging this work soon.

zeenix · 2024-04-26T10:53:10Z

zbus/src/connection/mod.rs

+            let name_request_future =
+                name_request_future.instrument(tracing::trace_span!("{}", lost_task_name));
+
+            Some(name_request_future)


IMO commits in this PR shouldn't need to change anything in the other parts of the code than the new logging mode. Can't we also abstract Instrument trait?

zeenix · 2024-04-26T10:57:00Z

zbus/tests/e2e.rs

@@ -460,7 +471,7 @@ impl MyIfaceImpl {
            .contains(zbus::message::Flags::NoAutoStart));
    }

-    #[instrument]
+    #[cfg_attr(feature = "tracing", tracing::instrument(level = "info"))]


addition of level specification is a separate logical change and should go into its own commit with its own justification. Why do we need it btw? Shouldn't that be the default anyway?

zeenix · 2024-04-26T10:58:30Z

zbus/tests/e2e.rs

+#[cfg(feature = "tracing")]
+use tracing::debug;
+#[cfg(not(feature = "tracing"))]
+macro_rules! debug {
+    ($lit:literal) => {
+        println!($lit)
+    };
+    ($lit:literal $(, $arg:expr)+) => {
+        println!($lit $(, $arg)+)
+    };
+}
+


We shouldn't need this. The new macros could check for cfg(tests) in addition to tracing feature.

zeenix · 2024-04-26T10:59:58Z

zbus/src/proxy/mod.rs

@@ -306,10 +309,12 @@ impl PropertiesCache {
                .keep_updated(prop_changes, interface, uncached_properties)
                .await
            {
-                debug!("Error keeping properties cache updated: {e}");
+                debug!("Error keeping properties cache updated: {}", e);


This shouldn't be needed at all and in fact is contrary to my wish for making {e} style the preferred one. :(

zeenix · 2024-04-26T11:00:56Z

zbus/src/proxy/mod.rs

+#[cfg(feature = "tracing")]
+use tracing::Instrument;


Best if we just remove the import and use it with full path. Best to minimize the conditional code.

zeenix · 2024-04-26T11:07:13Z

zbus/Cargo.toml

-tracing = "0.1.40"
-vsock = { version = "0.4.0", optional = true }
-tokio-vsock = { version = "0.4", optional = true }
-xdg-home = "1.1.0"
+


let's not include unneeded changes (talking about moving the deps here).

zeenix · 2024-06-02T13:19:06Z

@REALERvolker1 Hi, do you think you'll have the time and motivation to finish this?

zeenix requested changes Apr 9, 2024

View reviewed changes

REALERvolker1 force-pushed the main branch from 8aa0dd3 to 2ec3054 Compare April 9, 2024 20:25

REALERvolker1 closed this Apr 11, 2024

REALERvolker1 force-pushed the main branch from 2ec3054 to 84f6753 Compare April 11, 2024 02:51

REALERvolker1 added 3 commits April 10, 2024 21:53

REALERvolker1 reopened this Apr 11, 2024

REALERvolker1 force-pushed the main branch from f69084f to ac4b3ec Compare April 15, 2024 22:18

REALERvolker1 force-pushed the main branch from ac4b3ec to 45c9e0f Compare April 16, 2024 00:06

REALERvolker1 force-pushed the main branch from 45c9e0f to 83bff60 Compare April 16, 2024 00:09

zeenix reviewed Apr 16, 2024

View reviewed changes

REALERvolker1 force-pushed the main branch from 83bff60 to 4bd8de1 Compare April 17, 2024 03:11

REALERvolker1 force-pushed the main branch from 4bd8de1 to 26a7cd8 Compare April 25, 2024 20:43

zeenix requested changes Apr 26, 2024

View reviewed changes

zeenix mentioned this pull request Jun 3, 2024

Affect on the binary size #304

Open

♻️ zb: Make tracing an optional dependency #712

Are you sure you want to change the base?

♻️ zb: Make tracing an optional dependency #712

Conversation

REALERvolker1 commented Apr 9, 2024 • edited Loading

zeenix left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

zeenix commented Apr 9, 2024

REALERvolker1 commented Apr 9, 2024

REALERvolker1 commented Apr 9, 2024

zeenix commented Apr 9, 2024 • edited Loading

REALERvolker1 commented Apr 10, 2024

REALERvolker1 commented Apr 10, 2024

REALERvolker1 commented Apr 11, 2024

zeenix commented Apr 11, 2024

zeenix commented Apr 15, 2024

REALERvolker1 commented Apr 16, 2024

Choose a reason for hiding this comment

zeenix commented Apr 16, 2024

REALERvolker1 commented Apr 17, 2024

zeenix commented Apr 18, 2024

REALERvolker1 commented Apr 18, 2024

REALERvolker1 commented Apr 18, 2024

zeenix commented Apr 18, 2024

zeenix commented Apr 18, 2024

zeenix commented Apr 18, 2024

REALERvolker1 commented Apr 18, 2024

REALERvolker1 commented Apr 18, 2024

zeenix commented Apr 18, 2024

zeenix commented Apr 18, 2024

REALERvolker1 commented Apr 25, 2024

zeenix left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

zeenix commented Jun 2, 2024

REALERvolker1 commented Apr 9, 2024 •

edited

Loading

zeenix commented Apr 9, 2024 •

edited

Loading