How to turn on logging in libraries?

Bit of a rust question…

In sn_node the logging is initialized in init_logging(config).

Within that there’s a line to determine the filter level:
format!("{}={}", NODE_MODULE_NAME, level_filter.to_string());
ie
sn_node=INFO
More details in log level docs.

We can use RUST_LOG env var to override it, eg in the shell
export RUST_LOG="info,bls_dkg=trace"
which should show trace level logging for the bls_dkg crate.

However I do not see any bls_dkg records in my node logs. Any ideas why? Is this just me or do other people see this too?

I just gave it a try and I’m seeing some bls-dkg logs with RUST_LOG=bls_dkg=debug, perhaps the info I see in your "info,bls_dkg=trace" value is the problem?

Thanks for confirming this.

I found the problem, sn_launch_tool seems to be clobbering the RUST_LOG environment variable via the --rust_log flag.

My short term fix was to remove that flag entirely from sn_launch_tool, but I’ll come up with a cleaner fix in a future PR.

My thinking-out-load thinks this line is missing a check for the actual environment variable (it only checks for the flag):

and then this line seals the fate, ignoring any ‘real’ environment variable that was set:

I was trying to change the sn_node init_logging to a hardcoded filter level, but a) the launcher was always overriding it with the RUST_LOG environment variable, and b) RUST_LOG was only loaded from the flag (never the environment).

So many permutations of flags and env vars!!

3 Likes

Ah right, the idea behind all that was that RUST_LOG would apply only to the app you are effectively running, in this case the launch_tool, but that doesn’t necessarily mean it’s the log level you want for the sn-nodes being launched by it. So that was an attempt to make that separation. Since as you say it’s confusing, it’s probably ok to have both the tool and nodes being launched to all go with the same level which is just from RUST_LOG I guess…

2 Likes

I think we can probably still achieve this.

  • Add a --rust-log flag to $ safe node run-baby-fleming here
  • Pass that flag to sn_launch_tool here
  • the nodes will use the --rust_log flag, but sn_launch_tool and sn_api will use the RUST_LOG env var

Maybe rename --rust_log to --node_rust_log just so it’s clear it’s only able to affect the node log level…?

1 Like

That sounds excellent to me, although

Note we already have the y flag here, and here, so we’d just need to rename/change them.

1 Like

not just rename, also pass it correctly on to sn_launch_tool.

We’d need to add an extra flag here and here, something like

...
"--node_verbosity",
&arg_node_verbosity,
...

Note sn_cli has a hardcoded -v verbosity for the sn_launch_tool logs which is potentially easy to confuse with the desired node_verbosity.

I think logically the steps to take are

Sound ok?

I acknowledge this seems like a lot of messing around in the weeds but logging is an important feature to get right. When we need it we really need it.

2 Likes

Yes, I agree. We are on the same page, I was just trying to point out that the CLI -y flag actually ends up setting the -y flag in the launch tool here, which is done from here, that’s how it’s been supported till now. So we can change them as you describe, the -y is very confusing. It’ll be different though as the new --node-verbosity will expect a RUST_LOG value while the existing -y is just mapping from occurrences to log levels, but I don’t think we need that if we have all the power of the RUST_LOG value.

The hardcoded -v is for having the launch-tool to print out the messages about the nodes being launched and so forth on the stdout.

1 Like

Oh right, I hadn’t picked up on that chain. Thanks for pointing it out.

1 Like