Allow log filtering with $RUST_LOG #2130

Bravo555 · 2023-08-04T16:24:12Z

Proposed changes

--debug flag used to increase log verbosity is very noisy, as it enables trace (lowest level) logs from all modules, as well as dependencies.
On the contrary, RUST_LOG environment variable can be used to set different logging levels on a per-module basis, allowing to e.g. set trace for a module one is currently working on and info on the rest, or limiting logging only to the current crate.

As such, set_log_level function was modified to not overide a $RUST_LOG filter if it is present. If this variable is not present, it sets log level globally as usual.

Types of changes

Bugfix (non-breaking change which fixes an issue)
New feature (non-breaking change which adds functionality)
Improvement (general improvements like code refactoring that doesn't explicitly fix a bug or add any new functionality)
Documentation Update (if none of the other choices apply)
Breaking change (fix or feature that would cause existing functionality to not work as expected)

Paste Link to the issue

Checklist

I have read the CONTRIBUTING doc
I have signed the CLA (in all commits with git commit -s)
I ran cargo fmt as mentioned in CODING_GUIDELINES
I used cargo clippy as mentioned in CODING_GUIDELINES
I have added tests that prove my fix is effective or that my feature works
I have added necessary documentation (if appropriate)

Further comments

codecov · 2023-08-04T16:43:46Z

Codecov Report

Merging #2130 (a5a5ff9) into main (d35823f) will decrease coverage by 0.1%.
The diff coverage is 35.7%.

Additional details and impacted files

Files Changed	Coverage Δ
crates/common/download/src/download.rs	`76.1% <ø> (+0.1%)`	⬆️
crates/common/flockfile/src/unix.rs	`65.4% <0.0%> (ø)`
crates/core/tedge_agent/src/main.rs	`0.0% <0.0%> (ø)`
crates/core/tedge_mapper/src/main.rs	`0.0% <0.0%> (ø)`
crates/core/tedge_watchdog/src/main.rs	`0.0% <0.0%> (ø)`
crates/extensions/c8y_http_proxy/src/actor.rs	`40.0% <0.0%> (ø)`
plugins/c8y_configuration_plugin/src/main.rs	`0.0% <0.0%> (ø)`
plugins/c8y_firmware_plugin/src/main.rs	`0.0% <0.0%> (ø)`
plugins/c8y_log_plugin/src/main.rs	`0.0% <0.0%> (ø)`
crates/extensions/c8y_log_manager/src/actor.rs	`76.1% <33.3%> (-0.2%)`	⬇️
... and 3 more

... and 2 files with indirect coverage changes

PradeepKiruvale

IMO, it's better to mention in the documentation, which is a higher priority RUST_LOG Vs --debug flag.

PradeepKiruvale · 2023-08-07T00:37:08Z

crates/common/tedge_config/src/system_services/log_config.rs

@@ -19,14 +19,23 @@ pub fn get_log_level(
    }
 }

-/// Initialize a `tracing_subscriber`
-/// Reports all the log events sent either with the `log` crate or the `tracing` crate.
+/// Initializes a tracing subscriber with a given log level if environment


Suggested change

/// Initializes a tracing subscriber with a given log level if environment

/// Initializes a tracing subscriber with a given log level through --debug, if the environment

It's the caller who chooses whether or not to call this function when --debug is present or not, and the function doesn't check if --debug is present or not, so the function doc should not mention it.

reubenmiller · 2023-08-07T08:40:27Z

I like the idea and proactive nature of the PR, though just a few minor points to make it more inline with existing functionality and some general questions.

General points

avoid any usage of Rust specific names in the user interface, e.g. the environment variable RUST_LOG.
we should try to re-use the existing tedge config env variable/config file mechanism that we have (if possible) rather than creating another custom env variable mapping.
configuration should use the following order of preference (following the 12 factor app guidelines), where the first non-empty value is used in order of:
1. flag (if one exists)
2. environment variable
3. config file

Do we really need a crate-level granularity for filtering log levels?

I think this is a byproduct to the real issue that we are logging in some instances to INFO instead of TRACE. For example, the software list messages result in multiple (very long) messages being logged essentially spamming the log output when there are a large number (>200) debian packages being detected by tedge-apt-plugin. One could argue if TRACE would better suited for showing inter actor communication, and only the MQTT message are logged (or some variant of that).

Though if we did support crate-level log filtering, I don't think it would be that useful for users as they would have to first know what the crate name was, and if that crate name would change due to refactoring, then their log filter would not work anymore (which would also be unexpected for users).

didier-wenzek · 2023-08-08T14:50:37Z

Do we really need a crate-level granularity for filtering log levels?

I see that as useful, knowing that this can be done at the actor level:

RUST_LOG=C8yMapper=debug,MQTT=debug tedge-mapper c8y

One could argue if TRACE would better suited for showing inter actor communication, and only the MQTT message are logged (or some variant of that).

Agree, however I vote for DEBUG, as TRACE is super (too) verbose.

I also see as an issue the fact that --debug enable the TRACE level. --debug should be DEBUG.

I think this is a byproduct to the real issue that we are logging in some instances to INFO instead of TRACE. For example, the software list messages result in multiple (very long) messages being logged essentially spamming the log output when there are a large number (>200) debian packages being detected by tedge-apt-plugin.

Yes, TRACE would be better for this message (as published over MQTT).

github-actions · 2023-08-17T11:33:54Z

Robot Results

✅ Passed	❌ Failed	⏭️ Skipped	Total	Pass %
257	0	5	257	100

didier-wenzek

@Bravo555 and @reubenmiller We need to discuss the log level used for the messages received by the actors.

crates/core/tedge_actors/src/message_boxes.rs

`--debug` flag used to increase log verbosity is very noisy, as it enables `trace` (lowest level) logs from all modules, as well as dependencies. On the contrary, `RUST_LOG` environment variable can be used to set different logging levels on a per-module basis, allowing to e.g. set `trace` for a module one is currently working on and `info` on the rest, or limiting logging only to the current crate. As such, `set_log_level` function was modified to not overide a `$RUST_LOG` filter if it is present. If this variable is not present, it sets log level globally as usual. Signed-off-by: Marcel Guzik <[email protected]>

Signed-off-by: Marcel Guzik <[email protected]>

The principles behind the changes were: - if there is an interaction with the outside (eg. upload/download) - INFO - inter-actor messages and other communication - DEBUG - message payloads (they can be very large and there's no reason to print them multiple times) - TRACE - implementation-level event that should be of no concern to the user, isn't a lot of data, and should be called once or few times - DEBUG Signed-off-by: Marcel Guzik <[email protected]>

Bravo555 · 2023-08-21T13:12:39Z

configuration should use the following order of preference (following the 12 factor app guidelines), where the first non-empty value is used in order of:

flag (if one exists)

environment variable

config file

Doing this would require rewriting more code in each crate that we do config, taking more time and effort that i don't think is worth it. It's just every time I start working on a feature, I need to comment out the set_log_level call to be able to filter out log messages by crate or level. If having this undocumented environment variable which overrides the --debug flag is a problem, then I can discard this commit, leaving the ones that tweak log levels of some messages, on which we seem to have a consensus.

we should try to re-use the existing tedge config env variable/config file mechanism that we have (if possible) rather than creating another custom env variable mapping.

To be honest, I have no idea what options in our tedge config do we have, that would be relevant to this. It's just that crate based-filtering is very useful for developers and it's what you get with log and tracing crates for free, but from my point of view it seems that it was disabled unintentionally.

didier-wenzek

Approved

Bravo555 requested a review from PradeepKiruvale August 4, 2023 16:24

PradeepKiruvale reviewed Aug 7, 2023

View reviewed changes

Bravo555 force-pushed the allow-rust_log branch from 70d15b7 to 0d28008 Compare August 17, 2023 10:27

Bravo555 had a problem deploying to Test Pull Request August 17, 2023 10:41 — with GitHub Actions Failure

Bravo555 force-pushed the allow-rust_log branch from 0d28008 to 55d723d Compare August 17, 2023 11:00

Bravo555 temporarily deployed to Test Pull Request August 17, 2023 11:10 — with GitHub Actions Inactive

didier-wenzek reviewed Aug 18, 2023

View reviewed changes

crates/core/tedge_actors/src/message_boxes.rs Outdated Show resolved Hide resolved

Bravo555 force-pushed the allow-rust_log branch 2 times, most recently from c6ee49d to 8388fe6 Compare August 21, 2023 12:59

Bravo555 added 3 commits August 21, 2023 13:00

Use debug log level for --debug flag

f75238f

Signed-off-by: Marcel Guzik <[email protected]>

Bravo555 force-pushed the allow-rust_log branch from 8388fe6 to a5a5ff9 Compare August 21, 2023 13:00

Bravo555 temporarily deployed to Test Pull Request August 21, 2023 13:21 — with GitHub Actions Inactive

didier-wenzek approved these changes Aug 21, 2023

View reviewed changes

didier-wenzek merged commit 8971b91 into thin-edge:main Aug 21, 2023
18 checks passed

Bravo555 deleted the allow-rust_log branch August 21, 2023 14:33

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Allow log filtering with $RUST_LOG #2130

Allow log filtering with $RUST_LOG #2130

Bravo555 commented Aug 4, 2023

codecov bot commented Aug 4, 2023 •

edited

Loading

PradeepKiruvale left a comment

PradeepKiruvale Aug 7, 2023

Bravo555 Aug 17, 2023

reubenmiller commented Aug 7, 2023

didier-wenzek commented Aug 8, 2023

github-actions bot commented Aug 17, 2023 •

edited

Loading

didier-wenzek left a comment

Bravo555 commented Aug 21, 2023

didier-wenzek left a comment

	/// Initializes a tracing subscriber with a given log level if environment
	/// Initializes a tracing subscriber with a given log level through --debug, if the environment

Allow log filtering with $RUST_LOG #2130

Allow log filtering with $RUST_LOG #2130

Conversation

Bravo555 commented Aug 4, 2023

Proposed changes

Types of changes

Paste Link to the issue

Checklist

Further comments

codecov bot commented Aug 4, 2023 • edited Loading

Codecov Report

PradeepKiruvale left a comment

Choose a reason for hiding this comment

PradeepKiruvale Aug 7, 2023

Choose a reason for hiding this comment

Bravo555 Aug 17, 2023

Choose a reason for hiding this comment

reubenmiller commented Aug 7, 2023

didier-wenzek commented Aug 8, 2023

github-actions bot commented Aug 17, 2023 • edited Loading

Robot Results

didier-wenzek left a comment

Choose a reason for hiding this comment

Bravo555 commented Aug 21, 2023

didier-wenzek left a comment

Choose a reason for hiding this comment

codecov bot commented Aug 4, 2023 •

edited

Loading

github-actions bot commented Aug 17, 2023 •

edited

Loading