RPC to allow setting the log filter #7474

mattrutherford · 2020-10-31T13:22:38Z

Features to allow dynamically reloading the log filter via RPC in order to add filter directives, or reset to the original directives specified at startup:

Implement system_addLogFilter RPC to add log directives to the filter
Implement system_resetLogFilter RPC to reset the filter to it's original state
Create subscriber reload handle at tracing init
Store default directives from substrate, including CLI-supplied log directives
Add CLI flag to opt-out of filter reloading (due to small performance cost)

polkadot companion: paritytech/polkadot#1985

bkchr · 2020-10-31T13:30:48Z

primitives/tracing/src/logging.rs

@@ -33,7 +33,7 @@ use tracing_subscriber::{
 /// Span name used for the logging prefix. See macro `sc_cli::prefix_logs_with!`
 pub const PREFIX_LOG_SPAN: &str = "substrate-log-prefix";

-pub(crate) struct EventFormat<T = SystemTime> {
+pub struct EventFormat<T = SystemTime> {


Why does this file is now duplicated?

While working out some things I needed access to some of the types here so was considering a refactor to move this to the sc_tracing crate - it needs resolving

@mattrutherford I am confused. Do you mean moving this to the sp_tracing or sc_tracing crate? In #7328 @cecton added this stuff to cli/src/logging.rs.

I meant to sc_tracing because it's client/tracing related code - however, the way we're implementing it now means it's not required to be there - so a refactor would be optional and probably out of scope for this PR.

Actually I should probably move those in something common (sc-service I guess) that I can share with substrate-browser-utils. I will investigate that on my PR #7463 because it's blocking

client/rpc-api/src/system/mod.rs

Co-authored-by: Pierre Krieger <pierre.krieger1708@gmail.com>

dvdplm · 2020-11-09T09:01:03Z

client/cli/src/lib.rs

+		// TODO: Q - There's a small cost to this, do we make it opt-in/out with cli flag?
+		.with_filter_reloading();


I investigated this and I think we should enable this by default until it can be proven to be significant for our use-case. In an artificial context the performance impact is significant: it's twice as slow, but we're talking about ~35ns –> ~70ns for the worst case. Once you add in all the filtering and other options we use the impact is negligible.

Benchmarks for a "complex" setup very similar to our own (but using a noop writer):

reload/complex-collector time: [1.8996 us 1.9034 us 1.9076 us] change: [-3.5626% -3.1266% -2.7425%] (p = 0.00 < 0.05) Performance has improved. Found 1 outliers among 100 measurements (1.00%) 1 (1.00%) high mild reload/complex-collector-reloadable time: [1.9313 us 1.9382 us 1.9456 us] change: [-1.9828% -1.7096% -1.4540%] (p = 0.00 < 0.05) Performance has improved. Found 1 outliers among 100 measurements (1.00%) 1 (1.00%) high mild

OK - nice to have some figures for that. In that case I'll just add an opt-out CLI option --disable-log-reloading or similar

One reason for leaving it on by default is that making it optional is nasty; the reloading changes the types such that I think we'd have to duplicate a lot of code (essentially everything from here to the end of the method). I don't think it's worth it.

OK, that's a good point. But if it's not too ugly then IMO I think it's worth having - simply because if it's an optional performance configuration option implemented in tracing then I think we should mirror it.

I'll try it out and we can see in review

I just added a commit to do this - it worked out OK, only requiring 2 lines of duplicated code - one to finish the builder, another to call a new function that accepts a generic Subscriber. I don't think there is any downside to having this feature.

Move profiling CLI options to SharedParams

…log-reloading

client/cli/src/config.rs

client/cli/src/lib.rs

client/cli/src/params/shared_params.rs

client/rpc-api/src/system/mod.rs

client/tracing/src/lib.rs

client/rpc/src/system/tests.rs

bkchr · 2020-11-29T19:33:40Z

client/rpc/src/system/tests.rs

@@ -333,3 +333,92 @@ fn system_network_remove_reserved() {
 	assert_eq!(runtime.block_on(good_fut), Ok(()));
 	assert!(runtime.block_on(bad_fut).is_err());
 }
+
+#[test]
+fn test_add_reset_log_filter() {


Really nice test!

thanks! got the initial idea from the Telemetry PR by @cecton

client/cli/src/lib.rs

bkchr · 2020-11-29T19:36:49Z

client/cli/src/lib.rs

+	use sc_tracing::parse_default_directive;
+
+	// Accept all valid directives and print invalid ones
+	fn parse_user_directives(mut env_filter: EnvFilter, dirs: &str) -> EnvFilter {


Suggested change

fn parse_user_directives(mut env_filter: EnvFilter, dirs: &str) -> EnvFilter {

fn parse_user_directives(mut env_filter: EnvFilter, dirs: &str) -> std::result::Result<EnvFilter, String> {

I tried out this change of return type, but I reverted it because I think it means:

Have to duplicate code in thew 4 other places it's called

We bail on first bad directive, don't accept the rest and only print the first bad one (in case there may be more than 1 invalid)

Would it make more sense to rename the fn name to add_directives_and_print_invalid ?

This is completely fine to only bail out the first one. This is about telling the user that he tried an invalid configuration parameter.
He will find out about the others when fixing the first one.

This is very unlikely anyway, however I would like to have this. We already had it twice that we didn't accepted a particular directive, but silently ignored it.

yeah, before this PR it was silently ignored. So just to clarify, do you want to just eprintln the bad directive, ignore the remaining (possibly valid) directives but still start the node?

Currently it does actually eprintln all of the invalid directives so the user should be aware; and accept all valid ones.

I for one would be ok to halt the startup process and exit, with an error message Invalid logging directive: x (and if the next is invalid too, rinse&repeat until they get it right): users tend to not read logs very carefully so an eprintln will be missed.

OK, I got it now. The behavior before this PR was if init_logger fails the node continues to start - I'll fix that.

Yeah, before it continued. I want, as @dvdplm that we return an error and exit the node. An eprintln would just be ignored.

client/cli/src/lib.rs

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

bkchr

Some last nitpicks, otherwise it looks good! TY!

client/tracing/src/lib.rs

client/cli/src/lib.rs

bkchr · 2020-11-30T15:43:28Z

client/cli/src/lib.rs

+	use sc_tracing::parse_default_directive;
+
+	// Accept all valid directives and print invalid ones
+	fn parse_user_directives(mut env_filter: EnvFilter, dirs: &str) -> EnvFilter {


This is completely fine to only bail out the first one. This is about telling the user that he tried an invalid configuration parameter.
He will find out about the others when fixing the first one.

This is very unlikely anyway, however I would like to have this. We already had it twice that we didn't accepted a particular directive, but silently ignored it.

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

# Conflicts: # Cargo.lock # client/cli/Cargo.toml # client/executor/Cargo.toml

mattrutherford · 2020-12-01T16:46:21Z

Should be ready for final review

cecton

LGTM 👍

mattrutherford · 2020-12-03T13:17:37Z

bot merge

ghost · 2020-12-03T13:17:43Z

Trying merge.

* Add filter reload handle * add RPC, move logging module from cli to tracing * remove dup fn * working example * Update client/rpc-api/src/system/mod.rs Co-authored-by: Pierre Krieger <pierre.krieger1708@gmail.com> * Prefer "set" to "reload" * Re-enable the commented out features of the logger * Remove duplicate code * cleanup * unneeded lvar * Bump to latest patch release * Add new CLI option to disable log filter reloading, Move profiling CLI options to SharedParams * Apply suggestions from code review Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com> * Applied suggestions from reviews * Fix calls to init_logger() * Handle errors when parsing logging directives * Deny `system_setLogFilter` RPC by default * One more time * Don't ignore parse errors for log directives set via CLI or RPC * Improve docs * Apply suggestions from code review Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com> * Update client/cli/src/config.rs Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com> * fix merge errors * include default directives with system_setLogFilter RPC, implement system_rawSetLogFilter RPC to exclude defaults * docs etc... * update test * refactor: rename fn * Add a test for system_set_log_filter – NOTE: the code should likely change to return an error when bad directives are passed * Update client/cli/src/lib.rs Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com> * Address review grumbles * Add doc note on panicking behaviour * print all invalid directives before panic * change RPCs to: addLogFilter and resetLogFilter * make CLI log directives default * add comments * restore previous behaviour to panic when hard-coded directives are invalid * change/refactor directive parsing * fix line width * add test for log filter reloading * Apply suggestions from code review Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com> * finish up suggestions from code review * improve test * change expect message * change fn name * Apply suggestions from code review Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com> * Apply suggestions from code review Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com> * add docs, remove unused fn * propagate Err on invalid log directive * Update tracing-subscriber version * Improve docs for `disable_log_reloading` CLI param Co-authored-by: Matt <mattrutherford@users.noreply.github.com> Co-authored-by: David <dvdplm@gmail.com> Co-authored-by: Pierre Krieger <pierre.krieger1708@gmail.com> Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

mattrutherford added 4 commits October 30, 2020 19:45

Add filter reload handle

0c480ef

add RPC, move logging module from cli to tracing

767f61a

remove dup fn

5643e7e

working example

cd8815e

mattrutherford added A3-in_progress Pull request is in progress. No review needed at this stage. B5-clientnoteworthy C1-low PR touches the given topic and has a low impact on builders. labels Oct 31, 2020

mattrutherford marked this pull request as draft October 31, 2020 13:22

github-actions bot added A0-please_review Pull request needs code review. and removed A3-in_progress Pull request is in progress. No review needed at this stage. labels Oct 31, 2020

bkchr reviewed Oct 31, 2020

View reviewed changes

tomaka reviewed Nov 2, 2020

View reviewed changes

client/rpc-api/src/system/mod.rs Outdated Show resolved Hide resolved

dvdplm and others added 3 commits November 2, 2020 11:31

Update client/rpc-api/src/system/mod.rs

eb429e1

Co-authored-by: Pierre Krieger <pierre.krieger1708@gmail.com>

Prefer "set" to "reload"

884c1db

Re-enable the commented out features of the logger

57ae457

dvdplm self-assigned this Nov 4, 2020

dvdplm added 4 commits November 4, 2020 13:57

Merge branch 'master' into log-reloading

297e75f

Remove duplicate code

7960ebb

cleanup

8ca1301

unneeded lvar

2b11d45

dvdplm reviewed Nov 9, 2020

View reviewed changes

dvdplm and others added 4 commits November 9, 2020 15:30

Merge branch 'master' into log-reloading

86ad90a

Bump to latest patch release

1406207

Add new CLI option to disable log filter reloading,

2d8dfa0

Move profiling CLI options to SharedParams

Merge branch 'log-reloading' of github.com:paritytech/substrate into …

992e69c

…log-reloading

mattrutherford changed the title ~~[WIP] Log reloading~~ Log reloading Nov 9, 2020

mattrutherford marked this pull request as ready for review November 9, 2020 20:39

mattrutherford changed the title ~~Log reloading~~ RPC to allow setting the log filter Nov 9, 2020

github-actions bot added the A7-needspolkadotpr label Nov 9, 2020

bkchr reviewed Nov 9, 2020

View reviewed changes

bkchr reviewed Nov 29, 2020

View reviewed changes

mattrutherford and others added 3 commits November 30, 2020 10:05

Apply suggestions from code review

3d49c2a

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

finish up suggestions from code review

098e730

improve test

b5d4378

bkchr reviewed Nov 30, 2020

View reviewed changes

bkchr requested a review from cecton November 30, 2020 15:44

mattrutherford and others added 8 commits November 30, 2020 16:05

change expect message

5da34f0

change fn name

728ed21

Apply suggestions from code review

990c0c9

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

Apply suggestions from code review

1a7cf5c

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

add docs, remove unused fn

b941066

propagate Err on invalid log directive

1207ef7

Merge branch 'master' into log-reloading

042e4fe

# Conflicts: # Cargo.lock # client/cli/Cargo.toml # client/executor/Cargo.toml

Update tracing-subscriber version

397b09c

github-actions bot added the A7-needspolkadotpr label Dec 1, 2020

bkchr approved these changes Dec 2, 2020

View reviewed changes

Improve docs for disable_log_reloading CLI param

0489d8a

github-actions bot removed the A7-needspolkadotpr label Dec 2, 2020

Merge branch 'master' into log-reloading

5baa021

cecton approved these changes Dec 3, 2020

View reviewed changes

mattrutherford removed the A0-please_review Pull request needs code review. label Dec 3, 2020

ghost merged commit 0dfdc32 into master Dec 3, 2020

ghost deleted the log-reloading branch December 3, 2020 13:17

jacogr mentioned this pull request Dec 6, 2020

system_{addLogFilter, resetLogFilter} RPCs polkadot-js/api#2916

Merged

dvdplm mentioned this pull request Dec 31, 2020

Logging takes quite some CPU time #7800

Closed

bkchr mentioned this pull request Feb 3, 2021

Change the logging levels on the fly paritytech/polkadot#2376

Open

This pull request was closed.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

RPC to allow setting the log filter #7474

RPC to allow setting the log filter #7474

mattrutherford commented Oct 31, 2020 •

edited

Loading

bkchr Oct 31, 2020

mattrutherford Oct 31, 2020

dvdplm Nov 4, 2020

mattrutherford Nov 4, 2020

cecton Nov 5, 2020

dvdplm Nov 9, 2020

mattrutherford Nov 9, 2020

dvdplm Nov 9, 2020

mattrutherford Nov 9, 2020

mattrutherford Nov 9, 2020

mattrutherford Nov 9, 2020

bkchr Nov 29, 2020

mattrutherford Nov 30, 2020

bkchr Nov 29, 2020

mattrutherford Nov 30, 2020

bkchr Nov 30, 2020

mattrutherford Nov 30, 2020

dvdplm Nov 30, 2020

mattrutherford Dec 1, 2020

bkchr Dec 1, 2020

bkchr left a comment

bkchr Nov 30, 2020

mattrutherford commented Dec 1, 2020

cecton left a comment

mattrutherford commented Dec 3, 2020

ghost commented Dec 3, 2020

		// TODO: Q - There's a small cost to this, do we make it opt-in/out with cli flag?
		.with_filter_reloading();

	fn parse_user_directives(mut env_filter: EnvFilter, dirs: &str) -> EnvFilter {
	fn parse_user_directives(mut env_filter: EnvFilter, dirs: &str) -> std::result::Result<EnvFilter, String> {

RPC to allow setting the log filter #7474

RPC to allow setting the log filter #7474

Conversation

mattrutherford commented Oct 31, 2020 • edited Loading

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

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

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

bkchr left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mattrutherford commented Dec 1, 2020

cecton left a comment

Choose a reason for hiding this comment

mattrutherford commented Dec 3, 2020

ghost commented Dec 3, 2020

mattrutherford commented Oct 31, 2020 •

edited

Loading